audit-logger, model-usage: retry a failed write and never lose the event (hq issue 276) #94

2026-10-06T16:36:41Z

mesh-admin commented

2026-10-06 16:36:41 +00:00

Both modules caught a failed write in their event handler and took the event anyway — lost silently. Under mesh-sdk 0.1.13's rule (README, "Taking an event") a handler throws when the work was not done. The operator's decision: they retry, and never lose an event.

Behaviour

A failed write throws, so the bus offers the event again (5 s, up to the consumer's max-deliver of 5).
The first failure spools the event on disk (one file per event, written + fsynced before the throw). From then on the event is on the machine's disk whatever the bus does.
The spool counts failed deliveries — the runtime does not pass the bus's delivery count to a handler (node-tools launch.Start sends only the envelope) — and the count survives a restart. On the 5th failed delivery the event is taken: the spool holds it.
A background pass (every 30 s) replays the spool, oldest first, stopping at the first failure; any successful write (redelivery or replay) removes the spooled copy.
Over its bound (more than 1000 spooled, or one waiting more than 30 min) every event is still spooled, but the last delivery is not taken: the bus gives it up and the controller raises max-deliveries for the module's consumer (to-be 45, S9). No module-level standing exists (ADR 0224's is a provider's, and the bus would refuse it from these modules), so the bound borrows the existing condition instead of inventing one. A loud log line every 15 min while over the bound.
Status tools: audit_status (new; audit-logger had no tools) and model_usage_status — spooled, held, oldest, last error, over-bound and why. Read from disk, since each entrypoint is its own process.
Idempotent writes: the trail skips an event id it already wrote (seeded from the last 8 MiB of the trail on start; an append-only file has no ON CONFLICT, this is the SDK's "skip an id already done"), and fsyncs each line. The usage upsert keeps the reading observed latest (event at), so a redelivery rewrites the same row and a late replay never overwrites a newer reading — migration 2 adds observed_at, event_id.
Spool directories are declared as data, class valuable (ADR 0233).
Postgres pool is bounded (connect 10 s, query 30 s) so an unreachable store is a thrown error well inside the runtime's 2-min event timeout, not a hang.

Also

model-usage moves to the bundle shape (ADR 0198), as the audit-logger did in dd93cfd: its container had a placeholder all-zero image digest and no Dockerfile, and its tools were never loaded. Schema now in a prepare run-once step (ADR 0135, as mesh-catalog), migrations numbered and recorded in usage_schema, each safe on the v1 table that exists without a record.
A row the store could never take (missing key, non-number value) is said and skipped — retrying would not change it.
Null body: the log-only handlers of redis, mssql, mosquitto, mongodb, mesh-vault, showcase and mesh-catalog's build handler no longer throw a TypeError on an event without a body. Go handlers were checked: they unmarshal into structs and are safe.
Both on @novox/mesh-sdk ^0.1.13. spool.ts is the same file in both modules; a third user means it belongs in the SDK.

Tests

npm test in each (builds to dist, as gitea does):

audit-logger (10): records every event; write fails → handler throws and is spooled; redelivery after success, after a restart, and after a spooled failure → one line; 5th delivery → spooled and taken; delivery count survives restart; spool replays once each; over bound (count, age) → not taken but kept; null body / no id → recorded once; audit_status.
model-usage (7): store refuses → throws + spooled; redelivery → no second row, spool cleared; 5th delivery → spooled and taken; replay works and an older reading replayed late doesn't overwrite a newer; null/garbage body taken without TypeError; model_usage_status offered even without a store; and, with TEST_DATABASE_URL, the real SQL — run against a throwaway postgres 17 seeded with the v1 table: migrations 1, 2 applied, second run applies none, latest-observed upsert holds.
mesh-controller module check: both ok, spool (valuable).
tsc clean for every touched module (showcase has two pre-existing errors in files not touched).

Rollout

Neither module is assigned on any machine today (checked through mesh-controller.node for all four), so merging changes nothing live. When assigned: model-usage's prepare step migrates the store before the new version starts. Nothing to do by hand.

Both modules caught a failed write in their event handler and took the event anyway — lost silently. Under mesh-sdk 0.1.13's rule (README, "Taking an event") a handler throws when the work was not done. The operator's decision: they retry, and never lose an event. ## Behaviour - **A failed write throws**, so the bus offers the event again (5 s, up to the consumer's max-deliver of 5). - **The first failure spools the event** on disk (one file per event, written + fsynced before the throw). From then on the event is on the machine's disk whatever the bus does. - **The spool counts failed deliveries** — the runtime does not pass the bus's delivery count to a handler (node-tools `launch.Start` sends only the envelope) — and the count survives a restart. **On the 5th failed delivery the event is taken**: the spool holds it. - **A background pass (every 30 s) replays the spool**, oldest first, stopping at the first failure; any successful write (redelivery or replay) removes the spooled copy. - **Over its bound** (more than 1000 spooled, or one waiting more than 30 min) every event is still spooled, but the last delivery is *not* taken: the bus gives it up and the controller raises `max-deliveries` for the module's consumer (to-be 45, S9). No module-level standing exists (ADR 0224's is a provider's, and the bus would refuse it from these modules), so the bound borrows the existing condition instead of inventing one. A loud log line every 15 min while over the bound. - **Status tools**: `audit_status` (new; audit-logger had no tools) and `model_usage_status` — spooled, held, oldest, last error, over-bound and why. Read from disk, since each entrypoint is its own process. - **Idempotent writes**: the trail skips an event id it already wrote (seeded from the last 8 MiB of the trail on start; an append-only file has no ON CONFLICT, this is the SDK's "skip an id already done"), and fsyncs each line. The usage upsert keeps the reading *observed* latest (event `at`), so a redelivery rewrites the same row and a late replay never overwrites a newer reading — migration 2 adds `observed_at`, `event_id`. - Spool directories are declared as data, class **valuable** (ADR 0233). - Postgres pool is bounded (connect 10 s, query 30 s) so an unreachable store is a thrown error well inside the runtime's 2-min event timeout, not a hang. ## Also - **model-usage moves to the bundle shape (ADR 0198)**, as the audit-logger did in dd93cfd: its container had a placeholder all-zero image digest and no Dockerfile, and its tools were never loaded. Schema now in a `prepare` run-once step (ADR 0135, as mesh-catalog), migrations numbered and recorded in `usage_schema`, each safe on the v1 table that exists without a record. - A row the store could never take (missing key, non-number value) is said and skipped — retrying would not change it. - **Null body**: the log-only handlers of redis, mssql, mosquitto, mongodb, mesh-vault, showcase and mesh-catalog's build handler no longer throw a TypeError on an event without a body. Go handlers were checked: they unmarshal into structs and are safe. - Both on `@novox/mesh-sdk ^0.1.13`. `spool.ts` is the same file in both modules; a third user means it belongs in the SDK. ## Tests `npm test` in each (builds to dist, as gitea does): - audit-logger (10): records every event; write fails → handler throws and is spooled; redelivery after success, after a restart, and after a spooled failure → one line; 5th delivery → spooled and taken; delivery count survives restart; spool replays once each; over bound (count, age) → not taken but kept; null body / no id → recorded once; `audit_status`. - model-usage (7): store refuses → throws + spooled; redelivery → no second row, spool cleared; 5th delivery → spooled and taken; replay works and an older reading replayed late doesn't overwrite a newer; null/garbage body taken without TypeError; `model_usage_status` offered even without a store; and, with `TEST_DATABASE_URL`, the real SQL — run against a throwaway postgres 17 seeded with the v1 table: migrations 1, 2 applied, second run applies none, latest-observed upsert holds. - `mesh-controller module check`: both ok, spool (valuable). - `tsc` clean for every touched module (showcase has two pre-existing errors in files not touched). ## Rollout Neither module is assigned on any machine today (checked through `mesh-controller.node` for all four), so merging changes nothing live. When assigned: model-usage's prepare step migrates the store before the new version starts. Nothing to do by hand.

mesh-admin added 1 commit 2026-10-06 16:36:41 +00:00

audit-logger, model-usage: retry a failed write and never lose the event (hq issue 276) 08265a70ca

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.

mesh-admin merged commit 7f99fb4a85 into main

2026-10-06 16:38:07 +00:00

mesh-admin deleted branch fix/audit-and-usage-never-lose-an-event

2026-10-06 16:38:07 +00:00

mesh-admin commented

2026-10-06 23:08:49 +00:00

Delivery novox/mesh-catalog@7f99fb4a85b8 — delivered since 2026-10-06T23:05:28Z

Machines

build-agent on ace: sent
fail2ban on ace: sent
mesh-catalog on novox: sent
records on novox: sent

Transitions

2026-10-06 23:05 (new) → proposed (announced): novox/mesh-catalog#94 merged; its head was not heard by this owner, so it is made from the forge's word
2026-10-06 23:05 proposed → held (merged-unchecked): merged without a passing check — a verdict known with it is taken first: only a person decides that it goes on
2026-10-06 23:05 held → delivering (go): its walk started on a word that was not this owner's: the controller's own path, which waits for nobody, or a person's plans go
2026-10-06 23:05 delivering → delivered (done): its walk is done: every machine of its deploy plan passed, or was left as its policy says

The commit's note under refs/notes/mesh-plan keeps every transition: git log --notes=mesh-plan.

**Delivery** `novox/mesh-catalog@7f99fb4a85b8` — **delivered** since 2026-10-06T23:05:28Z **Machines** - build-agent on ace: sent - fail2ban on ace: sent - mesh-catalog on novox: sent - records on novox: sent **Transitions** - 2026-10-06 23:05 (new) → proposed (announced): novox/mesh-catalog#94 merged; its head was not heard by this owner, so it is made from the forge's word - 2026-10-06 23:05 proposed → held (merged-unchecked): merged without a passing check — a verdict known with it is taken first: only a person decides that it goes on - 2026-10-06 23:05 held → delivering (go): its walk started on a word that was not this owner's: the controller's own path, which waits for nobody, or a person's `plans go` - 2026-10-06 23:05 delivering → delivered (done): its walk is done: every machine of its deploy plan passed, or was left as its policy says The commit's note under `refs/notes/mesh-plan` keeps every transition: `git log --notes=mesh-plan`.

Sign in to join this conversation.

1 Participants

Notifications

Due Date

No due date set.

Dependencies

No dependencies set.

Reference: novox/mesh-catalog#94