CODEWITHSUNDEEP
node.jsrestify
jribeiro
jribeiro

Reputation: 3463

Node Restify not responding to consecutive requests to the same endpoint

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

Upvotes: 0

Views: 591

Answers (1)

jribeiro
jribeiro

Reputation: 3463

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.

Upvotes: 1

Related Questions