Http4s: Easy to reproduce unhandled EOF exception when using ZIO

[Dennis4b]

(tested with 0.20.6, so not fixed by #2651)

When websocat disconnects from an http4s websocket server using ZIO for the effect types and runtime, an EOF slips through somewhere.
I ran into the problem with Firefox but it turns out to be easily triggerable with websocat.

I've made a simple testcase available at:
https://github.com/Dennis4b/test-http4s-websocket-eof-problem

Just run it:
sbt run

and then run websocat (I have version 1.2.0):
websocat ws://localhost:10080/wstest, wait a second, press Ctrl-C

output appears in the server:

01:10:05.670 [scala-execution-context-global-99] DEBUG org.http4s.server.blaze.WSFrameAggregator - Stage WSFrameAggregator sending inbound command: Connected
01:10:05.670 [scala-execution-context-global-99] DEBUG org.http4s.blazecore.websocket.Http4sWSStage - Starting up.
>> Inputstream closed
>> Outputstream closed
01:10:06.863 [zio-default-async-26-1845069441] DEBUG org.http4s.blazecore.websocket.Http4sWSStage - Shutting down.
01:10:06.863 [zio-default-async-26-1845069441] DEBUG org.http4s.server.blaze.WSFrameAggregator - Shutting down.
01:10:06.863 [zio-default-async-26-1845069441] DEBUG org.http4s.server.blaze.WebSocketDecoder - Shutting down.
01:10:06.863 [zio-default-async-26-1845069441] DEBUG org.http4s.blazecore.IdleTimeoutStage - Shutting down idle timeout stage
01:10:06.864 [zio-default-async-26-1845069441] DEBUG org.http4s.blazecore.IdleTimeoutStage - Shutting down.
01:10:06.864 [zio-default-async-26-1845069441] DEBUG org.http4s.blaze.channel.nio1.NIO1HeadStage - Shutting down.
01:10:06.865 [blaze-selector-1] DEBUG org.http4s.blaze.channel.nio1.NIO1HeadStage - Stage NIO1HeadStage sending inbound command: Disconnected
01:10:06.865 [blaze-selector-1] DEBUG org.http4s.blazecore.IdleTimeoutStage - Shutting down idle timeout stage
01:10:06.865 [blaze-selector-1] DEBUG org.http4s.blazecore.IdleTimeoutStage - Shutting down.
01:10:06.865 [blaze-selector-1] DEBUG org.http4s.blazecore.IdleTimeoutStage - Stage IdleTimeoutStage sending inbound command: Disconnected
01:10:06.865 [blaze-selector-1] DEBUG org.http4s.server.blaze.WebSocketDecoder - Shutting down.
01:10:06.865 [blaze-selector-1] DEBUG org.http4s.server.blaze.WebSocketDecoder - Stage WebSocketDecoder sending inbound command: Disconnected
01:10:06.865 [blaze-selector-1] DEBUG org.http4s.server.blaze.WSFrameAggregator - Shutting down.
01:10:06.865 [blaze-selector-1] DEBUG org.http4s.server.blaze.WSFrameAggregator - Stage WSFrameAggregator sending inbound command: Disconnected
01:10:06.866 [blaze-selector-1] DEBUG org.http4s.blazecore.websocket.Http4sWSStage - Shutting down.
01:10:06.868 [zio-default-async-21-1845069441] ERROR org.http4s.blazecore.websocket.Http4sWSStage - Error closing Web Socket
org.http4s.blaze.pipeline.Command$EOF$: EOF
Fiber failed.
A checked error was not handled.
EOF

Fiber:281 was supposed to continue to:
  a future continuation at fs2.internal.Algebra$.compileLoop(Algebra.scala:349)
  a future continuation at fs2.internal.Algebra$.compile(Algebra.scala:167)
  a future continuation at zio.ZIO.run(ZIO.scala:1080)
  a future continuation at zio.interop.CatsEffect.bracketCase(catsjvm.scala:234)
  a future continuation at fs2.Stream$CompileOps.foldChunks(Stream.scala:4023)
  a future continuation at zio.interop.CatsConcurrentEffect.runAsync(catsjvm.scala:112)

Fiber:281 execution trace:
  at fs2.internal.Algebra$.compileLoop(Algebra.scala:307)
  at fs2.internal.CompileScope.openAncestor(CompileScope.scala:233)
  at cats.effect.concurrent.Ref$SyncRef.get(Ref.scala:219)
  at fs2.internal.Algebra$.compileLoop(Algebra.scala:306)
  at fs2.internal.CompileScope.close(CompileScope.scala:219)
  at cats.effect.concurrent.Ref$SyncRef.modify(Ref.scala:253)
  at fs2.internal.CompileScope.close(CompileScope.scala:218)
  at fs2.internal.CompileScope.close(CompileScope.scala:217)
  .. snipped

[ghostdogpr]

I'm having this exact error as well.

[Dennis4b]

The following appears to fix the issue.
In Http4sWSStage.scala:

def inputstream: Stream[F,WebSocketFrame] = {
  def loop: Stream[F,WebSocketFrame] = {
    Stream.eval(handleRead.attempt).flatMap{
      case Right(r) => Stream.emit(r) ++ loop
      case _ => Stream.empty
    }
  }
  loop
}

So just terminate the inputstream on any read errors.

[rossabaker]

Thanks for the report and the repro. A few things I had to add:

• The project needs to be on http4s-0.20.6 to have the bugfix
• I had to add a logging backend.
• I had to use 127.0.0.1 instead of localhost in my websocat call, but that's probably on me.

The problem boils down to this:

object Boom extends Exception
F.runAsync(F.raiseError(Boom)) {
  case Left(Boom) => IO(println("Caught boom"))
  case x => IO(println("Oops: "+x))
}.unsafeRunSync()

By law, this prints "Caught boom" for any Effect. But your runtime is loudly logging the boom before passing it to the runAsync callback. This is not unlawful, because the laws do not consider logging, but it violates the spirit of EffectLaws.runAsyncRaiseErrorProducesLeftIO. You're going to tend to see a lot of suppressed errors being logged once and library-logged errors being logged twice.

It works quietly and correctly with cats.effect.IO.

[jdegoes]

@Dennis4b @rossabaker

Any third-party effect type that is "run" to a concrete type such as SyncIO (which is really Cats IO in disguise) has to be fully evaluated by the third-party runtime system. If, to avoid the loss of information, the runtime system logs unhandled errors (as ZIO does, and probably Monix), then such a conversion point will generated logged errors.

The runtime system has no way of knowing what will happen "after" the conversion; this is an information-theoretic limitation and cannot be "solved".

The best possible solution would be to never materialize an F[_] into a concrete Cats IO data type; failing that, pushing errors into values via attempt through such conversion points would avoid the issue; and failing that, spot fixes such as the above could work in some cases.

[neko-kai]

For anyone who's wondering how to turn of these error messages: you can always disable uncaught error logging in Platform.withReportFailure - https://github.com/zio/zio/blob/master/core/shared/src/main/scala/zio/internal/Platform.scala#L82

DefaultPlatform.withReportFailure( => ())