Connection drops suddenly and is unable to recover

[Popeyef5]

I have a simple raspberry pi hosting a dockerized fastapi really simple server to which only one client connects. This other client is itself a fastapi app. Every so often, the connection drops. Upon inspecting the logs generated by running both client and server with engineio_logs=True, it would appear that while the socketio part goes down, the underlying engineio websocket is still alive and sending pings and pongs back and forth. The problem is that this becomes the perpetual state of the connection, no reconnects are attempted.

When trying to emit from the client to the server, I get "/" is not a connected namespace.

During the re-connection procedure, at some point the server sends "Unable to connect". I've somewhat tried to trace back the error, and it appears that when the server is handling the new connection attempt, sid is None. This can be due to some weird namespace issue, which would be strange because I haven't touched anything and I'm using the default one, or the manager is returning None on this bit

       try:
            self.basic_enter_room(sid, namespace, None, eio_sid=eio_sid)
       except ValueDuplicationError:
            # already connected
            return None

as if the client was already connected.

These are the log extracts from the client:

claw_fastapi  | Received packet PING data 
claw_fastapi  | INFO:engineio.client:Received packet PING data 
claw_fastapi  | Sending packet PONG data 
claw_fastapi  | INFO:engineio.client:Sending packet PONG data 
claw_fastapi  | packet queue is empty, aborting
claw_fastapi  | ERROR:engineio.client:packet queue is empty, aborting
claw_fastapi  | Exiting write loop task
claw_fastapi  | INFO:engineio.client:Exiting write loop task
claw_fastapi  | Server has stopped communicating, aborting
claw_fastapi  | WARNING:engineio.client:Server has stopped communicating, aborting
claw_fastapi  | Waiting for write loop task to end
claw_fastapi  | INFO:engineio.client:Waiting for write loop task to end
claw_fastapi  | INFO:claw:[PI STATUS] connected=False namespace_ok=False
claw_fastapi  | WARNING:claw:Pi socket DISCONNECTED because of: transport error – will retry...
claw_fastapi  | Exiting read loop task
claw_fastapi  | INFO:engineio.client:Exiting read loop task
claw_fastapi  | Attempting WebSocket connection to wss://url.ngrok.app/socket.io/?transport=websocket&EIO=4
claw_fastapi  | INFO:engineio.client:Attempting WebSocket connection to wss://url.ngrok.app/socket.io/?transport=websocket&EIO=4
claw_fastapi  | WebSocket connection accepted with {'sid': '3MvawFfWQesmEof2AAAU', 'upgrades': [], 'pingTimeout': 50000, 'pingInterval': 60000, 'maxPayload': 1000000}
claw_fastapi  | INFO:engineio.client:WebSocket connection accepted with {'sid': '3MvawFfWQesmEof2AAAU', 'upgrades': [], 'pingTimeout': 50000, 'pingInterval': 60000, 'maxPayload': 1000000}
claw_fastapi  | Sending packet MESSAGE data 0{}
claw_fastapi  | INFO:engineio.client:Sending packet MESSAGE data 0{}
claw_fastapi  | Exiting write loop task
claw_fastapi  | INFO:engineio.client:Exiting write loop task
claw_fastapi  | Sending packet CLOSE data None
claw_fastapi  | INFO:engineio.client:Sending packet CLOSE data None
claw_fastapi  | Server sent close packet data None, aborting
claw_fastapi  | WARNING:engineio.client:Server sent close packet data None, aborting
claw_fastapi  | Waiting for write loop task to end
claw_fastapi  | INFO:engineio.client:Waiting for write loop task to end
claw_fastapi  | Exiting read loop task
claw_fastapi  | INFO:engineio.client:Exiting read loop task
claw_fastapi  | Attempting WebSocket connection to wss://url.ngrok.app/socket.io/?transport=websocket&EIO=4
claw_fastapi  | INFO:engineio.client:Attempting WebSocket connection to wss://url.ngrok.app/socket.io/?transport=websocket&EIO=4
claw_fastapi  | WebSocket connection accepted with {'sid': '5H91k3-2M_OUfwemAAAV', 'upgrades': [], 'pingTimeout': 50000, 'pingInterval': 60000, 'maxPayload': 1000000}
claw_fastapi  | INFO:engineio.client:WebSocket connection accepted with {'sid': '5H91k3-2M_OUfwemAAAV', 'upgrades': [], 'pingTimeout': 50000, 'pingInterval': 60000, 'maxPayload': 1000000}
claw_fastapi  | Sending packet MESSAGE data 0{}
claw_fastapi  | INFO:engineio.client:Sending packet MESSAGE data 0{}
claw_fastapi  | Exiting write loop task
claw_fastapi  | INFO:engineio.client:Exiting write loop task
claw_fastapi  | Received packet MESSAGE data 0{"sid":"9gyZhiHl0Oo9Pe9XAAAW"}
claw_fastapi  | INFO:engineio.client:Received packet MESSAGE data 0{"sid":"9gyZhiHl0Oo9Pe9XAAAW"}
claw_fastapi  | INFO:claw:[PI STATUS] connected=True namespace_ok=True
claw_fastapi  | INFO:claw:Pi socket CONNECTED (reconnect OK)
claw_fastapi  | INFO:claw:Connected namespaces: {'/': '9gyZhiHl0Oo9Pe9XAAAW'}
claw_fastapi  | Server has stopped communicating, aborting
claw_fastapi  | WARNING:engineio.client:Server has stopped communicating, aborting
claw_fastapi  | Waiting for write loop task to end
claw_fastapi  | INFO:engineio.client:Waiting for write loop task to end
claw_fastapi  | INFO:claw:[PI STATUS] connected=False namespace_ok=False
claw_fastapi  | WARNING:claw:Pi socket DISCONNECTED because of: transport error – will retry...
claw_fastapi  | Exiting read loop task
claw_fastapi  | INFO:engineio.client:Exiting read loop task
claw_fastapi  | Attempting WebSocket connection to wss://url.ngrok.app/socket.io/?transport=websocket&EIO=4
claw_fastapi  | INFO:engineio.client:Attempting WebSocket connection to wss://url.ngrok.app/socket.io/?transport=websocket&EIO=4
claw_fastapi  | WebSocket connection accepted with {'sid': 'fQx7bwjmlyCvruKRAAAX', 'upgrades': [], 'pingTimeout': 50000, 'pingInterval': 60000, 'maxPayload': 1000000}
claw_fastapi  | INFO:engineio.client:WebSocket connection accepted with {'sid': 'fQx7bwjmlyCvruKRAAAX', 'upgrades': [], 'pingTimeout': 50000, 'pingInterval': 60000, 'maxPayload': 1000000}
claw_fastapi  | Sending packet MESSAGE data 0{}
claw_fastapi  | INFO:engineio.client:Sending packet MESSAGE data 0{}
claw_fastapi  | Received packet MESSAGE data 0{"sid":"pVPPxMt_pwRSvIS_AAAY"}
claw_fastapi  | INFO:engineio.client:Received packet MESSAGE data 0{"sid":"pVPPxMt_pwRSvIS_AAAY"}
claw_fastapi  | INFO:claw:[PI STATUS] connected=True namespace_ok=True
claw_fastapi  | Received packet MESSAGE data 4"Unable to connect"
claw_fastapi  | INFO:engineio.client:Received packet MESSAGE data 4"Unable to connect"
claw_fastapi  | INFO:claw:Pi socket CONNECTED (reconnect OK)
claw_fastapi  | INFO:claw:Connected namespaces: {'/': 'pVPPxMt_pwRSvIS_AAAY'}
claw_fastapi  | INFO:claw:[PI STATUS] connected=False namespace_ok=False
claw_fastapi  | WARNING:claw:Pi socket CONNECTION FAILED because of: Unable to connect
claw_fastapi  | Received packet PING data 
claw_fastapi  | INFO:engineio.client:Received packet PING data 
claw_fastapi  | Sending packet PONG data 
claw_fastapi  | INFO:engineio.client:Sending packet PONG data 
claw_fastapi  | Received packet PING data 
claw_fastapi  | INFO:engineio.client:Received packet PING data 
claw_fastapi  | Sending packet PONG data 
claw_fastapi  | INFO:engineio.client:Sending packet PONG data 
claw_fastapi  | Received packet PING data 
claw_fastapi  | INFO:engineio.client:Received packet PING data 
claw_fastapi  | Sending packet PONG data 
claw_fastapi  | INFO:engineio.client:Sending packet PONG data 

Happy to provide any more context or anything useful.

As a side note, I don't know if this is relevant, but I increased the ping_interval and ping_timeout to around 60s each and this was mitigated, although it does continue to happen.

[miguelgrinberg]

This messages:

packet queue is empty, aborting
Server has stopped communicating, aborting

indicate that the server is not sending PINGs at the expected interval. The most common reason why this happens is that you are blocking the async loop for too long, so the server task that sends these pings does not get a chance to run. Possible?

[Popeyef5]

Sorry, I got caught up with work. I did in fact have a synchronous method which should be async, but I wouldn't expect that to be the issue because the total running time of it was pretty minute, and the disconnection happend while the server was idle (only pings and pongs). I have made the corresponding changes and will report back if the error persists.

[Popeyef5]

Yes, that's what I meant in my last post: I didn't mean the pings, but the packages I highlighted which are the ones you refer in your last reply.

I'll drop ngrok and see what happens. But just as a follow-up: I know this might be an edge case, but don't you think that in this case either

1. the client should drop all connection, possibly including the base engineio connection, and re-attempt to connect?
   or
2. the error message should say that the namespace is already connected, so the client instead of stalemating in this error configuration simply carries on with the connection?

It's the fact that this situation is a final equilibrium that bugs me a bit. Would love to know what you think. Of course, this might be too much of an edge case to care about it, but ngrok is a reasonably popular service. In any case, I'll attempt without it and get back here.

[miguelgrinberg]

I really don't see how this would help you though. Let's assume we put a fix for the second problem and the connection is retried. Wouldn't it end up in a constant retry cycle? The first issue is going to reoccur. Sounds like you have no trouble getting it to reproduce.

In my view this is very low priority, because it addresses a case in which there is a misbehaving participant, either the client, the server or the network in between them.

[Popeyef5]

I can get the connection to work when I restart the server service. The connection works just fine for a certrain amount of time, usually several hours. When the error occurs, it stays in this state permanently. I'm not sure that the duplicate messages occur every time, the initial successful connection being proof, so if the connection dropped completely and attempted to reconnect from zero, I think it would resolve itself. It would probably reoccur every few hours, but it would resolve itself quickly rather than stagnating in an error state.

Likewise, if on a connection attempt to an already connected namespace the server reported this fact to the client, maybe the client should acknowledge this and do nothing instead of dropping the connection since it's already there? I'm not sure.

[Popeyef5]

What I mean is that, in my current view, this seems to be a bug in the "auto_reconnect" feature, where there is a connection error and it stays there instead of trying to reconnect like it does with other errors.

Irrespective of the source of the error, the client having received a connection error message, shouldn't it attempt to reconnect?

[miguelgrinberg]

When the error occurs, it stays in this state permanently.

Yes, this is because the duplicated message is disconnecting only the Socket.IO side. In a real disconnect the server would disconnect all the namespaces first, then it would disconnect the Engine.IO layer as well.

Irrespective of the source of the error, the client having received a connection error message, shouldn't it attempt to reconnect?

No. This error is for a namespace. It is a logical connection error. It does not indicate a failure, just that the server does not want the client to connect. It's not supposed to be retried, as far as I understand the Socket.IO protocol. The errors that are retried are the disconnections at the Engine.IO layer, which are the "hard" failures.

What I really think is concerning is that if I were to agree to implement a fix that covers this specific duplicated message, eventually you are going to see some other message getting duplicated and generating another unexpected situation. If we can agree that ngrok is causing this, then the ultimate solution is to use a better proxy than ngrok. I don't think it makes sense to start adding patches in the server or the client to account for unexpected packets received at unexpected times. As I said before, the assumption is that all the parties are reliable. If I have to also consider unreliable networks, or unreliable clients or servers, then there's a lot of things that can go wrong, not just this one that you've seen.