Merge pull request 'The provider loop's tests wait on what they mean, not on the clock (issue 1901 note 27)' (#101) from fix/standing-test-races into main

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<World> {
   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); },
   });
@@ -109,8 +110,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 +158,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 +303,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 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, EVERY * 3);
+    await until(() => w.created.length > before, 1000);
     assert.equal(w.created.at(-1), "b");
   } finally {
     w.done();

test/standing.test.ts

@@ -27,14 +27,18 @@ async function until(cond: () => boolean, ms = 4000): Promise<void> {
   }
 }
 
-interface Said { event: string; body: Record<string, unknown> }
+interface Said { event: string; body: Record<string, unknown>; at: number }
 
 interface World {
   dir: string;
   ask(list: { as: string; node?: string; values?: Record<string, unknown> }[]): Promise<void>;
   failing: Error | null;
   holdsErr: Error | null;
+  /** When set, holds fails only for these consumers (holdsErr's error). */
+  holdsErrFor: Set<string> | 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[];
@@ -44,7 +48,7 @@ interface World {
 async function world(opts: { classify?: boolean; announce?: false; stableForMs?: number } = {}): Promise<World> {
   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: [], attempts: 0, said: [], all: [] } as unknown as World;
   w.ask = async (list) => {
     const given = [];
     for (const g of list) {
@@ -55,13 +59,14 @@ 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);
     },
     async remove() {},
     async retire() {},
-    async holds() {
+    async holds(p) {
-      if (w.holdsErr) throw w.holdsErr;
+      if (w.holdsErr && (!w.holdsErrFor || w.holdsErrFor.has(p.as))) throw w.holdsErr;
       return true;
     },
     ...(opts.classify ? { classify: () => "its-own" } : {}),
@@ -73,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<string, unknown>) => {
-        w.all.push({ event, body });
+        const said = { event, body, at: Date.now() };
-        if (body.why !== "first-success") w.said.push({ event, body });
+        w.all.push(said);
+        if (body.why !== "first-success") w.said.push(said);
       },
     }),
   });
@@ -92,10 +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 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 - 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");
@@ -103,15 +112,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 - 10, `repeated after ${w.said[1].at - w.said[0].at} ms, before sayAgainEveryMs`);
 
     // The first success takes it back.
     w.failing = null;
@@ -127,15 +135,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");
+    // 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
-    await w.ask([{ as: "a" }]);
+    // stretched to failingAfterMs is a long run and may be announced, so only runs that stayed short are asserted.
-    await sleep(FAILING_AFTER * 0.6);
+    const run = async (values?: Record<string, unknown>): Promise<number> => {
-    w.failing = null;
+      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 && Date.now() - start >= FAILING_AFTER * 0.6);
+      w.failing = null;
+      return Date.now() - start;
+    };
+    const first = await run();
     await until(() => w.created.length === 1);
-    w.failing = new Error("connection refused");
+    const second = await run({ name: "changed" });
-    await w.ask([{ as: "a", values: { name: "changed" } }]);
+    if (first < FAILING_AFTER && second < FAILING_AFTER) assert.equal(events(w.said), "", "two short runs are not one long one");
-    await sleep(FAILING_AFTER * 0.6);
-    assert.equal(events(w.said), "", "two short runs are not one long one");
   } finally {
     w.stop();
   }
@@ -197,9 +211,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");