Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Spurious websocket close errors #668

Open
megri opened this issue Sep 2, 2019 · 9 comments
Open

Spurious websocket close errors #668

megri opened this issue Sep 2, 2019 · 9 comments

Comments

@megri
Copy link

megri commented Sep 2, 2019

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 megri changed the title Spurious websocket errors Spurious websocket close errors Sep 2, 2019
@megri
Copy link
Author

megri commented Sep 2, 2019

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
Copy link
Member

Some thinking out loud on Gitter.

@saraiva132
Copy link

saraiva132 commented Oct 8, 2019

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
Copy link

nbenns commented Apr 27, 2020

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

@nbenns
Copy link

nbenns commented Apr 27, 2020

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

@rossabaker
Copy link
Member

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
Copy link

nbenns commented Apr 30, 2020

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
Copy link

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
Copy link

swiesend commented Mar 22, 2022

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)

@rossabaker rossabaker transferred this issue from http4s/http4s May 24, 2022
geminicaprograms added a commit to softwaremill/adopt-tapir that referenced this issue Oct 12, 2022
There issue with non-deterministic EOF is obsevable by others but so far
there is no good explanation (or test method) given (see [1]) therefore
for the time being we are switching to vertx http server.

TODO:
* `OPTIONS` request is not accepted and results in `405 Method Not
  Allowed` therefore UI is not able to talk to the server but calling
  `curl` works
* at the moment one cannot customise the logs hence they are not
  displayed when the server is started

Verifies #49

[1] http4s/blaze#668
geminicaprograms added a commit to softwaremill/adopt-tapir that referenced this issue Oct 12, 2022
There issue with non-deterministic EOF is observable by others but so far
there is no good explanation (or test method) given (see [1]) therefore
for the time being we are switching to vertx http server.

TODO:
* `OPTIONS` request is not accepted and results in `405 Method Not
  Allowed` therefore UI is not able to talk to the server but calling
  `curl` works
* at the moment one cannot customise the logs hence they are not
  displayed when the server is started

Verifies #49

[1] http4s/blaze#668
geminicaprograms added a commit to softwaremill/adopt-tapir that referenced this issue Oct 12, 2022
There issue with non-deterministic EOF is observable by others but so far
there is no good explanation (or test method) given (see [1]) therefore
for the time being we are switching to vertx http server.

TODO:
* `OPTIONS` request is not accepted and results in `405 Method Not
  Allowed` therefore UI is not able to talk to the server but calling
  `curl` works
* at the moment one cannot customise the logs hence they are not
  displayed when the server is started

Verifies #49

[1] http4s/blaze#668
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

6 participants