Connection events not firing in master?

[elad]

Hello,

It seems like connection events aren't always fired, causing requests to timeout.

On one terminal I have this code (from the example) running:

var sticky = require('sticky-session');

sticky(require('http').createServer(function(req, res) {
    res.end('worker: ' + process.env.NODE_WORKER_ID);
})).listen(3000, function() {
    console.log('server started on 3000 port');
});

I put it in a file called dummy_sticky.js and ran it with:

$ node dummy_sticky.js 
server started on 3000 port
server started on 3000 port

On another terminal I'm running a little program to make a few requests in parallel. Here's the program:

var async = require('async'),
    request = require('request'),
    moment = require('moment');

function dummy_request(callback) {
    request.get({
        url: 'http://localhost:3000',
        json: true
    }, function(err, res, body) {
        callback(err);
    });
}

function run(n) {
    var mstart = moment();
    async.times(n, function(i, callback) {
        var mstart2 = moment();
        async.parallel({
            dummy1: dummy_request,
            dummy2: dummy_request,
            dummy3: dummy_request,
            dummy4: dummy_request,
            dummy5: dummy_request,
        }, function(err, results) {
            var mend2 = moment();
            console.log(i, 'done, err:', err, 'time elapsed (ms):', mend2.diff(mstart2));
            callback();
        });
    }, function(err) {
        var mend = moment();
        console.log('time elapsed (ms):', mend.diff(mstart));
    });
}

var n = parseInt(process.argv[2]) || 10;
console.log('running', n, 'times');
run(n);

(it requires the async, request, and moment modules.)

I run it:

$ nodejs stress_dummy 5
running 5 times
1 'done, err:' undefined 'time elapsed (ms):' 56
2 'done, err:' undefined 'time elapsed (ms):' 61
3 'done, err:' undefined 'time elapsed (ms):' 63
4 'done, err:' undefined 'time elapsed (ms):' 69
^C
$

And you can see that the first (index zero) request is not succeeding, and if I don't hit ^C the program just hangs there.

Sometimes it does succeed, though. For example, most of the times after I hit ^C and run the program again it works.

When it times out, it does so after 60 seconds.

If I run a server without passing the connection from the master to the worker, for example:

var http = require('http');

var server = http.createServer(function(req, res) {
    res.writeHead(200, { 'Content-Type': 'text/plain' });
    res.end('okay');
}).listen(3000);

Everything works fine.

Node.JS is version 0.10.28.

Any ideas what's the cause or how to debug?

[elad]

In case it might help with debugging, I used tcpdump to get a bit more insight into this, and compared "good" and "bad" sessions, where the latter is one similar to what I reported above (one out of five requests times out).

What I saw is that in both cases there's a series of five handshakes (SYN-SYN/ACK-ACK) from five sequential source ports, so I believe the server gets the connection. Then, there are two series of PSH/ACK-ACK. The first has five exchanges involving all five sequential source ports from the client, and another with only four exchanges - this time without one of the ports. That's where communication on this port stops.

Then there's data exchange with more PSH/ACK packets, again, involving only four of the original five source ports the client used.

Finally there's the FIN/ACK-ACK exchange, closing the connection for the four active ports.

The reason the fifth port times out is probably because there's no communication on it and the operating system just shuts it down.

[elad]

Another data point: reproduces locally on both Ubuntu 13.10 and Mac OS X Mavericks.

[paulbjensen]

Hi,

I experienced exactly the same issue (Node v0.10.28 on Mac OS X Mavericks). I'm wondering if it's a Node 0.10 issue?

[elad]

@paulbjensen - look at the node.js issue I referenced, it's an issue with node, not necessarily sticky-session.

[paulbjensen]

Thanks @elad. Deeper down the rabbit hole we go.

[elad]

The cause for this issue was fixed yesterday.