Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

HttpObjectAggregator could possibly leak in some conditions #5631

Closed
Spikhalskiy opened this issue Aug 4, 2016 · 7 comments
Closed

HttpObjectAggregator could possibly leak in some conditions #5631

Spikhalskiy opened this issue Aug 4, 2016 · 7 comments
Assignees
@Scottmitch

Comments

@Spikhalskiy
Copy link
Contributor

Spikhalskiy commented Aug 4, 2016 •
edited

Hi,

I am getting messages about buffer leaks in netty server very rarely, like once in 4-6 hours. And it looks like from advanced logging info that HttpObjectAggregator could not release buffer sometimes. My assumption - it could be related to closing idle connection while HttpObjectAggregator has something cached inside and HttpObjectAggregator doesn't release it correctly.

This is how my pipeline looks like:

        p.addLast("idleState", new IdleStateHandler(0, 0, idleChannelTimeOutSec));
        p.addLast("httpCodec", new HttpServerCodec());
        p.addLast("unGzip", new HttpContentDecompressor());
        p.addLast("httpAggregator", new HttpObjectAggregator(64 * 1024));
        p.addLast("handler", mainHandler);

mainHandler has

    @Override
    public void channelRead(ChannelHandlerContext ctx, Object msg) throws Exception {
        try {
            ...
        } finally {
            ReferenceCountUtil.release(msg);
        }
    }

This is how cleaned up version of log looks like:

[03 Aug 2016 18:44:55,952][ERROR][ResourceLeakDetector,httpServerWorker-4-1] - LEAK: ByteBuf.release() was not called before it's garbage-collected. See http://netty.io/wiki/reference-counted-objects.html for more information.
Recent access records: 13
#13:
    io.netty.buffer.AdvancedLeakAwareByteBuf.release(AdvancedLeakAwareByteBuf.java:61)
    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:90)
    io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
    io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:334)
    io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:327)
    io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:435)
    io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:293)
    io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:267)
    io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:250)
    io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
    io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:334)
    io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:327)
    io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86)
    io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
    io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:334)
    io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:327)
    io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1279)
    io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
    io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:334)
    io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:889)
    io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:131)
    io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:572)
    io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:513)
    io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:427)
    io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:399)
    io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:136)
    io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:145)
    java.lang.Thread.run(Thread.java:745)

#10:
    io.netty.buffer.AdvancedLeakAwareByteBuf.retain(AdvancedLeakAwareByteBuf.java:731)
    io.netty.handler.codec.http.DefaultHttpContent.retain(DefaultHttpContent.java:60)
    io.netty.handler.codec.http.HttpObjectAggregator.decode(HttpObjectAggregator.java:225)
    io.netty.handler.codec.http.HttpObjectAggregator.decode(HttpObjectAggregator.java:57)
    io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:88)
    io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
    io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:334)
    io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:327)
    io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:435)
    io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:293)
    io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:267)
    io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:250)
    io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
    io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:334)
    io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:327)
    io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86)
    io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
    io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:334)
    io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:327)
    io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1279)
    io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
    io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:334)
    io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:889)
    io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:131)
    io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:572)
    io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:513)
    io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:427)
    io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:399)
    io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:136)
    io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:145)
    java.lang.Thread.run(Thread.java:745)
#9:
    io.netty.buffer.AdvancedLeakAwareByteBuf.release(AdvancedLeakAwareByteBuf.java:61)
    io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:256)
    io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:250)
    io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
    io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:334)
    io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:327)
    io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86)
    io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
    io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:334)
    io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:327)
    io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1279)
    io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
    io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:334)
    io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:889)
    io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:131)
    io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:572)
    io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:513)
    io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:427)
    io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:399)
    io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:136)
    io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:145)
    java.lang.Thread.run(Thread.java:745)
#8:
    io.netty.buffer.AdvancedLeakAwareByteBuf.retain(AdvancedLeakAwareByteBuf.java:731)
    io.netty.handler.codec.http.HttpObjectDecoder.decode(HttpObjectDecoder.java:347)
    io.netty.handler.codec.http.HttpClientCodec$Decoder.decode(HttpClientCodec.java:152)
    io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:411)
    io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:248)
    io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:250)
    io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
    io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:334)
    io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:327)
    io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86)
    io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
    io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:334)
    io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:327)
    io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1279)
    io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
    io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:334)
    io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:889)
    io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:131)
    io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:572)
    io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:513)
    io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:427)
    io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:399)
    io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:136)
    io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:145)
    java.lang.Thread.run(Thread.java:745)

Full advanced logs: log1.txt log2.txt.

If this info would not be enough for troubleshooting I would try to write a handler that will analyse/log this situation more deeply when I get a chance.
Or, please, let me know if it looks like a mistake in user code, but for me it doesn't.

Netty version 4.0.38
@Scottmitch
Copy link
Member

thanks for reporting @Spikhalskiy ! will look soon

@Scottmitch Scottmitch self-assigned this Aug 4, 2016
@Scottmitch
Copy link
Member

@Spikhalskiy - do you get any requests of type 100? also do you get any requests that exceed the maximum content length? are you able to reproduce the conditions that cause the leak?

@Spikhalskiy
Copy link
Contributor Author

Spikhalskiy commented Aug 5, 2016 •
edited

do you get any requests of type 100?

Yes, we have some % of requests of type "100 Continue".

do you get any requests that exceed the maximum content length?

No, we don't get TooLongFrameException in mainHandler.

are you able to reproduce the conditions that cause the leak?

No, I don't know which specific request or condition causing this leak. If it's hard to get into this problem with already provided info I would think about a way of collecting more data.

@Spikhalskiy
Copy link
Contributor Author

Spikhalskiy commented Aug 5, 2016 •
edited

BTW, more info, that could be related. We had a bug that we returned

if (HttpHeaders.is100ContinueExpected(request)) {
    send100Continue(ctx);
}

in the mainHandler AFTER HttpObjectAggregator, which already does this. And looks like our clients failed after receiving this second "continue". After fixing this bug (removing this code from mainHandler) I didn't see leaks anymore, so it looks like something possibly related, or just by chance and I will see leak soon (this bug fixed just yesterday).

On the same time, I don't get how it could be related because we sent this second continue in mainHandler, which have release() inside channelRead and we should see this release in advanced logs, but we don't. So, it shouldn't be that cases when we send this second continue.

Just a stream of thoughts, that probably could be useful for you.

@Scottmitch
Copy link
Member

Scottmitch commented Aug 5, 2016 •
edited

The HttpObjectAggregator owns the responsibility to send a 100 continue response (because it aggregates and knows the limit on how much data you want to accept). Your peer may get confused if you send 2 continue responses. I will throw together a PR which tightens up the release related stuff in HttpObjectAggregator and ping you when ready.

@Spikhalskiy
Copy link
Contributor Author

@Scottmitch yep, I already got it and bug with double continue fixed now in our server. Thanks for your work, waiting.

@Scottmitch Scottmitch mentioned this issue Aug 10, 2016
Closed
@Spikhalskiy
Copy link
Contributor Author

Closed by #5676

@Scottmitch Scottmitch mentioned this issue Oct 21, 2016
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@Scottmitch Scottmitch

Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@Spikhalskiy @Scottmitch