Socket.io: First message never gets sent

[eneroth]

For some reason, whenever a new connection is established, the first message I send always seems to go silently ignored. I switched on logging on the Node side, and this is the output:

  engine intercepting request for path "/socket.io/" +14ms
  engine handling "GET" http request "/socket.io/?EIO=3&transport=polling&t=1444437518880-2&sid=DMd9QzeN3O9frdIRAAAA" +0ms
  engine setting new request for existing client +4ms
  engine:polling setting request +0ms
  engine:socket writing a noop packet to polling for fast upgrade +89ms
  engine:polling writing "�6" +1ms
  engine:ws received "5" +41ms
  engine:socket got upgrade packet - upgrading +1ms
Sending bullshit-message 1
  socket.io-parser encoding packet {"type":2,"data":["bullshit-message","Not seen on client"],"nsp":"/"} +0ms
  socket.io-parser encoded {"type":2,"data":["bullshit-message","Not seen on client"],"nsp":"/"} as 2["bullshit-message","Not seen on client"] +1ms
Sending bullshit-message 2
  socket.io:client writing packet {"type":2,"data":["bullshit-message","THIS will be seen on client"],"nsp":"/"} +10s
  socket.io-parser encoding packet {"type":2,"data":["bullshit-message","THIS will be seen on client"],"nsp":"/"} +10s
  socket.io-parser encoded {"type":2,"data":["bullshit-message","THIS will be seen on client"],"nsp":"/"} as 2["bullshit-message","THIS will be seen on client"] +0ms
  engine:socket sending packet "message" (2["bullshit-message","THIS will be seen on client"]) +10s
  engine:socket flushing buffer to transport +0ms
  engine:ws writing "42["bullshit-message","THIS will be seen on client"]" +0ms
Sending Testing 1! to client DMd9QzeN3O9frdIRAAAA
  socket.io:client writing packet {"type":2,"data":["message","Testing 1!"],"nsp":"/"} +5ms
  socket.io-parser encoding packet {"type":2,"data":["message","Testing 1!"],"nsp":"/"} +4ms
  socket.io-parser encoded {"type":2,"data":["message","Testing 1!"],"nsp":"/"} as 2["message","Testing 1!"] +0ms
  engine:socket sending packet "message" (2["message","Testing 1!"]) +4ms
Sending Testing 2! to client DMd9QzeN3O9frdIRAAAA
  socket.io:client writing packet {"type":2,"data":["message","Testing 2!"],"nsp":"/"} +1ms
  socket.io-parser encoding packet {"type":2,"data":["message","Testing 2!"],"nsp":"/"} +1ms
  socket.io-parser encoded {"type":2,"data":["message","Testing 2!"],"nsp":"/"} as 2["message","Testing 2!"] +0ms
  engine:socket sending packet "message" (2["message","Testing 2!"]) +1ms
  engine:socket flushing buffer to transport +2ms
  engine:ws writing "42["message","Testing 1!"]" +0ms
  engine:ws writing "42["message","Testing 2!"]" +0ms
  engine:ws received "2" +15s
  engine:socket packet +1ms
  engine:socket got ping +0ms
  engine:socket sending packet "pong" (undefined) +0ms
  engine:socket flushing buffer to transport +0ms

It seems like the first message (the bullshit-message, as I've come to call it in testing) is encoded, but never actually sent off to the client. What is going on here?

On client:

  engine.io-client:socket changing transport and sending upgrade packet +1ms
  socket.io-1.3.7.js:2 engine.io-client:socket setting transport websocket +1ms
  socket.io-1.3.7.js:2 engine.io-client:socket clearing existing transport polling +1ms
  socket.io-1.3.7.js:2 engine.io-client:polling ignoring poll - transport state "paused" +1ms
  socket.io-1.3.7.js:2 engine.io-client:socket socket receive: type "message", data "2["bullshit-message","THIS will be seen on client"]" +10s
  socket.io-1.3.7.js:1 socket.io-parser decoded 2["bullshit-message","THIS will be seen on client"] as %j +9s Object {type: 2, nsp: "/", data: Array[2]}
  socket.io-1.3.7.js:1 socket.io-client:socket emitting event %j +9s ["bullshit-message", "THIS will be seen on client"]
Bullshit data received THIS will be seen on client
  socket.io-1.3.7.js:2 engine.io-client:socket socket receive: type "message", data "2["message","Testing 1!"]" +5ms
  socket.io-1.3.7.js:1 socket.io-parser decoded 2["message","Testing 1!"] as %j +5ms Object {type: 2, nsp: "/", data: Array[2]}
  socket.io-1.3.7.js:1 socket.io-client:socket emitting event %j +5ms ["message", "Testing 1!"]
Data received Testing 1!
  socket.io-1.3.7.js:2 engine.io-client:socket socket receive: type "message", data "2["message","Testing 2!"]" +8ms
  socket.io-1.3.7.js:1 socket.io-parser decoded 2["message","Testing 2!"] as %j +8ms Object {type: 2, nsp: "/", data: Array[2]}
  socket.io-1.3.7.js:1 socket.io-client:socket emitting event %j +8ms ["message", "Testing 2!"]
Data received Testing 2!

[EvHaus]

I'm having the exact same issue. Adding a 250ms delay before sending the first message seems to make it go through.

[nkzawa]

Hi, thanks for your report. Can you post your code to reproduce the issue?

[EvHaus]

Sure thing. My client code looks like this:

const BASE_URL = 'http://myurlhere';
const TOKEN = 'myauthtokenhere';

class SocketAPI {
    connect () {
        return new Promise((resolve, reject) => {
            this._socket = new this._io(BASE_URL);
            this._socket.on('connect', resolve);
            this._socket.on('connect_error', reject);
            return this._socket;
        });
    }

    login = () => {
        this._socket.emit('login', TOKEN);
    }
}

I then run:

const S = new SocketAPI();
S.connect().then(S.login);

The code above with fail about 50% of the time. However, if I change the login function to:

login = () => {
        setTimeout(() => {
            this._socket.emit('login', API.token);
        }, 250);
    };

Then I'm able to get 100% success rate.

I have confirmed that it's not a race condition issue. The connection always succeeds first before the login method is called. So by the time I emit the login event, the connection is definitely established.

Looking at the Frames in the Network tab of the Chrome dev tools, I see that without the timeout, the 'login' event frame doesn't always get published.

[nkzawa]

@globexdesigns thanks, but somehow I couldn't reproduce. It worked fine to me.

[EvHaus]

Digging into this a bit more, I believe something strange is going on with the onopen event. Here is the order of events I'm seeing in the browser:

• socket.client-io establishes WebSocket connection to server
• socket.client-io fires onopen event
• socket.client-io emits my first event (in this case login)
• engine.io fires onopen event
• engine.io receives ping events from server
• engine.io receives first response from server

Why is socket.client-io firing the onopen event before the engine.io has emitted it?

UPDATE: I was able to solve my problem by changing:

import io from 'socket.io-client';

// Instead of
this.socket = new io(BASE_URL);

// I now initialize the Socket.IO client class as:
this.socket = new io(BASE_URL, {transports: ['websocket']});

By default transports seems to be set to ['polling', 'websocket']. I have no idea what polling is or what the transports option does (documentation for this is very hard to find). But it seems to solve my problem. I now consistently see my requests sent and received.

[JamiesonWarner]

I have encountered the same problem: the first message is not sent, but all messages after are. Setting transports to ['websocket'] has no effect. I am using Socket.io 1.7.2, node 4.1.0, Socket.io client 1.7.2.

[darrachequesne]

@EvNaverniouk please see https://github.com/socketio/engine.io#goals for details about long-polling / Websocket transports

Using { transports: ['websocket'] } means there will be no fallback if the Websocket connection cannot be established.

Related: https://github.com/socketio/socket.io/issues/2485

[darrachequesne]

As commented here, I couldn't reproduce: https://github.com/darrachequesne/socket.io-fiddle/tree/issue/lost-message

Is is related to a given browser?

[darrachequesne]

@eneroth Could you please provide the code you used (which produced the log below)?

It seems Client.packet is not called here (you would have either writing packet ... or ignoring packet write ... in the logs), and I didn't find anything which would block the process socket.emit => socket.packet => client.packet.

Did you use a global broadcast?

io.on('connect', function (socket) {
  io.emit('bullshit-message');
});

In that case, the socket.io-parser encoding packet log would come from the adapter here, and the packet could maybe be lost there:

for (var id in self.sids) {
  if (self.sids.hasOwnProperty(id)) {
   if (~except.indexOf(id)) continue;
   socket = self.nsp.connected[id];
   if (socket) socket.packet(encodedPackets, packetOpts);
  }
}

Those values are set there:

Socket.prototype.onconnect = function(){
  debug('socket connected - writing packet');
  this.join(this.id); // => update the sids values in the adapter
  this.packet({ type: parser.CONNECT });
  this.nsp.connected[this.id] = this;
};

Which is called there:

socket.onconnect();
if (fn) fn();

// fire user-set events
self.emit('connect', socket);
self.emit('connection', socket);

A simple race condition here?

[darrachequesne]

It seems I was able to (kind of) reproduce the issue here, by changing the following lines:

Socket.prototype.onconnect = function(){
  debug('socket connected - writing packet');
  this.nsp.connected[this.id] = this;
  //this.join(this.id);
  setTimeout(() => this.join(this.id), 10);
  this.packet({ type: parser.CONNECT });
};

The browser gets:

connect TAwlYvORlhMfpl1cAAAA
// missing "got 1"
got 2
got 3

@eneroth could you confirm that behaviour?

[vinz243]

Same issue here, please find a fix!

update: rather than applying a timeout, process.nextTick seems a better solution

[darrachequesne]

@vinz243 Which version of socket.io are you using? Could you provide some code please?

[vinz243]

I have socketio 1.7.3. It's been a week sorry I'm not sure the exact fix, maybe this code on server:

emitter.on(['server', 'ping'], () => {
  process.nextTick(() => {
    return emitter.emit(['client', 'pong']);
  })
});

[darrachequesne]

@vinz243 please provide a full code example reproducing the issue.

Meanwhile, I'll close that particular issue, as I think it was fixed by https://github.com/socketio/socket.io/commit/425409945bc53960cc9c3cbd4e5b0879aa27c1a2.

[vinz243]

@darrachequesne this is a quite large project and I have no idea how i fixed the issue sorry

[svenez]

Any ideas? Same issue

require('log-timestamp');
const   app = require('express')(),
        http = require('http').Server(app),
        io = require('socket.io')(http),
        path = require('path');

app.get('/client', function(req, res) {
    res.sendFile(path.join(__dirname + '/index.html'));
});

http.listen(8080, function(){});
io.on('connection', function (socket) {
    socket.emit('immediate',{'some' : 'data'});  //never received in browser
    setTimeout(() => {
        socket.emit('deferred',{'some' : 'some'}); //always received in browser
    },1500);
});

what i've pointed out is that at emmititing 'immediate' event the socket.client.Client.conn.socket.upgraded is false, but after 1.5s that is true, and all works just fine