ZClient - PrematureChannelClosureException

[xkrillex]

Describe the bug
io.netty.handler.codec.PrematureChannelClosureException: Channel closed while executing the request. This is likely caused due to a client connection misconfiguration / io.netty.handler.codec.PrematureChannelClosureException: channel gone inactive with 1 missing response(s) when making simple HTTP GET requests

Note 10 second idleTimeout on the client config.

ZIO-HTTP-3.0.0-RC6

To Reproduce

package reproducer

import zio.http.*
import zio.*
import zio.http.netty.NettyConfig
import zio.durationInt

object ReproducerShortIdleTimeout extends ZIOAppDefault {

  override def run: ZIO[Any, Any, Unit] = {

    val appLogic = for {
      _ <- ZIO.logInfo("Starting HTTP server")

      routes = Routes(
        Method.GET / "sleep" / int("seconds") -> handler { (duration: Int, _: Request) =>
          ZIO.sleep(duration.seconds).as(Response.ok)
        },
        Method.GET / "makeSleepRequest" / int("seconds") -> handler { (seconds:Int, _: Request) =>
          for {
            _ <- ZIO.logInfo(s"Make Sleep Request: $seconds")
            client <- ZIO.service[ZClient[Any, Body, Throwable, Response]]
            _ <- ZIO.scoped {
              client.request(Request.get(s"http://127.0.0.1:8080/sleep/$seconds"))
                .tap {
                  response =>
                    ZIO.logInfo(s"Got response. Status: ${response.status.code} ")
                }
                .unit
                .catchAllCause {
                  cause =>
                    ZIO.logErrorCause(cause).unit
                }
            }
          } yield Response.ok
        }
      )

      port <- Server.install(routes.toHttpApp)
      _ <- ZIO.logInfo(s"Server started on port: $port")
      _ <- ZIO.never
    } yield ()

    val clientConfig = ZClient.Config.default.idleTimeout(10.seconds)
    val zClient = (ZLayer.succeed(clientConfig) ++ ZLayer.succeed(NettyConfig.defaultWithFastShutdown) ++ DnsResolver.default) >>> ZClient.live

    appLogic.provide(
      ZLayer.succeed(Server.Config.default.binding("0.0.0.0", 8080)),
      ZLayer.succeed(NettyConfig.default),
      zClient,
      Server.customized,
    ).catchAllCause(cause => ZIO.logErrorCause("Encountered an fatal error", cause))

  }

}

Making a GET Request to http://127.0.0.1:8080/makeSleepRequest/10 gives following output (no successful responses - sleep time equals idleTimeout):

timestamp=2024-05-13T10:46:04.255313800Z level=INFO thread=#zio-fiber-48 message="Make Sleep Request: 10" location=reproducer.Reproducer.run.appLogic.routes file=Reproducer.scala line=21
timestamp=2024-05-13T10:46:14.353016Z level=ERROR thread=#zio-fiber-48 message="" cause="Exception in thread "zio-fiber-48" io.netty.handler.codec.PrematureChannelClosureException: Channel closed while executing the request. This is likely caused due to a client connection misconfiguration
	at zio.http.netty.client.NettyClientDriver.requestOnChannel$$anonfun$1$$anonfun$2$$anonfun$2$$anonfun$1(NettyClientDriver.scala:171)
	at zio.ZIO$ZIOBooleanOps$.$amp$amp$extension$$anonfun$1(ZIO.scala:5186)
	at zio.ZIO$ZIOBooleanOps$.$amp$amp$extension$$anonfun$adapted$1(ZIO.scala:5186)
	at reproducer.Reproducer.run.appLogic.routes(Reproducer.scala:24)
	at reproducer.Reproducer.run.appLogic.routes(Reproducer.scala:28)
	at reproducer.Reproducer.run.appLogic.routes(Reproducer.scala:29)
	at reproducer.Reproducer.run.appLogic.routes(Reproducer.scala:33)
	at reproducer.Reproducer.run.appLogic.routes(Reproducer.scala:34)
	at reproducer.Reproducer.run.appLogic.routes(Reproducer.scala:35)" location=reproducer.Reproducer.run.appLogic.routes file=Reproducer.scala line=32

Making 3 subsequent GET Requests to http://127.0.0.1:8080/makeSleepRequest/4 (4 seconds sleep time) gives following output (first two requests are successful - third which goes past idleTimeout are not successful):

timestamp=2024-05-13T10:51:53.547703600Z level=INFO thread=#zio-fiber-48 message="Make Sleep Request: 4" location=reproducer.ReproducerShortIdleTimeout.run.appLogic.routes file=Reproducer.scala line=21
timestamp=2024-05-13T10:51:57.677798800Z level=INFO thread=#zio-fiber-48 message="Got response. Status: 200 " location=reproducer.ReproducerShortIdleTimeout.run.appLogic.routes file=Reproducer.scala line=27
timestamp=2024-05-13T10:51:59.265433100Z level=INFO thread=#zio-fiber-58 message="Make Sleep Request: 4" location=reproducer.ReproducerShortIdleTimeout.run.appLogic.routes file=Reproducer.scala line=21
timestamp=2024-05-13T10:52:03.291908800Z level=INFO thread=#zio-fiber-58 message="Got response. Status: 200 " location=reproducer.ReproducerShortIdleTimeout.run.appLogic.routes file=Reproducer.scala line=27
timestamp=2024-05-13T10:52:04.075285500Z level=INFO thread=#zio-fiber-73 message="Make Sleep Request: 4" location=reproducer.ReproducerShortIdleTimeout.run.appLogic.routes file=Reproducer.scala line=21
timestamp=2024-05-13T10:52:07.687879800Z level=ERROR thread=#zio-fiber-73 message="" cause="Exception in thread "zio-fiber-73" io.netty.handler.codec.PrematureChannelClosureException: channel gone inactive with 1 missing response(s)
	at io.netty.handler.codec.http.HttpClientCodec$Decoder.channelInactive(HttpClientCodec.java:333)
	at io.netty.channel.CombinedChannelDuplexHandler.channelInactive(CombinedChannelDuplexHandler.java:221)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:303)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:281)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:274)
	at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:81)
	at io.netty.handler.timeout.IdleStateHandler.channelInactive(IdleStateHandler.java:277)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:303)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:281)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:274)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelInactive(DefaultChannelPipeline.java:1405)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:301)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:281)
	at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:901)
	at io.netty.channel.AbstractChannel$AbstractUnsafe$7.run(AbstractChannel.java:813)
	at io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java:173)
	at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:166)
	at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:470)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:569)
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.base/java.lang.Thread.run(Thread.java:840)
	at reproducer.ReproducerShortIdleTimeout.run.appLogic.routes(Reproducer.scala:24)
	at reproducer.ReproducerShortIdleTimeout.run.appLogic.routes(Reproducer.scala:28)
	at reproducer.ReproducerShortIdleTimeout.run.appLogic.routes(Reproducer.scala:29)
	at reproducer.ReproducerShortIdleTimeout.run.appLogic.routes(Reproducer.scala:33)
	at reproducer.ReproducerShortIdleTimeout.run.appLogic.routes(Reproducer.scala:34)
	at reproducer.ReproducerShortIdleTimeout.run.appLogic.routes(Reproducer.scala:35)" location=reproducer.ReproducerShortIdleTimeout.run.appLogic.routes file=Reproducer.scala line=32

[xkrillex]

Changing to val clientConfig = ZClient.Config.default.idleTimeout(10.seconds).disabledConnectionPool gives no errors

[kyri-petrou]

Thanks for reporting @xkrillex. This issue seems to be present only under ZIO 2.1.x. #2843 fixes it

[xkrillex]

@kyri-petrou The reproducer and results described above was with ZIO 2.0.21. I have now tested with ZIO 2.1.1 and ZIO-HTTP 3.0.0-RC7. The issue is still exactly the same

[kyri-petrou]

@xkrillex my bad, I only just realised this issue was related to idleTimeout rather than ZIO 2.1.x. I'll reopen it and check it out

[hearnadam]

@kyri-petrou @jdegoes when do you plan to cut a release?

[kyri-petrou]

@kyri-petrou @jdegoes when do you plan to cut a release?

I'm not an admin of this repo, but I think @987Nabil is going to make one soon

[987Nabil]

I'll do one over the weekend

[hearnadam]

@987Nabil please ping me when the release is ready.