From 3a095a66bef3e68b6f4605429737384511355944 Mon Sep 17 00:00:00 2001 From: jochen Date: Mon, 26 Oct 2026 20:33:23 +0100 Subject: [PATCH 1/4] The standing test keeps c failing alone after its ask is dropped, so its only recovery is its retirement: clearing every failure at once raced the loop's read of the new list under load (issue 1126; the hidden failure of try-1793042418286545971, issue 1901) --- test/standing.test.ts | 14 +++++++++----- 1 file changed, 9 insertions(+), 5 deletions(-) diff --git a/test/standing.test.ts b/test/standing.test.ts index 107cb49..bfc916a 100644 --- a/test/standing.test.ts +++ b/test/standing.test.ts @@ -34,6 +34,8 @@ interface World { ask(list: { as: string; node?: string; values?: Record }[]): Promise; failing: Error | null; holdsErr: Error | null; + /** When set, holds fails only for these consumers (holdsErr's error). */ + holdsErrFor: Set | null; created: string[]; /** Every event but the first success since start, which has its own test. */ said: Said[]; @@ -44,7 +46,7 @@ interface World { async function world(opts: { classify?: boolean; announce?: false; stableForMs?: number } = {}): Promise { const dir = await mkdtemp(join(tmpdir(), "standing-")); const receives = join(dir, "postgres-database.json"); - const w = { dir, failing: null, holdsErr: null, created: [], said: [], all: [] } as unknown as World; + const w = { dir, failing: null, holdsErr: null, holdsErrFor: null, created: [], said: [], all: [] } as unknown as World; w.ask = async (list) => { const given = []; for (const g of list) { @@ -60,8 +62,8 @@ async function world(opts: { classify?: boolean; announce?: false; stableForMs?: }, async remove() {}, async retire() {}, - async holds() { - if (w.holdsErr) throw w.holdsErr; + async holds(p) { + if (w.holdsErr && (!w.holdsErrFor || w.holdsErrFor.has(p.as))) throw w.holdsErr; return true; }, ...(opts.classify ? { classify: () => "its-own" } : {}), @@ -197,9 +199,11 @@ test("a failing consumer the mesh stopped asking for is said recovered when it i await until(() => w.created.length === 3); w.holdsErr = new Error("boom"); await until(() => w.said.filter((s) => s.event === FAILING_EVENT).length >= 3); - // c is no longer asked for while it is still failing; the others then recover. + // c is no longer asked for while it is still failing; the others then recover. c keeps failing, so its only way + // to be said recovered is its retirement: clearing every failure at once raced the loop's read of the new list + // under load (a pass before that read recovered c as an ordinary recovery, with no why). await w.ask([{ as: "a" }, { as: "b" }]); - w.holdsErr = null; + w.holdsErrFor = new Set(["c"]); await until(() => w.said.some((s) => s.event === RECOVERED_EVENT && s.body.consumer === "c")); const c = w.said.find((s) => s.event === RECOVERED_EVENT && s.body.consumer === "c")!; assert.equal(c.body.why, "retired"); -- 2.54.0 From 36ae0c691b713ef730bfdab36727dbe955660fad Mon Sep 17 00:00:00 2001 From: jochen Date: Mon, 26 Oct 2026 21:44:06 +0100 Subject: [PATCH 2/4] The standing and retirement tests wait on what they mean, not on a slept fraction of a bound: announcements are timed from the clock at the moment they are said, short runs are counted in attempts, an addition is proved by a hold it must not wait for (the second timing race of one kind in a day; issue 1126) --- test/retire.test.ts | 14 +++++++++----- test/standing.test.ts | 45 +++++++++++++++++++++++++++---------------- 2 files changed, 37 insertions(+), 22 deletions(-) diff --git a/test/retire.test.ts b/test/retire.test.ts index a000760..25e3155 100644 --- a/test/retire.test.ts +++ b/test/retire.test.ts @@ -109,8 +109,10 @@ test("the fifth pass and not the fourth retires", async () => { // Driven by the clock: five passes 10 ms apart take at least 40 ms after the first sees the set. const w = await world(["a", "b", "c"]); try { - await w.ask(["b", "c"]); + // The clock starts before the file is written: a pass may read it the moment it lands, before any line after the + // write runs, and a start taken after would then count fewer than four intervals. const start = Date.now(); + await w.ask(["b", "c"]); await until(() => w.retired.length === 1); assert.ok(Date.now() - start >= 4 * EVERY - 2, `retired after ${Date.now() - start} ms, before five passes`); } finally { @@ -155,10 +157,10 @@ test("five passes are not enough: the same set must also hold for stableForMs", const HOLD = 400; const w = await world(["a", "b", "c"], { stableForMs: HOLD }); try { + const start = Date.now(); // before the write, as in the fifth-pass test await w.ask(["b", "c"]); - const start = Date.now(); await sleep(EVERY * 10); // well past five passes, well short of the hold - assert.deepEqual(w.retired, [], "retired after five passes, before the set held long enough"); + if (Date.now() - start < HOLD) assert.deepEqual(w.retired, [], "retired after five passes, before the set held long enough"); await until(() => w.retired.length === 1, 3000); assert.ok(Date.now() - start >= HOLD - 5, `retired after ${Date.now() - start} ms, before ${HOLD} ms`); assert.equal((await w.p.retirement()).stable_for_seconds, 0); // 400 ms rounds to 0 s @@ -300,11 +302,13 @@ test("delete refuses an active consumer and deletes only the named retired one", }); test("an addition acts on the first pass", async () => { - const w = await world(["a"]); + // Not gated by the stability a retirement waits for: with a hold of a minute, only a pass that acts at once creates b + // in the time the test waits. A deadline of three intervals, as before, was a race with the scheduler under load. + const w = await world(["a"], { stableForMs: 60_000 }); try { const before = w.created.length; await w.ask(["a", "b"]); - await until(() => w.created.length > before, EVERY * 3); + await until(() => w.created.length > before); assert.equal(w.created.at(-1), "b"); } finally { w.done(); diff --git a/test/standing.test.ts b/test/standing.test.ts index bfc916a..49e3db2 100644 --- a/test/standing.test.ts +++ b/test/standing.test.ts @@ -27,7 +27,7 @@ async function until(cond: () => boolean, ms = 4000): Promise { } } -interface Said { event: string; body: Record } +interface Said { event: string; body: Record; at: number } interface World { dir: string; @@ -37,6 +37,8 @@ interface World { /** When set, holds fails only for these consumers (holdsErr's error). */ holdsErrFor: Set | null; created: string[]; + /** How many times create was asked, failed or not. */ + attempts: number; /** Every event but the first success since start, which has its own test. */ said: Said[]; all: Said[]; @@ -46,7 +48,7 @@ interface World { async function world(opts: { classify?: boolean; announce?: false; stableForMs?: number } = {}): Promise { const dir = await mkdtemp(join(tmpdir(), "standing-")); const receives = join(dir, "postgres-database.json"); - const w = { dir, failing: null, holdsErr: null, holdsErrFor: null, created: [], said: [], all: [] } as unknown as World; + const w = { dir, failing: null, holdsErr: null, holdsErrFor: null, created: [], attempts: 0, said: [], all: [] } as unknown as World; w.ask = async (list) => { const given = []; for (const g of list) { @@ -57,6 +59,7 @@ async function world(opts: { classify?: boolean; announce?: false; stableForMs?: }; const adapter: Adapter = { async create(p) { + w.attempts++; if (w.failing) throw w.failing; w.created.push(p.as); }, @@ -75,8 +78,9 @@ async function world(opts: { classify?: boolean; announce?: false; stableForMs?: failingAfterMs: FAILING_AFTER, sayAgainEveryMs: SAY_AGAIN, stableForMs: opts.stableForMs ?? 0, ...(opts.announce === false ? {} : { announce: (event: string, body: Record) => { - w.all.push({ event, body }); - if (body.why !== "first-success") w.said.push({ event, body }); + const said = { event, body, at: Date.now() }; + w.all.push(said); + if (body.why !== "first-success") w.said.push(said); }, }), }); @@ -94,10 +98,12 @@ test("a consumer failed for minutes is announced, naming it, its machine and the const w = await world(); try { w.failing = new Error(`token request failed: 401 {"error":"invalid_grant"} for pw-a`); + // "Not before failingAfterMs" and "not again too soon" are read from the clock at the moment each is said, not + // from a sleep: a sleep overruns under load and lets the very announcement it checks the absence of fall due. + const asked = Date.now(); await w.ask([{ as: "a", node: "anchor" }]); - await sleep(FAILING_AFTER / 2); - assert.equal(events(w.said), "", "announced before failingAfterMs"); await until(() => w.said.length === 1); + assert.ok(w.said[0].at - asked >= FAILING_AFTER, `announced after ${w.said[0].at - asked} ms, before failingAfterMs`); const b = w.said[0].body; assert.equal(w.said[0].event, FAILING_EVENT); assert.equal(b.consumer, "a"); @@ -105,15 +111,14 @@ test("a consumer failed for minutes is announced, naming it, its machine and the assert.equal(b.class, CLASS_CREDENTIALS); assert.equal(b.provider, "postgres-database"); assert.equal(b["provider-node"], "home-server"); - assert.ok((b.attempts as number) > 3, `attempts ${b.attempts}`); + assert.ok((b.attempts as number) > 1, `attempts ${b.attempts}`); assert.match(String(b.since), /^\d{4}-\d{2}-\d{2}T/); assert.doesNotMatch(String(b.error), /pw-a/, "the consumer's password travelled"); // Said again while it lasts, not every pass. - await sleep(SAY_AGAIN / 2); - assert.equal(events(w.said), FAILING_EVENT, "repeated too soon"); await until(() => w.said.length === 2); assert.equal(events(w.said), `${FAILING_EVENT},${FAILING_EVENT}`); + assert.ok(w.said[1].at - w.said[0].at >= SAY_AGAIN, `repeated after ${w.said[1].at - w.said[0].at} ms, before sayAgainEveryMs`); // The first success takes it back. w.failing = null; @@ -129,15 +134,21 @@ test("a consumer failed for minutes is announced, naming it, its machine and the test("one success between failures starts the run again", async () => { const w = await world(); try { - w.failing = new Error("connection refused"); - await w.ask([{ as: "a" }]); - await sleep(FAILING_AFTER * 0.6); - w.failing = null; + // Each failing run lasts two failed attempts, counted, not a slept fraction of failingAfterMs. A run the load + // stretched to failingAfterMs is a long run and may be announced, so only runs that stayed short are asserted. + const run = async (values?: Record): Promise => { + const start = Date.now(); + const base = w.attempts; + w.failing = new Error("connection refused"); + await w.ask([{ as: "a", values }]); + await until(() => w.attempts >= base + 2); + w.failing = null; + return Date.now() - start; + }; + const first = await run(); await until(() => w.created.length === 1); - w.failing = new Error("connection refused"); - await w.ask([{ as: "a", values: { name: "changed" } }]); - await sleep(FAILING_AFTER * 0.6); - assert.equal(events(w.said), "", "two short runs are not one long one"); + const second = await run({ name: "changed" }); + if (first < FAILING_AFTER && second < FAILING_AFTER) assert.equal(events(w.said), "", "two short runs are not one long one"); } finally { w.stop(); } -- 2.54.0 From cf930388f93bf9f754adafdd4d9225831c73b575 Mon Sep 17 00:00:00 2001 From: jochen Date: Mon, 26 Oct 2026 21:49:03 +0100 Subject: [PATCH 3/4] The standing test's runs last 0.6 of failingAfterMs of clock as well as two attempts, so a success that does not reset a run is caught; the addition test holds a thousand stable passes, so 'first pass' is proved (review of the standing test races) --- test/retire.test.ts | 11 ++++++----- test/standing.test.ts | 4 ++-- 2 files changed, 8 insertions(+), 7 deletions(-) diff --git a/test/retire.test.ts b/test/retire.test.ts index 25e3155..4b6f4e7 100644 --- a/test/retire.test.ts +++ b/test/retire.test.ts @@ -38,7 +38,7 @@ interface World { async function world( names: string[], - opts: { retire?: boolean; held?: string[]; del?: boolean; reenable?: boolean; stableForMs?: number } = {}, + opts: { retire?: boolean; held?: string[]; del?: boolean; reenable?: boolean; stableForMs?: number; stablePasses?: number } = {}, ): Promise { const dir = await mkdtemp(join(tmpdir(), "retire-")); const receives = join(dir, "postgres-database.json"); @@ -64,6 +64,7 @@ async function world( }; w.p = runProviderLoop("postgres-database", adapter, { receives, everyMs: EVERY, node: "anchor", stableForMs: opts.stableForMs ?? 0, + ...(opts.stablePasses ? { stablePasses: opts.stablePasses } : {}), // Only retirement is these tests'; the standing (provisioner.failing, .recovered) is standing.test.ts's. announce: (event, body) => { if (event === RETIREMENT_EVENT) w.events.push(body); }, }); @@ -302,13 +303,13 @@ test("delete refuses an active consumer and deletes only the named retired one", }); test("an addition acts on the first pass", async () => { - // Not gated by the stability a retirement waits for: with a hold of a minute, only a pass that acts at once creates b - // in the time the test waits. A deadline of three intervals, as before, was a race with the scheduler under load. - const w = await world(["a"], { stableForMs: 60_000 }); + // Not gated by the stability a retirement waits for: with a hold of a minute and a thousand passes, only a pass that + // acts at once creates b. The deadline is a few passes, not three intervals of 10 ms: a scheduler stall must not fail it. + const w = await world(["a"], { stableForMs: 60_000, stablePasses: 1000 }); try { const before = w.created.length; await w.ask(["a", "b"]); - await until(() => w.created.length > before); + await until(() => w.created.length > before, 1000); assert.equal(w.created.at(-1), "b"); } finally { w.done(); diff --git a/test/standing.test.ts b/test/standing.test.ts index 49e3db2..de76be3 100644 --- a/test/standing.test.ts +++ b/test/standing.test.ts @@ -134,14 +134,14 @@ test("a consumer failed for minutes is announced, naming it, its machine and the test("one success between failures starts the run again", async () => { const w = await world(); try { - // Each failing run lasts two failed attempts, counted, not a slept fraction of failingAfterMs. A run the load + // Each failing run lasts two counted failed attempts and at least 0.6 of failingAfterMs of clock (long enough that a success which did not reset the run would be announced at the second run). A run the load // stretched to failingAfterMs is a long run and may be announced, so only runs that stayed short are asserted. const run = async (values?: Record): Promise => { const start = Date.now(); const base = w.attempts; w.failing = new Error("connection refused"); await w.ask([{ as: "a", values }]); - await until(() => w.attempts >= base + 2); + await until(() => w.attempts >= base + 2 && Date.now() - start >= FAILING_AFTER * 0.6); w.failing = null; return Date.now() - start; }; -- 2.54.0 From 18e541c1badca3108249c1c320d2d35bac4c5d82 Mon Sep 17 00:00:00 2001 From: jochen Date: Mon, 26 Oct 2026 21:55:46 +0100 Subject: [PATCH 4/4] The standing test allows 10 ms between the loop's clock and the test's stamp of an announcement --- test/standing.test.ts | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/test/standing.test.ts b/test/standing.test.ts index de76be3..658ec6b 100644 --- a/test/standing.test.ts +++ b/test/standing.test.ts @@ -98,12 +98,13 @@ test("a consumer failed for minutes is announced, naming it, its machine and the const w = await world(); try { w.failing = new Error(`token request failed: 401 {"error":"invalid_grant"} for pw-a`); + // The loop stamps its own clock before it calls announce, so the test's stamp may read a few ms short: 10 ms of slack. // "Not before failingAfterMs" and "not again too soon" are read from the clock at the moment each is said, not // from a sleep: a sleep overruns under load and lets the very announcement it checks the absence of fall due. const asked = Date.now(); await w.ask([{ as: "a", node: "anchor" }]); await until(() => w.said.length === 1); - assert.ok(w.said[0].at - asked >= FAILING_AFTER, `announced after ${w.said[0].at - asked} ms, before failingAfterMs`); + assert.ok(w.said[0].at - asked >= FAILING_AFTER - 10, `announced after ${w.said[0].at - asked} ms, before failingAfterMs`); const b = w.said[0].body; assert.equal(w.said[0].event, FAILING_EVENT); assert.equal(b.consumer, "a"); @@ -118,7 +119,7 @@ test("a consumer failed for minutes is announced, naming it, its machine and the // Said again while it lasts, not every pass. await until(() => w.said.length === 2); assert.equal(events(w.said), `${FAILING_EVENT},${FAILING_EVENT}`); - assert.ok(w.said[1].at - w.said[0].at >= SAY_AGAIN, `repeated after ${w.said[1].at - w.said[0].at} ms, before sayAgainEveryMs`); + assert.ok(w.said[1].at - w.said[0].at >= SAY_AGAIN - 10, `repeated after ${w.said[1].at - w.said[0].at} ms, before sayAgainEveryMs`); // The first success takes it back. w.failing = null; -- 2.54.0