0

I have a node.js script which allows a client to connect and receive some realtime data from an external script.

I have just upgraded node.js & socket.io to the current versions (from <0.9) and am trying to get to grips with what happens when a client quits, times out or disconnects from the server.

Here is my current node.js script;

var options = {
    allowUpgrades: true,
    pingTimeout: 50000,
    pingInterval: 25000,
    cookie: 'k1'
    };

var io = require('socket.io')(8002, options);
cp = require('child_process');
var tail = cp.spawn('test-scripts/k1.rb');


//On connection do the code below//
io.on('connection', function(socket) {
    console.log('************ new client connected ****************', io.engine.clientsCount);

    //Read from mongodb//
    var connection_string = '127.0.0.1:27017/k1-test';
    var mongojs = require('mongojs');
    var db = mongojs(connection_string, ['k1']);
    var k1 = db.collection('k1');
    db.k1.find({}, {'_id': 0, "data.time":0}).forEach(function(err, doc) {
        if (err) throw err;
        if (doc) { socket.emit('k1', doc); }
        });

    //Run Ruby script & Listen to STDOUT//
    tail.stdout.on('data', function(chunk) {
        var closer = chunk.toString()
        var sampArray = closer.split('\n');
        for (var i = 0; i < sampArray.length; i++) {
        try {
            var newObj = JSON.parse(sampArray[i]);
            // DO SOCKET //
            socket.emit('k1', newObj);
            } catch (err) {}
        }   
    });

    socket.on('disconnect', function(){
    console.log('****************** user disconnected *******************', socket.id, io.engine.clientsCount);
    socket.disconnect();
    });

});

In the old version of socket.io when a client exits I get the following logged in debug;

   info  - transport end (undefined)
   debug - set close timeout for client Owb_B6I0ZEIXf6vOF_b-
   debug - cleared close timeout for client Owb_B6I0ZEIXf6vOF_b-
   debug - cleared heartbeat interval for client Owb_B6I0ZEIXf6vOF_b-
   debug - discarding transport

then everything goes quite and all is well.

With the new (1.3.7) version of socket.io when a client exits I get the following logged in debug;

  socket.io:client client close with reason transport close +2s
  socket.io:socket closing socket - reason transport close +1ms
  socket.io:client ignoring remove for -0BK2XTmK98svWTNAAAA +1ms
****************** user disconnected ******************* -0BK2XTmK98svWTNAAAA

note the line socket.io:client ignoring remove for -0BK2XTmK98svWTNAAAA

but after that and with no other clients connected to the server I'm still seeing it trying to write data to a client that already left. (in the example below this is what I get after I've had 2 clients connected, both of which have since disconnected.

  socket.io:client ignoring packet write {"type":2,"data":["k1",{"item":"switch2","datapoint":{"type":"SWITCH","state":"0"}}],"nsp":"/"} +1ms
  socket.io:client ignoring packet write {"type":2,"data":["k1",{"item":"switch2","datapoint":{"type":"SWITCH","state":"0"}}],"nsp":"/"} +3ms

I'm trying to stop this apparently new behaviour so that once a client has disconnected and the server is idle its not still trying to send data out.

I've been playing about with socket.disconnect and delete socket["id"] but I'm still left with the same thing.

I tried with io.close() which sort of worked - it booted any clients who where actually connected and made them re-connect but still left the server sitting there trying to send updates to the client that had left.

Am I missing something obvious, or has there been a change in the way this is done with the new version of socket.io? There is nothing in the migration doc about this. The only other result I found was this bug report from June 2014 which has been marked as closed. From my reading of it - it appears to be the same problem I'm having but with the current version.

Update: I've done some more testing and added io.engine.clientsCount to both instances of console.log to track what it's doing. It appears when I connect 1 client it gives me 1 (as expected) and when I close that client it changes to 0 (as expected) this leads me to believe that the client connection has been closed and engine.io know this. So why am I still seeing all the 'ignoring packet write' lines and more with every client who has disconnected.

Update 2: I've updated the code above to include the parser section and the DB section - this represents the full node script as there was a thought that I may need to clean up my own clients. I have tried adding the following code to the script in the hope it would but alas not :(

In the connection event I added clients[socket.id] = socket; and the disconnection event I added delete clients[socket.id]; but it didn't change anything (that I could see)

Update 3: Answer thanks to @robertklep It was an 'event handler leak' that I was actually looking for. Having found that I also found this post.

Community
  • 1
  • 1
user3788685
  • 2,943
  • 5
  • 26
  • 45
  • It looks like your own code keeps writing to sockets that are already closed (you're not showing that you clean up the database connection and Ruby process once a client disconnects). – robertklep Dec 07 '15 at 14:49
  • Ahhh - this sounds interesting - I'll update the question with the full code later when I get some time but I've never had anything in my old node/socket 0.9 app by the way of closing down. If you have some time to check back after 19:00 GMT I'll update the missing bits of the code. Might need some pointers as to how to do any cleaning up. – user3788685 Dec 07 '15 at 14:54
  • My guess is that your previous code exhibited the same behaviour but that `socket.io` just didn't log any of it ;-) – robertklep Dec 07 '15 at 14:55
  • @robertklep - Updated the code above with the full node script if you wouldn't mind casting your eyes over it. This is (apparently) working fine in 'old node' If you want to see the ruby file that's being refereed too that may be a bit harder but not impossible. – user3788685 Dec 07 '15 at 18:15

2 Answers2

1

My guess is that the newer socket.io is just showing you (by way of debug messages) a situation that was already happening in the old socket.io, where it just wasn't being logged.

I think the main issue is this setup:

var tail = cp.spawn('test-scripts/k1.rb');

io.on('connection', function(socket) {
  ...
  tail.stdout.on('data', function(chunk) { ... });
  ...
});

This adds a new handler for each incoming connection. However, these won't miraculously disappear once the socket is disconnected, so they keep on trying to push new data through the socket (whether it's disconnected or not). It's basically an event handler leak, as they aren't getting cleaned up.

To clean up the handlers, you need to keep a reference to the handler function and remove it as a listener in the disconnect event handler:

var handler = function(chunk) { ... }:
tail.stdout.on('data', handler)

socket.on('disconnect', function() {
  tail.stdout.removeListener('data', handler);
});

There's also a (slight) chance that you will get ignored packet writes from your MongoDB code, if the socket is closed before the forEach() has finished, but that may be acceptable (since the amount of data is finite).

PS: eventually, you should consider moving the processing code (what handler is doing) to outside the socket code, as it's now being run for each connected socket. You can create a separate event emitter instance that will emit the processed data, and subscribe to that from each new socket connection (and unsubscribe again when they disconnect), so they only have to pass the processed data to the clients.

robertklep
  • 198,204
  • 35
  • 394
  • 381
  • Thanks - just running a quick test to see what happens... I did wonder at the start of my project if I was calling `cp.spawn` every time someone connected but for a few users and only testing never thought much more of it. I'm guessing now I have the same issue with the database connection and I call the db with every connection & not clear up after myself – user3788685 Dec 07 '15 at 19:31
  • Yes! That fixed it for me - thank you. Now once clients go the ignored messages go as well. I feel a bit silly as had I know it was an 'event handler leak' then I would of found post #28773807 – user3788685 Dec 07 '15 at 20:01
0

This is most probably due to your connection is established via polling transport, which is sooo painful for developer. The reason is that this transport uses timeout to determine if the client is here or not. The behavior you see is due to the client has left but next polling session opening moment has not come yet, and due to it server still thinks that client "it out there".

I have tried to "fight" this problem in many ways (like adding a custom onbeforeunload event on client side to force disconnect) but they all just do not work in 100% cases when polling is used as transport.

kaytrance
  • 2,657
  • 4
  • 30
  • 49
  • I'll so some tests when I have some free time later on to see what happens if I use a websocket only connection. I suspect I need to keep the option of polling to avoid issues with firewalls and some mobile networks/devices. But from what you said about the client timing out etc. If you see my log entry it appears to know the client has gone by the next ping anyway so I'd expect it to clean up after its self...?? – user3788685 Dec 07 '15 at 14:44
  • Tried forcing a websocket only connection but the clients refuse to connect. They all like to start with polling then upgrade to a WS. – user3788685 Dec 07 '15 at 18:02
  • Inability to initialize connection using web socket transport is a pain I a b*t number two. I have tried even to contact heroku support once for this with no luck. – kaytrance Dec 07 '15 at 18:23
  • see the accepted answer. It turned out to be an 'event handler leak' in this instance. – user3788685 Dec 07 '15 at 20:13