Behavior unexpected sending bytes compressed with gzip setting property 'resteasy.gzip.max.input'

jcarranzan commented 3 months ago

Describe the bug

I'm encountering a java.net.SocketTimeoutException: Read timed out exception when I send Gzip compressed data from my test to a Quarkus endpoint. I've configured my application.properties with:

quarkus.resteasy.gzip.enabled=true

quarkus.resteasy.gzip.max-input=1k

I've created byte[] gzip_max_input_1K = new byte[1000]; that after I compress in gzip data then I send to the Quarkus endpoint and then in the logs, I can see the error mentioned.

My reproducer: git clone -b gzip-input-bytes-reproducer https://github.com/jcarranzan/quarkus-reproducer.git

Logs with the error:

07:35:54,742 INFO  ## Running test GzipMaxInputIT.testGzipAboveTheMaxLimit()
HTTP/1.1 500 Internal Server Error
content-type: application/json; charset=utf-8
content-length: 72

{
    "details": "Error id 7c94905c-e232-43d8-ba81-08e8de910e59-1",
    "stack": ""
}
07:36:26,451 [app] 07:36:25,366 HTTP Request to /gzip failed, error id: 7c94905c-e232-43d8-ba81-08e8de910e59-3: org.jboss.resteasy.spi.UnhandledException: jakarta.ws.rs.ProcessingException: RESTEASY004655: Unable to invoke request: java.net.SocketTimeoutException: Read timed out
07:36:26,451 INFO  [app] 07:36:25,366 HTTP Request to /gzip failed, error id: 7c94905c-e232-43d8-ba81-08e8de910e59-3: org.jboss.resteasy.spi.UnhandledException: jakarta.ws.rs.ProcessingException: RESTEASY004655: Unable to invoke request: java.net.SocketTimeoutException: Read timed out
07:36:26,451 [app]  at org.jboss.resteasy.core.ExceptionHandler.handleApplicationException(ExceptionHandler.java:107)
07:36:26,451 INFO  [app]    at org.jboss.resteasy.core.ExceptionHandler.handleApplicationException(ExceptionHandler.java:107)
07:36:26,451 [app]  at org.jboss.resteasy.core.ExceptionHandler.handleException(ExceptionHandler.java:344)
07:36:26,451 INFO  [app]    at org.jboss.resteasy.core.ExceptionHandler.handleException(ExceptionHandler.java:344)
07:36:26,452 [app]  at org.jboss.resteasy.core.SynchronousDispatcher.writeException(SynchronousDispatcher.java:205)
07:36:26,452 INFO  [app]    at org.jboss.resteasy.core.SynchronousDispatcher.writeException(SynchronousDispatcher.java:205)
07:36:26,452 [app]  at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:452)
07:36:26,452 INFO  [app]    at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:452)
07:36:26,452 [app]  at org.jboss.resteasy.core.SynchronousDispatcher.lambda$invokePropagateNotFound$6(SynchronousDispatcher.java:275)
07:36:26,452 INFO  [app]    at org.jboss.resteasy.core.SynchronousDispatcher.lambda$invokePropagateNotFound$6(SynchronousDispatcher.java:275)
07:36:26,452 [app]  at org.jboss.resteasy.core.SynchronousDispatcher.lambda$preprocess$0(SynchronousDispatcher.java:154)
07:36:26,452 INFO  [app]    at org.jboss.resteasy.core.SynchronousDispatcher.lambda$preprocess$0(SynchronousDispatcher.java:154)
07:36:26,452 [app]  at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:321)
07:36:26,452 INFO  [app]    at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:321)
07:36:26,452 [app]  at org.jboss.resteasy.core.SynchronousDispatcher.preprocess(SynchronousDispatcher.java:157)
07:36:26,452 INFO  [app]    at org.jboss.resteasy.core.SynchronousDispatcher.preprocess(SynchronousDispatcher.java:157)
07:36:26,453 [app]  at org.jboss.resteasy.core.SynchronousDispatcher.invokePropagateNotFound(SynchronousDispatcher.java:260)
07:36:26,453 INFO  [app]    at org.jboss.resteasy.core.SynchronousDispatcher.invokePropagateNotFound(SynchronousDispatcher.java:260)
07:36:26,453 [app]  at io.quarkus.resteasy.runtime.standalone.RequestDispatcher.service(RequestDispatcher.java:84)
07:36:26,453 INFO  [app]    at io.quarkus.resteasy.runtime.standalone.RequestDispatcher.service(RequestDispatcher.java:84)
07:36:26,453 [app]  at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.dispatch(VertxRequestHandler.java:151)
07:36:26,453 INFO  [app]    at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.dispatch(VertxRequestHandler.java:151)
07:36:26,453 [app]  at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler$1.run(VertxRequestHandler.java:97)
07:36:26,453 INFO  [app]    at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler$1.run(VertxRequestHandler.java:97)
07:36:26,453 [app]  at io.quarkus.vertx.core.runtime.VertxCoreRecorder$14.runWith(VertxCoreRecorder.java:599)
07:36:26,453 INFO  [app]    at io.quarkus.vertx.core.runtime.VertxCoreRecorder$14.runWith(VertxCoreRecorder.java:599)
07:36:26,453 [app]  at org.jboss.threads.EnhancedQueueExecutor$Task.doRunWith(EnhancedQueueExecutor.java:2516)
07:36:26,453 INFO  [app]    at org.jboss.threads.EnhancedQueueExecutor$Task.doRunWith(EnhancedQueueExecutor.java:2516)
07:36:26,453 [app]  at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2495)
07:36:26,453 INFO  [app]    at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2495)
07:36:26,454 [app]  at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1495)
07:36:26,454 INFO  [app]    at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1495)
07:36:26,454 [app]  at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:11)
07:36:26,454 INFO  [app]    at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:11)
07:36:26,454 [app]  at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:11)
07:36:26,454 INFO  [app]    at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:11)
07:36:26,454 [app]  at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
07:36:26,454 INFO  [app]    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
07:36:26,454 [app]  at java.base/java.lang.Thread.run(Thread.java:840)
07:36:26,454 INFO  [app]    at java.base/java.lang.Thread.run(Thread.java:840)
07:36:26,454 [app] Caused by: jakarta.ws.rs.ProcessingException: RESTEASY004655: Unable to invoke request: java.net.SocketTimeoutException: Read timed out
07:36:26,454 INFO  [app] Caused by: jakarta.ws.rs.ProcessingException: RESTEASY004655: Unable to invoke request: java.net.SocketTimeoutException: Read timed out
07:36:26,454 [app]  at org.jboss.resteasy.client.jaxrs.engines.ManualClosingApacheHttpClient43Engine.invoke(ManualClosingApacheHttpClient43Engine.java:361)
07:36:26,454 INFO  [app]    at org.jboss.resteasy.client.jaxrs.engines.ManualClosingApacheHttpClient43Engine.invoke(ManualClosingApacheHttpClient43Engine.java:361)
07:36:26,455 [app]  at org.jboss.resteasy.client.jaxrs.internal.ClientInvocation.invoke(ClientInvocation.java:427)
07:36:26,455 INFO  [app]    at org.jboss.resteasy.client.jaxrs.internal.ClientInvocation.invoke(ClientInvocation.java:427)
07:36:26,455 [app]  at org.jboss.resteasy.client.jaxrs.internal.proxy.ClientInvoker.invokeSync(ClientInvoker.java:134)
07:36:26,455 INFO  [app]    at org.jboss.resteasy.client.jaxrs.internal.proxy.ClientInvoker.invokeSync(ClientInvoker.java:134)
07:36:26,455 [app]  at org.jboss.resteasy.client.jaxrs.internal.proxy.ClientInvoker.invoke(ClientInvoker.java:103)
07:36:26,455 INFO  [app]    at org.jboss.resteasy.client.jaxrs.internal.proxy.ClientInvoker.invoke(ClientInvoker.java:103)
07:36:26,455 [app]  at org.jboss.resteasy.client.jaxrs.internal.proxy.ClientProxy.invoke(ClientProxy.java:61)
07:36:26,455 INFO  [app]    at org.jboss.resteasy.client.jaxrs.internal.proxy.ClientProxy.invoke(ClientProxy.java:61)
07:36:26,455 [app]  at jdk.proxy2/jdk.proxy2.$Proxy27.gzip(Unknown Source)

Expected behavior

The server successfully processes Gzip data sent from the test and response 200 OK.

Actual behavior

org.jboss.resteasy.spi.UnhandledException: jakarta.ws.rs.ProcessingException: RESTEASY004655: Unable to invoke request: java.net.SocketTimeoutException: Read timed out

How to Reproduce?

No response

Output of `uname -a` or `ver`

No response

Output of `java -version`

No response

Quarkus version or git rev

No response

Build tool (ie. output of `mvnw --version` or `gradlew --version`)

No response

Additional information

No response

geoand commented 3 months ago

cc @jamezp

jcarranzan commented 3 months ago

Hi @geoand & @jamezp , I've updated the reproducer adding some extra tests that also trigger the SocketTimeoutException and also I've updated the quarkus version to <quarkus.platform.version>3.8.999-SNAPSHOT</quarkus.platform.version> where the backport (https://github.com/quarkusio/quarkus/pull/40663/commits/8b683ee24fdeea6978156dd889f7ee8c3fee6f0c) was done. Thanks.

jamezp commented 3 months ago

I can't seem to reproduce this with plain RESTEasy using the Jakarta SeBootstrap. I assume the issue is somewhere in Quarkus, but I can't figure out how to debug through the test. I'm not familiar with the Quarkus QE Test Framework.

rsvoboda commented 3 months ago

Closing the issue, it's test case design issue where recursive call through rest client is made in GzipResource. @jcarranzan I extended https://github.com/quarkusio/quarkus/issues/39636 reproducer and also updated your reproducer to identify the issue is in test application. I will comment on test coverage PR. @jamezp the app is Quarkus vanilla one, Quarkus QE Test Framework gives us some goodies + we run against standalone java process as customers would do in production. There is no need to be afraid of that stuff :)

jamezp commented 3 months ago

@jamezp the app is Quarkus vanilla one, Quarkus QE Test Framework gives us some goodies + we run against standalone java process as customers would do in production. There is no need to be afraid of that stuff :)

Good to know. I just wasn't sure what it was and I unfortunately just don't have much experience with Quarkus at all. One of these days I'll be able to dig into it more :)

quarkusio / quarkus