intermittent ReadTimeoutException and warning issue using reactive HTTP Client

[lucasgust]

I'm working on a Kotlin application that uses Micronaut to consume messages via Kafka and perform REST integrations via HTTPS with a reactive HTTP Client. However, I've been experiencing two intermittent issues and I don't know if they are related.

Here is my project that can be used for further investigation: https://github.com/lucasgust/micronaut-reactive-http-client-with-coroutines
It is using the same structure, libraries, and configurations as my production environment application (except for Kafka, as I believe it is not necessary). I used the same project as the one used in Micronaut HTTP Client Guide.

---

1. ReadTimeoutException shortly after calling: Occasionally (usually once a day), I'm encountering the ReadTimeoutException immediately after consuming a message (I can notice this by logs). The client's default timeout doesn't seem to be respected, giving the impression that the external service isn't even being requested. Unfortunately I can't reproduce this error in local development.
   
   

Datadog logs shows that the message was consumed by the consumer, and less than 100ms after, the HTTP Client threw a ReadTimeoutException

Stacktrace

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:981)
	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:1117)
	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)

---

2. Warning message after fixed time: After successfully making an external call, a warning message is issued exactly after 2 minutes, however this only happens when the HTTP Client experiences inactivity. To reproduce this, you can simply use my shared project, run it and make an API call just like HTTP Client Micronaut Guide and wait for exactly 2 minutes; the warning message will appear.
   

Unexpected message on HTTP2 connection channel: DefaultHttp2GoAwayFrame(errorCode=0, content=UnpooledSlicedByteBuf(ridx: 0, widx: 0, cap: 0/0, unwrapped: PooledUnsafeDirectByteBuf(ridx: 17, widx: 17, cap: 46)), extraStreamIds=0, lastStreamId=9)

[graemerocher]

Have you tried the latest version of 4.1.x? There were some fixes to the connection pooling by @yawkat

[lucasgust]

@graemerocher no, I'm using version 4.0.2 in my production application. I will update to 4.1.1

however the Warning message after fixed time issue is happening in the latest version (4.1.1) as demonstrated in my example:
https://github.com/lucasgust/micronaut-reactive-http-client-with-coroutines

[graemerocher]

could you report an issue? Thank you