I am running a spring cloud gateway and I am hitting a reproducible issue I don't understand. I have a route in the gateway that redirects to another webapp which exposes actuator endpoints, the scenario is the following:
- When I request actuator/logfile then actuator/health, a connection is reused from the connection pool I got a PrematureCloseException on the second call. The log file is approx' 70MB.
- When I request actuator/health even 200 times, I never got an error and the pool behaves correctly (reuse and recreates connections).
Below are the logs with the first scenario when it fails. I don't understand the "Channel closed" while there is an active connection.
Disabling the pool fixes the issue and setting timeouts (max-lifetime/max-idle) also works with very low value which is like disabling the pool. Waiting a couple seconds between the calls also works as a new connection is used.
2022-06-15 16:59:51,523 r.n.r.PooledConnectionProvider: [a3b5326c] Created a new pooled channel, now: 0 active connections, 0 inactive connections and 0 pending acquire requests.
2022-06-15 16:59:51,580 r.n.r.DefaultPooledConnectionProvider: [a3b5326c, L:/*** - R:***] Registering pool release on close event for channel
2022-06-15 16:59:51,580 r.n.r.PooledConnectionProvider: [a3b5326c, L:/*** - R:***] Channel connected, now: 1 active connections, 0 inactive connections and 0 pending acquire requests.
2022-06-15 16:59:51,617 r.n.r.DefaultPooledConnectionProvider: [a3b5326c, L:/*** - R:***] onStateChange(PooledConnection{channel=[id: 0xa3b5326c, L:/*** - R:***]}, [connected])
2022-06-15 16:59:51,618 r.n.r.DefaultPooledConnectionProvider: [a3b5326c-1, L:/*** - R:***] onStateChange(GET{uri=/, connection=PooledConnection{channel=[id: 0xa3b5326c, L:/*** - R:***]}}, [configured])
2022-06-15 16:59:51,618 r.n.h.c.HttpClientConnect: [a3b5326c-1, L:/*** - R:***] Handler is being applied: {uri=***/actuator/logfile, method=GET}
2022-06-15 16:59:51,618 r.n.r.DefaultPooledConnectionProvider: [a3b5326c-1, L:/*** - R:***] onStateChange(GET{uri=/zas-eessi-webapp/actuator/logfile, connection=PooledConnection{channel=[id: 0xa3b5326c, L:/*** - R:***]}}, [request_prepared])
2022-06-15 16:59:51,618 r.n.r.DefaultPooledConnectionProvider: [a3b5326c-1, L:/*** - R:***] onStateChange(GET{uri=/zas-eessi-webapp/actuator/logfile, connection=PooledConnection{channel=[id: 0xa3b5326c, L:/*** - R:***]}}, [request_sent])
2022-06-15 16:59:51,654 r.n.h.c.HttpClientOperations: [a3b5326c-1, L:/*** - R:***] Received response (auto-read:false) : [Date=Wed, 15 Jun 2022 14:59:51 GMT, Server=Apache, Vary=Origin,Access-Control-Request-Method,Access-Control-Request-Headers, Accept-Ranges=bytes, X-Content-Type-Options=nosniff, X-XSS-Protection=1; mode=block, Cache-Control=no-cache, no-store, max-age=0, must-revalidate, Pragma=no-cache, Expires=0, Strict-Transport-Security=max-age=31536000 ; includeSubDomains, X-Frame-Options=DENY, Content-Type=text/plain;charset=UTF-8, content-length=78644765]
2022-06-15 16:59:51,654 r.n.r.DefaultPooledConnectionProvider: [a3b5326c-1, L:/*** - R:***] onStateChange(GET{uri=/zas-eessi-webapp/actuator/logfile, connection=PooledConnection{channel=[id: 0xa3b5326c, L:/*** - R:***]}}, [response_received])
2022-06-15 17:00:09,625 r.n.h.c.HttpClientOperations: [a3b5326c-1, L:/*** - R:***] Received last HTTP packet
2022-06-15 17:00:09,625 r.n.r.DefaultPooledConnectionProvider: [a3b5326c, L:/*** - R:***] onStateChange(GET{uri=/zas-eessi-webapp/actuator/logfile, connection=PooledConnection{channel=[id: 0xa3b5326c, L:/*** - R:***]}}, [response_completed])
2022-06-15 17:00:09,625 r.n.r.DefaultPooledConnectionProvider: [a3b5326c, L:/*** - R:***] onStateChange(GET{uri=/zas-eessi-webapp/actuator/logfile, connection=PooledConnection{channel=[id: 0xa3b5326c, L:/*** - R:***]}}, [disconnecting])
2022-06-15 17:00:09,625 r.n.r.DefaultPooledConnectionProvider: [a3b5326c, L:/*** - R:***] Releasing channel
2022-06-15 17:00:09,625 r.n.r.PooledConnectionProvider: [a3b5326c, L:/*** - R:***] Channel cleaned, now: 0 active connections, 1 inactive connections and 0 pending acquire requests.
2022-06-15 17:00:10,995 r.n.r.PooledConnectionProvider: [a3b5326c, L:/*** - R:***] Channel acquired, now: 1 active connections, 0 inactive connections and 0 pending acquire requests.
2022-06-15 17:00:10,995 r.n.h.c.HttpClientConnect: [a3b5326c-2, L:/*** - R:***] Handler is being applied: {uri=***/actuator/health, method=GET}
2022-06-15 17:00:10,995 r.n.r.DefaultPooledConnectionProvider: [a3b5326c-2, L:/*** - R:***] onStateChange(GET{uri=/zas-eessi-webapp/actuator/health, connection=PooledConnection{channel=[id: 0xa3b5326c, L:/*** - R:***]}}, [request_prepared])
2022-06-15 17:00:10,996 r.n.r.DefaultPooledConnectionProvider: [a3b5326c-2, L:/*** - R:***] onStateChange(GET{uri=/zas-eessi-webapp/actuator/health, connection=PooledConnection{channel=[id: 0xa3b5326c, L:/*** - R:***]}}, [request_sent])
2022-06-15 17:00:26,034 r.n.r.PooledConnectionProvider: [a3b5326c-2, L:/*** ! R:***] Channel closed, now: 0 active connections, 0 inactive connections and 0 pending acquire requests.
2022-06-15 17:00:26,034 r.n.r.DefaultPooledConnectionProvider: [a3b5326c-2, L:/*** ! R:***] onStateChange(GET{uri=/zas-eessi-webapp/actuator/health, connection=PooledConnection{channel=[id: 0xa3b5326c, L:/*** ! R:***]}}, [response_incomplete])
2022-06-15 17:00:26,034 WARN r.n.h.c.HttpClientConnect: [a3b5326c-2, L:/*** ! R:***] The connection observed an error
reactor.netty.http.client.PrematureCloseException: Connection prematurely closed BEFORE response
Versions:
- Spring cloud gateway 2021.0.3
- reactor-netty 1.0.19.
- Java 11