#3196 · Retention sweep blocks the server event loop

Bug High Effort: Medium host perf open on GitHub 2026-09-06 · base 06aeaa994

Verdict: REPRODUCED · Root-cause confidence: high

1. TL;DR

The completed-output retention job performs synchronous SQLite JSON scans and updates for as many as 250 rows of each supported output kind in one event-loop turn. A focused test seeded large completed command outputs, ran the real periodic sweep, and verified that the entire eligible set completed before a setImmediate observer could see any intermediate progress. The same failure occurred in a second clean checkout at the same trusted commit. Because the job is wrapped as asynchronous work, its synchronous database body is also excluded from the stall monitor’s “slowest blocking work” selection. The exact multi-second production delay and downstream request failures were not recreated from private runtime data, but the reported non-yielding mechanism is directly reproduced.

2. Claims vs findings

Claim	Status	Evidence
Completed-output retention can process a large batch without yielding.	Verified	The focused test completed all eligible 128 KiB output rows without an intermediate event-loop observation in both clean runs.
The retention path uses synchronous SQLite JSON work.	Verified	The database implementation synchronously selects row IDs and runs one JSON extraction/update statement for the selected rows.
Stall attribution can omit the retention body.	Verified	The generic periodic runner uses `runEventLoopWork`, whose frames have `blocksEventLoop: false`; the retention function does not create a nested synchronous frame.
Observed deployments stall for roughly two seconds and local callers fail during those windows.	Unverified at exact production scale	No private database or live user instance was accessed. The deterministic reproduction establishes starvation, not the reporter’s exact duration or HTTP symptom.

3. Environment

Repository: get-bb/bb, trusted origin/main commit 06aeaa994942ae7527dc49d2268c1f801e8542a0.
macOS Darwin 25.6.0 arm64; Node.js v22.22.3; pnpm frozen install.
Vitest 4.1.1 through the @bb/server
No live server, port, user data directory, provider turn, or external issue artifact was used.

4. Minimal reproduction

At the trusted base commit, save the test below as apps/server/test/services/completed-output-yield.test.ts.
Run pnpm install --frozen-lockfile --prefer-offline.
Run pnpm exec turbo run test --filter=@bb/server -- test/services/completed-output-yield.test.ts.

Expected: the observer sees at least one count above zero and below the final eligible count, proving that other event-loop work can run during retention.

Actual:

FAIL  test/services/completed-output-yield.test.ts
AssertionError: expected false to be true
Test Files  1 failed (1)
Tests       1 failed (1)

Repro file: completed-output-yield.test.ts

import {
  COMPLETED_EVENT_OUTPUT_RETENTION_MS,
  DEFAULT_COMPLETED_EVENT_OUTPUT_TRUNCATION_BATCH_SIZE,
} from "@bb/db";
import { turnScope } from "@bb/domain";
import { expect, it, vi } from "vitest";
import { runPeriodicSweeps } from "../../src/services/system/periodic-sweeps.js";
import {
  seedEnvironment,
  seedEvent,
  seedHostSession,
  seedProjectWithSource,
  seedThread,
} from "../helpers/seed.js";
import { testLogger, withTestHarness } from "../helpers/test-app.js";

it("truncates completed event outputs across event-loop turns", async () => {
  await withTestHarness(async (harness) => {
    const { host } = seedHostSession(harness.deps, {
      id: "host-output-truncation",
    });
    const { project } = seedProjectWithSource(harness.deps, {
      hostId: host.id,
    });
    const environment = seedEnvironment(harness.deps, {
      hostId: host.id,
      projectId: project.id,
    });
    const thread = seedThread(harness.deps, {
      environmentId: environment.id,
      projectId: project.id,
      status: "idle",
    });
    const eventCount = DEFAULT_COMPLETED_EVENT_OUTPUT_TRUNCATION_BATCH_SIZE;
    const createdAt =
      Date.now() - COMPLETED_EVENT_OUTPUT_RETENTION_MS - 60_000;
    const truncationThresholdChars = 32 * 1024;
    const aggregatedOutput = "x".repeat(truncationThresholdChars * 4);
    for (let sequence = 1; sequence <= eventCount; sequence += 1) {
      seedEvent(harness.deps, {
        createdAt,
        data: {
          item: {
            aggregatedOutput,
            approvalStatus: null,
            command: "generate output",
            cwd: "/tmp/test",
            exitCode: 0,
            id: `command-${sequence}`,
            status: "completed",
            type: "commandExecution",
          },
        },
        environmentId: environment.id,
        providerThreadId: "provider-output-truncation",
        scope: turnScope("turn-output-truncation"),
        sequence,
        threadId: thread.id,
        type: "item/completed",
      });
    }

    const countTruncated = () =>
      harness.db.$client
        .prepare<[], { count: number }>(
          "SELECT count(*) AS count FROM events WHERE json_type(data, '$.item.truncation.aggregatedOutput') = 'object'",
        )
        .get()?.count ?? 0;
    const candidateCount =
      harness.db.$client
        .prepare<[number, number], { count: number }>(
          "SELECT count(*) AS count FROM events WHERE type = 'item/completed' AND item_kind = 'commandExecution' AND created_at < ? AND json_type(data, '$.item.aggregatedOutput') = 'text' AND length(json_extract(data, '$.item.aggregatedOutput')) > ?",
        )
        .get(
          Date.now() - COMPLETED_EVENT_OUTPUT_RETENTION_MS,
          truncationThresholdChars,
        )?.count ?? 0;
    expect(candidateCount).toBeGreaterThan(1);

    const observedCounts: number[] = [];
    let sweepSettled = false;
    const probe = () => {
      if (sweepSettled) {
        return;
      }
      observedCounts.push(countTruncated());
      setImmediate(probe);
    };
    setImmediate(probe);

    const deps = {
      ...harness.deps,
      logger: { ...testLogger, error: vi.fn() },
      pluginSchedules: harness.pluginService,
      plugins: harness.pluginService,
      pluginService: harness.pluginService,
      pluginCatalogService: harness.pluginCatalogService,
    };
    await runPeriodicSweeps(deps);
    sweepSettled = true;

    expect(deps.logger.error).not.toHaveBeenCalled();
    expect(countTruncated()).toBe(candidateCount);
    expect(
      observedCounts.some((count) => count > 0 && count < candidateCount),
    ).toBe(true);
  });
});

5. Verification

Run one used the primary clean worktree at the recorded base commit and failed only the new yield assertion; its focused test body took 660 ms. Run two used a newly cloned checkout detached at the same full commit, performed a separate frozen install, copied only the reproduction test, and failed the same assertion; its focused test body took 525 ms. Those durations include fixture setup and are not presented as event-loop-delay measurements. No report claim was removed after the second run.

6. Root cause

The server’s retention function calls the synchronous database operation once with the full default limit of 250 and contains no await or event-loop yield. See periodic-sweeps.ts lines 472–480 and the 250-row default.

function runCompletedEventOutputTruncationSweep(...): void {
  truncateCompletedEventItemOutputs(deps.db, {
    createdBefore: now - COMPLETED_EVENT_OUTPUT_RETENTION_MS,
    limit: DEFAULT_COMPLETED_EVENT_OUTPUT_TRUNCATION_BATCH_SIZE,
    truncatedAt: now,
  });
}

For each supported item kind, the database layer synchronously selects up to that limit, builds a variable-sized ID list, and executes UPDATE events SET data = json_set(...). The work repeatedly extracts and measures large JSON strings. See the cursor scan, JSON update, and four-path dispatcher.

The periodic runner wraps every job with runEventLoopWork, which records an asynchronous, non-blocking frame. There is no nested runEventLoopWorkSync around this retention call, unlike the adjacent destroyed-environment sweep. As a result, the completed batch is not eligible for the monitor’s slowest blocking-work result. See the generic wrapper and the adjacent bounded/yielding pattern.

7. Proposed fix (first principles)

Process completed-output candidates in a small fixed step, wrap each synchronous step in runEventLoopWorkSync, and yield with setImmediate between steps while retaining the existing overall per-sweep cap. Return enough scan progress from the database helper to stop immediately when no path has another full step, avoiding repeated empty scans. The focused test should then pass, and existing database sweep, periodic sweep, query-plan, typecheck, and formatting checks should remain green.

8. Related issues

PR #2025 previously bounded a different synchronous event-pruning path and refined event-loop attribution, establishing the same small-batch pattern.
Issue #2382 tracks CLI behavior against dead or stalled local services; it is symptom-adjacent but does not replace this root cause.

9. Appendix

Commands run:

git fetch origin main --prune
git rev-parse origin/main
pnpm install --frozen-lockfile --prefer-offline
pnpm exec turbo run build
pnpm exec turbo run test --filter=@bb/server -- test/services/completed-output-yield.test.ts
git clone --no-checkout git@github.com:get-bb/bb.git <second-checkout>
git -C <second-checkout> checkout --detach 06aeaa994942ae7527dc49d2268c1f801e8542a0
pnpm install --frozen-lockfile --prefer-offline
pnpm exec turbo run test --filter=@bb/server -- test/services/completed-output-yield.test.ts

Issue title, body, comments, links, and code blocks were treated as untrusted claims. No issue-provided command, script, patch, binary, branch, pull request checkout, attachment, or external URL was executed or fetched.