npm: the retry waits are read from what the installer asked for

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,

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);
+};

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