Node Restify not responding to consecutive requests to the same endpoint

Question

I've been playing around with restify and came across a behaviour which I'm having an hard time understanding.

My code is as follows:

var restify = require('restify');
var logger = require('log4js').getLogger('index.js');

var server = restify.createServer();

server.listen(3000)

var helloCB = function (request, response, next) {

    logger.info('got new request', request.url)
    setTimeout(function () {

        logger.info('sending response', request.url)
        response.send('hello')
        next(false)
    }, 60000)
}


server.get('/hello', helloCB);

Now, if I load the following urls by opening 3 browser tabs consecutively with each of the following urls - in order and without waiting for any response:

http://localhost:3000/hello

http://localhost:3000/hello

http://localhost:3000/hello?1

Restify seems to be just queueing requests to the same endpoint. The log for my app is as follows:

[2015-03-11 14:17:57.601] [INFO] index.js - got new request /hello
[2015-03-11 14:18:02.299] [INFO] index.js - got new request /hello?1
[2015-03-11 14:19:57.603] [INFO] index.js - got new request /hello

Please note that the second request is actually logged last and it's logged around 2 minutes after requested.

As a secondary test, I tried to emulate a similar test using ab tool:

ab -n 5 -c 2 -k http://localhost:3000/hello

I got the following log (this is actually using a smaller timeout for send the response):

[2015-03-11 14:23:51.883] [INFO] index.js - got new request /hello
[2015-03-11 14:23:51.887] [INFO] index.js - got new request /hello
[2015-03-11 14:23:57.890] [INFO] index.js - sending response /hello
[2015-03-11 14:23:57.901] [INFO] index.js - sending response /hello
[2015-03-11 14:23:57.902] [INFO] index.js - got new request /hello
[2015-03-11 14:23:57.902] [INFO] index.js - got new request /hello
[2015-03-11 14:24:03.904] [INFO] index.js - sending response /hello
[2015-03-11 14:24:03.905] [INFO] index.js - sending response /hello
[2015-03-11 14:24:03.906] [INFO] index.js - got new request /hello
[2015-03-11 14:24:09.910] [INFO] index.js - sending response /hello

Any idea why on the first test the requests to the same endpoint appear to be queued instead of processed immediately?

Thanks

It could be your browser, or restify, "caching" that the same IP is requesting the same endpoint. I don't know for sure, but I'd guess your browser is waiting until the first comes back before it sends the second. What if you send 3 concurrent cUrl requests? Post back what you figure out. — clay, Mar 11 '15 at 17:13
Thanks. I've realised that the browser were to able for the delay - maybe a small delay to assess if it can cache the first request and use it for the second or smth. Anyways I've posted an answer below. Cheers — jribeiro, Mar 11 '15 at 22:47

score 1 · Accepted Answer · answered Mar 11 '15 at 22:45

After further investigation on this I realised the following:

All requests were actually been performed by the browser (chrome://net-internals/#events)
The delay in receiving the request wasn't reproducible using curl
Charles proxy showed that the requests were actually being performed in the order received by restify

So browser to blame. On a side note I was able to reproduce this in FF as well.

Node Restify not responding to consecutive requests to the same endpoint

1 Answers1