WebClient using default reactor-netty client leaks netty ByteBufs on timeout

[danielra]

Affects: 5.1.4.RELEASE

I see buffer leak reports from Netty's ResourceLeakDetector when a Mono.timeout cancels a subscription to the Mono returned from bodyToMono. I've created a demo project with a test case which seems to reliably reproduce the issue. A separate test case is included which uses the reactor-netty HttpClient directly instead of using it through the WebClient wrapper - and I have not seen any leak reports in this case with the current version of reactor-netty (v0.8.4.RELEASE).

Demo project with mentioned test cases can be found here:
https://github.com/danielra/buffer-leak-repro-reactor-netty
The specific test case which reproduces the leak can be seen here:
https://github.com/danielra/buffer-leak-repro-reactor-netty/blob/master/src/test/java/com/example/demo/DemoApplicationTests.java#L59

The tests can be run via ./gradlew clean test --debug. Please note that the tests "pass" unconditionally, but buffer leak reports can be viewed in the console output.

Here is an example of the leak report log messages I have observed from this test case:
webclient_buffer_leak_example_log.txt

---

[rstoyanchev]

Thanks for the report. This has been tagged as Reactor Netty issue. Please follow reactor/reactor-netty#603.

[danielra]

Thanks. I will follow that issue as you suggest. Interesting that the issue here is actually with reactor-netty, when the problem doesn't seem to reproduce when using their HttpClient directly - only when using reactor-netty indirectly via WebClient. Thanks for looking into it and forwarding appropriately!

[rstoyanchev]

Interesting that the issue here is actually with reactor-netty, when the problem doesn't seem to reproduce when using their HttpClient directly - only when using reactor-netty indirectly via WebClient.

Are you sure about this? I see the exact opposite. When I run the tests with @Ignore on reproBufferLeakOnTimeout I see the leaks, or vice versa if i put @Ignore on noReproBufferLeakOnTimeout the leak reports go away.

This is also supported by looking at the source code. The Reactor Netty ByteBufFlux#aggregate is accumulating and retains without provisions for cancellation. By contrast the StringDecoder does use onDiscard.

So as far as I can see we're okay in the Spring Framework. /cc @violetagg

[violetagg]

@rstoyanchev I'm not able to reproduce the issue.

Only these exceptions appear in the log files

1. Handle "IllegalReferenceCountException: refCnt: 0, decrement: 1" when ByteBufFlux#aggregate reactor/reactor-netty#636

io.netty.util.IllegalReferenceCountException: refCnt: 0
	at io.netty.buffer.AbstractByteBuf.ensureAccessible(AbstractByteBuf.java:1441)
	at io.netty.buffer.AbstractByteBuf.checkIndex(AbstractByteBuf.java:1373)
	at io.netty.buffer.PooledHeapByteBuf.nioBuffer(PooledHeapByteBuf.java:298)
	at io.netty.buffer.AbstractByteBuf.nioBuffer(AbstractByteBuf.java:1224)
	at org.springframework.core.io.buffer.NettyDataBuffer.asByteBuffer(NettyDataBuffer.java:266)
	at org.springframework.core.codec.StringDecoder.decodeDataBuffer(StringDecoder.java:207)
	at org.springframework.core.codec.StringDecoder.decodeDataBuffer(StringDecoder.java:59)
	at org.springframework.core.codec.AbstractDataBufferDecoder.lambda$decodeToMono$1(AbstractDataBufferDecoder.java:68)
	at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onNext(FluxMapFuseable.java:107)
	at reactor.core.publisher.FluxContextStart$ContextStartSubscriber.onNext(FluxContextStart.java:103)
	at reactor.core.publisher.FluxMapFuseable$MapFuseableConditionalSubscriber.onNext(FluxMapFuseable.java:287)
	at reactor.core.publisher.FluxFilterFuseable$FilterFuseableConditionalSubscriber.onNext(FluxFilterFuseable.java:331)
	at reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:1505)
	at reactor.core.publisher.MonoCollectList$MonoBufferAllSubscriber.onComplete(MonoCollectList.java:123)
	at reactor.core.publisher.FluxMap$MapSubscriber.onComplete(FluxMap.java:136)
	at reactor.core.publisher.FluxPeek$PeekSubscriber.onComplete(FluxPeek.java:252)
	at reactor.core.publisher.FluxPeek$PeekSubscriber.onComplete(FluxPeek.java:252)
	at reactor.core.publisher.FluxMap$MapSubscriber.onComplete(FluxMap.java:136)
	at reactor.netty.channel.FluxReceive.terminateReceiver(FluxReceive.java:372)
	at reactor.netty.channel.FluxReceive.drainReceiver(FluxReceive.java:196)
	at reactor.netty.channel.FluxReceive.onInboundComplete(FluxReceive.java:337)
	at reactor.netty.channel.ChannelOperations.onInboundComplete(ChannelOperations.java:334)
	at reactor.netty.channel.ChannelOperations.terminate(ChannelOperations.java:384)
	at reactor.netty.http.client.HttpClientOperations.onInboundNext(HttpClientOperations.java:522)
	at reactor.netty.channel.ChannelOperationsHandler.channelRead(ChannelOperationsHandler.java:141)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:359)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:345)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:337)
	at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:102)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:359)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:345)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:337)
	at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:438)
	at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:323)
	at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:297)
	at io.netty.channel.CombinedChannelDuplexHandler.chan
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:359)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:345)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:337)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1408)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:359)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:345)
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:930)
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:163)
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:677)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:612)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:529)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:491)
	at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:905)
	at java.base/java.lang.Thread.run(Thread.java:834)

I'm using Netty 4.1.34.Final and Reactor Netty 0.8.6.BUILD-SNAPSHOT

[danielra]

I just took another look at this. I've upgraded the spring-boot version from 2.1.2.RELEASE to 2.1.3.RELEASE, and thus spring-framework 5.1.5.RELEASE and reactor-netty 0.8.5.RELEASE.

It looks like I may have just gotten "lucky" in my initial runs of my test cases and only happened to see leak reports when running the one that uses the WebClient. I do still see leak messages emitted when running both test cases (but only sometimes).

I ran the following 20 times (running just the test case which uses a WebClient which uses reactor-netty):

./gradlew clean test --debug --tests com.example.demo.DemoApplicationTests.webClient

and here is the output from the 6 of those times where leak reports were emitted:
webclient-test-log-with-leak_1.txt
webclient-test-log-with-leak_2.txt
webclient-test-log-with-leak_3.txt
webclient-test-log-with-leak_4.txt
webclient-test-log-with-leak_5.txt
webclient-test-log-with-leak_6.txt

I ran the following 20 times (running just the test case which uses reactor-netty directly):

./gradlew clean test --debug --tests com.example.demo.DemoApplicationTests.reactorNetty

and here is the output from the 4 of those times where leak reports were emitted:
reactor-netty-test-log-with-leak_1.txt
reactor-netty-test-log-with-leak_2.txt
reactor-netty-test-log-with-leak_3.txt
reactor-netty-test-log-with-leak_4.txt

There is some variety to the leak reports. One general observation is that in the direct reactor-netty cases, the leak reports were always accompanied by IllegalReferenceCountExceptions like the one noted above. In contrast, none of the WebClient test runs which emitted leak reports contained this exception (though I did see this exception on a few runs which did not emit leak reports). I don't know whether this detail is a coincident or not.

I've pushed a few minor changes to the test cases along with the version update noted above.

[rstoyanchev]

I'm using Netty 4.1.34.Final and Reactor Netty 0.8.6.BUILD-SNAPSHOT

@danielra did you notice the versions mentioned? Can you also try with:

ext['reactor-bom.version'] = 'Californium-BUILD-SNAPSHOT'

[danielra]

Thank you for calling that out! I did miss updating that version. I have done so now (and pushed the change), and on my first attempt with the webClient test, I observed this leak report emitted via:

./gradlew clean test --debug --tests com.example.demo.DemoApplicationTests.webClient

webclient-test-log-with-leak-updated-reactor_1.txt
It took a few runs, but I also observed a leak report in the test case that uses the reactor-netty client directly via:

./gradlew clean test --debug --tests com.example.demo.DemoApplicationTests.reactorNetty

reactor-netty-test-log-with-leak-updated-reactor_1.txt

FWIW, the pattern of correlation with IllegalReferenceCountExceptions occurring when leak reports are emitted by the direct reactorNetty test (but not in the webClient test) persisted.