blaze-server error logs on shutdown

[agourlay]

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]

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

[igor-ramazanov]

@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.

[agourlay]

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

Thanks a lot for the tip 🙇

[rossabaker]

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]

@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]

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

[fmeeuw]

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]

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

[vasyl-zhurba]

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]

Seems like its still present in 0.23.6

[kunalherkal]

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]

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