Http client pool does not re-use connection that idle-times out on CloseDelimited

[jypma]

When a misbehaving server just returns 503 Service Unavailable with a Connection: close, but then never closes the connection, we hit the internal idle-timeout on the connection pool, but that signal somehow doesn't reach PoolConductor; it doesn't re-use that connection slot.

Reproducer:

import com.typesafe.config.ConfigFactory
import scala.concurrent.duration._
import akka.actor.ActorSystem
import akka.http.scaladsl.Http
import java.net.ServerSocket
import scala.io.BufferedSource
import java.io.PrintStream
import akka.http.scaladsl.model.HttpRequest
import akka.stream.ActorMaterializer
import scala.concurrent.Future
import scala.concurrent.Await
import org.scalatest.WordSpec

class HttpLingerConnSpec extends WordSpec  {
  val config = ConfigFactory.parseString("""
akka {
  loglevel = "DEBUG"
}
akka.http {
  client {
    idle-timeout = 2 seconds // seems to not affect behaviour
  }
  host-connection-pool {
    max-connections = 4
    client {
      idle-timeout = 2 seconds
    }
  }
}
""")
  implicit val system = ActorSystem("test", config)
  implicit val materializer = ActorMaterializer()
  import system.dispatcher
  val http = Http(system)
  
  "a misbehaving server" should {
    
      new Thread {
    override def run {
      val server = new ServerSocket(9999)
      while (true) {
          val s = server.accept()
          val in = new BufferedSource(s.getInputStream()).getLines()
          val out = new PrintStream(s.getOutputStream())
      
          in.find(_.isEmpty()) // read until end of request headers
          out.print("HTTP/1.1 503 Service Not Available\r\n")
          out.print("\r\n")
          // leave socket lingering after this.
      }      
    }
  }.start()
  

    "still allow a connection pool slot to be reused" in {
      
  val f = (0.until(10)).map(i => {
    println("Making request " + i)
    http.singleRequest(HttpRequest(uri = "http://localhost:9999")).map { resp =>
      println("Response " + i + ": " + resp)
      resp
    }
  })
  
  Await.result(Future.sequence(f), 15.seconds)
    }
  } 
}

The debug logging shows the idle-timeout kicking in after 2 seconds, but nothing after that.

[jrudolph]

Thanks a lot, @jypma. I'll have a look tomorrow.

[jrudolph]

I've found the problem. It's that too many outstanding request completions can clog the pipeline in this line:

akka-http/akka-http-core/src/main/scala/akka/http/impl/engine/client/PoolConductor.scala

Line 83 in 40bd7a2

case SlotEvent.RequestCompletedFuture(future) ⇒ future

The underlying problem (at least one of them) seems to be that the idle timeout doesn't fail the incoming response stream.

[jrudolph]

The actual problem is that you don't read the response entity (which would have bad performance in any case).

The thing that we didn't realize so far is that if you don't read the entity, the idle timeout won't free the slot again, so that's the bug we need to fix.

We can fix this by either

• always pre-materializing the entity stream (e.g. using Sink.asPublisher?) so that the idle timeout at least reaches the PoolSlot
• or by adding another timeout that makes sure to drain the entity if hasn't been at least subscribed quickly enough

[jypma]

Ah, reading the response entity on error strikes again... yes, this was originally refactored spray code, that could indeed be the culprit. Adding resp.discardEntityBytes() triggers the idle timeouts properly. Thanks for that!

I'm afraid I don't know enough about the internals at this point to evaluate the proposed solutions for triggering a timeout when the response is not read.

[gosubpl]

Very leaky abstraction that Client Pool is.

[maheshb415]

Hi guyz, I have encountered same problem with akka http version 10.0.5 and akka version 2.5.0.
I see an increase in number of dead sockets in state "can't identify protocol" whenever we hit the "akka.stream.scaladsl.TcpIdleTimeoutException" in Http().cachedHostConnectionPoolHttps.
Please tell me which akka-http version has the fix for this?

[jrudolph]

I'm going to close this one because it is likely fixed with the new pool implementation which is the default in 10.1.x.