Packets getting delivered to wrong room

[gkcgautam]

You want to:

• report a bug
• request a feature

Bug

We use Socket.io for running a Chat service wherein students can chat with teachers for getting their doubts solved. We've been getting reports of messages being delivered to a wrong student or sometimes messages getting lost before they reach the student. Based on the investigation that we did, it appears that if a single socket instance (teacher) emits messages to several rooms simultaneously, some of the messages might make it to a wrong room.
This might also be related to #2726

Current behaviour

This happens because when invoking socket.to('room') or socket.in('room'), the list of target rooms is stored within the _rooms key of the socket instance with this code:

Socket.prototype.to =
Socket.prototype.in = function(name){
  if (!~this._rooms.indexOf(name)) this._rooms.push(name);
  return this;
};

When we call the socket.emit method, after setting the target room, it checks whether the message is intended for a room with this code:

if (this._rooms.length || this.flags.broadcast) {
  this.adapter.broadcast(packet, {
    except: [this.id],
    rooms: this._rooms,
    flags: this.flags
  });
} else {
  // dispatch packet
  this.packet(packet, this.flags);
}

If this._rooms is not empty, the message gets broadcasted to the rooms present in the array.
While this approach works fine in a synchronous code, or on a smaller scale, it can create problems if the same socket instance tries to broadcast large number of different messages to different rooms simultaneously.

Just to give an example, let's assume that a single socket instance is going to emit messages to multiple rooms simultaneously from two different async functions:

// Message 1 to Room 1 in an async function
socket.to('room-1').emit('nice game', 'well done');
...
// Message 2 to Room 2 in another async function
// by the same socket instance
socket.to('room-2').emit('poor game', 'we need to do better next time');

Now if the socket.to('room-2') code was to get invoked immediately after socket.to('room-1'), the message intended for room-1 will also be sent to room-2 as both of the rooms will be present in the socket._rooms array when the emit method is invoked for first message.

The order in which the methods actually got invoked:

// _rooms is []
socket.to('room-1')
// _rooms is ['room-1'] now
socket.to('room-2')
// _rooms is ['room-1', 'room-2'] now
emit('nice game', 'well done');
// The above message will be sent to both rooms

Temporary fix

As a temporary fix, we've forked the socket.io repo and created a new emitToRoom method wherein we can pass the room names and messages within a single invocation and do not need to use the socket._rooms key. This is our fix:

Socket.prototype.emitToRoom = function(){
  var args = Array.prototype.slice.call(arguments);
  if (args.length < 2) {
    throw new Error('Insufficient arguments provided');
  }

  var rooms = args.shift();
  if (!Array.isArray(rooms)) {
    rooms = [rooms];
  }

  var packet = {};
  packet.type = hasBin(args) ? parser.BINARY_EVENT : parser.EVENT;
  packet.data = args;

  // access last argument to see if it's an ACK callback
  if ('function' == typeof args[args.length - 1]) {
    throw new Error('Callbacks are not supported when broadcasting');
  }

  this.adapter.broadcast(packet, {
    except: [this.id],
    rooms: rooms,
    flags: {}
  });
  return this;
};

Setup

• OS: N/A
• browser: N/A
• socket.io version: All versions

[darrachequesne]

@gkcgautam thanks for the detailed write-up. Are you able to actually reproduce the issue? At first sight, it seems weird that socket.emit would not immediately follow socket.to in the callstack.

[gkcgautam]

@darrachequesne Yes, we have been able to reproduce this issue in our production environment. We never emit to more than one room in our code base, but have noticed socket._rooms array having more than one value in our logs. We compared our logs with the user complaints about missing messages, and were able to pin down the issue.
We stopped receiving the complaints after we implemented the temporary fix shared above.

[darrachequesne]

@gkcgautam I think it may happen since _rooms is sent by reference here: https://github.com/socketio/socket.io/blob/2.0.2/lib/socket.js#L161

Maybe we could update it to:

this.adapter.broadcast(packet, {
  except: [this.id],
  rooms: this._rooms.slice(0),
  flags: this.flags
});

What do you think?

[gkcgautam]

@darrachequesne I don't think that this would fix the issue entirely, as the value contained within socket._rooms would still remain the same.
We had added the logs before the invocation of socket.adapter.broadcast method, and could notice that socket._rooms had more than one values. Even we pass a copy of socket._rooms to the broadcast method, socket._rooms will still keep holding the same value.
May be we can clone the socket._rooms array in the very beginning of the function and reset it. Then we won't have to wait for the adapter.broadcast method to finish it's work for resetting the flags.

[gkcgautam]

This is where we added the logs:

Socket.prototype.emit = function(ev){
  if (~exports.events.indexOf(ev)) {
    emit.apply(this, arguments);
  } else {
    // Log emit events to multiple rooms
    if (this._rooms && this._rooms.length > 1) {
        console.log((new Date).toLocaleTimeString(), `socketRooms: ${this.id} -`, this._rooms, `on ${ev}`);
    }
    var args = Array.prototype.slice.call(arguments);
    ...

Small sample of the logs that we got from this:

12:59:46 AM socketRooms: 96luqhaywaKxC-T7AW4_ - [ '548176', 474291 ] on receiveDoubtMessage
12:59:53 AM socketRooms: 96luqhaywaKxC-T7AW4_ - [ 474291, 548176 ] on receiveDoubtMessage
1:00:46 AM socketRooms: RnRCtxCDCKlhcJFeAXuk - [ '117344', 117344 ] on messageDelivered
1:03:29 AM socketRooms: em7og1zY4JYfUwagAXuZ - [ 511110, 547112 ] on messageDelivered
1:03:30 AM socketRooms: HdoE6_aVuTKlnyYyAXux - [ 117344, 547112 ] on messageDelivered

All of these events were sent to a single room from our code like this:

socket.to(roomId).emit('messageDelivered', data);