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.

Sign up for GitHub

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

Jump to bottom

blaze-server error logs on shutdown #672

Open
agourlay opened this issue Feb 4, 2019 · 12 comments
Open

blaze-server error logs on shutdown #672

agourlay opened this issue Feb 4, 2019 · 12 comments
Labels
bug module:blaze-server

Comments

@agourlay
Copy link
Contributor

agourlay commented Feb 4, 2019 •
edited
Loading

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(...)
@agourlay agourlay mentioned this issue Feb 4, 2019
Closed
6 tasks
@mr-git mr-git mentioned this issue May 2, 2019
Open
@rossabaker
Copy link
Member

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

@rossabaker rossabaker added the bug label May 29, 2019
@igor-ramazanov
Copy link

@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
Copy link
Contributor Author

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

Thanks a lot for the tip 🙇

agourlay referenced this issue in agourlay/cornichon May 29, 2019
using withNio2 removes noisy stacktraces on shutdown
5da3aae 
https://github.com/http4s/http4s/issues/2383
@rossabaker
Copy link
Member

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

@rossabaker thanks a lot for adding this important precision 👍

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

@pratikadhau11 pratikadhau11 mentioned this issue May 26, 2020
Open
@rossabaker
Copy link
Member

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

agourlay referenced this issue in agourlay/cornichon May 15, 2021
@agourlay
Http4s servers use nio1 instead of nio2
ed27a93 
The switched to nio2 was motivated by a noisy stacktrace with nio1

https://github.com/http4s/http4s/issues/2383

However nio2 is being deprecated for 0.22 and there is no replacement

http4s/http4s#4572

As a result we switch back to nio1 and hope the stacktrace won't be too noisy
@agourlay agourlay mentioned this issue May 15, 2021
Merged
@fmeeuw
Copy link

fmeeuw commented May 31, 2021

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

hamnis commented May 31, 2021

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

@hamnis hamnis closed this as completed May 31, 2021
@vasyl-zhurba
Copy link

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

Seems like its still present in 0.23.6

@armanbilge armanbilge reopened this Nov 8, 2021
@kunalherkal
Copy link

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

danicheg commented Apr 1, 2022

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

@rossabaker rossabaker transferred this issue from http4s/http4s May 24, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug module:blaze-server
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
10 participants
@hamnis @channingwalton @rossabaker @agourlay @armanbilge @kunalherkal @igor-ramazanov @fmeeuw @vasyl-zhurba @danicheg