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

HTTP/2 InboundHttp2ToHttpAdapter Leak #4780

Closed
Scottmitch opened this issue Jan 28, 2016 · 8 comments
Closed

HTTP/2 InboundHttp2ToHttpAdapter Leak #4780

Scottmitch opened this issue Jan 28, 2016 · 8 comments
Assignees
@Scottmitch
Labels
defect
Milestone
4.1.0.CR3

Comments

@Scottmitch
Copy link
Member

PR #4774 uncovered a leak in the HTTP/2 codec.

Running io.netty.handler.codec.http2.InboundHttp2ToHttpAdapterTest
21:47:12.267 [defaultEventLoopGroup-49-1] DEBUG i.n.u.i.JavassistTypeParameterMatcherGenerator - Generated: io.netty.util.internal.__matchers__.io.netty.handler.codec.http.HttpObjectMatcher
21:47:12.270 [defaultEventLoopGroup-48-2] DEBUG i.n.u.i.JavassistTypeParameterMatcherGenerator - Generated: io.netty.util.internal.__matchers__.io.netty.handler.codec.http2.Http2SettingsMatcher
21:47:12.292 [defaultEventLoopGroup-49-1] DEBUG io.netty.buffer.PoolThreadCache - Freed 2 thread-local buffer(s) from thread: defaultEventLoopGroup-49-1
21:47:12.307 [defaultEventLoopGroup-50-2] DEBUG io.netty.buffer.PoolThreadCache - Freed 1 thread-local buffer(s) from thread: defaultEventLoopGroup-50-2
21:47:12.318 [defaultEventLoopGroup-51-1] DEBUG io.netty.buffer.PoolThreadCache - Freed 4 thread-local buffer(s) from thread: defaultEventLoopGroup-51-1
21:47:12.327 [defaultEventLoopGroup-52-2] DEBUG io.netty.buffer.PoolThreadCache - Freed 1 thread-local buffer(s) from thread: defaultEventLoopGroup-52-2
21:47:12.334 [defaultEventLoopGroup-53-1] DEBUG io.netty.buffer.PoolThreadCache - Freed 3 thread-local buffer(s) from thread: defaultEventLoopGroup-53-1
21:47:12.347 [defaultEventLoopGroup-54-2] DEBUG io.netty.buffer.PoolThreadCache - Freed 1 thread-local buffer(s) from thread: defaultEventLoopGroup-54-2
21:47:12.348 [defaultEventLoopGroup-55-1] DEBUG io.netty.buffer.PoolThreadCache - Freed 2 thread-local buffer(s) from thread: defaultEventLoopGroup-55-1
21:47:12.395 [defaultEventLoopGroup-56-2] DEBUG io.netty.buffer.PoolThreadCache - Freed 6 thread-local buffer(s) from thread: defaultEventLoopGroup-56-2
21:47:12.398 [defaultEventLoopGroup-57-1] DEBUG io.netty.buffer.PoolThreadCache - Freed 5 thread-local buffer(s) from thread: defaultEventLoopGroup-57-1
21:47:12.420 [defaultEventLoopGroup-58-2] DEBUG io.netty.buffer.PoolThreadCache - Freed 1 thread-local buffer(s) from thread: defaultEventLoopGroup-58-2
21:47:12.423 [defaultEventLoopGroup-59-1] DEBUG io.netty.buffer.PoolThreadCache - Freed 2 thread-local buffer(s) from thread: defaultEventLoopGroup-59-1
21:47:12.441 [defaultEventLoopGroup-61-1] DEBUG io.netty.buffer.PoolThreadCache - Freed 2 thread-local buffer(s) from thread: defaultEventLoopGroup-61-1
21:47:12.441 [defaultEventLoopGroup-60-2] DEBUG io.netty.buffer.PoolThreadCache - Freed 1 thread-local buffer(s) from thread: defaultEventLoopGroup-60-2
21:47:12.467 [defaultEventLoopGroup-62-2] DEBUG io.netty.buffer.PoolThreadCache - Freed 1 thread-local buffer(s) from thread: defaultEventLoopGroup-62-2
21:47:12.468 [defaultEventLoopGroup-63-1] DEBUG io.netty.buffer.PoolThreadCache - Freed 5 thread-local buffer(s) from thread: defaultEventLoopGroup-63-1
21:47:12.485 [defaultEventLoopGroup-64-2] DEBUG io.netty.buffer.PoolThreadCache - Freed 3 thread-local buffer(s) from thread: defaultEventLoopGroup-64-2
21:47:12.487 [defaultEventLoopGroup-65-1] DEBUG io.netty.buffer.PoolThreadCache - Freed 4 thread-local buffer(s) from thread: defaultEventLoopGroup-65-1
21:47:12.498 [defaultEventLoopGroup-67-1] DEBUG io.netty.buffer.PoolThreadCache - Freed 1 thread-local buffer(s) from thread: defaultEventLoopGroup-67-1
21:47:13.189 [defaultEventLoopGroup-69-1] ERROR io.netty.util.ResourceLeakDetector - 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: 0
Created at:
    io.netty.buffer.PooledByteBufAllocator.newDirectBuffer(PooledByteBufAllocator.java:271)
    io.netty.buffer.AbstractByteBufAllocator.directBuffer(AbstractByteBufAllocator.java:179)
    io.netty.buffer.AbstractByteBufAllocator.directBuffer(AbstractByteBufAllocator.java:165)
    io.netty.buffer.AbstractByteBufAllocator.buffer(AbstractByteBufAllocator.java:99)
    io.netty.handler.codec.http2.HttpConversionUtil.toHttpRequest(HttpConversionUtil.java:231)
    io.netty.handler.codec.http2.InboundHttp2ToHttpAdapter.newMessage(InboundHttp2ToHttpAdapter.java:128)
    io.netty.handler.codec.http2.InboundHttp2ToHttpAdapter.processHeadersBegin(InboundHttp2ToHttpAdapter.java:160)
    io.netty.handler.codec.http2.InboundHttp2ToHttpPriorityAdapter.processHeadersBegin(InboundHttp2ToHttpPriorityAdapter.java:138)
    io.netty.handler.codec.http2.InboundHttp2ToHttpAdapter.onHeadersRead(InboundHttp2ToHttpAdapter.java:229)
    io.netty.handler.codec.http2.Http2TestUtil$FrameAdapter$1.onHeadersRead(Http2TestUtil.java:155)
    io.netty.handler.codec.http2.DefaultHttp2FrameReader$2.processFragment(DefaultHttp2FrameReader.java:466)
    io.netty.handler.codec.http2.DefaultHttp2FrameReader.readHeadersFrame(DefaultHttp2FrameReader.java:474)
    io.netty.handler.codec.http2.DefaultHttp2FrameReader.processPayloadState(DefaultHttp2FrameReader.java:243)
    io.netty.handler.codec.http2.DefaultHttp2FrameReader.readFrame(DefaultHttp2FrameReader.java:147)
    io.netty.handler.codec.http2.Http2TestUtil$FrameAdapter.decode(Http2TestUtil.java:138)
    io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:369)
    io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:244)
    io.netty.channel.ChannelHandlerInvokerUtil.invokeChannelReadNow(ChannelHandlerInvokerUtil.java:83)
    io.netty.channel.DefaultChannelHandlerInvoker.invokeChannelRead(DefaultChannelHandlerInvoker.java:154)
    io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:154)
    io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:913)
    io.netty.channel.local.LocalChannel.finishPeerRead0(LocalChannel.java:437)
    io.netty.channel.local.LocalChannel.access$500(LocalChannel.java:48)
    io.netty.channel.local.LocalChannel$5.run(LocalChannel.java:393)
    io.netty.channel.DefaultEventLoop.run(DefaultEventLoop.java:54)
    io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:742)
    io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:137)
    java.lang.Thread.run(Thread.java:745)
@Scottmitch Scottmitch self-assigned this Jan 28, 2016
@Scottmitch Scottmitch added this to the 4.1.0.CR2 milestone Jan 28, 2016
@Scottmitch Scottmitch mentioned this issue Jan 28, 2016
Closed
@blucas
Copy link
Contributor

blucas commented Jan 28, 2016

@Scottmitch - I know where and why this leak is occurring, I just don't know what the preferred netty solution is to fixing this.

Where:

InboundHttp2ToHttpAdapterTest.clientRequestSingleHeaderNonAsciiShouldThrow()

Why:

It is happening because addHttp2ToHttpHeaders is throwing an exception due to an invalid character in a HTTP/2 Header's name/value. So basically the allocator is creating a ByteBuf for use in the FullHttpMessage, then the addHttp2ToHttpHeaders method is called passing in the FullHttpMessage. addHttp2ToHttpHeaders throws a validation exception, and the buffer is not released.

One solution is for the toHttpRequest/Response to take responsibility for this and release the buffer if an exception occurs before returning the message. The other is to treat this as an unusual circumstance and just fix the unit-test. I prefer the former, but it would also require us to look at other scenarios (such as SPDY or even HTTP/1.x header validation).

@normanmaurer
Copy link
Member

@blucas I think the former is the right solution. @Scottmitch ?

@blucas
Copy link
Contributor

blucas commented Jan 28, 2016

@normanmaurer Agreed. It makes more sense this way.

As an example of the former solution, lines 393-396 would have to be wrapped in a try/catch block to ensure the buffer is released if an exception (such as validation of a header) occurred.

@Scottmitch
Copy link
Member Author

@blucas - I have a PR which reworks a bunch of the logic in InboundHttp2ToHttpAdapter and the unit test. Lets review and make sure I have it covered when I push upstream.

@Scottmitch Scottmitch mentioned this issue Jan 29, 2016
Closed
Scottmitch added a commit to Scottmitch/netty that referenced this issue Feb 1, 2016
@Scottmitch
InboundHttp2ToHttpAdapter leak and logic improvements
5f154a5 
Motivation:
In HttpConversionUtil's toHttpRequest and toHttpResponse methods can
allocate FullHttpMessage objects, and if an exeception is thrown during
the header conversion then this object will not be released. If a
FullHttpMessage is not fired up the pipeline, and the stream is closed
then we remove from the map, but do not release the object. This leads
to a ByteBuf leak. Some of the logic related to stream lifetime management
and FullHttpMessage also predates the RFC being finalized and is not correct.

Modifications:
- Fix leaks in HttpConversionUtil
- Ensure the objects are released when they are removed from the map.
- Correct logic and unit tests where they are found to be incorrect.

Result:
Fixes netty#4780
Fixes netty#3619
@Scottmitch
Copy link
Member Author

A leak still exists (as seen in PR #4831). I suspect it may be related to the HTTP//2 codec not necessarily calling streamRemoved if a channel is not active (#4838)

[21:37:14]i:         [io.netty:netty-codec-http2] io.netty.handler.codec.http2.UniformStreamByteDistributorTest
[21:37:14]i:             [io.netty.handler.codec.http2.UniformStreamByteDistributorTest] bytesUnassignedAfterProcessing
[21:37:14]i:             [io.netty.handler.codec.http2.UniformStreamByteDistributorTest] minChunkShouldBeAllocatedPerStream
[21:37:14]i:             [io.netty.handler.codec.http2.UniformStreamByteDistributorTest] connectionErrorForWriterException
[21:37:14]i:             [io.netty.handler.codec.http2.UniformStreamByteDistributorTest] streamWithMoreDataShouldBeEnqueuedAfterWrite
[21:37:14]i:             [io.netty.handler.codec.http2.UniformStreamByteDistributorTest] streamWindowExhaustedDoesNotWrite
[21:37:14]i:             [io.netty.handler.codec.http2.UniformStreamByteDistributorTest] emptyFrameAtHeadIsWritten
[21:37:16] :         [io.netty:netty-codec-http2] 21:37:16.227 [defaultEventLoopGroup-78-2] DEBUG io.netty.buffer.PoolThreadCache - Freed 4 thread-local buffer(s) from thread: defaultEventLoopGroup-78-2
[21:37:16] :         [io.netty:netty-codec-http2] 21:37:16.236 [defaultEventLoopGroup-79-1] DEBUG io.netty.buffer.PoolThreadCache - Freed 3 thread-local buffer(s) from thread: defaultEventLoopGroup-79-1
[21:37:16] :         [io.netty:netty-codec-http2] 21:37:16.316 [defaultEventLoopGroup-81-1] ERROR io.netty.util.ResourceLeakDetector - LEAK: ByteBuf.release() was not called before it's garbage-collected. See http://netty.io/wiki/reference-counted-objects.html for more information.
[21:37:16] :         [io.netty:netty-codec-http2] Recent access records: 0
[21:37:16] :         [io.netty:netty-codec-http2] Created at:
[21:37:16] :         [io.netty:netty-codec-http2]   io.netty.buffer.PooledByteBufAllocator.newDirectBuffer(PooledByteBufAllocator.java:271)
[21:37:16] :         [io.netty:netty-codec-http2]   io.netty.buffer.AbstractByteBufAllocator.directBuffer(AbstractByteBufAllocator.java:179)
[21:37:16] :         [io.netty:netty-codec-http2]   io.netty.buffer.AbstractByteBufAllocator.directBuffer(AbstractByteBufAllocator.java:165)
[21:37:16] :         [io.netty:netty-codec-http2]   io.netty.buffer.AbstractByteBufAllocator.buffer(AbstractByteBufAllocator.java:99)
[21:37:16] :         [io.netty:netty-codec-http2]   io.netty.handler.codec.http2.HttpConversionUtil.toHttpResponse(HttpConversionUtil.java:204)
[21:37:16] :         [io.netty:netty-codec-http2]   io.netty.handler.codec.http2.InboundHttp2ToHttpAdapter.newMessage(InboundHttp2ToHttpAdapter.java:153)
[21:37:16] :         [io.netty:netty-codec-http2]   io.netty.handler.codec.http2.InboundHttp2ToHttpAdapter.processHeadersBegin(InboundHttp2ToHttpAdapter.java:187)
[21:37:16] :         [io.netty:netty-codec-http2]   io.netty.handler.codec.http2.InboundHttp2ToHttpPriorityAdapter.processHeadersBegin(InboundHttp2ToHttpPriorityAdapter.java:142)
[21:37:16] :         [io.netty:netty-codec-http2]   io.netty.handler.codec.http2.InboundHttp2ToHttpAdapter.onPushPromiseRead(InboundHttp2ToHttpAdapter.java:288)
[21:37:16] :         [io.netty:netty-codec-http2]   io.netty.handler.codec.http2.DefaultHttp2ConnectionDecoder$FrameReadListener.onPushPromiseRead(DefaultHttp2ConnectionDecoder.java:514)
[21:37:16] :         [io.netty:netty-codec-http2]   io.netty.handler.codec.http2.DefaultHttp2FrameReader$3.processFragment(DefaultHttp2FrameReader.java:537)
[21:37:16] :         [io.netty:netty-codec-http2]   io.netty.handler.codec.http2.DefaultHttp2FrameReader.readPushPromiseFrame(DefaultHttp2FrameReader.java:545)
[21:37:16] :         [io.netty:netty-codec-http2]   io.netty.handler.codec.http2.DefaultHttp2FrameReader.processPayloadState(DefaultHttp2FrameReader.java:255)
[21:37:16] :         [io.netty:netty-codec-http2]   io.netty.handler.codec.http2.DefaultHttp2FrameReader.readFrame(DefaultHttp2FrameReader.java:147)
[21:37:16] :         [io.netty:netty-codec-http2]   io.netty.handler.codec.http2.DefaultHttp2ConnectionDecoder.decodeFrame(DefaultHttp2ConnectionDecoder.java:106)
[21:37:16] :         [io.netty:netty-codec-http2]   io.netty.handler.codec.http2.Http2ConnectionHandler$FrameDecoder.decode(Http2ConnectionHandler.java:341)
[21:37:16] :         [io.netty:netty-codec-http2]   io.netty.handler.codec.http2.Http2ConnectionHandler.decode(Http2ConnectionHandler.java:401)
[21:37:16] :         [io.netty:netty-codec-http2]   io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:369)
[21:37:16] :         [io.netty:netty-codec-http2]   io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:244)
[21:37:16] :         [io.netty:netty-codec-http2]   io.netty.channel.ChannelHandlerInvokerUtil.invokeChannelReadNow(ChannelHandlerInvokerUtil.java:83)
[21:37:16] :         [io.netty:netty-codec-http2]   io.netty.channel.DefaultChannelHandlerInvoker.invokeChannelRead(DefaultChannelHandlerInvoker.java:154)
[21:37:16] :         [io.netty:netty-codec-http2]   io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:439)
[21:37:16] :         [io.netty:netty-codec-http2]   io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:162)
[21:37:16] :         [io.netty:netty-codec-http2]   io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:924)
[21:37:16] :         [io.netty:netty-codec-http2]   io.netty.channel.local.LocalChannel.finishPeerRead0(LocalChannel.java:437)
[21:37:16] :         [io.netty:netty-codec-http2]   io.netty.channel.local.LocalChannel.access$500(LocalChannel.java:48)
[21:37:16] :         [io.netty:netty-codec-http2]   io.netty.channel.local.LocalChannel$5.run(LocalChannel.java:393)
[21:37:16] :         [io.netty:netty-codec-http2]   io.netty.channel.DefaultEventLoop.run(DefaultEventLoop.java:54)
[21:37:16] :         [io.netty:netty-codec-http2]   io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:742)
[21:37:16] :         [io.netty:netty-codec-http2]   io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:137)
[21:37:16] :         [io.netty:netty-codec-http2]   java.lang.Thread.run(Thread.java:745)

@Scottmitch Scottmitch reopened this Feb 4, 2016
@Scottmitch Scottmitch mentioned this issue Feb 4, 2016
Closed
@normanmaurer normanmaurer modified the milestones: 4.1.0.CR2, 4.1.0.CR3 Feb 5, 2016
@normanmaurer
Copy link
Member

I think this was fixed

@Scottmitch
Copy link
Member Author

@blucas - Were you ever able to repro on your new PR #4831 after you rebased?

@blucas
Copy link
Contributor

blucas commented Feb 25, 2016

@Scottmitch - I didn't try. I figured the CI would reliably fail the build.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@Scottmitch Scottmitch

Labels
defect
Projects
None yet
Milestone
4.1.0.CR3
Development

Successfully merging a pull request may close this issue.

InboundHttp2ToHttpAdapter leak and logic improvements Scottmitch/netty
3 participants
@normanmaurer @blucas @Scottmitch