Skip to content

Timed out event is still buffered #4318

Open
dyk1454683243-sudo/socket.io
#1

Description

@shayanYousefi

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

Activity

  1. darrachequesne commented on Mar 21, 2022

    @darrachequesne
    Member

    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

  2. added
    questionFurther information is requested
    and removed
    to triageWaiting to be triaged by a member of the team
    on Mar 21, 2022
  3. shayanYousefi commented on Apr 3, 2022

    @shayanYousefi
    ContributorAuthor

    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
    
  4. darrachequesne commented on Apr 5, 2022

    @darrachequesne
    Member

    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.

  5. added
    bugSomething isn't working
    and removed
    questionFurther information is requested
    on Apr 5, 2022
  6. sercangoger commented on Dec 26, 2023

    @sercangoger

    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)
    "

  7. added a commit that references this issue on Jan 10, 2026
    dcf7bb4
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    bugSomething isn't working

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions