A slow model call shows in job_get and warns the caller

[tobert]

The decision

A kaijutsu review on the crusoe cast ran 29 minutes before the caller cancelled it. ClickStack had the answer the whole time — GLM-5.3 at ~100 s a call — but nothing in the tool surface pointed at it: every span was Unset and the only signal a caller had was elapsed time. The tracker entry proposed two things, per-call latency in the progress line and a warn past a threshold. Amy: "take a look at the lift, good idea, and we can check our tracing health while we're there."

Tracing health, checked first: spans and logs land through today, zero error-status spans since 09-05. And the traces settle what the slow review was. GLM-5.3 on Crusoe took the same ~100k-token prompts on 09-10 and 09-12, but per-call p50 went 3.8 s → 40 s → 104 s and output speed 102 → 21 → 7 tok/s over three days. The endpoint degraded, not the prompt. The lift would have shown that at the first poll.

What ships

• A ChatCompleted beat from the completion wrapper. Watched already measured every provider call and threw the number away after the metrics write. It now emits the duration as a progress event labeled with the cast role, success or failure.
• job_get shows each role's latency beside the latest beat: synth chat: last 107 s, p50 98 s over 9 calls. A chat beat does not touch the "currently" line or its step count; those track tool activity.
• A call that reaches [defaults] slow_chat_secs warns the caller through job_wait. Default 60, 0 turns it off, env KAIBO_SLOW_CHAT_SECS, rendered in kaibo://config, documented in the template and the guide.
• A retried call is timed and counted per attempt. The watcher now sits inside the retry wrapper, so the beat, the client metrics, and inference_calls see the provider's time and never kaibo's backoff sleep. The attempts doc comment was already claiming this; the code now does it.

Where the threshold lives, and why

On TracingSink, not PhaseContext. Two reasons. Every one of the 17 PhaseContext literals in the tree is exhaustive, so a field there is 17 edits for one number. And the mark is an audience decision — who is told — which is exactly what the sink's level convention already routes (mcp_log.rs: Warn means "the calling model should see this"). promotes_to_caller stays a pure predicate by taking the threshold as an argument. The three async job lanes build the sink through one helper, job_progress_log, so the mark cannot be dropped at one lane and kept at another.

The phase runner's sink became an owned Arc (the wrapper rig clones into each agent has to hold it) and the runner takes the ModelRole, so the beat says synth or explorer. The single-shot lanes (oneshot, deliberate direct) are unchanged; their caller waits on one call anyway.

Review, and what changed because of it

The deepseek cast mapped the path before I wrote a line (all nine citations I spot-checked held) and reviewed the change after. Every citation in the review was checked against source before acting. It found two real things:

1. The docs claimed a synchronous call's log stream carries the warn. It does not — only the async lanes build a TracingSink; a sync consult routes beats to progress notifications, which have no level. Fixed by narrowing the three texts to what the code does. A synchronous caller still sees every call's time in its progress line; a warn-level log notification would not reach a Claude Code agent mid-call anyway.
2. The beat's elapsed time included kaibo's own retry backoff, up to a minute per attempt, so a promoted warning could blame the model for kaibo's waiting. Fixed by swapping the wrapper order (retried(watched(model))), with a test that pins one beat per attempt and fails under the old order.

Also from the review: the warn string's advice was ungrammatical and said "past" a mark the predicate treats as inclusive (now "reaching", and "job_cancel it"); whole seconds are floored so 60 s means the mark was reached and 59 s means it was not.

One finding is a deliberate trade, flagged rather than changed: on a uniformly slow backend every call promotes, so a parked job_wait wakes once per call. That is the signal the knob exists to send; an operator who wants the park back raises slow_chat_secs.

Verification

Ten new tests. Each guarded behavior was sabotaged and its test went red: no emit in the wrapper, no beat attached in the engine, a chat call never promoting, a chat beat overwriting the latest line, 0 not honored, and the watcher moved back outside the retry. Full suite and clippy clean; counts in the commit messages.

Reviewed-by: kaibo cast deepseek (deepseek-flash explorer + synth), two passes

🤖 Generated with Claude Code