fix(sel): warm singleton at startup; drop per-site audit hops (#8608) - #8741
Conversation
SecurityEventLog._init_locked ran on whatever thread first called sel(): blocking file I/O (trust-dir creation, HMAC key load/create, a tail read of the live log) that stalled the event loop when a handler's audit was the process's first touch. The per-site fix — asyncio.to_thread wrappers around log_api_access — was replicated 17 times across the dashboard while 250+ other call sites remained candidate first-touch stalls. Cause-level fix: warm the singleton once, off the loop, in BOTH async server start paths (warm_sel_singleton, mirroring warm_auth_singletons), before the middleware chain is built and before the socket binds. A post-init non-critical log_api_access only enqueues to the writer thread, so the 17 non-critical per-site to_thread wrappers are replaced with direct calls. Deliberately KEPT offloaded (read before deleting, per the issue's own caveat): the seven critical=True sites (autonudge_authz x2, taskrunner, cron x3, md_notebook) — a critical audit writes SYNCHRONOUSLY on its caller's thread by design, so their to_thread wrappers carry the write, not just the init. Also kept: per-site best-effort exception guards where they existed — construction can still raise after a FAILED warm (e.g. a trust root too short to sign the chain), and an unguarded audit would turn a 403 denial into a 500. Review-driven hardening (pre-push GPT lane): log()'s writer-unavailable fallback used to _flush_batch synchronously on whatever thread hit it — reachable ON the event loop once the per-site hops are gone. The fallback is now loop-aware: on the loop a non-critical event is dropped with a warning (best-effort by contract; a frozen loop is not survivable), off the loop it still writes synchronously; either way the failed enqueue's pending credit is returned so flush() cannot wait on a count nothing will decrement. Boot-path note (AUTOSDE no-new-work-on-gateway-boot-path): the warm is one awaited asyncio.to_thread before readiness, explicitly the rule's allowed shape for init that must precede serving traffic. Worst-case bound does not scale with user data: one key-file read (or create), a tail read of the live log (one 4 KiB chunk on a healthy log, worst case a full backward scan bounded by _SEGMENT_MAX_BYTES on a corrupt tail), one stat. Best-effort: a failed warm logs and never blocks readiness; the first later touch retries init on its caller's thread (the pre-warm behavior), and critical audits still fail closed at their own sites. Tests: the #8523 first-touch off-loop property migrates from the members deny path to the startup warm (test_sel_startup_warm.py: real _init_locked off-loop, failure swallow, and a source guard pinning both start paths warm before state.ready and before the middleware chain). The members thread-ident tests now pin the inline enqueue, and the members AST guard is inverted: no log_api_access may hide inside a to_thread lambda. Mutation-verified: bare-sel() warm, dropped except, dropped/moved warm in either start path, and a re-added per-site wrapper are each caught by a distinct test, as are dropping the loop-guard on the writer-unavailable fallback and making it drop unconditionally. Closes #8608
Design Review (Fable 5) — ✅ PASSDesign-level review of The design here is sound: this replaces 17 per-site symptom patches with a single root-cause fix at the correct layer, following an existing precedent in the same file. Design-Verdict: PASS Root-cause fix at the right seam: one startup warm retires a growing class of per-site thread hops, with critical-write offloads correctly preserved. The failed-warm residual (first later touch retries blocking init on the caller's thread, potentially the loop) is disclosed, bounded to already-broken SEL storage, and the rejected alternative (warm-state gating every call site) would reintroduce exactly the per-site complexity being deleted. The newly reachable sync fallback was made loop-aware rather than left latent, and the seven [DESIGN-REVIEWED] 91ae2c8 |
GPT 5.6 Review — ✅ no blocking findingsGPT 5.6 completed its review of This comment is updated in place on each push. Review detailsNo findings. False positive or not applicable? A repository writer can comment: |
Opus 4.8 Review — ✅ no blocking findingsReviewed Review detailsBoth candidates hinge on failure modes that do not occur in normal operation — Candidate 1 requires the SEL writer thread failing to start (FD/thread exhaustion), Candidate 2 requires the startup warm itself raising. Neither supplies a concrete input that occurs in practice; both describe documented, deliberate best-effort tradeoffs, and Candidate 2's exposure pre-existed at 250+ unwrapped sites. The pending-credit accounting ( No findings. [OPUS-REVIEWED] 91ae2c8 Verdict parsed from the review's SHA-scoped output markers for commit False positive or not applicable? A repository writer can comment: |
First Principles Review (Fable 5) — ✅ PASSPremise-level review of All claims verified. I have everything needed to produce the review. First-Principles-Verdict: PASS Cause-level fix for a counted class (18+ per-site hops, 1070 latent sites): warm once at startup, delete the workarounds; every item earns its place. What this change shipsIntent: stop the SEL singleton's first-touch file I/O from ever landing on the event loop, without a per-call-site workaround. FIX.
WatchThe description's "7 Subtractions
[FIRST-PRINCIPLES-REVIEWED] 91ae2c8 |
…thread (#8844) #8741 (#8608) warmed the SEL singleton at startup and inverted the members AST guard: no log_api_access may hide inside an asyncio.to_thread lambda, because the first-touch initialization that hop used to offload never runs. #7235 then landed two to_thread-wrapped audits for the member rules GET and PUT, so main fails test_no_members_sel_audit_is_offloaded on every PR's merge ref (seen on #8816, Backend Tests (Windows) 3). Direct enqueue, guarded the way the deny-path audits in this file already are.
Problem / Motivation
SecurityEventLog._init_lockedruns on whatever thread first callssel()(blocking file I/O: trust-dir creation, HMAC key load/create, a tail read of the live log). On a fresh gateway, whichever handler audits first paid that init on the event loop — stalling every session's turn and the liveness heartbeat. The per-site fix,await asyncio.to_thread(lambda: _sel().log_api_access(...)), was replicated 17 times across the dashboard (four of them added by PR #8604), while 250+ otherlog_api_accesscall sites insrc/kiro_crewremained candidate first-touch stalls.Why it matters
Every new audit site is a latent loop stall unless its author remembers the wrapper — a class that grows with the codebase. The wrappers themselves add a suspension point and a worker dispatch per audit (some on deny paths where the surrounding code explicitly must not yield), and the members.py AST guard existed only to police the workaround.
What changed (motivation → approach → change)
Symptom → cause: the per-site hops only dodge the singleton's first touch; after init a non-critical
log_api_accessis an enqueue. So pay the first touch once, at startup, off the loop:sel.warm_sel_singleton()(new):await asyncio.to_thread(sel), best-effort. Awaited by BOTHstart_dashboardandstart_api_serverright afterawait warm_auth_singletons()— before the middleware chain is built and before the socket binds, so no handler or middleware can be the first touch. Same shape and position as the auth-singleton warm precedent._shared,autonudge,connections×5,cron×2,members×4,messaging,secrets,session_controlhandlers,server._audit_denied) — replaced with direct calls. Pre-existing per-sitetry/exceptguards are KEPT: construction can still raise after a FAILED warm (e.g. a trust root too short to sign the chain), and an unguarded audit would turn a 403 denial into a 500.critical=Truesites deliberately keep theirto_threadwrappers (autonudge_authz×2,taskrunner,cron×3,md_notebook): a critical audit writes SYNCHRONOUSLY on its caller's thread by design (audit-or-deny), so their offload carries the write, not just the init. This is the issue's own "verify no site was relying on the wrapper for more than warm-up cost" caveat — the issue's "delete all 18" over-counted.log()writer-unavailable fallback made loop-aware (pre-push GPT review finding): the synchronous_flush_batchfallback was reachable ON the loop once the hops were gone. On the loop a non-critical event is now dropped with a warning (best-effort by contract; a frozen loop is not survivable); off the loop it still writes synchronously. Either way the failed enqueue's pending credit is returned soflush()cannot wait on a count nothing will decrement.docs/system-specs/modules/sel.mdgains the startup-warm paragraph (including the failed-warm caveat).Boot-path justification (AUTOSDE
no-new-work-on-gateway-boot-path): the warm is one awaitedasyncio.to_threadbefore readiness — the rule's explicitly allowed shape for init that must precede serving traffic. Worst-case bound on a large profile: one key-file read (or create), one backward tail read of the live log — a single 4 KiB chunk on a healthy log, worst case a full backward scan bounded by rotation's_SEGMENT_MAX_BYTES(32 MiB) when the tail holds no parseable record — and astat. No cross-process chain lock is taken at init. A failed warm logs and never blocks readiness; the first later touch then retries init on its caller's thread (as every call site did before the per-site hops existed), andcritical=Trueaudits still fail closed at their own sites.Pre-push review dispositions (GPT
gpt-5.6-sol+ Opusclaude-opus-5):warm_auth_singletons()(threeto_threadhops readingtoken_signing.keyunder the sameconfig_dir()data home) before this warm, so a hung data-home filesystem wedges boot at the existing precedent first; this warm adds no new failure mode, and the proposed dual-path mitigation would reintroduce the per-site complexity this PR exists to delete.sel.mdabsolute softened with the failed-warm caveat, "only enqueues" qualified with the writer's one-time start.Tests
test/test_sel_startup_warm.py(new): realSecurityEventLoginit runs off-loop through the warm (migrated members.py denial audits initialize SEL synchronously on the event loop #8523 first-touch property); a failed warm is swallowed and logged; a source guard pins both start paths awaiting the warm beforestate.ready = Trueand before the middleware chain; the writer-unavailable fallback drops on-loop, writes off-loop, and leaks no pending credit.test/test_members_dm_thread.py: thread-ident tests flipped to pin the inline enqueue; the members AST guard is inverted (nolog_api_accessmay hide inside ato_threadlambda).test/test_api_health.py:_audit_deniedpins updated (direct call, still best-effort; boundary audit asserted onMainThread).sel()in the warm, droppedexcept, warm removed from either start path, warm moved after readiness, a re-added per-site wrapper, the fallback's loop-guard dropped, the fallback made drop-unconditional.Manual verification
N/A — unit coverage sufficient: the startup ordering, off-loop init, failure swallow, and fallback semantics are each pinned by an automated test; no UI or external service is involved.
Related Issues
Closes #8608
Refs #8523, PR #8604 (the four wrappers + AST guard + test this migrates)
Pattern harvest
Rule candidate: review-prompt
Pattern: "per-call-site thread hop to dodge a singleton's first-touch init — warm the singleton once at startup instead, and check whether any site's offload carries a synchronous write (critical=True) rather than just init cost"
Checklist
feat|fix|docs|refactor|perf|test|chore|ci|build|revert: ...)