Suppress Reactor Netty "disconnected client" exceptions the logs [SPR-17257]

[spring-projects-issues]

David Terk opened SPR-17257 and commented

I am seeing  WARN 15 — [-server-epoll-9] o.s.h.s.r.ReactorHttpHandlerAdapter : Handling completed with error: Connection has been closed

All over my logs.  Nearly every request through my gateway.  Why would this happen?  All requests are completing without ANY errors.

Sorry but I don't have much more info than that.  I am using Spring Cloud Gateway.  Seems to happen on calls which make a POST.

I am finding that I need to turn off logging on both

org.springframework.http.server.reactive.ReactorHttpHandlerAdapter
org.springframework.web.server.adapter.HttpWebHandlerAdapter

Otherwise there is an unbelievable amount of logs being generated from what appears to be requests and responses that are functioning normally.

 

Would be useful to show the trace to have an idea where it is coming from.

---

Affects: 5.0.8, 5.1.2

Issue Links:

• Disconnected client exception logging should differentiate remote service exceptions too [SPR-17341] #21875 Disconnected client exception logging should differentiate remote service exceptions too

0 votes, 5 watchers

[spring-projects-issues]

Rossen Stoyanchev commented

The log message indicates an error was thrown at some point during request handling. Given the error message ("Connection has been closed"), and that it's a gateway, maybe the request from the gateway to the remote server generates this error for some reason, and then the error propagates? The only other option is the client of the gateway application has gone away.

Either way something is raising this exception. The key is to find out where it originates. You can try to enable debug logging for org.springframework.web and for Spring Cloud Gateway for a start. If the error details don't appear for some reason, you can also try to install a WebFilter with a high precedence (i.e. before others) and use chain.filter(exchange).doOnError(ex -> ...) to inspect or log it.

[spring-projects-issues]

David Terk commented

Coming from Netty Reactor.  Only on my posts.  Can't seem to reproduce locally, only on this environment.

 

   2018-09-10T18:22:56.22-0400 [APP/PROC/WEB/0] OUT 2018-09-10 22:22:56.220 TRACE 14 --- [server-epoll-10] filter.ErrorFilter  : reactor.ipc.netty.channel.AbortedException: Connection has been closed   2018-09-10T18:22:56.22-0400 [APP/PROC/WEB/0] OUT 2018-09-10 22:22:56.220 TRACE 14 --- [server-epoll-10] c.u.u.mobile.gateway.filter.ErrorFilter  : reactor.ipc.netty.channel.AbortedException: Connection has been closed   2018-09-10T18:22:56.22-0400 [APP/PROC/WEB/0] OUT reactor.ipc.netty.channel.AbortedException: Connection has been closed   2018-09-10T18:22:56.22-0400 [APP/PROC/WEB/0] OUT  at reactor.ipc.netty.channel.ChannelOperationsHandler.discard(ChannelOperationsHandler.java:365) ~[reactor-netty-0.7.8.RELEASE.jar!/:0.7.8.RELEASE]   2018-09-10T18:22:56.22-0400 [APP/PROC/WEB/0] OUT  at reactor.ipc.netty.channel.ChannelOperationsHandler.drain(ChannelOperationsHandler.java:375) ~[reactor-netty-0.7.8.RELEASE.jar!/:0.7.8.RELEASE]   2018-09-10T18:22:56.22-0400 [APP/PROC/WEB/0] OUT  at reactor.ipc.netty.channel.ChannelOperationsHandler.handlerRemoved(ChannelOperationsHandler.java:208) ~[reactor-netty-0.7.8.RELEASE.jar!/:0.7.8.RELEASE]   2018-09-10T18:22:56.22-0400 [APP/PROC/WEB/0] OUT  at io.netty.channel.DefaultChannelPipeline.callHandlerRemoved0(DefaultChannelPipeline.java:670) ~[netty-transport-4.1.27.Final.jar!/:4.1.27.Final]   2018-09-10T18:22:56.22-0400 [APP/PROC/WEB/0] OUT  at io.netty.channel.DefaultChannelPipeline.destroyDown(DefaultChannelPipeline.java:922) ~[netty-transport-4.1.27.Final.jar!/:4.1.27.Final]   2018-09-10T18:22:56.22-0400 [APP/PROC/WEB/0] OUT  at io.netty.channel.DefaultChannelPipeline.destroyUp(DefaultChannelPipeline.java:888) ~[netty-transport-4.1.27.Final.jar!/:4.1.27.Final]   2018-09-10T18:22:56.22-0400 [APP/PROC/WEB/0] OUT  at io.netty.channel.DefaultChannelPipeline.destroy(DefaultChannelPipeline.java:880) ~[netty-transport-4.1.27.Final.jar!/:4.1.27.Final]   2018-09-10T18:22:56.22-0400 [APP/PROC/WEB/0] OUT  at io.netty.channel.DefaultChannelPipeline.access$700(DefaultChannelPipeline.java:46) ~[netty-transport-4.1.27.Final.jar!/:4.1.27.Final]   2018-09-10T18:22:56.22-0400 [APP/PROC/WEB/0] OUT  at io.netty.channel.DefaultChannelPipeline$HeadContext.channelUnregistered(DefaultChannelPipeline.java:1416) ~[netty-transport-4.1.27.Final.jar!/:4.1.27.Final]   2018-09-10T18:22:56.22-0400 [APP/PROC/WEB/0] OUT  at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:181) ~[netty-transport-4.1.27.Final.jar!/:4.1.27.Final]   2018-09-10T18:22:56.22-0400 [APP/PROC/WEB/0] OUT  at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:167) ~[netty-transport-4.1.27.Final.jar!/:4.1.27.Final]   2018-09-10T18:22:56.22-0400 [APP/PROC/WEB/0] OUT  at io.netty.channel.DefaultChannelPipeline.fireChannelUnregistered(DefaultChannelPipeline.java:865) ~[netty-transport-4.1.27.Final.jar!/:4.1.27.Final]   2018-09-10T18:22:56.22-0400 [APP/PROC/WEB/0] OUT  at io.netty.channel.AbstractChannel$AbstractUnsafe$8.run(AbstractChannel.java:830) ~[netty-transport-4.1.27.Final.jar!/:4.1.27.Final]   2018-09-10T18:22:56.22-0400 [APP/PROC/WEB/0] OUT  at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163) ~[netty-common-4.1.27.Final.jar!/:4.1.27.Final]   2018-09-10T18:22:56.22-0400 [APP/PROC/WEB/0] OUT  at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:404) ~[netty-common-4.1.27.Final.jar!/:4.1.27.Final]   2018-09-10T18:22:56.22-0400 [APP/PROC/WEB/0] OUT  at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:322) ~[netty-transport-native-epoll-4.1.27.Final-linux-x86_64.jar!/:4.1.27.Final]   2018-09-10T18:22:56.22-0400 [APP/PROC/WEB/0] OUT  at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:884) ~[netty-common-4.1.27.Final.jar!/:4.1.27.Final]   2018-09-10T18:22:56.22-0400 [APP/PROC/WEB/0] OUT  at java.lang.Thread.run(Thread.java:748) ~[na:1.8.0_172]

[spring-projects-issues]

David Terk commented

   2018-09-10T18:17:33.03-0400 [APP/PROC/WEB/1] OUT 2018-09-10 22:17:33.029 ERROR 16 --- [server-epoll-13] o.s.w.s.adapter.HttpWebHandlerAdapter    : Unhandled failure: Connection has been closed, response already set (status=200)   2018-09-10T18:17:33.03-0400 [APP/PROC/WEB/1] OUT 2018-09-10 22:17:33.029 ERROR 16 --- [server-epoll-13] o.s.w.s.adapter.HttpWebHandlerAdapter    : Unhandled failure: Connection has been closed, response already set (status=200)   2018-09-10T18:17:33.03-0400 [APP/PROC/WEB/1] OUT 2018-09-10 22:17:33.029  WARN 16 --- [server-epoll-13] o.s.h.s.r.ReactorHttpHandlerAdapter      : Handling completed with error: Connection has been closed   2018-09-10T18:17:33.37-0400 [APP/PROC/WEB/1] OUT 2018-09-10 22:17:33.372 TRACE 16 --- [server-epoll-12] c.filter.ErrorFilter  : reactor.ipc.netty.channel.AbortedException: Connection has been closed   2018-09-10T18:17:33.37-0400 [APP/PROC/WEB/1] OUT reactor.ipc.netty.channel.AbortedException: Connection has been closed   2018-09-10T18:17:33.37-0400 [APP/PROC/WEB/1] OUT  at reactor.ipc.netty.channel.ChannelOperationsHandler.discard(ChannelOperationsHandler.java:365) ~[reactor-netty-0.7.8.RELEASE.jar!/:0.7.8.RELEASE]   2018-09-10T18:17:33.37-0400 [APP/PROC/WEB/1] OUT  at reactor.ipc.netty.channel.ChannelOperationsHandler.drain(ChannelOperationsHandler.java:375) ~[reactor-netty-0.7.8.RELEASE.jar!/:0.7.8.RELEASE]   2018-09-10T18:17:33.37-0400 [APP/PROC/WEB/1] OUT  at reactor.ipc.netty.channel.ChannelOperationsHandler.handlerRemoved(ChannelOperationsHandler.java:208) ~[reactor-netty-0.7.8.RELEASE.jar!/:0.7.8.RELEASE]   2018-09-10T18:17:33.37-0400 [APP/PROC/WEB/1] OUT  at io.netty.channel.DefaultChannelPipeline.callHandlerRemoved0(DefaultChannelPipeline.java:670) ~[netty-transport-4.1.27.Final.jar!/:4.1.27.Final]   2018-09-10T18:17:33.37-0400 [APP/PROC/WEB/1] OUT  at io.netty.channel.DefaultChannelPipeline.destroyDown(DefaultChannelPipeline.java:922) ~[netty-transport-4.1.27.Final.jar!/:4.1.27.Final]   2018-09-10T18:17:33.37-0400 [APP/PROC/WEB/1] OUT  at io.netty.channel.DefaultChannelPipeline.destroyUp(DefaultChannelPipeline.java:888) ~[netty-transport-4.1.27.Final.jar!/:4.1.27.Final]   2018-09-10T18:17:33.37-0400 [APP/PROC/WEB/1] OUT  at io.netty.channel.DefaultChannelPipeline.destroy(DefaultChannelPipeline.java:880) ~[netty-transport-4.1.27.Final.jar!/:4.1.27.Final]   2018-09-10T18:17:33.37-0400 [APP/PROC/WEB/1] OUT  at io.netty.channel.DefaultChannelPipeline.access$700(DefaultChannelPipeline.java:46) ~[netty-transport-4.1.27.Final.jar!/:4.1.27.Final]   2018-09-10T18:17:33.37-0400 [APP/PROC/WEB/1] OUT  at io.netty.channel.DefaultChannelPipeline$HeadContext.channelUnregistered(DefaultChannelPipeline.java:1416) ~[netty-transport-4.1.27.Final.jar!/:4.1.27.Final]   2018-09-10T18:17:33.37-0400 [APP/PROC/WEB/1] OUT  at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:181) ~[netty-transport-4.1.27.Final.jar!/:4.1.27.Final]   2018-09-10T18:17:33.37-0400 [APP/PROC/WEB/1] OUT  at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:167) ~[netty-transport-4.1.27.Final.jar!/:4.1.27.Final]   2018-09-10T18:17:33.37-0400 [APP/PROC/WEB/1] OUT  at io.netty.channel.DefaultChannelPipeline.fireChannelUnregistered(DefaultChannelPipeline.java:865) ~[netty-transport-4.1.27.Final.jar!/:4.1.27.Final]   2018-09-10T18:17:33.37-0400 [APP/PROC/WEB/1] OUT  at io.netty.channel.AbstractChannel$AbstractUnsafe$8.run(AbstractChannel.java:830) ~[netty-transport-4.1.27.Final.jar!/:4.1.27.Final]   2018-09-10T18:17:33.37-0400 [APP/PROC/WEB/1] OUT  at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163) ~[netty-common-4.1.27.Final.jar!/:4.1.27.Final]   2018-09-10T18:17:33.37-0400 [APP/PROC/WEB/1] OUT  at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:404) ~[netty-common-4.1.27.Final.jar!/:4.1.27.Final]   2018-09-10T18:17:33.37-0400 [APP/PROC/WEB/1] OUT  at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:322) ~[netty-transport-native-epoll-4.1.27.Final-linux-x86_64.jar!/:4.1.27.Final]   2018-09-10T18:17:33.37-0400 [APP/PROC/WEB/1] OUT  at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:884) ~[netty-common-4.1.27.Final.jar!/:4.1.27.Final]   2018-09-10T18:17:33.37-0400 [APP/PROC/WEB/1] OUT  at java.lang.Thread.run(Thread.java:748) ~[na:1.8.0_172]

[spring-projects-issues]

Rossen Stoyanchev commented

It's not clear what we can do about this in the Spring Framework. At best we could add the exception to the list of exceptions for a disconnected client in order to reduce noise. Violeta Georgieva, does it make sense to add Reactor Netty's AbortedException to that list?

Although here it's not a case of the client going away, but rather a remote backend service closes the connection. Yet the request from a client's perspective appears to succeed. David Terk are you certain the gateway does manage to post the data in its entirety and the exception happens after that? Or could it be that the gateway fails to post all the data and it's just too late to change the response status at that point, so it only appears to succeed?

Beyond that I would suggest to try the latest Reactor Netty 0.7.9 snapshots, or better yet Spring Framework 5.1 + Reactor Netty 0.8. Spring Framework 5.1 alone has major changes around logging, so you shouldn't see as much output, but again the question remains what the errors actually mean.

 

[spring-projects-issues]

Rossen Stoyanchev commented

/cc Spencer Gibb in case anything here rings a bell.

[spring-projects-issues]

Spencer Gibb commented

Only thing I can think of is the HiddenHttpMethodFilter problem that was causing post problems in boot 2.0.5+

[spring-projects-issues]

Violeta Georgieva commented

Rossen Stoyanchev Can you use this? https://github.com/reactor/reactor-netty/blob/0.7.x/src/main/java/reactor/ipc/netty/channel/AbortedException.java#L60

[spring-projects-issues]

Rossen Stoyanchev commented

I've created #21875 in order to differentiate between server response and client remote service exceptions like the ones above.

David Terk, as for the actual issue, to summarize, it would be very useful if you could:

1. Use the workaround in SCG for the HiddenHttpMethodFilter issue that's mentioned here.
2. Verify if the gateway succeeds in posting all the data, possibly by checking on the remote service side, to see if all looks fine there.
3. Try using the latest Reactor Netty 0.7.9 snapshot.
4. If feasible try Reactor Netty 0.8.0 (Californium) with Spring Framework 5.1.

[spring-projects-issues]

Rossen Stoyanchev commented

Resolving for now. Feel free to comment further or re-open.

[spring-projects-issues]

David Terk commented

Rossen Stoyanchev Spencer Gibb

 I am testing again on both 2.0.x and 2.1.x.  In both cases the error is not gone.  Again this is only happening with POST.

   2018-11-28T13:00:25.80-0500 [APP/PROC/WEB/0] OUT 2018-11-28 18:00:25.803 ERROR 14 --- [or-http-epoll-2] o.s.w.s.adapter.HttpWebHandlerAdapter    : [fa274997] Error [reactor.netty.channel.AbortedException: Connection has been closed] for HTTP POST "", but ServerHttpResponse already committed (200 OK)
   2018-11-28T13:00:30.22-0500 [APP/PROC/WEB/0] OUT 2018-11-28 18:00:30.228 ERROR 14 --- [or-http-epoll-1] o.s.w.s.adapter.HttpWebHandlerAdapter    : [01db2d4a] Error [reactor.netty.channel.AbortedException: Cannot publish the contentFluxMap, the connection has been closed] for HTTP POST "", but ServerHttpResponse already committed (200 OK)

 

[spring-projects-issues]

David Terk commented

Added additonal details.  Tested on 2.0.6 and 2.1.x latest versions.  No change.

[spring-projects-issues]

Rossen Stoyanchev commented

David Terk, thanks for testing and for the info but those log messages aren't enough for us to go on.

There are two parts to this issue: 1) why does the issue occur? and 2) how should it be logged? For 2) I've created #21875 to make it possible to differentiate between connection closed issues coming from the client (should be suppressed) vs from a remote server. That may help some. What we really need to understand is the root cause.

In my previous comment I made 4 suggestions for investigation that you can do on your side to get further. Without a sample we can't do that ourselves. So try those and please do try the latest Californium-BUILD-SNAPSHOT for Reactor since there have been some recent fixes related to connection closed issues.

Spencer Gibb anything you can think of on your end? Were there any recent fixes on the SCG side related to connection closed?

[spring-projects-issues]

David Terk commented

1. I have tested on 2.0.6 and Greenwich.  My understanding is that both have the fix and it doesn't do anything in this case.
2. The data is being posted correctly.
3. I used the latest 0.7.x build same issue.
4. I tried Greenwich with 0.83 (latest) again same issue.

 

[spring-projects-issues]

David Terk commented

Is it possible that this is somehow related?

spring-cloud/spring-cloud-gateway#685

In the issue there - clearly the timeout is not being reset as the connections are done and then re-used yet somehow they are being treated like old connections which haven't responded in a long time which is not the case.  Is it possible that something similar is happening here where whatever state is associated with a connection is not being purged/discarded prior to it being put back in the pool.

[spring-projects-issues]

David Terk commented

Tested again with Snapshot versions.  Same result.

 

<parent>
 <groupId>org.springframework.boot</groupId>
 <artifactId>spring-boot-starter-parent</artifactId>
 <version>2.1.1.BUILD-SNAPSHOT</version>
 <relativePath/> <!-- lookup parent from repository -->
</parent>

<properties>
 <project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
 <project.reporting.outputEncoding>UTF-8</project.reporting.outputEncoding>
 <java.version>1.8</java.version>
 <spring-cloud.version>Greenwich.BUILD-SNAPSHOT</spring-cloud.version>
 <reactor-bom.version>Californium-BUILD-SNAPSHOT</reactor-bom.version>
 <netty.version>4.1.31.Final</netty.version>
</properties>