From d6f03dcaa047c80f17cbe4ffc6d5e33a2bb46972 Mon Sep 17 00:00:00 2001 From: kkroo Date: Fri, 14 Aug 2026 05:12:21 +0000 Subject: [PATCH 1/2] fix: harden queued-run observability Co-Authored-By: Paperclip --- .../paperclip/templates/prometheusrule.yaml | 21 +- .../paperclip/tests/prometheus-rule.test.mjs | 48 +++-- deploy/helm/paperclip/values.yaml | 4 +- ...at-runs-queued-age-index-migration.test.ts | 100 ++++++++++ .../0217_heartbeat_runs_queued_age_idx.sql | 72 +++++++ packages/db/src/migrations/meta/_journal.json | 7 + packages/db/src/schema/heartbeat_runs.ts | 3 + runbooks/README.md | 4 + runbooks/queued-run-stranded.md | 186 ++++++++++-------- server/src/__tests__/metrics-service.test.ts | 28 ++- .../__tests__/queued-run-age-metrics.test.ts | 119 ++++++++++- server/src/services/metrics.ts | 75 ++++--- server/src/services/queued-run-age-metrics.ts | 56 ++++-- server/src/services/recovery/service.ts | 28 +-- 14 files changed, 565 insertions(+), 186 deletions(-) create mode 100644 packages/db/src/heartbeat-runs-queued-age-index-migration.test.ts create mode 100644 packages/db/src/migrations/0217_heartbeat_runs_queued_age_idx.sql diff --git a/deploy/helm/paperclip/templates/prometheusrule.yaml b/deploy/helm/paperclip/templates/prometheusrule.yaml index 05b7a9cb7a88..f7fb8070ef30 100644 --- a/deploy/helm/paperclip/templates/prometheusrule.yaml +++ b/deploy/helm/paperclip/templates/prometheusrule.yaml @@ -317,15 +317,30 @@ spec: # indefinitely while each individual row is young. This gauge # carries the server-computed age of the oldest queued row PER # AGENT (refreshed on every /metrics scrape from a live - # MIN(created_at) aggregate), so `for:` here is only riding out + # MIN(coalesce(queued_at, created_at)) aggregate), so `for:` here is only riding out # scrape flapping, not standing in for the real age. - expr: max(paperclip_queued_run_oldest_age_seconds) by (agent_id) > {{ .Values.prometheusRule.queuedRunStrandedAgeSeconds }} + # The freshness gate is load-bearing: a failed database refresh + # leaves the previous gauge value in memory, so stale data must not + # qualify a strand alert. + expr: (max(paperclip_queued_run_oldest_age_seconds) by (agent_id) > {{ .Values.prometheusRule.queuedRunStrandedAgeSeconds }}) and on() (paperclip_queued_run_age_metrics_refresh_success == 1) for: {{ .Values.prometheusRule.queuedRunStrandedFor }} labels: severity: warning annotations: summary: "Paperclip agent {{`{{ $labels.agent_id }}`}} has a queued run stranded for longer than {{ .Values.prometheusRule.queuedRunStrandedAgeSeconds }}s" - description: "Agent {{`{{ $labels.agent_id }}`}}'s oldest `queued` heartbeat run has been waiting for {{`{{ $value }}`}}s (BLO-21116). The issue it targets looks `in_progress`/assigned with an active run and generates no other alert, but nothing is executing -- and left alone this also manufactures a false productivity-review escalation reading the queue time as unattended active duration. Check whether the agent is at `maxConcurrentRuns` (capacity starvation -- other runs should still be cycling) or fully idle (a scheduler-tick or dispatch-path fault). Query `select id, agent_id, status, created_at, queued_at, now() - coalesce(queued_at, created_at) as age, context_snapshot ->> 'issueId' as issue_id from heartbeat_runs where status = 'queued' and agent_id = '{{`{{ $labels.agent_id }}`}}' order by coalesce(queued_at, created_at) asc limit 10` to find the specific rows -- ordered and aged by the same coalesce(queued_at, created_at) the gauge itself uses, so a scheduled-retry promotion cannot appear hours older here than the $value that fired. See the runbook for the starvation-vs-dropped triage." + description: "Agent {{`{{ $labels.agent_id }}`}}'s oldest `queued` heartbeat run has been waiting for {{`{{ $value }}`}}s since queue entry (BLO-21116). The age is only trusted while paperclip_queued_run_age_metrics_refresh_success is 1. The issue it targets looks `in_progress`/assigned with an active run, but nothing is executing. Query coalesce(queued_at, created_at), not created_at alone: retries promoted from scheduled_retry intentionally reset their dispatch-wait clock. See the runbook for saturation-versus-dispatch triage." + runbook_url: {{ .Values.prometheusRule.queuedRunStrandedRunbookUrl | quote }} + - alert: PaperclipQueuedRunAgeMetricsRefreshFailed + # This is deliberately separate from the strand alert. A failed + # refresh means the age gauge is not fresh, not that the queue is + # empty; page on it so the freshness gate cannot hide a real strand. + expr: paperclip_queued_run_age_metrics_refresh_success == 0 + for: {{ .Values.prometheusRule.queuedRunAgeMetricsRefreshFailureFor }} + labels: + severity: warning + annotations: + summary: "Paperclip queued-run age metric refresh is failing" + description: "The most recent /metrics queued-run-age database refresh failed (BLO-21116), so queued-run ages may be stale and PaperclipQueuedRunStranded is intentionally gated off. Check Paperclip logs and database connectivity; do not interpret a stale zero as an empty queue." runbook_url: {{ .Values.prometheusRule.queuedRunStrandedRunbookUrl | quote }} {{- with .Values.prometheusRule.additionalGroups }} {{- toYaml . | nindent 4 }} diff --git a/deploy/helm/paperclip/tests/prometheus-rule.test.mjs b/deploy/helm/paperclip/tests/prometheus-rule.test.mjs index 2fb0171198cf..a61478ac2b24 100644 --- a/deploy/helm/paperclip/tests/prometheus-rule.test.mjs +++ b/deploy/helm/paperclip/tests/prometheus-rule.test.mjs @@ -307,24 +307,13 @@ test("PaperclipPrReviewWakeTerminalFailed is pr_review-scoped, gauge-keyed, and ); }); -test("PaperclipQueuedRunStranded is agent-keyed, gauge-thresholded, and links its runbook (BLO-21116)", () => { - const rendered = execFileSync( - "helm", - [ - "template", - "paperclip", - "deploy/helm/paperclip", - "--namespace", - "paperclip", - "-f", - "deploy/helm/paperclip/values.blockcast.yaml", - "--show-only", - "templates/prometheusrule.yaml", - "--set", - "prometheusRule.enabled=true", - ], - { cwd: repoRoot, encoding: "utf8" }, - ); +test("PaperclipQueuedRunStranded is agent-keyed, freshness-gated, and fires before 30m (BLO-21116)", () => { + const rendered = renderChart([ + "--show-only", + "templates/prometheusrule.yaml", + "--set", + "prometheusRule.enabled=true", + ]); assert.match(rendered, /alert: PaperclipQueuedRunStranded/); const [, expr] = rendered.match( @@ -340,12 +329,12 @@ test("PaperclipQueuedRunStranded is agent-keyed, gauge-thresholded, and links it // is young. assert.match( expr, - /^max\(paperclip_queued_run_oldest_age_seconds\) by \(agent_id\) > (\d+)$/, + /^\(max\(paperclip_queued_run_oldest_age_seconds\) by \(agent_id\) > (\d+)\) and on\(\) \(paperclip_queued_run_age_metrics_refresh_success == 1\)$/, "queued-run-stranded alert must threshold the per-agent age gauge, " + "not a summed count under a long `for:`", ); - const [, ageThreshold] = expr.match(/> (\d+)$/) ?? []; + const [, ageThreshold] = expr.match(/> (\d+)\)/) ?? []; // The gauge is reset-then-set to 0 for every known agent on each refresh // (see setQueuedRunOldestAgeMetrics), so a strictly positive threshold is // the silent-in-steady-state guarantee. @@ -390,3 +379,22 @@ test("PaperclipQueuedRunStranded is agent-keyed, gauge-thresholded, and links it ); }); +test("PaperclipQueuedRunAgeMetricsRefreshFailed exposes a stale snapshot instead of hiding it", () => { + const rendered = renderChart([ + "--show-only", + "templates/prometheusrule.yaml", + "--set", + "prometheusRule.enabled=true", + ]); + + assert.match( + rendered, + /alert: PaperclipQueuedRunAgeMetricsRefreshFailed[\s\S]*?\n\s+expr: paperclip_queued_run_age_metrics_refresh_success == 0\n/, + "a failed queued-run-age refresh must have its own alert", + ); + assert.match( + rendered, + /alert: PaperclipQueuedRunAgeMetricsRefreshFailed[\s\S]*?runbook_url: "[^"]*runbooks\/queued-run-stranded\.md"/, + "the freshness failure alert must route responders to the queued-run runbook", + ); +}); diff --git a/deploy/helm/paperclip/values.yaml b/deploy/helm/paperclip/values.yaml index eee7e2ed1c01..c59df3b657a8 100644 --- a/deploy/helm/paperclip/values.yaml +++ b/deploy/helm/paperclip/values.yaml @@ -495,7 +495,9 @@ prometheusRule: queuedRunStrandedAgeSeconds: 1440 # -- Scrape-flap tolerance only (BLO-21116). The ageing lives in queuedRunStrandedAgeSeconds above; it stacks on top of that threshold rather than testing independently, which is why the threshold is 1440 and not 1800. queuedRunStrandedFor: 5m - # -- Runbook for the queued-run-stranded alert, linked from its annotation. + # -- Alert only after sustained failed refreshes; a one-off failed scrape is logged and retried on the next scrape. + queuedRunAgeMetricsRefreshFailureFor: 5m + # -- Runbook for the queued-run-stranded and metric-freshness alerts, linked from their annotations. queuedRunStrandedRunbookUrl: "https://github.com/Blockcast/paperclip/blob/master/runbooks/queued-run-stranded.md" # -- Prometheus regex of suppression causes that mean an outage rather than a deliberate decline (BLO-18859). Expected policy declines (company.inactive, heartbeat.cooldown.active, heartbeat.disabled, heartbeat.wakeOnDemand.disabled, budget.blocked, agent.not_invokable, heartbeat.worktree_execution_cutoff, issue_tree_hold_active) are excluded so they never page. `other` is included: it is the bucket for a skip reason missing from KNOWN_GITHUB_SUPPRESSION_CAUSES, and an untriaged cause is not a known-good decline. githubDeliverySuppressionOutageCauses: "heartbeat.scheduling_suppressed|dispatch_rejected|other" diff --git a/packages/db/src/heartbeat-runs-queued-age-index-migration.test.ts b/packages/db/src/heartbeat-runs-queued-age-index-migration.test.ts new file mode 100644 index 000000000000..f68645018065 --- /dev/null +++ b/packages/db/src/heartbeat-runs-queued-age-index-migration.test.ts @@ -0,0 +1,100 @@ +/** + * BLO-21116 review follow-up: migration 0217 must not build the queued-age + * index inline on a populated heartbeat_runs table. + */ +import { createHash } from "node:crypto"; +import fs from "node:fs"; +import { afterEach, describe, expect, it } from "vitest"; +import postgres from "postgres"; +import { applyPendingMigrations, inspectMigrations } from "./client.js"; +import { + getEmbeddedPostgresTestSupport, + startEmbeddedPostgresTestDatabase, +} from "./test-embedded-postgres.js"; + +const MIGRATION_FILE = "0217_heartbeat_runs_queued_age_idx.sql"; +const INDEX_NAME = "heartbeat_runs_queued_age_idx"; +const INDEX_DEFINITION = + `ON heartbeat_runs USING btree (agent_id, (coalesce(queued_at, created_at))) ` + + `WHERE status = 'queued'`; +const cleanups: Array<() => Promise> = []; +const embeddedPostgresSupport = await getEmbeddedPostgresTestSupport(); +const describeEmbeddedPostgres = embeddedPostgresSupport.supported ? describe : describe.skip; + +async function migrationHash() { + const content = await fs.promises.readFile( + new URL(`./migrations/${MIGRATION_FILE}`, import.meta.url), + "utf8", + ); + return createHash("sha256").update(content).digest("hex"); +} + +afterEach(async () => { + while (cleanups.length > 0) await cleanups.pop()?.(); +}, 60_000); + +describeEmbeddedPostgres("heartbeat-run queued-age index migration", () => { + it("requires online precreation for a populated heartbeat_runs table", async () => { + const database = await startEmbeddedPostgresTestDatabase("paperclip-heartbeat-queued-age-index-"); + cleanups.push(database.cleanup); + const sql = postgres(database.connectionString, { max: 1, onnotice: () => {} }); + cleanups.push(async () => sql.end()); + + await sql.unsafe(` + SET session_replication_role = replica; + INSERT INTO heartbeat_runs (company_id, agent_id, status, context_snapshot) + VALUES ('11111111-1111-4111-8111-111111111111', '22222222-2222-4222-8222-222222222222', 'queued', '{}'::jsonb); + SET session_replication_role = origin; + DROP INDEX ${INDEX_NAME}; + `); + await sql` + DELETE FROM "drizzle"."__drizzle_migrations" + WHERE "hash" = ${await migrationHash()} + `; + + await expect(applyPendingMigrations(database.connectionString)).rejects.toMatchObject({ + message: "migration 0217 requires online queued-age index precreation", + hint: expect.stringContaining(`CREATE INDEX CONCURRENTLY IF NOT EXISTS ${INDEX_NAME}`), + }); + expect(await inspectMigrations(database.connectionString)).toMatchObject({ + status: "needsMigrations", + pendingMigrations: [MIGRATION_FILE], + }); + + await sql.unsafe(`CREATE INDEX CONCURRENTLY IF NOT EXISTS ${INDEX_NAME} ${INDEX_DEFINITION}`); + await applyPendingMigrations(database.connectionString); + expect((await inspectMigrations(database.connectionString)).status).toBe("upToDate"); + + const indexes = await sql<{ indexdef: string }[]>` + SELECT indexdef + FROM pg_indexes + WHERE schemaname = 'public' AND indexname = ${INDEX_NAME} + `; + expect(indexes).toHaveLength(1); + expect(indexes[0]?.indexdef).toContain("COALESCE(queued_at, created_at)"); + expect(indexes[0]?.indexdef).toContain("WHERE (status = 'queued'::text)"); + }, 60_000); + + it("rejects an invalid same-name precreated index", async () => { + const database = await startEmbeddedPostgresTestDatabase("paperclip-heartbeat-queued-age-invalid-"); + cleanups.push(database.cleanup); + const sql = postgres(database.connectionString, { max: 1, onnotice: () => {} }); + cleanups.push(async () => sql.end()); + + await sql` + DELETE FROM "drizzle"."__drizzle_migrations" + WHERE "hash" = ${await migrationHash()} + `; + await sql.unsafe(` + DROP INDEX ${INDEX_NAME}; + CREATE INDEX ${INDEX_NAME} + ON heartbeat_runs USING btree (agent_id, created_at) + WHERE status = 'queued' + `); + + await expect(applyPendingMigrations(database.connectionString)).rejects.toMatchObject({ + message: "migration 0217 found an invalid or incorrectly defined queued-age index", + hint: expect.stringContaining(`DROP INDEX CONCURRENTLY IF EXISTS ${INDEX_NAME}`), + }); + }, 60_000); +}); diff --git a/packages/db/src/migrations/0217_heartbeat_runs_queued_age_idx.sql b/packages/db/src/migrations/0217_heartbeat_runs_queued_age_idx.sql new file mode 100644 index 000000000000..2a0e99cdd76c --- /dev/null +++ b/packages/db/src/migrations/0217_heartbeat_runs_queued_age_idx.sql @@ -0,0 +1,72 @@ +-- BLO-21116: make the scrape-time queued-run age aggregate use a queue-only +-- expression index. The queued_at column and its rollout backfill already live +-- in migration 0215 on current master. +-- +-- Drizzle migrations run in a transaction, so CREATE INDEX CONCURRENTLY is not +-- available here. A plain index build would take a SHARE lock over the hot +-- heartbeat_runs table. Populated databases must precreate this index online; +-- empty bootstrap databases can build it inline. +-- paperclip:migration-safety-ignore large-create-index-not-concurrently: the populated-table path fails closed and supplies the concurrent command. +DO $$ +DECLARE + normalized_predicate text; +BEGIN + IF to_regclass('public.heartbeat_runs_queued_age_idx') IS NOT NULL THEN + SELECT trim(regexp_replace( + coalesce(pg_get_expr(index_metadata.indpred, index_metadata.indrelid, TRUE), ''), + '\s+', ' ', 'g')) + INTO normalized_predicate + FROM pg_index AS index_metadata + WHERE index_metadata.indexrelid = to_regclass('public.heartbeat_runs_queued_age_idx'); + + IF NOT EXISTS ( + SELECT 1 + FROM pg_index AS index_metadata + JOIN pg_class AS index_relation + ON index_relation.oid = index_metadata.indexrelid + JOIN pg_am AS access_method + ON access_method.oid = index_relation.relam + WHERE index_metadata.indexrelid = to_regclass('public.heartbeat_runs_queued_age_idx') + AND index_metadata.indrelid = 'public.heartbeat_runs'::regclass + AND index_metadata.indisvalid + AND access_method.amname = 'btree' + AND index_metadata.indnkeyatts = 2 + AND index_metadata.indnatts = 2 + AND ARRAY( + SELECT pg_get_indexdef(index_metadata.indexrelid, key_position, TRUE) + FROM generate_series(1, index_metadata.indnkeyatts) AS key_position + ORDER BY key_position + ) = ARRAY['agent_id', 'COALESCE(queued_at, created_at)'] + AND index_metadata.indoption = '0 0'::int2vector + AND normalized_predicate = 'status = ''queued''::text' + ) + THEN + RAISE EXCEPTION USING + MESSAGE = 'migration 0217 found an invalid or incorrectly defined queued-age index', + HINT = 'Run DROP INDEX CONCURRENTLY IF EXISTS heartbeat_runs_queued_age_idx; then CREATE INDEX CONCURRENTLY heartbeat_runs_queued_age_idx ON heartbeat_runs USING btree (agent_id, (coalesce(queued_at, created_at))) WHERE status = ''queued''; then retry migrations.'; + END IF; + ELSE + IF EXISTS (SELECT 1 FROM "heartbeat_runs" LIMIT 1) THEN + RAISE EXCEPTION USING + MESSAGE = 'migration 0217 requires online queued-age index precreation', + HINT = 'Run CREATE INDEX CONCURRENTLY IF NOT EXISTS heartbeat_runs_queued_age_idx ON heartbeat_runs USING btree (agent_id, (coalesce(queued_at, created_at))) WHERE status = ''queued''; then retry migrations.'; + END IF; + + -- Close the gap between the empty-table check and CREATE INDEX without + -- taking this lock on a populated production table. + LOCK TABLE "heartbeat_runs" IN SHARE MODE; + IF EXISTS (SELECT 1 FROM "heartbeat_runs" LIMIT 1) THEN + RAISE EXCEPTION USING + MESSAGE = 'migration 0217 requires online queued-age index precreation', + HINT = 'Run CREATE INDEX CONCURRENTLY IF NOT EXISTS heartbeat_runs_queued_age_idx ON heartbeat_runs USING btree (agent_id, (coalesce(queued_at, created_at))) WHERE status = ''queued''; then retry migrations.'; + END IF; + + CREATE INDEX "heartbeat_runs_queued_age_idx" + ON "heartbeat_runs" USING btree ( + "agent_id", + (coalesce("queued_at", "created_at")) + ) + WHERE "status" = 'queued'; + END IF; +END +$$; diff --git a/packages/db/src/migrations/meta/_journal.json b/packages/db/src/migrations/meta/_journal.json index 68be76d4f835..def581985ce3 100644 --- a/packages/db/src/migrations/meta/_journal.json +++ b/packages/db/src/migrations/meta/_journal.json @@ -1464,6 +1464,13 @@ "when": 1786360500000, "tag": "0216_issue_work_products_external_identity", "breakpoints": true + }, + { + "idx": 217, + "version": "7", + "when": 1786682095165, + "tag": "0217_heartbeat_runs_queued_age_idx", + "breakpoints": true } ] } diff --git a/packages/db/src/schema/heartbeat_runs.ts b/packages/db/src/schema/heartbeat_runs.ts index 19fd28928eff..6a1fa76d965d 100644 --- a/packages/db/src/schema/heartbeat_runs.ts +++ b/packages/db/src/schema/heartbeat_runs.ts @@ -124,5 +124,8 @@ export const heartbeatRuns = pgTable( table.companyId, table.createdAt.desc(), ), + queuedAgeIdx: index("heartbeat_runs_queued_age_idx") + .on(table.agentId, sql`coalesce(${table.queuedAt}, ${table.createdAt})`) + .where(sql`${table.status} = 'queued'`), }), ); diff --git a/runbooks/README.md b/runbooks/README.md index e6d53440efad..c1c68b4b6c8e 100644 --- a/runbooks/README.md +++ b/runbooks/README.md @@ -18,6 +18,10 @@ platform cannot resolve automatically. Each runbook should be: which nothing re-drives: decide re-review vs accept without double-posting a review. Trigger: alert `PaperclipPrReviewWakeTerminalFailed`, or `paperclip_agent_wakeup_terminal_failed_unresolved{scope="pr_review"} > 0`. +- [`queued-run-stranded.md`](queued-run-stranded.md) — a dispatchable + `heartbeat_runs.status='queued'` row is not advancing, or its age snapshot + cannot be refreshed safely. Trigger: `PaperclipQueuedRunStranded` or + `PaperclipQueuedRunAgeMetricsRefreshFailed`. - [`clear-polluted-ssh-workspace.md`](clear-polluted-ssh-workspace.md) — recover a stranded SSH-driven run whose workspace import is failing on a sibling task's leftover scratch state. Trigger: blocked issue auto-comment diff --git a/runbooks/queued-run-stranded.md b/runbooks/queued-run-stranded.md index e14fb1fb1f6a..d9a76675f7e2 100644 --- a/runbooks/queued-run-stranded.md +++ b/runbooks/queued-run-stranded.md @@ -1,7 +1,20 @@ # Stranded queued runs (an issue looks active, but nothing is executing) -Source: `server/src/services/queued-run-age-metrics.ts` (`refreshQueuedRunAgeMetrics`), `server/src/services/metrics.ts` (`QUEUED_RUN_OLDEST_AGE_METRIC`, `setQueuedRunOldestAgeMetrics`) -Trigger: alert `PaperclipQueuedRunStranded` — `max(paperclip_queued_run_oldest_age_seconds) by (agent_id) > 1440` for 5m +Source: `server/src/services/queued-run-age-metrics.ts` +(`refreshQueuedRunAgeMetrics`) and `server/src/services/metrics.ts` +(`QUEUED_RUN_OLDEST_AGE_METRIC`, +`QUEUED_RUN_AGE_METRICS_REFRESH_SUCCESS_METRIC`). + +Triggers: + +- `PaperclipQueuedRunStranded` — an agent's oldest queued run is older than + `queuedRunStrandedAgeSeconds` (1440 seconds by default), and the age + snapshot refreshed successfully. The five-minute alert hold means it can + fire before 30 minutes of real queue wait. +- `PaperclipQueuedRunAgeMetricsRefreshFailed` — the most recent `/metrics` + database refresh failed, so queued-run ages are stale and intentionally do + not qualify the stranded-run alert. + Owner: Platform / SRE (BLO-21116) ## The invariant @@ -12,6 +25,15 @@ within one scheduler tick (default 30s) of a concurrency slot opening. A `queued` row that sits for a long time is not a wake that failed to enqueue — it is a run the dispatcher is failing to advance. +Age is measured from `coalesce(queued_at, created_at)`: + +- A fresh queued row has no `queued_at`; `created_at` is its queue-entry time. +- A row promoted from `scheduled_retry`, or returned from a K8s isolation + conflict, records `queued_at` at that transition. +- Migration `0215_heartbeat_runs_queued_at` backfills existing queued rows + from `updated_at`. Migration `0217_heartbeat_runs_queued_age_idx` adds + the queue-only expression index used by the scrape query. + ## Why this needed its own alert Before BLO-21116, a stranded `queued` run was invisible: @@ -19,26 +41,43 @@ Before BLO-21116, a stranded `queued` run was invisible: - The issue it targets still shows `status: in_progress`, an assignee, and an `activeRun` with `status: queued` — it looks like normal in-flight work, not a fault. -- No existing series covered it. - `paperclip_external_runtime_reservation_oldest_age_seconds` tracks - external-runtime **slot reservations**, a different resource. - `paperclip_agent_wakeup_terminal_failed_oldest_age_seconds` only covers wakes - that reached the **terminal** `failed` state — a `queued` run is by - definition not terminal. -- It actively generates noise: the productivity-review detector reads - undispatched queue time as "unattended active duration" and files a false - escalation against the assignee, consuming a reviewer heartbeat to - adjudicate a non-problem. See BLO-21116's description for a worked example - (BLO-18991 / BLO-21114) and the issue's own thread for at least three more - (BLO-20807, BLO-20171, BLO-20725 / BLO-21082 / BLO-21701). +- No existing series covered it. The external-runtime reservation age tracks + a different resource, and the terminal-failed wake age only covers wakes + that have already become terminal. +- It actively generates noise: the productivity-review detector can read + undispatched queue time as unattended active duration and file a false + escalation against the assignee. + +## Read the two gauges together + +```promql +paperclip_queued_run_oldest_age_seconds +paperclip_queued_run_age_metrics_refresh_success +``` + +The freshness gauge is `1` only when the current scrape's database +aggregation succeeded and `0` when it failed. It is not a queue-health gauge: +`0` means the age is unknown, never that no queued work exists. + +The stranded-run alert requires freshness to be `1`. A failed refresh retains +the last age snapshot in memory, but the freshness gate prevents stale data +from firing or suppressing the primary alert. Resolve the refresh-failure +alert first. ## What to do when paged ### Step 1 — find the rows for the paged agent +Use the same queue-entry expression as the metric. Do not query or sort by +`created_at` alone: that overstates a retry recently promoted from a long +scheduled backoff. + ```sql -select id, agent_id, status, created_at, queued_at, - now() - coalesce(queued_at, created_at) as age, +select id, + agent_id, + status, + coalesce(queued_at, created_at) as queued_at, + now() - coalesce(queued_at, created_at) as queue_age, context_snapshot ->> 'issueId' as issue_id, context_snapshot ->> 'wakeReason' as wake_reason from heartbeat_runs @@ -48,90 +87,71 @@ order by coalesce(queued_at, created_at) asc limit 10; ``` -`queued_at` is null for a run that entered `queued` fresh (where `created_at` -already is the queue-entry time); it is stamped only when an *existing* row -is requeued (a promoted `scheduled_retry`, or a `running` deferred back to -`queued`). Use `coalesce(queued_at, created_at)` for age and ordering, the -same expression the gauge itself uses — a bare `created_at` can show a -retried row as hours older than the `$value` that actually fired. +The first row is the one whose age drove the alert. ### Step 2 — tell starvation apart from a dropped dispatch These need different fixes; do not assume one covers both. - **Saturation (starvation).** The agent is at `maxConcurrentRuns` running - pods, and OTHER queued runs for the same agent are cycling through slots - while this one is not. This is a **fairness** problem in the dispatch-rank - aging: `dispatchRank` in `server/src/services/heartbeat.ts` preserves ranks - 0-1 for explicit critical-priority work "no matter how long" a non-critical - run has waited (see the BLO-16253 comment block), so a non-critical run can - in principle wait indefinitely under sustained critical-priority pressure on - one agent. Confirm via `mcp__k8s-ro__pods_list_in_namespace` / - `kubectl get pods -n paperclip -l paperclip.io/agent-id=` — if the pod - count equals `maxConcurrentRuns` and none of them belong to the stranded - run's `id`, this is starvation, not a lost dispatch. -- **Dropped dispatch.** The agent has a free slot (fewer running pods than - `maxConcurrentRuns`) and the row is still `queued`. This points at the - scheduler tick itself: check whether `heartbeatSchedulerStopped` / - `heartbeatStartupRecoveryPending` is stuck true on the serving pod (would - silently no-op the *entire* periodic chain — dispatch AND scheduled-retry - promotion — on that pod only), or whether `getSchedulingSuppression()` is - unexpectedly returning `suppressed: true`. -- **A promoted scheduled retry that then stalled.** If the row's - `contextSnapshot` shows it originated from a `scheduled_retry` (a 429 - provider-capacity or dependency-blocked deferral), confirm - `promoteDueScheduledRetries` actually flipped it to `queued` (it will have, - if `status` reads `queued` rather than `scheduled_retry`) and then apply the - saturation/dropped-dispatch split above — promotion succeeding does not by - itself guarantee dispatch. + pods, and other queued runs for the same agent are cycling through slots + while this one is not. Confirm with + `kubectl get pods -n paperclip -l paperclip.io/agent-id=`; if the pod + count equals `maxConcurrentRuns` and none belongs to the stranded run, this + is starvation rather than a lost dispatch. +- **Dropped dispatch.** The agent has a free slot and the row is still + `queued`. Check whether `heartbeatSchedulerStopped` or + `heartbeatStartupRecoveryPending` is stuck on the serving pod, whether the + periodic dispatch tick is running, and whether `getSchedulingSuppression()` + unexpectedly reports `suppressed: true`. +- **A promoted scheduled retry that then stalled.** If the row originated as + `scheduled_retry`, confirm `promoteDueScheduledRetries` flipped it to + `queued`, then apply the saturation/dropped-dispatch split. Promotion does + not itself guarantee dispatch; its age must be based on `queued_at`. ### Step 3 — check whether the recovery path already knows -`GET /api/issues/{issueId}` → `activeRecoveryAction` and `successfulRunHandoff`. -A `successfulRunHandoff.hasLiveContinuation: true` pointing at a `liveRunId` -that matches the stranded run does NOT mean the run is progressing — it means -the control plane believes a live continuation exists, which can suppress a -corrective re-wake (`decideSuccessfulRunHandoff`, skip reason "issue already -has an active execution path"). If the named `liveRunId` has no matching pod, -that suppression is stale. +`GET /api/issues/{issueId}` → `activeRecoveryAction` and +`successfulRunHandoff`. A `successfulRunHandoff.hasLiveContinuation: true` +pointing at a `liveRunId` that matches the stranded run does not prove that it +is progressing. If the named `liveRunId` has no matching pod, that suppression +is stale and needs correction before a re-wake is dismissed. + +## When the refresh-failure alert fires + +1. Inspect serving Paperclip logs for `failed to refresh queued-run-age + metrics before scrape` and the underlying database error. +2. Check database reachability, connection-pool saturation, and query latency. + Do not interpret an exported age of `0` as current data while freshness is + `0`. +3. Confirm a fresh `/metrics` scrape exposes + `paperclip_queued_run_age_metrics_refresh_success 1`. +4. If queued rows are urgent while the metric is stale, run the SQL above + manually and work from that result. ## Silencing -`severity: warning`. Silence on the alert name plus `agent_id` for a bounded -window if you are deliberately holding an agent at saturation (e.g. an -intentional capacity-limited rollout); do not raise the threshold — the AC -this alert backs (BLO-21116) is explicit about firing before 30m. +Both alerts are `severity: warning`. Silence on the alert name and +`agent_id` for a bounded window only when intentionally holding a known agent +at capacity. Do not raise the age threshold to conceal an incident, and never +silence the refresh-failure alert merely because the last visible age is zero. ## Verifying the signal is live -``` -paperclip_queued_run_oldest_age_seconds -``` +The age gauge is reset-then-set for every known agent on each successful +`/metrics` refresh, so a healthy idle agent renders `0`, not “No data”. +“No data” means the scrape or the refresh function is broken. -Zero-initialized per known agent on every `/metrics` scrape (reset-then-set, -see `setQueuedRunOldestAgeMetrics`), so a healthy fleet renders **0** per -agent, not "No data" — a "No data" reading means the scrape or the refresh -function is broken, which is a different and worse problem than the alert -firing. - -### Where the rule actually runs - -Same caveat as `runbooks/agent-wakeup-terminal-failed.md`: the chart copy at -`deploy/helm/paperclip/templates/prometheusrule.yaml` **does not deploy on -Blockcast** (`prometheusRule.enabled: false`). The rule that fires in -production must be landed in `Blockcast/onprem-k8s`, in both lockstep-enforced -files (`monitoring/prometheus-configmap.yaml` key -`paperclip-runtime-alerts.rules.yml`, authoritative, plus the CRD -documentation copy) and then manually synced through the `monitoring-rules` -Argo app (BLO-19095 — that gate once stranded 15 merged alerts for 8 days). -**As of this writing that onprem-k8s change has not yet been confirmed live — -verify against `/api/v1/rules` before treating this alert as production -observability, the same way BLO-20255's alert had to be verified.** +The chart rule in `deploy/helm/paperclip/templates/prometheusrule.yaml` is a +mirror on Blockcast: `prometheusRule.enabled` is false in +`values.blockcast.yaml`. The production rule must also be landed in both +lockstep `Blockcast/onprem-k8s` alert files and synced through the +`monitoring-rules` Argo application. Merging this repository alone does not +make the alert live; verify `/api/v1/rules` after deployment. ## References - `runbooks/README.md` — index -- BLO-21116 (this alert and the underlying strand investigation) -- `runbooks/agent-wakeup-terminal-failed.md` — the sibling alert and the - onprem-k8s lockstep mechanics this one reuses -- BLO-19095 — the manual Argo sync gate that stands between merge and deploy +- BLO-21116 — JSON-parse recovery classification and queued-run observability +- `runbooks/agent-wakeup-terminal-failed.md` — the sibling alert +- BLO-19095 — the manual Argo sync gate between merge and deployment diff --git a/server/src/__tests__/metrics-service.test.ts b/server/src/__tests__/metrics-service.test.ts index 27a84082a23b..41ec0d9fb971 100644 --- a/server/src/__tests__/metrics-service.test.ts +++ b/server/src/__tests__/metrics-service.test.ts @@ -34,6 +34,8 @@ import { KNOWN_WORKFLOW_RUN_CONCLUSIONS, PROCESS_LOST_LIVENESS_NULL_METRIC, PROCESS_LOST_TOTAL_METRIC, + QUEUED_RUN_AGE_METRICS_REFRESH_SUCCESS_METRIC, + QUEUED_RUN_OLDEST_AGE_METRIC, UNKNOWN_EXTERNAL_ADAPTER, UNKNOWN_PROCESS_LOSS_CLASSIFICATION, UNKNOWN_PROCESS_LOST_BUCKET, @@ -55,7 +57,7 @@ import { normalizeExternalLifecycleTerminalStatus, recordExternalLifecycleRunSilenceGap, setQueuedRunOldestAgeMetrics, - QUEUED_RUN_OLDEST_AGE_METRIC, + setQueuedRunAgeMetricsRefreshSuccess, } from "../services/metrics.js"; import { incrementRoutineDispatchMetric, @@ -682,6 +684,30 @@ describe("setExternalLifecycleRunningRuns (BLO-16184 denominator #1)", () => { }); }); +describe("queued-run age metrics (BLO-21116)", () => { + it("publishes explicit queue zeros and a separate refresh-success signal", async () => { + const agentA = "11111111-1111-1111-1111-111111111111"; + const agentB = "22222222-2222-2222-2222-222222222222"; + const known = new Set([agentA, agentB]); + + setQueuedRunOldestAgeMetrics([{ agentId: agentA, ageSeconds: 54000 }], known); + setQueuedRunAgeMetricsRefreshSuccess(true); + let body = (await renderMetrics()).body; + expect(body).toContain(`${QUEUED_RUN_OLDEST_AGE_METRIC}{agent_id="${agentA}"} 54000`); + expect(body).toContain(`${QUEUED_RUN_OLDEST_AGE_METRIC}{agent_id="${agentB}"} 0`); + expect(body).toContain(`${QUEUED_RUN_AGE_METRICS_REFRESH_SUCCESS_METRIC} 1`); + + // A successful next refresh with no queued rows resolves the age. A + // failed refresh is independently visible rather than being mistaken for + // a fresh zero. + setQueuedRunOldestAgeMetrics([], known); + setQueuedRunAgeMetricsRefreshSuccess(false); + body = (await renderMetrics()).body; + expect(body).toContain(`${QUEUED_RUN_OLDEST_AGE_METRIC}{agent_id="${agentA}"} 0`); + expect(body).toContain(`${QUEUED_RUN_AGE_METRICS_REFRESH_SUCCESS_METRIC} 0`); + }); +}); + describe("recordProcessLostLivenessNull (BLO-16184 denominator #2)", () => { it("registers the counter TYPE line and increments per blind cycle", async () => { let body = (await renderMetrics()).body; diff --git a/server/src/__tests__/queued-run-age-metrics.test.ts b/server/src/__tests__/queued-run-age-metrics.test.ts index 4c15434f32f3..876e98ee5471 100644 --- a/server/src/__tests__/queued-run-age-metrics.test.ts +++ b/server/src/__tests__/queued-run-age-metrics.test.ts @@ -1,11 +1,17 @@ import { randomUUID } from "node:crypto"; import { afterAll, afterEach, beforeAll, describe, expect, it } from "vitest"; +import { sql } from "drizzle-orm"; import { agents, companies, createDb, heartbeatRuns } from "@paperclipai/db"; import { getEmbeddedPostgresTestSupport, startEmbeddedPostgresTestDatabase, } from "./helpers/embedded-postgres.js"; -import { __resetMetricsForTest, renderMetrics } from "../services/metrics.js"; +import { + __resetMetricsForTest, + QUEUED_RUN_AGE_METRICS_REFRESH_SUCCESS_METRIC, + QUEUED_RUN_OLDEST_AGE_METRIC, + renderMetrics, +} from "../services/metrics.js"; import { refreshQueuedRunAgeMetrics } from "../services/queued-run-age-metrics.js"; const embeddedPostgresSupport = await getEmbeddedPostgresTestSupport(); @@ -21,9 +27,11 @@ describeEmbeddedPostgres("refreshQueuedRunAgeMetrics (BLO-21116)", () => { }, 120_000); afterEach(async () => { - await db.delete(heartbeatRuns); - await db.delete(agents); - await db.delete(companies); + // The planner regression test inserts 30k rows. A row-by-row delete is + // quadratic here because heartbeat_runs has a self-reference without a + // child-key index; this database is private to the file, so truncate the + // fixture graph instead of making cleanup dominate the test timeout. + await db.execute(sql`TRUNCATE TABLE heartbeat_runs, agents, companies CASCADE`); __resetMetricsForTest(); }); @@ -72,7 +80,8 @@ describeEmbeddedPostgres("refreshQueuedRunAgeMetrics (BLO-21116)", () => { await refreshQueuedRunAgeMetrics(db, now); const { body } = await renderMetrics(); - expect(body).toContain(`paperclip_queued_run_oldest_age_seconds{agent_id="${agentId}"} 600`); + expect(body).toContain(`${QUEUED_RUN_OLDEST_AGE_METRIC}{agent_id="${agentId}"} 600`); + expect(body).toContain(`${QUEUED_RUN_AGE_METRICS_REFRESH_SUCCESS_METRIC} 1`); }); it("ages a promoted retry off queuedAt, not off its original (much older) createdAt", async () => { @@ -98,7 +107,105 @@ describeEmbeddedPostgres("refreshQueuedRunAgeMetrics (BLO-21116)", () => { await refreshQueuedRunAgeMetrics(db, now); const { body } = await renderMetrics(); - expect(body).toContain(`paperclip_queued_run_oldest_age_seconds{agent_id="${agentId}"} 90`); + expect(body).toContain(`${QUEUED_RUN_OLDEST_AGE_METRIC}{agent_id="${agentId}"} 90`); expect(body).not.toMatch(new RegExp(`agent_id="${agentId}"\\} 43[0-9]{3}`)); }); + + it("marks the age snapshot stale after a refresh failure without publishing a false zero", async () => { + const { companyId, agentId } = await insertCompanyAndAgent(); + const now = new Date("2026-08-04T12:00:00.000Z"); + const createdAt = new Date(now.getTime() - 600_000); + + await db.insert(heartbeatRuns).values({ + companyId, + agentId, + invocationSource: "assignment", + status: "queued", + contextSnapshot: {}, + createdAt, + updatedAt: createdAt, + }); + await refreshQueuedRunAgeMetrics(db, now); + + const failingDb = { + select: () => { + throw new Error("simulated queued-run metric refresh outage"); + }, + } as unknown as typeof db; + await expect(refreshQueuedRunAgeMetrics(failingDb, now)).rejects.toThrow("simulated queued-run metric refresh outage"); + + const { body } = await renderMetrics(); + expect(body).toContain(`${QUEUED_RUN_OLDEST_AGE_METRIC}{agent_id="${agentId}"} 600`); + expect(body).toContain(`${QUEUED_RUN_AGE_METRICS_REFRESH_SUCCESS_METRIC} 0`); + }); + + it("keeps the queue-age aggregate off a full heartbeat history scan", async () => { + const { companyId, agentId } = await insertCompanyAndAgent(); + await db.execute(sql` + INSERT INTO heartbeat_runs ( + company_id, + agent_id, + invocation_source, + status, + context_snapshot, + queued_at, + created_at, + updated_at + ) + SELECT + ${companyId}::uuid, + ${agentId}::uuid, + 'assignment', + CASE WHEN series <= 300 THEN 'queued' ELSE 'succeeded' END, + '{}'::jsonb, + CASE WHEN series <= 300 AND series % 2 = 0 THEN now() - (series || ' seconds')::interval ELSE NULL END, + now() - ((series + 1000) || ' seconds')::interval, + now() + FROM generate_series(1, 30000) AS series + `); + await db.execute(sql`ANALYZE heartbeat_runs`); + + // PostgreSQL 18 can prefer a skip scan over an older company/status index + // for this synthetic one-company data set. Remove those competing indexes + // in this disposable database so the regression proves the dedicated + // queue-age index independently of planner-version cost heuristics. + await db.execute(sql`DROP INDEX heartbeat_runs_agent_dispatch_idx`); + await db.execute(sql`DROP INDEX heartbeat_runs_company_status_last_output_idx`); + await db.execute(sql`DROP INDEX heartbeat_runs_company_status_process_started_idx`); + + const rows = await db.execute(sql` + EXPLAIN (ANALYZE, BUFFERS, FORMAT JSON) + SELECT agent_id, min(coalesce(queued_at, created_at)) AS oldest_queued_at + FROM heartbeat_runs + WHERE status = 'queued' + GROUP BY agent_id + `); + const root = ((rows[0] as { "QUERY PLAN": Array<{ Plan: PlanNode }> })["QUERY PLAN"])[0]?.Plan; + expect(root).toBeDefined(); + + const nodes: PlanNode[] = []; + const visit = (node: PlanNode | undefined) => { + if (!node) return; + nodes.push(node); + for (const child of node.Plans ?? []) visit(child); + }; + visit(root); + + const heartbeatScanNodes = nodes.filter((node) => node["Relation Name"] === "heartbeat_runs"); + expect(heartbeatScanNodes).not.toHaveLength(0); + expect(heartbeatScanNodes.some((node) => node["Node Type"] === "Seq Scan")).toBe(false); + expect( + heartbeatScanNodes.some((node) => + ["Index Scan", "Index Only Scan", "Bitmap Heap Scan"].includes(String(node["Node Type"])), + ), + ).toBe(true); + expect(nodes.some((node) => node["Index Name"] === "heartbeat_runs_queued_age_idx")).toBe(true); + }); }); + +type PlanNode = { + "Node Type": string; + "Relation Name"?: string; + "Index Name"?: string; + Plans?: PlanNode[]; +}; diff --git a/server/src/services/metrics.ts b/server/src/services/metrics.ts index 2b47e53210c9..e1f133fff54e 100644 --- a/server/src/services/metrics.ts +++ b/server/src/services/metrics.ts @@ -86,6 +86,7 @@ export const EXTERNAL_RUNTIME_RESERVATION_OLDEST_AGE_METRIC = "paperclip_externa // CONCURRENT_RUN_BLOCKED_METRIC) so `max(...) by (agent_id) > threshold` // identifies which agent is starved. export const QUEUED_RUN_OLDEST_AGE_METRIC = "paperclip_queued_run_oldest_age_seconds"; +export const QUEUED_RUN_AGE_METRICS_REFRESH_SUCCESS_METRIC = "paperclip_queued_run_age_metrics_refresh_success"; /** * process_lost reap counter (BLO-16184, parent BLO-12292). Incremented once at * the reaper's `process_lost` mint, labeled by bounded `adapter` @@ -922,6 +923,7 @@ let agentZeroTokenCompletedRunStreak: Gauge<"agent_id" | "adapter"> | null = nul let externalRuntimeReservationEvents: Counter<"event"> | null = null; let externalRuntimeReservationsActive: Gauge | null = null; let externalRuntimeReservationOldestAge: Gauge | null = null; +let queuedRunAgeMetricsRefreshSuccess: Gauge | null = null; let processLostTotal: Counter<"adapter" | "error_bucket" | "classification"> | null = null; let externalLifecycleRunningRuns: Gauge<"adapter"> | null = null; let externalLifecycleRunSilenceGap: Histogram<"adapter" | "status"> | null = null; @@ -960,6 +962,7 @@ function ensureRegistry(): { agentWakeupTerminalFailedOldestAgeGauge: Gauge<"scope">; githubWorkflowRunConclusionCounter: Counter<"conclusion" | "supersession">; queuedRunOldestAgeGauge: Gauge<"agent_id">; + queuedRunAgeMetricsRefreshSuccessGauge: Gauge; authRequestCounter: Counter<"operation" | "outcome">; } { if ( @@ -972,6 +975,7 @@ function ensureRegistry(): { || !externalRuntimeReservationEvents || !externalRuntimeReservationsActive || !externalRuntimeReservationOldestAge + || !queuedRunAgeMetricsRefreshSuccess || !processLostTotal || !externalLifecycleRunningRuns || !externalLifecycleRunSilenceGap @@ -1054,6 +1058,14 @@ function ensureRegistry(): { help: "Age in seconds of the oldest unreleased external-runtime slot reservation.", registers: [registry], }); + queuedRunAgeMetricsRefreshSuccess = new Gauge({ + name: QUEUED_RUN_AGE_METRICS_REFRESH_SUCCESS_METRIC, + help: + "1 when the most recent queued-run-age database refresh completed before metrics exposition; " + + "0 when it failed, so stale queued-run ages cannot be read as fresh.", + registers: [registry], + }); + queuedRunAgeMetricsRefreshSuccess.set(0); processLostTotal = new Counter({ name: PROCESS_LOST_TOTAL_METRIC, help: @@ -1280,7 +1292,7 @@ function ensureRegistry(): { name: QUEUED_RUN_OLDEST_AGE_METRIC, help: "Age in seconds of the oldest `queued` heartbeat run for an agent (BLO-21116). " - + "Refreshed on scrape from a live MIN(created_at) aggregate, not a Prometheus " + + "Refreshed on scrape from a live MIN(coalesce(queued_at, created_at)) aggregate, not a Prometheus " + "`for:` clause -- same reasoning as " + AGENT_WAKEUP_TERMINAL_FAILED_OLDEST_AGE_METRIC + ": `for:` measures how long the alert expression has been true, not the age of " + "any one row. Reset-then-set every refresh (see setQueuedRunOldestAgeMetrics) so an " @@ -1316,6 +1328,7 @@ function ensureRegistry(): { externalRuntimeReservationEventsCounter: externalRuntimeReservationEvents, externalRuntimeReservationsActiveGauge: externalRuntimeReservationsActive, externalRuntimeReservationOldestAgeGauge: externalRuntimeReservationOldestAge, + queuedRunAgeMetricsRefreshSuccessGauge: queuedRunAgeMetricsRefreshSuccess, processLostTotalCounter: processLostTotal, externalLifecycleRunningRunsGauge: externalLifecycleRunningRuns, externalLifecycleRunSilenceGapHistogram: externalLifecycleRunSilenceGap, @@ -1502,6 +1515,36 @@ export function setExternalRuntimeReservationMetrics(input: { metrics.externalRuntimeReservationOldestAgeGauge.set(Math.max(0, input.oldestAgeSeconds)); } +/** + * Publish the oldest queued-run age per known agent. Reset-then-set is + * deliberate: an agent whose queue drains must read 0 rather than retaining a + * stale age that would keep the stranded-run alert open forever. + */ +export function setQueuedRunOldestAgeMetrics( + entries: ReadonlyArray<{ agentId: string | null | undefined; ageSeconds: number }>, + knownAgentIds: ReadonlySet, +): void { + const gauge = ensureRegistry().queuedRunOldestAgeGauge; + gauge.reset(); + const oldestByAgentId = new Map(); + for (const entry of entries) { + const agentId = normalizeAgentId(entry.agentId, knownAgentIds); + const ageSeconds = Number.isFinite(entry.ageSeconds) ? Math.max(0, entry.ageSeconds) : 0; + const current = oldestByAgentId.get(agentId); + if (current === undefined || ageSeconds > current) oldestByAgentId.set(agentId, ageSeconds); + } + for (const agentId of knownAgentIds) { + gauge.set({ agent_id: agentId }, oldestByAgentId.get(agentId) ?? 0); + } + const unknownAge = oldestByAgentId.get(UNKNOWN_AGENT_ID); + if (unknownAge !== undefined) gauge.set({ agent_id: UNKNOWN_AGENT_ID }, unknownAge); +} + +/** Mark whether the queued-run age gauge was refreshed from the database. */ +export function setQueuedRunAgeMetricsRefreshSuccess(success: boolean): void { + ensureRegistry().queuedRunAgeMetricsRefreshSuccessGauge.set(success ? 1 : 0); +} + /** * Record one process_lost reap (BLO-16184 numerator). All three labels are * normalized to bounded allow-lists before touching the registry. Returns the @@ -1765,35 +1808,6 @@ export function recordGithubWorkflowRunConclusion( return conclusionLabel; } -/** - * Snapshot the oldest-`queued`-run age per agent (BLO-21116). Reset-then-set, - * same reasoning as {@link setExternalLifecycleRunningRuns}: an agent absent - * from `entries` must read back an explicit 0, not a frozen stale value from - * before its queue drained -- that explicit 0 is what lets an alert on this - * series resolve. `knownAgentIds` bounds the label the same way - * {@link recordConcurrentRunBlocked} does; an id outside that set collapses to - * `UNKNOWN_AGENT_ID` instead of minting an unbounded series. - */ -export function setQueuedRunOldestAgeMetrics( - entries: ReadonlyArray<{ agentId: string | null | undefined; ageSeconds: number }>, - knownAgentIds: ReadonlySet, -): void { - const gauge = ensureRegistry().queuedRunOldestAgeGauge; - gauge.reset(); - const oldestByAgentId = new Map(); - for (const entry of entries) { - const agentId = normalizeAgentId(entry.agentId, knownAgentIds); - const ageSeconds = Number.isFinite(entry.ageSeconds) ? Math.max(0, entry.ageSeconds) : 0; - const current = oldestByAgentId.get(agentId); - if (current === undefined || ageSeconds > current) oldestByAgentId.set(agentId, ageSeconds); - } - for (const agentId of knownAgentIds) { - gauge.set({ agent_id: agentId }, oldestByAgentId.get(agentId) ?? 0); - } - const unknownAge = oldestByAgentId.get(UNKNOWN_AGENT_ID); - if (unknownAge !== undefined) gauge.set({ agent_id: UNKNOWN_AGENT_ID }, unknownAge); -} - export function recordAuthRequest(input: { operation: string | null | undefined; outcome: string | null | undefined; @@ -1849,6 +1863,7 @@ export function __resetMetricsForTest(): void { externalRuntimeReservationEvents = null; externalRuntimeReservationsActive = null; externalRuntimeReservationOldestAge = null; + queuedRunAgeMetricsRefreshSuccess = null; processLostTotal = null; externalLifecycleRunningRuns = null; externalLifecycleRunSilenceGap = null; diff --git a/server/src/services/queued-run-age-metrics.ts b/server/src/services/queued-run-age-metrics.ts index 2fab9fc60317..e86839e7a1ca 100644 --- a/server/src/services/queued-run-age-metrics.ts +++ b/server/src/services/queued-run-age-metrics.ts @@ -1,11 +1,14 @@ import { eq, sql } from "drizzle-orm"; import type { Db } from "@paperclipai/db"; import { agents, heartbeatRuns } from "@paperclipai/db"; -import { setQueuedRunOldestAgeMetrics } from "./metrics.js"; +import { + setQueuedRunAgeMetricsRefreshSuccess, + setQueuedRunOldestAgeMetrics, +} from "./metrics.js"; /** * Refresh the per-agent oldest-`queued`-run-age gauge (BLO-21116). Recomputed - * live on every scrape from a MIN(created_at) aggregate over `heartbeatRuns` + * live on every scrape from a MIN(coalesce(queued_at, created_at)) aggregate over `heartbeatRuns` * status='queued', the same "compute on scrape, never trust a stale cache" * shape as {@link refreshExternalRuntimeReservationMetrics}. `heartbeatRuns` * is the correct table for this: a `queued` row is a run Paperclip has @@ -30,25 +33,36 @@ import { setQueuedRunOldestAgeMetrics } from "./metrics.js"; * a sibling gauge. */ export async function refreshQueuedRunAgeMetrics(db: Db, now = new Date()): Promise { - const [agentRows, oldestByAgent] = await Promise.all([ - db.select({ id: agents.id }).from(agents), - db - .select({ - agentId: heartbeatRuns.agentId, - oldestQueuedAt: sql`min(coalesce(${heartbeatRuns.queuedAt}, ${heartbeatRuns.createdAt}))`, - }) - .from(heartbeatRuns) - .where(eq(heartbeatRuns.status, "queued")) - .groupBy(heartbeatRuns.agentId), - ]); + try { + const [agentRows, oldestByAgent] = await Promise.all([ + db.select({ id: agents.id }).from(agents), + // Keep this predicate in the same simple form as the queue-only age + // index from migration 0217 so scrapes never scan heartbeat history. + db + .select({ + agentId: heartbeatRuns.agentId, + oldestQueuedAt: sql`min(coalesce(${heartbeatRuns.queuedAt}, ${heartbeatRuns.createdAt}))`, + }) + .from(heartbeatRuns) + .where(eq(heartbeatRuns.status, "queued")) + .groupBy(heartbeatRuns.agentId), + ]); - const knownAgentIds = new Set(agentRows.map((row) => row.id)); - const entries = oldestByAgent - .filter((row) => row.agentId !== null && row.oldestQueuedAt) - .map((row) => ({ - agentId: row.agentId, - ageSeconds: Math.max(0, (now.getTime() - new Date(row.oldestQueuedAt as Date | string).getTime()) / 1000), - })); + const knownAgentIds = new Set(agentRows.map((row) => row.id)); + const entries = oldestByAgent + .filter((row) => row.agentId !== null && row.oldestQueuedAt) + .map((row) => ({ + agentId: row.agentId, + ageSeconds: Math.max(0, (now.getTime() - new Date(row.oldestQueuedAt as Date | string).getTime()) / 1000), + })); - setQueuedRunOldestAgeMetrics(entries, knownAgentIds); + setQueuedRunOldestAgeMetrics(entries, knownAgentIds); + setQueuedRunAgeMetricsRefreshSuccess(true); + } catch (error) { + // Do not replace the last age snapshot with synthetic zeros: that would + // hide a real strand. The companion freshness gauge makes the stale data + // ineligible for the stranded-run alert and pages its own failure alert. + setQueuedRunAgeMetricsRefreshSuccess(false); + throw error; + } } diff --git a/server/src/services/recovery/service.ts b/server/src/services/recovery/service.ts index fab749910784..1b6fe0061193 100644 --- a/server/src/services/recovery/service.ts +++ b/server/src/services/recovery/service.ts @@ -1158,29 +1158,15 @@ export function classifyAdapterFailureForRecovery( } const resultJson = parseObject(latestRun.resultJson); const rawError = latestRun.error ?? ""; - // BLO-21116: an `adapter_failed` whose own message names a response-parse - // failure means resultJson is an untrusted/truncated payload, not a source of - // classification evidence -- exclude it from the combined search string so a - // stray substring inside the raw blob cannot false-positive as a config or - // quota phrase, and never let it read as configuration_incomplete. - const isResponseParseFailure = - latestRun.errorCode === "adapter_failed" && ADAPTER_RESPONSE_PARSE_FAILURE_RE.test(rawError); - const error = [latestRun.errorCode ?? "", rawError, isResponseParseFailure ? "" : JSON.stringify(resultJson)] - .join("\n"); - if ( - !isResponseParseFailure && - (latestRun.errorCode === "configuration_incomplete" || CONFIGURATION_INCOMPLETE_ERROR_RE.test(error)) - ) { + // A malformed adapter response is transport-level evidence only. Its raw + // text and truncated result payload are untrusted and must not drive either + // configuration or quota recovery heuristics. + if (ADAPTER_RESPONSE_PARSE_FAILURE_RE.test(rawError)) return null; + + const error = [latestRun.errorCode ?? "", rawError, JSON.stringify(resultJson)].join("\n"); + if (latestRun.errorCode === "configuration_incomplete" || CONFIGURATION_INCOMPLETE_ERROR_RE.test(error)) { return { kind: "configuration_incomplete" }; } - // Same untrusted-payload reasoning as the configuration_incomplete guard - // above: `error` still carries `rawError` verbatim (only `resultJson` was - // dropped from the join), so a response-parse-failure payload containing a - // phrase like "quota exceeded" or "model is at capacity" would otherwise - // still satisfy PROVIDER_QUOTA_ERROR_RE below and misclassify as - // provider_quota instead of configuration_incomplete -- the same defect - // class, just the other branch (Ally review, 2026-08-04). - if (isResponseParseFailure) return null; if (latestRun.errorCode !== "provider_quota" && !PROVIDER_QUOTA_ERROR_RE.test(error)) return null; const persistedRetryAt = readNonEmptyString(resultJson.retryNotBefore) ?? From 26492da8d5f19f8f0ffb02ec8f22fda971b5d169 Mon Sep 17 00:00:00 2001 From: kkroo Date: Fri, 14 Aug 2026 05:50:41 +0000 Subject: [PATCH 2/2] fix: close queued-run observability review findings Co-Authored-By: Paperclip --- .../paperclip/templates/prometheusrule.yaml | 7 +- .../paperclip/tests/prometheus-rule.test.mjs | 7 +- runbooks/queued-run-stranded.md | 20 +++-- .../__tests__/queued-run-age-metrics.test.ts | 82 +++++++++++-------- .../provider-failure-classification.test.ts | 23 ++++++ server/src/services/recovery/service.ts | 24 ++++-- 6 files changed, 113 insertions(+), 50 deletions(-) diff --git a/deploy/helm/paperclip/templates/prometheusrule.yaml b/deploy/helm/paperclip/templates/prometheusrule.yaml index f7fb8070ef30..5f141859ee9a 100644 --- a/deploy/helm/paperclip/templates/prometheusrule.yaml +++ b/deploy/helm/paperclip/templates/prometheusrule.yaml @@ -321,8 +321,11 @@ spec: # scrape flapping, not standing in for the real age. # The freshness gate is load-bearing: a failed database refresh # leaves the previous gauge value in memory, so stale data must not - # qualify a strand alert. - expr: (max(paperclip_queued_run_oldest_age_seconds) by (agent_id) > {{ .Values.prometheusRule.queuedRunStrandedAgeSeconds }}) and on() (paperclip_queued_run_age_metrics_refresh_success == 1) + # qualify a strand alert. Gate each API replica against its own + # refresh result before taking the fleet-wide per-agent max; an + # `on()` join would let one healthy replica bless another replica's + # stale age snapshot. + expr: max by (agent_id) (paperclip_queued_run_oldest_age_seconds and on(instance) (paperclip_queued_run_age_metrics_refresh_success == 1)) > {{ .Values.prometheusRule.queuedRunStrandedAgeSeconds }} for: {{ .Values.prometheusRule.queuedRunStrandedFor }} labels: severity: warning diff --git a/deploy/helm/paperclip/tests/prometheus-rule.test.mjs b/deploy/helm/paperclip/tests/prometheus-rule.test.mjs index a61478ac2b24..a6e28b62a011 100644 --- a/deploy/helm/paperclip/tests/prometheus-rule.test.mjs +++ b/deploy/helm/paperclip/tests/prometheus-rule.test.mjs @@ -329,12 +329,11 @@ test("PaperclipQueuedRunStranded is agent-keyed, freshness-gated, and fires befo // is young. assert.match( expr, - /^\(max\(paperclip_queued_run_oldest_age_seconds\) by \(agent_id\) > (\d+)\) and on\(\) \(paperclip_queued_run_age_metrics_refresh_success == 1\)$/, - "queued-run-stranded alert must threshold the per-agent age gauge, " - + "not a summed count under a long `for:`", + /^max by \(agent_id\) \(paperclip_queued_run_oldest_age_seconds and on\(instance\) \(paperclip_queued_run_age_metrics_refresh_success == 1\)\) > (\d+)$/, + "queued-run-stranded alert must gate each replica's age before taking the per-agent max", ); - const [, ageThreshold] = expr.match(/> (\d+)\)/) ?? []; + const [, ageThreshold] = expr.match(/> (\d+)$/) ?? []; // The gauge is reset-then-set to 0 for every known agent on each refresh // (see setQueuedRunOldestAgeMetrics), so a strictly positive threshold is // the silent-in-steady-state guarantee. diff --git a/runbooks/queued-run-stranded.md b/runbooks/queued-run-stranded.md index d9a76675f7e2..ee6758a11892 100644 --- a/runbooks/queued-run-stranded.md +++ b/runbooks/queued-run-stranded.md @@ -95,7 +95,12 @@ These need different fixes; do not assume one covers both. - **Saturation (starvation).** The agent is at `maxConcurrentRuns` running pods, and other queued runs for the same agent are cycling through slots - while this one is not. Confirm with + while this one is not. This is a dispatch fairness problem: inspect + `dispatchRank` in `server/src/services/heartbeat.ts` and its BLO-16253 + comments. The normal aging lanes preserve ranks 0–1 for explicit + critical-priority work, so a sustained stream of fresh critical work can + keep routine work waiting until the absolute starvation ceiling is reached. + Confirm with `kubectl get pods -n paperclip -l paperclip.io/agent-id=`; if the pod count equals `maxConcurrentRuns` and none belongs to the stranded run, this is starvation rather than a lost dispatch. @@ -144,10 +149,15 @@ The age gauge is reset-then-set for every known agent on each successful The chart rule in `deploy/helm/paperclip/templates/prometheusrule.yaml` is a mirror on Blockcast: `prometheusRule.enabled` is false in -`values.blockcast.yaml`. The production rule must also be landed in both -lockstep `Blockcast/onprem-k8s` alert files and synced through the -`monitoring-rules` Argo application. Merging this repository alone does not -make the alert live; verify `/api/v1/rules` after deployment. +`values.blockcast.yaml`. The production rule must also be landed in the two +lockstep `Blockcast/onprem-k8s` alert files: the authoritative +`monitoring/prometheus-configmap.yaml` key +`paperclip-runtime-alerts.rules.yml` and the CRD documentation copy. Then +manually sync the `monitoring-rules` Argo application (BLO-19095). Merging +this repository alone does not make the alert live. Before treating the +signal as production observability, verify the rendered rule in Prometheus +at `/api/v1/rules` after deployment; the onprem-k8s change and Argo sync must +be confirmed separately. ## References diff --git a/server/src/__tests__/queued-run-age-metrics.test.ts b/server/src/__tests__/queued-run-age-metrics.test.ts index 876e98ee5471..f985dc1d383d 100644 --- a/server/src/__tests__/queued-run-age-metrics.test.ts +++ b/server/src/__tests__/queued-run-age-metrics.test.ts @@ -168,38 +168,56 @@ describeEmbeddedPostgres("refreshQueuedRunAgeMetrics (BLO-21116)", () => { // PostgreSQL 18 can prefer a skip scan over an older company/status index // for this synthetic one-company data set. Remove those competing indexes // in this disposable database so the regression proves the dedicated - // queue-age index independently of planner-version cost heuristics. - await db.execute(sql`DROP INDEX heartbeat_runs_agent_dispatch_idx`); - await db.execute(sql`DROP INDEX heartbeat_runs_company_status_last_output_idx`); - await db.execute(sql`DROP INDEX heartbeat_runs_company_status_process_started_idx`); - - const rows = await db.execute(sql` - EXPLAIN (ANALYZE, BUFFERS, FORMAT JSON) - SELECT agent_id, min(coalesce(queued_at, created_at)) AS oldest_queued_at - FROM heartbeat_runs - WHERE status = 'queued' - GROUP BY agent_id - `); - const root = ((rows[0] as { "QUERY PLAN": Array<{ Plan: PlanNode }> })["QUERY PLAN"])[0]?.Plan; - expect(root).toBeDefined(); - - const nodes: PlanNode[] = []; - const visit = (node: PlanNode | undefined) => { - if (!node) return; - nodes.push(node); - for (const child of node.Plans ?? []) visit(child); - }; - visit(root); - - const heartbeatScanNodes = nodes.filter((node) => node["Relation Name"] === "heartbeat_runs"); - expect(heartbeatScanNodes).not.toHaveLength(0); - expect(heartbeatScanNodes.some((node) => node["Node Type"] === "Seq Scan")).toBe(false); - expect( - heartbeatScanNodes.some((node) => - ["Index Scan", "Index Only Scan", "Bitmap Heap Scan"].includes(String(node["Node Type"])), - ), - ).toBe(true); - expect(nodes.some((node) => node["Index Name"] === "heartbeat_runs_queued_age_idx")).toBe(true); + // queue-age index independently of planner-version cost heuristics, then + // restore the schema in finally so a later test cannot inherit the altered + // planner surface. + try { + await db.execute(sql`DROP INDEX IF EXISTS heartbeat_runs_agent_dispatch_idx`); + await db.execute(sql`DROP INDEX IF EXISTS heartbeat_runs_company_status_last_output_idx`); + await db.execute(sql`DROP INDEX IF EXISTS heartbeat_runs_company_status_process_started_idx`); + + const rows = await db.execute(sql` + EXPLAIN (ANALYZE, BUFFERS, FORMAT JSON) + SELECT agent_id, min(coalesce(queued_at, created_at)) AS oldest_queued_at + FROM heartbeat_runs + WHERE status = 'queued' + GROUP BY agent_id + `); + const root = ((rows[0] as { "QUERY PLAN": Array<{ Plan: PlanNode }> })["QUERY PLAN"])[0]?.Plan; + expect(root).toBeDefined(); + + const nodes: PlanNode[] = []; + const visit = (node: PlanNode | undefined) => { + if (!node) return; + nodes.push(node); + for (const child of node.Plans ?? []) visit(child); + }; + visit(root); + + const heartbeatScanNodes = nodes.filter((node) => node["Relation Name"] === "heartbeat_runs"); + expect(heartbeatScanNodes).not.toHaveLength(0); + expect(heartbeatScanNodes.some((node) => node["Node Type"] === "Seq Scan")).toBe(false); + expect( + heartbeatScanNodes.some((node) => + ["Index Scan", "Index Only Scan", "Bitmap Heap Scan"].includes(String(node["Node Type"])), + ), + ).toBe(true); + expect(nodes.some((node) => node["Index Name"] === "heartbeat_runs_queued_age_idx")).toBe(true); + } finally { + await db.execute(sql` + CREATE INDEX IF NOT EXISTS heartbeat_runs_agent_dispatch_idx + ON heartbeat_runs USING btree (agent_id, status, created_at, id) + WHERE status IN ('queued', 'scheduled_retry') + `); + await db.execute(sql` + CREATE INDEX IF NOT EXISTS heartbeat_runs_company_status_last_output_idx + ON heartbeat_runs USING btree (company_id, status, last_output_at) + `); + await db.execute(sql` + CREATE INDEX IF NOT EXISTS heartbeat_runs_company_status_process_started_idx + ON heartbeat_runs USING btree (company_id, status, process_started_at) + `); + } }); }); diff --git a/server/src/services/recovery/provider-failure-classification.test.ts b/server/src/services/recovery/provider-failure-classification.test.ts index 7d2a746d303c..002200e1df28 100644 --- a/server/src/services/recovery/provider-failure-classification.test.ts +++ b/server/src/services/recovery/provider-failure-classification.test.ts @@ -120,6 +120,29 @@ describe("classifyAdapterFailureForRecovery", () => { })).toBeNull(); }); + it("preserves an authoritative provider_quota code when its message mentions JSON parsing", () => { + const now = new Date("2026-07-15T20:00:00.000Z"); + const classification = classifyAdapterFailureForRecovery({ + errorCode: "provider_quota", + error: "JSON parsing failed while recording the provider quota response.", + resultJson: null, + }, now); + + expect(classification).toEqual({ + kind: "provider_quota", + retryAt: new Date(now.getTime() + PROVIDER_QUOTA_RECOVERY_DEFAULT_BACKOFF_MS), + parsedResetTime: false, + }); + }); + + it("preserves an authoritative configuration_incomplete code when its message mentions JSON parsing", () => { + expect(classifyAdapterFailureForRecovery({ + errorCode: "configuration_incomplete", + error: "JSON parsing failed while reading the configuration response.", + resultJson: null, + })).toEqual({ kind: "configuration_incomplete" }); + }); + it("still classifies a genuine configuration failure reported via adapter_failed alongside an unrelated resultJson blob", () => { // The parse-failure guard must be narrowly scoped to the parse-failure // shape -- a real config error without that shape keeps classifying. diff --git a/server/src/services/recovery/service.ts b/server/src/services/recovery/service.ts index 1b6fe0061193..bf4c85ffd28c 100644 --- a/server/src/services/recovery/service.ts +++ b/server/src/services/recovery/service.ts @@ -1158,15 +1158,25 @@ export function classifyAdapterFailureForRecovery( } const resultJson = parseObject(latestRun.resultJson); const rawError = latestRun.error ?? ""; - // A malformed adapter response is transport-level evidence only. Its raw - // text and truncated result payload are untrusted and must not drive either - // configuration or quota recovery heuristics. - if (ADAPTER_RESPONSE_PARSE_FAILURE_RE.test(rawError)) return null; - - const error = [latestRun.errorCode ?? "", rawError, JSON.stringify(resultJson)].join("\n"); - if (latestRun.errorCode === "configuration_incomplete" || CONFIGURATION_INCOMPLETE_ERROR_RE.test(error)) { + // An `adapter_failed` whose own message names a response-parse failure means + // resultJson is an untrusted/truncated payload, not classification evidence. + // Keep the guard scoped to that durable error code: provider_quota and + // configuration_incomplete are authoritative classifications and must not be + // discarded merely because their human-readable message contains the same + // phrase. + const isResponseParseFailure = + latestRun.errorCode === "adapter_failed" && ADAPTER_RESPONSE_PARSE_FAILURE_RE.test(rawError); + const error = [latestRun.errorCode ?? "", rawError, isResponseParseFailure ? "" : JSON.stringify(resultJson)] + .join("\n"); + if ( + !isResponseParseFailure && + (latestRun.errorCode === "configuration_incomplete" || CONFIGURATION_INCOMPLETE_ERROR_RE.test(error)) + ) { return { kind: "configuration_incomplete" }; } + // The raw parse-failure text can itself contain quota-like words, so do not + // let an adapter_failed transport fault enter the provider-quota path. + if (isResponseParseFailure) return null; if (latestRun.errorCode !== "provider_quota" && !PROVIDER_QUOTA_ERROR_RE.test(error)) return null; const persistedRetryAt = readNonEmptyString(resultJson.retryNotBefore) ??