Socket.io-client-swift: Socket stops pinging for unknown reason

[vincedev]

Hi, I'm facing an issue.
In my case this happens on macOS (didn't see similar behavior on iOS).

Although reconnection works for me, the connection with the server keeps being closed because the server didn't get the PING in time.
Logging produces this output :

2017-12-01 10:16:35.897967+0100 Application[19936:973300] LOG SocketEngine: Got message: 3
2017-12-01 10:16:37.882025+0100 Application[19936:973300] LOG SocketEngine: Writing ws: has data: false
2017-12-01 10:16:37.882136+0100 Application[19936:973300] LOG SocketEngineWebSocket: Sending ws: as type: 2
2017-12-01 10:16:37.897835+0100 Application[19936:973300] LOG SocketEngine: Got message: 3
2017-12-01 10:16:39.882151+0100 Application[19936:965577] LOG SocketEngine: Writing ws: has data: false
2017-12-01 10:16:39.882520+0100 Application[19936:965577] LOG SocketEngineWebSocket: Sending ws: as type: 2
2017-12-01 10:16:39.898686+0100 Application[19936:965577] LOG SocketEngine: Got message: 3
2017-12-01 10:16:41.882477+0100 Application[19936:965577] LOG SocketEngine: Writing ws: has data: false
2017-12-01 10:16:41.883000+0100 Application[19936:965577] LOG SocketEngineWebSocket: Sending ws: as type: 2
2017-12-01 10:16:41.907961+0100 Application[19936:973300] LOG SocketEngine: Got message: 3
2017-12-01 10:16:48.909072+0100 Application[19936:965578] ERROR SocketEngine:
2017-12-01 10:16:48.909941+0100 Application[19936:959424] ERROR SocketIOClient:
2017-12-01 10:16:48.910204+0100 Application[19936:959424] LOG SocketIOClient: Handling event: error with data: [""]
2017-12-01 10:16:48.911094+0100 Application[19936:959424] LOG SocketIOClient: Handling event: statusChange with data: [SocketIO.SocketIOClientStatus]
2017-12-01 10:16:48.911310+0100 Application[19936:959424] LOG SocketIOClient: Starting reconnect
2017-12-01 10:16:48.911715+0100 Application[19936:959424] LOG SocketIOClient: Handling event: reconnect with data: [""]
2017-12-01 10:16:48.912023+0100 Application[19936:959424] LOG SocketIOClient: Trying to reconnect
2017-12-01 10:16:48.912507+0100 Application[19936:959424] LOG SocketIOClient: Handling event: reconnectAttempt with data: [-1]
2017-12-01 10:16:48.915810+0100 Application[19936:959424] LOG SocketIOClient: Handling event: statusChange with data: [SocketIO.SocketIOClientStatus]
2017-12-01 10:16:48.920342+0100 Application[19936:974381] LOG SocketEngine: Starting engine. Server: http://host.fr.office:57570
2017-12-01 10:16:48.920816+0100 Application[19936:974381] LOG SocketEngine: Handshaking
// etc

The log says at some point an error is being triggered, but associated data contains an empty string, so I can't understand what's happening :

Handling event: error with data: [""]

I'm using version 12.1.3 of socket.io-client-swift, originally upgraded from 12.1.2 (same issue). I'm using default ping timeout options, ping every 2 seconds, timeout after 5 seconds, and the server promptly closes the connection.
This is highly reproducible, in experiments, within 1-2 minutes the error happens.

Any clue on this ? Can it be a timer somewhere that doesn't fire or something ?

[nuclearace]

I thought this would've been fixed in 12.1.3. You can try adding some prints to https://github.com/socketio/socket.io-client-swift/blob/master/Source/SocketIO/Engine/SocketEngine.swift#L515 to see why it stops pinging.

[vincedev]

@nuclearace : I did put some debug printing into sendPing() and here are my results.
While most of the time ping is sent in time, it happens that it delayed (sometimes for many seconds) :

2017-12-05 15:37:51 +0000: Sendind ping again...
2017-12-05 15:37:51 +0000:  sendPing()
2017-12-05 15:37:51 +0000: Checking pong missed...
2017-12-05 15:37:51 +0000: Writing ping....
2017-12-05 15:37:51 +0000: Scheduling new ping
2017-12-05 15:38:03 +0000: Sendind ping again...
2017-12-05 15:38:03 +0000:  sendPing()
2017-12-05 15:38:03 +0000: Checking pong missed...
2017-12-05 15:38:03 +0000: Writing ping....
2017-12-05 15:38:03 +0000: Scheduling new ping
2017-12-05 15:38:05 +0000: Sendind ping again...
2017-12-05 15:38:05 +0000:  sendPing()
2017-12-05 15:38:05 +0000: Checking pong missed...
2017-12-05 15:38:05 +0000: Writing ping....
2017-12-05 15:38:05 +0000: Scheduling new ping
2017-12-05 15:38:07 +0000: Sendind ping again...
2017-12-05 15:38:07 +0000:  sendPing()
2017-12-05 15:38:07 +0000: Checking pong missed...
2017-12-05 15:38:07 +0000: Writing ping....
2017-12-05 15:38:07 +0000: Scheduling new ping
2017-12-05 15:38:14 +0000: Sendind ping again...
2017-12-05 15:38:14 +0000:  sendPing()
2017-12-05 15:38:14 +0000: Checking pong missed...
2017-12-05 15:38:14 +0000: Writing ping....
2017-12-05 15:38:14 +0000: Scheduling new ping

I clearly see delays like 12 seconds, or 7 seconds...
So our server uses small timeout, ping every 2 seconds, timeout after 5 seconds..

I can't see clearly why pings are delayed like this, can it be the engineQueue is busy in any way ?
Would using a separate queue resolve the problem ? 🤔

[nuclearace]

I don't know why the engine queue would be delayed so much... If we have to use a new queue it'll get more complicated since you'll need to add locking.

[vincedev]

@nuclearace I did put together a minimal server, and minimal application to try to replicate the problem.

Please check out both server and app in attachements.
Running the sample app for about 20 min I have been disconnected two times due to ping timeout.

SocketIOPing.zip
server.js.zip

Please note that on server-side I use v1.4.5 of socket.io which is the version running on our servers, and both app and server are running locally on my machine.

Here's what I have in Xcode console :

2017-12-07 10:06:33.459763+0100 SocketIOPing[1772:7747144] LOG SocketIOClient{/}: Handling event: ping with data: []
2017-12-07 10:06:33.462170+0100 SocketIOPing[1772:7747144] LOG SocketIOClient{/}: Handling event: pong with data: []
2017-12-07 10:06:35.458844+0100 SocketIOPing[1772:7747144] LOG SocketIOClient{/}: Handling event: ping with data: []
2017-12-07 10:06:35.460793+0100 SocketIOPing[1772:7747144] LOG SocketIOClient{/}: Handling event: pong with data: []
2017-12-07 10:06:37.458942+0100 SocketIOPing[1772:7747144] LOG SocketIOClient{/}: Handling event: ping with data: []
2017-12-07 10:06:37.461110+0100 SocketIOPing[1772:7747144] LOG SocketIOClient{/}: Handling event: pong with data: []
2017-12-07 10:06:44.462269+0100 SocketIOPing[1772:7747144] LOG SocketIOClient{/}: Handling event: error with data: [""]
2017-12-07 10:06:44.462633+0100 SocketIOPing[1772:7747144] LOG SocketIOClient{/}: Handling event: statusChange with data: [connecting]
2017-12-07 10:06:44.462726+0100 SocketIOPing[1772:7747144] LOG SocketIOClient{/}: Handling event: reconnect with data: [""]
2017-12-07 10:06:44.462962+0100 SocketIOPing[1772:7747144] LOG SocketIOClient{/}: Handling event: reconnectAttempt with data: [-1]
2017-12-07 10:06:44.509604+0100 SocketIOPing[1772:7747144] LOG SocketIOClient{/}: Handling event: ping with data: []
2017-12-07 10:06:44.509941+0100 SocketIOPing[1772:7747144] LOG SocketIOClient{/}: Handling event: statusChange with data: [connected]
2017-12-07 10:06:44.510375+0100 SocketIOPing[1772:7747144] LOG SocketIOClient{/}: Handling event: connect with data: ["/"]
2017-12-07 10:06:44.524403+0100 SocketIOPing[1772:7747144] LOG SocketIOClient{/}: Handling event: news with data: [{
2017-12-07 10:06:44.528518+0100 SocketIOPing[1772:7747144] LOG SocketIOClient{/}: Handling event: pong with data: []
2017-12-07 10:06:44.700578+0100 SocketIOPing[1772:7747144] LOG SocketIOClient{/}: Handling event: pong with data: []
2017-12-07 10:06:46.509943+0100 SocketIOPing[1772:7747144] LOG SocketIOClient{/}: Handling event: ping with data: []
2017-12-07 10:06:46.512049+0100 SocketIOPing[1772:7747144] LOG SocketIOClient{/}: Handling event: pong with data: []
2017-12-07 10:06:52.981487+0100 SocketIOPing[1772:7747144] LOG SocketIOClient{/}: Handling event: ping with data: []
2017-12-07 10:06:52.984617+0100 SocketIOPing[1772:7747144] LOG SocketIOClient{/}: Handling event: pong with data: []
....
....
2017-12-07 10:14:31.850652+0100 SocketIOPing[1772:7747144] LOG SocketIOClient{/}: Handling event: ping with data: []
2017-12-07 10:14:31.853581+0100 SocketIOPing[1772:7747144] LOG SocketIOClient{/}: Handling event: pong with data: []
2017-12-07 10:14:38.859349+0100 SocketIOPing[1772:7747144] LOG SocketIOClient{/}: Handling event: error with data: [""]
2017-12-07 10:14:38.859768+0100 SocketIOPing[1772:7747144] LOG SocketIOClient{/}: Handling event: statusChange with data: [connecting]
2017-12-07 10:14:38.859837+0100 SocketIOPing[1772:7747144] LOG SocketIOClient{/}: Handling event: reconnect with data: [""]
2017-12-07 10:14:38.859931+0100 SocketIOPing[1772:7747144] LOG SocketIOClient{/}: Handling event: reconnectAttempt with data: [-1]
2017-12-07 10:14:38.902743+0100 SocketIOPing[1772:7747144] LOG SocketIOClient{/}: Handling event: ping with data: []
2017-12-07 10:14:38.902968+0100 SocketIOPing[1772:7747144] LOG SocketIOClient{/}: Handling event: statusChange with data: [connected]
2017-12-07 10:14:38.903043+0100 SocketIOPing[1772:7747144] LOG SocketIOClient{/}: Handling event: connect with data: ["/"]
2017-12-07 10:14:38.926976+0100 SocketIOPing[1772:7747144] LOG SocketIOClient{/}: Handling event: news with data: [{
2017-12-07 10:14:38.930436+0100 SocketIOPing[1772:7747144] LOG SocketIOClient{/}: Handling event: pong with data: []
2017-12-07 10:14:39.151074+0100 SocketIOPing[1772:7747144] LOG SocketIOClient{/}: Handling event: pong with data: []
2017-12-07 10:14:40.903124+0100 SocketIOPing[1772:7747144] LOG SocketIOClient{/}: Handling event: ping with data: []

[nuclearace]

@vincedev Well first off, if you're using socket.io 1.0 and anything higher than 9.0 on the client, you have a version mismatch. Anything past 9.0 is for 2.0.

[vincedev]

@nuclearace Oh well didn't realize that, thanks for telling me that.

[nuclearace]

I don't think it would cause this issue though. The most visible breaking change has to do with how unicode is handled.

[vincedev]

There are a bunch of fixes, but indeed didn't notice anything regarding ping or pong

[nuclearace]

I would still recommend updating to 2.0 though. It's not much lift on the server-side.

[vincedev]

Alright, I'll update socket.io version on server and post back the results, probably tomorrow when I get time.

[vincedev]

Same behavior with latest socket.io on server side, but at least I now get a valuable error string :

Handling event: error with data: ["connection closed by server"]

[vincedev]

@nuclearace I wonder if you replicated this behavior using the samples I uploaded ?

[vincedev]

@nuclearace : Hi, can you confirm you reproduce the bug using the sample I provided. I didn't hear from you for 13 days on this, still the issue has a "unconfirmed" label, so maybe it's time to confirm the bug, or close this issue ?

[nuclearace]

@vincedev Sorry, I've been busy with work related things and have just now gotten around to looking at it. I haven't been able to reproduce, but I will say that such short ping times are far from the default socket.io ping times. (Ping every 25 seconds, timeout after 60.)

I've tried lowering the ping interval down to a second and haven't seen a timeout yet after ~20 minutes. So my guess is it could be tied to either how busy the engine queue gets (should be uncommon since the engine queue should be fast) or how busy the system is (highly unlikely on modern systems.)

(Note this was testing on the latest version)

[psykotox]

Hello,

I have the same problem on my Mac with the SocketIOPing of vincedev and the latest socket.io server v2.0.4 (nodejs 9.3.0).
If I increase the timeout the problem doesn't disappear, it happens less often but he's still here.
The ping frequency is not respected and this is critical for the stability of the connection.
Increasing the timeout to a higher value only hides the problem.

How are you trying to replicate the problem ? With which version of each component ? It's really weird, several people I work with have tested on different Macs and they all have the problem...

[nuclearace]

Okay, now I'm able to reproduce when I use an actual app. When I just ran a bare bones run loop I wasn't able to reproduce.

[nuclearace]

Switching to a dispatch timer doesn't seem to solve the issue either.

[vincedev]

@nuclearace : good to know 👍

I've been trying to debug a little, and I admit it's hard to know what's happening on the queue.

What I can tell is the problem isn't related to network latency or so (I reproduce the issue on my machine running both server and client, as well as on a local network).

I did try to ping the server manually, writing something through the socket, using a timer but at some point it was blocked (I imagine for the same reason the [socket.io] ping doesn't get fired).
I'll go further in debugging and post back if I find something.

[nuclearace]

@vincedev I may have figured it out. I think it's AppNap thinking there's nothing meaningful going on, maybe because there's no UI updates being done? So it lowers the priority of the app's queueing and throttles the timers.

[nuclearace]

When I add some

let activity = ProcessInfo.processInfo.beginActivity(options: .userInitiated, reason: "some reason")

Inside the app, it seems to not timeout. Although that's probably not the best solution.

[nuclearace]

https://developer.apple.com/library/content/documentation/Performance/Conceptual/power_efficiency_guidelines_osx/AppNap.html

[vincedev]

@nuclearace

Good catch! When I think I was trying to debug some kind of lock mess somewhere 😆 ...
I tried this by my side and could not trigger any timeout, so this definitely is the way to go I think..

that's probably not the best solution

Maybe not, but as far as I can tell, isn't it the _only_ solution ?
After all, the app starts communicating with a server and must maintain the communication so we need a way to tell the OS, and prevent it from considering the app does nothing.

I also was looking for an Info.plist flag to add, but could not find it so far..

Considering this API is the way to go (it is for me now without anything else), do you think it's the app responsibility to call it, or the library should go ahead and call it at appropriate time ?

[nuclearace]

It should be the app's responsibility I think.