fix(call-omo-agent): fail fast on lost prompts
Detect OpenCode promptAsync calls that return before a child session has any durable message, and surface a prompt acceptance error before the generic five-minute sync poll timeout. Add a failing-first regression for the idle zero-message case and keep the existing durable-message completion path covered. Debugging-Journal: .debugging
This commit is contained in:
YeonGyu-Kim
+134
@@ -52,3 +52,137 @@
|
||||
2. Check opencode logs for hanging requests
|
||||
3. Create a reproduction test
|
||||
4. Fix the root cause
|
||||
|
||||
---
|
||||
|
||||
# Debugging Journal — 2026-05-17 gpt 5.5 xhigh Run
|
||||
|
||||
Started: 2026-05-17T13:34:00+09:00
|
||||
Goal: Debug and fix the prompt hang/race between sibling `opencode` and `omo` with failing-first tests, manual QA, clean PR, CI pass, and Cubic pass.
|
||||
|
||||
## Environment Snapshot
|
||||
|
||||
- Runtime: Bun 1.3.12, Node v26.0.0
|
||||
- OMO worktree: `/Users/yeongyu/local-workspaces/gpt 5.5 xhigh`
|
||||
- OMO branch: `code-yeongyu/fix-prompt-hang-race`
|
||||
- Base: `origin/dev` at `75223149d`
|
||||
- Sibling OpenCode repo: `/Users/yeongyu/local-workspaces/opencode`
|
||||
- Debug ports checked: 9229, 9230
|
||||
- References read:
|
||||
- `/Users/yeongyu/.agents/skills/debugging/SKILL.md`
|
||||
- `/Users/yeongyu/.agents/skills/debugging/references/runtimes/node.md`
|
||||
- `/Users/yeongyu/.agents/skills/debugging/references/methodology/00-setup.md`
|
||||
- `/Users/yeongyu/.agents/skills/debugging/references/methodology/02-investigate.md`
|
||||
- `/Users/yeongyu/local-workspaces/omo/.agents/skills/work-with-pr/SKILL.md`
|
||||
- `/Users/yeongyu/.agents/skills/git-master/SKILL.md`
|
||||
|
||||
## Hypotheses
|
||||
|
||||
1. [OPEN] OpenCode `promptAsync` can resolve before the prompt is durably accepted, then a later `session.error` leaves OMO believing dispatch succeeded while no live parent turn will complete. Distinguishing evidence: OpenCode handler response path returns before durable session acceptance, and OMO currently releases or retains reservations in a way that allows an orphaned dispatch.
|
||||
2. [OPEN] OMO has at least one raw `session.prompt` or `session.promptAsync` route outside `src/shared/prompt-async-gate.ts`, allowing concurrent idle/error/completion hooks to inject multiple internal prompts or hang one behind another. Distinguishing evidence: raw call sites outside the shared gate or a static invariant test gap.
|
||||
3. [OPEN] The shared prompt gate does not bound the full dispatch lifecycle correctly when the underlying SDK fetch never resolves, leaving duplicate-injection state or optimistic loop state stuck forever. Distinguishing evidence: a failing test where unresolved `promptAsync` blocks or leaks reservation/task state past the expected timeout path.
|
||||
4. [OPEN] Sibling `opencode` changed event/session semantics in a way that makes previous OMO idle-settle assumptions too weak. Distinguishing evidence: event/prompt implementation or tests in `../opencode` showing an accepted response can be followed by async prompt rejection/error edge.
|
||||
|
||||
## Artifacts To Revert Or Preserve
|
||||
|
||||
- [ ] `/Users/yeongyu/local-workspaces/gpt 5.5 xhigh` — temporary worktree. Remove after merged PR with `git worktree remove`.
|
||||
- [ ] Branch `code-yeongyu/fix-prompt-hang-race` — temporary PR branch. Delete via PR squash merge or `git branch -D` only after safe cleanup.
|
||||
- [ ] `.debugging` — journal update requested by user. Preserve unless final cleanup requires restoring debug-only notes.
|
||||
- [ ] `src/tools/call-omo-agent/completion-poller.test.ts` — failing-first regression for 204-without-durable-message prompt acceptance. Preserve as product test.
|
||||
- [ ] `src/tools/call-omo-agent/completion-poller.ts` — minimal prompt acceptance timeout fix. Preserve as product fix.
|
||||
- [ ] `evidence/` — local QA/test output. Remove before final commit unless intentionally ignored.
|
||||
- [ ] tmux session `ulw-qa-call-omo-agent` if created. Kill only this session, never the tmux server.
|
||||
- [ ] `/tmp/ulw-call-omo-agent-qa.ts` — temporary tmux manual QA script. Remove after QA.
|
||||
|
||||
## Findings
|
||||
|
||||
### 2026-05-17T13:47:00+09:00 — OpenCode promptAsync is not durable acceptance
|
||||
- Source: `/Users/yeongyu/local-workspaces/opencode/packages/opencode/src/server/routes/instance/httpapi/handlers/session.ts:295-314`
|
||||
- Value: `promptAsync` forks `promptSvc.prompt({ ...ctx.payload, sessionID })` with `Effect.forkIn(scope, { startImmediately: true })` and then returns `HttpApiSchema.NoContent.make()`.
|
||||
- Interpretation: OMO can receive 204 before OpenCode persists the user message or enters the busy run loop.
|
||||
- Confirms: H1 and H4.
|
||||
|
||||
### 2026-05-17T13:48:00+09:00 — OpenCode can fail before user-message persistence
|
||||
- Source: `/Users/yeongyu/local-workspaces/opencode/packages/opencode/src/session/prompt.ts:1092-1101`
|
||||
- Value: `createUserMessage` publishes `Session.Event.Error` and throws when an agent name is not found, before `sessions.updateMessage(info)`.
|
||||
- Interpretation: a forked promptAsync attempt can later error while `session.messages()` still returns zero messages.
|
||||
- Confirms: H1.
|
||||
|
||||
### 2026-05-17T13:49:00+09:00 — OMO sync child poller waits on zero durable messages
|
||||
- Source: `src/tools/call-omo-agent/completion-poller.ts:25-63`
|
||||
- Value: loop treats idle with `currentMsgCount === 0` as not complete and only exits at `MAX_POLL_TIME_MS` with `Agent task timed out after 5 minutes.`
|
||||
- Interpretation: when promptAsync returns 204 but OpenCode fails before persisting the user message, OMO waits for the generic five-minute poll timeout instead of surfacing prompt acceptance failure promptly.
|
||||
- Confirms: H1; refutes H2 for this hang because production prompt routes are gate-routed.
|
||||
|
||||
## Root Cause (confirmed 2026-05-17T13:56:00+09:00)
|
||||
|
||||
- Mechanism: OpenCode `session.promptAsync` returns 204 after forking the real prompt, so OMO's sync child prompt path can begin polling before the user message is durably written. If the forked OpenCode prompt fails before `sessions.updateMessage(info)`, status remains idle or absent and `session.messages()` stays empty. `call_omo_agent` then waits for the generic five-minute poll timeout because zero messages never satisfy the stable-message completion condition.
|
||||
- Evidence: `/Users/yeongyu/local-workspaces/opencode/packages/opencode/src/server/routes/instance/httpapi/handlers/session.ts:295-314`, `/Users/yeongyu/local-workspaces/opencode/packages/opencode/src/session/prompt.ts:1092-1101`, `src/tools/call-omo-agent/completion-poller.ts:25-63`, and red test output in `evidence/task-2-red.txt`.
|
||||
- Toggle proof: with the pre-fix poller, the red test receives `Agent task timed out after 5 minutes.` With the acceptance-timeout guard, the same simulated OpenCode 204-without-message sequence receives `Prompt was not durably accepted by OpenCode for session ses-undurable.`
|
||||
- Fix scope: `src/tools/call-omo-agent/completion-poller.ts` and `src/tools/call-omo-agent/completion-poller.test.ts`.
|
||||
|
||||
### Red phase (2026-05-17T13:53:00+09:00)
|
||||
- Test: `src/tools/call-omo-agent/completion-poller.test.ts`
|
||||
- Command: `bun test src/tools/call-omo-agent/completion-poller.test.ts --bail`
|
||||
- Output: `Expected substring: "Prompt was not durably accepted by OpenCode"; Received message: "Agent task timed out after 5 minutes."`
|
||||
|
||||
### Green phase (2026-05-17T13:55:00+09:00)
|
||||
- Fix: `src/tools/call-omo-agent/completion-poller.ts` tracks whether any active status was observed and fails after 30s of idle zero-message polling before the generic five-minute timeout.
|
||||
- Test: `bun test src/tools/call-omo-agent/completion-poller.test.ts --bail` passes with 2 tests.
|
||||
- Adjacent checks:
|
||||
- `bun test src/tools/call-omo-agent/sync-executor.test.ts src/tools/call-omo-agent/sync-executor-leak.test.ts src/tools/call-omo-agent/completion-poller.test.ts --bail` passes with 23 tests.
|
||||
- `bun test src/hooks/shared/prompt-async-gate.test.ts src/shared/prompt-async-route-audit.test.ts --bail` passes with 20 tests.
|
||||
|
||||
### Manual QA — tmux sync prompt poller (2026-05-17T14:03:00+09:00)
|
||||
- Scenario: run the real `waitForCompletion` implementation in a tmux session with an OpenCode-like client that reports idle status and zero messages after promptAsync acceptance.
|
||||
- Command: `tmux new-session -d -s ulw-qa-call-omo-agent ... bun /tmp/ulw-call-omo-agent-qa.ts`
|
||||
- Observed output: `Prompt was not durably accepted by OpenCode for session ses_qa.`
|
||||
- Expected output: prompt acceptance failure appears promptly instead of generic five-minute timeout.
|
||||
- Fix verified: yes.
|
||||
- Cleanup: tmux session `ulw-qa-call-omo-agent` removed; `/tmp/ulw-call-omo-agent-qa.ts` removed.
|
||||
|
||||
## Scenario Notes
|
||||
|
||||
- Path: `/var/folders/nj/hqfr8ndn5q56cqw7jqgbrck40000gn/T/ulw-scenarios.XXXXXX.md.QVTvXtyXKK`
|
||||
|
||||
## Final Validation (2026-05-17T14:15:00+09:00)
|
||||
|
||||
- Focused regression:
|
||||
- `bun test src/tools/call-omo-agent/completion-poller.test.ts --bail`
|
||||
- Result: 2 pass, 0 fail.
|
||||
- Adjacent call_omo_agent:
|
||||
- `bun test src/tools/call-omo-agent/sync-executor.test.ts src/tools/call-omo-agent/sync-executor-leak.test.ts src/tools/call-omo-agent/completion-poller.test.ts --bail`
|
||||
- Result: 23 pass, 0 fail.
|
||||
- Prompt gate invariant:
|
||||
- `bun test src/hooks/shared/prompt-async-gate.test.ts src/shared/prompt-async-route-audit.test.ts --bail`
|
||||
- Result: 20 pass, 0 fail.
|
||||
- Combined focused suite:
|
||||
- `bun test src/tools/call-omo-agent/completion-poller.test.ts src/tools/call-omo-agent/sync-executor.test.ts src/tools/call-omo-agent/sync-executor-leak.test.ts src/hooks/shared/prompt-async-gate.test.ts src/shared/prompt-async-route-audit.test.ts --bail`
|
||||
- Result: 43 pass, 0 fail.
|
||||
- TypeScript quality:
|
||||
- `bun --install=fallback /Users/yeongyu/.config/opencode/skills/typescript-programmer/scripts/check-no-excuse-rules.ts src/tools/call-omo-agent/completion-poller.ts src/tools/call-omo-agent/completion-poller.test.ts`
|
||||
- Result: no no-excuse violations.
|
||||
- Typecheck:
|
||||
- `bun run typecheck`
|
||||
- Result: pass.
|
||||
- Build:
|
||||
- `bun run build`
|
||||
- Result: pass.
|
||||
- Full suite in required worktree path:
|
||||
- `bun test`
|
||||
- Result: fail with 99 failures caused by Bun/test harness dynamic imports from an encoded path such as `/Users/yeongyu/local-workspaces/gpt%205.5%20xhigh/...`.
|
||||
- Interpretation: path-space-specific validation failure, not a product regression from this patch. Single-file reproduction: `bun test src/shared/load-opencode-plugins.test.ts --bail` fails before test logic with `Cannot find module '/Users/yeongyu/local-workspaces/gpt%205.5%20xhigh/src/shared/load-opencode-plugins.ts?...'`.
|
||||
- Full suite in no-space validation worktree with the same patch:
|
||||
- Validation worktree: `/tmp/omo-ci-validation.9lEM4g`
|
||||
- `bun install --frozen-lockfile && bun test`
|
||||
- Result: 7014 pass, 1 skip, 0 fail across 724 files.
|
||||
- Cleanup: validation worktree removed with `git worktree remove --force /tmp/omo-ci-validation.9lEM4g`.
|
||||
|
||||
## Final Status Before PR
|
||||
|
||||
- Product behavior change: only `call_omo_agent` sync polling now fails fast when OpenCode never durably accepts a prompt after returning from `promptAsync`.
|
||||
- Behavior preserved:
|
||||
- Durable message completion still requires stable idle message count.
|
||||
- Busy/non-idle child sessions continue polling as before.
|
||||
- Existing shared `promptAsync` gate and raw-prompt audit are unchanged and green.
|
||||
- Remaining gates: commit, PR, GitHub CI, Cubic review, PR merge, final requested worktree cleanup.
|
||||
|
||||
@@ -0,0 +1,105 @@
|
||||
import { describe, expect, mock, test } from "bun:test"
|
||||
|
||||
import { waitForCompletion } from "./completion-poller"
|
||||
|
||||
function createToolContext(): Parameters<typeof waitForCompletion>[1] {
|
||||
return {
|
||||
sessionID: "parent-session",
|
||||
messageID: "parent-message",
|
||||
agent: "sisyphus",
|
||||
abort: new AbortController().signal,
|
||||
metadata: mock(() => {}),
|
||||
}
|
||||
}
|
||||
|
||||
function createContext(args: {
|
||||
status: ReturnType<typeof mock>
|
||||
messages: ReturnType<typeof mock>
|
||||
}): Parameters<typeof waitForCompletion>[2] {
|
||||
return {
|
||||
client: {
|
||||
session: {
|
||||
status: args.status,
|
||||
messages: args.messages,
|
||||
},
|
||||
},
|
||||
} as never
|
||||
}
|
||||
|
||||
describe("waitForCompletion", () => {
|
||||
test("#given promptAsync returned before OpenCode saved a user message #when the child session stays idle with zero messages #then it fails as a prompt acceptance error", async () => {
|
||||
// given
|
||||
const originalDateNow = Date.now
|
||||
const originalSetTimeout = globalThis.setTimeout
|
||||
let currentTime = 0
|
||||
Date.now = () => {
|
||||
currentTime += 60_000
|
||||
return currentTime
|
||||
}
|
||||
globalThis.setTimeout = ((handler: TimerHandler) => {
|
||||
if (typeof handler === "function") {
|
||||
handler()
|
||||
}
|
||||
return originalSetTimeout(() => {}, 0)
|
||||
}) as typeof globalThis.setTimeout
|
||||
|
||||
const status = mock(async () => ({ data: { "ses-undurable": { type: "idle" } } }))
|
||||
const messages = mock(async () => ({ data: [] }))
|
||||
|
||||
try {
|
||||
// when
|
||||
const result = waitForCompletion(
|
||||
"ses-undurable",
|
||||
createToolContext(),
|
||||
createContext({ status, messages }),
|
||||
)
|
||||
|
||||
// then
|
||||
await expect(result).rejects.toThrow("Prompt was not durably accepted by OpenCode")
|
||||
expect(messages).toHaveBeenCalled()
|
||||
} finally {
|
||||
Date.now = originalDateNow
|
||||
globalThis.setTimeout = originalSetTimeout
|
||||
}
|
||||
})
|
||||
|
||||
test("#given the child session has durable messages #when it stays idle and stable #then completion succeeds", async () => {
|
||||
// given
|
||||
const originalDateNow = Date.now
|
||||
const originalSetTimeout = globalThis.setTimeout
|
||||
let currentTime = 0
|
||||
Date.now = () => {
|
||||
currentTime += 100
|
||||
return currentTime
|
||||
}
|
||||
globalThis.setTimeout = ((handler: TimerHandler) => {
|
||||
if (typeof handler === "function") {
|
||||
handler()
|
||||
}
|
||||
return originalSetTimeout(() => {}, 0)
|
||||
}) as typeof globalThis.setTimeout
|
||||
|
||||
const status = mock(async () => ({ data: { "ses-complete": { type: "idle" } } }))
|
||||
const messages = mock(async () => ({
|
||||
data: [
|
||||
{ info: { id: "msg-user", role: "user" } },
|
||||
{ info: { id: "msg-assistant", role: "assistant" } },
|
||||
],
|
||||
}))
|
||||
|
||||
try {
|
||||
// when
|
||||
await waitForCompletion(
|
||||
"ses-complete",
|
||||
createToolContext(),
|
||||
createContext({ status, messages }),
|
||||
)
|
||||
|
||||
// then
|
||||
expect(messages).toHaveBeenCalled()
|
||||
} finally {
|
||||
Date.now = originalDateNow
|
||||
globalThis.setTimeout = originalSetTimeout
|
||||
}
|
||||
})
|
||||
})
|
||||
@@ -17,10 +17,12 @@ export async function waitForCompletion(
|
||||
|
||||
const POLL_INTERVAL_MS = 500
|
||||
const MAX_POLL_TIME_MS = 5 * 60 * 1000 // 5 minutes max
|
||||
const PROMPT_ACCEPTANCE_TIMEOUT_MS = 30 * 1000
|
||||
const pollStart = Date.now()
|
||||
let lastMsgCount = 0
|
||||
let stablePolls = 0
|
||||
const STABILITY_REQUIRED = 3
|
||||
let sawActiveStatus = false
|
||||
|
||||
while (Date.now() - pollStart < MAX_POLL_TIME_MS) {
|
||||
if (toolContext.abort?.aborted) {
|
||||
@@ -35,6 +37,7 @@ export async function waitForCompletion(
|
||||
const sessionStatus = allStatuses[sessionID]
|
||||
|
||||
if (sessionStatus && sessionStatus.type !== "idle") {
|
||||
sawActiveStatus = true
|
||||
stablePolls = 0
|
||||
lastMsgCount = 0
|
||||
continue
|
||||
@@ -46,6 +49,15 @@ export async function waitForCompletion(
|
||||
})
|
||||
const currentMsgCount = msgs.length
|
||||
|
||||
if (currentMsgCount === 0) {
|
||||
stablePolls = 0
|
||||
lastMsgCount = 0
|
||||
if (!sawActiveStatus && Date.now() - pollStart >= PROMPT_ACCEPTANCE_TIMEOUT_MS) {
|
||||
throw new Error(`Prompt was not durably accepted by OpenCode for session ${sessionID}.`)
|
||||
}
|
||||
continue
|
||||
}
|
||||
|
||||
if (currentMsgCount > 0 && currentMsgCount === lastMsgCount) {
|
||||
stablePolls++
|
||||
if (stablePolls >= STABILITY_REQUIRED) {
|
||||
|
||||
Reference in New Issue
Block a user