blaze icon indicating copy to clipboard operation
blaze copied to clipboard
verified publisher icon http4s

Disturbing error logs from blaze-client 0.17 under heavy load

Open mflis opened this issue 8 years ago • 26 comments

Problem occurs with blaze client (version 0.17.0-M3). I'm using default PooledHttp1Client() and after performing load testing with apache benchmark(and other tools like siege or gatling)(few thousands GET requests, concurrency level 15) I get stacktrace listed below. Despite error message everything seems to work fine(All the messages I'm getting from client are correct)

Background:

  • I'm using akka-http as server and http4s as a client for getting request
  • I've set up mock server for testing performance, so client is getting always the same message
  • sometimes error occurs only after few hundred messages, sometimes after few thousands.

Discussion on gitter suggested that it's probably debug message that somehow got to stacktrace

[info] java.lang.Exception: Cannot send inbound command on disconnected stage
[info] 	at org.http4s.blaze.pipeline.Head$class.sendInboundCommand(Stages.scala:241) [blaze-core_2.11-0.12.5.jar:0.12.5]
[info] 	at org.http4s.client.blaze.ClientTimeoutStage.sendInboundCommand(ClientTimeoutStage.scala:17) [http4s-blaze-client_2.11-0.17.0-M3.jar:0.17.0-M3]
[info] 	at org.http4s.blaze.pipeline.Head$class.inboundCommand(Stages.scala:251) [blaze-core_2.11-0.12.5.jar:0.12.5]
[info] 	at org.http4s.client.blaze.ClientTimeoutStage.inboundCommand(ClientTimeoutStage.scala:17) [http4s-blaze-client_2.11-0.17.0-M3.jar:0.17.0-M3]
[info] 	at org.http4s.blaze.pipeline.Head$class.sendInboundCommand(Stages.scala:238) [blaze-core_2.11-0.12.5.jar:0.12.5]
[info] 	at org.http4s.client.blaze.ReadBufferStage.sendInboundCommand(ReadBufferStage.scala:14) [http4s-blaze-client_2.11-0.17.0-M3.jar:0.17.0-M3]
[info] 	at org.http4s.blaze.pipeline.Head$class.inboundCommand(Stages.scala:251) [blaze-core_2.11-0.12.5.jar:0.12.5]
[info] 	at org.http4s.client.blaze.ReadBufferStage.inboundCommand(ReadBufferStage.scala:14) [http4s-blaze-client_2.11-0.17.0-M3.jar:0.17.0-M3]
[info] 	at org.http4s.blaze.pipeline.Head$class.sendInboundCommand(Stages.scala:238) [blaze-core_2.11-0.12.5.jar:0.12.5]
[info] 	at org.http4s.blaze.channel.nio2.ByteBufferHead.sendInboundCommand(ByteBufferHead.scala:17) [blaze-core_2.11-0.12.5.jar:0.12.5]
[info] 	at org.http4s.blaze.channel.nio2.ByteBufferHead$$anon$3.failed(ByteBufferHead.scala:90) [blaze-core_2.11-0.12.5.jar:0.12.5]
[info] 	at org.http4s.blaze.channel.nio2.ByteBufferHead$$anon$3.failed(ByteBufferHead.scala:87) [blaze-core_2.11-0.12.5.jar:0.12.5]
[info] 	at sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:128) [na:1.8.0_131]
[info] 	at sun.nio.ch.Invoker$2.run(Invoker.java:218) [na:1.8.0_131]
[info] 	at sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112) [na:1.8.0_131]
[info] 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_131]
[info] 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_131]
[info] 	at java.lang.Thread.run(Thread.java:748) [na:1.8.0_131]
[info]  [2017-07-11T08:43:30.867Z] [ERROR]; ; ReadBufferingStage received unhandled error command
[info] java.lang.Exception: Cannot send inbound command on disconnected stage
[info] 	at org.http4s.blaze.pipeline.Head$class.sendInboundCommand(Stages.scala:241) [blaze-core_2.11-0.12.5.jar:0.12.5]
[info] 	at org.http4s.client.blaze.ClientTimeoutStage.sendInboundCommand(ClientTimeoutStage.scala:17) ~[http4s-blaze-client_2.11-0.17.0-M3.jar:0.17.0-M3]
[info] 	at org.http4s.blaze.pipeline.Head$class.inboundCommand(Stages.scala:251) [blaze-core_2.11-0.12.5.jar:0.12.5]
[info] 	at org.http4s.client.blaze.ClientTimeoutStage.inboundCommand(ClientTimeoutStage.scala:17) ~[http4s-blaze-client_2.11-0.17.0-M3.jar:0.17.0-M3]
[info] 	at org.http4s.blaze.pipeline.Head$class.sendInboundCommand(Stages.scala:238) [blaze-core_2.11-0.12.5.jar:0.12.5]
[info] 	at org.http4s.client.blaze.ReadBufferStage.sendInboundCommand(ReadBufferStage.scala:14) [http4s-blaze-client_2.11-0.17.0-M3.jar:0.17.0-M3]
[info] 	at org.http4s.blaze.pipeline.Head$class.inboundCommand(Stages.scala:251) [blaze-core_2.11-0.12.5.jar:0.12.5]
[info] 	at org.http4s.client.blaze.ReadBufferStage.inboundCommand(ReadBufferStage.scala:14) [http4s-blaze-client_2.11-0.17.0-M3.jar:0.17.0-M3]
[info] 	at org.http4s.blaze.pipeline.Head$class.sendInboundCommand(Stages.scala:238) [blaze-core_2.11-0.12.5.jar:0.12.5]
[info] 	at org.http4s.blaze.channel.nio2.ByteBufferHead.sendInboundCommand(ByteBufferHead.scala:17) [blaze-core_2.11-0.12.5.jar:0.12.5]
[info] 	at org.http4s.blaze.channel.nio2.ByteBufferHead$$anon$3.failed(ByteBufferHead.scala:90) [blaze-core_2.11-0.12.5.jar:0.12.5]
[info] 	at org.http4s.blaze.channel.nio2.ByteBufferHead$$anon$3.failed(ByteBufferHead.scala:87) [blaze-core_2.11-0.12.5.jar:0.12.5]
[info] 	at sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:128) [na:1.8.0_131]
[info] 	at sun.nio.ch.Invoker$2.run(Invoker.java:218) [na:1.8.0_131]
[info] 	at sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112) [na:1.8.0_131]
[info] 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_131]
[info] 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_131]
[info] 	at java.lang.Thread.run(Thread.java:748) [na:1.8.0_131]
[info]  [2017-07-11T08:43:30.868Z] [ERROR]; ; NIO2 channel closed with an unexpected error
[info] java.lang.Exception: Cannot send inbound command on disconnected stage
[info] 	at org.http4s.blaze.pipeline.Head$class.sendInboundCommand(Stages.scala:241) [blaze-core_2.11-0.12.5.jar:0.12.5]
[info] 	at org.http4s.client.blaze.ClientTimeoutStage.sendInboundCommand(ClientTimeoutStage.scala:17) ~[http4s-blaze-client_2.11-0.17.0-M3.jar:0.17.0-M3]
[info] 	at org.http4s.blaze.pipeline.Head$class.inboundCommand(Stages.scala:251) [blaze-core_2.11-0.12.5.jar:0.12.5]
[info] 	at org.http4s.client.blaze.ClientTimeoutStage.inboundCommand(ClientTimeoutStage.scala:17) ~[http4s-blaze-client_2.11-0.17.0-M3.jar:0.17.0-M3]
[info] 	at org.http4s.blaze.pipeline.Head$class.sendInboundCommand(Stages.scala:238) [blaze-core_2.11-0.12.5.jar:0.12.5]
[info] 	at org.http4s.client.blaze.ReadBufferStage.sendInboundCommand(ReadBufferStage.scala:14) [http4s-blaze-client_2.11-0.17.0-M3.jar:0.17.0-M3]
[info] 	at org.http4s.blaze.pipeline.Head$class.inboundCommand(Stages.scala:251) [blaze-core_2.11-0.12.5.jar:0.12.5]
[info] 	at org.http4s.client.blaze.ReadBufferStage.inboundCommand(ReadBufferStage.scala:14) [http4s-blaze-client_2.11-0.17.0-M3.jar:0.17.0-M3]
[info] 	at org.http4s.blaze.pipeline.Head$class.sendInboundCommand(Stages.scala:238) [blaze-core_2.11-0.12.5.jar:0.12.5]
[info] 	at org.http4s.blaze.channel.nio2.ByteBufferHead.sendInboundCommand(ByteBufferHead.scala:17) [blaze-core_2.11-0.12.5.jar:0.12.5]
[info] 	at org.http4s.blaze.channel.nio2.ByteBufferHead$$anon$3.failed(ByteBufferHead.scala:90) [blaze-core_2.11-0.12.5.jar:0.12.5]
[info] 	at org.http4s.blaze.channel.nio2.ByteBufferHead$$anon$3.failed(ByteBufferHead.scala:87) [blaze-core_2.11-0.12.5.jar:0.12.5]
[info] 	at sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:128) [na:1.8.0_131]
[info] 	at sun.nio.ch.Invoker$2.run(Invoker.java:218) [na:1.8.0_131]
[info] 	at sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112) [na:1.8.0_131]
[info] 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_131]
[info] 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_131]
[info] 	at java.lang.Thread.run(Thread.java:748) [na:1.8.0_131]

mflis avatar Jul 14 '17 07:07 mflis

I'm getting the exact same behaviour with version 0.15.13a under heavy load on the pooled HTTP client.

11:54:46 ERROR org.http4s.blaze.pipeline.Stage:259 ReadBufferingStage received unhandled error command
java.lang.Exception: Cannot send inbound command on disconnected stage
	at org.http4s.blaze.pipeline.Head.sendInboundCommand(Stages.scala:241)
	at org.http4s.blaze.pipeline.Head.sendInboundCommand$(Stages.scala:235)
	at org.http4s.client.blaze.ClientTimeoutStage.sendInboundCommand(ClientTimeoutStage.scala:17)
	at org.http4s.blaze.pipeline.Head.inboundCommand(Stages.scala:251)
	at org.http4s.blaze.pipeline.Head.inboundCommand$(Stages.scala:249)
	at org.http4s.client.blaze.ClientTimeoutStage.inboundCommand(ClientTimeoutStage.scala:17)
	at org.http4s.blaze.pipeline.Head.sendInboundCommand(Stages.scala:238)
	at org.http4s.blaze.pipeline.Head.sendInboundCommand$(Stages.scala:235)
	at org.http4s.client.blaze.ReadBufferStage.sendInboundCommand(ReadBufferStage.scala:14)
	at org.http4s.blaze.pipeline.Head.inboundCommand(Stages.scala:251)
	at org.http4s.blaze.pipeline.Head.inboundCommand$(Stages.scala:249)
	at org.http4s.client.blaze.ReadBufferStage.inboundCommand(ReadBufferStage.scala:14)
	at org.http4s.blaze.pipeline.Head.sendInboundCommand(Stages.scala:238)
	at org.http4s.blaze.pipeline.Head.sendInboundCommand$(Stages.scala:235)
	at org.http4s.blaze.channel.nio2.ByteBufferHead.sendInboundCommand(ByteBufferHead.scala:17)
	at org.http4s.blaze.channel.nio2.ByteBufferHead$$anon$3.completed(ByteBufferHead.scala:102)
	at org.http4s.blaze.channel.nio2.ByteBufferHead$$anon$3.completed(ByteBufferHead.scala:87)
	at sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:126)
	at sun.nio.ch.Invoker$2.run(Invoker.java:218)
	at sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:748)
11:54:46 ERROR org.http4s.blaze.pipeline.Stage:125 NIO2 channel closed with an unexpected error
java.lang.Exception: Cannot send inbound command on disconnected stage
	at org.http4s.blaze.pipeline.Head.sendInboundCommand(Stages.scala:241)
	at org.http4s.blaze.pipeline.Head.sendInboundCommand$(Stages.scala:235)
	at org.http4s.client.blaze.ClientTimeoutStage.sendInboundCommand(ClientTimeoutStage.scala:17)
	at org.http4s.blaze.pipeline.Head.inboundCommand(Stages.scala:251)
	at org.http4s.blaze.pipeline.Head.inboundCommand$(Stages.scala:249)
	at org.http4s.client.blaze.ClientTimeoutStage.inboundCommand(ClientTimeoutStage.scala:17)
	at org.http4s.blaze.pipeline.Head.sendInboundCommand(Stages.scala:238)
	at org.http4s.blaze.pipeline.Head.sendInboundCommand$(Stages.scala:235)
	at org.http4s.client.blaze.ReadBufferStage.sendInboundCommand(ReadBufferStage.scala:14)
	at org.http4s.blaze.pipeline.Head.inboundCommand(Stages.scala:251)
	at org.http4s.blaze.pipeline.Head.inboundCommand$(Stages.scala:249)
	at org.http4s.client.blaze.ReadBufferStage.inboundCommand(ReadBufferStage.scala:14)
	at org.http4s.blaze.pipeline.Head.sendInboundCommand(Stages.scala:238)
	at org.http4s.blaze.pipeline.Head.sendInboundCommand$(Stages.scala:235)
	at org.http4s.blaze.channel.nio2.ByteBufferHead.sendInboundCommand(ByteBufferHead.scala:17)
	at org.http4s.blaze.channel.nio2.ByteBufferHead$$anon$3.completed(ByteBufferHead.scala:102)
	at org.http4s.blaze.channel.nio2.ByteBufferHead$$anon$3.completed(ByteBufferHead.scala:87)
	at sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:126)
	at sun.nio.ch.Invoker$2.run(Invoker.java:218)
	at sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:748)
11:54:48 ERROR org.http4s.blaze.pipeline.Stage:126 
java.lang.Exception: Cannot send outbound command on disconnected stage
	at org.http4s.blaze.pipeline.Tail.sendOutboundCommand(Stages.scala:125)
	at org.http4s.blaze.pipeline.Tail.sendOutboundCommand$(Stages.scala:119)
	at org.http4s.client.blaze.ClientTimeoutStage.sendOutboundCommand(ClientTimeoutStage.scala:17)
	at org.http4s.blaze.pipeline.MidStage.outboundCommand(Stages.scala:307)
	at org.http4s.blaze.pipeline.MidStage.outboundCommand$(Stages.scala:305)
	at org.http4s.client.blaze.ClientTimeoutStage.outboundCommand(ClientTimeoutStage.scala:83)
	at org.http4s.blaze.pipeline.Tail.sendOutboundCommand(Stages.scala:122)
	at org.http4s.blaze.pipeline.Tail.sendOutboundCommand$(Stages.scala:119)
	at org.http4s.client.blaze.Http1Connection.sendOutboundCommand(Http1Connection.scala:28)
	at org.http4s.client.blaze.Http1Connection.shutdownWithError(Http1Connection.scala:83)
	at org.http4s.client.blaze.Http1Connection.stageShutdown(Http1Connection.scala:53)
	at org.http4s.blaze.pipeline.Stage.inboundCommand(Stages.scala:65)
	at org.http4s.blaze.pipeline.Stage.inboundCommand$(Stages.scala:63)
	at org.http4s.client.blaze.Http1Connection.inboundCommand(Http1Connection.scala:28)
	at org.http4s.blaze.pipeline.Head.sendInboundCommand(Stages.scala:238)
	at org.http4s.blaze.pipeline.Head.sendInboundCommand$(Stages.scala:235)
	at org.http4s.client.blaze.ClientTimeoutStage.sendInboundCommand(ClientTimeoutStage.scala:17)
	at org.http4s.blaze.pipeline.Head.inboundCommand(Stages.scala:251)
	at org.http4s.blaze.pipeline.Head.inboundCommand$(Stages.scala:249)
	at org.http4s.client.blaze.ClientTimeoutStage.inboundCommand(ClientTimeoutStage.scala:17)
	at org.http4s.blaze.pipeline.Head.sendInboundCommand(Stages.scala:238)
	at org.http4s.blaze.pipeline.Head.sendInboundCommand$(Stages.scala:235)
	at org.http4s.client.blaze.ReadBufferStage.sendInboundCommand(ReadBufferStage.scala:14)
	at org.http4s.blaze.pipeline.Head.inboundCommand(Stages.scala:251)
	at org.http4s.blaze.pipeline.Head.inboundCommand$(Stages.scala:249)
	at org.http4s.client.blaze.ReadBufferStage.inboundCommand(ReadBufferStage.scala:14)
	at org.http4s.blaze.pipeline.Head.sendInboundCommand(Stages.scala:238)
	at org.http4s.blaze.pipeline.Head.sendInboundCommand$(Stages.scala:235)
	at org.http4s.blaze.channel.nio2.ByteBufferHead.sendInboundCommand(ByteBufferHead.scala:17)
	at org.http4s.blaze.channel.nio2.ByteBufferHead$$anon$3.completed(ByteBufferHead.scala:102)
	at org.http4s.blaze.channel.nio2.ByteBufferHead$$anon$3.completed(ByteBufferHead.scala:87)
	at sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:126)
	at sun.nio.ch.Invoker$2.run(Invoker.java:218)
	at sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:748)

amrhassan avatar Jul 18 '17 11:07 amrhassan

I'm having the same issue, http4s version: 0.17.6

Any update?

sergiotudela avatar Feb 14 '18 10:02 sergiotudela

I've not reproduced this. Is there a reproducible case, like a mock service, we can use that makes this happen?

rossabaker avatar Feb 14 '18 13:02 rossabaker

@bryce-anderson, didn't some of your recent blaze work target this? I'm having trouble finding the reference.

There are no reports of this on a supported version. I'm going to close for now, but if anybody sees this on http4s-0.18, please reopen.

rossabaker avatar Mar 26 '18 15:03 rossabaker

I see this error repeatedly on 0.18.3 and 0.18.5

gondorAppServer 2018-03-30 21:46:29 ERROR [Thread-105] [] [ByteBufferHead.scala:132] - NIO2 channel closed with an unexpected error
gondorAppServer java.lang.Exception: Cannot send inbound command on disconnected stage
gondorAppServer         at org.http4s.blaze.pipeline.Head.sendInboundCommand(Stages.scala:241)
gondorAppServer         at org.http4s.blaze.pipeline.Head.sendInboundCommand$(Stages.scala:235)
gondorAppServer         at org.http4s.client.blaze.ClientTimeoutStage.sendInboundCommand(ClientTimeoutStage.scala:14)
gondorAppServer         at org.http4s.blaze.pipeline.Head.inboundCommand(Stages.scala:251)
gondorAppServer         at org.http4s.blaze.pipeline.Head.inboundCommand$(Stages.scala:249)
gondorAppServer         at org.http4s.client.blaze.ClientTimeoutStage.inboundCommand(ClientTimeoutStage.scala:14)
gondorAppServer         at org.http4s.blaze.pipeline.Head.sendInboundCommand(Stages.scala:238)
gondorAppServer         at org.http4s.blaze.pipeline.Head.sendInboundCommand$(Stages.scala:235)
gondorAppServer         at org.http4s.client.blaze.ReadBufferStage.sendInboundCommand(ReadBufferStage.scala:13)
gondorAppServer         at org.http4s.blaze.pipeline.Head.inboundCommand(Stages.scala:251)
gondorAppServer         at org.http4s.blaze.pipeline.Head.inboundCommand$(Stages.scala:249)
gondorAppServer         at org.http4s.client.blaze.ReadBufferStage.inboundCommand(ReadBufferStage.scala:13)
gondorAppServer         at org.http4s.blaze.pipeline.Head.sendInboundCommand(Stages.scala:238)
gondorAppServer         at org.http4s.blaze.pipeline.Head.sendInboundCommand$(Stages.scala:235)
gondorAppServer         at org.http4s.blaze.channel.nio2.ByteBufferHead.sendInboundCommand(ByteBufferHead.scala:17)
gondorAppServer         at org.http4s.blaze.channel.nio2.ByteBufferHead$$anon$3.failed(ByteBufferHead.scala:94)
gondorAppServer         at org.http4s.blaze.channel.nio2.ByteBufferHead$$anon$3.failed(ByteBufferHead.scala:91)
gondorAppServer         at sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:128)
gondorAppServer         at sun.nio.ch.Invoker$2.run(Invoker.java:218)
gondorAppServer         at sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112)
gondorAppServer         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
gondorAppServer         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
gondorAppServer         at java.lang.Thread.run(Thread.java:748)

ngbinh avatar Mar 30 '18 15:03 ngbinh

doesn't look like any bad outcomes happened though (at least not that I can tell)

ngbinh avatar Mar 30 '18 15:03 ngbinh

the requesting part usually looks like this:

import monix.eval.Task
...
object httpClient {
    private val clientTask: Task[Client[Task]] = Http1Client[Task](blazeClientConfig)

     def fetch[T](req: => Request[Task])(callback: Response[Task] => Task[T]): Task[T] = {
        clientTask.bracket(_.fetch(req)(callback))(_.shutdown)
     }
}

Not sure if it is correct pattern.

ngbinh avatar Mar 30 '18 15:03 ngbinh

@ngbinh, do you mind opening an issue with those stack traces in blaze? I don't think they are anything but noise, but they should be cleaned up. With InboundCommands being hints at this point, I don't think we shouldn't be raising these exceptions.

bryce-anderson avatar Mar 30 '18 15:03 bryce-anderson

Can this be fixed in 0.12 series, or are we waiting for master?

rossabaker avatar Mar 30 '18 17:03 rossabaker

I've seen this come up occasionally , but am now actually also seeing this with a mock API server being used at work (currently using 0.18.4). I will need to change some stuff around but should be able to provide mock service for replication purposes if needed. This is used for ETL and there aren't any ill-effects in any of the data-integrity checks being made. It's also not occurring on every test run.

    11:46:54.069 [blaze-nio1-acceptor] INFO  o.h.blaze.channel.ServerChannelGroup - Connection to /127.0.0.1:62624 accepted at Fri Mar 30 11:46:54 PDT 2018.
    11:46:54.069 [ForkJoinPool-1-worker-13] DEBUG org.http4s.blaze.pipeline.Stage - ByteBufferHead starting up at Fri Mar 30 11:46:54 PDT 2018
    11:46:54.069 [ForkJoinPool-1-worker-13] DEBUG org.http4s.blaze.pipeline.Stage - Stage ByteBufferHead sending inbound command: Connected
    11:46:54.069 [ForkJoinPool-1-worker-13] DEBUG org.http4s.blaze.pipeline.Stage - Stage started up. Beginning read buffering
    11:46:54.069 [ForkJoinPool-1-worker-13] DEBUG org.http4s.blaze.pipeline.Stage - Stage ReadBufferStage sending inbound command: Connected
    11:46:54.069 [blaze-nio-fixed-selector-pool-6] DEBUG org.http4s.blaze.pipeline.Stage - SocketChannelHead starting up at Fri Mar 30 11:46:54 PDT 2018
    11:46:54.070 [ForkJoinPool-1-worker-13] DEBUG org.http4s.blaze.pipeline.Stage - Http1Connection starting up at Fri Mar 30 11:46:54 PDT 2018
    11:46:54.070 [blaze-nio-fixed-selector-pool-6] DEBUG org.http4s.blaze.pipeline.Stage - Stage SocketChannelHead sending inbound command: Connected
    11:46:54.070 [ForkJoinPool-1-worker-13] DEBUG org.http4s.blaze.pipeline.Stage - ClientTimeoutStage starting up at Fri Mar 30 11:46:54 PDT 2018
    11:46:54.070 [blaze-nio-fixed-selector-pool-6] DEBUG org.http4s.blaze.pipeline.Stage - QuietTimeoutStage starting up at Fri Mar 30 11:46:54 PDT 2018
    11:46:54.070 [ForkJoinPool-1-worker-13] DEBUG org.http4s.blaze.pipeline.Stage - Connection was idle. Running.
    11:46:54.070 [blaze-nio-fixed-selector-pool-6] DEBUG org.http4s.blaze.pipeline.Stage - Stage QuietTimeoutStage sending inbound command: Connected
    11:46:54.070 [ForkJoinPool-1-worker-13] DEBUG org.http4s.blaze.pipeline.Stage - Beginning request: GET http://localhost:62618/*******
    11:46:54.070 [blaze-nio-fixed-selector-pool-6] DEBUG org.http4s.blaze.pipeline.Stage - Starting HTTP pipeline
    11:46:54.070 [blaze-nio-fixed-selector-pool-6] DEBUG o.h.blaze.channel.nio1.SelectorLoop - Started channel.
    11:46:54.071 [ForkJoinPool-1-worker-13] DEBUG org.http4s.blaze.pipeline.Stage - Stage Http1Connection sending outbound command: org.http4s.client.blaze.ClientTimeoutStage$RequestSendComplete$@700381f3
    11:46:54.081 [ForkJoinPool-1-worker-13] DEBUG org.http4s.blaze.pipeline.Stage - Websocket key: None
    Request headers: Headers(Host: localhost:62618, Authorization: Bearer, Accept: application/json, User-Agent: http4s-blaze/0.18.4, Content-Length: 0)
    11:46:54.083 [ForkJoinPool-1-worker-9] DEBUG org.http4s.blaze.pipeline.Stage - Stage Http1Connection sending outbound command: org.http4s.client.blaze.ClientTimeoutStage$ResponseHeaderComplete$@2e1a29bf
    11:46:54.094 [ForkJoinPool-1-worker-1] DEBUG org.http4s.blaze.pipeline.Stage - Resetting org.http4s.client.blaze.Http1Connection after completing request.
    11:46:54.094 [ForkJoinPool-1-worker-1] DEBUG org.http4s.blaze.pipeline.Stage - Stage Http1Connection sending outbound command: Disconnect
    11:46:54.095 [ForkJoinPool-1-worker-1] DEBUG org.http4s.blaze.pipeline.Stage - ClientTimeoutStage shutting down at Fri Mar 30 11:46:54 PDT 2018
    11:46:54.095 [ForkJoinPool-1-worker-1] DEBUG org.http4s.blaze.pipeline.Stage - Stage ClientTimeoutStage sending outbound command: Disconnect
    11:46:54.095 [ForkJoinPool-1-worker-1] DEBUG org.http4s.blaze.pipeline.Stage - ReadBufferStage shutting down at Fri Mar 30 11:46:54 PDT 2018
    11:46:54.095 [ForkJoinPool-1-worker-1] DEBUG org.http4s.blaze.pipeline.Stage - Stage ReadBufferStage sending outbound command: Disconnect
    11:46:54.095 [ForkJoinPool-1-worker-1] DEBUG org.http4s.blaze.pipeline.Stage - closeWithError(EOF)
    11:46:54.095 [ForkJoinPool-1-worker-1] DEBUG org.http4s.blaze.pipeline.Stage - Http1Connection shutting down at Fri Mar 30 11:46:54 PDT 2018
    11:46:54.095 [blaze-nio-fixed-selector-pool-6] DEBUG org.http4s.blaze.pipeline.Stage - Stage SocketChannelHead sending inbound command: Disconnected
    11:46:54.095 [Thread-13] DEBUG org.http4s.blaze.pipeline.Stage - Stage ByteBufferHead sending inbound command: Disconnected
    11:46:54.095 [blaze-nio-fixed-selector-pool-6] DEBUG org.http4s.blaze.pipeline.Stage - QuietTimeoutStage shutting down at Fri Mar 30 11:46:54 PDT 2018
    11:46:54.095 [Thread-13] DEBUG org.http4s.blaze.pipeline.Stage - ReadBufferStage shutting down at Fri Mar 30 11:46:54 PDT 2018
    11:46:54.095 [blaze-nio-fixed-selector-pool-6] DEBUG org.http4s.blaze.pipeline.Stage - Stage QuietTimeoutStage sending inbound command: Disconnected
    11:46:54.095 [Thread-13] DEBUG org.http4s.blaze.pipeline.Stage - Stage ReadBufferStage sending inbound command: Disconnected
    11:46:54.095 [ForkJoinPool-1-worker-1] DEBUG org.http4s.blaze.pipeline.Stage - ClientTimeoutStage shutting down at Fri Mar 30 11:46:54 PDT 2018
    11:46:54.096 [blaze-nio-fixed-selector-pool-6] DEBUG org.http4s.blaze.pipeline.Stage - Shutting down HttpPipeline
    11:46:54.096 [Thread-13] DEBUG org.http4s.blaze.pipeline.Stage - ClientTimeoutStage shutting down at Fri Mar 30 11:46:54 PDT 2018
    11:46:54.096 [ForkJoinPool-1-worker-1] DEBUG org.http4s.client.PoolManager - Recycling connection: curAllocated=1 idleQueues.size=0 waitQueue.size=0 maxWaitQueueLimit=256 closed=false
    11:46:54.096 [blaze-nio-fixed-selector-pool-6] DEBUG org.http4s.blaze.pipeline.Stage - anon$1 shutting down at Fri Mar 30 11:46:54 PDT 2018
    11:46:54.096 [Thread-13] DEBUG org.http4s.blaze.pipeline.Stage - Stage ClientTimeoutStage sending inbound command: Disconnected
    11:46:54.096 [ForkJoinPool-1-worker-1] DEBUG org.http4s.client.PoolManager - expired requests: 0
    11:46:54.096 [blaze-nio-fixed-selector-pool-6] DEBUG org.http4s.blaze.pipeline.Stage - Shutting down HttpPipeline
    11:46:54.096 [ForkJoinPool-1-worker-1] DEBUG org.http4s.client.PoolManager - Dropped expired requests: curAllocated=0 idleQueues.size=0 waitQueue.size=0 maxWaitQueueLimit=256 closed=false
    11:46:54.096 [Thread-13] ERROR org.http4s.blaze.pipeline.Stage - 
    java.lang.Exception: Cannot send inbound command on disconnected stage
        at org.http4s.blaze.pipeline.Head$class.sendInboundCommand(Stages.scala:241) [blaze-core_2.11-0.12.12.jar:0.12.12]
        at org.http4s.client.blaze.ClientTimeoutStage.sendInboundCommand(ClientTimeoutStage.scala:14) [http4s-blaze-client_2.11-0.18.4.jar:0.18.4]
        at org.http4s.blaze.pipeline.Head$class.inboundCommand(Stages.scala:251) [blaze-core_2.11-0.12.12.jar:0.12.12]
        at org.http4s.client.blaze.ClientTimeoutStage.inboundCommand(ClientTimeoutStage.scala:14) [http4s-blaze-client_2.11-0.18.4.jar:0.18.4]
        at org.http4s.blaze.pipeline.Head$class.sendInboundCommand(Stages.scala:238) [blaze-core_2.11-0.12.12.jar:0.12.12]
        at org.http4s.client.blaze.ReadBufferStage.sendInboundCommand(ReadBufferStage.scala:13) [http4s-blaze-client_2.11-0.18.4.jar:0.18.4]
        at org.http4s.blaze.pipeline.Head$class.inboundCommand(Stages.scala:251) [blaze-core_2.11-0.12.12.jar:0.12.12]
        at org.http4s.client.blaze.ReadBufferStage.inboundCommand(ReadBufferStage.scala:13) [http4s-blaze-client_2.11-0.18.4.jar:0.18.4]
        at org.http4s.blaze.pipeline.Head$class.sendInboundCommand(Stages.scala:238) [blaze-core_2.11-0.12.12.jar:0.12.12]
        at org.http4s.blaze.channel.nio2.ByteBufferHead.sendInboundCommand(ByteBufferHead.scala:17) [blaze-core_2.11-0.12.12.jar:0.12.12]
        at org.http4s.blaze.channel.nio2.ByteBufferHead$$anon$3.failed(ByteBufferHead.scala:94) [blaze-core_2.11-0.12.12.jar:0.12.12]
        at org.http4s.blaze.channel.nio2.ByteBufferHead$$anon$3.failed(ByteBufferHead.scala:91) [blaze-core_2.11-0.12.12.jar:0.12.12]
        at sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:128) [na:1.8.0_74]
        at sun.nio.ch.Invoker$2.run(Invoker.java:218) [na:1.8.0_74]
        at sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112) [na:1.8.0_74]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_74]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_74]
        at java.lang.Thread.run(Thread.java:745) [na:1.8.0_74]
    11:46:54.096 [blaze-nio-fixed-selector-pool-6] DEBUG org.http4s.blaze.pipeline.Stage - anon$1 shutting down at Fri Mar 30 11:46:54 PDT 2018
    11:46:54.096 [ForkJoinPool-1-worker-1] DEBUG org.http4s.client.PoolManager - Connection could not be recycled, no pending requests. Shrinking pool: curAllocated=0 idleQueues.size=0 waitQueue.size=0 maxWaitQueueLimit=256 closed=false
    11:46:54.097 [Thread-13] ERROR org.http4s.blaze.pipeline.Stage - ReadBufferingStage received unhandled error command
    java.lang.Exception: Cannot send inbound command on disconnected stage
        at org.http4s.blaze.pipeline.Head$class.sendInboundCommand(Stages.scala:241) [blaze-core_2.11-0.12.12.jar:0.12.12]
        at org.http4s.client.blaze.ClientTimeoutStage.sendInboundCommand(ClientTimeoutStage.scala:14) ~[http4s-blaze-client_2.11-0.18.4.jar:0.18.4]
        at org.http4s.blaze.pipeline.Head$class.inboundCommand(Stages.scala:251) [blaze-core_2.11-0.12.12.jar:0.12.12]
        at org.http4s.client.blaze.ClientTimeoutStage.inboundCommand(ClientTimeoutStage.scala:14) ~[http4s-blaze-client_2.11-0.18.4.jar:0.18.4]
        at org.http4s.blaze.pipeline.Head$class.sendInboundCommand(Stages.scala:238) [blaze-core_2.11-0.12.12.jar:0.12.12]
        at org.http4s.client.blaze.ReadBufferStage.sendInboundCommand(ReadBufferStage.scala:13) [http4s-blaze-client_2.11-0.18.4.jar:0.18.4]
        at org.http4s.blaze.pipeline.Head$class.inboundCommand(Stages.scala:251) [blaze-core_2.11-0.12.12.jar:0.12.12]
        at org.http4s.client.blaze.ReadBufferStage.inboundCommand(ReadBufferStage.scala:13) [http4s-blaze-client_2.11-0.18.4.jar:0.18.4]
        at org.http4s.blaze.pipeline.Head$class.sendInboundCommand(Stages.scala:238) [blaze-core_2.11-0.12.12.jar:0.12.12]
        at org.http4s.blaze.channel.nio2.ByteBufferHead.sendInboundCommand(ByteBufferHead.scala:17) [blaze-core_2.11-0.12.12.jar:0.12.12]
        at org.http4s.blaze.channel.nio2.ByteBufferHead$$anon$3.failed(ByteBufferHead.scala:94) [blaze-core_2.11-0.12.12.jar:0.12.12]
        at org.http4s.blaze.channel.nio2.ByteBufferHead$$anon$3.failed(ByteBufferHead.scala:91) [blaze-core_2.11-0.12.12.jar:0.12.12]
        at sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:128) [na:1.8.0_74]
        at sun.nio.ch.Invoker$2.run(Invoker.java:218) [na:1.8.0_74]
        at sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112) [na:1.8.0_74]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_74]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_74]
        at java.lang.Thread.run(Thread.java:745) [na:1.8.0_74]
    11:46:54.098 [Thread-13] DEBUG org.http4s.blaze.pipeline.Stage - Stage ReadBufferStage sending outbound command: org.http4s.blaze.pipeline.Command$Error: java.lang.Exception: Cannot send inbound command on disconnected stage
    11:46:54.098 [Thread-13] ERROR org.http4s.blaze.pipeline.Stage - NIO2 channel closed with an unexpected error
    java.lang.Exception: Cannot send inbound command on disconnected stage
        at org.http4s.blaze.pipeline.Head$class.sendInboundCommand(Stages.scala:241) [blaze-core_2.11-0.12.12.jar:0.12.12]
        at org.http4s.client.blaze.ClientTimeoutStage.sendInboundCommand(ClientTimeoutStage.scala:14) ~[http4s-blaze-client_2.11-0.18.4.jar:0.18.4]
        at org.http4s.blaze.pipeline.Head$class.inboundCommand(Stages.scala:251) [blaze-core_2.11-0.12.12.jar:0.12.12]
        at org.http4s.client.blaze.ClientTimeoutStage.inboundCommand(ClientTimeoutStage.scala:14) ~[http4s-blaze-client_2.11-0.18.4.jar:0.18.4]
        at org.http4s.blaze.pipeline.Head$class.sendInboundCommand(Stages.scala:238) [blaze-core_2.11-0.12.12.jar:0.12.12]
        at org.http4s.client.blaze.ReadBufferStage.sendInboundCommand(ReadBufferStage.scala:13) [http4s-blaze-client_2.11-0.18.4.jar:0.18.4]
        at org.http4s.blaze.pipeline.Head$class.inboundCommand(Stages.scala:251) [blaze-core_2.11-0.12.12.jar:0.12.12]
        at org.http4s.client.blaze.ReadBufferStage.inboundCommand(ReadBufferStage.scala:13) [http4s-blaze-client_2.11-0.18.4.jar:0.18.4]
        at org.http4s.blaze.pipeline.Head$class.sendInboundCommand(Stages.scala:238) [blaze-core_2.11-0.12.12.jar:0.12.12]
        at org.http4s.blaze.channel.nio2.ByteBufferHead.sendInboundCommand(ByteBufferHead.scala:17) [blaze-core_2.11-0.12.12.jar:0.12.12]
        at org.http4s.blaze.channel.nio2.ByteBufferHead$$anon$3.failed(ByteBufferHead.scala:94) [blaze-core_2.11-0.12.12.jar:0.12.12]
        at org.http4s.blaze.channel.nio2.ByteBufferHead$$anon$3.failed(ByteBufferHead.scala:91) [blaze-core_2.11-0.12.12.jar:0.12.12]
        at sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:128) [na:1.8.0_74]
        at sun.nio.ch.Invoker$2.run(Invoker.java:218) [na:1.8.0_74]
        at sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112) [na:1.8.0_74]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_74]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_74]
        at java.lang.Thread.run(Thread.java:745) [na:1.8.0_74]
    11:46:54.098 [Thread-13] DEBUG org.http4s.blaze.pipeline.Stage - closeWithError(EOF)

marcovivero avatar Mar 30 '18 19:03 marcovivero

When we have a new blaze, we'll cut a patch release, and those of you seeing this on 0.18 can try it, and we can close it for better reasons than "nobody has complained for a while." Thanks for the reports.

rossabaker avatar Mar 30 '18 19:03 rossabaker

I'd have to look into it more to see if it's something that should be changed on 0.12.x. My gut feeling is that this would be a pretty serious API contract change.

bryce-anderson avatar Mar 31 '18 00:03 bryce-anderson

Same here on 0.18.9:

2018-04-26 01:49:08,480 [ERROR] org.http4s.blaze.pipeline.Stage -
java.lang.Exception: Cannot send inbound command on disconnected stage
	at org.http4s.blaze.pipeline.Head.sendInboundCommand(Stages.scala:241)
	at org.http4s.blaze.pipeline.Head.sendInboundCommand$(Stages.scala:235)
	at org.http4s.client.blaze.ClientTimeoutStage.sendInboundCommand(ClientTimeoutStage.scala:14)
	at org.http4s.blaze.pipeline.Head.inboundCommand(Stages.scala:251)
	at org.http4s.blaze.pipeline.Head.inboundCommand$(Stages.scala:249)
	at org.http4s.client.blaze.ClientTimeoutStage.inboundCommand(ClientTimeoutStage.scala:14)
	at org.http4s.blaze.pipeline.Head.sendInboundCommand(Stages.scala:238)
	at org.http4s.blaze.pipeline.Head.sendInboundCommand$(Stages.scala:235)
	at org.http4s.client.blaze.ReadBufferStage.sendInboundCommand(ReadBufferStage.scala:13)
	at org.http4s.blaze.pipeline.Head.inboundCommand(Stages.scala:251)
	at org.http4s.blaze.pipeline.Head.inboundCommand$(Stages.scala:249)
	at org.http4s.client.blaze.ReadBufferStage.inboundCommand(ReadBufferStage.scala:13)
	at org.http4s.blaze.pipeline.Head.sendInboundCommand(Stages.scala:238)
	at org.http4s.blaze.pipeline.Head.sendInboundCommand$(Stages.scala:235)
	at org.http4s.blaze.channel.nio2.ByteBufferHead.dt_2_sendInboundCommand_50(ByteBufferHead.scala)
	at org.http4s.blaze.channel.nio2.ByteBufferHead.sendInboundCommand(ByteBufferHead.scala:17)
	at org.http4s.blaze.channel.nio2.ByteBufferHead$$anon$3.failed(ByteBufferHead.scala:94)
	at org.http4s.blaze.channel.nio2.ByteBufferHead$$anon$3.failed(ByteBufferHead.scala:91)
	at sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:128)
	at sun.nio.ch.Invoker$2.run(Invoker.java:218)
	at sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
2018-04-26 01:49:08,481 [ERROR] org.http4s.blaze.pipeline.Stage - ReadBufferingStage received unhandled error command
java.lang.Exception: Cannot send inbound command on disconnected stage
	at org.http4s.blaze.pipeline.Head.sendInboundCommand(Stages.scala:241)
	at org.http4s.blaze.pipeline.Head.sendInboundCommand$(Stages.scala:235)
	at org.http4s.client.blaze.ClientTimeoutStage.sendInboundCommand(ClientTimeoutStage.scala:14)
	at org.http4s.blaze.pipeline.Head.inboundCommand(Stages.scala:251)
	at org.http4s.blaze.pipeline.Head.inboundCommand$(Stages.scala:249)
	at org.http4s.client.blaze.ClientTimeoutStage.inboundCommand(ClientTimeoutStage.scala:14)
	at org.http4s.blaze.pipeline.Head.sendInboundCommand(Stages.scala:238)
	at org.http4s.blaze.pipeline.Head.sendInboundCommand$(Stages.scala:235)
	at org.http4s.client.blaze.ReadBufferStage.sendInboundCommand(ReadBufferStage.scala:13)
	at org.http4s.blaze.pipeline.Head.inboundCommand(Stages.scala:251)
	at org.http4s.blaze.pipeline.Head.inboundCommand$(Stages.scala:249)
	at org.http4s.client.blaze.ReadBufferStage.inboundCommand(ReadBufferStage.scala:13)
	at org.http4s.blaze.pipeline.Head.sendInboundCommand(Stages.scala:238)
	at org.http4s.blaze.pipeline.Head.sendInboundCommand$(Stages.scala:235)
	at org.http4s.blaze.channel.nio2.ByteBufferHead.dt_2_sendInboundCommand_50(ByteBufferHead.scala)
	at org.http4s.blaze.channel.nio2.ByteBufferHead.sendInboundCommand(ByteBufferHead.scala:17)
	at org.http4s.blaze.channel.nio2.ByteBufferHead$$anon$3.failed(ByteBufferHead.scala:94)
	at org.http4s.blaze.channel.nio2.ByteBufferHead$$anon$3.failed(ByteBufferHead.scala:91)
	at sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:128)
	at sun.nio.ch.Invoker$2.run(Invoker.java:218)
	at sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
2018-04-26 01:49:08,481 [ERROR] org.http4s.blaze.pipeline.Stage - NIO2 channel closed with an unexpected error
java.lang.Exception: Cannot send inbound command on disconnected stage
	at org.http4s.blaze.pipeline.Head.sendInboundCommand(Stages.scala:241)
	at org.http4s.blaze.pipeline.Head.sendInboundCommand$(Stages.scala:235)
	at org.http4s.client.blaze.ClientTimeoutStage.sendInboundCommand(ClientTimeoutStage.scala:14)
	at org.http4s.blaze.pipeline.Head.inboundCommand(Stages.scala:251)
	at org.http4s.blaze.pipeline.Head.inboundCommand$(Stages.scala:249)
	at org.http4s.client.blaze.ClientTimeoutStage.inboundCommand(ClientTimeoutStage.scala:14)
	at org.http4s.blaze.pipeline.Head.sendInboundCommand(Stages.scala:238)
	at org.http4s.blaze.pipeline.Head.sendInboundCommand$(Stages.scala:235)
	at org.http4s.client.blaze.ReadBufferStage.sendInboundCommand(ReadBufferStage.scala:13)
	at org.http4s.blaze.pipeline.Head.inboundCommand(Stages.scala:251)
	at org.http4s.blaze.pipeline.Head.inboundCommand$(Stages.scala:249)
	at org.http4s.client.blaze.ReadBufferStage.inboundCommand(ReadBufferStage.scala:13)
	at org.http4s.blaze.pipeline.Head.sendInboundCommand(Stages.scala:238)
	at org.http4s.blaze.pipeline.Head.sendInboundCommand$(Stages.scala:235)
	at org.http4s.blaze.channel.nio2.ByteBufferHead.dt_2_sendInboundCommand_50(ByteBufferHead.scala)
	at org.http4s.blaze.channel.nio2.ByteBufferHead.sendInboundCommand(ByteBufferHead.scala:17)
	at org.http4s.blaze.channel.nio2.ByteBufferHead$$anon$3.failed(ByteBufferHead.scala:94)
	at org.http4s.blaze.channel.nio2.ByteBufferHead$$anon$3.failed(ByteBufferHead.scala:91)
	at sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:128)
	at sun.nio.ch.Invoker$2.run(Invoker.java:218)
	at sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)

lucaviolanti avatar Apr 26 '18 09:04 lucaviolanti

@rossabaker I have a gist with instructions on how to re-create the error. I do not believe that the request is a representative sample of real-world use cases, but it is generating the same error. That is reported above.

ehoner avatar Jul 20 '18 14:07 ehoner

Any updates on this? This is almost a blocker to have http4s in production :disappointed:

bijancn avatar Jul 27 '18 11:07 bijancn

v0.19.0-M1 with the new blaze is already out. Hopefully someone who can reliably reproduce this issue will run their code against the new version, and report the results here.

nigredo-tori avatar Jul 27 '18 11:07 nigredo-tori

Also seeing this - turning the logging for that class off until 0.19 is out, I'll re-test then

adamw avatar Sep 19 '18 13:09 adamw

Is this still happening on 0.19.0-M2?

rossabaker avatar Sep 19 '18 16:09 rossabaker

@rossabaker The api seems to have significant changes. Can you confirm for me that translating between the two looks correct?

Assuming its correct, the error appears resolved for me.

0.18.15

Http1Client.stream[IO]().flatMap { client =>
  BlazeBuilder[IO]
    .bindHttp(8080, "127.0.0.1")
    .mountService(client.toHttpService, "/")
    .serve
}.compile.drain.unsafeRunSync

0.19.0-M2

object Test extends IOApp {

  import cats.syntax.functor._

  def run(args: List[String]): IO[ExitCode] =
    BlazeClientBuilder[IO](global).stream.flatMap { client =>
      BlazeServerBuilder[IO].bindHttp(8080, "127.0.0.1")
        .withHttpApp(client.toHttpApp)
        .serve
    }.compile.drain.as(ExitCode.Success)
}

Test.run(Nil).unsafeRunSync

ehoner avatar Sep 20 '18 18:09 ehoner

Yes, that looks correct. Thanks for testing! I think this was fixed in http4s/http4s#2061. We had a blaze issue related to that, and we failed to connect the dots to this one.

If anybody is seeing this on http4s-0.19.0-M2 or later, please reopen.

rossabaker avatar Sep 20 '18 21:09 rossabaker

Hello, will the fix be backported to 0.18, please? I'd love to use newer lins but there is some dependency hell (Monix incompatible with cats-effect 1.0 yet, but http4s > 0.18 using it) so I am not able to upgrade right now.

jendakol avatar Dec 19 '18 10:12 jendakol

Seeing these on a server running http4s 0.20.0-M4.

java.lang.Exception: Cannot send inbound command on disconnected stage
                at org.http4s.blaze.pipeline.Head.sendInboundCommand(Stages.scala:264)
                at org.http4s.blaze.pipeline.Head.sendInboundCommand$(Stages.scala:252)
                at org.http4s.blazecore.IdleTimeoutStage.sendInboundCommand(IdleTimeoutStage.scala:12)
                at org.http4s.blaze.pipeline.Head.inboundCommand(Stages.scala:273)
                at org.http4s.blaze.pipeline.Head.inboundCommand$(Stages.scala:271)
                at org.http4s.blazecore.IdleTimeoutStage.inboundCommand(IdleTimeoutStage.scala:12)
                at org.http4s.blaze.pipeline.Head.sendInboundCommand(Stages.scala:256)
                at org.http4s.blaze.pipeline.Head.sendInboundCommand$(Stages.scala:252)
                at org.http4s.blaze.channel.ChannelHead.sendInboundCommand(ChannelHead.scala:9)
                at org.http4s.blaze.channel.nio1.NIO1HeadStage.org$http4s$blaze$channel$nio1$NIO1HeadStage$$doClose$1(NIO1HeadStage.scala:311)
                at org.http4s.blaze.channel.nio1.NIO1HeadStage$$anon$3.run(NIO1HeadStage.scala:326)
                at org.http4s.blaze.util.TaskQueue.go$1(TaskQueue.scala:82)
                at org.http4s.blaze.util.TaskQueue.executeTasks(TaskQueue.scala:99)
                at org.http4s.blaze.channel.nio1.SelectorLoop.org$http4s$blaze$channel$nio1$SelectorLoop$$runLoop(SelectorLoop.scala:165)
                at org.http4s.blaze.channel.nio1.SelectorLoop$$anon$1.run(SelectorLoop.scala:67)
                at java.lang.Thread.run(Thread.java:748)

BobWall23 avatar Jan 03 '19 18:01 BobWall23

We just came across this issue in our company. The server that experienced this issue seemed just fine after new deployment over a while (since first half of december 2018), but about 1-2 hours in strange behavior started to occur, with some of the customers affected. Initially some, then more and more, until eventually everyone was. The server instance seemed to just drop the process for no reason and continue with another one. We eventually tracked the issue to an inhouse developed library (included in pom) which had this dependency in it's pom with version 0.18.0-M5. About a thousand customers were affected.

tanel3203 avatar Feb 15 '19 12:02 tanel3203

Hate to be the bearer of bad news but this is still happening as of 0.20.0-M6

10:36:14.536 blaze-selector-0-3 [ERROR] o.h.blaze.channel.nio1.NIO1HeadStage - Exception caught when attempting inbound command
java.lang.Exception: Cannot send inbound command on disconnected stage
at org.http4s.blaze.pipeline.Head$class.sendInboundCommand(Stages.scala:264)
at org.http4s.blazecore.IdleTimeoutStage.sendInboundCommand(IdleTimeoutStage.scala:12)
at org.http4s.blaze.pipeline.Head$class.inboundCommand(Stages.scala:273)
at org.http4s.blazecore.IdleTimeoutStage.inboundCommand(IdleTimeoutStage.scala:12)
at org.http4s.blaze.pipeline.Head$class.sendInboundCommand(Stages.scala:256)
at org.http4s.blaze.channel.ChannelHead.sendInboundCommand(ChannelHead.scala:9)
at org.http4s.blaze.channel.nio1.NIO1HeadStage.org$http4s$blaze$channel$nio1$NIO1HeadStage$$doClose$1(NIO1HeadStage.scala:311)
at org.http4s.blaze.channel.nio1.NIO1HeadStage$$anon$3.run(NIO1HeadStage.scala:326)
at org.http4s.blaze.channel.nio1.SelectorLoop.executeTask(SelectorLoop.scala:93)
at org.http4s.blaze.channel.nio1.NIO1HeadStage.doClosePipeline(NIO1HeadStage.scala:314)
at org.http4s.blaze.pipeline.HeadStage$class.closePipeline(Stages.scala:323)
at org.http4s.blaze.channel.ChannelHead.closePipeline(ChannelHead.scala:9)
at org.http4s.blaze.pipeline.Tail$class.closePipeline(Stages.scala:81)
at org.http4s.blazecore.IdleTimeoutStage.closePipeline(IdleTimeoutStage.scala:12)
at org.http4s.blaze.pipeline.Tail$class.closePipeline(Stages.scala:81)
at org.http4s.server.blaze.Http1ServerStage.closePipeline(Http1ServerStage.scala:68)
at org.http4s.server.blaze.Http1ServerStage.org$http4s$server$blaze$Http1ServerStage$$closeConnection(Http1ServerStage.scala:292)
at org.http4s.server.blaze.Http1ServerStage$$anonfun$3.apply(Http1ServerStage.scala:129)
at org.http4s.server.blaze.Http1ServerStage$$anonfun$3.apply(Http1ServerStage.scala:127)
at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:36)
at org.http4s.blaze.util.Execution$ThreadLocalTrampoline.run(Execution.scala:108)
at org.http4s.blaze.util.Execution$ThreadLocalTrampoline.execute(Execution.scala:94)
at org.http4s.blaze.util.Execution$$anon$2.execute(Execution.scala:53)
at scala.concurrent.impl.CallbackRunnable.executeWithValue(Promise.scala:44)
at scala.concurrent.impl.Promise$DefaultPromise.tryComplete(Promise.scala:252)
at scala.concurrent.Promise$class.tryFailure(Promise.scala:112)
at scala.concurrent.impl.Promise$DefaultPromise.tryFailure(Promise.scala:157)
at org.http4s.blaze.channel.nio1.NIO1HeadStage.org$http4s$blaze$channel$nio1$NIO1HeadStage$$doClose$1(NIO1HeadStage.scala:296)
at org.http4s.blaze.channel.nio1.NIO1HeadStage$$anon$3.run(NIO1HeadStage.scala:326)
at org.http4s.blaze.util.TaskQueue.go$1(TaskQueue.scala:82)
at org.http4s.blaze.util.TaskQueue.executeTasks(TaskQueue.scala:99)
at org.http4s.blaze.channel.nio1.SelectorLoop.org$http4s$blaze$channel$nio1$SelectorLoop$$runLoop(SelectorLoop.scala:165)
at org.http4s.blaze.channel.nio1.SelectorLoop$$anon$1.run(SelectorLoop.scala:67)
at java.lang.Thread.run(Thread.java:748)

I have not been able to create a minimized test case and have only seen it on applications running for a few hours. https dependencies (note I'm not using blaze client):

"org.http4s"                        %% "http4s-core"                 
"org.http4s"                        %% "http4s-blaze-server"         
"org.http4s"                        %% "http4s-async-http-client"    
"org.http4s"                        %% "http4s-circe"                
"org.http4s"                        %% "http4s-dsl"                  
"org.http4s"                        %% "http4s-twirl"

frosforever avatar Mar 12 '19 13:03 frosforever

Yet again on 0.21.0 server

2020-04-08 07:45:27.108 ERROR [    blaze-selector-2]        org.http4s.blaze.channel.nio1.NIO1HeadStage: Abnormal NIO1HeadStage termination
java.lang.Exception: Cannot send inbound command on disconnected stage
        at org.http4s.blaze.pipeline.Head.sendInboundCommand(Stages.scala:264)
        at org.http4s.blaze.pipeline.Head.sendInboundCommand$(Stages.scala:252)
        at org.http4s.blazecore.IdleTimeoutStage.sendInboundCommand(IdleTimeoutStage.scala:12)
        at org.http4s.blaze.pipeline.Head.inboundCommand(Stages.scala:273)
        at org.http4s.blaze.pipeline.Head.inboundCommand$(Stages.scala:271)
        at org.http4s.blazecore.IdleTimeoutStage.inboundCommand(IdleTimeoutStage.scala:12)
        at org.http4s.blaze.pipeline.Head.sendInboundCommand(Stages.scala:256)
        at org.http4s.blaze.pipeline.Head.sendInboundCommand$(Stages.scala:252)
        at org.http4s.blaze.channel.ChannelHead.sendInboundCommand(ChannelHead.scala:9)
        at org.http4s.blaze.channel.nio1.NIO1HeadStage.org$http4s$blaze$channel$nio1$NIO1HeadStage$$doClose$1(NIO1HeadStage.scala:311)
        at org.http4s.blaze.channel.nio1.NIO1HeadStage$$anon$3.run(NIO1HeadStage.scala:326)
        at org.http4s.blaze.util.TaskQueue.go$1(TaskQueue.scala:82)
        at org.http4s.blaze.util.TaskQueue.executeTasks(TaskQueue.scala:99)
        at org.http4s.blaze.channel.nio1.SelectorLoop.org$http4s$blaze$channel$nio1$SelectorLoop$$runLoop(SelectorLoop.scala:166)
        at org.http4s.blaze.channel.nio1.SelectorLoop$$anon$1.run(SelectorLoop.scala:67)
        at java.lang.Thread.run(Thread.java:748)

jsilva avatar Apr 08 '20 13:04 jsilva

Reopening because we've also seen this particular bug pop up again on the 0.21.x series, going to spend some time looking into it

RaasAhsan avatar Jan 25 '21 15:01 RaasAhsan