# Root-cause the attribution batch hang

## Context

The de-flake job (2026-09-08, `a32612a`→`fea2996` on `one-core/phase-1`) fixed three of four
e2e flakes. The fourth reproduces: `editor/e2e/attribution.spec.ts:349` "Run from the video
page runs that video and no other" fails 1-2 in 10 under `--repeat-each 10`, waiting the full
90 s for the batch's closing "1 done" line. It runs through `runOperationBatch`, the runner
Phase 1.2 introduced, so a batch that never finishes after its unit's write is a candidate
production bug and could surface on operator gate A. The operator chose to root-cause it
before merge. Land on `one-core/phase-1` (same branch as the de-flake commits; cherry-picks
to `main` cleanly).

## What is known, and why it does not add up

Recorded in `plans/STATE.md` ("The fourth REPRODUCED") from the earlier experiment:

1. Server log on every failure ends on three lines: the "Backfill attribution-channel …"
   header, "Attribute attrvid0002: 120 cues → 1 chunk(s), text-only.", and the ollama
   timing line. The unit's closing "Attribute attrvid0002 (text-only): …" line never appears.
2. The freshness pill reads "current", so `attribution.json` was written.
3. `/api/pulse` answered with an unchanging `rev` for 90 s, so the job record never moved.

The code says these three cannot all be true. `common/controller/attributeOne.ts:306-314`:
`await writeAttribution(...)` then `log(...)` are adjacent statements; `log` is
`opts.onLog` = `task.onLog` (`operationBatch.ts:1768`) → `taskHooks.ts:87-104` forwards first
→ the job's `onLog` (`common/jobs/streamCommand.ts:311-315`) which is a synchronous
`fileStream.write` + `safeEnqueue`. `writeAttribution` (`common/lib/attribution-server.ts:40-48`)
is `writeFile(tmp)` + `rename`, no lock, no hook. So if (2) then the closing line reached the
log FILE, even if the SSE stream was already closed (`safeStreamController.ts:28-41` drops
silently after `cancel()` → `markClosed()`, `streamCommand.ts:289-295`). The two panel-side
"reconcile against the file" attempts were reverted with "the file has no more than the
panel" — that reading was taken when the stream ended, which under hypothesis 1 below is
BEFORE the batch continues. At least one of (1)–(3) is a measurement artifact; the plan's
first job is to find which.

## Code path (verified 2026-09-08 at `fea2996`)

1. Button: `editor/app/channels/[slug]/videos/[id]/components/SpeakerBodies.tsx:246-252` →
   `runOperationForVideoAction` (`operationActions.ts:26-56`: `kindIds:[op]`, `ids:[videoId]`).
2. Client: `common/components/StreamActionLog.tsx:127-163` reads the stream until `done`,
   then `setRunning(false)` and `router.refresh()` (`:163`). The 1 s status poll (`:101-126`)
   runs only while `running`.
3. Job: `common/controller/operationJobs.ts:78-152`, `runManagedFunction` on
   `BACKFILL_QUEUE`; the "N done" summary is `:128-146`, after `runOperationBatch` returns.
4. Stream/registry: `common/jobs/streamCommand.ts:264-370`; finalize `:338-362` →
   `registry.finalize` (`common/jobs/registry.ts:202-218`).
5. Batch: `common/controller/operationBatch.ts:1544`; `next()` `:1682-1710`; `runOne`
   `:1751-1785`; `runPool` call `:1799-1826` with `limit()` `:1801-1824`, `finite: true`.
6. Pool: `common/jobs/concurrentRunner.ts:82-133`. If `limit()` reads 0 when the last unit
   settles, `:92-93` waits forever and the finite-exhaustion break (`:104-108`) is
   unreachable. Every 0 from `backfillLaneLimit` (`operationBatch.ts:313-410`) carries a
   `hold` whose message is logged edge-triggered at `:1806-1812` — a line the failures
   do NOT show, which argues against this path unless that log was also lost.
7. Unit: `runOperationUnit` `:947-1058` → `executeUnit` `:1066-1110` (`acquireLlmSlot`
   `:1086`, `op.run` `:1090`, release in `finally` `:1106-1110`) → `attributeOne.ts:124`;
   engine call `common/lib/digestApps.ts:168-270` (`await res.json()` at `:220` precedes the
   timing log at `:255`, so the body is drained; stub `editor/e2e/fixtures/ollama-stub.mjs:204-221`).
8. Pulse: `editor/app/api/pulse/route.ts:65-118` folds `id:status:startedAt:endedAt:
   draining:progress:tasks.length` per job off `globalThis.__yttJobRegistry__`.

## Hypotheses, ranked, each with the observation that decides it

| # | Hypothesis | Blocking point | Decided by |
|---|---|---|---|
| H1 | The SSE stream is torn down early (RSC/action teardown from a pulse-driven `router.refresh()`); the batch finishes normally but the panel froze, so the test's 90 s wait on the panel text never sees "1 done". Pill reads "current" because `router.refresh()` at `:163` re-rendered. (3) was misread. | none in the server | server-side: closing line + summary present in the job log FILE with timestamps after the client's `cancel()`; `record.status` becomes `done` |
| H2 | `limit()` returned 0 at the wake after the unit settled; `runPool` idle-waits forever. | `concurrentRunner.ts:93` | per-wait trace shows `target=0, inFlight=0, drain=false`; hold line at `operationBatch.ts:1806` in the file |
| H3 | The unit promise never settles after `op.run` returns (LLM slot release, `task.end()`, `reportProgress`). | `operationBatch.ts:1106-1110` or `:1779-1783` | `runOne`'s `finally` timestamp missing while `attributeOne.ts:314` timestamp present |
| H4 | Finalize skipped or registry global replaced, so pulse folds a stale/empty list while the batch is actually done. | `streamCommand.ts:338-362`, `invalidate-cache` route | `/api/jobs/<id>/log` status after the failure: `done` vs `running` |
| H5 | A late abort (previous test's `cancelLiveJobs`) fired `opts.signal`, `runPool` broke without the summary. | `runPool` exit | `signal.aborted === true` at pool exit |

## Step 1 — Instrumented reproduction (worktree only, never committed)

Worktree of `fea2996` per `plans/FACTS.md` (composed fixture site copied into
`export/public`; add-by-path rule irrelevant since nothing is committed from it). Set
`stdout: "pipe"`/`stderr: "pipe"` on the editor webServer in the worktree's
`editor/playwright.config.ts`. All instrumentation goes to `console.error` with an ISO
timestamp and the job id, never through the job's `onLog` (which is part of what is under
test):

- `common/controller/attributeOne.ts:306` and `:315` — before `writeAttribution`, after the
  closing `log` call.
- `common/jobs/streamCommand.ts:311` — per `onLog`: line counter, `safe.isClosed()`,
  first 60 chars. `:289` — the `cancel()` with timestamp. `:338/:351/:362` — which settle
  branch ran and `record.status`.
- `common/jobs/concurrentRunner.ts:88-93` — per wait iteration: `target`, `inFlight.size`,
  `drainSignal.aborted`, `signal.aborted`, `finite`.
- `common/controller/operationBatch.ts:1783` (unit `finally`) and `:1826` (after `runPool`).
- `editor/e2e/attribution.spec.ts:349` — on failure only (wrap the "1 done" expect in
  try/catch, rethrow): fetch `/api/jobs/<id>/log` (job id from the panel's `data-*` or the
  status poll URL, see `StreamActionLog.tsx:101-126`) and `/api/pulse`, print status, line
  count and the last five lines to the test output; then rethrow.

Run: `node ../scripts/queue-lock.mjs --ports PORT:3011,EXPORT_PORT:3010,OLLAMA_STUB_PORT:11435
-- pnpm exec playwright test attribution.spec.ts --repeat-each 15` from the worktree's
`editor/`, detached, watched with Monitor. Expected 1-3 failures. Collect, for each failure,
the ordered stderr trace for that job id and the test's failure dump, and decide H1–H5 by
the table. If 15/15 pass, run once more with `--repeat-each 25`; if still clean, the
instrumentation changed the timing — drop the `concurrentRunner` trace (the noisiest) and
re-run 15. Stop after three attempts and record "unreproduced under instrumentation" with
the run log paths.

## Step 2 — Fix at the cause (one commit, with a test that fails before it)

Exactly one of these, chosen by Step 1; do not ship a fix for a hypothesis the trace killed.

- **H1 (test/UI-side):** the product is correct (the batch finished, disk is right), the
  panel is not: after the stream ends `StreamActionLog` must show the job's terminal state.
  Fix in `common/components/StreamActionLog.tsx:141-163`: when `reader.read()` returns
  `done` and the job is not terminal per the status poll, keep polling `/api/jobs/<id>/log`
  until it is, and render its tail (the file has every line, `streamCommand.ts:311`). Test:
  a unit test for the reconcile (or an e2e route mock that cancels the stream early) that
  fails at `fea2996`. Also fix the trigger if it is ours: if the teardown comes from the
  pulse-driven refresh re-rendering the panel, gate that refresh while a run is streaming.
  (The de-flake implementer tried two reconcile variants and measured no change — but its
  measurement read the file at stream end, before the batch continued. A reconcile that
  keeps polling until terminal is a different fix; verify against the trace, not the memo.)
- **H2:** find why `backfillLaneLimit` (or `isGateHeld`) reads 0 after the unit — the trace
  says which term. Fix that term (e.g. a settings read racing the test's `writeSettings`, or
  `transcriptionActivity()` seeing a stale worker). Do NOT change `runPool`'s hold
  semantics ("a zero limit is a hold, never a stop", `operationBatch.ts:22-25`). Add a
  `concurrentRunner.test.ts` case only if the runner itself is at fault.
- **H3:** the pending await in `executeUnit`'s `finally` or `runOne`; fix and add a unit test
  in `common/controller/` that runs a unit whose engine call resolves and asserts the pool
  exits.
- **H4:** make finalize unconditional (`streamCommand.ts:338-362`, a throwing `onLog` in
  `.catch` must not skip `registry.finalize`) or stop `invalidate-cache` from replacing the
  global registry under a live job. Unit test in `common/jobs/`.
- **H5:** `resetData` ordering / `cancelLiveJobs` aborting a record the next test owns;
  fix in `editor/app/api/test/invalidate-cache/route.ts` or `editor/e2e/helpers.ts`.

Remove every instrumentation line before committing; `git diff fea2996 --stat` in the
primary checkout must list only the fix, its test, and the plan records.

## Step 3 — Records

- `plans/STATE.md`: replace "The fourth REPRODUCED, is NOT fixed" with what it was, the
  discriminating trace excerpt (≤ 8 lines), and the fix sha. If the earlier claim "the log
  file has no more than the panel" was the artifact, say so, so nobody trusts it again.
- `plans/deflake-e2e.md`: a "### 4, as shipped" section with the same.
- `plans/FACTS.md` one-core Phase 1 section: one paragraph on the runner/stream fact
  learned (whichever hypothesis held), file:line pinned to the fix sha.

## Not in scope

- Any change to lane hold semantics, `retries`, `test.slow`, or serial markers.
- The homepage theme test's early read (`homepage/e2e/theme.spec.ts:47`), noted in the
  de-flake review as a weakened assertion, not a flake.
- Phase 2 of one-core.

## Verification

- `tsc --noEmit` in common, export, editor; `pnpm --filter yt-dlp-transcript-common test`
  (the new test fails at `fea2996`, passes at the fix — show both runs).
- `attribution.spec.ts --repeat-each 20` from a worktree at the fix sha, no instrumentation:
  20/20 (baseline was 1-2 failures per 10, so 20 clean runs is the bar, not 10).
- Full editor e2e from the worktree at the final sha, detached, Monitor-watched: 515/515.
- Commit shape: (1) the fix + its test, message carrying the trace excerpt and the 20/20;
  (2) `plans:` records. Trailers as on the de-flake commits. Never `git add -A`
  (`editor/content` symlink).

## Execution

Per the standing cadence: one Opus general-purpose implementer with the fish/`commit -F`,
no-boot-against-`transcripts/`, detached-e2e and DO-NOT-POLL (Monitor) instructions;
report contract = commit shas, exact gate outputs, the decisive trace lines, which
hypothesis held and which were killed, every divergence. A second Opus agent reviews the
diff before the final full e2e.

## Outcome (2026-09-08, `fae99f1`)

The cause was none of H1–H5 but a sixth mechanism outside the table: the job finished normally
in 65 ms with every line written and `done` recorded, and React then UNMOUNTED the log panel —
`SpeakerBodies.tsx`'s two branches put the unkeyed `<RunOne>` at different child indices, so
the record landing (on the `router.refresh()` `StreamActionLog` fires itself) hit a positional
type mismatch and destroyed `StreamActionLog`'s state, `<pre role="log">` and all. H1's
disposition held (server innocent, failure client-side) but its mechanism did not, and the
log-file-polling fix prescribed for it was NOT shipped and would not have worked.

Fixed by giving both bodies one two-child list with `RunOne` last and keyed; the spec now
asserts the log still reads "1 done" after the freshness pill reads "current" (red 5/5 at
`fea2996`, `--repeat-each 20` green at the fix). Full record, trace and the durable rule:
[`deflake-e2e.md`](deflake-e2e.md)'s "### 4, as shipped" and `FACTS.md`.