Hapi: Socket disconnects when payload timeout is false

[kedemd]

ECONNRESET Error: Client request error: socket hang up

In route config, when { payload: { timeout: false }} (never) the socket will timeout after 2 minutes (node default).
To fix this problem { timeout: { socket : false } } must be specified.

I expected that the socket timeout config will automatically be the size of the payload timeout.

Route validation will catch similar problems, for example:
When payload timeout is specified in milliseconds ({ payload: { timeout: 240000 }}) the server will throw if the timeout is greater than socket timeout (if specified or not).

Route validation should fail if { payload: { timeout: false} } and { timeout: { socket: 120000 }}
or
Socket timeout should automatically be set to payload timeout.

[kanongil]

The { payload: { timeout: false} } and { timeout: { socket: 120000 }} case is a valid configuration, which means that the request should never timeout except if there has been no activity on the socket for 2 minutes. You might want to read up on how socket timeouts work.

[kedemd]

In that case the problem is even worse because sending data does not keep the socket open. (hapi 13.2.1 and node 4.2.6)

[kedemd]

I wrote a script to verify.
It is configured to test what @kanongil said but it is easy to change the parameters to test other scenarios as well.

Check it out at:
https://github.com/kedemd/hapi-test-socket-timeout

For the following configuration:

internals.sendDataInterval = 10;             // Send data over the network to the socket "keep alive"
internals.timeUntilAllDataIsSent = 1000;     // Time until it will finish transmitting data
internals.socketTimeout = 100;               // Time until the socket will timeout, undefined for default
internals.payloadTimeout = false;            // Time until the payload will timeout, undefined for default

Output:
{ [Error: Client request error: socket hang up] code: 'ECONNRESET', trace: [ { method: 'POST', url: 'http://test:35748/upload' } ], isBoom: true, isServer: true, data: null, output: { statusCode: 502, payload: { statusCode: 502, error: 'Bad Gateway', message: 'socket hang up' }, headers: {} }, reformat: [Function] }

[kanongil]

It appears that the socket timeout behavior is bugged (at least for http-based sockets) on the current node releases. I will try to investigate further.

[mtharrison]

Here's a script that emulates the issue you're seeing without any hapi stuff:

const Http = require('http');

const server = Http.createServer((req, res) => {

    req.socket.setTimeout(100);   // there shouldn't be 100ms of 'inactivity' because we write every 10ms

    req.pipe(process.stdout);
    req.on('end', () => {

        res.end('hiii');
    });
});

server.listen(4052, (err) => {

    if (err) {
        throw err;
    }
    console.log('Listening!');

    const req = Http.request({
        hostname: 'localhost',
        port: 4052,
        path: '/',
        method: 'POST'
    }, (res) => {});

    const interval = setInterval(() => {

        req.write('a');
    }, 10);

    req.on('error', (err) => {

        console.log(err);
        clearInterval(interval);
        server.close();
    });
});

Console:

Listening!
aaaaaaaaa{ [Error: socket hang up] code: 'ECONNRESET' }

[mtharrison]

I ran this above across a few Node versions:

No error in node v0.10.43, v0.12.2
Errors in v4.0.0, v4.4.1, v5.9.1

[mtharrison]

Node seems to set its own timeout on HTTP sockets, the fix seems to be to remove Node's own listener when adding yours:

const server = Http.createServer((req, res) => {

    req.socket.removeAllListeners('timeout');        // remove node's default listener
    req.socket.setTimeout(100);                      // there shouldn't be 100ms of 'inactivity' because we write every 10ms

    req.pipe(process.stdout);
    req.on('end', () => {

        res.end('hiii');
    });
});

hapi should probably do something similar if this isn't working properly.

[kanongil]

@mtharrison That won't work. You just removed the close behavior on timeouts.

[kanongil]

Basically, what happens is that http requests hide the actual transmission from the socket, which means that the activity tracking code is never called (intentionally or not). In any case, node either has a bug or incorrect documentation.

FYI, I found https://github.com/nodejs/node/issues/3319 which seems to be about this issue.

Edit: I'm leaning towards an implementation bug in node.

[mtharrison]

Yeah, I was being lazy and not really testing my idea. Good find on the above ^^

[mtharrison]

I ran a test script with git bisect run on node source between v0.12.2 and v4.0.0 and this is the very first commit that introduces the different/incorrect behaviour https://github.com/nodejs/node/commit/607bbd3166b0b3bd6d3303b4115029b28b4283d0

[kanongil]

@mtharrison I was just about to suggest that commit as the root cause :smiley:

From https://github.com/nodejs/node/pull/2355

[mtharrison]

Nice, I left a comment over there. I guess either way it's a bug in node's code/docs or some behaviour change needed in hapi.

[shugigo]

NodeJS also are mentioning in the documentation that by default the socket timeout is never, which obviously is not the case.
NodeJS v4.2.6 - https://nodejs.org/docs/v4.2.6/api/net.html#net_socket_settimeout_timeout_callback
NodeJS v4.4.1 - https://nodejs.org/dist/v4.4.1/docs/api/net.html#net_socket_settimeout_timeout_callback
NodeJS v5.9.1 - https://nodejs.org/dist/latest-v5.x/docs/api/net.html#net_socket_settimeout_timeout_callback

[kanongil]

@shugigo The default is changed since it is from a http server connection. See https://nodejs.org/api/http.html#http_server_timeout.

[mtharrison]

Looks like a fix is incoming for Node: https://github.com/nodejs/node/pull/6286

[mtharrison]

@kedemd @kanongil

The fix for this has landed:

Node 4.4.5: https://github.com/nodejs/node/pull/6824
Node 5.11.0: https://github.com/nodejs/node/pull/6824

Data flowing on the socket will now reset the timeout.

Confirmed my test case above works now in both versions, so closing this issue.