audit-logger, model-usage: retry a failed write and never lose the event (hq issue 276)
Both caught a failed write and took the event, losing it silently; the SDK's rule is to throw when the work was not done. A failed write now throws so the bus offers the event again, and is spooled on disk at once; on its last delivery the spooled event is taken, and a background pass replays the spool once writing works. The runtime does not pass the delivery count, so the spool counts failed deliveries itself, across restarts. Over its bound (1000 events or 30 minutes) the last delivery is no longer taken, so the bus gives it up and the controller raises max-deliveries - the one existing condition that names a consumer which cannot keep up - while the spool still holds it. Writes are idempotent by event: the trail skips an id it already wrote; the usage upsert keeps the reading observed latest (migration 2), so a late replay never overwrites a newer one. Each module has a status tool for the spool, declared as valuable data (ADR 0233). model-usage moves to the bundle shape (ADR 0198) with its schema in a prepare step and numbered migrations; its old container shape had no image. Both on mesh-sdk 0.1.13. The log-only handlers of redis, mssql, mosquitto, mongodb, mesh-vault, showcase and the catalogue no longer throw a TypeError on an event without a body.
This commit is contained in:
jochen
@@ -1,20 +1,33 @@
|
||||
// The audit handler — appends one line per event to an append-only audit log. It is the whole of
|
||||
// the module's code: an audit logger is not a privileged component, only a module that listens to
|
||||
// everything and writes it down (novox/hq ADR 0041).
|
||||
//
|
||||
// **Written once per event.** Delivery is at-least-once, and since novox/hq issue 276 a failed write
|
||||
// is asked for again and an event that keeps failing is replayed from the spool — so the same event can
|
||||
// reach the trail more than once. An append-only file has no ON CONFLICT; its equivalent is the SDK's
|
||||
// other answer ("Taking an event"): skip an event id already written, remembering it only once the line
|
||||
// is on disk. The ids remembered are the most recent ones, seeded from the end of the trail on start,
|
||||
// which covers every redelivery (seconds apart) and a restart between a write and its answer.
|
||||
|
||||
import { appendFile, mkdir } from "node:fs/promises";
|
||||
import { mkdir, open, stat } from "node:fs/promises";
|
||||
import { dirname } from "node:path";
|
||||
import type { Event } from "@novox/mesh-sdk/events";
|
||||
import { keyOf } from "./spool.js";
|
||||
|
||||
/** Where the trail is written. A directory the host applies; one file per node. */
|
||||
export function auditLogPath(env: NodeJS.ProcessEnv = process.env): string {
|
||||
return env.AUDIT_LOG ?? "/var/lib/audit-logger/audit.log";
|
||||
}
|
||||
|
||||
/** Append an event to the trail as one JSON line, keeping the metadata an audit needs first. The id
|
||||
* is the event's own x-event-id (ADR 0042) — the handle a reader dedups the at-least-once trail on. */
|
||||
export async function record(event: Event, path: string): Promise<void> {
|
||||
const line =
|
||||
/** Where an event that could not be written waits (see spool.ts). Beside the trail unless said. */
|
||||
export function auditSpoolPath(env: NodeJS.ProcessEnv = process.env): string {
|
||||
return env.AUDIT_SPOOL ?? `${dirname(auditLogPath(env))}/spool`;
|
||||
}
|
||||
|
||||
/** One event as the trail's line, keeping the metadata an audit needs first. The id is the event's own
|
||||
* x-event-id (ADR 0042) — the handle a reader dedups the at-least-once trail on. */
|
||||
export function lineOf(event: Event): string {
|
||||
return (
|
||||
JSON.stringify({
|
||||
id: event.id,
|
||||
type: event.type,
|
||||
@@ -23,8 +36,82 @@ export async function record(event: Event, path: string): Promise<void> {
|
||||
at: event.at,
|
||||
...(event.causationId ? { causationId: event.causationId } : {}),
|
||||
...(event.schema ? { schema: event.schema } : {}),
|
||||
body: event.body,
|
||||
}) + "\n";
|
||||
await mkdir(dirname(path), { recursive: true }).catch(() => {});
|
||||
await appendFile(path, line, { mode: 0o600 });
|
||||
body: event.body ?? null,
|
||||
}) + "\n"
|
||||
);
|
||||
}
|
||||
|
||||
/** How many recent event ids a trail remembers, and how much of its end it reads to seed them. */
|
||||
const REMEMBERED = 50_000;
|
||||
const SEED_BYTES = 8 * 1024 * 1024;
|
||||
|
||||
export class Trail {
|
||||
private readonly seen = new Map<string, true>();
|
||||
|
||||
private constructor(readonly path: string) {}
|
||||
|
||||
/** Open the trail at `path`, remembering the ids at its end. */
|
||||
static async open(path: string): Promise<Trail> {
|
||||
const t = new Trail(path);
|
||||
await t.seed();
|
||||
return t;
|
||||
}
|
||||
|
||||
has(event: Event): boolean {
|
||||
return this.seen.has(keyOf(event));
|
||||
}
|
||||
|
||||
/** Append the event as one line and sync it, unless this trail already holds it. Throws when the
|
||||
* line could not be written — the handler's cue to ask for the event again. */
|
||||
async record(event: Event): Promise<void> {
|
||||
const key = keyOf(event);
|
||||
if (this.seen.has(key)) return;
|
||||
await mkdir(dirname(this.path), { recursive: true }).catch(() => {});
|
||||
const fh = await open(this.path, "a", 0o600);
|
||||
try {
|
||||
await fh.appendFile(lineOf(event));
|
||||
await fh.datasync();
|
||||
} finally {
|
||||
await fh.close();
|
||||
}
|
||||
this.remember(key);
|
||||
}
|
||||
|
||||
private remember(key: string): void {
|
||||
this.seen.set(key, true);
|
||||
if (this.seen.size > REMEMBERED) {
|
||||
const first = this.seen.keys().next().value;
|
||||
if (first !== undefined) this.seen.delete(first);
|
||||
}
|
||||
}
|
||||
|
||||
private async seed(): Promise<void> {
|
||||
let size: number;
|
||||
try {
|
||||
size = (await stat(this.path)).size;
|
||||
} catch {
|
||||
return; // no trail yet
|
||||
}
|
||||
const from = Math.max(0, size - SEED_BYTES);
|
||||
const fh = await open(this.path, "r");
|
||||
let text: string;
|
||||
try {
|
||||
const buf = Buffer.alloc(size - from);
|
||||
await fh.read(buf, 0, buf.length, from);
|
||||
text = buf.toString("utf8");
|
||||
} finally {
|
||||
await fh.close();
|
||||
}
|
||||
const lines = text.split("\n");
|
||||
if (from > 0) lines.shift(); // the first is cut
|
||||
for (const line of lines) {
|
||||
if (!line) continue;
|
||||
try {
|
||||
const l = JSON.parse(line);
|
||||
this.remember(keyOf({ id: l.id ?? "", type: l.type, source: l.source, node: l.node, at: l.at, body: l.body }));
|
||||
} catch {
|
||||
// a line cut short by a failed write: its event was asked for again
|
||||
}
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
@@ -1,20 +1,26 @@
|
||||
// The audit-logger's entrypoint. The per-node module runtime imports this once the broker is
|
||||
// bound; the on("#") subscription is the whole handshake — it consumes every event on the mesh
|
||||
// (module.*, mesh.*, node.*) and writes each to the trail.
|
||||
//
|
||||
// **No event is lost** (novox/hq issue 276). A line that cannot be written is thrown, so the bus offers
|
||||
// the event again; the first failure spools it on disk, its last delivery is taken from the spool, and
|
||||
// the spool is replayed into the trail once writing works again (spool.ts). The trail skips an event id
|
||||
// it already holds, so a redelivery or a replay never writes it twice (audit.ts).
|
||||
|
||||
import { on } from "@novox/mesh-sdk/events";
|
||||
import { auditLogPath, record } from "./audit.js";
|
||||
import { auditLogPath, auditSpoolPath, Trail } from "./audit.js";
|
||||
import { replayEvery, Spool, takeOrSpool } from "./spool.js";
|
||||
|
||||
const path = auditLogPath();
|
||||
const say = (line: string) => console.error(`[audit-logger] ${line}`);
|
||||
const trail = await Trail.open(auditLogPath());
|
||||
const spool = await Spool.open(auditSpoolPath());
|
||||
const write = (event: Parameters<Trail["record"]>[0]) => trail.record(event);
|
||||
|
||||
await on("#", async (event) => {
|
||||
try {
|
||||
await record(event, path);
|
||||
} catch (err) {
|
||||
// A failure to write the audit trail is worth a loud line, never a swallowed one — but it must
|
||||
// not throw back into the broker and wedge the subscription.
|
||||
console.error(`[audit-logger] could not record ${event.type}: ${err}`);
|
||||
}
|
||||
});
|
||||
replayEvery(spool, write, 30_000, say);
|
||||
|
||||
console.log(`[audit-logger] recording all mesh events to ${path}`);
|
||||
await on("#", (event) => takeOrSpool(event, write, spool, say));
|
||||
|
||||
console.log(
|
||||
`[audit-logger] recording all mesh events to ${trail.path}` +
|
||||
(spool.size > 0 ? `; ${spool.size} spooled event(s) wait in ${spool.dir}` : ""),
|
||||
);
|
||||
|
||||
@@ -12,13 +12,16 @@
|
||||
"kind": "bundle",
|
||||
"language": "typescript",
|
||||
"entrypoints": [
|
||||
"index.js"
|
||||
"index.js",
|
||||
"tools/index.js"
|
||||
],
|
||||
"loads": [
|
||||
"index.js"
|
||||
"index.js",
|
||||
"tools/index.js"
|
||||
],
|
||||
"env": {
|
||||
"AUDIT_LOG": "${dir:trail}/audit.log"
|
||||
"AUDIT_LOG": "${dir:trail}/audit.log",
|
||||
"AUDIT_SPOOL": "${dir:spool}"
|
||||
}
|
||||
}
|
||||
]
|
||||
@@ -30,6 +33,12 @@
|
||||
"path": "${dir:trail}",
|
||||
"class": "valuable",
|
||||
"why": "the audit trail, written nowhere else"
|
||||
},
|
||||
{
|
||||
"id": "spool",
|
||||
"path": "${dir:spool}",
|
||||
"class": "valuable",
|
||||
"why": "events the trail could not take yet; after the bus gives one up, the only copy"
|
||||
}
|
||||
]
|
||||
},
|
||||
@@ -44,6 +53,11 @@
|
||||
"id": "trail",
|
||||
"type": "directory",
|
||||
"mode": "0700"
|
||||
},
|
||||
{
|
||||
"id": "spool",
|
||||
"type": "directory",
|
||||
"mode": "0700"
|
||||
}
|
||||
],
|
||||
"capabilities": [
|
||||
|
||||
@@ -4,8 +4,12 @@
|
||||
"description": "audit-logger — records every event on the mesh (module, mesh and node) to an append-only trail.",
|
||||
"type": "module",
|
||||
"private": true,
|
||||
"scripts": {
|
||||
"build": "tsc audit.ts spool.ts index.ts tools/index.ts --module NodeNext --moduleResolution NodeNext --target ES2022 --strict --skipLibCheck --outDir dist",
|
||||
"test": "npm run build && node --test --experimental-strip-types 'test/*.test.ts'"
|
||||
},
|
||||
"dependencies": {
|
||||
"@novox/mesh-sdk": "^0.1.0"
|
||||
"@novox/mesh-sdk": "^0.1.13"
|
||||
},
|
||||
"devDependencies": {
|
||||
"@types/node": "^22.0.0",
|
||||
|
||||
@@ -0,0 +1,336 @@
|
||||
// The spool — where an event this module could not write waits until it can (novox/hq issue 276).
|
||||
//
|
||||
// **A handler takes an event by returning and asks for it again by throwing** (mesh-sdk README,
|
||||
// "Taking an event"). A write that failed is therefore thrown, and the bus offers the event again five
|
||||
// seconds later, up to the consumer's maximum deliveries — after which the bus gives it up. For a
|
||||
// module whose whole job is to keep what it is sent, giving up is losing, so:
|
||||
//
|
||||
// - **The first failed write puts the event in the spool**, one file per event, written and synced
|
||||
// before the handler throws. From then on the event is on this machine's disk, whatever the bus does.
|
||||
// - **The spool counts the failed deliveries**, because the runtime does not hand a handler the bus's
|
||||
// delivery count. On the last one the event is **taken**: it is in the spool, and the bus giving it
|
||||
// up would only raise a condition about an event that is not lost.
|
||||
// - **A background pass replays the spool** into the store once writes work again, oldest first, and
|
||||
// stops at the first failure. A write that succeeds — by a redelivery or by a replay — removes the
|
||||
// event from the spool. The module's writes are idempotent by the event's id, so a replay and a
|
||||
// redelivery of the same event write it once.
|
||||
// - **Over its bound** — too many events, or one waiting too long — the spool still keeps every event,
|
||||
// but the last delivery is no longer taken: the bus gives it up and the controller raises
|
||||
// `max-deliveries` for this module's consumer (to-be 45, S9). That is the one condition the mesh
|
||||
// has today that names a consumer which cannot keep up; a module has no standing of its own to report
|
||||
// (ADR 0224's is a provider's), so the bound borrows that one rather than inventing a second.
|
||||
//
|
||||
// The same file lives in audit-logger and model-usage; a third copy belongs in the SDK instead.
|
||||
|
||||
import { mkdir, open, readdir, readFile, rename, unlink } from "node:fs/promises";
|
||||
import { createHash } from "node:crypto";
|
||||
import { join } from "node:path";
|
||||
import type { Event } from "@novox/mesh-sdk/events";
|
||||
|
||||
/** The controller's maximum deliveries for a module's consumer (mesh-controller
|
||||
* internal/broker/derived.go). The spool takes an event on this, its last, failed delivery. */
|
||||
export const MAX_DELIVERIES = 5;
|
||||
/** More events spooled than this is over the bound. */
|
||||
export const BOUND_COUNT = 1000;
|
||||
/** An event spooled longer than this is over the bound. */
|
||||
export const BOUND_AGE_MS = 30 * 60 * 1000;
|
||||
|
||||
/** One event waiting in the spool. */
|
||||
export interface SpoolEntry {
|
||||
key: string;
|
||||
event: Event;
|
||||
/** Failed deliveries seen so far. */
|
||||
attempts: number;
|
||||
/** When it first failed, and last. */
|
||||
first: string;
|
||||
last: string;
|
||||
/** The last failure's words. */
|
||||
error: string;
|
||||
/** Taken on its last delivery: only the spool holds it now. */
|
||||
held: boolean;
|
||||
}
|
||||
|
||||
/** What the spool holds, for the module's status tool and its log. */
|
||||
export interface Standing {
|
||||
dir: string;
|
||||
spooled: number;
|
||||
held: number;
|
||||
oldest?: string;
|
||||
lastError?: string;
|
||||
overBound: boolean;
|
||||
why?: string;
|
||||
bound: { count: number; ageMinutes: number };
|
||||
}
|
||||
|
||||
export interface SpoolOptions {
|
||||
maxDeliveries?: number;
|
||||
boundCount?: number;
|
||||
boundAgeMs?: number;
|
||||
now?: () => Date;
|
||||
}
|
||||
|
||||
/** What a failed write became: asked for again, held and taken, or asked for again past the bound. */
|
||||
export type Verdict = "retry" | "held" | "over-bound";
|
||||
|
||||
/** The key an event is spooled and deduplicated by: its x-event-id when it is a safe file name, else a
|
||||
* hash of what identifies it (an event without an id is still one event). */
|
||||
export function keyOf(event: Pick<Event, "id" | "type" | "source" | "node" | "at" | "body">): string {
|
||||
if (event.id && /^[A-Za-z0-9_-][A-Za-z0-9._-]{0,127}$/.test(event.id)) return event.id;
|
||||
const h = createHash("sha256");
|
||||
for (const part of [event.id ?? "", event.type, event.source, event.node, event.at, JSON.stringify(event.body ?? null)]) {
|
||||
h.update(String(part));
|
||||
h.update("\0");
|
||||
}
|
||||
return "h-" + h.digest("hex");
|
||||
}
|
||||
|
||||
export class Spool {
|
||||
private readonly entries = new Map<string, SpoolEntry>();
|
||||
private chain: Promise<unknown> = Promise.resolve();
|
||||
private readonly max: number;
|
||||
private readonly boundCount: number;
|
||||
private readonly boundAgeMs: number;
|
||||
private readonly now: () => Date;
|
||||
|
||||
private constructor(readonly dir: string, opts: SpoolOptions) {
|
||||
this.max = opts.maxDeliveries ?? MAX_DELIVERIES;
|
||||
this.boundCount = opts.boundCount ?? BOUND_COUNT;
|
||||
this.boundAgeMs = opts.boundAgeMs ?? BOUND_AGE_MS;
|
||||
this.now = opts.now ?? (() => new Date());
|
||||
}
|
||||
|
||||
/** Open the spool in `dir`, creating it, and read what it already holds. */
|
||||
static async open(dir: string, opts: SpoolOptions = {}): Promise<Spool> {
|
||||
const s = new Spool(dir, opts);
|
||||
await mkdir(dir, { recursive: true, mode: 0o700 });
|
||||
await s.load(true);
|
||||
return s;
|
||||
}
|
||||
|
||||
/** Read a spool another process writes, without changing it — for the status tool. */
|
||||
static async read(dir: string, opts: SpoolOptions = {}): Promise<Spool> {
|
||||
const s = new Spool(dir, opts);
|
||||
await s.load(false);
|
||||
return s;
|
||||
}
|
||||
|
||||
get size(): number {
|
||||
return this.entries.size;
|
||||
}
|
||||
|
||||
has(key: string): boolean {
|
||||
return this.entries.has(key);
|
||||
}
|
||||
|
||||
list(): SpoolEntry[] {
|
||||
return [...this.entries.values()].sort((a, b) => a.first.localeCompare(b.first));
|
||||
}
|
||||
|
||||
/** Record a failed write of `event`. Synced to disk before it returns; throws if it could not be. */
|
||||
failed(event: Event, err: unknown): Promise<Verdict> {
|
||||
return this.serial(async () => {
|
||||
const key = keyOf(event);
|
||||
const prev = this.entries.get(key);
|
||||
const at = this.now().toISOString();
|
||||
const entry: SpoolEntry = {
|
||||
key,
|
||||
event,
|
||||
attempts: (prev?.attempts ?? 0) + 1,
|
||||
first: prev?.first ?? at,
|
||||
last: at,
|
||||
error: String(err instanceof Error ? err.message : err).slice(0, 500),
|
||||
held: false,
|
||||
};
|
||||
const last = entry.attempts >= this.max;
|
||||
let oldest = entry.first;
|
||||
for (const e of this.entries.values()) if (e.first < oldest) oldest = e.first;
|
||||
const over = this.over(prev ? this.entries.size : this.entries.size + 1, oldest);
|
||||
entry.held = last && !over;
|
||||
await this.persist(entry);
|
||||
this.entries.set(key, entry);
|
||||
return last ? (over ? "over-bound" : "held") : "retry";
|
||||
});
|
||||
}
|
||||
|
||||
/** The event was written: it need not wait any longer. */
|
||||
done(key: string): Promise<void> {
|
||||
if (!this.entries.has(key)) return Promise.resolve();
|
||||
return this.serial(async () => {
|
||||
if (!this.entries.has(key)) return;
|
||||
await unlink(this.file(key)).catch((e: NodeJS.ErrnoException) => {
|
||||
if (e.code !== "ENOENT") throw e;
|
||||
});
|
||||
this.entries.delete(key);
|
||||
});
|
||||
}
|
||||
|
||||
/** Write every spooled event again, oldest first, stopping at the first that still fails. */
|
||||
async replay(write: (event: Event) => Promise<void>): Promise<{ replayed: number; left: number; error?: string }> {
|
||||
let replayed = 0;
|
||||
for (const entry of this.list()) {
|
||||
try {
|
||||
await write(entry.event);
|
||||
} catch (err) {
|
||||
return { replayed, left: this.entries.size, error: String(err instanceof Error ? err.message : err) };
|
||||
}
|
||||
await this.done(entry.key);
|
||||
replayed++;
|
||||
}
|
||||
return { replayed, left: this.entries.size };
|
||||
}
|
||||
|
||||
standing(): Standing {
|
||||
const list = this.list();
|
||||
const oldest = list[0]?.first;
|
||||
const newest = list.reduce<SpoolEntry | undefined>((n, e) => (!n || e.last > n.last ? e : n), undefined);
|
||||
const over = this.over(list.length, oldest);
|
||||
return {
|
||||
dir: this.dir,
|
||||
spooled: list.length,
|
||||
held: list.filter((e) => e.held).length,
|
||||
...(oldest ? { oldest } : {}),
|
||||
...(newest ? { lastError: newest.error } : {}),
|
||||
overBound: over,
|
||||
...(over ? { why: this.why(list.length, oldest) } : {}),
|
||||
bound: { count: this.boundCount, ageMinutes: Math.round(this.boundAgeMs / 60000) },
|
||||
};
|
||||
}
|
||||
|
||||
private over(count: number, oldest: string | undefined): boolean {
|
||||
return this.why(count, oldest) !== undefined;
|
||||
}
|
||||
|
||||
private why(count: number, oldest: string | undefined): string | undefined {
|
||||
if (count > this.boundCount) return `${count} events spooled, more than ${this.boundCount}`;
|
||||
if (oldest && this.now().getTime() - Date.parse(oldest) > this.boundAgeMs) {
|
||||
return `an event has waited since ${oldest}, longer than ${Math.round(this.boundAgeMs / 60000)} minutes`;
|
||||
}
|
||||
return undefined;
|
||||
}
|
||||
|
||||
private file(key: string): string {
|
||||
return join(this.dir, `${key}.json`);
|
||||
}
|
||||
|
||||
private async load(tidy: boolean): Promise<void> {
|
||||
let names: string[];
|
||||
try {
|
||||
names = await readdir(this.dir);
|
||||
} catch (e) {
|
||||
if ((e as NodeJS.ErrnoException).code === "ENOENT") return;
|
||||
throw e;
|
||||
}
|
||||
for (const name of names) {
|
||||
if (name.endsWith(".tmp")) {
|
||||
// A write cut short: the event it was for was never answered as taken, so the bus has it.
|
||||
if (tidy) await unlink(join(this.dir, name)).catch(() => {});
|
||||
continue;
|
||||
}
|
||||
if (!name.endsWith(".json")) continue;
|
||||
try {
|
||||
const entry = JSON.parse(await readFile(join(this.dir, name), "utf8")) as SpoolEntry;
|
||||
if (entry?.key && entry.event) this.entries.set(entry.key, entry);
|
||||
} catch (err) {
|
||||
// Kept on disk for a person, never deleted: it may be the only copy of an event.
|
||||
console.error(`[spool] ${join(this.dir, name)} cannot be read and is left as it is: ${err}`);
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
/** Written to a temporary file, synced, renamed over the entry, and the directory synced. */
|
||||
private async persist(entry: SpoolEntry): Promise<void> {
|
||||
const final = this.file(entry.key);
|
||||
const tmp = `${final}.tmp`;
|
||||
const fh = await open(tmp, "w", 0o600);
|
||||
try {
|
||||
await fh.writeFile(JSON.stringify(entry) + "\n");
|
||||
await fh.sync();
|
||||
} finally {
|
||||
await fh.close();
|
||||
}
|
||||
await rename(tmp, final);
|
||||
const dh = await open(this.dir, "r");
|
||||
try {
|
||||
await dh.sync();
|
||||
} catch {
|
||||
// Not every filesystem syncs a directory; the rename stands either way.
|
||||
} finally {
|
||||
await dh.close();
|
||||
}
|
||||
}
|
||||
|
||||
private serial<T>(fn: () => Promise<T>): Promise<T> {
|
||||
const run = this.chain.then(fn, fn);
|
||||
this.chain = run.catch(() => {});
|
||||
return run;
|
||||
}
|
||||
}
|
||||
|
||||
/**
|
||||
* The handler's whole discipline: write the event; if that fails, spool it and ask for it again —
|
||||
* or, on its last delivery, take it, because the spool now holds it. A write that cannot even be
|
||||
* spooled is asked for again, which is all that is left.
|
||||
*/
|
||||
export async function takeOrSpool(
|
||||
event: Event,
|
||||
write: (event: Event) => Promise<void>,
|
||||
spool: Spool,
|
||||
say: (line: string) => void = (l) => console.error(l),
|
||||
): Promise<void> {
|
||||
const what = `${event.type} (${event.id || "no id"})`;
|
||||
try {
|
||||
await write(event);
|
||||
} catch (err) {
|
||||
let verdict: Verdict;
|
||||
try {
|
||||
verdict = await spool.failed(event, err);
|
||||
} catch (spoolErr) {
|
||||
say(`could not write ${what}: ${err}; and could not spool it either: ${spoolErr}; asking for it again`);
|
||||
throw err;
|
||||
}
|
||||
if (verdict === "held") {
|
||||
say(`could not write ${what} on its last delivery: ${err}; spooled and taken, written when writing works again`);
|
||||
return;
|
||||
}
|
||||
say(
|
||||
verdict === "over-bound"
|
||||
? `could not write ${what} on its last delivery: ${err}; spooled, and NOT taken because the spool is over its bound (${spool.standing().why}) — the bus gives it up and the controller raises max-deliveries; the spool still writes it when it can`
|
||||
: `could not write ${what}: ${err}; spooled, asking for it again`,
|
||||
);
|
||||
throw err;
|
||||
}
|
||||
// Written: a copy spooled by an earlier failed delivery is no longer needed. Failing to remove it
|
||||
// costs one idempotent write on the next replay, so it is said, never thrown.
|
||||
await spool.done(keyOf(event)).catch((e) => say(`wrote ${what} but could not remove its spooled copy: ${e}`));
|
||||
}
|
||||
|
||||
/** Replay the spool every `everyMs` while it holds anything, and say loudly — every fifteen minutes —
|
||||
* while it is over its bound. Returns a stop. */
|
||||
export function replayEvery(
|
||||
spool: Spool,
|
||||
write: (event: Event) => Promise<void>,
|
||||
everyMs = 30_000,
|
||||
say: (line: string) => void = (l) => console.error(l),
|
||||
): () => void {
|
||||
let running = false;
|
||||
let loudAt = 0;
|
||||
const timer = setInterval(async () => {
|
||||
if (running || spool.size === 0) return;
|
||||
running = true;
|
||||
try {
|
||||
const r = await spool.replay(write);
|
||||
if (r.replayed > 0) say(`replayed ${r.replayed} spooled event(s); ${r.left} left`);
|
||||
const st = spool.standing();
|
||||
if (st.overBound && Date.now() - loudAt > 15 * 60_000) {
|
||||
loudAt = Date.now();
|
||||
say(`THE SPOOL IS OVER ITS BOUND: ${st.why}; ${st.spooled} event(s) wait in ${st.dir}, last error: ${r.error ?? st.lastError}`);
|
||||
}
|
||||
} catch (err) {
|
||||
say(`replaying the spool failed: ${err}`);
|
||||
} finally {
|
||||
running = false;
|
||||
}
|
||||
}, everyMs);
|
||||
timer.unref?.();
|
||||
return () => clearInterval(timer);
|
||||
}
|
||||
@@ -1,40 +1,188 @@
|
||||
import { test } from "node:test";
|
||||
import assert from "node:assert/strict";
|
||||
import { mkdtemp, readFile } from "node:fs/promises";
|
||||
import { mkdtemp, readFile, readdir } from "node:fs/promises";
|
||||
import { tmpdir } from "node:os";
|
||||
import { join } from "node:path";
|
||||
|
||||
import { useBroker } from "@novox/mesh-sdk/messaging";
|
||||
import { emit, on } from "@novox/mesh-sdk/events";
|
||||
import { record } from "../audit.ts";
|
||||
import { emit, on, type Event } from "@novox/mesh-sdk/events";
|
||||
import { Trail } from "../dist/audit.js";
|
||||
import { Spool, takeOrSpool } from "../dist/spool.js";
|
||||
import { getAuditTools } from "../dist/tools/index.js";
|
||||
|
||||
async function lines(path: string): Promise<Record<string, any>[]> {
|
||||
const text = await readFile(path, "utf8").catch(() => "");
|
||||
return text.trim() === "" ? [] : text.trim().split("\n").map((l) => JSON.parse(l));
|
||||
}
|
||||
|
||||
function ev(id: string, body: unknown = { n: 1 }): Event {
|
||||
return { type: "umami.site.created", id, source: "umami", node: "anchor", at: "2026-10-06T10:00:00.000Z", body };
|
||||
}
|
||||
|
||||
async function setup() {
|
||||
const dir = await mkdtemp(join(tmpdir(), "audit-"));
|
||||
const trail = await Trail.open(join(dir, "audit.log"));
|
||||
const spool = await Spool.open(join(dir, "spool"));
|
||||
const store = { broken: false };
|
||||
const write = async (e: Event) => {
|
||||
if (store.broken) throw new Error("ENOSPC: no space left on device");
|
||||
await trail.record(e);
|
||||
};
|
||||
const said: string[] = [];
|
||||
const handle = (e: Event) => takeOrSpool(e, write, spool, (l) => said.push(l));
|
||||
return { dir, trail, spool, store, write, handle, said, path: join(dir, "audit.log") };
|
||||
}
|
||||
|
||||
test("audit-logger records every event to the trail as one line each", async () => {
|
||||
const broker = memBroker();
|
||||
useBroker(() => broker);
|
||||
const dir = await mkdtemp(join(tmpdir(), "audit-"));
|
||||
const path = join(dir, "audit.log");
|
||||
const { handle, path } = await setup();
|
||||
|
||||
// The audit-logger's whole behaviour: consume everything, record it.
|
||||
await on("#", async (event) => record(event, path)); // the pattern index.ts subscribes
|
||||
await on("#", handle); // the pattern index.ts subscribes
|
||||
|
||||
process.env.MESH_MODULE = "umami";
|
||||
process.env.MESH_NODE = "anchor";
|
||||
await emit("site.created", { domain: "my-app" });
|
||||
await emit("node.anchor.joined", { role: "worker" }); // a node event, not a module one
|
||||
|
||||
const lines = (await readFile(path, "utf8")).trim().split("\n").map((l) => JSON.parse(l));
|
||||
assert.equal(lines.length, 2);
|
||||
const got = await lines(path);
|
||||
assert.equal(got.length, 2);
|
||||
// A module names its events locally (design 29); the module is the `source`, which together with
|
||||
// the type says whose event it was. This broker does no namespacing, so the type is as emitted.
|
||||
assert.deepEqual(lines.map((l) => l.type), ["site.created", "node.anchor.joined"]);
|
||||
assert.equal(lines[0].source, "umami");
|
||||
assert.equal(lines[0].node, "anchor");
|
||||
assert.equal(lines[0].body.domain, "my-app");
|
||||
assert.deepEqual(got.map((l) => l.type), ["site.created", "node.anchor.joined"]);
|
||||
assert.equal(got[0].source, "umami");
|
||||
assert.equal(got[0].node, "anchor");
|
||||
assert.equal(got[0].body.domain, "my-app");
|
||||
|
||||
delete process.env.MESH_MODULE;
|
||||
delete process.env.MESH_NODE;
|
||||
});
|
||||
|
||||
test("a write that fails is thrown, so the bus offers the event again — and it is spooled at once", async () => {
|
||||
const broker = memBroker();
|
||||
useBroker(() => broker);
|
||||
const { handle, store, spool, path } = await setup();
|
||||
await on("#", handle);
|
||||
store.broken = true;
|
||||
await assert.rejects(emit("site.created", { domain: "x" }), /ENOSPC/);
|
||||
assert.equal(spool.size, 1, "spooled on the first failure");
|
||||
assert.equal(spool.list()[0].attempts, 1);
|
||||
assert.equal(spool.list()[0].held, false);
|
||||
assert.deepEqual(await lines(path), []);
|
||||
});
|
||||
|
||||
test("a redelivered event is written once — also after a restart, and also when its earlier failure was spooled", async () => {
|
||||
const { handle, store, spool, path, dir } = await setup();
|
||||
await handle(ev("e1"));
|
||||
await handle(ev("e1")); // the answer was lost; the bus offers it again
|
||||
assert.equal((await lines(path)).length, 1);
|
||||
|
||||
// A restart between writing and answering: the trail remembers the ids at its end.
|
||||
const again = await Trail.open(path);
|
||||
await again.record(ev("e1"));
|
||||
assert.equal((await lines(path)).length, 1);
|
||||
|
||||
// Failed once, then written: the spooled copy goes.
|
||||
store.broken = true;
|
||||
await assert.rejects(handle(ev("e2")));
|
||||
assert.equal(spool.size, 1);
|
||||
store.broken = false;
|
||||
await handle(ev("e2"));
|
||||
assert.equal(spool.size, 0);
|
||||
assert.deepEqual(await readdir(join(dir, "spool")), []);
|
||||
assert.deepEqual((await lines(path)).map((l) => l.id), ["e1", "e2"]);
|
||||
});
|
||||
|
||||
test("on its last delivery a failed event is spooled and taken", async () => {
|
||||
const { handle, store, spool, said } = await setup();
|
||||
store.broken = true;
|
||||
for (let i = 1; i < 5; i++) await assert.rejects(handle(ev("e3")), /ENOSPC/, `delivery ${i} asks again`);
|
||||
await handle(ev("e3")); // the fifth — the controller's max-deliver — returns: taken
|
||||
const [entry] = spool.list();
|
||||
assert.equal(entry.attempts, 5);
|
||||
assert.equal(entry.held, true);
|
||||
assert.match(said.at(-1)!, /spooled and taken/);
|
||||
});
|
||||
|
||||
test("the delivery count survives a restart, because it is the spool's", async () => {
|
||||
const { handle, store, dir } = await setup();
|
||||
store.broken = true;
|
||||
for (let i = 0; i < 3; i++) await assert.rejects(handle(ev("e4")));
|
||||
const reopened = await Spool.open(join(dir, "spool"));
|
||||
assert.equal(reopened.list()[0].attempts, 3);
|
||||
});
|
||||
|
||||
test("the spool replays into the trail once writing works, once each", async () => {
|
||||
const { handle, store, spool, write, path } = await setup();
|
||||
store.broken = true;
|
||||
for (let i = 0; i < 5; i++) await handle(ev("e5")).catch(() => {});
|
||||
for (let i = 0; i < 5; i++) await handle(ev("e6")).catch(() => {});
|
||||
assert.equal(spool.size, 2);
|
||||
|
||||
// Still broken: the pass stops at the first failure and keeps everything.
|
||||
let r = await spool.replay(write);
|
||||
assert.equal(r.replayed, 0);
|
||||
assert.equal(spool.size, 2);
|
||||
|
||||
store.broken = false;
|
||||
r = await spool.replay(write);
|
||||
assert.deepEqual(r, { replayed: 2, left: 0 });
|
||||
await handle(ev("e5")); // a late redelivery after the replay
|
||||
assert.deepEqual((await lines(path)).map((l) => l.id), ["e5", "e6"]);
|
||||
});
|
||||
|
||||
test("over its bound the spool keeps the event but does not take it, so the bus gives it up and says so", async () => {
|
||||
const dir = await mkdtemp(join(tmpdir(), "audit-"));
|
||||
const spool = await Spool.open(join(dir, "spool"), { boundCount: 1 });
|
||||
const failing = async () => {
|
||||
throw new Error("down");
|
||||
};
|
||||
for (let i = 0; i < 5; i++) await takeOrSpool(ev("a"), failing, spool, () => {}).catch(() => {});
|
||||
assert.equal(spool.list()[0].held, true, "within the bound: taken");
|
||||
for (let i = 1; i < 5; i++) await assert.rejects(takeOrSpool(ev("b"), failing, spool, () => {}));
|
||||
await assert.rejects(takeOrSpool(ev("b"), failing, spool, () => {}), /down/, "over the bound: asked again on its last");
|
||||
assert.equal(spool.size, 2, "and still spooled");
|
||||
const st = spool.standing();
|
||||
assert.equal(st.overBound, true);
|
||||
assert.equal(st.spooled, 2);
|
||||
assert.equal(st.held, 1);
|
||||
assert.match(st.why!, /more than 1/);
|
||||
});
|
||||
|
||||
test("an event without a body, or without an id, is recorded once", async () => {
|
||||
const { handle, path } = await setup();
|
||||
await handle(ev("e7", null));
|
||||
await handle(ev("", undefined));
|
||||
await handle(ev("", undefined));
|
||||
const got = await lines(path);
|
||||
assert.equal(got.length, 2);
|
||||
assert.equal(got[0].body, null);
|
||||
});
|
||||
|
||||
test("an event waiting longer than the bound puts the spool over it", async () => {
|
||||
const dir = await mkdtemp(join(tmpdir(), "audit-"));
|
||||
let now = new Date("2026-10-06T10:00:00Z");
|
||||
const spool = await Spool.open(join(dir, "spool"), { now: () => now });
|
||||
await takeOrSpool(ev("old"), async () => { throw new Error("down"); }, spool, () => {}).catch(() => {});
|
||||
assert.equal(spool.standing().overBound, false);
|
||||
now = new Date("2026-10-06T10:31:00Z");
|
||||
assert.match(spool.standing().why!, /longer than 30 minutes/);
|
||||
});
|
||||
|
||||
test("audit_status says what waits in the spool, read from disk by the tool's own process", async () => {
|
||||
const { handle, store, dir } = await setup();
|
||||
store.broken = true;
|
||||
for (let i = 0; i < 5; i++) await handle(ev("s1")).catch(() => {});
|
||||
await handle(ev("s2")).catch(() => {});
|
||||
const [tool] = getAuditTools({ AUDIT_LOG: join(dir, "audit.log"), AUDIT_SPOOL: join(dir, "spool") });
|
||||
assert.equal(tool.name, "audit_status");
|
||||
const got = (await tool.run({}, {} as never)) as { spool: { spooled: number; held: number; lastError: string } };
|
||||
assert.equal(got.spool.spooled, 2);
|
||||
assert.equal(got.spool.held, 1);
|
||||
assert.match(got.spool.lastError, /ENOSPC/);
|
||||
});
|
||||
|
||||
function memBroker() {
|
||||
const subs: { pattern: string; handler: (env: { key: string; node: string; body: unknown }) => Promise<void> }[] = [];
|
||||
return {
|
||||
|
||||
@@ -0,0 +1,27 @@
|
||||
// The audit-logger's one tool — its standing: where the trail is, and what waits in the spool
|
||||
// (novox/hq issue 276). Launched as its own process beside the handler, so it reads the spool from
|
||||
// disk rather than asking the handler.
|
||||
|
||||
import { stat } from "node:fs/promises";
|
||||
import { registerModuleTools, type ToolDefinition } from "@novox/mesh-sdk/tools";
|
||||
import { auditLogPath, auditSpoolPath } from "../audit.js";
|
||||
import { Spool } from "../spool.js";
|
||||
|
||||
export function getAuditTools(env: NodeJS.ProcessEnv = process.env): ToolDefinition[] {
|
||||
return [
|
||||
{
|
||||
name: "audit_status",
|
||||
description:
|
||||
"The audit trail's standing: its path and size, and the events that could not be written yet — how many wait in the spool, how many were taken from the bus and are held only there, the oldest, the last error, and whether the spool is over its bound (then the bus gives events up and max-deliveries is raised).",
|
||||
input: {},
|
||||
run: async () => {
|
||||
const path = auditLogPath(env);
|
||||
const size = await stat(path).then((s) => s.size, () => null);
|
||||
const spool = await Spool.read(auditSpoolPath(env));
|
||||
return { trail: { path, bytes: size }, spool: spool.standing() };
|
||||
},
|
||||
},
|
||||
];
|
||||
}
|
||||
|
||||
registerModuleTools("audit-logger", (env) => getAuditTools(env));
|
||||
@@ -8,5 +8,10 @@
|
||||
"skipLibCheck": true,
|
||||
"noEmit": true
|
||||
},
|
||||
"include": ["audit.ts", "index.ts"]
|
||||
"include": [
|
||||
"audit.ts",
|
||||
"spool.ts",
|
||||
"index.ts",
|
||||
"tools/index.ts"
|
||||
]
|
||||
}
|
||||
|
||||
Reference in New Issue
Block a user