http4s/blaze

blaze-server error logs on shutdown

Opened this issue · 12 comments

agourlay commented

Using 0.20.0-M5 blaze-server via the BlazeServerBuilder.

On shutdown I can find the following entries in my logs.

ERROR org.http4s.blaze.channel.nio1.NIO1HeadStage - Abnormal NIO1HeadStage termination
java.nio.channels.ShutdownChannelGroupException
at org.http4s.blaze.channel.nio1.SelectorLoop.killSelector(SelectorLoop.scala:224)
at org.http4s.blaze.channel.nio1.SelectorLoop.org$http4s$blaze$channel$nio1$SelectorLoop$$runLoop(SelectorLoop.scala:184)
at org.http4s.blaze.channel.nio1.SelectorLoop$$anon$1.run(SelectorLoop.scala:67)
 at java.base/java.lang.Thread.run(Thread.java:844)

ERROR org.http4s.server.blaze.Http1ServerStage$$anon$1 - Fatal Error: Error in requestLoop()
 java.nio.channels.ShutdownChannelGroupException
at org.http4s.blaze.channel.nio1.SelectorLoop.killSelector(SelectorLoop.scala:224)
at org.http4s.blaze.channel.nio1.SelectorLoop.org$http4s$blaze$channel$nio1$SelectorLoop$$runLoop(SelectorLoop.scala:184)
at org.http4s.blaze.channel.nio1.SelectorLoop$$anon$1.run

This happens during an integration test for which the server is shutdown while the client side is still running (blaze-client).

The server is running with the default configuration.

BlazeServerBuilder[Task]
    .bindHttp(port, interface)
    .withoutBanner
    .withHttpApp(myRouter)
    .resource
    .use(...)
rossabaker commented

This is not fatal, but is unacceptably noisy. I'd still like to squash this.

  • 👍1
igor-ramazanov commented

@agourlay Doesn't BlazeServerBuilder[Task].withNio2(true) solves the problem?

We had the same issue in our tests with a WebSockets http4s server and it went away with the above option.

  • 👍1
  • 🎉1
agourlay commented

@igor-ramazanov I just gave it a try and you are correct; the stacktraces are now gone!

Thanks a lot for the tip 🙇

  • 👍1
rossabaker commented

A long, long time ago, nio2 didn't do as well as nio1 on benchmarks. I don't remember it being hugely different, but it's the reason that nio1 remained the default. If you're in a high load situation, it may be worth a round of performance testing.

agourlay commented

@rossabaker thanks a lot for adding this important precision 👍

Performance is not critical for my use case therefore I am fine switching to nio2.

rossabaker commented

Note that nio2 is gone, so the workaround is about to be gone. We'll need to do something else.

fmeeuw commented

We do encounter this issue with http4s 0.21.23. It would be very much appreciated if it is picked up at some point. :)

hamnis commented

This should have been fixed in 0.21.24. Please try with that, reopen if not.

vasyl-zhurba commented

I think it is still present in 0.21.24

ERROR org.http4s.blaze.channel.nio1.NIO1HeadStage - Abnormal NIO1HeadStage termination
o.h.b.u.TickWheelExecutor$AlreadyShutdownException$: TickWheelExecutor is shutdown
	at o.h.b.u.TickWheelExecutor$AlreadyShutdownException$.<clinit>(TickWheelExecutor.scala:277)
	at o.h.b.u.TickWheelExecutor.schedule(TickWheelExecutor.scala:131)
	at o.h.b.u.TickWheelExecutor.schedule(TickWheelExecutor.scala:94)
	at o.h.b.IdleTimeoutStage.org$http4s$blazecore$IdleTimeoutStage$$resetTimeout(IdleTimeoutStage.scala:109)
	at o.h.b.IdleTimeoutStage$$anonfun$readRequest$1.applyOrElse(IdleTimeoutStage.scala:42)
	at o.h.b.IdleTimeoutStage$$anonfun$readRequest$1.applyOrElse(IdleTimeoutStage.scala:42)
	at s.concurrent.Future.$anonfun$andThen$1(Future.scala:500)
	at s.c.i.Promise$Transformation.run(Promise.scala:439)
	at o.h.b.u.Execution$$anon$3.execute(Execution.scala:80)
	at s.c.i.Promise$Transformation.submitWithValue(Promise.scala:393)
	at s.c.i.Promise$DefaultPromise.submitWithValue(Promise.scala:302)
	at s.c.i.Promise$DefaultPromise.tryComplete0(Promise.scala:249)
	at s.c.i.Promise$DefaultPromise.tryComplete(Promise.scala:242)
	at s.concurrent.Promise.tryFailure(Promise.scala:117)
	at s.concurrent.Promise.tryFailure$(Promise.scala:117)
	at s.c.i.Promise$DefaultPromise.tryFailure(Promise.scala:104)
	at o.h.b.c.n.NIO1HeadStage.org$http4s$blaze$channel$nio1$NIO1HeadStage$$doClose$1(NIO1HeadStage.scala:301)
	at o.h.b.c.n.NIO1HeadStage$$anon$3.run(NIO1HeadStage.scala:331)
	at o.h.b.c.n.SelectorLoop.executeTask(SelectorLoop.scala:85)
	at o.h.b.c.n.NIO1HeadStage.doClosePipeline(NIO1HeadStage.scala:319)
	at o.h.b.c.n.NIO1HeadStage.close(NIO1HeadStage.scala:288)
	at o.h.b.c.n.SelectorLoop.$anonfun$killSelector$1(SelectorLoop.scala:228)
	at o.h.b.c.n.SelectorLoop.$anonfun$killSelector$1$adapted(SelectorLoop.scala:224)
	at s.c.IterableOnceOps.foreach(IterableOnce.scala:563)
	at s.c.IterableOnceOps.foreach$(IterableOnce.scala:561)
	at s.c.AbstractIterable.foreach(Iterable.scala:919)
	at o.h.b.c.n.SelectorLoop.killSelector(SelectorLoop.scala:224)
	at o.h.b.c.n.SelectorLoop.org$http4s$blaze$channel$nio1$SelectorLoop$$runLoop(Sel...
channingwalton commented

Seems like its still present in 0.23.6

kunalherkal commented

Also present in 0.23.10 with three different error messages: Abnormal NIO1HeadStage termination, Error encountered in Direct EC and Fatal Error: Error in requestLoop(), while stack-trace is always exactly same:

org.http4s.blaze.util.TickWheelExecutor$AlreadyShutdownException$: TickWheelExecutor is shutdown
	at org.http4s.blaze.util.TickWheelExecutor$AlreadyShutdownException$.<clinit>(TickWheelExecutor.scala:291)
	at org.http4s.blaze.util.TickWheelExecutor.schedule(TickWheelExecutor.scala:140)
	at org.http4s.blaze.util.TickWheelExecutor.schedule(TickWheelExecutor.scala:99)
	at org.http4s.blazecore.IdleTimeoutStage.org$http4s$blazecore$IdleTimeoutStage$$resetTimeout(IdleTimeoutStage.scala:115)
	at org.http4s.blazecore.IdleTimeoutStage$$anonfun$readRequest$1.applyOrElse(IdleTimeoutStage.scala:48)
	at org.http4s.blazecore.IdleTimeoutStage$$anonfun$readRequest$1.applyOrElse(IdleTimeoutStage.scala:48)
	at scala.concurrent.Future.$anonfun$andThen$1(Future.scala:506)
	at scala.concurrent.impl.Promise$Transformation.run(Promise.scala:475)
	at org.http4s.blaze.util.Execution$$anon$3.execute(Execution.scala:79)
	at scala.concurrent.impl.Promise$Transformation.submitWithValue(Promise.scala:429)
	at scala.concurrent.impl.Promise$DefaultPromise.submitWithValue(Promise.scala:338)
	at scala.concurrent.impl.Promise$DefaultPromise.tryComplete0(Promise.scala:285)
	at scala.concurrent.impl.Promise$DefaultPromise.tryComplete(Promise.scala:278)
	at scala.concurrent.Promise.tryFailure(Promise.scala:117)
	at scala.concurrent.Promise.tryFailure$(Promise.scala:117)
	at scala.concurrent.impl.Promise$DefaultPromise.tryFailure(Promise.scala:104)
	at org.http4s.blaze.channel.nio1.NIO1HeadStage.org$http4s$blaze$channel$nio1$NIO1HeadStage$$doClose$1(NIO1HeadStage.scala:305)
	at org.http4s.blaze.channel.nio1.NIO1HeadStage$$anon$3.run(NIO1HeadStage.scala:336)
	at org.http4s.blaze.channel.nio1.SelectorLoop.executeTask(SelectorLoop.scala:87)
	at org.http4s.blaze.channel.nio1.NIO1HeadStage.doClosePipeline(NIO1HeadStage.scala:324)
	at org.http4s.blaze.channel.nio1.NIO1HeadStage.close(NIO1HeadStage.scala:292)
	at org.http4s.blaze.channel.nio1.SelectorLoop.$anonfun$killSelector$1(SelectorLoop.scala:234)
	at org.http4s.blaze.channel.nio1.SelectorLoop.$anonfun$killSelector$1$adapted(SelectorLoop.scala:230)
	at scala.collection.IterableOnceOps.foreach(IterableOnce.scala:563)
	at scala.collection.IterableOnceOps.foreach$(IterableOnce.scala:561)
	at scala.collection.AbstractIterable.foreach(Iterable.scala:926)
	at org.http4s.blaze.channel.nio1.SelectorLoop.killSelector(SelectorLoop.scala:230)
	at org.http4s.blaze.channel.nio1.SelectorLoop.org$http4s$blaze$channel$nio1$SelectorLoop$$runLoop(SelectorLoop.scala:186)
	at org.http4s.blaze.channel.nio1.SelectorLoop$$anon$1.run(SelectorLoop.scala:62)
	at java.base/java.lang.Thread.run(Unknown Source)
danicheg commented

Recently was did http4s/http4s#6198. So we hope the next releases will reduce some error logs. Especially about AlreadyShutdownException.

  • 🎉1