Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

UnexpectedConnectionClosureException with upgrade to 10.2.2 #3759

Closed
shayangz opened this issue Feb 12, 2021 · 3 comments
Closed

UnexpectedConnectionClosureException with upgrade to 10.2.2 #3759

shayangz opened this issue Feb 12, 2021 · 3 comments
Milestone
duplicate

Comments

@shayangz
Copy link

Team,

We have a micro-services architecture where we make cross service calls through binary POST HTTP calls on back of akka-http (both client and server side). When service A wants to send a message to service B, it sends a message to an actor A_B which puts that message into a stream that processes the message via Flow[(HttpRequest, ActorRef), (Try[HttpResponse], ActorRef), Http.HostConnectionPool] and the response gets translated into a message to the original sender.

When we attempted to upgrade from akka-http 10.1.11 to 10.2.2 we started seeing these exceptions randomly sprinkled in logs.

akka.http.impl.engine.client.OutgoingConnectionBlueprint$UnexpectedConnectionClosureException: The http server closed the connection unexpectedly before delivering responses for 1 outstanding requests

Nothing else about the infrastructure has changed. We reverted all the services back to 10.1.11 and the exceptions have disappeared.

We upgraded only one of the services to 10.2.2 leaving the rest of infrastructure on 10.1.11 and we still see the issue. In this scenario, the client is running 10.2.2 and calling to a bunch of 10.1.11 servers. When we turn on debugging on the client where we see the exceptions, we catch situations like this

2021-02-12 01:10:54,890 [serviceX-akka.actor.default-dispatcher-9] DEBUG akka.http.impl.engine.client.PoolId - Creating pool.
2021-02-12 01:10:54,893 [serviceX-akka.actor.default-dispatcher-39] DEBUG akka.http.impl.engine.client.PoolId - Dispatching request [POST /api/internal Strict(92 bytes)] to pool
2021-02-12 01:10:54,894 [serviceX-akka.actor.default-dispatcher-6] DEBUG akka.http.impl.engine.client.PoolId - [0 (Idle)]Dispatching request [POST /api/internal Strict(92 bytes)]
2021-02-12 01:10:54,894 [serviceX-akka.actor.default-dispatcher-6] DEBUG akka.http.impl.engine.client.PoolId - [0 (Idle)]Before event [onNewRequest] In state [Idle] for [3287 ms]
2021-02-12 01:10:54,894 [serviceX-akka.actor.default-dispatcher-6] DEBUG akka.http.impl.engine.client.PoolId - [0 (PushingRequestToConnection)]After event [onNewRequest] State change [Idle] -> [PushingRequestToConnection]
2021-02-12 01:10:54,894 [serviceX-akka.actor.default-dispatcher-6] DEBUG akka.http.impl.engine.client.PoolId - [0 (PushingRequestToConnection)]Before event [onRequestDispatched] In state [PushingRequestToConnection] for [0 ms]
2021-02-12 01:10:54,894 [serviceX-akka.actor.default-dispatcher-6] DEBUG akka.http.impl.engine.client.PoolId - [0 (WaitingForResponse)]After event [onRequestDispatched] State change [PushingRequestToConnection] -> [WaitingForResponse]
2021-02-12 01:10:54,894 [serviceX-akka.actor.default-dispatcher-6] DEBUG akka.http.impl.engine.client.PoolId - Dispatching request [POST /api/internal Strict(93 bytes)] to pool
2021-02-12 01:10:54,894 [serviceX-akka.actor.default-dispatcher-6] DEBUG akka.http.impl.engine.client.PoolId - [1 (Idle)]Dispatching request [POST /api/internal Strict(93 bytes)]
2021-02-12 01:10:54,894 [serviceX-akka.actor.default-dispatcher-6] DEBUG akka.http.impl.engine.client.PoolId - [1 (Idle)]Before event [onNewRequest] In state [Idle] for [50719 ms]
2021-02-12 01:10:54,894 [serviceX-akka.actor.default-dispatcher-6] DEBUG akka.http.impl.engine.client.PoolId - [1 (PushingRequestToConnection)]After event [onNewRequest] State change [Idle] -> [PushingRequestToConnection]
2021-02-12 01:10:54,894 [serviceX-akka.actor.default-dispatcher-6] DEBUG akka.http.impl.engine.client.PoolId - [1 (PushingRequestToConnection)]Before event [onRequestDispatched] In state [PushingRequestToConnection] for [0 ms]
2021-02-12 01:10:54,894 [serviceX-akka.actor.default-dispatcher-6] DEBUG akka.http.impl.engine.client.PoolId - [1 (WaitingForResponse)]After event [onRequestDispatched] State change [PushingRequestToConnection] -> [WaitingForResponse]
2021-02-12 01:10:54,896 [serviceX-akka.actor.default-dispatcher-8] DEBUG akka.http.impl.engine.client.PoolId - [1 (WaitingForResponse)]Connection failed
2021-02-12 01:10:54,896 [serviceX-akka.actor.default-dispatcher-8] DEBUG akka.http.impl.engine.client.PoolId - [1 (WaitingForResponse)]Before event [onConnectionFailed] In state [WaitingForResponse] for [1 ms]
2021-02-12 01:10:54,896 [serviceX-akka.actor.default-dispatcher-8] DEBUG akka.http.impl.engine.client.PoolId - [1 (WaitingForResponse)]Ongoing request [POST /api/internal Strict(93 bytes)] is failed because of [connection failure]: [The http server closed the connection unexpectedly before delivering responses for 1 outstanding requests]
2021-02-12 01:10:54,896 [serviceX-akka.actor.default-dispatcher-8] DEBUG akka.http.impl.engine.client.PoolId - [1 (WaitingForResponseDispatch)]After event [onConnectionFailed] State change [WaitingForResponse] -> [WaitingForResponseDispatch]
2021-02-12 01:10:54,896 [serviceX-akka.actor.default-dispatcher-8] DEBUG akka.http.impl.engine.client.PoolId - [1 (WaitingForResponseDispatch)]Before event [onResponseDispatchable] In state [WaitingForResponseDispatch] for [0 ms]
2021-02-12 01:10:54,896 [serviceX-akka.actor.default-dispatcher-8] DEBUG akka.http.impl.engine.client.PoolId - [1 (Failed)]After event [onResponseDispatchable] State change [WaitingForResponseDispatch] -> [Failed]
2021-02-12 01:10:54,896 [serviceX-akka.actor.default-dispatcher-8] DEBUG akka.http.impl.engine.client.PoolId - [1 (Failed)]State change from [WaitingForResponseDispatch] to [Failed(akka.http.impl.engine.client.OutgoingConnectionBlueprint$UnexpectedConnectionClosureException: The http server closed the connection unexpectedly before delivering responses for 1 outstanding requests)]. Closing the existing connection.
2021-02-12 01:10:54,896 [serviceX-akka.actor.default-dispatcher-8] DEBUG akka.http.impl.engine.client.PoolId - [1 (Unconnected)]Slot became idle... Trying to pull
2021-02-12 01:10:54,903 [serviceX-akka.actor.default-dispatcher-4] ERROR X_Y_Actor - error making service request to serviceY.service.consul at serviceY.service.consul:50060
akka.http.impl.engine.client.OutgoingConnectionBlueprint$UnexpectedConnectionClosureException: The http server closed the connection unexpectedly before delivering responses for 1 outstanding requests
  at akka.http.impl.engine.client.OutgoingConnectionBlueprint$.$anonfun$apply$6(OutgoingConnectionBlueprint.scala:123)
  at akka.http.impl.engine.client.OutgoingConnectionBlueprint$.$anonfun$apply$6$adapted(OutgoingConnectionBlueprint.scala:123)
  at akka.http.impl.util.One2OneBidiFlow$One2OneBidi$$anon$1$$anon$4.onUpstreamFinish(One2OneBidiFlow.scala:97)
  at akka.stream.impl.fusing.GraphInterpreter.processEvent(GraphInterpreter.scala:523)
  at akka.stream.impl.fusing.GraphInterpreter.execute(GraphInterpreter.scala:390)
  at akka.stream.impl.fusing.GraphInterpreterShell.runBatch(ActorGraphInterpreter.scala:625)
  at akka.stream.impl.fusing.GraphInterpreterShell$AsyncInput.execute(ActorGraphInterpreter.scala:502)
  at akka.stream.impl.fusing.GraphInterpreterShell.processEvent(ActorGraphInterpreter.scala:600)
  at akka.stream.impl.fusing.ActorGraphInterpreter.akka$stream$impl$fusing$ActorGraphInterpreter$$processEvent(ActorGraphInterpreter.scala:773)
  at akka.stream.impl.fusing.ActorGraphInterpreter.akka$stream$impl$fusing$ActorGraphInterpreter$$shortCircuitBatch(ActorGraphInterpreter.scala:762)
  at akka.stream.impl.fusing.ActorGraphInterpreter$$anonfun$receive$1.applyOrElse(ActorGraphInterpreter.scala:789)
  at akka.actor.Actor.aroundReceive(Actor.scala:537)
  at akka.actor.Actor.aroundReceive$(Actor.scala:535)
  at akka.stream.impl.fusing.ActorGraphInterpreter.aroundReceive(ActorGraphInterpreter.scala:691)
  at akka.actor.ActorCell.receiveMessage(ActorCell.scala:577)
  at akka.actor.ActorCell.invoke(ActorCell.scala:547)
  at akka.dispatch.Mailbox.processMailbox(Mailbox.scala:270)
  at akka.dispatch.Mailbox.run(Mailbox.scala:231)
  at akka.dispatch.Mailbox.exec(Mailbox.scala:243)
  at java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:289)
  at java.util.concurrent.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1056)
  at java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1692)
  at java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:157)
2021-02-12 01:10:54,903 [serviceX-akka.actor.default-dispatcher-4] DEBUG akka.http.impl.engine.client.PoolId - Dispatching request [POST /api/internal Strict(111 bytes)] to pool
2021-02-12 01:10:54,904 [serviceX-akka.actor.default-dispatcher-4] DEBUG akka.http.impl.engine.client.PoolId - [0 (Unconnected)]Dispatching request [POST /api/internal Strict(111 bytes)]
2021-02-12 01:10:54,904 [serviceX-akka.actor.default-dispatcher-4] DEBUG akka.http.impl.engine.client.PoolId - [0 (Unconnected)]Before event [onNewRequest] In state [Unconnected] for [10 ms]
2021-02-12 01:10:54,904 [serviceX-akka.actor.default-dispatcher-4] DEBUG akka.http.impl.engine.client.PoolId - [0 (Unconnected)]Establishing connection
2021-02-12 01:10:54,904 [serviceX-akka.actor.default-dispatcher-4] DEBUG akka.http.impl.engine.client.PoolId - [0 (Connecting)]After event [onNewRequest] State change [Unconnected] -> [Connecting]
2021-02-12 01:10:54,904 [serviceX-akka.actor.default-dispatcher-4] DEBUG akka.http.impl.engine.client.PoolId - [0 (WaitingForResponse)]Received response
2021-02-12 01:10:54,905 [serviceX-akka.actor.default-dispatcher-4] DEBUG akka.http.impl.engine.client.PoolId - [0 (WaitingForResponse)]Before event [onResponseReceived] In state [WaitingForResponse] for [9 ms]
2021-02-12 01:10:54,905 [serviceX-akka.actor.default-dispatcher-4] DEBUG akka.http.impl.engine.client.PoolId - [0 (WaitingForResponse)]onResponseReceived in WaitingForResponse with false
2021-02-12 01:10:54,905 [serviceX-akka.actor.default-dispatcher-4] DEBUG akka.http.impl.engine.client.PoolId - [0 (WaitingForResponseDispatch)]After event [onResponseReceived] State change [WaitingForResponse] -> [WaitingForResponseDispatch]
2021-02-12 01:10:54,905 [serviceX-akka.actor.default-dispatcher-4] DEBUG akka.http.impl.engine.client.PoolId - [0 (WaitingForResponseDispatch)]Before event [onResponseDispatchable] In state [WaitingForResponseDispatch] for [0 ms]
2021-02-12 01:10:54,905 [serviceX-akka.actor.default-dispatcher-4] DEBUG akka.http.impl.engine.client.PoolId - [0 (WaitingForResponseEntitySubscription)]After event [onResponseDispatchable] State change [WaitingForResponseDispatch] -> [WaitingForResponseEntitySubscription]
2021-02-12 01:10:54,905 [serviceX-akka.actor.default-dispatcher-4] DEBUG akka.http.impl.engine.client.PoolId - [0 (WaitingForResponseEntitySubscription)]Before event [onResponseEntitySubscribed] In state [WaitingForResponseEntitySubscription] for [0 ms]
2021-02-12 01:10:54,905 [serviceX-akka.actor.default-dispatcher-4] DEBUG akka.http.impl.engine.client.PoolId - [0 (WaitingForEndOfResponseEntity)]After event [onResponseEntitySubscribed] State change [WaitingForResponseEntitySubscription] -> [WaitingForEndOfResponseEntity]
2021-02-12 01:10:54,905 [serviceX-akka.actor.default-dispatcher-4] DEBUG akka.http.impl.engine.client.PoolId - [0 (WaitingForEndOfResponseEntity)]Before event [onResponseEntityCompleted] In state [WaitingForEndOfResponseEntity] for [0 ms]
2021-02-12 01:10:54,906 [serviceX-akka.actor.default-dispatcher-4] DEBUG akka.http.impl.engine.client.PoolId - [0 (Idle)]After event [onResponseEntityCompleted] State change [WaitingForEndOfResponseEntity] -> [Idle]
2021-02-12 01:10:54,906 [serviceX-akka.actor.default-dispatcher-9] DEBUG akka.http.impl.engine.client.PoolId - [0 (Idle)]Slot became idle... Trying to pull
2021-02-12 01:10:54,906 [serviceX-akka.actor.default-dispatcher-9] INFO  a.kafka.internal.SingleSourceLogic - [b504b] Completing
2021-02-12 01:10:54,918 [serviceX-akka.actor.default-dispatcher-6] DEBUG akka.http.impl.engine.client.PoolId - [0 (Connecting)]Connection attempt succeeded
2021-02-12 01:10:54,918 [serviceX-akka.actor.default-dispatcher-6] DEBUG akka.http.impl.engine.client.PoolId - [0 (Connecting)]Before event [onConnectionAttemptSucceeded] In state [Connecting] for [14 ms]
2021-02-12 01:10:54,918 [serviceX-akka.actor.default-dispatcher-6] DEBUG akka.http.impl.engine.client.PoolId - [0 (Connecting)]Slot connection was established
2021-02-12 01:10:54,918 [serviceX-akka.actor.default-dispatcher-6] DEBUG akka.http.impl.engine.client.PoolId - [0 (PushingRequestToConnection)]After event [onConnectionAttemptSucceeded] State change [Connecting] -> [PushingRequestToConnection]
2021-02-12 01:10:54,918 [serviceX-akka.actor.default-dispatcher-6] DEBUG akka.http.impl.engine.client.PoolId - [0 (PushingRequestToConnection)]Before event [onRequestDispatched] In state [PushingRequestToConnection] for [0 ms]
2021-02-12 01:10:54,918 [serviceX-akka.actor.default-dispatcher-6] DEBUG akka.http.impl.engine.client.PoolId - [0 (WaitingForResponse)]After event [onRequestDispatched] State change [PushingRequestToConnection] -> [WaitingForResponse]
2021-02-12 01:10:55,022 [serviceX-akka.actor.default-dispatcher-9] DEBUG akka.http.impl.engine.client.PoolId - [0 (WaitingForResponse)]Received response
2021-02-12 01:10:55,022 [serviceX-akka.actor.default-dispatcher-9] DEBUG akka.http.impl.engine.client.PoolId - [0 (WaitingForResponse)]Before event [onResponseReceived] In state [WaitingForResponse] for [104 ms]
2021-02-12 01:10:55,022 [serviceX-akka.actor.default-dispatcher-9] DEBUG akka.http.impl.engine.client.PoolId - [0 (WaitingForResponse)]onResponseReceived in WaitingForResponse with false
2021-02-12 01:10:55,022 [serviceX-akka.actor.default-dispatcher-9] DEBUG akka.http.impl.engine.client.PoolId - [0 (WaitingForResponseDispatch)]After event [onResponseReceived] State change [WaitingForResponse] -> [WaitingForResponseDispatch]
2021-02-12 01:10:55,022 [serviceX-akka.actor.default-dispatcher-9] DEBUG akka.http.impl.engine.client.PoolId - [0 (WaitingForResponseDispatch)]Before event [onResponseDispatchable] In state [WaitingForResponseDispatch] for [0 ms]
2021-02-12 01:10:55,022 [serviceX-akka.actor.default-dispatcher-9] DEBUG akka.http.impl.engine.client.PoolId - [0 (WaitingForResponseEntitySubscription)]After event [onResponseDispatchable] State change [WaitingForResponseDispatch] -> [WaitingForResponseEntitySubscription]
2021-02-12 01:10:55,022 [serviceX-akka.actor.default-dispatcher-9] DEBUG akka.http.impl.engine.client.PoolId - [0 (WaitingForResponseEntitySubscription)]Before event [onResponseEntitySubscribed] In state [WaitingForResponseEntitySubscription] for [0 ms]
2021-02-12 01:10:55,022 [serviceX-akka.actor.default-dispatcher-9] DEBUG akka.http.impl.engine.client.PoolId - [0 (WaitingForEndOfResponseEntity)]After event [onResponseEntitySubscribed] State change [WaitingForResponseEntitySubscription] -> [WaitingForEndOfResponseEntity]
2021-02-12 01:10:55,022 [serviceX-akka.actor.default-dispatcher-9] DEBUG akka.http.impl.engine.client.PoolId - [0 (WaitingForEndOfResponseEntity)]Before event [onResponseEntityCompleted] In state [WaitingForEndOfResponseEntity] for [0 ms]
2021-02-12 01:10:55,022 [serviceX-akka.actor.default-dispatcher-9] DEBUG akka.http.impl.engine.client.PoolId - [0 (Idle)]After event [onResponseEntityCompleted] State change [WaitingForEndOfResponseEntity] -> [Idle]
2021-02-12 01:10:55,022 [serviceX-akka.actor.default-dispatcher-9] DEBUG akka.http.impl.engine.client.PoolId - [0 (Idle)]Slot became idle... Trying to pull

I noticed issue #3481 also saw a similar issue but unlike that scenario, when these events occur no services were staring or stopping. Our services are behind haproxy as a TCP backend, so the proxy does not interfere with anything HTTP level.

Any pointers would be appreciated as this is blocking us from upgrade forward.
@marcinkierus marcinkierus mentioned this issue Apr 26, 2021
Closed
@octonato octonato mentioned this issue May 21, 2021
Merged
@jrudolph jrudolph added this to the duplicate milestone Jun 14, 2021
@jrudolph
Copy link
Contributor

The best guess is that this is another case of the infamous race-condition inherent in persistent HTTP connections where a server may close a connection at the same time that a client tries to push the next request.

We just merged a new feature in #3816 where you can define a new keep-alive-timeout for the client pool to close the connection on the client side before the server does. You need to know the keep alive timeout for your server / reverse proxy and then set the new keep-alive-timeout to a value smaller than that.

@jrudolph
Copy link
Contributor

You can try the latest snapshot 10.2.4+39-814ad18f-SNAPSHOT (once published) to try out this feature.

I'm closing this for now as a duplicate.

@jrudolph jrudolph mentioned this issue Jun 14, 2021
Open
@jrudolph
Copy link
Contributor

I also filed a new ticket for a potential alternative solution: #3834.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
duplicate
Development

No branches or pull requests
2 participants
@jrudolph @shayangz