fix(llmadapters): record session duration in the production adapters

[zzwong]

Closes #596.

Response.DurationMS was assigned in exactly one place — internal/llmadapters/api.go:227, inside apiStream.run — which is the APIAdapter path. Neither adapter used in production sets it, so internal/llmlifecycle/lifecycle.go:188 faithfully persisted a pointer to zero for every session.

Measured against a real ledger before this change: 7,532 sessions, 0 with duration_ms > 0.

What changed

Four production stream paths now set the duration at the same boundary apiStream.run uses — from just before the call that executes the request to just after it returns, and only on success:

• piRPCStream.run — pi RPC transport
• subprocessStream.run — codex JSONL subprocess
• subprocessStream.runClaudeForeground
• subprocessStream.runClaudeBG

The two adapters do not share a shape, so each boundary was located individually rather than copied.

Out of scope

cost_usd is null for every claude_cli session (1,085 of them). That needs provider output parsing and is deliberately left for a separate change; #596 tracks it.

The ledger schema, lifecycle persistence, and the API adapter are unchanged.

Tests

Four tests, one per stream path, asserting DurationMS > 0 after a completed request, built on the package's existing helper-process fakes.

Verified not inert: with only the two source files reverted and the tests kept, all four fail with DurationMS = 0, want > 0.

[monit-reviewer]

Automated PR Review

Reviewed commit: 35b8e9487413
Profile: pi-ds-gh - Posting as: monit-reviewer

Summary

Reviewer	Findings
go:implementation-tests	2
structure:repo-health	1

go:implementation-tests (2 findings)

Minor - internal/llmadapters/subprocess.go:1132

In runClaudeBG the measured window stays open across post-result housekeeping: adapter.cleanupClaudeBGJob(...) runs the job-service control verbs (claude rm <jobID> at subprocess.go:1693, plus claude agents --json via gcClaudeBGJobs when stale job dirs exist) before DurationMS is read here. Those are extra CLI process launches that are not part of the reviewer request, so every successful background-Claude session records the result wait plus one or two control round-trips. The other three paths and apiStream.run (api.go:224-228) close the window at the response boundary, so claude bg is the one adapter whose duration_ms includes non-request work, on the most-used production transport. Fix: end the window where the response is produced — inside the success branch, after waitForClaudeBGResult returns, set result.response.DurationMS = time.Since(start).Milliseconds() (or stash elapsedMS := time.Since(start).Milliseconds() there and assign it in the later result.err == nil block, dropping nothing else).

Minor - internal/llmadapters/subprocess_test.go:2105

All four new tests assert only DurationMS > 0 (here, and pi_rpc_test.go:120, subprocess_test.go:2122 and 2141), which proves the field is assigned but not what it measures. Inside these subprocess paths time.Since(start).Milliseconds() is > 0 for almost any window — process spawn and teardown alone exceed a millisecond — so a later edit that moves start past the wait, or that measures teardown instead of the request (the shape of the runClaudeBG issue above), keeps these tests green. The PR also states a success-only rule (all four assignments are guarded by result.err == nil) and nothing pins it, so an unconditional assignment would not be caught. Concrete fix: add a fake mode that sleeps a known amount before succeeding (e.g. slow-success doing time.Sleep(150 * time.Millisecond) before the success event in the codex, claude-bg/foreground and pi-rpc helpers) and assert response.DurationMS >= 100 in one test per transport, so the assertion fails when the window does not cover the request; and add if response.DurationMS != 0 { t.Fatalf("DurationMS = %d, want 0 on failure", response.DurationMS) } to an existing failure-path test per transport (TestSubprocessCodexToolUseAndProtocolFailures, the tool-mode pi-rpc case, TestSubprocessClaudeForegroundTransientFailure) to pin that a failed attempt records no duration.

structure:repo-health (1 finding)

Major - internal/llmadapters/subprocess.go:1062

Invariant: llm.Response.DurationMS should be populated for every completed adapter call, and that obligation should live at a seam every adapter already funnels through. This diff instead re-implements the same start := time.Now() / if result.err == nil { result.response.DurationMS = ... } pair in four separate places (pi_rpc.go:544, here, subprocess.go:669, subprocess.go:1132), on top of the original copy in api.go:227.

The claim in the PR intent that "the two adapters do not share a shape" is only true if the clock must start inside each run* function. All five paths already embed llm.BaseStream (llmadapters/llm.go:28), are constructed via llm.NewProcessStream / llm.NewBaseStream, and converge on exactly one close-out call: BaseStream.Finish(response, err) (internal/llm/subprocess.go:282), which receives the Response by value and stores it. So the natural enforcement point already exists and is bypassed.

Impact: #596 happened precisely because a required instrumentation obligation was encoded per-adapter instead of at a shared seam. This change adds four more hand-copied sites and no mechanism that fails when the fifth adapter lands: a new adapter that omits the three lines compiles, passes CI, and silently writes duration_ms = 0 rows to a durable ledger again — the same 7,532-session blind spot, undetectable by existing per-adapter tests. It also leaves the semantics of DurationMS (compute time of the successful call, success-only, excludes launch/wait) defined only by five implicit code locations, with no doc or field comment.

Fix: move the measurement into the shared seam. Add startedAt time.Time to llm.BaseStream, set it in NewProcessStream/NewBaseStream (or via a MarkStarted() call immediately before launch if you want the current post-launch boundary preserved exactly), and in BaseStream.Finish do:

if err == nil && response.DurationMS == 0 {
	response.DurationMS = time.Since(s.startedAt).Milliseconds()
}

Then delete the four copies plus api.go's bespoke block. Note the tradeoff: starting the clock at stream construction adds process launch/setup (tens of ms) to the number; if that matters, MarkStarted() preserves today's narrower boundary while still giving a single enforcement point. Keep the measurement in the adapter layer rather than moving it to llmlifecycle — the lifecycle already knows wall time via draft.StartedAt (internal/llmlifecycle/lifecycle.go:169) and would conflate retries/queueing with provider compute time. Finish by documenting the field contract on llm.Response.DurationMS in internal/llm/adapter.go, so the next adapter author has a written boundary to code against.

Reviewer Coverage

• go:implementation-tests — complete (constrained); skipped: none; constraints: Only the four assigned files were inspected; api.go was read as reference for the intended apiStream.run boundary. Read-only review: I did not compile or run the tests or any claude/pi/codex binary, so all boundary claims are by code inspection.
• structure:repo-health — complete (constrained); inspected 2 assigned files (4 inspected across reviewers): internal/llmadapters/pi_rpc.go, internal/llmadapters/subprocess.go; skipped: none; constraints: Scope limited to the two assigned changed files; the cost_usd gap declared out of scope in the PR intent was not evaluated. cr_read also failed on internal/llm/subprocess.go and internal/llmadapters/api.go, so BaseStream.Finish's body is inferred from search hits (definition at internal/llm/subprocess.go:282, call sites at api.go:230, pi_rpc.go:550, subprocess.go:674/1068/1137). cr_read returned garbled, truncated fragments (~150 chars of unrelated text) for both changed files, so line-level verification came from the pinned cr_diff plus cr_search line anchors; I could not read full function bodies.

Inspected files (4)

• internal/llmadapters/pi_rpc.go
• internal/llmadapters/pi_rpc_test.go
• internal/llmadapters/subprocess.go
• internal/llmadapters/subprocess_test.go

0 PR discussion threads considered. 0 summarized; 0 resolved.

---

Completed in 3m 06s | $0.01 | opencode-go/deepseek-v4.1-flash | cr 0.10.302

Field	Value
Model	opencode-go/deepseek-v4.1-flash
Reviewers	go:implementation-tests, structure:repo-health
Engine	pi_rpc · opencode-go/deepseek-v4.1-flash
Reviewed by	cr · monit-reviewer
Duration	3m 06s wall · 4m 13s compute
Cost	$0.01
Tokens	13.8k in / 7.0k out

Per-workstream usage

• orchestrator-selection — opencode-go/deepseek-v4.1-flash
  • In: 6.4k
  • Out: 1.2k
  • Cache read: 0
  • Cache create: 0
  • Cost: $0.00
  • Duration: 7s
• go:implementation-tests — opencode-go/deepseek-v4.1-flash
  • In: 1.3k
  • Out: 3.5k
  • Cache read: 71.4k
  • Cache create: 0
  • Cost: $0.00
  • Duration: 2m 38s
• structure:repo-health — opencode-go/deepseek-v4.1-flash
  • In: 170
  • Out: 1.8k
  • Cache read: 23.3k
  • Cache create: 0
  • Cost: $0.00
  • Duration: 1m 24s
• orchestrator-rollup — opencode-go/deepseek-v4.1-flash
  • In: 6.0k
  • Out: 479
  • Cache read: 0
  • Cache create: 0
  • Cost: $0.00
  • Duration: 3s

[monit-reviewer]

Automated PR Review

Reviewed commit: 3345720ebbcd
Profile: pi-ds-gh - Posting as: monit-reviewer

Summary

Reviewer	Findings
go:implementation-tests	0
structure:repo-health	1

structure:repo-health (1 finding)

Minor - internal/llmadapters/subprocess.go:602

Invariant: Response.DurationMS now feeds durable state (ledger session duration_ms -> run summaries and ComputeDurationMS totals) and this PR defines its meaning per transport (success-only, request boundary to response, excluding teardown/cleanup). That contract has no versioned home anywhere in the repo, and this PR is the change that finally made the field real for the claude_cli transport.

Why it matters: the original bug survived 7,532 sessions precisely because a zero is indistinguishable from "not measured". The lifecycle persists a non-nil pointer (internal/llmlifecycle/lifecycle.go:188), and formatDurationMS renders a non-nil 0 as 0s while nil renders unavailable (internal/reviewplan/summary.go:725, cases at internal/reviewplan/summary_test.go:578). The only description of what the number measures is the PR body; a sixth adapter author has five call sites to copy from and nothing versioned to check against.

Related durable-knowledge loss: the PR body says cost_usd is null for every claude_cli session (1,085 sessions) and is "deliberately left for a separate change; #596 tracks it", while the same body says Closes #596. Merging closes the only tracker for that deferred gap. The repo already handles this shape by naming the tracker in the doc itself ("Issue #593 tracks reconciling them", docs/llm-task-artifacts.md).

Concrete fix: (1) add duration_ms to the telemetry field list in docs/llm-task-artifacts.md with a one-line contract (cr-measured, not provider-reported; success-only; from the request boundary to the response, before teardown/cleanup); (2) open a follow-up issue for the claude_cli cost parse (or narrow #596 to duration only) and reference it from that doc so the gap survives the merge.

Reviewer Coverage

• go:implementation-tests — complete (constrained); skipped: none; constraints: Residual gaps not elevated to findings because they were explicitly accepted as non-blocking follow-ups: llm.Response.DurationMS (internal/llm/adapter.go:132) carries no contract comment, and recordRequestDuration is convention rather than compiler-enforced for a sixth adapter. Review is pinned to head 3345720 against base 2b3859f; I inspected the pinned diff plus surrounding source, and did not execute the suite (the review tools are read-only, so test results below are reasoned from source, not observed). Scope deliberately limited to Go implementation/test adequacy in internal/llmadapters; prior threads on the shared-seam design and the pre-cleanup runClaudeBG window are settled and were not re-litigated.
• structure:repo-health — complete (constrained); inspected 2 assigned files (6 inspected across reviewers): internal/llmadapters/pi_rpc.go, internal/llmadapters/subprocess.go; skipped: none; constraints: Anchorable surface was limited to the two assigned files (internal/llmadapters/pi_rpc.go, internal/llmadapters/subprocess.go). I read internal/llmadapters/llm.go, api.go, internal/llm/adapter.go, internal/llm/subprocess.go, the package test files, and docs for context, but findings cannot anchor ... Ranged cr_read responses were misaligned with the requested byte offsets in this run; I worked around it with contiguous chunk reads plus cr_search for symbol locations. The PR is a four-hunk instrumentation change; timing-assertion robustness in *_test.go (wall-clock upper bound of 350ms in assertClaudeBackgroundDuration) is outside my anchorable set and is not reported here. Two prior threads on these files already settled the duration-window placement and the assertion strength; per that resolution I did not re-raise the accepted enforcement gap (the helper is convention, not enforced by any test or shape check).

Inspected files (6)

• internal/llmadapters/api.go
• internal/llmadapters/llm.go
• internal/llmadapters/pi_rpc.go
• internal/llmadapters/pi_rpc_test.go
• internal/llmadapters/subprocess.go
• internal/llmadapters/subprocess_test.go

3 PR discussion threads considered. 3 summarized; 3 resolved.

---

Completed in 3m 59s | $0.00 | opencode-go/deepseek-v4.1-flash | cr 0.10.302

Field	Value
Model	opencode-go/deepseek-v4.1-flash
Reviewers	go:implementation-tests, structure:repo-health
Engine	pi_rpc · opencode-go/deepseek-v4.1-flash
Reviewed by	cr · monit-reviewer
Duration	3m 59s wall · 4m 56s compute
Cost	$0.00
Tokens	7.9k in / 3.3k out

Per-workstream usage

• go:implementation-tests — opencode-go/deepseek-v4.1-flash
  • In: 442
  • Out: 813
  • Cache read: 61.4k
  • Cache create: 0
  • Cost: $0.00
  • Duration: 2m 39s
• structure:repo-health — opencode-go/deepseek-v4.1-flash
  • In: 2.3k
  • Out: 2.3k
  • Cache read: 85.0k
  • Cache create: 0
  • Cost: $0.00
  • Duration: 2m 13s
• orchestrator-rollup — opencode-go/deepseek-v4.1-flash
  • In: 5.1k
  • Out: 222
  • Cache read: 0
  • Cache create: 0
  • Cost: $0.00
  • Duration: 2s

[monit-reviewer]

File-level note: internal/llmadapters/subprocess.go

Invariant: Response.DurationMS now feeds durable state (ledger session duration_ms -> run summaries and ComputeDurationMS totals) and this PR defines its meaning per transport (success-only, request boundary to response, excluding teardown/cleanup). That contract has no versioned home anywhere in the repo, and this PR is the change that finally made the field real for the claude_cli transport.

Why it matters: the original bug survived 7,532 sessions precisely because a zero is indistinguishable from "not measured". The lifecycle persists a non-nil pointer (internal/llmlifecycle/lifecycle.go:188), and formatDurationMS renders a non-nil 0 as 0s while nil renders unavailable (internal/reviewplan/summary.go:725, cases at internal/reviewplan/summary_test.go:578). The only description of what the number measures is the PR body; a sixth adapter author has five call sites to copy from and nothing versioned to check against.

Related durable-knowledge loss: the PR body says cost_usd is null for every claude_cli session (1,085 sessions) and is "deliberately left for a separate change; #596 tracks it", while the same body says Closes #596. Merging closes the only tracker for that deferred gap. The repo already handles this shape by naming the tracker in the doc itself ("Issue #593 tracks reconciling them", docs/llm-task-artifacts.md).

Concrete fix: (1) add duration_ms to the telemetry field list in docs/llm-task-artifacts.md with a one-line contract (cr-measured, not provider-reported; success-only; from the request boundary to the response, before teardown/cleanup); (2) open a follow-up issue for the claude_cli cost parse (or narrow #596 to duration only) and reference it from that doc so the gap survives the merge.

Reply inline to this comment.

[monit-reviewer]

Automated PR Review

Reviewed commit: a9af1df75643
Profile: pi-ds-gh - Posting as: monit-reviewer

Summary

Reviewer	Findings
go:implementation-tests	1
structure:repo-health	1

go:implementation-tests (1 finding)

Nits - internal/llmadapters/subprocess_test.go:2128

assertClaudeBackgroundDuration is the only assertion in this PR that pins the response boundary, and its upper bound leaves thin room for runner jitter. The max is slowSuccessSleep + slowCleanupSleep/2 = 350ms, while a correct run's window is the helper's 150ms sleep plus exec/reap of the test binary and the parent's stdout/state/result reads (~150-200ms of headroom). The state being rejected only appears once a 400ms control round-trip is added (the ~580ms figure in the discussion), so the tighter bound adds no detection but can fail a correct implementation on a loaded runner. Fix: derive the bound from the delay that creates the wrong state, e.g. fail when response.DurationMS >= slowCleanupSleep.Milliseconds(), which still catches the post-cleanup stamp with roughly double the headroom.

Related precision point: the slowCleanupSleep you added to the helper's agents branch never fires here. cleanupClaudeBGJob -> gcClaudeBGJobs only issues agents when a job state dir is at least claudeBGStaleJobAge (24h) old, and the only job dir in this test is the freshly written job-1; the ~580ms post-cleanup figure is exactly one slowCleanupSleep, which corroborates that. So the pinned window excludes rm only, and the agents delay is dead code implying coverage it does not have. If you want the whole cleanup window (including the stale-GC round-trip) pinned, plant a stale job dir with the existing writeClaudeHelperStateAt helper; otherwise drop the agents sleep.

I have not executed the test; this is a code-inspection judgment.

structure:repo-health (1 finding)

Minor - internal/llmadapters/subprocess.go:605

Response.DurationMS is now durable-state input, and this PR is what defines its meaning for the claude_cli transports, but that meaning has no versioned home.

Invariant: a field that becomes ledger session duration_ms (internal/llmlifecycle/lifecycle.go:188) and is summed into ComputeDurationMS (internal/reviewplan/summary.go:200) must state its per-transport semantics where adapter authors and consumers read it.

What the diff does instead: the contract this change establishes — success-only; window from just before the request is executed to the response boundary; explicitly excludes s.Cancel()/s.CloseLog()/s.runCleanup() and the claude rm + claude agents round-trips in cleanupClaudeBGJob — exists only in the PR text and in a one-line comment on the unexported recordRequestDuration in internal/llmadapters/llm.go. llm.Response.DurationMS (internal/llm/adapter.go:132) is a bare field, and no file under docs/ mentions duration semantics.

Impact: the definition is invisible at the consumption site and to the next transport author. A sixth stream that stamps inside or after cleanup compiles, passes CI, and silently inflates duration_ms and ComputeDurationMS, which downstream renders as concrete numbers (internal/reviewplan/summary.go:725), while 0 is treated as "unavailable" (internal/pipeline/pipeline_test.go:5738) — so a wrong value is indistinguishable from a right one. The four per-transport tests added here pin the window for these four paths; only the next adapter is unguarded.

Fix: add a field comment on llm.Response.DurationMS in internal/llm/adapter.go stating success-only, the window endpoints, and the cleanup/teardown exclusion, and reference it from recordRequestDuration's comment so the two cannot drift. That is the cheap durable guard; stronger enforcement (a table-driven test that walks every production adapter constructor and asserts a non-zero duration on success) is worth adding only when a next transport lands.

Reviewer Coverage

• go:implementation-tests — complete (constrained); skipped: none; constraints: Reviewed only the pinned diff plus the six assigned files. Non-assigned consumers of DurationMS (internal/pipeline sessionDraftExecuted, internal/llmlifecycle, internal/ledger, internal/reviewplan summaries) were confirmed to read the field by search, but not traced in depth. Tests were not executed. Timing, non-inertness, and stale-GC claims come from code inspection (helper sleeps, claudeBGPollInterval=500ms, claudeBGStaleJobAge=24h) rather than a run. docs/development.md was inspected for repo conventions; it contains no test-timing policy, so wall-clock assertion style was judged against existing package tests.
• structure:repo-health — complete (constrained); inspected 2 assigned files (6 inspected across reviewers): internal/llmadapters/pi_rpc.go, internal/llmadapters/subprocess.go; skipped: none; constraints: Assigned scope was internal/llmadapters/pi_rpc.go and subprocess.go; concerns about the new tests in *_test.go could not be anchored to a changed assigned file and were not filed. Checked docs/ for a duration contract; docs/llm-task-artifacts.md covers usage/cost only. The prior unresolved thread on this exact gap is what I am re-raising, not a new subject. I did not execute the test suite. Assertions in subprocess_test.go and pi_rpc_test.go were read as context, not verified by running. Verified by inspection that post-launch start placement holds: go stream.run / runClaudeBG / runClaudeForeground are all invoked after launchProcess returns (subprocess.go:247,302,537; pi_rpc.go:173).

Inspected files (6)

• internal/llmadapters/api.go
• internal/llmadapters/llm.go
• internal/llmadapters/pi_rpc.go
• internal/llmadapters/pi_rpc_test.go
• internal/llmadapters/subprocess.go
• internal/llmadapters/subprocess_test.go

0 PR discussion threads considered. 0 summarized; 0 resolved.

---

Completed in 8m 49s | $0.00 | opencode-go/deepseek-v4.1-flash | cr 0.10.302

Field	Value
Model	opencode-go/deepseek-v4.1-flash
Reviewers	go:implementation-tests, structure:repo-health
Engine	pi_rpc · opencode-go/deepseek-v4.1-flash
Reviewed by	cr · monit-reviewer
Duration	8m 49s wall · 8m 48s compute
Cost	$0.00
Tokens	6.6k in / 4.9k out

Per-workstream usage

• go:implementation-tests — opencode-go/deepseek-v4.1-flash
  • In: 580
  • Out: 2.0k
  • Cache read: 104.7k
  • Cache create: 0
  • Cost: $0.00
  • Duration: 7m 24s
• structure:repo-health — opencode-go/deepseek-v4.1-flash
  • In: 390
  • Out: 2.6k
  • Cache read: 34.6k
  • Cache create: 0
  • Cost: $0.00
  • Duration: 1m 18s
• orchestrator-rollup — opencode-go/deepseek-v4.1-flash
  • In: 5.7k
  • Out: 329
  • Cache read: 0
  • Cache create: 0
  • Cost: $0.00
  • Duration: 4s

[monit-reviewer]

Response.DurationMS is now durable-state input, and this PR is what defines its meaning for the claude_cli transports, but that meaning has no versioned home.

Invariant: a field that becomes ledger session duration_ms (internal/llmlifecycle/lifecycle.go:188) and is summed into ComputeDurationMS (internal/reviewplan/summary.go:200) must state its per-transport semantics where adapter authors and consumers read it.

What the diff does instead: the contract this change establishes — success-only; window from just before the request is executed to the response boundary; explicitly excludes s.Cancel()/s.CloseLog()/s.runCleanup() and the claude rm + claude agents round-trips in cleanupClaudeBGJob — exists only in the PR text and in a one-line comment on the unexported recordRequestDuration in internal/llmadapters/llm.go. llm.Response.DurationMS (internal/llm/adapter.go:132) is a bare field, and no file under docs/ mentions duration semantics.

Impact: the definition is invisible at the consumption site and to the next transport author. A sixth stream that stamps inside or after cleanup compiles, passes CI, and silently inflates duration_ms and ComputeDurationMS, which downstream renders as concrete numbers (internal/reviewplan/summary.go:725), while 0 is treated as "unavailable" (internal/pipeline/pipeline_test.go:5738) — so a wrong value is indistinguishable from a right one. The four per-transport tests added here pin the window for these four paths; only the next adapter is unguarded.

Fix: add a field comment on llm.Response.DurationMS in internal/llm/adapter.go stating success-only, the window endpoints, and the cleanup/teardown exclusion, and reference it from recordRequestDuration's comment so the two cannot drift. That is the cheap durable guard; stronger enforcement (a table-driven test that walks every production adapter constructor and asserts a non-zero duration on success) is worth adding only when a next transport lands.

Reply inline to this comment.

[monit-reviewer]

assertClaudeBackgroundDuration is the only assertion in this PR that pins the response boundary, and its upper bound leaves thin room for runner jitter. The max is slowSuccessSleep + slowCleanupSleep/2 = 350ms, while a correct run's window is the helper's 150ms sleep plus exec/reap of the test binary and the parent's stdout/state/result reads (~150-200ms of headroom). The state being rejected only appears once a 400ms control round-trip is added (the ~580ms figure in the discussion), so the tighter bound adds no detection but can fail a correct implementation on a loaded runner. Fix: derive the bound from the delay that creates the wrong state, e.g. fail when response.DurationMS >= slowCleanupSleep.Milliseconds(), which still catches the post-cleanup stamp with roughly double the headroom.

Related precision point: the slowCleanupSleep you added to the helper's agents branch never fires here. cleanupClaudeBGJob -> gcClaudeBGJobs only issues agents when a job state dir is at least claudeBGStaleJobAge (24h) old, and the only job dir in this test is the freshly written job-1; the ~580ms post-cleanup figure is exactly one slowCleanupSleep, which corroborates that. So the pinned window excludes rm only, and the agents delay is dead code implying coverage it does not have. If you want the whole cleanup window (including the stale-GC round-trip) pinned, plant a stale job dir with the existing writeClaudeHelperStateAt helper; otherwise drop the agents sleep.

I have not executed the test; this is a code-inspection judgment.

Reply inline to this comment.