Skip to content

feat(server): observability primitives — build identity, turn outcomes, transcript degradation#55

Merged
andybons merged 6 commits into
mainfrom
feat/turn-outcome-observability
Jul 9, 2026
Merged

feat(server): observability primitives — build identity, turn outcomes, transcript degradation#55
andybons merged 6 commits into
mainfrom
feat/turn-outcome-observability

Conversation

@andybons

@andybons andybons commented Jul 9, 2026

Copy link
Copy Markdown
Contributor

Three primitives from today's incident review, each converting a debugging blind spot into a self-announcing signal. Companion to the docs in #54; motivation details in each commit.

  • 4076e6e — GET /health returns vcs_revision/vcs_time (from runtime/debug.ReadBuildInfo; empty when unavailable). "Is this binary stale?" becomes one curl — today that question cost a forensics dispatch.
  • 061cf69 — durable turn.end records + last_turn: {outcome, error} on GET /session/{id} and /session/status, flowing through the /event stream like other durable records. "Idle because done" and "idle because the stream died mid-turn" are now different, queryable states — replacing the monitor heuristic of sniffing reasoning-only message tails (three silent plain-prompt deaths today).
  • 7f742d2 — GET /session/{id}/message degrades per-message: an unmarshalable resident message yields a {id, role, marshal_error} placeholder instead of 500ing the entire transcript. During today's poisoning incident the transcript view died exactly when it was most needed; post-fix(message,engine): truncated ToolCall.Arguments must never poison history #52 this class shouldn't recur, but the observability layer must never again be a casualty of the thing it exists to observe.

All red-first with incident-shaped tests; openapi.yaml updated for every surface change.

🤖 Generated with Claude Code

https://claude.ai/code/session_013B9pwUYhT4o8se9skmS5PP

Harness Agent added 3 commits July 9, 2026 20:19
An engineer burned 30 minutes today suspecting a stale box binary because
/health only ever echoed the config Version string (0.1.0-dev), which never
changes across deploys. /health now also returns vcs_revision and vcs_time,
read from runtime/debug.ReadBuildInfo's VCS settings, so a live process can
be matched to an exact commit. Both fields are always present (never
omitted) and empty when build info carries no VCS settings, which is the
ordinary case for a go test binary.
…shable from idle-because-died

Three plain-prompt turns died mid-stream today (final assistant message
reasoning-only, no text, no tool call) and every monitor had to infer death
from message part shapes. Journal a durable turn.end record — outcome
'completed' or 'error' plus a sanitized (never credentials/request bodies)
error string on failure — whenever a prompt (prompt_async) or a goal-worker
loop (POST /session/{id}/goal) finishes. It reaches /event like any other
durable record and is mirrored as Session.last_turn and each /session/status
entry's last_turn, so a poller can read the outcome directly instead of
reverse-engineering it from transcript content. A deliberate abort still
emits only session.aborted/goal.cleared, exactly as before — turn.end covers
completion and failure, not cancellation. No goal semantics changed; the
goal loop's state machine, retries, and events are untouched.
…r 500 wholesale

Today GET /session/{id}/message 500'd entirely because one resident message
failed json.Marshal ('json: error calling MarshalJSON for type
message.Parts'), taking down the whole transcript view exactly when it was
most needed to diagnose the death (ses_01kx453ewfedqrg7p3c64f8sca,
ses_01kx453ev9ejattygpf7rbzptw). The handler now marshals each message
independently and substitutes a {id, role, marshal_error} MessagePlaceholder
for any message that fails, returning 200 with every other message intact.

The regression test builds the poison directly: message.Normalize only
scrubs a ZERO-length Reasoning.ProviderData entry (mirroring the
ToolCall.Arguments guard), never a present-but-invalid one, so a scripted
provider's assistant message carrying a non-empty-but-truncated
ProviderData entry sails through ingest untouched and reproduces the exact
production failure.
@claude

claude Bot commented Jul 9, 2026

Copy link
Copy Markdown
📦 Previous Review (superseded by newer review)

Claude finished @andybons's task in 4m 38s —— View job


Review: observability primitives (PR #55)

  • Read AGENTS.md and gather context
  • Review server/handlers.go (health vcs, last_turn, message degradation)
  • Review server/journal.go (turn.end records)
  • Review server/server.go and tests
  • Review openapi.yaml accuracy
  • Post review feedback

Built clean, go test ./server/ passes. Three well-scoped primitives, each with an incident-shaped, red-first test and matching openapi updates. The lock discipline (server.mu as a leaf; recordTurnEnd sets lastTurn and emits the durable record in one critical section before the idle transition) is correct, and turn.end correctly precedes session.status idle so a collect-until-idle reader always sees the outcome first. I found one correctness issue and a couple of minor notes.


🔴 turn.end{completed} is emitted for goals that never met their condition

runGoal (server/handlers.go:556-564) discards GoalResult and keys the outcome purely on err == nil:

_, err := st.sess.PursueGoal(...)
...
case err == nil:
    s.recordTurnEnd(id, "completed", nil)

But PursueGoal returns a nil error with Achieved:false in two terminal cases:

  • MaxTurns exhaustionengine/goal.go:357 returns {Achieved:false, Reason:"max turns"}, nil. A goal that gives up after burning its turn budget is recorded as turn.end{outcome:"completed"} / last_turn={completed} — telling a poller "idle because done" for a goal that was never met. Reachable from the public API: POST /session/{id}/goal passes max_turns straight into runGoal.
  • Clear-in-flight raceengine/goal.go:345,351 return {Achieved:false, Reason:"goal cleared"}, nil (not context.Canceled) when ClearGoal races an in-flight eval. That path records turn.end{completed} for a cleared goal, contradicting the openapi contract this PR adds ("DELETE /session/{id}/goal … does not emit turn.end").

This is the one primitive whose whole purpose is disambiguating "idle because done" from "idle because not-done," so a false completed is more than cosmetic. Fix: capture the result and only record "completed" when res.Achieved; treat max-turns / cleared as a distinct non-completed outcome (or suppress like the Canceled case). Details + suggested diff in the inline comment. A red-first goal-max-turns test would pin it.


Minor notes (non-blocking)

  • last_turn doesn't survive a process restart, but turn.end does. lastTurn is populated only by recordTurnEnd in-process; reconcile()/loadJournal rebuild seen from the journal but not lastTurn. After a restart, GET /session/{id} shows no last_turn even though the durable turn.end record is still in events.jsonl. This is documented ("this process" / "never-prompted-here"), and the outcome is recoverable via /event replay — but since the incident that motivated this is a process that died mid-turn, repopulating lastTurn from the last turn.end per session during reconcile() would give last_turn the same durability as the record it mirrors. Worth considering.

  • messagePlaceholder.role enum. openapi's MessagePlaceholder.role enum is [user, assistant, tool], but the handler emits string(m.Role) verbatim — if a system/other role ever reaches history, the placeholder would carry a value outside the enum. Cosmetic given current roles; just noting the coupling.

Nice touches worth calling out: the double-guarded placeholder fallback in handleMessages (a plain-string struct that itself can't re-trigger the 500), the always-present (never-omitted) vcs_* keys so clients skip the absent-vs-empty branch, and buildInfo() reading debug.ReadBuildInfo (in-memory, off the startup path) rather than shelling out.
· branch feat/turn-outcome-observability

Comment thread server/handlers.go
Harness Agent added 3 commits July 9, 2026 20:44
PR #55 review finding: runGoal recorded turn.end{outcome:"completed"}
whenever PursueGoal returned a nil error, but PursueGoal returns a NIL error
with Achieved:false in two cases that are not completions:

- MaxTurns exhausted without the evaluator ever returning MET (Reason "max
  turns") — the goal gave up, it did not finish. Now recorded as its own
  outcome, max_turns_exceeded (added to the openapi enum and documented),
  never "completed".
- ClearGoal winning a race against an in-flight worker retry or evaluator
  call (Reason "goal cleared"), reached without the loop's context ever
  being cancelled. This is a clear, same as the existing context.Canceled
  path — no turn.end is emitted at all, matching the documented "DELETE
  /session/{id}/goal does not emit turn.end" contract.

Both paths previously surfaced as last_turn={completed}, recreating the
exact idle-because-done-vs-idle-because-it-died-or-gave-up ambiguity this
primitive exists to remove. Red-first tests cover both: a max-turns
exhaustion asserting a non-completed outcome, and a goal cleared while an
evaluator call is deliberately blocked in flight (bypassing DELETE, which
would otherwise take the already-correct context.Canceled path) asserting
turn.end is suppressed entirely.
…s a restart

PR #55 review finding: reconcile()/loadJournal() already replay events.jsonl
on boot to rebuild the seen-message index, but did nothing with turn.end
records — so last_turn, a field whose entire purpose is answering "did the
last turn finish cleanly" for an orchestrator reconnecting after this
process restarts, was silently lost across exactly the restart it needs to
survive: the durable record stayed on disk while the in-memory field it
drives reset to absent.

loadJournal now folds each turn.end record into Server.lastTurn as it
replays the journal in file order, so the last one seen for a session is,
by construction, its most recent — no sequence-number bookkeeping needed.
Red-first test builds a Server, drives one prompt to completion, closes it,
and opens a second Server over the same session directory (simulating a
process restart), asserting GET /session/{id} and /session/status still
carry last_turn.
PR #55 review finding (cosmetic): the handler sets MessagePlaceholder.Role
from string(m.Role) verbatim — a degraded-path fallback for a message the
server couldn't even marshal — but the openapi schema constrained it to the
Message.role enum [user, assistant, tool], which can drift the moment
message.Role gains a variant this schema isn't updated to match, on exactly
the failure path that must never itself risk being rejected by a stricter
consumer. Schema only; handler behavior is unchanged.
@claude

claude Bot commented Jul 9, 2026

Copy link
Copy Markdown

Claude finished @andybons's task in 3m 53s —— View job


Review: observability primitives (PR #55) — re-review after fixes

  • Read AGENTS.md and gather context
  • Verify runGoal turn.end outcome fix (prior blocking finding)
  • Review server/handlers.go (health, message degradation)
  • Review server/journal.go + restart reconciliation
  • Review openapi.yaml accuracy
  • Build + go test -race ./server/

Built clean; go test -race ./server/ green. All three findings from the previous round are resolved, each with a red-first regression test. Nice work — the fixes are precise and the tests pin exactly the ambiguities the primitives exist to remove.


Prior findings — confirmed resolved

🔴 (blocking) turn.end{completed} for goals that never met their condition — fixed. runGoal (server/handlers.go:579-595) now branches on the result, not just err == nil:

case err == nil && res.Achieved:
    s.recordTurnEnd(id, "completed", nil)
case err == nil && res.Reason == "goal cleared":
    // cleared in flight: no turn.end (matches DELETE contract)
case err == nil:
    s.recordTurnEnd(id, outcomeMaxTurnsExceeded, nil)  // "max_turns_exceeded"
  • Max-turns exhaustion now records the distinct max_turns_exceeded outcome (new constant outcomeMaxTurnsExceeded, journal.go:94), covered by TestTurnEndOnGoalMaxTurnsIsNotCompleted.
  • Clear-in-flight suppresses turn.end entirely, matching the openapi "DELETE does not emit turn.end" contract, covered by TestTurnEndSuppressedOnGoalClearedInFlight (which deterministically wins the race by blocking the evaluator stream on a channel — no sleeps, per AGENTS.md).
  • I verified no nil-deref risk: every PursueGoal return with a nil error carries a non-nil *GoalResult (engine/goal.go), so res.Achieved/res.Reason in the err == nil arms are always safe.

(minor) last_turn didn't survive restart — fixed. loadJournal now rebuilds lastTurn from the last turn.end per session on boot (journal.go:509-511), giving the field the same durability as the record it mirrors. TestLastTurnSurvivesRestart builds a second Server over the same dir and asserts it, non-vacuously (asserts {completed} in process 1 first).

(cosmetic) MessagePlaceholder.role enum — fixed. openapi relaxed to a plain string with a comment explaining the degraded-path fallback must never reject a value the handler actually produced (openapi.yaml:309-317).


One minor, non-blocking note

String coupling on "goal cleared". handlers.go:582 distinguishes the clear-in-flight case by matching res.Reason == "goal cleared" — a literal that lives in engine/goal.go (five call sites). If the engine ever reworded that reason, the server would silently mis-record a cleared goal as max_turns_exceeded instead of suppressing turn.end. It's guarded by TestTurnEndSuppressedOnGoalClearedInFlight, so a regression would go red — but a shared exported sentinel (e.g. engine.ReasonGoalCleared) would make the coupling compile-time rather than test-time. Purely a robustness nicety; not worth blocking. Fix this →

Not an issue — just noting for context: session.error still emits raw err.Error() while the adjacent recordTurnEnd sanitizes via plugin.SanitizeSessionError. That raw emission predates this PR, so it's out of scope here, but worth a follow-up if session.error is client-facing.

Verdict: LGTM. The blocking finding is fully addressed with an incident-shaped, red-first test; the two minor notes are resolved; openapi tracks every surface change. Ship it.
· branch feat/turn-outcome-observability

@andybons andybons merged commit bfabdc5 into main Jul 9, 2026
2 checks passed
@andybons andybons deleted the feat/turn-outcome-observability branch July 9, 2026 21:05
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.

1 participant