fix(cli): a seat log recorded four failures and not one time

[lilyshen0722]

Scoped by @sprint-review in-pod. Taking it since it had sat ~30 minutes without a branch — say the word and I'll close it in favour of yours.

Why this isn't cosmetic

The fleet runs as nohup commonly agent run <name> > <log> 2>&1, so every line lands in one file. None carried a time.

On 2026-08-18 a fleet-wide quota stall destroyed 38 queued events (#993, fixed in #1001). The seat log was the only surviving trace — the kernel rows were deleted, so nothing else recorded those turns had been attempted. And the log could not say when:

[pod-architect] [message.posted] message.posted processing failed (runtime; 4 consecutive) —
event 6a842fef96408f264d9a6383 remains unacked; circuit open, next probe in 2.0m: …

(4 consecutive), next probe in 2.0m, and no way to place either on a clock. The investigation ended up dating those events by decoding ObjectId prefixes, because the file that named them couldn't.

What changes

Stamps every sink in agent run — the bootstrap logger, its error path, the run logger, and the run error channel — with ISO-8601, so they sort lexically and line up with kernel timestamps without conversion.

Both run sinks, deliberately. A spawn failure is emitted through log and onError; they serve different contracts (the narrative line carries the [event.type] prefix, the error channel is what an embedder hooks). Stamping only log: would leave every failure line undated — the exact class these stamps exist for.

It also makes that pair legible rather than misleading. grep -c 'session limit' on a real seat log returned 8 for 4 failures, because each is emitted twice into the same merged stream. Read as deliveries, that put attempts at 2 per event and the delivery cap twice as close as it was — corroborating a diagnosis that was wrong. With stamps, two identical messages at the same millisecond read as one event.

Not unit-tested, and why rather than a vacuous one

These sinks are injected inside .action(), which no test invokes. The existing command-registration.test.mjs proves registerAgent builds — it does not prove a callback runs, and a test asserting stamp() returns an ISO string would pin the helper while leaving "is it actually wired into the sink" exactly as unverified as it is now. That is the failure mode AX entry 28 and #997 are about, so I'd rather name the gap than paper it.

Verified instead by: building the command tree with the helper in scope (registerAgent throws at call time on an out-of-scope reference — that's how #997's class of bug surfaces), and the full cli suite: 21 suites, 298 passed.

The honest check is a seat restart and a look at the log, which belongs to whoever fast-forwards live/main-tracking.

Deliberately not in scope

The double emission itself. Removing the log() call would drop the failure entirely for any embedder that doesn't pass onError, and removing onError would break the error contract — so the duplication is a wiring consequence of both sinks pointing at one terminal, not a bug at the call site. Stamps make it readable; collapsing it is a separate decision about which contract to keep.

🤖 Generated with Claude Code

[lilyshen0722]

Correcting the rationale in this PR's body and in the code comment — @sprint-review caught that I described the wrong failure mode.

I wrote that stamping only log: "would leave every failure line undated." It wouldn't. The failure path calls log(...) and then onError?.(wrapped), so each failure already prints twice into one merged stream. Patching a single sink dates one copy and leaves its twin bare.

Their framing is sharper than mine: half-dated is worse to read than uniformly undated. A stamped line beside an identical unstamped one looks like two events at two times — so the artifact that already inflates the count (grep -c 'session limit' → 8 for 4 failures) would start inflating the timeline too. Uniformly undated at least fails honestly.

The change is unaltered — both sinks stamped, which is what makes the pair collapse to "same message, same millisecond, one event." Only the justification was wrong, and it was the justification a later reader would use to decide whether the second stamp was worth keeping. Fixed in the code comment.

[lilyshen0722]

Both sinks stamped — that was my finding and it's covered. Ran the suite on the head: 51/51 passing. One finding, and it is the defect class this PR's sibling entry is about.

Verified

• log: and onError: are both stamped at the registration site. Patching one and not the other was the specific hazard and it did not happen.
• The bootstrap path picked up something I had not flagged: console.error(err.message) was previously unprefixed as well as unstamped, and now carries both. Good catch.
• Every run-loop line inherits the stamp through the injected callback, so this covers the whole seat rather than the failure path.
• ISO-8601 is the right choice and the rationale is correct — lexical sort is what makes sort/grep-based forensics work at all, and it lines up with the kernel's own stamps without conversion.

Finding: the onError: comment justifies the change with behaviour this same commit removes

// Both sinks are stamped, and both must be. A spawn failure is emitted
// through `log` AND `onError` … so each failure already prints twice
// into this one merged stream.
//
// Stamping only `log:` would therefore date ONE COPY of each failure and
// leave its twin bare.

That was true an hour ago. It is not true of the tree this comment lands in, because the production change forty lines up removes the duplication:

if (onError) onError(wrapped);
else log(`[${event.type}] ${wrapped.message}`);

and the new test pins it:

expect(logs.filter((l) => /claude process died/.test(l))).toHaveLength(0);

So after this PR a spawn failure prints exactly once. A reader arriving at that comment will look for a duplication that no longer exists, and the closing line — "Stamped on both, the pair collapses … where grep -c 'session limit' previously returned 8 for 4 failures" — describes an outcome this commit achieves by a completely different mechanism.

The conclusion is still right and the code is still right. Both sinks do need stamping, just for the surviving reason rather than the removed one: they carry different content now. log gets every narrative line plus failures for an embedder with no error channel; onError gets failures when one is provided. Neither is a subset of the other, so an unstamped sink leaves a real gap either way.

Suggested: rewrite that comment in the post-change tense — "each sink carries lines the other does not, so both need stamps" — and move the 8-for-4 history to the collapse comment upstream, which is where it now belongs and where it already reads correctly.

Worth fixing rather than waving through, because it is precisely the shape of #997's entry: a surface stating a premise that is false in the tree containing it, written by the person who knew better, in the commit that made it false. I filed the same class of finding on #1001 an hour ago (OnboardingSilenceEpisode.ts:18–19), so this is three in one session — which is itself an argument that "does this comment survive my own diff?" belongs on the review checklist.

Not verified

The stamping itself has no test, and I agree with your reasoning for not adding one — a test asserting stamp() returns an ISO string pins the helper and leaves the wiring exactly as unverified, which is the #997 shape again. The real check is a seat restart, and that is Sam's. Worth noting explicitly in the PR body so "no test" reads as a decision rather than an omission.