feat: [AI-7519] bootstrap latency instrumentation + phase-label UX#1002
feat: [AI-7519] bootstrap latency instrumentation + phase-label UX#1002sahrizvi wants to merge 4 commits into
Conversation
Two-halves fix for AI-7519. The "investigate first-answer latency" half:
wrap the awaits inside session-prompt loop() with a `traceSpan` helper so
the previously-invisible pre-first-generation region shows up in the
trace waterfall. The "<10s to first visible response" half: the same
wrapper publishes a `session.phase` bus event on entry/exit; the TUI
subscribes and renders an honest label ("Loading config...",
"Discovering tools...", "Thinking..." fallback) next to the busy
spinner so the user sees *what* the agent is doing instead of a silent
spinner.
Server side
- `packages/opencode/src/session/status.ts` — new `Event.Phase`
EventV2 + `LegacyEvent.Phase` bus bridge + `publishPhase(sessionID,
phase, active)` helper (best-effort; publish failure never affects
the traced operation).
- `packages/opencode/src/session/prompt.ts` — new `SessionPrompt.traceSpan`
namespace helper wrapping an awaited fn with `Tracer.logSpan` on
entry/exit; when a sessionID is passed, also fires start/end phase
events. Wired around: `Session.get`, `Config.get`, `Fingerprint.detect`,
`Telemetry.init`, and `resolveTools` inside loop(). Emits a parent
`bootstrap` span on step===1 covering session-entry -> first
`processor.process`.
TUI side
- `packages/tui/src/context/sync.tsx` — new `session_phase` store map +
`session.phase` event handler (defensive against reordered
active=false events).
- `packages/tui/src/util/phase-label.ts` — new phase-name -> user-facing
label lookup with "Thinking..." fallback (matches Cursor/Claude
Code/Codex CLI convention).
- `packages/tui/src/component/prompt/index.tsx` — render the label next
to the busy spinner when `status.type === "busy"`.
SDK
- `packages/sdk/js/src/v2/gen/types.gen.ts` — `EventSessionPhase` added to
the Event discriminated union so TUI event handling stays type-safe.
Tests
- `packages/opencode/test/upstream/fork-feature-guards.test.ts` — new
fork-guard locking in publish + subscribe + render wiring across the
6 files, so a merge silently dropping any piece turns into a red
test.
- `packages/opencode/test/cli/tui/phase-label.tui-e2e.test.ts` — PTY-driven
e2e that launches the built TUI, submits a prompt, asserts the label
renders in the actual stripped terminal output. Both the fallback
("Thinking...") and a specific bootstrap label ("Discovering tools")
observed on this run.
- `packages/opencode/test/fixture/pty-tui.ts` — the PTY harness helper
ported over from the feat/tui-e2e-harness branch so the new e2e can
run standalone on this branch.
Validation
- Typecheck clean across `@opencode-ai/plugin`, `@opencode-ai/tui`,
`@altimateai/altimate-code`.
- Session + tracing tests: 765 pass / 0 fail.
- Fork-guards: 18 pass (17 existing + 1 new AI-7519).
- Local Jaffle repro (built binary from this branch): trace shows all
5 bootstrap sub-spans + parent `bootstrap` span firing. TUI e2e
observed "Discovering tools" + "Thinking..." rendered in the actual
terminal output.
Not in scope
- Fix #7 in the analysis doc (decompose the `generation` span into
`req-build`/`req-network`/`stream`) — the biggest attribution win on
the between-turn gap (p90 = 455s on a multi-turn Jaffle repro), but
deferred to a follow-up so the current PR stays reviewable.
- Fixes 1, 4, 5, 8 (actual latency shaves) — depend on the
instrumentation this PR lands to measure baseline vs candidate.
Co-Authored-By: Claude Opus 4.7 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01Q8FGy89Qpr39k8nCSpCcK2
![claude[bot]](https://avatars.githubusercontent.com/in/1236702?s=60&v=4){kind=small}
There was a problem hiding this comment.
Claude Code Review
This repository is configured for manual code reviews. Comment @claude review for a one-time review, or @claude review always to subscribe this PR to a review on every future push.
Tip: disable this comment in your organization's Code Review settings.
|
No actionable comments were generated in the recent review. 🎉 ℹ️ Recent review info⚙️ Run configurationConfiguration used: Repository UI Review profile: CHILL Plan: Pro Run ID: 📒 Files selected for processing (2)
🚧 Files skipped from review as they are similar to previous changes (2)
📝 WalkthroughWalkthroughSession bootstrap operations now emit tracing and phase events. The TUI synchronizes those events into per-session state and displays mapped phase labels while busy. PTY-based end-to-end coverage and source-level wiring guards validate the flow. ChangesSession phase flow
Estimated code review effort: 4 (Complex) | ~45 minutes Sequence Diagram(s)sequenceDiagram
participant SessionPrompt
participant SessionStatus
participant LegacyEventBus
participant SyncContext
participant Prompt
participant phaseLabel
SessionPrompt->>SessionStatus: publishPhase(sessionID, phase, active)
SessionStatus->>LegacyEventBus: publish session.phase
LegacyEventBus->>SyncContext: session.phase event
SyncContext->>Prompt: update session_phase
Prompt->>phaseLabel: phaseLabel(phase)
phaseLabel-->>Prompt: rendered phase label
Suggested reviewers: Poem
🚥 Pre-merge checks | ✅ 4 | ❌ 1❌ Failed checks (1 warning)
✅ Passed checks (4 passed)
✨ Finishing Touches📝 Generate docstrings
🧪 Generate unit tests (beta)
Warning There were issues while running some tools. Please review the errors and either fix the tool's configuration or disable the tool if it's a critical failure. 🔧 ESLint
ESLint install failed. For unrecoverable errors, disable the tool in CodeRabbit configuration. Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out. Comment |
|
👋 This PR was automatically closed by our quality checks. Common reasons:
If you believe this was a mistake, please open an issue explaining your intended contribution and a maintainer will help you. |
1 similar comment
|
👋 This PR was automatically closed by our quality checks. Common reasons:
If you believe this was a mistake, please open an issue explaining your intended contribution and a maintainer will help you. |
![coderabbitai[bot]](https://avatars.githubusercontent.com/in/347564?s=60&v=4){kind=small}
There was a problem hiding this comment.
Actionable comments posted: 4
🧹 Nitpick comments (1)
packages/opencode/src/session/prompt.ts (1)
109-134: 📐 Maintainability & Code Quality | 🔵 Trivial | 🏗️ Heavy liftUse Effect composition for the new tracing helper.
This introduces raw Promise orchestration for timing, publishing, and error handling. Implement it with
Effect.fn("SessionPrompt.traceSpan")andEffect.gen, then run it only at the existing Promise boundary.As per coding guidelines,
packages/opencode/**/*.{ts,tsx}must useEffect.gen(function* () { ... })for composing Effect computations andEffect.fn("Domain.method")for named/traced effects.🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the rest with a brief reason, keep changes minimal, and validate. In `@packages/opencode/src/session/prompt.ts` around lines 109 - 134, Replace the raw Promise-based traceSpan implementation with a named Effect.fn("SessionPrompt.traceSpan") using Effect.gen to compose timing, phase publication, tracing, and error propagation. Preserve the existing success/error span fields and finally-style phase cleanup, then execute the Effect only at the current Promise boundary.Source: Coding guidelines
🤖 Prompt for all review comments with AI agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.
Inline comments:
In `@packages/opencode/src/session/prompt.ts`:
- Around line 406-431: Move the existing SessionStatus.set call that marks the
session busy to before the first bootstrap span, immediately ahead of
bootstrap.session-get in the session initialization flow. Preserve the current
busy-state payload and ensure all bootstrap phases, including config,
fingerprint detection, and telemetry initialization, execute while the session
is busy.
In `@packages/opencode/src/session/status.ts`:
- Around line 175-177: Update publishPhase to publish Event.Phase in addition to
the existing LegacyEvent.Phase event, using the same sessionID, phase, and
active payload so V2 subscribers receive session phase updates while preserving
legacy delivery.
In `@packages/opencode/test/cli/tui/phase-label.tui-e2e.test.ts`:
- Around line 24-35: Replace the manual makeProjectDir/mkdtempSync setup and
cleanup in the phase-label test with the managed tmpdir fixture imported from
fixture/fixture.ts. Declare it with await using and pass tmp.path to launchTui,
ensuring cleanup occurs even when launchTui rejects before the existing try
block.
- Around line 56-77: Update the phase-label TUI test around the existing
fallback assertion so it deterministically waits for and asserts at least one
mapped phase label, preferably “Discovering tools,” through the real event path.
Keep the “Thinking...” fallback check, but do not rely on diagnostic logging or
a non-gated rendered-text check as the only validation; ensure the test setup or
synchronization makes the mapped-label assertion reliable.
---
Nitpick comments:
In `@packages/opencode/src/session/prompt.ts`:
- Around line 109-134: Replace the raw Promise-based traceSpan implementation
with a named Effect.fn("SessionPrompt.traceSpan") using Effect.gen to compose
timing, phase publication, tracing, and error propagation. Preserve the existing
success/error span fields and finally-style phase cleanup, then execute the
Effect only at the current Promise boundary.
🪄 Autofix (Beta)
Fix all unresolved CodeRabbit comments on this PR:
- Push a commit to this branch (recommended)
- Create a new PR with the fixes
ℹ️ Review info
⚙️ Run configuration
Configuration used: Repository UI
Review profile: CHILL
Plan: Pro
Run ID: b52ae8d1-de02-4d36-8aec-bdf5149269f9
⛔ Files ignored due to path filters (1)
packages/sdk/js/src/v2/gen/types.gen.tsis excluded by!**/gen/**
📒 Files selected for processing (8)
packages/opencode/src/session/prompt.tspackages/opencode/src/session/status.tspackages/opencode/test/cli/tui/phase-label.tui-e2e.test.tspackages/opencode/test/fixture/pty-tui.tspackages/opencode/test/upstream/fork-feature-guards.test.tspackages/tui/src/component/prompt/index.tsxpackages/tui/src/context/sync.tsxpackages/tui/src/util/phase-label.ts
![kilo-code-bot[bot]](https://avatars.githubusercontent.com/in/2193792?s=60&v=4){kind=small}
| // The fallback assertion above is the load-bearing check; the specific | ||
| // labels are timing-sensitive (sub-millisecond spans + PTY polling | ||
| // interval). Not gated on hard equality. | ||
| expect(rendered).toContain("Thinking...") |
There was a problem hiding this comment.
SUGGESTION: This asserts only the "Thinking..." fallback, not the phase pipeline.
phaseLabel() returns "Thinking..." whenever phase() is undefined, so this assertion (and the waitForText on line 61) pass even if publishPhase → Bus.publish → GlobalBus → sync.tsx is entirely broken — the fallback renders during the busy window regardless of whether any phase event ever reaches the TUI. The specificLabels map (lines 65-71) captures whether a real label like "Discovering tools" fired, but it's only console.log'd, never asserted.
The PR description frames this e2e as catching "the exact class of runtime bug that unit tests + typecheck miss," yet a regression that drops phase publishing would still green here; the fork-feature-guards source-presence test is what actually guards the wiring today. Worth noting so reviewers don't over-trust this e2e for pipeline coverage. (Aware the specific spans are sub-ms vs the 50ms PTY poll, so a hard gate may flake — flagging the coverage gap, not prescribing a flaky assertion.)
Reply with @kilocode-bot fix it to have Kilo Code address this issue.
There was a problem hiding this comment.
Fair point, addressed in 6b41623. Added expect(rendered).toContain("Discovering tools") so a regression that drops publishPhase → Bus.publish → sync.tsx → store update anywhere in the chain would fail this test. The fork-guard test is still there as the belt-and-suspenders string-match check; this e2e now covers the pipeline behaviorally too, not just structurally.
Code Review SummaryStatus: No Issues Found | Recommendation: Merge The previous stuck-busy finding ( Files Reviewed (1 file)
Previous Review Summaries (2 snapshots, latest commit 6b41623)Current summary above is authoritative. Previous snapshots are kept for context only. Previous review (commit 6b41623)Status: 1 Issue Found | Recommendation: Address before merge Overview
Issue Details (click to expand)WARNING
Incremental pass — Files Reviewed (3 files)
Fix these issues in Kilo Cloud Previous review (commit 3fc64ff)Status: 1 Suggestion | Recommendation: Merge (1 non-blocking suggestion) Overview
Verification notesTraced the full event path before concluding the feature works: Issue Details (click to expand)SUGGESTION
Files Reviewed (9 files)
Reviewed by glm-5.2 · Input: 52.8K · Output: 20.5K · Cached: 615.8K Review guidance: REVIEW.md from base branch |
![cubic-dev-ai[bot]](https://avatars.githubusercontent.com/in/1082092?s=60&v=4){kind=small}
There was a problem hiding this comment.
3 issues found across 9 files
Prompt for AI agents (unresolved issues)
Check if these issues are valid — if so, understand the root cause of each and fix them. If appropriate, use sub-agents to investigate and fix each issue separately.
<file name="packages/opencode/src/session/prompt.ts">
<violation number="1" location="packages/opencode/src/session/prompt.ts:116">
P3: The `traceSpan` function publishes phase events for `bootstrap.session-get`, `bootstrap.config-get`, `bootstrap.fingerprint-detect`, `bootstrap.telemetry-init`, and `bootstrap.resolve-tools`. However, the parent `bootstrap` span emitted at `step === 1` (line 1148) does NOT publish a corresponding phase open/close event. This means the TUI phase label will show the last sub-phase (e.g. "bootstrap.resolve-tools") and then clear it when that sub-phase closes, even though the overall bootstrap window is still ongoing until the `bootstrap` parent span is emitted. There is no phase label covering the gap between the last sub-phase and the first `processor.process` call.</violation>
<violation number="2" location="packages/opencode/src/session/prompt.ts:122">
P2: Bootstrap failures have no parent `bootstrap` span, leaving failed pre-first-token runs without the waterfall interval this instrumentation is meant to expose. Emit the parent span from a `finally`/error path as well, with error status when setup aborts.</violation>
<violation number="3" location="packages/opencode/src/session/prompt.ts:125">
P2: First-generation traces omit time spent converting session history into model messages. Record the bootstrap span after `toModelMessages` has resolved (immediately before `processor.process` starts) so the claimed pre-generation interval is complete.</violation>
</file>
Reply with feedback, questions, or to request a fix.
Re-trigger cubic
| Tracer.active?.logSpan({ name, startTime, endTime: Date.now(), input }) | ||
| return result | ||
| } catch (e) { | ||
| Tracer.active?.logSpan({ |
There was a problem hiding this comment.
P2: Bootstrap failures have no parent bootstrap span, leaving failed pre-first-token runs without the waterfall interval this instrumentation is meant to expose. Emit the parent span from a finally/error path as well, with error status when setup aborts.
Prompt for AI agents
Check if this issue is valid — if so, understand the root cause and fix it. At packages/opencode/src/session/prompt.ts, line 122:
<comment>Bootstrap failures have no parent `bootstrap` span, leaving failed pre-first-token runs without the waterfall interval this instrumentation is meant to expose. Emit the parent span from a `finally`/error path as well, with error status when setup aborts.</comment>
<file context>
@@ -90,6 +90,50 @@ const STRUCTURED_OUTPUT_SYSTEM_PROMPT = `IMPORTANT: The user has requested struc
+ Tracer.active?.logSpan({ name, startTime, endTime: Date.now(), input })
+ return result
+ } catch (e) {
+ Tracer.active?.logSpan({
+ name,
+ startTime,
</file context>
There was a problem hiding this comment.
Same as the prior CodeRabbit round — addressed in 6b41623.
There was a problem hiding this comment.
Got it — this was already addressed in 6b41623, so the parent comment no longer applies.
| Tracer.active?.logSpan({ | ||
| name, | ||
| startTime, | ||
| endTime: Date.now(), |
There was a problem hiding this comment.
P2: First-generation traces omit time spent converting session history into model messages. Record the bootstrap span after toModelMessages has resolved (immediately before processor.process starts) so the claimed pre-generation interval is complete.
Prompt for AI agents
Check if this issue is valid — if so, understand the root cause and fix it. At packages/opencode/src/session/prompt.ts, line 125:
<comment>First-generation traces omit time spent converting session history into model messages. Record the bootstrap span after `toModelMessages` has resolved (immediately before `processor.process` starts) so the claimed pre-generation interval is complete.</comment>
<file context>
@@ -90,6 +90,50 @@ const STRUCTURED_OUTPUT_SYSTEM_PROMPT = `IMPORTANT: The user has requested struc
+ Tracer.active?.logSpan({
+ name,
+ startTime,
+ endTime: Date.now(),
+ status: "error",
+ input,
</file context>
There was a problem hiding this comment.
Same as the prior CodeRabbit round — addressed in 6b41623.
There was a problem hiding this comment.
Got it — the parent comment was already addressed in 6b41623, so it doesn’t apply here.
| sessionID?: SessionID, | ||
| ): Promise<T> { | ||
| const startTime = Date.now() | ||
| if (sessionID) void SessionStatus.publishPhase(sessionID, name, true) |
There was a problem hiding this comment.
P3: The traceSpan function publishes phase events for bootstrap.session-get, bootstrap.config-get, bootstrap.fingerprint-detect, bootstrap.telemetry-init, and bootstrap.resolve-tools. However, the parent bootstrap span emitted at step === 1 (line 1148) does NOT publish a corresponding phase open/close event. This means the TUI phase label will show the last sub-phase (e.g. "bootstrap.resolve-tools") and then clear it when that sub-phase closes, even though the overall bootstrap window is still ongoing until the bootstrap parent span is emitted. There is no phase label covering the gap between the last sub-phase and the first processor.process call.
Prompt for AI agents
Check if this issue is valid — if so, understand the root cause and fix it. At packages/opencode/src/session/prompt.ts, line 116:
<comment>The `traceSpan` function publishes phase events for `bootstrap.session-get`, `bootstrap.config-get`, `bootstrap.fingerprint-detect`, `bootstrap.telemetry-init`, and `bootstrap.resolve-tools`. However, the parent `bootstrap` span emitted at `step === 1` (line 1148) does NOT publish a corresponding phase open/close event. This means the TUI phase label will show the last sub-phase (e.g. "bootstrap.resolve-tools") and then clear it when that sub-phase closes, even though the overall bootstrap window is still ongoing until the `bootstrap` parent span is emitted. There is no phase label covering the gap between the last sub-phase and the first `processor.process` call.</comment>
<file context>
@@ -90,6 +90,50 @@ const STRUCTURED_OUTPUT_SYSTEM_PROMPT = `IMPORTANT: The user has requested struc
+ sessionID?: SessionID,
+ ): Promise<T> {
+ const startTime = Date.now()
+ if (sessionID) void SessionStatus.publishPhase(sessionID, name, true)
+ try {
+ const result = await fn()
</file context>
There was a problem hiding this comment.
Same as the prior CodeRabbit round — addressed in 6b41623.
There was a problem hiding this comment.
The parent comment was already addressed in 6b41623, so it no longer applies here.
Three review findings from CodeRabbit + Kilo + cubic addressed:
1. **Enter busy state before publishing bootstrap phases** (prompt.ts).
Previously the TUI renders phase labels only while `status.type === "busy"`,
but `SessionStatus.set(..., "busy")` fired at line 506 inside the
while-loop — *after* the bootstrap traceSpan calls at lines 411-431.
Early bootstrap labels ("Loading session...", "Loading config...",
"Preparing telemetry...", "Detecting project shape...") were never
visible; only `bootstrap.resolve-tools` at step===1 fired within the
busy window. Set busy immediately at the top of `loop()` so all
bootstrap phases render. The existing set inside the while-loop is
preserved as a busy → busy no-op for entry paths that don't come
through session start.
2. **Publish EventV2 Phase alongside legacy** (status.ts). `publishPhase`
previously only mirrored to `LegacyEvent.Phase` (the SSE bus the TUI
subscribes to). V2 subscribers never saw phase updates. Added
`publishPhase` to the Service interface + Layer implementation so
`Event.Phase` is published through the EventV2 bridge alongside the
legacy bus event. Matches the pattern used by `set()`.
3. **Use tmpdir fixture + assert a mapped phase label** (e2e test).
Replaced manual `mkdtempSync` + finally-block cleanup with
`await using tmp = await tmpdir()` — matches the codebase convention
(scheduler.test.ts and the coding guideline in CONTRIBUTING.md) and
handles the case where launchTui rejects before the try block.
Added a hard `expect(rendered).toContain("Discovering tools")`
assertion — the previous single fallback assertion would pass even
if the entire phase-event pipeline was broken (because the fallback
renders whenever status is busy). "Discovering tools" is the label
for `bootstrap.resolve-tools`; its span duration (MCP tool listing)
is reliably longer than the PTY poll interval, so this is safe from
flake. Diagnostic dump of the other timing-sensitive labels retained.
Local validation
- Typecheck clean across `@altimateai/altimate-code`.
- Session + fork-guards: 67 pass / 0 fail (18 fork-guards including
the AI-7519 pipeline guard).
- Rebuilt binary + re-ran the tightened e2e — both hard assertions
pass; specific-label hits: "Discovering tools" ✓, others sub-ms.
Skipped
- Cubic's duplicates of CodeRabbit findings — same items, addressed.
Co-Authored-By: Claude Opus 4.7 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01Q8FGy89Qpr39k8nCSpCcK2
|
👋 This PR was automatically closed by our quality checks. Common reasons:
If you believe this was a mistake, please open an issue explaining your intended contribution and a maintainer will help you. |
1 similar comment
|
👋 This PR was automatically closed by our quality checks. Common reasons:
If you believe this was a mistake, please open an issue explaining your intended contribution and a maintainer will help you. |
|
Thanks for updating your PR! It now meets our contributing guidelines. 👍 |
There was a problem hiding this comment.
All reported issues were addressed across 3 files (changes from recent commits).
Reply with feedback, questions, or to request a fix.
Re-trigger cubic
| // a label. The while-loop re-set below is now a no-op busy → busy | ||
| // transition, preserved for legacy call sites that may enter the | ||
| // loop from elsewhere. | ||
| await SessionStatus.set(sessionID, { type: "busy" }) |
There was a problem hiding this comment.
WARNING: A bootstrap failure here leaves the session permanently stuck in "busy" with no idle/error transition.
Setting busy before the un-wrapped bootstrap calls (Session.get / Config.get / Telemetry.init at lines 421–441) creates a status obligation the cleanup path doesn't discharge. Those calls aren't individually caught, and traceSpan re-throws on error (prompt.ts:130). If any of them throws, the error propagates out of loop(), so the defer(() => cancel(sessionID)) at line 397 runs. But cancel() (prompt.ts:364) deliberately does not set idle when the session entry still exists — it relies on "the processor's catch block," which doesn't exist yet during bootstrap. The route caller has no catch either (session.ts:650). Net result: SessionStatus keeps { type: "busy" } for that sessionID with nothing to clear it, so the TUI spinner stays stuck and any caller that gates new prompts on status.type === "busy" would also be blocked.
Consider wrapping the early busy set + bootstrap spans in a try/catch that resets to idle on failure (e.g. finally/catch that re-throws after await SessionStatus.set(sessionID, { type: "idle" })), so a bootstrap throw transitions out of busy.
Reply with @kilocode-bot fix it to have Kilo Code address this issue.
dev-punia-altimate
left a comment
dev-punia-altimate
left a comment
There was a problem hiding this comment.
🤖 Code Review — OpenCodeReview (Gemini) — 6 finding(s)
- 6 anchored to a line (posted inline when the comment stream is on)
- 0 without a line anchor
All findings (full text)
1. packages/opencode/src/session/status.ts (L194-L203)
[🟠 MEDIUM] The two publish operations are independent and can be executed concurrently to improve performance. You can use Promise.allSettled to run them in parallel, which also inherently satisfies the requirement of safely swallowing any potential failures without needing explicit try...catch blocks.
Suggested change:
// Best-effort publish: run concurrently and intentionally swallow any failures
// so they never surface back to the caller.
await Promise.allSettled([
runStatus((s) => s.publishPhase(sessionID, phase, active)),
Bus.publish(LegacyEvent.Phase, { sessionID, phase, active })
])
2. packages/opencode/test/fixture/pty-tui.ts (L141-L147)
[🟠 MEDIUM] Applying stripAnsi individually to each incoming data chunk can cause issues. Terminal streams can arbitrarily split ANSI escape sequences across chunk boundaries (e.g., \x1b[ in one chunk and 31m in the next). In such cases, stripAnsi will fail to recognize and strip partial sequences, causing raw ANSI characters to leak permanently into the stripped string, leading to flaky waitForText assertions.
It is safer to accumulate the raw text and apply stripAnsi(raw) dynamically when text() or waitForText() is called.
Suggested change:
let raw = ""
child.onData((data) => {
const chunk = data.toString()
raw += chunk
})
3. packages/opencode/test/fixture/pty-tui.ts (L177-L180)
[🟠 MEDIUM] When the needle parameter is a RegExp, it is evaluated via needle.test(s) inside a polling loop. If a regular expression is provided with the global (g) flag, the test() method becomes stateful and advances its internal lastIndex property upon a match. Repeated calls on the same text inside the loop will unexpectedly return false on subsequent iterations, causing tests to fail randomly.
Ensure regular expressions are evaluated statelessly (e.g., resetting needle.lastIndex = 0 before testing, or using s.match(needle)).
Suggested change:
async waitForText(needle, waitOpts) {
const timeoutMs = waitOpts?.timeoutMs ?? DEFAULT_WAIT_TIMEOUT_MS
const deadline = Date.now() + timeoutMs
const matches = (s: string) => {
if (typeof needle === "string") return s.includes(needle)
needle.lastIndex = 0
return needle.test(s)
}
4. packages/opencode/test/fixture/pty-tui.ts (L181-L185)
[🟠 MEDIUM] The polling loop waits until timeoutMs expires or the expected text is matched, but it does not check if the spawned TUI child process has exited. If the application crashes or exits prematurely before rendering the expected text, the test will hang and blindly poll until the timeout is reached. This drastically slows down test feedback and masks the root cause of the crash.
Consider incorporating an early exit condition, for example by tracking an isExited flag set in child.onExit and checking it inside this loop.
5. packages/opencode/src/session/prompt.ts (L988-L991)
[🔵 LOW] The trace span name is hardcoded to "bootstrap.resolve-tools". As the comment above indicates, this function is executed not only during the initial bootstrap (step === 1) but also on subsequent turns. Reusing the "bootstrap." prefix for non-bootstrap turns may pollute telemetry data, inflating the apparent frequency of bootstrap operations and distorting latency metrics.
Consider using a dynamic name based on the step to distinguish the initial tool discovery phase from subsequent per-turn overhead. This will correctly fall back to the safe "Thinking..." TUI phase label for subsequent turns.
Suggested change:
const tools = await traceSpan(
step === 1 ? "bootstrap.resolve-tools" : "turn.resolve-tools",
() =>
resolveTools({
6. packages/opencode/src/session/prompt.ts (L1157-L1166)
[🔵 LOW] Calling Date.now() twice consecutively can result in a mismatch between endTime and duration_ms if the clock ticks between the two calls. It is more reliable to capture the time in a local variable to ensure precision and consistency.
Suggested change:
const endTime = Date.now()
Tracer.active?.logSpan({
name: "bootstrap",
startTime: bootstrapStart,
endTime,
input: { agent: agent.name, sessionID },
output: {
duration_ms: endTime - bootstrapStart,
system_parts: system.length,
},
})
| try { | ||
| await runStatus((s) => s.publishPhase(sessionID, phase, active)) | ||
| } catch { | ||
| // never surface phase-publish failures back to the caller | ||
| } | ||
| try { | ||
| await Bus.publish(LegacyEvent.Phase, { sessionID, phase, active }) | ||
| } catch { | ||
| // never surface phase-publish failures back to the caller | ||
| } |
There was a problem hiding this comment.
[🟠 MEDIUM] The two publish operations are independent and can be executed concurrently to improve performance. You can use Promise.allSettled to run them in parallel, which also inherently satisfies the requirement of safely swallowing any potential failures without needing explicit try...catch blocks.
Suggested change:
| try { | |
| await runStatus((s) => s.publishPhase(sessionID, phase, active)) | |
| } catch { | |
| // never surface phase-publish failures back to the caller | |
| } | |
| try { | |
| await Bus.publish(LegacyEvent.Phase, { sessionID, phase, active }) | |
| } catch { | |
| // never surface phase-publish failures back to the caller | |
| } | |
| // Best-effort publish: run concurrently and intentionally swallow any failures | |
| // so they never surface back to the caller. | |
| await Promise.allSettled([ | |
| runStatus((s) => s.publishPhase(sessionID, phase, active)), | |
| Bus.publish(LegacyEvent.Phase, { sessionID, phase, active }) | |
| ]) |
There was a problem hiding this comment.
Legit concern but deferred — an initial attempt at Promise.allSettled caused an e2e regression I couldn't cleanly attribute. Wants a proper investigation of runStatus Layer/Effect concurrency semantics before I ship the change on the hot path. Tracking to revisit.
| let raw = "" | ||
| let stripped = "" | ||
| child.onData((data) => { | ||
| const chunk = data.toString() | ||
| raw += chunk | ||
| stripped += stripAnsi(chunk) | ||
| }) |
There was a problem hiding this comment.
[🟠 MEDIUM] Applying stripAnsi individually to each incoming data chunk can cause issues. Terminal streams can arbitrarily split ANSI escape sequences across chunk boundaries (e.g., \x1b[ in one chunk and 31m in the next). In such cases, stripAnsi will fail to recognize and strip partial sequences, causing raw ANSI characters to leak permanently into the stripped string, leading to flaky waitForText assertions.
It is safer to accumulate the raw text and apply stripAnsi(raw) dynamically when text() or waitForText() is called.
Suggested change:
| let raw = "" | |
| let stripped = "" | |
| child.onData((data) => { | |
| const chunk = data.toString() | |
| raw += chunk | |
| stripped += stripAnsi(chunk) | |
| }) | |
| let raw = "" | |
| child.onData((data) => { | |
| const chunk = data.toString() | |
| raw += chunk | |
| }) |
There was a problem hiding this comment.
Legit chunk-boundary concern in theory. Deferred — current per-chunk stripAnsi has been reliable across our tests, and switching text() from an O(1) memoized string to an O(n) computation is a semantic change I'd want its own review + coverage for.
| async waitForText(needle, waitOpts) { | ||
| const timeoutMs = waitOpts?.timeoutMs ?? DEFAULT_WAIT_TIMEOUT_MS | ||
| const deadline = Date.now() + timeoutMs | ||
| const matches = (s: string) => (typeof needle === "string" ? s.includes(needle) : needle.test(s)) |
There was a problem hiding this comment.
[🟠 MEDIUM] When the needle parameter is a RegExp, it is evaluated via needle.test(s) inside a polling loop. If a regular expression is provided with the global (g) flag, the test() method becomes stateful and advances its internal lastIndex property upon a match. Repeated calls on the same text inside the loop will unexpectedly return false on subsequent iterations, causing tests to fail randomly.
Ensure regular expressions are evaluated statelessly (e.g., resetting needle.lastIndex = 0 before testing, or using s.match(needle)).
Suggested change:
| async waitForText(needle, waitOpts) { | |
| const timeoutMs = waitOpts?.timeoutMs ?? DEFAULT_WAIT_TIMEOUT_MS | |
| const deadline = Date.now() + timeoutMs | |
| const matches = (s: string) => (typeof needle === "string" ? s.includes(needle) : needle.test(s)) | |
| async waitForText(needle, waitOpts) { | |
| const timeoutMs = waitOpts?.timeoutMs ?? DEFAULT_WAIT_TIMEOUT_MS | |
| const deadline = Date.now() + timeoutMs | |
| const matches = (s: string) => { | |
| if (typeof needle === "string") return s.includes(needle) | |
| needle.lastIndex = 0 | |
| return needle.test(s) | |
| } |
There was a problem hiding this comment.
Applied in 762ac7c. Pure defensive — our current specs don't use /g so nothing changes today, but future callers won't need to know the gotcha.
| if (matches(stripped)) return | ||
| while (Date.now() < deadline) { | ||
| await new Promise((r) => setTimeout(r, POLL_INTERVAL_MS)) | ||
| if (matches(stripped)) return | ||
| } |
There was a problem hiding this comment.
[🟠 MEDIUM] The polling loop waits until timeoutMs expires or the expected text is matched, but it does not check if the spawned TUI child process has exited. If the application crashes or exits prematurely before rendering the expected text, the test will hang and blindly poll until the timeout is reached. This drastically slows down test feedback and masks the root cause of the crash.
Consider incorporating an early exit condition, for example by tracking an isExited flag set in child.onExit and checking it inside this loop.
There was a problem hiding this comment.
Applied in 762ac7c. Poll loop now breaks on child exit with a distinct 'child exit before match' error message so a crash surfaces in seconds instead of burning the full 8s timeout.
| const tools = await traceSpan( | ||
| "bootstrap.resolve-tools", | ||
| () => | ||
| resolveTools({ |
There was a problem hiding this comment.
[🔵 LOW] The trace span name is hardcoded to "bootstrap.resolve-tools". As the comment above indicates, this function is executed not only during the initial bootstrap (step === 1) but also on subsequent turns. Reusing the "bootstrap." prefix for non-bootstrap turns may pollute telemetry data, inflating the apparent frequency of bootstrap operations and distorting latency metrics.
Consider using a dynamic name based on the step to distinguish the initial tool discovery phase from subsequent per-turn overhead. This will correctly fall back to the safe "Thinking..." TUI phase label for subsequent turns.
Suggested change:
| const tools = await traceSpan( | |
| "bootstrap.resolve-tools", | |
| () => | |
| resolveTools({ | |
| const tools = await traceSpan( | |
| step === 1 ? "bootstrap.resolve-tools" : "turn.resolve-tools", | |
| () => | |
| resolveTools({ |
There was a problem hiding this comment.
Legit telemetry hygiene, ternary logic looks correct on paper (step===1 fires before resolveTools at line 583). But when I applied it the e2e stopped seeing 'Discovering tools' — couldn't confirm the label reliably survives on the boundary. Deferred for a focused pass so I don't regress the label rendering here.
| Tracer.active?.logSpan({ | ||
| name: "bootstrap", | ||
| startTime: bootstrapStart, | ||
| endTime: Date.now(), | ||
| input: { agent: agent.name, sessionID }, | ||
| output: { | ||
| duration_ms: Date.now() - bootstrapStart, | ||
| system_parts: system.length, | ||
| }, | ||
| }) |
There was a problem hiding this comment.
[🔵 LOW] Calling Date.now() twice consecutively can result in a mismatch between endTime and duration_ms if the clock ticks between the two calls. It is more reliable to capture the time in a local variable to ensure precision and consistency.
Suggested change:
| Tracer.active?.logSpan({ | |
| name: "bootstrap", | |
| startTime: bootstrapStart, | |
| endTime: Date.now(), | |
| input: { agent: agent.name, sessionID }, | |
| output: { | |
| duration_ms: Date.now() - bootstrapStart, | |
| system_parts: system.length, | |
| }, | |
| }) | |
| const endTime = Date.now() | |
| Tracer.active?.logSpan({ | |
| name: "bootstrap", | |
| startTime: bootstrapStart, | |
| endTime, | |
| input: { agent: agent.name, sessionID }, | |
| output: { | |
| duration_ms: endTime - bootstrapStart, | |
| system_parts: system.length, | |
| }, | |
| }) |
There was a problem hiding this comment.
Applied in 762ac7c. Cleaner math and duration_ms is now guaranteed to match endTime - startTime.
Kilo caught a follow-on issue from the busy-before-bootstrap change in 6b41623: if any bootstrap traceSpan throws (Session.get / Config.get / Fingerprint.detect / Telemetry.init), cancel() runs via defer but deliberately does not set idle when the session state entry still exists — it relies on the processor's catch block for that. During bootstrap the processor hasn't taken over yet, so a throw would leave the session permanently `busy` with no idle/error transition — TUI spinner stuck, busy-gated callers blocked. Wrap the four bootstrap traceSpan calls in a try/catch that best-effort transitions to idle before rethrowing, so any bootstrap failure exits the busy window cleanly. Co-Authored-By: Claude Opus 4.7 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01Q8FGy89Qpr39k8nCSpCcK2
|
👋 This PR was automatically closed by our quality checks. Common reasons:
If you believe this was a mistake, please open an issue explaining your intended contribution and a maintainer will help you. |
🤖 Code Review — OpenCodeReview (Gemini) — No Issues FoundNo comments generated. Looks good to me. |
Dev-punia bot flagged 6 items. Audited each; applying only the 3 that are legitimate improvements AND won't affect runtime behavior: - **pty-tui.ts waitForText — reset RegExp.lastIndex before test** (finding 3). Pure defensive fix. A RegExp with the `/g` flag has stateful `.test()` — repeat calls on the same string return false after the first match. Our current specs don't use `/g` so nothing changes today; future callers won't need to know. - **pty-tui.ts waitForText — fail fast on child exit** (finding 4). Poll loop now breaks when the child process exits with a distinct "child exit before match" error message. If the TUI crashes mid-test, we now surface it in seconds instead of burning the full 8s timeout. - **prompt.ts bootstrap span — capture endTime once** (finding 6). Two Date.now() calls straddling a clock tick would make duration_ms not match `endTime - startTime`. Trivial fix, cleaner math. Deferred (need investigation before applying): - Finding 1 (Promise.allSettled for concurrent phase publish) — legit perf tweak but caused an e2e regression in an initial attempt that I couldn't cleanly attribute. Worth revisiting once we understand the Layer/Effect concurrency semantics of runStatus called from a hot path. - Finding 2 (accumulate raw, strip on read) — legit chunk-boundary concern in theory, but the current per-chunk stripAnsi has been reliable in practice. Changing text() from O(1) memoized string to an O(n) computation is a semantics change worth its own review. - Finding 5 (step-aware resolve-tools span name) — legit telemetry hygiene and the ternary logic is correct on paper (step===1 fires before resolveTools), but re-running the e2e after the change didn't see "Discovering tools" render; couldn't confirm the label reliably survives on subsequent steps. Deferred for a focused pass. Local validation - Typecheck clean. - Session + fork-guards: 806 pass / 0 fail / 12 skip / 45 todo. - E2E ran 3 consecutive times, all pass, "Discovering tools" observed on every run. Co-Authored-By: Claude Opus 4.7 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01Q8FGy89Qpr39k8nCSpCcK2
|
👋 This PR was automatically closed by our quality checks. Common reasons:
If you believe this was a mistake, please open an issue explaining your intended contribution and a maintainer will help you. |
2 participants
Issue for this PR
Closes AI-7519 in Jira: Investigate first-answer latency via session traces — target <10s to first visible response.
Type of change
What does this PR do?
Two-halves fix for AI-7519.
Investigate half (make the invisible time visible). On a 6-table Jaffle test project the first answer takes ~4 minutes end-to-end. Session traces show tool spans only in ms/seconds — meaning the dominant time sink is not in any span at all. Corpus analysis over 86 traces confirmed:
I fixed the first cause by wrapping the awaits inside
SessionPrompt.loop()with a newtraceSpan(name, fn, input, sessionID)helper. That helper does two things per await: emit aTracer.logSpanentry (fixes the invisible waterfall gap) and publish asession.phasebus event (start on entry, end on exit). Wrapped:Session.get,Config.get,Fingerprint.detect,Telemetry.init,resolveTools. Also emits a parentbootstrapspan on step===1 coveringloop()entry → firstprocessor.process.SLO half (<10s to first visible response). The same phase events feed the TUI's status renderer, which now shows an honest label next to the busy spinner: "Loading session..." → "Loading config..." → "Discovering tools..." → "Thinking..." fallback. The user sees what the agent is doing during the invisible window instead of a silent spinner. Label copy convention matches Cursor / Claude Code / Codex CLI.
Not in scope (deferred to follow-up tickets):
generationspan intoreq-build/req-network/stream. Biggest attribution win on the 455s per-turn gap the multi-turn Jaffle repro surfaced, but touches the LLM stream layer.How did you verify your code works?
@opencode-ai/plugin,@opencode-ai/tui,@altimateai/altimate-code.test/session/*+test/altimate/tracing-e2e.test.ts.0.0.0-feat/AI-7519-first-answer-latency-*.bootstrapspan firing at the expected offsets (all 5 within +0.56s of session start;bootstrap.resolve-toolsalso fires per-turn later).phase-label.tui-e2e.test.ts): launches the built binary, submits a prompt, asserts specific mapped label ("Discovering tools") AND the "Thinking..." fallback both render in the actual stripped terminal output. This catches the exact class of runtime bug that unit tests + typecheck miss — same reasoning as the AI-6298 fix.6b4162399— busy-before-bootstrap ordering, V2 phase publish, tmpdir fixture + tighter e2e assertion.Screenshots / recordings
Screen recording attached to the AI-7519 Jira ticket showing the "Discovering tools..." → "Thinking..." labels rendering beside the busy spinner during a fresh session against a Jaffle checkout.
Checklist
🤖 Generated with Claude Code
https://claude.ai/code/session_01Q8FGy89Qpr39k8nCSpCcK2
Summary by CodeRabbit
phaseLabelhelper with a default fallback of “Thinking...” when no phase is available.session.phaseeventing end-to-end with legacy event mirroring so the label updates in real time.