Send callback may not be called if message is sent during upgrade window

[jonathanperret]

Describe the bug

There is a 100-millisecond window starting with the emission of the upgrading event where a message sent by the server will be correctly received by the client, but never trigger the callback passed to send.

To Reproduce

Engine.IO server version: 6.5.4

Server

const engine = require("engine.io");
const server = engine.listen(3000, {});

server.on("connection", (socket) => {
  console.log("connection");

  // this callback would be called correctly:
  // socket.send("hello", ()=>console.log("message sent"));

  socket.on("upgrading", ()=>{
    // the following callback is not called, even though the message is sent
    socket.send("hello", ()=>console.log("message sent"));

    // this callback would also fail to be called:
    // setTimeout(() => { socket.send("hello", ()=>console.log("message sent")); }, 50);

    // this callback would correctly be called:
    // setTimeout(() => { socket.send("hello", ()=>console.log("message sent")); }, 150);
  });

  socket.on("message", (data) => {
    console.log("data", data);
  });

  socket.on("close", () => {
    console.log("close");
  });
});

Engine.IO client version: 6.5.0

Client

const socket = new (require("engine.io-client").Socket)("ws://localhost:3000");

socket.on("open", () => {
  console.log("open");

  socket.on("message", (data) => {
    console.log("data", data);
  });

  socket.on("close", () => {
    console.log("close");
  });
});

Expected behavior

I expected the callback passed to send to be called if the message was successfully sent. Instead what happens with the code above is:

• the client logs that the message was received;
• the server never logs that the callback was called.

If the message is sent before the upgrading event (e.g. right upon the connection event), the callback is correctly fired. Likewise, if the message is sent more than 100 milliseconds after receiving the upgrading event, the callback is fired as well.

Platform:

• Device: M1 MacBook Pro
• OS: macOS Sonoma 14.2

Additional context

I hit upon this bug not because I specifically wanted to send messages right after the upgrading event, but because the code I was integrating engine.io into occasionnally ended up sending its first message within that window (which tends to start a few milliseconds after receiving the connection event and lasts for 100 milliseconds as reported above).

It's only after investigating the bug that I identified that specific window. The duration of 100 milliseconds is related to the interval before the server sends its first noop packet to speed up upgrading here (changing that interval in socket.ts changes the duration of the problematic window).

I have created a branch that shows the bug as a failing test here: main...jonathanperret:engine.io:lost-callback-while-upgrading

Another observation is that once such a lost callback has occured, future callbacks do get fired but out of sync: the callback for message N is only fired when message N+1 (or a ping packet) is sent and so on.

[darrachequesne]

@jonathanperret thanks a lot for all the details. This should be fixed by 362bc78, included in version 6.6.0. Could you please check?

[darrachequesne]

I think this can be closed now. Please reopen if needed.