From 2e99109a931d7aa9ce71e2e0584005ea757f8612 Mon Sep 17 00:00:00 2001 From: Peter Steinberger Date: Fri, 2 Oct 2026 09:58:45 -0700 Subject: [PATCH] fix(doctor): migrate memory vectors one row at a time and keep native crash diagnostics (#163640) A 2026.9.5 to 9.7 candidate Doctor died after about five minutes in "Checking data migrations" with a native stack through node::sqlite::DatabaseSync::Exec, and the recorded failure kept only an adjacent plugin warning (#163531). The memory schema storage migration called its UDF in bulk and retained every row embedding JSON in the JavaScript heap until the native call returned, which exhausts the heap on large legacy embedding caches; it now validates and converts one memory vector at a time inside the same transaction, preserving row identities, 64-bit rowids and stored text. Candidate validation now records a signal termination with its phase, fatal header and a bounded stderr tail in the update-run record and report instead of letting an unrelated warning take precedence. Thanks @fenglanhua for the stack. Refs #163531 --- docs/cli/update/status-and-history.md | 10 ++ .../database-schemas/agent-schema-history.md | 16 ++- .../src/schema/update-runs.ts | 3 + .../memory-schema-storage-migration.test.ts | 76 ++++++++++- .../host/memory-schema-storage-migration.ts | 121 ++++++++++++------ src/cli/update-cli/progress.ts | 5 +- src/infra/update-candidate-canary-process.ts | 16 ++- ...date-candidate-canary.exit.process.test.ts | 90 ++++++++++++- .../update-candidate-canary.lint.test.ts | 4 +- src/infra/update-candidate-canary.ts | 44 +++---- src/infra/update-failure-facts.ts | 45 +++++++ src/infra/update-failure-report-artifact.ts | 25 +++- src/infra/update-failure-report-prepare.ts | 12 +- src/infra/update-run-codec.ts | 27 +++- src/infra/update-run-record.ts | 9 +- src/infra/update-run-report.ts | 3 + src/infra/update-run-schema.ts | 3 + src/infra/update-run-step.ts | 6 + 18 files changed, 434 insertions(+), 81 deletions(-) diff --git a/docs/cli/update/status-and-history.md b/docs/cli/update/status-and-history.md index 1c79fda7de6b..46514bfc11e0 100644 --- a/docs/cli/update/status-and-history.md +++ b/docs/cli/update/status-and-history.md @@ -323,6 +323,16 @@ diagnostic failures remain warnings, while refused config writes and incomplete required migrations remain errors. Historical runs cannot recover facts that their updater never recorded. +If a candidate check exits by signal, its failed step retains `termination`, +`signal`, and a redacted `stderrTail` (up to 80 lines, 512 characters per line, +and 8,192 characters total, reserving the fatal header when present). The report names the check, including **Checking +data migrations** for Doctor, and shows the native diagnostics ahead of adjacent +plugin warnings. The terminal and local Markdown report retain the excerpt; +the short status report can truncate it. JSON history keeps the bounded excerpt, +and reviewed public reports retain the termination class and recognized signal. This capture +requires the updated updater; a candidate cannot restore diagnostics that an +older installed driver discarded. + Current updaters record their process identities and refresh the ledger every 30 seconds during long build, install, and finalization phases. Those writes pause whenever a Doctor child is repairing state: finalization pauses them diff --git a/docs/reference/database-schemas/agent-schema-history.md b/docs/reference/database-schemas/agent-schema-history.md index a1e61713f2d2..20a0c11f8727 100644 --- a/docs/reference/database-schemas/agent-schema-history.md +++ b/docs/reference/database-schemas/agent-schema-history.md @@ -114,13 +114,15 @@ existing rebuild claims, cursors, active-path rows, and canonical-validation pending rows are preserved. The unpublished compressed schema-22 draft is not a supported predecessor. -The admitted migration converts one transcript record at a time, verifies each -compressed frame against its original bytes, preserves row identities and -timestamps, and commits table replacements with both schema markers. Unknown -columns or dependencies that a rebuild would discard cause a refusal. Earlier -supported schemas run their prerequisite migrations first. Conversion needs -temporary space for old and replacement tables, journal/WAL activity, and the -verified backup. Freed pages are reusable; a smaller payload does not by itself +The admitted migration converts one transcript record or memory vector at a time, +verifies each compressed transcript frame against its original bytes, preserves +row identities and timestamps, and commits table replacements with both schema +markers. Memory validation and conversion return from SQLite after each row so +large legacy embedding caches do not accumulate their JSON strings in the +JavaScript heap. Unknown columns or dependencies that a rebuild would discard +cause a refusal. Earlier supported schemas run their prerequisite migrations +first. Conversion needs temporary space for old and replacement tables, +journal/WAL activity, and the verified backup. Freed pages are reusable; a smaller payload does not by itself shrink the database file. Existing maintenance owns physical reclamation. Stop all writers and take a verified WAL-aware backup before upgrading. Supported diff --git a/packages/gateway-protocol/src/schema/update-runs.ts b/packages/gateway-protocol/src/schema/update-runs.ts index c0baf70b1d47..b9a9e2b1c858 100644 --- a/packages/gateway-protocol/src/schema/update-runs.ts +++ b/packages/gateway-protocol/src/schema/update-runs.ts @@ -129,6 +129,9 @@ export const UpdateRunRecordSchema = closedObject({ startedAtMs: Type.Optional(timestamp), endedAtMs: Type.Optional(timestamp), exitCode: Type.Optional(Type.Union([Type.Integer(), Type.Null()])), + termination: Type.Optional(Type.Enum(["exit", "timeout", "no-output-timeout", "signal"])), + signal: Type.Optional(Type.Union([Type.String({ maxLength: 32 }), Type.Null()])), + stderrTail: Type.Optional(Type.String({ maxLength: 8192 })), detail: Type.Optional(text), failureFacts: Type.Optional( Type.Array( diff --git a/packages/memory-host-sdk/src/host/memory-schema-storage-migration.test.ts b/packages/memory-host-sdk/src/host/memory-schema-storage-migration.test.ts index c1686b846e5c..cdc9bf786ee8 100644 --- a/packages/memory-host-sdk/src/host/memory-schema-storage-migration.test.ts +++ b/packages/memory-host-sdk/src/host/memory-schema-storage-migration.test.ts @@ -1,5 +1,8 @@ +import { spawnSync } from "node:child_process"; import { DatabaseSync } from "node:sqlite"; -import { describe, expect, it, onTestFinished, vi } from "vitest"; +import { fileURLToPath } from "node:url"; +import { afterEach, describe, expect, it, onTestFinished, vi } from "vitest"; +import { useAutoCleanupTempDirTracker } from "../../../../test/helpers/temp-dir.js"; import { decodeMemoryEmbedding, encodeMemoryEmbedding } from "./embedding-vector.js"; import { buildMemoryEmbeddingCacheSchema, @@ -7,6 +10,8 @@ import { } from "./memory-schema-base.js"; import { migrateMemoryIndexStorage } from "./memory-schema-storage-migration.js"; +const tempDirs = useAutoCleanupTempDirTracker(afterEach); + function legacyDatabase(): DatabaseSync { const db = new DatabaseSync(":memory:"); onTestFinished(() => db.close()); @@ -64,6 +69,75 @@ function snapshot(db: DatabaseSync) { } describe("memory storage migration", () => { + it("converts legacy vectors larger than the child heap while preserving 64-bit storage identities", () => { + const stateDir = tempDirs.make("memory-storage-heap-"); + const args = [ + "--max-old-space-size=96", + "--import", + fileURLToPath(new URL("../../../../scripts/tsx.mjs", import.meta.url)), + "--input-type=module", + "--eval", + ` + import { DatabaseSync } from 'node:sqlite'; + import { migrateMemoryIndexStorage } from ${JSON.stringify(new URL("./memory-schema-storage-migration.ts", import.meta.url).href)}; + const embedding = JSON.stringify(Array.from({ length: 3072 }, (_, index) => (index + 0.1234567890123456) / 9000)); + const results = []; + for (const kind of ['cache', 'chunks']) { + const db = new DatabaseSync(':memory:'); + const table = kind === 'cache' ? 'memory_embedding_cache' : 'memory_index_chunks'; + db.exec(kind === 'cache' ? + \`CREATE TABLE memory_embedding_cache ( + provider TEXT NOT NULL, model TEXT NOT NULL, provider_key TEXT NOT NULL, + hash TEXT NOT NULL, embedding TEXT NOT NULL, dims INTEGER, updated_at INTEGER NOT NULL, + PRIMARY KEY (provider, model, provider_key, hash) + ) STRICT;\` : + \`CREATE TABLE memory_index_meta (key TEXT PRIMARY KEY, value TEXT NOT NULL) STRICT; + CREATE TABLE memory_index_sources ( + path TEXT NOT NULL, source TEXT NOT NULL, hash TEXT NOT NULL, UNIQUE (path, source) + ) STRICT; + CREATE TABLE memory_index_chunks ( + id TEXT PRIMARY KEY, path TEXT NOT NULL, source TEXT NOT NULL DEFAULT 'memory', + start_line INTEGER NOT NULL, end_line INTEGER NOT NULL, hash TEXT NOT NULL, + model TEXT NOT NULL, text TEXT NOT NULL, embedding TEXT NOT NULL, updated_at INTEGER NOT NULL + ) STRICT;\`); + const insert = db.prepare(kind === 'cache' ? + "INSERT INTO memory_embedding_cache(rowid, provider, model, provider_key, hash, embedding, dims, updated_at) VALUES (?, 'provider', 'model', 'key', ?, ?, 3072, 123)" : + "INSERT INTO memory_index_chunks(rowid, id, path, source, start_line, end_line, hash, model, text, embedding, updated_at) VALUES (?, ?, 'memory/a.md', 'memory', 1, 2, 'h', 'model', CAST(X'80' AS TEXT), ?, 123)"); + insert.setReadBigInts(true); + for (let index = 0; index < 3000; index++) { + insert.run(9007199254740993n + BigInt(index), String(index), embedding); + } + migrateMemoryIndexStorage(db); + results.push(db.prepare(\`SELECT count(*) AS rows, sum(length(embedding)) AS bytes, + CAST(min(rowid) AS TEXT) AS first, CAST(max(rowid) AS TEXT) AS last + FROM \${table}\`).get()); + if (kind === 'chunks') { + results.push(db.prepare('SELECT DISTINCT hex(text) AS textBytes FROM memory_index_chunks').get()); + } + db.close(); + } + console.log(JSON.stringify(results)); + `, + ]; + const command = process.platform === "win32" ? process.execPath : "/bin/sh"; + const childArgs = + process.platform === "win32" + ? args + : ["-c", 'ulimit -c 0; exec "$@"', "memory-migration", process.execPath, ...args]; + const result = spawnSync(command, childArgs, { + env: { ...process.env, OPENCLAW_STATE_DIR: stateDir }, + encoding: "utf8", + }); + expect(result.status, result.error?.message ?? result.stderr).toBe(0); + const expected = { + rows: 3000, + bytes: 73_728_000, + first: "9007199254740993", + last: "9007199254743992", + }; + expect(JSON.parse(result.stdout)).toEqual([expected, expected, { textBytes: "80" }]); + }); + it("converts vectors without providers and preserves identity, provenance, cache age, and FTS maintenance", () => { const db = legacyDatabase(); migrateMemoryIndexStorage(db); diff --git a/packages/memory-host-sdk/src/host/memory-schema-storage-migration.ts b/packages/memory-host-sdk/src/host/memory-schema-storage-migration.ts index 25bf0f14f6df..4865b4e2872d 100644 --- a/packages/memory-host-sdk/src/host/memory-schema-storage-migration.ts +++ b/packages/memory-host-sdk/src/host/memory-schema-storage-migration.ts @@ -198,14 +198,58 @@ function storageShapes(db: DatabaseSync, cacheTable: string) { } function assertBinaryEmbeddings(db: DatabaseSync, table: string): void { - if ( - db - .prepare( - `SELECT 1 FROM ${table} WHERE openclaw_memory_embedding_blob_valid(embedding) = 0 LIMIT 1`, - ) - .get() - ) { - throw new Error(`Memory storage migration found invalid binary embeddings in ${table}`); + const rows = db.prepare( + `SELECT openclaw_memory_embedding_blob_valid(embedding) AS valid FROM ${table}`, + ); + for (const row of rows.iterate()) { + if (row.valid === 0) { + throw new Error(`Memory storage migration found invalid binary embeddings in ${table}`); + } + } +} + +function copyMemoryStorageRows(db: DatabaseSync, table: string, sql: string): void { + const rows = db.prepare(`SELECT rowid AS storage_rowid FROM ${table}`); + rows.setReadBigInts(true); + const copy = db.prepare(sql); + copy.setReadBigInts(true); + // node:sqlite retains UDF argument handles until its native call returns. + // Copy one row per call, keeping other persisted fields inside SQLite. + for (const row of rows.iterate()) { + if (typeof row.storage_rowid !== "bigint") { + throw new Error("Invalid memory storage identity during migration"); + } + copy.run(row.storage_rowid); + } +} + +function markInvalidMemoryEmbeddings(db: DatabaseSync, sql: string): void { + const rows = db.prepare(sql); + rows.setReadBigInts(true); + const dirtySource = db.prepare(` + UPDATE main.memory_index_sources SET hash = '' + WHERE (path, source) IN ( + SELECT path, source FROM main.memory_index_chunks WHERE rowid = ? + )`); + dirtySource.setReadBigInts(true); + let invalid = false; + // Project validity instead of filtering on the UDF: each native step must + // return even when every embedding is valid. + for (const row of rows.iterate()) { + if (row.valid === 0) { + if (typeof row.storage_rowid !== "bigint") { + throw new Error("Invalid memory storage identity during migration"); + } + dirtySource.run(row.storage_rowid); + invalid = true; + } + } + if (invalid) { + db.exec(` + INSERT INTO main.memory_index_meta (key, value) + VALUES ('memory_vector_rebuild_v1', '1') + ON CONFLICT(key) DO UPDATE SET value = excluded.value; + `); } } @@ -272,19 +316,16 @@ export function markInvalidImportedMemoryEmbeddings(db: DatabaseSync, schema: st if (!/^[A-Za-z_][A-Za-z0-9_]*$/u.test(schema)) { throw new Error("Invalid legacy memory schema identifier"); } - const invalidChunks = ` - SELECT chunk.path, chunk.source + markInvalidMemoryEmbeddings( + db, + ` + SELECT chunk.rowid AS storage_rowid, + openclaw_memory_embedding_json_valid(legacy.embedding) AS valid FROM ${schema}.chunks AS legacy JOIN main.memory_index_chunks AS chunk ON chunk.id = legacy.id - WHERE openclaw_memory_embedding_json_valid(legacy.embedding) = 0 - AND length(chunk.embedding) = 0`; - db.exec(` - UPDATE main.memory_index_sources SET hash = '' - WHERE (path, source) IN (${invalidChunks}); - INSERT INTO main.memory_index_meta (key, value) - SELECT 'memory_vector_rebuild_v1', '1' WHERE EXISTS (${invalidChunks}) - ON CONFLICT(key) DO UPDATE SET value = excluded.value; - `); + WHERE length(chunk.embedding) = 0 + `, + ); } function columns(db: DatabaseSync, table: string): Map { @@ -341,20 +382,14 @@ export function migrateMemoryIndexStorage( ensureMemoryRecallMetadataSchema(db); // Keep text and provenance searchable, but never invent a vector from // malformed legacy JSON. Source sync owns regeneration of these rows. - db.exec(` - UPDATE memory_index_sources SET hash = '' - WHERE (path, source) IN ( - SELECT path, source FROM memory_index_chunks - WHERE openclaw_memory_embedding_json_valid(embedding) = 0 - ); - INSERT INTO memory_index_meta (key, value) - SELECT 'memory_vector_rebuild_v1', '1' - WHERE EXISTS ( - SELECT 1 FROM memory_index_chunks - WHERE openclaw_memory_embedding_json_valid(embedding) = 0 - ) - ON CONFLICT(key) DO UPDATE SET value = excluded.value; - `); + markInvalidMemoryEmbeddings( + db, + ` + SELECT rowid AS storage_rowid, + openclaw_memory_embedding_json_valid(embedding) AS valid + FROM memory_index_chunks + `, + ); dropMemoryChunkFtsTriggers(db); db.exec( MEMORY_INDEX_CHUNKS_SCHEMA_SQL.replace( @@ -362,13 +397,19 @@ export function migrateMemoryIndexStorage( "CREATE TABLE", ).replace("memory_index_chunks", "memory_index_chunks_storage_migration"), ); - db.exec(` + copyMemoryStorageRows( + db, + "memory_index_chunks", + ` INSERT INTO memory_index_chunks_storage_migration ( chunk_rowid, id, path, source, start_line, end_line, hash, model, text, embedding, updated_at ) SELECT rowid, id, path, source, start_line, end_line, hash, model, text, openclaw_memory_embedding_from_json(embedding), updated_at - FROM memory_index_chunks; + FROM memory_index_chunks WHERE rowid = ? + `, + ); + db.exec(` DROP TABLE memory_index_chunks; ALTER TABLE memory_index_chunks_storage_migration RENAME TO memory_index_chunks; `); @@ -394,11 +435,17 @@ export function migrateMemoryIndexStorage( ); // Empty vectors retain a cache miss for malformed entries. Provider // identity, age, and rowid eviction order survive the conversion. - db.exec(` + copyMemoryStorageRows( + db, + cacheTable, + ` INSERT INTO ${replacement} (rowid, provider, model, provider_key, hash, embedding, dims, updated_at) SELECT rowid, provider, model, provider_key, hash, openclaw_memory_embedding_from_json(embedding), dims, updated_at - FROM ${cacheTable}; + FROM ${cacheTable} WHERE rowid = ? + `, + ); + db.exec(` DROP TABLE ${cacheTable}; ALTER TABLE ${replacement} RENAME TO ${cacheTable}; `); diff --git a/src/cli/update-cli/progress.ts b/src/cli/update-cli/progress.ts index 08f9f3d285f2..2c6cdb9db29d 100644 --- a/src/cli/update-cli/progress.ts +++ b/src/cli/update-cli/progress.ts @@ -262,7 +262,10 @@ function printStep(step: Omit): void { ? [step.stdoutTail, step.stderrTail] : updateStepDiagnostics(step).tails; for (const output of tails) { - for (const line of (output ?? "").trimEnd().split("\n").slice(-10)) { + for (const line of (output ?? "") + .trimEnd() + .split("\n") + .slice(step.termination === "signal" ? -80 : -10)) { if (line.trim()) { defaultRuntime.log(` ${color(line)}`); } diff --git a/src/infra/update-candidate-canary-process.ts b/src/infra/update-candidate-canary-process.ts index 2cafcb61220e..341ff88d0c40 100644 --- a/src/infra/update-candidate-canary-process.ts +++ b/src/infra/update-candidate-canary-process.ts @@ -31,6 +31,9 @@ export function launchCanary(params: { }); let stdout = ""; let lastStderrLine: string | undefined; + const stderrLines: string[] = []; + let fatalHeader: string | undefined; + const stderrTail = () => (fatalHeader ? [fatalHeader, ...stderrLines] : stderrLines).join("\n"); let cliReason: string | undefined; const captureStderr = (line: string) => { if (!line.trim() || line.startsWith(UPDATE_CANARY_PROGRESS_PREFIX)) { @@ -42,6 +45,16 @@ export function launchCanary(params: { Number.MAX_SAFE_INTEGER, ); lastStderrLine = sliceUtf16Safe(safe, -200); + if (safe.startsWith("FATAL ERROR:")) { + // A long native stack must not evict the fatal cause with earlier warnings. + fatalHeader = sliceUtf16Safe(safe, 0, 512); + stderrLines.length = 0; + } else { + stderrLines.push(sliceUtf16Safe(safe, 0, 512)); + } + while (stderrLines.length > (fatalHeader ? 79 : 80) || stderrTail().length > 8192) { + stderrLines.shift(); + } // The CLI prints a generic heading before its actual failure reason. if (line.startsWith("[openclaw] Reason: ")) { cliReason = sliceUtf16Safe(safe.replace(/^\[openclaw\] Reason: /u, ""), -200); @@ -138,7 +151,8 @@ export function launchCanary(params: { hasExited: () => exited, processExited: () => processExited, stdout: () => stdout, - stderrDiagnostic: () => cliReason ?? lastStderrLine, + stderrDiagnostic: () => fatalHeader ?? cliReason ?? lastStderrLine, + stderrTail, outputExceeded: () => outputExceeded, }; } diff --git a/src/infra/update-candidate-canary.exit.process.test.ts b/src/infra/update-candidate-canary.exit.process.test.ts index 52b96daa62ad..cd6ec44d7b9d 100644 --- a/src/infra/update-candidate-canary.exit.process.test.ts +++ b/src/infra/update-candidate-canary.exit.process.test.ts @@ -2,17 +2,30 @@ import fs from "node:fs/promises"; import path from "node:path"; import { afterEach, expect, it, vi } from "vitest"; import { useAutoCleanupTempDirTracker } from "../../test/helpers/temp-dir.js"; +import { closeOpenClawStateDatabaseForTest } from "../state/openclaw-state-db.js"; import { tryListenOnPort } from "./ports-probe.js"; import { validateUpdateCandidateCanary } from "./update-candidate-canary.js"; +import { renderSteps } from "./update-candidate-canary.test-support.js"; import * as rehearsals from "./update-candidate-rehearsal.js"; +import { writeUpdateRunReportArtifact } from "./update-failure-report-artifact.js"; +import { prepareUpdateFailureReport } from "./update-failure-report-prepare.js"; import { buildUpdateRehearsalPathEnv } from "./update-rehearsal-paths.js"; +import { + createUpdateRun, + finishUpdateRun, + getUpdateRun, + recordUpdateRunStep, +} from "./update-run-ledger.js"; import { renderUpdateRunReport, updateRunReportInputFromResult } from "./update-run-report.js"; +import { updateRunStepsFromResultStep } from "./update-run-step.js"; const dirs = useAutoCleanupTempDirTracker(afterEach); afterEach(() => vi.restoreAllMocks()); +afterEach(() => closeOpenClawStateDatabaseForTest()); it.each([ "doctor", + "doctor-signal", "lint", "policy", "missing", @@ -37,11 +50,23 @@ it.each([ path.join(root, "dist", "index.js"), `import { createServer } from "node:http"; import { spawn } from "node:child_process"; +import { writeFileSync } from "node:fs"; const mode = ${JSON.stringify(mode)}; const args = process.argv.slice(2); if (args.includes("--fix")) { + if (mode === "doctor-signal") { + writeFileSync(process.env.OPENCLAW_UPDATE_POST_INSTALL_DOCTOR_RESULT_PATH, JSON.stringify({ + status: "error", failureFacts: [{check: "plugins", code: "doctor-failed", message: "Plugin repair deferred"}], + })); + console.error(Array.from({length: 60}, (_, index) => "earlier warning " + index).join("\\n")); + console.error("FATAL ERROR: synthetic native failure token=synthetic-secret"); + console.error(Array.from({length: 60}, (_, index) => index + ": node::sqlite::DatabaseSync::Exec(v8::FunctionCallbackInfo const&) [openclaw]").join("\\n")); + console.log("adjacent stdout warning\\n".repeat(60)); + process.stderr.write("last native frame", () => process.kill(process.pid, "SIGTERM")); + } else { console.error("└ Doctor complete."); if (mode === "doctor") setInterval(() => {}, 1000); + } } else if (args.includes("--lint")) { if (mode !== "missing") console.log(JSON.stringify({ ok: mode !== "failed" && mode !== "policy", checksRun: 1, @@ -86,12 +111,73 @@ if (args.includes("--fix")) { cleanupDirectories: [], cleanup: async () => {}, }); + const options = { env: { OPENCLAW_STATE_DIR: path.join(root, "ledger") } }; + const run = mode === "doctor-signal" ? createUpdateRun({ trigger: "cli" }, options) : undefined; const result = await validateUpdateCandidateCanary({ root, config: {}, stateDir, timeoutMs: 2_000, + onStep: run + ? (step) => { + for (const receipt of updateRunStepsFromResultStep(step)) { + recordUpdateRunStep(run.runId, receipt, options); + } + } + : undefined, }); + if (run) { + for (let index = 0; index < 24; index++) { + recordUpdateRunStep( + run.runId, + { step: `finalize:fixture-${index}`, status: "completed", detail: "detail ".repeat(140) }, + options, + ); + } + finishUpdateRun(run.runId, { status: "failed", reason: "doctor-failed" }, options); + closeOpenClawStateDatabaseForTest(); + const saved = getUpdateRun(run.runId, options)!; + const crash = saved.steps.find((step) => step.step === "candidate-doctor")!; + expect(result).toMatchObject({ status: "error", phase: "doctor" }); + expect(crash).toMatchObject({ exitCode: null, termination: "signal", signal: "SIGTERM" }); + expect(crash.failureFacts?.[0]).toMatchObject({ check: "doctor", code: "signal" }); + expect(crash.detail).toContain("Checking data migrations"); + expect(crash.stderrTail).toContain("FATAL ERROR: synthetic native failure"); + expect(crash.stderrTail).toContain("0: node::sqlite::DatabaseSync::Exec"); + expect(crash.stderrTail).toContain("last native frame"); + expect(crash.stderrTail?.split("\n").length).toBeLessThanOrEqual(80); + expect(crash.stderrTail!.length).toBeLessThanOrEqual(8192); + expect(crash.stderrTail!.length).toBeGreaterThan(4096); + expect(crash.stderrTail).not.toContain("adjacent stdout"); + expect(JSON.stringify(saved)).not.toContain("synthetic-secret"); + const report = renderUpdateRunReport(saved); + expect(report.markdown).toContain("SIGTERM"); + expect(report.markdown).toContain("Checking data migrations"); + expect(report.markdown).toContain("FATAL ERROR: synthetic native failure"); + expect(report.lines.join("\n")).toContain("last native frame"); + const terminal = renderSteps(result.steps); + expect(terminal).toContain("SIGTERM"); + expect(terminal).toContain("FATAL ERROR: synthetic native failure"); + expect(terminal).toContain("last native frame"); + const failure = { ...result, mode: "npm" as const, root, runId: run.runId }; + const artifact = await writeUpdateRunReportArtifact({ + result: failure, + report, + readRun: () => saved, + env: options.env, + }); + const markdown = await fs.readFile(artifact, "utf8"); + expect(markdown).toContain("FATAL ERROR: synthetic native failure"); + expect(markdown).toContain("last native frame"); + expect(markdown).not.toContain("synthetic-secret"); + const publicReport = await prepareUpdateFailureReport( + { attemptId: run.runId, result: { ...failure, steps: [] }, recordedRun: saved }, + options, + ); + expect(publicReport.body).toContain("termination signal (SIGTERM)"); + expect(publicReport.body).toContain("candidate-doctor"); + return; + } const failedExit = mode === "failed-exit" || mode === "signalled-exit"; const step = result.steps.find((candidate) => failedExit ? candidate.name === "candidate-doctor-lint" : candidate.termination === "timeout", @@ -104,7 +190,9 @@ if (args.includes("--fix")) { expect(result, report).toMatchObject({ status: "error", phase: "lint" }); expect(step.exitCode).toBe(mode === "failed-exit" ? 7 : null); expect(step.signal).toBe(mode === "signalled-exit" ? "SIGTERM" : null); - expect(step.failureFacts).toMatchObject([{ check: "lint", code: "doctor-failed" }]); + expect(step.failureFacts).toMatchObject([ + { check: "lint", code: mode === "signalled-exit" ? "signal" : "doctor-failed" }, + ]); expect(step.advisory).toBeUndefined(); expect(step.warnings).not.toContainEqual(expect.stringContaining("exit phase")); } else if (mode === "missing" || mode === "failed") { diff --git a/src/infra/update-candidate-canary.lint.test.ts b/src/infra/update-candidate-canary.lint.test.ts index 2ff6592a0be0..3c249b3c1d12 100644 --- a/src/infra/update-candidate-canary.lint.test.ts +++ b/src/infra/update-candidate-canary.lint.test.ts @@ -363,7 +363,9 @@ describe("update candidate Doctor lint", () => { expect(renderSteps([step])).toContain( physical.outputLimitExceeded && physical.exitCode === 0 ? "Update health check output exceeded the inspection limit" - : "Update health check failed", + : physical.signal + ? `terminated by ${physical.signal}` + : "Update health check failed", ); expect(renderUpdateRunReport(updateRunReportInputFromResult(failure)).markdown).toContain( "Failed: candidate-doctor-lint", diff --git a/src/infra/update-candidate-canary.ts b/src/infra/update-candidate-canary.ts index af91d231b48e..533a83070f93 100644 --- a/src/infra/update-candidate-canary.ts +++ b/src/infra/update-candidate-canary.ts @@ -45,6 +45,7 @@ import { type UpdatePostInstallDoctorResult, } from "./update-doctor-result.js"; import { + createUpdateCanaryFailureFacts, createUpdateFailureFact, parseConfigFailureFacts, type UpdateFailureFact, @@ -344,6 +345,7 @@ export async function validateUpdateCandidateCanary( }, }); let code: number | null = null; + let signal: NodeJS.Signals | null = null; let doctorAdvisory: UpdateStepResult["advisory"]; let doctorReceipt: UpdatePostInstallDoctorResult | null = null; const pluginFailures: UpdateFailureFact[] = []; @@ -356,6 +358,7 @@ export async function validateUpdateCandidateCanary( // Freeze the winning outcome before teardown can make a killed child // emit a successful close event. code = outcome.status === "completed" ? outcome.value : 1; + signal = outcome.status === "completed" ? running.child.signalCode : null; timedOut = outcome.status === "deadline"; if (timedOut) { const elapsed = Date.now() - stepStartedAt; @@ -384,7 +387,7 @@ export async function validateUpdateCandidateCanary( doctorResultPath, doctorResultOptions, ); - if (doctorReceipt?.status === "error") { + if (doctorReceipt?.status === "error" && !signal) { code = 1; } doctorConfigChanges = doctorReceipt?.configChanges ?? []; @@ -419,6 +422,7 @@ export async function validateUpdateCandidateCanary( durationMs: Date.now() - stepStartedAt, exitCode: running.child.exitCode, signal: running.child.signalCode, + stderrTail: signal ? running.stderrTail() : undefined, killed: running.child.killed, termination: timedOut ? "timeout" : running.child.signalCode ? "signal" : "exit", outputLimitExceeded: running.outputExceeded(), @@ -501,7 +505,11 @@ export async function validateUpdateCandidateCanary( cwd: params.root, durationMs: Date.now() - stepStartedAt, exitCode: timedOut ? null : code, - ...(timedOut ? { termination: "timeout" as const } : {}), + ...(timedOut + ? { termination: "timeout" as const } + : signal + ? { termination: "signal" as const, signal, stderrTail: running.stderrTail() } + : {}), }; if (doctorAdvisory) { step.advisory = doctorAdvisory; @@ -528,25 +536,17 @@ export async function validateUpdateCandidateCanary( if (!findings?.length && phase === "config" && !running.outputExceeded()) { findings = parseConfigFailureFacts(running.stdout(), env); } - step.failureFacts = findings?.length - ? findings - : [ - createUpdateFailureFact( - { - check: phase, - code: - timedOut && !exitWarning - ? "candidate-checks-timeout" - : phase === "doctor" || phase === "lint" - ? "doctor-failed" - : `candidate-${phase}-failed`, - message: timedOut - ? failureMessage - : (running.stderrDiagnostic() ?? failureMessage), - }, - env, - ), - ]; + step.failureFacts = createUpdateCanaryFailureFacts({ + phase, + name: command.name, + signal, + timedOut, + exitWarning, + failureMessage, + diagnostic: running.stderrDiagnostic(), + findings, + env, + }); } steps.push(step); if (code !== 0 && !doctorAdvisory) { @@ -687,7 +687,7 @@ export async function validateUpdateCandidateCanary( failed.failureFacts.some( (fact) => failureLine === `${displayPhase}: ${fact.message} (${durationMs}ms)`, ); - failed.stderrTail = stepLogTail.slice(0, repeatsFact ? -1 : undefined).join("\n"); + failed.stderrTail ??= stepLogTail.slice(0, repeatsFact ? -1 : undefined).join("\n"); try { await receipts.onStep?.(failed); } catch (recordingError) { diff --git a/src/infra/update-failure-facts.ts b/src/infra/update-failure-facts.ts index 5cf54c2bed44..2e5b4717725c 100644 --- a/src/infra/update-failure-facts.ts +++ b/src/infra/update-failure-facts.ts @@ -213,6 +213,51 @@ export function normalizeUpdateFailureFacts( return facts.slice(0, 5).map((fact) => createUpdateFailureFact(fact, env)); } +export function createUpdateCanaryFailureFacts(params: { + phase: string; + name: string; + signal: NodeJS.Signals | null; + timedOut: boolean; + exitWarning?: string; + failureMessage: string; + diagnostic?: string; + findings?: UpdateFailureFact[]; + env: NodeJS.ProcessEnv; +}): UpdateFailureFact[] { + const { phase, signal, timedOut, exitWarning, failureMessage, diagnostic, findings, env } = + params; + if (signal) { + return [ + createUpdateFailureFact( + { + check: phase, + code: "signal", + message: `${phase === "doctor" ? "Checking data migrations" : params.name}: terminated by ${signal}`, + }, + env, + ), + ...(findings ?? []).slice(0, 4), + ]; + } + return findings?.length + ? findings + : [ + createUpdateFailureFact( + { + check: phase, + code: + timedOut && !exitWarning + ? "candidate-checks-timeout" + : phase === "doctor" || phase === "lint" + ? "doctor-failed" + : `candidate-${phase}-failed`, + message: timedOut ? failureMessage : (diagnostic ?? failureMessage), + }, + env, + ), + ]; +} + /** Config validation issues are more specific than the CLI's failure envelope. */ export function parseConfigFailureFacts( stdout: string, diff --git a/src/infra/update-failure-report-artifact.ts b/src/infra/update-failure-report-artifact.ts index b1e2feb0004c..9912ae0f2117 100644 --- a/src/infra/update-failure-report-artifact.ts +++ b/src/infra/update-failure-report-artifact.ts @@ -23,9 +23,25 @@ import { renderUpdateRunReport, type UpdateRunReport, } from "./update-run-report.js"; +import { updateRunStepsFromResultStep } from "./update-run-step.js"; import type { UpdateRunResult } from "./update-runner-types.js"; const DOCTOR_LINT_REPORT_SECTION = "\n## Complete Doctor lint findings ("; +const NATIVE_FAILURE_REPORT_SECTION = "\n## Native process diagnostics\n"; + +function nativeFailureDiagnostics(steps: UpdateRunRecord["steps"]): string { + const diagnostics = steps.flatMap((step) => + step.status === "failed" && step.termination === "signal" && step.stderrTail + ? [ + `Check: ${step.step}; termination: signal; signal: ${step.signal ?? "unknown"}\n\n${step.stderrTail + .split("\n") + .map((line) => ` ${line}`) + .join("\n")}`, + ] + : [], + ); + return diagnostics.length ? `${NATIVE_FAILURE_REPORT_SECTION}\n${diagnostics.join("\n\n")}` : ""; +} async function withUpdateReportWrite(outputPath: string, write: () => Promise): Promise { await fs.mkdir(path.dirname(outputPath), { recursive: true, mode: 0o700 }); @@ -68,11 +84,14 @@ export async function refreshUpdateRunReportArtifact( // Preserve the artifact writer's appendix while refreshing only its summary. const appendixStart = previous.indexOf(DOCTOR_LINT_REPORT_SECTION); const appendix = appendixStart < 0 ? "" : `\n${previous.slice(appendixStart)}`; + const native = appendix.includes(NATIVE_FAILURE_REPORT_SECTION) + ? "" + : nativeFailureDiagnostics(run.steps); const report = renderUpdateRunReport(run, { mode: run.target.kind }); await writeTextAtomic( outputPath, redactSupportString( - `${report.markdown}${appendix}`, + `${report.markdown}${appendix}${native}`, { env, stateDir }, { maxLength: Number.MAX_SAFE_INTEGER }, ), @@ -174,10 +193,14 @@ export async function writeUpdateRunReportArtifact(params: { ) : undefined; const findings = params.result.steps.flatMap((step) => step.doctorLintFindings ?? []); + const native = nativeFailureDiagnostics( + run?.steps ?? params.result.steps.flatMap(updateRunStepsFromResultStep), + ); const body = [ report.markdown, `${DOCTOR_LINT_REPORT_SECTION}${findings.length})\n`, ...findings.map((finding) => `- ${formatUpdateDoctorLintFinding(finding, env)}`), + ...(native ? [native] : []), failurePath ? `\nBounded diagnostic JSON: ${path.relative(directory, failurePath)}` : "", ].join("\n"); await writeTextAtomic( diff --git a/src/infra/update-failure-report-prepare.ts b/src/infra/update-failure-report-prepare.ts index ea3159a87061..6f61aeb26d5e 100644 --- a/src/infra/update-failure-report-prepare.ts +++ b/src/infra/update-failure-report-prepare.ts @@ -1,5 +1,6 @@ /** Sanitizes and prepares one explicitly reviewed update-failure report. */ import { isIP } from "node:net"; +import { constants } from "node:os"; import path from "node:path"; import { valid as validSemver } from "semver"; import { resolveStateDir } from "../config/paths.js"; @@ -129,7 +130,7 @@ function sanitizeFactIdentifier(value: string, context: UpdateFailureReportConte type ReportedFailedStep = Pick< UpdateStepResult, "name" | "exitCode" | "termination" | "failureFacts" | "stderrTail" -> & { detail?: string }; +> & { detail?: string; signal?: string | null }; function resolveFailedSteps(input: UpdateFailureReportInput): ReportedFailedStep[] { const direct = new Map(input.result.steps.map((step) => [updateRunStepKey(step.name), step])); @@ -154,6 +155,9 @@ function resolveFailedSteps(input: UpdateFailureReportInput): ReportedFailedStep exitCode: step.exitCode ?? null, failureFacts: step.failureFacts, detail: step.detail, + termination: step.termination, + signal: step.signal, + stderrTail: step.stderrTail, }, ] : []; @@ -279,7 +283,11 @@ async function renderBoundedDiagnostics( } for (const step of selectUpdateFailureReportSteps(steps)) { const phase = sanitizeFactIdentifier(step.name, context); - const termination = step.termination ? `, termination ${step.termination}` : ""; + const signal = + step.signal && Object.hasOwn(constants.signals, step.signal) ? step.signal : null; + const termination = step.termination + ? `, termination ${step.termination}${signal ? ` (${signal})` : ""}` + : ""; const message = [ ...(step.failureFacts ?? []).flatMap((fact) => [fact.message, fact.code]), step.detail, diff --git a/src/infra/update-run-codec.ts b/src/infra/update-run-codec.ts index 364ef8905b3b..488eee9e0078 100644 --- a/src/infra/update-run-codec.ts +++ b/src/infra/update-run-codec.ts @@ -96,7 +96,9 @@ export function isRetainedStep(item: unknown): boolean { return ( isRecord(item) && typeof item.step === "string" && - (item.step.startsWith("finalize:") || RETAINED_STEP_NAMES.some((name) => name === item.step)) + (item.termination === "signal" || + item.step.startsWith("finalize:") || + RETAINED_STEP_NAMES.some((name) => name === item.step)) ); } @@ -117,6 +119,7 @@ function boundedJson( // Recovery details are the durable backup receipt, not optional diagnostics. const compacted = value.map((item) => isRecord(item) && + item.termination !== "signal" && item.step !== "task-delivery-recovery" && item.step !== "diagnostic:database snapshot" && item.step !== "diagnostic:database migration writes" && @@ -126,9 +129,23 @@ function boundedJson( : item, ); if (JSON.stringify(compacted) === json) { - throw new Error("Update run retained step metadata exceeds its byte limit"); + // Native output is diagnostic, never a reason to refuse a recovery receipt. + const item = value.findLast( + (entry): entry is Record & { stderrTail: string } => + isRecord(entry) && + typeof entry.stderrTail === "string" && + entry.stderrTail.length > 0, + ); + if (!item) { + throw new Error("Update run retained step metadata exceeds its byte limit"); + } + value = value.with(value.indexOf(item), { + ...item, + stderrTail: truncateUtf16Safe(item.stderrTail, Math.floor(item.stderrTail.length / 2)), + }); + } else { + value = compacted; } - value = compacted; } } else if (isRecord(value)) { const object = value; @@ -259,12 +276,12 @@ export function encodeRun(input: UpdateRunRecord, options: UpdateRunLedgerOption : {}), })), }, - (value) => { + (value, key) => { let text = redactSensitiveText(value, { mode: "tools" }); for (const [pattern, replacement] of redactPaths) { text = text.replace(pattern, () => replacement); } - return truncateUtf16Safe(text, UPDATE_RUN_TEXT_LIMIT); + return truncateUtf16Safe(text, key === "stderrTail" ? 8192 : UPDATE_RUN_TEXT_LIMIT); }, ), ); diff --git a/src/infra/update-run-record.ts b/src/infra/update-run-record.ts index 72ed1831357b..fb53af2e45e8 100644 --- a/src/infra/update-run-record.ts +++ b/src/infra/update-run-record.ts @@ -53,7 +53,7 @@ export function updateStepDiagnostics( export function summarizeUpdateStepFailure( step: Pick< UpdateStepResult, - "name" | "exitCode" | "termination" | "stdoutTail" | "stderrTail" | "failureFacts" + "name" | "exitCode" | "termination" | "signal" | "stdoutTail" | "stderrTail" | "failureFacts" >, ): string { const diagnostics = updateStepDiagnostics(step); @@ -86,7 +86,12 @@ export function summarizeUpdateStepFailure( return [truncateUtf16Safe(causeOnly, 120 - outcome.length - 2), outcome].join("; "); }); return truncateUtf16Safe( - [step.termination ?? `Exit code: ${step.exitCode ?? "unknown"}`, ...excerpts] + [ + step.termination === "signal" + ? `signal: ${step.signal ?? "unknown"}` + : (step.termination ?? `Exit code: ${step.exitCode ?? "unknown"}`), + ...excerpts, + ] .filter(Boolean) .join("; "), 300, diff --git a/src/infra/update-run-report.ts b/src/infra/update-run-report.ts index 77564645dbfe..418049d628e9 100644 --- a/src/infra/update-run-report.ts +++ b/src/infra/update-run-report.ts @@ -333,6 +333,9 @@ export function renderUpdateRunReport( )) { const failure = `Failed: ${step.step}${step.detail ? ` — ${step.detail}` : ""}`; lines.push(bounded(failure, 300)); + if (step.termination === "signal" && step.stderrTail) { + lines.push(`Stderr (${step.signal ?? "unknown signal"}):\n${step.stderrTail}`); + } lines.push( ...(step.failureFacts ?? []).slice(0, 5).map((fact) => formatUpdateFailureFact({ diff --git a/src/infra/update-run-schema.ts b/src/infra/update-run-schema.ts index 50ee14e1b8e4..1a7e27878640 100644 --- a/src/infra/update-run-schema.ts +++ b/src/infra/update-run-schema.ts @@ -188,6 +188,9 @@ const UpdateRunStepSchema = z.object({ startedAtMs: timestamp.optional(), endedAtMs: timestamp.optional(), exitCode: z.number().int().nullable().optional(), + termination: z.enum(["exit", "timeout", "no-output-timeout", "signal"]).optional(), + signal: z.string().max(32).nullable().optional(), + stderrTail: z.string().max(8192).optional(), detail: text.optional(), failureFacts: z.array(UpdateFailureFactSchema).max(5).optional(), configChange: z diff --git a/src/infra/update-run-step.ts b/src/infra/update-run-step.ts index ae453b02b787..87f098de9587 100644 --- a/src/infra/update-run-step.ts +++ b/src/infra/update-run-step.ts @@ -90,6 +90,12 @@ export function updateRunStepsFromResultStep(step: ResultStep): UpdateRunStep[] step: text(step.name), status: failed ? "failed" : "completed", exitCode: step.exitCode, + termination: step.termination, + signal: step.signal, + stderrTail: + failed && step.termination === "signal" && step.stderrTail + ? truncateUtf16Safe(step.stderrTail, 8192) + : undefined, // A completed retry replaces diagnostics from the previous attempt with the same ID. failureFacts: step.failureFacts?.length && !step.advisory ? step.failureFacts.slice(0, 5) : undefined,