fix: tweak keep-alive timeout implementation (#3145)

* fix: tweak keep-alive timeout implementation

Closes #3141

* fix test impacted by default keepAliveTimeoutThreshold change

* adjust timer registration strategy

* only use fast timers with delay > 1000ms

docs/docs/api/Client.md

@@ -23,7 +23,7 @@ Returns: `Client`
 * **headersTimeout** `number | null` (optional) - Default: `300e3` - The amount of time, in milliseconds, the parser will wait to receive the complete HTTP headers while not sending the request. Defaults to 300 seconds.
 * **keepAliveMaxTimeout** `number | null` (optional) - Default: `600e3` - The maximum allowed `keepAliveTimeout`, in milliseconds, when overridden by *keep-alive* hints from the server. Defaults to 10 minutes.
 * **keepAliveTimeout** `number | null` (optional) - Default: `4e3` - The timeout, in milliseconds, after which a socket without active requests will time out. Monitors time between activity on a connected socket. This value may be overridden by *keep-alive* hints from the server. See [MDN: HTTP - Headers - Keep-Alive directives](https://developer.mozilla.org/en-US/docs/Web/HTTP/Headers/Keep-Alive#directives) for more details. Defaults to 4 seconds.
-* **keepAliveTimeoutThreshold** `number | null` (optional) - Default: `1e3` - A number of milliseconds subtracted from server *keep-alive* hints when overriding `keepAliveTimeout` to account for timing inaccuracies caused by e.g. transport latency. Defaults to 1 second.
+* **keepAliveTimeoutThreshold** `number | null` (optional) - Default: `2e3` - A number of milliseconds subtracted from server *keep-alive* hints when overriding `keepAliveTimeout` to account for timing inaccuracies caused by e.g. transport latency. Defaults to 2 seconds.
 * **maxHeaderSize** `number | null` (optional) - Default: `--max-http-header-size` or `16384` - The maximum length of request headers in bytes. Defaults to Node.js' --max-http-header-size or 16KiB.
 * **maxResponseSize** `number | null` (optional) - Default: `-1` - The maximum length of response body in bytes. Set to `-1` to disable.
 * **pipelining** `number | null` (optional) - Default: `1` - The amount of concurrent requests to be sent over the single TCP/TLS connection according to [RFC7230](https://tools.ietf.org/html/rfc7230#section-6.3.2). Carefully consider your workload and environment before enabling concurrent requests as pipelining may reduce performance if used incorrectly. Pipelining is sensitive to network stack settings as well as head of line blocking caused by e.g. long running requests. Set to `0` to disable keep-alive connections.

lib/dispatcher/client.js

@@ -226,7 +226,7 @@ class Client extends DispatcherBase {
     this[kMaxHeadersSize] = maxHeaderSize || http.maxHeaderSize
     this[kKeepAliveDefaultTimeout] = keepAliveTimeout == null ? 4e3 : keepAliveTimeout
     this[kKeepAliveMaxTimeout] = keepAliveMaxTimeout == null ? 600e3 : keepAliveMaxTimeout
-    this[kKeepAliveTimeoutThreshold] = keepAliveTimeoutThreshold == null ? 1e3 : keepAliveTimeoutThreshold
+    this[kKeepAliveTimeoutThreshold] = keepAliveTimeoutThreshold == null ? 2e3 : keepAliveTimeoutThreshold
     this[kKeepAliveTimeoutValue] = this[kKeepAliveDefaultTimeout]
     this[kServerName] = null
     this[kLocalAddress] = localAddress != null ? localAddress : null

lib/util/timers.js

@@ -1,5 +1,7 @@
 'use strict'
 
+const TICK_MS = 499
+
 let fastNow = Date.now()
 let fastNowTimeout
 
@@ -14,7 +16,7 @@ function onTimeout () {
     const timer = fastTimers[idx]
 
     if (timer.state === 0) {
-      timer.state = fastNow + timer.delay
+      timer.state = fastNow + timer.delay - TICK_MS
     } else if (timer.state > 0 && fastNow >= timer.state) {
       timer.state = -1
       timer.callback(timer.opaque)
@@ -43,7 +45,7 @@ function refreshTimeout () {
     fastNowTimeout.refresh()
   } else {
     clearTimeout(fastNowTimeout)
-    fastNowTimeout = setTimeout(onTimeout, 1e3)
+    fastNowTimeout = setTimeout(onTimeout, TICK_MS)
     if (fastNowTimeout.unref) {
       fastNowTimeout.unref()
     }
@@ -83,7 +85,7 @@ class Timeout {
 
 module.exports = {
   setTimeout (callback, delay, opaque) {
-    return delay < 1e3
+    return delay <= 1e3
       ? setTimeout(callback, delay, opaque)
       : new Timeout(callback, delay, opaque)
   },

test/node-test/balanced-pool.js

@@ -491,7 +491,7 @@ describe('weighted round robin', () => {
       const urls = servers.map(server => `http://localhost:${server.port}`)
 
       // add upstreams
-      const client = new BalancedPool(urls[0], { maxWeightPerServer, errorPenalty })
+      const client = new BalancedPool(urls[0], { maxWeightPerServer, errorPenalty, keepAliveTimeoutThreshold: 100 })
       urls.slice(1).map(url => client.addUpstream(url))
 
       let connectionRefusedErrors = 0

test/util.js

@@ -1,10 +1,12 @@
 'use strict'
 
+const { tspl } = require('@matteo.collina/tspl')
 const { strictEqual, throws, doesNotThrow } = require('node:assert')
 const { test, describe } = require('node:test')
 const { isBlobLike, parseURL, isHttpOrHttpsPrefixed, isValidPort } = require('../lib/core/util')
 const { Blob, File } = require('node:buffer')
 const { InvalidArgumentError } = require('../lib/core/errors')
+const timers = require('../lib/util/timers')
 
 describe('isBlobLike', () => {
   test('buffer', () => {
@@ -253,3 +255,79 @@ describe('parseURL', () => {
     })
   })
 })
+
+describe('timers', () => {
+  const getDelta = (start, target) => {
+    const end = process.hrtime.bigint()
+    const actual = (end - start) / 1_000_000n
+    return actual - BigInt(target)
+  }
+
+  // timers.setTimeout impelements a low resolution timer with a 500 ms granularity
+  // It is expected that in the worst case, a timer will fire about 500 ms after the
+  // intended amount of time, an extra 200 ms is added to account event loop overhead
+  // Timers should never fire excessively early, 1ms early is tolerated
+  const ACCEPTABLE_DELTA = 700n
+
+  test('meet acceptable resolution time', async (t) => {
+    const testTimeouts = [0, 1, 499, 500, 501, 990, 999, 1000, 1001, 1100, 1400, 1499, 1500, 4000, 5000]
+
+    t = tspl(t, { plan: 1 + testTimeouts.length * 2 })
+
+    const start = process.hrtime.bigint()
+
+    for (const target of testTimeouts) {
+      timers.setTimeout(() => {
+        const delta = getDelta(start, target)
+
+        t.ok(delta >= -1n, `${target}ms fired early`)
+        t.ok(delta < ACCEPTABLE_DELTA, `${target}ms fired late`)
+      }, target)
+    }
+
+    setTimeout(() => t.ok(true), 6000)
+    await t.completed
+  })
+
+  test('refresh correctly with timeout < TICK_MS', async (t) => {
+    t = tspl(t, { plan: 3 })
+
+    const start = process.hrtime.bigint()
+
+    const timeout = timers.setTimeout(() => {
+      // 400 ms timer was refreshed after 600ms; total target is 1000
+      const delta = getDelta(start, 1000)
+
+      t.ok(delta >= -1n, 'refreshed timer fired early')
+      t.ok(delta < ACCEPTABLE_DELTA, 'refreshed timer fired late')
+    }, 400)
+
+    setTimeout(() => timeout.refresh(), 200)
+    setTimeout(() => timeout.refresh(), 400)
+    setTimeout(() => timeout.refresh(), 600)
+
+    setTimeout(() => t.ok(true), 1500)
+    await t.completed
+  })
+
+  test('refresh correctly with timeout > TICK_MS', async (t) => {
+    t = tspl(t, { plan: 3 })
+
+    const start = process.hrtime.bigint()
+
+    const timeout = timers.setTimeout(() => {
+      // 501ms timer was refreshed after 1250ms; total target is 1751
+      const delta = getDelta(start, 1751)
+
+      t.ok(delta >= -1n, 'refreshed timer fired early')
+      t.ok(delta < ACCEPTABLE_DELTA, 'refreshed timer fired late')
+    }, 501)
+
+    setTimeout(() => timeout.refresh(), 250)
+    setTimeout(() => timeout.refresh(), 750)
+    setTimeout(() => timeout.refresh(), 1250)
+
+    setTimeout(() => t.ok(true), 3000)
+    await t.completed
+  })
+})