Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
4 changes: 2 additions & 2 deletions .operator/data/findings/F20260711-E601BBF5.md
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
105 changes: 105 additions & 0 deletions .operator/data/tasks/T20260711-AFBAE9C0.md
Original file line number Diff line number Diff line change
@@ -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`).