The provider loop's tests wait on what they mean, not on the clock (issue 1901 note 27) #101

Merged
mesh-tools merged 4 commits from fix/standing-test-races into main 2026-10-26 20:58:45 +00:00
2 changed files with 48 additions and 27 deletions
+11 -6
View File
@@ -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();
+37 -21
View File
@@ -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() {
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" } : {}),
@@ -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 });
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);
},
}),
});
@@ -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");
await w.ask([{ as: "a" }]);
await sleep(FAILING_AFTER * 0.6);
w.failing = null;
// 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<string, unknown>): Promise<number> => {
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");
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();
}
@@ -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");