Spurious websocket close errors

[megri]

http4s-version: 0.20.10 java-version: 11.0.4 (adoptopenjdk) scala: 2.12.9 server backend: blaze (whatever version comes with http4s 0.20.10)

When running jmeter against a websocket endpoint I'm getting these kinds of errors every now and then:

2019-09-02T13:56:30,040Z [scala-execution-context-global-14] ERROR o.h.b.websocket.Http4sWSStage - Error closing Web Socket
fs2.CompositeFailure: Multiple exceptions were thrown (2), first org.http4s.blaze.pipeline.Command$EOF$: EOF
… further stack-trace of FS2/Monix stuff

It seems to have some impact on the connecting client as about 1 out of 20 jmeter results end up red.

[megri]

Full stack trace:

2019-09-02T13:56:34,335Z [scala-execution-context-global-16] ERROR o.h.b.websocket.Http4sWSStage - Error closing Web Socket
fs2.CompositeFailure: Multiple exceptions were thrown (2), first org.http4s.blaze.pipeline.Command$EOF$: EOF
        at fs2.CompositeFailure$.apply(CompositeFailure.scala:21)
        at fs2.internal.Algebra$.$anonfun$scope0$3(Algebra.scala:132)
        at fs2.internal.FreeC.$anonfun$transformWith$1(FreeC.scala:43)
        at fs2.internal.Algebra$.$anonfun$compileLoop$18(Algebra.scala:308)
        at monix.eval.internal.TaskRunLoop$.startFull(TaskRunLoop.scala:169)
        at monix.eval.internal.TaskRestartCallback.syncOnSuccess(TaskRestartCallback.scala:101)
        at monix.eval.internal.TaskRestartCallback$$anon$1.run(TaskRestartCallback.scala:114)
        at monix.execution.internal.Trampoline.monix$execution$internal$Trampoline$$immediateLoop(Trampoline.scala:66)
        at monix.execution.internal.Trampoline.startLoop(Trampoline.scala:32)
        at monix.execution.schedulers.TrampolineExecutionContext$JVMOptimalTrampoline.startLoop(TrampolineExecutionContext.scala:143)
        at monix.execution.internal.Trampoline.execute(Trampoline.scala:40)
        at monix.execution.schedulers.TrampolineExecutionContext.execute(TrampolineExecutionContext.scala:63)
        at monix.execution.schedulers.BatchingScheduler.execute(BatchingScheduler.scala:50)
        at monix.execution.schedulers.BatchingScheduler.execute$(BatchingScheduler.scala:47)
        at monix.execution.schedulers.AsyncScheduler.execute(AsyncScheduler.scala:31)
        at monix.execution.Callback$Base.onError(Callback.scala:231)
        at monix.execution.Callback.apply(Callback.scala:49)
        at monix.execution.Callback.apply(Callback.scala:40)
        at org.http4s.blazecore.websocket.Http4sWSStage.$anonfun$readFrameTrampoline$2(Http4sWSStage.scala:57)
        at org.http4s.blazecore.websocket.Http4sWSStage.$anonfun$readFrameTrampoline$2$adapted(Http4sWSStage.scala:55)
        at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:64)
        at org.http4s.blaze.util.Execution$ThreadLocalTrampoline.run(Execution.scala:109)
        at org.http4s.blaze.util.Execution$ThreadLocalTrampoline.execute(Execution.scala:95)
        at org.http4s.blaze.util.Execution$$anon$2.execute(Execution.scala:54)
        at scala.concurrent.impl.CallbackRunnable.executeWithValue(Promise.scala:72)
        at scala.concurrent.impl.Promise$DefaultPromise.$anonfun$tryComplete$1(Promise.scala:288)
        at scala.concurrent.impl.Promise$DefaultPromise.$anonfun$tryComplete$1$adapted(Promise.scala:288)
        at scala.concurrent.impl.Promise$DefaultPromise.tryComplete(Promise.scala:288)
        at scala.concurrent.Promise.complete(Promise.scala:53)
        at scala.concurrent.Promise.complete$(Promise.scala:52)
        at scala.concurrent.impl.Promise$DefaultPromise.complete(Promise.scala:187)
        at scala.concurrent.Promise.failure(Promise.scala:104)
        at scala.concurrent.Promise.failure$(Promise.scala:104)
        at scala.concurrent.impl.Promise$DefaultPromise.failure(Promise.scala:187)
        at org.http4s.blaze.channel.nio1.NIO1HeadStage.readReady(NIO1HeadStage.scala:152)
        at org.http4s.blaze.channel.nio1.NIO1HeadStage.opsReady(NIO1HeadStage.scala:130)
        at org.http4s.blaze.channel.nio1.SelectorLoop.processKeys(SelectorLoop.scala:200)
        at org.http4s.blaze.channel.nio1.SelectorLoop.org$http4s$blaze$channel$nio1$SelectorLoop$$runLoop(SelectorLoop.scala:171)
        at org.http4s.blaze.channel.nio1.SelectorLoop$$anon$1.run(SelectorLoop.scala:68)
        at java.base/java.lang.Thread.run(Thread.java:834)
Caused by: org.http4s.blaze.pipeline.Command$EOF$: EOF

[rossabaker]

Some thinking out loud on Gitter.

[saraiva132]

Is there any update on this issue? I am handling error on the evalMap and, apart from this noise, I also capture

java.lang.RuntimeException: TickWheelExecutor is shutdown
    at scala.sys.package$.error(package.scala:30)
    at org.http4s.blaze.util.TickWheelExecutor.schedule(TickWheelExecutor.scala:116)

when the client side shuts down the connection (it seems?).

[nbenns]

I also have this issue, and would love an answer. Is there any work being done on the braze connector?

[nbenns]

If you can point me into a direction I'll even take a look

[rossabaker]

I'm not actively working on it. A reliable reproduction would help a lot.

The TickWheelExecutor is a resource, which is used here. That shouldn't close the tick wheel until the server shuts down.

Adding logging to the tickWheelResource shutdown might be helpful. I would also very carefully scan for other errors that might be causing the server to shut down around the same time. Though it sounds like maybe requests are continuing to be served after this appears in the log?

[nbenns]

From what I can tell the connection to the client is severed.

I'll take a look into the TicketWheelExecutor and let you know what I'll find out. I'll also put together steps to reproduce the problem, it happened to me from a stock test of the demo echo server from what I remember, so it shouldn't be too difficult to reproduce.

[counter2015]

I meet the same problem, but package name different. And I also use websocket.

http4s-version: 0.23.6 java-version: 17 scala: 2.13.8 server backend: blaze

2022-03-10 08:44:49.071 [zio-default-async-10] ERROR o.h.b.s.Http1ServerStage$$anon$1 Error writing body
fs2.CompositeFailure: Multiple exceptions were thrown (2), first org.http4s.blaze.pipeline.Command$EOF$: EOF
    at fs2.CompositeFailure$.apply(CompositeFailure.scala:58)
    at fs2.CompositeFailure$.apply(CompositeFailure.scala:45)
    at fs2.Pull$.addError$1(Pull.scala:1114)
    at fs2.Pull$.viewCont$1(Pull.scala:1121)
    at fs2.Pull$.$anonfun$compile$22(Pull.scala:1158)
    at zio.internal.FiberContext.evaluateNow(FiberContext.scala:925)
    at zio.internal.FiberContext.$anonfun$evaluateLater$1(FiberContext.scala:787)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)

[swiesend]

I also run into this, but only when trying to run my server Resources sequentially with the org.specs2 sequential keyword:

val server: Resource[IO, Server[IO]] =
    BlazeServerBuilder(ec)(ioConcurrentEffect, timer)
      .bindHttp(8080, "localhost")
      .withHttpApp(httpAppWithLoggers)
      .resource

val client: Resource[IO, Client[IO]] =
    BlazeClientBuilder(ec)(ioConcurrentEffect)
    .resource
    .map(c => client.middleware.RequestLogger(logHeaders = true, logBody = true)(c))

http4s: 0.20.23 server backend: blaze java: 11.0.14 (Ubuntu Java) scala: 2.12.14 sbt: sbt 1.6.1

build.sbt:

"org.specs2" %% "specs2-core" % "4.3.4"
"org.typelevel" %% "cats-core" % "1.3.1"
"org.typelevel" %% "cats-effect" % "1.0.0"

2022-03-22 13:18:00,818 ERROR org.http4s.server.blaze.Http1ServerStage$$anon$1 - Error writing body
java.lang.RuntimeException: TickWheelExecutor is shutdown
    at scala.sys.package$.error(package.scala:30)
    at org.http4s.blaze.util.TickWheelExecutor.schedule(TickWheelExecutor.scala:115)
    at org.http4s.blazecore.IdleTimeoutStage.resetTimeout(IdleTimeoutStage.scala:66)
    at org.http4s.blazecore.IdleTimeoutStage.writeRequest(IdleTimeoutStage.scala:40)
    at org.http4s.blaze.pipeline.Tail.channelWrite(Stages.scala:96)
    at org.http4s.blaze.pipeline.Tail.channelWrite$(Stages.scala:94)
    at org.http4s.server.blaze.Http1ServerStage.channelWrite(Http1ServerStage.scala:68)
    at org.http4s.blazecore.util.IdentityWriter.writeBodyChunk(IdentityWriter.scala:58)
    at org.http4s.blazecore.util.IdentityWriter.writeEnd(IdentityWriter.scala:65)
    at org.http4s.blazecore.util.EntityBodyWriter.$anonfun$writeEntityBody$1(EntityBodyWriter.scala:54)
    at cats.effect.internals.IORunLoop$.cats$effect$internals$IORunLoop$$loop(IORunLoop.scala:87)
    at cats.effect.internals.IORunLoop$RestartCallback.signal(IORunLoop.scala:355)
    at cats.effect.internals.IORunLoop$RestartCallback.apply(IORunLoop.scala:376)
    at cats.effect.internals.IORunLoop$RestartCallback.apply(IORunLoop.scala:316)
    at cats.effect.internals.IORunLoop$.cats$effect$internals$IORunLoop$$loop(IORunLoop.scala:136)
    at cats.effect.internals.IORunLoop$RestartCallback.signal(IORunLoop.scala:355)
    at cats.effect.internals.IORunLoop$RestartCallback.apply(IORunLoop.scala:376)
    at cats.effect.internals.IORunLoop$RestartCallback.apply(IORunLoop.scala:316)
    at cats.effect.internals.IORunLoop$.cats$effect$internals$IORunLoop$$loop(IORunLoop.scala:136)
    at cats.effect.internals.IORunLoop$.startCancelable(IORunLoop.scala:41)
    at cats.effect.internals.IOBracket$BracketStart.run(IOBracket.scala:86)
    at cats.effect.internals.Trampoline.cats$effect$internals$Trampoline$$immediateLoop(Trampoline.scala:70)
    at cats.effect.internals.Trampoline.startLoop(Trampoline.scala:36)
    at cats.effect.internals.TrampolineEC$JVMTrampoline.super$startLoop(TrampolineEC.scala:93)
    at cats.effect.internals.TrampolineEC$JVMTrampoline.$anonfun$startLoop$1(TrampolineEC.scala:93)
    at scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.java:23)
    at scala.concurrent.BlockContext$.withBlockContext(BlockContext.scala:85)
    at cats.effect.internals.TrampolineEC$JVMTrampoline.startLoop(TrampolineEC.scala:93)
    at cats.effect.internals.Trampoline.execute(Trampoline.scala:43)
    at cats.effect.internals.TrampolineEC.execute(TrampolineEC.scala:44)
    at cats.effect.internals.Callback$AsyncIdempotentCallback.apply(Callback.scala:133)
    at cats.effect.internals.Callback$AsyncIdempotentCallback.apply(Callback.scala:120)
    at cats.effect.concurrent.Deferred$ConcurrentDeferred.$anonfun$unsafeRegister$1(Deferred.scala:205)
    at cats.effect.concurrent.Deferred$ConcurrentDeferred.$anonfun$unsafeRegister$1$adapted(Deferred.scala:205)
    at cats.effect.concurrent.Deferred$ConcurrentDeferred.$anonfun$notifyReadersLoop$1(Deferred.scala:241)
    at scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.java:23)
    at cats.effect.internals.IORunLoop$.cats$effect$internals$IORunLoop$$loop(IORunLoop.scala:87)
    at cats.effect.internals.IORunLoop$RestartCallback.signal(IORunLoop.scala:355)
    at cats.effect.internals.IORunLoop$RestartCallback.apply(IORunLoop.scala:376)
    at cats.effect.internals.IORunLoop$RestartCallback.apply(IORunLoop.scala:316)
    at cats.effect.internals.IOShift$Tick.run(IOShift.scala:36)
    at java.base/java.util.concurrent.ForkJoinTask$RunnableExecuteAction.exec(ForkJoinTask.java:1426)
    at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:290)
    at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1020)
    at java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1656)
    at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1594)
    at java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:183)
2022-03-22 13:18:00,831 ERROR org.http4s.blaze.channel.nio1.NIO1HeadStage - Event loop closed. Closing in current thread.
java.util.concurrent.RejectedExecutionException: This SelectorLoop is closed.
    at org.http4s.blaze.channel.nio1.SelectorLoop.enqueueTask(SelectorLoop.scala:118)
    at org.http4s.blaze.channel.nio1.SelectorLoop.executeTask(SelectorLoop.scala:92)
    at org.http4s.blaze.channel.nio1.NIO1HeadStage.doClosePipeline(NIO1HeadStage.scala:311)
    at org.http4s.blaze.pipeline.HeadStage.closePipeline(Stages.scala:321)
    at org.http4s.blaze.pipeline.HeadStage.closePipeline$(Stages.scala:319)
    at org.http4s.blaze.channel.ChannelHead.closePipeline(ChannelHead.scala:9)
    at org.http4s.blaze.pipeline.Tail.closePipeline(Stages.scala:81)
    at org.http4s.blaze.pipeline.Tail.closePipeline$(Stages.scala:77)
    at org.http4s.blazecore.IdleTimeoutStage.closePipeline(IdleTimeoutStage.scala:12)
    at org.http4s.blaze.pipeline.Tail.closePipeline(Stages.scala:81)
    at org.http4s.blaze.pipeline.Tail.closePipeline$(Stages.scala:77)
    at org.http4s.server.blaze.Http1ServerStage.closePipeline(Http1ServerStage.scala:68)
    at org.http4s.server.blaze.Http1ServerStage.org$http4s$server$blaze$Http1ServerStage$$closeConnection(Http1ServerStage.scala:289)
    at org.http4s.server.blaze.Http1ServerStage.$anonfun$renderResponse$10(Http1ServerStage.scala:282)
    at scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.java:23)
    at cats.effect.internals.IORunLoop$.cats$effect$internals$IORunLoop$$loop(IORunLoop.scala:87)
    at cats.effect.internals.IORunLoop$.start(IORunLoop.scala:34)
    at cats.effect.IO.unsafeRunAsync(IO.scala:258)
    at cats.effect.IO.unsafeRunAsyncAndForget(IO.scala:273)
    at cats.effect.IO.$anonfun$runAsync$2(IO.scala:178)
    at cats.effect.IO.$anonfun$runAsync$2$adapted(IO.scala:178)
    at scala.Function1.$anonfun$andThen$1(Function1.scala:57)
    at cats.effect.internals.IORunLoop$.cats$effect$internals$IORunLoop$$loop(IORunLoop.scala:100)
    at cats.effect.internals.IORunLoop$RestartCallback.signal(IORunLoop.scala:355)
    at cats.effect.internals.IORunLoop$RestartCallback.apply(IORunLoop.scala:376)
    at cats.effect.internals.IORunLoop$RestartCallback.apply(IORunLoop.scala:316)
    at cats.effect.internals.IORunLoop$.cats$effect$internals$IORunLoop$$loop(IORunLoop.scala:136)
    at cats.effect.internals.IORunLoop$RestartCallback.signal(IORunLoop.scala:355)
    at cats.effect.internals.IORunLoop$RestartCallback.apply(IORunLoop.scala:376)
    at cats.effect.internals.IORunLoop$RestartCallback.apply(IORunLoop.scala:316)
    at cats.effect.internals.IORunLoop$.cats$effect$internals$IORunLoop$$loop(IORunLoop.scala:136)
    at cats.effect.internals.IORunLoop$.startCancelable(IORunLoop.scala:41)
    at cats.effect.internals.IOBracket$BracketStart.run(IOBracket.scala:86)
    at cats.effect.internals.Trampoline.cats$effect$internals$Trampoline$$immediateLoop(Trampoline.scala:70)
    at cats.effect.internals.Trampoline.startLoop(Trampoline.scala:36)
    at cats.effect.internals.TrampolineEC$JVMTrampoline.super$startLoop(TrampolineEC.scala:93)
    at cats.effect.internals.TrampolineEC$JVMTrampoline.$anonfun$startLoop$1(TrampolineEC.scala:93)
    at scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.java:23)
    at scala.concurrent.BlockContext$.withBlockContext(BlockContext.scala:85)
    at cats.effect.internals.TrampolineEC$JVMTrampoline.startLoop(TrampolineEC.scala:93)
    at cats.effect.internals.Trampoline.execute(Trampoline.scala:43)
    at cats.effect.internals.TrampolineEC.execute(TrampolineEC.scala:44)
    at cats.effect.internals.Callback$AsyncIdempotentCallback.apply(Callback.scala:133)
    at cats.effect.internals.Callback$AsyncIdempotentCallback.apply(Callback.scala:120)
    at cats.effect.concurrent.Deferred$ConcurrentDeferred.$anonfun$unsafeRegister$1(Deferred.scala:205)
    at cats.effect.concurrent.Deferred$ConcurrentDeferred.$anonfun$unsafeRegister$1$adapted(Deferred.scala:205)
    at cats.effect.concurrent.Deferred$ConcurrentDeferred.$anonfun$notifyReadersLoop$1(Deferred.scala:241)
    at scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.java:23)
    at cats.effect.internals.IORunLoop$.cats$effect$internals$IORunLoop$$loop(IORunLoop.scala:87)
    at cats.effect.internals.IORunLoop$RestartCallback.signal(IORunLoop.scala:355)
    at cats.effect.internals.IORunLoop$RestartCallback.apply(IORunLoop.scala:376)
    at cats.effect.internals.IORunLoop$RestartCallback.apply(IORunLoop.scala:316)
    at cats.effect.internals.IOShift$Tick.run(IOShift.scala:36)
    at java.base/java.util.concurrent.ForkJoinTask$RunnableExecuteAction.exec(ForkJoinTask.java:1426)
    at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:290)
    at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1020)
    at java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1656)
    at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1594)
    at java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:183)