HTTP: Connection resets after 60 seconds in node.js upload application

[ipbc-dev]

• Version: v12.19.0
• Platform: Linux snip 4.15.0-121-generic Async listener removal also drops tracing #123-Ubuntu SMP Mon Oct 5 16:16:40 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux (Ubuntu 18.04.5 LTS)
• Subsystem: http

What steps will reproduce the bug?

The client depends on node-fetch v2.6.1

testServer.js

// -- DevNull Start --
var util         = require('util')
  , stream       = require('stream')
  , Writable     = stream.Writable
  , setImmediate = setImmediate || function (fn) { setTimeout(fn, 0) }
  ;
util.inherits(DevNull, Writable);
function DevNull (opts) {
  if (!(this instanceof DevNull)) return new DevNull(opts);
  opts = opts || {};
  Writable.call(this, opts);
}
DevNull.prototype._write = function (chunk, encoding, cb) {
  setImmediate(cb);
}
// -- DevNull End --
const http = require('http');
const server = http.createServer();
server.on('request', async (req, res) => {
  try {
    req.socket.on('end', function() { 
      console.log('SOCKET END: other end of the socket sends a FIN packet');
    });
    req.socket.on('timeout', function() { 
      console.log('SOCKET TIMEOUT');
    });
    req.socket.on('error', function(error) { 
      console.log('SOCKET ERROR: ' + JSON.stringify(error));
    });
    req.socket.on('close', function(had_error) { 
      console.log('SOCKET CLOSED. IT WAS ERROR: ' + had_error);
    });
    const writeStream = DevNull();
    const promise = new Promise((resolve, reject) => {
      req.on('end', resolve);
      req.on('error', reject);
    });
    req.pipe(writeStream);
    await promise;
    res.writeHead(200);
    res.end('OK');
  } catch (err) {
    res.writeHead(500);
    res.end(err.message);
  }
});
server.listen(8081)
  .on('listening', () => { console.log('Listening on port', server.address().port); });

testClient.js

// -- RandomStream Start --
var crypto = require('crypto');
var stream = require('stream');
var util = require('util');
var Readable = stream.Readable;
function RandomStream(length, options) {
  // allow calling with or without new
  if (!(this instanceof RandomStream)) {
    return new RandomStream(length, options);
  }
  // init Readable
  Readable.call(this, options);
  // save the length to generate
  this.lenToGenerate = length;
}
util.inherits(RandomStream, Readable);
RandomStream.prototype._read = function (size) {
  if (!size) size = 1024; // default size
  var ready = true;
  while (ready) { // only cont while push returns true
    if (size > this.lenToGenerate) { // only this left
      size = this.lenToGenerate;
    }
    if (size) {
      ready = this.push(crypto.randomBytes(size));
      this.lenToGenerate -= size;
    }
    // when done, push null and exit loop
    if (!this.lenToGenerate) {
      this.push(null);
      ready = false;
    }
  }
};
// -- RandomStream End --
const fetch = require('node-fetch');
const runSuccess = async () => { // Runs in ~35 seconds
  const t = Date.now();
  try {
    const resp = await fetch('http://localhost:8081/test', {
      method: 'PUT',
      body: new RandomStream(256e6) // new RandomStream(1024e6)
    });
    const data = await resp.text();
    console.log(Date.now() - t, data);
  } catch (err) {
    console.warn(Date.now() - t, err);
  }
};
const runFail = async () => { // Fails after 60 seconds
  const t = Date.now();
  try {
    const resp = await fetch('http://localhost:8081/test', {
      method: 'PUT',
      body: new RandomStream(1024e6)
    });
    const data = await resp.text();
    console.log(Date.now() - t, data);
  } catch (err) {
    console.warn(Date.now() - t, err);
  }
};
// runSuccess().then(() => process.exit(0));
runFail().then(() => process.exit(0));

• Install node-fetch in the same folder as the reproduction scripts: npm i node-fetch
• Start the server with node testServer.js - This creates a new HTTP server listening on port 8081
• Run the client with node testClient.js

How often does it reproduce? Is there a required condition?

The value inside RandomStream needs to be high enough to cause the request to take longer than 60 seconds.

What is the expected behavior?

In Node.js 10:

$ node testClient.js
145014 'OK'

What do you see instead?

In Node.js 12:

$ node testClient.js
60014 FetchError: request to http://localhost:8081/test failed, reason: write ECONNRESET
    at ClientRequest.<anonymous> (/home/*snip*/node_modules/node-fetch/lib/index.js:1461:11)
    at ClientRequest.emit (events.js:326:22)
    at Socket.socketErrorListener (_http_client.js:428:9)
    at Socket.emit (events.js:314:20)
    at errorOrDestroy (internal/streams/destroy.js:108:12)
    at onwriteError (_stream_writable.js:418:5)
    at onwrite (_stream_writable.js:445:5)
    at internal/streams/destroy.js:50:7
    at Socket._destroy (net.js:681:5)
    at Socket.destroy (internal/streams/destroy.js:38:8) {
  type: 'system',
  errno: 'ECONNRESET',
  code: 'ECONNRESET'
}

Additional information

If there is any workaround, please let me know.

[mhemrg]

I'm facing the same issue on the same platform.

[ronag]

Do you think you could try to create a more minimal repro? Maybe without using node-fetch?

[ipbc-dev]

For the moment no, however I was able to fuss with this a bit more.

Setting server.headersTimeout = 10000; as the last line of the server. Then the reproduction client returns:
10041 FetchError: request to http://localhost:8081/test failed, reason: read ECONNRESET

Setting server.headersTimeout = 0; causes the reproduction client to return a similar output to Node.js 10

[andrewnester]

Experiencing the same issue on Node 12.9.0 but not Node 12.8.2.

Could this change be related to the issue?
#32329

[neversun]

@ronag

I created a repro without node-fetch based on @ipbc-dev's code: https://github.com/neversun/node-issue-35661

There are 3 examples of a working (short) request, a long one with around 2 MB of data and a long but slow one with ~100KB of data.

What I see is, that it works on 12.18.2 and fails on 12.19.0:

{CLIENT} [read] 60.948s, size of read 16384, left 147456
{CLIENT} Error: socket hang up
    at connResetException (internal/errors.js:609:14)
    at Socket.socketOnEnd (_http_client.js:459:23)
    at Socket.emit (events.js:326:22)
    at endReadableNT (_stream_readable.js:1223:12)
    at processTicksAndRejections (internal/process/task_queues.js:84:21) {
  code: 'ECONNRESET'
}

Also I found a strange thing to happen on 12.19.0 if you attach a timeout handler like...

const server = http.createServer()

// server.on('request', async (req, res) => {
// ...
// })

server.on('timeout', () => {
  console.log('timeout')
})

...then the timeout handler is going to be called at around 60s. The request will come to a successful end then.
The timeout handler is not called on 12.18.2.

EDIT:
Platform: macOS (System Version: macOS 10.15.7 (19H2), Kernel Version: Darwin 19.6.0)

[ronag]

@nodejs/http

[orgads]

The problem is in the server. Here's a minimal example with no dependencies. It creates a server and a client which opens a POST request and keeps transmitting all the time. After 8s it is considered a success. With Node 12.19.0 it fails after 5s with "Premature close".

const http = require('http');
const stream = require('stream');
const time = () => new Date().toISOString();
const server = http.createServer((req, res) => {
  console.log(time(), 'Received request');
  stream.finished(req, (error) => {
    console.error(time(), 'Stream error:', error && error.message);
    process.exit(1);
  });
});
server.headersTimeout = 5000;
server.listen(7000);

const options = {
  host: 'localhost',
  port: 7000,
  path: '/',
  method: 'POST',
  headers: {
    'Content-Type': 'application/x-octet-stream'
  }
};

var req = http.request(options);
req.on('error', (err) => console.error(time(), 'client error', err));

// post the data
setInterval(() => req.write('hello'), 100);

setTimeout(() => {
  console.log(time(), 'Success!');
  process.exit(0);
}, 8000);

Call stack on error:

<anonymous> (f:\Projects\jstest\test.js:7)
<anonymous> (<node_internals>/internal/util.js:392)
onclose (<node_internals>/internal/streams/end-of-stream.js:76)
emit (<node_internals>/events.js:314)
abortIncoming (<node_internals>/_http_server.js:533)
socketOnClose (<node_internals>/_http_server.js:526)
emit (<node_internals>/events.js:326)
<anonymous> (<node_internals>/net.js:676)
callbackTrampoline (<node_internals>/internal/async_hooks.js:126)
TCPWRAP (Unknown Source:1)
init (<node_internals>/internal/inspector_async_hook.js:25)
emitInitNative (<node_internals>/internal/async_hooks.js:195)

[orgads]

I also suspect #34131. It doesn't reproduce with 14.14.0, so I suppose the backport was partial, or it depends on another commit that was not backported?

[ronag]

Maybe missing da4d8de?

[orgads]

Makes a lot of sense :)

[ronag]

backport PR welcome

[ronag]

@mcollina @addaleax FYI This seems like a valid issue.