refactor(timing): move model-call timing to the provider boundary by caihongwei2006 · Pull Request #562 · scitix/siclaw

caihongwei2006 · 2026-09-04T09:02:24Z

Summary

Record model-call timing at the provider boundary so tool-only calls, provider latency, reasoning, output, and failed routing attempts can be accounted for independently. Persist one assistant carrier per model call, bounded/redacted thinking rows, and tool-to-call attribution; remove the former gateway timing inference.

Transcript queries preserve legacy NULL-metadata messages and filter hidden telemetry before pagination in both chat and task-run traces. Thinking storage failures cannot prevent answer persistence, and stopped tools retain their call linkage.

Timing and persistence contract

metadata.llm_call.ms records net_ttft, thinking, output, and total on one clock. Provider usage and stop reason travel with the envelope.
The chat bubble badge now shows that message's single model-call duration, not cumulative turn time. For a multi-round tool turn, the final answer badge covers the final call only; the UI does not currently display the whole turn's wall-clock duration.
SSE and Lark persist failed calls on error/carrier rows and rolled-back calls on route notices. Buffered failed attempts send only their envelopes with the switch event; discarded text is not replayed.
Thinking text is redacted and clipped on a UTF-8 boundary to the existing MySQL TEXT limit (65,535 bytes including the marker). Truncation is explicit in metadata.
Thinking rows and empty assistant carriers with llm_call and no kind are hidden in transcripts. Explicit error/route kinds remain visible. Physical database message counts still count physical rows.
Synthetic notification turns now preserve recorder attempt state across fallback, but retain their existing conditional report persistence; they do not have the full SSE/Lark database timeline contract.
Historical rows without envelopes have no timing telemetry. There is no backfill or fallback to retired timing fields.

Deploy requirement

Rebuild the agentbox image, bump SICLAW_AGENTBOX_IMAGE, then recycle running agentbox pods. imagePullPolicy: Always pulls only when a pod is created. A gateway-only rollout leaves old pods emitting no envelopes and their sessions reporting timing count 0 until recycled.

Relationship to #536

Both changes carry tool-to-model-call attribution through different mechanisms. Reconcile that overlap before merging both.

Test Plan

Backend full suite: 6,694 passed, 2 skipped; adapter/transcript/recovery targeted suite: 280 passed.
Frontend suite: 249 passed.
Root TypeScript build and frontend production build.
Real node:sqlite chat/count/trace queries; multi-byte reasoning cap and failed insert; parallel tool abort linkage; buffered routing envelope delivery and redaction; synthetic recorder lifecycle.
Live MySQL and production rollout validation.

jacoblee-io

Re-reviewed the reworked version (the PR 559 findings — identity dedup, delegate-api CoT leak, lark revocation — all look addressed, and the recorder's failed-call FIFO was verified safe against the vendored pi retry semantics). Still withholding approval: verification confirmed 9 correctness bugs, and the top cluster is the Lark channel path's hand-copied persistence state machine diverging from sse-consumer in four separately confirmed ways (persist gating, recovery predicate, rollback semantics, empty-error guard). Inline comments below; three findings can't be anchored because their lines aren't in this diff:

src/portal/siclaw-api.ts:2674 — the task-run trace endpoint renders chain-of-thought. GET .../runs/:runId/messages selects chat_messages WITHOUT the metadata column and with no kind filter, and TraceView.tsx:83-91 renders every assistant row as a Markdown bubble. A scheduled task run on a reasoning model persists kind:"thinking" rows (full reasoning text as content) and content-empty model-call rows via the new consumer — the operator sees the model's complete reasoning duplicated ahead of each reply plus blank bubbles per tool-only call, with no field the frontend could even filter on. Violates ADR-018's own rule that every chat_messages reader must treat kind:'thinking' as hidden; delegate-api and usePilotChat were patched, this reader was not.
src/agentbox/session.ts:2184 — routed background/synthetic turns never wire the recorder's attempt protocol. handleRouteEvent never touches brain.llmCalls (no beginAttempt/rollbackAttempt/explicit beginPrompt), so with promptExplicit=false each per-candidate brain.prompt() fires an implicit beginPrompt that fully RESETS the recorder (attempt=1, round=0, new prompt_received_at). The surviving fallback's envelopes claim attempt=1, since_prev_ms no longer spans the discarded attempt (violating rollbackAttempt's own documented invariant), and trailing aux calls are dropped by the implicit endPrompt — the audit trail is wrong on exactly the failure turns it was built to explain.
src/gateway/sse-consumer.ts:1054 — stopped tool rows lose llm_round/tool_call_id. The abort finalizer builds stoppedMeta as only {status:'stopped', started_at} without spreading pendingCall.roundMeta, and updateMessage (adapter.ts:2907) runs SET metadata = ? wholesale — exactly the replacement pitfall the struct's own field doc ("must be re-stamped at end") and the normal tool_end path guard against. After reload, an aborted turn's stopped tool row can no longer be attributed to its model call, breaking the PR's "a tool's group is known without consulting a clock" contract.

Also confirmed but below the cap: the metrics timing endpoint JSON.parses each row's metadata up to 4× (≈200k parses per request at the 50k row limit); call-only model-call rows carry no metadata.kind, so each reader re-invents shape detection; docs/design/2026-08-02-error-surfacing-contract.md and ADR-014's ttft_ms claim are now factually false and weren't updated.

caihongwei2006 · 2026-09-07T03:25:00Z

Addressed the remaining review findings in 4dc3d9f, with replies on all five open inline threads.

The additional summary finding is fixed too: synthetic notification turns explicitly open/close the recorder around the entire routing run and apply attempt/rollback events. A regression verifies that implicit per-candidate prompt boundaries do not reset fallback attempt 2 to attempt 1.

For the lower-priority summary notes:

Timing metrics decode each row metadata once and reuse it for all four values.
ADR-014 and the error-surfacing contract now describe the current envelope/carrier behavior.
Kept the existing kind-less empty-call shape rather than introducing another format change. Portal readers share one SQL predicate, the frontend now preserves explicit error/route kinds even when empty, and ADR-018 states the discriminator and precedence. Synthetic notification reports remain outside the full SSE/Lark timeline persistence contract.

Validation: backend suite 6,691 passed / 2 skipped, updated Lark suite 248 passed, frontend suite 249 passed, root TypeScript build and frontend production build passed. SQLite statements were executed; no live MySQL or production deployment was exercised.

jacoblee-io

Read the whole change. The core refactor is clean: measurement moved to the provider boundary, the inferred fields are removed outright rather than dual-written, net_ttft + thinking + output == total genuinely holds by construction, and the thinking-row clip is correct (I ran the byte math separately — stays within 65,535 including the marker and never splits a character). Test coverage is solid.

Findings below, worst first. Only the first one I'd consider merge-blocking.

1. The upstream-mode transcript readers were not updated

transcriptVisiblePredicate reached two call sites (siclaw-api.ts:2291 pagination/count, :2696 task-run traces). The two mirrors in src/portal/adapter.ts are still bare queries:

chat.getMessages (RPC handler, adapter.ts:2957)
POST /api/internal/siclaw/chat/messages (adapter.ts:1885)

Both are WHERE session_id = ? ORDER BY created_at DESC, seq DESC, id DESC LIMIT ? with no kind filter, and in upstream mode that is the path the chat transcript actually comes from. After this ships those readers get, per model round, one kind: "thinking" row rendered as an assistant reply (up to 64KB of reasoning text) plus one empty assistant carrier row for every tool-only call. A limit: 50 page can now be almost entirely telemetry, so paging degrades as well.

ADR-018 states the requirement itself — "Any reader of chat_messages must treat kind: "thinking" as a hidden assistant kind before this runtime ships" — and these two readers are in this repo. CLAUDE.md also calls out that adapter's HTTP + WS mirrors have to move together.

If some consumers legitimately want the telemetry rows, an opt-in flag on those handlers is fine; silently returning them is not.

2. Row inflation vs. `message_count`

persistCallOnlyRows (sse-consumer.ts:149, lark.ts:3131) is the only write path that does not call incrementMessageCount; thinking rows, carrier rows and error rows all do. Two consequences:

A session's message_count (shown as "N messages" in the session list and audit views) now diverges from the number of rows the transcript renders by roughly 2–3×. The ADR acknowledges the daily message_count metric (siclaw-api.ts:3632) stepping on rollout, but not this one, and this is the number a user looks at directly.
Call-only rows being the single exception to the increment rule makes message_count mean neither "physical rows" nor "visible rows". Please make it consistent one way or the other.

3. `metadata` has no size bound while `content` now does

content got a 65,535-byte UTF-8-boundary clip. metadata is the same TEXT column and is unbounded: llm_call.blocks (two ISO timestamps per content block), tool_call_ids, nested aux_calls, and discarded_llm_calls (an array of envelopes) all grow without a cap.

Under MySQL strict mode an overflow is a thrown Data too long for column 'metadata'. The thinking-row insert is wrapped in try/catch (second commit), but the model-call row's appendRow is not, so the throw escapes the for await and takes the rest of the turn's SSE consumption with it. Realistically the envelope is a few KB, so this is unlikely rather than impossible — but having capped content it seems odd to leave the sibling column open. A cap on blocks length would cover the unbounded axis.

4. The chat bubble's "model time" changed meaning, and the PR description doesn't say so

combinedModelMs is now a single call's total. On a multi-round tool-using turn the badge shows only the last call — the one that produced the final text — so the number drops sharply, and nothing in the UI shows the turn's wall clock any more. since_prev_ms and the per-round envelopes are persisted but nothing renders them. The description covers the dashboard split; this user-visible change deserves a line too.

5. The live envelope is not redacted

sse-consumer.ts:850 attaches the original envelope to the event, so error_message (up to 500 chars of provider error text, which can echo a key) reaches the browser verbatim; only the persisted copy goes through redactLlmCallEnvelope. stream_error has the same pre-existing gap, so this isn't a regression — but it is a second channel, and the redactionConfig is right there. Attaching a redacted clone costs nothing.

6. Smaller things

Commit message contradicts the code. It says "prevResponseEndAt is not advanced, so the next call's since_prev_ms spans it and it is counted exactly once". sealFailedCall calls sealCall, whose agent branch unconditionally does this.round += 1 and this.prevResponseEndAt = responseEndAt. So a failed call that never finds a carrier has its span dropped rather than reattributed, and leaves a hole in the round numbering. The ADR's "round numbering has no holes" only holds for the retries that get replayed as empty rows.
Wall clock for durations. The partition identity is stated as holding by construction, but every interval comes from Date.now(). An NTP step backwards makes a Math.max(0, …) clamp break the identity. These are all same-process durations — performance.now() for the deltas, with the ISO timestamps kept as-is, would make the guarantee real.
transcriptVisiblePredicate de-sargables pagination and count. idx_chat_messages_session used to let COUNT(*) stay index-only; now every candidate row reads the metadata TEXT and runs JSON_VALID + JSON_EXTRACT. Worth measuring on a large session before rollout.
LlmCallRecorder.attemptStarted is declared in the middle of the class, after the methods that use it. Works, but reads badly.
TimingStatsCard's entry prop is kept but unused ("call-site compatibility"). Dropping it and updating the call site is cleaner than keeping a dead prop.

caihongwei2006 · 2026-09-07T03:48:09Z

Thanks for separating the merge blocker from the other findings. This revision fixes #1; the remaining points are clarified below without expanding the runtime refactor.

Adapter readers: fixed in 689d7e9. Both POST /api/internal/siclaw/chat/messages and chat.getMessages now use the same NULL-safe transcriptVisiblePredicate before LIMIT. Tests execute both handlers' SQL against SQLite with 60 hidden rows, legacy user/assistant rows, an explicit empty error notice, another session, and a before cursor. All three visible rows survive a limit of 3. No telemetry opt-in was added: the in-repo caller uses this as transcript/recovery data, while timing metrics query their own rows. These are Portal's upstream-compatible mirrors; this does not change an external upstream service's implementation.
Counts: the claimed inconsistency is not present. src/gateway/chat-repo.ts:400 implements incrementMessageCount() as a no-op. Both adapter append handlers increment chat_sessions.message_count after INSERT (HTTP append-message and RPC chat.appendMessage), including calls from persistCallOnlyRows. Adding another increment at those callers would change nothing. The count is physical rows, not visible bubbles; ADR-018 explicitly names both chat_sessions.message_count and the generic Portal metric. The divergence from visible bubbles is real and intentional. Changing that established count contract is outside this timing PR.
Metadata size: accepted as a possible limit, but not a demonstrated P1 workload. Reasoning text alone can exceed TEXT in an ordinary extended-thinking response; a call envelope has no reasoning body and grows with block/tool/attempt structure instead. Arbitrarily cutting blocks would discard measurement detail and would not bound aux_calls or discarded_llm_calls, so it is not a complete fix. Keeping the current envelope contract here; a supported metadata budget/schema decision should address the entire payload if actual workloads require it. This is not a claim that overflow is impossible.
Badge meaning: agreed; added an explicit line to the PR description. The badge is per model call, so the final answer's badge covers only its final call. It no longer claims cumulative turn time, and there is currently no full-turn wall-clock UI. This is the intended move from inferred turn figures to measured call figures; a turn timeline would be additional UI scope.
Live redaction: agreed that live error text is not uniformly redacted. Redacting only evt.llmCall would not close that boundary: the event also retains message.llmCall and message.errorMessage, and stream_error carries the error too. Persisted envelopes already use the configured redaction path. A consistent live-event redaction contract should cover all those fields together; leaving that pre-existing live-stream behavior outside this P1 fix rather than treating one cloned alias as sufficient.
Smaller points:
- The earlier commit prose is inaccurate: sealFailedCall does advance the recorder through sealCall. Failed time is represented by its retained carrier, not reattributed into since_prev_ms. If a carrier is absent, that is missing telemetry; there is no reconstruction guarantee. No history rewrite or new inference logic proposed.
- Same-process clocks avoid cross-pod subtraction, but do not make Date.now() monotonic. The partition statement assumes no wall-clock step during a request. A backward step is a valid limitation; changing the recorder's clock model is separate from the transcript blocker.
- The filter loses index-only counting, but does not remove the indexed session_id restriction. Reading metadata for candidate rows is the cost of filtering before pagination; filtering after LIMIT reintroduces the demonstrated empty-page problem. No large-session benchmark is claimed, and adding stored flags/indexes without workload evidence would be another schema change.
- Field placement and the unused compatibility prop are cleanup, not behavioral blockers. Leaving them out of this revision.

Validation: 280 targeted tests passed and the TypeScript build passed. Full-suite result: 6,694 passed / 2 skipped.

Model timing was inferred in the gateway from when SSE events arrived, and that made a turn's time impossible to take apart: - a model call that returned only tool calls had no row at all, so its time was parked on the tool rows as `pre_thinking_ms` — the bulk of model time living on tools; - the wait for the provider's first byte was never measured, because the clock started when the gateway saw an event, not when the request left; - time-to-first-token and output duration are two different quantities with two different causes, and `thinking_ms` blended them with reasoning, so "the provider is slow", "the model reasoned a while" and "the answer was long" all looked the same; - `turn_total_ms` was cumulative despite its name, and ttft/thinking overlapped so badly they needed a NOISE_FLOOR to deduplicate. This moves the measurement to the `chat.completions` boundary and deletes the inferred one. There is no dual-write and no compatibility path: the inference logic IS the defect, so keeping it behind a flag would keep the defect. - `src/core/llm-call-recorder.ts` wraps `agent.streamFn` innermost, before the guard pipeline, so guard work lands in setup rather than in net_ttft. Per request, on ONE clock: request/headers/first-token/block-edge/response-end timestamps, provider `usage` (reasoning tokens included), and `stop_reason`. `ms.net_ttft + ms.thinking + ms.output == ms.total`, by construction. - One agent-loop call ⇒ one assistant row carrying `metadata.llm_call`, even when the content is empty. Reasoning text becomes its own `kind: "thinking"` row written just before it. Tool rows carry `metadata.llm_round` + `metadata.tool_call_id`, so a tool's group is known without consulting a clock. - Failed calls ride the `error_response` row; a rolled-back routing attempt rides `model_route_notice` as `discarded_llm_calls`. Both are time the user waited for and neither had a carrier before. - Removed: `turnStartTime` / `firstTokenTime` / `lastBoundaryTime` / `pendingThinkingMs` / `NOISE_FLOOR_MS`, `pre_thinking_ms`, `timing.*`, and the portal's cross-pod `turnStartMs` anchor. Not dual-written — the inference logic is the thing being removed. Tool durations use a SINGLE clock end to end: the agentbox's when the runtime stamped both `startedAt` and `endedAt`, the gateway's when it stamped neither. Defaulting a missing stamp to `Date.now()` would subtract one pod's clock from another's, and the `Math.max(0, …)` guard would dress the skew up as a plausible measurement rather than surfacing it. Review fixes: - The error row keeps the failed call's envelope. A terminal failure is delivered twice — message_end then turn_end, on one message object — and binding the seenEnvelopes-deduplicated value meant the second pass replaced the queued row with an envelope-less one. That row is the call's ONLY carrier (a rollback uses discarded_llm_calls instead), so its time vanished. Dedup exists to keep the MODEL-CALL row single and has no business gating the error row's contents. - Live timing lands only on the bubble the call is streaming into. A live bubble is built from text, so a tool-only call has none, and the "last visible assistant" search badged the PREVIOUS call's finished bubble with a partition that was not its own — disagreeing with the reload for the length of the turn. - Lark buffers the error row instead of writing it on sight, reusing sse-consumer's own messageProducedOutput rule rather than a second copy of it. A primary that 429s before a successful fallback no longer leaves an error row sitting above its own answer in the thread. - A request that throws before any message exists is recorded as such. It has no carrier by design — the envelope is stamped onto a message — so its span is reattributed rather than lost: prevResponseEndAt is not advanced, so the next call's since_prev_ms spans it and it is counted exactly once, as setup or tool time rather than model time. Wrong bucket, never a double count. - Trailing compaction is named for what it is. aux_calls only ever ride a LATER agent call, and the agentbox defers the SSE close while compacting, so a post-final-call compaction has no carrier and its span stays in the prompt tail. The warning said "dropping ... from the previous prompt", which read like an anomaly; it is ordinary, and the residual is where it belongs. Closing the review gaps found on the first pass: - Envelope dedup keys on the envelope's VALUES, not object identity. message_end and turn_end arrive as separately JSON-parsed SSE frames, so an identity-based WeakSet never collapsed them at all — the failed call's error row, its only carrier, was then replaced by an envelope-less one and its time disappeared. - A pi in-turn auto-retry keeps its failed attempts: they are persisted as empty model-call rows on recovery, and written before the terminal error_response when the run really fails, so round numbering has no holes. - Every persisted llm_call copy is redacted, nested aux_calls and discarded_llm_calls included. A provider's error_message went into metadata.llm_call unredacted while the identical text in `content` was redacted; appendMessage does not redact metadata. - Lark buffers model errors with last-error-wins, drops them when a later attempt produces output or routing rolls back, and flushes only the terminal failure — so a 429-then-fallback-succeeds turn leaves no error row above its own answer. - The stream-cut partial row is attributed to the in-flight round rather than the preceding completed one. - Lark's llm-call bookkeeping (dedup, round tracking, event clock, tool metadata, duration, redaction, row eligibility) moved into the shared llm-call-rows module instead of a second inline copy of sse-consumer's. Data-format note for readers of `chat_messages`: `kind = "thinking"` must be treated as a hidden assistant kind, or a model call's own reasoning counts as a reply to the user. Empty model-call rows carry a call's timing and no content; they are identified by `metadata.llm_call` with an empty `content`, not by a kind. Both are documented on the envelope type.

Keep NULL-metadata messages visible and filter hidden telemetry before pagination. Bound reasoning storage and isolate its failures from answer persistence. Preserve stopped tool linkage and buffered routing envelopes, and bracket synthetic recorder attempts explicitly. Tested: backend suite (6691 passed, 2 skipped), updated Lark suite (248 passed), frontend suite (249 passed), root and frontend builds

Apply the shared visibility predicate before LIMIT in both HTTP and RPC mirrors so reasoning and empty call carriers cannot crowd out legacy messages. Tested: 280 targeted tests; full suite 6694 passed, 2 skipped; TypeScript build

Reconcile main knowledge-citation attribution with the model-call metadata contract. Remove only citations on rollback and verify that call envelopes survive.

jacoblee-io

Approving. The blocking finding is closed and the rebase holds up under review.

What I re-verified on fff04a60:

689d7e9b applies transcriptVisiblePredicate before LIMIT in both adapter mirrors, which was the one merge-blocker. The test covers HTTP and RPC separately, keeps NULL-metadata legacy rows visible, keeps a content-empty error_response visible, and pushes 60 hidden rows through to prove they can no longer crowd out a page.
The conflict resolution in sse-consumer.ts is not mechanical: main's per-row knowledge-citation attribution is correctly folded into the rewritten assistantRowMetadata. I checked the one hazard I could see — pendingRowCitations = [] now also runs on the empty-carrier branch — and it is safe, because pendingRowCitations is only ever set inside the base.trim() path, which sets assistantContent non-empty in the same iteration. Set and consumed in one event; nothing can leak onto a hidden row.
fff04a60 is a real fix, not conflict noise: main's rollback wrote {...lastRowMetadata, knowledge_citations: undefined, discarded_route_attempt: true}, and lastRowMetadata now carries llm_call. Destructuring only the citations out keeps the envelope on the discarded row, which stays consistent with the Lark switch notice only carrying calls that have no row of their own — no double count.
CI green across all four jobs.

Left open deliberately (my earlier comment, items 2–6 — none blocking, but they shouldn't be lost):

persistCallOnlyRows is still the only write path that skips incrementMessageCount. Please settle this one way or the other before or shortly after merge: as it stands message_count means neither "physical rows" nor "visible rows", and if the asymmetry is intentional it deserves a line in ADR-018 rather than being inferred from the code.
metadata has no size bound while content now does, and the model-call appendRow has no try/catch (the thinking row does).
The chat bubble's "model time" now shows one call's total, and nothing in the UI shows a turn's wall clock any more — worth a line in the description.
The live event carries the unredacted envelope; only the persisted copy goes through redactLlmCallEnvelope.
Smaller: the commit message's "prevResponseEndAt is not advanced" claim contradicts sealCall; wall-clock deltas make the partition identity breakable under an NTP step; transcriptVisiblePredicate de-sargables the chat count/pagination and is worth measuring on a large session; TimingStatsCard's entry prop is dead.

One observation from the rebase, pre-existing rather than introduced here: a rolled-back successful call is represented differently by the two paths — SSE writes no row and nests the envelope in model_route_notice.discarded_llm_calls, Lark writes the row and marks it discarded_route_attempt: true with llm_call retained. The metrics timing query reads rows and not discarded_llm_calls, so a channel session contributes one extra sample where an identical web session contributes none. Worth a follow-up issue.

Deploy: per the description this needs an agentbox rebuild + SICLAW_AGENTBOX_IMAGE bump + pod recycle. imagePullPolicy: Always only pulls on pod create, so verifying against a live session proves nothing.