Skip to content

fix(observability): log the cause when the tern health RPC fails - #1026

Open
aparajon wants to merge 2 commits into
mainfrom
armand/tern-health-log-cause
Open

fix(observability): log the cause when the tern health RPC fails#1026
aparajon wants to merge 2 commits into
mainfrom
armand/tern-health-log-cause

Conversation

@aparajon

Copy link
Copy Markdown
Collaborator

The tern Health RPC returns a sanitized codes.Unavailable to the caller, so
the underlying error was discarded entirely. A deployment could be marked
unhealthy by the control plane with nothing in the logs attributing the cause —
the operator sees an unhealthy deployment and has to go find out why by hand.

  • Log the underlying error at warn before returning, so the sanitized response
    stays sanitized and the cause is still recoverable from logs alone.
  • Healthy checks stay silent. The control plane polls every 30s per environment,
    so logging the success path would bury the apply-path logs an operator reads
    during a schema change.

This PR was written by Claude Code (claude-opus-5).

The health RPC returns a sanitized Unavailable to the caller, so the
underlying error was discarded entirely — a deployment could be marked
unhealthy by the control plane with nothing in the logs explaining why.
Log it at warn with the real error before returning.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Copilot AI lite review requested due to automatic review settings August 14, 2026 06:58

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 improves operator-facing observability for the Tern gRPC Health RPC by logging the underlying health failure server-side while still returning a sanitized codes.Unavailable to callers, ensuring the control plane’s “unhealthy” signal can be attributed to a concrete cause in logs.

Changes:

  • Add a slog.WarnContext log on Health failures before returning a sanitized codes.Unavailable.
  • Add unit tests asserting (1) failures are logged with the underlying error and (2) successful health checks do not log.

Reviewed changes

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

File Description
pkg/tern/server.go Logs underlying Health errors at warn while preserving the sanitized gRPC response.
pkg/tern/server_test.go Adds coverage ensuring failure logs are emitted and healthy checks stay silent.

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

Comment thread pkg/tern/server.go
A caller that hangs up mid-check reports nothing about deployment health
and is already recorded on the caller's side, so it logs at debug. An
expired deadline stays at warn: the check outran its budget, which is a
genuine unhealthy signal that only this side can attribute.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
@aparajon
aparajon marked this pull request as ready for review August 14, 2026 07:48
@Kiran01bm

Copy link
Copy Markdown
Collaborator

🤖 Review findings - created by Kiran's code review agent - for pull/1026, 7271a6d.

Verdict: 7 findings — 2 non-blocking (predicate tightening + test coverage), 5 suggestions; no blockers, and CI is green (32/32 checks) at head 7271a6d, state OPEN.

Non-blocking

  1. The errors.Is(err, context.Canceled) disjunct can downgrade a genuine failure to DEBUG while the request ctx is still live. In pkg/tern/server.go:59, a future Client.Health implementation or driver internals returning an error that wraps context.Canceled (internal sub-context cancellation) would trip callerAbandonedHealthCheck even though the caller never hung up, leaving the only server-side record of the cause at DEBUG — invisible at the prod Info default — which is the exact fail-silent gap this PR closes. Today the clause is redundant (both production backends reduce to storage.Ping, which only returns Canceled when the inbound ctx was cancelled), so dropping it and keying solely on ctx.Err() — the repo's own precedent at pkg/api/remote_deployment_health.go:156 — loses no behavior.

  2. The only downgrade test case sets both predicate clauses true, so neither disjunct is independently pinned. The "caller cancelled" row at pkg/tern/server_test.go:290 has clientErr: context.Canceled AND cancelCtx: true, so deleting either clause of the || in callerAbandonedHealthCheck leaves the whole suite green — e.g. a refactor to err-only would reintroduce WARN noise on every control-plane shutdown with all tests passing. Add one row per clause (clientErr=context.Canceled, cancelCtx=false and clientErr=generic, cancelCtx=true), each asserting the intended level.

General suggestions

  1. Test comment hardcodes "polled every 30s per environment," a cross-package runtime-configurable threshold. pkg/tern/server_test.go:337 embeds the value of RemoteDeploymentHealthCheckInterval (pkg/api/remote_deployment_health.go:16), which has a runtime setter, so the "30s" goes silently stale when tuned — the AGENTS.md "No fragile comments" failure mode. Rephrase to intent: "polled continuously by the control plane."

  2. A cancel racing in after the ping already failed with a real cause demotes that cause to DEBUG — delayed one poll cycle, not lost. If the DB is down and the control plane cancels the in-flight poll between the ping failure and the predicate check at pkg/tern/server.go:59, the "connection refused" lands at DEBUG; the next 30s poll re-warns and the caller-side warn+metric still fire. Worth at most a one-line note in the helper doc.

  3. Server logs via the global slog while every other logging component in pkg/tern takes an injected *slog.Logger. pkg/tern/server.go:41/:43 call package-level slog.DebugContext/WarnContext, so an embedder using RegisterGRPC who wires a structured logger but never calls slog.SetDefault gets health logs on the unconfigured stderr text handler while every tern client log carries their attrs. It works in the schemabot binary only because pkg/cmd/commands/serve.go:23 happens to slog.SetDefault(logger).

  4. The new warn carries only the error attribute, with no environment/deployment identifier. In an aggregated pipeline flattening multiple tern pods, the message at pkg/tern/server.go:43 doesn't say which deployment stopped reporting healthy, per AGENTS.md "Logs must answer the triage question." Heavily mitigated: each data-plane pod serves one deployment and the caller-side warn already carries deployment+environment (pkg/api/remote_deployment_health.go:168).

  5. Both commits use fix(observability) where AGENTS.md:68 classifies newly added log signal as feat(observability). The PR adds brand-new warn/debug statements with an error attribute, so anyone auditing observability additions by the feat scope misses it; borderline, since the PR frames it as fixing a triage gap — author's call.

The one thing that could have broken, verified

The riskiest mechanism is callerAbandonedHealthCheck (pkg/tern/server.go:58-60) deciding WARN vs DEBUG — whether a genuine deployment failure can be misfiled as caller abandonment and re-silence the very signal the PR adds. Tracing every client type behind tern.Server showed serve.go:545 is the sole production NewServer caller and both backends reduce to storage.Ping (target_router.go:322, local_client.go:611), so a caller hangup always surfaces as ctx cancellation caught by the second disjunct. Enumerating the truth table showed the err clause is only reachable today when the ctx itself was cancelled, and deadline expiry stays at WARN in both clauses (pinned by server_test.go:296-299). Even in the one misfire window — err wraps Canceled while ctx is live, possible only via a future Client.Health — the caller-side warn+metric still fire (remote_deployment_health.go:168-174), so only server-side cause detail, never the unhealthy signal, can go dark. Safe as shipped; the residual exposure is finding 1.

Verified correct

  • Sanitized response contract unchanged: both log branches still return codes.Unavailable with no raw cause (server.go:45; NotContains '3306' at server_test.go:269).
  • Caller-hangup detection is complete for the real deployment shape: both production backends propagate the request ctx into storage.Ping (local_client.go:611, target_router.go:322).
  • Deadline expiry deliberately stays at WARN — neither clause matches DeadlineExceeded (server_test.go:296-299).
  • The PR's premise holds — this is genuinely the only server-side record: bare grpc.NewServer() with no logging interceptor (serve.go:149).
  • Prod log-level wiring matches the design: slog.SetDefault with Info default suppresses the abandonment DEBUG and surfaces the failure WARN (pkg/cmd/commands/serve.go:23).
  • Healthy path stays silent — no 30s-cadence log spam (server_test.go:351 asserts Empty(logs)).
  • Even a misfiled downgrade cannot hide the unhealthy signal: the RPC still returns Unavailable and the control plane warn-logs with identifiers and records the metric (remote_deployment_health.go:168-174).
  • go test -race -run TestServerHealth ./pkg/tern passes at head 7271a6d; CI green, 32/32 checks at verification time.

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

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.

3 participants