Micronaut 4.1.x: the IdleStateEvent of the last request may cause a ReadTimeoutException on a healthy new request #9843
Description
Expected Behavior
Consider a reactive client with a connection pool and some read timeout configured:
micronaut.http.client.read-timeout=2s
micronaut.http.client.pool.enabled=true
Expected behavior: Two consecutive requests (A and B) that are executed approximately 2s apart, should result in two successful responses.
Actual Behaviour
Instead, the second one produces a ReadTimeoutException:
Note that requests A and B run faster than 2s (around 110ms each), so this is not a performance error. This only happens when the delay between A and B is near micronaut.http.client.read-timeout. If you make the delay shorter (200ms, for example) or longer (3s), all the requests are OK again.
Apparently, there exists a time window (that starts approximately 2s after A) in which a scheduled IdleStateEvent of A will be understood as a timeout on B. This time window seems to be large enough to reproduce it easily with a simple sleep.
Stack trace of the ReadTimeoutException:
i.m.http.server.RouteExecutor - Unexpected error occurred: Read Timeout
io.micronaut.http.client.exceptions.ReadTimeoutException: Read Timeout
at io.micronaut.http.client.exceptions.ReadTimeoutException.<clinit>(ReadTimeoutException.java:26)
at io.micronaut.http.client.netty.DefaultHttpClient$BaseHttpResponseHandler.exceptionCaught(DefaultHttpClient.java:1996)
at io.micronaut.http.client.netty.DefaultHttpClient$FullHttpResponseHandler.exceptionCaught(DefaultHttpClient.java:2267)
at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:346)
at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:325)
at io.netty.channel.AbstractChannelHandlerContext.fireExceptionCaught(AbstractChannelHandlerContext.java:317)
at io.netty.channel.DefaultChannelPipeline$HeadContext.exceptionCaught(DefaultChannelPipeline.java:1377)
at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:346)
at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:325)
at io.netty.channel.DefaultChannelPipeline.fireExceptionCaught(DefaultChannelPipeline.java:907)
at io.netty.handler.codec.http2.Http2MultiplexHandler$2.visit(Http2MultiplexHandler.java:314)
at io.netty.handler.codec.http2.Http2FrameCodec$1.visit(Http2FrameCodec.java:197)
at io.netty.handler.codec.http2.DefaultHttp2Connection$ActiveStreams.forEachActiveStream(DefaultHttp2Connection.java:978)
at io.netty.handler.codec.http2.DefaultHttp2Connection.forEachActiveStream(DefaultHttp2Connection.java:209)
at io.netty.handler.codec.http2.Http2FrameCodec.forEachActiveStream(Http2FrameCodec.java:193)
at io.netty.handler.codec.http2.Http2ChannelDuplexHandler.forEachActiveStream(Http2ChannelDuplexHandler.java:83)
at io.netty.handler.codec.http2.Http2MultiplexHandler.fireExceptionCaughtForActiveStream(Http2MultiplexHandler.java:309)
at io.netty.handler.codec.http2.Http2MultiplexHandler.exceptionCaught(Http2MultiplexHandler.java:298)
at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:346)
at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:325)
at io.netty.channel.AbstractChannelHandlerContext.fireExceptionCaught(AbstractChannelHandlerContext.java:317)
at io.netty.channel.ChannelInboundHandlerAdapter.exceptionCaught(ChannelInboundHandlerAdapter.java:143)
at io.netty.handler.codec.http2.Http2ConnectionHandler.exceptionCaught(Http2ConnectionHandler.java:582)
at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:346)
at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:325)
at io.netty.channel.AbstractChannelHandlerContext.fireExceptionCaught(AbstractChannelHandlerContext.java:317)
at io.netty.handler.ssl.SslHandler.exceptionCaught(SslHandler.java:1115)
at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:346)
at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:325)
at io.netty.channel.AbstractChannelHandlerContext.fireExceptionCaught(AbstractChannelHandlerContext.java:317)
at io.netty.channel.DefaultChannelPipeline$HeadContext.exceptionCaught(DefaultChannelPipeline.java:1377)
at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:346)
at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:325)
at io.netty.channel.DefaultChannelPipeline.fireExceptionCaught(DefaultChannelPipeline.java:907)
at io.micronaut.http.client.netty.ConnectionManager$Pool$Http2ConnectionHolder.fireReadTimeout(ConnectionManager.java:1350)
at io.micronaut.http.client.netty.ConnectionManager$Pool$ConnectionHolder$1.readTimedOut(ConnectionManager.java:1088)
at io.netty.handler.timeout.ReadTimeoutHandler.channelIdle(ReadTimeoutHandler.java:90)
at io.netty.handler.timeout.IdleStateHandler$ReaderIdleTimeoutTask.run(IdleStateHandler.java:503)
at io.netty.handler.timeout.IdleStateHandler$AbstractIdleTask.run(IdleStateHandler.java:475)
at io.netty.util.concurrent.PromiseTask.runTask(PromiseTask.java:98)
at io.netty.util.concurrent.ScheduledFutureTask.run(ScheduledFutureTask.java:153)
at io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java:174)
at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:167)
at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:470)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:569)
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.base/java.lang.Thread.run(Thread.java:833)
Possible cause of the error:
We believe that the cause of the error is that a IdleStateEvent of A is handled here:
https://github.com/micronaut-projects/micronaut-core/blame/4.1.x/http-client/src/main/java/io/micronaut/http/client/netty/ConnectionManager.java#L1085
And the if (hasLiveRequests()) resolves to true, but not due A being timeout, but due the new request B is being handled in the ConnectionPool in the same precise moment.
Other notes:
- This issue doesn't reproduce on Micronaut 3.x.x. This is keeping us from using 4.x.x right now.
- Apparently this happens more often than we could expect. In a production environment we had a 3% error rate due to this timeout.
Steps To Reproduce
- Use Java 17.
- Clone the given repository.
- Follow one of the two given options to reproduce. Example of reproduction using
./gradlew test --info:ReproduceIssue > runConsecutiveRequests() STANDARD_OUT - Running 10 request with 100ms delay between requests (874ms) 200 - Micronaut launch page has 3118 characters -- Sleeping for 100ms -- (157ms) 200 - Micronaut launch page has 3118 characters -- Sleeping for 100ms -- (164ms) 200 - Micronaut launch page has 3118 characters -- Sleeping for 100ms -- (173ms) 200 - Micronaut launch page has 3118 characters -- Sleeping for 100ms -- (162ms) 200 - Micronaut launch page has 3118 characters -- Sleeping for 100ms -- (161ms) 200 - Micronaut launch page has 3118 characters -- Sleeping for 100ms -- (161ms) 200 - Micronaut launch page has 3118 characters -- Sleeping for 100ms -- (170ms) 200 - Micronaut launch page has 3118 characters -- Sleeping for 100ms -- (171ms) 200 - Micronaut launch page has 3118 characters -- Sleeping for 100ms -- (202ms) 200 - Micronaut launch page has 3118 characters -- Sleeping for 100ms -- - Running 10 request with 1900ms delay between requests (163ms) 200 - Micronaut launch page has 3118 characters -- Sleeping for 1900ms -- (156ms) 500 - io.micronaut.http.client.exceptions.ReadTimeoutException: Read Timeout -- Sleeping for 1900ms -- (609ms) 200 - Micronaut launch page has 3118 characters -- Sleeping for 1900ms -- (99ms) 500 - io.micronaut.http.client.exceptions.ReadTimeoutException: Read Timeout -- Sleeping for 1900ms -- (683ms) 200 - Micronaut launch page has 3118 characters -- Sleeping for 1900ms -- (95ms) 500 - io.micronaut.http.client.exceptions.ReadTimeoutException: Read Timeout -- Sleeping for 1900ms -- (663ms) 200 - Micronaut launch page has 3118 characters -- Sleeping for 1900ms -- (101ms) 500 - io.micronaut.http.client.exceptions.ReadTimeoutException: Read Timeout -- Sleeping for 1900ms -- (649ms) 200 - Micronaut launch page has 3118 characters -- Sleeping for 1900ms -- (101ms) 500 - io.micronaut.http.client.exceptions.ReadTimeoutException: Read Timeout -- Sleeping for 1900ms --
Environment Information
- macOs 13.2 (22D49)
- java 17.0.7
Example Application
https://github.com/alsoba13/micronaut4-read-timeout-in-connection-pool-issue
Version
4.1.x