From 1fa3f89e1e7c06ce7e5a17aa49581f19ab0a9c3b Mon Sep 17 00:00:00 2001 From: Sawyer Cutler Date: Wed, 14 Oct 2026 13:03:40 -0700 Subject: [PATCH 1/2] refactor(logging): collapse double-log storms, fix levels, correlate ids MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Second-layer duplicates (store settlement, submit sent-append) collapse to single entries; per-field trust warn storms become one summary warn, with a per-file error shape on the migration result. Mis-leveled errors demote to warn; warn churn during teardown demotes to debug. caughtDebug is the single append-failure helper for persist/teardown catches. The exec/exit error paths it guards carry sessionId from where the id is already in scope; the MCP late-connect/retry warns name the server. The collapsed per-entry absolute resolution uses an explicit lambda (paths.map((p) => resolve(p))) so map's (value, index, array) triple can never reach path.resolve — avoiding the plan draft's would-crash shape (probe-verified: restoring bare .map(resolve) fails the trust store suite with ERR_INVALID_ARG_TYPE). The parent commit always had the safe per-entry loop; nothing here fixes a shipped crash. The migration's one-summary-warn contract is pinned by a log-capture test listing each skipped store. --- src/cost/pricing-fetcher.ts | 4 +- src/cost/pricing-metadata.ts | 11 +-- src/exec/dispose.ts | 17 ++-- src/exec/runner.ts | 88 +++++++++++-------- src/logging/caught.test.ts | 39 ++++++++ src/logging/caught.ts | 17 ++++ src/perf/otel-sink.ts | 4 +- .../approval-store-migration.test.ts | 51 +++++++++++ src/permission/approval-store-migration.ts | 33 ++++--- src/session/runtime-assembly.ts | 9 +- src/session/summarizer.ts | 4 +- src/subagent/agent-fleet.ts | 2 +- src/subagent/session-store.ts | 4 - src/trust/path-trust.ts | 35 ++++---- src/trust/project-trust.ts | 39 +++++--- src/tui/runner/exit.ts | 64 ++++++-------- src/tui/runner/index.ts | 1 + src/tui/runner/mcp.ts | 6 +- src/tui/runner/settings.ts | 57 +++--------- src/tui/runner/submit.ts | 19 ++-- 20 files changed, 303 insertions(+), 201 deletions(-) create mode 100644 src/logging/caught.test.ts create mode 100644 src/logging/caught.ts diff --git a/src/cost/pricing-fetcher.ts b/src/cost/pricing-fetcher.ts index 3a06a7a12..c10fcb4b0 100644 --- a/src/cost/pricing-fetcher.ts +++ b/src/cost/pricing-fetcher.ts @@ -306,9 +306,7 @@ export function startPricingRefresh( const refreshIntervalMs = options.refreshIntervalMs ?? DEFAULT_REFRESH_INTERVAL_MS; const timer = setInterval(() => { - loadPricing(options).catch((err: unknown) => { - process.stderr.write(`pricing-fetcher: refresh error: ${err}\n`); - }); + void loadPricing(options); }, refreshIntervalMs); return timer; } diff --git a/src/cost/pricing-metadata.ts b/src/cost/pricing-metadata.ts index 00d42d103..e06fa6313 100644 --- a/src/cost/pricing-metadata.ts +++ b/src/cost/pricing-metadata.ts @@ -29,14 +29,9 @@ export function schedulePricingMetadataRefresh( ): void { if (refreshScheduled) return; refreshScheduled = true; - void loadPricing(options) - .then((cache) => { - if (cache !== null) applyPricingCacheMetadata(cache); - }) - .catch((err: unknown) => { - // Match pricing-fetcher: keep refresh best-effort, surface the failure. - process.stderr.write(`pricing-metadata: refresh error: ${err}\n`); - }); + void loadPricing(options).then((cache) => { + if (cache !== null) applyPricingCacheMetadata(cache); + }); } export async function bootstrapPricingMetadata( diff --git a/src/exec/dispose.ts b/src/exec/dispose.ts index 53e897a35..9ef1f0085 100644 --- a/src/exec/dispose.ts +++ b/src/exec/dispose.ts @@ -1,6 +1,7 @@ import { getLogger } from "@intx/log"; import { LOG_NAMESPACE_ROOT } from "../branding.js"; +import { caughtDebug } from "../logging/caught.js"; import { awaitCloseWithoutHidingLeftover } from "../subagent/dispose.js"; import type { SubAgentSessionStore } from "../subagent/index.js"; @@ -59,9 +60,11 @@ async function runExecDispose(args: { try { await args.toolset.dispose(); } catch (err: unknown) { - logger.debug("toolset.dispose during exec finally failed: {error}", { - error: (args.sanitizeDiagnostic ?? String)(formatCaughtError(err)), - }); + caughtDebug( + logger, + "toolset.dispose during exec finally failed", + args.sanitizeDiagnostic, + )(err); failures.push(err); } } @@ -74,9 +77,11 @@ async function runExecDispose(args: { try { await awaitCloseWithoutHidingLeftover(args.agent.close(), failures[0]); } catch (err: unknown) { - logger.debug("agent.close during exec finally failed: {error}", { - error: (args.sanitizeDiagnostic ?? String)(formatCaughtError(err)), - }); + caughtDebug( + logger, + "agent.close during exec finally failed", + args.sanitizeDiagnostic, + )(err); failures.push(err); } } diff --git a/src/exec/runner.ts b/src/exec/runner.ts index 1f1417dcf..26aa22d58 100644 --- a/src/exec/runner.ts +++ b/src/exec/runner.ts @@ -42,6 +42,7 @@ import { } from "../subagent/index.js"; import { getProcessAdmissionQueue } from "../subagent/admission.js"; import { disposeExecRuntime, formatCaughtError } from "./dispose.js"; +import { caughtDebug } from "../logging/caught.js"; import { EXEC_MCP_CONNECT_WAIT_MS, EXEC_MCP_HANDSHAKE_TIMEOUT_MS, @@ -468,7 +469,10 @@ export async function runExec(config: Config): Promise { priorState = prior?.kind === "ok" ? prior.state : undefined; } catch (err) { const message = formatCaughtError(err); - logger.error("exec setup failed: {error}", { error: message }); + logger.error("exec setup failed: {error}", { + sessionId, + error: message, + }); stderr.write(`Error: ${message}\n`); liveTelemetry.capture( "session_end", @@ -598,11 +602,13 @@ export async function runExec(config: Config): Promise { try { // Pricing seed is optional for exec; continue without rates. - const inferenceDeps = await assembleInferenceBase((err: unknown) => { - logger.debug("seedPricingMetadataFromCache failed: {error}", { - error: sanitizeExecDiagnostic(formatCaughtError(err)), - }); - }); + const inferenceDeps = await assembleInferenceBase( + caughtDebug( + logger, + "seedPricingMetadataFromCache failed", + sanitizeExecDiagnostic, + ), + ); // One-shot migration only when the path-trust file is absent. Headless // exec has no frame to corrupt, so skipped members write straight to stderr. @@ -1217,22 +1223,22 @@ export async function runExec(config: Config): Promise { // entry and would write the whole reply as a spurious partial. // Dispose is a no-op on success and a real record only if a cycle // died without a terminal event. - await activeAgent.close().catch((err: unknown) => { - logger.debug( - "agent.close during successful-send teardown failed: {error}", - { - error: sanitizeExecDiagnostic(formatCaughtError(err)), - }, - ); - }); - await streamPromise.catch((err: unknown) => { - logger.debug( - "stream drain during successful-send teardown failed: {error}", - { - error: sanitizeExecDiagnostic(formatCaughtError(err)), - }, + await activeAgent + .close() + .catch( + caughtDebug( + logger, + "agent.close during successful-send teardown failed", + sanitizeExecDiagnostic, + ), ); - }); + await streamPromise.catch( + caughtDebug( + logger, + "stream drain during successful-send teardown failed", + sanitizeExecDiagnostic, + ), + ); await cycleRecorder.dispose("cancelled"); } else { // Failed or aborted send: close() tears down stream consumers before @@ -1241,22 +1247,22 @@ export async function runExec(config: Config): Promise { await cycleRecorder.dispose( sendCompleted ? "cancelled" : "send-failed", ); - await activeAgent.close().catch((err: unknown) => { - logger.debug( - "agent.close during failed-send teardown failed: {error}", - { - error: sanitizeExecDiagnostic(formatCaughtError(err)), - }, - ); - }); - await streamPromise.catch((err: unknown) => { - logger.debug( - "stream drain during failed-send teardown failed: {error}", - { - error: sanitizeExecDiagnostic(formatCaughtError(err)), - }, + await activeAgent + .close() + .catch( + caughtDebug( + logger, + "agent.close during failed-send teardown failed", + sanitizeExecDiagnostic, + ), ); - }); + await streamPromise.catch( + caughtDebug( + logger, + "stream drain during failed-send teardown failed", + sanitizeExecDiagnostic, + ), + ); } } @@ -1350,7 +1356,10 @@ export async function runExec(config: Config): Promise { return result; } catch (err) { const diagnosticMessage = sanitizeExecDiagnostic(formatCaughtError(err)); - logger.error("exec failed: {error}", { error: diagnosticMessage }); + logger.error("exec failed: {error}", { + sessionId, + error: diagnosticMessage, + }); const userMessage = sanitizeExecDiagnostic( execUserFailureMessage( config, @@ -1391,7 +1400,10 @@ export async function runExec(config: Config): Promise { }); } catch (err: unknown) { const message = sanitizeExecDiagnostic(formatCaughtError(err)); - logger.error("runtime dispose failed: {error}", { error: message }); + logger.error("runtime dispose failed: {error}", { + sessionId, + error: message, + }); stderr.write(`Error: runtime dispose failed: ${message}\n`); if (result !== undefined) { result.exitCode = 1; diff --git a/src/logging/caught.test.ts b/src/logging/caught.test.ts new file mode 100644 index 000000000..c44cd69ee --- /dev/null +++ b/src/logging/caught.test.ts @@ -0,0 +1,39 @@ +import { describe, expect, test } from "bun:test"; + +import { caughtDebug } from "./caught.js"; + +// @intx/log renders the {error} template at sink level, so capture both the +// message template and the properties to pin the normalization-and-append +// contract. +describe("caughtDebug", () => { + interface Capture { + message: string; + properties: Record | undefined; + } + const capture = { + debug: (message: string, properties?: Record) => { + capture.last = { message, properties }; + }, + last: undefined as Capture | undefined, + }; + + test("Error values feed {error} from .message", () => { + caughtDebug(capture, "teardown failed")(new Error("boom")); + expect(capture.last?.message).toBe("teardown failed: {error}"); + expect(capture.last?.properties).toEqual({ error: "boom" }); + }); + + test("non-Error values are String()ed", () => { + caughtDebug(capture, "teardown failed")("boom-string"); + expect(capture.last?.properties).toEqual({ error: "boom-string" }); + }); + + test("a sanitizer runs on the normalized error message", () => { + caughtDebug(capture, "teardown failed", (error) => + error.replaceAll("secret", "[redacted]"), + )(new Error("secret leaked")); + expect(capture.last?.properties).toEqual({ + error: "[redacted] leaked", + }); + }); +}); diff --git a/src/logging/caught.ts b/src/logging/caught.ts new file mode 100644 index 000000000..3ffb687ad --- /dev/null +++ b/src/logging/caught.ts @@ -0,0 +1,17 @@ +// Shared hunter for the "best-effort step failed" debug catch: callers keep +// their message; the helper owns the caught-value normalization-and-append +// shape so that boilerplate exists once, not per site. +interface DebugSink { + debug: (message: string, properties?: Record) => void; +} + +export function caughtDebug( + logger: DebugSink, + message: string, + sanitize?: (error: string) => string, +): (err: unknown) => void { + return (err) => { + const error = err instanceof Error ? err.message : String(err); + logger.debug(`${message}: {error}`, { error: (sanitize ?? String)(error) }); + }; +} diff --git a/src/perf/otel-sink.ts b/src/perf/otel-sink.ts index af502fdb1..d36ec7ca3 100644 --- a/src/perf/otel-sink.ts +++ b/src/perf/otel-sink.ts @@ -270,7 +270,9 @@ export async function flushPerfToOtel( try { const resolved = resolveOtelExportConfig(settings, env); if (!resolved.ok) { - log.warn("OTEL export skipped: {message}", { message: resolved.message }); + log.debug("OTEL export skipped: {message}", { + message: resolved.message, + }); return; } config = resolved.config; diff --git a/src/permission/approval-store-migration.test.ts b/src/permission/approval-store-migration.test.ts index 582f1319a..be7fe1c0b 100644 --- a/src/permission/approval-store-migration.test.ts +++ b/src/permission/approval-store-migration.test.ts @@ -9,6 +9,7 @@ import { } from "node:fs/promises"; import { tmpdir } from "node:os"; import { dirname, join } from "node:path"; +import { installFileLogSink } from "../logging/sink.js"; import { generateSessionId, sessionDir } from "../session/index.js"; import { loadSeededApprovals } from "../session/runtime-assembly.js"; import { normalizeSeededApprovals } from "./authz-grants.js"; @@ -297,6 +298,56 @@ describe("migratePersistedApprovalStores", () => { } }); + test("per-file migration failures surface once as a single summary warn", async () => { + const logDir = await mkdtemp(join(tmpdir(), "approval-migration-log-")); + installFileLogSink(join(logDir, "corbits.log")); + const sessionOriginal = { + approvals: [ + { tool: "update_plan", pattern: "plan *" }, + { tool: "run_shell", pattern: "npm *" }, + ], + }; + await writeFile(sessionStorePath(), JSON.stringify(sessionOriginal)); + await mkdir(join(cwd, ".corbits"), { recursive: true }); + await writeFile( + projectStorePath(), + JSON.stringify({ + approvals: [{ tool: "update_plan", pattern: "plan *" }], + }), + ); + // Read-only store dirs make the backup step fail, so both stores skip + // untouched while the global path (absent) stays a clean no-op. + const sessionStoreDir = dirname(sessionStorePath()); + const projectStoreDir = join(cwd, ".corbits"); + await chmod(sessionStoreDir, 0o555); + await chmod(projectStoreDir, 0o555); + try { + const result = await migratePersistedApprovalStores(cwd, sessionId, home); + expect(result.purged).toBe(0); + const failed = result.files.filter((file) => file.error !== undefined); + expect(failed).toHaveLength(2); + for (const file of failed) { + expect(file.error).toContain("backup failed"); + expect(file.purged).toBe(0); + } + + const lines = (await readFile(join(logDir, "corbits.log"), "utf8")) + .split("\n") + .filter((line) => line.includes("Skipped approval-store migration")); + // One summary warn for the whole migration, not one per failing store. + expect(lines).toHaveLength(1); + const summary = lines[0]; + if (summary === undefined) throw new Error("summary warn missing"); + expect(summary).toMatch(/"level":"warning"/); + expect(summary).toContain(sessionStorePath()); + expect(summary).toContain(projectStorePath()); + } finally { + await chmod(sessionStoreDir, 0o755); + await chmod(projectStoreDir, 0o755); + await rm(logDir, { recursive: true, force: true }); + } + }); + test("existing torn .bak plus live update_plan still purges live", async () => { const path = sessionStorePath(); const original = { diff --git a/src/permission/approval-store-migration.ts b/src/permission/approval-store-migration.ts index 7541472fa..4d7fc6911 100644 --- a/src/permission/approval-store-migration.ts +++ b/src/permission/approval-store-migration.ts @@ -5,6 +5,7 @@ import { join } from "node:path"; import { getLogger } from "@intx/log"; import { canonicalGrantTool } from "../agent/canonical-tool-name.js"; +import { errorMessage } from "../agent/error-message.js"; import { LOG_NAMESPACE_ROOT, SETTINGS_DIR_NAME } from "../branding.js"; import { sessionDir } from "../session/index.js"; import { chainObjectWrite } from "./store.js"; @@ -15,6 +16,8 @@ export interface ApprovalStoreMigrationFileResult { path: string; purged: number; backupPath?: string | undefined; + /** Why the file was skipped untouched (absent when migration ran). */ + error?: string | undefined; } export interface ApprovalStoreMigrationResult { @@ -101,6 +104,7 @@ export async function migrateApprovalStoreFile( const backupPath = `${path}.bak`; let purged = 0; let rewrote = false; + let skipped: string | undefined; try { await chainObjectWrite(path, async (current) => { const next: Record = { ...current }; @@ -139,10 +143,7 @@ export async function migrateApprovalStoreFile( ); } catch (err) { if (!isFileExistsError(err)) { - log.warn("Skipping approval-store migration for {path}: {error}", { - path, - error: err instanceof Error ? err.message : String(err), - }); + skipped = `backup failed: ${errorMessage(err)}`; return undefined; } } @@ -151,11 +152,14 @@ export async function migrateApprovalStoreFile( return next; }); } catch (err) { - log.warn("Skipping approval-store migration for {path}: {error}", { + return { path, - error: err instanceof Error ? err.message : String(err), - }); - return { path, purged: 0 }; + purged: 0, + error: `rewrite failed: ${errorMessage(err)}`, + }; + } + if (skipped !== undefined) { + return { path, purged: 0, error: skipped }; } if (!rewrote) return { path, purged: 0 }; return { path, purged, backupPath }; @@ -181,13 +185,20 @@ export async function migratePersistedApprovalStores( try { files.push(await migrateApprovalStoreFile(path)); } catch (err) { - log.warn("Skipping approval-store migration for {path}: {error}", { + files.push({ path, - error: err instanceof Error ? err.message : String(err), + purged: 0, + error: errorMessage(err), }); - files.push({ path, purged: 0 }); } } + // One summary warn per migration, not one per store file. + const failed = files.filter((file) => file.error !== undefined); + if (failed.length > 0) { + log.warn("Skipped approval-store migration: {details}", { + details: failed.map((file) => `${file.path}: ${file.error}`).join("; "), + }); + } return { purged: files.reduce((total, file) => total + file.purged, 0), backups: files.flatMap((file) => diff --git a/src/session/runtime-assembly.ts b/src/session/runtime-assembly.ts index fceab617b..4b4a85be3 100644 --- a/src/session/runtime-assembly.ts +++ b/src/session/runtime-assembly.ts @@ -144,13 +144,12 @@ export async function loadSeededApprovals( ): Promise { // One-time migration: purge persisted update_plan keys (dropped at load but // never rewritten) so removing the normalizer later cannot resurrect them. - // Best-effort and guarded so a throw cannot break session start. + // The migration reports its own per-file failures; this guard only keeps a + // residual throw from breaking session start. try { await migratePersistedApprovalStores(cwd, sessionId, home); - } catch (err) { - persistLogger.warn("Skipping approval-store migration: {error}", { - error: err instanceof Error ? err.message : String(err), - }); + } catch { + // Swallowed on purpose: the migration already surfaced the cause. } const sessionApprovals = await loadApprovals(cwd, sessionId, home); const [ diff --git a/src/session/summarizer.ts b/src/session/summarizer.ts index 635a23fbf..7cbc0f4f2 100644 --- a/src/session/summarizer.ts +++ b/src/session/summarizer.ts @@ -509,7 +509,7 @@ export function createModelSummarizer( failureClass === "provider"; if (retryable && !retried.has(failureClass)) { retried.add(failureClass); - logger.warn( + logger.debug( "compaction summary call failed ({class}); retrying once: {error}", { class: failureClass, error: err.message }, ); @@ -517,7 +517,7 @@ export function createModelSummarizer( try { await options.refreshAuth?.(); } catch (refreshError) { - logger.warn( + logger.debug( "credential re-read after summary auth failure failed: {error}", { error: diff --git a/src/subagent/agent-fleet.ts b/src/subagent/agent-fleet.ts index 9269c8139..9e099530f 100644 --- a/src/subagent/agent-fleet.ts +++ b/src/subagent/agent-fleet.ts @@ -1502,7 +1502,7 @@ export function createSpawnAgentTool(deps: AgentFleetDeps): AgentTool { : {}), }); } catch (err: unknown) { - log.error("spawn_agent worktree cleanup failed: {error}", { + log.warn("spawn_agent worktree cleanup failed: {error}", { error: errorMessage(err), }); } diff --git a/src/subagent/session-store.ts b/src/subagent/session-store.ts index ad9fec28a..121183d2e 100644 --- a/src/subagent/session-store.ts +++ b/src/subagent/session-store.ts @@ -1289,10 +1289,6 @@ export function createSubAgentSessionStore( } endFollowupTurn(id, failLifecycle); pendingFailures.delete(id); - log.error("followup turn failed for {id}: {error}", { - id, - error: errorMessage(err), - }); }; const queueFollowupTurn = ( id: string, diff --git a/src/trust/path-trust.ts b/src/trust/path-trust.ts index 025d98fea..7fef3ae9d 100644 --- a/src/trust/path-trust.ts +++ b/src/trust/path-trust.ts @@ -59,15 +59,19 @@ export async function readPathTrustStore( } // Grants are recorded absolute (see requireAbsolute); a relative entry // would bind to process.cwd(), so drop it here. - const paths: string[] = []; - for (const p of validated.trustedPluginPaths) { - if (!isAbsolute(p)) { - logger.warn`ignoring non-absolute path trust entry: ${p}`; - continue; - } - paths.push(resolve(p)); + let nonAbsolute = 0; + const paths = validated.trustedPluginPaths.filter((p) => { + if (isAbsolute(p)) return true; + nonAbsolute += 1; + return false; + }); + if (nonAbsolute > 0) { + logger.warn`path trust store at ${path} dropping ${nonAbsolute} non-absolute entries`; } - return { state: "valid", store: { trustedPluginPaths: paths } }; + return { + state: "valid", + store: { trustedPluginPaths: paths.map((p) => resolve(p)) }, + }; } export async function loadPathTrust( @@ -205,13 +209,14 @@ export async function migratePathTrustFromPluginPaths( } // A relative pluginPaths entry would bind to the launch cwd permanently; // drop it, matching readPathTrustStore on load. - const absolutePaths: string[] = []; - for (const p of pluginPaths) { - if (!isAbsolute(p)) { - logger.warn`skipping relative pluginPaths entry during path-trust migration: ${p}`; - continue; - } - absolutePaths.push(p); + let nonAbsolute = 0; + const absolutePaths = pluginPaths.filter((p) => { + if (isAbsolute(p)) return true; + nonAbsolute += 1; + return false; + }); + if (nonAbsolute > 0) { + logger.warn`skipping ${nonAbsolute} relative pluginPaths entries during path-trust migration`; } const members: string[] = []; for (const p of absolutePaths) { diff --git a/src/trust/project-trust.ts b/src/trust/project-trust.ts index 7d7798bfc..e887d2c14 100644 --- a/src/trust/project-trust.ts +++ b/src/trust/project-trust.ts @@ -52,15 +52,16 @@ const emptyStore = (): ProjectTrustStore => ({ /** * Extract a schema-confirmed array field: missing → [], non-strings dropped. - * Hand-edited partial files must not wipe consent. + * Hand-edited partial files must not wipe consent. Issues accumulate on + * `issues` for the caller's one summary warn per store. */ function extractStringArrayField( value: unknown[] | undefined, field: string, - path: string, + issues: string[], ): string[] { if (value === undefined) { - logger.warn`project trust store missing ${field} at ${path}; defaulting to []`; + issues.push(`${field}: missing, defaulting to []`); return []; } const strings: string[] = []; @@ -73,7 +74,7 @@ function extractStringArrayField( } } if (dropped > 0) { - logger.warn`project trust store dropping ${dropped} non-string entr${dropped === 1 ? "y" : "ies"} from ${field} at ${path}`; + issues.push(`${field}: dropped ${dropped} non-string entries`); } return strings; } @@ -146,20 +147,23 @@ export async function readProjectTrustStore( logger.warn`project trust store has an invalid shape at ${path}: ${validated.summary}`; return { state: "invalid", store: emptyStore() }; } + // Field/entry issues collect; the store gets one summary warn, not one + // per field or entry. + const issues: string[] = []; const trustedPluginPaths = extractStringArrayField( validated.trustedPluginPaths, "trustedPluginPaths", - path, + issues, ); const trustedMcpFingerprints = extractStringArrayField( validated.trustedMcpFingerprints, "trustedMcpFingerprints", - path, + issues, ); const trustedGrantFingerprints = extractStringArrayField( validated.trustedGrantFingerprints, "trustedGrantFingerprints", - path, + issues, ); // Reject a record keyed to another repo: the file stores its repo and it // must match this cwd. A missing or non-string `repo` is invalid too, or a @@ -176,18 +180,27 @@ export async function readProjectTrustStore( // Grants are recorded absolute (see resolveAgainstProjectCwd); a relative // entry would bind to process.cwd() — the confused-cwd bug path-trust.ts // guards against. Drop it. - const absolutePluginPaths: string[] = []; - for (const p of trustedPluginPaths) { + let nonAbsolute = 0; + const absolutePluginPaths = trustedPluginPaths.filter((p) => { if (!isAbsolute(p)) { - logger.warn`project trust store dropping non-absolute trustedPluginPaths entry at ${path}: ${p}`; - continue; + nonAbsolute += 1; + return false; } - absolutePluginPaths.push(resolve(p)); + return true; + }); + if (nonAbsolute > 0) { + issues.push( + `trustedPluginPaths: dropped ${nonAbsolute} non-absolute entries`, + ); + } + // One summary warn per store, not one warn per field or per entry. + if (issues.length > 0) { + logger.warn`project trust store issues at ${path} (${issues.length}): ${issues.join("; ")}`; } return { state: "valid", store: { - trustedPluginPaths: absolutePluginPaths, + trustedPluginPaths: absolutePluginPaths.map((p) => resolve(p)), trustedMcpFingerprints: [...trustedMcpFingerprints], trustedGrantFingerprints: [...trustedGrantFingerprints], }, diff --git a/src/tui/runner/exit.ts b/src/tui/runner/exit.ts index a05e221ce..a8bf7f6ef 100644 --- a/src/tui/runner/exit.ts +++ b/src/tui/runner/exit.ts @@ -63,6 +63,7 @@ import { type SnapshotStatus, } from "./state.js"; import { handleChatDirectorEvent } from "../../agent/chat-event-subscribers.js"; +import { caughtDebug } from "../../logging/caught.js"; const tuiLogger = getLogger([LOG_NAMESPACE_ROOT, "tui"]); @@ -136,9 +137,10 @@ export async function closeAgentForRebuild( await agent.close(); return true; } catch (err) { - tuiLogger.debug(`agent.close during ${context} teardown failed: {error}`, { - error: err instanceof Error ? err.message : String(err), - }); + caughtDebug( + tuiLogger, + `agent.close during ${context} teardown failed`, + )(err); return false; } } @@ -440,14 +442,9 @@ export async function createRunLifecycle( try { const old = liveAgent(state); const closedCleanly = await closeAgentForRebuild(old, "reload"); - await state.streamPromise?.catch((err: unknown) => { - tuiLogger.debug( - "stream drain during reload teardown failed: {error}", - { - error: err instanceof Error ? err.message : String(err), - }, - ); - }); + await state.streamPromise?.catch( + caughtDebug(tuiLogger, "stream drain during reload teardown failed"), + ); if (!closedCleanly) { throw new AgentContextLockError(state.workdir); } @@ -595,14 +592,12 @@ export async function createRunLifecycle( liveAgent(state), "interrupt", ); - await state.streamPromise?.catch((err: unknown) => { - tuiLogger.debug( - "stream drain during interrupt teardown failed: {error}", - { - error: err instanceof Error ? err.message : String(err), - }, - ); - }); + await state.streamPromise?.catch( + caughtDebug( + tuiLogger, + "stream drain during interrupt teardown failed", + ), + ); if (!closedCleanly) { throw new AgentContextLockError(state.workdir); } @@ -656,22 +651,18 @@ export async function createRunLifecycle( // targets the new, unlocked directory (see closeAgentForRebuild). await liveAgent(state) .close() - .catch((err: unknown) => { - tuiLogger.debug( - "agent.close during session-rotation teardown failed: {error}", - { - error: err instanceof Error ? err.message : String(err), - }, - ); - }); - await state.streamPromise?.catch((err: unknown) => { - tuiLogger.debug( - "stream drain during session-rotation teardown failed: {error}", - { - error: err instanceof Error ? err.message : String(err), - }, + .catch( + caughtDebug( + tuiLogger, + "agent.close during session-rotation teardown failed", + ), ); - }); + await state.streamPromise?.catch( + caughtDebug( + tuiLogger, + "stream drain during session-rotation teardown failed", + ), + ); await persistRunSnapshot( "done", { finishedAt: Date.now() }, @@ -767,6 +758,7 @@ export async function finalizeTUIRun( } catch (err) { teardownFailed = true; tuiLogger.error("runtime shutdown failed: {error}", { + sessionId: state.sessionId, error: err instanceof Error ? err.message : String(err), }); } @@ -838,9 +830,7 @@ export async function finalizeTUIRun( try { await state.streamPromise; } catch (err: unknown) { - tuiLogger.debug("stream promise rejected during exit: {error}", { - error: err instanceof Error ? err.message : String(err), - }); + caughtDebug(tuiLogger, "stream promise rejected during exit")(err); } // Last word on the restored terminal: every normal quit (exit/quit command, diff --git a/src/tui/runner/index.ts b/src/tui/runner/index.ts index cf8789005..b6a40ea2d 100644 --- a/src/tui/runner/index.ts +++ b/src/tui/runner/index.ts @@ -302,6 +302,7 @@ export async function runTUI(initialConfig: Config): Promise { await start.crashGuard.invokeDisposeHost(); } catch (disposeErr: unknown) { tuiLogger.warn("crash finalize: host dispose failed: {error}", { + sessionId: state.sessionId, error: disposeErr instanceof Error ? disposeErr.message : String(disposeErr), }); diff --git a/src/tui/runner/mcp.ts b/src/tui/runner/mcp.ts index 66e427389..389b08c01 100644 --- a/src/tui/runner/mcp.ts +++ b/src/tui/runner/mcp.ts @@ -75,7 +75,8 @@ export function wireMcp( ) .catch((err: unknown) => { if (err instanceof Error && err.name === "AbortError") return; - tuiLogger.error("Late MCP connect failed: {error}", { + tuiLogger.warn("Late MCP connect failed for {server}: {error}", { + server: server.name, error: err instanceof Error ? err.message : String(err), }); }); @@ -246,7 +247,8 @@ function createMcpSurface( services.mcpConnectController.signal, ) .catch((err: unknown) => { - tuiLogger.error("MCP retry failed: {error}", { + tuiLogger.warn("MCP retry failed for {server}: {error}", { + server: server.name, error: err instanceof Error ? err.message : String(err), }); }); diff --git a/src/tui/runner/settings.ts b/src/tui/runner/settings.ts index b214be125..b23249d21 100644 --- a/src/tui/runner/settings.ts +++ b/src/tui/runner/settings.ts @@ -58,6 +58,7 @@ import { } from "../shell/chrome.js"; import type { AppShell } from "../shell/internals.js"; import { setShellInputSuspended } from "../shell/prompt.js"; +import { caughtDebug } from "../../logging/caught.js"; import { warningsForPluginEntry } from "../../plugins/diagnostics.js"; import { isPluginEnabledForSurface } from "../plugin-surface.js"; import { resolveWaitForApproval } from "../../agent/tool-execution-watchdog.js"; @@ -237,11 +238,9 @@ export async function wireSettings( if (state.telemetryFirstRun) { void services.globalSettingsWriter .enqueue(() => markTelemetryNoticeShown(trueGlobalSettingsPath)) - .catch((err: unknown) => { - tuiLogger.debug("telemetry notice watermark persist failed: {error}", { - error: err instanceof Error ? err.message : String(err), - }); - }); + .catch( + caughtDebug(tuiLogger, "telemetry notice watermark persist failed"), + ); } // Post-upgrade release notes watermark policy: @@ -261,11 +260,7 @@ export async function wireSettings( .enqueue(() => markLastChangelogVersion(trueGlobalSettingsPath, stampVersion), ) - .catch((err: unknown) => { - tuiLogger.debug("changelog watermark persist failed: {error}", { - error: err instanceof Error ? err.message : String(err), - }); - }); + .catch(caughtDebug(tuiLogger, "changelog watermark persist failed")); } // Every settings RMW in this runner shares this tail, including writes to @@ -403,11 +398,7 @@ export async function wireSettings( nextProviders, ); }) - .catch((err: unknown) => { - tuiLogger.debug("go model prefetch failed: {error}", { - error: err instanceof Error ? err.message : String(err), - }); - }); + .catch(caughtDebug(tuiLogger, "go model prefetch failed")); } if (isZenProvider({ name: providerName })) { void prefetchZenModels() @@ -430,17 +421,9 @@ export async function wireSettings( nextProviders, ); }) - .catch((err: unknown) => { - tuiLogger.debug("zen model prefetch failed: {error}", { - error: err instanceof Error ? err.message : String(err), - }); - }); + .catch(caughtDebug(tuiLogger, "zen model prefetch failed")); } - })().catch((err: unknown) => { - tuiLogger.debug("provider connect failed: {error}", { - error: err instanceof Error ? err.message : String(err), - }); - }); + })().catch(caughtDebug(tuiLogger, "provider connect failed")); }; const pendingProviderRemovals = new Set(); @@ -499,11 +482,7 @@ export async function wireSettings( listRecentModels(next), listFavoriteModels(next), ); - })().catch((err: unknown) => { - tuiLogger.debug("model selection persist failed: {error}", { - error: err instanceof Error ? err.message : String(err), - }); - }); + })().catch(caughtDebug(tuiLogger, "model selection persist failed")); }; const onFavoriteToggle = (id: string): void => { @@ -526,11 +505,7 @@ export async function wireSettings( listRecentModels(next), listFavoriteModels(next), ); - })().catch((err: unknown) => { - tuiLogger.debug("favorite toggle persist failed: {error}", { - error: err instanceof Error ? err.message : String(err), - }); - }); + })().catch(caughtDebug(tuiLogger, "favorite toggle persist failed")); }; const onSetDefault = (id: string): void => { @@ -561,11 +536,7 @@ export async function wireSettings( ); state.config = { ...state.config, settings: next }; state.systemNotice?.(`Default set to ${ref.model} (${ref.provider})`); - })().catch((err: unknown) => { - tuiLogger.debug("set default persist failed: {error}", { - error: err instanceof Error ? err.message : String(err), - }); - }); + })().catch(caughtDebug(tuiLogger, "set default persist failed")); }; // Credential bit shared by the arm line and the post-delete notice: names @@ -778,11 +749,7 @@ export async function wireSettings( ), ); })() - .catch((err: unknown) => { - tuiLogger.debug("provider removal failed: {error}", { - error: err instanceof Error ? err.message : String(err), - }); - }) + .catch(caughtDebug(tuiLogger, "provider removal failed")) .finally(() => { pendingProviderRemovals.delete(provider); }); diff --git a/src/tui/runner/submit.ts b/src/tui/runner/submit.ts index 401853400..2154e53de 100644 --- a/src/tui/runner/submit.ts +++ b/src/tui/runner/submit.ts @@ -62,6 +62,13 @@ import { listCommands } from "../commands/registry.js"; const tuiLogger = getLogger([LOG_NAMESPACE_ROOT, "tui"]); +// Shared tail for both recordSent paths; append is best-effort recall. +const logSentAppendFailure = (err: unknown): void => { + tuiLogger.debug("sent-message append failed: {error}", { + error: err instanceof Error ? err.message : String(err), + }); +}; + export type SubmissionRoute = | { kind: "empty" } | { kind: "command"; name: string; args: string } @@ -447,11 +454,7 @@ export function createSubmitPath( state.sendAborted = false; if (text.trim().length > 0) { void appendSentMessage(state.config.cwd, state.sessionId, text).catch( - (err: unknown) => { - tuiLogger.debug("sent-message append failed: {error}", { - error: err instanceof Error ? err.message : String(err), - }); - }, + logSentAppendFailure, ); } const ingested = await ingestOperatorPrompt( @@ -547,11 +550,7 @@ export function createDeliverRouting( if (text.startsWith(ASK_DIRECTOR_WAKE_PREFIX)) return; if (text.startsWith(MAILBOX_MAIL_WAKE_PREFIX)) return; void appendSentMessage(state.config.cwd, state.sessionId, text).catch( - (err: unknown) => { - tuiLogger.debug("sent-message append failed: {error}", { - error: err instanceof Error ? err.message : String(err), - }); - }, + logSentAppendFailure, ); }, captureGeneration: services.deliveryGeneration.capture, From eee06d1de64bb6475b8c31191e232a82e3d92000 Mon Sep 17 00:00:00 2001 From: Sawyer Cutler Date: Thu, 15 Oct 2026 14:28:41 -0700 Subject: [PATCH 2/2] fix(logging): restore terminal follow-up failure log A final steer whose promise rejects was silent after settlement. Log that failure again with the same id and error shape as the handoff path, and drop the narration comments added with the collapse. --- src/logging/caught.ts | 3 -- src/permission/approval-store-migration.ts | 1 - src/session/runtime-assembly.ts | 4 +- src/subagent/session-store.test.ts | 52 ++++++++++++++-------- src/subagent/session-store.ts | 4 ++ src/trust/project-trust.ts | 6 +-- src/tui/runner/submit.ts | 12 ++--- 7 files changed, 42 insertions(+), 40 deletions(-) diff --git a/src/logging/caught.ts b/src/logging/caught.ts index 3ffb687ad..bc956d45e 100644 --- a/src/logging/caught.ts +++ b/src/logging/caught.ts @@ -1,6 +1,3 @@ -// Shared hunter for the "best-effort step failed" debug catch: callers keep -// their message; the helper owns the caught-value normalization-and-append -// shape so that boilerplate exists once, not per site. interface DebugSink { debug: (message: string, properties?: Record) => void; } diff --git a/src/permission/approval-store-migration.ts b/src/permission/approval-store-migration.ts index 4d7fc6911..fe6627369 100644 --- a/src/permission/approval-store-migration.ts +++ b/src/permission/approval-store-migration.ts @@ -192,7 +192,6 @@ export async function migratePersistedApprovalStores( }); } } - // One summary warn per migration, not one per store file. const failed = files.filter((file) => file.error !== undefined); if (failed.length > 0) { log.warn("Skipped approval-store migration: {details}", { diff --git a/src/session/runtime-assembly.ts b/src/session/runtime-assembly.ts index 076d2fc17..e31631a8f 100644 --- a/src/session/runtime-assembly.ts +++ b/src/session/runtime-assembly.ts @@ -149,9 +149,7 @@ export async function loadSeededApprovals( // residual throw from breaking session start. try { await migratePersistedApprovalStores(cwd, sessionId, home); - } catch { - // Swallowed on purpose: the migration already surfaced the cause. - } + } catch {} const sessionApprovals = await loadApprovals(cwd, sessionId, home); const [ projectApprovals, diff --git a/src/subagent/session-store.test.ts b/src/subagent/session-store.test.ts index c56f1bf52..754c42068 100644 --- a/src/subagent/session-store.test.ts +++ b/src/subagent/session-store.test.ts @@ -1,4 +1,6 @@ -import { describe, expect, test } from "bun:test"; +import { describe, expect, spyOn, test } from "bun:test"; +import { getLogger } from "@intx/log"; +import { LOG_NAMESPACE_ROOT } from "../branding.js"; import { createSubAgentSessionStore, @@ -656,24 +658,36 @@ describe("CL-6943 reusable worker sessions", () => { }); test("rejected followup restores strip status so interrupt_agent fails closed", async () => { - const store = createSubAgentSessionStore(); - const session = retainedSession(store, { - interrupt: true, - followup: async () => { - throw new Error("send failed"); - }, - complete: "## Summary\nDone.", - }); - resumeCompleted(store, session.id); - await new Promise((resolve) => setTimeout(resolve, 0)); - - const after = store.get(session.id); - expect(after?.status).toBe("done"); - expect(after?.lifecycleStatus).toBe("completed"); - expect(store.interruptOne(session.id)).toEqual({ - ok: false, - status: "completed", - }); + const errorLog = spyOn( + getLogger([LOG_NAMESPACE_ROOT, "subagent", "session-store"]), + "error", + ); + try { + const store = createSubAgentSessionStore(); + const session = retainedSession(store, { + interrupt: true, + followup: async () => { + throw new Error("send failed"); + }, + complete: "## Summary\nDone.", + }); + resumeCompleted(store, session.id); + await new Promise((resolve) => setTimeout(resolve, 0)); + + const after = store.get(session.id); + expect(after?.status).toBe("done"); + expect(after?.lifecycleStatus).toBe("completed"); + expect(store.interruptOne(session.id)).toEqual({ + ok: false, + status: "completed", + }); + expect(errorLog).toHaveBeenCalledWith( + "followup turn failed for {id}: {error}", + { id: session.id, error: "send failed" }, + ); + } finally { + errorLog.mockRestore(); + } }); test("rejected followup after interrupt restamps stopReason interrupted", async () => { diff --git a/src/subagent/session-store.ts b/src/subagent/session-store.ts index 919c058f3..5381e5efd 100644 --- a/src/subagent/session-store.ts +++ b/src/subagent/session-store.ts @@ -1289,6 +1289,10 @@ export function createSubAgentSessionStore( } endFollowupTurn(id, failLifecycle); pendingFailures.delete(id); + log.error("followup turn failed for {id}: {error}", { + id, + error: errorMessage(err), + }); }; const queueFollowupTurn = ( id: string, diff --git a/src/trust/project-trust.ts b/src/trust/project-trust.ts index e887d2c14..f52889f7a 100644 --- a/src/trust/project-trust.ts +++ b/src/trust/project-trust.ts @@ -52,8 +52,7 @@ const emptyStore = (): ProjectTrustStore => ({ /** * Extract a schema-confirmed array field: missing → [], non-strings dropped. - * Hand-edited partial files must not wipe consent. Issues accumulate on - * `issues` for the caller's one summary warn per store. + * Hand-edited partial files must not wipe consent. */ function extractStringArrayField( value: unknown[] | undefined, @@ -147,8 +146,6 @@ export async function readProjectTrustStore( logger.warn`project trust store has an invalid shape at ${path}: ${validated.summary}`; return { state: "invalid", store: emptyStore() }; } - // Field/entry issues collect; the store gets one summary warn, not one - // per field or entry. const issues: string[] = []; const trustedPluginPaths = extractStringArrayField( validated.trustedPluginPaths, @@ -193,7 +190,6 @@ export async function readProjectTrustStore( `trustedPluginPaths: dropped ${nonAbsolute} non-absolute entries`, ); } - // One summary warn per store, not one warn per field or per entry. if (issues.length > 0) { logger.warn`project trust store issues at ${path} (${issues.length}): ${issues.join("; ")}`; } diff --git a/src/tui/runner/submit.ts b/src/tui/runner/submit.ts index 023cb6b6c..88520cee9 100644 --- a/src/tui/runner/submit.ts +++ b/src/tui/runner/submit.ts @@ -55,6 +55,7 @@ import { type RunnerState, } from "./state.js"; import { LOG_NAMESPACE_ROOT } from "../../branding.js"; +import { caughtDebug } from "../../logging/caught.js"; import { buildCredentialRecoveryAlternatives } from "./credential-recovery.js"; import type { PendingCredentialRecovery } from "./credential-recovery.js"; import type { PendingReconnectRecovery } from "./reconnect-recovery.js"; @@ -62,13 +63,6 @@ import { listCommands } from "../commands/registry.js"; const tuiLogger = getLogger([LOG_NAMESPACE_ROOT, "tui"]); -// Shared tail for both recordSent paths; append is best-effort recall. -const logSentAppendFailure = (err: unknown): void => { - tuiLogger.debug("sent-message append failed: {error}", { - error: err instanceof Error ? err.message : String(err), - }); -}; - export type SubmissionRoute = | { kind: "empty" } | { kind: "command"; name: string; args: string } @@ -454,7 +448,7 @@ export function createSubmitPath( state.sendAborted = false; if (text.trim().length > 0) { void appendSentMessage(state.config.cwd, state.sessionId, text).catch( - logSentAppendFailure, + caughtDebug(tuiLogger, "sent-message append failed"), ); } const ingested = await ingestOperatorPrompt( @@ -550,7 +544,7 @@ export function createDeliverRouting( if (text.startsWith(ASK_DIRECTOR_WAKE_PREFIX)) return; if (text.startsWith(MAILBOX_MAIL_WAKE_PREFIX)) return; void appendSentMessage(state.config.cwd, state.sessionId, text).catch( - logSentAppendFailure, + caughtDebug(tuiLogger, "sent-message append failed"), ); }, captureGeneration: services.deliveryGeneration.capture,