Skip to content

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

Open
aparajon wants to merge 2 commits into
mainfrom
armand/engine-log-capture-level
Open

fix(observability): make the engine's log routing correct and race-free#1028
aparajon wants to merge 2 commits into
mainfrom
armand/engine-log-capture-level

Conversation

@aparajon

@aparajon aparajon commented Aug 14, 2026

Copy link
Copy Markdown
Collaborator

Why this matters

The apply log stream is the account of a schema change an operator actually reads — from the CLI, and from the summary comment a failed apply folds onto its PR. The engine's own lines are most of that account: copy progress, checksum results, the fatal line that explains a failure.

Two things stood between those lines and the stream.

The process log level decided for both consumers. The filter that routes engine lines serves the apply log stream and the process logs, but answered Enabled for only the second — and slog skips building the record entirely when a handler reports false. So the routing in Handle was never reached on a deployment that runs its own logs above info, and every apply recorded nothing from the engine. A setting about stdout verbosity quietly emptied the surface operators triage from.

                       before                          after

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

The callback itself was read unsynchronized. The filter reached the engine's log callback and debug toggle through raw pointers while engine methods wrote them under the engine mutex. A drive that unwires its apply-log callback as it hands the engine over raced with a runner still logging, and the callback's check-then-call window could dereference a cleared slot.

What it does

Each consumer decides for itself. A record is built when either wants it; it is routed to the apply log stream whenever an apply is being driven, and passed to the process logs only at the level that deployment configured. That second half is load-bearing — widening Enabled alone would fix the silence by printing every driven apply's info lines to a deployment's stdout, trading lost signal for unasked-for volume. An apply cannot raise a deployment's log volume, and a quiet deployment cannot silence an apply.

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 the Spirit runner's logging path, where taking the engine lock would invite reentrancy against the engine methods that already hold it.

🤖 Generated with Claude Code

…ss log level

The Spirit log filter serves two consumers — the apply log stream and the
process logs — but answered Enabled for only the second. slog skips building
the record entirely when a handler reports false, so a deployment running its
own logs above info recorded no engine lines at all for any apply: no copy
progress, no checksum lines, nothing in a failed apply's summary comment. The
apply log stream an operator reads was emptied by a setting about stdout.

Each consumer now decides for itself. A line is built when either wants it,
routed to the stream when an apply is being driven, and emitted to the process
logs only at the level that deployment configured — so an apply cannot raise a
deployment's log volume, and a quiet deployment cannot silence an apply.
Copilot AI lite review requested due to automatic review settings August 14, 2026 09:42

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Comment on lines 52 to +56
return slog.New(filter), func() []capturedLog {
mu.Lock()
defer mu.Unlock()
return append([]capturedLog(nil), captured...)
}
mu.Lock()
defer mu.Unlock()
return append([]capturedLog(nil), captured...)
}, func() string {
Comment thread pkg/engine/spirit/logger.go Outdated
Comment on lines 63 to 67
@@ -55,6 +67,13 @@ func (f *spiritLogFilter) Handle(ctx context.Context, r slog.Record) error {
(*f.onLogRef)(r.Level, tableName, msg)
…tomically

The Spirit log filter read the engine's onLog callback and debugLogs flag
through raw pointers while engine methods wrote them under the engine mutex.
A drive that unwires its apply-log callback while a runner is still logging
raced with the filter's read, and the callback's check-then-call window could
dereference a cleared slot.

Both now live in 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 the Spirit runner's logging path, where taking the engine lock
would invite reentrancy against the engine methods that already hold it.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
@aparajon aparajon changed the title fix(observability): record the engine's log lines regardless of process log level fix(observability): make the engine's log routing correct and race-free Aug 15, 2026
@aparajon
aparajon marked this pull request as ready for review August 15, 2026 02:09
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants