diff --git a/src/js/internal/timers.ts b/src/js/internal/timers.ts index ef48040fc6b8..f775dea62cb3 100644 --- a/src/js/internal/timers.ts +++ b/src/js/internal/timers.ts @@ -4,6 +4,16 @@ const NumberIsFinite = Number.isFinite; const TIMEOUT_MAX = 2 ** 31 - 1; +/** + * The real monotonic clock in whole milliseconds, for deadlines the runtime's + * own JS keeps (a mark recorded now and compared against when a timer fires). + * No JS-visible clock will do: bun:test's `setSystemTime()` overrides + * `Date.now()` inside the engine, and `useFakeTimers()` also overrides + * `performance.now()` and `process.hrtime()`, so a deadline measured with any + * of them freezes or jumps along with the mock. + */ +const monotonicNowMs = $newRustFunction("runtime/timer/Timer.rs", "internal_bindings.monotonicNowMs", 0); + function getTimerDuration(msecs, name) { validateNumber(msecs, name); if (msecs < 0 || !NumberIsFinite(msecs)) { @@ -29,4 +39,5 @@ export default { // tests that inspect socket[kTimeout]. kTimeout: Symbol.for("::buntimeout::"), getTimerDuration, + monotonicNowMs, }; diff --git a/src/js/node/_http_server.ts b/src/js/node/_http_server.ts index 89b6db00bacd..03e85bac9029 100644 --- a/src/js/node/_http_server.ts +++ b/src/js/node/_http_server.ts @@ -69,6 +69,7 @@ const { validateMsecs, } = require("internal/http"); const { FakeSocket } = require("internal/http/FakeSocket"); +const { monotonicNowMs } = require("internal/timers"); const NumberIsNaN = Number.isNaN; const { format } = require("internal/util/inspect"); @@ -120,7 +121,6 @@ const kEmptyBuffer = Buffer.alloc(0); const ObjectKeys = Object.keys; const MathMin = Math.min; const MathFloor = Math.floor; -const DateNow = Date.now; let cluster; @@ -1419,7 +1419,8 @@ const kKeepAliveTimeoutSet = Symbol("keepAliveTimeoutSet"); // When the keep-alive idle period on a connection started (the last response // finish). onResponseFinishHandleSocket records this instead of rescheduling // the socket timer on every response; onSocketTimeoutTimerExpired reads it to -// grant the remaining idle budget when the timer actually fires. +// grant the remaining idle budget when the timer actually fires. Read from +// monotonicNowMs(), which setSystemTime() / fake timers cannot move. const kKeepAliveIdleStart = Symbol("keepAliveIdleStart"); // HTTP/1.1 pipelining (responses queued behind an in-flight response): // - on the socket: array of queued ServerResponses, in arrival order @@ -1518,7 +1519,7 @@ function onSocketTimeoutTimerExpired(socket) { const idleStart = socket[kKeepAliveIdleStart]; if (idleStart !== undefined && socket[kKeepAliveTimeoutSet]) { socket[kKeepAliveIdleStart] = undefined; - const remaining = socket.timeout - (DateNow() - idleStart); + const remaining = socket.timeout - (monotonicNowMs() - idleStart); if (remaining > 0) { const existingTimer = socket[kSocketTimeoutTimer]; if (existingTimer !== undefined) clearTimeout(existingTimer); @@ -2512,14 +2513,17 @@ function onResponseFinishHandleSocket(server, socket, res) { // kept-alive connection), leave it in place and only record when this // idle period started; onSocketTimeoutTimerExpired grants the remaining // budget if the timer fires early, so the socket still closes after - // exactly `total` ms of idle. + // exactly `total` ms of idle. The mark is taken before the timer is armed: + // both are whole milliseconds, so a timer armed after the mark measures at + // least `total` when it fires and closes instead of re-arming for a + // rounding millisecond. + socket[kKeepAliveIdleStart] = monotonicNowMs(); const timer = socket[kSocketTimeoutTimer]; if (timer !== undefined && timer._idleTimeout === total) { socket.timeout = total; } else { socket.setTimeout(total); } - socket[kKeepAliveIdleStart] = DateNow(); socket[kKeepAliveTimeoutSet] = true; } } diff --git a/src/runtime/timer/Timer.rs b/src/runtime/timer/Timer.rs index 99d3b90ed1a1..792ff863c27b 100644 --- a/src/runtime/timer/Timer.rs +++ b/src/runtime/timer/Timer.rs @@ -596,4 +596,16 @@ pub(crate) mod internal_bindings { // `js_number(f64)` (i64 → f64 is lossless for the millisecond range). Ok(JSValue::js_number(now as f64)) } + + /// `require("internal/timers").monotonicNowMs()`, documented there. Always + /// the real clock, i.e. the one the real timer heap is drained against, + /// whatever bun:test has mocked. + #[bun_jsc::host_fn] + pub(crate) fn monotonic_now_ms( + _global_this: &JSGlobalObject, + _call_frame: &CallFrame, + ) -> JsResult { + let now = Timespec::now(TimespecMockMode::ForceRealTime).ms(); + Ok(JSValue::js_number(now as f64)) + } } diff --git a/test/js/node/http/node-http-server-timeouts.test.ts b/test/js/node/http/node-http-server-timeouts.test.ts index 98700bbdbec0..dd96f8f2a375 100644 --- a/test/js/node/http/node-http-server-timeouts.test.ts +++ b/test/js/node/http/node-http-server-timeouts.test.ts @@ -1,4 +1,4 @@ -import { describe, expect, test } from "bun:test"; +import { describe, expect, jest, setSystemTime, test } from "bun:test"; import { once } from "node:events"; import http from "node:http"; import net from "node:net"; @@ -218,3 +218,142 @@ describe("node:http server timeout enforcement", () => { } }); }); + +// The server notes when a connection's last response finished and, when the +// socket timer fires, grants whatever is left of the keep-alive budget from +// that mark. The mark has to be taken on the real monotonic clock: Date.now() +// follows bun:test's setSystemTime() and useFakeTimers(), and the mocked +// monotonic clock that useFakeTimers() installs starts over at zero, so a mark +// taken on either would decide when, or whether, an idle connection is closed. +// +// Each probe mocks the clock at some point, waits for the server to close the +// connection and reports how long after the last response that happened. It +// is timed with performance.now(), which setSystemTime() leaves alone and +// useFakeTimers() freezes, so the end is read only after the mocks are +// undone. Not concurrent: the mocks are process-wide and the tests above time +// themselves with Date.now(). +describe("keepAliveTimeout idle expiry ignores mocked clocks", () => { + const KEEP_ALIVE_MS = 500; + // How long the server sits on the second request before answering it. The + // socket timer armed by the first response keeps counting down meanwhile, + // so it fires KEEP_ALIVE_MS - SLOW_RESPONSE_MS (200ms) into the second + // response's idle period and the expiry has to be settled from the mark. + const SLOW_RESPONSE_MS = 300; + const HOUR_MS = 60 * 60 * 1000; + + async function probeIdleClose(options: { + requests: 1 | 2; + beforeRequests?: () => void; + afterLastResponse?: () => void; + }) { + // A probe that fails by timing out never reaches its cleanup; do not let + // its mocks leak into the next one. + jest.useRealTimers(); + setSystemTime(); + let requests = 0; + // Taken right before each res.end(), i.e. just before the server takes its + // own mark, so the idle time reported below can only be longer than what + // the server measured, never shorter because the response reached the + // client late. + let lastResponseEndedAt = 0; + const endResponse = (res: http.ServerResponse) => { + lastResponseEndedAt = performance.now(); + res.end("response-body"); + }; + const server = http.createServer({ keepAliveTimeoutBuffer: 0 }, (req, res) => { + req.resume(); + if (++requests === 2) { + setTimeout(endResponse, SLOW_RESPONSE_MS, res); + } else { + endResponse(res); + } + }); + server.keepAliveTimeout = KEEP_ALIVE_MS; + const port = await listen(server); + const socket = net.connect(port, "127.0.0.1"); + try { + socket.setNoDelay(true); + // An idle keep-alive close is a clean FIN; a reset or any other error + // would make this probe fail instead of timing an unrelated close. + const { promise: closed, resolve: onClosed, reject: onSocketError } = Promise.withResolvers(); + socket.on("error", onSocketError); + socket.on("close", () => onClosed()); + + let received = ""; + let responsesWanted = 0; + let onResponse = () => {}; + socket.on("data", chunk => { + received += chunk.toString("latin1"); + if (received.split("response-body").length - 1 >= responsesWanted) onResponse(); + }); + const request = () => { + const { promise, resolve } = Promise.withResolvers(); + responsesWanted++; + onResponse = resolve; + socket.write("GET / HTTP/1.1\r\nHost: a\r\n\r\n"); + return promise; + }; + + await once(socket, "connect"); + options.beforeRequests?.(); + await request(); + if (options.requests === 2) await request(); + options.afterLastResponse?.(); + await closed; + } finally { + jest.useRealTimers(); + setSystemTime(); + socket.destroy(); + server.closeAllConnections(); + server.close(); + } + return performance.now() - lastResponseEndedAt; + } + + test("a clock moved forwards does not close the connection before its idle budget is used up", async () => { + // Settled against Date.now(), the timer fire 200ms into the second idle + // period sees an hour of idle time and closes the connection right there. + const idleMs = await probeIdleClose({ + requests: 2, + afterLastResponse: () => setSystemTime(new Date(Date.now() + HOUR_MS)), + }); + expect(idleMs).toBeGreaterThanOrEqual(KEEP_ALIVE_MS - 150); + }); + + test("a pinned clock does not double the idle budget", async () => { + // Settled against a Date.now() that never advances, the timer fire sees + // no idle time at all and re-arms for the whole budget once more, so the + // connection is closed after two budgets. That floor does not depend on + // machine speed, which is what makes the upper bound safe. + const idleMs = await probeIdleClose({ + requests: 1, + beforeRequests: () => setSystemTime(new Date("2020-01-01T00:00:00Z")), + }); + expect(idleMs).toBeGreaterThanOrEqual(KEEP_ALIVE_MS - 150); + expect(idleMs).toBeLessThan(2 * KEEP_ALIVE_MS); + }); + + test("a clock moved backwards does not keep the idle connection open", async () => { + // Settled against Date.now(), the timer fire re-arms the connection for + // the budget plus the hour the clock went back, and this probe only + // returns once the test times out. + const idleMs = await probeIdleClose({ + requests: 1, + afterLastResponse: () => setSystemTime(new Date(Date.now() - HOUR_MS)), + }); + expect(idleMs).toBeGreaterThanOrEqual(KEEP_ALIVE_MS - 150); + }); + + test("fake timers enabled after the response do not keep the idle connection open", async () => { + // The socket timer was armed on real timers, so it still fires on its + // own; what fake timers change is the clocks. A mark taken on Date.now() + // (pinned when the fake timers were enabled) or on the mocked monotonic + // clock (which restarts at zero) makes that fire re-arm the connection, + // and the new timer lands in the fake heap, where nothing ever fires it. + const idleMs = await probeIdleClose({ + requests: 1, + afterLastResponse: () => jest.useFakeTimers(), + }); + expect(idleMs).toBeGreaterThanOrEqual(KEEP_ALIVE_MS - 150); + }); +});