diff --git a/messages/_pending/b.json b/messages/_pending/b.json new file mode 100644 index 000000000..8a7fa4f8e --- /dev/null +++ b/messages/_pending/b.json @@ -0,0 +1,65 @@ +{ + "en": { + "admin": { + "providerHealth": { + "statusPaused": "Paused", + "pausedHint": "Paused after repeated failures for {count} users until {at}. It is tried again automatically then.", + "modelNotServed": "The endpoint no longer offers the model {model}. Choose a model it lists in the AI settings." + } + } + }, + "de": { + "admin": { + "providerHealth": { + "statusPaused": "Pausiert", + "pausedHint": "Nach wiederholten Fehlern für {count} Nutzer pausiert bis {at}. Danach wird er automatisch wieder versucht.", + "modelNotServed": "Der Endpunkt bietet das Modell {model} nicht mehr an. Wähle in den KI-Einstellungen ein Modell, das er anbietet." + } + } + }, + "es": { + "admin": { + "providerHealth": { + "statusPaused": "En pausa", + "pausedHint": "En pausa tras fallos repetidos para {count} usuarios hasta {at}. Después se vuelve a intentar automáticamente.", + "modelNotServed": "El endpoint ya no ofrece el modelo {model}. Elige en los ajustes de IA un modelo que ofrezca." + } + } + }, + "fr": { + "admin": { + "providerHealth": { + "statusPaused": "En pause", + "pausedHint": "En pause après des échecs répétés pour {count} utilisateurs jusqu’au {at}. Il sera ensuite réessayé automatiquement.", + "modelNotServed": "Le point d’accès ne propose plus le modèle {model}. Choisissez dans les réglages IA un modèle qu’il propose." + } + } + }, + "it": { + "admin": { + "providerHealth": { + "statusPaused": "In pausa", + "pausedHint": "In pausa dopo errori ripetuti per {count} utenti fino al {at}. Poi viene ritentato automaticamente.", + "modelNotServed": "L’endpoint non offre più il modello {model}. Scegli nelle impostazioni IA un modello che offre." + } + } + }, + "ko": { + "admin": { + "providerHealth": { + "statusPaused": "일시 중지됨", + "pausedHint": "반복된 오류로 사용자 {count}명에 대해 {at}까지 일시 중지되었습니다. 그 후 자동으로 다시 시도합니다.", + "modelNotServed": "엔드포인트가 더 이상 {model} 모델을 제공하지 않습니다. AI 설정에서 제공되는 모델을 선택하세요." + } + } + }, + "pl": { + "admin": { + "providerHealth": { + "statusPaused": "Wstrzymany", + "pausedHint": "Wstrzymany po powtarzających się błędach dla {count} użytkowników do {at}. Potem zostanie automatycznie ponowiony.", + "modelNotServed": "Punkt końcowy nie oferuje już modelu {model}. Wybierz w ustawieniach AI model, który oferuje." + } + } + } +} diff --git a/src/__tests__/derived-response-consumer-guard.test.ts b/src/__tests__/derived-response-consumer-guard.test.ts index e219c8b9a..8b58f5780 100644 --- a/src/__tests__/derived-response-consumer-guard.test.ts +++ b/src/__tests__/derived-response-consumer-guard.test.ts @@ -972,7 +972,15 @@ describe("derived response consumer guard", () => { `derived apiSuccess branch ${index + 1} must preserve producer lineage`, ).toEqual(expectedLineage); } - expect(variableCall(ROUTE_FILE, "derived")).toBe("computeDerivedMetric"); + // v1.42 — the single read goes through the derived cache; the value is + // still the compute's, built inside the cache's builder. + const derivedProducer = variableCall(ROUTE_FILE, "derived"); + expect(["computeDerivedMetric", "cachedSwr"]).toContain(derivedProducer); + if (derivedProducer === "cachedSwr") { + expect(readFileSync(ROUTE_FILE, "utf8")).toMatch( + /const derived = await cachedSwr\([\s\S]*?computeDerivedMetric\(/, + ); + } expect(variableCall(ROUTE_FILE, "assessment")).toBe( "resolveDerivedAssessment", ); diff --git a/src/__tests__/error-level-discipline-guard.test.ts b/src/__tests__/error-level-discipline-guard.test.ts new file mode 100644 index 000000000..9dd6e6552 --- /dev/null +++ b/src/__tests__/error-level-discipline-guard.test.ts @@ -0,0 +1,316 @@ +/** + * A caught error in a background job is either reported or explained. + * + * The failures that cost the most in this codebase were never thrown at + * anyone: a nightly pass that caught its error, annotated an `info` line and + * carried on, completed in pg-boss every night while doing nothing. The + * briefing warm read "all-failed" for a week before anyone could tell which + * account and why; the environment fetch threw on every run for the life of + * the module. A `catch` that drops what it caught is where that starts. + * + * Scope: every `catch` clause and every `.catch(handler)` under + * `src/lib/jobs/` (tests excluded). A catch passes when its body does one of: + * + * - rethrows, rejects, or hands the error to a stream callback; + * - fails the job (`jobFailed`); + * - logs at warn or error: `logCaught` / `caughtAs`, `emitSignal`, + * `reportWorkerError`, + * `addWarning`, `setError`, `elevateLevel`, `workerLog("error", …)`, + * `console.error` / `console.warn`; + * - writes the failure to a ledger an operator surface reads + * (`recordSyncFailure`, `failAiRun`, `markFailed`, + * `recordThumbnailFailure`, `recordBriefingFailure`); + * - counts it into a failure tally (`failed += 1`, `errored++`, + * `failedSubjects.set(…)`) that the job reports in its outcome facts, so a + * systemic failure shows as a count and a partial run as + * `job.run.partial`; + * - hands it back to its caller in the result (`error: err…`), which is + * how every boot-time discovery enqueue reports to the registrar that + * logs it at error. + * + * Anything else is listed in `ALLOWED` below with the reason it may stay + * silent, keyed by file and enclosing function, with how many such catches + * that function holds. The reasons are the review: "best effort" is not one; + * "the pgboss schema is absent on a web-only deployment and null is the + * documented answer" is. + * + * The list cannot rot quietly in either direction. A new silent catch fails + * the second case. An entry whose catches were fixed or removed fails the + * third case (stale entry). And the fourth case removes each entry in turn + * and asserts the sweep goes red without it, so every entry is shown to be + * load-bearing, and the sweep is shown to find what it claims to find. + */ +import { readFileSync } from "node:fs"; +import { join } from "node:path"; +import ts from "typescript"; +import { describe, expect, it } from "vitest"; + +import { walkSourceFiles } from "./helpers/source-files"; + +const SRC = join(process.cwd(), "src"); +const SCOPE = "lib/jobs/"; + +const REPORTS = + /\bthrow\b|\breject\(|\bcallback\(\s*err|\bjobFailed\(|\blogCaught\(|\bcaughtAs\(|\bemitSignal\(|\breportWorkerError\(|\.addWarning\(|\.setError\(|\belevateLevel\(|\bworkerLog\(\s*["']error|\bconsole\.(error|warn)\(|\brecordSyncFailure\(|\bfailAiRun\(|\bmarkFailed\(|\brecordThumbnailFailure\(|\brecordBriefingFailure\(|\berror:\s*err\b/; + +/** A failure tally: `summary.failed += 1`, `errored++`, `failures += 1`. */ +const COUNTS = + /\b[\w.]*(?:failed|failures|errored|Failed|Failures)\w*\s*(?:\+=|\+\+|\.set\(|\.push\()/; + +interface Finding { + /** `::` */ + key: string; + line: number; + body: string; +} + +function scan(file: string, text: string): Finding[] { + const sf = ts.createSourceFile(file, text, ts.ScriptTarget.Latest, true); + const out: Finding[] = []; + const visit = (node: ts.Node, fn: string): void => { + let name = fn; + if ( + (ts.isFunctionDeclaration(node) || ts.isMethodDeclaration(node)) && + node.name + ) { + name = node.name.getText(sf); + } else if ( + ts.isVariableDeclaration(node) && + node.initializer && + (ts.isArrowFunction(node.initializer) || + ts.isFunctionExpression(node.initializer)) + ) { + name = node.name.getText(sf); + } + let body: string | null = null; + if (ts.isCatchClause(node)) body = node.block.getText(sf); + if ( + ts.isCallExpression(node) && + ts.isPropertyAccessExpression(node.expression) && + node.expression.name.getText(sf) === "catch" && + node.arguments[0] + ) { + body = node.arguments[0].getText(sf); + } + if (body !== null && !REPORTS.test(body) && !COUNTS.test(body)) { + out.push({ + key: `${file}::${name}`, + line: sf.getLineAndCharacterOfPosition(node.getStart(sf)).line + 1, + body, + }); + } + ts.forEachChild(node, (child) => visit(child, name)); + }; + visit(sf, ""); + return out; +} + +/** + * Catches allowed to stay silent, by file and function: how many, and why. + * Keep the reason checkable against the code it names. + */ +const ALLOWED: Readonly> = { + "lib/jobs/apple-health-import-worker.ts::reconcileOrphanImportJobs": { + count: 1, + reason: + "A failed live-state lookup reads as live on purpose: the heartbeat is fresh, flipping a running import would kill it, and the next boot re-evaluates once the heartbeat goes stale.", + }, + "lib/jobs/apple-health-import-worker.ts::safeUnlink": { + count: 1, + reason: + "Deleting a staged file that a previous step or sweep already removed; ENOENT is the expected case and nothing is lost either way.", + }, + "lib/jobs/backup-restore.ts::writeProgress": { + count: 1, + reason: + "A progress tick for the status poll; the next tick rewrites it and the job's own outcome is recorded by `finish`.", + }, + "lib/jobs/backup-restore.ts::runBackupRestoreJob": { + count: 1, + reason: + "Waits out the in-flight progress write before the final state is written; that write's failure is the progress tick's, see writeProgress.", + }, + "lib/jobs/backup-restore.ts::sweepInterruptedRestores": { + count: 1, + reason: + "Completing the dead worker's superseded pg-boss delivery; if it fails the delivery expires on its own, and the restore row it belonged to is already failed and counted.", + }, + "lib/jobs/boss-instance.ts::startProducerAttempts": { + count: 2, + reason: + "The start error is kept and thrown after the last attempt; stopping a boss that never started can only fail for the same reason.", + }, + "lib/jobs/boss-instance.ts::superviseProducerReconnect": { + count: 1, + reason: + "Stopping the producer whose connection already failed, before reconnecting; the reconnect loop reports its own failures.", + }, + "lib/jobs/free-text-encryption-backfill.ts::scrubContactAuditDetails": { + count: 1, + reason: + "A parser: details that are not this action's JSON are left alone by contract (null means 'nothing to scrub'), not an error.", + }, + "lib/jobs/geo-backfill.ts::runGeoBackfill": { + count: 1, + reason: + "The row was deleted by the retention sweep between read and update; counted as still unresolved, and the next pass no longer sees it.", + }, + "lib/jobs/host-metric-sampler.ts::captureHostMetric": { + count: 1, + reason: + "Disk counters exist only on Linux; elsewhere the sample records null for them by design.", + }, + "lib/jobs/host-metric-sampler.ts::readLinuxDiskStats": { + count: 1, + reason: "No /proc/diskstats outside Linux; see captureHostMetric.", + }, + "lib/jobs/job-failures.ts::readActiveJobsStartedBefore": { + count: 1, + reason: + "No pgboss schema on a web-only deployment; null is the documented 'no queue to ask', kept apart from an empty list.", + }, + "lib/jobs/job-failures.ts::readConsecutiveRunFailures": { + count: 1, + reason: + "Called from a failure path that is already logging at error; when the queue cannot be read, 1 (this run) is the only known count.", + }, + "lib/jobs/job-failures.ts::readFailingQueues": { + count: 1, + reason: "See readActiveJobsStartedBefore: null means no queue schema.", + }, + "lib/jobs/job-failures.ts::readLastQueueRun": { + count: 1, + reason: "See readActiveJobsStartedBefore: null means no queue schema.", + }, + "lib/jobs/job-failures.ts::readQueueFailureForUser": { + count: 1, + reason: "See readActiveJobsStartedBefore: null means no queue schema.", + }, + "lib/jobs/job-failures.ts::readQueueRunningSince": { + count: 1, + reason: "See readActiveJobsStartedBefore: null means no queue schema.", + }, + "lib/jobs/job-observer.ts::emitJobLine": { + count: 1, + reason: + "The catch around writing a log line itself; there is nowhere further to log to, and a log line must not break the job.", + }, + "lib/jobs/offhost-backup.ts::getS3Client": { + count: 2, + reason: + "headObject answers 'absent' for a missing object (its contract), and the lifecycle read maps NoSuchLifecycleConfiguration to 'missing' and anything else to 'unknown', which the status card shows.", + }, + "lib/jobs/offhost-backup.ts::loadOffhostConfigSafe": { + count: 1, + reason: + "A malformed key reads as 'not configured' for the status card; the backup pass itself calls the throwing loader and fails loudly.", + }, + "lib/jobs/offhost-backup.ts::probeOffhostLifecycle": { + count: 1, + reason: + "The lifecycle probe answers 'unknown', which the admin card renders as such; it is a display read, not a pass.", + }, + "lib/jobs/offhost-backup.ts::runOffhostRoundtripTest": { + count: 2, + reason: + "The admin's connection test returns its error in the result it shows (ok: false, error), and deleting its own probe object is cleanup.", + }, + "lib/jobs/offhost-backup.ts::withEachKey": { + count: 1, + reason: + "Trying each key of the ring in turn; the last error is thrown when no key opens the object.", + }, + "lib/jobs/reminder/medication-reminder-check.ts::cleanupScheduledTelegramDeletions": + { + count: 1, + reason: + "Deleting a reminder message the person usually already deleted; the scheduled row is removed either way, and logging every expected 400 would bury the real ones.", + }, + "lib/jobs/reminder/polar-sync.ts::syncUserPolarLegs": { + count: 2, + reason: + "Both legs run, the first error is kept and thrown after the second leg.", + }, + "lib/jobs/restore-drill.ts::runRestoreDrill": { + count: 1, + reason: + "The per-account drill failure is recorded on the account's result (ok: false, error) and counted into the run's restore_drill_accounts_failed fact.", + }, +}; + +function sweep(): Finding[] { + return walkSourceFiles(join(SRC, SCOPE), { floor: 100 }) + .filter((p) => !p.includes("__tests__") && !p.endsWith(".test.ts")) + .flatMap((p) => + scan(`${SCOPE}${p}`, readFileSync(join(SRC, SCOPE, p), "utf8")), + ); +} + +function unallowed( + findings: readonly Finding[], + allowed: Readonly>, +): string[] { + const byKey = new Map(); + for (const f of findings) { + byKey.set(f.key, [...(byKey.get(f.key) ?? []), f]); + } + const out: string[] = []; + for (const [key, list] of byKey) { + const allowance = allowed[key]?.count ?? 0; + if (list.length > allowance) { + for (const f of list.slice(allowance)) { + out.push( + `${key} (line ${f.line}): ${f.body.replace(/\s+/g, " ").slice(0, 120)}`, + ); + } + } + } + return out.sort(); +} + +describe("error-level discipline in background jobs", () => { + it("the scanner flags a silent catch and passes a reported one", () => { + const planted = scan( + "lib/jobs/planted.ts", + [ + "async function quiet() { try { await a(); } catch { /* best effort */ } }", + "async function info() { try { await a(); } catch (e) { annotate({ action: { name: 'x.failed' } }); } }", + "async function chained() { await a().catch(() => {}); }", + "async function loud() { try { await a(); } catch (e) { logCaught('x.y.failed', e); } }", + "async function counted() { try { await a(); } catch { summary.failed += 1; } }", + "async function rethrown() { try { await a(); } catch (e) { throw e; } }", + ].join("\n"), + ); + expect(planted.map((f) => f.key)).toEqual([ + "lib/jobs/planted.ts::quiet", + "lib/jobs/planted.ts::info", + "lib/jobs/planted.ts::chained", + ]); + }); + + it("every silent catch in src/lib/jobs is fixed or explained", () => { + expect(unallowed(sweep(), ALLOWED)).toEqual([]); + }); + + it("no allow-list entry outlives the catches it explains", () => { + const counts = new Map(); + for (const f of sweep()) counts.set(f.key, (counts.get(f.key) ?? 0) + 1); + const stale = Object.entries(ALLOWED) + .filter(([key, { count }]) => (counts.get(key) ?? 0) < count) + .map( + ([key, { count }]) => + `${key}: allows ${count}, finds ${counts.get(key) ?? 0}`, + ); + expect(stale).toEqual([]); + }); + + it("every allow-list entry is load-bearing: removing it turns the sweep red", () => { + const findings = sweep(); + const notLoadBearing = Object.keys(ALLOWED).filter((key) => { + const without = { ...ALLOWED }; + delete (without as Record)[key]; + return unallowed(findings, without).length === 0; + }); + expect(notLoadBearing).toEqual([]); + }); +}); diff --git a/src/__tests__/job-retention-floor-guard.test.ts b/src/__tests__/job-retention-floor-guard.test.ts new file mode 100644 index 000000000..52aeedb38 --- /dev/null +++ b/src/__tests__/job-retention-floor-guard.test.ts @@ -0,0 +1,105 @@ +/** + * No queue may forget its failed jobs before the failure readers look. + * + * `job-failures.ts` reads pg-boss's own `state = 'failed'` rows over a 72-hour + * window: the admin status card, the per-account "last run failed" hint and + * the repeated-failure count behind the `job.run.failed` alert all rest on + * those rows still existing. pg-boss deletes a terminal row + * `deleteAfterSeconds` after it finished. v1.42 shortens that option on the + * pure-volume queues, and a value under the reader window would make a + * failing queue read as healthy, with nothing anywhere saying so. + * + * The rule: a `deleteAfterSeconds` in the source is either produced by + * `failureReaderRetention(hours)` (which throws under the floor) or written as + * a plain literal at or above `FAILED_ROW_AVAILABILITY_FLOOR_HOURS`. Anything + * else, a named constant included, fails here, because a constant's value is + * not checkable from the call site and the helper exists to make it so. + * + * Mutation check, run when this guard was written: a planted + * `deleteAfterSeconds: 48 * 60 * 60` in a job file fails the second case, and + * `deleteAfterSeconds: VOLUME_SECONDS` fails it too; the matcher self-test + * below proves the scan sees both shapes, so an empty sweep is not mistaken + * for a clean one. + */ +import { readFileSync } from "node:fs"; +import { join } from "node:path"; +import { describe, expect, it } from "vitest"; + +import { walkSourceFiles } from "./helpers/source-files"; +import { FAILED_ROW_AVAILABILITY_FLOOR_HOURS } from "@/lib/jobs/job-failures"; + +const SRC = join(process.cwd(), "src"); +const FLOOR_SECONDS = FAILED_ROW_AVAILABILITY_FLOOR_HOURS * 3600; + +/** The one file allowed to spell the option out: the helper itself. */ +const HELPER_FILE = "lib/jobs/job-failures.ts"; + +const OPTION = /\bdeleteAfterSeconds\s*:\s*([^,}\n]+)/g; + +/** Evaluate a sum of products of integer literals; null for anything else. */ +function literalSeconds(expression: string): number | null { + const cleaned = expression.trim().replace(/_/g, ""); + if (!/^\d+(\s*[*+]\s*\d+)*$/.test(cleaned)) return null; + return cleaned + .split("+") + .map((term) => + term + .split("*") + .map((factor) => Number(factor.trim())) + .reduce((a, b) => a * b, 1), + ) + .reduce((a, b) => a + b, 0); +} + +interface Finding { + file: string; + expression: string; +} + +function scan(file: string, text: string): Finding[] { + const out: Finding[] = []; + for (const match of text.matchAll(OPTION)) { + out.push({ file, expression: match[1].trim() }); + } + return out; +} + +function violations(findings: readonly Finding[]): string[] { + return findings + .filter((f) => { + const seconds = literalSeconds(f.expression); + return seconds === null || seconds < FLOOR_SECONDS; + }) + .map((f) => `${f.file}: deleteAfterSeconds: ${f.expression}`); +} + +function sourceFindings(): Finding[] { + return walkSourceFiles(SRC, { floor: 3000 }) + .filter((p) => !p.startsWith("generated/")) + .filter((p) => !p.includes("__tests__")) + .filter((p) => !p.endsWith(".test.ts") && !p.endsWith(".test.tsx")) + .filter((p) => p !== HELPER_FILE) + .flatMap((p) => scan(p, readFileSync(join(SRC, p), "utf8"))); +} + +describe("job retention floor", () => { + it("the matcher sees both a short literal and a named constant", () => { + const planted = scan( + "planted.ts", + [ + "await boss.createQueue(Q, { deleteAfterSeconds: 48 * 60 * 60 });", + "await boss.createQueue(R, { deleteAfterSeconds: VOLUME_SECONDS });", + "await boss.createQueue(S, { deleteAfterSeconds: 7 * 24 * 3600 });", + ].join("\n"), + ); + expect(planted).toHaveLength(3); + expect(violations(planted)).toEqual([ + "planted.ts: deleteAfterSeconds: 48 * 60 * 60", + "planted.ts: deleteAfterSeconds: VOLUME_SECONDS", + ]); + }); + + it("every queue retention in the tree keeps failed rows past the reader window", () => { + expect(violations(sourceFindings())).toEqual([]); + }); +}); diff --git a/src/app/api/admin/provider-health/__tests__/route.test.ts b/src/app/api/admin/provider-health/__tests__/route.test.ts index 408ba63ea..6735c919b 100644 --- a/src/app/api/admin/provider-health/__tests__/route.test.ts +++ b/src/app/api/admin/provider-health/__tests__/route.test.ts @@ -17,13 +17,24 @@ vi.mock("@/lib/db", () => ({ prisma: { providerHealth: { groupBy: vi.fn(), + // v1.42 — the paused rows. + findMany: vi.fn(async () => []), }, coachUsage: { aggregate: vi.fn(), }, + // v1.42 — the operator key's model check reads the admin settings. + appSettings: { findUnique: vi.fn(async () => null) }, }, })); +// v1.42 — the model check probes the operator endpoint's listing. +const probeModelListing = vi.fn(); +vi.mock("@/lib/ai/model-availability", () => ({ + probeModelListing: (...a: unknown[]) => probeModelListing(...a), +})); +vi.mock("@/lib/crypto", () => ({ decrypt: (v: string) => v })); + vi.mock("@/lib/api-handler", async () => { const actual = await vi.importActual( @@ -115,6 +126,9 @@ describe("GET /api/admin/provider-health", () => { lastOkAt: "2026-08-27T07:00:00.000Z", lastFailureAt: "2026-08-27T06:00:00.000Z", lastFailureStatus: 503, + pausedUsers: 0, + pausedUntil: null, + modelListing: null, }, ]); }); @@ -257,3 +271,89 @@ describe("GET /api/admin/provider-health", () => { expect(body.data.providers).toEqual([]); }); }); + +describe("GET /api/admin/provider-health — pause and model check (v1.42)", () => { + const findMany = vi.mocked(prisma.providerHealth.findMany); + const settings = vi.mocked(prisma.appSettings.findUnique); + + beforeEach(() => { + vi.clearAllMocks(); + vi.mocked(requireAdmin).mockResolvedValue({ + user: { id: "admin" }, + } as never); + aggregate.mockResolvedValue({ + _sum: { totalTokens: 0, operatorTokens: 0 }, + } as never); + findMany.mockResolvedValue([] as never); + settings.mockResolvedValue(null as never); + }); + + it("counts the users a provider is paused for and when the last pause lifts", async () => { + groupBy.mockResolvedValue([ + group("admin-openai", "hard_failed", 2, { + consecutiveFailures: 1766, + lastFailureAt: new Date("2026-10-08T04:31:00Z"), + lastStatus: 500, + }), + ] as never); + findMany.mockResolvedValue([ + { + providerType: "admin-openai", + nextRetryAt: new Date("2026-10-08T05:01:00Z"), + }, + { + providerType: "admin-openai", + nextRetryAt: new Date("2026-10-09T04:31:00Z"), + }, + ] as never); + + const body = await (await GET()).json(); + expect(body.data.providers[0]).toMatchObject({ + pausedUsers: 2, + pausedUntil: "2026-10-09T04:31:00.000Z", + }); + // Only rows past the pause threshold, inside their window, are read. + expect(findMany.mock.calls[0][0]).toMatchObject({ + where: { + lastResult: "hard_failed", + consecutiveFailures: { gte: 5 }, + }, + }); + }); + + it("names a model the operator's endpoint no longer lists", async () => { + groupBy.mockResolvedValue([ + group("admin-openai", "hard_failed", 1, { + consecutiveFailures: 9, + lastFailureAt: new Date("2026-10-08T04:31:00Z"), + lastStatus: 500, + }), + ] as never); + settings.mockResolvedValue({ + adminAiModel: "gpt-5.4-mini", + adminAiBaseUrl: "http://openai-oauth-proxy:10531/v1", + adminAiKeyEncrypted: "key", + } as never); + probeModelListing.mockResolvedValue("not_listed"); + + const body = await (await GET()).json(); + expect(body.data.providers[0].modelListing).toEqual({ + model: "gpt-5.4-mini", + listing: "not_listed", + }); + expect(probeModelListing).toHaveBeenCalledWith( + expect.objectContaining({ operatorTrusted: true, model: "gpt-5.4-mini" }), + ); + }); + + it("does not probe while the operator's key is healthy", async () => { + groupBy.mockResolvedValue([ + group("admin-openai", "ok", 4, { + lastOkAt: new Date("2026-10-08T04:31:00Z"), + }), + ] as never); + const body = await (await GET()).json(); + expect(body.data.providers[0].modelListing).toBeNull(); + expect(probeModelListing).not.toHaveBeenCalled(); + }); +}); diff --git a/src/app/api/admin/provider-health/route.ts b/src/app/api/admin/provider-health/route.ts index 74579d8c3..199d99923 100644 --- a/src/app/api/admin/provider-health/route.ts +++ b/src/app/api/admin/provider-health/route.ts @@ -4,6 +4,14 @@ import { prisma } from "@/lib/db"; import { apiSuccess } from "@/lib/api-response"; import { annotate } from "@/lib/logging/context"; import { OPERATOR_HELD_PROVIDER_TYPES } from "@/lib/ai/provider-egress"; +import { PROVIDER_PAUSE_THRESHOLD } from "@/lib/ai/provider-health-ledger"; +import { + probeModelListing, + type ModelListing, +} from "@/lib/ai/model-availability"; +import { decrypt } from "@/lib/crypto"; +import { isAnthropicBaseUrl } from "@/lib/ai/provider"; +import { isCanonicalOpenAIEndpoint } from "@/lib/ai/openai-capabilities"; export const dynamic = "force-dynamic"; @@ -42,6 +50,20 @@ interface ProviderHealthSummary { * success clears the status along with the rest of the failure state. */ lastFailureStatus: number | null; + /** + * v1.42 — users whose chain has this provider PAUSED right now (a run of + * hard failures past the pause threshold, inside its window). The chain + * walks a paused provider last and tries it again once the window lifts. + */ + pausedUsers: number; + /** When the latest of those pauses lifts. Null when none is paused. */ + pausedUntil: string | null; + /** + * v1.42 — for the operator's own key while it is failing: whether its + * endpoint still lists the configured model. `not_listed` is the fix the + * card names; null when there is nothing to check. + */ + modelListing: { model: string; listing: ModelListing } | null; } /** @@ -71,6 +93,19 @@ export const GET = apiHandler(async () => { }, }); + // v1.42 — paused providers: a hard-failure run at or past the threshold, + // inside its window. Read as rows (one per user and type, two columns) so + // the count and the latest lift time are exact, not folded from a group. + const now = new Date(); + const pausedRows = await prisma.providerHealth.findMany({ + where: { + lastResult: "hard_failed", + consecutiveFailures: { gte: PROVIDER_PAUSE_THRESHOLD }, + nextRetryAt: { gt: now }, + }, + select: { providerType: true, nextRetryAt: true }, + }); + const byType = new Map(); for (const g of groups) { const row = byType.get(g.providerType) ?? { @@ -81,6 +116,9 @@ export const GET = apiHandler(async () => { lastOkAt: null, lastFailureAt: null, lastFailureStatus: null, + pausedUsers: 0, + pausedUntil: null, + modelListing: null, }; row.tracked += g._count._all; if (g.lastResult !== "ok") { @@ -103,6 +141,21 @@ export const GET = apiHandler(async () => { byType.set(g.providerType, row); } + for (const paused of pausedRows) { + const row = byType.get(paused.providerType); + if (!row || paused.nextRetryAt === null) continue; + row.pausedUsers += 1; + const until = paused.nextRetryAt.toISOString(); + if (!row.pausedUntil || until > row.pausedUntil) row.pausedUntil = until; + } + + // The operator's own key, while it is failing: does its endpoint still list + // the configured model? A free GET, cached; only on this admin read. + const adminRow = byType.get("admin-openai"); + if (adminRow && adminRow.failing > 0) { + adminRow.modelListing = await adminModelListing(); + } + const providers = [...byType.values()].sort((a, b) => { const ca = CENTRAL_TYPES.indexOf(a.providerType); const cb = CENTRAL_TYPES.indexOf(b.providerType); @@ -136,3 +189,42 @@ export const GET = apiHandler(async () => { }, }); }); + +/** + * The model check for the operator's key. Never fails the readout: a missing + * settings row, a key that does not decrypt, or a probe error is simply no + * answer. + */ +async function adminModelListing(): Promise<{ + model: string; + listing: ModelListing; +} | null> { + try { + const settings = await prisma.appSettings.findUnique({ + where: { id: "singleton" }, + select: { + adminAiModel: true, + adminAiBaseUrl: true, + adminAiKeyEncrypted: true, + }, + }); + if (!settings?.adminAiKeyEncrypted) return null; + const baseUrl = settings.adminAiBaseUrl ?? "https://api.openai.com/v1"; + // The same scope as the client's own check: an OpenAI-compatible + // endpoint the operator typed. `api.openai.com` names a missing model in + // its own error; Anthropic lists models on a different contract. + if (isCanonicalOpenAIEndpoint(baseUrl) || isAnthropicBaseUrl(baseUrl)) { + return null; + } + const model = settings.adminAiModel ?? "gpt-4o"; + const listing = await probeModelListing({ + baseUrl, + apiKey: decrypt(settings.adminAiKeyEncrypted), + model, + operatorTrusted: true, + }); + return { model, listing }; + } catch { + return null; + } +} diff --git a/src/app/api/insights/derived/__tests__/route.test.ts b/src/app/api/insights/derived/__tests__/route.test.ts index 2a3f56e68..efdb4407d 100644 --- a/src/app/api/insights/derived/__tests__/route.test.ts +++ b/src/app/api/insights/derived/__tests__/route.test.ts @@ -90,6 +90,7 @@ import { getSession } from "@/lib/auth/session"; import { prisma } from "@/lib/db"; import { computeDerivedMetric } from "@/lib/insights/derived"; import { DERIVED_MAX_WINDOW_DAYS } from "@/lib/insights/derived/types"; +import { __resetAllCachesForTests } from "@/lib/cache/server-cache"; const SESSION_OK = { session: { id: "sess-1", expiresAt: new Date(Date.now() + 3_600_000) }, @@ -119,6 +120,8 @@ function makeReqWith(params: Record): NextRequest { beforeEach(() => { vi.clearAllMocks(); + // v1.42 — the route reads through the derived cache now. + __resetAllCachesForTests(); vi.mocked(prisma.appSettings.findUnique).mockResolvedValue(null as never); vi.mocked(prisma.user.findUnique).mockResolvedValue({ dateOfBirth: new Date("1986-01-01"), @@ -270,3 +273,34 @@ describe("GET /api/insights/derived — windowDays", () => { } }); }); + +// v1.42 — the single-score read was the one derived surface with no cache: +// every open of a score's detail recomputed it over the rollup tier. +describe("GET /api/insights/derived — read-through cache (v1.42)", () => { + it("serves a repeat read from the cache, per metric, type and window", async () => { + vi.mocked(getSession).mockResolvedValue(SESSION_OK as never); + await callGet(makeReq("VITALS_BASELINE", "RESTING_HEART_RATE")); + await callGet(makeReq("VITALS_BASELINE", "RESTING_HEART_RATE")); + expect(computeDerivedMetric).toHaveBeenCalledTimes(1); + + await callGet(makeReq("VITALS_BASELINE", "WEIGHT")); + await callGet( + makeReqWith({ + metric: "VITALS_BASELINE", + type: "RESTING_HEART_RATE", + windowDays: "7", + }), + ); + expect(computeDerivedMetric).toHaveBeenCalledTimes(3); + }); + + it("recomputes after the account's measurements change", async () => { + vi.mocked(getSession).mockResolvedValue(SESSION_OK as never); + const { invalidateUserMeasurements } = + await import("@/lib/cache/invalidate"); + await callGet(makeReq("VITALS_BASELINE", "RESTING_HEART_RATE")); + invalidateUserMeasurements("user-1"); + await callGet(makeReq("VITALS_BASELINE", "RESTING_HEART_RATE")); + expect(computeDerivedMetric).toHaveBeenCalledTimes(2); + }); +}); diff --git a/src/app/api/insights/derived/route.ts b/src/app/api/insights/derived/route.ts index 2438fd636..ae67d9a22 100644 --- a/src/app/api/insights/derived/route.ts +++ b/src/app/api/insights/derived/route.ts @@ -12,7 +12,8 @@ * The `data` payload is the flat `Derived` union so iOS can decode + * combine values across metrics: `{ metric, status, value?, coverage, * confidence?, provenance, reason? }`. Numbers are pure compute over the - * rollup tier (Tier-1, no narrative) — no provider call, no cache table. + * rollup tier (Tier-1, no narrative) — no provider call, no cache table; + * since v1.42 the in-process derived cache, as the batch route uses. * * Wave 1 implements `VITALS_BASELINE` end-to-end; other registered ids * return a `not_implemented` insufficient until their compute lands in a @@ -36,6 +37,7 @@ import { DERIVED_MAX_WINDOW_DAYS } from "@/lib/insights/derived/types"; import { resolveDerivedAssessment } from "@/lib/insights/derived/derived-assessment-ai"; import { resolveServerLocale } from "@/lib/i18n/server-locale"; import { aiCapabilityToServe } from "@/lib/ai/capabilities/gate"; +import { cachedSwr, caches, type ServerCache } from "@/lib/cache/server-cache"; export const dynamic = "force-dynamic"; @@ -122,14 +124,31 @@ export const GET = apiHandler(async (request: NextRequest) => { if (!gate.enabled) return gate.response; } - const profile = await loadBaselineProfile(prisma, user.id); - const derived = await computeDerivedMetric({ - metric, - userId: user.id, - profile, - type: parsed.data.type ?? null, - windowDays: parsed.data.windowDays, - }); + // v1.42 — read-through the per-user derived cache with + // stale-while-revalidate, like the batch grid beside it. This single-score + // read was the one derived surface that recomputed on every request: the + // score detail sheet asks for it on each open, and a composite walks the + // rollup tier once per input. Same bucket, so the invalidation the batch + // relies on covers it unchanged (measurement writes evict or mark the + // `${userId}|` prefix stale, mood writes mark it stale). The module gate + // above and the AI assessment below stay per request. + const type = parsed.data.type ?? null; + const windowDays = parsed.data.windowDays; + const derived = await cachedSwr( + caches.insightsDerived as ServerCache< + Awaited> + >, + `${user.id}|single|${metric}|${type ?? ""}|${windowDays ?? ""}`, + async () => + computeDerivedMetric({ + metric, + userId: user.id, + profile: await loadBaselineProfile(prisma, user.id), + type, + windowDays, + }), + annotate, + ); annotate({ action: { name: "insights.derived" }, diff --git a/src/components/admin/provider-health-section.tsx b/src/components/admin/provider-health-section.tsx index 273c3559b..c0e0c066e 100644 --- a/src/components/admin/provider-health-section.tsx +++ b/src/components/admin/provider-health-section.tsx @@ -48,6 +48,14 @@ interface ProviderHealthRow { lastOkAt: string | null; lastFailureAt: string | null; lastFailureStatus: number | null; + /** v1.42 — users this provider is paused for, and when the last lifts. */ + pausedUsers?: number; + pausedUntil?: string | null; + /** v1.42 — the operator key's model check, while it is failing. */ + modelListing?: { + model: string; + listing: "listed" | "not_listed" | "unknown"; + } | null; } export function ProviderHealthSection() { @@ -151,11 +159,33 @@ export function ProviderHealthSection() { })}` : ""} + {p.pausedUsers && p.pausedUntil ? ( + + {t("admin.providerHealth.pausedHint", { + count: p.pausedUsers, + at: formatDateTime(p.pausedUntil), + })} + + ) : null} + {p.modelListing?.listing === "not_listed" ? ( + + {t("admin.providerHealth.modelNotServed", { + model: p.modelListing.model, + })} + + ) : null} {p.failing === 0 ? ( {t("admin.providerHealth.statusHealthy")} + ) : p.pausedUsers ? ( + + {t("admin.providerHealth.statusPaused")} + ) : ( {t("admin.providerHealth.statusFailing", { diff --git a/src/lib/ai/__tests__/codex-oauth.test.ts b/src/lib/ai/__tests__/codex-oauth.test.ts index 281efe1be..1092e26af 100644 --- a/src/lib/ai/__tests__/codex-oauth.test.ts +++ b/src/lib/ai/__tests__/codex-oauth.test.ts @@ -11,6 +11,8 @@ import { requestDeviceCode, pollDeviceCode, refreshDeviceTokens, + CodexRefreshError, + codexReconnectRequired, encryptCodexCreds, decryptCodexCreds, getCodexClientId, @@ -172,6 +174,76 @@ describe("codex-oauth", () => { }); }); + describe("refreshDeviceTokens failures", () => { + function failWith(status: number, body: string) { + global.fetch = vi.fn( + async () => + new Response(body, { + status, + headers: { "content-type": "application/json" }, + }), + ) as never; + } + + async function refreshError(): Promise { + try { + await refreshDeviceTokens("refresh-dead"); + } catch (err) { + return err as CodexRefreshError; + } + throw new Error("refresh unexpectedly succeeded"); + } + + it("reads a dead refresh token as an expired credential with an auth status", async () => { + // The production shape: 401 with `invalid_refresh_token`. + failWith(401, JSON.stringify({ error: "invalid_refresh_token" })); + const err = await refreshError(); + expect(err).toBeInstanceOf(CodexRefreshError); + expect(err.httpStatus).toBe(401); + expect(err.credentialExpired).toBe(true); + expect(err.oauthError).toBe("invalid_refresh_token"); + }); + + it("classifies invalid_grant on a 400 as a dead credential (401), not a request bug", async () => { + failWith( + 400, + JSON.stringify({ + error: { code: "invalid_grant", message: "Refresh token revoked" }, + }), + ); + const err = await refreshError(); + expect(err.httpStatus).toBe(401); + expect(err.credentialExpired).toBe(true); + expect(err.oauthError).toBe("invalid_grant"); + }); + + it("keeps the status of a refusal that is not about the credential", async () => { + failWith(503, "upstream unavailable"); + const err = await refreshError(); + expect(err.httpStatus).toBe(503); + expect(err.credentialExpired).toBe(false); + expect(err.oauthError).toBeNull(); + }); + + it("never quotes the response body in the message", async () => { + failWith( + 401, + JSON.stringify({ + error: "invalid_refresh_token", + error_description: "token rt-secret-value was revoked", + }), + ); + const err = await refreshError(); + expect(err.message).not.toContain("rt-secret-value"); + }); + + it("codexReconnectRequired carries the same auth contract", () => { + const err = codexReconnectRequired("no refresh token"); + expect(err.httpStatus).toBe(401); + expect(err.credentialExpired).toBe(true); + }); + }); + describe("encryptCodexCreds / decryptCodexCreds", () => { it("round-trips access token, refresh token, and account id", () => { const expiresAt = new Date(Date.now() + 3600_000); diff --git a/src/lib/ai/__tests__/model-availability.test.ts b/src/lib/ai/__tests__/model-availability.test.ts new file mode 100644 index 000000000..e24bb5e47 --- /dev/null +++ b/src/lib/ai/__tests__/model-availability.test.ts @@ -0,0 +1,160 @@ +/** + * v1.42 — a provider that stopped offering the configured model says so. + * + * The operator's OAuth proxy reinstalled itself at a newer version, dropped + * the configured model name, and answered every call with a bare HTTP 500. + * The chain recorded a generic failure 1 766 times in a row. These cases pin + * the diagnosis: after a 5xx from a non-canonical endpoint the client asks + * the endpoint's free `/models` listing, and a listing without the model + * turns the error into one that names the cause (`modelNotServed`), which + * the chain's hop line carries as `model_not_served`. + */ +import { afterEach, beforeEach, describe, expect, it, vi } from "vitest"; + +import { OpenAIClient } from "../openai-client"; +import { + clearModelListingCache, + probeModelListing, +} from "../model-availability"; +import { singleUserTurn } from "../types"; + +// safeFetch's requirePublicHost path runs through undici's own `fetch`; +// delegate it to the global stub so the interception still applies. +vi.mock("undici", async (importOriginal) => { + const actual = await importOriginal(); + return { + ...actual, + fetch: (input: unknown, init?: unknown) => + (globalThis.fetch as unknown as (i: unknown, n?: unknown) => unknown)( + input, + init, + ), + }; +}); +vi.mock("@/lib/logging/context", () => ({ annotate: vi.fn() })); +const emitSignal = vi.fn(); +vi.mock("@/lib/logging/signal", () => ({ + emitSignal: (...a: unknown[]) => emitSignal(...a), +})); + +const PROXY = "https://oauth-proxy.example.com/v1"; + +function listing(ids: string[]) { + return { + ok: true, + status: 200, + json: () => Promise.resolve({ data: ids.map((id) => ({ id })) }), + }; +} + +function serverError() { + return { + ok: false, + status: 500, + text: () => Promise.resolve("Internal Server Error"), + }; +} + +/** Route by method: the completion is a POST, the listing a GET. */ +function stubEndpoint(models: string[] | "broken") { + const fetchMock = vi.fn(async (_url: unknown, init?: { method?: string }) => + init?.method === "GET" + ? models === "broken" + ? { ok: false, status: 404, json: () => Promise.resolve({}) } + : listing(models) + : serverError(), + ); + vi.stubGlobal("fetch", fetchMock); + return fetchMock; +} + +const turn = () => singleUserTurn({ system: "s", user: "u" }); + +beforeEach(() => { + clearModelListingCache(); + emitSignal.mockClear(); +}); + +afterEach(() => { + vi.unstubAllGlobals(); +}); + +describe("probeModelListing", () => { + it("answers listed, not_listed, or unknown, and never guesses", async () => { + stubEndpoint(["gpt-6", "gpt-5.6-mini"]); + await expect( + probeModelListing({ baseUrl: PROXY, apiKey: "k", model: "gpt-6" }), + ).resolves.toBe("listed"); + await expect( + probeModelListing({ baseUrl: PROXY, apiKey: "k", model: "gpt-5.4-mini" }), + ).resolves.toBe("not_listed"); + + clearModelListingCache(); + stubEndpoint("broken"); + await expect( + probeModelListing({ baseUrl: PROXY, apiKey: "k", model: "gpt-5.4-mini" }), + ).resolves.toBe("unknown"); + }); + + it("asks the endpoint once per model for a burst of failures", async () => { + const fetchMock = stubEndpoint(["gpt-6"]); + for (let i = 0; i < 3; i += 1) { + await probeModelListing({ baseUrl: PROXY, apiKey: "k", model: "x" }); + } + expect(fetchMock).toHaveBeenCalledTimes(1); + }); +}); + +describe("OpenAIClient — a 500 from an endpoint that dropped the model", () => { + it("names the missing model and marks the error modelNotServed", async () => { + stubEndpoint(["gpt-6", "gpt-5.6-mini"]); + const client = new OpenAIClient({ + apiKey: "k", + model: "gpt-5.4-mini", + baseUrl: PROXY, + providerType: "admin-key", + operatorTrusted: true, + }); + await expect(client.generateCompletion(turn())).rejects.toMatchObject({ + httpStatus: 500, + modelNotServed: true, + message: expect.stringContaining('model "gpt-5.4-mini" is not offered'), + }); + expect(emitSignal).toHaveBeenCalledWith( + expect.objectContaining({ + action: "ai.provider.model_not_served", + level: "error", + }), + ); + }); + + it("leaves an ordinary 500 alone when the model is still listed", async () => { + stubEndpoint(["gpt-5.4-mini"]); + const client = new OpenAIClient({ + apiKey: "k", + model: "gpt-5.4-mini", + baseUrl: PROXY, + providerType: "admin-key", + operatorTrusted: true, + }); + const error = await client.generateCompletion(turn()).catch((e) => e); + expect(error.httpStatus).toBe(500); + expect(error.modelNotServed).toBeUndefined(); + }); + + it("never probes the canonical OpenAI endpoint", async () => { + const fetchMock = stubEndpoint(["gpt-6"]); + const client = new OpenAIClient({ + apiKey: "k", + model: "gpt-5.4-mini", + baseUrl: "https://api.openai.com/v1", + providerType: "admin-key", + }); + await client.generateCompletion(turn()).catch(() => undefined); + expect( + fetchMock.mock.calls.filter( + (c) => (c[1] as { method?: string })?.method === "GET", + ), + ).toHaveLength(0); + }); +}); diff --git a/src/lib/ai/__tests__/provider-health-ledger.test.ts b/src/lib/ai/__tests__/provider-health-ledger.test.ts index 7f01c13f5..1734bfaa8 100644 --- a/src/lib/ai/__tests__/provider-health-ledger.test.ts +++ b/src/lib/ai/__tests__/provider-health-ledger.test.ts @@ -26,7 +26,11 @@ import { AUTH_FAILURE_COOLDOWN_MS, HARD_FAILURE_COOLDOWN_MS, HARD_FAILURE_SKIP_THRESHOLD, + PROVIDER_PAUSE_BASE_MS, + PROVIDER_PAUSE_MAX_MS, + PROVIDER_PAUSE_THRESHOLD, classifyFailure, + hardFailureCooldownMs, createInMemoryProviderHealthLedger, findCredentialExpiredProviders, postgresProviderHealthLedger, @@ -197,3 +201,68 @@ describe("createInMemoryProviderHealthLedger", () => { expect((await ledger.getSkipHints("u1")).size).toBe(0); }); }); + +// v1.42 — a provider that keeps failing is paused with a pause that grows, +// and resumes by itself. Before, the five-minute backoff lifted after every +// failure and put a gateway that answered 500 to everything back at the front +// of the chain: 1 766 failures in a row. +describe("provider pause (v1.42)", () => { + afterEach(() => { + vi.useRealTimers(); + }); + + it("keeps the short backoff below the threshold and doubles from it, capped at a day", () => { + expect(hardFailureCooldownMs(1)).toBe(HARD_FAILURE_COOLDOWN_MS); + expect(hardFailureCooldownMs(PROVIDER_PAUSE_THRESHOLD - 1)).toBe( + HARD_FAILURE_COOLDOWN_MS, + ); + expect(hardFailureCooldownMs(PROVIDER_PAUSE_THRESHOLD)).toBe( + PROVIDER_PAUSE_BASE_MS, + ); + expect(hardFailureCooldownMs(PROVIDER_PAUSE_THRESHOLD + 1)).toBe( + 2 * PROVIDER_PAUSE_BASE_MS, + ); + expect(hardFailureCooldownMs(PROVIDER_PAUSE_THRESHOLD + 40)).toBe( + PROVIDER_PAUSE_MAX_MS, + ); + // Conservative: the pause never starts before the skip threshold. + expect(PROVIDER_PAUSE_THRESHOLD).toBeGreaterThan( + HARD_FAILURE_SKIP_THRESHOLD, + ); + }); + + it("pauses after N hard failures, keeps it paused past the old five minutes, and resumes after the window", async () => { + vi.useFakeTimers(); + vi.setSystemTime(new Date("2026-10-08T04:30:00Z")); + const ledger = createInMemoryProviderHealthLedger(); + for (let i = 0; i < PROVIDER_PAUSE_THRESHOLD; i += 1) { + await ledger.recordFailure("u1", "admin-openai", 500); + } + expect(ledger.inspect("u1").get("admin-openai")?.reason).toBe("paused"); + + // Past the old five-minute backoff it is still paused. + vi.advanceTimersByTime(HARD_FAILURE_COOLDOWN_MS + 1_000); + expect(ledger.inspect("u1").get("admin-openai")?.reason).toBe("paused"); + + // Past the pause it is tried again. + vi.advanceTimersByTime(PROVIDER_PAUSE_BASE_MS); + expect(ledger.inspect("u1").has("admin-openai")).toBe(false); + + // One more failure doubles the pause; a success clears it. + await ledger.recordFailure("u1", "admin-openai", 500); + const retryAt = ledger.inspect("u1").get("admin-openai")?.retryAt; + expect(retryAt!.getTime() - Date.now()).toBe(2 * PROVIDER_PAUSE_BASE_MS); + await ledger.recordSuccess("u1", "admin-openai"); + expect(ledger.inspect("u1").has("admin-openai")).toBe(false); + }); + + it("arms the escalating pause in the Postgres upsert itself", async () => { + await postgresProviderHealthLedger.recordFailure("u1", "admin-openai", 500); + const sql = ( + vi.mocked(prisma.$executeRaw).mock.calls[0][0] as unknown as string[] + ).join("?"); + expect(sql).toContain("power("); + expect(sql).toContain("LEAST("); + expect(sql).toMatch(/consecutive_failures \+ 1 >=/); + }); +}); diff --git a/src/lib/ai/__tests__/provider-runner.test.ts b/src/lib/ai/__tests__/provider-runner.test.ts index 58a077a6d..c191793b2 100644 --- a/src/lib/ai/__tests__/provider-runner.test.ts +++ b/src/lib/ai/__tests__/provider-runner.test.ts @@ -26,6 +26,12 @@ vi.mock("../coach/budget", async () => { }; }); +// v1.42 — the per-hop failure lines. +const emitSignal = vi.hoisted(() => vi.fn()); +vi.mock("@/lib/logging/signal", () => ({ + emitSignal: (...a: unknown[]) => emitSignal(...a), +})); + vi.mock("../provider-health-ledger", async () => { const actual = await vi.importActual< typeof import("../provider-health-ledger") @@ -52,8 +58,11 @@ import { } from "../provider-runner"; import { AUTH_FAILURE_COOLDOWN_MS, + PROVIDER_PAUSE_BASE_MS, + PROVIDER_PAUSE_THRESHOLD, createInMemoryProviderHealthLedger, } from "../provider-health-ledger"; +import { CodexRefreshError } from "../codex-oauth"; const VALID_RESPONSE = JSON.stringify({ summary: "ok", @@ -113,6 +122,7 @@ function err(status: number, msg = "boom"): Error & { httpStatus: number } { beforeEach(() => { clearLastWorkingProviderCache(); + emitSignal.mockClear(); budgetState.spent = 0; budgetState.operatorSpent = 0; }); @@ -946,3 +956,145 @@ describe("runRawCompletionWithFallback — operator-cost cap at hop time", () => expect(outcome.workingProvider.providerType).toBe("openai"); }); }); + +describe("v1.42 — failed hops get their own line", () => { + function linkSignals() { + return emitSignal.mock.calls + .map( + (c) => + c[0] as { + action: string; + level: string; + meta: Record; + }, + ) + .filter((x) => x.action === "ai.chain.link_failed"); + } + + it("logs a hop the next provider covered at warn, with a stable cause", async () => { + const admin = new ScriptedProvider({ + type: "admin-key", + script: [{ ok: false, error: err(500) }], + }); + const codex = new ScriptedProvider({ + type: "codex", + script: [{ ok: true }], + }); + await runRawCompletionWithFallback({ + userId: "u-signal-warn", + surface: "job", + providers: [ + { providerType: "admin-openai", instance: admin }, + { providerType: "codex", instance: codex }, + ], + params: singleUserTurn({ system: "s", user: "u" }), + }); + expect(linkSignals()).toEqual([ + expect.objectContaining({ + level: "warn", + meta: expect.objectContaining({ + provider: "admin-openai", + status: 500, + cause: "upstream_5xx", + recovered: true, + }), + }), + ]); + }); + + it("logs every hop at error when nothing answered", async () => { + const a = new ScriptedProvider({ + type: "codex", + script: [ + { ok: false, error: new CodexRefreshError(401, "invalid_grant") }, + ], + }); + const b = new ScriptedProvider({ + type: "admin-key", + script: [ + { + ok: false, + error: Object.assign(err(500), { modelNotServed: true }), + }, + ], + }); + await expect( + runRawCompletionWithFallback({ + userId: "u-signal-error", + surface: "job", + providers: [ + { providerType: "codex", instance: a }, + { providerType: "admin-openai", instance: b }, + ], + params: singleUserTurn({ system: "s", user: "u" }), + }), + ).rejects.toMatchObject({ primaryCredentialExpired: true }); + const signals = linkSignals(); + expect(signals.map((x) => x.level)).toEqual(["error", "error"]); + expect(signals.map((x) => x.meta.cause)).toEqual([ + "credential_expired", + "model_not_served", + ]); + }); + + it("records a dead Codex refresh token as an auth failure, not a network one", async () => { + const ledger = createInMemoryProviderHealthLedger(); + const codex = new ScriptedProvider({ + type: "codex", + script: [ + { ok: false, error: new CodexRefreshError(400, "invalid_grant") }, + ], + }); + await expect( + runRawCompletionWithFallback({ + userId: "u-dead-refresh", + surface: "job", + providers: [{ providerType: "codex", instance: codex }], + params: singleUserTurn({ system: "s", user: "u" }), + ledger, + }), + ).rejects.toBeInstanceOf(AllProvidersFailedError); + expect(ledger.inspect("u-dead-refresh").get("codex")?.reason).toBe( + "credential_expired", + ); + }); + + it("walks a paused provider last, so the healthy one answers without the failing hop", async () => { + vi.useFakeTimers(); + const ledger = createInMemoryProviderHealthLedger(); + for (let i = 0; i < PROVIDER_PAUSE_THRESHOLD; i += 1) { + await ledger.recordFailure("u-paused", "admin-openai", 500); + } + const admin = new ScriptedProvider({ + type: "admin-key", + script: [{ ok: true }], + }); + const codex = new ScriptedProvider({ + type: "codex", + script: [{ ok: true }], + }); + const run = () => + runRawCompletionWithFallback({ + userId: "u-paused", + surface: "job", + providers: [ + { providerType: "admin-openai", instance: admin }, + { providerType: "codex", instance: codex }, + ], + params: singleUserTurn({ system: "s", user: "u" }), + ledger, + }); + + // Well past the old five-minute backoff: still paused, never asked. + vi.advanceTimersByTime(20 * 60 * 1000); + clearLastWorkingProviderCache(); + expect((await run()).workingProvider.providerType).toBe("codex"); + expect(admin.callCount).toBe(0); + + // Once the pause lifts it leads the chain again and answers. + vi.advanceTimersByTime(PROVIDER_PAUSE_BASE_MS); + clearLastWorkingProviderCache(); + expect((await run()).workingProvider.providerType).toBe("admin-openai"); + expect(admin.callCount).toBe(1); + }); +}); diff --git a/src/lib/ai/coach/__tests__/tools-loop-budget.test.ts b/src/lib/ai/coach/__tests__/tools-loop-budget.test.ts index d98ccc52c..d208abff1 100644 --- a/src/lib/ai/coach/__tests__/tools-loop-budget.test.ts +++ b/src/lib/ai/coach/__tests__/tools-loop-budget.test.ts @@ -18,6 +18,11 @@ vi.mock("@/lib/ai/provider-runner", () => ({ runRawCompletionWithFallback: (args: unknown) => runRawCompletionWithFallback(args), })); +// v1.42 — the budget stop's own warn line. +const emitSignal = vi.fn(); +vi.mock("@/lib/logging/signal", () => ({ + emitSignal: (...a: unknown[]) => emitSignal(...a), +})); const runDialogTool = vi.fn(); vi.mock("@/lib/ai/coach/tools/dialog-tools", async (importOriginal) => ({ ...(await importOriginal()), @@ -106,6 +111,7 @@ function lastParams() { } beforeEach(() => { + emitSignal.mockReset(); executeCoachTool.mockReset(); runRawCompletionWithFallback.mockReset(); runDialogTool.mockReset(); @@ -461,3 +467,31 @@ describe("reasoning, provider state and the trail", () => { }); }); }); + +describe("budget stop line (v1.42)", () => { + it("writes coach.turn.budget_stop at warn, once, when the budget ends the turn", async () => { + runRawCompletionWithFallback + .mockResolvedValueOnce(round("", [table("bp")])) + .mockResolvedValueOnce(round("Answer from what I have.")); + await runCoachToolLoop({ + ...baseArgs, + budget: createTurnBudget({ + payer: "operator", + initialInputTokens: 10, + limits: { tokens: 500, wallMs: 1e9, maxRounds: 12 }, + }), + }); + expect(emitSignal).toHaveBeenCalledTimes(1); + expect(emitSignal.mock.calls[0][0]).toMatchObject({ + action: "coach.turn.budget_stop", + level: "warn", + meta: { reason: "budget", round: 2, payer: "operator" }, + }); + }); + + it("writes nothing for a turn that answered on its own", async () => { + runRawCompletionWithFallback.mockResolvedValueOnce(round("Plain answer.")); + await runCoachToolLoop({ ...baseArgs, budget: roomy() }); + expect(emitSignal).not.toHaveBeenCalled(); + }); +}); diff --git a/src/lib/ai/coach/tools/loop.ts b/src/lib/ai/coach/tools/loop.ts index ea45a44ad..2a0c40a82 100644 --- a/src/lib/ai/coach/tools/loop.ts +++ b/src/lib/ai/coach/tools/loop.ts @@ -33,6 +33,7 @@ import { coachPromptCacheKey } from "@/lib/ai/coach/prompt-cache-key"; import type { CoachHistoryReach } from "@/lib/ai/coach/history-reach"; import { annotate } from "@/lib/logging/context"; +import { emitSignal } from "@/lib/logging/signal"; import type { Locale } from "@/lib/i18n/config"; import { runRawCompletionWithFallback } from "@/lib/ai/provider-runner"; import type { ProviderChainResolved } from "@/lib/ai/provider-runner"; @@ -295,6 +296,7 @@ export async function runCoachToolLoop(args: { let planProposal: CoachPlanProposal | undefined; let callCount = 0; let stopReason: CoachStopReason | null = null; + let stopSignalled = false; let progressStalled = false; for (let round = 1; ; round += 1) { @@ -308,6 +310,23 @@ export async function runCoachToolLoop(args: { } const isFinal = stopReason !== null; if (stopReason) { + // v1.42 — a turn cut short by its budget is not a failure, but an + // operator who sees answers getting thin needs to count it. It used to + // be one `stop` meta key on the turn's info line. + if (!stopSignalled && stopReason !== "no_progress") { + stopSignalled = true; + emitSignal({ + action: "coach.turn.budget_stop", + level: "warn", + meta: { + reason: stopReason, + round, + spent: budget.spent(), + elapsedMs: budget.elapsedMs(), + payer: budget.payer, + }, + }); + } const label = stopActivityLabel(locale, stopReason); const id = activity.start({ phase: "stop", diff --git a/src/lib/ai/codex-oauth.ts b/src/lib/ai/codex-oauth.ts index 6d6e78ab2..6d389160c 100644 --- a/src/lib/ai/codex-oauth.ts +++ b/src/lib/ai/codex-oauth.ts @@ -288,14 +288,108 @@ export async function refreshDeviceTokens( }); if (!res.ok) { const body = await res.text().catch(() => ""); - throw new Error( - `Codex device-token refresh failed (${res.status}): ${body}`, - ); + throw codexRefreshError(res.status, body); } const tokens = (await res.json()) as RawTokenResponse; return buildCreds(tokens, refreshToken); } +/** + * OAuth error codes on the refresh grant that mean the stored refresh token + * is dead for good: revoked, expired, already rotated, or issued to another + * client. Retrying cannot help; only signing in again can. + */ +const DEAD_REFRESH_TOKEN_CODES: ReadonlySet = new Set([ + "invalid_grant", + "invalid_refresh_token", + "refresh_token_expired", + "refresh_token_reused", + "refresh_token_invalidated", + "invalid_token", +]); + +/** + * A failed refresh of the Codex OAuth token. + * + * The refresh used to throw a bare `Error` with the status only in its + * message. The chain runner reads `httpStatus` to classify a failure, so a + * dead refresh token read as a network error: the health ledger recorded + * `hard_failed` instead of `auth_failed`, nothing told the person to + * reconnect, and every night tried the same dead token again. + * + * `httpStatus` is 401 whenever the grant itself is dead (whatever status the + * token endpoint chose to send it with, 400 for `invalid_grant` included), so + * every classifier downstream (`classifyFailure`, `AllProvidersFailedError`, + * the briefing failure marker) reads it as an expired credential. Any other + * refusal keeps the endpoint's status. The body is not quoted: only the + * OAuth error code, which is the endpoint's vocabulary, rides on the error. + */ +export class CodexRefreshError extends Error { + readonly httpStatus: number; + readonly upstream = "codex"; + /** True when the person has to sign in to ChatGPT again. */ + readonly credentialExpired: boolean; + /** The OAuth `error` code from the response body, when it had one. */ + readonly oauthError: string | null; + + constructor(status: number, oauthError: string | null) { + const credentialExpired = + status === 401 || + status === 403 || + (oauthError !== null && DEAD_REFRESH_TOKEN_CODES.has(oauthError)); + super( + credentialExpired + ? `Codex sign-in expired (${status}${oauthError ? ` ${oauthError}` : ""}); reconnect ChatGPT` + : `Codex device-token refresh failed (${status}${oauthError ? ` ${oauthError}` : ""})`, + ); + this.name = "CodexRefreshError"; + this.credentialExpired = credentialExpired; + this.oauthError = oauthError; + this.httpStatus = credentialExpired && status !== 403 ? 401 : status; + } +} + +/** + * The stored Codex credential cannot be used at all (missing refresh token, + * or storage that no longer decrypts). Same contract as a dead refresh token: + * the person has to reconnect. + */ +export function codexReconnectRequired(reason: string): CodexRefreshError { + const err = new CodexRefreshError(401, null); + err.message = `Codex sign-in unusable (${reason}); reconnect ChatGPT`; + return err; +} + +/** Read the OAuth error code from a token-endpoint error body. */ +function readOAuthErrorCode(body: string): string | null { + try { + const parsed = JSON.parse(body) as { + error?: unknown; + code?: unknown; + }; + const error = parsed.error; + if (typeof error === "string") return normaliseCode(error); + if (error && typeof error === "object") { + const code = (error as { code?: unknown; type?: unknown }).code; + if (typeof code === "string") return normaliseCode(code); + } + if (typeof parsed.code === "string") return normaliseCode(parsed.code); + } catch { + // Not JSON: no code to read. The status still classifies the failure. + } + return null; +} + +/** Codes are the endpoint's own vocabulary; keep them short and plain. */ +function normaliseCode(code: string): string | null { + const trimmed = code.trim().toLowerCase(); + return /^[a-z0-9_.-]{1,64}$/.test(trimmed) ? trimmed : null; +} + +function codexRefreshError(status: number, body: string): CodexRefreshError { + return new CodexRefreshError(status, readOAuthErrorCode(body)); +} + // ─── Encrypted-storage codec ──────────────────────────────────────── // // We re-purpose `codexAccessTokenEncrypted` to store the entire creds diff --git a/src/lib/ai/model-availability.ts b/src/lib/ai/model-availability.ts new file mode 100644 index 000000000..0584f49f9 --- /dev/null +++ b/src/lib/ai/model-availability.ts @@ -0,0 +1,91 @@ +import { safeFetch } from "@/lib/safe-fetch"; +import { aiEgressPolicyFor } from "./local-host-allowlist"; + +/** + * Does an OpenAI-compatible endpoint still offer the configured model? + * + * The operator's provider pointed at an OAuth proxy that installs + * `openai-oauth@latest` on every restart. One restart later the proxy listed + * only newer model names, the configured one was gone, and every call + * answered HTTP 500 with a body that named nothing. From the outside that + * reads as "the provider is down", and the fix (pick a model the endpoint + * offers) is invisible. + * + * `GET {baseUrl}/models` answers the question for free: it is the standard + * listing every OpenAI-compatible server implements, it bills nothing, and + * it needs the same bearer as a completion. The answer is cached for a few + * minutes per endpoint and model, so a burst of failures probes once. + * + * Tri-state on purpose. `unknown` (no listing route, a non-JSON answer, the + * probe itself failing) never claims the model is missing: only an endpoint + * that answered with a list that does not contain the name earns + * `not_listed`. + */ +export type ModelListing = "listed" | "not_listed" | "unknown"; + +const PROBE_TIMEOUT_MS = 5_000; +const CACHE_TTL_MS = 10 * 60 * 1000; + +const cache = new Map(); + +/** Test-only: forget every cached answer. */ +export function clearModelListingCache(): void { + cache.clear(); +} + +export async function probeModelListing(input: { + baseUrl: string; + apiKey: string; + model: string; + /** See `OpenAIClient`'s `operatorTrusted`. */ + operatorTrusted?: boolean; + now?: number; +}): Promise { + const now = input.now ?? Date.now(); + const key = `${input.baseUrl}\u0000${input.model}`; + const hit = cache.get(key); + if (hit && now - hit.at < CACHE_TTL_MS) return hit.value; + + const value = await probeOnce(input); + cache.set(key, { at: now, value }); + return value; +} + +async function probeOnce(input: { + baseUrl: string; + apiKey: string; + model: string; + operatorTrusted?: boolean; +}): Promise { + const url = `${input.baseUrl.replace(/\/$/, "")}/models`; + const headers: Record = { Accept: "application/json" }; + const key = input.apiKey.trim(); + if (key) headers.Authorization = `Bearer ${key}`; + try { + const res = await safeFetch( + url, + { method: "GET", headers }, + { + timeoutMs: PROBE_TIMEOUT_MS, + ...aiEgressPolicyFor(url, { operatorTrusted: input.operatorTrusted }), + }, + ); + if (!res.ok) return "unknown"; + const json = (await res.json().catch(() => null)) as { + data?: unknown; + } | null; + if (!json || !Array.isArray(json.data)) return "unknown"; + const ids = json.data + .map((entry) => + entry && typeof entry === "object" + ? (entry as { id?: unknown }).id + : undefined, + ) + .filter((id): id is string => typeof id === "string"); + if (ids.length === 0) return "unknown"; + return ids.includes(input.model) ? "listed" : "not_listed"; + } catch { + // The probe is a diagnosis, never a gate: a failed probe says nothing. + return "unknown"; + } +} diff --git a/src/lib/ai/openai-client.ts b/src/lib/ai/openai-client.ts index 46c084158..ce57df3f7 100644 --- a/src/lib/ai/openai-client.ts +++ b/src/lib/ai/openai-client.ts @@ -1,6 +1,7 @@ import { safeFetch } from "@/lib/safe-fetch"; import { callTimeoutMs } from "./effective-timeout"; import { annotate } from "@/lib/logging/context"; +import { emitSignal } from "@/lib/logging/signal"; import type { AIProvider, CompletionParams, CompletionResult } from "./types"; import { isCanonicalOpenAIEndpoint, @@ -28,6 +29,7 @@ import { rememberJsonModeDialect, } from "./json-dialect"; import { aiEgressPolicyFor } from "./local-host-allowlist"; +import { probeModelListing } from "./model-availability"; import type { ReasoningEffort } from "./reasoning-effort"; import { buildOpenAIMessages, @@ -113,6 +115,33 @@ export class OpenAIClient implements AIProvider { this.type = config.providerType ?? "admin-key"; } + /** + * v1.42 — after a server error from an operator- or person-configured + * endpoint (never the canonical `api.openai.com`, which names a missing + * model in its own 404), check whether it still lists the configured + * model. A 4xx already carries its reason in the body; a 5xx from a proxy + * often carries none. See `model-availability.ts`. + */ + private async modelNoLongerServed(status: number): Promise { + if (status < 500) return false; + if (this.type === "codex") return false; + if (isCanonicalOpenAIEndpoint(this.config.baseUrl)) return false; + const listing = await probeModelListing({ + baseUrl: this.config.baseUrl, + apiKey: this.config.apiKey, + model: this.config.model, + operatorTrusted: this.config.operatorTrusted, + }); + if (listing === "not_listed") { + emitSignal({ + action: "ai.provider.model_not_served", + level: "error", + meta: { provider: this.type, model: this.config.model, status }, + }); + } + return listing === "not_listed"; + } + /** * True only for the user-configured gateway. Read it as "the base URL came * from a person, not from this repository" — every behaviour that must not @@ -306,8 +335,15 @@ export class OpenAIClient implements AIProvider { }); return this.generateCompletion(params); } + // v1.42 — a proxy that stopped offering the configured model answers + // with a bare 500 that names nothing. Ask its model listing (free, no + // completion) and say so plainly when the name is gone, so the chain, + // the health card and the log name the actual fix. + const modelNotServed = await this.modelNoLongerServed(res.status); const err = new Error( - `${this.isGateway ? "OpenAI-compatible gateway" : "OpenAI"} request failed (${res.status})`, + modelNotServed + ? `${this.isGateway ? "OpenAI-compatible gateway" : "OpenAI"} request failed (${res.status}): model "${this.config.model}" is not offered by this endpoint` + : `${this.isGateway ? "OpenAI-compatible gateway" : "OpenAI"} request failed (${res.status})`, ); // Keep the body in a structured field rather than the message so // Error.message stays short and the excerpt lands in dedicated log @@ -317,6 +353,7 @@ export class OpenAIClient implements AIProvider { upstream: this.isGateway ? "openai-compatible" : "openai", model: this.config.model, bodyExcerpt, + ...(modelNotServed ? { modelNotServed: true } : {}), }); throw err; } diff --git a/src/lib/ai/provider-health-ledger.ts b/src/lib/ai/provider-health-ledger.ts index 4aae33447..64c49388c 100644 --- a/src/lib/ai/provider-health-ledger.ts +++ b/src/lib/ai/provider-health-ledger.ts @@ -52,13 +52,59 @@ export const HARD_FAILURE_COOLDOWN_MS = 5 * 60 * 1000; // 5min * never productive. */ export const HARD_FAILURE_SKIP_THRESHOLD = 3; +/** + * v1.42 — a provider that keeps failing is PAUSED, with a pause that grows. + * + * The backoff above lifts five minutes after each failure, and a lifted + * provider goes back to the front of the chain. An operator gateway that + * answered HTTP 500 to every call (it no longer offered the configured model) + * was therefore tried first again every five minutes: 1 766 failures in a row, + * and a 500 in front of 61 chains that the next provider then answered. + * + * From `PROVIDER_PAUSE_THRESHOLD` consecutive hard failures on, each failure + * re-arms the skip window at `PROVIDER_PAUSE_BASE_MS` doubled per further + * failure, capped at `PROVIDER_PAUSE_MAX_MS`. Paused is the same skip as + * backoff (the provider moves to the tail of the chain, behind everything + * healthy, and is still walked as a last resort, so a chain never loses its + * only provider). When the window lifts, the next call tries it again: one + * success clears the count and resumes it in place, one more failure doubles + * the pause. Nothing needs to be reset by hand. The admin provider-health card + * shows a paused provider and until when. + * + * Conservative on purpose: five failures in a row is far past a brown-out, + * the first pause is half an hour, and the ceiling is a day, so a provider + * that recovers is tried again within a day even without a success elsewhere. + */ +export const PROVIDER_PAUSE_THRESHOLD = 5; +export const PROVIDER_PAUSE_BASE_MS = 30 * 60 * 1000; +export const PROVIDER_PAUSE_MAX_MS = 24 * 60 * 60 * 1000; + +/** + * The skip window a hard failure arms, given the consecutive-failure count + * INCLUDING that failure. Below the pause threshold it is the short backoff; + * from the threshold on it doubles per failure up to the ceiling. + */ +export function hardFailureCooldownMs(consecutiveFailures: number): number { + if (consecutiveFailures < PROVIDER_PAUSE_THRESHOLD) { + return HARD_FAILURE_COOLDOWN_MS; + } + const doublings = Math.min( + consecutiveFailures - PROVIDER_PAUSE_THRESHOLD, + 16, + ); + return Math.min( + PROVIDER_PAUSE_BASE_MS * 2 ** doublings, + PROVIDER_PAUSE_MAX_MS, + ); +} + export type ProviderHealthResult = "ok" | "hard_failed" | "auth_failed"; /** A provider the runner should skip (negative cache) on this call, * with the reason so the caller can surface it. */ export interface ProviderSkipHint { providerType: ProviderChainType; - reason: "credential_expired" | "backoff"; + reason: "credential_expired" | "backoff" | "paused"; /** When the negative cache lifts (ledger `nextRetryAt`). */ retryAt: Date | null; } @@ -132,7 +178,10 @@ export const postgresProviderHealthLedger: ProviderHealthLedger = { } else if (row.consecutiveFailures >= HARD_FAILURE_SKIP_THRESHOLD) { hints.set(provider, { providerType: provider, - reason: "backoff", + reason: + row.consecutiveFailures >= PROVIDER_PAUSE_THRESHOLD + ? "paused" + : "backoff", retryAt: row.nextRetryAt, }); } @@ -172,11 +221,18 @@ export const postgresProviderHealthLedger: ProviderHealthLedger = { const { result, cooldownMs } = classifyFailure(httpStatus); const interval = `${cooldownMs} milliseconds`; const status = httpStatus ?? null; + // v1.42 — the escalating pause for a hard failure, computed in SQL from + // the count the same statement writes, so two workers recording at once + // still arm the pause the combined count deserves. Mirrors + // `hardFailureCooldownMs`; an auth failure keeps its fixed cooldown. + const pauseFrom = PROVIDER_PAUSE_THRESHOLD; + const pauseBase = `${PROVIDER_PAUSE_BASE_MS} milliseconds`; + const pauseMax = `${PROVIDER_PAUSE_MAX_MS} milliseconds`; try { // Atomic upsert. `consecutive_failures` accumulates across workers; // an auth failure forces the cooldown regardless of count, a hard - // failure extends it. The fixed cooldown anchors on NOW() so a - // fresh failure always re-arms the skip window. + // failure extends it. The cooldown anchors on NOW() so a fresh failure + // always re-arms the skip window. await prisma.$executeRaw` INSERT INTO provider_health (id, user_id, provider_type, last_result, last_status, @@ -190,7 +246,18 @@ export const postgresProviderHealthLedger: ProviderHealthLedger = { last_status = ${status}, consecutive_failures = provider_health.consecutive_failures + 1, last_failure_at = NOW(), - next_retry_at = NOW() + ${interval}::interval, + next_retry_at = NOW() + CASE + WHEN ${result} = 'hard_failed' + AND provider_health.consecutive_failures + 1 >= ${pauseFrom}::int + THEN LEAST( + ${pauseMax}::interval, + ${pauseBase}::interval * power( + 2, + LEAST(provider_health.consecutive_failures + 1 - ${pauseFrom}::int, 16) + ) + ) + ELSE ${interval}::interval + END, updated_at = NOW() `; } catch { @@ -265,7 +332,10 @@ export function createInMemoryProviderHealthLedger(): ProviderHealthLedger & { ) { out.set(provider, { providerType: provider, - reason: "backoff", + reason: + row.consecutiveFailures >= PROVIDER_PAUSE_THRESHOLD + ? "paused" + : "backoff", retryAt: new Date(row.nextRetryAt), }); } @@ -289,11 +359,16 @@ export function createInMemoryProviderHealthLedger(): ProviderHealthLedger & { const prev = rowsFor(userId).get(providerType); const priorCount = prev && prev.result !== "ok" ? prev.consecutiveFailures : 0; + const count = priorCount + 1; rowsFor(userId).set(providerType, { result, status: httpStatus, - consecutiveFailures: priorCount + 1, - nextRetryAt: Date.now() + cooldownMs, + consecutiveFailures: count, + nextRetryAt: + Date.now() + + (result === "hard_failed" + ? hardFailureCooldownMs(count) + : cooldownMs), }); }, inspect(userId) { diff --git a/src/lib/ai/provider-runner.ts b/src/lib/ai/provider-runner.ts index 860da4973..3fd812767 100644 --- a/src/lib/ai/provider-runner.ts +++ b/src/lib/ai/provider-runner.ts @@ -6,6 +6,7 @@ import { type ProviderSkipHint, } from "./provider-health-ledger"; import { annotate } from "@/lib/logging/context"; +import { emitSignal } from "@/lib/logging/signal"; import { isOperatorFundedProvider, readDailySpend, @@ -395,6 +396,67 @@ export function classifyErrorBody(body: unknown): string | null { return `unclassified:${body.length}chars`; } +/** + * A short, stable cause for one failed hop, for the `ai.chain.link_failed` + * line. Our own vocabulary only: the provider's words never leave. + */ +function hopCause( + error: unknown, + status: number | null, + bodyClass: string | null, +): string { + const err = error as { + credentialExpired?: unknown; + modelNotServed?: unknown; + } | null; + if (err?.modelNotServed === true) return "model_not_served"; + if (err?.credentialExpired === true) return "credential_expired"; + if (bodyClass?.startsWith("classified:")) { + return bodyClass.slice("classified:".length); + } + if (status === null || status <= 0) return "network"; + if (status === 401 || status === 403) return "auth_rejected"; + if (status === 429) return "rate_limited"; + if (status >= 500) return "upstream_5xx"; + return "upstream_4xx"; +} + +interface HopSignal { + provider: ProviderChainType; + attempt: number; + status: number | null; + cause: string; +} + +/** + * v1.42 — one `ai.chain.link_failed` line per failed hop, written once the + * chain has settled: `warn` when a later provider answered (the fallback + * covered it), `error` when nothing did. The hop details used to live only as + * `ai_chain_hop_*` meta keys on the caller's line at level `info`, where a + * query for failures could not see them and the last caller of a batch + * overwrote the others. + */ +function signalFailedHops( + hops: readonly HopSignal[], + recovered: boolean, + surface: BudgetSurface, +): void { + for (const hop of hops) { + emitSignal({ + action: "ai.chain.link_failed", + level: recovered ? "warn" : "error", + meta: { + provider: hop.provider, + attempt: hop.attempt, + status: hop.status, + cause: hop.cause, + recovered, + surface, + }, + }); + } +} + /** * Shared chain walker for the two RAW runners (streaming + buffered). Owns the * one set of chain / fallback / health-ledger semantics — empty-chain guard, @@ -431,6 +493,7 @@ async function runRawChain( const ordered = await resolveChainOrder(userId, providers, ledger); const hops: FallbackHop[] = []; + const failedHops: HopSignal[] = []; for (let i = 0; i < ordered.length; i += 1) { const candidate = ordered[i]; @@ -510,6 +573,7 @@ async function runRawChain( : {}), }, }); + signalFailedHops(failedHops, true, surface); return { result, workingProvider: candidate, @@ -520,6 +584,12 @@ async function runRawChain( throw error; } const summary = summariseError(error); + failedHops.push({ + provider: candidate.providerType, + attempt: i + 1, + status: summary.status, + cause: hopCause(error, summary.status, summary.bodyExcerpt), + }); void ledger.recordFailure(userId, candidate.providerType, summary.status); const hop: FallbackHop = { providerType: candidate.providerType, @@ -545,6 +615,7 @@ async function runRawChain( ai_chain_fallback_count: hops.length, }, }); + signalFailedHops(failedHops, false, surface); throw new AllProvidersFailedError(hops); } diff --git a/src/lib/ai/provider.ts b/src/lib/ai/provider.ts index 847a9c442..6c90c3376 100644 --- a/src/lib/ai/provider.ts +++ b/src/lib/ai/provider.ts @@ -9,6 +9,7 @@ import { AnthropicClient } from "./anthropic-client"; import { LocalOpenAICompatibleClient } from "./local-client"; import { refreshDeviceTokens, + codexReconnectRequired, encryptCodexCreds, decryptCodexCreds, encryptAdminCodexCreds, @@ -328,14 +329,14 @@ async function resolveCodexProvider( !freshUser?.codexAccessTokenEncrypted || !freshUser.codexRefreshTokenEncrypted ) { - throw new Error("No refresh token available"); + throw codexReconnectRequired("no refresh token"); } const decoded = decryptCodexCreds({ accessEncrypted: freshUser.codexAccessTokenEncrypted, refreshEncrypted: freshUser.codexRefreshTokenEncrypted, }); if (!decoded) { - throw new Error("Codex token storage corrupt; user must re-link"); + throw codexReconnectRequired("token storage corrupt"); } const fresh = await refreshDeviceTokens(decoded.refreshToken); const enc = encryptCodexCreds(fresh); @@ -444,7 +445,7 @@ async function resolveAdminCodexProvider(): Promise { !fresh.adminCodexRefreshTokenEncrypted || !fresh.adminCodexAccountIdEncrypted ) { - throw new Error("No central-codex refresh token available"); + throw codexReconnectRequired("no central refresh token"); } const decoded = decryptAdminCodexCreds({ accessEncrypted: fresh.adminCodexAccessTokenEncrypted, @@ -453,9 +454,7 @@ async function resolveAdminCodexProvider(): Promise { expiresAt: fresh.adminCodexTokenExpiresAt, }); if (!decoded) { - throw new Error( - "Central-codex token storage corrupt; re-link required", - ); + throw codexReconnectRequired("central token storage corrupt"); } const refreshed = await refreshDeviceTokens(decoded.refreshToken); const enc = encryptAdminCodexCreds(refreshed); diff --git a/src/lib/google-health/__tests__/date-filter-fallback.test.ts b/src/lib/google-health/__tests__/date-filter-fallback.test.ts index c983cd3d6..981468d66 100644 --- a/src/lib/google-health/__tests__/date-filter-fallback.test.ts +++ b/src/lib/google-health/__tests__/date-filter-fallback.test.ts @@ -19,6 +19,8 @@ vi.mock("@/lib/safe-fetch", async (importOriginal) => { }); import { GOOGLE_HEALTH_DATA_TYPES, fetchDataPoints } from "../client"; +import { WideEventBuilder } from "@/lib/logging/event-builder"; +import { eventStorage } from "@/lib/logging/context"; import { GoogleHealthApiError } from "../response-classifier"; function jsonResponse(status: number, body: unknown): Response { @@ -177,3 +179,82 @@ describe("fetchDataPoints — daily-summary filter style", () => { expect(capturedFilter(0)).toBeNull(); }); }); + +// v1.42 (#1023) — the first-request 400 that triggers the snake_case retry is +// expected, and the 200 right after it is the answer. It was logged as an +// error beside that 200; a self-hoster read it as a failing sync. +describe("fetchDataPoints — the fallback's 400 is a note, not an error", () => { + async function callsFor(run: () => Promise) { + const evt = new WideEventBuilder("background"); + await eventStorage.run(evt, () => run().catch(() => undefined)); + return evt.toJSON().external_calls ?? []; + } + + it("records the rejected camelCase probe without an error", async () => { + safeFetchMock + .mockResolvedValueOnce( + jsonResponse(400, { + error: { status: "INVALID_ARGUMENT", message: "Invalid filter" }, + }), + ) + .mockResolvedValueOnce(jsonResponse(200, { dataPoints: [] })); + + const calls = await callsFor(() => + fetchDataPoints( + GOOGLE_HEALTH_DATA_TYPES.restingHeartRate, + "t", + "fetchRhr", + { + start, + }, + ), + ); + expect(calls).toHaveLength(2); + expect(calls[0]).toMatchObject({ + status: 400, + note: "date_filter_rejected_retrying_snake_case", + }); + expect(calls[0].error).toBeUndefined(); + expect(calls[1].error).toBeUndefined(); + }); + + it("still records the error when the snake_case retry is refused too", async () => { + safeFetchMock.mockResolvedValue( + jsonResponse(400, { + error: { status: "INVALID_ARGUMENT", message: "Invalid filter" }, + }), + ); + const calls = await callsFor(() => + fetchDataPoints( + GOOGLE_HEALTH_DATA_TYPES.restingHeartRate, + "t", + "fetchRhr", + { + start, + }, + ), + ); + expect(calls[1].error).toMatch(/400/); + }); + + it("still records a 400 on a sample read, which has no fallback", async () => { + safeFetchMock.mockResolvedValue( + jsonResponse(400, { + error: { status: "INVALID_ARGUMENT", message: "Invalid filter" }, + }), + ); + const calls = await callsFor(() => + fetchDataPoints( + GOOGLE_HEALTH_DATA_TYPES.heartRate, + "t", + "fetchHeartRate", + { + start, + }, + ), + ); + expect(calls).toHaveLength(1); + expect(calls[0].error).toBeDefined(); + expect(calls[0].note).toBeUndefined(); + }); +}); diff --git a/src/lib/google-health/__tests__/sync-intraday-overlap.test.ts b/src/lib/google-health/__tests__/sync-intraday-overlap.test.ts new file mode 100644 index 000000000..4bf475bbb --- /dev/null +++ b/src/lib/google-health/__tests__/sync-intraday-overlap.test.ts @@ -0,0 +1,88 @@ +/** + * v1.42 (#1023) — intraday heart rate re-reads two hours, not a day. + * + * Every hourly sync re-read the last 24 hours of every Google Health type, + * because daily summaries and sleep are re-scored after the fact. A + * per-minute heart-rate stream does not change once written, and re-reading + * a whole day of it each hour was 38 to 40 pages per sync on a slow host. + * Heart rate now uses the short intraday overlap; daily summaries keep the + * full day. + */ +import { beforeEach, describe, expect, it, vi } from "vitest"; + +const { safeFetchMock } = vi.hoisted(() => ({ safeFetchMock: vi.fn() })); + +vi.mock("@/lib/safe-fetch", async (importOriginal) => { + const actual = await importOriginal(); + return { ...actual, safeFetch: safeFetchMock }; +}); + +vi.mock("../sync-core", async (importOriginal) => { + const actual = await importOriginal(); + return { + ...actual, + getValidToken: vi.fn(async () => ({ accessToken: "token" })), + handleCollectionFetchError: vi.fn(async () => 0), + upsertGoogleHealthMeasurements: vi.fn(async () => ({ + imported: 0, + touched: [], + inserted: [], + })), + }; +}); + +vi.mock("@/lib/db", () => ({ + prisma: { user: { findUnique: vi.fn(), update: vi.fn() } }, +})); + +vi.mock("@/lib/tz/resolver", () => ({ + resolveUserTimezone: vi.fn(async () => "UTC"), +})); + +import { + GOOGLE_HEALTH_DEFAULT_OVERLAP_MS, + GOOGLE_HEALTH_INTRADAY_OVERLAP_MS, + incrementalStart, +} from "../sync-core"; +import { syncUserMetrics } from "../sync-metrics"; + +const LAST_SYNC = new Date("2026-10-08T03:00:00.000Z"); + +/** The `filter` the request for one data-type path carried. */ +function filterFor(path: string): string | null { + const call = safeFetchMock.mock.calls.find((c) => + new URL(c[0] as string).pathname.endsWith(`/dataTypes/${path}/dataPoints`), + ); + return call ? new URL(call[0] as string).searchParams.get("filter") : null; +} + +beforeEach(() => { + safeFetchMock.mockReset().mockImplementation(async () => ({ + status: 200, + ok: true, + json: async () => ({ dataPoints: [] }), + })); +}); + +describe("Google Health incremental overlap", () => { + it("keeps a day for summaries and narrows intraday samples to two hours", () => { + expect(GOOGLE_HEALTH_DEFAULT_OVERLAP_MS).toBe(24 * 60 * 60 * 1000); + expect(GOOGLE_HEALTH_INTRADAY_OVERLAP_MS).toBe(2 * 60 * 60 * 1000); + }); + + it("reads heart rate from the intraday start and resting heart rate from the day start", async () => { + const start = incrementalStart(LAST_SYNC); + const intradayStart = incrementalStart(LAST_SYNC, { + overlapMs: GOOGLE_HEALTH_INTRADAY_OVERLAP_MS, + }); + + await syncUserMetrics("u1", { start, intradayStart }); + + expect(filterFor("heart-rate")).toBe( + 'heart_rate.sample_time.physical_time >= "2026-10-08T01:00:00.000Z"', + ); + expect(filterFor("daily-resting-heart-rate")).toBe( + 'dailyRestingHeartRate.date >= "2026-10-07"', + ); + }); +}); diff --git a/src/lib/google-health/__tests__/sync-outcomes.test.ts b/src/lib/google-health/__tests__/sync-outcomes.test.ts index 140fbed28..4d4012476 100644 --- a/src/lib/google-health/__tests__/sync-outcomes.test.ts +++ b/src/lib/google-health/__tests__/sync-outcomes.test.ts @@ -135,6 +135,7 @@ vi.mock("@/lib/insights/comprehensive-generate", () => ({ vi.mock("../sync-core", () => ({ GOOGLE_HEALTH_INTEGRATION_KEY: "google-health", incrementalStart: vi.fn(() => undefined), + GOOGLE_HEALTH_INTRADAY_OVERLAP_MS: 2 * 60 * 60 * 1000, markSynced: vi.fn(async () => {}), runWithGoogleHealthSyncCycle: runCycle, })); diff --git a/src/lib/google-health/client.ts b/src/lib/google-health/client.ts index 923968b2a..e784bb5af 100644 --- a/src/lib/google-health/client.ts +++ b/src/lib/google-health/client.ts @@ -829,17 +829,32 @@ export async function forEachDataPointPage( verdict.classification === "success" ? undefined : extractGoogleApiErrorDetail(json); + // v1.42 (#1023) — the first filtered daily-summary read answering 400 + // is the expected trigger for the snake_case retry below, not a + // failure: some accounts reject the documented camelCase prefix on + // some types, and the very next request answers 200. It was logged as + // an error next to the 200 that followed it. It is recorded as a note + // now; any other 400 still carries its error. + const expectedFallback = + canFallBack && + dateStyle === "camel" && + requestCount === 1 && + res.status === 400; getEvent()?.addExternalCall({ service: "google-health", method: `${verb}(page=${pageCount})`, duration_ms: Math.round(performance.now() - pageStart), status: res.status, - error: - verdict.classification === "success" - ? undefined - : apiErrorDetail - ? `${verdict.reason} ${apiErrorDetail}` - : verdict.reason, + ...(expectedFallback + ? { note: "date_filter_rejected_retrying_snake_case" } + : { + error: + verdict.classification === "success" + ? undefined + : apiErrorDetail + ? `${verdict.reason} ${apiErrorDetail}` + : verdict.reason, + }), }); if (verdict.classification !== "success") { throw new GoogleHealthApiError({ diff --git a/src/lib/google-health/sync-core.ts b/src/lib/google-health/sync-core.ts index 3b478e8d4..eb7f86954 100644 --- a/src/lib/google-health/sync-core.ts +++ b/src/lib/google-health/sync-core.ts @@ -59,6 +59,16 @@ const TOKEN_REFRESH_BUFFER_MS = 5 * 60 * 1000; */ export const GOOGLE_HEALTH_DEFAULT_OVERLAP_MS = 24 * 60 * 60 * 1000; +/** + * v1.42 (#1023) — the overlap for intraday samples (heart rate, one point a + * minute). The 24 h overlap exists for daily summaries and sleep, which + * Google re-scores after the fact; a minute sample is final when it is + * written. Re-reading a whole day of it every hour meant 38 to 40 pages per + * sync on a per-minute stream, which a slow host felt. Two hours still + * covers a watch that syncs to the phone late. + */ +export const GOOGLE_HEALTH_INTRADAY_OVERLAP_MS = 2 * 60 * 60 * 1000; + export interface GoogleHealthTokenInfo { accessToken: string; connection: { id: string; googleUserId: string }; @@ -354,6 +364,12 @@ export interface GoogleHealthResourceSyncOptions { fullSync?: boolean; /** The incremental lower bound, snapshotted once by the orchestrator. */ start?: Date; + /** + * v1.42 — the incremental lower bound for intraday samples, from the same + * snapshot with `GOOGLE_HEALTH_INTRADAY_OVERLAP_MS`. Undefined on a full + * run, like `start`; a resource that does not set it falls back to `start`. + */ + intradayStart?: Date; /** * When true, `upsertGoogleHealthMeasurements` writes the rows but SKIPS the * inline per-(type,day) DAY-rollup recompute + status-insight invalidate, diff --git a/src/lib/google-health/sync-metrics.ts b/src/lib/google-health/sync-metrics.ts index d253ed437..473a06147 100644 --- a/src/lib/google-health/sync-metrics.ts +++ b/src/lib/google-health/sync-metrics.ts @@ -65,6 +65,11 @@ interface MetricResource { verb: string; /** Page ceiling for the walk; the client default when omitted. */ maxPages?: number; + /** + * v1.42 — a minute-level sample stream, final when written, so it + * re-reads only the short intraday overlap instead of a whole day. + */ + intraday?: boolean; } /** The launch metric resources (Measurement-producing). Height handled separately. */ @@ -104,6 +109,7 @@ const METRIC_RESOURCES: MetricResource[] = [ map: mapHeartRate, verb: "fetchHeartRate", maxPages: GOOGLE_HEALTH_DENSE_MAX_PAGES, + intraday: true, }, { dataType: GOOGLE_HEALTH_DATA_TYPES.bloodGlucose, @@ -166,7 +172,10 @@ export async function syncUserMetrics( resource.dataType, tokenInfo.accessToken, resource.verb, - { start, maxPages: resource.maxPages }, + { + start: resource.intraday ? (opts.intradayStart ?? start) : start, + maxPages: resource.maxPages, + }, async (points) => { const readings: GoogleHealthMeasurementUpsert[] = []; for (const point of points) { diff --git a/src/lib/google-health/sync.ts b/src/lib/google-health/sync.ts index 87cd3f9ba..202b4be07 100644 --- a/src/lib/google-health/sync.ts +++ b/src/lib/google-health/sync.ts @@ -19,6 +19,7 @@ import { syncUserWorkout } from "./sync-workout"; import { GOOGLE_HEALTH_INTEGRATION_KEY, incrementalStart, + GOOGLE_HEALTH_INTRADAY_OVERLAP_MS, markSynced, runWithGoogleHealthSyncCycle, type GoogleHealthResourceSyncOptions, @@ -173,9 +174,14 @@ export async function syncUserGoogleHealth( const start = incrementalStart(connection.lastSyncedAt, { fullSync: opts.fullSync, }); + const intradayStart = incrementalStart(connection.lastSyncedAt, { + fullSync: opts.fullSync, + overlapMs: GOOGLE_HEALTH_INTRADAY_OVERLAP_MS, + }); const resourceOpts: GoogleHealthResourceSyncOptions = { fullSync: opts.fullSync, start, + intradayStart, deferRollup: opts.fullSync === true, }; const resources = [ diff --git a/src/lib/insights/__tests__/comprehensive-outbound-repair.test.ts b/src/lib/insights/__tests__/comprehensive-outbound-repair.test.ts new file mode 100644 index 000000000..1a8b305f1 --- /dev/null +++ b/src/lib/insights/__tests__/comprehensive-outbound-repair.test.ts @@ -0,0 +1,177 @@ +/** + * v1.42 — one bounded repair after the outbound safety screen withholds a + * generated briefing. + * + * A screened generation used to fail outright, and the nightly pass then + * queued its 45-minute provider retry, which asked the same model the same + * question and was screened again (eight times a night on one account). Now + * the generator asks once more with the broken contract named, and persists + * the repair only when it passes the same parse, grounding and screen as a + * first pass. These tests pin the repair, its correction text, and that a + * repair which is screened again still persists nothing. + */ +import { describe, it, expect, vi, beforeEach } from "vitest"; + +const findUnique = vi.fn(); +const userUpdate = vi.fn(); +const resolveProviderChain = vi.fn(); +const resolveProvider = vi.fn(); +const runRawCompletionWithFallback = vi.fn(); +const extractFeatures = vi.fn(); + +vi.mock("@/lib/db", () => ({ + prisma: { + // The briefing path now reserves against the day's token ledger before + // egress and reconciles after (`reserveBudget` / `reconcileSpend`), both + // over raw SQL. A zero prior total keeps every generation under the cap, + // so these suites keep testing what they were written to test. + $queryRaw: vi.fn(async () => [{ total_tokens: 0, operator_tokens: 0 }]), + $executeRaw: vi.fn(async () => 0), + user: { + findUnique: (...a: unknown[]) => findUnique(...a), + update: (...a: unknown[]) => userUpdate(...a), + // v1.32.22 (M6) — the cache commit is now a privacy-mode-guarded + // updateMany; record it on the same spy but return a matched count so the + // guard proceeds (mode unchanged in these tests). + updateMany: (...a: unknown[]) => { + userUpdate(...a); + return Promise.resolve({ count: 1 }); + }, + }, + auditLog: { deleteMany: vi.fn() }, + // v1.41 — the operator's reasoning controls; an untouched instance. + appSettings: { findUnique: vi.fn(async () => null) }, + }, +})); +// The `briefing` capability is available in these fixtures; the refusal +// path has its own test in comprehensive-generate-force.test.ts. +// The wire re-check (`aiEgressRefusal`) passes in these fixtures; its refusal +// arm has its own test in comprehensive-budget-refusal.test.ts. +vi.mock("@/lib/ai/capabilities/egress", () => ({ + aiEgressRefusal: vi.fn(async () => null), +})); +vi.mock("@/lib/ai/capabilities/gate", () => ({ + aiCapabilityForRecord: vi.fn(async () => ({ + available: true, + reason: null, + onDeviceAllowed: true, + })), + aiCapabilityToServe: async () => ({ + available: true, + reason: null, + onDeviceAllowed: true, + }), +})); +vi.mock("@/lib/ai/provider", () => ({ + resolveProviderChain: (...a: unknown[]) => resolveProviderChain(...a), + resolveProvider: (...a: unknown[]) => resolveProvider(...a), +})); +vi.mock("@/lib/ai/provider-runner", () => ({ + AllProvidersFailedError: class extends Error {}, + runRawCompletionWithFallback: (...a: unknown[]) => + runRawCompletionWithFallback(...a), +})); +vi.mock("@/lib/insights/features", () => ({ + FeaturesPayloadTooLargeError: class extends Error { + sizeBytes = 0; + }, + extractFeatures: (...a: unknown[]) => extractFeatures(...a), + BRIEFING_FEATURE_WINDOW_DAYS: 400, +})); +vi.mock("@/lib/insights/illness-cycle-briefing", () => ({ + buildBriefingIllnessCycleContext: vi.fn().mockResolvedValue(null), + buildBriefingIllnessCyclePrompt: vi.fn().mockReturnValue(""), +})); +vi.mock("@/lib/insights/glp1-plateau", () => ({ + detectGlp1Plateau: vi.fn(async () => null), + buildGlp1PlateauPrompt: vi.fn(() => ""), +})); +vi.mock("@/lib/ai/coach/about-me", () => ({ + getSelfContextTextForUser: vi.fn(async () => null), + buildAboutMeInsightBlock: vi.fn(() => ""), +})); +vi.mock("@/lib/cache/invalidate", () => ({ + invalidateUserInsights: vi.fn(), +})); + +import { generateComprehensiveInsight } from "../comprehensive-generate"; + +const FEATURES = { weight: { count: 12, latest: 81.4, mean30: 82.1 } }; + +beforeEach(() => { + vi.clearAllMocks(); + // A once-queued reply must not leak from one case into the next. + runRawCompletionWithFallback.mockReset(); + resolveProviderChain.mockResolvedValue([ + { providerType: "openai", instance: {} }, + ]); + resolveProvider.mockResolvedValue({ type: "none" }); + extractFeatures.mockResolvedValue(FEATURES); + userUpdate.mockResolvedValue({}); + // No cached text / hash → always runs a full generation (no gate hit). + findUnique.mockResolvedValue({ + insightsPrivacyMode: "aggregated", + insightsCachedAt: null, + insightsCachedText: null, + insightsExcludeMetrics: [], + insightsSnapshotHash: null, + insightsBriefingRerollDate: null, + }); +}); + +const CAUSAL = JSON.stringify({ + summary: "Your weight fell because you slept more.", + dailyBriefing: { paragraph: "ok" }, +}); +const CLEAN = JSON.stringify({ + summary: "Your weight was lower on days when you slept longer.", + dailyBriefing: { paragraph: "ok" }, +}); + +function reply(content: string) { + return { + result: { content, tokensUsed: 10, model: "m" }, + workingProvider: { providerType: "openai" }, + fallbackHops: [], + }; +} + +describe("comprehensive outbound-screen repair", () => { + it("persists a repair that passes the screen, after one corrective call", async () => { + runRawCompletionWithFallback + .mockResolvedValueOnce(reply(CAUSAL)) + .mockResolvedValueOnce(reply(CLEAN)); + + const outcome = await generateComprehensiveInsight("u1", { locale: "en" }); + + expect(outcome).toEqual({ status: "generated", providerType: "openai" }); + expect(runRawCompletionWithFallback).toHaveBeenCalledTimes(2); + const repairPrompt = + runRawCompletionWithFallback.mock.calls[1][0].params.messages[0].content; + expect(repairPrompt).toContain("withheld by the safety screen"); + expect(repairPrompt).toContain("CAUSES"); + // The repaired text is what lands in the cache, never the screened one. + const written = JSON.stringify(userUpdate.mock.calls.at(-1)); + expect(written).toContain("on days when you slept longer"); + expect(written).not.toContain("because you slept more"); + }); + + it("stays withheld when the repair is screened again, and asks only once", async () => { + runRawCompletionWithFallback.mockResolvedValue(reply(CAUSAL)); + + const outcome = await generateComprehensiveInsight("u1", { locale: "en" }); + + expect(outcome).toEqual({ status: "failed", reason: "outbound-screened" }); + expect(runRawCompletionWithFallback).toHaveBeenCalledTimes(2); + }); + + it("stays withheld when the repair call itself fails", async () => { + runRawCompletionWithFallback + .mockResolvedValueOnce(reply(CAUSAL)) + .mockRejectedValueOnce(new Error("upstream down")); + + const outcome = await generateComprehensiveInsight("u1", { locale: "en" }); + + expect(outcome).toEqual({ status: "failed", reason: "outbound-screened" }); + }); +}); diff --git a/src/lib/insights/briefing-provider.ts b/src/lib/insights/briefing-provider.ts index a573e3a88..fb2686927 100644 --- a/src/lib/insights/briefing-provider.ts +++ b/src/lib/insights/briefing-provider.ts @@ -57,7 +57,7 @@ import { resolveJobReasoning } from "@/lib/ai/reasoning/controls"; * correction did not). */ export type BriefingCompletionStage = - "generate" | "json-retry" | "grounding-retry" | "reroll"; + "generate" | "json-retry" | "grounding-retry" | "screen-retry" | "reroll"; /** * Thrown when the reservation would push the user past the day's ceiling. diff --git a/src/lib/insights/comprehensive-generate.ts b/src/lib/insights/comprehensive-generate.ts index 37d74b324..cd396bfc3 100644 --- a/src/lib/insights/comprehensive-generate.ts +++ b/src/lib/insights/comprehensive-generate.ts @@ -41,6 +41,7 @@ import { fenceBlock, } from "@/lib/ai/coach/data-fence"; import { screenInsightPayloadProse } from "@/lib/ai/safety/insight-payload-screen"; +import type { OutboundReason } from "@/lib/ai/safety/outbound-screen"; import { computeCitationCoverage } from "@/lib/ai/citation-coverage"; import { applyInsightsExcludeFilter } from "@/lib/insights/exclude-filter"; import { getCachedFeatures } from "@/lib/insights/feature-cache"; @@ -166,7 +167,17 @@ export type GenerateOutcome = | "scope-changed" | "profile-scope-changed"; } - | { status: "failed"; reason: string }; + | { + status: "failed"; + reason: string; + /** + * v1.42 — the chain's first provider refused the credential (a dead + * Codex sign-in, a revoked key). The nightly pass reports the account + * as `auth_failed` and does not queue a retry that cannot succeed until + * the person reconnects. + */ + credentialExpired?: boolean; + }; /** Higher, seedless temperature for the daily-briefing phrasing re-roll. */ const BRIEFING_REROLL_TEMPERATURE = 0.6; @@ -1259,7 +1270,11 @@ export async function generateComprehensiveInsight( locale, httpStatus: typeof err.httpStatus === "number" ? err.httpStatus : null, }); - return { status: "failed", reason }; + const credentialExpired = + e instanceof AllProvidersFailedError && e.primaryCredentialExpired; + return credentialExpired + ? { status: "failed", reason, credentialExpired } + : { status: "failed", reason }; } // Anthropic + local have no native JSON mode, so a ```json-fenced or @@ -1492,14 +1507,72 @@ export async function generateComprehensiveInsight( // persists NOTHING -- the previous cached payload stays, exactly as a // provider outage or an unparseable response already behaves. The next run // regenerates from scratch. + // + // v1.42 — one bounded repair before giving up, the way the grounding gate + // above gets one corrective retry. A withheld generation used to fail + // outright, and the nightly pass then queued its 45-minute provider retry, + // which asked the same model the same question and was screened again: on + // one account that was eight wasted generations a night over a single + // causal sentence. The repair names the contract that tripped and asks for + // the whole object again; the repaired payload has to pass the same JSON + // parse, the same number grounding and the same screen as a first pass, or + // nothing is persisted, exactly as before. A screened outcome is final for + // the caller: it is not a provider fault, so nothing retries it. const screened = screenInsightPayloadProse(insights, locale); if (screened) { annotate({ action: { name: "insights.generate.outbound_blocked" }, meta: { locale, reason: screened }, }); - void recordBriefingFailure({ userId, reason: "outbound-screened", locale }); - return { status: "failed", reason: "outbound-screened" }; + let repaired = false; + try { + const retry = await runBriefingCompletion({ + userId, + chain, + systemPrompt, + userPrompt: `${userPrompt}\n\n${buildOutboundScreenCorrection(screened)}`, + temperature: AI_BUDGETS.comprehensive.temperature, + maxTokens: resolveInsightsMaxTokens(), + timeoutMs: effectiveTimeoutMs, + stage: "screen-retry", + }); + const retryInsights = parseComprehensiveResult(retry.result.content); + const retryUngrounded = + retryInsights === null + ? [] + : findUngroundedBriefingNumbers( + readBriefingBlock(retryInsights), + features.signalsOfDay ?? null, + features, + groundingExtra, + ); + if ( + retryInsights !== null && + retryUngrounded.length === 0 && + screenInsightPayloadProse(retryInsights, locale) === null + ) { + insights = retryInsights; + result = retry.result; + workingProviderType = retry.workingProvider.providerType; + briefingStrippedHard = false; + repaired = true; + } + } catch { + // A transport failure or the day's budget on the repair: the first + // pass stays withheld, nothing else changes. + } + annotate({ + action: { name: "insights.generate.outbound_repair" }, + meta: { locale, reason: screened, repaired }, + }); + if (!repaired) { + void recordBriefingFailure({ + userId, + reason: "outbound-screened", + locale, + }); + return { status: "failed", reason: "outbound-screened" }; + } } // v1.9.0 — the caller abandoned this generation (its bounded timeout @@ -1556,3 +1629,22 @@ export async function generateComprehensiveInsight( return { status: "generated", providerType: workingProviderType }; } + +/** + * The correction the one screen repair is sent with. Names the contract the + * first reply broke, never the sentence that broke it: the model gets the + * rule, not its own words back. + */ +export function buildOutboundScreenCorrection(reason: OutboundReason): string { + const rule = + reason === "causal_claim" + ? 'It stated that one measurement or habit CAUSES another. Describe co-occurrence and timing only ("was higher on days when", "tends to move together"); never say that something causes, drives, leads to or results in something else.' + : reason === "dose_prescription" + ? "It told the reader to take, change, stop or dose a medication. Never give a dose or a medication instruction; at most suggest discussing medication with their clinician." + : "It gave a risk score, a probability of disease or a diagnosis. Never estimate risk or name a diagnosis; describe the readings and their trend only."; + return ` +Your previous reply was withheld by the safety screen. ${rule} + +Re-write the whole JSON object with the same structure and the same numbers, changing only the wording that broke this rule. Return the full JSON object again. +`; +} diff --git a/src/lib/jobs/__tests__/insight-pregenerate.test.ts b/src/lib/jobs/__tests__/insight-pregenerate.test.ts index 846055bc1..392eac9a1 100644 --- a/src/lib/jobs/__tests__/insight-pregenerate.test.ts +++ b/src/lib/jobs/__tests__/insight-pregenerate.test.ts @@ -1508,3 +1508,131 @@ describe("runInsightPregenerate — warm budget honours the response timeout (v1 } }); }); + +// v1.42 — the run used to annotate one wide event per candidate and the last +// write won, so a night where one account worked and the last one failed read +// as `all-failed`. The run now reports every candidate's outcome together, a +// withheld (screened) briefing and a dead sign-in queue no provider retry, +// and a time-budget cut-off reports the unreached accounts as deferred. +describe("runInsightPregenerate — one outcome per candidate (v1.42)", () => { + type Reported = { + queue: string; + runId: string; + candidates: Array<{ key: string; outcome: string; cause?: string }>; + }; + + function harness(users: Array<{ id: string; locale: string }>) { + const { prisma } = makePrisma(users); + const reportRun = vi.fn(async (input: Reported) => ({ + total: input.candidates.length, + attempted: 0, + failed: 0, + allFailed: input.candidates.every((c) => c.outcome === "failed"), + partial: false, + })); + const enqueueRetry = vi.fn().mockResolvedValue(undefined); + const statusGenerators = Array.from({ length: 7 }, () => + vi.fn().mockResolvedValue({ hasProvider: true, cached: true }), + ); + const warmGenericMetrics = vi.fn().mockResolvedValue(0); + return { + prisma, + reportRun, + enqueueRetry, + statusGenerators, + warmGenericMetrics, + }; + } + + it("reports ok, auth_failed and screened candidates side by side, and retries none of the last two", async () => { + const h = harness([ + { id: "ok-user", locale: "de" }, + { id: "dead-codex", locale: "de" }, + { id: "screened", locale: "de" }, + ]); + const generate = vi + .fn() + .mockResolvedValueOnce({ status: "generated", providerType: "codex" }) + .mockResolvedValueOnce({ + status: "failed", + reason: "all-providers-failed", + credentialExpired: true, + }) + .mockResolvedValueOnce({ status: "failed", reason: "outbound-screened" }); + + const result = await runInsightPregenerate(h.prisma as never, { + generate, + statusGenerators: h.statusGenerators, + warmGenericMetrics: h.warmGenericMetrics, + enqueueRetry: h.enqueueRetry, + reportRun: h.reportRun as never, + }); + + expect(h.reportRun).toHaveBeenCalledTimes(1); + const reported = h.reportRun.mock.calls[0][0]; + expect(reported.queue).toBe(INSIGHT_PREGENERATE_QUEUE); + expect(reported.candidates.map((c) => c.outcome)).toEqual([ + "ok", + "auth_failed", + "screened", + ]); + expect(reported.candidates[1].cause).toBe("all-providers-failed"); + expect(reported.candidates[2].cause).toBe("outbound-screened"); + // Keys never carry the account id. + for (const c of reported.candidates) { + expect(c.key).toMatch(/^[0-9a-f]{8}$/); + expect(JSON.stringify(c)).not.toContain("user"); + } + expect(h.enqueueRetry).not.toHaveBeenCalled(); + expect(result.allFailed).toBe(false); + }); + + it("still queues the bounded retry for an ordinary provider failure", async () => { + const h = harness([{ id: "u1", locale: "de" }]); + const generate = vi + .fn() + .mockResolvedValue({ status: "failed", reason: "all-providers-failed" }); + + const result = await runInsightPregenerate(h.prisma as never, { + generate, + statusGenerators: h.statusGenerators, + warmGenericMetrics: h.warmGenericMetrics, + enqueueRetry: h.enqueueRetry, + reportRun: h.reportRun as never, + }); + + expect(h.enqueueRetry).toHaveBeenCalledTimes(1); + expect(h.reportRun.mock.calls[0][0].candidates).toEqual([ + expect.objectContaining({ + outcome: "failed", + cause: "all-providers-failed", + }), + ]); + expect(result.allFailed).toBe(true); + }); + + it("reports the candidates a time-budget stop never reached as deferred", async () => { + const h = harness([ + { id: "a", locale: "de" }, + { id: "b", locale: "de" }, + { id: "c", locale: "de" }, + ]); + const generate = vi + .fn() + .mockResolvedValue({ status: "generated", providerType: "x" }); + let calls = 0; + + await runInsightPregenerate(h.prisma as never, { + generate, + statusGenerators: h.statusGenerators, + warmGenericMetrics: h.warmGenericMetrics, + enqueueRetry: h.enqueueRetry, + reportRun: h.reportRun as never, + shouldStop: () => ++calls > 1, + }); + + expect( + h.reportRun.mock.calls[0][0].candidates.map((c) => c.outcome), + ).toEqual(["ok", "deferred", "deferred"]); + }); +}); diff --git a/src/lib/jobs/__tests__/job-failures-retention.test.ts b/src/lib/jobs/__tests__/job-failures-retention.test.ts index 7a0674c9b..89d798894 100644 --- a/src/lib/jobs/__tests__/job-failures-retention.test.ts +++ b/src/lib/jobs/__tests__/job-failures-retention.test.ts @@ -3,8 +3,10 @@ import { join } from "node:path"; import { describe, expect, it } from "vitest"; import { + FAILED_ROW_AVAILABILITY_FLOOR_HOURS, JOB_FAILURE_WINDOW_HOURS, - PG_BOSS_FAILED_ROW_AVAILABILITY_HOURS, + PG_BOSS_DEFAULT_FAILED_ROW_AVAILABILITY_HOURS, + failureReaderRetention, } from "@/lib/jobs/job-failures"; const PG_BOSS_ROOT = join(process.cwd(), "node_modules/pg-boss"); @@ -26,10 +28,28 @@ describe("pg-boss failed-row ledger retention", () => { ); expect(plans).toContain("CLOCK_FUNCTION_BODY = 'SELECT pg_catalog.now();'"); expect(JOB_FAILURE_WINDOW_HOURS).toBeLessThan( - PG_BOSS_FAILED_ROW_AVAILABILITY_HOURS, + PG_BOSS_DEFAULT_FAILED_ROW_AVAILABILITY_HOURS, ); }); + it("keeps the per-queue floor above the reader window, with a day of slack", () => { + expect(JOB_FAILURE_WINDOW_HOURS).toBe(72); + expect(FAILED_ROW_AVAILABILITY_FLOOR_HOURS).toBe(96); + expect(FAILED_ROW_AVAILABILITY_FLOOR_HOURS).toBeLessThanOrEqual( + PG_BOSS_DEFAULT_FAILED_ROW_AVAILABILITY_HOURS, + ); + }); + + it("refuses a queue retention that would hide failures from the readers", () => { + expect(failureReaderRetention(96)).toEqual({ deleteAfterSeconds: 345_600 }); + expect(failureReaderRetention(7 * 24)).toEqual({ + deleteAfterSeconds: 604_800, + }); + expect(() => failureReaderRetention(95)).toThrow(RangeError); + expect(() => failureReaderRetention(24)).toThrow(RangeError); + expect(() => failureReaderRetention(Number.NaN)).toThrow(RangeError); + }); + it("pins the queue defaults the data-backup window had to escape", () => { const plans = readFileSync(join(PG_BOSS_ROOT, "dist/plans.js"), "utf8"); diff --git a/src/lib/jobs/__tests__/job-run-report.test.ts b/src/lib/jobs/__tests__/job-run-report.test.ts new file mode 100644 index 000000000..2ccd2dd19 --- /dev/null +++ b/src/lib/jobs/__tests__/job-run-report.test.ts @@ -0,0 +1,142 @@ +/** + * v1.42 — `reportJobRun`: one line per run with every candidate's outcome, + * and a level that follows the run as a whole. + * + * The nightly briefing warm read as "all-failed" on seven nights because the + * last account of each run happened to fail. These cases pin the verdict + * (what counts as attempted, what makes a run failed versus partial) and the + * two signals an operator and the repeated-failure alert key on. + */ +import { beforeEach, describe, expect, it, vi } from "vitest"; + +const emitSignal = vi.fn(); +const annotate = vi.fn(); +const readConsecutiveRunFailures = vi.fn(async (_queue: string) => 3); + +vi.mock("@/lib/logging/signal", () => ({ + emitSignal: (...a: unknown[]) => emitSignal(...a), +})); +vi.mock("@/lib/logging/context", () => ({ + annotate: (...a: unknown[]) => annotate(...a), +})); +vi.mock("@/lib/jobs/job-failures", () => ({ + readConsecutiveRunFailures: (queue: string) => + readConsecutiveRunFailures(queue), +})); + +import { judgeJobRun, reportJobRun } from "../job-run-report"; + +beforeEach(() => { + vi.clearAllMocks(); +}); + +describe("judgeJobRun", () => { + it("leaves skipped and deferred candidates out of the attempted set", () => { + expect( + judgeJobRun([ + { key: "a", outcome: "skipped" }, + { key: "b", outcome: "deferred" }, + { key: "c", outcome: "failed" }, + ]), + ).toEqual({ + total: 3, + attempted: 1, + failed: 1, + allFailed: true, + partial: false, + }); + }); + + it("counts a dead credential as a failure", () => { + expect( + judgeJobRun([ + { key: "a", outcome: "auth_failed" }, + { key: "b", outcome: "failed" }, + ]).allFailed, + ).toBe(true); + }); + + it("reads one success among failures as partial, not failed", () => { + const verdict = judgeJobRun([ + { key: "a", outcome: "ok" }, + { key: "b", outcome: "failed" }, + ]); + expect(verdict.allFailed).toBe(false); + expect(verdict.partial).toBe(true); + }); + + it("reads a withheld result as partial: the provider answered", () => { + const verdict = judgeJobRun([{ key: "a", outcome: "screened" }]); + expect(verdict.allFailed).toBe(false); + expect(verdict.partial).toBe(true); + }); + + it("is neither failed nor partial when nothing was attempted", () => { + const verdict = judgeJobRun([{ key: "a", outcome: "skipped" }]); + expect(verdict.allFailed).toBe(false); + expect(verdict.partial).toBe(false); + }); +}); + +describe("reportJobRun", () => { + it("emits job.run.failed at error with the streak when every attempt failed", async () => { + const verdict = await reportJobRun({ + queue: "insight-pregenerate", + runId: "r1", + candidates: [ + { key: "a", outcome: "auth_failed", cause: "all-providers-failed" }, + { key: "b", outcome: "skipped", cause: "no-consent" }, + ], + }); + expect(verdict.allFailed).toBe(true); + expect(readConsecutiveRunFailures).toHaveBeenCalledWith( + "insight-pregenerate", + ); + expect(emitSignal).toHaveBeenCalledTimes(1); + expect(emitSignal.mock.calls[0][0]).toMatchObject({ + action: "job.run.failed", + level: "error", + meta: { + queue: "insight-pregenerate", + consecutiveFailures: 3, + failed: 1, + total: 1, + causes: ["auth_failed:all-providers-failed"], + }, + }); + }); + + it("emits job.run.partial at warn when only some failed", async () => { + await reportJobRun({ + queue: "q", + runId: "r", + candidates: [ + { key: "a", outcome: "ok" }, + { key: "b", outcome: "failed", cause: "timeout" }, + ], + }); + expect(readConsecutiveRunFailures).not.toHaveBeenCalled(); + expect(emitSignal.mock.calls[0][0]).toMatchObject({ + action: "job.run.partial", + level: "warn", + meta: { queue: "q", failed: 1, total: 2 }, + }); + }); + + it("emits nothing extra for a clean run, and lists every outcome on the run line", async () => { + await reportJobRun({ + queue: "q", + runId: "r", + candidates: [ + { key: "a", outcome: "ok" }, + { key: "b", outcome: "ok" }, + { key: "c", outcome: "skipped", cause: "no-provider" }, + ], + }); + expect(emitSignal).not.toHaveBeenCalled(); + const meta = annotate.mock.calls[0][0].meta; + expect(meta.outcomes).toEqual({ ok: 2, skipped: 1 }); + expect(meta.candidate_outcomes).toHaveLength(3); + expect(meta.all_failed).toBe(false); + }); +}); diff --git a/src/lib/jobs/__tests__/run-job.test.ts b/src/lib/jobs/__tests__/run-job.test.ts index 9b32e591f..555ef57cb 100644 --- a/src/lib/jobs/__tests__/run-job.test.ts +++ b/src/lib/jobs/__tests__/run-job.test.ts @@ -17,6 +17,19 @@ vi.mock("../report-worker-error", () => ({ reportWorkerError: (...a: unknown[]) => reportWorkerError(...a), })); +// v1.42 — the failed run's own line and the streak behind it. +const emitSignal = vi.fn(); +const readConsecutiveRunFailures = vi.fn(async (_queue: string) => 2); +vi.mock("@/lib/logging/signal", () => ({ + emitSignal: (...a: unknown[]) => emitSignal(...a), +})); +vi.mock("../job-failures", async () => ({ + ...(await vi.importActual( + "../job-failures", + )), + readConsecutiveRunFailures: (q: string) => readConsecutiveRunFailures(q), +})); + import { jobDone, jobFailed } from "../job-outcome"; import { JobFailure, runJob } from "../run-job"; @@ -171,3 +184,47 @@ describe("runJob observation (#1031)", () => { observe.mockRestore(); }); }); + +describe("runJob failure signal (v1.42)", () => { + it("emits job.run.failed at error with the queue's streak for a failed outcome", async () => { + const wrapped = runJob("environment-fetch", async () => + jobFailed("fetch_failed", new Error("open-meteo 503")), + ); + await expect(wrapped(noJobs)).rejects.toBeInstanceOf(JobFailure); + expect(readConsecutiveRunFailures).toHaveBeenCalledWith( + "environment-fetch", + ); + expect(emitSignal).toHaveBeenCalledTimes(1); + expect(emitSignal.mock.calls[0][0]).toMatchObject({ + action: "job.run.failed", + level: "error", + meta: { + queue: "environment-fetch", + reason: "fetch_failed", + consecutiveFailures: 2, + }, + }); + }); + + it("emits it for a handler that throws, and still rethrows the original error", async () => { + const original = new Error("boom"); + const wrapped = runJob("data-backup", async () => { + throw original; + }); + await expect(wrapped(noJobs)).rejects.toBe(original); + expect(emitSignal.mock.calls[0][0]).toMatchObject({ + action: "job.run.failed", + level: "error", + meta: { queue: "data-backup", reason: "handler_threw" }, + error: original, + }); + }); + + it("emits nothing for a successful run", async () => { + const wrapped = runJob("rate-limit-cleanup", async () => + jobDone({ deleted: 1 }), + ); + await wrapped(noJobs); + expect(emitSignal).not.toHaveBeenCalled(); + }); +}); diff --git a/src/lib/jobs/apple-health-import-worker.ts b/src/lib/jobs/apple-health-import-worker.ts index c803627e7..1622d7dac 100644 --- a/src/lib/jobs/apple-health-import-worker.ts +++ b/src/lib/jobs/apple-health-import-worker.ts @@ -54,6 +54,7 @@ import { sweepStaleImportStaging, type StagingInUse, } from "@/lib/import/apple-health-staging"; +import { caughtAs, logCaught } from "@/lib/logging/signal"; /** * Queue + cron for the periodic orphan-ImportJob sweep. v1.32.1 @@ -100,10 +101,16 @@ export async function handleImportJobReconcileTick( // deploy), the person's export does not stay in /tmp past this. // A queued or running import keeps its files whatever their age; // when that cannot be read, nothing is swept this tick. - const inUse = await stagedImportFilesInUse().catch(() => null); + const inUse = await stagedImportFilesInUse().catch((err: unknown) => { + logCaught("apple_health.import.staging_probe_failed", err); + return null; + }); const swept = inUse ? await sweepStaleImportStaging(undefined, undefined, inUse).catch( - () => 0, + (err: unknown) => { + logCaught("apple_health.import.staging_sweep_failed", err); + return 0; + }, ) : 0; evt.addMeta("import_staging_swept", swept); @@ -463,7 +470,7 @@ export async function handleAppleHealthImport( onExportDate: async (exportedAt) => { await prisma.importJob .update({ where: { id: importJobId }, data: { exportedAt } }) - .catch(() => {}); + .catch(caughtAs("apple_health.import.export_date_failed")); }, })), ecg: { diff --git a/src/lib/jobs/backup-pass-attempts.ts b/src/lib/jobs/backup-pass-attempts.ts index 389252334..115acd04e 100644 --- a/src/lib/jobs/backup-pass-attempts.ts +++ b/src/lib/jobs/backup-pass-attempts.ts @@ -28,6 +28,7 @@ * least every second run. */ import type { PrismaClient } from "@/generated/prisma/client"; +import { logCaught } from "@/lib/logging/signal"; /** The pass's queue name, which is also the marker's key. */ export type BackupPass = "data-backup" | "data-backup-offhost"; @@ -46,7 +47,8 @@ export async function markBackupAttemptStarted( update: { startedAt: at }, create: { userId, pass, startedAt: at }, }); - } catch { + } catch (err) { + logCaught("backup.attempt.mark_failed", err, { phase: "started" }); // Bookkeeping only; an account deleted meanwhile has no row to write. } } @@ -62,7 +64,8 @@ export async function markBackupAttemptFinished( where: { userId, pass }, data: { finishedAt: at }, }); - } catch { + } catch (err) { + logCaught("backup.attempt.mark_failed", err, { phase: "finished" }); // Bookkeeping only. } } @@ -87,7 +90,8 @@ export async function readInterruptedBackupAttempts( ) .map((row) => [row.userId, row.startedAt]), ); - } catch { + } catch (err) { + logCaught("backup.attempt.read_failed", err); return new Map(); } } @@ -131,7 +135,8 @@ export async function readAccountsToTakeLast( select: { userId: true, startedAt: true, finishedAt: true }, }); return heldBackAccounts(rows); - } catch { + } catch (err) { + logCaught("backup.attempt.read_failed", err); return new Map(); } } diff --git a/src/lib/jobs/backup-restore.ts b/src/lib/jobs/backup-restore.ts index e2af9e0dd..e17aa8865 100644 --- a/src/lib/jobs/backup-restore.ts +++ b/src/lib/jobs/backup-restore.ts @@ -77,6 +77,7 @@ import { RESTORE_FAILURE_CAUSES, type RestoreFailureCause, } from "@/lib/export/restore-failure-cause"; +import { logCaught } from "@/lib/logging/signal"; export const BACKUP_RESTORE_QUEUE = "backup-restore"; @@ -478,7 +479,8 @@ export async function admitBackupRestore(input: { data: { pgBossJobId: bossJobId }, }); return { admitted: true, jobId }; - } catch { + } catch (err) { + logCaught("backup.restore.enqueue_failed", err, { jobId }); // Written but never queued: fail it here, or it holds the account's slot // until the unclaimed window runs out. await prisma.backupRestoreJob.update({ @@ -818,7 +820,8 @@ export async function enqueueBackupRestoreSweepAtBoot( expireInSeconds: BACKUP_RESTORE_EXPIRE_SECONDS, }, ); - } catch { + } catch (err) { + logCaught("backup.restore.sweep_enqueue_failed", err); // The admission check fails an abandoned job the next time the account // is restored, so a missed sweep costs a retry, not a stuck account. } diff --git a/src/lib/jobs/coach-nudge-ai.ts b/src/lib/jobs/coach-nudge-ai.ts index a7056d7d4..3df90feeb 100644 --- a/src/lib/jobs/coach-nudge-ai.ts +++ b/src/lib/jobs/coach-nudge-ai.ts @@ -49,6 +49,7 @@ import { singleUserTurn } from "@/lib/ai/types"; import { screenCoachReply } from "@/lib/ai/coach/outbound-guard"; import { extractAssessmentSummary } from "@/lib/insights/status-shared"; import { annotate } from "@/lib/logging/context"; +import { caughtAs, logCaught } from "@/lib/logging/signal"; /** Per-call upstream timeout — kept inside the spec's ≤8–10 s window. */ export const COACH_NUDGE_AI_CALL_TIMEOUT_MS = 9_000; @@ -246,13 +247,14 @@ export const composeNudgeWithAI: ComposeNudgeWithAI = async (params) => { signal: AbortSignal.timeout(COACH_NUDGE_AI_CALL_TIMEOUT_MS + 1_000), }), ); - } catch { + } catch (err) { // Timeout / network / provider error → refund what wasn't spent and // fall back to the template. + logCaught("coach.nudge.ai_failed", err); await reconcileSpend(params.userId, reservation.reserved, 0, dateKey, 0, { servedBy: null, reservedOwner: reservation.owner, - }).catch(() => {}); + }).catch(caughtAs("coach.nudge.reconcile_failed")); annotate({ action: { name: "coach.nudge.ai.fallback" } }); return null; } @@ -264,7 +266,7 @@ export const composeNudgeWithAI: ComposeNudgeWithAI = async (params) => { dateKey, result.cachedInputTokens ?? 0, { servedBy: chain[0].providerType, reservedOwner: reservation.owner }, - ).catch(() => {}); + ).catch(caughtAs("coach.nudge.reconcile_failed")); const body = sanitiseAiBody(result.content, params.locale); if (!body) { @@ -274,7 +276,8 @@ export const composeNudgeWithAI: ComposeNudgeWithAI = async (params) => { annotate({ action: { name: "coach.nudge.ai.composed" } }); return { title: params.template.title, body }; - } catch { + } catch (err) { + logCaught("coach.nudge.compose_failed", err); // Defensive: any unexpected failure keeps the template. return null; } diff --git a/src/lib/jobs/cycle-reminder.ts b/src/lib/jobs/cycle-reminder.ts index 86111ae78..dadb0ff05 100644 --- a/src/lib/jobs/cycle-reminder.ts +++ b/src/lib/jobs/cycle-reminder.ts @@ -49,6 +49,7 @@ import type { EventType } from "@/lib/notifications/types"; import { isCycleReminderClientManaged } from "@/lib/validations/notification-prefs"; import { getEvent } from "@/lib/logging/context"; import { DEFAULT_TIMEZONE } from "@/lib/tz/format"; +import { logCaught } from "@/lib/logging/signal"; /** * Local-time hour (0–23) at which the daily cycle reminder fires. 09:00 is @@ -266,7 +267,10 @@ async function alreadyNotifiedToday( select: { id: true }, }); return row !== null; - } catch { + } catch (err) { + // Fail toward "not yet notified": a read failure must not silence the + // reminder for the day, but it has to be visible. + logCaught("cycle.reminder.dedupe_read_failed", err); return false; } } @@ -548,7 +552,8 @@ async function hasObservedPeriodNearPrediction( delta >= -PERIOD_CONFIRM_GRACE_DAYS && delta <= PERIOD_SOON_LEAD_DAYS ); }); - } catch { + } catch (err) { + logCaught("cycle.reminder.period_read_failed", err); return false; } } diff --git a/src/lib/jobs/data-arrival.ts b/src/lib/jobs/data-arrival.ts index a99c6da95..3e048ee61 100644 --- a/src/lib/jobs/data-arrival.ts +++ b/src/lib/jobs/data-arrival.ts @@ -44,6 +44,7 @@ import { isArrivalKind, type DataArrival } from "@/lib/arrivals/types"; import { enqueueWorkoutInsight } from "@/lib/jobs/workout-insight-generate-shared"; import { getWorkerPrisma, workerLog } from "./reminder/shared"; +import { logCaught } from "@/lib/logging/signal"; export { DATA_ARRIVAL_QUEUE }; @@ -274,7 +275,8 @@ export async function runDataArrival( // process, and it costs nothing when it is not. try { invalidateUserDashboardSnapshot(arrival.userId); - } catch { + } catch (err) { + logCaught("daily.arrival.cache_evict_failed", err); // A cache miss is never worth failing a job over. } diff --git a/src/lib/jobs/document-ai-run.ts b/src/lib/jobs/document-ai-run.ts index 40388d7e0..e556b5d3b 100644 --- a/src/lib/jobs/document-ai-run.ts +++ b/src/lib/jobs/document-ai-run.ts @@ -89,6 +89,7 @@ import { OCR_EXTRACT_MODEL_CALLS, } from "@/lib/labs/ocr-run"; import { annotate } from "@/lib/logging/context"; +import { logCaught } from "@/lib/logging/signal"; export const DOCUMENT_AI_RUN_QUEUE = "document-ai-run"; @@ -133,6 +134,7 @@ export async function enqueueDocumentAiRun( action: { name: "ai_runs.enqueue_failed" }, meta: { reason: err instanceof Error ? err.name : "unknown" }, }); + logCaught("ai_runs.enqueue_failed", err); return false; } } diff --git a/src/lib/jobs/document-index.ts b/src/lib/jobs/document-index.ts index 74f16d12d..f5ee4d462 100644 --- a/src/lib/jobs/document-index.ts +++ b/src/lib/jobs/document-index.ts @@ -16,6 +16,7 @@ import { maybeAutoStageLabFacts } from "@/lib/documents/auto-stage-labs"; import { indexDocumentContent } from "@/lib/documents/index-document"; import { getGlobalBoss } from "@/lib/jobs/boss-instance"; import { annotate } from "@/lib/logging/context"; +import { caughtAs, logCaught } from "@/lib/logging/signal"; export const DOCUMENT_INDEX_QUEUE = "document-index"; @@ -63,7 +64,9 @@ export async function runDocumentIndex( // A deferred import stages nothing: lab staging is an AI read, and the // person asked for those to wait. if (outcome.indexed && !localOnly) { - await maybeAutoStageLabFacts(userId, documentId).catch(() => {}); + await maybeAutoStageLabFacts(userId, documentId).catch( + caughtAs("documents.auto_index.lab_staging_failed"), + ); } } @@ -101,6 +104,7 @@ export async function enqueueDocumentIndex( action: { name: "documents.autoIndex.enqueueFailed" }, meta: { documentId, reason: err instanceof Error ? err.name : "unknown" }, }); + logCaught("documents.auto_index.enqueue_failed", err); return { enqueued: false }; } } diff --git a/src/lib/jobs/document-summary-catchup.ts b/src/lib/jobs/document-summary-catchup.ts index 55e083756..3cb5c191a 100644 --- a/src/lib/jobs/document-summary-catchup.ts +++ b/src/lib/jobs/document-summary-catchup.ts @@ -39,6 +39,7 @@ import { prisma } from "@/lib/db"; import { getGlobalBoss } from "@/lib/jobs/boss-instance"; import { enqueueDocumentSummary } from "@/lib/jobs/document-summary"; import { annotate } from "@/lib/logging/context"; +import { logCaught } from "@/lib/logging/signal"; export const DOCUMENT_SUMMARY_CATCHUP_QUEUE = "document-summary-catchup"; @@ -184,6 +185,7 @@ export async function enqueueSummaryCatchUp( action: { name: "documents.autoRead.catchUpEnqueueFailed" }, meta: { reason: err instanceof Error ? err.name : "unknown" }, }); + logCaught("documents.auto_read.catch_up_enqueue_failed", err); return { enqueued: false }; } } diff --git a/src/lib/jobs/document-summary.ts b/src/lib/jobs/document-summary.ts index d01048c30..02f495b81 100644 --- a/src/lib/jobs/document-summary.ts +++ b/src/lib/jobs/document-summary.ts @@ -48,6 +48,7 @@ import { prisma } from "@/lib/db"; import { getGlobalBoss } from "@/lib/jobs/boss-instance"; import { annotate } from "@/lib/logging/context"; import type { DocumentSummaryState } from "@/generated/prisma/client"; +import { logCaught } from "@/lib/logging/signal"; export const DOCUMENT_SUMMARY_QUEUE = "document-summary"; @@ -311,7 +312,8 @@ export async function runDocumentSummaryJob( persisted: written.count > 0, }, }); - } catch { + } catch (err) { + logCaught("documents.summary.auto_failed", err); // Refund the reservation on a provider miss; the document keeps no summary // (the on-demand route remains the manual fallback). Never rethrow — a // transient provider error must not retry-loop or fail the queue. @@ -394,6 +396,7 @@ export async function enqueueDocumentSummary( action: { name: "documents.summary.enqueueFailed" }, meta: { documentId, reason: err instanceof Error ? err.name : "unknown" }, }); + logCaught("documents.summary.enqueue_failed", err); return { enqueued: false }; } } diff --git a/src/lib/jobs/document-thumbnail-backfill.ts b/src/lib/jobs/document-thumbnail-backfill.ts index 9dc4b6fda..638275d50 100644 --- a/src/lib/jobs/document-thumbnail-backfill.ts +++ b/src/lib/jobs/document-thumbnail-backfill.ts @@ -29,6 +29,7 @@ import { nativeCanvasSupported } from "@/lib/documents/native-canvas-support"; import { getGlobalBoss } from "@/lib/jobs/boss-instance"; import { enqueueDocumentThumbnail } from "@/lib/jobs/document-thumbnail"; import { annotate } from "@/lib/logging/context"; +import { logCaught } from "@/lib/logging/signal"; export const DOCUMENT_THUMBNAIL_BACKFILL_QUEUE = "document-thumbnail-backfill"; @@ -211,7 +212,8 @@ export async function enqueueBootTimeThumbnailBackfill(): Promise<{ }, ); if (jobId) enqueued += 1; - } catch { + } catch (err) { + logCaught("documents.thumbnail.backfill_enqueue_failed", err); // A transient send failure is a no-op — the next boot re-discovers the // still-missing thumbnails. } diff --git a/src/lib/jobs/document-thumbnail.ts b/src/lib/jobs/document-thumbnail.ts index 3e4dddbe1..f593ab760 100644 --- a/src/lib/jobs/document-thumbnail.ts +++ b/src/lib/jobs/document-thumbnail.ts @@ -33,6 +33,7 @@ import { generateThumbnail } from "@/lib/documents/thumbnail"; import { getGlobalBoss } from "@/lib/jobs/boss-instance"; import { withBackgroundEvent } from "@/lib/logging/background"; import { annotate } from "@/lib/logging/context"; +import { logCaught } from "@/lib/logging/signal"; export const DOCUMENT_THUMBNAIL_QUEUE = "document-thumbnail"; @@ -213,6 +214,7 @@ export async function enqueueDocumentThumbnail( action: { name: "documents.thumbnail.enqueueFailed" }, meta: { documentId, reason: err instanceof Error ? err.name : "unknown" }, }); + logCaught("documents.thumbnail.enqueue_failed", err); return { enqueued: false }; } } diff --git a/src/lib/jobs/geolite2-fetch.ts b/src/lib/jobs/geolite2-fetch.ts index f8c6c6f80..8b1b14c01 100644 --- a/src/lib/jobs/geolite2-fetch.ts +++ b/src/lib/jobs/geolite2-fetch.ts @@ -23,6 +23,7 @@ import { envFlag } from "@/lib/env"; import { getGlobalBoss } from "@/lib/jobs/boss-instance"; import { offlineGeoReady } from "@/lib/geo"; import { annotate } from "@/lib/logging/context"; +import { logCaught } from "@/lib/logging/signal"; export const GEOLITE2_FETCH_QUEUE = "geolite2-fetch"; @@ -71,7 +72,8 @@ export async function enqueueGeolite2FetchBootDiscovery(): Promise<{ meta: { enqueued }, }); return { enqueued }; - } catch { + } catch (err) { + logCaught("geolite2.fetch.enqueue_failed", err); // A transient send failure is a no-op — the monthly cron and the next boot // both re-attempt. return { enqueued: 0 }; diff --git a/src/lib/jobs/insight-pregenerate-shared.ts b/src/lib/jobs/insight-pregenerate-shared.ts index 95e5aee07..136d9353a 100644 --- a/src/lib/jobs/insight-pregenerate-shared.ts +++ b/src/lib/jobs/insight-pregenerate-shared.ts @@ -16,6 +16,7 @@ import type { SupportedLocale } from "@/lib/insights/status-shared"; import { getGlobalBoss } from "@/lib/jobs/boss-instance"; import { annotate } from "@/lib/logging/context"; +import { logCaught } from "@/lib/logging/signal"; export const INSIGHT_PREGENERATE_QUEUE = "insight-pregenerate"; @@ -111,7 +112,8 @@ export async function enqueueForceWarm(payload: { action: { name: "insights.pregenerate.force.enqueued" }, meta: { locale: payload.locale }, }); - } catch { + } catch (err) { + logCaught("insights.pregenerate.enqueue_failed", err, { kind: "force" }); // Enqueue is best-effort; a failure here just means the caches stay // cold until the next poll / nightly cron warms them. } @@ -169,7 +171,8 @@ export async function enqueueTodayBriefingWarm(payload: { action: { name: "insights.pregenerate.today.enqueued" }, meta: { locale: payload.locale, immediate: payload.immediate }, }); - } catch { + } catch (err) { + logCaught("insights.pregenerate.enqueue_failed", err, { kind: "today" }); // Best-effort, like every warm enqueue: the next read asks again. } } @@ -240,7 +243,8 @@ export async function enqueuePregenerateFailureRetry(payload: { delay_seconds: PREGENERATE_RETRY_DELAY_SECONDS, }, }); - } catch { + } catch (err) { + logCaught("insights.pregenerate.enqueue_failed", err, { kind: "retry" }); // Best-effort: a failed enqueue leaves the nightly tick as the // catch-net, exactly the pre-retry behaviour. } diff --git a/src/lib/jobs/insight-pregenerate.ts b/src/lib/jobs/insight-pregenerate.ts index 5e37cea90..927a64fc9 100644 --- a/src/lib/jobs/insight-pregenerate.ts +++ b/src/lib/jobs/insight-pregenerate.ts @@ -48,12 +48,20 @@ * Recurring pg-boss task — never runs inside an HTTP request and never * shells out to `tsx` (CLAUDE.md DO-NOTs). */ +import { createHash, randomUUID } from "node:crypto"; import pLimit from "p-limit"; import type { PrismaClient } from "@/generated/prisma/client"; import { checkRateLimit } from "@/lib/rate-limit"; import { getAssistantFlags } from "@/lib/feature-flags"; import { annotate } from "@/lib/logging/context"; +import { withBackgroundEvent } from "@/lib/logging/background"; +import { logCaught } from "@/lib/logging/signal"; +import { + reportJobRun, + type JobRunCandidate, + type JobRunOutcome, +} from "@/lib/jobs/job-run-report"; import { aiCapabilityForJob } from "@/lib/ai/capabilities/gate"; import { userIdsWithModuleOff } from "@/lib/jobs/ai-job-candidates"; import type { SupportedLocale } from "@/lib/insights/status-shared"; @@ -279,6 +287,13 @@ export interface PregenerateRunResult { budgetBlocked: number; /** The job's time budget ran out before every candidate was reached. */ stoppedEarly: boolean; + /** + * v1.42 — every candidate the run attempted failed (see `reportJobRun`). + * Written into the job's facts as `all_failed`, which is how a completed + * night with nothing generated still counts toward the repeated-failure + * streak. + */ + allFailed: boolean; /** * Count of per-metric assessment caches written warm across the whole * run. The comprehensive generator evicts the seven `*-status` @@ -342,15 +357,11 @@ async function warmPerStatusCaches( } catch (err) { // A single card's generation failing must not abort the rest of // the warm pass for this user, nor the cron's user loop — but it - // must not be invisible either: annotate so a failing card is - // diagnosable from one grep instead of a silent zero. - annotate({ - action: { name: "insights.pregenerate.warm_failed" }, - meta: { - stage: "status-card", - locale, - message: describeError(err), - }, + // must not be invisible either: a warn line under one action, so a + // failing card is diagnosable from one grep instead of a silent zero. + logCaught("insights.pregenerate.warm_failed", err, { + stage: "status-card", + locale, }); return 0; } @@ -391,13 +402,9 @@ async function warmStatusBatch( } catch (err) { // The batch must never throw the cron's user loop off course — but // a swallowed batch failure left ~7 cards cold with zero signal. - annotate({ - action: { name: "insights.pregenerate.warm_failed" }, - meta: { - stage: "status-batch", - locale, - message: describeError(err), - }, + logCaught("insights.pregenerate.warm_failed", err, { + stage: "status-batch", + locale, }); } } @@ -440,9 +447,8 @@ async function warmGenericMetricCaches( } catch (err) { // Best-effort discovery — but a silently-failing grouped read used to // zero out the whole generic warm with no trace. - annotate({ - action: { name: "insights.pregenerate.warm_failed" }, - meta: { stage: "metric-discovery", message: describeError(err) }, + logCaught("insights.pregenerate.warm_failed", err, { + stage: "metric-discovery", }); return 0; } @@ -478,14 +484,10 @@ async function warmGenericMetricCaches( ? 1 : 0; } catch (err) { - annotate({ - action: { name: "insights.pregenerate.warm_failed" }, - meta: { - stage: "metric-card", - metric, - locale, - message: describeError(err), - }, + logCaught("insights.pregenerate.warm_failed", err, { + stage: "metric-card", + metric, + locale, }); return 0; } @@ -496,6 +498,15 @@ async function warmGenericMetricCaches( return results.reduce((sum: number, n) => sum + n, 0); } +/** + * A stable, non-identifying key for one candidate on the run's log line: a + * short hash of the account id, enough to follow one account across nights + * without naming it. + */ +function candidateKey(userId: string): string { + return createHash("sha256").update(userId).digest("hex").slice(0, 8); +} + interface PregenerateCandidate { id: string; locale: string | null; @@ -583,12 +594,15 @@ export async function runInsightPregenerate( * not reach are the stalest again tomorrow, so they lead the next pass. */ shouldStop?: () => boolean; + /** Injected for the test — defaults to the real run report. */ + reportRun?: typeof reportJobRun; } = {}, ): Promise { const now = options.now ?? new Date(); const cap = options.cap ?? PREGENERATE_BATCH_CAP; const generate = options.generate ?? generateComprehensiveInsight; const enqueueRetry = options.enqueueRetry ?? enqueuePregenerateFailureRetry; + const reportRun = options.reportRun ?? reportJobRun; // v1.18.7 (HIGH-1) — when the caller injects its own `statusGenerators` // (the unit tests do), keep the per-card warm so those assertions hold; // production injects nothing, so the seven warm calls collapse into ONE @@ -615,6 +629,7 @@ export async function runInsightPregenerate( failed: 0, budgetBlocked: 0, stoppedEarly: false, + allFailed: false, assessmentsWarmed: 0, metricAssessmentsWarmed: 0, }; @@ -627,197 +642,35 @@ export async function runInsightPregenerate( const candidates = await findPregenerateCandidates(prisma, now, cap); result.total = candidates.length; - for (const candidate of candidates) { + // v1.42 — one outcome per candidate, reported together at the end of the + // run (`reportJobRun`). Each candidate also runs inside its own wide event, + // so what one account's generation annotates (the provider chain's hops, + // the failure cause) lands on that account's line instead of overwriting + // the run's: the run used to read `all-failed` whenever the LAST account + // failed, on nights where the others had worked. + const runId = randomUUID(); + const runOutcomes: JobRunCandidate[] = []; + + for (const [index, candidate] of candidates.entries()) { if (options.shouldStop?.()) { result.stoppedEarly = true; + // The rest are the stalest again tomorrow; they lead the next pass. + for (const rest of candidates.slice(index)) { + runOutcomes.push({ + key: candidateKey(rest.id), + outcome: "deferred", + cause: "job_budget", + }); + } break; } - // v1.18.11 P3 — one feature-cache scope per candidate, so the - // comprehensive briefing's bounded feature read is computed once and any - // sibling consumer in this candidate's warm reuses it. Scoped per user so - // no cross-user object can leak. - await withFeatureCacheScope(async () => { - // The two capabilities this pass serves, resolved before any snapshot - // or rate-limit write: the briefing for the comprehensive insight, the - // status notes for the per-metric warm. Each half runs only when its - // own capability is available; the chokepoints re-check at the wire. - const [briefing, statusText] = await Promise.all([ - aiCapabilityForJob(candidate.id, "briefing"), - aiCapabilityForJob(candidate.id, "statusText"), - ]); - if (!briefing.available && !statusText.available) { - result.skipped++; - annotate({ - action: { name: "insights.pregenerate.skipped" }, - meta: { - briefing: briefing.reason, - status_text: statusText.reason, - }, - }); - return; - } - - // Budget gate — one COMPREHENSIVE pre-generation per user per 20 h. - // The route's on-demand path uses a different bucket - // (`insights:${userId}`), so this never starves a user's manual - // regenerate quota. The gate bounds the comprehensive cost only: a - // blocked user still gets the refill-only status warm below, because - // the 02:xx status crons already skipped every pregenerate candidate - // on the assumption that THIS pass warms their cards — exiting early - // here left those cards cold until the first on-visit generation. - const budget = briefing.available - ? await checkRateLimit( - `insight-pregenerate:${candidate.id}`, - 1, - PREGENERATE_BUDGET_WINDOW_MS, - ) - : null; - - // The stored locale, then the operator default: a NULL column used to - // resolve to English here, so a German-language instance warmed its - // briefings in English every night. - const locale = await resolveJobLocale(candidate.locale); - if (budget === null) { - result.skipped++; - annotate({ - action: { name: "insights.pregenerate.skipped" }, - meta: { briefing: briefing.reason }, - }); - } else if (!budget.allowed) { - result.budgetBlocked++; - } else { - // Force a fresh generation: the discovery window (20 h) is shorter - // than the generator's 24 h cache TTL, so without `force` a user - // whose cache is 20–24 h old would be discovered, consume the - // budget bucket, then short-circuit to `cached` with no actual - // pre-generation — defeating the "warm the cache before the user's - // morning visit" intent for the common case. The per-user budget - // bucket (above) bounds attempts, and the generator's content-hash - // gate (v1.16.8) turns a same-data force into a timestamp refresh - // (`unchanged`) with no provider call. - // - // Bounded budget + abort (v1.16.1): one stalled provider must not - // pin the whole batch behind a single candidate, and `withTimeout` - // alone cannot cancel the detached generation — without the abort a - // late resolve would still write a cache row + timestamp after the - // loop moved on (the same race the forced single-user warm closes). - const controller = new AbortController(); - // v1.25.3 — size the outer abort from the candidate's resolved - // response-timeout so a raised setting extends the warm budget - // instead of being clipped by a fixed cap. - const warmBudgetMs = comprehensiveWarmBudgetMs( - candidate.aiResponseTimeoutSeconds, - ); - // Capture the rejection so the failure annotation can carry the - // actual error text — `withTimeout` folds a rejection into a bare - // `errored: true` envelope, which made the cause undiagnosable. - let thrown: unknown = null; - const bounded = await withTimeout( - () => - generate(candidate.id, { - locale, - force: true, - signal: controller.signal, - }).catch((err: unknown) => { - thrown = err; - throw err; - }), - warmBudgetMs, - null, - () => controller.abort(), - ); - if (bounded.timedOut || bounded.errored || bounded.value === null) { - result.failed++; - // v1.21.5 — make the warm failure queryable. The nightly loop used to - // bump `failed` with no annotation, so a candidate whose comprehensive - // generation timed out (e.g. the briefing clipped at the old 45 s - // bound) left the cached block empty AND emitted nothing greppable. - // v1.28.30 — carry the stage + error text so ONE grep on - // `comprehensive_failed` names the failing catch and its cause. - annotate({ - action: { name: "insights.pregenerate.comprehensive_failed" }, - meta: { - locale, - stage: "nightly.bound", - cause: bounded.timedOut - ? "timeout" - : bounded.errored - ? "error" - : "null", - budget_ms: warmBudgetMs, - message: thrown === null ? null : describeError(thrown), - }, - }); - // v1.28.30 — bounded intra-day retry: one delayed forced warm for - // just this user, so a transient 04:30 provider hiccup heals - // before the morning visit instead of waiting for the next night. - await enqueueRetry({ userId: candidate.id, locale }); - } else { - const outcome = bounded.value; - switch (outcome.status) { - case "generated": - result.generated++; - break; - case "cached": - result.cached++; - break; - case "unchanged": - result.unchanged++; - break; - case "skipped": - result.skipped++; - break; - case "failed": - result.failed++; - // v1.28.30 — THE previously-silent failure path. A generator - // that resolves with `{ status: "failed" }` (features error, - // oversize payload, invalid JSON after retry, abort) bumped - // the tally with no annotation at all — the nightly summary - // showed `failed: 1` and nothing else was greppable. Reuse - // the `comprehensive_failed` shape with the generator's own - // reason as the cause. - annotate({ - action: { name: "insights.pregenerate.comprehensive_failed" }, - meta: { - locale, - stage: "nightly.generator", - cause: `generator:${outcome.reason}`, - budget_ms: warmBudgetMs, - message: null, - }, - }); - await enqueueRetry({ userId: candidate.id, locale }); - break; - } - } - } - - // Warm the per-metric assessment caches — refill-only, single locale - // (v1.16.8). The comprehensive write no longer evicts the per-status - // rows, so there is nothing to force-refill: a card already generated - // today is a cheap cache read, a cold card runs its generator, and the - // generator's content-hash gate turns a same-data regeneration into a - // timestamp refresh with no provider call. The warm runs on every - // comprehensive outcome (budget-blocked, failed, timed-out, - // consent-skipped included) because the 02:xx status crons skip every - // pregenerate candidate on the assumption that THIS pass covers them. - // - // Nothing to warm when the status notes themselves are unavailable. - if (!statusText.available) { - annotate({ - action: { name: "insights.pregenerate.status_skipped" }, - meta: { reason: statusText.reason }, - }); - return; - } - result.assessmentsWarmed += await warmStatus(candidate.id, [locale]); - // v1.8.7.1 — warm the generic per-HealthKit-metric caches too, for - // the user's data-bearing metrics only (the helper filters via one - // grouped count, so an empty metric never reaches the provider). - result.metricAssessmentsWarmed += await warmGenericMetrics(candidate.id, [ - locale, - ]); - }); + const key = candidateKey(candidate.id); + const outcome = await withBackgroundEvent( + "job.insight_pregenerate.candidate", + (evt) => + withFeatureCacheScope(() => pregenerateCandidate(candidate, key, evt)), + ); + runOutcomes.push(outcome); } // Wide-event tally so the nightly dashboard can track how many @@ -837,8 +690,254 @@ export async function runInsightPregenerate( metric_assessments_warmed: result.metricAssessmentsWarmed, }, }); + const verdict = await reportRun({ + queue: INSIGHT_PREGENERATE_QUEUE, + runId, + candidates: runOutcomes, + }); + result.allFailed = verdict.allFailed; return result; + + /** + * One candidate's whole pass: capabilities, the budget gate, the bounded + * comprehensive generation and the refill-only card warm. Returns how the + * candidate ended for the run report; never throws for a provider failure + * (those are outcomes), only for something unexpected, which aborts the + * run as it always did. + */ + async function pregenerateCandidate( + candidate: PregenerateCandidate, + key: string, + evt: { elevateLevel(level: "warn"): unknown }, + ): Promise { + annotate({ meta: { candidate: key, run_id: runId } }); + const state: { outcome: JobRunOutcome; cause?: string } = { + outcome: "ok", + }; + const settle = (outcome: JobRunOutcome, cause?: string) => { + state.outcome = outcome; + state.cause = cause; + }; + + // The two capabilities this pass serves, resolved before any snapshot + // or rate-limit write: the briefing for the comprehensive insight, the + // status notes for the per-metric warm. Each half runs only when its + // own capability is available; the chokepoints re-check at the wire. + const [briefing, statusText] = await Promise.all([ + aiCapabilityForJob(candidate.id, "briefing"), + aiCapabilityForJob(candidate.id, "statusText"), + ]); + if (!briefing.available && !statusText.available) { + result.skipped++; + annotate({ + action: { name: "insights.pregenerate.skipped" }, + meta: { + briefing: briefing.reason, + status_text: statusText.reason, + }, + }); + return { + key, + outcome: "skipped", + cause: briefing.reason ?? "unavailable", + }; + } + + // Budget gate — one COMPREHENSIVE pre-generation per user per 20 h. + // The route's on-demand path uses a different bucket + // (`insights:${userId}`), so this never starves a user's manual + // regenerate quota. The gate bounds the comprehensive cost only: a + // blocked user still gets the refill-only status warm below, because + // the 02:xx status crons already skipped every pregenerate candidate + // on the assumption that THIS pass warms their cards — exiting early + // here left those cards cold until the first on-visit generation. + const budget = briefing.available + ? await checkRateLimit( + `insight-pregenerate:${candidate.id}`, + 1, + PREGENERATE_BUDGET_WINDOW_MS, + ) + : null; + + // The stored locale, then the operator default: a NULL column used to + // resolve to English here, so a German-language instance warmed its + // briefings in English every night. + const locale = await resolveJobLocale(candidate.locale); + if (budget === null) { + result.skipped++; + settle("skipped", briefing.reason ?? "briefing_unavailable"); + annotate({ + action: { name: "insights.pregenerate.skipped" }, + meta: { briefing: briefing.reason }, + }); + } else if (!budget.allowed) { + result.budgetBlocked++; + settle("skipped", "budget_blocked"); + } else { + // Force a fresh generation: the discovery window (20 h) is shorter + // than the generator's 24 h cache TTL, so without `force` a user + // whose cache is 20–24 h old would be discovered, consume the + // budget bucket, then short-circuit to `cached` with no actual + // pre-generation — defeating the "warm the cache before the user's + // morning visit" intent for the common case. The per-user budget + // bucket (above) bounds attempts, and the generator's content-hash + // gate (v1.16.8) turns a same-data force into a timestamp refresh + // (`unchanged`) with no provider call. + // + // Bounded budget + abort (v1.16.1): one stalled provider must not + // pin the whole batch behind a single candidate, and `withTimeout` + // alone cannot cancel the detached generation — without the abort a + // late resolve would still write a cache row + timestamp after the + // loop moved on (the same race the forced single-user warm closes). + const controller = new AbortController(); + // v1.25.3 — size the outer abort from the candidate's resolved + // response-timeout so a raised setting extends the warm budget + // instead of being clipped by a fixed cap. + const warmBudgetMs = comprehensiveWarmBudgetMs( + candidate.aiResponseTimeoutSeconds, + ); + // Capture the rejection so the failure annotation can carry the + // actual error text — `withTimeout` folds a rejection into a bare + // `errored: true` envelope, which made the cause undiagnosable. + let thrown: unknown = null; + const bounded = await withTimeout( + () => + generate(candidate.id, { + locale, + force: true, + signal: controller.signal, + }).catch((err: unknown) => { + thrown = err; + throw err; + }), + warmBudgetMs, + null, + () => controller.abort(), + ); + if (bounded.timedOut || bounded.errored || bounded.value === null) { + result.failed++; + const boundCause = bounded.timedOut + ? "timeout" + : bounded.errored + ? "error" + : "null"; + settle("failed", boundCause); + // v1.21.5 — make the warm failure queryable. The nightly loop used to + // bump `failed` with no annotation, so a candidate whose comprehensive + // generation timed out (e.g. the briefing clipped at the old 45 s + // bound) left the cached block empty AND emitted nothing greppable. + // v1.28.30 — carry the stage + error text so ONE grep on + // `comprehensive_failed` names the failing catch and its cause. + annotate({ + action: { name: "insights.pregenerate.comprehensive_failed" }, + meta: { + locale, + stage: "nightly.bound", + cause: boundCause, + budget_ms: warmBudgetMs, + message: thrown === null ? null : describeError(thrown), + }, + }); + // v1.28.30 — bounded intra-day retry: one delayed forced warm for + // just this user, so a transient 04:30 provider hiccup heals + // before the morning visit instead of waiting for the next night. + await enqueueRetry({ userId: candidate.id, locale }); + } else { + const generated = bounded.value; + switch (generated.status) { + case "generated": + case "rerolled": + result.generated++; + break; + case "cached": + result.cached++; + break; + case "unchanged": + result.unchanged++; + break; + case "skipped": + result.skipped++; + settle("skipped", generated.reason); + break; + case "failed": + result.failed++; + // v1.28.30 — THE previously-silent failure path. A generator + // that resolves with `{ status: "failed" }` (features error, + // oversize payload, invalid JSON after retry, abort) bumped + // the tally with no annotation at all — the nightly summary + // showed `failed: 1` and nothing else was greppable. Reuse + // the `comprehensive_failed` shape with the generator's own + // reason as the cause. + annotate({ + action: { name: "insights.pregenerate.comprehensive_failed" }, + meta: { + locale, + stage: "nightly.generator", + cause: `generator:${generated.reason}`, + budget_ms: warmBudgetMs, + message: null, + }, + }); + if (generated.reason === "outbound-screened") { + // v1.42 — the model answered and the safety screen withheld + // it, after the generator's own repair. Asking the same model + // again in 45 minutes is not a provider retry; it is the same + // question, and it was screened eight times a night. + settle("screened", generated.reason); + } else if (generated.credentialExpired) { + // v1.42 — a dead sign-in (a Codex refresh token the issuer + // revoked) does not heal in 45 minutes either; the person has + // to reconnect, and the ledger already tells them so. + settle("auth_failed", generated.reason); + } else { + settle("failed", generated.reason); + await enqueueRetry({ userId: candidate.id, locale }); + } + break; + } + } + } + + // Warm the per-metric assessment caches — refill-only, single locale + // (v1.16.8). The comprehensive write no longer evicts the per-status + // rows, so there is nothing to force-refill: a card already generated + // today is a cheap cache read, a cold card runs its generator, and the + // generator's content-hash gate turns a same-data regeneration into a + // timestamp refresh with no provider call. The warm runs on every + // comprehensive outcome (budget-blocked, failed, timed-out, + // consent-skipped included) because the 02:xx status crons skip every + // pregenerate candidate on the assumption that THIS pass covers them. + // + // Nothing to warm when the status notes themselves are unavailable. + if (!statusText.available) { + annotate({ + action: { name: "insights.pregenerate.status_skipped" }, + meta: { reason: statusText.reason }, + }); + } else { + result.assessmentsWarmed += await warmStatus(candidate.id, [locale]); + // v1.8.7.1 — warm the generic per-HealthKit-metric caches too, for + // the user's data-bearing metrics only (the helper filters via one + // grouped count, so an empty metric never reaches the provider). + result.metricAssessmentsWarmed += await warmGenericMetrics(candidate.id, [ + locale, + ]); + } + + const final = state.outcome; + if (final === "failed" || final === "auth_failed" || final === "screened") { + evt.elevateLevel("warn"); + } + annotate({ + meta: { outcome: final, ...(state.cause ? { cause: state.cause } : {}) }, + }); + return { + key, + outcome: final, + ...(state.cause ? { cause: state.cause } : {}), + }; + } } /** @@ -1001,7 +1100,8 @@ export async function forceWarmUser( aiResponseTimeoutSeconds: true, }, }); - } catch { + } catch (err) { + logCaught("insights.pregenerate.force.preflight_failed", err); // Best-effort pre-flight — on a read failure fall through to the // budgeted generation attempt below. } @@ -1119,7 +1219,8 @@ export async function forceWarmUser( data: { insightsWarmFailedAt: null }, }); } - } catch { + } catch (err) { + logCaught("insights.pregenerate.force.marker_failed", err); // Marker maintenance is best-effort; never fail the warm on it. } } diff --git a/src/lib/jobs/insight-status-generate-shared.ts b/src/lib/jobs/insight-status-generate-shared.ts index 2b31f6e4a..5296732d1 100644 --- a/src/lib/jobs/insight-status-generate-shared.ts +++ b/src/lib/jobs/insight-status-generate-shared.ts @@ -20,6 +20,7 @@ import { providerWorkAuthorityForRecord, type ProviderWorkAuthority, } from "@/lib/sharing/provider-work-authority"; +import { logCaught } from "@/lib/logging/signal"; export const INSIGHT_STATUS_GENERATE_QUEUE = "insight-status-generate"; @@ -165,7 +166,10 @@ export async function enqueueStatusGeneration( action: { name: "insights.status.generate.enqueued" }, meta: { metric: payload.metric }, }); - } catch { + } catch (err) { + logCaught("insights.status.enqueue_failed", err, { + metric: payload.metric, + }); // Enqueue is best-effort; a failure here just means the card stays // in `preparing` until the next poll / nightly cron warms the cache. } diff --git a/src/lib/jobs/job-failures.ts b/src/lib/jobs/job-failures.ts index 9332b041d..db7604b6d 100644 --- a/src/lib/jobs/job-failures.ts +++ b/src/lib/jobs/job-failures.ts @@ -28,22 +28,61 @@ import { prisma } from "@/lib/db"; import { redactSecrets } from "@/lib/logging/redact"; /** - * pg-boss 12.34.0 stores terminal rows until - * `completed_on + deletion_seconds` (`dist/plans.js`). Its queue default is - * 604800 seconds, while `retention_seconds` defaults to 1209600 seconds; job - * insertion copies those queue values and maintenance applies the terminal-row - * deletion clock. The deployed queue-table audit found those same values on - * every queue, and no job submitter overrides either option. + * How long pg-boss keeps a terminal row, and why the readers below can rely + * on it. * - * Seven days is therefore the verified availability floor for failed rows. - * The reader stays at 72 hours, safely inside that floor, and pg-boss remains - * the single failure ledger. + * pg-boss 12.34.0 stores terminal rows until `completed_on + + * deletion_seconds` (`dist/plans.js`). The queue default is 604800 seconds + * (seven days), `retention_seconds` defaults to 1209600 seconds, and job + * insertion copies the queue's values onto each row. A queue created without + * a `deleteAfterSeconds` option therefore keeps its failed rows for seven + * days. + * + * That is no longer true for every queue. v1.42 shortens the retention of + * the pure-volume queues (a sampler that ticks every five minutes, the rollup + * recompute fan-out) so their completed rows stop bloating `job_common`. A + * failed row on such a queue lives only as long as that queue's own + * retention, and a reader that looks back 72 hours over a queue that forgets + * after 48 would report "nothing failed" about failures it can no longer see. + * + * So the availability is per queue now, and it has a floor: no queue may + * keep its terminal rows for less than `FAILED_ROW_AVAILABILITY_FLOOR_HOURS`, + * which is the 72-hour reader window plus a day of slack for a run that + * fails just before a maintenance pass. Every queue option that shortens + * retention goes through `failureReaderRetention`, which refuses a value + * under the floor, and `src/__tests__/job-retention-floor-guard.test.ts` + * refuses a `deleteAfterSeconds` anywhere that is neither a call to it nor a + * literal at or above the floor. pg-boss remains the single failure ledger. */ -export const PG_BOSS_FAILED_ROW_AVAILABILITY_HOURS = 7 * 24; +export const PG_BOSS_DEFAULT_FAILED_ROW_AVAILABILITY_HOURS = 7 * 24; /** How far back a failure still counts as news. */ export const JOB_FAILURE_WINDOW_HOURS = 72; +/** + * The shortest terminal-row retention any queue may have: the reader window + * plus a day. See the block above. + */ +export const FAILED_ROW_AVAILABILITY_FLOOR_HOURS = + JOB_FAILURE_WINDOW_HOURS + 24; + +/** + * The `deleteAfterSeconds` queue option for a queue that keeps its terminal + * rows for `hours`. Throws below the floor, so a retention change that would + * blind the failure readers fails at boot and in the test suite rather than + * silently three days later. + */ +export function failureReaderRetention(hours: number): { + deleteAfterSeconds: number; +} { + if (!Number.isFinite(hours) || hours < FAILED_ROW_AVAILABILITY_FLOOR_HOURS) { + throw new RangeError( + `queue retention of ${hours} h is below the ${FAILED_ROW_AVAILABILITY_FLOOR_HOURS} h the failure readers need`, + ); + } + return { deleteAfterSeconds: Math.round(hours * 3600) }; +} + /** Queues named in one report — enough to see a pattern, bounded for the wire. */ const MAX_QUEUES = 20; @@ -373,3 +412,52 @@ export async function readQueueRunningSince( return null; } } + +/** Newest terminal rows `readConsecutiveRunFailures` looks at. */ +const CONSECUTIVE_LOOKBACK_ROWS = 50; + +/** + * How many runs of `queue` in a row ended in failure, newest first, counting + * the run that is failing right now (so the result is at least 1). + * + * A run counts as failed when pg-boss failed it (`state = 'failed'`), or when + * it completed but said in its own facts that every candidate it attempted + * failed (`did.all_failed`, written through `reportJobRun`). A fan-out pass + * like the nightly briefing warm completes even when nothing worked, because + * failing the queue would retry the whole cohort over one account; its + * all-failed nights are still a streak an operator wants to hear about. + * + * Completed runs that do not report `all_failed` at all (a queue's on-demand + * single-account jobs share it with the nightly pass) are not evidence either + * way and are skipped. The streak ends at the first completed run that says + * it did not all fail. + * + * Fails soft to 1: when the queue schema cannot be read, this run is still a + * failure, and one is the only count that is known. + */ +export async function readConsecutiveRunFailures( + queue: string, +): Promise { + try { + const rows = await prisma.$queryRaw< + Array<{ state: string; all_failed: string | null }> + >` + SELECT state, output->'did'->>'all_failed' AS all_failed + FROM pgboss.job + WHERE name = ${queue} + AND state IN ('completed', 'failed') + AND completed_on IS NOT NULL + AND (state = 'failed' OR output->'did'->>'all_failed' IS NOT NULL) + ORDER BY completed_on DESC + LIMIT ${CONSECUTIVE_LOOKBACK_ROWS} + `; + let streak = 1; + for (const row of rows) { + if (row.state === "failed" || row.all_failed === "true") streak += 1; + else break; + } + return streak; + } catch { + return 1; + } +} diff --git a/src/lib/jobs/job-lock.ts b/src/lib/jobs/job-lock.ts index 5db0d75ba..a7a49e737 100644 --- a/src/lib/jobs/job-lock.ts +++ b/src/lib/jobs/job-lock.ts @@ -19,6 +19,7 @@ * One extra connection per running locked job. */ import { Client } from "pg"; +import { caughtAs } from "@/lib/logging/signal"; /** What a guarded run came to. */ export type GuardedRun = { ran: true; result: T } | { ran: false }; @@ -50,9 +51,9 @@ export async function withJobLock( } finally { await client .query("SELECT pg_advisory_unlock(hashtextextended($1, 0))", [key]) - .catch(() => {}); + .catch(caughtAs("jobs.lock.release_failed")); } } finally { - await client.end().catch(() => {}); + await client.end().catch(caughtAs("jobs.lock.release_failed")); } } diff --git a/src/lib/jobs/job-outcome.ts b/src/lib/jobs/job-outcome.ts index 33e994a32..61f9733b5 100644 --- a/src/lib/jobs/job-outcome.ts +++ b/src/lib/jobs/job-outcome.ts @@ -47,6 +47,8 @@ export const JOB_FACT_ALLOWLIST: ReadonlySet = new Set([ "ai_runs_deleted", "ai_runs_timed_out", "ai_runs_worker_unavailable", + // v1.42 — every candidate a fan-out pass attempted failed (`reportJobRun`). + "all_failed", // An admission delivery that found its import still running from an // earlier delivery of the same job and did nothing. "already_running", diff --git a/src/lib/jobs/job-run-report.ts b/src/lib/jobs/job-run-report.ts index f17d02795..4dadbd0f4 100644 --- a/src/lib/jobs/job-run-report.ts +++ b/src/lib/jobs/job-run-report.ts @@ -3,16 +3,31 @@ * * A pass over many accounts used to annotate its wide event once per * candidate, and the last write won: a run where six accounts worked and one - * failed read as whatever the last account did. `reportJobRun` takes the - * whole candidate list instead, so the run's line carries every outcome and - * the level follows the worst of them. + * failed read as whatever the last account did. The nightly briefing warm read + * as `all-failed` on seven nights in a row when it had in fact completed every + * night, because the last account of each run happened to fail. `reportJobRun` + * takes the whole candidate list instead, so the run's line carries every + * outcome and the level follows the run as a whole: * - * Contract stub: the signature is fixed for its callers (the insight - * pre-generation, the tombstone purge, the measurement maintenance). Until - * the implementation lands it annotates the run's counts the way the callers - * do today. + * - every attempted candidate failed → `job.run.failed` at `error`, with how + * many runs of the queue in a row have now failed (`consecutiveFailures`, + * the number the repeated-failure alert keys on); + * - some failed, or a result was withheld → `job.run.partial` at `warn`; + * - otherwise nothing extra: the run's own line says what it did. + * + * "Attempted" leaves out `skipped` and `deferred` candidates: an account + * without consent or one the job budget did not reach is not a failure of the + * run. `screened` (the model answered and the safety screen withheld it) is + * attempted but is not a provider failure, so a run of only screened + * candidates is partial, not failed. + * + * The verdict comes back to the caller, which writes `all_failed` into its + * `jobDone` facts. That fact is what lets `readConsecutiveRunFailures` count a + * completed-but-all-failed night as part of a streak. */ import { annotate } from "@/lib/logging/context"; +import { emitSignal } from "@/lib/logging/signal"; +import { readConsecutiveRunFailures } from "@/lib/jobs/job-failures"; /** How one candidate of a run ended. */ export type JobRunOutcome = @@ -26,20 +41,118 @@ export interface JobRunCandidate { cause?: string; } -export function reportJobRun(input: { +export interface JobRunVerdict { + /** Candidates the run looked at. */ + total: number; + /** Candidates it actually attempted (not skipped, not deferred). */ + attempted: number; + /** `failed` + `auth_failed`. */ + failed: number; + /** Every attempted candidate failed (and at least one was attempted). */ + allFailed: boolean; + /** Something failed or was withheld, but not everything. */ + partial: boolean; +} + +/** Candidates listed on the run's line; the counts always cover all of them. */ +const MAX_LISTED_CANDIDATES = 50; + +const FAILED: ReadonlySet = new Set(["failed", "auth_failed"]); +const NOT_ATTEMPTED: ReadonlySet = new Set([ + "skipped", + "deferred", +]); + +/** The verdict alone, without logging. Pure, for callers and tests. */ +export function judgeJobRun( + candidates: readonly JobRunCandidate[], +): JobRunVerdict { + const total = candidates.length; + const attempted = candidates.filter( + (c) => !NOT_ATTEMPTED.has(c.outcome), + ).length; + const failed = candidates.filter((c) => FAILED.has(c.outcome)).length; + const screened = candidates.filter((c) => c.outcome === "screened").length; + const allFailed = attempted > 0 && failed === attempted; + return { + total, + attempted, + failed, + allFailed, + partial: !allFailed && (failed > 0 || screened > 0), + }; +} + +export async function reportJobRun(input: { queue: string; runId: string; candidates: readonly JobRunCandidate[]; -}): void { - const failed = input.candidates.filter( - (c) => c.outcome === "failed" || c.outcome === "auth_failed", - ).length; +}): Promise { + const verdict = judgeJobRun(input.candidates); + const byOutcome: Record = {}; + for (const c of input.candidates) { + byOutcome[c.outcome] = (byOutcome[c.outcome] ?? 0) + 1; + } + annotate({ meta: { queue: input.queue, runId: input.runId, - candidates: input.candidates.length, - failed, + candidates: verdict.total, + attempted: verdict.attempted, + failed: verdict.failed, + all_failed: verdict.allFailed, + outcomes: byOutcome, + candidate_outcomes: input.candidates + .slice(0, MAX_LISTED_CANDIDATES) + .map((c) => ({ + key: c.key, + outcome: c.outcome, + ...(c.cause ? { cause: c.cause } : {}), + })), }, }); + + if (verdict.allFailed) { + const consecutiveFailures = await readConsecutiveRunFailures(input.queue); + emitSignal({ + action: "job.run.failed", + level: "error", + meta: { + queue: input.queue, + runId: input.runId, + consecutiveFailures, + failed: verdict.failed, + total: verdict.attempted, + causes: distinctCauses(input.candidates), + }, + }); + } else if (verdict.partial) { + emitSignal({ + action: "job.run.partial", + level: "warn", + meta: { + queue: input.queue, + runId: input.runId, + failed: verdict.failed, + total: verdict.attempted, + outcomes: byOutcome, + causes: distinctCauses(input.candidates), + }, + }); + } + return verdict; +} + +/** The distinct causes of the run's failed or withheld candidates, bounded. */ +function distinctCauses(candidates: readonly JobRunCandidate[]): string[] { + const causes = new Set(); + for (const c of candidates) { + if (c.outcome === "ok" || NOT_ATTEMPTED.has(c.outcome) || !c.cause) { + continue; + } + causes.add(`${c.outcome}:${c.cause}`); + if (causes.size >= 10) break; + } + return [...causes]; } diff --git a/src/lib/jobs/morning-digest-refresh-shared.ts b/src/lib/jobs/morning-digest-refresh-shared.ts index 2540c1630..4d136c1c1 100644 --- a/src/lib/jobs/morning-digest-refresh-shared.ts +++ b/src/lib/jobs/morning-digest-refresh-shared.ts @@ -15,6 +15,7 @@ */ import { getGlobalBoss } from "@/lib/jobs/boss-instance"; import { annotate } from "@/lib/logging/context"; +import { logCaught } from "@/lib/logging/signal"; export const MORNING_DIGEST_REFRESH_QUEUE = "morning-digest-refresh"; @@ -76,7 +77,8 @@ export async function enqueueMorningDigestRefresh( action: { name: "daily.morning_refresh.enqueued" }, meta: { local_date: payload.localDate }, }); - } catch { + } catch (err) { + logCaught("daily.morning_refresh.enqueue_failed", err); // Best-effort: a failed enqueue leaves the next sleep landing + the nightly // cron as the catch-net; the digest stays honestly provisional meanwhile. } diff --git a/src/lib/jobs/offhost-purge.ts b/src/lib/jobs/offhost-purge.ts index c7089b98a..cc08a3acc 100644 --- a/src/lib/jobs/offhost-purge.ts +++ b/src/lib/jobs/offhost-purge.ts @@ -45,6 +45,7 @@ import { import { reportWorkerError } from "@/lib/jobs/report-worker-error"; import { getWorkerPrisma } from "@/lib/jobs/reminder/shared"; import { withBackgroundEvent } from "@/lib/logging/background"; +import { logCaught } from "@/lib/logging/signal"; export const OFFHOST_PURGE_QUEUE = "offhost-backup-purge"; /** 03:40, after the nightly upload (02:30) has had its hour. */ @@ -104,7 +105,8 @@ export async function kickOffhostPurge(): Promise { retryDelay: 300, }, ); - } catch { + } catch (err) { + logCaught("backup.offhost_purge.kick_failed", err); // The cron is the backstop. } } diff --git a/src/lib/jobs/period-narrative-shared.ts b/src/lib/jobs/period-narrative-shared.ts index 56742c1ea..d46c2528f 100644 --- a/src/lib/jobs/period-narrative-shared.ts +++ b/src/lib/jobs/period-narrative-shared.ts @@ -20,6 +20,7 @@ import { } from "@/lib/sharing/provider-work-authority"; import type { NarrativePeriod } from "@/lib/insights/narrative/period-narrative"; import type { Locale } from "@/lib/i18n/config"; +import { logCaught } from "@/lib/logging/signal"; export const PERIOD_NARRATIVE_QUEUE = "period-narrative-warm"; @@ -100,7 +101,10 @@ export async function enqueueNarrativeWarm(payload: { action: { name: "insights.narrative.warm.enqueued" }, meta: { period: payload.period, locale: payload.locale }, }); - } catch { + } catch (err) { + logCaught("insights.narrative.enqueue_failed", err, { + period: payload.period, + }); // Best-effort — a failure just means the narrative stays as-is until the // next read or the nightly cron warms it. } diff --git a/src/lib/jobs/reaction-line.ts b/src/lib/jobs/reaction-line.ts index e5b646c1a..a30e48d3b 100644 --- a/src/lib/jobs/reaction-line.ts +++ b/src/lib/jobs/reaction-line.ts @@ -78,6 +78,7 @@ import { } from "@/lib/arrivals/reaction-line-shared"; import { workerLog } from "./reminder/shared"; +import { caughtAs } from "@/lib/logging/signal"; export { REACTION_LINE_QUEUE }; @@ -567,7 +568,7 @@ export async function runReactionLine( const hasReservedTokens = row.generationReservedTokens != null; const hasReservationDate = row.generationBudgetDateKey != null; if (hasReservedTokens !== hasReservationDate) { - await releaseClaim().catch(() => {}); + await releaseClaim().catch(caughtAs("reaction_line.cleanup_failed")); return { status: "skipped", reason: "invalid_reservation_state" }; } @@ -600,7 +601,7 @@ export async function runReactionLine( if (err instanceof ReactionClaimLostError) { return { status: "skipped", reason: "claim_lost" }; } - await releaseClaim().catch(() => {}); + await releaseClaim().catch(caughtAs("reaction_line.cleanup_failed")); throw err; } } @@ -620,7 +621,7 @@ export async function runReactionLine( } catch (err) { // No provider was touched, so releasing ownership is retry-safe. The // durable reservation remains attached and is reused by the retry. - await releaseClaim().catch(() => {}); + await releaseClaim().catch(caughtAs("reaction_line.cleanup_failed")); throw err; } @@ -690,8 +691,10 @@ export async function runReactionLine( reservation.dateKey, 0, { servedBy: chain[0].providerType, reservedOwner: reservation.owner }, - ).catch(() => {}); - await finishTerminalAttempt().catch(() => {}); + ).catch(caughtAs("reaction_line.cleanup_failed")); + await finishTerminalAttempt().catch( + caughtAs("reaction_line.cleanup_failed"), + ); workerLog("error", "[reaction-line] generation failed", err); return { status: "skipped", reason: "provider_failed" }; } @@ -708,14 +711,18 @@ export async function runReactionLine( } catch (err) { // Do not publish a line whose spend was not durably reconciled. The // invocation timestamp remains terminal, preventing a second provider call. - await finishTerminalAttempt().catch(() => {}); + await finishTerminalAttempt().catch( + caughtAs("reaction_line.cleanup_failed"), + ); workerLog("error", "[reaction-line] spend reconciliation failed", err); return { status: "skipped", reason: "spend_reconciliation_failed" }; } const line = sanitiseReactionLine(result.content, locale); if (!line) { - await finishTerminalAttempt().catch(() => {}); + await finishTerminalAttempt().catch( + caughtAs("reaction_line.cleanup_failed"), + ); return { status: "skipped", reason: "unusable_output" }; } // Prompt instructions are not an enforcement boundary. Grade every numeric @@ -729,7 +736,9 @@ export async function runReactionLine( (evidenceLedger.length === 0 && /\d/.test(line)) || findUnverifiedCoachNumbersInLedger(line, evidenceLedger, locale).length > 0; if (hasUngroundedNumber) { - await finishTerminalAttempt().catch(() => {}); + await finishTerminalAttempt().catch( + caughtAs("reaction_line.cleanup_failed"), + ); return { status: "skipped", reason: "ungrounded_output" }; } @@ -740,7 +749,9 @@ export async function runReactionLine( chain[0].providerType, ]); if (late) { - await finishTerminalAttempt().catch(() => {}); + await finishTerminalAttempt().catch( + caughtAs("reaction_line.cleanup_failed"), + ); return { status: "skipped", reason: late.reason }; } diff --git a/src/lib/jobs/reminder/insights-handlers.ts b/src/lib/jobs/reminder/insights-handlers.ts index c0443ac43..dff543080 100644 --- a/src/lib/jobs/reminder/insights-handlers.ts +++ b/src/lib/jobs/reminder/insights-handlers.ts @@ -381,6 +381,9 @@ export async function handleInsightPregenerateJob( failed: summary.failed, budget_blocked: summary.budgetBlocked, stopped_early: summary.stoppedEarly, + // v1.42 — read back by `readConsecutiveRunFailures`, so a night that + // completed with nothing generated counts toward the failure streak. + all_failed: summary.allFailed, assessments_warmed: summary.assessmentsWarmed, metric_assessments_warmed: summary.metricAssessmentsWarmed, }); diff --git a/src/lib/jobs/run-job.ts b/src/lib/jobs/run-job.ts index 9a673bc8c..114c26e26 100644 --- a/src/lib/jobs/run-job.ts +++ b/src/lib/jobs/run-job.ts @@ -29,6 +29,8 @@ import { } from "./job-outcome"; import { reportWorkerError } from "./report-worker-error"; import { observeJob } from "./job-observer"; +import { readConsecutiveRunFailures } from "./job-failures"; +import { emitSignal } from "@/lib/logging/signal"; /** A converted handler: it says what it did instead of just finishing. */ export type JobHandler = (jobs: Job[]) => Promise; @@ -67,14 +69,34 @@ function factMeta(did: JobFacts | undefined): Record { return meta; } +/** + * The failed run's own line: `job.run.failed` at `error`, naming the queue and + * how many runs of it in a row have now failed. Every queue reaches it, so + * the repeated-failure alert keys on one action and one number instead of on + * the handler's own task name, which differs per queue, or on the stderr line + * `reportWorkerError` writes, which is not structured. + */ +async function signalRunFailed( + queue: string, + reason: string, + error: unknown, +): Promise { + const consecutiveFailures = await readConsecutiveRunFailures(queue); + emitSignal({ + action: "job.run.failed", + level: "error", + meta: { queue, reason, consecutiveFailures }, + error, + }); +} + /** * Wrap a handler for `boss.work`. Resolves with the bounded, redacted * persistence representation on `ok: true`; reports and rethrows on * `ok: false`. * - * A handler that throws is left alone — the throw already fails the job, and - * re-wrapping it would only bury the original stack. `runJob` exists for the - * case the throw never happens. + * A handler that throws keeps its own error — re-wrapping it would only bury + * the original stack — but its run still gets the `job.run.failed` line. */ export function runJob( queue: string, @@ -83,11 +105,17 @@ export function runJob( return async (jobs: J[]): Promise => { // Observed, so a long run, an expiry and a cut-off leave a line in the // log naming the queue and how far it got (see `job-observer.ts`). - const outcome = await observeJob( - queue, - jobs as ReadonlyArray<{ id?: string; expireInSeconds?: number }>, - () => handler(jobs), - ); + let outcome: JobOutcome; + try { + outcome = await observeJob( + queue, + jobs as ReadonlyArray<{ id?: string; expireInSeconds?: number }>, + () => handler(jobs), + ); + } catch (error) { + await signalRunFailed(queue, "handler_threw", error); + throw error; + } if (outcome.ok) return serializeJobOutcome(outcome); const failure = new JobFailure(queue, outcome.reason, outcome.cause); @@ -102,6 +130,7 @@ export function runJob( ...factMeta(outcome.did), ...(causeMessage === undefined ? {} : { cause: causeMessage }), }); + await signalRunFailed(queue, outcome.reason, failure); throw failure; }; diff --git a/src/lib/jobs/workout-insight-generate-shared.ts b/src/lib/jobs/workout-insight-generate-shared.ts index 5108a0fdf..da8351199 100644 --- a/src/lib/jobs/workout-insight-generate-shared.ts +++ b/src/lib/jobs/workout-insight-generate-shared.ts @@ -14,6 +14,7 @@ */ import { getGlobalBoss } from "@/lib/jobs/boss-instance"; import { annotate } from "@/lib/logging/context"; +import { logCaught } from "@/lib/logging/signal"; export const WORKOUT_INSIGHT_GENERATE_QUEUE = "workout-insight-generate"; @@ -57,11 +58,12 @@ export async function enqueueWorkoutInsight( retryBackoff: true, }); return { enqueued: true }; - } catch { + } catch (err) { annotate({ action: { name: "workouts.insight.enqueue_failed" }, meta: { workoutId: payload.workoutId }, }); + logCaught("workouts.insight.enqueue_failed", err); return { enqueued: false }; } } diff --git a/src/lib/jobs/workout-insight-generate.ts b/src/lib/jobs/workout-insight-generate.ts index 083f77cd2..839d38eef 100644 --- a/src/lib/jobs/workout-insight-generate.ts +++ b/src/lib/jobs/workout-insight-generate.ts @@ -79,6 +79,7 @@ import { WORKOUT_INSIGHT_GENERATE_QUEUE, type WorkoutInsightGeneratePayload, } from "./workout-insight-generate-shared"; +import { caughtAs, logCaught } from "@/lib/logging/signal"; export { WORKOUT_INSIGHT_GENERATE_CONCURRENCY, WORKOUT_INSIGHT_GENERATE_QUEUE }; export type { WorkoutInsightGeneratePayload }; @@ -418,12 +419,12 @@ export async function runWorkoutInsightGenerate( })().catch(async (err) => { // Nothing could have reached a provider. Delete the reservation so a // backed-off retry can safely reclaim both ownership and daily capacity. - await releaseClaim().catch(() => {}); + await releaseClaim().catch(caughtAs("workouts.insight.cleanup_failed")); throw err; }); if (prepared.status === "unchanged") { - await releaseClaim().catch(() => {}); + await releaseClaim().catch(caughtAs("workouts.insight.cleanup_failed")); annotate({ action: { name: "workouts.insight.skipped" }, meta: { workoutId, reason: "unchanged" }, @@ -472,13 +473,18 @@ export async function runWorkoutInsightGenerate( temperature: AI_BUDGETS.workoutInsight.temperature, maxTokens: AI_BUDGETS.workoutInsight.maxTokens, }); - } catch { - await finishTerminalAttempt().catch(() => {}); + } catch (err) { + logCaught("workouts.insight.provider_failed", err, { workoutId }); + await finishTerminalAttempt().catch( + caughtAs("workouts.insight.cleanup_failed"), + ); return { status: "skipped", reason: "provider_uncertain" }; } if (outcome.kind !== "ok") { - await finishTerminalAttempt().catch(() => {}); + await finishTerminalAttempt().catch( + caughtAs("workouts.insight.cleanup_failed"), + ); annotate({ action: { name: "workouts.insight.skipped" }, meta: { workoutId, reason: outcome.kind }, @@ -488,7 +494,9 @@ export async function runWorkoutInsightGenerate( const screened = finalizeStatusSummary(outcome.content, prepared.locale); if (!screened.ok || !screened.text) { - await finishTerminalAttempt().catch(() => {}); + await finishTerminalAttempt().catch( + caughtAs("workouts.insight.cleanup_failed"), + ); annotate({ action: { name: "workouts.insight.outbound_blocked" }, meta: { workoutId, reason: screened.ok ? "empty" : screened.reason }, @@ -531,8 +539,11 @@ export async function runWorkoutInsightGenerate( throw new Error("Workout insight generation claim was lost"); } }); - } catch { - await finishTerminalAttempt().catch(() => {}); + } catch (err) { + logCaught("workouts.insight.persist_failed", err, { workoutId }); + await finishTerminalAttempt().catch( + caughtAs("workouts.insight.cleanup_failed"), + ); return { status: "skipped", reason: "persistence_uncertain" }; } diff --git a/src/lib/logging/__tests__/signal.test.ts b/src/lib/logging/__tests__/signal.test.ts new file mode 100644 index 000000000..a3c01ba3f --- /dev/null +++ b/src/lib/logging/__tests__/signal.test.ts @@ -0,0 +1,101 @@ +/** + * v1.42 — the logging pieces the error-log discipline rests on. + * + * - `emitSignal` writes its own line with a stable action and level, joined + * to the surrounding event by request and trace id, and leaves that event + * alone. + * - `setError` keeps `error` for real failures and records a refusal the + * request was meant to get (any 4xx) at `warn`. Expired-token 401s made up + * most of the error lines and hid the real ones. + */ +import { beforeEach, describe, expect, it, vi } from "vitest"; + +const emitted: Array> = []; +vi.mock("../transports", () => ({ + emitIfSampled: (event: Record) => emitted.push(event), +})); + +import { WideEventBuilder } from "../event-builder"; +import { eventStorage } from "../context"; +import { emitSignal, logCaught } from "../signal"; + +beforeEach(() => { + emitted.length = 0; +}); + +describe("emitSignal", () => { + it("writes one line with its own action and level, joined to the parent by id", () => { + const parent = new WideEventBuilder("http"); + parent.setAction({ name: "insights.generate" }); + eventStorage.run(parent, () => + emitSignal({ + action: "ai.chain.link_failed", + level: "error", + meta: { provider: "admin-openai", status: 500 }, + }), + ); + expect(emitted).toHaveLength(1); + const line = emitted[0] as { + action: { name: string }; + level: string; + request_id: string; + trace_id: string; + meta: Record; + }; + expect(line.action.name).toBe("ai.chain.link_failed"); + expect(line.level).toBe("error"); + expect(line.request_id).toBe(parent.getRequestId()); + expect(line.trace_id).toBe(parent.getTraceId()); + expect(line.meta).toMatchObject({ provider: "admin-openai", status: 500 }); + // The parent keeps its own action and level. + expect(parent.toJSON().action?.name).toBe("insights.generate"); + expect(parent.getLevel()).toBe("info"); + }); + + it("logCaught carries the error's type and a bounded, redacted message at warn", () => { + logCaught( + "jobs.enqueue.failed", + new Error(`boom Bearer sk-abcdefghijklmnopqrstuvwxyz ${"x".repeat(500)}`), + { queue: "insight-pregenerate" }, + ); + const line = emitted[0] as { level: string; meta: Record }; + expect(line.level).toBe("warn"); + expect(line.meta.error_type).toBe("Error"); + expect(line.meta.error_message.length).toBeLessThanOrEqual(240); + expect(line.meta.error_message).not.toContain("sk-abcdefghijklmnop"); + }); + + it("never throws, even when emitting fails", () => { + expect(() => + emitSignal({ + action: "x.y.z", + level: "warn", + meta: { + get bad(): never { + throw new Error("getter"); + }, + }, + }), + ).not.toThrow(); + }); +}); + +describe("setError level", () => { + it("records a 4xx refusal at warn", () => { + const evt = new WideEventBuilder("http"); + evt.setError( + Object.assign(new Error("Token expired"), { statusCode: 401 }), + ); + expect(evt.getLevel()).toBe("warn"); + expect(evt.toJSON().error?.message).toBe("Token expired"); + }); + + it("keeps a real failure at error", () => { + const evt = new WideEventBuilder("http"); + evt.setError(new Error("database unreachable")); + expect(evt.getLevel()).toBe("error"); + const five = new WideEventBuilder("http"); + five.setError(Object.assign(new Error("bad gateway"), { statusCode: 502 })); + expect(five.getLevel()).toBe("error"); + }); +}); diff --git a/src/lib/logging/event-builder.ts b/src/lib/logging/event-builder.ts index 1bcc0596c..09afd9819 100644 --- a/src/lib/logging/event-builder.ts +++ b/src/lib/logging/event-builder.ts @@ -167,7 +167,18 @@ export class WideEventBuilder { } setError(err: unknown): this { - this.elevateLevel("error"); + // v1.42 — a refusal the request was meant to get (an expired session, + // a missing permission, a validation error: anything that carries a 4xx + // status) is a `warn`, not an `error`. Every 401 from an expired token + // used to land at `error`, about nine in ten of all error lines, so a + // query or an alert on `level=error` could not see the real failures + // between them. The error details are recorded either way. + const status = (err as { statusCode?: unknown } | null)?.statusCode; + this.elevateLevel( + typeof status === "number" && status >= 400 && status < 500 + ? "warn" + : "error", + ); if (err instanceof Error) { this.event.error = { type: err.constructor.name, diff --git a/src/lib/logging/signal.ts b/src/lib/logging/signal.ts new file mode 100644 index 000000000..93e39b456 --- /dev/null +++ b/src/lib/logging/signal.ts @@ -0,0 +1,99 @@ +import { WideEventBuilder } from "./event-builder"; +import { getEvent } from "./context"; +import { emitIfSampled } from "./transports"; + +/** + * A failure that deserves its own log line, under its own action name. + * + * A wide event carries one action, and the last `annotate()` to name one wins. + * That is the right shape for "what did this request do", and the wrong one + * for "what went wrong on the way": a provider hop that failed before the + * next one answered, a job candidate that failed among six that worked, a + * Coach turn that ran out of budget, a caught error the code chose to carry + * on past. Each of those used to be either a meta key on someone else's line + * at level `info`, or nothing at all, so a query for `level=error` could not + * find it and an alert rule had no stable name to key on. + * + * `emitSignal` writes one extra line with the action, the level and a small + * pinned-shape meta bag. It carries the surrounding event's request and trace + * ids, so the signal and the line it happened inside join on one id; the + * surrounding event itself is not touched (its own level still describes its + * own outcome). + * + * Levels: `error` for a real failure nobody downstream recovered from, `warn` + * for one the code recovered from (a fallback answered, a degraded result was + * served) or a refusal by design that an operator should still be able to + * count. Nothing here is for `info`: an expected outcome belongs on the + * request's own line. + * + * Never throws. A log line must not break the work it describes. + */ +export interface SignalInput { + /** Stable `..` name, e.g. `ai.chain.link_failed`. */ + action: string; + level: "warn" | "error"; + /** Scalars and small arrays only; redacted on the way in like any meta. */ + meta?: Record; + /** The caught value, when there is one. Only its type and message leave. */ + error?: unknown; +} + +/** Longest error message a signal carries. */ +const MAX_MESSAGE_CHARS = 240; + +export function emitSignal(input: SignalInput): void { + try { + const event = new WideEventBuilder("background"); + const parent = getEvent(); + if (parent) { + event.setRequestId(parent.getRequestId()); + event.setTraceId(parent.getTraceId()); + } + event.setBackground({ task_name: input.action }); + event.setAction({ name: input.action }); + for (const [key, value] of Object.entries(input.meta ?? {})) { + event.addMeta(key, value); + } + if (input.error !== undefined) { + const err = input.error; + event.addMeta( + "error_type", + err instanceof Error ? err.name || "Error" : typeof err, + ); + const message = err instanceof Error ? err.message : String(err); + event.addMeta("error_message", message.slice(0, MAX_MESSAGE_CHARS)); + } + event.elevateLevel(input.level); + event.finish(); + emitIfSampled(event.toJSON()); + } catch { + // A log line must never break the work it describes. + } +} + +/** + * The common case of a `catch` that carries on: say what failed, at `warn`, + * under a stable action, with the caught error attached. Use it where the + * code deliberately degrades (an enqueue that the next tick repeats, a + * best-effort side write) instead of dropping the error or folding it into an + * `info` annotation. + */ +export function logCaught( + action: string, + error: unknown, + meta?: Record, +): void { + emitSignal({ action, level: "warn", error, meta }); +} + +/** + * `logCaught` shaped for a promise's `.catch`: `.catch(caughtAs("x.y.failed"))` + * in place of `.catch(() => {})`. The promise still settles, so a best-effort + * side write stays best-effort, and its failure leaves a `warn` line. + */ +export function caughtAs( + action: string, + meta?: Record, +): (error: unknown) => void { + return (error: unknown) => logCaught(action, error, meta); +} diff --git a/src/lib/logging/types.ts b/src/lib/logging/types.ts index 727f5440f..8a5119cdb 100644 --- a/src/lib/logging/types.ts +++ b/src/lib/logging/types.ts @@ -115,6 +115,12 @@ export interface WideEvent { duration_ms: number; status?: number; error?: string; + /** + * v1.42 — an expected non-2xx the caller recovers from by design (a + * filter dialect probe), recorded without `error` so a query for + * failed calls does not find it. + */ + note?: string; }>; // Hintergrundaufgabe (nur bei kind === "background") diff --git a/src/lib/rollups/tiered-context.ts b/src/lib/rollups/tiered-context.ts index d9d815c2e..b73f6073d 100644 --- a/src/lib/rollups/tiered-context.ts +++ b/src/lib/rollups/tiered-context.ts @@ -311,6 +311,16 @@ const BAND_TRUNC_UNIT: Record< * * `tzKey` (the far-from-UTC day-grain guard) buckets on the user's LOCAL * calendar via `AT TIME ZONE`; parameter-bound, never spliced. + * + * v1.42 — `measured_at` is a `timestamp` without time zone holding UTC wall + * time, so the local wall clock is `(measured_at AT TIME ZONE 'UTC') AT TIME + * ZONE tz`: the first step says what the value is, the second converts it. + * The single `measured_at AT TIME ZONE tz` this used read the UTC value AS IF + * it were local time and converted the wrong way, so a far-from-UTC reader's + * readings were shifted by twice their offset (sixteen hours in Los Angeles): + * an evening reading landed on the next day's bucket. Every other local-day + * reader + * (`day-aggregates.ts`, `day-mean.ts`) already used the two-step form. */ async function readBandLive( userId: string, @@ -337,7 +347,7 @@ async function readBandLive( }> >` SELECT - date_trunc(${unit}, m."measured_at" AT TIME ZONE ${tzKey}) AS bucket_start, + date_trunc(${unit}, (m."measured_at" AT TIME ZONE 'UTC') AT TIME ZONE ${tzKey}) AS bucket_start, COUNT(*)::int AS count, AVG(m."value")::double precision AS mean, MIN(m."value")::double precision AS min_value, @@ -419,7 +429,7 @@ async function readHourlyMeanBandLive( }), ); const bucket = tzKey - ? Prisma.sql`date_trunc(${unit}, m."measured_at" AT TIME ZONE ${tzKey})` + ? Prisma.sql`date_trunc(${unit}, (m."measured_at" AT TIME ZONE 'UTC') AT TIME ZONE ${tzKey})` : Prisma.sql`date_trunc(${unit}, m."measured_at")`; try { const rows = await prisma.$queryRaw< diff --git a/tests/integration/job-failures.test.ts b/tests/integration/job-failures.test.ts index a4c108986..981353dd0 100644 --- a/tests/integration/job-failures.test.ts +++ b/tests/integration/job-failures.test.ts @@ -17,6 +17,7 @@ import { afterAll, beforeAll, describe, expect, it } from "vitest"; import { readActiveJobsStartedBefore, + readConsecutiveRunFailures, readFailingQueues, readQueueFailureForUser, } from "@/lib/jobs/job-failures"; @@ -189,6 +190,46 @@ describe("readActiveJobsStartedBefore (#1031)", () => { }); }); +describe("readConsecutiveRunFailures (v1.42)", () => { + const STREAK_QUEUE = "insight-pregenerate"; + + /** Complete one job with the facts a handler returned. */ + async function completeOneJob(did: Record) { + const jobId = await boss.send(STREAK_QUEUE, {}, { retryLimit: 0 }); + const [job] = await boss.fetch(STREAK_QUEUE); + if (!job || job.id !== jobId) throw new Error("nothing to fetch"); + await boss.complete(STREAK_QUEUE, job.id, { ok: true, did }); + return jobId!; + } + + /** Pin the finishing order so the test does not race the clock. */ + async function finishedMinutesAgo(jobId: string, minutes: number) { + await getPrismaClient().$executeRawUnsafe( + `UPDATE pgboss.job SET completed_on = now() - make_interval(mins => ${minutes}) WHERE id = '${jobId}'`, + ); + } + + it("counts failed runs and all-failed nights, skips runs that do not say, and stops at a good night", async () => { + await boss.createQueue(STREAK_QUEUE); + // Oldest first: a good night, then a pg-boss failure, an on-demand job + // that reports nothing about the run, and an all-failed night. + await finishedMinutesAgo(await completeOneJob({ all_failed: false }), 40); + await finishedMinutesAgo( + await failOneJob(STREAK_QUEUE, {}, "worker died"), + 30, + ); + await finishedMinutesAgo(await completeOneJob({ forced: 1 }), 20); + await finishedMinutesAgo(await completeOneJob({ all_failed: true }), 10); + + // Two earlier failures plus the run failing now. + await expect(readConsecutiveRunFailures(STREAK_QUEUE)).resolves.toBe(3); + }); + + it("answers 1 for a queue with no history: the run failing now", async () => { + await expect(readConsecutiveRunFailures("never-ran")).resolves.toBe(1); + }); +}); + describe("no queue schema at all", () => { it("answers null rather than throwing, so the status page still renders", async () => { const prisma = getPrismaClient(); diff --git a/tests/integration/provider-pause.test.ts b/tests/integration/provider-pause.test.ts new file mode 100644 index 000000000..3845e1ca1 --- /dev/null +++ b/tests/integration/provider-pause.test.ts @@ -0,0 +1,80 @@ +/** + * v1.42 — the escalating provider pause, against the real upsert. + * + * The pause is computed inside the one `INSERT … ON CONFLICT DO UPDATE` that + * records a failure, from the count that same statement writes, so two + * workers failing at once still arm the pause their combined count deserves. + * Only Postgres can show the CASE arithmetic is right; the unit test can only + * show the statement carries it. + */ +import { beforeEach, describe, expect, it, vi } from "vitest"; + +import { getPrismaClient, truncateAllTables } from "./setup"; + +vi.mock("@/lib/db-compat", () => ({ + ensureDbCompatibility: vi.fn().mockResolvedValue(undefined), +})); + +import { + HARD_FAILURE_COOLDOWN_MS, + PROVIDER_PAUSE_BASE_MS, + PROVIDER_PAUSE_THRESHOLD, + postgresProviderHealthLedger as ledger, +} from "@/lib/ai/provider-health-ledger"; + +const prisma = getPrismaClient(); + +async function windowMs(userId: string): Promise { + const row = await prisma.providerHealth.findFirstOrThrow({ + where: { userId, providerType: "admin-openai" }, + select: { nextRetryAt: true, lastFailureAt: true }, + }); + return row.nextRetryAt!.getTime() - row.lastFailureAt!.getTime(); +} + +describe("provider pause in the Postgres ledger", () => { + let userId: string; + + beforeEach(async () => { + await truncateAllTables(prisma); + const user = await prisma.user.create({ + data: { + email: "pause@example.test", + username: "pause", + passwordHash: "x", + }, + }); + userId = user.id; + }); + + it("backs off briefly, then pauses from the threshold, doubling, and a success resumes", async () => { + for (let i = 1; i < PROVIDER_PAUSE_THRESHOLD; i += 1) { + await ledger.recordFailure(userId, "admin-openai", 500); + } + expect(await windowMs(userId)).toBe(HARD_FAILURE_COOLDOWN_MS); + expect( + (await ledger.getSkipHints(userId)).get("admin-openai")?.reason, + ).toBe("backoff"); + + await ledger.recordFailure(userId, "admin-openai", 500); + expect(await windowMs(userId)).toBe(PROVIDER_PAUSE_BASE_MS); + expect( + (await ledger.getSkipHints(userId)).get("admin-openai")?.reason, + ).toBe("paused"); + + await ledger.recordFailure(userId, "admin-openai", 500); + expect(await windowMs(userId)).toBe(2 * PROVIDER_PAUSE_BASE_MS); + + await ledger.recordSuccess(userId, "admin-openai"); + expect((await ledger.getSkipHints(userId)).has("admin-openai")).toBe(false); + }); + + it("keeps the fixed cooldown for a dead credential, however long the run", async () => { + for (let i = 0; i < PROVIDER_PAUSE_THRESHOLD + 2; i += 1) { + await ledger.recordFailure(userId, "admin-openai", 401); + } + expect( + (await ledger.getSkipHints(userId)).get("admin-openai")?.reason, + ).toBe("credential_expired"); + }); +}); diff --git a/tests/integration/tiered-context-local-day.test.ts b/tests/integration/tiered-context-local-day.test.ts new file mode 100644 index 000000000..a7dd40527 --- /dev/null +++ b/tests/integration/tiered-context-local-day.test.ts @@ -0,0 +1,69 @@ +/** + * v1.42 — the tiered context's live day band buckets on the reader's own + * calendar day, including on a daylight-saving changeover. + * + * For a reader far from UTC the 14–30-day band is read live, bucketed by + * `date_trunc('day', )`. `measured_at` is a `timestamp` + * without time zone holding UTC, and the band read it with a single + * `AT TIME ZONE tz`, which interprets the value as local time and converts + * the wrong way: in Los Angeles every reading moved sixteen hours, and an + * evening reading was summarised as the next day. The Coach and the briefing + * then quoted a day's mean built from two different days. + * + * 2026-03-08 is the US changeover (02:00 PST becomes 03:00 PDT). Two weight + * readings on that local day, 08:00 PDT (15:00Z) and 23:30 PDT (06:30Z on + * the 9th), must form one bucket for the 8th. + */ +import { beforeAll, describe, expect, it, vi } from "vitest"; + +import { getPrismaClient, truncateAllTables } from "./setup"; + +vi.mock("@/lib/db-compat", () => ({ + ensureDbCompatibility: vi.fn().mockResolvedValue(undefined), +})); + +import { buildTieredSeries } from "@/lib/rollups/tiered-context"; + +const prisma = getPrismaClient(); +const USER = "tiered-context-local-day"; +const TZ = "America/Los_Angeles"; +/** "Now" for the band arithmetic: the 8th sits inside the 14–30-day band. */ +const NOW = new Date("2026-03-25T12:00:00Z").getTime(); + +beforeAll(async () => { + await truncateAllTables(prisma); + await prisma.user.create({ + data: { id: USER, username: USER, timezone: TZ }, + }); + await prisma.measurement.createMany({ + data: [ + { at: "2026-03-08T15:00:00Z", value: 70 }, + { at: "2026-03-09T06:30:00Z", value: 80 }, + // A reading on the local 7th, late evening PST, for contrast. + { at: "2026-03-08T07:30:00Z", value: 90 }, + ].map(({ at, value }) => ({ + userId: USER, + type: "WEIGHT" as const, + value, + unit: "kg", + measuredAt: new Date(at), + source: "MANUAL" as const, + })), + }); +}); + +describe("tiered context — live day band on the reader's calendar", () => { + it("puts an evening reading on its own local day across the DST changeover", async () => { + const series = await buildTieredSeries(USER, "WEIGHT", { + tz: TZ, + now: NOW, + skipEnsureFresh: true, + }); + const byDay = Object.fromEntries( + series.dayBand.map((b) => [b.bucketStart.slice(0, 10), b]), + ); + expect(Object.keys(byDay).sort()).toEqual(["2026-03-07", "2026-03-08"]); + expect(byDay["2026-03-08"]).toMatchObject({ count: 2, mean: 75 }); + expect(byDay["2026-03-07"]).toMatchObject({ count: 1, mean: 90 }); + }); +});