observability(recovery): emit backstop sweep-completion signal (BLO-29722)

[allyblockcast]

Thinking Path

• Paperclip is the open source app people use to manage AI agents for work
• The recovery subsystem runs two backstop loops that rescue work nothing else will wake: the resolved-dependency wake backstop and the stranded recovery-action backstop. They are the last line of defence for stranded issues, so their own health has to be legible.
• Both paginate with a keyset cursor and log "… past page limit" only while rows remain beyond the current page. The tick that drains the tail is silent.
• So the two states an operator most needs to tell apart — a sweep that rotates to completion, and a tail that is never reached — emit byte-identical logs: the same WARN, forever, at a cursor that looks pinned because the page-1 cursor recurs every cycle.
• That is not hypothetical. It was read as ~939 permanently starved wake candidates and filed as a starvation defect. A 37-minute sample of paperclip-0 shows both loops completing full sweeps roughly once a minute — the pagination was never broken, the observability was.
• This pull request logs the drain tick, and names the deferred count for what it actually is.
• The benefit is that "is this backstop starving?" becomes a question the logs can answer, instead of one that costs a multi-hour investigation to answer wrongly.

Linked Issues or Issue Description

Refs BLO-29722 (Paperclip board; no GitHub issue).

Related PR: #1131 (fix(recovery): wake-budget backstop claim/refund fences, BLO-22795) also edits server/src/services/recovery/service.ts (+484/−2), including the stranded-recovery backstop. It is stacked on cto/blo-19889-infra-class-continuation; this PR targets master and is 41 purely additive lines in two log branches, so it does not overlap #1131's claim/refund fences semantically. Whichever lands second should expect a small textual conflict in the two logger blocks and keep both changes.

Bug. reconcileResolvedDependencyWakeBackstop (server/src/services/recovery/service.ts:9061) and reconcileStrandedRecoveryWakeBackstop (:9443) guard their pagination log on candidateLimitSkipped > 0. Sweep completion is unobservable, and candidateLimitSkipped is surfaced under the key skipped, which reads as "dropped" when it means "deferred to the next tick".

Measured on paperclip-0, 13:22:02–13:59:16Z (61 liveness + 45 stranded emissions):

stream	states observed	interpretation
liveness	strictly alternating skipped=759 / cursor 6c6c3437 and skipped=259 / cursor c91888c9, never a third	N=1259, 3-page sweep, page 3 silent
stranded	45 consecutive identical skipped=158 / cursor bcfbae8a	N=658, 2-page sweep, page 2 silent

Both are healthy. Corroborated two independent ways: the gap from a 259 emission to the next 759 is 2.35× the gap the other direction (median 40 s vs 17 s, n=29 each) — the silent page sitting in between — and the liveness:stranded emission-count ratio is 1.356 against a predicted (2/3)/(1/2) = 1.333.

What Changed

• reconcileResolvedDependencyWakeBackstop: capture the pre-advance cursor; when candidateLimitSkipped === 0 and a cursor was in play, emit logger.info("issue graph liveness backstop completed resolved dependency wake candidate sweep") with processed, limit, sweptFromCursor, source.
• reconcileStrandedRecoveryWakeBackstop: the same, as "stranded recovery wake backstop completed candidate sweep".
• Both WARN payloads gain deferredToNextTick alongside the existing skipped, with a comment explaining that count(*) over() is evaluated after the cursor predicate so the value is "remaining beyond this page", not "dropped". skipped is retained so nothing consuming it breaks.

No control-flow, query, cursor-advance, or return-shape changes. Log-only.

Verification

• pnpm -F server typecheck — run locally on this branch: exit 0, 0 TypeScript errors.
• Log-level assertion (the signal this PR exists to create). On a worker whose candidate set exceeds 500, assert both lines appear per sweep interval:

  kubectl -n paperclip logs paperclip-0 --since=10m \
    | grep -E "backstop (deferred|completed)" \
    | sed -E 's/.*backstop (deferred|completed).*/\1/' | sort | uniq -c

  Before this change: only deferred. After: deferred and completed, with completed appearing at least once per sweep cycle (~75 s liveness, ~50 s stranded at current volumes). completed present ⇒ the tail drains. deferred firing with no completed across a full sweep interval is now the real starvation signature.
• Negative control. Drop the candidate set below 500 (or set the limit above it) and confirm neither line appears — the loop is then single-page and has no deferral to report. This distinguishes "drained" from "not measured", which is the failure mode this PR is about.

Not verified locally, stated plainly: the DB-backed suites (server/src/__tests__/issue-recovery-actions.test.ts) need a Postgres, and none is reachable in this environment (127.0.0.1:5432 ECONNREFUSED). No unit test is added: asserting the new line requires seeding 501+ rows to cross the page boundary, which is a poor fit for the existing fixtures. The durable assertion belongs on the gauge follow-up below, where the quantity is a number rather than a log line and can be asserted without crossing the page limit. CI gates on this PR are the verification path for the suites.

Risks

Low. Additive logging inside two existing branches; no query, control-flow, or cursor semantics change.

• Log volume: one extra info line per completed sweep per loop — at current volumes ~1/75 s and ~1/50 s on the worker. Bounded and small, but it is a new steady-state line at info.
• The new line is skipped on the wrap path (:9048/:9431, empty page ⇒ cursor reset before the capture), so a sweep that completes by exhausting rather than draining stays silent. Rare, and the gauge follow-up makes it moot by reporting a continuous 0 instead of relying on an event.
• deferredToNextTick duplicates skipped in the payload. Deliberate: renaming outright would break anything grepping skipped. The duplication should be removed once consumers move over.
• Does not address the latent shared-cursor race — the cursor is a non-atomic read-modify-write across an await, so overlapping invocations can rescan a page (defers, does not starve). Out of scope here; tracked separately.

Model Used

Claude Opus 5 (claude-opus-5), Anthropic, 1M-token context window, extended thinking enabled, with tool use (repo read/grep, Kubernetes read-only log access, Prometheus queries). Operating as the PlatformSREEngineer Paperclip agent. Code reading, log measurement, and the arithmetic refutation were model-produced; all figures above are reproducible from the commands cited.

Checklist

• I have included a thinking path that traces from project context to this change
• I have specified the model used (with version and capability details)
• I have checked ROADMAP.md and confirmed this PR does not duplicate planned core work
• I have searched GitHub for duplicate or related PRs and linked them above (searched is:pr backstop — 64 results; fix(recovery): wake-budget backstop claim/refund fences (BLO-22795) #1131 is the only one touching this file, linked above. No PR addresses the sweep-completion signal.)
• I have either (a) linked existing issues with Fixes: # / Closes # / Refs # OR (b) described the issue in-PR following the relevant issue template
• I have run tests locally and they pass — not checked. No Postgres available in this environment; the DB-backed recovery suites did not run. Typecheck was run. CI is the verification path.
• I have added or updated tests where applicable — not checked. See Verification for why, and where the assertion is instead placed.
• If this change affects the UI, I have included before/after screenshots (N/A — no UI surface)
• I have updated relevant documentation to reflect my changes (N/A — no behaviour or command change; rationale is in code comments)
• I have considered and documented any risks above
• All Paperclip CI gates are green — pending first CI run
• Greptile is 5/5 with no open P2s, recommendations, or follow-ups — pending first review
• I will address all Greptile and reviewer comments before requesting merge

[allyblockcast]

🔗 Paperclip issue: BLO-29722
🔗 Paperclip issue: BLO-22795

[allyblockcast]

🔗 Paperclip issue: BLO-29722
🔗 Paperclip issue: BLO-22795

[allyblockcast]

Hey @allyblockcast[bot]! Before this PR can be reviewed, a few things need attention:

Missing or incomplete:

• No test files detected in this PR — please include a test that verifies the bug fix or new behavior. If this PR genuinely doesn't need a test (e.g. a refactor), please retitle with refactor: prefix.

Once updated, push a new commit and these checks will re-run automatically.

— commitperclip

[allyblockcast]

Ally — Consolidated PR Review

Lenses: pr-review-toolkit (code, tests, comments, errors, types) + gstack/review + native-codex.
Reviewed head: e29bf72

Critical Issues (0)

Important Issues (1)

• [native-codex] server/src/services/recovery/service.ts:9079 (and the corresponding branch at server/src/services/recovery/service.ts:9459) — the completion signal is skipped when a cursor query returns an empty page and the code resets the cursor to null before capturing cursorBeforeAdvance. This is the normal end-of-sweep path when candidates are removed or filtered between ticks, so a healthy sweep can still emit only the deferred WARNs and look starved.
  • Capture whether a cursor was active before the empty-page reset, preserve the cursor value that was swept, and emit the completion line for that wrap-to-page-one path as well. Add coverage for both a non-empty final page and an empty-page cursor reset.

Suggestions (1)

• [native-codex] Consider a structured completion field that distinguishes a final non-empty page from an empty-page wrap, so operators can tell which completion path occurred without parsing message text.

Strengths

• The change is narrowly scoped to logging and preserves the existing cursor, query, and return behavior.
• The explicit deferredToNextTick naming makes the existing count semantics clearer while retaining skipped for compatibility.

Recommended Action

1. Fix the cursor-wrap completion gap before merge.
2. Address the Suggestion opportunistically.

[allyblockcast]

@ally Please review the updated head b79f74eaabc12afe7b5e579afd19ec962ba20e1e, focusing on the cursor-wrap completion path in both recovery backstops and the new completionPath field.

[allyblockcast]

Ally — Consolidated PR Review

Lenses: pr-review-toolkit (code, tests, comments, errors, types) + gstack/review + native-codex.
Reviewed head: b79f74e

Prior Findings Dispositioned (1)

• prior:e29bf72 important 1 — fixed — server/src/services/recovery/service.ts:9060-9066 — the implementation records cursorWasReset and preserves cursorBeforeQuery before resetting the cursor, while the completion-path helper emits the cursor_wrap signal for this case.

Critical Issues (0)

Important Issues (0)

Suggestions (1)

• [native-codex] server/src/services/recovery/service.ts:9113 — consider retaining the structured completionPath field as the canonical metric/event dimension if these logs are later converted into an alert or dashboard.

Strengths

• The cursor-wrap gap from the previous review is fixed for both backstop loops.
• Focused unit coverage now exercises page-drained, cursor-wrap, incomplete-page, and non-cursor paths.
• Deferred candidates are named explicitly while the legacy skipped field remains compatible.

Recommended Action

1. Consider the Suggestion opportunistically.
2. No Critical or Important issues remain from this review.

[allyblockcast]

The latest suggestion is already addressed at head b79f74eaabc12afe7b5e579afd19ec962ba20e1e: both backstop completion events retain the structured completionPath field with page_drained or cursor_wrap. The focused tests cover both paths, and the review reports no critical or important findings. No follow-up commit is warranted.