[CAMEL-9040] netty4-http - LEAK: ByteBuf.release() was not called before it's garbage-collected

• Type: Bug
• Status: Resolved
• Priority: Critical
• Resolution: Fixed
• Affects Version/s: 2.15.1, 2.15.2
• Fix Version/s: 2.18.0
• Component/s: camel-netty4-http

Environment

Karaf 3.0.3

• Estimated Complexity: Unknown
• Assignee: Claus Ibsen
• Reporter: Ralf Steppacher
• Created: 31/Jul/15 12:16
• Updated: 04/May/16 12:10
• Resolved: 04/May/16 12:10

Description

In a reverse-proxy with multiple routes that utilize the netty4-http component both as the consumer and producer I am receiving the following error:

2015-07-30 11:52:34,416 | ERROR | yServerTCPWorker | ResourceLeakDetector             | 97 - io.netty.common - 4.0.27.Final |   | LEAK: ByteBuf.release() was not called before it's garbage-collected. See http://netty.io/wiki/reference-counted-objects.html for more information.

Setting the Netty leak reporting to paranoid (-Dio.netty.leakDetectionLevel=paranoid) yields an error for almost every request (it probably is 1:1).
The stacktraces come in two variants. Variant 1 is far less frequent than variant 2.

Variant 1:

Recent access records: 0
Created at:
io.netty.buffer.CompositeByteBuf.<init>(CompositeByteBuf.java:60)
io.netty.buffer.Unpooled.compositeBuffer(Unpooled.java:353)
io.netty.handler.codec.http.HttpObjectAggregator.decode(HttpObjectAggregator.java:153)
io.netty.handler.codec.http.HttpObjectAggregator.decode(HttpObjectAggregator.java:54)
io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:89)
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:339)
io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:324)
io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:242)
io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:147)
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:339)
io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:324)
io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:847)
io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:131)
io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511)
io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)
io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)
io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354)
io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:111)
java.lang.Thread.run(Thread.java:745)

Variant 2:

Recent access records: 5
#5:
io.netty.buffer.AdvancedLeakAwareByteBuf.getBytes(AdvancedLeakAwareByteBuf.java:223)
io.netty.buffer.CompositeByteBuf.getBytes(CompositeByteBuf.java:684)
io.netty.buffer.CompositeByteBuf.getBytes(CompositeByteBuf.java:40)
io.netty.buffer.AbstractByteBuf.readBytes(AbstractByteBuf.java:677)
io.netty.buffer.CompositeByteBuf.readBytes(CompositeByteBuf.java:1493)
io.netty.buffer.CompositeByteBuf.readBytes(CompositeByteBuf.java:40)
io.netty.buffer.ByteBufInputStream.read(ByteBufInputStream.java:120)
java.io.BufferedInputStream.fill(BufferedInputStream.java:235)
java.io.BufferedInputStream.read1(BufferedInputStream.java:275)
java.io.BufferedInputStream.read(BufferedInputStream.java:334)
org.bouncycastle.util.io.TeeInputStream.read(Unknown Source)
com.ctc.wstx.io.BaseReader.readBytes(BaseReader.java:155)
com.ctc.wstx.io.UTF8Reader.loadMore(UTF8Reader.java:368)
com.ctc.wstx.io.UTF8Reader.read(UTF8Reader.java:111)
com.ctc.wstx.io.ReaderBootstrapper.initialLoad(ReaderBootstrapper.java:250)
com.ctc.wstx.io.ReaderBootstrapper.bootstrapInput(ReaderBootstrapper.java:133)
com.ctc.wstx.stax.WstxInputFactory.doCreateSR(WstxInputFactory.java:545)
com.ctc.wstx.stax.WstxInputFactory.createSR(WstxInputFactory.java:605)
com.ctc.wstx.stax.WstxInputFactory.createSR(WstxInputFactory.java:628)
com.ctc.wstx.stax.WstxInputFactory.createXMLStreamReader(WstxInputFactory.java:331)
ch.vivates.pep.stream.ResponseStatusFilter.filter(ResponseStatusFilter.java:41)
ch.vivates.pep.stream.BaseStreamFilter.run(BaseStreamFilter.java:141)
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
java.util.concurrent.FutureTask.run(FutureTask.java:262)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
java.lang.Thread.run(Thread.java:745)
#4:
io.netty.buffer.AdvancedLeakAwareByteBuf.release(AdvancedLeakAwareByteBuf.java:45)
io.netty.handler.codec.http.DefaultHttpContent.release(DefaultHttpContent.java:72)
io.netty.util.ReferenceCountUtil.release(ReferenceCountUtil.java:59)
io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:91)
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:339)
io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:324)
io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:242)
io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:147)
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:339)
io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:324)
io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:847)
io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:131)
io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511)
io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)
io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)
io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354)
io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:111)
java.lang.Thread.run(Thread.java:745)
#3:
io.netty.buffer.AdvancedLeakAwareByteBuf.slice(AdvancedLeakAwareByteBuf.java:73)
io.netty.buffer.CompositeByteBuf.addComponent0(CompositeByteBuf.java:170)
io.netty.buffer.CompositeByteBuf.addComponent(CompositeByteBuf.java:112)
io.netty.handler.codec.http.HttpObjectAggregator.decode(HttpObjectAggregator.java:191)
io.netty.handler.codec.http.HttpObjectAggregator.decode(HttpObjectAggregator.java:54)
io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:89)
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:339)
io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:324)
io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:242)
io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:147)
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:339)
io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:324)
io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:847)
io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:131)
io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511)
io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)
io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)
io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354)
io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:111)
java.lang.Thread.run(Thread.java:745)
#2:
io.netty.buffer.AdvancedLeakAwareByteBuf.order(AdvancedLeakAwareByteBuf.java:63)
io.netty.buffer.CompositeByteBuf.addComponent0(CompositeByteBuf.java:170)
io.netty.buffer.CompositeByteBuf.addComponent(CompositeByteBuf.java:112)
io.netty.handler.codec.http.HttpObjectAggregator.decode(HttpObjectAggregator.java:191)
io.netty.handler.codec.http.HttpObjectAggregator.decode(HttpObjectAggregator.java:54)
io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:89)
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:339)
io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:324)
io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:242)
io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:147)
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:339)
io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:324)
io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:847)
io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:131)
io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511)
io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)
io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)
io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354)
io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:111)
java.lang.Thread.run(Thread.java:745)
#1:
io.netty.buffer.AdvancedLeakAwareByteBuf.retain(AdvancedLeakAwareByteBuf.java:709)
io.netty.handler.codec.http.DefaultHttpContent.retain(DefaultHttpContent.java:60)
io.netty.handler.codec.http.HttpObjectAggregator.decode(HttpObjectAggregator.java:190)
io.netty.handler.codec.http.HttpObjectAggregator.decode(HttpObjectAggregator.java:54)
io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:89)
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:339)
io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:324)
io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:242)
io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:147)
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:339)
io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:324)
io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:847)
io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:131)
io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511)
io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)
io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)
io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354)
io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:111)
java.lang.Thread.run(Thread.java:745)
Created at:
io.netty.buffer.UnpooledByteBufAllocator.newDirectBuffer(UnpooledByteBufAllocator.java:55)
io.netty.buffer.AbstractByteBufAllocator.directBuffer(AbstractByteBufAllocator.java:155)
io.netty.buffer.AbstractByteBufAllocator.directBuffer(AbstractByteBufAllocator.java:146)
io.netty.buffer.AbstractByteBufAllocator.ioBuffer(AbstractByteBufAllocator.java:107)
io.netty.channel.AdaptiveRecvByteBufAllocator$HandleImpl.allocate(AdaptiveRecvByteBufAllocator.java:104)
io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:117)
io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511)
io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)
io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)
io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354)
io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:111)
java.lang.Thread.run(Thread.java:745)

Variant 2 creates the buffer in UnpooledByteBufAllocator. Which might mean that there is no real resource leak in that case. Rather the coding pattern required for objects that might be pooled is not adhered to.
Nevertheless, running my load tests just long enough yields an OOME Direct buffer memory:

org.apache.camel.CamelExecutionException: Exception occurred during execution on the exchange: Exchange[Message: [Body is instance of org.apache.camel.StreamCache]]
        at org.apache.camel.util.ObjectHelper.wrapCamelExecutionException(ObjectHelper.java:1635)[70:org.apache.camel.camel-core:2.15.2]
        at org.apache.camel.impl.DefaultExchange.setException(DefaultExchange.java:308)[70:org.apache.camel.camel-core:2.15.2]
        at org.apache.camel.component.netty4.handlers.ClientChannelHandler.exceptionCaught(ClientChannelHandler.java:81)[143:org.apache.camel.camel-netty4:2.15.2]
        at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:275)[138:io.netty.transport:4.0.27.Final]
        at io.netty.channel.AbstractChannelHandlerContext.fireExceptionCaught(AbstractChannelHandlerContext.java:253)[138:io.netty.transport:4.0.27.Final]
        at io.netty.channel.ChannelInboundHandlerAdapter.exceptionCaught(ChannelInboundHandlerAdapter.java:131)[138:io.netty.transport:4.0.27.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:275)[138:io.netty.transport:4.0.27.Final]
        at io.netty.channel.AbstractChannelHandlerContext.fireExceptionCaught(AbstractChannelHandlerContext.java:253)[138:io.netty.transport:4.0.27.Final]
        at io.netty.channel.ChannelInboundHandlerAdapter.exceptionCaught(ChannelInboundHandlerAdapter.java:131)[138:io.netty.transport:4.0.27.Final]
        at io.netty.channel.CombinedChannelDuplexHandler.exceptionCaught(CombinedChannelDuplexHandler.java:137)[138:io.netty.transport:4.0.27.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:275)[138:io.netty.transport:4.0.27.Final]
        at io.netty.channel.AbstractChannelHandlerContext.fireExceptionCaught(AbstractChannelHandlerContext.java:253)[138:io.netty.transport:4.0.27.Final]
        at io.netty.channel.DefaultChannelPipeline.fireExceptionCaught(DefaultChannelPipeline.java:835)[138:io.netty.transport:4.0.27.Final]
        at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.handleReadException(AbstractNioByteChannel.java:87)[138:io.netty.transport:4.0.27.Final]
        at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:162)[138:io.netty.transport:4.0.27.Final]
        at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511)[138:io.netty.transport:4.0.27.Final]
        at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)[138:io.netty.transport:4.0.27.Final]
        at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)[138:io.netty.transport:4.0.27.Final]
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354)[138:io.netty.transport:4.0.27.Final]
        at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:111)[137:io.netty.common:4.0.27.Final]
        at java.lang.Thread.run(Thread.java:745)[:1.7.0_60]
Caused by: java.lang.OutOfMemoryError: Direct buffer memory
        at java.nio.Bits.reserveMemory(Bits.java:658)[:1.7.0_60]
        at java.nio.DirectByteBuffer.<init>(DirectByteBuffer.java:123)[:1.7.0_60]
        at java.nio.ByteBuffer.allocateDirect(ByteBuffer.java:306)[:1.7.0_60]
        at io.netty.buffer.UnpooledUnsafeDirectByteBuf.allocateDirect(UnpooledUnsafeDirectByteBuf.java:108)[139:io.netty.buffer:4.0.27.Final]
        at io.netty.buffer.UnpooledUnsafeDirectByteBuf.<init>(UnpooledUnsafeDirectByteBuf.java:69)[139:io.netty.buffer:4.0.27.Final]
        at io.netty.buffer.UnpooledByteBufAllocator.newDirectBuffer(UnpooledByteBufAllocator.java:50)[139:io.netty.buffer:4.0.27.Final]
        at io.netty.buffer.AbstractByteBufAllocator.directBuffer(AbstractByteBufAllocator.java:155)[139:io.netty.buffer:4.0.27.Final]
        at io.netty.buffer.AbstractByteBufAllocator.directBuffer(AbstractByteBufAllocator.java:146)[139:io.netty.buffer:4.0.27.Final]
        at io.netty.buffer.AbstractByteBufAllocator.ioBuffer(AbstractByteBufAllocator.java:107)[139:io.netty.buffer:4.0.27.Final]
        at io.netty.channel.AdaptiveRecvByteBufAllocator$HandleImpl.allocate(AdaptiveRecvByteBufAllocator.java:104)[138:io.netty.transport:4.0.27.Final]
        at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:117)[138:io.netty.transport:4.0.27.Final]
        ... 6 more

This is one of the routes that trigger the error:

<route id="pep-xds_b-registry">
	<from uri="netty4-http:http://{{pep.host}}:{{pep.xds.b.registry.port}}/XDS3/registry?matchOnUriPrefix=true&amp;disableStreamCache=true" />
	<process ref="registryInboundProcessor" />
	<to uri="netty4-http:http://{{xds.b.registry.host}}:{{xds.b.registry.port}}/XDS3/registry?bridgeEndpoint=true&amp;throwExceptionOnFailure=false&amp;chunkedMaxContentLength={{pep.xds.b.registry.max.message.size}}&amp;disableStreamCache=false" />
	<!-- Unfortunately disabling the stream cache only works for requests, but not responses: https://issues.apache.org/jira/browse/CAMEL-7638 -->
	<process ref="registryOutboundProcessor" />
</route>

Issue Links

• relates to: CAMEL-8899 netty4-http - Got a warn about leak detection
• relates to: CAMEL-9940 ProducerTemplate - Make extract result set part of UoW