SocketCluster/socketcluster-client

Response messages from server lost

Closed this issue · 0 comments

I have encountered a strange issue using the socketcluster client lib in integration tests.
Client socket opened with default configuration except multiplex = false.
Server is running on the same physical host; socket uses default config as well, except pingTimeout=60000.
In my tests I use client socket to send 3 messages in a row, handling the response by callback passed to socket.emit function.
So the issue is, with the default ackTimeout of 10000ms sometimes I observe that responses to 1 or 2 of the messages do not arrive in time to the socket. As I decrease the ackTimeout value, around 2000ms the issue becomes reproducible about 100% of attempts.
I've tried debugging it and adding more logging to my own code and socketcluster client, and I see that each time it happens the server sends reply correctly, about 1 second after the request is received.
The packet arrives to the client socket correctly as well, according to Wireshark.
But then nothing happens, and the emit callback is not called until the timeout triggers. Immediately after that I can see that socketcluster client has received the missing response, but callback has already been triggered.
Here are the logs (not really detailed) for this issue:

Logs

===== SCTransport.prototype.sendObject ===== { event: 'client.signedTransaction.send',
data:
{txId:'3897a8bde27f27570763d9fe5ce8fb9181b49951d63fede7454632fd816868c8'},
cid: 20 }

===== SCTransport.prototype.sendObject ===== { event: 'client.signedTransaction.send',
data:
{txId:'41737af17488576faf8da6e338f9ceefac43ddd72cfe4f16c0c148891f3896a6'},
cid: 21 }

===== SCTransport.prototype.sendObject ===== { event: 'client.signedTransaction.send',
data:
{txId:'09e128a7bd3ad638b61c0fb9d014c85ebbcb03d04d359680bbfce079645b5e2a'},
cid: 22 }

[Thu Jun 27 2019 15:16:17 GMT+0300 (Eastern European Summer Time)] ===== SCClientSocket.prototype._onSCEvent ===== message {"rid":20,"data":{"code":"VALID","txId":"3897a8bde27f27570763d9fe5ce8fb9181b49951d63fede7454632fd816868c8"}}

[Thu Jun 27 2019 15:16:17 GMT+0300 (Eastern European Summer Time)] ===== SCClientSocket.prototype._onSCEvent ===== message {"rid":21,"data":{"code":"VALID","txId":"41737af17488576faf8da6e338f9ceefac43ddd72cfe4f16c0c148891f3896a6"}}

[Thu Jun 27 2019 15:16:25 GMT+0300 (Eastern European Summer Time)] An error occurred while sending signed transaction 09e128a7bd3ad638b61c0fb9d014c85ebbcb03d04d359680bbfce079645b5e2a: Event response for 'client.signedTransaction.send' timed out

[Thu Jun 27 2019 15:16:25 GMT+0300 (Eastern European Summer Time)] ===== SCClientSocket.prototype._onSCEvent ===== message {"rid":22,"data":{"code":"VALID","txId":"09e128a7bd3ad638b61c0fb9d014c85ebbcb03d04d359680bbfce079645b5e2a"}}

And here is a screenshot from Wireshark, showing that the packet actually arrived to the client at 12:16:17, 8 seconds before the timeout was triggered

image

Socketcluster client version: 14.2.2, Socketcluster server version: 14.2.4