Failed: HostConnectionPoolSpec should create a new connection when previous one timed out between requests because of keep-alive-timeout

https://github.com/akka/akka-http/runs/3892348583

Details

Stack Trace

```
[info] - should create a new connection when previous one timed out between requests because of keep-alive-timeout *** FAILED *** (1 second, 751 milliseconds)
[info] 1664546842 nanoseconds was not less than 1500 milliseconds (HostConnectionPoolSpec.scala:367)
[info] org.scalatest.exceptions.TestFailedException:
[info] at org.scalatest.matchers.MatchersHelper$.indicateFailure(MatchersHelper.scala:339)
[info] at org.scalatest.matchers.should.Matchers$ShouldMethodHelperClass.shouldMatcher(Matchers.scala:6783)
[info] at org.scalatest.matchers.should.Matchers$AnyShouldWrapper.should(Matchers.scala:6822)
[info] at akka.http.impl.engine.client.HostConnectionPoolSpec$$anon$16.(HostConnectionPoolSpec.scala:367)
[info] at akka.http.impl.engine.client.HostConnectionPoolSpec.$anonfun$testSet$21(HostConnectionPoolSpec.scala:350)
[info] at akka.http.impl.engine.client.HostConnectionPoolSpec$EnhancedIn$1.$anonfun$inWithShutdown$1(HostConnectionPoolSpec.scala:81)
```

Debug log

```
--> [NewPoolImplementation on AkkaHttpEngineTCP should create a new connection when previous one timed out between requests because of keep-alive-timeout] Start of log messages of test that [Failed(org.scalatest.exceptions.TestFailedException: 1664546842 nanoseconds was not less than 1500 milliseconds)]
| [DEBUG] [10/14/2021 08:45:29.740] [pool-9-thread-4-ScalaTest-running-HostConnectionPoolSpec] [WithLogCapturing(akka://HostConnectionPoolSpec)] Logging started for test [NewPoolImplementation on AkkaHttpEngineTCP should create a new connection when previous one timed out between requests because of keep-alive-timeout]
| [DEBUG] [10/14/2021 08:45:29.761] [HostConnectionPoolSpec-akka.actor.default-dispatcher-3] [akka.actor.ActorSystemImpl(HostConnectionPoolSpec)] [0 (Unconnected)]Dispatching request [GET /simple Empty]
| [DEBUG] [10/14/2021 08:45:29.761] [HostConnectionPoolSpec-akka.actor.default-dispatcher-3] [akka.actor.ActorSystemImpl(HostConnectionPoolSpec)] [0 (Unconnected)]Before event [onNewRequest] In state [Unconnected] for [0 ms]
| [DEBUG] [10/14/2021 08:45:29.761] [HostConnectionPoolSpec-akka.actor.default-dispatcher-3] [akka.actor.ActorSystemImpl(HostConnectionPoolSpec)] [0 (Unconnected)]Establishing connection
| [DEBUG] [10/14/2021 08:45:29.782] [HostConnectionPoolSpec-akka.actor.default-dispatcher-3] [akka.actor.ActorSystemImpl(HostConnectionPoolSpec)] [0 (Connecting)]After event [onNewRequest] State change [Unconnected] -> [Connecting]
| [DEBUG] [10/14/2021 08:45:29.793] [pool-9-thread-4-ScalaTest-running-HostConnectionPoolSpec] [akka.actor.ActorSystemImpl(HostConnectionPoolSpec)] Binding server for test ...
| [DEBUG] [10/14/2021 08:45:29.795] [HostConnectionPoolSpec-akka.actor.default-dispatcher-7] [akka://HostConnectionPoolSpec/system/IO-TCP/selectors/$a/54] Successfully bound to /127.0.0.1:36041
| [DEBUG] [10/14/2021 08:45:29.795] [pool-9-thread-4-ScalaTest-running-HostConnectionPoolSpec] [akka.actor.ActorSystemImpl(HostConnectionPoolSpec)] Server bound to [/127.0.0.1:36041]
| [DEBUG] [10/14/2021 08:45:29.800] [HostConnectionPoolSpec-akka.actor.default-dispatcher-6] [akka://HostConnectionPoolSpec/system/IO-TCP/selectors/$a/55] Resolving localhost before connecting
| [DEBUG] [10/14/2021 08:45:29.800] [HostConnectionPoolSpec-akka.actor.default-dispatcher-6] [akka://HostConnectionPoolSpec/system/IO-TCP/selectors/$a/55] Attempting connection to [localhost/127.0.0.1:36041]
| [DEBUG] [10/14/2021 08:45:29.800] [HostConnectionPoolSpec-akka.actor.default-dispatcher-4] [akka://HostConnectionPoolSpec/system/IO-TCP/selectors/$a/54] New connection accepted
| [DEBUG] [10/14/2021 08:45:29.800] [HostConnectionPoolSpec-akka.actor.default-dispatcher-4] [akka://HostConnectionPoolSpec/system/IO-TCP/selectors/$a/55] Connection established to [localhost:36041]
| [DEBUG] [10/14/2021 08:45:29.802] [HostConnectionPoolSpec-akka.actor.default-dispatcher-7] [akka.actor.ActorSystemImpl(HostConnectionPoolSpec)] [0 (Connecting)]Connection attempt succeeded
| [DEBUG] [10/14/2021 08:45:29.802] [HostConnectionPoolSpec-akka.actor.default-dispatcher-7] [akka.actor.ActorSystemImpl(HostConnectionPoolSpec)] [0 (Connecting)]Before event [onConnectionAttemptSucceeded] In state [Connecting] for [19 ms]
| [DEBUG] [10/14/2021 08:45:29.802] [HostConnectionPoolSpec-akka.actor.default-dispatcher-7] [akka.actor.ActorSystemImpl(HostConnectionPoolSpec)] [0 (Connecting)]Slot connection was established
| [DEBUG] [10/14/2021 08:45:29.802] [HostConnectionPoolSpec-akka.actor.default-dispatcher-7] [akka.actor.ActorSystemImpl(HostConnectionPoolSpec)] [0 (PushingRequestToConnection)]After event [onConnectionAttemptSucceeded] State change [Connecting] -> [PushingRequestToConnection]
| [DEBUG] [10/14/2021 08:45:29.802] [HostConnectionPoolSpec-akka.actor.default-dispatcher-7] [akka.actor.ActorSystemImpl(HostConnectionPoolSpec)] [0 (PushingRequestToConnection)]Before event [onRequestDispatched] In state [PushingRequestToConnection] for [0 ms]
| [DEBUG] [10/14/2021 08:45:29.802] [HostConnectionPoolSpec-akka.actor.default-dispatcher-7] [akka.actor.ActorSystemImpl(HostConnectionPoolSpec)] [0 (WaitingForResponse)]After event [onRequestDispatched] State change [PushingRequestToConnection] -> [WaitingForResponse]
| [DEBUG] [10/14/2021 08:45:29.802] [HostConnectionPoolSpec-akka.actor.default-dispatcher-7] [akka.stream.Log(akka://HostConnectionPoolSpec/system/StreamSupervisor-42)] [client-plain-text ToNet ] Element: SendBytes ByteString(98 bytes)
| 47 45 54 20 2F 73 69 6D 70 6C 65 20 48 54 54 50 | GET /simple HTTP
| 2F 31 2E 31 0D 0A 48 6F 73 74 3A 20 6C 6F 63 61 | /1.1..Host: loca
| 6C 68 6F 73 74 3A 33 36 30 34 31 0D 0A 55 73 65 | lhost:36041..Use
| 72 2D 41 67 65 6E 74 3A 20 61 6B 6B 61 2D 68 74 | r-Agent: akka-ht
| 74 70 2F 31 30 2E 32 2E 36 2B 31 31 2D 64 30 30 | tp/10.2.6+11-d00
| 33 38 32 33 30 2D 53 4E 41 50 53 48 4F 54 0D 0A | 38230-SNAPSHOT..
| 0D 0A | ..
| [DEBUG] [10/14/2021 08:45:29.802] [HostConnectionPoolSpec-akka.actor.default-dispatcher-4] [akka.stream.Log(akka://HostConnectionPoolSpec/system/StreamSupervisor-42)] [server-plain-text FromNet] Element: SessionBytes ByteString(98 bytes)
| 47 45 54 20 2F 73 69 6D 70 6C 65 20 48 54 54 50 | GET /simple HTTP
| 2F 31 2E 31 0D 0A 48 6F 73 74 3A 20 6C 6F 63 61 | /1.1..Host: loca
| 6C 68 6F 73 74 3A 33 36 30 34 31 0D 0A 55 73 65 | lhost:36041..Use
| 72 2D 41 67 65 6E 74 3A 20 61 6B 6B 61 2D 68 74 | r-Agent: akka-ht
| 74 70 2F 31 30 2E 32 2E 36 2B 31 31 2D 64 30 30 | tp/10.2.6+11-d00
| 33 38 32 33 30 2D 53 4E 41 50 53 48 4F 54 0D 0A | 38230-SNAPSHOT..
| 0D 0A | ..
| [DEBUG] [10/14/2021 08:45:29.803] [HostConnectionPoolSpec-akka.actor.default-dispatcher-9] [akka.stream.Log(akka://HostConnectionPoolSpec/system/StreamSupervisor-42)] [server-plain-text ToNet ] Element: SendBytes ByteString(170 bytes)
| 48 54 54 50 2F 31 2E 31 20 32 30 30 20 4F 4B 0D | HTTP/1.1 200 OK.
| 0A 53 65 72 76 65 72 3A 20 61 6B 6B 61 2D 68 74 | .Server: akka-ht
| 74 70 2F 31 30 2E 32 2E 36 2B 31 31 2D 64 30 30 | tp/10.2.6+11-d00
| 33 38 32 33 30 2D 53 4E 41 50 53 48 4F 54 0D 0A | 38230-SNAPSHOT..
| 44 61 74 65 3A 20 54 68 75 2C 20 31 34 20 4F 63 | Date: Thu, 14 Oc
| 74 20 32 30 32 31 20 30 38 3A 34 35 3A 32 39 20 | t 2021 08:45:29
| 47 4D 54 0D 0A 43 6F 6E 74 65 6E 74 2D 54 79 70 | GMT..Content-Typ
| 65 3A 20 74 65 78 74 2F 70 6C 61 69 6E 3B 20 63 | e: text/plain; c
| 68 61 72 73 65 74 3D 55 54 46 2D 38 0D 0A 43 6F | harset=UTF-8..Co
| 6E 74 65 6E 74 2D 4C 65 6E 67 74 68 3A 20 37 0D | ntent-Length: 7.
| 0A 0D 0A 2F 73 69 6D 70 6C 65 | .../simple
| [DEBUG] [10/14/2021 08:45:29.804] [HostConnectionPoolSpec-akka.actor.default-dispatcher-6] [akka.stream.Log(akka://HostConnectionPoolSpec/system/StreamSupervisor-42)] [client-plain-text FromNet] Element: SessionBytes ByteString(170 bytes)
| 48 54 54 50 2F 31 2E 31 20 32 30 30 20 4F 4B 0D | HTTP/1.1 200 OK.
| 0A 53 65 72 76 65 72 3A 20 61 6B 6B 61 2D 68 74 | .Server: akka-ht
| 74 70 2F 31 30 2E 32 2E 36 2B 31 31 2D 64 30 30 | tp/10.2.6+11-d00
| 33 38 32 33 30 2D 53 4E 41 50 53 48 4F 54 0D 0A | 38230-SNAPSHOT..
| 44 61 74 65 3A 20 54 68 75 2C 20 31 34 20 4F 63 | Date: Thu, 14 Oc
| 74 20 32 30 32 31 20 30 38 3A 34 35 3A 32 39 20 | t 2021 08:45:29
| 47 4D 54 0D 0A 43 6F 6E 74 65 6E 74 2D 54 79 70 | GMT..Content-Typ
| 65 3A 20 74 65 78 74 2F 70 6C 61 69 6E 3B 20 63 | e: text/plain; c
| 68 61 72 73 65 74 3D 55 54 46 2D 38 0D 0A 43 6F | harset=UTF-8..Co
| 6E 74 65 6E 74 2D 4C 65 6E 67 74 68 3A 20 37 0D | ntent-Length: 7.
| 0A 0D 0A 2F 73 69 6D 70 6C 65 | .../simple
| [DEBUG] [10/14/2021 08:45:29.804] [HostConnectionPoolSpec-akka.actor.default-dispatcher-6] [akka.actor.ActorSystemImpl(HostConnectionPoolSpec)] [0 (WaitingForResponse)]Received response
| [DEBUG] [10/14/2021 08:45:29.804] [HostConnectionPoolSpec-akka.actor.default-dispatcher-6] [akka.actor.ActorSystemImpl(HostConnectionPoolSpec)] [0 (WaitingForResponse)]Before event [onResponseReceived] In state [WaitingForResponse] for [2 ms]
| [DEBUG] [10/14/2021 08:45:29.804] [HostConnectionPoolSpec-akka.actor.default-dispatcher-6] [akka.actor.ActorSystemImpl(HostConnectionPoolSpec)] [0 (WaitingForResponse)]onResponseReceived in WaitingForResponse with false
| [DEBUG] [10/14/2021 08:45:29.804] [HostConnectionPoolSpec-akka.actor.default-dispatcher-6] [akka.actor.ActorSystemImpl(HostConnectionPoolSpec)] [0 (WaitingForResponseDispatch)]After event [onResponseReceived] State change [WaitingForResponse] -> [WaitingForResponseDispatch]
| [DEBUG] [10/14/2021 08:45:29.804] [HostConnectionPoolSpec-akka.actor.default-dispatcher-4] [akka.actor.ActorSystemImpl(HostConnectionPoolSpec)] [0 (WaitingForResponseDispatch)]Before event [onResponseDispatchable] In state [WaitingForResponseDispatch] for [0 ms]
| [DEBUG] [10/14/2021 08:45:29.804] [HostConnectionPoolSpec-akka.actor.default-dispatcher-4] [akka.actor.ActorSystemImpl(HostConnectionPoolSpec)] [0 (WaitingForResponseEntitySubscription)]After event [onResponseDispatchable] State change [WaitingForResponseDispatch] -> [WaitingForResponseEntitySubscription]
| [DEBUG] [10/14/2021 08:45:29.804] [HostConnectionPoolSpec-akka.actor.default-dispatcher-4] [akka.actor.ActorSystemImpl(HostConnectionPoolSpec)] [0 (WaitingForResponseEntitySubscription)]Before event [onResponseEntitySubscribed] In state [WaitingForResponseEntitySubscription] for [0 ms]
| [DEBUG] [10/14/2021 08:45:29.804] [HostConnectionPoolSpec-akka.actor.default-dispatcher-4] [akka.actor.ActorSystemImpl(HostConnectionPoolSpec)] [0 (WaitingForEndOfResponseEntity)]After event [onResponseEntitySubscribed] State change [WaitingForResponseEntitySubscription] -> [WaitingForEndOfResponseEntity]
| [DEBUG] [10/14/2021 08:45:29.804] [HostConnectionPoolSpec-akka.actor.default-dispatcher-4] [akka.actor.ActorSystemImpl(HostConnectionPoolSpec)] [0 (WaitingForEndOfResponseEntity)]Before event [onResponseEntityCompleted] In state [WaitingForEndOfResponseEntity] for [0 ms]
| [DEBUG] [10/14/2021 08:45:29.804] [HostConnectionPoolSpec-akka.actor.default-dispatcher-4] [akka.actor.ActorSystemImpl(HostConnectionPoolSpec)] [0 (Idle)]After event [onResponseEntityCompleted] State change [WaitingForEndOfResponseEntity] -> [Idle]
| [DEBUG] [10/14/2021 08:45:29.804] [HostConnectionPoolSpec-akka.actor.default-dispatcher-4] [akka.actor.ActorSystemImpl(HostConnectionPoolSpec)] [0 (Idle)]Slot became idle... Trying to pull
| [DEBUG] [10/14/2021 08:45:31.468] [HostConnectionPoolSpec-akka.actor.default-dispatcher-2] [akka.actor.ActorSystemImpl(HostConnectionPoolSpec)] [0 (Idle)]Slot timeout after 800 milliseconds
| [DEBUG] [10/14/2021 08:45:31.468] [HostConnectionPoolSpec-akka.actor.default-dispatcher-2] [akka.actor.ActorSystemImpl(HostConnectionPoolSpec)] [0 (Idle)]Before event [onTimeout] In state [Idle] for [1663 ms]
| [DEBUG] [10/14/2021 08:45:31.468] [HostConnectionPoolSpec-akka.actor.default-dispatcher-2] [akka.actor.ActorSystemImpl(HostConnectionPoolSpec)] [0 (ToBeClosed)]After event [onTimeout] State change [Idle] -> [ToBeClosed]
| [DEBUG] [10/14/2021 08:45:31.468] [HostConnectionPoolSpec-akka.actor.default-dispatcher-2] [akka.actor.ActorSystemImpl(HostConnectionPoolSpec)] [0 (ToBeClosed)]State change from [Idle] to [ToBeClosed]. Closing the existing connection.
| [DEBUG] [10/14/2021 08:45:31.468] [HostConnectionPoolSpec-akka.actor.default-dispatcher-2] [akka.stream.Log(akka://HostConnectionPoolSpec/system/StreamSupervisor-42)] [client-plain-text ToNet ] Upstream finished.
| [DEBUG] [10/14/2021 08:45:31.469] [HostConnectionPoolSpec-akka.actor.default-dispatcher-4] [akka.stream.Log(akka://HostConnectionPoolSpec/system/StreamSupervisor-42)] [server-plain-text FromNet] Upstream finished.
| [DEBUG] [10/14/2021 08:45:31.469] [HostConnectionPoolSpec-akka.actor.default-dispatcher-4] [akka.stream.Log(akka://HostConnectionPoolSpec/system/StreamSupervisor-42)] [server-plain-text ToNet ] Upstream finished.
<-- [NewPoolImplementation on AkkaHttpEngineTCP should create a new connection when previous one timed out between requests because of keep-alive-timeout] End of log messages of test that [Failed(org.scalatest.exceptions.TestFailedException: 1664546842 nanoseconds was not less than 1500 milliseconds)]
```

Start with HostConnectionPoolSpec.scala at lines 350-367, then run the named HostConnectionPoolSpec test and compare its failure with the linked CI log. Trace the keep-alive timeout between requests and verify that the test observes a new connection within its timing expectation.

Written by the indexing model from the issue text.