Http4s: BlazeClient: requestTimeout is not enforced

[mblaze]

Problem Description

requestTimeout in BlazeClient is not enforced on certain requests.

Expected behavior: A timeout exception is thrown after 1 second.

Actual behavior: The request seems to be stuck indefinitely.

Related issues: #2338 (almost certainly the same source of the problem)

Source

Main.scala

import cats.effect._
import org.http4s._
import org.http4s.client.blaze.BlazeClientBuilder

import scala.concurrent.duration._
import scala.concurrent.ExecutionContext

object Main extends IOApp {

  override def run(args: List[String]): IO[ExitCode] = for {
    c <- BlazeClientBuilder[IO](ExecutionContext.global)
        .withRequestTimeout(1.second)
        .resource
        .allocated
    (client, _) = c
    _ <- IO { println("Sending a request.") }
    _ <- client.fetch(Request[IO](Method.GET, Uri.unsafeFromString("http://1.2.3.4:12345/")))(_ => IO.unit)
    _ <- IO { println("Got a response.") }
  } yield ExitCode.Success
}

build.sbt

name := "http4s-client-request-timeout-bug"

version := "0.1"

scalaVersion := "2.12.8"

libraryDependencies ++= Seq(
  "org.typelevel" %% "cats-core" % "1.5.0",
  "org.typelevel" %% "cats-effect" % "1.1.0",
  "org.http4s" %% "http4s-blaze-client" % "0.20.0-M5"
)

[kevinmeredith]

$time(curl -vi http://1.2.3.4:12345/)
*   Trying 1.2.3.4...
* TCP_NODELAY set
* Connection failed
* connect to 1.2.3.4 port 12345 failed: Operation timed out
* Failed to connect to 1.2.3.4 port 12345: Operation timed out
* Closing connection 0
curl: (7) Failed to connect to 1.2.3.4 port 12345: Operation timed out

real    1m15.105s
user    0m0.008s
sys 0m0.008s

My understanding of the above output is that the TCP Connection failed to become established.

Looking at the comment for requestTimeout:

requestTimeout maximum duration from the submission of a request through reading the body before a timeout.

https://github.com/http4s/http4s/blob/master/blaze-client/src/main/scala/org/http4s/client/blaze/BlazeClientConfig.scala#L17-L18

So, I'm guessing that this timeout counter doesn't begin when setting up the TCP Connection. I have no real experience with the Blaze code, so that's only a guess.

[RafalSumislawski]

@kevinmeredith
Yes, this is a failure to establish TCP connection, the timeout works correctly for regular cases of slow requests.

My understanding of "submission of a request" is "the moment client.fetch is executed".

The timeout is implemented here: https://github.com/http4s/http4s/blob/master/blaze-client/src/main/scala/org/http4s/client/blaze/BlazeClient.scala#L145 and it covers the execution of res - that includes establishing the connection, which is delegated to manager.borrow here: https://github.com/http4s/http4s/blob/master/blaze-client/src/main/scala/org/http4s/client/blaze/BlazeClient.scala#L63 .

An acquire operation of cats' Bracket/Resource is uncancelable, so given the implementation we have here, it's not very surprising that the 1.second timeout fails to be enforced. The surprising thing here is that the operation never ends despite the acquire operation failing after some lower-level connection establishing timeout.

I've tracked this issue down to strange behaviour of cancel on Bracket, reproducible with the following sample (no http4s involved):

  override def run(args: List[String]): IO[ExitCode] = for {
    _ <- IO(println(s"${System.currentTimeMillis()} Starting..."))
    result <- IO.race(
      Effect[IO].bracket( IO.sleep(4.seconds) *> IO.raiseError[String](new Exception("")))(_ => IO.pure("success"))(_ => IO.unit),
      IO.sleep(2.second) *> IO.pure("timeout")
    ).attempt
    _ <- IO(println(s"${System.currentTimeMillis()} Done: $result"))
  } yield ExitCode.Success

I would expect it to end in 4 seconds, but it doesn't.

It seems this is the cats issue we're facing: https://github.com/typelevel/cats-effect/issues/487

The workaround (attempt) described there can applied in http4s. As a further improvement the completion of a request could be decoupled in time from releasing resources (waiting for the connection establishing timeout).

[kevinmeredith]

Once https://github.com/typelevel/cats-effect/pull/499 gets published*, someone can open an http4s PR that will upgrade it to use that published version of cats-effect, which will then fix this issue?

*I'm assuming they're not since I don't see @RafalSumislawski's changes in https://github.com/typelevel/cats-effect/blob/v1.2.0/core/shared/src/main/scala/cats/effect/internals/IOBracket.scala

[RafalSumislawski]

The fix for typelevel/cats-effect#499 is in master, but there was no release since it was merged. I'll take care of removing the workaround code once a fixed casts-effect version is available.

[anilkumarmyla]

There is a new version 1.3.0 of cats-effect that was released today!

[RafalSumislawski]

Work-around removed in #2549

[rossabaker]

Fixed by #2470.