Netty connection in pool reset by peer in Spring Cloud Gateway Application

[clavinovahan]

We use Spring Cloud Gateway with Spring Security OAuth2.

SpringBoot version: 2.2.1
Spring Cloud version: Hoxton.Release
Netty: reactor-netty-0.9.2.RELEASE

The Spring security OAuth2 filter post request to UAA server, there is load balancer in between. While initially connection all good but after about 10-15 min, Netty used Spring OAuth2 filter got connection reset by peer and the other end is load balancer. If try again, then it will work. But after another 10-15 min, the problem happens again.

The log shows reactor.netty.resources.PooledConnectionProvider uses some active channel but it is actually not active. We are seeking solution to work around it. So far we tried
to customize Netty ClientHttpConnector (code as below) to disable pool, but no success. It seems that bean has no effect on Netty used by Spring security.

I uploaded demo project at GitHub link below,
spring-cloud/spring-cloud-gateway#1493

That project cannot produce problem at local as there is no load balancer between but it shows the way to customize ClientHttpConnector used by Spring Security to disable Netty Pool does not work.

@bean
public ClientHttpConnector clientHttpConnector() {
return new ReactorClientHttpConnector(HttpClient.create(ConnectionProvider.newConnection()));
}

From Netty side, is there any solution or work around to this issue? Since our project is due soon in production, any work around we are considering. If you could point out where in Netty code, we can disable the pool as a temporary solutions so that we can move forward and revisit this issue later on.

Here is the logs:

2019-12-19 18:07:53.460 DEBUG 7 --- [reactor-http-epoll-1] o.s.w.r.f.client.ExchangeFunctions       : [1b45ced7] HTTP POST https://server-name/oauth/token
2019-12-19 18:07:53.462 DEBUG 7 --- [reactor-http-epoll-4] r.n.resources.PooledConnectionProvider   : [id: 0x2a4d88b0, L:/xxx.xxx.xxx.xxx:38628 - R:xxx.xxx.xxx.xxx:443] Channel acquired, now 1 active connections and 1 inactive connections
2019-12-19 18:07:53.463 DEBUG 7 --- [reactor-http-epoll-4] r.netty.http.client.HttpClientConnect    : [id: 0x2a4d88b0, L:/xxx.xxx.xxx.xxx:38628 - R:xxx.xxx.xxx.xxx:443] Handler is being applied: {uri=https://server-name/oauth/token, method=POST}
2019-12-19 18:07:53.466 DEBUG 7 --- [reactor-http-epoll-4] o.s.http.codec.FormHttpMessageWriter     : [1b45ced7] Writing form fields [grant_type, code, redirect_uri] (content masked)
2019-12-19 18:07:53.471 DEBUG 7 --- [reactor-http-epoll-4] r.n.resources.PooledConnectionProvider   : [id: 0x2a4d88b0, L:/xxx.xxx.xxx.xxx:38628 - R:xxx.xxx.xxx.xxx:443] onStateChange(POST{uri=/oauth/token, connection=PooledConnection{channel=[id: 0x2a4d88b0, L:/xxx.xxx.xxx.xxx:38628 - R:xxx.xxx.xxx.xxx:443]}}, [request_sent])
2019-12-19 18:07:53.474 DEBUG 7 --- [reactor-http-epoll-4] r.netty.http.client.HttpClientConnect    : [id: 0x2a4d88b0, L:/xxx.xxx.xxx.xxx:38628 - R:xxx.xxx.xxx.xxx:443] The connection observed an error, the request will be retried

io.netty.channel.unix.Errors$NativeIoException: readAddress(..) failed: Connection reset by peer

2019-12-19 18:07:53.475 DEBUG 7 --- [reactor-http-epoll-4] r.n.resources.PooledConnectionProvider   : [id: 0x9bf92ed9, L:/xxx.xxx.xxx.xxx:38600 - R:xxx.xxx.xxx.xxx:443] Channel acquired, now 2 active connections and 0 inactive connections
2019-12-19 18:07:53.476 DEBUG 7 --- [reactor-http-epoll-4] r.netty.http.client.HttpClientConnect    : [id: 0x9bf92ed9, L:/xxx.xxx.xxx.xxx:38600 - R:xxx.xxx.xxx.xxx:443] Handler is being applied: {uri=https://server-name/oauth/token, method=POST}
2019-12-19 18:07:53.479 DEBUG 7 --- [reactor-http-epoll-4] o.s.http.codec.FormHttpMessageWriter     : [1b45ced7] Writing form fields [grant_type, code, redirect_uri] (content masked)
2019-12-19 18:07:53.492 DEBUG 7 --- [reactor-http-epoll-4] r.n.resources.PooledConnectionProvider   : [id: 0x9bf92ed9, L:/xxx.xxx.xxx.xxx:38600 - R:xxx.xxx.xxx.xxx:443] onStateChange(POST{uri=/oauth/token, connection=PooledConnection{channel=[id: 0x9bf92ed9, L:/xxx.xxx.xxx.xxx:38600 - R:xxx.xxx.xxx.xxx:443]}}, [request_sent])
2019-12-19 18:07:53.507 DEBUG 7 --- [reactor-http-epoll-4] r.n.resources.PooledConnectionProvider   : [id: 0x2a4d88b0, L:/xxx.xxx.xxx.xxx:38628 ! R:xxx.xxx.xxx.xxx:443] Channel closed, now 2 active connections and 0 inactive connections
2019-12-19 18:07:53.517 DEBUG 7 --- [reactor-http-epoll-4] r.n.resources.PooledConnectionProvider   : [id: 0x2a4d88b0, L:/xxx.xxx.xxx.xxx:38628 ! R:xxx.xxx.xxx.xxx:443] onStateChange(POST{uri=/oauth/token, connection=PooledConnection{channel=[id: 0x2a4d88b0, L:/xxx.xxx.xxx.xxx:38628 ! R:xxx.xxx.xxx.xxx:443]}}, [disconnecting])
2019-12-19 18:07:53.518 DEBUG 7 --- [reactor-http-epoll-4] r.n.resources.PooledConnectionProvider   : [id: 0x2a4d88b0, L:/xxx.xxx.xxx.xxx:38628 ! R:xxx.xxx.xxx.xxx:443] Releasing channel
2019-12-19 18:07:53.523 DEBUG 7 --- [reactor-http-epoll-4] r.n.resources.PooledConnectionProvider   : [id: 0x2a4d88b0, L:/xxx.xxx.xxx.xxx:38628 ! R:xxx.xxx.xxx.xxx:443] Channel cleaned, now 1 active connections and 0 inactive connections
2019-12-19 18:07:53.532 DEBUG 7 --- [reactor-http-epoll-4] r.netty.http.client.HttpClientConnect    : [id: 0x9bf92ed9, L:/xxx.xxx.xxx.xxx:38600 - R:xxx.xxx.xxx.xxx:443] The connection observed an error, the request will be retried

io.netty.channel.unix.Errors$NativeIoException: readAddress(..) failed: Connection reset by peer

2019-12-19 18:07:53.543 ERROR 7 --- [reactor-http-epoll-4] o.s.w.s.adapter.HttpWebHandlerAdapter    : [177851e0] 500 Server Error for HTTP GET "/login/oauth2/code/myapp?code=Jo87
qf1XIC&state=yMYngnlcVyuy8BgpgFGxZDwo0nmwYg7pa4mcvROTtrU%3D"

io.netty.channel.unix.Errors$NativeIoException: readAddress(..) failed: Connection reset by peer
        Suppressed: reactor.core.publisher.FluxOnAssembly$OnAssemblyException:
Error has been observed at the following site(s):
        |_ checkpoint  Request to POST https://server-name/oauth/token [DefaultWebClient]
        |_ checkpoint  org.springframework.security.oauth2.client.web.server.authentication.OAuth2LoginAuthenticationWebFilter [DefaultWebFilterChain]

[violetagg]

please provide TCP dump so that we can see which component is responsible for dropping the connection

[clavinovahan]

@violetagg,

Thanks for looking into this issue. Due to constraints, I am not sure if I am allowed to send the TCP dump. The application is deployed in cloud. Between our application and IDP server which application try to Post request to, there is AWS load Balancer (LB). The LB usually drops connection in 15 min idle. There is not much we can do at this point.

The log already clearly shows Peer resets connection which is LB.

2019-12-19 18:07:53.532 DEBUG 7 --- [reactor-http-epoll-4] r.netty.http.client.HttpClientConnect : [id: 0x9bf92ed9, L:/(Our app server IP address):38600 - R:(Load balancer IP address):443] The connection observed an error, the request will be retried
io.netty.channel.unix.Errors$NativeIoException: readAddress(..) failed: Connection reset by peer

The issue here is that how Netty Pool health check working, every 5 min, 30 min, etc? What kind of algorithm to do recovery? When connection get reset, I do see Netty retries 2-3 times by picking up the connection from pool, however, usually for this case, LB drop idle connection, they could drop all the connections in the pool which are idle. So retry never works.

I am think if Netty could improve its algorithm, if one connection bad, then dispose it and create new connection instead of picking up from pool once again, after that put that new connection into pool.

Our application is nearly in PROD and we are pending on the workaround or fix on this issue. Is it possible for Netty to have a quick patch or make a temp release to work around this issue so we can move forward and revisit this issue later on?

We tried disable Netty connection Pool, however Spring security creates its own webclient, not our application, and we tried different ways to customize it but no effective.

I uploaded demo project at GitHub link below to show the ways we try to disable the Netty Pool
spring-cloud/spring-cloud-gateway#1493
but so far nothing works.

So again Netty is a wonderful lib and Spring Cloud Gateway/WebFlux leverage on it. But when more and more applications leverage those technologies goes to PROD, especially to cloud, most of them will face load balancing and this issue will impact Netty in long run if all those applications have to disable pool or set HTTP_LIVE false or manipulate the timeout at application level.

[violetagg]

@hanscrg We check the health of the connection before using it
https://github.com/reactor/reactor-netty/blob/master/src/main/java/reactor/netty/resources/ConnectionProvider.java#L198
https://github.com/reactor/reactor-netty/blob/master/src/main/java/reactor/netty/resources/PooledConnectionProvider.java#L218
See the eviction predicate.
A connection that is closed, idle more than the specified time or have life more that specified time will be evicted.
If you cannot provide TCP dump then you can check it by yourself - when exactly the connection is closed.

From the logs above I can clearly see that the connection was ok at the beginning.

The LB usually drops connection in 15 min idle.

This can happen between our acquiring of the connection and sending the request.

By default there is neither idle timeout nor life time. So you have to configure them.

We retry only once when such issue happens, but the component that uses Reactor Netty may apply other strategy for retrying such issues (for example retry with backoff).

Also from the logs above I see the following:

• Channels with id 0x2a4d88b0 && 0x9bf92ed9 are retried
• Channel with id 177851e0 has 500 ISE no more information from the provided logs
• Channel with id 1b45ced7 has successful communication

Please note that everything is non-blocking so that you cannot correlate using thread id, because of that you have to use the channel id.

[clavinovahan]

@violetagg,
Thanks for looking into this issue. I will see if I could send out TCP dump. Question is what is gap in time when Netty checks the connection health and using that connection to send http request?

If Netty by default no idle timeout and life time. Then if Spring Security using Reactor Netty HTTP Client does not set those parameters, then the connection will be there all the time and for sure it will be disconnected by Load Balancer.

As I previously mentioned, retry by picking up the existing connection in the pool has a big risk that may have been disconnected also that makes retry not work most of time. I can see many reports on Netty connection reset, which most likely is due to load balancer or something in between drops connection. For some of the applications they have control on the Netty HTTP Client, they can apply different ways to recover. But for Spring applications leverage Spring Security, it creates HTTP Client on its own and the application do not have much control. Maybe Netty could optimize its recovery algorithm for this case, when doing retry, create new connection instead of reuse one in the pool.

I will update you more info when I look into our logs or if I can send TCP dump.

[violetagg]

If Netty by default no idle timeout and life time. Then if Spring Security using Reactor Netty HTTP Client does not set those parameters

They can expose a configuration. I think that if you have the configuration above you will be able to solve your use case. If that's not the case we can think of exposing an API for specifying the eviction.

But for Spring applications leverage Spring Security, it creates HTTP Client on its own and the application do not have much control.

There are different retry strategies (also have in mind that we retry only when there is Connection reset by peer) so I prefer the components (especially those working with sensitive data) that use Reactor Netty to define the retry functionality based on the strategy that they want and the exceptions that they want to handle.

Did you check Spring Security samples https://github.com/spring-projects/spring-security/tree/master/samples/boot/oauth2webclient-webflux
or this type of configuration is not sufficient for your use case?

[clavinovahan]

@violetagg
Thanks for the response. From the feedback from Spring Cloud Gateway, there is no configuration that works at their side as the WebClient is created in Spring Security and I have not get feedback from Spring Security yet. The Spring Security samples at the link above I looked through and does not find the way to customize the WebClient or ClientHTTPConnection which Spring Security uses. Also disable connection pool anyway is really a workaround and not the perfect solution even we can get it working.

I think the retry strategies should be implemented at the lower level which is Reactor Netty. Netty can define different strategies for example, Reuse First then New or New Only or Reuse Only, etc, by default Reuse First then New. WebClient or higher level components or lib which uses Netty has the option to choose the retry strategies based on their focus either on reliability or efficiency.

For applications moving to cloud or any application has load balancer which leverages Spring Security, this issue will become outstanding, I believe. I saw many posts which try different ways to work around it, disable pool, set HTTP_LIVE false, switch to undertow, set builder to native or tuning timeout parameters or even update their load balancing algorithm. That is not the situation which Netty want to see. Please consider a quick patch or fix if possible.

Meanwhile I am still checking with our management to see if I could get approval to send out TCPDump. If Netty has patch or fix, we can help to test it as soon as possible.

[odbuser2]

I believe this is still occurring under:

SpringBoot version: 2.2.2
Spring Cloud version: Hoxton.SR1
Netty: reactor-netty-0.9.2.RELEASE

Is there a better strategy to prevent the this? I concur with the complication that Spring Security introduces. The configuration is not exposed so the default behavior of Netty should be updated to in Netty (actually for any api that wraps Netty).

@hanscrg did you find a better way to handle this?

[clavinovahan]

@odbuser2, I tried boot 2.2.2 and Hoxton.SR1, the issue is still there. Actually the root of issue is Netty connection pool in Spring Security. Once the connection(channel) in pool dropped by network components after idle time 15min (very possible no RST send out), all the idle connections in pool do not work which Netty does not detect until it try to reuse the connection. Either Spring Security need to expose the HTTP Client configuration so we can disable the pool or Netty need to enhance the connection pool retry algorithm. I think disable pool is just a workaround even if Spring Security has such way which I do not find yet. The perfect solution is Netty enhance the retry algorithm.

With more API wraps Netty and connection pool is used, this issue will be more outstanding.

For us there is no better way to handle it, we just did some workaround at our application level to catch the exception and resend the request. We are still waiting for Netty to give a solution or Spring security to expose some way to disable its connection pool.