IllegalReferenceCountException when using sendObject

[pderop]

When an HTTP2 reactor-netty server is using sendObject when returning the response, sometimes, we see this exception on the server:

12:53:50.905 [reactor-http-nio-1] WARN  i.n.channel.DefaultChannelPipeline - An exceptionCaught() event was fired, and it reached at the tail of the pipeline. It usually means the last handler in the pipeline did not handle the exception.
io.netty.util.IllegalReferenceCountException: refCnt: 0
    at io.netty.buffer.AbstractByteBuf.ensureAccessible(AbstractByteBuf.java:1454)
    at io.netty.buffer.AbstractByteBuf.checkIndex(AbstractByteBuf.java:1383)
    at io.netty.buffer.PooledByteBuf.internalNioBuffer(PooledByteBuf.java:203)
    at io.netty.handler.ssl.SslHandler.wrap(SslHandler.java:1026)
    at io.netty.handler.ssl.SslHandler.wrap(SslHandler.java:829)
    at io.netty.handler.ssl.SslHandler.wrapAndFlush(SslHandler.java:800)
    at io.netty.handler.ssl.SslHandler.flush(SslHandler.java:781)
    at io.netty.channel.AbstractChannelHandlerContext.invokeFlush0(AbstractChannelHandlerContext.java:925)
    at io.netty.channel.AbstractChannelHandlerContext.invokeFlush(AbstractChannelHandlerContext.java:907)
    at io.netty.channel.AbstractChannelHandlerContext.flush(AbstractChannelHandlerContext.java:893)
    at io.netty.handler.logging.LoggingHandler.flush(LoggingHandler.java:304)
    at io.netty.channel.AbstractChannelHandlerContext.invokeFlush0(AbstractChannelHandlerContext.java:923)
    at io.netty.channel.AbstractChannelHandlerContext.invokeFlush(AbstractChannelHandlerContext.java:907)
    at io.netty.channel.AbstractChannelHandlerContext.flush(AbstractChannelHandlerContext.java:893)
    at io.netty.handler.codec.http2.Http2ConnectionHandler.flush(Http2ConnectionHandler.java:197)
    at io.netty.handler.codec.http2.Http2ConnectionHandler.channelReadComplete(Http2ConnectionHandler.java:555)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelReadComplete(AbstractChannelHandlerContext.java:486)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelReadComplete(AbstractChannelHandlerContext.java:463)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelReadComplete(AbstractChannelHandlerContext.java:456)
    at reactor.netty.tcp.SslProvider$SslReadHandler.channelReadComplete(SslProvider.java:842)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelReadComplete(AbstractChannelHandlerContext.java:486)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelReadComplete(AbstractChannelHandlerContext.java:463)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelReadComplete(AbstractChannelHandlerContext.java:456)
    at io.netty.handler.logging.LoggingHandler.channelReadComplete(LoggingHandler.java:272)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelReadComplete(AbstractChannelHandlerContext.java:484)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelReadComplete(AbstractChannelHandlerContext.java:463)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelReadComplete(AbstractChannelHandlerContext.java:456)
    at io.netty.handler.ssl.SslHandler.channelReadComplete0(SslHandler.java:1313)
    at io.netty.handler.ssl.SslHandler.channelReadComplete(SslHandler.java:1302)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelReadComplete(AbstractChannelHandlerContext.java:486)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelReadComplete(AbstractChannelHandlerContext.java:463)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelReadComplete(AbstractChannelHandlerContext.java:456)
    at io.netty.channel.DefaultChannelPipeline$HeadContext.channelReadComplete(DefaultChannelPipeline.java:1415)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelReadComplete(AbstractChannelHandlerContext.java:482)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelReadComplete(AbstractChannelHandlerContext.java:463)
    at io.netty.channel.DefaultChannelPipeline.fireChannelReadComplete(DefaultChannelPipeline.java:925)
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:171)
    at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562)
    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:1589)

Expected Behavior

Actual Behavior

Steps to Reproduce

static Consumer<? super HttpServerRoutes> routesBuilder() {
    return r -> r.get("/user/{id}", findUser());
    }

static BiFunction<HttpServerRequest, HttpServerResponse, Publisher<Void>> findUser() {
    return (req, res) ->
            res.header("Content-Type", "application/json")
                    .sendObject(toByteBuf(new User(req.param("id"), "Ben Chmark")));
}

See attached reproducer.tgz: reproducer.tgz

To reproduce:

• Use java 19

• ./gradlew build

• from one console, start the frontend server (using java19): java -DPROTOCOL=H2 -jar frontend-rn-11x/build/libs/frontend-rn-11x-1.0.0.jar

• from another console, start gatling (using java19): java -DPROTOCOL=H2 -DDURATION=20 -jar gatling/build/libs/gatling-1.0.0-all.jar application “H2 simulation / JsonGet” JsonGet

You should then see the IllegalReferenceCountException from the frontend console.

Analysis:

sometimes, it seems that we are facing this situation:

• A buffer is currently present in the SSLHandler.pendingUnencryptedWrites data structure here.
• Then, the buffer is released by HttpOperations here, line 491. This is because the stream is being cancelled/closed from this stacktrace:

 "reactor.netty.http.HttpOperations$PostHeadersNettyOutbound.run(HttpOperations.java:491)"
 "reactor.core.publisher.FluxPeekFuseable$PeekFuseableSubscriber.cancel(FluxPeekFuseable.java:152)"
 "reactor.core.publisher.Operators.terminate(Operators.java:1277)"
 "reactor.netty.channel.ChannelOperations.terminate(ChannelOperations.java:481)"
 "reactor.netty.http.server.HttpServerOperations.onInboundClose(HttpServerOperations.java:677)"
 "reactor.netty.channel.ChannelOperationsHandler.channelInactive(ChannelOperationsHandler.java:73)"
 "io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:305)"
 "io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:281)"
 "io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:274)"
 "io.netty.channel.DefaultChannelPipeline$HeadContext.channelInactive(DefaultChannelPipeline.java:1405)"
 "io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:301)"
 "io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:281)"
 "io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:901)"
 "io.netty.handler.codec.http2.AbstractHttp2StreamChannel$Http2ChannelUnsafe$2.run(AbstractHttp2StreamChannel.java:737)"
 "io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java:174)"
 "io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:167)"
 "io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:470)"
 "io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:566)"
 "io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)"
 "io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)"
 "io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)"
 "java.base/java.lang.Thread.run(Thread.java:1589)"

In fact, the above stack trace is triggered by this one (the stream is being closed):

fireChannelInactiveAndDeregister:733, AbstractHttp2StreamChannel$Http2ChannelUnsafe (io.netty.handler.codec.http2)
close:702, AbstractHttp2StreamChannel$Http2ChannelUnsafe (io.netty.handler.codec.http2)
closeForcibly:707, AbstractHttp2StreamChannel$Http2ChannelUnsafe (io.netty.handler.codec.http2)
doBeginRead:805, AbstractHttp2StreamChannel$Http2ChannelUnsafe (io.netty.handler.codec.http2)
streamClosed:299, AbstractHttp2StreamChannel (io.netty.handler.codec.http2)
userEventTriggered:249, Http2MultiplexHandler (io.netty.handler.codec.http2)
invokeUserEventTriggered:398, AbstractChannelHandlerContext (io.netty.channel)
invokeUserEventTriggered:376, AbstractChannelHandlerContext (io.netty.channel)
fireUserEventTriggered:368, AbstractChannelHandlerContext (io.netty.channel)
onHttp2StreamStateChanged:703, Http2FrameCodec (io.netty.handler.codec.http2)
onHttp2StreamStateChanged0:524, Http2FrameCodec$ConnectionListener (io.netty.handler.codec.http2)
onStreamClosed:513, Http2FrameCodec$ConnectionListener (io.netty.handler.codec.http2)
notifyClosed:357, DefaultHttp2Connection (io.netty.handler.codec.http2)
removeFromActiveStreams:1007, DefaultHttp2Connection$ActiveStreams (io.netty.handler.codec.http2)
deactivate:963, DefaultHttp2Connection$ActiveStreams (io.netty.handler.codec.http2)
close:515, DefaultHttp2Connection$DefaultStream (io.netty.handler.codec.http2)
close:521, DefaultHttp2Connection$DefaultStream (io.netty.handler.codec.http2)
closeStream:628, Http2ConnectionHandler (io.netty.handler.codec.http2)
closeStreamLocal:601, Http2ConnectionHandler (io.netty.handler.codec.http2)
writeComplete:623, DefaultHttp2ConnectionEncoder$FlowControlledBase (io.netty.handler.codec.http2)
writeAllocatedBytes:368, DefaultHttp2RemoteFlowController$FlowState (io.netty.handler.codec.http2)
write:547, DefaultHttp2RemoteFlowController$WritabilityMonitor (io.netty.handler.codec.http2)
write:612, WeightedFairQueueByteDistributor$State (io.netty.handler.codec.http2)
distribute:292, WeightedFairQueueByteDistributor (io.netty.handler.codec.http2)
distributeToChildren:325, WeightedFairQueueByteDistributor (io.netty.handler.codec.http2)
distribute:273, WeightedFairQueueByteDistributor (io.netty.handler.codec.http2)
writePendingBytes:627, DefaultHttp2RemoteFlowController$WritabilityMonitor (io.netty.handler.codec.http2)
writePendingBytes:267, DefaultHttp2RemoteFlowController (io.netty.handler.codec.http2)
flush:196, Http2ConnectionHandler (io.netty.handler.codec.http2)
invokeFlush0:925, AbstractChannelHandlerContext (io.netty.channel)
invokeFlush:907, AbstractChannelHandlerContext (io.netty.channel)
flush:893, AbstractChannelHandlerContext (io.netty.channel)
processPendingReadCompleteQueue:349, Http2MultiplexHandler (io.netty.handler.codec.http2)
channelReadComplete:330, Http2MultiplexHandler (io.netty.handler.codec.http2)
invokeChannelReadComplete:484, AbstractChannelHandlerContext (io.netty.channel)
invokeChannelReadComplete:463, AbstractChannelHandlerContext (io.netty.channel)
fireChannelReadComplete:456, AbstractChannelHandlerContext (io.netty.channel)
channelReadComplete0:570, Http2ConnectionHandler (io.netty.handler.codec.http2)
channelReadComplete:553, Http2ConnectionHandler (io.netty.handler.codec.http2)
invokeChannelReadComplete:486, AbstractChannelHandlerContext (io.netty.channel)
invokeChannelReadComplete:463, AbstractChannelHandlerContext (io.netty.channel)
fireChannelReadComplete:456, AbstractChannelHandlerContext (io.netty.channel)
channelReadComplete:272, LoggingHandler (io.netty.handler.logging)
invokeChannelReadComplete:484, AbstractChannelHandlerContext (io.netty.channel)
invokeChannelReadComplete:463, AbstractChannelHandlerContext (io.netty.channel)
fireChannelReadComplete:456, AbstractChannelHandlerContext (io.netty.channel)
channelReadComplete0:1329, SslHandler (io.netty.handler.ssl)
channelReadComplete:1318, SslHandler (io.netty.handler.ssl)
invokeChannelReadComplete:486, AbstractChannelHandlerContext (io.netty.channel)
invokeChannelReadComplete:463, AbstractChannelHandlerContext (io.netty.channel)
fireChannelReadComplete:456, AbstractChannelHandlerContext (io.netty.channel)
channelReadComplete:1415, DefaultChannelPipeline$HeadContext (io.netty.channel)
invokeChannelReadComplete:482, AbstractChannelHandlerContext (io.netty.channel)
invokeChannelReadComplete:463, AbstractChannelHandlerContext (io.netty.channel)
fireChannelReadComplete:925, DefaultChannelPipeline (io.netty.channel)
read:171, AbstractNioByteChannel$NioByteUnsafe (io.netty.channel.nio)
processSelectedKey:788, NioEventLoop (io.netty.channel.nio)
processSelectedKeysOptimized:724, NioEventLoop (io.netty.channel.nio)
processSelectedKeys:650, NioEventLoop (io.netty.channel.nio)
run:562, NioEventLoop (io.netty.channel.nio)
run:997, SingleThreadEventExecutor$4 (io.netty.util.concurrent)
run:74, ThreadExecutorMap$2 (io.netty.util.internal)
run:30, FastThreadLocalRunnable (io.netty.util.concurrent)
run:1589, Thread (java.lang)

• So, the buffer is released at HttpOperations.java:491, but the buffer has already been written to the channel (either here or here:), but is not yet flushed and still present in the SSLHandler.pendingUnencryptedWrites data structure

• Finally, when SSLHandler.flush is called after channelReadComplete, then it gets the IllegalReferenceCountException when accessing to the buffer from the pendingUnencryptedWrites data structure, because the buffer has already been released at HttpOperations.java:491

Possible Solution

Your Environment

• Reactor version(s) used: latest 1.0.x branch
• JVM version: 19

[pderop]

This issue is resolved by https://github.com/netty/netty/pull/13388, but I keep this issue opened because I will add some tests in reactor-netty for this issue.