Race condition at-or-near keep-alive expiration about undici HOT 6 CLOSED

The problem is timers always fire at least 1000ms after the provided timeout in the best case, and 2000ms after provided in the "best worst case" - ie just unlucky with the scheduling time, but no event loop contention.

Test case

const timers = require("./timers.js")

// needed because timers in `./timers.js` are unref-ed
setTimeout(() => {
    console.log("10s elapsed, exiting")
    process.exit(0)
}, 10000)

for(const target of [1000, 1500, 1990, 1999, 2000, 2001, 2500, 2990, 2999, 3000, 4000, 5000]) {
    const start = process.hrtime.bigint()
    timers.setTimeout(() => {
        const end = process.hrtime.bigint()
        console.log(`target = ${target}, actual = ${(end - start) / 1_000_000n}`)
    }, target)
}

Result

% node test-latency.js
target = 1000, actual = 2002
target = 1500, actual = 3020
target = 1990, actual = 3020
target = 1999, actual = 3020
target = 2000, actual = 3020
target = 2001, actual = 3021
target = 3000, actual = 4022
target = 2500, actual = 4023
target = 2990, actual = 4023
target = 2999, actual = 4024
target = 4000, actual = 5026
target = 5000, actual = 6028
10s elapsed, exiting

Which means for a server sent 5000 ms keep-alive and 1000ms default keepAliveTimeoutThreshold, the target is 4000, and the actual timeout is always too late - 5000ms or more.

Happy to propose a solution via PR, or @ronag jump in if you prefer.

Edit: I'm think best course of action is:

1. increase default keepAliveTimeoutThreshold to 2000ms
2. double the "tick rate" of the fast timeout code by reducing the setTimeout calls from 1000 to 500
3. subtract 500 from the requested timeout duration -- that means in the best case, the timer will fire exactly when called for.

Taking all three changes together, that means given a 5000ms keep alive, best case scenario we close the connection after 3000ms, best-worst case (ie- timeout scheduled just after a previous timeout was scheduled) it takes 3500ms, and then that leaves 1500ms of breathing room in the worst-worst case if the event loop is blocked.

from undici.

Regardless of the default, it appears to not be working as expected, and the cause is looking to be in lib/util/timers:

If I stub out the fast timers implementation, then no errors:

module.exports = {
  setTimeout (callback, delay, opaque) {
    return setTimeout(callback, delay, opaque)
  },

I will continue looking into lib/util/timers.

from undici.

Looking closer at the logs, I don't think there's anything undici can do. The socket is being closed by the server after the 2nd request has been sent, as far as I can tell.

...
FETCH 27254: sending request to GET http://127.0.0.1:3000//
TIMER 27254: 4990 list empty
NET 27254: destroy
NET 27254: close
NET 27254: close handle
NET 27254: emit close
FETCH 27254: request to GET http://127.0.0.1:3000// errored - read ECONNRESET
node:internal/deps/undici/undici:12500
      Error.captureStackTrace(err, this);
            ^

TypeError: fetch failed
    at node:internal/deps/undici/undici:12500:13
    at async Timeout.start [as _onTimeout] (/Users/matt/code/replicate-undici-3133/client.js:6:15) {
  [cause]: Error: read ECONNRESET
      at TCP.onStreamRead (node:internal/stream_base_commons:217:20) {
    errno: -54,
    code: 'ECONNRESET',
    syscall: 'read'
  }
}

Node.js v21.7.3

from undici.

one option could be to always add the retry interceptor for gets (and just retry them).

for posts and all non-idempotent requests is a bit more tricky.

from undici.

What is the goal of keepAliveTimeoutThreshold? With a Keep-Alive: timeout=5 returned by the server, and a default keepAliveTimeoutThreshhold of 1000ms, is it unexpected that after 4900ms a request sent on the existing connection?

from undici.

I think we should always be keeping 2s (or more) to account for slow networks. So if the server gives us 5s, we should actually consider it 3s.

from undici.