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;/);