Reactor-netty: reactor.netty.http.client.PrematureCloseException: Connection prematurely closed BEFORE response

[yantaowu]

I use spring cloud gateway as our gateway, this exception occurs in our production environment randomly when the request arrived. I search the related issue on the github and found it had been fixed, but my reactor-netty is the latest release(0.9.7).

Steps to Reproduce

It is very difficult to reproduce，which only occurs in production environment randomly.
This is the log when the exception occurs:

2020-05-12 17:31:22.948 DEBUG [reactor-http-epoll-11] [PooledConnectionProvider] [id: 0xcbc4c890, L:/172.18.206.6:23016 - R:172.18.207.3/172.18.207.3:8151] Channel acquired, now 1 active connections and 0 inactive connections
2020-05-12 17:31:22.948 DEBUG [reactor-http-epoll-11] [HttpClientConnect] [id: 0xcbc4c890, L:/172.18.206.6:23016 - R:172.18.207.3/172.18.207.3:8151] Handler is being applied: {uri=http://172.18.207.3:8151/route, method=POST}
2020-05-12 17:31:22.948 DEBUG [reactor-http-epoll-11] [PooledConnectionProvider] [id: 0xcbc4c890, L:/172.18.206.6:23016 - R:172.18.207.3/172.18.207.3:8151] onStateChange(POST{uri=/route, connection=PooledConnection{channel=[id: 0xcbc4c890, L:/172.18.206.6:23016 - R:172.18.207.3/172.18.207.3:8151]}}, [request_prepared])
2020-05-12 17:31:22.948 DEBUG [reactor-http-epoll-11] [PooledConnectionProvider] [id: 0xcbc4c890, L:/172.18.206.6:23016 - R:172.18.207.3/172.18.207.3:8151] onStateChange(POST{uri=/route, connection=PooledConnection{channel=[id: 0xcbc4c890, L:/172.18.206.6:23016 - R:172.18.207.3/172.18.207.3:8151]}}, [request_sent])
2020-05-12 17:31:22.948 DEBUG [reactor-http-epoll-11] [PooledConnectionProvider] [id: 0xcbc4c890, L:/172.18.206.6:23016 ! R:172.18.207.3/172.18.207.3:8151] Channel closed, now 0 active connections and 0 inactive connections
2020-05-12 17:31:22.948 DEBUG [reactor-http-epoll-11] [PooledConnectionProvider] [id: 0xcbc4c890, L:/172.18.206.6:23016 ! R:172.18.207.3/172.18.207.3:8151] onStateChange(POST{uri=/route, connection=PooledConnection{channel=[id: 0xcbc4c890, L:/172.18.206.6:23016 ! R:172.18.207.3/172.18.207.3:8151]}}, [response_incomplete])
2020-05-12 17:31:22.949 WARN [reactor-http-epoll-11] [HttpClientConnect] [id: 0xcbc4c890, L:/172.18.206.6:23016 ! R:172.18.207.3/172.18.207.3:8151] The connection observed an error
reactor.netty.http.client.PrematureCloseException: Connection prematurely closed BEFORE response

The configuration of spring cloud gateway:

spring.cloud.gateway.httpclient.pool.type=fixed
spring.cloud.gateway.httpclient.pool.max-connections=1000
spring.cloud.gateway.httpclient.pool.acquire-timeout=7500
spring.cloud.gateway.httpclient.pool.max-idle-time=90s
spring.cloud.gateway.httpclient.pool.max-life-time=90s

Your Environment

• reactor-netty: 0.9.7.RELEASE
• netty: 4.1.49.Final
• spring cloud gateway: 2.2.2.RELEASE
• JVM version (javar -version): jdk 1.8
• OS and version (eg uname -a): centos 6.7

[violetagg]

@yantaowu There might be several causes about this. Can you confirm that you do not have these issues:

https://github.com/reactor/reactor-netty/issues/1008
https://github.com/reactor/reactor-netty/issues/1038
https://github.com/reactor/reactor-netty/issues/564#issuecomment-576244256

[yantaowu]

@yantaowu There might be several causes about this. Can you confirm that you do not have these issues:

1008

1038

#564 (comment)

Thanks a lot. I will try my best to obtain the tcp dump and have a feedback.

[violetagg]

@yantaowu I'm closing this. We can reopen it if it is needed.

[iceqing]

same problem

2020-06-03 18:18:46,385 ERROR [7a22b978d4d1866c, 7a22b978d4d1866c] [][reactor-http-epoll-2] org.springframework.boot.autoconfigure.web.reactive.error.AbstractErrorWebExceptionHandler:122 - [db1e0f50-76]  500 Server Error for HTTP GET "/app/xxx/index?device=android&from=6.1.2"
reactor.netty.http.client.PrematureCloseException: Connection prematurely closed BEFORE response
        Suppressed: reactor.core.publisher.FluxOnAssembly$OnAssemblyException:
Error has been observed at the following site(s):
        |_ checkpoint ⇢ org.springframework.cloud.gateway.filter.WeightCalculatorWebFilter [DefaultWebFilterChain]
        |_ checkpoint ⇢ org.springframework.cloud.sleuth.instrument.web.TraceWebFilter [DefaultWebFilterChain]
        |_ checkpoint ⇢ org.springframework.boot.actuate.metrics.web.reactive.server.MetricsWebFilter [DefaultWebFilterChain]
        |_ checkpoint ⇢ HTTP GET "/app/licai/message/index?device=android&from=6.1.2" [ExceptionHandlingWebHandler]
Stack trace:

[violetagg]

@iceqing Did you check https://github.com/reactor/reactor-netty/issues/1092#issuecomment-627792713? If nothing from the links helps then create a new issue with a reproducible example.

[yantaowu]

@violetagg I obtain the tcp dump，if we can check the connection state before sending request，maybe resolve the problem。
log and tcp dump：

2020-06-04 06:58:09.151 WARN [reactor-http-epoll-8] [HttpClientConnect] [id: 0x483deb13, L:/172.18.206.6:39284 ! R:172.18.207.2/172.18.207.2:8151] The connection observed an error
reactor.netty.http.client.PrematureCloseException: Connection prematurely closed BEFORE response

[violetagg]

@yantaowu So the one with port 8151 is that the server? Why this RST is sent?

[yantaowu]

@violetagg The one with port 8151 is server. According to the dump, I think the server close the connection first, then the client with port 39284 send a request to the server, since the connection is closed, so return the RST to client.

[violetagg]

@yantaowu Why has the server closed the connection? Are there any logs on the server?

[yantaowu]

@violetagg There are no logs on the server. I have a question, why sending a request to the server on the closed connection. Could we check the connection state before sending the request?

[yantaowu]

@violetagg The post request with path "/route" is the request to the server, but the connection has been closed before sending at this time.

[yangbongsoo]

when I made poor server that send response header only(not response body)
the result is Connection prematurely closed DURING response
cf ) https://github.com/reactor/reactor-netty/issues/1037#issuecomment-602444231

so I think that PrematureCloseException is not always a reactor-netty problem.

[violetagg]

@yantaowu The connection state is checked several times before issuing the request.

1. before acquiring from the pool
   https://github.com/reactor/reactor-netty/blob/1cab53a2503ff06399ed1bc4e92aa6f4d5d01dc2/src/main/java/reactor/netty/resources/PooledConnectionProvider.java#L686
2. after acquiring from the pool
   https://github.com/reactor/reactor-netty/blob/1cab53a2503ff06399ed1bc4e92aa6f4d5d01dc2/src/main/java/reactor/netty/resources/PooledConnectionProvider.java#L523
3. before sending the request
   https://github.com/reactor/reactor-netty/blob/1cab53a2503ff06399ed1bc4e92aa6f4d5d01dc2/src/main/java/reactor/netty/http/HttpOperations.java#L166

So it is important to understand the scenario when this happens and why the server closed the connection.

[yantaowu]

@yantaowu The connection state is checked several times before issuing the request.

1. before acquiring from the pool
   https://github.com/reactor/reactor-netty/blob/1cab53a2503ff06399ed1bc4e92aa6f4d5d01dc2/src/main/java/reactor/netty/resources/PooledConnectionProvider.java#L686
2. after acquiring from the pool
   https://github.com/reactor/reactor-netty/blob/1cab53a2503ff06399ed1bc4e92aa6f4d5d01dc2/src/main/java/reactor/netty/resources/PooledConnectionProvider.java#L523
3. before sending the request
   https://github.com/reactor/reactor-netty/blob/1cab53a2503ff06399ed1bc4e92aa6f4d5d01dc2/src/main/java/reactor/netty/http/HttpOperations.java#L166

So it is important to understand the scenario when this happens and why the server closed the connection.

Thank you very much.

[ehongyu]

+1
Got the same / similar problems from time to time in production. It happens with both the old version and the latest 0.9.7.RELEASE in Spring webflux:

nested exception is reactor.core.Exceptions$ReactiveException: reactor.netty.http.client.PrematureCloseException: Connection prematurely closed BEFORE response] with root cause
reactor.netty.http.client.PrematureCloseException: Connection prematurely closed BEFORE response
        Suppressed: reactor.core.publisher.FluxOnAssembly$OnAssemblyException:

[violetagg]

@ehongyu And you checked https://github.com/reactor/reactor-netty/issues/1092#issuecomment-628433209 and it is nothing from the list. Can you take a tcp dump? I would really appreciate if you start a new issue related to your use case. It might seems similar but it might appear that it is a different root cause.

[ehongyu]

I wish I could get a tcpdump, but this annoying issue only happened once in a while on the production box and our company's production box is beyond our reach.

[iceqing]

I get a tcpdump.

2020-06-19 15:23:22,186 ERROR [183a4835e96dd39f, 183a4835e96dd39f] [][reactor-http-epoll-4] org.springframework.boot.au
toconfigure.web.reactive.error.AbstractErrorWebExceptionHandler:122 - [f762e0e8-47621]  500 Server Error for HTTP GET "
/app/licai/message/index/not_login"
reactor.netty.http.client.PrematureCloseException: Connection prematurely closed BEFORE response
        Suppressed: reactor.core.publisher.FluxOnAssembly$OnAssemblyException:
Error has been observed at the following site(s):
        |_ checkpoint ⇢ org.springframework.cloud.gateway.filter.WeightCalculatorWebFilter [DefaultWebFilterChain]
        |_ checkpoint ⇢ org.springframework.cloud.sleuth.instrument.web.TraceWebFilter [DefaultWebFilterChain]
        |_ checkpoint ⇢ org.springframework.boot.actuate.metrics.web.reactive.server.MetricsWebFilter [DefaultWebFilter
Chain]
        |_ checkpoint ⇢ HTTP GET "/app/licai/message/index/not_login" [ExceptionHandlingWebHandler]
Stack trace:

client(10.157.122.166):

server(10.138.7.86):

[violetagg]

@iceqing So do you have some logs on the server that indicate why the server closes the connection?

[violetagg]

From the linked issue https://github.com/spring-cloud/spring-cloud-gateway/issues/1148

It appears that the server is Tomcat with configurations

connectionTimeout | The number of milliseconds this Connector will wait, after accepting a connection, for the request URI line to be presented. Use a value of -1 to indicate no (i.e. infinite) timeout. The default value is 60000 (i.e. 60 seconds) but note that the standard server.xml that ships with Tomcat sets this to 20000 (i.e. 20 seconds). Unless disableUploadTimeout is set to false, this timeout will also be used when reading the request body (if any).

and

keepAliveTimeout | The number of milliseconds this Connector will wait for another HTTP request before closing the connection. The default value is to use the value that has been set for the connectionTimeout attribute. Use a value of -1 to indicate no (i.e. infinite) timeout.

These two configurations might be a cause for a connection close.

I would recommend to configure maxIdleTime on the client side having in mind the keepAliveTimeout on Tomcat. Without such configuration Reactor Netty can receive the close event at any time between acquiring the connection from the pool and before actual sending of the request. Also you might want to switch to LIFO leasing strategy so that you will use always the most recently used connection.