diff --git a/src/cli/fleet.test.ts b/src/cli/fleet.test.ts index f5c34b1..875be77 100644 --- a/src/cli/fleet.test.ts +++ b/src/cli/fleet.test.ts @@ -6,7 +6,7 @@ import { dirname, join } from 'node:path' import type { CloseProbePrInput, Factory, FactoryPorts, createFactory } from '../index' import { FileStateStore } from '../state/file-state-store' import { FakeFleetClient, FakeMountClient } from '../testing' -import { installFactoryStopSignalHandlers, parseFleetCommand, parseGlobalOptions, resolveBrokerConnectionPath, runFleetCli } from './fleet' +import { formatLogArgs, installFactoryStopSignalHandlers, parseFleetCommand, parseGlobalOptions, resolveBrokerConnectionPath, runFleetCli } from './fleet' const issuePath = '/linear/issues/AR-77__uuid-77.json' @@ -62,6 +62,35 @@ const githubIssueFile = (repo: string, number = 48) => ({ }, }) +describe('fleet CLI logging', () => { + it('keeps every argument when Errors and unserializable values reach the stream logger', () => { + const circular: Record = { sibling: 'kept' } + circular.self = circular + const throwingToJson = { + sibling: 'also kept', + toJSON: () => { + throw new Error('must not run') + }, + } + + const output = formatLogArgs([ + new Error('top-level failure'), + { nested: new Error('nested failure') }, + circular, + throwingToJson, + 42n, + 'tail', + ]) + + expect(output).toContain('"message":"top-level failure"') + expect(output).toContain('"message":"nested failure"') + expect(output).toContain('"self":"[Circular]"') + expect(output).toContain('also kept') + expect(output).toContain('"42n"') + expect(output).toContain(' tail') + }) +}) + describe('fleet CLI parsing', () => { it('parses spawn flags into a FleetClient spawn input shape', () => { expect(parseFleetCommand([ diff --git a/src/cli/fleet.ts b/src/cli/fleet.ts index 44badb9..cf43587 100644 --- a/src/cli/fleet.ts +++ b/src/cli/fleet.ts @@ -2,6 +2,7 @@ import { existsSync } from 'node:fs' import { readFile } from 'node:fs/promises' import { dirname, join, resolve } from 'node:path' +import { stringifyLogValue } from '../logging' import { ensureLocalMount } from '../mount/local-mount-preflight' import { resolveLocalFactoryConfig, type LocalClonePathOptions } from '../config/local-clone-paths' import { @@ -818,13 +819,9 @@ function streamLogger(stream: Pick): Logger { } } -function formatLogArgs(args: unknown[]): string { +export function formatLogArgs(args: unknown[]): string { if (args.length === 0) return '' - try { - return ` ${args.map((arg) => (typeof arg === 'string' ? arg : JSON.stringify(arg))).join(' ')}` - } catch { - return '' - } + return ` ${args.map((arg) => (typeof arg === 'string' ? arg : stringifyLogValue(arg))).join(' ')}` } export function resolveBrokerConnectionPath(startCwd = process.cwd()): string | undefined { diff --git a/src/fleet/internal-fleet-client.test.ts b/src/fleet/internal-fleet-client.test.ts index 8c48240..57c4393 100644 --- a/src/fleet/internal-fleet-client.test.ts +++ b/src/fleet/internal-fleet-client.test.ts @@ -1227,7 +1227,11 @@ describe('InternalFleetClient', () => { await vi.waitFor(() => expect(harness.sent).toHaveLength(2)) await vi.waitFor(() => expect(logger.warn).toHaveBeenCalledWith( '[factory-sdk] readiness-triggered resend failed, but original event is still active', - resendError, + expect.objectContaining({ + name: 'Error', + message: 'resend transport failed', + stack: expect.stringContaining('Error: resend transport failed'), + }), )) harness.emit({ kind: 'delivery_injected', diff --git a/src/fleet/internal-fleet-client.ts b/src/fleet/internal-fleet-client.ts index 2309f74..bdb7593 100644 --- a/src/fleet/internal-fleet-client.ts +++ b/src/fleet/internal-fleet-client.ts @@ -8,6 +8,7 @@ import type { BrokerEvent, ListAgent, SendMessageInput, SpawnPtyInput } from '@a import type { AgentMessage, AgentPidResolution, Capability, FleetClient, RosterEntry, SendInput, SpawnInput, SpawnResult } from '../ports/fleet' import type { Logger } from '../ports/system' +import { normalizeLogger } from '../logging' import { resolveRelayWorkspaceKey } from './relay-workspace-key' const requireForResolve = createRequire(import.meta.url) @@ -132,7 +133,7 @@ export class InternalFleetClient implements FleetClient { this.#connectionPath = options.connectionPath this.#workspaceKey = options.workspaceKey this.#resumeCapability = options.resumeCapability ?? 'spawn:codex' - this.#logger = options.logger + this.#logger = options.logger ? normalizeLogger(options.logger) : undefined this.#resolveAgentRelayMcpCommand = options.resolveAgentRelayMcpCommand ?? resolveAgentRelayMcpCommand this.#client = options.client ?? HarnessDriverClient.connect({ cwd: options.cwd, connectionPath: options.connectionPath }) this.#ownsBroker = options.ownsBroker ?? false diff --git a/src/logging.test.ts b/src/logging.test.ts new file mode 100644 index 0000000..8918479 --- /dev/null +++ b/src/logging.test.ts @@ -0,0 +1,243 @@ +import { describe, expect, it, vi } from 'vitest' + +import { normalizeLogger, normalizeLogValue, stringifyLogValue } from './logging' + +describe('log metadata normalization', () => { + it('serializes a plain Error with its non-enumerable diagnostic fields', () => { + const error = new Error('plain failure') + + expect(normalizeLogValue(error)).toMatchObject({ + name: 'Error', + message: 'plain failure', + stack: expect.stringContaining('Error: plain failure'), + }) + expect(stringifyLogValue(error)).not.toBe('{}') + }) + + it('preserves safe structured error fields while redacting sensitive metadata and omitting causes', () => { + class ProtocolError extends Error { + name = 'HarnessDriverProtocolError' + code = 'http_500' + status = 500 + retryable = true + data = { error: 'internal reply dropped', accessToken: 'do-not-log' } + apiKey = 'do-not-log' + } + const error = new ProtocolError('broker request failed', { cause: new Error('secret upstream response') }) + Object.defineProperty(error, 'cause', { value: error.cause, enumerable: true }) + + expect(normalizeLogValue(error)).toMatchObject({ + name: 'HarnessDriverProtocolError', + message: 'broker request failed', + stack: expect.stringContaining('ProtocolError: broker request failed'), + code: 'http_500', + status: 500, + retryable: true, + data: { + error: 'internal reply dropped', + accessToken: '[Redacted]', + }, + apiKey: '[Redacted]', + }) + expect(normalizeLogValue(error)).not.toHaveProperty('cause') + }) + + it('contains nested errors, cycles, BigInts, getters, and throwing toJSON hooks', () => { + const metadata: Record = { + error: new Error('nested failure'), + count: 12n, + sibling: 'still visible', + toJSON: () => { + throw new Error('must not run') + }, + } + Object.defineProperty(metadata, 'broken', { + enumerable: true, + get: () => { + throw new Error('must not run') + }, + }) + metadata.self = metadata + + const normalized = normalizeLogValue(metadata) + expect(normalized).toMatchObject({ + error: { + name: 'Error', + message: 'nested failure', + stack: expect.stringContaining('Error: nested failure'), + }, + count: '12n', + sibling: 'still visible', + broken: '[Getter]', + self: '[Circular]', + }) + expect(() => stringifyLogValue(metadata)).not.toThrow() + expect(stringifyLogValue(metadata)).toContain('still visible') + }) + + it('does not invoke accessor-backed Error fields or array elements', () => { + let errorGets = 0 + const error = new Error() + for (const key of ['name', 'message', 'code']) { + Object.defineProperty(error, key, { + configurable: true, + enumerable: true, + get: () => { + errorGets += 1 + return `getter-${key}` + }, + }) + } + const stackError = new Error('safe message') + Object.defineProperty(stackError, 'stack', { + configurable: true, + get: () => { + errorGets += 1 + return 'getter-stack' + }, + }) + let arrayGets = 0 + const array: unknown[] = [] + Object.defineProperty(array, '0', { + configurable: true, + enumerable: true, + get: () => { + arrayGets += 1 + return 'getter-item' + }, + }) + + expect(normalizeLogValue(error)).toEqual({ name: 'Error', message: 'Error' }) + expect(normalizeLogValue(stackError)).toEqual({ + name: 'Error', + message: 'safe message', + stack: 'Error: safe message', + }) + expect(normalizeLogValue(array)).toEqual(['[Getter]']) + expect(errorGets).toBe(0) + expect(arrayGets).toBe(0) + }) + + it('uses intrinsic special-object conversion without calling instance hooks', () => { + let dateCalls = 0 + const date = new Date(0) + Object.defineProperty(date, 'toISOString', { + value: () => { + dateCalls += 1 + return 'unsafe date' + }, + }) + let regexpCalls = 0 + const regexp = /factory/giu + Object.defineProperty(regexp, 'toString', { + value: () => { + regexpCalls += 1 + return 'unsafe regexp' + }, + }) + Object.defineProperty(regexp, 'source', { + configurable: true, + get: () => { + regexpCalls += 1 + return 'unsafe-source' + }, + }) + Object.defineProperty(regexp, 'flags', { + configurable: true, + get: () => { + regexpCalls += 1 + return 'i' + }, + }) + let functionNameGets = 0 + const fn = () => undefined + Object.defineProperty(fn, 'name', { + configurable: true, + get: () => { + functionNameGets += 1 + return 'unsafe function name' + }, + }) + + expect(normalizeLogValue(date)).toBe('1970-01-01T00:00:00.000Z') + expect(normalizeLogValue(regexp)).toBe('/factory/giu') + expect(normalizeLogValue(fn)).toBe('[Function]') + expect({ dateCalls, regexpCalls, functionNameGets }).toEqual({ + dateCalls: 0, + regexpCalls: 0, + functionNameGets: 0, + }) + }) + + it('does not materialize a lazy stack through a custom Error.prepareStackTrace hook', () => { + const errorCreatedBeforeHook = new Error('before hook') + const original = Object.getOwnPropertyDescriptor(Error, 'prepareStackTrace') + let calls = 0 + Object.defineProperty(Error, 'prepareStackTrace', { + configurable: true, + value: () => { + calls += 1 + return 'unsafe stack hook output' + }, + }) + try { + const errorCreatedAfterHook = new Error('after hook') + expect(normalizeLogValue(errorCreatedBeforeHook)).toEqual({ + name: 'Error', + message: 'before hook', + stack: 'Error: before hook', + }) + expect(normalizeLogValue(errorCreatedAfterHook)).toEqual({ + name: 'Error', + message: 'after hook', + stack: 'Error: after hook', + }) + expect(calls).toBe(0) + } finally { + if (original) Object.defineProperty(Error, 'prepareStackTrace', original) + else delete (Error as ErrorConstructor & { prepareStackTrace?: unknown }).prepareStackTrace + } + }) + + it('applies the global field budget to branching nested arrays', () => { + const branch = (depth: number): unknown => depth === 0 + ? 'leaf' + : Array.from({ length: 5 }, () => branch(depth - 1)) + const normalized = normalizeLogValue(branch(6)) + const countNodes = (value: unknown): number => Array.isArray(value) + ? 1 + value.reduce((count, child) => count + countNodes(child), 0) + : 1 + + expect(countNodes(normalized)).toBeLessThanOrEqual(210) + expect(JSON.stringify(normalized)).toContain('[FieldLimit]') + }) + + it('normalizes every argument passed through an injected logger', () => { + const warn = vi.fn() + const logger = normalizeLogger({ warn }) + + logger.warn?.('representative warning', new Error('raw failure'), { + nested: new Error('nested failure'), + }) + + expect(warn).toHaveBeenCalledWith( + 'representative warning', + expect.objectContaining({ message: 'raw failure', stack: expect.any(String) }), + { nested: expect.objectContaining({ message: 'nested failure', stack: expect.any(String) }) }, + ) + }) + + it('keeps the default console logger callable through the adapter', () => { + const error = vi.spyOn(console, 'error').mockImplementation(() => undefined) + try { + normalizeLogger(console).error?.('default console error', new Error('console failure')) + + expect(error).toHaveBeenCalledWith( + 'default console error', + expect.objectContaining({ message: 'console failure', stack: expect.any(String) }), + ) + } finally { + error.mockRestore() + } + }) +}) diff --git a/src/logging.ts b/src/logging.ts new file mode 100644 index 0000000..d099cac --- /dev/null +++ b/src/logging.ts @@ -0,0 +1,348 @@ +import type { Logger } from './ports/system' + +const REDACTED = '[Redacted]' +const CIRCULAR = '[Circular]' +const UNSERIALIZABLE = '[Unserializable]' +const MAX_DEPTH = 6 +const MAX_FIELDS = 100 +const MAX_ARRAY_ITEMS = 100 +const MAX_STRING_LENGTH = 32_000 +const SAFE_ERROR_STACKS = new WeakMap() +const NATIVE_REGEXP_SOURCE_GETTER = Object.getOwnPropertyDescriptor(RegExp.prototype, 'source')?.get +const NATIVE_REGEXP_FLAG_GETTERS = [ + ['d', Object.getOwnPropertyDescriptor(RegExp.prototype, 'hasIndices')?.get], + ['g', Object.getOwnPropertyDescriptor(RegExp.prototype, 'global')?.get], + ['i', Object.getOwnPropertyDescriptor(RegExp.prototype, 'ignoreCase')?.get], + ['m', Object.getOwnPropertyDescriptor(RegExp.prototype, 'multiline')?.get], + ['s', Object.getOwnPropertyDescriptor(RegExp.prototype, 'dotAll')?.get], + ['u', Object.getOwnPropertyDescriptor(RegExp.prototype, 'unicode')?.get], + ['v', Object.getOwnPropertyDescriptor(RegExp.prototype, 'unicodeSets')?.get], + ['y', Object.getOwnPropertyDescriptor(RegExp.prototype, 'sticky')?.get], +] as const + +const SENSITIVE_FIELD = /authorization|cookie|credential|password|passwd|privatekey|secret|token|apikey/iu + +interface NormalizationState { + readonly seen: WeakSet + fieldsRemaining: number +} + +/** + * Convert logger metadata to a bounded JSON-safe value. + * + * Error's useful built-in fields are non-enumerable, so they are copied + * deliberately. Other objects retain only their enumerable data properties, + * matching JSON.stringify's normal visibility without invoking getters or + * toJSON hooks. Sensitive-looking fields and Error causes are not exposed. + */ +export function normalizeLogValue(value: unknown): unknown { + try { + return normalizeValue(value, 0, { + seen: new WeakSet(), + fieldsRemaining: MAX_FIELDS, + }) + } catch { + return UNSERIALIZABLE + } +} + +/** Wrap a Logger so every metadata argument is safe for structured sinks. */ +export function normalizeLogger(logger: Logger): Logger { + const wrap = (level: keyof Logger): Logger[typeof level] => { + let sink: Logger[typeof level] + try { + sink = logger[level] + } catch { + return undefined + } + if (typeof sink !== 'function') return undefined + return (message: string, ...args: unknown[]) => { + sink.call(logger, message, ...args.map(normalizeLogValue)) + } + } + + return { + debug: wrap('debug'), + info: wrap('info'), + warn: wrap('warn'), + error: wrap('error'), + } +} + +/** Serialize one log value without allowing it to throw or disappear. */ +export function stringifyLogValue(value: unknown): string { + try { + return JSON.stringify(normalizeLogValue(value)) ?? UNSERIALIZABLE + } catch { + return UNSERIALIZABLE + } +} + +/** Attach a stack assembled from already-normalized diagnostics. */ +export function setSafeErrorStack(error: Error, stack: string): void { + Object.defineProperty(error, 'stack', { + configurable: true, + writable: true, + value: stack, + }) + SAFE_ERROR_STACKS.set(error, stack) +} + +function normalizeValue(value: unknown, depth: number, state: NormalizationState): unknown { + if (typeof value === 'string') return boundedString(value) + if (value === null || typeof value === 'boolean') return value + if (typeof value === 'number') return Number.isFinite(value) ? value : String(value) + if (typeof value === 'bigint') return `${value}n` + if (typeof value === 'undefined') return '[undefined]' + if (typeof value === 'symbol') return `[${String(value)}]` + if (typeof value === 'function') return '[Function]' + if (typeof value !== 'object') return String(value) + + if (state.seen.has(value)) return CIRCULAR + if (depth >= MAX_DEPTH) return '[MaxDepth]' + state.seen.add(value) + + if (value instanceof Error) return normalizeError(value, depth, state) + if (value instanceof Date) { + try { + return Date.prototype.toISOString.call(value) + } catch { + return '[Invalid Date]' + } + } + if (value instanceof RegExp) { + try { + if (!NATIVE_REGEXP_SOURCE_GETTER) return '[RegExp]' + const source = NATIVE_REGEXP_SOURCE_GETTER.call(value) + const flags = NATIVE_REGEXP_FLAG_GETTERS + .filter(([, getter]) => getter?.call(value)) + .map(([flag]) => flag) + .join('') + return `/${source}/${flags}` + } catch { + return '[RegExp]' + } + } + + if (Array.isArray(value)) return normalizeArray(value, depth, state) + + return normalizeObject(value, depth, state) +} + +function normalizeError(error: Error, depth: number, state: NormalizationState): Record { + const result: Record = {} + let descriptors: PropertyDescriptorMap + try { + descriptors = getOwnErrorDescriptors(error) + } catch { + return { name: 'Error', message: 'Error' } + } + const name = safeDataField(error, descriptors, 'name') + const message = safeDataField(error, descriptors, 'message') + const displayFieldHasAccessor = hasAccessorField(error, descriptors, 'name') || hasAccessorField(error, descriptors, 'message') + const markedSafeStack = SAFE_ERROR_STACKS.get(error) + const stack = markedSafeStack ?? ( + displayFieldHasAccessor || hasCustomPrepareStackTrace() + ? undefined + : safeStackField(error) + ) + const code = safeDataField(error, descriptors, 'code') + + result.name = typeof name === 'string' && name ? boundedString(name) : 'Error' + result.message = typeof message === 'string' && message ? boundedString(message) : result.name + if (typeof stack === 'string' && stack) result.stack = boundedString(stack) + else if (!displayFieldHasAccessor) { + // Stack descriptors are runtime-specific: inspecting one can materialize + // V8's lazy stack and execute Error.prepareStackTrace on Node 20. Keep a + // safe diagnostic header whenever the full stack cannot be read without + // invoking user code. + result.stack = `${result.name}: ${result.message}` + } + if (isSafeErrorCode(code)) result.code = code + + appendEnumerableProperties(result, descriptors, depth, state, new Set(['name', 'message', 'stack', 'code', 'cause'])) + return result +} + +function getOwnErrorDescriptors(error: Error): PropertyDescriptorMap { + const descriptors: PropertyDescriptorMap = {} + for (const key of Reflect.ownKeys(error)) { + if (typeof key !== 'string' || key === 'stack') continue + const descriptor = Object.getOwnPropertyDescriptor(error, key) + if (descriptor) descriptors[key] = descriptor + } + return descriptors +} + +function safeStackField(error: Error): unknown { + let descriptor: PropertyDescriptor | undefined + try { + descriptor = Object.getOwnPropertyDescriptor(error, 'stack') + } catch { + return undefined + } + if (!descriptor) return undefined + if ('value' in descriptor) return descriptor.value + + const nativeGetter = getNativeErrorStackGetter() + if (!nativeGetter || descriptor.get !== nativeGetter) return undefined + try { + return nativeGetter.call(error) + } catch { + return undefined + } +} + +let nativeErrorStackGetter: (() => string) | undefined +let nativeErrorStackGetterResolved = false + +function getNativeErrorStackGetter(): (() => string) | undefined { + if (hasCustomPrepareStackTrace()) return undefined + if (nativeErrorStackGetterResolved) return nativeErrorStackGetter + nativeErrorStackGetterResolved = true + try { + nativeErrorStackGetter = Object.getOwnPropertyDescriptor(new Error(), 'stack')?.get + } catch { + nativeErrorStackGetter = undefined + } + return nativeErrorStackGetter +} + +function normalizeArray(value: unknown[], depth: number, state: NormalizationState): unknown[] | string { + let descriptors: PropertyDescriptorMap + try { + descriptors = Object.getOwnPropertyDescriptors(value) as unknown as PropertyDescriptorMap + } catch { + return UNSERIALIZABLE + } + const rawLength = descriptors.length && 'value' in descriptors.length ? descriptors.length.value : 0 + const length = typeof rawLength === 'number' && Number.isSafeInteger(rawLength) && rawLength >= 0 ? rawLength : 0 + const visibleLength = Math.min(length, MAX_ARRAY_ITEMS) + const items: unknown[] = [] + for (let index = 0; index < visibleLength; index += 1) { + if (state.fieldsRemaining <= 0) { + items.push('[FieldLimit]') + return items + } + state.fieldsRemaining -= 1 + const descriptor = descriptors[String(index)] + if (!descriptor) { + items.push(null) + continue + } + if (!('value' in descriptor)) { + items.push('[Getter]') + } else { + items.push(normalizeValue(descriptor.value, depth + 1, state)) + } + } + if (length > MAX_ARRAY_ITEMS) items.push(`[${length - MAX_ARRAY_ITEMS} more items]`) + return items +} + +function normalizeObject(value: object, depth: number, state: NormalizationState): Record | string { + let descriptors: PropertyDescriptorMap + try { + descriptors = Object.getOwnPropertyDescriptors(value) + } catch { + return UNSERIALIZABLE + } + const result: Record = {} + appendEnumerableProperties(result, descriptors, depth, state, new Set(['toJSON'])) + return result +} + +function appendEnumerableProperties( + target: Record, + descriptors: PropertyDescriptorMap, + depth: number, + state: NormalizationState, + excluded: ReadonlySet, +): void { + for (const [key, descriptor] of Object.entries(descriptors)) { + if (!descriptor.enumerable || excluded.has(key)) continue + // Match JSON object semantics for values it normally omits. Top-level + // logger arguments still receive explicit placeholders from normalizeValue. + if ( + 'value' in descriptor && + (typeof descriptor.value === 'undefined' || typeof descriptor.value === 'symbol' || typeof descriptor.value === 'function') + ) continue + if (state.fieldsRemaining <= 0) { + target.__truncated__ = '[FieldLimit]' + break + } + state.fieldsRemaining -= 1 + if (isSensitiveField(key)) { + target[key] = REDACTED + } else if (!('value' in descriptor)) { + target[key] = '[Getter]' + } else { + target[key] = normalizeValue(descriptor.value, depth + 1, state) + } + } +} + +function safeDataField(error: Error, ownDescriptors: PropertyDescriptorMap, key: string): unknown { + const descriptor = findPropertyDescriptor(error, ownDescriptors, key) + if (!descriptor) return undefined + if ('value' in descriptor) return descriptor.value + return undefined +} + +function hasCustomPrepareStackTrace(): boolean { + let current: object | null = Error + for (let depth = 0; current && depth < MAX_DEPTH; depth += 1) { + try { + const descriptor = Object.getOwnPropertyDescriptor(current, 'prepareStackTrace') + if (descriptor) return !('value' in descriptor) || descriptor.value !== undefined + current = Object.getPrototypeOf(current) + } catch { + return true + } + } + return false +} + +function hasAccessorField(error: Error, ownDescriptors: PropertyDescriptorMap, key: string): boolean { + const descriptor = findPropertyDescriptor(error, ownDescriptors, key) + return Boolean(descriptor && !('value' in descriptor)) +} + +function findPropertyDescriptor( + error: Error, + ownDescriptors: PropertyDescriptorMap, + key: string, +): PropertyDescriptor | undefined { + const own = ownDescriptors[key] + if (own) return own + + let current: object | null + try { + current = Object.getPrototypeOf(error) + } catch { + return undefined + } + for (let depth = 0; current && depth < MAX_DEPTH; depth += 1) { + try { + const descriptor = Object.getOwnPropertyDescriptor(current, key) + if (descriptor) return descriptor + current = Object.getPrototypeOf(current) + } catch { + return undefined + } + } + return undefined +} + +function isSafeErrorCode(value: unknown): value is string | number { + return typeof value === 'string' || (typeof value === 'number' && Number.isFinite(value)) +} + +function isSensitiveField(key: string): boolean { + return SENSITIVE_FIELD.test(key.replace(/[^a-z0-9]/giu, '').toLowerCase()) +} + +function boundedString(value: string): string { + if (value.length <= MAX_STRING_LENGTH) return value + return `${value.slice(0, MAX_STRING_LENGTH)}...[truncated ${value.length - MAX_STRING_LENGTH} chars]` +} diff --git a/src/orchestrator/factory.test.ts b/src/orchestrator/factory.test.ts index 1a6565d..75226ff 100644 --- a/src/orchestrator/factory.test.ts +++ b/src/orchestrator/factory.test.ts @@ -6083,7 +6083,13 @@ describe('FactoryLoop', () => { const mount = new FakeMountClient({ [issuePath(9)]: issueFile(9) }) mount.setConfirmWrite(issuePath(9), 'failed') const fleet = new FakeFleetClient() - const factory = createFactory(config(), { mount, fleet, triage: new StaticTriage() }) + const loggedErrors: unknown[][] = [] + const factory = createFactory(config(), { + mount, + fleet, + triage: new StaticTriage(), + logger: { error: (...args: unknown[]) => loggedErrors.push(args) }, + }) const errors: unknown[] = [] factory.on('error', (payload) => errors.push(payload)) const decision = await factory.triageIssue(parseLinearIssue(issuePath(9), issueFile(9))) @@ -6098,6 +6104,74 @@ describe('FactoryLoop', () => { errorMessage: expect.stringContaining('Writeback not acked'), errorStack: expect.stringContaining('Error: Writeback not acked'), }) + expect(loggedErrors).toContainEqual([ + '[factory] error', + expect.objectContaining({ + name: 'Error', + message: expect.stringContaining('Writeback not acked'), + stack: expect.stringContaining('Error: Writeback not acked'), + errorMessage: expect.stringContaining('Writeback not acked'), + errorStack: expect.stringContaining('Error: Writeback not acked'), + issue: 'AR-9', + }), + ]) + expect(factory.status().counters.errors).toBe(1) + }) + + it('preserves structured custom error fields in #error logs without leaking sensitive metadata', async () => { + const mount = new FakeMountClient({ [issuePath(83)]: issueFile(83) }) + const fleet = new FakeFleetClient() + const loggedErrors: unknown[][] = [] + const emittedErrors: unknown[] = [] + const protocolError = Object.assign(new Error('internal reply dropped'), { + name: 'HarnessDriverProtocolError', + code: 'http_500', + status: 500, + retryable: true, + data: { error: 'internal reply dropped', authorization: 'Bearer do-not-log' }, + }) + const linear: LinearWriteback = { + async postComment() {}, + async setState() { + throw protocolError + }, + async createIssue() { + throw new Error('not used') + }, + async verify() { + return true + }, + } + const factory = createFactory(config(), { + mount, + fleet, + triage: new StaticTriage(), + linear, + logger: { error: (...args: unknown[]) => loggedErrors.push(args) }, + }) + factory.on('error', (payload) => emittedErrors.push(payload)) + const decision = await factory.triageIssue(parseLinearIssue(issuePath(83), issueFile(83))) + + await expect(factory.dispatch(decision)).rejects.toBe(protocolError) + + expect(loggedErrors).toContainEqual([ + '[factory] error', + expect.objectContaining({ + name: 'HarnessDriverProtocolError', + message: 'internal reply dropped', + stack: expect.stringContaining('HarnessDriverProtocolError: internal reply dropped'), + errorMessage: 'internal reply dropped', + errorStack: expect.stringContaining('HarnessDriverProtocolError: internal reply dropped'), + code: 'http_500', + status: 500, + retryable: true, + data: { error: 'internal reply dropped', authorization: '[Redacted]' }, + issue: 'AR-83', + }), + ]) + expect(emittedErrors).toHaveLength(1) + expect(emittedErrors[0]).toMatchObject({ error: protocolError, issue: { key: 'AR-83' } }) + expect(factory.status().counters.errors).toBe(1) }) it('classifies fleet spawn failures with issue, agent, capability, and cwd context', async () => { @@ -6155,7 +6229,11 @@ describe('FactoryLoop', () => { }) expect(warnings[0]).toEqual([ '[factory] comment writeback skipped', - expect.objectContaining({ message: 'unsupported Linear writeback path' }), + expect.objectContaining({ + name: 'Error', + message: 'unsupported Linear writeback path', + stack: expect.stringContaining('Error: unsupported Linear writeback path'), + }), ]) expect(mount.writes).toContainEqual({ path: issuePath(25), content: { stateId: implementing } }) }) @@ -9061,7 +9139,14 @@ describe('FactoryLoop', () => { expect(factory.status().counters.clarificationWakeLeaseLosses).toBeUndefined() expect(warnings).toContainEqual([ '[factory] transient error renewing clarification wake lease; retrying', - expect.objectContaining({ issue: 'AR-52', error: expect.any(Error) }), + expect.objectContaining({ + issue: 'AR-52', + error: expect.objectContaining({ + name: 'Error', + message: 'transient state store outage', + stack: expect.stringContaining('Error: transient state store outage'), + }), + }), ]) } finally { vi.useRealTimers() diff --git a/src/orchestrator/factory.ts b/src/orchestrator/factory.ts index cdc8170..c24dfaa 100644 --- a/src/orchestrator/factory.ts +++ b/src/orchestrator/factory.ts @@ -31,6 +31,7 @@ import type { import type { Clock, Logger } from '../ports/system' import { InMemoryStateStore } from '../state/in-memory-state-store' import { containsExplicitIssueReference, containsIssueKey } from '../issue-key-match' +import { normalizeLogger, normalizeLogValue, setSafeErrorStack, stringifyLogValue } from '../logging' import { isInFactoryScope } from '../safety/factory-scope' import { dispatchRelayflowForChangeEvent } from '../dispatch/relayflow-registry' import { @@ -338,7 +339,7 @@ export class FactoryLoop implements Factory { this.#customProbePrResolver = Boolean(ports.probePrResolver) this.#probePrGhRunner = ports.probePrGhRunner ?? failClosedGhRunner this.#probePrResolver = ports.probePrResolver ?? ((issue) => this.#resolveIssuePr(issue)) - this.#logger = ports.logger ?? console + this.#logger = normalizeLogger(ports.logger ?? console) this.#clock = ports.clock ?? realClock this.#processIdentityReader = ports.processIdentityReader ?? readProcessIdentity this.#processFinder = ports.processFinder ?? ((agentName, opts) => findAgentProcessByName(agentName, { @@ -4437,8 +4438,17 @@ export class FactoryLoop implements Factory { #error(error: unknown, issue?: IssueRef): void { this.#increment('errors') - this.#logger.error?.('[factory] error', error) - this.#emit('error', { error, ...describeError(error), issue }) + const details = describeError(error) + const normalized = normalizeLogValue(error) + const errorFields = normalized && typeof normalized === 'object' && !Array.isArray(normalized) + ? normalized as Record + : { error: normalized } + this.#logger.error?.('[factory] error', { + ...errorFields, + ...details, + ...(issue ? { issue: issue.key } : {}), + }) + this.#emit('error', { error, ...details, issue }) } #surfaceEscalationDeliveryFailure( @@ -7414,24 +7424,30 @@ export const changeEventPath = (event: ChangeEvent): string | undefined => { } const describeError = (error: unknown): { errorMessage: string; errorStack?: string } => { - if (error instanceof Error) { - return { - errorMessage: error.message || error.name || 'Error', - errorStack: error.stack, + try { + if (error instanceof Error) { + const normalized = normalizeLogValue(error) as Record + const message = typeof normalized.message === 'string' ? normalized.message : undefined + const name = typeof normalized.name === 'string' ? normalized.name : undefined + const stack = typeof normalized.stack === 'string' ? normalized.stack : undefined + return { + errorMessage: message || name || 'Error', + ...(stack ? { errorStack: stack } : {}), + } } + } catch { + // Continue through the serializer for hostile proxy values. } if (typeof error === 'string') { return { errorMessage: error } } + const serialized = stringifyLogValue(error) + if (serialized && serialized !== '{}') return { errorMessage: serialized } try { - const serialized = JSON.stringify(error) - if (serialized && serialized !== '{}') { - return { errorMessage: serialized } - } + return { errorMessage: String(error) } } catch { - // Fall through to String(error). + return { errorMessage: 'Unknown error' } } - return { errorMessage: String(error) } } const failedIterationReport = (error: unknown, dryRun: boolean): IterationReport => { @@ -7476,7 +7492,11 @@ const contextualError = (context: string, error: unknown): Error => { const details = describeError(error) const wrapped = new Error(`${context}: ${details.errorMessage}`) if (details.errorStack) { - wrapped.stack = `${wrapped.stack ?? wrapped.message}\nCaused by: ${details.errorStack}` + const wrappedDetails = describeError(wrapped) + setSafeErrorStack( + wrapped, + `${wrappedDetails.errorStack ?? wrapped.message}\nCaused by: ${details.errorStack}`, + ) } const withCause = wrapped as Error & { cause?: unknown } withCause.cause = error diff --git a/src/orchestrator/reaper.ts b/src/orchestrator/reaper.ts index 7e0b7de..ab3125f 100644 --- a/src/orchestrator/reaper.ts +++ b/src/orchestrator/reaper.ts @@ -4,6 +4,7 @@ import { promisify } from 'node:util' import { parseJsonContent } from '../writeback/shared' import type { Clock, FleetClient, Logger } from '../ports' +import { normalizeLogger } from '../logging' import type { FactoryInFlightRegistry, FactoryInFlightRegistryAgent, FactoryInFlightRegistryProcess } from '../types' import { checkFactoryLoopLiveness, readFactoryLoopHeartbeat } from './factory' import { findAgentProcessByName, readProcessIdentity, type AgentProcessFinder, type ProcessIdentity } from './process-identity' @@ -175,6 +176,7 @@ const parsePidList = (stdout: string | Buffer | undefined): number[] => { } export async function reapFactoryOrphansOnce(opts: FactoryReaperOptions): Promise { + const logger = opts.logger ? normalizeLogger(opts.logger) : undefined const heartbeat = await readFactoryLoopHeartbeat(opts.heartbeatPath) const liveness = checkFactoryLoopLiveness(heartbeat, { nowMs: opts.nowMs ?? opts.clock?.now(), staleMs: opts.staleMs }) if (!liveness.stale) { @@ -190,7 +192,7 @@ export async function reapFactoryOrphansOnce(opts: FactoryReaperOptions): Promis const reaped: FactoryReaperReport['reaped'] = [] const skipped: FactoryReaperReport['skipped'] = [] const kill = opts.kill ?? process.kill - const protectedPids = await reaperProtectedPids(opts) + const protectedPids = await reaperProtectedPids(opts, logger) const processes = await registryProcesses(registry, opts, skipped, protectedPids) for (const processInfo of processes) { @@ -215,7 +217,7 @@ export async function reapFactoryOrphansOnce(opts: FactoryReaperOptions): Promis }) for (const entry of report.terminated) { reaped.push(entry) - opts.logger?.warn?.('[factory-reaper] reaped orphaned factory pid', { pid: entry.pid, signals: entry.signals }) + logger?.warn?.('[factory-reaper] reaped orphaned factory pid', { pid: entry.pid, signals: entry.signals }) } for (const entry of report.skipped) { skipped.push(entry) @@ -267,11 +269,11 @@ export class FactoryReaper { } } -async function reaperProtectedPids(opts: FactoryReaperOptions): Promise { +async function reaperProtectedPids(opts: FactoryReaperOptions, logger?: Logger): Promise { try { return await opts.fleet?.protectedPids?.() ?? [] } catch (error) { - opts.logger?.warn?.('[factory-reaper] failed to resolve protected fleet pids', error) + logger?.warn?.('[factory-reaper] failed to resolve protected fleet pids', error) return [] } }