Client leaks connections on cancellation #1188
Description
Hello there!
It appears that the JdkHttpClient doesn't properly release connections when a request is cancelled, leading to a leak of file descriptors.
Code to reproduce (it's slightly messy, but it does the job):
//> using dep org.http4s:http4s-jdk-http-client_2.13:0.10.0
//> using dep org.http4s:http4s-dsl_2.13:0.23.30
//> using dep org.http4s:http4s-blaze-server_2.13:0.23.17
import cats.effect._
import cats.effect.std._
import cats.syntax.all._
import org.http4s._
import org.http4s.blaze.server._
import org.http4s.client._
import org.http4s.dsl.io._
import org.http4s.jdkhttpclient._
import org.http4s.syntax.literals._
import scala.concurrent.duration._
object Main extends IOApp {
val port: Int = 8081
val app = HttpRoutes
.of[IO] { case GET -> Root =>
Ok {
IO
.sleep(3.seconds)
.as("this is a response")
}
}
.orNotFound
val server =
BlazeServerBuilder[IO]
.bindLocal(port)
.withHttpApp(app)
.resource
val request = (client: Client[IO]) =>
client.expect[String](s"http://localhost:$port/")
val step = (msg: String) => IO.println(s"---------- $msg ----------")
val makeClient = JdkHttpClient.simple[IO]
val leaks = (client: Client[IO]) =>
step("starting leaking code") >>
request(client).timeoutTo(1.seconds, IO.println("timed out")) >>
step("leaking code exited")
val doesntLeak = (client: Client[IO]) =>
step("starting non-leaking code") >>
request(client) >>
step("non-leaking code exited")
val init =
IO.delay(java.lang.ProcessHandle.current().pid())
.flatMap(IO.println)
.toResource >> (server, makeClient).tupled
def run(args: List[String]) =
init.use { case (_, client) =>
for {
_ <- args.take(1) match {
case List("leak") => leaks(client)
case List("no-leak") => doesntLeak(client)
case Nil => doesntLeak(client)
case _ => IO.raiseError(new RuntimeException("bad arguments"))
}
_ <- step(
"keeping alive for 15 seconds (connections will close after 10 s)"
)
_ <- IO.sleep(15.seconds)
_ <- step("closing connections(?)")
} yield ()
} >> step("client exited").as(ExitCode.Success)
}Run with -Djdk.httpclient.HttpClient.log=trace and -Djdk.httpclient.keepalive.timeout=10. (Scala CLI command: scala-cli run --java-opt -Djdk.httpclient.HttpClient.log=trace --java-opt -Djdk.httpclient.keepalive.timeout=10 -S 2.13.16 repro.scala --)
Run without leaking:
% scala-cli run --java-opt -Djdk.httpclient.HttpClient.log=trace --java-opt -Djdk.httpclient.keepalive.timeout=10 -S 2.13.16 repro.scala --
SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.
38438
---------- starting non-leaking code ----------
Jun 03, 2025 1:18:48 PM jdk.internal.net.http.MultiExchange requestFilters
INFO: MISC: Applying request filters
Jun 03, 2025 1:18:48 PM jdk.internal.net.http.MultiExchange requestFilters
INFO: MISC: Applying jdk.internal.net.http.AuthenticationFilter@664d031e
Jun 03, 2025 1:18:48 PM jdk.internal.net.http.MultiExchange requestFilters
INFO: MISC: Applying jdk.internal.net.http.RedirectFilter@3df72b50
Jun 03, 2025 1:18:48 PM jdk.internal.net.http.MultiExchange requestFilters
INFO: MISC: All filters applied
Jun 03, 2025 1:18:48 PM jdk.internal.net.http.HttpClientImpl registerTimer
INFO: MISC: Registering timer ConnectTimerEvent, TimeoutEvent[id=1, duration=PT10S, deadline=2025-06-03T13:18:58.464610080Z]
Jun 03, 2025 1:18:48 PM jdk.internal.net.http.HttpClientImpl cancelTimer
INFO: MISC: Canceling timer ConnectTimerEvent, TimeoutEvent[id=1, duration=PT10S, deadline=2025-06-03T13:18:58.464610080Z]
Jun 03, 2025 1:18:51 PM jdk.internal.net.http.MultiExchange responseFilters
INFO: MISC: Applying response filters
Jun 03, 2025 1:18:51 PM jdk.internal.net.http.MultiExchange responseFilters
INFO: MISC: Applying jdk.internal.net.http.RedirectFilter@3df72b50
Jun 03, 2025 1:18:51 PM jdk.internal.net.http.MultiExchange responseFilters
INFO: MISC: Applying jdk.internal.net.http.AuthenticationFilter@664d031e
Jun 03, 2025 1:18:51 PM jdk.internal.net.http.MultiExchange responseFilters
INFO: MISC: All filters applied
Jun 03, 2025 1:18:51 PM jdk.internal.net.http.Http1Response onFinished
INFO: MISC: Attempting to return connection to the pool: PlainHttpConnection: HttpConnection: java.nio.channels.SocketChannel[connected local=/127.0.0.1:41830 remote=localhost/127.0.0.1:8081]
Jun 03, 2025 1:18:51 PM jdk.internal.net.http.HttpConnection closeOrReturnToCache
INFO: MISC: Returning connection to the pool: PlainHttpConnection: HttpConnection: java.nio.channels.SocketChannel[connected local=/127.0.0.1:41830 remote=localhost/127.0.0.1:8081]
---------- non-leaking code exited ----------
---------- keeping alive for 15 seconds (connections will close after 10 s) ----------
Jun 03, 2025 1:19:01 PM jdk.internal.net.http.PlainHttpConnection close
INFO: MISC: Closing: PlainHttpConnection: HttpConnection: java.nio.channels.SocketChannel[connected local=/127.0.0.1:41830 remote=localhost/127.0.0.1:8081]
Jun 03, 2025 1:19:01 PM jdk.internal.net.http.HttpClientImpl cancelTimer
INFO: MISC: Canceling timer ConnectTimerEvent, TimeoutEvent[id=1, duration=PT10S, deadline=2025-06-03T13:18:58.464610080Z]
---------- closing connections(?) ----------
Jun 03, 2025 1:19:06 PM jdk.internal.net.http.HttpClientImpl$SelectorManager run
INFO: MISC: HttpClient-1-SelectorManager: HttpClient finished. Exiting...
Jun 03, 2025 1:19:06 PM jdk.internal.net.http.HttpClientImpl$SelectorManager shutdown
INFO: MISC: HttpClient-1-SelectorManager: shutting down
---------- client exited ----------
Run with leaking:
% scala-cli run --java-opt -Djdk.httpclient.HttpClient.log=trace --java-opt -Djdk.httpclient.keepalive.timeout=10 -S 2.13.16 repro.scala -- leak
SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.
38974
---------- starting leaking code ----------
Jun 03, 2025 1:24:29 PM jdk.internal.net.http.MultiExchange requestFilters
INFO: MISC: Applying request filters
Jun 03, 2025 1:24:29 PM jdk.internal.net.http.MultiExchange requestFilters
INFO: MISC: Applying jdk.internal.net.http.AuthenticationFilter@d1f2aed
Jun 03, 2025 1:24:29 PM jdk.internal.net.http.MultiExchange requestFilters
INFO: MISC: Applying jdk.internal.net.http.RedirectFilter@12e2e860
Jun 03, 2025 1:24:29 PM jdk.internal.net.http.MultiExchange requestFilters
INFO: MISC: All filters applied
Jun 03, 2025 1:24:29 PM jdk.internal.net.http.HttpClientImpl registerTimer
INFO: MISC: Registering timer ConnectTimerEvent, TimeoutEvent[id=1, duration=PT10S, deadline=2025-06-03T13:24:39.919649937Z]
Jun 03, 2025 1:24:29 PM jdk.internal.net.http.HttpClientImpl cancelTimer
INFO: MISC: Canceling timer ConnectTimerEvent, TimeoutEvent[id=1, duration=PT10S, deadline=2025-06-03T13:24:39.919649937Z]
timed out
---------- leaking code exited ----------
---------- keeping alive for 15 seconds (connections will close after 10 s) ----------
Jun 03, 2025 1:24:33 PM jdk.internal.net.http.MultiExchange responseFilters
INFO: MISC: Applying response filters
Jun 03, 2025 1:24:33 PM jdk.internal.net.http.MultiExchange responseFilters
INFO: MISC: Applying jdk.internal.net.http.RedirectFilter@12e2e860
Jun 03, 2025 1:24:33 PM jdk.internal.net.http.MultiExchange responseFilters
INFO: MISC: Applying jdk.internal.net.http.AuthenticationFilter@d1f2aed
Jun 03, 2025 1:24:33 PM jdk.internal.net.http.MultiExchange responseFilters
INFO: MISC: All filters applied
---------- closing connections(?) ----------
# the process hangs here and never exits
# In a separate terminal
% lsof -p 38974
...
java 38974 rasmus.precenth 93u IPv6 103576 0t0 TCP localhost:53658->localhost:sunproxyadmin (CLOSE_WAIT)
In short, cancelling the requests leaves the connection in a stuck state that it never recovers from.
I can see that the code tries its best to juggle cancelable and uncancelable effects, but that seems to not be enough in this case.