Akka-http: [10.1.10] Outgoing request stream error on pool shutdown due to idle timeout

[el-dom]

Using akka-http 10.1.10 on scala 2.13.0

I have a dedicated dispatcher configured for blocking calls when using a java API

auth-dispatcher {
  type = Dispatcher
  executor = "thread-pool-executor"
  thread-pool-executor {
    fixed-pool-size = 2
  }
  throughput = 1
}

Up until 10.1.9 this worked flawlessly. Since 10.1.10 it still seems to behave correctly but the log gets spammed with "Outgoing request stream error" messages everytime the idle-timeout kicks in

[INFO] [09/23/2019 12:32:07.431] [tsmAdmin-akka.actor.default-dispatcher-7] [tsmAdmin/Pool(shared->https://keycloak.example.com:443)] Pool shutting down because akka.http.host-connection-pool.idle-timeout triggered after 30 seconds.
[INFO] [09/23/2019 12:32:07.436] [tsmAdmin-akka.actor.default-dispatcher-7] [tsmAdmin/Pool(shared->https://keycloak.example.com:443)] Pool is now shutting down as requested.
[ERROR] [09/23/2019 12:32:07.451] [tsmAdmin-akka.actor.default-dispatcher-7] [akka.actor.ActorSystemImpl(tsmAdmin)] Outgoing request stream error (akka.http.impl.engine.client.pool.NewHostConnectionPool$HostConnectionPoolStage$$anon$1$Slot$$anon$2: Pool slot was shut down)
[INFO] [09/23/2019 12:32:37.771] [tsmAdmin-akka.actor.default-dispatcher-5] [tsmAdmin/Pool(shared->https://keycloak.example.com:443)] Pool shutting down because akka.http.host-connection-pool.idle-timeout triggered after 30 seconds.
[INFO] [09/23/2019 12:32:37.771] [tsmAdmin-akka.actor.default-dispatcher-5] [tsmAdmin/Pool(shared->https://keycloak.example.com:443)] Pool is now shutting down as requested.
[ERROR] [09/23/2019 12:32:37.772] [tsmAdmin-akka.actor.default-dispatcher-5] [akka.actor.ActorSystemImpl(tsmAdmin)] Outgoing request stream error (akka.http.impl.engine.client.pool.NewHostConnectionPool$HostConnectionPoolStage$$anon$1$Slot$$anon$2: Pool slot was shut down)

[radusw]

I can confirm this happening when doing the simplest things like Http().singleRequest(). The response entity is properly handled/discarded.

The logs are full of:

[INFO] ..."Pool is now shutting down as requested." ...
[ERROR] ..."Pool slot was shut down" ... "Outgoing request stream error"...

I think the idle-timeout timer is being reinitialized after being previously canceled.

[markus1189]

We are experiencing the same issue. We schedule a Http.singleRequest every 2 minutes and as @radusw we made sure that the response entity is properly consumed/discarded.

However, when the pool goes idle after the idle-timeout, it seems like there are some stale connections being closed. The logging was introduced in https://github.com/akka/akka-http/pull/2631, it seems like before that change there was no logging at all. So it's possible that this issue was already present but not noticeable...

[markus1189]

I added a minimal example here: https://github.com/markus1189/akka-http-10-1-10-2728

If you run this the output is:

[INFO] [09/24/2019 11:23:54.120] [default-akka.actor.default-dispatcher-2] [default/Pool(shared->http://akka.io:80)] Pool shutting down because akka.http.host-connection-pool.idle-timeout triggered after 30 seconds.
[INFO] [09/24/2019 11:23:54.121] [default-akka.actor.default-dispatcher-2] [default/Pool(shared->http://akka.io:80)] Pool is now shutting down as requested.
[ERROR] [09/24/2019 11:23:54.125] [default-akka.actor.default-dispatcher-2] [akka.actor.ActorSystemImpl(default)] Outgoing request stream error (akka.http.impl.engine.client.pool.NewHostConnectionPool$HostConnectionPoolStage$$anon$1$Slot$$anon$2: Pool slot was shut down)
[INFO] [09/24/2019 11:24:28.839] [default-akka.actor.default-dispatcher-2] [default/Pool(shared->http://akka.io:80)] Pool shutting down because akka.http.host-connection-pool.idle-timeout triggered after 30 seconds.
[INFO] [09/24/2019 11:24:28.839] [default-akka.actor.default-dispatcher-2] [default/Pool(shared->http://akka.io:80)] Pool is now shutting down as requested.
[ERROR] [09/24/2019 11:24:28.840] [default-akka.actor.default-dispatcher-2] [akka.actor.ActorSystemImpl(default)] Outgoing request stream error (akka.http.impl.engine.client.pool.NewHostConnectionPool$HostConnectionPoolStage$$anon$1$Slot$$anon$2: Pool slot was shut down)
... (and so on)

[jrudolph]

That's annoying indeed. For the time being, you can increase
akka.http.host-connection-pool.idle-timeout to some higher value. As long
as you don't make requests to millions of hosts during the lifetime of the
process even infinite should be fine (keeping a bit of memory for each
host accessed at least once).

[radusw]

@jrudolph Increasing the idle-timeout will just delay the error messages but the number of "errors" in the logs will be the same. Making it infinite seems wasteful.
I think the bug is that the idle-timeout timer is being reinitialized for no reason after a request is done and the response processed.

[abdolence]

I have the same behaviour like this. I had to downgrade it back to 10.1.9.

[markus1189]

@jrudolph Increasing the timeout would reduce the logging, not get rid of it. Keeping them infinitely works, but if it is actually a leak of connections that sounds like a bad idea :/

[jrudolph]

It's the timeout for the pool, the connections are governed by the
akka.http.client.idle-timeout so it should not leak connections but only
the internal pool data structures.

Increasing the pool idle-timeout above the maximum interval between two
requests to one host should actually silence the messages completely.

[vaslabs]

This also happens for akka cluster bootstrap which uses akka management (with akka http) if it helps you reproduce this

From a behavioural point I saw no changes in our service(s) but I haven't done any soak testing to see how this issue evolves

[vaslabs]

Did a bit of digging and it looks like this was maybe not intended

Changing it passes all the tests (in akka-http-core)
https://github.com/vaslabs/akka-http/commit/d234d095c6b7102169a576ede0376b9218f32417

[jrudolph]

The extra INFO logging was intended but the extra ERROR logging is an
unexpected consequence of idle-shutting down a pool while there are still
idle connections open. So, one way to prevent those messages would be to
make sure the akka.http.host-connection-pool.idle-timeout is greater than
the akka.http.client.idle-timeout (by default it's not, 30s for the pool
60s for connections). We should do two things here:

• increase the host-connection-pool.idle-timeout above the value for
  akka.http.client.idle-timeout
• don't deliver the error to pool connections (similar to what you
  suggested, @vaslabs), we just have to make sure the connections are closed
  in all cases when a pool slot fails, also if there are still responses
  pending.

[vaslabs]

Thanks for the info, I'll try to make the configuration changes and see how it goes . For the code changes are you planning something? I have a bit more understanding of the problem now to come up with a test but I can't promise. If you're not planning the second point soon then let me know and I'll spend some time this weekend

[jrudolph]

You can have a look but I'll guess we'll otherwise fix it next week. Not
sure if a new release is warranted because of that regression but we'll see.

[radusw]

• increase the host-connection-pool.idle-timeout above the value for akka.http.client.idle-timeout

This hasn't worked for me

[jrudolph]

This hasn't worked for me

Did nothing change? Or did just the frequency of the messsages change but
it is still emitting the error? What values did you use?

[radusw]

Did nothing change? Or did just the frequency of the messsages change but it is still emitting the error? What values did you use?

I guess the only effect is that the timer period has increased. I don't think there is a relationship with the client idle-timeout as it is always scheduled regardless.

    def afterRequestFinished(): Unit = {
      shutdownIfRequestedAndPossible()
      resetIdleTimer()
    }    
    ...
    def resetIdleTimer(): Unit = {
      cancelTimer(IdleTimeout)

      if (shouldStopOnIdle) scheduleOnce(IdleTimeout, idleTimeout.asInstanceOf[FiniteDuration])
    }
    ...
    def shouldStopOnIdle: Boolean =
      !shuttingDown && remainingRequested == 0 && idleTimeout.isFinite && hcps.setup.settings.minConnections == 0

Logs:

"event": "Pool shutting down because akka.http.host-connection-pool.idle-timeout 
triggered after 150 seconds."

Config:

akka {
  http {
    client {
      idle-timeout = 120 s
    }

    host-connection-pool {
      idle-timeout = 150 s
    }
  }
}

[el-dom]

In my understanding, you won't get rid of the INFO level logs, as they are intended. If you don't see the ERROR logs anymore, it did work.

[radusw]

In my understanding, you won't get rid of the INFO level logs, as they are intended. If you don't see the ERROR logs anymore, it did work.

Ah, yes, you are right. I confused which pool the logs were from as I have in my service another pool configured to 30 seconds, while the client timeout was set to 120 seconds.
So, yes, this workaround works for long running services and we get only INFO level spam.

But, the problem is that I have also have some short lived batch jobs and at the end of the program I shutdown the pools ( httpClient.shutdownAllConnectionPools() ) and of course this cause the ERRORs to surface again and this can't be fixed by playing around with the timeouts.

[radusw]

@jrudolph Any ideas about how can I exclude the Pool slot was shut down errors from being logged?

[jrudolph]

@radusw, you might install a custom logging filter with the akka.logging-filter setting to filter out those message until this issue is fixed.

[robstoll]

I experience the same issue, however, I already used 10.1.10 and it worked fine. It started when I switched to actor typed, using toUntyped for akka-http

[Ksisu]

@jrudolph Any ideas about how can I exclude the Pool slot was shut down errors from being logged?

If you use logback you can set WARN level for this class.

<logger name="akka.http.impl.engine.client.PoolGateway" level="WARN"/>

[will-sargent-eero]

I'm running into this as well.

[psisoyev]

If you use logback you can set WARN level for this class.

<logger name="akka.http.impl.engine.client.PoolGateway" level="WARN"/>

This won't help as the message is ERROR level. I have tried setting it to OFF, but it didn't help as well.

[froth]

The used logger name is akka.actor.ActorSystemImpl but I do not think that it would be wise to disable logging for this class...
But if you want:

  <logger name="akka.actor.ActorSystemImpl" level="OFF"/>

@radusw what I tried to do is disabling the logging only during shutdown before I call shutdownAllConnectionPools:

  private[this] def disableAkkaSystemLoggingDuringShutdown(): Unit = {
    val loggerContext = LoggerFactory.getILoggerFactory.asInstanceOf[LoggerContext]
    val akkaSystemLogger = loggerContext.getLogger("akka.actor.ActorSystemImpl")
    akkaSystemLogger.setLevel(Level.OFF)
  }

LoggerContext and Level are from ch.qos.logback.classic

[aserrallerios]

Is this supposed to get rid of the ERROR messages? I don't mind any additional INFO logs.

akka {
  http {
    client {
      idle-timeout = 120 s
    }

    host-connection-pool {
      idle-timeout = 150 s
    }
  }
}

In my case it's not working, so, what is this config supposed to fix?

[jrudolph]

In my case is not working, so, what is this config supposed to fix?

It will only help if the idle timeout now triggers less than before. If you only send request every now and then and the idle timeout still triggers you will still get the warning.

We know this is a nuisance and will release a fix with 10.1.11 which is planned for the next weeks.

[cjxiao]

It's said this issue is fixed in 10.1.11. But I'm still seeing this error log.

[INFO] ... Pool is now shutting down as requested.
[ERROR] ... [akka.actor.ActorSystemImpl(ShardingSystem)] Outgoing request stream error (akka.http.impl.engine.client.pool.NewHostConnectionPool$HostConnectionPoolStage$$anon$1$Slot$$anon$2: Pool slot was shut down)

val akkaHttpVersion = "10.1.11"
...
      "com.typesafe.akka" %% "akka-http"   % akkaHttpVersion,

[jrudolph]

It's said this issue is fixed in 10.1.11. But I'm still seeing this error log.

I cannot see how that would still happen 10.1.11. Could you (or anyone of the people who :+1:'d provide steps to reproduce with akka-http 10.1.11?

[jrudolph]

This minimal example doesn't show the extra log messages any more with 10.1.11:

package example

import akka.actor.ActorSystem
import akka.http.scaladsl.Http
import akka.http.scaladsl.model.HttpRequest

object AkkaClientTest extends App {
  implicit val system = ActorSystem()
  import system.dispatcher

  Http().singleRequest(HttpRequest(uri = "http://localhost:12349/")).onComplete { res =>
    println(res)
  }
}

build.sbt:

val scalaV = "2.13.1"

libraryDependencies ++= Seq(
  "com.typesafe.akka" %% "akka-stream" % "2.6.1",
  "com.typesafe.akka" %% "akka-http-core" % "10.1.11"
)

scalaVersion := scalaV

[cjxiao]

It's said this issue is fixed in 10.1.11. But I'm still seeing this error log.

I cannot see how that would still happen 10.1.11. Could you (or anyone of the people who 👍'd provide steps to reproduce with akka-http 10.1.11?

Sorry for forgetting to update my case here: it turned out it was due to some configuration bug in my code. Your fix works!

[nterry]

@cjxiao What was the config issue? I am seeing this issue

[cjxiao]

@cjxiao What was the config issue? I am seeing this issue

The akka http settings in my application.conf didn't take effect.