Runbook Async Event Log Mirror

Runbook: the async event-log mirror

noetl/ai-meta#155. LIVE on prod since 2026-08-19. Last verified 2026-08-20.

The one-flag rollback

kubectl -n noetl set env deploy/noetl-server-rust \
  NOETL_EHDB_EVENTLOG_MIRROR_ASYNC=false \
  NOETL_EHDB_CROSSSTORE_PARITY_LAG_TOLERANCE_SECS=0

No image roll. Restores the inline mirror, which is what prod ran before.

⚠ Set both or neither. MIRROR_ASYNC=true with the tolerance at 0 is the dangerous pairing: the mirror is queued while the comparator has no recency bound, so it reports missing_event for events that are merely in flight and the tier is judged divergent on its own liveness.

What changed and why

The server mirrors every authoritative event into the event-log tier. That mirror used to run inline on the emit_events chokepoint, so every event paid a relay round trip plus a tier append before the write returned — measured at 110 ms/call × 76 calls ≈ 8.4 s per Muno planner turn, after the runtime cache had already cut it from 85.6 s.

None of that work is on the critical path of anything: the authoritative write has already committed when the mirror runs. It now goes through a bounded in-process queue drained by a single task.

Measured on prod: emit_mirror 78.6–87.6 ms → 0.1 ms per call (~6.0 s → 0.007 s per turn); median warm turn 16.9 s → 13.0 s.

⚠ The turn-level win is smaller than the mirror cost removed, because not all 76 mirror calls sit on the turn's critical path. Both numbers are real; quote both.

Why it could not ship as just a queue

The cross-store comparator is the tier's correctness evidence, and it had no recency bound — correct while the mirror was synchronous, because an event was in the tier before emit_events returned. Async breaks that assumption.

So the change ships with a lag-tolerance window: mirror-expected events younger than the window are treated as in flight rather than missing. It is a latency concession, never a coverage one — a genuinely lost event is invisible for the window and then reports missing_event forever.

The window is a prefix cut at the first event newer than it, excluded from both sides, so a fast mirror that already delivered a recent record is not scored as holding an extra. An execution wholly inside the window scores pending_mirror, not match — an untaken comparison is not agreement.

The two controls that give it teeth

lag_within_window and lag_beyond_window run on every sampler tick over one fixture driven twice with only the horizon moved. A single control proves nothing here: a comparator taught to ignore everything passes "clean parity under tolerance" perfectly. The pair asserts a discrimination — the same absent event is forgiven inside the window and still reported outside it.

Check them live:

kubectl -n noetl exec deploy/noetl-server-rust -- \
  wget -qO- 127.0.0.1:8082/api/ehdb/parity/self-test \
  | jq '.controls[] | select(.expected == false)'

Empty output is the healthy answer. Anything listed voids every zero the comparator has published.

Sizing the window — measure, then set

Do not pick the window. Turn async on behind a deliberately wide window, measure, then narrow:

1. Enable async with a wide window (300 s) — both flags in one rollout, so there is never an instant with async armed and the window at 0.
2. Read the real lag: noetl_ehdb_eventlog_mirror_lag_seconds.
3. Set the window comfortably above the observed p99.

Prod measurement at cutover, 241 observations: mean 84 ms, p50 67 ms, p95 374 ms, p99 699 ms, max < 1 s → window set to 30 s (≈43× p99).

⚠ 30 s is deliberately below the sampler's SETTLE_SECS (120 s). That keeps the background sampler comparing every execution exactly as before; the window then guards only the on-demand endpoint, which has no settle filter. Keep that inequality if you retune either.

⚠ A window at or below the real lag self-demotes a healthy tier. Driven hard in kind until mean lag hit 5.76 s against a 5 s window, the comparator correctly reported divergence.

Backpressure — three rungs, no drop rung

1. try_send — room on the queue, microseconds.
2. reserve() with a timeout — the queue is full, so the emit path waits. Nothing lost, order preserved.
3. inline delivery — the queue stayed full past the timeout; i.e. the pre-change behaviour.

Rung 3 is the only path that can deliver out of order relative to batches still queued for the same execution, so it is metered separately (queue_full_inline) and alerted on. At prod load rung 2 has never engaged.

⚠ reserve() rather than send() is load-bearing. send(batch) moves the batch into the future, so a timeout cancellation takes the events with it. The first implementation did exactly that and lost 32 of 60 records while every counter still read correctly, because the events were counted at the moment they were lost.

SIGTERM flushes the queue; anything still pending at the deadline is counted shutdown_abandoned, so a later divergence is attributable to the restart.

Metrics

metric	the question only it answers
..._mirror_lag_seconds	is the real lag inside the window the comparator was told to allow
..._mirror_pending_events	is the queue drained or stalled — a stalled queue emits no lag observations, so its histogram reads exactly like an idle system
..._mirror_queue_total{outcome}	conservation: enqueued + enqueued_after_wait must equal drained
..._mirror_async_enabled	is this process async, vs "flag on but the drain never started"
..._crossstore_parity_lag_tolerance_seconds	the configured window, published so the alert reads it rather than a copy
..._crossstore_pending_total	what the window cost, published rather than subtracted in silence
..._mirror_send_error_total{kind}	which transport failure — the discriminator attempt{unavailable} lacks (see below)
..._mirror_repair_total{outcome}	did a repair close the gap; ⚠ repaired alone says nothing about CONTENT — read hydrated too

Healthy snapshot (prod, 2026-08-20): enqueued 380 = drained 380, pending 0, queue_full_inline 0, shutdown_abandoned 0, parity match 268 / divergent 0, served_primary 925 with every demote outcome 0.

A repair closes the COUNT gap and used to open a CONTENT gap

Fixed in noetl-server v3.109.1 (server#430). Read this before trusting any "repaired" outcome from before it.

The ai-meta#342 repair sweep re-mirrors missing rows through mirror_rows, the same chokepoint the live path uses — and the call site's comment claimed that made a repaired record "byte-identical to a first-delivery one". It did not, because the two paths hand that chokepoint different rows:

path	source of the row	result carries
live mirror	the EventRow the writer holds in memory	inlined content
repair	the persisted noetl.event row	a reference (under NOETL_PERMANENT_LOG_LEAN=true)

So a repair closed the count gap and left the content divergent, and repairing again could not fix it — it rewrote the same reference.

Measured on prod 2026-09-12, on the two executions the sweep had repaired:

execution	re-mirrored	still differing on result	outside the re-mirrored set
357138298767941632	39	3	0
357138152818745344	26	3	0
357138424311848960 (never repaired)	—	0	—

Three of each because only results over the inline budget are externalised.

⚠ Why it went unseen for a whole session: the field-level differ (/api/ehdb/projection-fold/diff/{id}) was itself unhydrated, so it reported result as differing on every execution with an externalised result. The three events that really differed were indistinguishable from the artefact. Fixing the instrument is what made the defect legible — the third unhydrated comparator found in this area after server#425 and server#426.

Operationally: repair now reports hydrated — how many re-mirrored rows carried an externalised result. A repair that closes missing_after while leaving content divergent reads identically to a clean one from the outcome alone, which is exactly how this hid.

not_comparable is not a divergence

An execution the tier cannot return is not a divergent one, and until server#429 the parity surface could not say so: digests_agree: bool has no third value, so a refused read read as false.

On a fixed 40-execution prod sample (2026-09-12), 3 of the 19 apparent divergences were unreadable rather than divergent — all large muno/playbooks/itinerary-planner runs refused by the tier-service frame cap:

read: tier-service frame of 1174874 bytes exceeds the 1048576-byte cap

The verdict is three-valued now (agree / diverged / not_comparable), and the equivalence sweep publishes accounted_for — agreed + disagreed + not_comparable + comparison_errors == examined. A scan that does not publish its denominator is the failure one layer up: before this, unreadable executions left agreed + disagreed silently and equivalence_holds was computed over a population the response never stated.

The cap itself is worker#311 (not deployed — the tier service runs in noetl-cmdbus-writer-0, which hosts both buses, so rolling it is owner-gated). The codec was asymmetric: write_frame checked only u32 overflow while read_frame enforced 1 MiB, and both ends shared one constant — so the service could serialise replies its own client structurally could not read, deterministically, for every execution over the cap.

Attributing a mirror send failure

attempt_total{outcome="unavailable"} counts a timeout, a refused connection and a mid-body reset identically, and reqwest's Display for a timeout is the bare error sending request for url (…) with no source chain. That is why the APPEND_TIMEOUT hypothesis went a full session without being settled.

Since v3.109.0 the cause is a label:

metric	the question only it answers
..._mirror_send_error_total{kind}	which transport failure — timeout / connect / body / decode / redirect / request / other

All seven are pinned at 0, because Registry::gather prunes empty families and an absent series reads exactly like a zero one — and on a healthy writer most of these legitimately never fire.

⚠ Change APPEND_TIMEOUT only if kind="timeout" is the label that moves. Raising a timeout before the error says what it is produces a mitigation nobody can evaluate: if it helps you do not learn why, and if it does not you have widened a window on the event-write path for nothing.

The timeout is an un-batched fan-out, not a slow network

Every mirror send failure measured on prod 2026-09-12 was a timeout — send_error_total{kind="timeout"}, with connect, body, decode, redirect, request and other all at 0. The cause is one layer below:

noetl_ehdb_tier_append_records_total{path="single"}  80264
noetl_ehdb_tier_append_records_total{path="batch"}       0     ← never once

The relay appends one record at a time. A 29-record mirror POST is 29 sequential tier-service round trips against an fsync-per-append writer, and the per-record fsync measures ~118 ms at production payload size — so 29 records overrun the server's 5 s APPEND_TIMEOUT unaided.

⚠ Do not raise APPEND_TIMEOUT. It would buy time for a loop that should not exist.

Arming the batch path

NOETL_EHDB_TIER_APPEND_BATCH=true on the relay. Two things to know:

1. It requires chunking (noetl/worker#313). append_batch_tier puts every payload in one frame, and the tier service reads requests at MAX_FRAME_BYTES = 1 MiB — which noetl/ai-meta#343 deliberately did not raise, because it bounds an untrusted length prefix checked before any allocation. A 64-event itinerary-planner batch is ~1.17 MB, so arming batching unchunked fixes the small executions and hard-fails the large ones that are already failing. The two limits are coupled.
2. Verify the path actually runs. tier_append_records_total{path="batch"} has never been non-zero. "The flag is set" and "the path runs" are independent claims, and this counter is the one that settles the second.

⚠ The chunk budget counts escaped bytes. Payloads are JSON documents embedded as JSON strings, so every " becomes \" and the serialised cost approaches twice the raw length. Budgeting on raw length builds frames that pass the local check and are refused by the service.

⛔ A record already written to the tier cannot be corrected

Worth knowing before anyone designs a "re-mirror to fix it" path.

The event-log tier deduplicates by IGNORING, not by replacing — "a dedupe returns the existing position and does not advance the count". Re-sending the same event_id with corrected content is a no-op that reports success.

And the tier service accepts exactly five ops:

Append   AppendBatch   Health   ReadExecution   Scan

No replace, no upsert, no delete. The KV and vector engines have them; the event log deliberately does not, because it is append-only — the same invariant that governs noetl.event itself.

So content written in error (see the repair section above) is not repairable in place. The remedies are to let a tier refill re-mirror it through the live path, or to mark the execution known-divergent so it stops polluting the parity metric. Adding a mutation operation to an append-only log is not a fix, it is a new problem.

✅ The batch path is LIVE (2026-09-13) — and what proved it

NOETL_EHDB_TIER_APPEND_BATCH=true is armed on the relay, with chunking (noetl/worker#313, v5.132.0) and the frame-cap fix (v5.131.3).

The counter that had never moved:

tier_append_records_total{path="batch"}   0 -> 460      (was 0 of 80,264 records, ever)
tier_append_records_total{path="single"}            2

⚠ Always check this counter after arming the flag. "The flag is set" and "the path runs" are independent claims, and this counter is the only thing that settles the second.

What it changed for repair:

	before	after
a 64-event repair	partial, 1 of 39 landed	repaired, 64 of 64, one pass
14 executions / 378 missing events	—	missing_after = 0, 0 partial
new dropped / timeout	climbing	0 / 0

Parity on those 14: agree 14, diverged 0, not_comparable 0 — including the three executions that had defined the whole investigation, now all agree pg=64 tier=64.

⚠ Rolling the worker pools in a capacity-tight cluster

Check node memory requests before any roll. The relay is replicas: 1 with maxSurge: 25%, which rounds up to +1 pod at 3 Gi. With nodes at 99% memory requests that surge cannot schedule, forces an Autopilot scale-up, and — if quota blocks the scale-up — takes the writer down with it. That is the 2026-09-13 outage in one sentence.

Surge-free roll (what the pools now use):

kubectl -n noetl patch deploy/<pool> --type=merge \
  -p '{"spec":{"strategy":{"rollingUpdate":{"maxSurge":0,"maxUnavailable":1}}}}'

spec.strategy is not part of the pod template, so this apply causes zero churn. A correct surge-free rollout logs 0 of N updated replicas are available — terminate-then-create, capacity-neutral. Cost is a brief single-replica gap; mirror deliveries retry across it.

⚠⚠ The writer StatefulSet has no volumeClaimTemplates

noetl-cmdbus-writer mounts cmdbus-data, eventbus-data and eventbus-kv by name from spec.template.spec.volumes. Deleting those PVCs does not cause them to be recreated — the pod declares volumes that do not exist and is unschedulable forever. That is the noetl/ai-meta#323 shape. If you ever delete them, recreate them explicitly before scaling the StatefulSet back up.

⚠ Related trap: a GCE disk showing USERS=0 means its pod is not currently scheduled, not that nothing uses it. During an outage every one of the writer's disks reads USERS=0.

⚠ And the PVCs are named after the buses (eventbus-*), not the workload that mounts them (cmdbus-writer) — because one writer process hosts both buses. They look orphaned and are not.

Alerts

Six policies guard this, declared as code in noetl/ops at ci/monitoring/alertpolicies.json: lag past the window, queue stalled, inline fallback, shutdown-abandoned, comparator comparing nothing, controls failed.

⚠ They are Cloud Monitoring alert policies, not GMP Rules. On this project the GMP Rules → managed Alertmanager path is inert — the OperatorConfig names a configSecret that does not exist in gmp-public — so anything that must page belongs in alertpolicies.json. See noetl/ai-meta#238.

Configuration reference

variable	default	notes
NOETL_EHDB_EVENTLOG_MIRROR_ASYNC	false	arms the queue + drain task at startup
NOETL_EHDB_CROSSSTORE_PARITY_LAG_TOLERANCE_SECS	0	required whenever async is on; keep below SETTLE_SECS
NOETL_EHDB_EVENTLOG_MIRROR_QUEUE_CAPACITY	512	depth in batches
NOETL_EHDB_EVENTLOG_MIRROR_ENQUEUE_TIMEOUT_MS	5000	wait for room before rung 3
NOETL_EHDB_EVENTLOG_MIRROR_DRAIN_MAX_BATCHES	64	batches coalesced per drain pass
NOETL_EHDB_EVENTLOG_MIRROR_FLUSH_TIMEOUT_MS	10000	shutdown flush deadline

Full env-var rationale: the deployment-specification page on the noetl/server wiki.

Option 1 — the runtime replay cache

NOETL_EHDB_REFERENCE_RUNTIME_CACHE=true, worker v5.119.1, live on the cmdbus-writer StatefulSet (where the tier store lives — not on the worker Deployments, which do not need it).

tier_store::driver() built a new driver per operation, and every method called LocalReferenceRuntime::open, which replayed the entire JSONL log — 161 MB. The tell was a read-only probe: scan(limit=10) returning 8 KB cost the same 835 ms as a read_execution returning 92 KB. Cost independent of result size ⇒ not the read, the replay in front of it.

emit_mirror 1141 ms → 110 ms per call; tier read_execution 858 ms → 23 ms.

Option 2 — the batch append substrate

NOETL_EHDB_TIER_APPEND_BATCH (ehdb#317 + worker#281): one open, N writes, one fsync.

⚠ Still OFF on prod as of 2026-08-20 — noetl_ehdb_tier_append_records_total{path="batch"} 0 on both replicas. It was measured inert under the synchronous mirror (prod events arrive p50 225 ms apart, so the mirror got ~1 record per call) and a coalescing window was deliberately not built, because it would add latency to every event and batch nothing. The async queue is what creates multi-record batches — proven in kind at 104 batched vs 8 single. Enabling it on prod is tracked at noetl/ai-meta#284.

⚠ The split is per pod: the relay targets a Service, so every append lands on one replica and the other reads 0. Sum across replicas.

Related

• noetl/ai-meta#155 — the arc
• noetl/ai-meta#238 — alerting
• Runbook: prod cutover, event log
• noetl/ops runbooks/noetl-ehdb-mirror-async.md — the ops-side twin