http - calls from an external IP close after 5-20 seconds using response.end and Content-Length header is set (Node 8.X)

[mtraynham]

• Version: v8.0.0, v8.1.0, v8.4.0
• Platform: Linux 4.10.0-28-generic 32~16.04.2-Ubuntu SMP Thu Jul 20 10:19:48 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux, Linux 2.6.32-573.3.1.el6.x86_64 1 SMP Thu Aug 13 22:55:16 UTC 2015 x86_64 x86_64 x86_64 GNU/Linux
• Subsystem: http

Executing a request from an external IP address, results in a closed connection after about 5 - 20 seconds when the Content-Length header is set. When Content-Length is not set, it seems ok.
Executing a request locally always seems to respect the server timeout regardless of Content-Length.

This works correctly in Node 7.10.1.

Using the following code (thanks to Doug Wilson at ExpressJS):

var fs = require('fs');
var http = require('http');
var wordsFile = '/usr/share/dict/words';
function app (req, res) {
    switch (req.url) {
        case '/send':
            var contents = fs.readFileSync(wordsFile);
            res.setHeader('Content-Length', contents.length);
            res.end(contents);
            break;
        case '/sendNoLength':
            var contents = fs.readFileSync(wordsFile);
            res.end(contents);
            break;
        default:
            res.statusCode = 404;
            res.end();
    }
}
var server = http.createServer(app);
server.timeout = 120000 * 5;
server.listen('3000');

I've changed my IPs here to Google's...

> wget 8.8.8.8:3000/send --limit-rate=5k

--2017-08-16 18:03:56--  http://8.8.8.8:3000/send
Connecting to 8.8.8.8:3000... connected.
HTTP request sent, awaiting response... 200 OK
Length: 938848 (917K)
Saving to: “send” --- 64,990      5.00K/s   in 13s     

2017-08-16 18:04:09 (5.00 KB/s) - Connection closed at byte 64990. Retrying.

--2017-08-16 18:04:10--  (try: 2)  http://8.8.8.8:3000/send
Connecting to 8.8.8.8:3000... connected.
HTTP request sent, awaiting response... 200 OK
Length: 938848 (917K)
Saving to: “send” --- 67,724      5.00K/s   in 13s     

2017-08-16 18:04:23 (5.00 KB/s) - Connection closed at byte 67724. Retrying.

--2017-08-16 18:04:25--  (try: 3)  http://8.8.8.8:3000/send
Connecting to 8.8.8.8:3000... connected.
HTTP request sent, awaiting response... 200 OK
Length: 938848 (917K)
Saving to: “send”  --- 62,256      5.00K/s   in 12s     

2017-08-16 18:04:37 (5.00 KB/s) - Connection closed at byte 67724. Retrying.

--2017-08-16 18:04:40--  (try: 4)  http://8.8.8.8:3000/send
Connecting to 8.8.8.8:3000... connected.
HTTP request sent, awaiting response... 200 OK
Length: 938848 (917K)
Saving to: “send” --- 64,990      5.00K/s   in 13s     

2017-08-16 18:04:53 (5.00 KB/s) - Connection closed at byte 67724. Retrying.

---

It works when you don't set the Content-Length header:

> wget 8.8.8.8:3000/sendNoLength --limit-rate=5k

--2017-08-16 18:22:49--  http://8.8.8.8:3000/sendNoLength
Connecting to 8.8.8.8:3000... connected.
HTTP request sent, awaiting response... 200 OK
Length: unspecified
Saving to: “sendNoLength”

2017-08-16 18:25:52 (5.00 KB/s) - “sendNoLength” saved [938848]

---

Paper trail of how I got here
angular/angular-cli#7197
webpack/webpack-dev-server#1044
expressjs/express#3392

[bnoordhuis]

I'm afraid I can't reproduce and honestly, I can't think of anything in node that would cause that. I think a more likely explanation is that there is something on your local system or network that causes the issue.

[mtraynham]

@bnoordhuis If it helps, instead of using Linux Mint 18 as the node server, I've tried hosting on a Mac OSX Sierra (10.12.6) from a completely different network and it's happening here as well. The differences here being, size of words file and it seemingly takes much longer than 15 seconds, instead taking about 50-70 seconds. I'm not sure if the connection closing at the same byte every time is somewhat suspect.

Node 8.4.0
Mac OSX 10.12.6

(obfuscated my IPs)

--2017-08-18 07:34:26--  http://8.8.8.9:3000/send
Connecting to 8.8.8.9:3000... connected.
HTTP request sent, awaiting response... 200 OK
Length: 2493109 (2.4M)
Saving to: ‘send’ --- 148.37K  3.00KB/s    in 60s

2017-08-18 07:35:27 (2.48 KB/s) - Connection closed at byte 151935. Retrying.

--2017-08-18 07:35:28--  (try: 2)  http://8.8.8.9:3000/send
Connecting to 8.8.8.9:3000... connected.
HTTP request sent, awaiting response... 200 OK
Length: 2493109 (2.4M)
Saving to: ‘send’ --- 147.69K  2.49KB/s    in 67s

2017-08-18 07:36:36 (2.19 KB/s) - Connection closed at byte 151935. Retrying.

--2017-08-18 07:36:38--  (try: 3)  http://8.8.8.9:3000/send
Connecting to 8.8.8.9:3000... connected.
HTTP request sent, awaiting response... 200 OK
Length: 2493109 (2.4M)
Saving to: ‘send’ --- 145.55K  2.51KB/s    in 55s

2017-08-18 07:37:34 (2.63 KB/s) - Connection closed at byte 151935. Retrying.

--2017-08-18 07:37:37--  (try: 4)  http://8.8.8.9:3000/send
Connecting to 8.8.8.9:3000... connected.
HTTP request sent, awaiting response... 200 OK
Length: 2493109 (2.4M)
Saving to: ‘send’ ---  5.55K  3.00KB/s

[bnoordhuis]

I tried it on a different box with, going by the file size, probably the same words file as you (Ubuntu 16.04) and it still works. It takes about three minutes to download the file but it doesn't error, Content-Length header or not, local or external interface.

[mtraynham]

I also tried the MacOSX with Node 7.10.1 and it seems to work correctly. It does eventually timeout according to the server timeout, but it seems to be at almost 11 minutes rather than 10 which is weird...

> wget 8.8.8.9:3000/send --limit-rate=3k

--2017-08-18 07:55:54--  http://8.8.8.9:3000/send
Connecting to 8.8.8.9:3000... connected.
HTTP request sent, awaiting response... 200 OK
Length: 2493109 (2.4M)
Saving to: ‘send’ --- 1.42M  1.92KB/s    in 10m 56s

2017-08-18 08:06:59 (2.21 KB/s) - Connection closed at byte 1486335. Retrying.

--2017-08-18 08:07:00--  (try: 2)  http://8.8.8.9:3000/send
Connecting to 8.8.8.9:3000... connected.
HTTP request sent, awaiting response... 200 OK
Length: 2493109 (2.4M)
Saving to: ‘send’ --- 72.02K  2.52KB/s    eta 18m 50s

[mtraynham]

Also to add, I tried hosting on a bare bones AWS EC2 - Centos 6 (Linux 2.6.32-573.3.1.el6.x86_64 SMP Thu Aug 13 22:55:16 UTC 2015 x86_64 x86_64 x86_64 GNU/Linux) machine. I had to ship a different file, but it still experiences the same symptoms as before.

Previously, I had been using NVM to handle installations of Node, but this time I tried just the Linux x64 binaries. With v8.4.0, sure enough, it fails the request after about 15 seconds when Content-Length is set.

> wget http://8.8.8.8:3000/send --limit-rate=3k

--2017-08-18 09:23:07--  http://8.8.8.8:3000/send
Resolving 8.8.8.8 (8.8.8.8)... 8.8.8.8
Connecting to 8.8.8.8 (8.8.8.8)|8.8.8.8|:3000... connected.
HTTP request sent, awaiting response... 200 OK
Length: 19189239 (18M)
Saving to: ‘send.1’ --- 42.32K  3.00KB/s    in 14s     

2017-08-18 09:23:21 (3.00 KB/s) - Connection closed at byte 43334. Retrying.

--2017-08-18 09:23:22--  (try: 2)  http://8.8.8.8:3000/send
Connecting to 8.8.8.8 (8.8.8.8)|8.8.8.8|:3000... connected.
HTTP request sent, awaiting response... 200 OK
Length: 19189239 (18M)
Saving to: ‘send.1’ --- 42.32K  3.00KB/s    in 14s     

2017-08-18 09:23:37 (3.00 KB/s) - Connection closed at byte 43334. Retrying.

--2017-08-18 09:23:39--  (try: 3)  http://8.8.8.8:3000/send
Connecting to 8.8.8.8 (8.8.8.8)|8.8.8.8|:3000... connected.
HTTP request sent, awaiting response... 200 OK
Length: 19189239 (18M)
Saving to: ‘send.1’ ---  5.55K  3.00KB/s

Tried the v7.10.1 binary and it seems to timeout at about 10 minutes per server timeout.

> wget http://8.8.8.8:3000/send --limit-rate=3k

--2017-08-18 09:26:04--  http://8.8.8.8:3000/send
Resolving 8.8.8.8 (8.8.8.8)... 8.8.8.8
Connecting to 8.8.8.8 (8.8.8.8)|8.8.8.8|:3000... connected.
HTTP request sent, awaiting response... 200 OK
Length: 19189239 (18M)
Saving to: ‘send’ ---  1.79M  3.00KB/s    in 10m 10s

2017-08-18 09:36:14 (3.00 KB/s) - Connection closed at byte 1873606. Retrying.

Tried with v8.0.0 binary, and it seems to fail at 15 seconds like before.

> wget http://8.8.8.8:3000/send --limit-rate=3k

--2017-08-18 09:49:55--  http://8.8.8.8:3000/send
Resolving 8.8.8.8 (8.8.8.8)... 8.8.8.8
Connecting to 8.8.8.8 (8.8.8.8)|8.8.8.8|:3000... connected.
HTTP request sent, awaiting response... 200 OK
Length: 19189239 (18M)
Saving to: ‘send.1’ --- 40.90K  3.00KB/s    in 14s     

2017-08-18 09:50:08 (3.00 KB/s) - Connection closed at byte 41886. Retrying.

--2017-08-18 09:50:09--  (try: 2)  http://8.8.8.8:3000/send
Connecting to 8.8.8.8 (8.8.8.8)|8.8.8.8|:3000... connected.
HTTP request sent, awaiting response... 200 OK
Length: 19189239 (18M)
Saving to: ‘send.1’ --- 42.32K  3.00KB/s    in 14s     

2017-08-18 09:50:23 (3.00 KB/s) - Connection closed at byte 43334. Retrying.

--2017-08-18 09:50:25--  (try: 3)  http://8.8.8.8:3000/send
Connecting to 8.8.8.8 (8.8.8.8)|8.8.8.8|:3000... connected.
HTTP request sent, awaiting response... 200 OK
Length: 19189239 (18M)
Saving to: ‘send.1’ --- 42.32K  3.00KB/s    in 14s     

2017-08-18 09:50:40 (3.00 KB/s) - Connection closed at byte 43334. Retrying.

[sk91]

same issue node v8.4.0

[sk91]

@mtraynham it seems to be related to this commit: a7f5c9c

server.keepAliveTimeout = 120000 * 5;

will fix your test

[mtraynham]

@sk91 You are a life saver! I do believe that is it!

It looks like this has already been discovered and fixed with #13391, so I will close this and convey the message back upstream to the other issues that lead me here.