Error message contains "CIRCULAR REFERENCE" during client connection timeout which is misleading

[visat4]

Describe the bug

We have an application based in Quarkus framework which exposes an REST endpoint. This endpoint accepts a big json payload. Sometimes the client closes the connection too soon and we see the following exception message.

javax.ws.rs.WebApplicationException: HTTP 400 Bad Request at io.quarkus.resteasy.reactive.jackson.runtime.serialisers.ServerJacksonMessageBodyReader.readFrom(ServerJacksonMessageBodyReader.java:60) at io.quarkus.resteasy.reactive.jackson.runtime.serialisers.ServerJacksonMessageBodyReader.readFrom(ServerJacksonMessageBodyReader.java:77) at org.jboss.resteasy.reactive.server.handlers.RequestDeserializeHandler.readFrom(RequestDeserializeHandler.java:122) at org.jboss.resteasy.reactive.server.handlers.RequestDeserializeHandler.handle(RequestDeserializeHandler.java:81) at io.quarkus.resteasy.reactive.server.runtime.QuarkusResteasyReactiveRequestContext.invokeHandler(QuarkusResteasyReactiveRequestContext.java:108) at org.jboss.resteasy.reactive.common.core.AbstractResteasyReactiveContext.run(AbstractResteasyReactiveContext.java:145) at io.quarkus.vertx.core.runtime.VertxCoreRecorder$14.runWith(VertxCoreRecorder.java:576) at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2449) at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1478) at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29) at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29) at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.base/java.lang.Thread.run(Thread.java:833) Caused by: com.fasterxml.jackson.databind.JsonMappingException: Read timed out (through reference chain: com.test.StockReport["data"]->java.util.ArrayList[9037]) at com.fasterxml.jackson.databind.JsonMappingException.wrapWithPath(JsonMappingException.java:402) at com.fasterxml.jackson.databind.JsonMappingException.wrapWithPath(JsonMappingException.java:373) at com.fasterxml.jackson.databind.deser.std.CollectionDeserializer._deserializeFromArray(CollectionDeserializer.java:375) at com.fasterxml.jackson.databind.deser.std.CollectionDeserializer.deserialize(CollectionDeserializer.java:244) at com.fasterxml.jackson.databind.deser.std.CollectionDeserializer.deserialize(CollectionDeserializer.java:28) at com.fasterxml.jackson.databind.deser.impl.MethodProperty.deserializeAndSet(MethodProperty.java:129) at com.fasterxml.jackson.databind.deser.BeanDeserializer.vanillaDeserialize(BeanDeserializer.java:314) at com.fasterxml.jackson.databind.deser.BeanDeserializer.deserialize(BeanDeserializer.java:177) at com.fasterxml.jackson.databind.deser.DefaultDeserializationContext.readRootValue(DefaultDeserializationContext.java:323) at com.fasterxml.jackson.databind.ObjectReader._bindAndClose(ObjectReader.java:2105) at com.fasterxml.jackson.databind.ObjectReader.readValue(ObjectReader.java:1481) at io.quarkus.resteasy.reactive.jackson.runtime.serialisers.ServerJacksonMessageBodyReader.doReadFrom(ServerJacksonMessageBodyReader.java:87) at io.quarkus.resteasy.reactive.jackson.runtime.serialisers.ServerJacksonMessageBodyReader.readFrom(ServerJacksonMessageBodyReader.java:38) ... 12 more Suppressed: java.io.IOException: java.io.IOException: Read timed out at org.jboss.resteasy.reactive.server.vertx.VertxInputStream$VertxBlockingInput.readBlocking(VertxInputStream.java:255) at org.jboss.resteasy.reactive.server.vertx.VertxInputStream.readIntoBuffer(VertxInputStream.java:122) at org.jboss.resteasy.reactive.server.vertx.VertxInputStream.close(VertxInputStream.java:150) at com.fasterxml.jackson.core.json.UTF8StreamJsonParser._closeInput(UTF8StreamJsonParser.java:291) at com.fasterxml.jackson.core.base.ParserBase.close(ParserBase.java:386) at com.fasterxml.jackson.databind.ObjectReader._bindAndClose(ObjectReader.java:2112) ... 15 more Caused by: java.io.IOException: Read timed out at org.jboss.resteasy.reactive.server.vertx.VertxInputStream$VertxBlockingInput.readBlocking(VertxInputStream.java:237) at org.jboss.resteasy.reactive.server.vertx.VertxInputStream.readIntoBuffer(VertxInputStream.java:122) at org.jboss.resteasy.reactive.server.vertx.VertxInputStream.read(VertxInputStream.java:84) at com.fasterxml.jackson.core.json.UTF8StreamJsonParser._loadMore(UTF8StreamJsonParser.java:257) at com.fasterxml.jackson.core.json.UTF8StreamJsonParser.parseEscapedName(UTF8StreamJsonParser.java:2101) at com.fasterxml.jackson.core.json.UTF8StreamJsonParser.slowParseName(UTF8StreamJsonParser.java:2009) at com.fasterxml.jackson.core.json.UTF8StreamJsonParser._parseName(UTF8StreamJsonParser.java:1797) at com.fasterxml.jackson.core.json.UTF8StreamJsonParser.nextToken(UTF8StreamJsonParser.java:797) at com.fasterxml.jackson.databind.deser.BeanDeserializer.deserialize(BeanDeserializer.java:177) at com.fasterxml.jackson.databind.deser.std.CollectionDeserializer._deserializeFromArray(CollectionDeserializer.java:359) at com.fasterxml.jackson.databind.deser.std.CollectionDeserializer.deserialize(CollectionDeserializer.java:244) at com.fasterxml.jackson.databind.deser.std.CollectionDeserializer.deserialize(CollectionDeserializer.java:28) at com.fasterxml.jackson.databind.deser.impl.MethodProperty.deserializeAndSet(MethodProperty.java:129) at com.fasterxml.jackson.databind.deser.BeanDeserializer.vanillaDeserialize(BeanDeserializer.java:314) at com.fasterxml.jackson.databind.deser.BeanDeserializer.deserialize(BeanDeserializer.java:177) at com.fasterxml.jackson.databind.deser.DefaultDeserializationContext.readRootValue(DefaultDeserializationContext.java:323) at com.fasterxml.jackson.databind.ObjectReader._bindAndClose(ObjectReader.java:2105) ... 15 more Caused by: [CIRCULAR REFERENCE: java.io.IOException: Read timed out]

The error says it is caused by "CIRCULAR REFERENCE" which is kind of misleading

Expected behavior

The error message should be not mislead.

Actual behavior

The error message is misleading.

How to Reproduce?

Made a reproducer in the below url. https://github.com/vigneshsn/quarkus-reative

Output of uname -a or ver

No response

Output of java -version

17

GraalVM version (if different from Java)

No response

Quarkus version or git rev

2.16.4.Final

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

No response

Additional information

No response

[quarkus-bot[bot]]

/cc @FroMage (resteasy-reactive), @Sgitario (resteasy-reactive), @geoand (jackson,resteasy-reactive), @gsmet (jackson), @stuartwdouglas (resteasy-reactive)

[Sgitario]

I tried to see the issue with the issue you shared, but it's failing with:

2023-05-05 06:52:26,849 ERROR [org.jbo.res.rea.com.cor.AbstractResteasyReactiveContext] (executor-thread-0) Request failed: java.lang.NullPointerException: Cannot invoke "org.acme.getting.started.model.Greetings.getGreetings()" because "greetings" is null
    at org.acme.getting.started.NonReactiveGreetingResource.greeting(NonReactiveGreetingResource.java:20)
    at org.acme.getting.started.NonReactiveGreetingResource$quarkusrestinvoker$greeting_02b8405fcb0d184c21d8f28def585b303dca37cb.invoke(Unknown Source)
    at org.jboss.resteasy.reactive.server.handlers.InvocationHandler.handle(InvocationHandler.java:29)
    at io.quarkus.resteasy.reactive.server.runtime.QuarkusResteasyReactiveRequestContext.invokeHandler(QuarkusResteasyReactiveRequestContext.java:114)
    at org.jboss.resteasy.reactive.common.core.AbstractResteasyReactiveContext.run(AbstractResteasyReactiveContext.java:145)
    at io.quarkus.vertx.core.runtime.VertxCoreRecorder$14.runWith(VertxCoreRecorder.java:576)
    at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2449)
    at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1478)
    at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
    at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.base/java.lang.Thread.run(Thread.java:833)

Can you fix it, so we can see the issue in action?

[visat4]

@Sgitario can you try again? I have moved the test data to the root of the project folder and should work now.

[visat4]

Also, we see the above issue is caused by hardcoded timeout value of InputStream. The vertxInputStream is hardcoded during creation, is there a way to override this value?

VertxResteasyReactiveRequestContext.class @Override public InputStream createInputStream() { if (context.getBody() != null) { byte[] data = new byte[context.getBody().length()]; context.getBody().getBytes(data); return new ByteArrayInputStream(data); } return new VertxInputStream(context, 10000, this); }

[Sgitario]

@Sgitario can you try again? I have moved the test data to the root of the project folder and should work now.

Thanks, I can reproduce the issue now.

[Sgitario]

Also, we see the above issue is caused by hardcoded timeout value of InputStream. The vertxInputStream is hardcoded during creation, is there a way to override this value?

VertxResteasyReactiveRequestContext.class @Override public InputStream createInputStream() { if (context.getBody() != null) { byte[] data = new byte[context.getBody().length()]; context.getBody().getBytes(data); return new ByteArrayInputStream(data); } return new VertxInputStream(context, 10000, this); }

I think we can't override this value, so we will probably need to either map it to an existing property for this purpose or create a new one. Wdyt @geoand ?

[geoand]

Yeah, it probably should be configurable, although I don't think there is an existing property that could be used.

[visat4]

@geoand @Sgitario should I create another ticket for the hardcoded timeout ? or it is already taken care as part of this issue?

We have client running in slow network and we observed it took more than 10s for the request which POST a big json file. so, we have switched to rest easy classic to temporarily mitigate the issue.

[Sgitario]

@geoand @Sgitario should I create another ticket for the hardcoded timeout ? or it is already taken care as part of this issue?

We have client running in slow network and we observed it took more than 10s for the request which POST a big json file. so, we have switched to rest easy classic to temporarily mitigate the issue.

I think we don't need another ticket for this. Btw, do you use any special configuration/properties in resteasy classic to make it work?

[visat4]

@Sgitario Yes I have increased the 'quarkus.http.read-timeout' value to 60, but Ideally I would not like to increase the read timeout of server. I'm trying to figure out why the server takes more time to read the request.

Our usecase The request contains a json payload around 2MB and We get several (~3-4) of these report at same time. The readBlocking() method took more than 30s sometimes to process these request. it is not very clear why it takes more time to read the request.

[Sgitario]

@Sgitario Yes I have increased the 'quarkus.http.read-timeout' value to 60, but Ideally I would not like to increase the read timeout of server. I'm trying to figure out why the server takes more time to read the request.

This is really weird since the default value for read-timeout is already 60 seconds. Also, I tried to use your reproducer using the RESTEasy classic extension and it did the same that the RESTEasy reactive extension. Can you update it to easily reproduce the issue when using both the RESTEasy classic and the RESTEasy reactive extensions? So, we can see the difference.

Anyway, I spot that the 10000 was wrongly hardcoded instead of using the quarkus.http.read-timeout property that was being used in this scenario. This should be fixed by https://github.com/quarkusio/quarkus/pull/33398.

Note that I can't tell if this indeed fixes your issue because I could not reproduce it, but if you can try yourself the changes, please let us know.

[Sgitario]

@visat4 can you check whether https://github.com/quarkusio/quarkus/pull/33398 fixed your issue? This change should be part of Quarkus 3.1.0.CR1

[visat4]

@Sgitario thanks for quick fix. I'm going to verify on 3.1.2 and get confirm you.

[geoand]

@visat4 did this fix your issue?

[visat4]

@geoand the issue has been fixed in latest version, now the server timeout takes the configured value from property quarkus.http.read-timeout

[geoand]

Thanks for the update