requestTimeout and long running uploads

[julien-f]

Version

v18.14.0

Platform

Linux prometheus 6.1.9-200.fc37.x86_64 #1 SMP PREEMPT_DYNAMIC Thu Feb 2 00:21:48 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux

Subsystem

http

What steps will reproduce the bug?

Create an HTTP server with a big requestTimeout (a day in this example):

require('node:http').createServer({
  requestTimeout: 24 * 60 * 60 * 1e3, // a day
}, (req, res) => {
  console.log(req.method, req.url);

  req.resume().on('end', () => {
    res.end('Ok');
  }).on('error', console.warn);
}
).listen(8080);

Do a long running request to it:

$ curl -T /dev/urandom http://localhost:8080 -v
*   Trying 127.0.0.1:8080...
* Connected to localhost (127.0.0.1) port 8080 (#0)
> PUT /urandom HTTP/1.1
> Host: localhost:8080
> User-Agent: curl/7.85.0
> Accept: */*
> Transfer-Encoding: chunked
> Expect: 100-continue
> 
* Mark bundle as not supporting multiuse
< HTTP/1.1 100 Continue
* Mark bundle as not supporting multiuse
< HTTP/1.1 408 Request Timeout
< Connection: close
< 
* Send failure: Connection reset by peer
* Closing connection 0
curl: (55) Send failure: Connection reset by peer

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

It happens everytime, and I haven't been able to pinpoint the exact value at which it becomes problematic.

What is the expected behavior?

It should interrupt the request after 24 hours.

What do you see instead?

It interrupt the request after ~30 seconds.

Additional information

I can work-around by disabling the timeout (requestTimeout: 0) completely but setting a value, even high, seemed preferable.

Any other suggestions on how to handle long running uploads?

[theanarkh]

Try this.

require('node:http').createServer({
  requestTimeout: 24 * 60 * 60 * 1e3, // a day
  connectionsCheckingInterval: 24 * 60 * 60 * 1e3
}, (req, res) => {
  console.log(req.method, req.url);

  req.resume().on('end', () => {
    res.end('Ok');
  }).on('error', console.warn);
}
).listen(8080);

[julien-f]

@theanarkh Why? What do you expect to see with this?

From what I understand, there is still an issue in how requestTimeout is handled, and even if connectionsCheckingInterval works, it will check all connections every 24 hours, this will not guarantee that a specific connection can stay open for 24 hours.

[julien-f]

@ShogunPanda Any opinions on this?

[ShogunPanda]

Inside the connection handling algorithm I always use uv_hrtime to track connections.

@nodejs/libuv Do you think this might explain it?

[bnoordhuis]

@ShogunPanda explain what exactly?

[ShogunPanda]

@bnoordhuis I re-read it and got it wrong probably. I'll try to reproduce and see what happens. I'll get back here shortly.

[StephenKelly94]

I have been experiencing the same issue. I set a requestTimeout to 2 hours, and was seeing the same result (connection reset by peer after ~30 seconds).

I noticed though after 2 hours of uptime on the system it started to work correctly. After this I set the requestTimeout to 5 minutes and sure enough it started working after 5 minutes uptime. So perhaps it's related to system uptime?

So I opted to set the requestTimeout to 0, and this fixes the issue for now.

[ShogunPanda]

Unfortunately I cannot reproduce this. I tried both on a Mac and on Linux.
Given you were mentioning uptime of the system and time of the day, can you provide more info so I can take a look?

[julien-f]

I don't see anything related to the uptime of my machine.

@ShogunPanda What behavior do you get with my test script above? On my system (and others like Ubuntu), curl get an ECONNRESET before 30 seconds.

[ShogunPanda]

@julien-f In my case the server keeps receiving the request without issues.

[StephenKelly94]

So I altered the @julien-f script to work more closely with how we have encountered it.

Node Version: 18.12.1

const http = require('node:http');
const srv = http.createServer((req, res) => {
    console.log(req.method, req.url);

    req.resume().on('end', () => {
        res.end('Ok');
    }).on('error', console.warn);
}
).listen(10080);
srv.requestTimeout = 10 * 60 * 1000; // 10 minute timeout

I get the following output before 10 minutes uptime:

$ uptime
07:44:46 up 5 min,  0 users,  load average: 29.40, 19.92, 8.74
$ curl -T /dev/urandom http://localhost:10080 | cat
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100  211M    0     0    0  211M      0  20.0M --:--:--  0:00:10 --:--:-- 20.6M
curl: (55) Send failure: Broken pipe
$ curl -T /dev/urandom http://localhost:10080 | cat
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100  256M    0     0    0  256M      0  20.8M --:--:--  0:00:12 --:--:-- 21.3M
curl: (55) Send failure: Broken pipe

After 10 minutes of uptime it looks like this:

$ uptime
 07:56:26 up 16 min,  0 users,  load average: 2.90, 6.76, 8.16
$ curl -T /dev/urandom http://localhost:10080 | cat
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100 13.3G    0     0    0 13.3G      0  21.9M --:--:--  0:10:25 --:--:-- 22.3M
curl: (55) Send failure: Broken pipe
$ curl -T /dev/urandom http://localhost:10080 | cat
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100 12.8G    0     0    0 12.8G      0  21.9M --:--:--  0:10:01 --:--:-- 21.2M
curl: (55) Send failure: Broken pipe

I'm not sure if I'm missing anything or if setting the requestTimeout after the server is instantiated makes a difference.