scala - Akka-Http client shuts down connection pool while request is in flight

Question

I'm seeing intermittent issues in a test pipeline.

Occasionally the akka-http client we use will close the connection pool for a host before we receive the response from an in-flight request.

[DEBUG] [01/08/2021 03:17:31.803] [Test worker-ScalaTest-running-CertLyftSpec] [EventStream(akka://TestClient)] logger log1-Logging$DefaultLogger started
[DEBUG] [01/08/2021 03:17:31.803] [Test worker-ScalaTest-running-CertLyftSpec] [EventStream(akka://TestClient)] Default Loggers started
[DEBUG] [01/08/2021 03:17:31.823] [Test worker-ScalaTest-running-CertLyftSpec] [akka.serialization.Serialization(akka://TestClient)] Replacing JavaSerializer with DisabledJavaSerializer, due to `akka.actor.allow-java-serialization = off`.
[DEBUG] [01/08/2021 03:17:31.826] [TestClient-akka.actor.default-dispatcher-5] [TestClient/Pool(shared->https://<host>.com:443)] Creating pool.
[DEBUG] [01/08/2021 03:17:31.830] [TestClient-akka.actor.default-dispatcher-5] [TestClient/Pool(shared->https://<host>.com:443)] Dispatching request [GET <url> Empty] to pool
[DEBUG] [01/08/2021 03:17:31.831] [TestClient-akka.actor.default-dispatcher-5] [TestClient/Pool(shared->https://<host>.com:443)] [0 (Unconnected)]Dispatching request [GET <url> Empty]
[DEBUG] [01/08/2021 03:17:31.831] [TestClient-akka.actor.default-dispatcher-5] [TestClient/Pool(shared->https://<host>.com:443)] [0 (Unconnected)]Before event [onNewRequest] In state [Unconnected] for [1 ms]
[DEBUG] [01/08/2021 03:17:31.831] [TestClient-akka.actor.default-dispatcher-5] [TestClient/Pool(shared->https://<host>.com:443)] [0 (Unconnected)]Establishing connection
[DEBUG] [01/08/2021 03:17:31.832] [TestClient-akka.actor.default-dispatcher-5] [TestClient/Pool(shared->https://<host>.com:443)] [0 (Connecting)]After event [onNewRequest] State change [Unconnected] -> [Connecting]
[DEBUG] [01/08/2021 03:17:31.833] [TestClient-akka.actor.internal-dispatcher-3] [akka://TestClient/system/IO-TCP/selectors/$a/0] Resolving <host>.com before connecting
[DEBUG] [01/08/2021 03:17:31.836] [TestClient-akka.actor.internal-dispatcher-3] [akka://TestClient/system/IO-DNS] Resolution request for <host>.com from Actor[akka://TestClient/system/IO-TCP/selectors/$a/0#-1391171914]
[DEBUG] [01/08/2021 03:17:31.837] [TestClient-akka.actor.default-blocking-io-dispatcher-17] [akka://TestClient/system/IO-DNS/inet-address/$a] Request for [<host>.com] was not yet cached
[DEBUG] [01/08/2021 03:17:31.837] [TestClient-akka.actor.internal-dispatcher-3] [akka://TestClient/system/IO-TCP/selectors/$a/0] Attempting connection to [<host>.com/x.x.x.x:443]
[DEBUG] [01/08/2021 03:17:31.839] [TestClient-akka.actor.internal-dispatcher-3] [akka://TestClient/system/IO-TCP/selectors/$a/0] Connection established to [<host>.com:443]
[DEBUG] [01/08/2021 03:17:31.839] [TestClient-akka.actor.default-dispatcher-5] [TestClient/Pool(shared->https://<host>.com:443)] [0 (Connecting)]Connection attempt succeeded
[DEBUG] [01/08/2021 03:17:31.839] [TestClient-akka.actor.default-dispatcher-5] [TestClient/Pool(shared->https://<host>.com:443)] [0 (Connecting)]Before event [onConnectionAttemptSucceeded] In state [Connecting] for [7 ms]
[DEBUG] [01/08/2021 03:17:31.839] [TestClient-akka.actor.default-dispatcher-5] [TestClient/Pool(shared->https://<host>.com:443)] [0 (Connecting)]Slot connection was established
[DEBUG] [01/08/2021 03:17:31.839] [TestClient-akka.actor.default-dispatcher-5] [TestClient/Pool(shared->https://<host>.com:443)] [0 (PushingRequestToConnection)]After event [onConnectionAttemptSucceeded] State change [Connecting] -> [PushingRequestToConnection]
[DEBUG] [01/08/2021 03:17:31.839] [TestClient-akka.actor.default-dispatcher-5] [TestClient/Pool(shared->https://<host>.com:443)] [0 (PushingRequestToConnection)]Before event [onRequestDispatched] In state [PushingRequestToConnection] for [0 ms]
[DEBUG] [01/08/2021 03:17:31.839] [TestClient-akka.actor.default-dispatcher-5] [TestClient/Pool(shared->https://<host>.com:443)] [0 (WaitingForResponse)]After event [onRequestDispatched] State change [PushingRequestToConnection] -> [WaitingForResponse]
[DEBUG] [01/08/2021 03:17:31.841] [TestClient-akka.actor.default-dispatcher-5] [akka.stream.Log(akka://TestClient/system/Materializers/StreamSupervisor-4)] [client-plain-text ToNet  ] Element: SendBytes  ByteString(159 bytes)
   xx xx xx xx xx xx xx xx xx xx xx xx xx xx xx xx  | GET xxxxxxxxxxxx
   xx xx xx xx xx xx xx xx xx xx xx xx xx xx xx xx  | xxxxxxx HTTP/1.1
   xx xx xx xx xx xx xx xx xx xx xx xx xx xx xx xx  | ..Host: xxxxxxxx
   xx xx xx xx xx xx xx xx xx xx xx xx xx xx xx xx  | xxxxxxxxxxxxxx.c
   6F 6D 0D 0A 58 2D 57 44 2D 52 45 51 55 45 53 54  | om..X-WD-REQUEST
   2D 49 44 3A 20 53 54 46 7C 65 35 63 30 30 36 62  | -ID: STF|e5c006b
   38 2D 35 65 39 33 2D 34 61 64 65 2D 62 31 34 32  | 8-5e93-4ade-b142
   2D 66 63 39 33 31 33 37 35 34 35 31 39 0D 0A 55  | -fc9313754519..U
   73 65 72 2D 41 67 65 6E 74 3A 20 61 6B 6B 61 2D  | ser-Agent: akka-
   68 74 74 70 2F 31 30 2E 32 2E 31 0D 0A 0D 0A     | http/10.2.1....
[DEBUG] [01/08/2021 03:18:01.191] [TestClient-akka.actor.default-dispatcher-6] [TestClient/Pool(shared->https://<host>.com:443)] Pool shutting down because akka.http.host-connection-pool.idle-timeout triggered after 30 seconds.
[DEBUG] [01/08/2021 03:18:01.191] [TestClient-akka.actor.default-dispatcher-6] [TestClient/Pool(shared->https://<host>.com:443)] Pool is now shutting down as requested.
[DEBUG] [01/08/2021 03:18:01.193] [TestClient-akka.actor.default-dispatcher-5] [akka://TestClient/system/pool-master] connection pool for Pool(shared->https://<host>.com:443) was shut down because of idle timeout
[DEBUG] [01/08/2021 03:18:01.193] [TestClient-akka.actor.default-dispatcher-6] [TestClient/Pool(shared->https://<host>.com:443)] Pool downstream cancelled
[DEBUG] [01/08/2021 03:18:01.196] [TestClient-akka.actor.default-dispatcher-6] [TestClient/Pool(shared->https://<host>.com:443)] Pool stopped
[DEBUG] [01/08/2021 03:18:01.197] [TestClient-akka.actor.default-dispatcher-6] [akka.stream.Log(akka://TestClient/system/Materializers/StreamSupervisor-1)] [client-plain-text ToNet  ] Upstream finished.
[DEBUG] [01/08/2021 03:18:01.204] [TestClient-akka.actor.default-dispatcher-6] [akka.stream.Log(akka://TestClient/system/Materializers/StreamSupervisor-1)] [client-plain-text FromNet] Upstream finished.

akka-http version: 10.2.1

Config

akka.http {
  client.log-unencrypted-network-bytes = 1024
  host-connection-pool {
    max-connections = 100
    min-connections = 0
    max-open-requests = 512
    max-retries = 3
    base-connection-backoff = 200ms
    max-connection-backoff = 2 min
    pool-implementation = new
    response-entity-subscription-timeout = 5.second
    client = {
      connecting-timeout = 10s
      idle-timeout = 60 s
     }
  }
}

My understanding is that akka.http.host-connection-pool.idle-timeout should not terminate the pool if there are pending requests.

When I check the host logs I see that the request was received (albeit, received 30 seconds after the pool was shut down). I suspect the reason for the delay is an overloaded jenkins server, or something in the network as the request is proxied and hits load balancers - in any case I would not expect the connection pool to shut down before receiving some kind of response or the connection being reset.

Question

• Is my understanding of akka.http.host-connection-pool.idle-timeout correct?
• Am I missing something in my akka-http config

As a work around I can increase the value of akka.http.host-connection-pool.idle-timeout but I'd rather not have connection pools hanging around longer than necessary - especially for prod configuration.

Answer 1

等待大神答复