Node: Socket setTimeout behaviour not working as expected for HTTP requests

[mtharrison]

Summary

timeout events are fired on sockets assigned to an HTTP request even when there is activity (data being written) within the timeout period. This is unexpected and not explicitly documented.

This did not used to be the case, it used to work like a normal net socket, with the timeout being essentially "reset" on any activity. The behaviour changed after this commit https://github.com/nodejs/node/commit/607bbd3166b0b3bd6d3303b4115029b28b4283d0 without any obvious doc changes.

Full background

A TCP (net) socket has a setTimeout method which sets the socket to emit a timeout event after a certain number of ms of inactivity. This currently works correctly on all tested versions. An example is below:

var net = require('net');

var server = net.createServer(function (socket) {
    socket.setTimeout(200, socket.destroy);              // Setting to less than 100 will cause timeout
    socket.pipe(process.stdout);
});

server.listen(function () {
    var client = net.connect(server.address().port, function () {
        var interval = setInterval(function () {
            client.write('a');
        }, 100);
        setTimeout(function () {
            clearInterval(interval);
            client.end();
            server.close();
        }, 1000);
    });
});

There’s also a setTimeout method available on a HTTP request which proxies the setTimeout call through to the underlying TCP socket. So I expected it to work the same. But it does not, it will timeout even when data is being written actively to the socket.

var http = require('http');

var server = http.createServer(function (req, res) {

    req.setTimeout(200);                              // this will timeout even though data is being written
    req.pipe(process.stdout);
    req.on('end', function () { res.end() });
});

server.listen(function () {

    var address = server.address();
    var req = http.request({
        port: address.port,
        method: 'POST'
    });

    var interval = setInterval(function () {
        req.write('a');
    }, 100);
    setTimeout(function () {
        clearInterval(interval);
        req.end();
        server.close();
    }, 1000);
});

It was an issue posted at https://github.com/hapijs/hapi/issues/3099 that led me to this digging. I used the script above to git bisect the Node core repo back to the commit where the behaviour changed https://github.com/nodejs/node/commit/607bbd3166b0b3bd6d3303b4115029b28b4283d0 which is part of PR https://github.com/nodejs/node/pull/2355.

Conclusion

I think this is either a bug or If the new behaviour is intended, a documentation update is probably needed to explicitly state that the timeout on an http socket works differently than a regular net socket.

• Version: 607bbd3 - master
• Platform: Darwin 15.3.0 Darwin Kernel Version 15.3.0: Thu Dec 10 18:40:58 PST 2015; root:xnu-3248.30.4~1/RELEASE_X86_64 x86_64
• Subsystem: net, http

[silverwind]

Dupe of https://github.com/nodejs/node/issues/3319 maybe?

edit: closed the other issue as this one has more detail.

[silverwind]

@indutny

[indutny]

cc @nodejs/http

[alanstott]

+1

[indutny]

Confirmed, caused by stream consumption indeed. Working on a fix, thanks!

[indutny]

Fix https://github.com/nodejs/node/pull/6286

[baolinCloud]

I met the same issue with node-v0.10.36, should I upgrade the node to solve this problem? Any other ideas?

[cjihrig]

Yes. This likely won't make it back to the 0.10 release line.

[thomas-riccardi]

@baolinCloud node-v0.10 doesn't include the initial commit 607bbd3166b0b3bd6d3303b4115029b28b4283d0 that introduced the regression. lib/http.js hasn't changed on things related to timeout since before this regression commit: https://github.com/nodejs/node/commits/v0.10/lib/http.js
And we only encountered the issue when starting using node v4.

So I think this bug is not present in node v0.10.

[thomas-riccardi]

nodejs v4.4.4 was released after this fix landed on master, but didn't include this fix.
It was released in v5.11.0 though (although with no explicit comment explaining that setTimeout was broken...), and v6.0.0.

When will this be released in v4.x ?

This is a severe regression for all users of setTimeout.

[jasnell]

v4.4.4 was intentionally limited to a smaller set of security related fixes. I imagine this can hit in v4.4.5. /cc @TheAlphaNerd

[MylesBorins]

I just push this change to v4.x-staging and it will be included in v4.4.5

Expect an rc later today and a release next week

[baolinCloud]

@triccardi-systran My test code is simple:

var http = require('http');

server = http.createServer(function (request, response) {
setTimeout(function() {
response.writeHead(200, {'Content-Type': 'text/plain'});
response.end('Hello World\n');
}, 200);
request.socket.setTimeout(500);
request.socket.removeAllListeners('timeout');
request.socket.once('timeout', function () {
response.writeHead(200, {'content-type': 'text/html'});
response.end('hello world');
console.log('timeout');
});
}).listen(1337, '127.0.0.1');

When I use postman to get from http://127.0.0.1:1337 , I get the response of 'Hello World'. But also log 'timeout'. My node version is 0.10.36. Any thing is wrong with my code? I just want to set timeout to less than 2min.

[mtharrison]

@baolinCloud I think that's expected behaviour. You responded and ended the first request in the 200ms timeout, then the socket (still connected because of Keep-Alive) times out.

If you just want to change the timeout on the server to less than 2 min use server.setTimeout():

var http = require('http');

server = http.createServer(function (request, response) {

    // set to more than 200ms and no response will come back because of timeout

    setTimeout(function() {
        response.writeHead(200, {'Content-Type': 'text/plain'});
        response.end('Hello World\n');
    }, 200);

}).listen(1337, '127.0.0.1');

server.setTimeout(500);

[baolinCloud]

@mtharrison I want to catch the timeout event and response a specified message.

For example, if time out , log the event and response 'hello'. Otherwise, response 'HELLO'.

And I don not want to log timeout if not timeout.

In fact I always get the timeout log whether timeout or not.

Any ideas ?

[matthiasg]

This seems to happen again in node 14. Really bad behavior. Uploads stop at about 1m with ECONNRESET

[kanongil]

@matthiasg You should open a new issue with details.