Merge AI operations and error-log discipline into release/v1.42.0

This commit is contained in:
Marc-André Bombeck committed 2026-10-08 09:06:58 +02:00
commit 5c23f9ed63
71 files changed
+3650 -340

No files matched your search

+65
View File
@@ -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."
}
}
}
}
@@ -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",
);
@@ -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 {
/** `<file under src>::<enclosing function>` */
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, "<module>");
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<Record<string, { count: number; reason: string }>> = {
"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<Record<string, { count: number }>>,
): string[] {
const byKey = new Map<string, Finding[]>();
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<string, number>();
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<string, unknown>)[key];
return unallowed(findings, without).length === 0;
});
expect(notLoadBearing).toEqual([]);
});
});
@@ -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([]);
});
});
@@ -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<typeof import("@/lib/api-handler")>(
@@ -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();
});
});
@@ -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<string, ProviderHealthSummary>();
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;
}
}
@@ -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<string, string>): 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);
});
});
+28 -9
View File
@@ -12,7 +12,8 @@
* The `data` payload is the flat `Derived<T>` 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<ReturnType<typeof computeDerivedMetric>>
>,
`${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" },
@@ -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() {
})}`
: ""}
</span>
{p.pausedUsers && p.pausedUntil ? (
<span
className="text-muted-foreground text-xs"
data-slot="provider-paused"
>
{t("admin.providerHealth.pausedHint", {
count: p.pausedUsers,
at: formatDateTime(p.pausedUntil),
})}
</span>
) : null}
{p.modelListing?.listing === "not_listed" ? (
<span className="text-sm" data-slot="provider-model-missing">
{t("admin.providerHealth.modelNotServed", {
model: p.modelListing.model,
})}
</span>
) : null}
</div>
{p.failing === 0 ? (
<Badge variant="secondary">
{t("admin.providerHealth.statusHealthy")}
</Badge>
) : p.pausedUsers ? (
<Badge variant="destructive">
{t("admin.providerHealth.statusPaused")}
</Badge>
) : (
<Badge variant="destructive">
{t("admin.providerHealth.statusFailing", {
+72
View File
@@ -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<CodexRefreshError> {
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);
@@ -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<typeof import("undici")>();
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);
});
});
@@ -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 >=/);
});
});
@@ -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<string, unknown>;
},
)
.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);
});
});
@@ -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<object>()),
@@ -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();
});
});
+19
View File
@@ -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",
+97 -3
View File
@@ -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<string> = 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
+91
View File
@@ -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<string, { at: number; value: ModelListing }>();
/** 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<ModelListing> {
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<ModelListing> {
const url = `${input.baseUrl.replace(/\/$/, "")}/models`;
const headers: Record<string, string> = { 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";
}
}
+38 -1
View File
@@ -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<boolean> {
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;
}
+83 -8
View File
@@ -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) {
+71
View File
@@ -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);
}
+5 -6
View File
@@ -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<AIProvider | null> {
!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<AIProvider | null> {
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);
@@ -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<unknown>) {
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();
});
});
@@ -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<typeof import("@/lib/safe-fetch")>();
return { ...actual, safeFetch: safeFetchMock };
});
vi.mock("../sync-core", async (importOriginal) => {
const actual = await importOriginal<typeof import("../sync-core")>();
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"',
);
});
});
@@ -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,
}));
+21 -6
View File
@@ -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({
+16
View File
@@ -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,
+10 -1
View File
@@ -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) {
+6
View File
@@ -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 = [
@@ -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" });
});
});
+1 -1
View File
@@ -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.
+96 -4
View File
@@ -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.
`;
}
@@ -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"]);
});
});
@@ -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");
@@ -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);
});
});
+57
View File
@@ -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<typeof import("../job-failures")>(
"../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();
});
});
+10 -3
View File
@@ -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: {
+9 -4
View File
@@ -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();
}
}
+5 -2
View File
@@ -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.
}
+7 -4
View File
@@ -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;
}
+7 -2
View File
@@ -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;
}
}
+3 -1
View File
@@ -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.
}
+2
View File
@@ -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;
}
}
+5 -1
View File
@@ -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 };
}
}
+2
View File
@@ -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 };
}
}
+4 -1
View File
@@ -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 };
}
}
+3 -1
View File
@@ -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.
}
+2
View File
@@ -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 };
}
}
+3 -1
View File
@@ -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 };
+7 -3
View File
@@ -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.
}
+317 -216
View File
@@ -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<PregenerateRunResult> {
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<JobRunCandidate> {
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.
}
}
@@ -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.
}
+98 -10
View File
@@ -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<number> {
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;
}
}
+3 -2
View File
@@ -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<T> = { ran: true; result: T } | { ran: false };
@@ -50,9 +51,9 @@ export async function withJobLock<T>(
} 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"));
}
}
+2
View File
@@ -47,6 +47,8 @@ export const JOB_FACT_ALLOWLIST: ReadonlySet<string> = 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",
+127 -14
View File
@@ -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<JobRunOutcome> = new Set(["failed", "auth_failed"]);
const NOT_ATTEMPTED: ReadonlySet<JobRunOutcome> = 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<JobRunVerdict> {
const verdict = judgeJobRun(input.candidates);
const byOutcome: Record<string, number> = {};
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<string>();
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];
}
@@ -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.
}
+3 -1
View File
@@ -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<void> {
retryDelay: 300,
},
);
} catch {
} catch (err) {
logCaught("backup.offhost_purge.kick_failed", err);
// The cron is the backstop.
}
}
+5 -1
View File
@@ -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.
}
+20 -9
View File
@@ -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 };
}
@@ -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,
});
+37 -8
View File
@@ -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<T> = (jobs: Job<T>[]) => Promise<JobOutcome>;
@@ -67,14 +69,34 @@ function factMeta(did: JobFacts | undefined): Record<string, JobFact> {
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<void> {
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<J>(
queue: string,
@@ -83,11 +105,17 @@ export function runJob<J>(
return async (jobs: J[]): Promise<SerializedJobOutcome> => {
// 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<J>(
...factMeta(outcome.did),
...(causeMessage === undefined ? {} : { cause: causeMessage }),
});
await signalRunFailed(queue, outcome.reason, failure);
throw failure;
};
@@ -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 };
}
}
+19 -8
View File
@@ -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" };
}
+101
View File
@@ -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<Record<string, unknown>> = [];
vi.mock("../transports", () => ({
emitIfSampled: (event: Record<string, unknown>) => 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<string, unknown>;
};
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<string, string> };
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");
});
});
+12 -1
View File
@@ -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,
+99
View File
@@ -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 `<surface>.<noun>.<verb>` 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<string, unknown>;
/** 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<string, unknown>,
): 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<string, unknown>,
): (error: unknown) => void {
return (error: unknown) => logCaught(action, error, meta);
}
+6
View File
@@ -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")
+12 -2
View File
@@ -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<
+41
View File
@@ -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<string, unknown>) {
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();
+80
View File
@@ -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<number> {
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");
});
});
@@ -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', <local wall clock>)`. `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 });
});
});