blaze
blaze copied to clipboard
Published
20 hours ago •
http4s
http4s
Spurious websocket close errors
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.
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
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?).
I also have this issue, and would love an answer. Is there any work being done on the braze connector?
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?
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.
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)
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)
