apache / apache/pekko-http

UnexpectedConnectionClosureException errors

Open
#705 1 comment 0 reactions 0 assignees View on GitHub
Dominant language
Scala
Stars
196
Forks
55
Avg merge
4d 52m
Merged PRs (30d)
74

Description

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
```

Contributor guide

Open the contributing guide

Research direction

Reproduce the client/server sequence with the server keep-alive timeout set to 5 seconds, using the client and server logs in the report as the baseline. Trace the HTTP client pool through the idle connection and connection-failure states; done means the expected behavior for the third request is established and covered by a regression test.

Written by the indexing model from the issue text.

Assessment

Tech stack
scala
Domain
networking
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Needs clarification
Newbie friendliness
35/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.