feat(cli): S4 follow-up, refusal backoff and tracker boot (row 45, #1527)
Rocko's round 2 candidate, packet agents/rocko/work/s4-follow-up/
(build.patch c8cec070, candidate manifest 5b067a9d, 8/8 OK).
- Definite DM refusals wait the full 30-minute cap, counted from the
journal's last refusal, so five refusals span about two hours before
gave-up (lead decision 73). Unknown outcomes keep doubling.
- Broker close sends at host.mjs:144/150/184/188 pass a callback, which
closes the EPIPE window both reviewers found in round 1.
- README documents manual recovery for an open decision.
- trackers-boot test, X9, X14, and Darkwing's round 1 notes 1-4.
- The append type check stays out; Rocko's reason holds (both reviewers
agree).
Reviews: Darkwing approve (comment 26884), Filbert approve (26886).
Landing gate on b13fef4c plus the patch: every node suite and every
scripts/test-*.sh green, test-task 98/0.
Co-Authored-By: Claude Opus 5.5 <[email protected]>
This commit is contained in:
Claude Opus 5.5
@@ -1,12 +1,15 @@
|
||||
import { test } from "node:test";
|
||||
import assert from "node:assert/strict";
|
||||
import { appendFileSync, chmodSync, mkdirSync, readdirSync, readFileSync, statSync, symlinkSync, writeFileSync } from "node:fs";
|
||||
import { appendFileSync, chmodSync, mkdirSync, readdirSync, readFileSync, rmSync, statSync, symlinkSync, writeFileSync } from "node:fs";
|
||||
import { dirname, join } from "node:path";
|
||||
import { createNotifier, digestContent, digestNonce, dmNonce, journalPath, openJournal, runLoop, zoned } from "../src/notifier.mjs";
|
||||
import { createNotifier, digestContent, digestNonce, dmNonce, journalPath, openJournal, POLL_MS, REFUSAL_LIMIT, runLoop, zoned } from "../src/notifier.mjs";
|
||||
import { RestOutcome } from "../../discord/src/rest.mjs";
|
||||
import { broker, tmp } from "./helpers.mjs";
|
||||
|
||||
const AT = "2026-10-08T12:00:00.000Z";
|
||||
|
||||
// Discord-side fake: records sends, answers from a script (default: ok).
|
||||
// An entry is "ok", "refused" (HTTP 403), "unknown", or {kind, status}.
|
||||
function fakeDirect(script = []) {
|
||||
const sends = [];
|
||||
let n = 0;
|
||||
@@ -16,7 +19,8 @@ function fakeDirect(script = []) {
|
||||
sends.push(m);
|
||||
const next = script.shift() ?? "ok";
|
||||
if (next === "ok") return { messageId: `30000000000000${String(++n).padStart(4, "0")}` };
|
||||
throw new RestOutcome(next, `dm: ${next}`, { status: next === "refused" ? 403 : null });
|
||||
const { kind, status } = typeof next === "string" ? { kind: next, status: next === "refused" ? 403 : null } : next;
|
||||
throw new RestOutcome(kind, `dm: ${kind}`, { status });
|
||||
},
|
||||
};
|
||||
}
|
||||
@@ -91,14 +95,117 @@ test("a failed DM is journaled, backs off, and is retried until it lands", async
|
||||
assert.equal((await s.notifier.tick()).failed, 0, "inside the first 30 s backoff");
|
||||
s.time.advance(25_000);
|
||||
assert.equal((await s.notifier.tick()).failed, 1, "second attempt refused");
|
||||
s.time.advance(45_000);
|
||||
assert.equal((await s.notifier.tick()).dms, 0, "inside the 60 s backoff");
|
||||
s.time.advance(20_000);
|
||||
s.time.advance(29 * 60_000);
|
||||
assert.equal((await s.notifier.tick()).dms, 0, "a definite refusal waits the full 30 min, not the 60 s step");
|
||||
s.time.advance(60_000);
|
||||
assert.equal((await s.notifier.tick()).dms, 1);
|
||||
assert.deepEqual(s.journal().map((r) => r.outcome), ["unknown", "refused", "confirmed"]);
|
||||
assert.equal(s.journal()[1].status, 403);
|
||||
assert.equal(new Set(s.direct.sends.map((m) => m.nonce)).size, 1, "every retry reuses the nonce");
|
||||
assert.ok(s.logs.some((l) => /retry in 30 s/.test(l)));
|
||||
assert.ok(s.logs.some((l) => /unknown; retry in 30 s/.test(l)));
|
||||
assert.ok(s.logs.some((l) => /refused \(HTTP 403\); retry in 1800 s/.test(l)));
|
||||
});
|
||||
|
||||
// 05:00Z is 00:00 Chicago: eight hours of polls before the digest is due.
|
||||
const MIDNIGHT = "2026-10-08T05:00:00Z";
|
||||
const PAST_BACKOFF = 31 * 60_000;
|
||||
|
||||
test("five definite refusals stop a DM: one gave-up line, one log line, and a restart keeps the count", async (t) => {
|
||||
assert.equal(REFUSAL_LIMIT, 5);
|
||||
const s = setup(t, MIDNIGHT, ["refused", "refused", "refused", { kind: "refused", status: 404 }, { kind: "refused", status: 400 }]);
|
||||
const d = s.raise("git.push.protected", { target: "refactor", blocking: true, task_ref: "vikunja:1/7" });
|
||||
for (let i = 0; i < 3; i++) {
|
||||
assert.equal((await s.notifier.tick()).failed, 1);
|
||||
s.time.advance(PAST_BACKOFF);
|
||||
}
|
||||
const after = s.make();
|
||||
for (let i = 0; i < 2; i++) {
|
||||
assert.equal((await after.tick()).failed, 1, "the restart did not reset the count");
|
||||
s.time.advance(PAST_BACKOFF);
|
||||
}
|
||||
assert.equal(s.direct.sends.length, 5);
|
||||
assert.deepEqual(s.journal().map((r) => r.outcome), ["refused", "refused", "refused", "refused", "refused", "gave-up"]);
|
||||
assert.deepEqual(s.journal().at(-1), { at: s.journal().at(-1).at, kind: "dm", decision: d.id, outcome: "gave-up", messageId: null });
|
||||
assert.deepEqual(await after.tick(), { dms: 0, digest: false, failed: 0 });
|
||||
assert.deepEqual(await s.make().tick(), { dms: 0, digest: false, failed: 0 });
|
||||
assert.equal(s.direct.sends.length, 5, "never sent again, before or after a restart");
|
||||
assert.equal(s.journal().length, 6);
|
||||
const gave = s.logs.filter((l) => /gave up/.test(l));
|
||||
assert.deepEqual(gave, [`notify: dm ${d.id.slice(0, 8)} refused 5 times; gave up, not retried`]);
|
||||
assert.equal(s.logs.filter((l) => /retry in/.test(l)).length, 4, "the fifth refusal logs the give-up, not a retry");
|
||||
s.time.clock.t = new Date("2026-10-08T13:00:00Z");
|
||||
assert.equal((await s.make().tick()).digest, true);
|
||||
assert.match(s.direct.sends.at(-1).content, new RegExp(`\\[blocking, DM refused, not retried\\] ${d.id.slice(0, 8)} git\\.push\\.protected`));
|
||||
});
|
||||
|
||||
test("429s, 5xx-style unknowns and refusals without a status never count toward the limit", async (t) => {
|
||||
const script = [
|
||||
...Array(6).fill({ kind: "refused", status: 429 }),
|
||||
...Array(3).fill("unknown"),
|
||||
{ kind: "refused", status: null },
|
||||
...Array(REFUSAL_LIMIT - 1).fill("refused"),
|
||||
"ok",
|
||||
];
|
||||
const s = setup(t, MIDNIGHT, [...script]);
|
||||
s.raise("git.push.protected", { target: "refactor", blocking: true, task_ref: "vikunja:1/7" });
|
||||
for (let i = 0; i < script.length; i++) {
|
||||
await s.notifier.tick();
|
||||
s.time.advance(PAST_BACKOFF);
|
||||
}
|
||||
assert.equal(s.direct.sends.length, script.length);
|
||||
assert.equal(s.journal().at(-1).outcome, "confirmed");
|
||||
assert.ok(!s.journal().some((r) => r.outcome === "gave-up"));
|
||||
assert.ok(!s.logs.some((l) => /gave up/.test(l)));
|
||||
});
|
||||
|
||||
test("a crash between the fifth refusal and its gave-up line: the next poll appends it and sends nothing", async (t) => {
|
||||
const s = setup(t, MIDNIGHT);
|
||||
const d = s.raise("git.push.protected", { target: "refactor", blocking: true, task_ref: "vikunja:1/7" });
|
||||
const file = journalPath(s.dataRoot, "demo");
|
||||
const line = { at: AT, kind: "dm", decision: d.id, outcome: "refused", messageId: null, status: 403 };
|
||||
appendFileSync(file, `${JSON.stringify(line)}\n`.repeat(REFUSAL_LIMIT));
|
||||
assert.deepEqual(await s.make().tick(), { dms: 0, digest: false, failed: 0 });
|
||||
assert.equal(s.direct.sends.length, 0);
|
||||
assert.equal(s.journal().at(-1).outcome, "gave-up");
|
||||
assert.equal(s.logs.filter((l) => /gave up/.test(l)).length, 1);
|
||||
await s.make().tick();
|
||||
assert.equal(s.journal().length, REFUSAL_LIMIT + 1, "one gave-up line only");
|
||||
});
|
||||
|
||||
// Polls every POLL_MS from the current clock up to `until` ms later; returns
|
||||
// the minute (from `from`) of each new send.
|
||||
async function pollUntil(s, notifier, from, until, onPoll = () => {}) {
|
||||
const minutes = [];
|
||||
for (let elapsed = s.time.clock.t.getTime() - from; elapsed <= until; elapsed += POLL_MS) {
|
||||
const before = s.direct.sends.length;
|
||||
await notifier.tick();
|
||||
if (s.direct.sends.length > before) minutes.push(elapsed / 60_000);
|
||||
onPoll(elapsed);
|
||||
s.time.advance(POLL_MS);
|
||||
}
|
||||
return minutes;
|
||||
}
|
||||
|
||||
test("polled every POLL_MS against a permanent 403, a DM is sent at 0, 30, 60, 90 and 120 min and gives up only then", async (t) => {
|
||||
const s = setup(t, MIDNIGHT, Array(10).fill("refused"));
|
||||
s.raise("git.push.protected", { target: "refactor", blocking: true, task_ref: "vikunja:1/7" });
|
||||
const from = s.time.clock.t.getTime();
|
||||
const gaveUp = () => s.journal().some((r) => r.outcome === "gave-up");
|
||||
const minutes = await pollUntil(s, s.notifier, from, 120 * 60_000 + POLL_MS, (elapsed) => {
|
||||
assert.equal(gaveUp(), elapsed >= 120 * 60_000, `gave-up line at +${elapsed / 1000} s`);
|
||||
});
|
||||
assert.deepEqual(minutes, [0, 30, 60, 90, 120]);
|
||||
assert.equal(s.logs.filter((l) => /refused \(HTTP 403\); retry in 1800 s/.test(l)).length, 4);
|
||||
});
|
||||
|
||||
test("a restart after the second refusal does not send before that refusal's 30 min are up", async (t) => {
|
||||
const s = setup(t, MIDNIGHT, Array(10).fill("refused"));
|
||||
s.raise("git.push.protected", { target: "refactor", blocking: true, task_ref: "vikunja:1/7" });
|
||||
const from = s.time.clock.t.getTime();
|
||||
assert.deepEqual(await pollUntil(s, s.notifier, from, 30 * 60_000), [0, 30]);
|
||||
s.time.advance(60_000);
|
||||
const after = s.make();
|
||||
assert.deepEqual(await pollUntil(s, after, from, 60 * 60_000), [60], "nothing between the restart and +60 min");
|
||||
});
|
||||
|
||||
test("the digest goes at 08:00 Chicago once a day, with blocking ones marked as DM'd", async (t) => {
|
||||
@@ -150,7 +257,7 @@ const FRAGMENT = '{"at":"x","kind":"dm","dec';
|
||||
|
||||
test("the journal: a torn tail is copied out and truncated, so an append after it reopens cleanly", (t) => {
|
||||
const file = journalPath(tmp(t), "demo");
|
||||
openJournal(file).append({ at: "x", kind: "dm", decision: "a", outcome: "confirmed", messageId: "1" });
|
||||
openJournal(file).append({ at: AT, kind: "dm", decision: "a", outcome: "confirmed", messageId: "1" });
|
||||
const good = readFileSync(file);
|
||||
appendFileSync(file, FRAGMENT);
|
||||
const logs = [];
|
||||
@@ -164,7 +271,7 @@ test("the journal: a torn tail is copied out and truncated, so an append after i
|
||||
assert.equal(logs.length, 2);
|
||||
assert.match(logs[0], /copied a torn final line \(26 bytes\) to torn-20261008T235212345Z\.bin/);
|
||||
assert.match(logs[1], /truncated .* to its last newline/);
|
||||
j.append({ at: "y", kind: "dm", decision: "b", outcome: "confirmed", messageId: "2" });
|
||||
j.append({ at: AT, kind: "dm", decision: "b", outcome: "confirmed", messageId: "2" });
|
||||
const again = [];
|
||||
assert.deepEqual([...openJournal(file, { log: (l) => again.push(l) }).sent], ["a", "b"]);
|
||||
assert.deepEqual(again, [], "nothing torn the second time");
|
||||
@@ -172,7 +279,7 @@ test("the journal: a torn tail is copied out and truncated, so an append after i
|
||||
|
||||
test("the journal: a crash between the copy and the truncate leaves a tail the next open repairs", (t) => {
|
||||
const file = journalPath(tmp(t), "demo");
|
||||
openJournal(file).append({ at: "x", kind: "dm", decision: "a", outcome: "confirmed", messageId: "1" });
|
||||
openJournal(file).append({ at: AT, kind: "dm", decision: "a", outcome: "confirmed", messageId: "1" });
|
||||
appendFileSync(file, FRAGMENT);
|
||||
const now = () => new Date("2026-10-08T23:52:12.345Z");
|
||||
// The log after step 1 throws: the process dies before step 2.
|
||||
@@ -182,7 +289,7 @@ test("the journal: a crash between the copy and the truncate leaves a tail the n
|
||||
const j = openJournal(file, { now });
|
||||
assert.deepEqual(tornFiles(file), ["torn-20261008T235212345Z-1.bin", "torn-20261008T235212345Z.bin"], "a second copy, the first kept");
|
||||
for (const n of tornFiles(file)) assert.equal(readFileSync(join(dirname(file), n), "utf8"), FRAGMENT);
|
||||
j.append({ at: "y", kind: "dm", decision: "b", outcome: "confirmed", messageId: "2" });
|
||||
j.append({ at: AT, kind: "dm", decision: "b", outcome: "confirmed", messageId: "2" });
|
||||
assert.deepEqual([...openJournal(file).sent], ["a", "b"]);
|
||||
});
|
||||
|
||||
@@ -222,6 +329,108 @@ test("the journal: a loose file mode, a loose directory or a symlinked journal r
|
||||
assert.throws(() => openJournal(linked), (e) => e.exitCode === 3 && /must not be a symlink/.test(e.message));
|
||||
});
|
||||
|
||||
test("the journal: a line with a wrong type refuses with exit 3 and names the field", (t) => {
|
||||
const file = journalPath(tmp(t), "demo");
|
||||
openJournal(file);
|
||||
const dm = { at: AT, kind: "dm", decision: "a", outcome: "confirmed", messageId: "1" };
|
||||
const digest = { at: AT, kind: "digest", decision: null, day: "2026-10-08", outcome: "confirmed", messageId: "2" };
|
||||
const bad = [
|
||||
["record", [1]],
|
||||
["at", { ...dm, at: "x" }],
|
||||
["at", { ...dm, at: "2026-10-08" }],
|
||||
["at", { ...dm, at: 1 }],
|
||||
["kind", { ...dm, kind: "dg" }],
|
||||
["decision", { ...dm, decision: 7 }],
|
||||
["decision", { ...dm, decision: "" }],
|
||||
["decision", { ...digest, decision: "a" }],
|
||||
["day", { ...digest, day: undefined }],
|
||||
["day", { ...digest, day: "2026-10-8" }],
|
||||
["day", { ...digest, day: "2026-13-45" }],
|
||||
["day", { ...digest, day: "2026-02-30" }],
|
||||
["day", { ...dm, day: 20261008 }],
|
||||
["outcome", { ...dm, outcome: "sent" }],
|
||||
["outcome", { ...digest, outcome: "gave-up", messageId: null }],
|
||||
["messageId", { ...dm, messageId: null }],
|
||||
["messageId", { ...dm, outcome: "refused", messageId: 1 }],
|
||||
["status", { ...dm, outcome: "refused", messageId: null, status: "403" }],
|
||||
["status", { ...dm, outcome: "refused", messageId: null, status: 403.5 }],
|
||||
];
|
||||
for (const [field, r] of bad) {
|
||||
const text = `${JSON.stringify(dm)}\n${JSON.stringify(r)}\n`;
|
||||
writeFileSync(file, text);
|
||||
assert.throws(() => openJournal(file), (e) => e.exitCode === 3 && e.message === `notify journal line 2 is malformed (${field}): ${file}`, `${field}: ${JSON.stringify(r)}`);
|
||||
assert.equal(readFileSync(file, "utf8"), text, "a refusal changes nothing");
|
||||
}
|
||||
const good = [dm, digest, { ...dm, outcome: "refused", messageId: null, status: 403 }, { ...dm, outcome: "gave-up", messageId: null }, { ...digest, outcome: "unknown", messageId: null }];
|
||||
writeFileSync(file, good.map((r) => `${JSON.stringify(r)}\n`).join(""));
|
||||
const j = openJournal(file);
|
||||
assert.deepEqual([...j.sent], ["a"]);
|
||||
assert.deepEqual([...j.days], ["2026-10-08"]);
|
||||
assert.deepEqual([...j.gaveUp], ["a"]);
|
||||
assert.deepEqual([...j.refusals], [["a", 1]]);
|
||||
});
|
||||
|
||||
test("the journal: a symlinked directory refuses and says it is a link", (t) => {
|
||||
const root = tmp(t);
|
||||
const real = join(root, "real");
|
||||
mkdirSync(real, { mode: 0o700 });
|
||||
const file = journalPath(root, "demo");
|
||||
mkdirSync(dirname(dirname(file)), { mode: 0o700 });
|
||||
symlinkSync(real, dirname(file));
|
||||
assert.throws(() => openJournal(file), (e) => e.exitCode === 3 && e.message === `notify journal directory must not be a symlink: ${dirname(file)}`);
|
||||
assert.deepEqual(readdirSync(real), [], "nothing was created through the link");
|
||||
});
|
||||
|
||||
test("the journal: a dangling directory link, a parent that is a file and a journal that is a directory each refuse with exit 3", (t) => {
|
||||
const root = tmp(t);
|
||||
const dangling = journalPath(root, "demo");
|
||||
mkdirSync(dirname(dirname(dangling)), { mode: 0o700 });
|
||||
symlinkSync(join(root, "missing"), dirname(dangling));
|
||||
assert.throws(() => openJournal(dangling), (e) => e.exitCode === 3 && e.message === `notify journal directory must not be a symlink: ${dirname(dangling)}`);
|
||||
const under = join(root, "plain", "notify", "demo", "sent.jsonl");
|
||||
writeFileSync(join(root, "plain"), "");
|
||||
assert.throws(() => openJournal(under), (e) => e.exitCode === 3 && e.message === `notify journal directory cannot be created (ENOTDIR): ${dirname(under)}`);
|
||||
const asDir = journalPath(root, "acme");
|
||||
mkdirSync(asDir, { recursive: true, mode: 0o700 });
|
||||
assert.throws(() => openJournal(asDir), (e) => e.exitCode === 3 && e.message === `notify journal must be a regular file, mode 0600, owned by this user: ${asDir}`);
|
||||
});
|
||||
|
||||
test("the journal: an append after the file was swapped for a symlink refuses and writes nothing through it", (t) => {
|
||||
const root = tmp(t);
|
||||
const file = journalPath(root, "demo");
|
||||
const j = openJournal(file);
|
||||
const other = join(root, "elsewhere.jsonl");
|
||||
writeFileSync(other, "", { mode: 0o600 });
|
||||
rmSync(file);
|
||||
symlinkSync(other, file);
|
||||
assert.throws(() => j.append({ at: AT, kind: "dm", decision: "a", outcome: "confirmed", messageId: "1" }), (e) => e.code === "ELOOP");
|
||||
assert.equal(readFileSync(other, "utf8"), "");
|
||||
});
|
||||
|
||||
test("the journal: a directory it cannot write or create refuses with exit 3 and names the path", { skip: process.getuid() === 0 && "root ignores the modes" }, (t) => {
|
||||
const root = tmp(t);
|
||||
const file = journalPath(root, "demo");
|
||||
mkdirSync(dirname(file), { recursive: true, mode: 0o700 });
|
||||
// Modes are restored in finally: tmp()'s cleanup runs first among the after hooks.
|
||||
chmodSync(dirname(file), 0o500);
|
||||
try {
|
||||
assert.throws(() => openJournal(file), (e) => e.exitCode === 3 && e.message === `notify journal directory is not writable (EACCES): ${dirname(file)}`);
|
||||
} finally {
|
||||
chmodSync(dirname(file), 0o700);
|
||||
}
|
||||
openJournal(file);
|
||||
chmodSync(file, 0o400);
|
||||
assert.throws(() => openJournal(file), (e) => e.exitCode === 3 && e.message === `notify journal is not writable (EACCES): ${file}`);
|
||||
const parent = join(root, "notify");
|
||||
const other = journalPath(root, "acme");
|
||||
chmodSync(parent, 0o500);
|
||||
try {
|
||||
assert.throws(() => openJournal(other), (e) => e.exitCode === 3 && e.message === `notify journal directory cannot be created (EACCES): ${dirname(other)}`);
|
||||
} finally {
|
||||
chmodSync(parent, 0o700);
|
||||
}
|
||||
});
|
||||
|
||||
test("digest content stays within Discord's 2000 characters", () => {
|
||||
const inbox = Array.from({ length: 60 }, (_, i) => ({ id: `${String(i).padStart(8, "0")}-x`, action: "deploy", question: "q".repeat(300), blocking: i % 2 === 0 }));
|
||||
const text = digestContent("demo", "2026-10-08", inbox, () => true);
|
||||
|
||||
Reference in New Issue
Block a user