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

Fixed netty leak on DELETE operations in GATEWAY mode #14727

Merged
merged 1 commit into from
Sep 2, 2020
Merged

Fixed netty leak on DELETE operations in GATEWAY mode #14727

merged 1 commit into from
Sep 2, 2020
+7 −30

Conversation

kushagraThapar
Copy link
Member

@kushagraThapar kushagraThapar commented Sep 2, 2020 •
edited
Loading

Here are findings on how the leak was detected and fixed - using netty debug level logs.

BEFORE FIX: Subscribe operation is not happening on DELETE calls in Gateway mode.

[2020-09-01T23:35:57.052Z] [DEBUG] [id: 0x4b1bdf4b, L:/172.17.0.2:33890 - R:netty-leak-detection-test-eastus2.documents.azure.com/104.208.231.16:443] Handler is being applied: {uri=https://netty-leak-detection-test-eastus2.documents.azure.com/dbs/AzureSampleFamilyDB/colls/FamilyContainer1/docs/bad2, method=DELETE}

[2020-09-01T23:35:57.053Z] [DEBUG] [id: 0x4b1bdf4b, L:/172.17.0.2:33890 - R:netty-leak-detection-test-eastus2.documents.azure.com/104.208.231.16:443] onStateChange(DELETE{uri=/dbs/AzureSampleFamilyDB/colls/FamilyContainer1/docs/bad2, connection=PooledConnection{channel=[id: 0x4b1bdf4b, L:/172.17.0.2:33890 - R:netty-leak-detection-test-eastus2.documents.azure.com/104.208.231.16:443]}}, [request_prepared])

[2020-09-01T23:35:57.054Z] [DEBUG] [id: 0x4b1bdf4b, L:/172.17.0.2:33890 - R:netty-leak-detection-test-eastus2.documents.azure.com/104.208.231.16:443] onStateChange(DELETE{uri=/dbs/AzureSampleFamilyDB/colls/FamilyContainer1/docs/bad2, connection=PooledConnection{channel=[id: 0x4b1bdf4b, L:/172.17.0.2:33890 - R:netty-leak-detection-test-eastus2.documents.azure.com/104.208.231.16:443]}}, [request_sent])

[2020-09-01T23:35:57.148Z] [DEBUG] [id: 0x4b1bdf4b, L:/172.17.0.2:33890 - R:netty-leak-detection-test-eastus2.documents.azure.com/104.208.231.16:443] Received response (auto-read:false) : [Transfer-Encoding=chunked, Content-Type=application/json, Content-Location=https://netty-leak-detection-test-eastus2.documents.azure.com/dbs/AzureSampleFamilyDB/colls/FamilyContainer1/docs/bad2, Server=Microsoft-HTTPAPI/2.0, x-ms-last-state-change-utc=Sat, 29 Aug 2020 10:07:19.454 GMT, lsn=433, x-ms-schemaversion=1.9, x-ms-quorum-acked-lsn=433, x-ms-current-write-quorum=3, x-ms-current-replica-set-size=4, x-ms-xp-role=1, x-ms-global-Committed-lsn=433, x-ms-number-of-read-regions=0, x-ms-transport-request-id=82, x-ms-cosmos-llsn=433, x-ms-cosmos-quorum-acked-llsn=433, x-ms-session-token=0:-1#433, x-ms-request-charge=1.24, x-ms-serviceversion=version=2.11.0.0, x-ms-activity-id=4eebc3f3-554b-44d3-bf71-2985679e9a6a, Strict-Transport-Security=max-age=31536000, x-ms-gatewayversion=version=2.11.0, Date=Tue, 01 Sep 2020 23:35:56 GMT]

[2020-09-01T23:35:57.149Z] [DEBUG] [id: 0x4b1bdf4b, L:/172.17.0.2:33890 - R:netty-leak-detection-test-eastus2.documents.azure.com/104.208.231.16:443] onStateChange(DELETE{uri=/dbs/AzureSampleFamilyDB/colls/FamilyContainer1/docs/bad2, connection=PooledConnection{channel=[id: 0x4b1bdf4b, L:/172.17.0.2:33890 - R:netty-leak-detection-test-eastus2.documents.azure.com/104.208.231.16:443]}}, [response_received])

[2020-09-01T23:35:57.154Z] [DEBUG] [id: 0x4b1bdf4b, L:/172.17.0.2:33890 - R:netty-leak-detection-test-eastus2.documents.azure.com/104.208.231.16:443] Received last HTTP packet

[2020-09-01T23:35:57.154Z] [DEBUG] [id: 0x4b1bdf4b, L:/172.17.0.2:33890 - R:netty-leak-detection-test-eastus2.documents.azure.com/104.208.231.16:443] onStateChange(DELETE{uri=/dbs/AzureSampleFamilyDB/colls/FamilyContainer1/docs/bad2, connection=PooledConnection{channel=[id: 0x4b1bdf4b, L:/172.17.0.2:33890 - R:netty-leak-detection-test-eastus2.documents.azure.com/104.208.231.16:443]}}, [response_completed])

[2020-09-01T23:35:57.154Z] [DEBUG] [id: 0x4b1bdf4b, L:/172.17.0.2:33890 - R:netty-leak-detection-test-eastus2.documents.azure.com/104.208.231.16:443] onStateChange(DELETE{uri=/dbs/AzureSampleFamilyDB/colls/FamilyContainer1/docs/bad2, connection=PooledConnection{channel=[id: 0x4b1bdf4b, L:/172.17.0.2:33890 - R:netty-leak-detection-test-eastus2.documents.azure.com/104.208.231.16:443]}}, [disconnecting])

[2020-09-01T23:35:57.155Z] [DEBUG] [id: 0x4b1bdf4b, L:/172.17.0.2:33890 - R:netty-leak-detection-test-eastus2.documents.azure.com/104.208.231.16:443] Releasing channel

[2020-09-01T23:35:57.155Z] [DEBUG] [id: 0x4b1bdf4b, L:/172.17.0.2:33890 - R:netty-leak-detection-test-eastus2.documents.azure.com/104.208.231.16:443] Channel cleaned, now 3 active connections and 1 inactive connections

[2020-09-01T23:35:57.279Z] [ERROR] LEAK: ByteBuf.release() was not called before it's garbage-collected. See https://netty.io/wiki/reference-counted-objects.html for more information.
Recent access records: 
#1:
	Hint: [id: 0x4b1bdf4b, L:/172.17.0.2:33890 - R:netty-leak-detection-test-eastus2.documents.azure.com/104.208.231.16:443] Buffered ByteBufHolder in Inbound Flux Queue
	io.netty.handler.codec.http.DefaultHttpContent.touch(DefaultHttpContent.java:86)
	io.netty.handler.codec.http.DefaultHttpContent.touch(DefaultHttpContent.java:25)
	reactor.netty.channel.FluxReceive.onInboundNext(FluxReceive.java:357)
	reactor.netty.channel.ChannelOperations.onInboundNext(ChannelOperations.java:358)
	reactor.netty.http.client.HttpClientOperations.onInboundNext(HttpClientOperations.java:677)
	reactor.netty.channel.ChannelOperationsHandler.channelRead(ChannelOperationsHandler.java:96)
	io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
	io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:436)
	io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:324)
	io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:296)
	io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:251)
	io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
	io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1526)
	io.netty.handler.ssl.SslHandler.decodeJdkCompatible(SslHandler.java:1275)
	io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1322)
	io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:501)
	io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:440)
	io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:276)
	io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
	io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
	io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
	io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:792)
	io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:475)
	io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:378)
	io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
	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:834)

AFTER FIX: Subscribe operation is happening on DELETE operations in Gateway mode.

[2020-09-02T00:20:19.808Z] [DEBUG] [id: 0xb4d8e549, L:/172.17.0.2:34022 - R:netty-leak-detection-test-eastus2.documents.azure.com/104.208.231.16:443] Subscribing inbound receiver [pending: 0, cancelled:false, inboundDone: false]

@ghost ghost added the Cosmos label Sep 2, 2020
@kushagraThapar
Copy link
Member Author

/azp run java - cosmos - tests

@azure-pipelines
Copy link

Azure Pipelines successfully started running 1 pipeline(s).

@kirankumarkolli
Copy link
Member

Thoughts on covering some of these aspects through UT?

moderakh
moderakh approved these changes Sep 2, 2020
View reviewed changes
Copy link
Contributor

@moderakh moderakh left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

we discussed offline this yesterday.

LGTM.

@kushagraThapar
Copy link
Member Author

Thoughts on covering some of these aspects through UT?

Sure, will come up with a way to make sure the body of Reactor Netty response is always subscribed.

simplynaveen20
simplynaveen20 reviewed Sep 2, 2020
View reviewed changes
...smos/azure-cosmos/src/main/java/com/azure/cosmos/implementation/http/ReactorNettyClient.java
byteBuf.retain();
return byteBuf;
});
.doOnSubscribe(this::updateSubscriptionState);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

what this change for ?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Just removed the unnecessary map operator. We don't need to retain the byteBuf here, as it is not released afterwards.
This can potentially raise IllegalReferenceCount issue with netty.
Although, we don't use this API, which is why no one has seen this issue.

@kushagraThapar
Copy link
Member Author

/check-enforcer override

@kushagraThapar kushagraThapar merged commit 37c78d7 into Azure:master Sep 2, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@simplynaveen20 simplynaveen20 simplynaveen20 left review comments

@moderakh moderakh moderakh approved these changes

@FabianMeiswinkel FabianMeiswinkel FabianMeiswinkel approved these changes

@David-Noble-at-work David-Noble-at-work Awaiting requested review from David-Noble-at-work

@kirankumarkolli kirankumarkolli Awaiting requested review from kirankumarkolli

@mbhaskar mbhaskar Awaiting requested review from mbhaskar

@milismsft milismsft Awaiting requested review from milismsft

@xinlian12 xinlian12 Awaiting requested review from xinlian12

Assignees
No one assigned
Labels
Cosmos
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
5 participants
@kushagraThapar @kirankumarkolli @FabianMeiswinkel @moderakh @simplynaveen20