IOError on sending PONG

[xarg]

We're getting quite a lot of these errors (about 2k/month): https://sentry.io/share/issue/06b32b9f853a4d4abc4f664a0734347a/

OSError: Socket is closed
  File "engineio/socket.py", line 210, in _websocket_handler
    self.receive(pkt)
  File "engineio/socket.py", line 54, in receive
    self.send(packet.Packet(packet.PONG, pkt.data))
  File "engineio/socket.py", line 68, in send
    raise IOError('Socket is closed')

It looks like this happens when the socket is closed between the client PING and the server PONG. I'm not 100% why this happens, I'd say that the clients disconnect in between PING and PONG and thus that error is thrown.

A possible solution here is to ignore it for PONG in particular since it's clear that it's not possible to send a reply which is the whole point of this PONG - but this is only based on my assumption that it is caused by client disconnects.

[miguelgrinberg]

Are you running with Socket.IO logging enabled? That should indicate if there are disconnects.

[8BitJosh]

emitting event "playlistList" to all [/main]
Receive error
Traceback (most recent call last):
  File "/usr/lib/python3.6/site-packages/engineio/asyncio_socket.py", line 198, in _websocket_handler
    await self.receive(pkt)
  File "/usr/lib/python3.6/site-packages/engineio/asyncio_socket.py", line 40, in receive
    await self.send(packet.Packet(packet.PONG, pkt.data))
  File "/usr/lib/python3.6/site-packages/engineio/asyncio_socket.py", line 55, in send
    raise IOError('Socket is closed')
OSError: Socket is closed
received event "sendAll" from f8f73ff9a8d14d8dbe05a4e1faef86ee [/main]

I get the same issue with my program. As shown with the logger enabled no disconnects are printed in the console when the error occurs

[miguelgrinberg]

@8BitJosh add engineio_logger=True to your SocketIO class to have more detailed logging please.

[8BitJosh]

emitting event "playlistList" to all [/main]
0c777092efda4ea187c3d52497eb517d: Sending packet MESSAGE data 2/main,["playlistList",{}]
1668a11a4754485c9afec096b55b48bb: Received packet PING data None
Receive error
Traceback (most recent call last):
  File "/usr/lib/python3.6/site-packages/engineio/asyncio_socket.py", line 198, in _websocket_handler
    await self.receive(pkt)
  File "/usr/lib/python3.6/site-packages/engineio/asyncio_socket.py", line 40, in receive
    await self.send(packet.Packet(packet.PONG, pkt.data))
  File "/usr/lib/python3.6/site-packages/engineio/asyncio_socket.py", line 55, in send
    raise IOError('Socket is closed')
OSError: Socket is closed
0c777092efda4ea187c3d52497eb517d: Received packet PING data None
0c777092efda4ea187c3d52497eb517d: Sending packet PONG data None
0c777092efda4ea187c3d52497eb517d: Received packet MESSAGE data 2/main,["sendAll"]
received event "sendAll" from 0c777092efda4ea187c3d52497eb517d [/main]

Here is the error with the logger enabled. There are two devices connected to the webpage as you can see one PING/PONG creates an error on the reply. The second one does not

[miguelgrinberg]

@8BitJosh I need the complete log, starting from the time the device that shows the problem connected to the server. Also, are you by any chance changing the default ping/pong interval timeouts?

[8BitJosh]

Here is the Full log. The error occurs at about line 240
CMDlog.LOG

I have the interval timeouts all set to the default values

[miguelgrinberg]

Did you notice the "client is gone" message a few lines above the error? That means that the server did not receive a PING packet in more than the "ping timeout" period which is one minute.

If you look at all the PING packets in your log, you'll notice there is a cadence to them. Except that a little bit before the error the pings stop appearing. As a result of the missing PINGs, the server closed the socket. But then a PING does finally arrive, but by that time it is too late, since the socket is closed.

What client are you using? Is there a way to log from that side to see if there is anything that might be delaying the pings?

[8BitJosh]

From what i can tell the errors mainly occur when connecting from mobile devices and happens if you leave the browser open and lock the phone. The pings keep on coming from the device after it is locked but then that error will randomly occur after some time.

I dont know whether the phone puts the browser in a low power state to preserve power which causes delays in the ping taking place.

As it is a locked mobile device i dont think there is anyway of logging on the device what is happening

(This is tested with both firefox and chrome on an android phone and both create this error)

[miguelgrinberg]

@8BitJosh It's odd that your mobile client appears to still be sending application events, even after the pings were suspended. The browser must be making some sort of distinction between the main thread of the app versus the background threads that handling things such as pings.

So is this a problem? If the phone stops sending pings then the server will close the connection, and once the phone wakes up it will reconnect. I think I'm going to suppress the stack trace for this error, since it isn't providing any useful information, but other than that I'm not sure what else I can do to handle this better.

[xarg]

+1 for suppressing this error. I don't think there can be done anything here.

[8BitJosh]

I think just suppressing this error would be best solution

[miguelgrinberg]

@xarg were your clients also mobile browsers?

[xarg]

I don't know, we don't have that many mobile users.