restify/clients

HTTPClient: requestTimeout doesn't work on third and further requests

hekike opened this issue · 1 comments

Moved from: restify/node-restify#1265

The issue can be easily reproduced, all you need is just a simple HTTP server which replies with a delay (e.g. 10 sec). Here is a simple script to illustrate the problem

const restify = require('restify');
const assert = require('assert');
const exec = require('child_process').exec;

var server = restify.createServer();

var i = 0;

server.get('/', function (req, res, next) {
    if (i++) {
        setInterval(function() {
            res.send('bar');
            next();
        }, 10000);

        return;
    }

    res.send('foo');
    next();
});

server.listen(7777, function() {
    console.log('server started');
});

var client = restify.createStringClient({
    url: 'http://127.0.0.1:7777',
    connectTimeout: 3000,
    requestTimeout: 3000,
    version: '*',
    retry: false
});

console.log('request 1');

client.get('/', function(err, req, res, data)  {
    assert(!err);

    console.log('request 2', new Date());
    client.get('/', function(err, req, res, data) {
        console.log("done", err, new Date());

        console.log('request 3', new Date());
        client.get('/', function(err, req, res, data) {
            console.log("done", err, new Date());
        });
    });
});

The output:

request 1
server started
request 2 Fri Jan 13 2017 16:03:30 GMT+0000 (GMT)
done { [RequestTimeoutError: request timeout after 3000ms]
  message: 'request timeout after 3000ms',
  name: 'RequestTimeoutError' } Fri Jan 13 2017 16:03:33 GMT+0000 (GMT)
request 3 Fri Jan 13 2017 16:03:33 GMT+0000 (GMT)
done null Fri Jan 13 2017 16:03:43 GMT+0000 (GMT)

As you can see third request took 10 seconds despite of requestTimeout.

As I understand the problem is here (requestTimeout is just not set if socket is not connecting):
https://github.com/restify/node-restify/blob/4.x/lib/clients/http_client.js#L223

Also, there is one more weird thing, for second request it works correctly because _socket._connecting == true, but my understanding is _socket._connecting should be false for the second request as well.

I was unable to repro - I believe this was fixed by #152