From 0afda3773a36f8c6e13be152d4c4bb71b6d6c219 Mon Sep 17 00:00:00 2001 From: Operator Bot Date: Thu, 6 Aug 2026 23:28:38 +0100 Subject: [PATCH] Finding F20260711-E601BBF5: planner emitted child item(s) --- .operator/data/findings/F20260711-E601BBF5.md | 4 +- .operator/data/tasks/T20260711-AFBAE9C0.md | 105 ++++++++++++++++++ 2 files changed, 107 insertions(+), 2 deletions(-) create mode 100644 .operator/data/tasks/T20260711-AFBAE9C0.md diff --git a/.operator/data/findings/F20260711-E601BBF5.md b/.operator/data/findings/F20260711-E601BBF5.md index 90869fa..8d5859d 100644 --- a/.operator/data/findings/F20260711-E601BBF5.md +++ b/.operator/data/findings/F20260711-E601BBF5.md @@ -2,12 +2,12 @@ id: F20260711-E601BBF5 kind: finding title: Expired-lock reap in LocalIdempotencyGuard is a silent recovery — no logger, no WARN when a dead instance's lock is stolen -status: pending +status: in-progress priority: 4 source: resilience-boundaries#FINDING-001 created_at: '2026-07-11T03:00:06Z' +started_at: "2026-08-06T22:28:38Z" --- - **Severity**: medium **Priority**: 4 **Files Affected**: 2 diff --git a/.operator/data/tasks/T20260711-AFBAE9C0.md b/.operator/data/tasks/T20260711-AFBAE9C0.md new file mode 100644 index 0000000..96abf49 --- /dev/null +++ b/.operator/data/tasks/T20260711-AFBAE9C0.md @@ -0,0 +1,105 @@ +--- +id: T20260711-AFBAE9C0 +kind: task +title: Log expired-lock reaps in LocalIdempotencyGuard via an injected Logger +status: pending +priority: 4 +created_at: '2026-08-06T22:28:38Z' +parent_id: F20260711-E601BBF5 +--- + +# Log expired-lock reaps in LocalIdempotencyGuard via an injected Logger + +## Problem + +`LocalIdempotencyGuard` — the live `IdempotencyGuard` wired at `engine/entry.ts:133` and the +single primitive enforcing "one run per stage per scope" — steals expired locks silently. + +- `engine/infra/local/sqlite-guard.ts:36` bulk-purges every row with `expires_at < now` on + every `acquire`, with no log line. +- `engine/infra/local/sqlite-guard.ts:43-50` reaps a same-key expired row and re-acquires, + also with no log line. +- The constructor (`:25-29`) takes only `dbPath` — the class holds no `Logger` — and + `acquire` ignores its `_ctx` (`:31`). + +Callers observe only handle-vs-null (`engine/pipeline/run-stage.ts:198` with +`DEFAULT_LOCK_TTL_MS = 600_000`, `engine/engine/engine.ts:221` with a 6 h TTL, +`engine/agents/runtime.ts:156`), so they cannot distinguish "acquired a fresh lock" from +"stole a dead run's lock". A crash loop that repeatedly orphans and reaps stage locks is +invisible in the INFO/WARN stream. This violates the observability gate in +`intelligence/rules/typescript.md` §REQUIRED (every fallback / catch-and-continue path warns +with the reason) and the BLOCKER observability gate in `intelligence/rules/migration.md`. + +Note the asymmetry: the boot-time reap already logs — `engine/entry.ts:185-192` WARNs with the +count returned by `clearActiveLocks`. Only the mid-cycle per-`acquire` reap has no surface. + +## Solution + +1. **Inject a logger.** Add an optional `readonly log?: Logger` parameter to the + `LocalIdempotencyGuard` constructor (`engine/infra/local/sqlite-guard.ts:25`), typed via + `import type { Logger } from "../../logging/logger.js"`. This mirrors the existing + precedent at `engine/infra/workspace-init.ts:7` (type-only `Logger` import inside + `engine/infra/**`), so no new layer deviation is introduced. Keep the parameter optional so + existing construction sites and tests stay valid. + +2. **Wire it from the composition root.** `engine/entry.ts:133` — pass the already-constructed + `log` (available since `entry.ts:104`): + `new LocalIdempotencyGuard(resolve(stateDir, "guard.db"), log)`. + +3. **Emit the WARN where the reap actually happens — the bulk delete at `:36`.** + This is the important implementation detail: line 36 deletes every row with + `expires_at < now`, so an expired same-key row is already gone before control reaches the + `existing` branch at `:43`. Line 47 returns null for `expires_at > now`, leaving line 49 + reachable only in the degenerate `expires_at === now` tie. A WARN placed *only* in the + `:47-49` branch would practically never fire. + + Therefore: before running the bulk `DELETE`, `SELECT key, lock_id, acquired_at, expires_at, + completed FROM locks WHERE expires_at < ?` and, for each row with `completed = 0`, emit one + WARN naming the reaped `key`, the stolen `lockId`, its `acquired_at`, and the overrun past + `expires_at` in ms. Rows with `completed = 1` are ordinary dedup-window expiry, not orphan + recovery — do not WARN for them (a DEBUG line is acceptable). + + Keep the WARN in the `:47-49` branch as well for the tie case, so the reap path is covered + wherever it fires. + +4. **Constraints.** Do not change the reap behaviour itself — it is already TTL-bounded and + correct. Preserve the non-throwing contract of `acquire`. Log only through the injected + logger (no `console.*`); when no logger was supplied the class must behave exactly as today. + Thread `ctx` into the log data (rename `_ctx` to `ctx` at `:31` and include `traceId` / + `repoId`). `engine/infra/local/sqlite-guard.ts` must stay under the 300-line cap + (log/comment lines are excluded from the cap — do not strip logs to fit). + +5. **Out of scope.** `packages/adapters/src/kvstore-sqlite/local-storage-bundle.ts:169-196` + carries a structurally identical silent reap in its own `acquire`. It is a different + surface and is not the guard wired at `entry.ts:133` — leave it untouched so this change + stays revertible in one commit. + +## Affected Files + +- `engine/infra/local/sqlite-guard.ts:25` — add optional `readonly log?: Logger` constructor + parameter + type-only import. +- `engine/infra/local/sqlite-guard.ts:31` — rename `_ctx` to `ctx` and use it in log data. +- `engine/infra/local/sqlite-guard.ts:36` — capture expired rows before the bulk delete; WARN + once per reaped `completed = 0` row with `key`, `lockId`, `acquired_at`, overrun ms. +- `engine/infra/local/sqlite-guard.ts:47-49` — WARN on the same-key tie-case reap. +- `engine/entry.ts:133` — pass `log` into the `LocalIdempotencyGuard` constructor. +- `engine/infra/local/sqlite-guard.test.ts:23` — construct the guard with a fake logger; add + the regression test below. + +## Acceptance Criteria + +- `LocalIdempotencyGuard` accepts an optional `Logger` through constructor injection, wired + from `engine/entry.ts:133`; omitting it preserves current behaviour. +- `acquire` emits exactly one WARN per reaped orphan lock, including the reaped `key`, the + reaped `lockId`, its `acquired_at`, and how far past `expires_at` the reap occurred. +- Expiry of a `completed = 1` dedup row does NOT produce a WARN. +- Regression test in `engine/infra/local/sqlite-guard.test.ts` named for the bug scenario + (e.g. `"warns when an expired lock from a dead holder is reaped and re-acquired"`): + acquires a key with a ~1 ms TTL, waits past expiry (cf. the existing pattern at + `sqlite-guard.test.ts:63-72`), calls `acquire` for the same key, and asserts a WARN naming + that key and the reaped lockId was logged. The test must fail on pre-fix code (no logger + exists, no WARN is ever emitted) and pass after the fix. +- A second test asserts no WARN is emitted when only a completed dedup row expires. +- Coverage on `engine/infra/local/sqlite-guard.ts` stays >= 90%. +- `npm run typecheck && npm run lint && npm test` pass (lint includes `ts-prune` + `knip`). +