← reports

#2291 · provider.list_models startup probe logs "ACP agent is not authenticated." at warn on every daemon start

Bug Priority: Low Effort: small providers · provider-acp · host open on GitHub 2026-08-24 · base 494f66526

Verdict: PARTIALLY REPRODUCED · Root-cause confidence: high (for the log line) · Issue's "startup race" theory: refuted on this machine, unverifiable on the reporter's.

1. TL;DR

When an ACP provider's model-list CLI (for Cursor: cursor-agent --list-models) answers "Authentication required", the ACP bridge rejects model/list with a typed authRequired recovery hint, the agent runtime turns it into AgentRuntimeRecoveryError { code: "auth_required" }, and the host daemon's CommandRouter.handleOnlineRpcRequest logs online host RPC failed at warn level, stack trace and all, before returning the same outcome to the server as { ok:false, errorCode:"auth_required" }. The server then logs its own warn (Failed to resolve provider models) and surfaces modelLoadError: auth_required to the UI. So the daemon line is indeed a duplicate of a condition the server already reports. That part reproduces exactly, both in a unit test at the router and live on my dev instance.

What does not hold up is the issue's causal story. The probe does not "race the ACP agent's auth handshake": the model probe never talks to an ACP agent process at all — it execFiles the agent's list command as a plain subprocess. On this machine the Cursor CLI reports "Logged in" yet --list-models fails with "Authentication required" on every run, with no bb involved, so the warn fires on every execution-options read (4 reads → 4 daemon warns + 4 server warns), not once per daemon start. The issue's "one per session, later probes succeed" observation is unverifiable from here, and its "picker falls back to declared models" claim is wrong at base: auth_required deliberately returns an empty model list. Linked PR #2294 makes the right one-line change, but its regression test no longer compiles against main's intent (it relies on a regex classifier removed in e42a4ef48) and the test file conflicts; it needs a rebase and a new test.

2. Claims vs findings

3. Environment

• bb base commit 494f66526913557ab076e048218236f0a6610927 (main, 2026-08-24); no later commit on origin/main touches the daemon router, dispatch support, ACP bridge, or execution-options (checked git log 494f66526..origin/main).
• macOS 26.5.2 (25F84), Apple Silicon; Node v22.23.1; pnpm 9.15.0.
• Cursor CLI cursor-agent 2026.06.19-20-24-33-653a7fb at ~/.local/bin/cursor-agent; cursor-agent status prints "Logged in (unable to fetch user details)"; cursor-agent --list-models exits 1 with "Error: Authentication required. Run 'agent login', …".
• My dev instance (from scripts/bb-dev-app current in my worktree): App :11723, Server :19723, Host daemon :27723, data dir ~/.bb-dev/bb-machines-HOST.getbb.app-checkouts-bb-.claude-worktrees-wf_846839f8-f8a-62-52752453907a, host id host_f5y3w5zzsd. Stopped and deleted after the investigation.

4. Minimal reproduction

4a. Unit level (no CLI or account needed) — fails on base

1. Save command-router.issue-2291.test.ts as apps/host-daemon/src/command-router.issue-2291.test.ts. It builds a real CommandRouter whose listModels throws the exact AgentRuntimeRecoveryError the runtime produces for an ACP authRequired rejection, then sends a provider.list_models online RPC.
2. Run it:

   cd apps/host-daemon && pnpm exec vitest run src/command-router.issue-2291.test.ts

3. Expected: the response is { ok:false, errorCode:"auth_required" }, the debug accounting line fires, and logger.warn is never called. Actual on 494f66526 (full output):

   AssertionError: expected [ { fields: { …(2) }, …(1) } ] to deeply equal []
   + [
   +   {
   +     "fields": {
   +       "err": AgentRuntimeRecoveryError {
   +         "message": "ACP agent is not authenticated.",
   +         "code": "auth_required",
   +         "recovery": { "kind": "authRequired", "providerId": "acp-cursor", "retryable": false, … },
   +       },
   +       "type": "provider.list_models",
   +     },
   +     "message": "online host RPC failed",
   +   },
   + ]
    ❯ src/command-router.issue-2291.test.ts:93:23

   The first two assertions (typed response, debug line) pass — only the warn is wrong.

/**
 * Issue #2291 reproduction.
 *
 * The ACP bridge rejects `model/list` with a typed `authRequired` recovery
 * hint when the agent's model-list CLI reports "Authentication required".
 * The agent runtime turns that into `AgentRuntimeRecoveryError` with
 * `code: "auth_required"`, which the daemon's `CommandRouter` receives from
 * `provider.list_models`. This test drives the router through exactly that
 * failure and checks what it logs.
 *
 * On 494f66526 (main) the second assertion FAILS: the router logs
 * `online host RPC failed` at warn level for the auth_required outcome even
 * though the same outcome is returned to the server as a typed
 * `{ ok: false, errorCode: "auth_required" }` response and logged there.
 */
import { AgentRuntimeRecoveryError } from "@bb/agent-runtime";
import { describe, expect, it, vi } from "vitest";
import {
  DISPATCH_TEST_BRIDGE_LAUNCH,
  fetchDispatchTestArtifact,
  makeTempDir,
  unexpectedProjectAttachmentFetch,
  unexpectedProviderMaintenance,
} from "../test/command/dispatch-helpers.js";
import { CommandRouter } from "./command-router.js";
import { noopEventSink } from "./command-dispatch-support.js";
import type { RuntimeManager } from "./runtime-manager.js";

const ACP_MODEL_LIST_AUTH_MESSAGE = "ACP agent is not authenticated.";

describe("issue #2291: provider.list_models auth_required logging", () => {
  it("returns auth_required to the server and does not warn for it", async () => {
    const dataDir = await makeTempDir("bb-issue-2291-");
    const logger = { debug: vi.fn(), warn: vi.fn() };
    const router = new CommandRouter({
      dataDir,
      fetchProjectAttachment: unexpectedProjectAttachmentFetch,
      fetchPluginHostArtifact: fetchDispatchTestArtifact,
      // provider.list_models never touches the runtime manager.
      runtimeManager: {} as RuntimeManager,
      eventSink: noopEventSink,
      ...unexpectedProviderMaintenance,
      listModels: async () => {
        // What `@bb/agent-runtime` throws when the bridge rejects with
        // `error.data.recovery = { kind: "authRequired" }`.
        throw new AgentRuntimeRecoveryError({
          code: "auth_required",
          message: ACP_MODEL_LIST_AUTH_MESSAGE,
          recovery: {
            kind: "authRequired",
            message: ACP_MODEL_LIST_AUTH_MESSAGE,
            retryable: false,
            providerId: "acp-cursor",
          },
          cause: new Error(ACP_MODEL_LIST_AUTH_MESSAGE),
        });
      },
      threadStorageRootPath: dataDir,
      logger,
    });

    const response = await router.handleOnlineRpcRequest({
      type: "host-rpc.request",
      requestId: "issue-2291",
      command: {
        type: "provider.list_models",
        providerId: "acp-cursor",
        bridgeLaunch: DISPATCH_TEST_BRIDGE_LAUNCH,
      },
    });

    // The typed outcome reaches the server intact (this part already works).
    expect(response).toMatchObject({
      ok: false,
      commandType: "provider.list_models",
      errorCode: "auth_required",
      errorMessage: ACP_MODEL_LIST_AUTH_MESSAGE,
    });
    // The debug-level failure accounting still fires.
    expect(logger.debug).toHaveBeenCalledWith(
      expect.objectContaining({
        commandType: "provider.list_models",
        errorCode: "auth_required",
        ok: false,
      }),
      "Online host RPC",
    );
    // Issue #2291: on main this assertion fails because the router also
    // warns "online host RPC failed" for the auth_required outcome.
    const warnCalls = logger.warn.mock.calls.map(
      ([fields, message]) => ({ fields, message }),
    );
    expect(warnCalls).toEqual([]);
  });
});

4b. Live (needs a Cursor CLI whose --list-models is rejected)

1. Confirm the CLI state with no bb involved (cursor-list-models-persistence.sh):

   $ zsh cursor-list-models-persistence.sh
   cursor-agent version: 2026.06.19-20-24-33-653a7fb
   cursor-agent status:  ✓ Login successful! Logged in (unable to fetch user details)
   run 1 exit=1 elapsed=1.42s :: Error: Authentication required. Run 'agent login', pass --api-key/--auth-token, or set CURSOR_API_KEY/CURSOR_AUTH_TOKEN.
   run 2 exit=1 elapsed=0.41s :: Error: Authentication required. …
   run 3 exit=1 elapsed=0.44s :: Error: Authentication required. …
   run 4 exit=1 elapsed=0.41s :: Error: Authentication required. …

2. Start a dev instance from the worktree: scripts/bb-dev-app current, then eval "$(scripts/bb-dev-app env)". Note: no warn appears on daemon start by itself (inspect-dev-instance.sh showed zero warn lines 100 s after "Host plugin worker ready"); the probe is driven by a client reading execution options, which the desktop app does immediately on (re)connect.
3. Read execution options for Cursor four times, 4 s apart (trigger-probes.sh):

   $ curl -s "$BB_SERVER_URL/api/v1/system/execution-options?providerId=acp-cursor"
   read 1: 1066ms :: modelLoadError={'providerId': 'acp-cursor', 'code': 'auth_required'} models=[] :: daemon warns so far=0 server warns so far=0
   read 2:  448ms :: modelLoadError={'providerId': 'acp-cursor', 'code': 'auth_required'} models=[] :: daemon warns so far=1 server warns so far=1
   read 3:  421ms :: modelLoadError={'providerId': 'acp-cursor', 'code': 'auth_required'} models=[] :: daemon warns so far=3 server warns so far=2
   read 4:  596ms :: modelLoadError={'providerId': 'acp-cursor', 'code': 'auth_required'} models=[] :: daemon warns so far=3 server warns so far=3
   (counts lag by one line because grep ran before the last pino flush; final totals below are 4 and 4)

   Expected (per the issue): at most one daemon warn per daemon session, and a model list populated from declared fallbacks. Actual: one daemon warn and one server warn per read, models: [] every time:

   host-daemon.1.log:
   {"level":40,"time":1787597947647,"component":"host-daemon","type":"provider.list_models","err":{"type":"AgentRuntimeRecoveryError","message":"ACP agent is not authenticated.","code":"auth_required","recovery":{"kind":"authRequired","providerId":"acp-cursor","retryable":false},"cause":{"type":"JsonRpcResponseError","code":-32000,…}},"msg":"online host RPC failed"}
   {"level":40,"time":1787597952214, … "msg":"online host RPC failed"}
   {"level":40,"time":1787597956767, … "msg":"online host RPC failed"}
   {"level":40,"time":1787597961474, … "msg":"online host RPC failed"}
   server.1.log:
   {"level":40,"time":1787597947655,"component":"server","errorCode":"auth_required","errorMessage":"ACP agent is not authenticated.","errorStatus":502,"errorRetryable":false,"hostId":"host_f5y3w5zzsd","providerId":"acp-cursor","msg":"Failed to resolve provider models"}
   … ×4

Repro files: 2291/repro/ · raw logs: 2291/

5. Root cause

The log line. The daemon router warns for every online-RPC failure except an allow-list of two codes:

// apps/host-daemon/src/command-dispatch-support.ts#L123-L133
const EXPECTED_ONLINE_RPC_FAILURE_CODES = new Set([
  "file_too_large",
  "provision_cancelled",
]);
export function isExpectedOnlineRpcFailureError(error: unknown): boolean {
  return isExpectedCommandDispatchError(error) ||
    EXPECTED_ONLINE_RPC_FAILURE_CODES.has(getErrorCode(error));
}

// apps/host-daemon/src/command-router.ts#L129-L152
} catch (error) {
  const errorCode = getErrorCode(error);
  if (!isExpectedOnlineRpcFailureError(error)) {
    this.logger.warn({ type: message.command.type, err: error }, "online host RPC failed");
  }
  this.logOnlineRpc({ commandType, errorCode, handlerMs, ok: false });
  return { type: "host-rpc.response", …, ok: false, errorCode, errorMessage };
}

Links: dispatch-support#L123-L133, command-router#L111-L152. The chain that produces the auth_required code at base is fully typed, no regex: bridge AcpModelListAuthRequiredError → JSON-RPC error with data.recovery = { kind:"authRequired" } (bridge.ts#L1035-L1053) → JsonRpcResponseError.recovery → runtime actOnRejection case authRequired throws AgentRuntimeRecoveryError({ code:"auth_required" }) (runtime.ts#L625-L628) → daemon getErrorCode reads error.code. Since the server turns the response into a 502 ApiError with the same code and logs it with host/provider context (execution-options.ts#L575-L597), the daemon warn carries no information the server line lacks — it is duplicate, and uglier (it dumps two nested stacks).

Why it fires "on every daemon start". The server's model-probe memo key includes the daemon session id and never memoizes failures (#L607-L641), and the app reads execution options on every thread open / focus / reconnect. A fresh daemon session therefore always gets a fresh probe as soon as a client is connected, and an agent whose list command is rejected fails that probe every time. This is not a startup race: the probe's only external dependency is the agent's list CLI, run via execFile with no ACP session, no initialize, no authenticate (bridge.ts#L786-L815). The issue's "+650 ms" is the CLI's own runtime.

Deeper/underlying issue (outside bb's code). On this machine the Cursor CLI is in a split state: cursor-agent status says "Logged in" but cannot fetch user details, and --list-models is rejected. That is a stale/expired Cursor credential, which bb correctly reports as auth_required; the Cursor row in the picker shows "Authentication is required" and no models. The reporter's "next probe succeeds" would need a Cursor-side token refresh that happens between probes — possible, but nothing in bb waits for or causes it. If it is real on the reporter's host, a retry-with-backoff in the server would be the fix for the symptom they care about (empty picker until the next open), and the daemon warn would be a side-effect of that.

6. Proposed fix (first principles)

Confident about the log line. The daemon should not warn for a failure it has already classified into a typed code that the server owns the policy for. Two options, smallest first:

1. Allow-list the typed code (what PR #2294 does): add "auth_required" (and, by the same logic, "rate_limited", the only other AgentRuntimeRecoveryError code) to EXPECTED_ONLINE_RPC_FAILURE_CODES in apps/host-daemon/src/command-dispatch-support.ts. Risk: it silences the daemon warn for every online RPC type that throws that code, not just provider.list_models — today that is the provider maintenance commands (provider.list_models/usage/installation.*) and any plugin.host.call whose error object happens to carry code === "auth_required". All of those return the code to the server, which logs or surfaces it, so this is acceptable, but it should be stated.
2. Type-based: treat error instanceof AgentRuntimeRecoveryError as expected in isExpectedOnlineRpcFailureError. Narrower (only runtime-typed recovery rejections, which by construction are user/provider state, never daemon bugs) and does not depend on a string code that other layers could reuse. The daemon already imports from @bb/agent-runtime.

Either way the regression test must construct the error the way the runtime does (a typed code property), not a bare new Error("ACP agent is not authenticated.") — the message-regex classifier was removed in e42a4ef48 and must not come back. The repro test above is a suitable regression test as-is (it passes with either fix; verified for option 1). No wire change, so no HOST_DAEMON_PROTOCOL_VERSION bump. Do not touch the server's warn or the auth_required fallback policy.

7. PR review

PR #2294 · "Treat auth-required probe failures as expected online RPC failures" (head 192a39a20, based on fff3ae8)

What it changes: adds "auth_required" to EXPECTED_ONLINE_RPC_FAILURE_CODES with a comment (6 lines), and adds one test asserting isExpectedOnlineRpcFailureError(new Error("ACP agent is not authenticated.")) and the Cursor CLI prose are true.

Root cause vs symptom: the source change is the correct, minimal fix for the duplicate log line (option 1 above) and is at the right layer (daemon owns its own logging; server keeps the policy). It does not, and does not claim to, address the "first probe fails, second succeeds" behaviour, which I could not confirm exists.

Tests I ran: git cherry-pick pr-2294 onto 494f66526 (conflict in the test file; resolved by keeping base content + the PR's new test, saved as pr-2294-command-dispatch-support.test.resolved.ts); pnpm exec vitest run src/command-dispatch-support.test.ts src/command-router.issue-2291.test.ts → PR test 1 failed, my router repro passed (so the 1-line source change does silence the warn on main). CI on the PR: no checks recorded (statusCheckRollup: [], mergeable UNKNOWN at review time).

Verdict: REQUEST CHANGES. Keep the one-line source change (or switch to the instanceof AgentRuntimeRecoveryError form), rebase onto main, replace the test with one that throws a typed auth_required error through the router, and drop the "auth handshake race" wording.

8. Related issues

• #1688 (closed) Cursor Grok 4.6 hidden from the primary picker — same cursor-agent --list-models probe path (fixture issue-1688-cursor-list-models.txt in the ACP bridge).
• #1758 (closed) github plugin latched needs-configuration on one transient auth failure — the opposite failure mode; relevant if the server ever starts memoizing auth_required probe failures.
• #2306 (open) Spawn falls back to Codex when a project has no remembered provider even if Codex has no models — another consumer of modelLoadError/empty model lists.
• #2325 (merged, e42a4ef48) Provider plugins: one API — removed the daemon's message regex that PR #2294's test depends on; introduced the typed AgentRuntimeRecoveryError.
• Precedent for the allow-list: commit 4c7d2a97d "fix: silence expected provision cancellation RPC failures" (2026-06-10) introduced EXPECTED_ONLINE_RPC_FAILURE_CODES.

9. Appendix

Files

• repro/command-router.issue-2291.test.ts — unit repro (fails on base, passes with PR #2294's source change).
• repro/repro-test-base-output.txt — vitest output on base.
• repro/cursor-list-models-persistence.sh, cursor-list-models-persistence.log, cursor-list-models-{1..4}.txt — standalone CLI runs.
• repro/inspect-dev-instance.sh, repro/trigger-probes.sh, trigger-probes-run1.log, execution-options-{1..4}.json — live repro.
• daemon-warn-lines.jsonl, server-warn-lines.jsonl — the warn lines from my instance's logs.
• pr-2294-tests-on-base.log, repro/pr-2294-command-dispatch-support.test.resolved.ts — PR review evidence.
• install.log, build.log, dev-app-start.log, dev-stop.log.

Full first daemon warn entry (stacks trimmed)

{
 "level": 40, "time": 1787597947647, "component": "host-daemon", "serverUrl": "http://127.0.0.1:19723",
 "type": "provider.list_models",
 "err": {
  "type": "AgentRuntimeRecoveryError", "message": "ACP agent is not authenticated.",
  "stack": "AgentRuntimeRecoveryError: ACP agent is not authenticated.\n    at toRecoveryError (packages/agent-runtime/src/runtime.ts:663:12)\n    at actOnRejection (packages/agent-runtime/src/runtime.ts:627:15)\n    at sendRequestWithRecovery (packages/agent-runtime/src/runtime.ts:580:20)\n    at async Object.listModels (packages/agent-runtime/src/runtime.ts:2472:22)\n    at async RuntimeManager.withProviderMaintenanceRuntime (…)",
  "cause": {
   "type": "JsonRpcResponseError", "message": "ACP agent is not authenticated.", "code": -32000,
   "recovery": { "message": "ACP agent is not authenticated.", "kind": "authRequired", "retryable": false }
  },
  "code": "auth_required",
  "recovery": { "message": "ACP agent is not authenticated.", "providerId": "acp-cursor", "kind": "authRequired", "retryable": false }
 },
 "msg": "online host RPC failed"
}

Daemon debug accounting lines for the same four probes

{"level":20,"time":1787597947654,"commandType":"provider.list_models","errorCode":"auth_required","handlerMs":1036.7,"ok":false,"msg":"Online host RPC"}
{"level":20,"time":1787597952214,"commandType":"provider.list_models","errorCode":"auth_required","handlerMs":420,"ok":false,"msg":"Online host RPC"}
{"level":20,"time":1787597956767,"commandType":"provider.list_models","errorCode":"auth_required","handlerMs":389.8,"ok":false,"msg":"Online host RPC"}
{"level":20,"time":1787597961474,"commandType":"provider.list_models","errorCode":"auth_required","handlerMs":569.6,"ok":false,"msg":"Online host RPC"}

Commands run (in order)

gh issue view 2291 --repo get-bb/bb --json …   # no comments on the issue
pnpm install --frozen-lockfile --prefer-offline
git checkout 494f66526 && pnpm exec turbo run build
gh pr view 2294 --json … ; gh pr diff 2294
git log -S auth_required -- apps/host-daemon/src/command-dispatch-support.ts   # e42a4ef48, 0a62319b8
git show e42a4ef48 -- apps/host-daemon/src/command-dispatch-support.ts         # ACP_AUTH_REQUIRED_PATTERN removed
git fetch origin main; git log 494f66526..origin/main -- <relevant paths>     # empty
git fetch origin pull/2294/head:pr-2294; git merge-tree --write-tree --name-only 494f66526 pr-2294   # CONFLICT in test file
cursor-agent status; cursor-agent --list-models (×5)
cd apps/host-daemon && pnpm exec vitest run src/command-router.issue-2291.test.ts     # FAIL on base (expected)
scripts/bb-dev-app current; eval "$(scripts/bb-dev-app env)"
zsh inspect-dev-instance.sh; zsh trigger-probes.sh 4 4
git checkout -b issue-2291-pr-2294-on-base 494f66526; git cherry-pick pr-2294  # conflict; resolved
pnpm exec vitest run src/command-dispatch-support.test.ts src/command-router.issue-2291.test.ts   # PR test fails, repro passes
git cherry-pick --abort; git checkout 494f66526
gh search issues --repo get-bb/bb "not authenticated" / "auth_required" / "list_models cursor"
pnpm dev:stop; rm -rf <my dev data dir>; lsof -nP -iTCP -sTCP:LISTEN | grep -E '11723|19723|27723'