fix(observability): make the engine's log routing correct and race-free

[aparajon]

Why this matters

The apply log stream is what an operator reads when a schema change goes wrong — from the CLI, and from the summary comment on the PR. Most of it comes from the engine: copy progress, checksum results, the fatal line. Two bugs sat between those lines and the stream.

The callback was read unsynchronized. The filter read the engine's log callback through a raw pointer while engine methods wrote it under the engine mutex. A finished drive unwires that callback, and a Spirit runner winding down is still logging through the same filter — so the write races the read on every apply, and the check-then-call window can dereference a slot cleared in between.

The process log level decided for both consumers. The filter feeds two: the apply log stream and the process logs. It answered Enabled for only the second, and slog skips building the record entirely when a handler says no — so on a process logging above info, the routing never ran and the apply recorded nothing from the engine.

Nothing runs above info today, so no stream is empty right now. The trap is that turning the level up, the ordinary way to cut noise, silently empties the surface operators triage from. It is worse for an embedder, whose own logger sets that threshold outside SchemaBot entirely.

                       before                          after

Info line   ──> Enabled? handler only ──> dropped   ──> Enabled? either consumer
                                                          ├──> apply log stream
                                                          └──> process logs, only
                                                               at their own level

What it does

The callback and debug toggle move into atomic slots, and the filter loads the callback once per record and calls through that copy. Atomics rather than the engine mutex: the filter runs on Spirit's logging path, where taking the engine lock would invite reentrancy.

Each consumer then decides for itself. A record is built if either wants it, routed to the apply log stream whenever an apply is being driven, and passed to the process logs only at their configured level. That second part is load-bearing — widening Enabled alone would push every driven apply's info lines to a deployment's stdout, trading lost signal for unasked-for volume. Debug lines stay the process logs' call alone.

🤖 Generated with Claude Code

[Copilot]

Pull request overview

This PR fixes an observability gap in the Spirit engine slog filter so engine INFO+ lines are always recorded into the apply log stream even when the deployment’s process log level would otherwise filter them out, while still preserving the deployment’s configured verbosity for stdout/stderr logs.

Changes:

• Adjust spiritLogFilter.Enabled to return true when either the apply log stream or the process logger would consume the record.
• Prevent “apply-log-only” records from being emitted to the process logs when the handler’s level would reject them.
• Expand unit tests to distinguish apply-log routing vs process-log emission.

Reviewed changes

Copilot reviewed 2 out of 2 changed files in this pull request and generated 2 comments.

File	Description
pkg/engine/spirit/logger.go	Updates slog handler filtering so apply-log routing is independent of process log level and avoids increasing deployment log volume.
pkg/engine/spirit/logger_test.go	Adds tests covering routing below process log level and the “no callback installed” case; updates logger setup helper.

---

💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.

[Kiran01bm]

🤖 Review findings - created by Kiran's code review agent - for pull/1028, ead7fe5.

Verdict: 3 findings — all general suggestions (no blocking/non-blocking); 31/31 CI checks pass at head ead7fe5 (Build, Unit Tests, Integration Tests, Lint, all E2E/LocalScale variants), and local repro of go build ./..., go vet ./pkg/engine/spirit/..., gofmt -l, and go test -race -count=1 ./pkg/engine/spirit/... (1.874s, no race reports) all confirm the fix is clean.

General suggestions

1. New concurrency test's assertion is too loose to catch a routing regression. logger_test.go:208 only checks routed.Load() <= 2000 in TestSpiritLogFilter_UnwiringTheCallbackWhileLoggingIsSafe; if a future change silently broke loadLogCallback/Store wiring so the callback never fired (routed stuck at 0), this assertion would still pass. The real safety net here is -race, not the test's own logic — consider also asserting routed > 0.

2. Debug-toggle delivery has no dedicated unit test. logger.go:58 gates debug lines, but no test in the package asserts that SetDebugLogs(true) actually lets a debug-level line reach the process handler — every helper leaves debug at its false zero value except the concurrent unwiring test, which doesn't assert on debug delivery specifically. Pre-existing gap, but this PR touches exactly this line.

3. PR title undersells the routing fix bundled into this branch. The branch carries two commits touching the same 3 files — a nil-panic/atomicity fix and a separate Enabled/Handle routing-contract fix — but the PR title only names the atomicity fix (the body's Why section does cover both). Consider retitling to reflect both fixes, or splitting.

The one thing that could have broken, verified

The riskiest mechanism is the load-once-then-call pattern in spiritLogFilter.Handle (logger.go:65) racing Engine.SetLogCallback's atomic store (spirit.go:283) while a Spirit runner goroutine is still logging through the same filter during a drive's unwire — the exact #1027 check-then-call nil-panic window this PR claims to close. Verified three ways: a repo-wide grep confirms zero residual raw reads/writes of onLog/debugLogs remain outside .Store()/.Load() (e.g. spirit.go:283-295, direct.go:448); the PR's new adversarial test (logger_test.go:177-210) was run under go test -race -count=1 and passed with no race reported; and SetLogCallback(nil) was confirmed to store a non-nil *logCallback wrapping a nil func, which loadLogCallback (logger.go:18-24) safely unwraps without a typed-nil panic, matching TestSpiritLogFilter_ClearedCallbackRecordsNothing. No incomplete sweep or stale-read path was found.

Verified correct

• logger.go:18-24 loadLogCallback treats never-set and explicitly-cleared slots identically as nil, with no typed-nil panic risk.
• logger.go:52-53 Enabled() unions both consumers' interest, and logger.go:93-95 Handle() independently re-gates the process-log side at the handler's own level.
• logger.go:106 WithAttrs/WithGroup share the parent's atomic cells (not copies), so a rebound child sees later SetLogCallback/SetDebugLogs updates.
• spirit.go:206-295 all callback/debug access goes through atomic.Pointer/atomic.Bool Store/Load, with no residual e.mu usage on this path.
• spirit.go:301-315 Drain() waits on the run-group before clearing runningSchemaChange, ruling out cross-apply log-stream contamination from a stale post-unwire call.
• No file overlap with test(engine): cover the checkpoint a shutdown takes mid-copy #1033's shutdown_halt_test.go — zero matches for onLog/debugLogs/SetLogCallback/SetDebugLogs in that file.
• logCallback remains a type alias (logger.go:13), so external callers (pkg/tern/local_apply.go:291, local_control_resume.go:865) compile unmodified.
• 31/31 CI checks green at ead7fe5; local go build, go vet, gofmt -l, and go test -race -count=1 ./pkg/engine/spirit/... (1.874s) all reproduce clean with no data races.

This review was generated by Claude Code (claude-fable-5).

[aparajon]

🤖 Thanks — all three addressed or answered in acd65584.

1. Loose assertion in the concurrency test — agreed, fixed, but not quite the way you suggested. You're right that routed <= 2000 is satisfied by a filter that never calls through its callback slot at all, so the test was leaning entirely on -race for its value. I didn't add a post-race routed > 0 though, because that floor is only true probabilistically: nothing forbids the toggler goroutine from holding its slot through the whole logging loop, leaving the callback unset for every line, and that's a flake waiting for a loaded runner. Instead the test now installs the callback and routes one line before the race starts and requires it landed, then bounds the total at racingInfoLines+1. Same race coverage, deterministic floor.

2. No test for debug-toggle delivery — added. TestEngineDebugLogsToggleGovernsSpiritDebugLines drives the real New() wiring rather than the package's test helper: a debug line is dropped with the toggle off, reaches the process handler after SetDebugLogs(true), is dropped again after SetDebugLogs(false), and the apply-log callback records none of the three — which is the other half of the contract, since debug lines are deliberately not part of the apply log stream. Mutation-checked rather than assumed: neutering the f.debug.Load() gate fails it on two assertions.

3. Title — already covers both fixes. The title was renamed to "make the engine's log routing correct and race-free" on Aug 15, two days before this review ran, so the review was reading the original "record the engine's log lines regardless of process log level". "Routing correct" is the Enabled/Handle contract fix and "race-free" is the atomicity fix, so I've left it. Not splitting the branch at this point either, since both commits are already approved together.

This reply was generated by Claude Code (claude-opus-5).