Ktor: Websocket 1006 close error on official examples

Created on 8 Nov 2019 · 7Comments · Source: ktorio/ktor

EDIT: the example work FINE on firefox!

I'm a beginner at Ktor.
Using the websockets examples from the doc/guide and testing with http://demos.kaazing.com/echo/index.html at ws://0.0.0.0:8080/myws/echo

When I try to connect to the ws route, it close after a few seconds with status code 1006 (close error)
I cannot send any text from the client nor send any text from the server.

for the following code

webSocket("/myws/echo") {
            println("dimnationnnn")
            send(Frame.Text("Hi from server"))
            while (true) {
                val frame = incoming.receive()
                if (frame is Frame.Text) {
                    send(Frame.Text("Client said: " + frame.readText()))
                }
            }
        }

I get the following log:

dimnation
2019-11-08 11:53:59.670 [nioEventLoopGroup-4-3] INFO  Application - 101 Switching Protocols: GET - /myws/echo
2019-11-08 11:53:59.673 [nioEventLoopGroup-3-3] ERROR Application - Websocket handler failed
kotlinx.coroutines.channels.ClosedReceiveChannelException: Channel was closed
    at kotlinx.coroutines.channels.Closed.getReceiveException(AbstractChannel.kt:1049)
    at kotlinx.coroutines.channels.AbstractChannel$ReceiveElement.resumeReceiveClosed(AbstractChannel.kt:878)
    at kotlinx.coroutines.channels.AbstractSendChannel.helpClose(AbstractChannel.kt:308)
    at kotlinx.coroutines.channels.AbstractSendChannel.close(AbstractChannel.kt:247)
    at kotlinx.coroutines.channels.SendChannel$DefaultImpls.close$default(Channel.kt:100)
    at io.ktor.http.cio.websocket.DefaultWebSocketSessionImpl$runIncomingProcessor$1.invokeSuspend(DefaultWebSocketSessionImpl.kt:139)
    at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
    at kotlinx.coroutines.ResumeModeKt.resumeMode(ResumeMode.kt:67)
    at kotlinx.coroutines.DispatchedKt.resume(Dispatched.kt:319)
    at kotlinx.coroutines.DispatchedKt.resumeUnconfined(Dispatched.kt:49)
    at kotlinx.coroutines.DispatchedKt.dispatch(Dispatched.kt:298)
    at kotlinx.coroutines.CancellableContinuationImpl.dispatchResume(CancellableContinuationImpl.kt:250)
    at kotlinx.coroutines.CancellableContinuationImpl.completeResume(CancellableContinuationImpl.kt:327)
    at kotlinx.coroutines.channels.AbstractChannel$ReceiveHasNext.resumeReceiveClosed(AbstractChannel.kt:918)
    at kotlinx.coroutines.channels.AbstractSendChannel.helpClose(AbstractChannel.kt:308)
    at kotlinx.coroutines.channels.AbstractSendChannel.close(AbstractChannel.kt:247)
    at kotlinx.coroutines.channels.SendChannel$DefaultImpls.close$default(Channel.kt:100)
    at io.ktor.http.cio.websocket.WebSocketReader$readerJob$1.invokeSuspend(WebSocketReader.kt:50)
    at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
    at kotlinx.coroutines.DispatchedTask.run(Dispatched.kt:241)
    at io.netty.util.concurrent.AbstractEventExecutor.safeExecute$$$capture(AbstractEventExecutor.java:163)
    at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java)
    at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:416)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:515)
    at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:918)
    at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.lang.Thread.run(Thread.java:748)
2019-11-08 11:53:59.693 [nioEventLoopGroup-4-4] INFO  Application - 200 OK: GET - /`


The websocket route indeed is called as it print.

I doubt it's a ktor bug but this is a bad developper experience, I'm probably missing an information that should be (and isn't) provided by the doc and the guide.

BTW can I switch from CIO to apache and still get websocket support ?
Note: my boilerplate is generated by the ktor plugin.

I also get the following exception finally
`Exception in thread "nioEventLoopGroup-3-1" io.ktor.util.cio.ChannelWriteException: Cannot write to a channel
    at io.ktor.server.netty.cio.NettyResponsePipeline.processCallFailed(NettyResponsePipeline.kt:144)
    at io.ktor.server.netty.cio.NettyResponsePipeline.access$processCallFailed(NettyResponsePipeline.kt:26)
    at io.ktor.server.netty.cio.NettyResponsePipeline.processJobs(NettyResponsePipeline.kt:447)
    at io.ktor.server.netty.cio.NettyResponsePipeline$processJobs$1.invokeSuspend(NettyResponsePipeline.kt)
    at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
    at kotlinx.coroutines.DispatchedTask.run(Dispatched.kt:241)
    at io.netty.util.concurrent.AbstractEventExecutor.safeExecute$$$capture(AbstractEventExecutor.java:163)
    at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java)
    at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:416)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:515)
    at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:918)
    at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.lang.Thread.run(Thread.java:748)
Caused by: java.nio.channels.ClosedChannelException
    at io.netty.channel.AbstractChannel$AbstractUnsafe.newClosedChannelException(AbstractChannel.java:955)
    at io.netty.channel.AbstractChannel$AbstractUnsafe.write(AbstractChannel.java:863)
    at io.netty.channel.DefaultChannelPipeline$HeadContext.write(DefaultChannelPipeline.java:1365)
    at io.netty.channel.AbstractChannelHandlerContext.invokeWrite0(AbstractChannelHandlerContext.java:716)
    at io.netty.channel.AbstractChannelHandlerContext.invokeWriteAndFlush(AbstractChannelHandlerContext.java:763)
    at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:789)
    at io.netty.channel.AbstractChannelHandlerContext.writeAndFlush(AbstractChannelHandlerContext.java:757)
    at io.netty.channel.AbstractChannelHandlerContext.invokeWriteAndFlush(AbstractChannelHandlerContext.java:766)
    at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:789)
    at io.netty.channel.AbstractChannelHandlerContext.writeAndFlush(AbstractChannelHandlerContext.java:757)
    at io.netty.channel.AbstractChannelHandlerContext.invokeWriteAndFlush(AbstractChannelHandlerContext.java:766)
    at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:789)
    at io.netty.channel.AbstractChannelHandlerContext.writeAndFlush(AbstractChannelHandlerContext.java:757)
    at io.netty.channel.AbstractChannelHandlerContext.writeAndFlush(AbstractChannelHandlerContext.java:812)
    at io.ktor.server.netty.cio.NettyResponsePipeline$processBodyFlusher$2.invokeSuspend(NettyResponsePipeline.kt:312)
    ... 10 more

You could save learners a lot of time by documenting this behavior.

bug

Source

LifeIsStrange

All 7 comments

EDIT: the example work FINE on firefox!
So either http://demos.kaazing.com/echo/index.html has a bug on chrome which I doubt.
either ktor hit a bug only on chrome which I doubt too.

What do you think, feel free to close the issue.

LifeIsStrange on 8 Nov 2019

I hit the same bug on https://www.websocket.org/echo.html which is the de facto standard for quick websocket testing. But this website use the same code as kaazing.

LifeIsStrange on 8 Nov 2019

On firefox when I ask the client to close the connection, the connection close fine (no error code)
but the server output
ERROR Application - Websocket handler failed kotlinx.coroutines.channels.ClosedReceiveChannelException: Channel was closed at kotlinx.coroutines.channels.Closed.getReceiveException(AbstractChannel.kt:1049) at kotlinx.coroutines.channels.AbstractChannel$ReceiveElement.resumeReceiveClosed(AbstractChannel.kt:878) at kotlinx.coroutines.channels.AbstractSendChannel.helpClose(AbstractChannel.kt:308) at kotlinx.coroutines.channels.AbstractSendChannel.close(AbstractChannel.kt:247) at kotlinx.coroutines.channels.SendChannel$DefaultImpls.close$default(Channel.kt:100) at io.ktor.http.cio.websocket.DefaultWebSocketSessionImpl$runIncomingProcessor$1.invokeSuspend(DefaultWebSocketSessionImpl.kt:139) at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33) at kotlinx.coroutines.ResumeModeKt.resumeMode(ResumeMode.kt:67) at kotlinx.coroutines.DispatchedKt.resume(Dispatched.kt:319) at kotlinx.coroutines.DispatchedKt.resumeUnconfined(Dispatched.kt:49) at kotlinx.coroutines.DispatchedKt.dispatch(Dispatched.kt:298) at kotlinx.coroutines.CancellableContinuationImpl.dispatchResume(CancellableContinuationImpl.kt:250) at kotlinx.coroutines.CancellableContinuationImpl.completeResume(CancellableContinuationImpl.kt:327) at kotlinx.coroutines.channels.AbstractChannel$ReceiveHasNext.completeResumeReceive(AbstractChannel.kt:907) at kotlinx.coroutines.channels.ArrayChannel.offerInternal(ArrayChannel.kt:80) at kotlinx.coroutines.channels.AbstractSendChannel.offer(AbstractChannel.kt:160) at kotlinx.coroutines.channels.AbstractSendChannel.send(AbstractChannel.kt:146) at io.ktor.http.cio.websocket.WebSocketReader.handleFrameIfProduced(WebSocketReader.kt:105) at io.ktor.http.cio.websocket.WebSocketReader.parseLoop(WebSocketReader.kt:87) at io.ktor.http.cio.websocket.WebSocketReader.readLoop(WebSocketReader.kt:69) at io.ktor.http.cio.websocket.WebSocketReader$readLoop$1.invokeSuspend(WebSocketReader.kt) at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33) at kotlinx.coroutines.DispatchedTask.run(Dispatched.kt:241) at io.netty.util.concurrent.AbstractEventExecutor.safeExecute$$$capture(AbstractEventExecutor.java:163) at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java) at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:416) at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:515) at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:918) at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.lang.Thread.run(Thread.java:748)
Closing normally shouldn't be an error ?
(Functionally it works)

LifeIsStrange on 8 Nov 2019

I've encountered the same bug, in Chrome when closing from the web client after a few seconds it errors with code 1006. Weirdly this occurs only when using Chrome and the Netty engine. The other engines/browser combinations I've tested works fine

fis-live on 9 Nov 2019

😕1

Hi @LifeIsStrange, thanks for the report.

I've investigated the problem and realized that ktor WebSockets have a lifecycle that's not RFC compliant. We don't close TCP connection on the server-side assuming that it's the responsibility of a client. It's not RFC compliant as I said, but Firefox handles this case also unlike Chrome.

Well, we changed the default behavior and now we close TCP connection on the server-side, so the next release will include this fix.