Shorter than expected headers timeout exception is fired

[kajiiiro]

Bug Description

i update v5.15.0 -> v5.18.0, it increased unexpected headers timeout exception. my condition is

• set headersTimeout 1000msec
• under high load
• destination server response in about 50msec but it fired headers timeout.

i see lib/timers.js set invalid expired time. https://github.com/nodejs/undici/blob/main/lib/timers.js#L72

fastNow is expected current time,fastNow is updated in onTimeout function. Normally onTimeout is called in 1000msec. But under high load onTimeout is called in over 1000msec.

Reproducible By

I checked fastNow and Date.now().

add console.log after this line. console.log('diff', Date.now() - fastNow) https://github.com/nodejs/undici/blob/main/lib/timers.js#L72

exec the following code.

"use strict";
const request = require("undici").request;

const sleep = msec => new Promise(resolve => setTimeout(resolve, msec));

const port = 3000;
const server = require("express")()
server.get('/', (_, res) => { res.send('ok') });
server.listen(port, async () => {
    for (let j = 0; j < 100; ++j) {
        for (let i = 0; i < 50; ++i) {
            request(`http://localhost:${port}`, { headersTimeout: 500 })
                .catch(error => { console.error(error); process.exit(1) })
        }
        await sleep(100)
    }
})

setTimeout(() => { process.exit(0) }, 10 * 1000)

output

diff 918
...

Expected Behavior

expired = current time(timers.setTimeout called time) + delay.

Logs & Screenshots

Environment

Node v18 undici ^5.18.0

Additional context

it is fixed the following code.

diff --git a/lib/timers.js b/lib/timers.js
index 4f4fcea4..955c4f34 100644
--- a/lib/timers.js
+++ b/lib/timers.js
@@ -65,10 +65,10 @@ class Timeout {
       fastTimers.push(this)
       if (!fastNowTimeout || fastTimers.length === 1) {
         refreshTimeout()
-        fastNow = Date.now()
       }
     }

+    fastNow = Date.now()
     this.expires = fastNow + this.delay
   }

[ronag]

Can you try with https://github.com/nodejs/undici/pull/1977?

[kajiiiro]

@ronag i change server response over 1000msec, but i don't see timeout.

https://github.com/nodejs/undici/pull/1977/files#r1121362150

[ronag]

Do you have a test case I can use?

[kajiiiro]

@ronag

"use strict";

const request = require("undici").request;

const sleep = msec => new Promise(resolve => setTimeout(resolve, msec));

const port = 3000;
const server = require("express")()

server.get('/', async (_, res) => { await sleep(1000); res.send('ok') });

server.listen(port, async () => {
    for (let j = 0; j < 100; ++j) {
        for (let i = 0; i < 100; ++i) {
            console.time(`${j}-${i}`);
            request(`http://localhost:${port}`, { headersTimeout: 1000 })
                .then(() => { console.timeEnd(`${j}-${i}`) })
                .catch(error => { console.timeEnd(`${j}-${i}`); console.error(error); process.exit(1) })
        }
        await sleep(100)
    }
})

setTimeout(() => { process.exit(0) }, 10 * 1000)

[ronag]

@kajiiiro What am I supposed to see? I only get a spam of numbers in the log... could you write it as a test?

[kajiiiro]

@ronag Reproduced in an existing test.

diff --git a/test/request-timeout.js b/test/request-timeout.js
index 3ec5c107..ae92847d 100644
--- a/test/request-timeout.js
+++ b/test/request-timeout.js
@@ -28,7 +28,7 @@ test('request timeout', (t) => {
   t.teardown(server.close.bind(server))

   server.listen(0, () => {
-    const client = new Client(`http://localhost:${server.address().port}`, { headersTimeout: 500 })
+    const client = new Client(`http://localhost:${server.address().port}`, { headersTimeout: 1000 })
     t.teardown(client.destroy.bind(client))

     client.request({ path: '/', method: 'GET' }, (err, response) => {

[ronag]

That makes the test invalid... the server delay is 1s so the exception doesn't occur.

[kajiiiro]

server delay set 1.5s, this test is fail. this problem depends on the frequency of the event loop(now, interval about 1sec). Doesn't it guarantee second accuracy(ex expected timeout + max 1sec??...)?

diff --git a/test/request-timeout.js b/test/request-timeout.js
index 3ec5c107..0cdd04b2 100644
--- a/test/request-timeout.js
+++ b/test/request-timeout.js
@@ -23,12 +23,12 @@ test('request timeout', (t) => {
   const server = createServer((req, res) => {
     setTimeout(() => {
       res.end('hello')
-    }, 1000)
+    }, 1500)
   })
   t.teardown(server.close.bind(server))

   server.listen(0, () => {
-    const client = new Client(`http://localhost:${server.address().port}`, { headersTimeout: 500 })
+    const client = new Client(`http://localhost:${server.address().port}`, { headersTimeout: 1000 })
     t.teardown(client.destroy.bind(client))

     client.request({ path: '/', method: 'GET' }, (err, response) => {

[ronag]

Accuracy is about 1 sec, not exactly. If you change it to 1.5 sec it's still within the margin of error.

[kajiiiro]

@ronag How about that user is set the event loop interval, like the following.

benefits

• timers code is testable like this issue
• users who want to improve accuracy can adjust

diff --git a/lib/timers.js b/lib/timers.js
index 4f4fcea4..5257d72c 100644
--- a/lib/timers.js
+++ b/lib/timers.js
@@ -2,6 +2,7 @@

 let fastNow = Date.now()
 let fastNowTimeout
+let fastNowEventLoopInterval = 1e3

 const fastTimers = []

@@ -41,7 +42,7 @@ function refreshTimeout () {
     fastNowTimeout.refresh()
   } else {
     clearTimeout(fastNowTimeout)
-    fastNowTimeout = setTimeout(onTimeout, 1e3)
+    fastNowTimeout = setTimeout(onTimeout, fastNowEventLoopInterval)
     if (fastNowTimeout.unref) {
       fastNowTimeout.unref()
     }
@@ -89,5 +90,8 @@ module.exports = {
     } else {
       clearTimeout(timeout)
     }
+  },
+  setEventLoopInterval (interval) {
+    fastNowEventLoopInterval = interval
   }
 }

[ronag]

I'm not sure I want to add that complexity.

[ronag]

I think https://github.com/nodejs/undici/pull/1977 will resolve your issue.