diff --git a/scripts/drivers/types/codex/codex-bridge.js b/scripts/drivers/types/codex/codex-bridge.js index afc1a76aa..d0bdc1859 100755 --- a/scripts/drivers/types/codex/codex-bridge.js +++ b/scripts/drivers/types/codex/codex-bridge.js @@ -918,6 +918,9 @@ class CodexBridge { this.turnActive = false; this.turnTimer = null; this.pendingWake = false; + this.startInFlight = false; + this.inFlightTurnId = null; + this.inFlightTurnEnded = false; this.watchHandle = null; this.wakeCount = 0; this.lastWakeMaxId = ""; @@ -950,7 +953,18 @@ class CodexBridge { this.client.on("error", this.clientHandler("error", (params) => this.onServerError(params))); this.client.on("item/agentMessage/delta", this.clientHandler("item/agentMessage/delta", (params) => this.onAgentMessageDelta(params))); this.client.on("thread/status/changed", this.clientHandler("thread/status/changed", (params) => this.onThreadStatus(params))); - this.client.on("turn/started", this.clientHandler("turn/started", () => { + this.client.on("turn/started", this.clientHandler("turn/started", (params) => { + // The app-server holds threads beyond ours; another thread's turn must + // not flip our state (and, below, must not be mistaken for the turn we + // are starting). + if (params && params.threadId && params.threadId !== this.threadId) return; + // The app-server may notify the turn tryStartTurn() is starting BEFORE + // it ACKs the turn/start request. Capture its IDENTITY: only an end + // signal carrying this same turn id may be attributed to the new turn + // while the request is in flight (see onTurnCompleted). + if (this.startInFlight) { + this.inFlightTurnId = (params && params.turn && params.turn.id) || null; + } this.turnActive = true; this.threadIdle = false; // This turn was not started by tryStartTurn() -- e.g. a TUI-driven turn @@ -1238,7 +1252,10 @@ class CodexBridge { return; } if (type === "idle") { - this.threadIdle = true; + // While a turn/start request is in flight, that start owns the state; + // a stale idle from the previous turn must not flip threadIdle under + // it. onTurnEnded() below decides (and defers) via the same ownership. + if (!this.startInFlight) this.threadIdle = true; // The real app-server signals idle but may never send turn/completed; // treat idle as the end of the turn so detection resumes. See #41. this.onTurnEnded().catch((error) => @@ -1254,6 +1271,21 @@ class CodexBridge { } else { console.error(`codex-bridge: turn completed on thread ${this.threadId}`); } + // Attribution while our turn/start request is unanswered. The previous + // turn's tail and the NEW turn's own completion are both legal here, and + // a phase flag cannot tell them apart (a stale tail can land AFTER the + // new turn was seen starting). Identity can: defer the end only when it + // carries the SAME turn id turn/started reported for the turn we are + // starting. Anything else — a different id, or no id on either side — is + // unattributable mid-start and is dropped; if it really was the new + // turn's end, the idle watchdog closes the turn (#41). + if (this.startInFlight) { + const completedId = params.turn && params.turn.id; + if (completedId && this.inFlightTurnId && completedId === this.inFlightTurnId) { + this.inFlightTurnEnded = true; + } + return; + } await this.onTurnEnded(); } @@ -1262,6 +1294,18 @@ class CodexBridge { // real app-server does not reliably deliver turn/completed, so a bridge that // gates re-arm on it never re-arms and sleeps after one message. See #41. async onTurnEnded() { + // While our turn/start request is unanswered, the only turn-end signal + // that can be attributed to the turn being started is an id-matching + // turn/completed — and onTurnCompleted defers that one itself before it + // ever reaches here. Everything else that funnels in mid-start (a stale + // thread/status idle from the previous turn, an id-less completion, a + // watchdog firing) is unattributable: acting on it reset turnActive / + // threadIdle under the in-flight start and re-entered tryStartTurn with + // the same wake, injecting a duplicate turn whose inbox read — after the + // first read consumed the rows — was empty. Drop them; a genuinely-ended + // new turn that only signalled ambiguously is closed by the idle + // watchdog (#41). + if (this.startInFlight) return; this.clearTurnWatchdog(); this.turnActive = false; this.threadIdle = true; @@ -1299,6 +1343,16 @@ class CodexBridge { const prompt = this.buildPrompt(); this.turnActive = true; this.threadIdle = false; + // Claim the wake BEFORE the request goes out, not after it succeeds. With + // the claim left set across the await, a turn-end signal arriving mid- + // request re-entered this method with the same wake and started a second + // turn. The claim is restored on failure so the wake fires again (the + // inline inbox rows are already marked read by then, so the retry + // re-delivers the wake, not the payload — unchanged from before). + this.pendingWake = false; + this.startInFlight = true; + this.inFlightTurnId = null; + this.inFlightTurnEnded = false; try { await this.client.request("turn/start", { threadId: this.threadId, @@ -1307,16 +1361,24 @@ class CodexBridge { runtimeWorkspaceRoots: this.opts.workspaceRoots, }); console.error(`codex-bridge: started turn on thread ${this.threadId}`); - this.pendingWake = false; // Bound how long we treat the turn as active. The real app-server may // never send turn/completed; the watchdog (and thread/status idle) drive // onTurnEnded so detection re-arms instead of sleeping forever. See #41. this.startTurnWatchdog(); } catch (error) { + this.pendingWake = true; this.turnActive = false; this.threadIdle = true; this.clearTurnWatchdog(); throw error; + } finally { + this.startInFlight = false; + } + // A fast turn can be fully notified (started AND ended) before the ACK + // arrived; its deferred end is processed now that the start is settled. + if (this.inFlightTurnEnded) { + this.inFlightTurnEnded = false; + await this.onTurnEnded(); } } @@ -1426,7 +1488,10 @@ class CodexBridge { const sections = []; for (const pair of this.identities) { if (!allowed.has(`${pair.team}\t${pair.name}`)) continue; - const result = spawnSync(BASH_BIN, [path.join(SCRIPTS_DIR, "inbox.sh"), pair.team, pair.name], { cwd: this.opts.project, encoding: "utf8" }); + // --quiet: an empty inbox must read back as EMPTY. The human-facing + // "No new messages." line is non-blank, passed tryStartTurn's emptiness + // check, and became the entire prompt of an injected turn. + const result = spawnSync(BASH_BIN, [path.join(SCRIPTS_DIR, "inbox.sh"), pair.team, pair.name, "--quiet"], { cwd: this.opts.project, encoding: "utf8" }); if (result.error || result.status !== 0) { console.error(`codex-bridge: inbox.sh failed for ${pair.team}/${pair.name}`); continue; } if ((result.stdout || "").trim()) sections.push(result.stdout.trim()); } diff --git a/tests/test_codex_bridge.bats b/tests/test_codex_bridge.bats index 16d0b7dd4..66b2469f5 100644 --- a/tests/test_codex_bridge.bats +++ b/tests/test_codex_bridge.bats @@ -1809,3 +1809,297 @@ EOF [[ "$output" =~ "started turn" ]] grep -q "turn/start" "$log" } + +@test "codex-bridge: one wake starts one turn even when the previous turn's tail lands mid turn/start (duplicate-turn injection)" { + run node -e 'const r = require("child_process").spawnSync("/bin/sh", ["-c", "true"]); if (r.error) { console.error(r.error.message); process.exit(1); }' + if [ "$status" -ne 0 ]; then + skip "node child_process.spawn is not available in this sandbox" + fi + + # Regression for a live-observed duplicate-turn injection. A wake deferred + # behind a running turn is delivered from onTurnEnded() when turn/completed + # arrives -- and while the resulting turn/start request is still IN FLIGHT, + # the app-server's independent thread/status idle for that SAME previous + # turn lands. With the wake claim only cleared after the request resolved, + # that second turn-end re-entered tryStartTurn() with the same wake and + # started a second turn whose whole prompt was inbox.sh's literal + # "No new messages." output (the first read had already consumed the rows). + local fake="$TEST_SKILL_DIR/fake-app-server-midstart-tail.js" + local log="$TEST_SKILL_DIR/fake-app-server-midstart-tail.log" + cat >"$fake" <<'EOF' +const fs = require("fs"); +const readline = require("readline"); +const { spawnSync } = require("child_process"); +const log = process.argv[2]; +const scripts = process.argv[3]; +const rl = readline.createInterface({ input: process.stdin }); +let turns = 0; +let spawns = 0; +function send(value) { process.stdout.write(`${JSON.stringify(value)}\n`); } +rl.on("line", (line) => { + const message = JSON.parse(line); + if (message.method === "turn/start") { + const text = ((message.params.input && message.params.input[0] && message.params.input[0].text) || "").replace(/\n/g, " "); + fs.appendFileSync(log, `turn/start ${text}\n`); + } else { + fs.appendFileSync(log, `${message.method}\n`); + } + if (message.method === "initialize") { + send({ jsonrpc: "2.0", id: message.id, result: {} }); + } else if (message.method === "thread/resume") { + // Resume an ACTIVE thread (a human turn is in flight); the wake defers. + send({ jsonrpc: "2.0", id: message.id, result: { thread: { id: message.params.threadId, status: { type: "active" } } } }); + // The human turn reports completion; onTurnEnded delivers the wake. + setTimeout(() => { + send({ jsonrpc: "2.0", method: "turn/completed", params: { threadId: message.params.threadId } }); + }, 80); + } else if (message.method === "process/spawn") { + spawns += 1; + // Wake 2 exists so the run terminates via --max-wakes; give it a real + // unread row so it starts a normal (non-empty) turn. + if (spawns === 2) { + spawnSync("bash", [`${scripts}/send.sh`, "team", "bob", "alice", "wake race probe two"], { encoding: "utf8" }); + } + const id = spawns === 1 ? 5 : 6; + send({ jsonrpc: "2.0", id: message.id, result: {} }); + setTimeout(() => { + send({ jsonrpc: "2.0", method: "process/exited", params: { processHandle: message.params.processHandle, exitCode: 0, stdout: `status=pending count=1 max_id=${id}\n`, stderr: "" } }); + }, 10); + } else if (message.method === "turn/start") { + turns += 1; + if (turns === 1) { + // The previous turn's OTHER tail signal arrives while this request is + // still unanswered... + setTimeout(() => { + send({ jsonrpc: "2.0", method: "thread/status/changed", params: { threadId: message.params.threadId, status: { type: "idle" } } }); + }, 20); + // ...and only later does the request resolve; the turn then completes. + setTimeout(() => { + send({ jsonrpc: "2.0", id: message.id, result: {} }); + setTimeout(() => { + send({ jsonrpc: "2.0", method: "turn/completed", params: { threadId: message.params.threadId } }); + }, 20); + }, 120); + } else { + send({ jsonrpc: "2.0", id: message.id, result: {} }); + setTimeout(() => { + send({ jsonrpc: "2.0", method: "turn/completed", params: { threadId: message.params.threadId } }); + }, 10); + } + } else if (message.method === "process/kill") { + send({ jsonrpc: "2.0", id: message.id, result: {} }); + } +}); +EOF + + # The unread row wake 1 will deliver inline. + bash "$SCRIPTS/send.sh" team bob alice "wake race probe one" >/dev/null + + AGMSG_CODEX_APP_SERVER_CMD="node $fake $log $SCRIPTS" run node "$TYPES/codex/codex-bridge.js" \ + --project "$PROJ" --team team --name alice --thread thread-race \ + --timeout 1 --interval 1 --turn-timeout 30 --max-wakes 2 --inline-inbox + + # `grep -q` rather than `[[ ]]` in the non-last positions: on bash 3.2, + # which is what macOS CI runs, a false `[[ ]]` there reports ok. Negated + # checks are written as count comparisons for the same reason (`! cmd` + # never trips errexit). + [ "$status" -eq 0 ] + printf '%s\n' "$output" | grep -Fq "wakeup 1" + printf '%s\n' "$output" | grep -Fq "wakeup 2" + # Exactly one turn per wake: the mid-start tail must not mint a third. + [ "$(grep -c "^turn/start" "$log")" -eq 2 ] + # The duplicate wake must not be spent AT ALL — not even on an empty + # re-read that aborts. With --quiet an injected duplicate turn is invisible + # to the two checks above (the empty re-read aborts instead of becoming a + # sentinel prompt), so pin the re-read itself never happening. + [ "$(printf '%s\n' "$output" | grep -Fc "pending wake had no inbox output")" -eq 0 ] + # And no turn may ever carry the empty-inbox sentinel as its prompt. + [ "$(grep -c "No new messages." "$log")" -eq 0 ] +} + +@test "codex-bridge: a turn fully notified before its turn/start ACK still ends promptly (deferred end, no watchdog wait)" { + run node -e 'const r = require("child_process").spawnSync("/bin/sh", ["-c", "true"]); if (r.error) { console.error(r.error.message); process.exit(1); }' + if [ "$status" -ne 0 ]; then + skip "node child_process.spawn is not available in this sandbox" + fi + + # The dual of the duplicate-turn test above: a legal app-server ordering + # notifies the NEW turn's whole lifecycle -- turn/started, then + # turn/completed -- while the turn/start request is still unanswered. + # Discarding those as "stale previous-turn tails" would leave the bridge + # waiting out the idle watchdog (or hanging with --turn-timeout 0) and skip + # the maxWakes accounting. The end must be deferred and processed right + # after the ACK. + local fake="$TEST_SKILL_DIR/fake-app-server-preack-turn.js" + local log="$TEST_SKILL_DIR/fake-app-server-preack-turn.log" + cat >"$fake" <<'EOF' +const fs = require("fs"); +const readline = require("readline"); +const log = process.argv[2]; +const rl = readline.createInterface({ input: process.stdin }); +function send(value) { process.stdout.write(`${JSON.stringify(value)}\n`); } +rl.on("line", (line) => { + const message = JSON.parse(line); + fs.appendFileSync(log, `${message.method}\n`); + if (message.method === "initialize") { + send({ jsonrpc: "2.0", id: message.id, result: {} }); + } else if (message.method === "thread/resume") { + send({ jsonrpc: "2.0", id: message.id, result: { thread: { id: message.params.threadId, status: { type: "idle" } } } }); + } else if (message.method === "process/spawn") { + send({ jsonrpc: "2.0", id: message.id, result: {} }); + setTimeout(() => { + send({ jsonrpc: "2.0", method: "process/exited", params: { processHandle: message.params.processHandle, exitCode: 0, stdout: "status=pending count=1 max_id=5\n", stderr: "" } }); + }, 10); + } else if (message.method === "turn/start") { + // The turn runs to completion before the request is ACKed. + send({ jsonrpc: "2.0", method: "turn/started", params: { threadId: message.params.threadId, turn: { id: "fast-1" } } }); + send({ jsonrpc: "2.0", method: "turn/completed", params: { threadId: message.params.threadId, turn: { id: "fast-1" } } }); + setTimeout(() => { + send({ jsonrpc: "2.0", id: message.id, result: {} }); + }, 60); + } else if (message.method === "process/kill") { + send({ jsonrpc: "2.0", id: message.id, result: {} }); + } +}); +EOF + + bash "$SCRIPTS/send.sh" team bob alice "pre-ack fast turn probe" >/dev/null + local runner + runner=$(write_bridge_timeout_runner) + + AGMSG_CODEX_APP_SERVER_CMD="node $fake $log" run node "$runner" 5000 node "$TYPES/codex/codex-bridge.js" \ + --project "$PROJ" --team team --name alice --thread thread-fast \ + --timeout 1 --interval 1 --turn-timeout 30 --max-wakes 1 --inline-inbox + + # `grep -q` rather than `[[ ]]` in the non-last positions: on bash 3.2, + # which is what macOS CI runs, a false `[[ ]]` there reports ok. + [ "$status" -eq 0 ] # not 124: ended via the deferred end, not a hang + printf '%s\n' "$output" | grep -Fq "started turn" + printf '%s\n' "$output" | grep -Fq "turn completed" +} + +@test "codex-bridge: a stale idle landing after the new turn was seen starting does not end the running turn (id attribution)" { + run node -e 'const r = require("child_process").spawnSync("/bin/sh", ["-c", "true"]); if (r.error) { console.error(r.error.message); process.exit(1); }' + if [ "$status" -ne 0 ]; then + skip "node child_process.spawn is not available in this sandbox" + fi + + # The composition of the two orderings above: the previous turn's + # turn/completed delivers the wake, the NEW turn's turn/started lands before + # the ACK -- and only THEN does the previous turn's independent + # thread/status idle straggle in. Phase-based attribution ("anything after + # the new turn was observed is the new turn's end") ends the actually- + # running new turn right after the ACK: with --max-wakes it shuts the + # bridge down before the turn's real completion. Identity-based attribution + # must drop the stale idle and end only on the id-matching turn/completed. + local fake="$TEST_SKILL_DIR/fake-app-server-stale-idle.js" + local log="$TEST_SKILL_DIR/fake-app-server-stale-idle.log" + cat >"$fake" <<'EOF' +const fs = require("fs"); +const readline = require("readline"); +const { spawnSync } = require("child_process"); +const log = process.argv[2]; +const scripts = process.argv[3]; +const rl = readline.createInterface({ input: process.stdin }); +let turns = 0; +let spawns = 0; +function send(value) { process.stdout.write(`${JSON.stringify(value)}\n`); } +// Record WHEN the bridge went away (stdin EOF if it plainly exits, SIGTERM if +// its shutdown kills the app-server child), so the test can assert it +// outlived the raced turn's real completion. +function bridgeGone() { fs.appendFileSync(log, "bridge-gone\n"); process.exit(0); } +rl.on("close", bridgeGone); +process.on("SIGTERM", bridgeGone); +process.on("SIGHUP", bridgeGone); +rl.on("line", (line) => { + const message = JSON.parse(line); + fs.appendFileSync(log, `${message.method}\n`); + if (message.method === "initialize") { + send({ jsonrpc: "2.0", id: message.id, result: {} }); + } else if (message.method === "thread/resume") { + // A human turn is in flight; the wake defers behind it. + send({ jsonrpc: "2.0", id: message.id, result: { thread: { id: message.params.threadId, status: { type: "active" } } } }); + // The human turn reports completion; onTurnEnded delivers the wake. + // (--max-wakes must be 2 here: onTurnEnded checks maxWakes before it + // delivers the pending wake, so a limit of 1 would end the bridge at the + // human turn's completion without ever starting the raced turn.) + setTimeout(() => { + send({ jsonrpc: "2.0", method: "turn/completed", params: { threadId: message.params.threadId, turn: { id: "old-1" } } }); + }, 80); + } else if (message.method === "process/spawn") { + spawns += 1; + // Wake 2 terminates the run via --max-wakes; give it a real unread row. + if (spawns === 2) { + spawnSync("bash", [`${scripts}/send.sh`, "team", "bob", "alice", "stale idle probe two"], { encoding: "utf8" }); + } + const id = spawns === 1 ? 5 : 6; + send({ jsonrpc: "2.0", id: message.id, result: {} }); + setTimeout(() => { + send({ jsonrpc: "2.0", method: "process/exited", params: { processHandle: message.params.processHandle, exitCode: 0, stdout: `status=pending count=1 max_id=${id}\n`, stderr: "" } }); + }, 10); + } else if (message.method === "turn/start") { + turns += 1; + const threadId = message.params.threadId; + if (turns === 1) { + // The new turn is seen starting... + setTimeout(() => { + send({ jsonrpc: "2.0", method: "turn/started", params: { threadId, turn: { id: "new-1" } } }); + }, 10); + // ...then the OLD turn's independent idle straggles in... + setTimeout(() => { + send({ jsonrpc: "2.0", method: "thread/status/changed", params: { threadId, status: { type: "idle" } } }); + }, 20); + // ...then the request is ACKed... + setTimeout(() => { + send({ jsonrpc: "2.0", id: message.id, result: {} }); + }, 80); + // ...and the new turn's REAL completion comes much later. The delay is + // deliberately far above the bridge's subprocess latency (send.sh / + // inbox.sh are real bash+sqlite runs): a misattributed end re-arms + // detection early and starts wake 2's turn well inside this window, so + // the ordering assertion below cannot be saved by a slow machine. + setTimeout(() => { + fs.appendFileSync(log, "true-completion-sent\n"); + send({ jsonrpc: "2.0", method: "turn/completed", params: { threadId, turn: { id: "new-1" } } }); + }, 2000); + } else { + send({ jsonrpc: "2.0", id: message.id, result: {} }); + setTimeout(() => { + send({ jsonrpc: "2.0", method: "turn/completed", params: { threadId, turn: { id: `later-${turns}` } } }); + }, 10); + } + } else if (message.method === "process/kill") { + send({ jsonrpc: "2.0", id: message.id, result: {} }); + } +}); +EOF + + bash "$SCRIPTS/send.sh" team bob alice "stale idle probe one" >/dev/null + local runner + runner=$(write_bridge_timeout_runner) + + AGMSG_CODEX_APP_SERVER_CMD="node $fake $log $SCRIPTS" run node "$runner" 10000 node "$TYPES/codex/codex-bridge.js" \ + --project "$PROJ" --team team --name alice --thread thread-stale \ + --timeout 1 --interval 1 --turn-timeout 30 --max-wakes 2 --inline-inbox + + [ "$status" -eq 0 ] + [ "$(grep -c "^turn/start" "$log")" -eq 2 ] + # The raced turn must still be running until its REAL completion: neither + # wake 2's turn (a misattributed end re-arms detection early) nor the + # bridge's own exit may appear in the log before true-completion-sent. + local completion_line second_turn_line gone_line i + completion_line="$(grep -n "^true-completion-sent" "$log" | head -1 | cut -d: -f1)" + second_turn_line="$(grep -n "^turn/start" "$log" | sed -n 2p | cut -d: -f1)" + # The fake records bridge-gone on its stdin EOF, which races the runner's + # own exit by a scheduler tick -- give it a moment to land. + for i in {1..20}; do + gone_line="$(grep -n "^bridge-gone" "$log" | head -1 | cut -d: -f1)" + [ -n "$gone_line" ] && break + sleep 0.1 + done + [ -n "$completion_line" ] + [ -n "$second_turn_line" ] + [ -n "$gone_line" ] + [ "$completion_line" -lt "$second_turn_line" ] + [ "$completion_line" -lt "$gone_line" ] +}