softwaremill / softwaremill/tapir

[BUG] Websockets with zio-http can fail on too early messages on slow hosts

Open
#3,685 0 comments 1 reaction 0 assignees View on GitHub

Nobody has claimed this yet.

Dominant language
Scala
Stars
1.5k
Forks
468
Avg merge
5h 37m
Merged PRs (30d)
34

Description

Tapir version: 1.9.9
ZIO-Http version: 3.0.0-RC4

Scala version: 3.3.3

Describe the bug

  def websocketBroken(_u: Unit): ZIO[Any, Unit, ZioStream[Throwable, String] => ZioStream[Throwable, String]] =
    ZIO.succeed(_ => ZStream.succeed("Answer"))

  val socketApp = ZioHttpInterpreter[Any](ZioHttpServerOptions.default).toHttp(
    List(
      endpoint
        .in("websocketBroken")
        .out(webSocketBody[String, CodecFormat.TextPlain, String, CodecFormat.TextPlain](ZioStreams))
        .zServerLogic(websocketBroken)
    )
  )

When creating a websocket endpoint that sends a message to the client immedtiately after the connection is opened and using zio-http as backend, the endpoint sometimes fails with the exception shown below.
The web client does not notice the server failure and tries to re-connect after a timeout.

Log message
backend-server-1  | 2024-03-20T07:29:02.13 level=DEBUG zio-fiber-1100 not-available: "An error was silently ignored because it is not anticipated to be useful" cause=Exception in thread "zio-fiber-1102" java.lang.UnsupportedOperationException: unsupported message type: PingWebSocketFrame (expected: ByteBuf, DefaultFileRegion)
backend-server-1  |     at io.netty.channel.epoll.AbstractEpollStreamChannel.filterOutboundMessage(AbstractEpollStreamChannel.java:529)
backend-server-1  |     at io.netty.channel.AbstractChannel$AbstractUnsafe.write(AbstractChannel.java:868)
backend-server-1  |     at io.netty.channel.DefaultChannelPipeline$HeadContext.write(DefaultChannelPipeline.java:1367)
backend-server-1  |     at io.netty.channel.AbstractChannelHandlerContext.invokeWrite0(AbstractChannelHandlerContext.java:877)
backend-server-1  |     at io.netty.channel.AbstractChannelHandlerContext.invokeWrite(AbstractChannelHandlerContext.java:863)
backend-server-1  |     at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:968)
backend-server-1  |     at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:856)
backend-server-1  |     at io.netty.handler.codec.http.HttpObjectEncoder.write(HttpObjectEncoder.java:103)
backend-server-1  |     at io.netty.channel.AbstractChannelHandlerContext.invokeWrite0(AbstractChannelHandlerContext.java:881)
backend-server-1  |     at io.netty.channel.AbstractChannelHandlerContext.invokeWrite(AbstractChannelHandlerContext.java:863)
backend-server-1  |     at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:968)
backend-server-1  |     at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:856)
backend-server-1  |     at io.netty.channel.ChannelDuplexHandler.write(ChannelDuplexHandler.java:115)
backend-server-1  |     at io.netty.handler.codec.http.HttpServerKeepAliveHandler.write(HttpServerKeepAliveHandler.java:87)
backend-server-1  |     at io.netty.channel.AbstractChannelHandlerContext.invokeWrite0(AbstractChannelHandlerContext.java:879)
backend-server-1  |     at io.netty.channel.AbstractChannelHandlerContext.invokeWrite(AbstractChannelHandlerContext.java:863)
backend-server-1  |     at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:968)
backend-server-1  |     at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:856)
backend-server-1  |     at io.netty.channel.ChannelDuplexHandler.write(ChannelDuplexHandler.java:115)
backend-server-1  |     at io.netty.channel.AbstractChannelHandlerContext.invokeWrite0(AbstractChannelHandlerContext.java:879)
backend-server-1  |     at io.netty.channel.AbstractChannelHandlerContext.invokeWriteAndFlush(AbstractChannelHandlerContext.java:940)
backend-server-1  |     at io.netty.channel.AbstractChannelHandlerContext$WriteTask.run(AbstractChannelHandlerContext.java:1247)
backend-server-1  |     at io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java:173)
backend-server-1  |     at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:166)
backend-server-1  |     at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:470)
backend-server-1  |     at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:413)
backend-server-1  |     at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
backend-server-1  |     at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
backend-server-1  |     at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
backend-server-1  |     at java.base/java.lang.Thread.run(Unknown Source)
backend-server-1  |     at sttp.tapir.server.ziohttp.ZioHttpInterpreter.handleWebSocketResponse.app(ZioHttpInterpreter.scala:81)

The issue is basically caused by tapir sending a ping frame before zio-http and netty being ready for it.
Deactivating automatic ping handling in tapir and delaying the first message for a few milliseconds successfully solves the problem.

I reported this bug already to zio-http in https://github.com/zio/zio-http/issues/2737, where they concluded that it is caused by using the API in a wrong way by sending the first message without waiting for UserEventTriggered(HandshakeComplete) to happen.

How to reproduce?

The given script shows the setup I encountered the problem with. Sadly, I can only witness the bug when running the server on a slow remote VM, where the problem occurs more than half of the time. Using the script locally on my dev machine never fails.

Steps to reproduce:

  1. Run the script with scala-cli
  2. Visit the shown URL
  3. Open the browser dev console and inspect the logs. Connections to two websockets are opended ten times each and a message is printed when a message was received from the websocket. We expect 10 messages for each websocket.
//> using dep "dev.zio::zio-http::3.0.0-RC6"
//> using dep "dev.zio::zio-logging::2.2.2"
//> using dep   "com.softwaremill.sttp.tapir::tapir-zio-http-server::1.10.4"
//> using scala "3.3.3"

import zio.http.{Server, Method, Routes, handler, Response}
import zio.http.template.*
import zio.logging.*

import zio.*
import zio.stream.{Stream => ZioStream, ZStream}

import sttp.tapir.server.ziohttp.*
import sttp.tapir.ztapir.*
import sttp.tapir.CodecFormat

import sttp.capabilities.zio.ZioStreams
import sttp.model.StatusCode

object MainServer extends ZIOAppDefault {

  def app = Routes(
    Method.GET / "" -> handler(
      Response.html(Dom.raw("""<script>
// Create WebSocket connection.
let receivedBroken = 0
let receivedWorking = 0

for(let x = 0; x<10; x++) {
const s1 = new WebSocket("ws://localhost:6896/websocketBroken");
const s2 = new WebSocket("ws://localhost:6896/websocketWorking");

// Listen for messages
s1.addEventListener("message", (event) => {
  receivedBroken += 1;
  console.log("Received broken: "+receivedBroken)
});
s2.addEventListener("message", (event) => {
  receivedWorking += 1;
  console.log("Received working: "+receivedWorking)
});
}
      </script>"""))
    )
  ).toHttpApp

  def websocketBroken(_u: Unit): ZIO[Any, Unit, ZioStream[Throwable, String] => ZioStream[Throwable, String]] =
    ZIO.succeed(_ => ZStream.succeed("Answer"))

  def websocketWorking(_u: Unit): ZIO[Any, Unit, ZioStream[Throwable, String] => ZioStream[Throwable, String]] =
    ZIO.succeed((_: ZioStream[Throwable, String]) => ZStream.succeed("Answer")).delay(Duration.fromMillis(100))

  val socketApp = ZioHttpInterpreter[Any](ZioHttpServerOptions.default).toHttp(
    List(
      endpoint
        .in("websocketBroken")
        .out(webSocketBody[String, CodecFormat.TextPlain, String, CodecFormat.TextPlain](ZioStreams))
        .zServerLogic(websocketBroken),
      endpoint
        .in("websocketWorking")
        .out(webSocketBody[String, CodecFormat.TextPlain, String, CodecFormat.TextPlain](ZioStreams))
        .zServerLogic(websocketWorking)
    )
  )

  def logger = consoleLogger(
    ConsoleLoggerConfig.default.copy(filter = LogFilter.LogLevelByNameConfig(LogLevel.All, Map.empty[String, LogLevel]))
  )

  override val bootstrap = Runtime.removeDefaultLoggers >>> logger

  def run = Console.printLine("http://localhost:6896/") *>
    Server.serve(app ++ socketApp).provide(Server.defaultWith(_.port(6896)))

}

Additional information

See previous issue https://github.com/zio/zio-http/issues/2737
The log message shown in that issue is slightly different as the problem there was caused by a too early text frame instead of a ping frame, yet this shouldn't make any difference.

Contributor guide

No contributing guide indexed for this repository

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start at sttp.tapir.server.ziohttp.ZioHttpInterpreter.handleWebSocketResponse in ZioHttpInterpreter.scala:81 and review the supplied scala-cli reproduction using the broken and working websocket endpoints. Run it on a slow remote VM and compare the connection failures and Netty stack trace. Done means the immediate websocket message path no longer intermittently fails before the connection is ready.

Written by the indexing model from the issue text.

Assessment

Tech stack
scala
Domain
backend
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Mostly clear
Newbie friendliness
35/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.