UnexpectedConnectionClosureException errors

[marcellustavares]

Hi team,

I’m investigating an issue in my application server logs, and I can see several entries related to abrupt connection interruptions before server response.

I've tried to simulate the error locally by configuring a server keepAlive timeout to 5s and I can see a similar error in the logs. The server closes the connection between request 2 and 3, however Pekko apparently does not recover and fails the third request.

I was wondering if Pekko should verify the connection state before failing the request? Any insights are appreciated.

Thanks

Client.log

[Client] Sending 2 request at 09:04:07.715981
15546 [PekkoHttpClientReproducer-pekko.actor.default-dispatcher-6] DEBUG org.apache.pekko.http.impl.engine.client.PoolId  - Dispatching request [GET / Empty] to pool
15546 [PekkoHttpClientReproducer-pekko.actor.default-dispatcher-6] DEBUG org.apache.pekko.http.impl.engine.client.PoolId  - [0 (Idle)]Dispatching request [GET / Empty]
15546 [PekkoHttpClientReproducer-pekko.actor.default-dispatcher-6] DEBUG org.apache.pekko.http.impl.engine.client.PoolId  - [0 (Idle)]Before event [onNewRequest] In state [Idle] for [3448 ms]
15547 [PekkoHttpClientReproducer-pekko.actor.default-dispatcher-6] DEBUG org.apache.pekko.http.impl.engine.client.PoolId  - [0 (PushingRequestToConnection)]After event [onNewRequest] State change [Idle] -> [PushingRequestToConnection]
15547 [PekkoHttpClientReproducer-pekko.actor.default-dispatcher-6] DEBUG org.apache.pekko.http.impl.engine.client.PoolId  - [0 (PushingRequestToConnection)]Before event [onRequestDispatched] In state [PushingRequestToConnection] for [0 ms]
15547 [PekkoHttpClientReproducer-pekko.actor.default-dispatcher-6] DEBUG org.apache.pekko.http.impl.engine.client.PoolId  - [0 (WaitingForResponse)]After event [onRequestDispatched] State change [PushingRequestToConnection] -> [WaitingForResponse]
20554 [PekkoHttpClientReproducer-pekko.actor.default-dispatcher-6] DEBUG org.apache.pekko.http.impl.engine.client.PoolId  - [0 (WaitingForResponse)]Received response
20555 [PekkoHttpClientReproducer-pekko.actor.default-dispatcher-6] DEBUG org.apache.pekko.http.impl.engine.client.PoolId  - [0 (WaitingForResponse)]Before event [onResponseReceived] In state [WaitingForResponse] for [5007 ms]
20555 [PekkoHttpClientReproducer-pekko.actor.default-dispatcher-6] DEBUG org.apache.pekko.http.impl.engine.client.PoolId  - [0 (WaitingForResponse)]onResponseReceived in WaitingForResponse with false
20555 [PekkoHttpClientReproducer-pekko.actor.default-dispatcher-6] DEBUG org.apache.pekko.http.impl.engine.client.PoolId  - [0 (WaitingForResponseDispatch)]After event [onResponseReceived] State change [WaitingForResponse] -> [WaitingForResponseDispatch]
20555 [PekkoHttpClientReproducer-pekko.actor.default-dispatcher-6] DEBUG org.apache.pekko.http.impl.engine.client.PoolId  - [0 (WaitingForResponseDispatch)]Before event [onResponseDispatchable] In state [WaitingForResponseDispatch] for [0 ms]
20556 [PekkoHttpClientReproducer-pekko.actor.default-dispatcher-6] DEBUG org.apache.pekko.http.impl.engine.client.PoolId  - [0 (WaitingForResponseEntitySubscription)]After event [onResponseDispatchable] State change [WaitingForResponseDispatch] -> [WaitingForResponseEntitySubscription]
20556 [PekkoHttpClientReproducer-pekko.actor.default-dispatcher-6] DEBUG org.apache.pekko.http.impl.engine.client.PoolId  - [0 (WaitingForResponseEntitySubscription)]Before event [onResponseEntitySubscribed] In state [WaitingForResponseEntitySubscription] for [0 ms]
20556 [PekkoHttpClientReproducer-pekko.actor.default-dispatcher-6] DEBUG org.apache.pekko.http.impl.engine.client.PoolId  - [0 (WaitingForEndOfResponseEntity)]After event [onResponseEntitySubscribed] State change [WaitingForResponseEntitySubscription] -> [WaitingForEndOfResponseEntity]
20556 [PekkoHttpClientReproducer-pekko.actor.default-dispatcher-6] DEBUG org.apache.pekko.http.impl.engine.client.PoolId  - [0 (WaitingForEndOfResponseEntity)]Before event [onResponseEntityCompleted] In state [WaitingForEndOfResponseEntity] for [0 ms]
20556 [PekkoHttpClientReproducer-pekko.actor.default-dispatcher-6] DEBUG org.apache.pekko.http.impl.engine.client.PoolId  - [0 (Idle)]After event [onResponseEntityCompleted] State change [WaitingForEndOfResponseEntity] -> [Idle]
20556 [PekkoHttpClientReproducer-pekko.actor.default-dispatcher-8] DEBUG org.apache.pekko.http.impl.engine.client.PoolId  - [0 (Idle)]Slot became idle... Trying to pull
[Client] 2 Response: 200 OK at 09:04:12.727531


[Client] Sending 3 request at 09:04:20.548659
28379 [PekkoHttpClientReproducer-pekko.actor.default-dispatcher-5] DEBUG org.apache.pekko.http.impl.engine.client.PoolId  - Dispatching request [GET / Empty] to pool
28379 [PekkoHttpClientReproducer-pekko.actor.default-dispatcher-5] DEBUG org.apache.pekko.http.impl.engine.client.PoolId  - [0 (Idle)]Dispatching request [GET / Empty]
28379 [PekkoHttpClientReproducer-pekko.actor.default-dispatcher-5] DEBUG org.apache.pekko.http.impl.engine.client.PoolId  - [0 (Idle)]Before event [onNewRequest] In state [Idle] for [7823 ms]
28379 [PekkoHttpClientReproducer-pekko.actor.default-dispatcher-5] DEBUG org.apache.pekko.http.impl.engine.client.PoolId  - [0 (PushingRequestToConnection)]After event [onNewRequest] State change [Idle] -> [PushingRequestToConnection]
28379 [PekkoHttpClientReproducer-pekko.actor.default-dispatcher-5] DEBUG org.apache.pekko.http.impl.engine.client.PoolId  - [0 (PushingRequestToConnection)]Before event [onRequestDispatched] In state [PushingRequestToConnection] for [0 ms]
28379 [PekkoHttpClientReproducer-pekko.actor.default-dispatcher-5] DEBUG org.apache.pekko.http.impl.engine.client.PoolId  - [0 (WaitingForResponse)]After event [onRequestDispatched] State change [PushingRequestToConnection] -> [WaitingForResponse]
28383 [PekkoHttpClientReproducer-pekko.actor.default-dispatcher-5] DEBUG org.apache.pekko.http.impl.engine.client.PoolId  - [0 (WaitingForResponse)]Connection failed
28383 [PekkoHttpClientReproducer-pekko.actor.default-dispatcher-5] DEBUG org.apache.pekko.http.impl.engine.client.PoolId  - [0 (WaitingForResponse)]Before event [onConnectionFailed] In state [WaitingForResponse] for [3 ms]
28383 [PekkoHttpClientReproducer-pekko.actor.default-dispatcher-5] DEBUG org.apache.pekko.http.impl.engine.client.PoolId  - [0 (WaitingForResponse)]Ongoing request [GET / Empty] is failed because of [connection failure]: [The http server closed the connection unexpectedly before delivering responses for 1 outstanding requests]
28383 [PekkoHttpClientReproducer-pekko.actor.default-dispatcher-5] DEBUG org.apache.pekko.http.impl.engine.client.PoolId  - [0 (WaitingForResponseDispatch)]After event [onConnectionFailed] State change [WaitingForResponse] -> [WaitingForResponseDispatch]
28383 [PekkoHttpClientReproducer-pekko.actor.default-dispatcher-5] DEBUG org.apache.pekko.http.impl.engine.client.PoolId  - [0 (WaitingForResponseDispatch)]Before event [onResponseDispatchable] In state [WaitingForResponseDispatch] for [0 ms]
28383 [PekkoHttpClientReproducer-pekko.actor.default-dispatcher-5] DEBUG org.apache.pekko.http.impl.engine.client.PoolId  - [0 (Failed)]After event [onResponseDispatchable] State change [WaitingForResponseDispatch] -> [Failed]
28384 [PekkoHttpClientReproducer-pekko.actor.default-dispatcher-5] DEBUG org.apache.pekko.http.impl.engine.client.PoolId  - [0 (Failed)]State change from [WaitingForResponseDispatch] to [Failed(org.apache.pekko.http.impl.engine.client.OutgoingConnectionBlueprint$UnexpectedConnectionClosureException: The http server closed the connection unexpectedly before delivering responses for 1 outstanding requests)]. Closing the existing connection.
28385 [PekkoHttpClientReproducer-pekko.actor.default-dispatcher-5] DEBUG org.apache.pekko.http.impl.engine.client.PoolId  - [0 (Unconnected)]Slot became idle... Trying to pull
28385 [PekkoHttpClientReproducer-pekko.actor.default-dispatcher-5] DEBUG org.apache.pekko.http.impl.engine.client.PoolId  - [0 (Unconnected)]Preconnecting because number of connected slots fell down to 0
28385 [PekkoHttpClientReproducer-pekko.actor.default-dispatcher-5] DEBUG org.apache.pekko.http.impl.engine.client.PoolId  - [0 (Unconnected)]Before event [onPreConnect] In state [Unconnected] for [0 ms]
28385 [PekkoHttpClientReproducer-pekko.actor.default-dispatcher-5] DEBUG org.apache.pekko.http.impl.engine.client.PoolId  - [0 (Unconnected)]Establishing connection
28386 [PekkoHttpClientReproducer-pekko.actor.default-dispatcher-5] DEBUG org.apache.pekko.http.impl.engine.client.PoolId  - [0 (PreConnecting)]After event [onPreConnect] State change [Unconnected] -> [PreConnecting]
[Client] 3 Failed: The http server closed the connection unexpectedly before delivering responses for 1 outstanding requests at 09:04:20.556410
unknown exception The http server closed the connection unexpectedly before delivering responses for 1 outstanding requests

Server.log

[Server] NEW connection from ::ffff:127.0.0.1:57861 at 9:03:52 AM
incoming request #0
responding request #0
request closed
incoming request #1
responding request #1
request closed
incoming request #2
responding request #2
request closed
[Server] CLOSE Connection ::ffff:127.0.0.1:57861 at 9:04:18 AM
[Server] NEW connection from ::ffff:127.0.0.1:57877 at 9:04:33 AM
incoming request #4
responding request #4
request closed
[Server] CLOSE Connection ::ffff:127.0.0.1:57877 at 9:04:44 AM

[pjfanning]

Maybe related to akka/akka-http#3759 and akka/akka-http#3834

Our docs have this advice which may or may not be relevant.
https://pekko.apache.org/docs/pekko-http/current/common/timeouts.html#keep-alive-timeout