diff --git a/docs/ops/measurement-maintenance.md b/docs/ops/measurement-maintenance.md index eb95cb053..f7ca054ab 100644 --- a/docs/ops/measurement-maintenance.md +++ b/docs/ops/measurement-maintenance.md @@ -165,8 +165,9 @@ singleton key with the run you start, so the two never overlap. The admin card keeps showing only the runs you started. The check also measures how far the table file has grown past what its live -rows need (`maintenance_bloat_factor` on the wide event, `bloat_factor` in the -job result). Past 3 it adds a warning to the event: a vacuum makes the space +rows need (`maintenance_bloat_factor` on the wide event, as a factor such as +1.3; `bloat_percent` in the job result, as whole percent such as 130, because a +job fact is a whole number). Past 3 it adds a warning to the event: a vacuum makes the space reusable but does not shrink the file, and only `VACUUM FULL` does (see below). diff --git a/src/__tests__/job-fact-whole-number-guard.test.ts b/src/__tests__/job-fact-whole-number-guard.test.ts new file mode 100644 index 000000000..30020df6e --- /dev/null +++ b/src/__tests__/job-fact-whole-number-guard.test.ts @@ -0,0 +1,134 @@ +/** + * A job fact is a non-negative whole number, a stable code or a boolean + * (`src/lib/jobs/job-outcome.ts`). A producer that hands a ratio, an average + * or a quotient over as a number passes the type checker and fails the + * outcome's validation at run time: the nightly measurements check reported + * its bloat factor (1.3) that way and failed every run (#1271). + * + * This reads every module that reports a job outcome and refuses a fact whose + * value is a division, or names a ratio-shaped quantity (a name ending in + * factor, ratio, average, mean, share, fraction or percent), unless it goes through + * `wholeFact`/`percentFact` or an explicit `Math.round`/`floor`/`ceil`/`trunc`. + * A text-level check: it sees the expression written at the fact, not what a + * variable it names was computed from. The runtime half is `runJob`, which + * drops and signals an invalid fact instead of failing finished work. + */ +import ts from "typescript"; +import { join } from "node:path"; +import { describe, expect, it } from "vitest"; + +import { JOB_FACT_ALLOWLIST } from "@/lib/jobs/job-outcome"; + +import { readSourceText, walkSourceFiles } from "./helpers/source-files"; +import { parse } from "./helpers/source-metrics"; + +const SRC = join(process.cwd(), "src"); +/** The last word of a camelCase or snake_case name: what the value IS. */ +const RATIO_NOUN = /^(factor|ratio|average|avg|mean|share|fraction|percent)$/; +function namesRatio(name: string): boolean { + const words = name + .replace(/([a-z0-9])([A-Z])/g, "$1_$2") + .toLowerCase() + .split("_") + .filter(Boolean); + return RATIO_NOUN.test(words[words.length - 1] ?? ""); +} +const ROUNDING_CALL = + /^(wholeFact|percentFact|Math\.(round|floor|ceil|trunc))$/; + +function roundedByCall(node: ts.Node): boolean { + for (let n: ts.Node | undefined = node; n; n = n.parent) { + if (ts.isCallExpression(n) && ROUNDING_CALL.test(n.expression.getText())) { + return true; + } + if (ts.isPropertyAssignment(n)) return false; + } + return false; +} + +function suspicious(initializer: ts.Expression): boolean { + let found = false; + const visit = (node: ts.Node): void => { + if (found) return; + const divides = + ts.isBinaryExpression(node) && + node.operatorToken.kind === ts.SyntaxKind.SlashToken; + const ratioName = + (ts.isIdentifier(node) || ts.isPrivateIdentifier(node)) && + namesRatio(node.text); + if ((divides || ratioName) && !roundedByCall(node)) { + found = true; + return; + } + ts.forEachChild(node, visit); + }; + visit(initializer); + return found; +} + +/** `file:line key` for every allowlisted fact whose value looks fractional. */ +function offenders(rel: string, text: string): string[] { + if (!text.includes("jobDone(") && !text.includes("jobFailed(")) return []; + const source = parse(rel, text); + const out: string[] = []; + const visit = (node: ts.Node): void => { + if ( + ts.isPropertyAssignment(node) && + (ts.isIdentifier(node.name) || ts.isStringLiteral(node.name)) && + JOB_FACT_ALLOWLIST.has(node.name.text) && + suspicious(node.initializer) + ) { + const { line } = source.getLineAndCharacterOfPosition(node.getStart()); + out.push(`${rel}:${line + 1} ${node.name.text}`); + } + ts.forEachChild(node, visit); + }; + visit(source); + return out; +} + +describe("job facts are whole numbers at the source", () => { + const files = walkSourceFiles(SRC, { floor: 1500 }).filter( + (rel) => + !rel.startsWith("generated/") && + !rel.includes("__tests__") && + !rel.endsWith(".test.ts"), + ); + + it("reads the producers it claims to check", () => { + const producers = files.filter((rel) => + readSourceText(join(SRC, rel)).includes("jobDone("), + ); + expect(producers.length).toBeGreaterThan(40); + }); + + it("finds no fact that carries a ratio or a quotient as it stands", () => { + const found = files.flatMap((rel) => + offenders(rel, readSourceText(join(SRC, rel))), + ); + expect(found).toEqual([]); + }); + + it("catches the shape it guards against, and lets the rounded one through", () => { + const old = [ + "const facts = {", + " dead_rows: health.deadRows,", + " bloat_percent: health.bloatFactor ?? 0,", + " duration_ms: elapsed / 1000,", + "};", + "return jobDone(facts);", + ].join("\n"); + expect(offenders("x.ts", old)).toEqual([ + "x.ts:3 bloat_percent", + "x.ts:4 duration_ms", + ]); + const fixed = [ + "const facts = {", + " bloat_percent: percentFact(health.bloatFactor),", + " duration_ms: Math.round(elapsed / 1000),", + "};", + "return jobDone(facts);", + ].join("\n"); + expect(offenders("x.ts", fixed)).toEqual([]); + }); +}); diff --git a/src/lib/jobs/__tests__/measurement-maintenance-facts.test.ts b/src/lib/jobs/__tests__/measurement-maintenance-facts.test.ts new file mode 100644 index 000000000..4c15498af --- /dev/null +++ b/src/lib/jobs/__tests__/measurement-maintenance-facts.test.ts @@ -0,0 +1,89 @@ +/** + * #1271: the nightly measurements check failed every run, because it reported + * its bloat factor (heap size over what the live rows need, a ratio such as + * 1.3) as a job fact, and a fact is a non-negative whole number. The factor + * now rides as whole percent. + * + * The handler runs for real against a stand-in connection that answers the + * table-statistics read with a heap 1.3 times what its rows need; its outcome + * goes through the strict serializer, which refused the old fact. + */ +import { describe, expect, it, vi } from "vitest"; +import type { Job } from "pg-boss"; + +vi.mock("pg", () => ({ + Client: class { + on() {} + async connect() {} + async end() {} + async query(sql: string) { + if (sql.includes("pg_stat_user_tables")) { + // 1,000 rows of 72 bytes plus 28 of overhead at fill factor 0.85 + // need about 117,647 bytes; the heap holds 1.3 times that. + return { + rows: [{ live: "1000", dead: "40", heap: "152941", width: "72" }], + }; + } + if (sql.includes("pg_total_relation_size")) { + return { rows: [{ table: "300000", indexes: "100000" }] }; + } + return { rows: [] }; + } + }, +})); +vi.mock("@/lib/db", () => ({ sessionOptionsDisabled: () => true })); +vi.mock("@/lib/jobs/job-lock", () => ({ + withJobLock: async (_queue: string, run: () => Promise) => ({ + ran: true, + result: await run(), + }), +})); +vi.mock("@/lib/jobs/job-run-report", () => ({ reportJobRun: () => {} })); + +import { + jobDone, + percentFact, + serializeJobOutcome, + wholeFact, +} from "../job-outcome"; +import { + handleMeasurementMaintenance, + type MeasurementMaintenancePayload, +} from "../measurement-maintenance"; + +describe("the measurement maintenance outcome", () => { + it("serialises with a realistic, fractional bloat factor", async () => { + const outcome = await handleMeasurementMaintenance([ + { id: "run-1", data: {} } as Job, + ]); + expect(outcome.ok).toBe(true); + const serialized = serializeJobOutcome(outcome); + expect(serialized.ok).toBe(true); + expect(serialized.did).toMatchObject({ + dead_rows: 40, + bloat_percent: 130, + }); + expect(serialized.did).not.toHaveProperty("bloat_factor"); + }); +}); + +describe("the fact helpers", () => { + it("round a measured value to a whole, non-negative fact", () => { + expect(wholeFact(12.5)).toBe(13); + expect(wholeFact(-4)).toBe(0); + expect(wholeFact(Number.NaN)).toBe(0); + expect(wholeFact(null)).toBe(0); + }); + + it("turn a ratio into whole percent", () => { + expect(percentFact(1.3)).toBe(130); + expect(percentFact(0.004)).toBe(0); + expect(percentFact(undefined)).toBe(0); + }); + + it("leave the strict serializer refusing what the helpers exist to prevent", () => { + expect(() => serializeJobOutcome(jobDone({ dead_rows: 1.3 }))).toThrow( + /non-negative safe integer/, + ); + }); +}); diff --git a/src/lib/jobs/__tests__/run-job.test.ts b/src/lib/jobs/__tests__/run-job.test.ts index 555ef57cb..f0e635af4 100644 --- a/src/lib/jobs/__tests__/run-job.test.ts +++ b/src/lib/jobs/__tests__/run-job.test.ts @@ -87,17 +87,53 @@ describe("runJob", () => { expect(reportWorkerError).not.toHaveBeenCalled(); }); - it("refuses to persist credentials or unbounded facts on success", async () => { + it("refuses to persist credentials on success, without failing the finished run", async () => { const wrapped = runJob("google-health-sync", async () => jobDone({ refresh_token: "private-token", + processed: 2, } as unknown as Record), ); - await expect(wrapped(noJobs)).rejects.toThrow(/fact key is not allowed/i); + // The run's work is done: the result keeps what the contract allows and + // drops the rest, and the drop is an error-level signal naming the key. + await expect(wrapped(noJobs)).resolves.toEqual({ + ok: true, + did: { processed: 2 }, + }); + expect(emitSignal).toHaveBeenCalledWith( + expect.objectContaining({ + action: "job.outcome.fact_invalid", + level: "error", + meta: { queue: "google-health-sync", key: "refresh_token" }, + }), + ); + expect(JSON.stringify(emitSignal.mock.calls)).not.toContain( + "private-token", + ); expect(reportWorkerError).not.toHaveBeenCalled(); }); + it("does not fail a finished run over a fact that is not a whole number (#1271)", async () => { + // The nightly measurements check reported its bloat factor, a ratio such + // as 1.3, as a fact. The validation refused it after the VACUUM had run, + // so every run failed and pg-boss retried finished work. + const wrapped = runJob("measurement-maintenance", async () => + jobDone({ processed: 3, duration_ms: 12.5, dead_rows: 40 }), + ); + + await expect(wrapped(noJobs)).resolves.toEqual({ + ok: true, + did: { processed: 3, dead_rows: 40 }, + }); + expect(emitSignal).toHaveBeenCalledWith( + expect.objectContaining({ + action: "job.outcome.fact_invalid", + meta: { queue: "measurement-maintenance", key: "duration_ms" }, + }), + ); + }); + it("rethrows a failed outcome so pg-boss records a failed job", async () => { const cause = new Error("statement timeout"); const wrapped = runJob("push-attempt-cleanup", async () => diff --git a/src/lib/jobs/job-outcome.ts b/src/lib/jobs/job-outcome.ts index 1460c78e4..250838b7d 100644 --- a/src/lib/jobs/job-outcome.ts +++ b/src/lib/jobs/job-outcome.ts @@ -57,8 +57,9 @@ export const JOB_FACT_ALLOWLIST: ReadonlySet = new Set([ "assessments_warmed", "auto_resolved", "backed", - // The nightly measurements check: heap size over what the live rows need. - "bloat_factor", + // The nightly measurements check: heap size over what the live rows need, + // in percent (130 is a heap 1.3 times the size its live rows need). + "bloat_percent", "buckets_collapsed", "buckets_recomputed", "budget_blocked", @@ -367,46 +368,86 @@ function assertStableCode(value: string, label: string): void { } } -function validateFacts(facts: JobFacts): JobFacts { +/** + * A measured quantity as a fact: a duration or an amount computed in floating + * point, rounded on purpose. A fact is a non-negative whole number, and a + * value that is not one fails the outcome's validation. + */ +export function wholeFact(value: number | null | undefined): number { + if (value == null || !Number.isFinite(value)) return 0; + return Math.max(0, Math.round(value)); +} + +/** + * A ratio as a fact, in whole percent: 1.3 is 130. A ratio is not a whole + * number, so it cannot be a fact as it stands; this is the one way to report + * one. Absent or unmeasurable is 0. + */ +export function percentFact(ratio: number | null | undefined): number { + if (ratio == null || !Number.isFinite(ratio)) return 0; + return wholeFact(ratio * 100); +} + +/** Why one fact is refused, or null when it is a valid fact. */ +function invalidFact(key: string, value: unknown): string | null { + if (!JOB_FACT_ALLOWLIST.has(key)) + return `job fact key is not allowed: ${key}`; + if (typeof value === "number") { + return Number.isSafeInteger(value) && value >= 0 + ? null + : `job fact ${key} must be a non-negative safe integer`; + } + if (typeof value === "string") { + return STABLE_CODE_PATTERN.test(value) + ? null + : `job fact ${key} must be a stable lowercase code`; + } + return typeof value === "boolean" + ? null + : `job fact ${key} must be a bounded scalar`; +} + +/** + * Called for each fact the serializer drops instead of throwing over it. A + * caller that passes it has already done the run's work: refusing the whole + * outcome over one malformed fact would fail completed work, and pg-boss + * would retry it. + */ +export type InvalidFactHandler = (key: string, reason: string) => void; + +function validateFacts( + facts: JobFacts, + onInvalidFact?: InvalidFactHandler, +): JobFacts { const entries = Object.entries(facts); if (entries.length > MAX_JOB_FACTS) { throw new RangeError(`job outcome exceeds ${MAX_JOB_FACTS} facts`); } + const kept: Array<[string, JobFact]> = []; for (const [key, value] of entries) { - if (!JOB_FACT_ALLOWLIST.has(key)) { - throw new TypeError(`job fact key is not allowed: ${key}`); - } - - if (typeof value === "number") { - if (!Number.isSafeInteger(value) || value < 0) { - throw new TypeError( - `job fact ${key} must be a non-negative safe integer`, - ); - } + const reason = invalidFact(key, value); + if (reason === null) { + kept.push([key, value]); continue; } - - if (typeof value === "string") { - assertStableCode(value, `job fact ${key}`); - continue; - } - - if (typeof value !== "boolean") { - throw new TypeError(`job fact ${key} must be a bounded scalar`); - } + if (!onInvalidFact) throw new TypeError(reason); + onInvalidFact(key, reason); } - return Object.freeze(Object.fromEntries(entries)) as JobFacts; + return Object.freeze(Object.fromEntries(kept)) as JobFacts; } /** * Produce the only representation suitable for persistence or structured * logging. The raw `cause` deliberately remains in-process for retry handling. */ -export function serializeJobOutcome(outcome: JobOutcome): SerializedJobOutcome { - const did = validateFacts(outcome.did ?? {}); +export function serializeJobOutcome( + outcome: JobOutcome, + options: { onInvalidFact?: InvalidFactHandler } = {}, +): SerializedJobOutcome { + const did = validateFacts(outcome.did ?? {}, options.onInvalidFact); const serialized: SerializedJobOutcome = outcome.ok ? { ok: true, did } : (() => { diff --git a/src/lib/jobs/measurement-maintenance.ts b/src/lib/jobs/measurement-maintenance.ts index 144427b66..a917f77a3 100644 --- a/src/lib/jobs/measurement-maintenance.ts +++ b/src/lib/jobs/measurement-maintenance.ts @@ -61,7 +61,13 @@ import type { Job } from "pg-boss"; import { sessionOptionsDisabled } from "@/lib/db"; import { withJobLock } from "@/lib/jobs/job-lock"; -import { jobDone, jobFailed, type JobOutcome } from "@/lib/jobs/job-outcome"; +import { + jobDone, + jobFailed, + percentFact, + wholeFact, + type JobOutcome, +} from "@/lib/jobs/job-outcome"; import { reportJobRun, type JobRunCandidate } from "@/lib/jobs/job-run-report"; import { withBackgroundEvent } from "@/lib/logging/background"; import { logCaught } from "@/lib/logging/signal"; @@ -640,10 +646,12 @@ export async function handleMeasurementMaintenance( outcome: result.outcome, processed: result.steps.filter((s) => s.ok).length, failed: result.steps.filter((s) => !s.ok).length, - duration_ms: Date.now() - startedAt, + duration_ms: wholeFact(Date.now() - startedAt), dead_rows: health.deadRows, - // Zero before the table has statistics to measure against. - bloat_factor: health.bloatFactor ?? 0, + // In whole percent: a fact is a whole number and the factor a ratio + // (1.3). Reported as the ratio itself it failed every run's outcome + // validation (#1271). Zero before the table has statistics. + bloat_percent: percentFact(health.bloatFactor), }; if (result.outcome === "failed") { const firstError = result.steps.find((s) => !s.ok); diff --git a/src/lib/jobs/run-job.ts b/src/lib/jobs/run-job.ts index 114c26e26..f4df20089 100644 --- a/src/lib/jobs/run-job.ts +++ b/src/lib/jobs/run-job.ts @@ -116,7 +116,21 @@ export function runJob( await signalRunFailed(queue, "handler_threw", error); throw error; } - if (outcome.ok) return serializeJobOutcome(outcome); + // The work is done by now. A fact that breaks the contract is a + // programming error in the handler, reported at error level and dropped + // from the result; failing the run over it would retry work that already + // succeeded (a nightly VACUUM, a full sweep). + if (outcome.ok) { + return serializeJobOutcome(outcome, { + onInvalidFact: (key, reason) => + emitSignal({ + action: "job.outcome.fact_invalid", + level: "error", + meta: { queue, key }, + error: new TypeError(reason), + }), + }); + } const failure = new JobFailure(queue, outcome.reason, outcome.cause); const causeMessage =