In trying to reproduce errors from a larger project I have created a server using python's aiohttp and the following python-socketio (v5.12.0) namespace:
class MyNamespace(AsyncNamespace):
clients = []
async def on_connect(self, sid, _environ, auth):
print(f"{sid} has connected")
self.clients.append(sid)
async def on_disconnect(self, sid, reason):
print(f"{sid} has disconnected ({reason})")
try:
self.clients.remove(sid)
except ValueError:
pass
async def on_poll(self, sid, _data):
"""Return random number"""
rand = random.randint(0, 9)
await self.emit("result", {"data": rand}, to=sid)
The client is running the following JS, making use of https://cdn.socket.io/4.5.0/socket.io.min.js :
const sio = io("/", {});
setInterval(function() {
console.log("polling server...")
sio.emit("poll", {});
}, 5000);
sio.on("result", (data) => {
console.log(data);
});
This works, at least initially, as this is what we see in the browser console:
[09:13:49] connected!
[09:13:54] polling server...
[09:13:54] got 7
[09:13:59] polling server...
[09:13:59] got 2
[09:14:04] polling server...
[09:14:04] got 0
[09:14:09] polling server...
[09:14:14] polling server... # Something's gone wrong!
[09:14:19] polling server...
[09:14:24] polling server...
[09:14:29] polling server...
[09:14:29] connected! # Did we disconnect?
[09:14:29] got 6 # We're back?
[09:14:34] polling server...
[09:14:34] got 0
...
Given the precise 30 second delay after which it failed, a quick google suggested that the problem was version (in)compatability, but this table clearly indicates that my versions are compatible.
On instruction from further googling, I added some more logging to the server side code. The following is the contnet of the server logs over more or less the same time interval:
Apr 27 09:13:46 raspberrypi start-server[250784]: Server running...
Apr 27 09:13:50 raspberrypi start-server[250784]: YQoJ9GLsXolsywhqAAAA: Sending packet OPEN data {'sid': 'YQoJ9GLsXolsywhqAAAA', 'upgrades': ['websocket'], 'pingTimeout': 20000, 'pingInterval': 25000, 'maxPayload': 1000000}
Apr 27 09:13:51 raspberrypi start-server[250784]: YQoJ9GLsXolsywhqAAAA: Received packet MESSAGE data 0/,
Apr 27 09:13:51 raspberrypi start-server[250784]: VVvlt4tqCS-5BMuqAAAB has connected
Apr 27 09:13:51 raspberrypi start-server[250784]: YQoJ9GLsXolsywhqAAAA: Sending packet MESSAGE data 0/,{"sid":"VVvlt4tqCS-5BMuqAAAB"}
Apr 27 09:13:51 raspberrypi start-server[250784]: YQoJ9GLsXolsywhqAAAA: Received request to upgrade to websocket
Apr 27 09:13:51 raspberrypi start-server[250784]: YQoJ9GLsXolsywhqAAAA: Upgrade to websocket successful
Apr 27 09:13:56 raspberrypi start-server[250784]: YQoJ9GLsXolsywhqAAAA: Received packet MESSAGE data 2/,["poll",{}]
Apr 27 09:13:56 raspberrypi start-server[250784]: received event "poll" from VVvlt4tqCS-5BMuqAAAB [/]
Apr 27 09:13:56 raspberrypi start-server[250784]: Sending 7 to VVvlt4tqCS-5BMuqAAAB
Apr 27 09:13:56 raspberrypi start-server[250784]: emitting event "result" to VVvlt4tqCS-5BMuqAAAB [/]
Apr 27 09:13:56 raspberrypi start-server[250784]: YQoJ9GLsXolsywhqAAAA: Sending packet MESSAGE data 2/,["result",{"value":7}]
Apr 27 09:14:00 raspberrypi start-server[250784]: YQoJ9GLsXolsywhqAAAA: Received packet MESSAGE data 2/,["poll",{}]
Apr 27 09:14:00 raspberrypi start-server[250784]: received event "poll" from VVvlt4tqCS-5BMuqAAAB [/]
Apr 27 09:14:00 raspberrypi start-server[250784]: Sending 2 to VVvlt4tqCS-5BMuqAAAB
Apr 27 09:14:00 raspberrypi start-server[250784]: emitting event "result" to VVvlt4tqCS-5BMuqAAAB [/]
Apr 27 09:14:00 raspberrypi start-server[250784]: YQoJ9GLsXolsywhqAAAA: Sending packet MESSAGE data 2/,["result",{"value":2}]
Apr 27 09:14:05 raspberrypi start-server[250784]: YQoJ9GLsXolsywhqAAAA: Received packet MESSAGE data 2/,["poll",{}]
Apr 27 09:14:05 raspberrypi start-server[250784]: received event "poll" from VVvlt4tqCS-5BMuqAAAB [/]
Apr 27 09:14:05 raspberrypi start-server[250784]: Sending 0 to VVvlt4tqCS-5BMuqAAAB
Apr 27 09:14:05 raspberrypi start-server[250784]: emitting event "result" to VVvlt4tqCS-5BMuqAAAB [/]
Apr 27 09:14:05 raspberrypi start-server[250784]: YQoJ9GLsXolsywhqAAAA: Sending packet MESSAGE data 2/,["result",{"value":0}]
Apr 27 09:14:15 raspberrypi start-server[250784]: YQoJ9GLsXolsywhqAAAA: Sending packet PING data None
Apr 27 09:14:30 raspberrypi start-server[250784]: 7aB5pFuYnarQTTCRAAAC: Sending packet OPEN data {'sid': '7aB5pFuYnarQTTCRAAAC', 'upgrades': ['websocket'], 'pingTimeout': 20000, 'pingInterval': 25000, 'maxPayload': 1000000}
So it seemingly sends the expected ping packet after the pingInterval of 25s, but presumably the client died, then it reconnects after the pingTimeout - but I'm not sure why this is 15s after the last ping.
In researching this error, I've heard other saying that browsers can close connections on inactive tabs. But in this case the tab clearly isn't inactive - it's polling every 5 seconds! Nor was it minimised in this testing.
I'm at a loss of why this is failing. I can't see any record that the client recieves the ping packet.
The socket.io troubleshooting guide suggests that one possible problem is "A proxy in front of your servers does not accept the WebSocket connection", and I am proxying through Cloudflare... but it clearly works initially, so I don't think that's the issue. The guide also makes it clear that "disconnections are common and expected". So, if that is the case, should I redesign this code to work under this assumption? If I have const sio = io(...) within the polling loop, it seems to work indefinitely, which is fine for this client, but I want other clients to be listening for result events too, and it's not clear how I can just maintain a connection like that.
RetroSearch is an open source project built by @garambo | Open a GitHub Issue
Search and Browse the WWW like it's 1997 | Search results from DuckDuckGo
HTML:
3.2
| Encoding:
UTF-8
| Version:
0.7.4