socket.io
socket.io copied to clipboard
Published
20 hours ago •
socketio
socketio
Timed out event is still buffered
Describe the bug
For a timed out event, If connection between client and server is disrupted but not closed yet, client still buffers event.
To Reproduce
1- After connection between client and server is established disconnect the network. 2- before the client closes the connection send an event with timeout. 3- after the event times out connect the network. 4- client still sends the timed out event
Socket.IO server version: 4.4.1
Server
import { Server } from "socket.io";
const port = 3000;
const io = new Server(port);
console.log(`listening to ${port}`);
io.on("connection", (socket) => {
console.log('user connected');
socket.on("emited", (cb) => {
console.log('got event');
cb('done');
});
});
});
Socket.IO client version: 4.4.1
Client
import { io } from "socket.io-client";
const socket = io("ws://server-ip:3000");
// send a message to the server
setTimeout(() => {
socket.timeout(1000).emit("emited", (err, msg) => {
if (err) {
console.log(err);
return;
}
console.log(msg);
});
console.log('event sent');
}, 10000);
Expected behavior
After the event times out, the event should have been removed from buffer so it wouldn't be sent to server.
Platform:
- OS:Ubuntu 20.04
Hi! I wasn't able to reproduce the issue:
import { io } from "socket.io-client";
const socket = io("http://localhost:3000");
socket.emit("test", "one", (err) => {
console.log(err); // undefined
});
socket.timeout(1000).emit("test", "two", (err) => {
console.log(err); // operation has timed out
});
socket.timeout(30000).emit("test", "three", (err) => {
console.log(err); // null
});
If you start the server after a few seconds, only 1st and 3rd events gets through. Isn't that the case for you?
The timed out events are removed here: https://github.com/socketio/socket.io-client/blob/eaf782c41b9b92d4f39aa221a4166de4a30fb560/lib/socket.ts#L207-L217
Hi
Yes, If the server is restarted or started after the client you are right. the 2nd event is removed correctly. but if connection between server and client is established completely and server is not restarted THEN you make it so that all events are buffered in client, the 2nd event is not removed.
The way I buffer the events is by using a second pc for server. after connection is established and before events are sent (with a setTimeout for emit() ) I turn off wired connection, then after second event times out I reconnect it. but I could not figure out how to reproduce that with one pc.
this is the code and log used for server and client, if it helps:
client code :
import { io } from "socket.io-client";
const socket = io("http://192.168.4.3:10090");
setTimeout(() => {
socket.emit("test", "one", (err) => {
console.log(err); // done
});
socket.timeout(1000).emit("test", "two", (err) => {
console.log(err); // operation has timed out
});
socket.timeout(30000).emit("test", "three", (err) => {
console.log(err); // null
});
}, 5000)
server code:
import { Server } from "socket.io";
let port = +process.argv[2]
const io = new Server(port);
console.log(`listening on ${port}`);
io.on("connection", (socket) => {
console.log('user connected');
socket.on("test", (msg,cb) => {
console.log(`got event ${msg}`);
cb('done');
});
});
client log:
socket.io-client:url parse http://192.168.4.3:10090 +0ms
socket.io-client new io instance for http://192.168.4.3:10090 +0ms
socket.io-client:manager readyState closed +0ms
socket.io-client:manager opening http://192.168.4.3:10090 +1ms
engine.io-client:socket creating transport "polling" +0ms
engine.io-client:socket options: {"path":"/socket.io/","agent":false,"withCredentials":false,"upgrade":true,"timestampParam":"t","rememberUpgrade":false,"rejectUnauthorized":true,"perMessageDeflate":{"threshold":1024},"transportOptions":{},"closeOnBeforeunload":true,"hostname":"192.168.4.3","secure":false,"port":"10090","query":{"EIO":4,"transport":"polling"},"socket":{"secure":false,"hostname":"192.168.4.3","port":"10090","transports":["polling","websocket"],"readyState":"opening","writeBuffer":[],"prevBufferLen":0,"opts":{"path":"/socket.io/","agent":false,"withCredentials":false,"upgrade":true,"timestampParam":"t","rememberUpgrade":false,"rejectUnauthorized":true,"perMessageDeflate":{"threshold":1024},"transportOptions":{},"closeOnBeforeunload":true,"hostname":"192.168.4.3","secure":false,"port":"10090"},"id":null,"upgrades":null,"pingInterval":null,"pingTimeout":null,"pingTimeoutTimer":null}} +0ms
engine.io-client:polling polling +0ms
engine.io-client:polling-xhr xhr poll +0ms
engine.io-client:polling-xhr xhr open GET: http://192.168.4.3:10090/socket.io/?EIO=4&transport=polling&t=N_kZ5AP&b64=1 +0ms
engine.io-client:polling-xhr xhr data null +1ms
engine.io-client:socket setting transport polling +6ms
socket.io-client:manager connect attempt will timeout after 20000 +6ms
socket.io-client:manager readyState opening +1ms
engine.io-client:polling polling got data 0{"sid":"k_m7pW-OP1Q-7u2hAAAA","upgrades":["websocket"],"pingInterval":25000,"pingTimeout":20000} +32ms
engine.io-client:socket socket receive: type "open", data "{"sid":"k_m7pW-OP1Q-7u2hAAAA","upgrades":["websocket"],"pingInterval":25000,"pingTimeout":20000}" +27ms
engine.io-client:socket socket open +0ms
socket.io-client:manager open +26ms
socket.io-client:manager cleanup +1ms
socket.io-client:socket transport is open - connecting +0ms
socket.io-client:manager writing packet {"type":0,"nsp":"/"} +0ms
socket.io-parser encoding packet {"type":0,"nsp":"/"} +0ms
socket.io-parser encoded {"type":0,"nsp":"/"} as 0 +0ms
engine.io-client:socket flushing 1 packets in socket +1ms
engine.io-client:polling-xhr xhr open POST: http://192.168.4.3:10090/socket.io/?EIO=4&transport=polling&t=N_kZ5Ax&b64=1&sid=k_m7pW-OP1Q-7u2hAAAA +33ms
engine.io-client:polling-xhr xhr data 40 +0ms
engine.io-client:socket starting upgrade probes +2ms
engine.io-client:socket probing transport "websocket" +0ms
engine.io-client:socket creating transport "websocket" +0ms
engine.io-client:socket options: [Circular] +0ms
engine.io-client:polling polling +6ms
engine.io-client:polling-xhr xhr poll +4ms
engine.io-client:polling-xhr xhr open GET: http://192.168.4.3:10090/socket.io/?EIO=4&transport=polling&t=N_kZ5A_&b64=1&sid=k_m7pW-OP1Q-7u2hAAAA +0ms
engine.io-client:polling-xhr xhr data null +0ms
engine.io-client:socket probe transport "websocket" opened +17ms
engine.io-client:polling polling got data 40{"sid":"iMFjBx5CorPjQcuTAAAB"} +16ms
engine.io-client:socket socket receive: type "message", data "0{"sid":"iMFjBx5CorPjQcuTAAAB"}" +2ms
socket.io-parser decoded 0{"sid":"iMFjBx5CorPjQcuTAAAB"} as {"type":0,"nsp":"/","data":{"sid":"iMFjBx5CorPjQcuTAAAB"}} +21ms
socket.io-client:socket socket connected with id iMFjBx5CorPjQcuTAAAB +21ms
engine.io-client:polling polling +0ms
engine.io-client:polling-xhr xhr poll +16ms
engine.io-client:polling-xhr xhr open GET: http://192.168.4.3:10090/socket.io/?EIO=4&transport=polling&t=N_kZ5BF&b64=1&sid=k_m7pW-OP1Q-7u2hAAAA +0ms
engine.io-client:polling-xhr xhr data null +1ms
engine.io-client:socket probe transport "websocket" pong +4ms
engine.io-client:socket pausing current transport "polling" +0ms
engine.io-client:polling we are currently polling - waiting to pause +4ms
engine.io-client:polling polling got data 6 +101ms
engine.io-client:socket socket receive: type "noop", data "undefined" +102ms
engine.io-client:polling pre-pause polling complete +1ms
engine.io-client:polling paused +0ms
engine.io-client:socket changing transport and sending upgrade packet +0ms
engine.io-client:socket setting transport websocket +0ms
engine.io-client:socket clearing existing transport polling +1ms
engine.io-client:polling ignoring poll - transport state "paused" +1ms
socket.io-client:socket emitting packet with ack id 0 +5s
socket.io-client:manager writing packet {"type":2,"data":["test","one"],"options":{"compress":true},"id":0,"nsp":"/"} +5s
socket.io-parser encoding packet {"type":2,"data":["test","one"],"options":{"compress":true},"id":0,"nsp":"/"} +5s
socket.io-parser encoded {"type":2,"data":["test","one"],"options":{"compress":true},"id":0,"nsp":"/"} as 20["test","one"] +0ms
engine.io-client:socket flushing 1 packets in socket +5s
socket.io-client:socket emitting packet with ack id 1 +2ms
socket.io-client:manager writing packet {"type":2,"data":["test","two"],"options":{"compress":true},"id":1,"nsp":"/"} +2ms
socket.io-parser encoding packet {"type":2,"data":["test","two"],"options":{"compress":true},"id":1,"nsp":"/"} +1ms
socket.io-parser encoded {"type":2,"data":["test","two"],"options":{"compress":true},"id":1,"nsp":"/"} as 21["test","two"] +0ms
socket.io-client:socket emitting packet with ack id 2 +1ms
socket.io-client:manager writing packet {"type":2,"data":["test","three"],"options":{"compress":true},"id":2,"nsp":"/"} +1ms
socket.io-parser encoding packet {"type":2,"data":["test","three"],"options":{"compress":true},"id":2,"nsp":"/"} +1ms
socket.io-parser encoded {"type":2,"data":["test","three"],"options":{"compress":true},"id":2,"nsp":"/"} as 22["test","three"] +0ms
engine.io-client:socket flushing 2 packets in socket +3ms
socket.io-client:socket event with ack id 1 has timed out after 1000 ms +1s
Error: operation has timed out
at Timeout._onTimeout (file:///home/yusef/Projects/socket-timeout-test/node_modules/socket.io-client/build/esm-debug/socket.js:157:28)
at listOnTimeout (node:internal/timers:559:17)
at processTimers (node:internal/timers:502:7)
engine.io-client:socket socket receive: type "message", data "30["done"]" +7s
socket.io-parser decoded 30["done"] as {"type":3,"nsp":"/","id":0,"data":["done"]} +7s
socket.io-client:socket calling ack 0 with ["done"] +6s
done
engine.io-client:socket socket receive: type "message", data "31["done"]" +2ms
socket.io-parser decoded 31["done"] as {"type":3,"nsp":"/","id":1,"data":["done"]} +2ms
socket.io-client:socket bad ack 1 +2ms
engine.io-client:socket socket receive: type "message", data "32["done"]" +1ms
socket.io-parser decoded 32["done"] as {"type":3,"nsp":"/","id":2,"data":["done"]} +1ms
socket.io-client:socket calling ack 2 with ["done"] +1ms
null
server log:
socket.io:server initializing namespace / +0ms
socket.io:server creating http server and binding to 10090 +1ms
socket.io:server creating engine.io instance with opts {"path":"/socket.io"} +4ms
socket.io:server attaching client serving req handler +1ms
listening on 10090
engine intercepting request for path "/socket.io/" +0ms
engine handling "GET" http request "/socket.io/?EIO=4&transport=polling&t=N_kZ5AP&b64=1" +1ms
engine handshaking client "k_m7pW-OP1Q-7u2hAAAA" +5ms
engine:transport readyState updated from undefined to open (polling) +0ms
engine:socket readyState updated from undefined to opening +0ms
engine:socket readyState updated from opening to open +0ms
engine:socket sending packet "open" ({"sid":"k_m7pW-OP1Q-7u2hAAAA","upgrades":["websocket"],"pingInterval":25000,"pingTimeout":20000}) +1ms
engine:polling setting request +0ms
engine:socket flushing buffer to transport +1ms
engine:polling writing "0{"sid":"k_m7pW-OP1Q-7u2hAAAA","upgrades":["websocket"],"pingInterval":25000,"pingTimeout":20000}" +2ms
engine:socket executing batch send callback +7ms
socket.io:server incoming connection with id k_m7pW-OP1Q-7u2hAAAA +4s
engine intercepting request for path "/socket.io/" +21ms
engine handling "POST" http request "/socket.io/?EIO=4&transport=polling&t=N_kZ5Ax&b64=1&sid=k_m7pW-OP1Q-7u2hAAAA" +0ms
engine setting new request for existing client +2ms
engine:polling received "40" +19ms
engine:socket received packet message +15ms
socket.io-parser decoded 0 as {"type":0,"nsp":"/"} +0ms
socket.io:client connecting to namespace / +0ms
socket.io:namespace adding socket to nsp / +0ms
socket.io:socket socket connected - writing packet +0ms
socket.io:socket join room iMFjBx5CorPjQcuTAAAB +0ms
socket.io-parser encoding packet {"type":0,"data":{"sid":"iMFjBx5CorPjQcuTAAAB"},"nsp":"/"} +3ms
socket.io-parser encoded {"type":0,"data":{"sid":"iMFjBx5CorPjQcuTAAAB"},"nsp":"/"} as 0{"sid":"iMFjBx5CorPjQcuTAAAB"} +0ms
engine:socket sending packet "message" (0{"sid":"iMFjBx5CorPjQcuTAAAB"}) +4ms
user connected
engine upgrading existing transport +9ms
engine:transport readyState updated from undefined to open (websocket) +32ms
engine:socket might upgrade socket transport from "polling" to "websocket" +4ms
engine intercepting request for path "/socket.io/" +1ms
engine handling "GET" http request "/socket.io/?EIO=4&transport=polling&t=N_kZ5A_&b64=1&sid=k_m7pW-OP1Q-7u2hAAAA" +0ms
engine setting new request for existing client +1ms
engine:polling setting request +10ms
engine:socket flushing buffer to transport +1ms
engine:polling writing "40{"sid":"iMFjBx5CorPjQcuTAAAB"}" +0ms
engine:socket executing batch send callback +0ms
engine:ws received "2probe" +0ms
engine:socket got probe ping packet, sending pong +3ms
engine:ws writing "3probe" +1ms
engine intercepting request for path "/socket.io/" +5ms
engine handling "GET" http request "/socket.io/?EIO=4&transport=polling&t=N_kZ5BF&b64=1&sid=k_m7pW-OP1Q-7u2hAAAA" +0ms
engine setting new request for existing client +0ms
engine:polling setting request +5ms
engine:socket writing a noop packet to polling for fast upgrade +101ms
engine:polling writing "6" +99ms
engine:ws received "5" +105ms [0/4818]
engine:socket got upgrade packet - upgrading +4ms
engine:transport readyState updated from open to closing (polling) +111ms
engine:polling closing +5ms
engine:polling transport discarded - closing right away +0ms
engine:transport readyState updated from closing to closed (polling) +1ms
engine:ws received "420["test","one"]" +11s
engine:socket received packet message +11s
socket.io-parser decoded 20["test","one"] as {"type":2,"nsp":"/","id":0,"data":["test","one"]} +12s
socket.io:socket got packet {"type":2,"nsp":"/","id":0,"data":["test","one"]} +12s
socket.io:socket emitting event ["test","one"] +1ms
socket.io:socket attaching ack callback to event +0ms
socket.io:socket dispatching an event ["test","one",null] +0ms
got event one
socket.io:socket sending ack ["done"] +1ms
socket.io-parser encoding packet {"id":0,"type":3,"data":["done"],"nsp":"/"} +2ms
socket.io-parser encoded {"id":0,"type":3,"data":["done"],"nsp":"/"} as 30["done"] +0ms
engine:socket sending packet "message" (30["done"]) +2ms
engine:socket flushing buffer to transport +1ms
engine:ws writing "430["done"]" +4ms
engine:ws received "421["test","two"]" +0ms
engine:socket received packet message +0ms
socket.io-parser decoded 21["test","two"] as {"type":2,"nsp":"/","id":1,"data":["test","two"]} +2ms
engine:ws received "422["test","three"]" +1ms
engine:socket received packet message +1ms
socket.io-parser decoded 22["test","three"] as {"type":2,"nsp":"/","id":2,"data":["test","three"]} +0ms
socket.io:socket got packet {"type":2,"nsp":"/","id":1,"data":["test","two"]} +2ms
socket.io:socket emitting event ["test","two"] +0ms
socket.io:socket attaching ack callback to event +0ms
socket.io:socket dispatching an event ["test","two",null] +1ms
socket.io:socket got packet {"type":2,"nsp":"/","id":2,"data":["test","three"]} +0ms
socket.io:socket emitting event ["test","three"] +0ms
socket.io:socket attaching ack callback to event +0ms
socket.io:socket dispatching an event ["test","three",null] +0ms
got event two
socket.io:socket sending ack ["done"] +0ms
socket.io-parser encoding packet {"id":1,"type":3,"data":["done"],"nsp":"/"} +1ms
socket.io-parser encoded {"id":1,"type":3,"data":["done"],"nsp":"/"} as 31["done"] +0ms
engine:socket sending packet "message" (31["done"]) +1ms
engine:socket flushing buffer to transport +0ms
engine:ws writing "431["done"]" +1ms
got event three
socket.io:socket sending ack ["done"] +1ms
socket.io-parser encoding packet {"id":2,"type":3,"data":["done"],"nsp":"/"} +1ms
socket.io-parser encoded {"id":2,"type":3,"data":["done"],"nsp":"/"} as 32["done"] +0ms
engine:socket sending packet "message" (32["done"]) +1ms
engine:socket flushing buffer to transport +0ms
engine:ws writing "432["done"]" +1ms
engine:transport readyState updated from open to closed (websocket) +14s
engine:socket readyState updated from open to closed +3s
socket.io:client client close with reason transport close +14s
socket.io:socket closing socket - reason transport close +3s
I think this might indeed happen if the packets are buffered in the underlying Engine.IO client. The WebSocket connection is not really closed, so the packets are not discarded and they are sent once the connection is healthy again.
Hello, I also have a problem regarding this issue. I am working locally and I have a code like below.
//timeout func mandatory IO.timeout(2000).to(driverId).emit("catch", "TAKSIISTEGI", (err, resp) => {
if (err || resp === null) {
console.log("err : ", err);
console.log("resp : ", resp);
logger.warn(`socketId of the drivers whose driving request cannot be sent: ${driverId}`);
} else {
console.log("resp : ", resp);
logger.info(`driving request sent to ${driverId}.`);
}
}); //emit
I run this code and it falls into the if block. But when I go to postman and look, I see that it sent the data.
It sends the data but cannot say that it was sent successfully. It throws an error instead
" err : Error: operation has timed out at Timeout._onTimeout (/Users/gospeed/Documents/Backend/gospeed-websocket-socketio/node_modules/socket.io/dist/broadcast-operator.js:181:30) at listOnTimeout (node:internal/timers:573:17) at process.processTimers (node:internal/timers:514:7) "
