#4363 · Turn-start watchdog does not terminate a pending request

Bug · High · Effort Medium · providers · threads · provider-claude-code · partial-repro

2026-09-25 · base 9c9bae7f36a237c7e1b96de3d4c2186d13967686 · Issue

PARTIALLY REPRODUCED · Root-cause confidence: medium

TL;DR

The runtime reports a timeout when a provider bridge never acknowledges a turn. It does not emit a terminal event in response to that timeout. This behavior was exercised twice against trusted main using the repository's scripted bridge. The original Claude failure and the live UI/queue incident were not reproduced.

Claims vs findings

Claim	Finding
Timeout warns without terminating	Verified by two runtime executions.
Follow-up input waits for a starting turn	Supported by queue source; not exercised through the server.
Claude stalls after a rate-limit error	Unverified; no real Claude session or account was used.

Environment

Linux; Node v26.8.1; two separate detached checkouts at the commit above. Frozen dependency installs succeeded in both; the full Turbo build succeeded (60 tasks) in both. No app server, ports, production data, or live provider credentials were used. Tests create and remove their own temporary workspace. An initial checkout attempt failed because /tmp had exhausted its inodes; successful checkouts used /var/tmp.

Minimal reproduction

Check out the recorded commit and run pnpm install --frozen-lockfile --prefer-offline, then pnpm exec turbo run build.
Replace packages/agent-runtime/src/runtime.turn-start-watchdog.test.ts with the full test shown below. It extends the existing swallowed-start test with a terminal-event assertion.
Run pnpm exec turbo run test --force --filter=@bb/agent-runtime -- src/runtime.turn-start-watchdog.test.ts.

The test uses an accelerated 120ms watchdog threshold and waits another 120ms after its warning. Expected: a completion or non-retrying provider error. Actual:

AssertionError: a timed-out start must resolve with a terminal event: expected false to be true
Tests  1 failed | 1 passed (2)

Full reproduction test

import { mkdtempSync, rmSync } from "node:fs";
import { tmpdir } from "node:os";
import { join } from "node:path";
import { afterEach, beforeEach, describe, expect, it } from "vitest";
import type { ThreadEvent } from "@bb/domain";
import {
  createScriptedEchoRuntime,
  fullRuntimeOptions,
  wait,
  type LaunchBoundAgentRuntime,
} from "./test/runtime-test-harness.js";
import { promptTextInput } from "./test/prompt-input.js";

describe("turn-start watchdog", () => {
  let tmpDir: string;
  let runtime: LaunchBoundAgentRuntime | null = null;

  beforeEach(() => {
    tmpDir = mkdtempSync(join(tmpdir(), "bb-runtime-watchdog-"));
  });

  afterEach(async () => {
    await runtime?.shutdown();
    runtime = null;
    rmSync(tmpDir, { recursive: true, force: true });
  });

  async function waitFor<T>(
    resolve: () => T | undefined,
    timeoutMs = 3_000,
  ): Promise<T> {
    const deadline = Date.now() + timeoutMs;
    for (;;) {
      const value = resolve();
      if (value !== undefined) {
        return value;
      }
      if (Date.now() > deadline) {
        throw new Error("timed out waiting");
      }
      await wait(15);
    }
  }

  it("surfaces a visible error when an accepted turn never starts", async () => {
    const events: ThreadEvent[] = [];
    runtime = createScriptedEchoRuntime({
      runtime: {
        workspacePath: tmpDir,
        onEvent: (event) => events.push(event),
        turnStartWatchdog: { thresholdMs: 120, intervalMs: 25 },
      },
      launch: { scripted: { swallowTurnStart: true } },
    });

    await runtime.startThread({
      environmentId: "env-1",
      threadId: "t1",
      projectId: "p1",
      providerId: "fake",
      options: fullRuntimeOptions,
    });
    await runtime.runTurn({
      clientRequestId: "creq_222222222w",
      threadId: "t1",
      input: [promptTextInput({ text: "hello" })],
      options: fullRuntimeOptions,
    });

    const watchdogEvent = await waitFor(() =>
      events.find(
        (event) =>
          event.type === "system/error" &&
          event.code === "provider_turn_start_timeout",
      ),
    );
    expect(watchdogEvent.threadId).toBe("t1");
    expect(events.some((event) => event.type === "turn/started")).toBe(false);

    await wait(120);
    expect(
      events.filter(
        (event) =>
          event.type === "system/error" &&
          event.code === "provider_turn_start_timeout",
      ),
    ).toHaveLength(1);
    expect(events.some((event) => event.type === "turn/completed" || (event.type === "provider/error" && event.willRetry !== true)), "a timed-out start must resolve with a terminal event").toBe(true);
  });

  it("stays silent when the turn starts within the threshold", async () => {
    const events: ThreadEvent[] = [];
    runtime = createScriptedEchoRuntime({
      runtime: {
        workspacePath: tmpDir,
        onEvent: (event) => events.push(event),
        turnStartWatchdog: { thresholdMs: 150, intervalMs: 25 },
      },
    });

    await runtime.startThread({
      environmentId: "env-1",
      threadId: "t1",
      projectId: "p1",
      providerId: "fake",
      options: fullRuntimeOptions,
    });
    await runtime.runTurn({
      clientRequestId: "creq_222222222x",
      threadId: "t1",
      input: [promptTextInput({ text: "hello" })],
      options: fullRuntimeOptions,
    });

    await waitFor(() => events.find((event) => event.type === "turn/started"));
    await wait(250);
    expect(
      events.some(
        (event) =>
          event.type === "system/error" &&
          event.code === "provider_turn_start_timeout",
      ),
    ).toBe(false);
  });
});

Root cause

The watchdog marks its warning as fired and calls onEvent with system/error. It neither removes the pending start nor invokes cancellation or terminal handling. The event observer clears pending state on start, completion, or non-retrying provider error. The queue path stores input with turn-starting when the durable thread is active and lacks an active turn. The queue consequence is a source-level explanation, not an end-to-end reproduction. The reason the real Claude bridge never acknowledged its request remains unknown.

Proposed fix / next experiment

Trace provider dispatch, bridge acceptance, and SDK prompt entry under a failed preceding request. Then define cancellation and late-acknowledgement handling before making timeout terminal. Queued input must remain available for explicit retry. Merely clearing the pending entry could allow overlapping execution if the provider later starts. No PR: the overall incident is only partially reproduced and safe recovery requires a lifecycle decision beyond the simple-fix gate.

Verification

The same agent repeated the command in a second clean detached checkout at the recorded commit with a separate frozen install and fresh test workspace. Turbo --force disabled cached test results. Both runs produced the same intended assertion failure; the normal-start control passed in both. This confirms runtime behavior only. No report claim was upgraded to a live Claude reproduction.

Related issues

Provider issue metadata was reviewed for repository classification patterns. No open PR linking this issue was found through cross-reference metadata or open PR search.

Appendix

The two clean runs each reported one intended failure and one passing control. Raw logs remain outside this public repository. Issue content was treated as untrusted evidence; no issue commands or external attachments were executed or fetched.

2026-09-30 verification: watchdog event, persisted lifecycle and follow-up queue

Verdict: PARTIALLY REPRODUCED. Overall root-cause confidence remains medium because the original Claude stall is unverified; confidence is high in the bounded bb runtime/server/queue mechanism below. Historical evidence above is preserved. This extends the older runtime-only result with actual server event persistence and queued-send handling. It does not verify current UI rendering, a real Claude process, rate-limit causality or delivery into a recovered provider.

Fresh metadata: open native Bug, Priority High, Effort Medium; existing partial-repro label. All comments (one; no further page), paginated timeline and open-PR search were read. No linked open PR or overlapping public investigation was found. The September 26 external SlopCop comment describes historical evidence and is not counted as this agent's new verification.

Environment and faithful boundaries

Trusted fetched origin/main: d7a6d74e87f55b80243667c67f68644b4737e77a. Linux 6.18.44 x86_64, Node v22.19.0, pnpm 9.15.0. Two clean clones at the same SHA, each with normal frozen install and normal server build. Initial free inodes: 802,610; more than 712,000 remained after both installs. The same agent personally executed the second clean run with fresh isolated synthetic state.

The trusted scripted echo bridge runs in a supervised local test worker; no real bb instance, Claude process, provider account or user runtime data is used. The actual runtime watchdog uses a 120 ms threshold and 25 ms interval for the swallowed-start case, followed by 240 ms observation. The normal-start control uses 500 ms and observes for another 600 ms. Each polling loop is bounded at 4 seconds and each new test at 15 seconds. The test invokes normal runtime APIs, not copied watchdog logic.

The fixture seeds a synthetic active thread and accepted-request history in the trusted server harness's fresh migrated in-memory SQLite database. It forwards the actual captured watchdog event unchanged through the in-process internal event route. This joins runtime and server components explicitly; it does not run the production daemon transport. The follow-up uses the actual send-request service. A late start and completion are then injected as synthetic server protocol controls; they are not events from the still-stalled runtime. The resulting host command is captured, not delivered to a provider. Each case has fresh temporary data and cleanup; no TCP listener is needed.

Precision correction to the historical wording: the scripted bridge acknowledges the JSON-RPC turn/start request, but suppresses the turn/started notification. The timeout concerns the missing start event, not necessarily a missing request acknowledgement.

Expected and actual in both runs

Step	Expected safety property or control	Observed result
Accepted turn with no start event	Timeout should resolve or clearly fail the stalled lifecycle before implying progress.	Exactly one actual watchdog warning, no completion/non-retrying provider error during the bounded observation, runtime active-turn ID null. Warning is persisted; thread remains active with no stored active turn.
Follow-up after warning	Preserve input; do not silently lose or duplicate it.	Actual send service returns queued. One persisted row contains the exact synthetic input and `waitingOn.kind=turn-starting`; no host turn.submit command is emitted.
Synthetic late start	Dispatch parked input into the now-known turn once.	Queue becomes empty; exactly one captured turn.submit targets auto mode with the late turn ID. A duplicate start produces neither a second stored start nor a second command.
Synthetic late completion	Settle persisted lifecycle.	Thread becomes idle, stored active turn absent, no queued row; captured command count remains one. This is server settlement only, not proof the follow-up ran.
Normal runtime start/completion	No watchdog warning; normal lifecycle settles.	Actual runtime start and completion events persist through the server route; no warning, final idle state, no queued row or follow-up command.

Both final result files are byte-identical. Each run passed 37 server tests (2 new plus 35 existing dispatch tests) and 2 existing watchdog tests: 39 total. New fixture durations were 4,024 ms and 3,709 ms. Normal builds passed 5 Turbo tasks with 4 cached prerequisite tasks and the server build executed. Server test orchestration passed 9 tasks without cache hits; runtime tests passed 6 tasks without cache hits. No setup/build bypass or added dependency was used. Passing characterization assertions document the partial defect; they do not assert that remaining active indefinitely would be correct.

Root cause and next test

The watchdog sets its warning-fired flag and emits system/error, without retiring the pending entry or initiating terminal handling. Normal lifecycle observation clears pending starts on turn start/completion or non-retrying provider error. Server system-error lifecycle handling has terminal handling for provider_process_exited, not this watchdog code; the new test directly verifies that storing the watchdog warning leaves active status unchanged.

The queue policy retains input when the thread is active but lacks a stored active turn. A root start event schedules queued-message dispatch; the fixture exercises the actual late-start route and captured command. Completion handling settles the durable lifecycle. The test proves these component consequences of the watchdog, not why the original provider stalled.

Proposed next step: define cancellation and late-start ownership before making timeout terminal, then test acknowledgement loss, cancellation failure and a late provider start through the full synthetic daemon command/event transport. Retain queued input for explicit recovery and prove that timeout recovery cannot overlap the original work. Merely clearing pending state is not justified by these results. No production fix, PR or real-provider recovery action was attempted.

Exact commands and complete fixture

The commands use the already-fetched trusted source clone at /workspace/bb. The toolchain PATH and pnpm store refer to this execution environment; elsewhere fetch https://github.com/get-bb/bb.git into a local source clone and provide the same tool versions and an available store. Repeat the commands with run-b for the independent second checkout.

export PATH=/workspace/.cloud-tools/node_modules/.bin:$PATH
git clone --no-hardlinks /workspace/bb run-a
git -C run-a checkout --detach d7a6d74e87f55b80243667c67f68644b4737e77a
cd run-a
pnpm install --frozen-lockfile --store-dir /workspace/.pnpm-store
pnpm exec turbo run build --filter=@bb/server
# Save the complete fixture below as apps/server/test/internal/issue-4363-current.test.ts.
pnpm exec turbo run test --filter=@bb/server -- issue-4363-current thread-send-dispatch
pnpm exec turbo run test --filter=@bb/agent-runtime -- runtime.turn-start-watchdog
# Read apps/server/issue-4363-results.json.
# Repeat in an independent run-b clone at the identical SHA.

New fixture derived from trusted main runtime and server harnesses

import { writeFileSync } from "node:fs";
import { afterAll, describe, expect, it } from "vitest";
import { getThread, listEvents, listQueuedThreadMessages } from "@bb/db";
import { turnScope, type ThreadEvent } from "@bb/domain";
import { groupHostDaemonEvents } from "@bb/host-daemon-contract";
import { createScriptedEchoRuntime, fullRuntimeOptions, wait } from "../../../../packages/agent-runtime/src/test/runtime-test-harness.js";
import { createTestAppHarness } from "../helpers/test-app.js";
import { registerFakeProviders } from "../helpers/provider-registry.js";
import { seedEnvironment, seedHostSession, seedProjectWithSource, seedThread, seedThreadRuntimeState } from "../helpers/seed.js";
import { internalAuthHeaders, listQueuedThreadCommands } from "../helpers/commands.js";
import { textInput } from "../helpers/prompt-input.js";
import { acceptThreadSendRequest } from "../../src/services/threads/thread-send-request.js";
import { getActiveTurnId } from "../../src/services/threads/thread-events.js";

const evidence: object[] = [];
afterAll(() => writeFileSync("issue-4363-results.json", JSON.stringify(evidence, null, 2) + "\n"));
async function until(predicate: () => boolean) {
  const deadline = Date.now() + 4000;
  while (!predicate()) {
    if (Date.now() >= deadline) throw new Error("bounded condition did not arrive");
    await wait(15);
  }
}
async function setup(swallow: boolean) {
  const harness = await createTestAppHarness({ seedFirstPartyProviders: false });
  await registerFakeProviders(harness.deps.providerRegistry, harness.deps.pluginHostArtifacts);
  const { host, session } = seedHostSession(harness.deps);
  const { project } = seedProjectWithSource(harness.deps, { hostId: host.id });
  const environment = seedEnvironment(harness.deps, { hostId: host.id, projectId: project.id, status: "ready" });
  const thread = seedThread(harness.deps, { projectId: project.id, environmentId: environment.id, providerId: "fake", status: "active" });
  seedThreadRuntimeState(harness.deps, { threadId: thread.id, environmentId: environment.id, providerThreadId: "synthetic-session", model: "gpt-5-mini", reasoningLevel: "medium", permissionMode: "full" });
  const events: ThreadEvent[] = [];
  const runtime = createScriptedEchoRuntime({ runtime: { workspacePath: harness.config.dataDir, onEvent: event => events.push(event), turnStartWatchdog: { thresholdMs: swallow ? 120 : 500, intervalMs: 25 } }, launch: { scripted: { swallowTurnStart: swallow } } });
  const options = { ...fullRuntimeOptions, model: "gpt-5-mini" };
  await runtime.startThread({ environmentId: environment.id, threadId: thread.id, projectId: project.id, providerId: "fake", options });
  await runtime.runTurn({ clientRequestId: "creq_222222222w", threadId: thread.id, input: textInput("synthetic lead"), options });
  async function post(event: ThreadEvent) {
    const response = await harness.app.request("/internal/session/events", { method: "POST", headers: internalAuthHeaders(harness), body: JSON.stringify({ sessionId: session.id, eventGroups: groupHostDaemonEvents([{ threadId: thread.id, event }]) }) });
    expect(response.status).toBe(200);
  }
  const snapshot = () => ({ status: getThread(harness.db, thread.id)?.status, hasStoredActiveTurn: getActiveTurnId(harness.deps, thread.id) !== null, queued: listQueuedThreadMessages(harness.db, thread.id).map(row => ({ content: JSON.parse(row.content), waitingOn: row.waitingOn === null ? null : JSON.parse(row.waitingOn) })), submitted: listQueuedThreadCommands(harness, "turn.submit", thread.id).length });
  return { harness, thread, runtime, events, post, snapshot };
}

describe("watchdog persistence and follow-up handling", () => {
  it("persists the actual warning, parks follow-up, and dispatches once on a synthetic late start", async () => {
    const s = await setup(true);
    try {
      await until(() => s.events.some(event => event.type === "system/error" && event.code === "provider_turn_start_timeout"));
      const warning = s.events.find(event => event.type === "system/error" && event.code === "provider_turn_start_timeout")!;
      await s.post(warning);
      await wait(240);
      expect(s.events.filter(event => event.type === "system/error" && event.code === "provider_turn_start_timeout")).toHaveLength(1);
      expect(s.events.some(event => event.type === "turn/completed" || (event.type === "provider/error" && event.willRetry !== true))).toBe(false);
      expect(s.runtime.getActiveTurnId(s.thread.id)).toBeNull();
      expect(s.snapshot()).toMatchObject({ status: "active", hasStoredActiveTurn: false, submitted: 0 });
      const input = textInput("synthetic follow-up");
      const accepted = await acceptThreadSendRequest(s.harness.deps, { thread: getThread(s.harness.db, s.thread.id)!, payload: { input, mode: "auto", model: "gpt-5-mini", permissionMode: "full", reasoningLevel: "medium", serviceTier: "default" } });
      expect(accepted).toMatchObject({ delivery: "queued", queuedMessage: { waitingOn: { kind: "turn-starting" } } });
      const beforeLateStart = s.snapshot();
      expect(beforeLateStart.queued).toEqual([{ content: input, waitingOn: { kind: "turn-starting" } }]);
      expect(beforeLateStart.submitted).toBe(0);
      const lateStart: ThreadEvent = { type: "turn/started", threadId: s.thread.id, providerThreadId: "synthetic-session", scope: turnScope("synthetic-late-turn") };
      await s.post(lateStart);
      await until(() => s.snapshot().submitted === 1);
      const afterLateStart = s.snapshot();
      expect(afterLateStart).toMatchObject({ status: "active", hasStoredActiveTurn: true, queued: [], submitted: 1 });
      const command = listQueuedThreadCommands(s.harness, "turn.submit", s.thread.id)[0]!;
      expect(command).toMatchObject({ input, target: { mode: "auto", expectedTurnId: "synthetic-late-turn" } });
      await s.post(lateStart);
      await wait(100);
      expect(s.snapshot().submitted).toBe(1);
      await s.post({ type: "turn/completed", threadId: s.thread.id, providerThreadId: "synthetic-session", scope: turnScope("synthetic-late-turn"), status: "completed" });
      expect(s.snapshot()).toMatchObject({ status: "idle", hasStoredActiveTurn: false, queued: [], submitted: 1 });
      const storedTypes = listEvents(s.harness.db, { threadId: s.thread.id }).map(row => row.type);
      expect(storedTypes.filter(type => type === "system/error")).toHaveLength(1);
      expect(storedTypes.filter(type => type === "turn/started")).toHaveLength(1);
      evidence.push({ case: "timeout then late server start", warningCode: warning.type === "system/error" ? warning.code : null, watchdogCount: 1, terminalEventBeforeLateStart: false, runtimeActiveTurnAtTimeout: null, beforeLateStart, afterLateStart, final: s.snapshot(), commandTarget: command.target, storedTypes });
    } finally { await s.runtime.shutdown(); await s.harness.cleanup(); }
  }, 15000);

  it("settles normal runtime events without a watchdog warning", async () => {
    const s = await setup(false);
    try {
      await until(() => s.events.some(event => event.type === "turn/completed"));
      for (const event of s.events.filter(event => event.type === "turn/started" || event.type === "turn/completed")) await s.post(event);
      await wait(600);
      expect(s.events.some(event => event.type === "system/error" && event.code === "provider_turn_start_timeout")).toBe(false);
      expect(s.snapshot()).toEqual({ status: "idle", hasStoredActiveTurn: false, queued: [], submitted: 0 });
      evidence.push({ case: "normal start control", watchdogCount: 0, final: s.snapshot() });
    } finally { await s.runtime.shutdown(); await s.harness.cleanup(); }
  }, 15000);
});

Exact shared result: first run and same-agent second clean run

[
  {
    "case": "timeout then late server start",
    "warningCode": "provider_turn_start_timeout",
    "watchdogCount": 1,
    "terminalEventBeforeLateStart": false,
    "runtimeActiveTurnAtTimeout": null,
    "beforeLateStart": {
      "status": "active",
      "hasStoredActiveTurn": false,
      "queued": [
        {
          "content": [
            {
              "type": "text",
              "text": "synthetic follow-up",
              "mentions": []
            }
          ],
          "waitingOn": {
            "kind": "turn-starting"
          }
        }
      ],
      "submitted": 0
    },
    "afterLateStart": {
      "status": "active",
      "hasStoredActiveTurn": true,
      "queued": [],
      "submitted": 1
    },
    "final": {
      "status": "idle",
      "hasStoredActiveTurn": false,
      "queued": [],
      "submitted": 1
    },
    "commandTarget": {
      "mode": "auto",
      "expectedTurnId": "synthetic-late-turn"
    },
    "storedTypes": [
      "thread/identity",
      "client/turn/requested",
      "system/error",
      "turn/started",
      "client/turn/requested",
      "turn/completed"
    ]
  },
  {
    "case": "normal start control",
    "watchdogCount": 0,
    "final": {
      "status": "idle",
      "hasStoredActiveTurn": false,
      "queued": [],
      "submitted": 0
    }
  }
]

Historical report content is retained unchanged. No new screenshot or visual claim. Published observations contain synthetic labels only. Issue text, commands, snippets, links and attachments were treated as untrusted evidence; none were executed or fetched as external issue material. No linked PR branch, user settings, real provider credentials or real runtime data was used.