Socket.io: transport close - ping has not timeout

[tady21cn]

Note: for support questions, please use one of these channels: stackoverflow or slack

You want to:

• [x] report a bug
• [ ] request a feature

Current behaviour

socket.io will occur "transport close" when i use the internet proxy software.
I want to know the root cause, so open DEBUG model on client and server sides, still no answer after check the log.

remark : the option of client reconnect is closed.

I guessed that:

1. The part of data packets are lossing
2. Heartbeat is timeout(i have tried increase the timeout of by the options "pingTimeout" and "pingInterval", but it seems that the effect is not obvious)

server log:
Tue, 06 Mar 2018 10:00:39 GMT socket.io:socket got packet {"type":2,"nsp":"/","data":["message",{"message_id":"msg_sync_mouse_1520330439192","client_id":"p-VZ_JZeeBABWZwYAAAB","type":"sync_mouse","initiator":"5a379898f329915fd2470d72","data":{"user_id":"5a379898f329915fd2470d72","meeting_id":"5a72ba31f329910992b98de0","x":402,"y":-13,"cursor":"default"}}]} Tue, 06 Mar 2018 10:00:39 GMT socket.io:socket emitting event ["message",{"message_id":"msg_sync_mouse_1520330439192","client_id":"p-VZ_JZeeBABWZwYAAAB","type":"sync_mouse","initiator":"5a379898f329915fd2470d72","data":{"user_id":"5a379898f329915fd2470d72","meeting_id":"5a72ba31f329910992b98de0","x":402,"y":-13,"cursor":"default"}}] Tue, 06 Mar 2018 10:00:39 GMT socket.io:socket dispatching an event ["message",{"message_id":"msg_sync_mouse_1520330439192","client_id":"p-VZ_JZeeBABWZwYAAAB","type":"sync_mouse","initiator":"5a379898f329915fd2470d72","data":{"user_id":"5a379898f329915fd2470d72","meeting_id":"5a72ba31f329910992b98de0","x":402,"y":-13,"cursor":"default"}}] Tue, 06 Mar 2018 10:00:39 GMT socket.io:client client close with reason transport close Tue, 06 Mar 2018 10:00:39 GMT socket.io:socket closing socket - reason transport close Tue, 06 Mar 2018 10:00:39 GMT socket.io:socket leave room 5a72ba31f329910992b98de0 Tue, 06 Mar 2018 10:00:39 GMT socket.io:socket left room 5a72ba31f329910992b98de0

client log:
browser.js:133 engine.io-client:socket flushing 1 packets in socket +15ms 18:00:39.425 browser.js:123 socket.io-client:manager writing packet {"type":2,"data":["message",{"message_id":"msg_sync_mouse_1520330439426","client_id":"p-VZ_JZeeBABWZwYAAAB","type":"sync_mouse","initiator":"5a379898f329915fd2470d72","data":{"user_id":"5a379898f329915fd2470d72","meeting_id":"5a72ba31f329910992b98de0","x":439,"y":62,"cursor":"default"}}],"options":{"compress":true},"nsp":"/"} +18ms 18:00:39.425 browser.js:133 socket.io-parser encoding packet {"type":2,"data":["message",{"message_id":"msg_sync_mouse_1520330439426","client_id":"p-VZ_JZeeBABWZwYAAAB","type":"sync_mouse","initiator":"5a379898f329915fd2470d72","data":{"user_id":"5a379898f329915fd2470d72","meeting_id":"5a72ba31f329910992b98de0","x":439,"y":62,"cursor":"default"}}],"options":{"compress":true},"nsp":"/"} +17ms 18:00:39.426 browser.js:133 socket.io-parser encoded {"type":2,"data":["message",{"message_id":"msg_sync_mouse_1520330439426","client_id":"p-VZ_JZeeBABWZwYAAAB","type":"sync_mouse","initiator":"5a379898f329915fd2470d72","data":{"user_id":"5a379898f329915fd2470d72","meeting_id":"5a72ba31f329910992b98de0","x":439,"y":62,"cursor":"default"}}],"options":{"compress":true},"nsp":"/"} as 2["message",{"message_id":"msg_sync_mouse_1520330439426","client_id":"p-VZ_JZeeBABWZwYAAAB","type":"sync_mouse","initiator":"5a379898f329915fd2470d72","data":{"user_id":"5a379898f329915fd2470d72","meeting_id":"5a72ba31f329910992b98de0","x":439,"y":62,"cursor":"default"}}] +0ms 18:00:39.426 browser.js:133 engine.io-client:socket flushing 1 packets in socket +17ms 18:00:39.429 browser.js:133 engine.io-client:socket socket close with reason: "transport close" +3ms 18:00:39.429 browser.js:123 socket.io-client:manager onclose +4ms 18:00:39.430 browser.js:123 socket.io-client:manager cleanup +0ms 18:00:39.430 browser.js:123 socket.io-client:socket close (transport close) +1ms

Steps to reproduce (if the current behaviour is a bug)

Note: the best way to get a quick answer is to provide a failing test case, by forking the following fiddle for example.

Expected behaviour

to find out the reason, avoid "transport close"

Setup

• OS:mac ox
• browser:chorme
• socket.io version:2.0.4

Other information (e.g. stacktraces, related issues, suggestions how to fix)

[tady21cn]

add client log again.
transport close but ping has not timeout.

[darrachequesne]

@tady21cn it seems the ping has failed. What is the status of the request in the Network panel?

[bczofyou]

I'm having same issue. Did you solve this problem, please?

[ViniciusPaldes]

Someone has any updates on this issue?

[FaizanZahid]

still facing same issue on "socket.io": "2.2.0",
"socket.io-client": "2.2.0",

socket.io-client:socket close (ping timeout) +22s

[vinaymuley96]

Still facing issue on "socket.io": "2.3.0"
"socket.io-client":"2.3.0"

Client randomly disconnects with reason transport close and reason on server is ping timeout.
disconnect event is triggered only when client is receiving data continuously. I have tried changing ping interval and ping timeout on both client and server.

The socket is stable and ping/pong events are triggered as expected.

I didn't faced any issues on both client and server on version 2.0.3. I have tried degrading the version to 2.0.3 and everything worked without any disconnect event

[Unforgiven-wanda]

I second @vinaymuley96
Socket.io 2.3.0 would throw transport error after a few seconds of inactivity on React-native Android (with the app closed and the socket being inside a headless script). Downgrading to 2.0.3 seems to have fixed this.

[CuteShaun]

@vinaymuley96 @Unforgiven-wanda
The same problem, downgrading from 2.3.0 to 2.0.3 seems to have fixed this, thanks guys, you saved my time 👍

[kevinwaelkens]

Downgrading to 2.0.3 did not solve this for me. Still running into this issue, created a Stackoverflow question for this. Sometimes it works, sometimes it doesn't. The most recent update I have is the difference in the logging of socket.io when it works vs when it doesn't

Left is the case where it doesn't work, right is the case where it does work. Can we track down issues from these logs?

[darrachequesne]

OK, let's try to find the needle...

transport close is emitted here: https://github.com/socketio/engine.io-client/blob/3.4.4/lib/socket.js#L283-L285 and reemitted here: https://github.com/socketio/engine.io-client/blob/3.4.4/lib/socket.js#L725

The close event is emitted here: https://github.com/socketio/engine.io-client/blob/3.4.4/lib/transport.js#L158-L161

The Transport#onClose method is called:

• for the WebSocket transport: https://github.com/socketio/engine.io-client/blob/3.4.4/lib/transports/websocket.js#L156-L158

Which would mean that either the WebSocket connection is severed (the client looses connection) or the server forcefully closes the connection (here).

• for the HTTP long-polling transport: https://github.com/socketio/engine.io-client/blob/3.4.4/lib/transports/polling.js#L138-L141

In that case, the server also forcefully closes the connection by sending a 'close' packet (here).

Which brings us to Socket.clearTransport and finally Socket.onClose on the server side.

Several possibilities here:

• parse error: a parsing error
• ping timeout: a ping timeout (the server did not receive the ping packet in time)
• transport error: something bad happened to the connection (HTTP long-polling or WebSocket)
• forced close: the server is stopping
• transport close: the transport was closed cleanly (which can only happen with WebSocket)

It would be interesting to have the Engine.IO server logs, to understand why the server closes the connection.

If it's a ping timeout, it could be a case of delayed timer on the client. Which is why the heartbeat mechanism will be reverted (server sends a ping, and client responds with a pong) in Socket.IO v3.

[kevinwaelkens]

@darrachequesne Can I be of help to figure out those Engine.IO server logs? Not exactly sure right now if I can still provide some helpful info.

I have been able to get my chat working without noticing the POST instead of GET difference (from my screenshot earlier). I thought that was a crucial part for it to work. However, I also have an example where the polling uses POST instead of GET.

This is a diffcheck between two working examples.

If I can still be of help figuring this out, or help providing info, let me know! Thanks for putting your attention on this :)

[darrachequesne]

POST requests are used to send data when in polling mode (more information here), so they are expected.

@kevinwaelkens are you able to reproduce the issue? under which conditions?

Note: could you please provide the logs as plain text instead of an image? Thanks!

[sebastianfelipe]

Is still happening