Websocket IO::Error

[adacosta]

Description

An Unhandled exception in spawn: Closed stream (IO::Error) can be raised if the socket connection is closed and data is then written.

2020-02-21T07:00:51.332728616Z app[web.1]: 07:00:51 Server     | (INFO) DevicesSocket on_connect
2020-02-21T07:00:51.379814540Z app[web.1]: 07:00:51 Server     | (INFO) DevicesChannel handle_joined message = {"event" => "join", "topic" => "device_updates:device_id:1"}
^[[B2020-02-21T07:01:17.009775817Z app[web.1]: Unhandled exception in spawn: Closed stream (IO::Error)
2020-02-21T07:01:17.009843179Z app[web.1]:   from /tmp/crystal/share/crystal/src/io/buffered.cr:127:0 in 'write_byte'
2020-02-21T07:01:17.009854193Z app[web.1]:   from /tmp/crystal/share/crystal/src/http/web_socket/protocol.cr:123:12 in 'send'
2020-02-21T07:01:17.009861528Z app[web.1]:   from /tmp/build/lib/amber/src/amber/websockets/client_sockets.cr:15:17 in '->'
2020-02-21T07:01:17.009869293Z app[web.1]:   from /tmp/crystal/share/crystal/src/fiber.cr:255:3 in 'run'
2020-02-21T07:01:17.009877515Z app[web.1]:   from ???
2020-02-21T07:01:18.185522765Z app[web.1]: Unhandled exception in spawn: Closed stream (IO::Error)
2020-02-21T07:01:18.185580991Z app[web.1]:   from /tmp/crystal/share/crystal/src/io/buffered.cr:127:0 in 'write_byte'
2020-02-21T07:01:18.185605845Z app[web.1]:   from /tmp/crystal/share/crystal/src/http/web_socket/protocol.cr:123:12 in 'send'
2020-02-21T07:01:18.185616858Z app[web.1]:   from /tmp/build/lib/amber/src/amber/websockets/client_sockets.cr:15:17 in '->'
2020-02-21T07:01:18.185624217Z app[web.1]:   from /tmp/crystal/share/crystal/src/fiber.cr:255:3 in 'run'
2020-02-21T07:01:18.185631246Z app[web.1]:   from ???

Steps to Reproduce

I don't have exact steps for timing out the connection, but it looks like an IO::Error can be raised in the while block, I'm not sure if it's because the error trace doesn't specify the location within the while block or if it's really the first line. It looks odd to me that the connection is checked for a close then there's a sleep, then the .beat (write). That would give the connection a chance to close and still have a write.

edit: It looks like beat() has a rescue IO::Error, so I assume it isn't coming from beat() unless disconnect! can cause a write.

https://github.com/amberframework/amber/blob/master/src/amber/websockets/client_sockets.cr#L14 Here's the code, lines 14-18.

        spawn do
          while client_socket && !client_socket.socket.closed?
            sleep ClientSocket::BEAT_INTERVAL
            client_socket.beat
          end
        end

Expected behavior: IO::Error will not be raised.

Actual behavior: IO::Error is raised

Reproduces how often: It's a timing issue, but not too often. Maybe once per day per user?

Versions

0.33.0

Additional Information

I'm using Redis with the websocket.