From 24a01e35909d26c555f01ffec8fa336e2c8796fe Mon Sep 17 00:00:00 2001 From: E Ismail Date: Sun, 11 Oct 2026 01:12:32 +0300 Subject: [PATCH] npm: the retry waits are read from what the installer asked for The row "the waits between attempts are one second and then two" timed the pauses between three attempts at the server and required each one inside a window, 900-1800 ms and then 1900-2800 ms. A hosted Windows runner stalled for several seconds once, the second pause measured 5407 ms, and the row went red with the schedule correct. A stopwatch on a shared machine measures the machine. The schedule is now read from the child. A preload in the test tree, beside the other two, replaces the global setTimeout in the installer's process: it writes down every delay asked for and when each one fires, synchronously, and hands every call to the real timer, so each pause is still spent. The row requires the whole record: set 30000, set 1000, fired 1000, set 30000, set 2000, fired 2000, set 30000 which also shows each attempt arming a fresh deadline, and that each pause fires before the next attempt starts. The installer is unchanged and carries no hook. The server still counts three attempts, and the pauses it sees keep their lower bounds, 900 ms and 1900 ms. The ceilings are gone: the server stamps an arrival and drops it in one step, so a stalled machine can only lengthen a pause, and the floors are what catch a pause that was recorded and never spent. Arrivals are stamped on a monotonic clock. The row is three subtests over one install, and prints its record and both pauses before asserting anything, so every log carries a sample. The file header and the pin row's comment are rewritten to say what is taken where. --- npm/test/helpers/harness.js | 12 ++++- npm/test/helpers/recorded-waits.js | 45 +++++++++++++++++++ npm/test/retry.test.js | 70 ++++++++++++++++++++++++------ 3 files changed, 113 insertions(+), 14 deletions(-) create mode 100644 npm/test/helpers/recorded-waits.js diff --git a/npm/test/helpers/harness.js b/npm/test/helpers/harness.js index 1888611..5f3bfd0 100644 --- a/npm/test/helpers/harness.js +++ b/npm/test/helpers/harness.js @@ -18,6 +18,7 @@ const https = require('node:https'); const net = require('node:net'); const os = require('node:os'); const path = require('node:path'); +const { performance } = require('node:perf_hooks'); const zlib = require('node:zlib'); const { spawn } = require('node:child_process'); @@ -30,6 +31,10 @@ const PRELOAD = path.join(__dirname, 'fake-platform.js'); // name so it is visible at the call site rather than switched on by a // flag somewhere else. const LOCKED_FILES = path.join(__dirname, 'locked-files.js'); +// The preload that writes down every wait the script asks the timer for, +// and when each one fires, while still letting it run. Asked for by name +// for the same reason. +const RECORDED_WAITS = path.join(__dirname, 'recorded-waits.js'); // The version the copied package declares, read from the real // package.json rather than chosen here: a row asserting the constructed @@ -374,10 +379,14 @@ function serveProxy(t, { // A listener that answers nothing and counts who arrived. It stands at // the address a proxy row's URL names, so "no direct request was made" // is an observation rather than an absence of evidence. +// +// Each arrival is stamped on a clock that never steps backwards, because +// a row measures the pause between two of them, and a wall clock that is +// corrected mid-row could make a correct pause look short. function watchPort(t) { const arrivals = []; const server = net.createServer((socket) => { - arrivals.push(Date.now()); + arrivals.push(performance.now()); socket.destroy(); }); t.after(() => shutdown(server)); @@ -436,6 +445,7 @@ module.exports = { BINARY_GZ, BINARY_DIGEST, PACKAGE_ROOT, + RECORDED_WAITS, VERSION, assetPath, assertNoSecretIn, diff --git a/npm/test/helpers/recorded-waits.js b/npm/test/helpers/recorded-waits.js new file mode 100644 index 0000000..79b7e82 --- /dev/null +++ b/npm/test/helpers/recorded-waits.js @@ -0,0 +1,45 @@ +'use strict'; + +// A preload that writes down every wait the install script asks the +// timer for, and when each one fires, while still letting it run. +// +// A STOPWATCH ON A SHARED MACHINE MEASURES THE MACHINE. A hosted runner +// can stall every process on it for seconds, which stretches the pause +// a server sees between two attempts without the script having chosen +// anything different. What the script chose is what it asked the timer +// for, and that is what is written down here. +// +// NOTHING IS FAKED. Every call goes to the real timer with the same +// delay and arguments, and the real handle comes back, so each pause is +// really spent and clearing a deadline still clears it. A recorder that +// ended the waits at once would be a fake clock, and a row reading it +// would pass a script that never waits at all. +// +// THE FIRING IS WRITTEN DOWN AS WELL AS THE ASKING. A script that asks +// for a pause and does not wait for it arms the next attempt's deadline +// before the pause fires, and the order of the lines shows that however +// slow the machine was. +// +// Each line is written synchronously, because the script exits the +// moment its last attempt fails and a write still pending then is lost. +// +// It sits beside the other preloads, and for the same reason: the test +// tree ships nowhere, so the script under test carries no hook of its +// own. The file it writes to is named by a variable only this preload +// reads. + +const fs = require('node:fs'); + +const record = process.env.CURIOUS_TEST_WAITS_FILE; +if (!record) { + throw new Error('recorded-waits.js was loaded without CURIOUS_TEST_WAITS_FILE'); +} + +const realSetTimeout = globalThis.setTimeout; +globalThis.setTimeout = function setTimeout(callback, ms, ...rest) { + fs.appendFileSync(record, `set ${ms}\n`); + return realSetTimeout(function fired(...args) { + fs.appendFileSync(record, `fired ${ms}\n`); + return callback.apply(this, args); + }, ms, ...rest); +}; diff --git a/npm/test/retry.test.js b/npm/test/retry.test.js index a2cab1a..8221c10 100644 --- a/npm/test/retry.test.js +++ b/npm/test/retry.test.js @@ -2,11 +2,19 @@ // Trying again, and the two waits between three attempts. // -// EVERY COUNT AND EVERY INTERVAL HERE IS TAKEN AT THE SERVER. Counting -// attempts inside the script would let a configuration error that never -// reaches the network look like three attempts, and a backoff asserted -// against a fake clock or a standalone helper proves nothing about the -// downloader that will actually pause. +// THE COUNT OF ATTEMPTS AND THE PAUSES BETWEEN THEM ARE TAKEN AT THE +// SERVER. Counting attempts inside the script would let a configuration +// error that never reaches the network look like three attempts, and a +// backoff asserted against a fake clock or a standalone helper proves +// nothing about the downloader that will actually pause. +// +// WHICH WAITS THE SCRIPT CHOSE IS TAKEN FROM THE CHILD. A preload writes +// down every delay the running script asks the timer for, and when each +// one fires, and hands every one to the real timer. A stopwatch cannot +// carry that half: a shared runner can stall a process for seconds, and +// the pause the server sees then measures the machine, not the schedule. +// So the server's pauses are bounded from below only, which load cannot +// break, and the record says what the schedule is. const test = require('node:test'); const assert = require('node:assert'); @@ -41,18 +49,52 @@ test('a connection that keeps failing is tried three times and then explained', test('the waits between attempts are one second and then two', async (t) => { const dead = await h.watchPort(t); const dir = h.makePackage(t, { checksums: h.checksumsFor([ASSET]) }); + const record = path.join(h.tempDir(t, 'waits'), 'waits.txt'); const run = await h.runInstall(t, dir, { base: `http://127.0.0.1:${dead.port}`, ...TARGET, + env: { CURIOUS_TEST_WAITS_FILE: record }, + preload: [h.RECORDED_WAITS], }); - assert.notStrictEqual(run.code, 0, run.output); - assert.strictEqual(dead.arrivals.length, 3); + const asked = fs.existsSync(record) ? fs.readFileSync(record, 'utf8').trim().split('\n') : []; // THREE ATTEMPTS HAVE TWO GAPS. A schedule with a third term is // unsatisfiable without quietly adding a fourth attempt, which is // exactly the shape a row can force an implementer into. const gaps = [dead.arrivals[1] - dead.arrivals[0], dead.arrivals[2] - dead.arrivals[1]]; - assert.ok(gaps[0] >= 900 && gaps[0] < 1800, `first wait was ${gaps[0]}ms, want about 1000`); - assert.ok(gaps[1] >= 1900 && gaps[1] < 2800, `second wait was ${gaps[1]}ms, want about 2000`); + const shown = gaps.map((g) => `${Math.round(g)}ms`); + // Printed BEFORE anything is asserted, on every run, so a green log is a + // sample too, and a red one still says what it saw. + t.diagnostic(`asked for: ${asked.join(', ')}; pauses at the server: ${shown.join(', ')}`); + + await t.test('the server saw three attempts', () => { + assert.notStrictEqual(run.code, 0, run.output); + assert.strictEqual(dead.arrivals.length, 3, `the server saw ${dead.arrivals.length} attempts`); + }); + + // Each attempt arms its own thirty-second deadline, then the pause is + // asked for, and the pause FIRES before the next attempt arms anything. + // A pause that is asked for and not waited on puts the next deadline + // ahead of its firing. + await t.test('the script waited one second and then two', () => { + assert.deepStrictEqual(asked, [ + 'set 30000', + 'set 1000', + 'fired 1000', + 'set 30000', + 'set 2000', + 'fired 2000', + 'set 30000', + ]); + }); + + // NO CEILING. The server stamps an arrival and drops it in one step, so + // the script cannot start a pause before its stamp, and a stalled + // machine can only lengthen what is measured here. What a floor catches + // is a pause that was recorded and never really spent. + await t.test('each pause really passed', () => { + assert.ok(gaps[0] >= 900, `first pause was ${shown[0]}, want at least 900ms`); + assert.ok(gaps[1] >= 1900, `second pause was ${shown[1]}, want at least 1900ms`); + }); }); test('a download that is slow but still moving is not killed', async (t) => { @@ -145,10 +187,12 @@ test('a fault whose body never ends is closed on every attempt', async (t) => { test('the numbers this script chose are the numbers it declares', () => { // A PIN, and it is named as one rather than dressed as a behaviour // row. No row here can observe thirty seconds without spending - // thirty, and no row can show that a retry gets a FRESH deadline - // without two attempts that each outlast one. What this buys is that - // the numbers cannot be changed silently; the rows above are what - // show the two waits and the three attempts really happen. + // thirty. The waits row shows that each attempt ARMS a fresh deadline + // of that length; it does not show the deadline bounding or ending an + // attempt, which would take two attempts that each outlast one. What + // this buys is that the numbers cannot be changed silently; the rows + // above are what show the two waits and the three attempts really + // happen. const source = fs.readFileSync(path.join(h.PACKAGE_ROOT, 'install.js'), 'utf8'); assert.match(source, /const ATTEMPT_TIMEOUT_MS = 30_000;/); assert.match(source, /const ATTEMPTS = 3;/);