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

LEAK on PrematureCloseException from springboot webflux #3415

Open
gusrb415 opened this issue Aug 30, 2024 · 0 comments
Open

LEAK on PrematureCloseException from springboot webflux #3415

gusrb415 opened this issue Aug 30, 2024 · 0 comments
Assignees
@violetagg
Labels
type/bug A general bug

Comments

@gusrb415
Copy link

gusrb415 commented Aug 30, 2024 •
edited
Loading

Hi, I am operating a springboot webflux server that proxies download stream from another NodeJS server that is behind nginx proxy and developed by another company.

However, I am occasionally seeing a memory leak that is detected a few minutes after PrematureCloseException occurs. After many leaks accumulated for several days, the server won't die or correctly response the data. Therefore, I have to keep my eyes on the server status in case the LEAK accumulates too much.

I tried a lot to find some ways to release the DataBuffer on reactor but couldn't achieve it through doOnDiscard or doFinally. However, none of the methods worked.

Please help me to find if it is a bug or if there are ways to deal with this.

Maybe it is similar to #3407.

Expected Behavior

No memory leak

Actual Behavior

Memory leak

2024-08-30 10:51:09.580 [reactor-http-epoll-1] [ERROR] (i.n.u.ResourceLeakDetector:337) [] 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: [f68fcb11-1, L:/172.xxx.xxx.xxx:38820 - R:10.xxx.xxx.xxx/10.xxx.xxx.xxx:80] Buffered ByteBufHolder in the inbound buffer 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:399)
	reactor.netty.channel.ChannelOperations.onInboundNext(ChannelOperations.java:426)
	reactor.netty.http.client.HttpClientOperations.onInboundNext(HttpClientOperations.java:815)
	reactor.netty.channel.ChannelOperationsHandler.channelRead(ChannelOperationsHandler.java:114)
	io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444)
	io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
	io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
	io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:289)
	io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442)
	io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
	io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
	io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:436)
	io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:346)
	io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:318)
	io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:251)
	io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442)
	io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
	io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
	io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
	io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440)
	io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
	io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
	io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:800)
	io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:509)
	io.netty.channel.epoll.EpollEventLoop.run(Unknown Source)
	io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
	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(Unknown Source)
#2:
	Hint: 'reactor.right.reactiveBridge' will handle the message from this point.
	io.netty.handler.codec.http.DefaultHttpContent.touch(DefaultHttpContent.java:86)
	io.netty.handler.codec.http.DefaultHttpContent.touch(DefaultHttpContent.java:25)
	io.netty.channel.DefaultChannelPipeline.touch(DefaultChannelPipeline.java:116)
	io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:417)
	io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
	io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:289)
	io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442)
	io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
	io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
	io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:436)
	io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:346)
	io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:318)
	io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:251)
	io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442)
	io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
	io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
	io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
	io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440)
	io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
	io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
	io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:800)
	io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:509)
	io.netty.channel.epoll.EpollEventLoop.run(Unknown Source)
	io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
	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(Unknown Source)
#3:
	Hint: 'ReadTimeoutHandler' will handle the message from this point.
	io.netty.handler.codec.http.DefaultHttpContent.touch(DefaultHttpContent.java:86)
	io.netty.handler.codec.http.DefaultHttpContent.touch(DefaultHttpContent.java:25)
	io.netty.channel.DefaultChannelPipeline.touch(DefaultChannelPipeline.java:116)
	io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:417)
	io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
	io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:436)
	io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:346)
	io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:318)
	io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:251)
	io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442)
	io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
	io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
	io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
	io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440)
	io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
	io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
	io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:800)
	io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:509)
	io.netty.channel.epoll.EpollEventLoop.run(Unknown Source)
	io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
	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(Unknown Source)
Created at:
	io.netty.buffer.SimpleLeakAwareByteBuf.unwrappedDerived(SimpleLeakAwareByteBuf.java:144)
	io.netty.buffer.SimpleLeakAwareByteBuf.readRetainedSlice(SimpleLeakAwareByteBuf.java:67)
	io.netty.buffer.AdvancedLeakAwareByteBuf.readRetainedSlice(AdvancedLeakAwareByteBuf.java:108)
	io.netty.handler.codec.http.HttpObjectDecoder.decode(HttpObjectDecoder.java:439)
	io.netty.handler.codec.http.HttpClientCodec$Decoder.decode(HttpClientCodec.java:320)
	io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:529)
	io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:468)
	io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:290)
	io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:251)
	io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442)
	io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
	io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
	io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
	io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440)
	io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
	io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
	io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:800)
	io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:509)
	io.netty.channel.epoll.EpollEventLoop.run(Unknown Source)
	io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
	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(Unknown Source)
--

The below is the logs searched by request hash(f68fcb11-1)

2024-08-30 10:44:19.253 [reactor-http-epoll-1] [WARN ] (r.n.c.FluxReceive:304) [] [f68fcb11-1, L:/172.xxx.xxx.xxx:38820 ! R:10.xxx.xxx.xxx/10.xxx.xxx.xxx:80] An exception has been observed post termination
reactor.netty.http.client.PrematureCloseException: Connection prematurely closed DURING response
2024-08-30 10:44:19.253 [reactor-http-epoll-1] [DEBUG] (r.n.r.DefaultPooledConnectionProvider:259) [] [f68fcb11-1, L:/172.xxx.xxx.xxx:38820 ! R:10.xxx.xxx.xxx/10.xxx.xxx.xxx:80] onStateChange(GET{uri=/cache/files/data/v.14101.drive.NzY4NjQwMDJ8MjI4NTk5MDgzMzEyNzY.1655303692000/Editor.bin/Editor.bin, connection=PooledConnection{channel=[id: 0xf68fcb11, L:/172.xxx.xxx.xxx:38820 ! R:10.xxx.xxx.xxx/10.xxx.xxx.xxx:80]}}, [response_incomplete])
2024-08-30 10:44:19.253 [reactor-http-epoll-1] [DEBUG] (r.n.ReactorNetty:259) [] [f68fcb11-1, L:/172.xxx.xxx.xxx:38820 ! R:10.xxx.xxx.xxx/10.xxx.xxx.xxx:80] Non Removed handler: ReadTimeoutHandler, context: ChannelHandlerContext(ReadTimeoutHandler, [id: 0xf68fcb11, L:/172.xxx.xxx.xxx:38820 ! R:10.xxx.xxx.xxx/10.xxx.xxx.xxx:80]), pipeline: DefaultChannelPipeline{(reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (ReadTimeoutHandler = io.netty.handler.timeout.ReadTimeoutHandler), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2024-08-30 10:44:19.252 [reactor-http-epoll-1] [DEBUG] (r.n.r.PooledConnectionProvider:259) [] [f68fcb11-1, L:/172.xxx.xxx.xxx:38820 ! R:10.xxx.xxx.xxx/10.xxx.xxx.xxx:80] Channel closed, now: 0 active connections, 0 inactive connections and 0 pending acquire requests.
2024-08-30 10:43:49.250 [reactor-http-epoll-1] [DEBUG] (o.s.w.r.f.c.ExchangeFunctions:120) [-] [5f3ac442] [f68fcb11-1, L:/172.xxx.xxx.xxx:38820 - R:10.xxx.xxx.xxx/10.xxx.xxx.xxx:80] Response 200 OK
2024-08-30 10:43:49.250 [reactor-http-epoll-1] [DEBUG] (r.n.r.DefaultPooledConnectionProvider:259) [] [f68fcb11-1, L:/172.xxx.xxx.xxx:38820 - R:10.xxx.xxx.xxx/10.xxx.xxx.xxx:80] onStateChange(GET{uri=/cache/files/data/v.14101.drive.NzY4NjQwMDJ8MjI4NTk5MDgzMzEyNzY.1655303692000/Editor.bin/Editor.bin, connection=PooledConnection{channel=[id: 0xf68fcb11, L:/172.xxx.xxx.xxx:38820 - R:10.xxx.xxx.xxx/10.xxx.xxx.xxx:80]}}, [response_received])
2024-08-30 10:43:49.250 [reactor-http-epoll-1] [DEBUG] (r.n.h.c.HttpClientOperations:259) [] [f68fcb11-1, L:/172.xxx.xxx.xxx:38820 - R:10.xxx.xxx.xxx/10.xxx.xxx.xxx:80] Received response (auto-read:false) : RESPONSE(decodeResult: success, version: HTTP/1.1)
HTTP/1.1 200 OK
server: <filtered>
date: <filtered>
content-type: <filtered>
content-length: <filtered>
last-modified: <filtered>
vary: <filtered>
etag: <filtered>
content-disposition: <filtered>
accept-ranges: <filtered>
x-envoy-upstream-service-time: <filtered>
2024-08-30 10:43:49.246 [reactor-http-epoll-1] [DEBUG] (r.n.r.DefaultPooledConnectionProvider:259) [] [f68fcb11-1, L:/172.xxx.xxx.xxx:38820 - R:10.xxx.xxx.xxx/10.xxx.xxx.xxx:80] onStateChange(GET{uri=/cache/files/data/v.14101.drive.NzY4NjQwMDJ8MjI4NTk5MDgzMzEyNzY.1655303692000/Editor.bin/Editor.bin, connection=PooledConnection{channel=[id: 0xf68fcb11, L:/172.xxx.xxx.xxx:38820 - R:10.xxx.xxx.xxx/10.xxx.xxx.xxx:80]}}, [request_sent])
2024-08-30 10:43:49.245 [reactor-http-epoll-1] [DEBUG] (r.n.ReactorNetty:259) [] [f68fcb11-1, L:/172.xxx.xxx.xxx:38820 - R:10.xxx.xxx.xxx/10.xxx.xxx.xxx:80] Added decoder [ReadTimeoutHandler] at the end of the user pipeline, full pipeline: [reactor.left.httpCodec, ReadTimeoutHandler, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
2024-08-30 10:43:49.245 [reactor-http-epoll-1] [DEBUG] (r.n.r.DefaultPooledConnectionProvider:259) [] [f68fcb11-1, L:/172.xxx.xxx.xxx:38820 - R:10.xxx.xxx.xxx/10.xxx.xxx.xxx:80] onStateChange(GET{uri=/cache/files/data/v.14101.drive.NzY4NjQwMDJ8MjI4NTk5MDgzMzEyNzY.1655303692000/Editor.bin/Editor.bin, connection=PooledConnection{channel=[id: 0xf68fcb11, L:/172.xxx.xxx.xxx:38820 - R:10.xxx.xxx.xxx/10.xxx.xxx.xxx:80]}}, [request_prepared])
2024-08-30 10:43:49.245 [reactor-http-epoll-1] [DEBUG] (r.n.h.c.HttpClientConnect:259) [] [f68fcb11-1, L:/172.xxx.xxx.xxx:38820 - R:10.xxx.xxx.xxx/10.xxx.xxx.xxx:80] Handler is being applied: {uri=http://10.xxx.xxx.xxx/cache/files/data/v.14101.drive.NzY4NjQwMDJ8MjI4NTk5MDgzMzEyNzY.1655303692000/Editor.bin/Editor.bin?md5=op35GAm3OGkDfT77WtlNFQ&expires=1725241609&shardkey=v.14101.drive.NzY4NjQwMDJ8MjI4NTk5MDgzMzEyNzY.1655303692000&filename=Editor.bin, method=GET}
2024-08-30 10:43:49.244 [reactor-http-epoll-1] [DEBUG] (r.n.r.DefaultPooledConnectionProvider:259) [] [f68fcb11-1, L:/172.xxx.xxx.xxx:38820 - R:10.xxx.xxx.xxx/10.xxx.xxx.xxx:80] onStateChange(GET{uri=null, connection=PooledConnection{channel=[id: 0xf68fcb11, L:/172.xxx.xxx.xxx:38820 - R:10.xxx.xxx.xxx/10.xxx.xxx.xxx:80]}}, [configured])
2024-08-30 10:43:49.244 [reactor-http-epoll-1] [DEBUG] (r.n.r.DefaultPooledConnectionProvider:259) [] [f68fcb11, L:/172.xxx.xxx.xxx:38820 - R:10.xxx.xxx.xxx/10.xxx.xxx.xxx:80] onStateChange(PooledConnection{channel=[id: 0xf68fcb11, L:/172.xxx.xxx.xxx:38820 - R:10.xxx.xxx.xxx/10.xxx.xxx.xxx:80]}, [connected])
2024-08-30 10:43:49.244 [reactor-http-epoll-1] [DEBUG] (r.n.r.PooledConnectionProvider:259) [-] [f68fcb11, L:/172.xxx.xxx.xxx:38820 - R:10.xxx.xxx.xxx/10.xxx.xxx.xxx:80] Channel connected, now: 2 active connections, 0 inactive connections and 0 pending acquire requests.
2024-08-30 10:43:49.244 [reactor-http-epoll-1] [DEBUG] (r.n.r.DefaultPooledConnectionProvider:254) [-] [f68fcb11, L:/172.xxx.xxx.xxx:38820 - R:10.xxx.xxx.xxx/10.xxx.xxx.xxx:80] Registering pool release on close event for channel
2024-08-30 10:43:49.244 [reactor-http-epoll-1] [DEBUG] (r.n.t.TransportConnector:254) [] [f68fcb11] Connecting to [/10.xxx.xxx.xxx:80].
2024-08-30 10:43:49.244 [reactor-http-epoll-1] [DEBUG] (r.n.t.TransportConfig:259) [] [f68fcb11] Initialized pipeline DefaultChannelPipeline{(reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2024-08-30 10:43:49.243 [reactor-http-epoll-1] [DEBUG] (r.n.r.PooledConnectionProvider:259) [] [f68fcb11] Created a new pooled channel, now: 1 active connections, 0 inactive connections and 0 pending acquire requests.

Steps to Reproduce

Cannot reproduce on local even with when I tried to force PrematureCloseException with the help of another temporary server. I don't know why... But this is where the download occurs and it is directly returned to the spring RestController method.

// proxy download code
return webClient.get()
	.uri(uri)
	.retrieve()
	.toEntityFlux(DataBuffer.class);

Your Environment

  • Spring Boot webflux: 3.2.4
  • Reactor: 3.6.4
  • Reactor Netty Http/Core: 1.1.17
  • Netty 4.1.107.Final
  • Java 17
  • RHEL 8
@gusrb415 gusrb415 added status/need-triage A new issue that still need to be evaluated as a whole type/bug A general bug labels Aug 30, 2024
@violetagg violetagg self-assigned this Sep 10, 2024
@violetagg violetagg removed the status/need-triage A new issue that still need to be evaluated as a whole label Sep 10, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@violetagg violetagg

Labels
type/bug A general bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@violetagg @gusrb415