diff --git a/packages/workflow-executor/CLAUDE.md b/packages/workflow-executor/CLAUDE.md index 9a3dabe201..d455ea2d29 100644 --- a/packages/workflow-executor/CLAUDE.md +++ b/packages/workflow-executor/CLAUDE.md @@ -94,6 +94,7 @@ src/ - **Pre-recorded AI decisions** — Record step executors support `preRecordedArgs` in the step definition to bypass AI calls. When provided, executors use the pre-recorded values (display names) directly instead of invoking the AI. Each record step type has its own typed `preRecordedArgs` shape. Validation happens via schema resolution — invalid display names throw `InvalidPreRecordedArgsError`. Partial args are supported: only the provided fields skip AI, the rest still use AI. - **Graceful shutdown** — `stop()` drains in-flight steps before closing resources. The `state` getter exposes the lifecycle: `idle → running → draining → stopped`. `stopTimeoutMs` (default 30s) prevents `stop()` from hanging forever if a step is stuck. The HTTP server stays up during drain so the frontend can still query run status. Signal handling (`SIGTERM`/`SIGINT`) is the consumer's responsibility — the Runner is a library class. - **Structured log context** — `BaseStepExecutor.execute()` stamps every log line with a shared `logCtx` (`runId`, `stepId`, `stepIndex`, `stepType`). Executors with type-specific identifiers add them via the `getExtraLogContext()` hook (default `{}`), keeping the base class free of step-specific knowledge — e.g. `McpStepExecutor` returns `{ mcpServerId, mcpServerName }` so MCP step logs unambiguously identify the targeted server (`mcpServerId` is canonical; `mcpServerName` is the human-readable Record key, not guaranteed unique at the DB level). `mcpServerName` is resolved by `RemoteToolFetcher.fetch()` from the scoped config Record key and forwarded to the executor constructor. +- **Logger shape** — `Logger = (level, message, context?) => void` with `LoggerLevel = 'Debug' | 'Info' | 'Warn' | 'Error'` (signature aligned with `@forestadmin/agent`; the executor extends it with a structured `context` object). Adapters `createConsoleLogger(minLevel)` (JSON) and `createPrettyLogger(minLevel)` (colorized) are factories that close over a min-level filter — calls below the threshold are dropped at the source. CLI minimum level comes from `LOG_LEVEL` env var (default `Info`); library consumers pass `loggerLevel` in `ExecutorOptions`. - **Boundary validation** — Types that cross a trust boundary (wire from the orchestrator, or mapper output) live under `src/types/validated/` as zod schemas with TS types inferred via `z.infer<>`. Strictness depends on origin: schemas the executor **produces** (mapper output) and **frontend** HTTP bodies use `.strict()` (catch our own bugs / input hygiene); the **orchestrator collection schema** instead **strips** unknown keys and requires only structural fields, with step-specific props optional and asserted at use-time by the consuming executor. This keeps the executor resilient to independent orchestrator drift — we fail at step execution, only when a step genuinely lacks what it needs, never in bulk up front for an unrelated add/remove. Validation runs where data enters (`forest-server-workflow-port.getCollectionSchema`, `run-to-available-step-mapper.toAvailableStepExecution`). On parse failure: throw `DomainValidationError` (extends `WorkflowExecutorError`) → bucketized as malformed (dispatch) or surfaced as a step error (execution). Types outside `validated/` are internal runtime state and not zod-validated. Note: `StepOutcome` is validated when it arrives as input via `previousSteps`; executor outputs are trusted by construction. ## Commands diff --git a/packages/workflow-executor/example/.env.executors.example b/packages/workflow-executor/example/.env.executors.example index 86ee59cfbc..4df6b4b7a8 100644 --- a/packages/workflow-executor/example/.env.executors.example +++ b/packages/workflow-executor/example/.env.executors.example @@ -24,4 +24,7 @@ NODE_TLS_REJECT_UNAUTHORIZED=0 # Optional — default shown. -POLLING_INTERVAL_MS=5000 \ No newline at end of file +POLLING_INTERVAL_MS=5000 + +# Optional — minimum log level (Debug | Info | Warn | Error). Default: Info. +# LOG_LEVEL=Info \ No newline at end of file diff --git a/packages/workflow-executor/example/docker-compose.executors.yml b/packages/workflow-executor/example/docker-compose.executors.yml index 5c6b8d00f9..510e13330b 100644 --- a/packages/workflow-executor/example/docker-compose.executors.yml +++ b/packages/workflow-executor/example/docker-compose.executors.yml @@ -22,6 +22,7 @@ x-executor-env: &executor-env POLLING_INTERVAL_MS: ${POLLING_INTERVAL_MS:-5000} HTTP_PORT: "3400" NODE_TLS_REJECT_UNAUTHORIZED: 0 + LOG_LEVEL: ${LOG_LEVEL} x-executor-common: &executor-common image: forest-workflow-executor:local diff --git a/packages/workflow-executor/src/adapters/console-logger.ts b/packages/workflow-executor/src/adapters/console-logger.ts index 090aaf5845..0376603d15 100644 --- a/packages/workflow-executor/src/adapters/console-logger.ts +++ b/packages/workflow-executor/src/adapters/console-logger.ts @@ -1,15 +1,22 @@ -import type { Logger } from '../ports/logger-port'; +import type { Logger, LoggerLevel } from '../ports/logger-port'; -export default class ConsoleLogger implements Logger { - error(message: string, context: Record): void { - console.error(JSON.stringify({ message, timestamp: new Date().toISOString(), ...context })); - } +const ORDER: LoggerLevel[] = ['Debug', 'Info', 'Warn', 'Error']; - warn(message: string, context: Record): void { - console.warn(JSON.stringify({ message, timestamp: new Date().toISOString(), ...context })); - } +export default function createConsoleLogger(minLevel: LoggerLevel = 'Info'): Logger { + const minIndex = ORDER.indexOf(minLevel); - info(message: string, context: Record): void { - console.info(JSON.stringify({ message, timestamp: new Date().toISOString(), ...context })); - } + return (level, message, context) => { + if (ORDER.indexOf(level) < minIndex) return; + + const payload = JSON.stringify({ + level, + message, + timestamp: new Date().toISOString(), + ...(context ?? {}), + }); + + if (level === 'Error') console.error(payload); + else if (level === 'Warn') console.warn(payload); + else console.info(payload); + }; } diff --git a/packages/workflow-executor/src/adapters/forest-server-workflow-port.ts b/packages/workflow-executor/src/adapters/forest-server-workflow-port.ts index ab38d77e52..86bfc28149 100644 --- a/packages/workflow-executor/src/adapters/forest-server-workflow-port.ts +++ b/packages/workflow-executor/src/adapters/forest-server-workflow-port.ts @@ -15,7 +15,7 @@ import type { HttpOptions } from '@forestadmin/forestadmin-client'; import { ServerUtils } from '@forestadmin/forestadmin-client'; import { z } from 'zod'; -import ConsoleLogger from './console-logger'; +import createConsoleLogger from './console-logger'; import toAvailableStepExecution from './run-to-available-step-mapper'; import toUpdateStepRequest from './step-outcome-to-update-step-mapper'; import withRetry from './with-retry'; @@ -55,7 +55,7 @@ export default class ForestServerWorkflowPort implements WorkflowPort { constructor(params: { envSecret: string; forestServerUrl: string; logger?: Logger }) { this.options = { envSecret: params.envSecret, forestServerUrl: params.forestServerUrl }; - this.logger = params.logger ?? new ConsoleLogger(); + this.logger = params.logger ?? createConsoleLogger(); } async getAvailableRuns(): Promise { @@ -74,7 +74,7 @@ export default class ForestServerWorkflowPort implements WorkflowPort { if (error instanceof WorkflowExecutorError) { malformed.push(this.toMalformedInfo(run, error)); } else { - this.logger.error('Failed to hydrate pending run — unexpected error', { + this.logger('Error', 'Failed to hydrate pending run — unexpected error', { runId: run.id, error: extractErrorMessage(error), }); @@ -171,7 +171,7 @@ export default class ForestServerWorkflowPort implements WorkflowPort { } catch (error) { // The outcome was recorded server-side; only the chain parse failed. Fall back to the // next poll cycle — don't let a malformed chain response mask the successful update. - this.logger.error('Failed to parse chained next step from /update-step response', { + this.logger('Error', 'Failed to parse chained next step from /update-step response', { runId: String(run.id), error: extractErrorMessage(error), }); diff --git a/packages/workflow-executor/src/adapters/forestadmin-client-activity-log-port.ts b/packages/workflow-executor/src/adapters/forestadmin-client-activity-log-port.ts index f72ed8089e..7ae2939643 100644 --- a/packages/workflow-executor/src/adapters/forestadmin-client-activity-log-port.ts +++ b/packages/workflow-executor/src/adapters/forestadmin-client-activity-log-port.ts @@ -44,7 +44,7 @@ export default class ForestadminClientActivityLogPort implements ActivityLogPort return { id: response.id, index: response.attributes.index }; } catch (cause) { - this.logger.error('activity log create failed', { + this.logger('Error', 'activity log create failed', { action: args.action, collectionId: args.collectionId, status: (cause as { status?: number }).status, @@ -68,7 +68,7 @@ export default class ForestadminClientActivityLogPort implements ActivityLogPort { logger: this.logger, extraRetryStatuses: [404] }, ); } catch (err) { - this.logger.error('activity log mark-as-completed failed', { + this.logger('Error', 'activity log mark-as-completed failed', { handleId: handle.id, error: extractErrorMessage(err), }); @@ -90,7 +90,7 @@ export default class ForestadminClientActivityLogPort implements ActivityLogPort { logger: this.logger, extraRetryStatuses: [404] }, ); } catch (err) { - this.logger.error('activity log mark-as-failed failed', { + this.logger('Error', 'activity log mark-as-failed failed', { handleId: handle.id, stepErrorMessage: errorMessage, error: extractErrorMessage(err), diff --git a/packages/workflow-executor/src/adapters/pretty-logger.ts b/packages/workflow-executor/src/adapters/pretty-logger.ts index 35d23d5f65..7f845c9ab3 100644 --- a/packages/workflow-executor/src/adapters/pretty-logger.ts +++ b/packages/workflow-executor/src/adapters/pretty-logger.ts @@ -1,38 +1,44 @@ -import type { Logger } from '../ports/logger-port'; +import type { Logger, LoggerLevel } from '../ports/logger-port'; import pc from 'picocolors'; +const ORDER: LoggerLevel[] = ['Debug', 'Info', 'Warn', 'Error']; + +const LABEL: Record = { + Debug: pc.blue('debug'), + Info: pc.cyan('info '), + Warn: pc.yellow('warn '), + Error: pc.red('error'), +}; + +function formatContext(context: Record): string { + const parts = Object.entries(context).map(([key, value]) => `${key}=${JSON.stringify(value)}`); + if (parts.length === 0) return ''; + + return pc.dim(parts.join(' ')); +} + +function format(level: LoggerLevel, message: string, context: Record): string { + const timestamp = pc.dim(new Date().toISOString().substring(11, 19)); + const contextStr = formatContext(context); + + return contextStr + ? `${timestamp} ${LABEL[level]} ${message} ${contextStr}` + : `${timestamp} ${LABEL[level]} ${message}`; +} + // Colorized logger for TTY/dev. Pair with ConsoleLogger for piped output. // CLI auto-picks via process.stdout.isTTY + --pretty/--json flags. NO_COLOR is honored. -export default class PrettyLogger implements Logger { - info(message: string, context: Record): void { - // eslint-disable-next-line no-console - console.info(this.format(pc.cyan('info '), message, context)); - } - - warn(message: string, context: Record): void { - // eslint-disable-next-line no-console - console.warn(this.format(pc.yellow('warn '), message, context)); - } - - error(message: string, context: Record): void { - // eslint-disable-next-line no-console - console.error(this.format(pc.red('error'), message, context)); - } - - private format(level: string, message: string, context: Record): string { - const timestamp = pc.dim(new Date().toISOString().substring(11, 19)); - const contextStr = this.formatContext(context); - - return contextStr - ? `${timestamp} ${level} ${message} ${contextStr}` - : `${timestamp} ${level} ${message}`; - } - - private formatContext(context: Record): string { - const parts = Object.entries(context).map(([key, value]) => `${key}=${JSON.stringify(value)}`); - if (parts.length === 0) return ''; - - return pc.dim(parts.join(' ')); - } +export default function createPrettyLogger(minLevel: LoggerLevel = 'Info'): Logger { + const minIndex = ORDER.indexOf(minLevel); + + return (level, message, context) => { + if (ORDER.indexOf(level) < minIndex) return; + + const line = format(level, message, context ?? {}); + + if (level === 'Error') console.error(line); + else if (level === 'Warn') console.warn(line); + else console.info(line); + }; } diff --git a/packages/workflow-executor/src/adapters/with-retry.ts b/packages/workflow-executor/src/adapters/with-retry.ts index 0c8eeab6d2..bb1d470245 100644 --- a/packages/workflow-executor/src/adapters/with-retry.ts +++ b/packages/workflow-executor/src/adapters/with-retry.ts @@ -32,7 +32,7 @@ export default async function withRetry( } catch (err) { lastError = err; if (!isRetryable(err, extraRetryStatuses) || attempt === RETRY_DELAYS_MS.length) throw err; - logger.warn(`"${label}" failed, retrying`, { + logger('Warn', `"${label}" failed, retrying`, { attempt: attempt + 1, status: (err as { status?: number }).status, error: extractErrorMessage(err), diff --git a/packages/workflow-executor/src/build-workflow-executor.ts b/packages/workflow-executor/src/build-workflow-executor.ts index c5f44cd43c..e03f450677 100644 --- a/packages/workflow-executor/src/build-workflow-executor.ts +++ b/packages/workflow-executor/src/build-workflow-executor.ts @@ -1,4 +1,4 @@ -import type { Logger } from './ports/logger-port'; +import type { Logger, LoggerLevel } from './ports/logger-port'; import type { RunnerState } from './runner'; import type { AiConfiguration } from '@forestadmin/ai-proxy'; import type { Options as SequelizeOptions } from 'sequelize'; @@ -9,13 +9,14 @@ import { Sequelize } from 'sequelize'; import AgentClientAgentPort from './adapters/agent-client-agent-port'; import AiClientAdapter from './adapters/ai-client-adapter'; import AlwaysErrorAiModelPort from './adapters/always-error-ai-model-port'; -import ConsoleLogger from './adapters/console-logger'; +import createConsoleLogger from './adapters/console-logger'; import ForestServerWorkflowPort from './adapters/forest-server-workflow-port'; import ForestadminClientActivityLogPortFactory from './adapters/forestadmin-client-activity-log-port-factory'; import ServerAiAdapter from './adapters/server-ai-adapter'; import { DEFAULT_AI_INVOKE_TIMEOUT_MS, DEFAULT_FOREST_SERVER_URL, + DEFAULT_LOGGER_LEVEL, DEFAULT_POLLING_INTERVAL_MS, DEFAULT_SCHEMA_CACHE_TTL_MS, DEFAULT_STEP_TIMEOUT_MS, @@ -43,6 +44,7 @@ export interface ExecutorOptions { aiConfigurations?: AiConfiguration[]; pollingIntervalMs?: number; logger?: Logger; + loggerLevel?: LoggerLevel; stopTimeoutMs?: number; stepTimeoutMs?: number; aiInvokeTimeoutMs?: number; @@ -65,7 +67,7 @@ function positiveOrDefault(value: number | undefined, fallback: number): number function buildCommonDependencies(options: ExecutorOptions) { const forestServerUrl = options.forestServerUrl ?? DEFAULT_FOREST_SERVER_URL; - const logger = options.logger ?? new ConsoleLogger(); + const logger = options.logger ?? createConsoleLogger(options.loggerLevel ?? DEFAULT_LOGGER_LEVEL); const workflowPort = new ForestServerWorkflowPort({ envSecret: options.envSecret, @@ -76,12 +78,12 @@ function buildCommonDependencies(options: ExecutorOptions) { const forceAiError = options.forceAiError && process.env.NODE_ENV !== 'production'; if (forceAiError) { - logger.info( + logger( + 'Info', 'FORCE_AI_ERROR is enabled — AI calls will always fail. Do not use in production.', - {}, ); } else if (options.forceAiError && process.env.NODE_ENV === 'production') { - logger.info('FORCE_AI_ERROR is set but ignored in production.', {}); + logger('Info', 'FORCE_AI_ERROR is set but ignored in production.'); } let aiModelPort; @@ -142,7 +144,7 @@ function createWorkflowExecutor( try { await server.stop(); } catch (err) { - logger.error('HTTP server close failed during shutdown', { + logger('Error', 'HTTP server close failed during shutdown', { error: err instanceof Error ? err.message : String(err), }); } @@ -151,14 +153,14 @@ function createWorkflowExecutor( }; const onSignal = async () => { - logger.info?.('Received shutdown signal, stopping gracefully...', {}); + logger('Info', 'Received shutdown signal, stopping gracefully...'); try { if (!shutdownPromise) shutdownPromise = shutdown(); await shutdownPromise; process.exitCode = 0; } catch (error) { - logger.error('Graceful shutdown failed', { + logger('Error', 'Graceful shutdown failed', { error: error instanceof Error ? error.message : String(error), }); process.exitCode = 1; @@ -167,7 +169,7 @@ function createWorkflowExecutor( // Safety net: force exit if the event loop doesn't drain // eslint-disable-next-line no-console setTimeout(() => { - logger.error('Process did not exit after shutdown — forcing exit', {}); + logger('Error', 'Process did not exit after shutdown — forcing exit'); process.exit(process.exitCode ?? 1); }, FORCE_EXIT_DELAY_MS).unref(); }; diff --git a/packages/workflow-executor/src/cli-core.ts b/packages/workflow-executor/src/cli-core.ts index 6d4e442a74..5e6a78fe65 100644 --- a/packages/workflow-executor/src/cli-core.ts +++ b/packages/workflow-executor/src/cli-core.ts @@ -1,12 +1,12 @@ /* eslint-disable no-console */ -import type { Logger } from './ports/logger-port'; +import type { Logger, LoggerLevel } from './ports/logger-port'; import type { AiConfiguration } from '@forestadmin/ai-proxy'; import { z } from 'zod'; -import ConsoleLogger from './adapters/console-logger'; -import PrettyLogger from './adapters/pretty-logger'; +import createConsoleLogger from './adapters/console-logger'; +import createPrettyLogger from './adapters/pretty-logger'; import { type DatabaseExecutorOptions, type ExecutorOptions, @@ -16,6 +16,7 @@ import { DEFAULT_AI_INVOKE_TIMEOUT_MS, DEFAULT_FOREST_SERVER_URL, DEFAULT_HTTP_PORT, + DEFAULT_LOGGER_LEVEL, DEFAULT_MAX_CHAIN_DEPTH, DEFAULT_POLLING_INTERVAL_MS, DEFAULT_SCHEMA_CACHE_TTL_MS, @@ -25,6 +26,7 @@ import { import { ConfigurationError, extractErrorMessage } from './errors'; const POSITIVE_INT = z.coerce.number().int().positive(); +const LOGGER_LEVEL_SCHEMA = z.enum(['Debug', 'Info', 'Warn', 'Error']); function parsePositiveIntEnv(name: string, raw: string | undefined): number | undefined { if (!raw) return undefined; @@ -38,6 +40,20 @@ function parsePositiveIntEnv(name: string, raw: string | undefined): number | un return parsed.data; } +function parseLoggerLevelEnv(raw: string | undefined): LoggerLevel | undefined { + if (!raw) return undefined; + + const parsed = LOGGER_LEVEL_SCHEMA.safeParse(raw); + + if (!parsed.success) { + throw new ConfigurationError( + `LOG_LEVEL must be one of Debug, Info, Warn, Error (got "${raw}")`, + ); + } + + return parsed.data; +} + // eslint-disable-next-line @typescript-eslint/no-var-requires, import/no-dynamic-require, global-require const { version } = require('../package.json') as { version: string }; @@ -100,11 +116,15 @@ export function parseArgs(argv: string[]): CliArgs { // Priority: --json → Console; --pretty → Pretty; TTY → Pretty; else Console (piped/docker/k8s/CI). // NO_COLOR is respected by picocolors so pretty output stays monochrome where ANSI is banned. -export function pickLogger(args: CliArgs, stdout: NodeJS.WriteStream = process.stdout): Logger { - if (args.json) return new ConsoleLogger(); - if (args.pretty) return new PrettyLogger(); - - return stdout.isTTY ? new PrettyLogger() : new ConsoleLogger(); +export function pickLogger( + args: CliArgs, + level: LoggerLevel, + stdout: NodeJS.WriteStream = process.stdout, +): Logger { + if (args.json) return createConsoleLogger(level); + if (args.pretty) return createPrettyLogger(level); + + return stdout.isTTY ? createPrettyLogger(level) : createConsoleLogger(level); } function parseAiConfig(env: NodeJS.ProcessEnv): AiConfiguration[] | undefined { @@ -163,6 +183,7 @@ export function readEnvConfig(env: NodeJS.ProcessEnv, args: CliArgs): CliConfig aiInvokeTimeoutMs: parsePositiveIntEnv('AI_INVOKE_TIMEOUT_MS', env.AI_INVOKE_TIMEOUT_MS), maxChainDepth: parsePositiveIntEnv('MAX_CHAIN_DEPTH', env.MAX_CHAIN_DEPTH), schemaCacheTtlMs: parsePositiveIntEnv('SCHEMA_CACHE_TTL_MS', env.SCHEMA_CACHE_TTL_MS), + loggerLevel: parseLoggerLevelEnv(env.LOG_LEVEL) ?? DEFAULT_LOGGER_LEVEL, ...(aiConfigurations && { aiConfigurations }), ...(env.FORCE_AI_ERROR === 'true' && { forceAiError: true }), }; @@ -201,6 +222,7 @@ Optional environment variables: AI_INVOKE_TIMEOUT_MS Max duration of a single AI provider invocation in ms (default: ${DEFAULT_AI_INVOKE_TIMEOUT_MS}) MAX_CHAIN_DEPTH Max steps auto-executed per run before yielding (default: ${DEFAULT_MAX_CHAIN_DEPTH}) SCHEMA_CACHE_TTL_MS Collection schema cache TTL in ms (default: ${DEFAULT_SCHEMA_CACHE_TTL_MS}) + LOG_LEVEL Debug | Info | Warn | Error (default: ${DEFAULT_LOGGER_LEVEL}) NO_COLOR Set to any value to disable ANSI colors in pretty logs FORCE_AI_ERROR Set to "true" to make every AI call fail (dev only, to test error paths) @@ -229,12 +251,13 @@ export function logStartup(logger: Logger, config: CliConfig): void { aiLabel = 'server fallback'; } - logger.info('Workflow executor starting', { + logger('Info', 'Workflow executor starting', { mode, forestServerUrl: opts.forestServerUrl ?? DEFAULT_FOREST_SERVER_URL, agentUrl: opts.agentUrl, httpPort: opts.httpPort, pollingIntervalMs: opts.pollingIntervalMs ?? DEFAULT_POLLING_INTERVAL_MS, + loggerLevel: opts.loggerLevel ?? DEFAULT_LOGGER_LEVEL, aiConfig: aiLabel, }); } @@ -259,7 +282,7 @@ export async function runCli( } const config = readEnvConfig(env, args); - const logger = pickLogger(args); + const logger = pickLogger(args, config.executorOptions.loggerLevel ?? DEFAULT_LOGGER_LEVEL); config.executorOptions.logger = logger; logStartup(logger, config); @@ -278,13 +301,13 @@ export async function runCli( } await executor.start(); - logger.info('Workflow executor ready', { + logger('Info', 'Workflow executor ready', { url: `http://localhost:${config.executorOptions.httpPort}`, }); return executor; } catch (error) { - logger.error('Workflow executor failed to start', { + logger('Error', 'Workflow executor failed to start', { error: extractErrorMessage(error), }); throw error; diff --git a/packages/workflow-executor/src/defaults.ts b/packages/workflow-executor/src/defaults.ts index b0e9784dda..726f6eddde 100644 --- a/packages/workflow-executor/src/defaults.ts +++ b/packages/workflow-executor/src/defaults.ts @@ -1,3 +1,5 @@ +import type { LoggerLevel } from './ports/logger-port'; + export const DEFAULT_HTTP_PORT = 3400; export const DEFAULT_FOREST_SERVER_URL = 'https://api.forestadmin.com'; export const DEFAULT_POLLING_INTERVAL_MS = 30_000; @@ -6,3 +8,4 @@ export const DEFAULT_AI_INVOKE_TIMEOUT_MS = 30_000; export const DEFAULT_STOP_TIMEOUT_MS = 30_000; export const DEFAULT_MAX_CHAIN_DEPTH = 50; export const DEFAULT_SCHEMA_CACHE_TTL_MS = 10 * 60_000; +export const DEFAULT_LOGGER_LEVEL: LoggerLevel = 'Info'; diff --git a/packages/workflow-executor/src/executors/base-step-executor.ts b/packages/workflow-executor/src/executors/base-step-executor.ts index fb91e1549f..771b910256 100644 --- a/packages/workflow-executor/src/executors/base-step-executor.ts +++ b/packages/workflow-executor/src/executors/base-step-executor.ts @@ -44,7 +44,7 @@ export default abstract class BaseStepExecutor { const { baseRecordRef } = this.context; - this.context.logger.info('Step execution started', { + this.context.logger('Info', 'Step execution started', { ...this.logCtx, collection: baseRecordRef.collectionName, }); @@ -55,7 +55,7 @@ export default abstract class BaseStepExecutor { if (!hasTimeoutFired) return; - this.context.logger.warn('Step work rejected after timeout — result discarded', { + this.context.logger('Warn', 'Step work rejected after timeout — result discarded', { ...this.logCtx, error: extractErrorMessage(err), }); diff --git a/packages/workflow-executor/src/executors/load-related-record-step-executor.ts b/packages/workflow-executor/src/executors/load-related-record-step-executor.ts index 232e359f38..448794b9c5 100644 --- a/packages/workflow-executor/src/executors/load-related-record-step-executor.ts +++ b/packages/workflow-executor/src/executors/load-related-record-step-executor.ts @@ -598,7 +598,7 @@ export default class LoadRelatedRecordStepExecutor extends RecordStepExecutor try { formattedResponse = await this.formatToolResult(target, toolResult); } catch (cause) { - this.context.logger.error('Failed to format MCP tool result, using generic fallback', { + this.context.logger('Error', 'Failed to format MCP tool result, using generic fallback', { runId: this.context.runId, stepIndex: this.context.stepIndex, toolName: target.name, @@ -175,7 +175,8 @@ export default class McpStepExecutor extends BaseStepExecutor executionResult: { ...baseExecutionResult, formattedResponse }, }); } catch (cause) { - this.context.logger.error( + this.context.logger( + 'Error', 'MCP tool result formatted but enriched state could not be persisted', { runId: this.context.runId, diff --git a/packages/workflow-executor/src/executors/step-executor-factory.ts b/packages/workflow-executor/src/executors/step-executor-factory.ts index 3fd1533df9..68e4795716 100644 --- a/packages/workflow-executor/src/executors/step-executor-factory.ts +++ b/packages/workflow-executor/src/executors/step-executor-factory.ts @@ -95,7 +95,7 @@ export default class StepExecutorFactory { ); } } catch (error) { - contextConfig.logger.error('Step execution failed unexpectedly', { + contextConfig.logger('Error', 'Step execution failed unexpectedly', { runId: step.runId, stepId: step.stepId, stepIndex: step.stepIndex, diff --git a/packages/workflow-executor/src/http/executor-http-server.ts b/packages/workflow-executor/src/http/executor-http-server.ts index a1926cbb9b..86fb86a09f 100644 --- a/packages/workflow-executor/src/http/executor-http-server.ts +++ b/packages/workflow-executor/src/http/executor-http-server.ts @@ -11,7 +11,7 @@ import Koa from 'koa'; import koaJwt from 'koa-jwt'; import serializeStepForWire from './step-serializer'; -import ConsoleLogger from '../adapters/console-logger'; +import createConsoleLogger from '../adapters/console-logger'; import { RunNotFoundError, UserMismatchError, @@ -35,7 +35,7 @@ export default class ExecutorHttpServer { constructor(options: ExecutorHttpServerOptions) { this.options = options; - this.logger = options.logger ?? new ConsoleLogger(); + this.logger = options.logger ?? createConsoleLogger(); this.app = new Koa(); // Error middleware — catches all errors (including JWT 401) and returns structured JSON @@ -52,7 +52,7 @@ export default class ExecutorHttpServer { return; } - this.logger.error('Unhandled HTTP error', { + this.logger('Error', 'Unhandled HTTP error', { method: ctx.method, path: ctx.path, error: extractErrorMessage(err), @@ -143,7 +143,7 @@ export default class ExecutorHttpServer { return; } } catch (err) { - this.logger.error('Failed to check run access', { + this.logger('Error', 'Failed to check run access', { runId: ctx.params.runId, method: ctx.method, path: ctx.path, @@ -192,7 +192,7 @@ export default class ExecutorHttpServer { } if (err instanceof UserMismatchError) { - this.logger.error('User mismatch on trigger', { runId, bearerUserId }); + this.logger('Error', 'User mismatch on trigger', { runId, bearerUserId }); ctx.status = 403; ctx.body = { error: 'Forbidden' }; @@ -200,7 +200,7 @@ export default class ExecutorHttpServer { } if (err instanceof WorkflowExecutorError) { - this.logger.error('Malformed run on trigger', { + this.logger('Error', 'Malformed run on trigger', { runId, bearerUserId, error: extractErrorMessage(err), diff --git a/packages/workflow-executor/src/ports/logger-port.ts b/packages/workflow-executor/src/ports/logger-port.ts index 8fe56a50dc..a0bde7cbbc 100644 --- a/packages/workflow-executor/src/ports/logger-port.ts +++ b/packages/workflow-executor/src/ports/logger-port.ts @@ -1,5 +1,7 @@ -export interface Logger { - error(message: string, context: Record): void; - warn(message: string, context: Record): void; - info(message: string, context: Record): void; -} +export type LoggerLevel = 'Debug' | 'Info' | 'Warn' | 'Error'; + +export type Logger = ( + level: LoggerLevel, + message: string, + context?: Record, +) => void; diff --git a/packages/workflow-executor/src/remote-tool-fetcher.ts b/packages/workflow-executor/src/remote-tool-fetcher.ts index d79c956adf..1b79c44c24 100644 --- a/packages/workflow-executor/src/remote-tool-fetcher.ts +++ b/packages/workflow-executor/src/remote-tool-fetcher.ts @@ -58,7 +58,8 @@ export default class RemoteToolFetcher { .map(cfg => cfg.id) .filter((id): id is string => Boolean(id)); - this.logger.warn( + this.logger( + 'Warn', Object.keys(configs).length === 0 ? 'MCP step targets a server but orchestrator returned no MCP configs' : 'MCP step targets a server not advertised by the orchestrator', @@ -82,7 +83,7 @@ export default class RemoteToolFetcher { if (failedConfigNames.length === 0) return; - this.logger.error('MCP servers failed to load tools', { + this.logger('Error', 'MCP servers failed to load tools', { requestedMcpServerId: mcpServerId, mcpServerName, failedConfigNames, diff --git a/packages/workflow-executor/src/runner.ts b/packages/workflow-executor/src/runner.ts index 79ea45ba22..1afcf599b5 100644 --- a/packages/workflow-executor/src/runner.ts +++ b/packages/workflow-executor/src/runner.ts @@ -10,7 +10,7 @@ import type { AvailableStepExecution, StepExecutionResult } from './types/execut import type { StepExecutionData } from './types/step-execution-data'; import type { StepOutcome } from './types/validated/step-outcome'; -import ConsoleLogger from './adapters/console-logger'; +import createConsoleLogger from './adapters/console-logger'; import { DEFAULT_MAX_CHAIN_DEPTH, DEFAULT_STOP_TIMEOUT_MS } from './defaults'; import { MalformedRunError, @@ -61,7 +61,7 @@ export default class Runner { constructor(config: RunnerConfig) { this.config = config; - this.logger = config.logger ?? new ConsoleLogger(); + this.logger = config.logger ?? createConsoleLogger(); this.remoteToolFetcher = new RemoteToolFetcher( config.workflowPort, config.aiModelPort, @@ -84,7 +84,7 @@ export default class Runner { // Probe the agent first so we fail fast without opening DB connections when unreachable. await this.config.agentPort.probe(); - this.logger.info('Agent probe passed', {}); + this.logger('Info', 'Agent probe passed', {}); await this.config.runStore.init(this.logger); this._state = 'running'; @@ -96,7 +96,7 @@ export default class Runner { if (this._state === 'idle' || this._state === 'stopped' || this._state === 'draining') return; this._state = 'draining'; - this.logger.info('Graceful shutdown initiated', { inFlightRuns: this.inFlightRuns.size }); + this.logger('Info', 'Graceful shutdown initiated', { inFlightRuns: this.inFlightRuns.size }); if (this.pollingTimer !== null) { clearTimeout(this.pollingTimer); @@ -106,7 +106,7 @@ export default class Runner { try { // Drain in-flight runs (each entry may cover a whole auto-chain). if (this.inFlightRuns.size > 0) { - this.logger.info('Draining in-flight runs', { + this.logger('Info', 'Draining in-flight runs', { count: this.inFlightRuns.size, runs: [...this.inFlightRuns.keys()], }); @@ -125,12 +125,12 @@ export default class Runner { ]); if (drainResult === 'timeout') { - this.logger.error('Drain timeout — runs still in flight', { + this.logger('Error', 'Drain timeout — runs still in flight', { remainingRuns: [...this.inFlightRuns.keys()], timeoutMs: timeout, }); } else { - this.logger.info('All in-flight runs drained', {}); + this.logger('Info', 'All in-flight runs drained', {}); } } @@ -145,14 +145,14 @@ export default class Runner { for (const result of results) { if (result.status === 'rejected') { - this.logger.error('Resource cleanup failed during shutdown', { + this.logger('Error', 'Resource cleanup failed during shutdown', { error: result.reason instanceof Error ? result.reason.message : String(result.reason), }); } } } finally { this._state = 'stopped'; - this.logger.info('Workflow executor stopped', {}); + this.logger('Info', 'Workflow executor stopped', {}); } } @@ -185,7 +185,7 @@ export default class Runner { } if (this.inFlightRuns.has(step.runId)) { - this.logger.info('Trigger ignored — run already in flight', { + this.logger('Info', 'Trigger ignored — run already in flight', { runId: step.runId, stepIndex: step.stepIndex, }); @@ -208,7 +208,7 @@ export default class Runner { await Promise.allSettled(malformed.map(info => this.reportMalformedRun(info))); const dispatchable = pending.filter(d => !this.inFlightRuns.has(d.step.runId)); - this.logger.info('Poll cycle completed', { + this.logger('Info', 'Poll cycle completed', { fetched: pending.length, dispatching: dispatchable.length, malformed: malformed.length, @@ -217,7 +217,7 @@ export default class Runner { dispatchable.map(d => this.executeStep(d.step, d.auth.forestServerToken)), ); } catch (error) { - this.logger.error('Poll cycle failed', { + this.logger('Error', 'Poll cycle failed', { error: extractErrorMessage(error), stack: error instanceof Error ? error.stack : undefined, }); @@ -231,7 +231,7 @@ export default class Runner { // ops has to clean up manually. private async reportMalformedRun(info: MalformedRunInfo): Promise { if (info.stepId === null || info.stepIndex === null) { - this.logger.error('Malformed run cannot be reported — no available step identified', { + this.logger('Error', 'Malformed run cannot be reported — no available step identified', { runId: info.runId, error: info.technicalMessage, }); @@ -247,13 +247,13 @@ export default class Runner { status: 'error', error: info.userMessage, }); - this.logger.error('Malformed run reported as error', { + this.logger('Error', 'Malformed run reported as error', { runId: info.runId, stepIndex: info.stepIndex, error: info.technicalMessage, }); } catch (reportErr) { - this.logger.error('Malformed run — also failed to report', { + this.logger('Error', 'Malformed run — also failed to report', { runId: info.runId, mappingError: info.technicalMessage, reportError: extractErrorMessage(reportErr), @@ -303,12 +303,16 @@ export default class Runner { ); result = await executor.execute(); } catch (error) { - this.logger.error('FATAL: executor contract violated — reporting synthetic error outcome', { - runId: currentStep.runId, - stepId: currentStep.stepId, - stepIndex: currentStep.stepIndex, - error: extractErrorMessage(error), - }); + this.logger( + 'Error', + 'FATAL: executor contract violated — reporting synthetic error outcome', + { + runId: currentStep.runId, + stepId: currentStep.stepId, + stepIndex: currentStep.stepIndex, + error: extractErrorMessage(error), + }, + ); // Report a synthetic error outcome so the orchestrator marks the run failed and stops // re-dispatching — without this, the contract-violating step loops forever. @@ -323,7 +327,7 @@ export default class Runner { try { await this.config.workflowPort.updateStepExecution(currentStep.runId, syntheticOutcome); } catch (reportErr) { - this.logger.error('FATAL: also failed to report synthetic error outcome', { + this.logger('Error', 'FATAL: also failed to report synthetic error outcome', { runId: currentStep.runId, stepId: currentStep.stepId, reportError: extractErrorMessage(reportErr), @@ -341,7 +345,7 @@ export default class Runner { result.stepOutcome, ); } catch (error) { - this.logger.error('Failed to report step outcome', { + this.logger('Error', 'Failed to report step outcome', { runId: currentStep.runId, stepId: currentStep.stepId, stepIndex: currentStep.stepIndex, @@ -354,7 +358,7 @@ export default class Runner { } if (nextDispatch === null) { - this.logger.info('Chain completed — orchestrator returned no further step', { + this.logger('Info', 'Chain completed — orchestrator returned no further step', { runId: currentStep.runId, stepIndex: currentStep.stepIndex, }); @@ -370,7 +374,7 @@ export default class Runner { nextDispatch.step.runId !== currentStep.runId || nextDispatch.step.stepIndex <= currentStep.stepIndex ) { - this.logger.error('Server returned non-progressing next step — exiting chain', { + this.logger('Error', 'Server returned non-progressing next step — exiting chain', { runId: currentStep.runId, currentStepIndex: currentStep.stepIndex, returnedRunId: nextDispatch.step.runId, @@ -383,7 +387,7 @@ export default class Runner { // Cap check BEFORE incrementing: chainedCount counts chained steps we've already executed. // maxDepth=2 means "run up to 2 chained steps after the initial one" (3 total). if (chainedCount >= maxDepth) { - this.logger.info('Chain depth cap reached — yielding to next poll', { + this.logger('Info', 'Chain depth cap reached — yielding to next poll', { runId: currentStep.runId, stepIndex: currentStep.stepIndex, maxDepth, @@ -394,7 +398,7 @@ export default class Runner { // Graceful stop: finish the current step, then yield instead of chaining further. if (this._state === 'draining') { - this.logger.info('Chain interrupted by stop() — yielding', { + this.logger('Info', 'Chain interrupted by stop() — yielding', { runId: currentStep.runId, stepIndex: currentStep.stepIndex, }); diff --git a/packages/workflow-executor/src/stores/database-store.ts b/packages/workflow-executor/src/stores/database-store.ts index 7eb587be88..99641c8b49 100644 --- a/packages/workflow-executor/src/stores/database-store.ts +++ b/packages/workflow-executor/src/stores/database-store.ts @@ -81,7 +81,7 @@ export default class DatabaseStore implements RunStore { try { await umzug.up(); } catch (error) { - logger?.error('Database migration failed', { + logger?.('Error', 'Database migration failed', { error: extractErrorMessage(error), }); throw error; @@ -127,7 +127,7 @@ export default class DatabaseStore implements RunStore { try { await this.sequelize.close(); } catch (error) { - logger?.error('Failed to close database connection', { + logger?.('Error', 'Failed to close database connection', { error: extractErrorMessage(error), }); } diff --git a/packages/workflow-executor/test/adapters/console-logger.test.ts b/packages/workflow-executor/test/adapters/console-logger.test.ts index d7d8af3826..77080453d5 100644 --- a/packages/workflow-executor/test/adapters/console-logger.test.ts +++ b/packages/workflow-executor/test/adapters/console-logger.test.ts @@ -1,35 +1,78 @@ -import ConsoleLogger from '../../src/adapters/console-logger'; +import createConsoleLogger from '../../src/adapters/console-logger'; -describe('ConsoleLogger', () => { - let logger: ConsoleLogger; +describe('createConsoleLogger', () => { + let logger: ReturnType; beforeEach(() => { - logger = new ConsoleLogger(); + logger = createConsoleLogger(); }); - it('info() writes to console.info as JSON', () => { + it('Info level writes to console.info as JSON', () => { const spy = jest.spyOn(console, 'info').mockImplementation(); - logger.info('test message', { key: 'value' }); + logger('Info', 'test message', { key: 'value' }); expect(spy).toHaveBeenCalledTimes(1); const output = JSON.parse(spy.mock.calls[0][0]); - expect(output).toMatchObject({ message: 'test message', key: 'value' }); + expect(output).toMatchObject({ level: 'Info', message: 'test message', key: 'value' }); expect(output.timestamp).toBeDefined(); spy.mockRestore(); }); - it('warn() writes to console.warn as JSON', () => { + it('Warn level writes to console.warn as JSON', () => { const spy = jest.spyOn(console, 'warn').mockImplementation(); - logger.warn('something suspicious', { count: 3 }); + logger('Warn', 'something suspicious', { count: 3 }); expect(spy).toHaveBeenCalledTimes(1); const output = JSON.parse(spy.mock.calls[0][0]); - expect(output).toMatchObject({ message: 'something suspicious', count: 3 }); + expect(output).toMatchObject({ level: 'Warn', message: 'something suspicious', count: 3 }); expect(output.timestamp).toBeDefined(); spy.mockRestore(); }); + + it('Error level writes to console.error as JSON', () => { + const spy = jest.spyOn(console, 'error').mockImplementation(); + + logger('Error', 'boom', { code: 'E1' }); + + expect(spy).toHaveBeenCalledTimes(1); + const output = JSON.parse(spy.mock.calls[0][0]); + expect(output).toMatchObject({ level: 'Error', message: 'boom', code: 'E1' }); + + spy.mockRestore(); + }); + + it('omits log calls below the configured minimum level', () => { + const filtered = createConsoleLogger('Warn'); + const infoSpy = jest.spyOn(console, 'info').mockImplementation(); + const warnSpy = jest.spyOn(console, 'warn').mockImplementation(); + const errorSpy = jest.spyOn(console, 'error').mockImplementation(); + + filtered('Debug', 'dbg'); + filtered('Info', 'info'); + filtered('Warn', 'warn'); + filtered('Error', 'err'); + + expect(infoSpy).not.toHaveBeenCalled(); + expect(warnSpy).toHaveBeenCalledTimes(1); + expect(errorSpy).toHaveBeenCalledTimes(1); + + infoSpy.mockRestore(); + warnSpy.mockRestore(); + errorSpy.mockRestore(); + }); + + it('accepts a missing context argument', () => { + const spy = jest.spyOn(console, 'info').mockImplementation(); + + logger('Info', 'no ctx'); + + const output = JSON.parse(spy.mock.calls[0][0]); + expect(output).toMatchObject({ level: 'Info', message: 'no ctx' }); + + spy.mockRestore(); + }); }); diff --git a/packages/workflow-executor/test/adapters/forest-server-workflow-port.test.ts b/packages/workflow-executor/test/adapters/forest-server-workflow-port.test.ts index 30c8a4eaca..9991dd1d8b 100644 --- a/packages/workflow-executor/test/adapters/forest-server-workflow-port.test.ts +++ b/packages/workflow-executor/test/adapters/forest-server-workflow-port.test.ts @@ -314,7 +314,7 @@ describe('ForestServerWorkflowPort', () => { }); it('logs and skips when the mapping throws a non-WorkflowExecutorError', async () => { - const logger = { error: jest.fn(), warn: jest.fn(), info: jest.fn() }; + const logger = jest.fn(); const portWithLogger = new ForestServerWorkflowPort({ ...options, logger }); // Simulate a non-domain error by passing a run whose workflowHistory will // blow up a pure JS operation inside the mapper (missing `find` on non-array). @@ -325,7 +325,8 @@ describe('ForestServerWorkflowPort', () => { expect(result.pending).toEqual([]); expect(result.malformed).toEqual([]); - expect(logger.error).toHaveBeenCalledWith( + expect(logger).toHaveBeenCalledWith( + 'Error', 'Failed to hydrate pending run — unexpected error', expect.objectContaining({ runId: 111 }), ); diff --git a/packages/workflow-executor/test/adapters/forestadmin-client-activity-log-port-factory.test.ts b/packages/workflow-executor/test/adapters/forestadmin-client-activity-log-port-factory.test.ts index fd5a89e465..bfeea0e486 100644 --- a/packages/workflow-executor/test/adapters/forestadmin-client-activity-log-port-factory.test.ts +++ b/packages/workflow-executor/test/adapters/forestadmin-client-activity-log-port-factory.test.ts @@ -4,7 +4,7 @@ import ForestadminClientActivityLogPort from '../../src/adapters/forestadmin-cli import ForestadminClientActivityLogPortFactory from '../../src/adapters/forestadmin-client-activity-log-port-factory'; function makeLogger() { - return { info: jest.fn(), warn: jest.fn(), error: jest.fn() }; + return jest.fn(); } function makeService(): jest.Mocked { diff --git a/packages/workflow-executor/test/adapters/forestadmin-client-activity-log-port.test.ts b/packages/workflow-executor/test/adapters/forestadmin-client-activity-log-port.test.ts index 428206a2d9..138f18a0be 100644 --- a/packages/workflow-executor/test/adapters/forestadmin-client-activity-log-port.test.ts +++ b/packages/workflow-executor/test/adapters/forestadmin-client-activity-log-port.test.ts @@ -5,7 +5,7 @@ import ForestadminClientActivityLogPort from '../../src/adapters/forestadmin-cli import { ActivityLogCreationError } from '../../src/errors'; function makeLogger() { - return { info: jest.fn(), warn: jest.fn(), error: jest.fn() }; + return jest.fn(); } function makeService(): jest.Mocked { @@ -95,7 +95,8 @@ describe('ForestadminClientActivityLogPort', () => { expect(handle).toEqual({ id: 'log-2', index: '1' }); expect(service.createActivityLog).toHaveBeenCalledTimes(2); - expect(logger.warn).toHaveBeenCalledWith( + expect(logger).toHaveBeenCalledWith( + 'Warn', expect.stringContaining('activity log create'), expect.objectContaining({ attempt: 1 }), ); @@ -211,7 +212,8 @@ describe('ForestadminClientActivityLogPort', () => { const promise = port.markSucceeded({ id: 'log-1', index: '0' }); await jest.advanceTimersByTimeAsync(2_600); await expect(promise).resolves.toBeUndefined(); - expect(logger.error).toHaveBeenCalledWith( + expect(logger).toHaveBeenCalledWith( + 'Error', 'activity log mark-as-completed failed', expect.objectContaining({ handleId: 'log-1' }), ); @@ -263,7 +265,8 @@ describe('ForestadminClientActivityLogPort', () => { const promise = port.markFailed({ id: 'log-1', index: '0' }, 'step-error-msg'); await jest.advanceTimersByTimeAsync(2_600); await expect(promise).resolves.toBeUndefined(); - expect(logger.error).toHaveBeenCalledWith( + expect(logger).toHaveBeenCalledWith( + 'Error', 'activity log mark-as-failed failed', expect.objectContaining({ handleId: 'log-1', diff --git a/packages/workflow-executor/test/adapters/pretty-logger.test.ts b/packages/workflow-executor/test/adapters/pretty-logger.test.ts index f89c859143..8f9ffe74af 100644 --- a/packages/workflow-executor/test/adapters/pretty-logger.test.ts +++ b/packages/workflow-executor/test/adapters/pretty-logger.test.ts @@ -1,16 +1,16 @@ -import PrettyLogger from '../../src/adapters/pretty-logger'; +import createPrettyLogger from '../../src/adapters/pretty-logger'; // eslint-disable-next-line no-control-regex const ANSI_PATTERN = /\x1B\[[0-9;]*m/g; const stripAnsi = (s: string): string => s.replace(ANSI_PATTERN, ''); -describe('PrettyLogger', () => { - let logger: PrettyLogger; +describe('createPrettyLogger', () => { + let logger: ReturnType; let infoSpy: jest.SpyInstance; let errorSpy: jest.SpyInstance; beforeEach(() => { - logger = new PrettyLogger(); + logger = createPrettyLogger(); infoSpy = jest.spyOn(console, 'info').mockImplementation(() => {}); errorSpy = jest.spyOn(console, 'error').mockImplementation(() => {}); }); @@ -20,9 +20,9 @@ describe('PrettyLogger', () => { errorSpy.mockRestore(); }); - describe('info', () => { + describe('Info', () => { it('prints the timestamp, level, message and context', () => { - logger.info('Poll cycle completed', { fetched: 0, dispatching: 0 }); + logger('Info', 'Poll cycle completed', { fetched: 0, dispatching: 0 }); expect(infoSpy).toHaveBeenCalledTimes(1); const output = stripAnsi(infoSpy.mock.calls[0][0] as string); @@ -32,14 +32,21 @@ describe('PrettyLogger', () => { }); it('omits the context chunk when empty', () => { - logger.info('Ready', {}); + logger('Info', 'Ready', {}); + + const output = stripAnsi(infoSpy.mock.calls[0][0] as string); + expect(output).toMatch(/^\d{2}:\d{2}:\d{2} info {2}Ready$/); + }); + + it('omits the context chunk when the arg is missing', () => { + logger('Info', 'Ready'); const output = stripAnsi(infoSpy.mock.calls[0][0] as string); expect(output).toMatch(/^\d{2}:\d{2}:\d{2} info {2}Ready$/); }); it('JSON-quotes string values in context', () => { - logger.info('Step execution started', { runId: '42', stepIndex: 2 }); + logger('Info', 'Step execution started', { runId: '42', stepIndex: 2 }); const output = stripAnsi(infoSpy.mock.calls[0][0] as string); expect(output).toContain('runId="42"'); @@ -47,16 +54,16 @@ describe('PrettyLogger', () => { }); it('preserves context insertion order', () => { - logger.info('ordered', { a: 1, b: 2, c: 3 }); + logger('Info', 'ordered', { a: 1, b: 2, c: 3 }); const output = stripAnsi(infoSpy.mock.calls[0][0] as string); expect(output).toMatch(/a=1 b=2 c=3$/); }); }); - describe('error', () => { + describe('Error', () => { it('prints on console.error with "error" level', () => { - logger.error('Poll cycle failed', { error: 'timeout' }); + logger('Error', 'Poll cycle failed', { error: 'timeout' }); expect(errorSpy).toHaveBeenCalledTimes(1); expect(infoSpy).not.toHaveBeenCalled(); @@ -65,11 +72,11 @@ describe('PrettyLogger', () => { }); }); - describe('warn', () => { + describe('Warn', () => { it('prints on console.warn with "warn" level', () => { const warnSpy = jest.spyOn(console, 'warn').mockImplementation(() => {}); - logger.warn('rate limit approaching', { remaining: 5 }); + logger('Warn', 'rate limit approaching', { remaining: 5 }); expect(warnSpy).toHaveBeenCalledTimes(1); expect(infoSpy).not.toHaveBeenCalled(); @@ -79,4 +86,22 @@ describe('PrettyLogger', () => { warnSpy.mockRestore(); }); }); + + describe('level filtering', () => { + it('drops messages strictly below the configured minimum', () => { + const warnSpy = jest.spyOn(console, 'warn').mockImplementation(() => {}); + const filtered = createPrettyLogger('Warn'); + + filtered('Debug', 'dbg'); + filtered('Info', 'info'); + filtered('Warn', 'warn'); + filtered('Error', 'err'); + + expect(infoSpy).not.toHaveBeenCalled(); + expect(warnSpy).toHaveBeenCalledTimes(1); + expect(errorSpy).toHaveBeenCalledTimes(1); + + warnSpy.mockRestore(); + }); + }); }); diff --git a/packages/workflow-executor/test/adapters/run-to-available-step-mapper.test.ts b/packages/workflow-executor/test/adapters/run-to-available-step-mapper.test.ts index 8919712a43..f2d78a4d71 100644 --- a/packages/workflow-executor/test/adapters/run-to-available-step-mapper.test.ts +++ b/packages/workflow-executor/test/adapters/run-to-available-step-mapper.test.ts @@ -17,12 +17,12 @@ import { import { DomainValidationError, InvalidStepDefinitionError } from '../../src/errors'; import { StepType } from '../../src/types/validated/step-definition'; -const logger = { info: jest.fn(), warn: jest.fn(), error: jest.fn() }; +const logger = jest.fn(); beforeEach(() => { - logger.info.mockClear(); - logger.warn.mockClear(); - logger.error.mockClear(); + logger.mockClear(); + logger.mockClear(); + logger.mockClear(); }); function makeTaskStepDef( diff --git a/packages/workflow-executor/test/adapters/with-retry.test.ts b/packages/workflow-executor/test/adapters/with-retry.test.ts index 098c525b90..f1df0e4f5d 100644 --- a/packages/workflow-executor/test/adapters/with-retry.test.ts +++ b/packages/workflow-executor/test/adapters/with-retry.test.ts @@ -2,11 +2,7 @@ import type { Logger } from '../../src/ports/logger-port'; import withRetry from '../../src/adapters/with-retry'; -const makeLogger = (): jest.Mocked => ({ - info: jest.fn(), - warn: jest.fn(), - error: jest.fn(), -}); +const makeLogger = (): jest.MockedFunction => jest.fn(); const makeHttpError = (status: number) => { const err = new Error(`HTTP ${status}`); @@ -32,7 +28,7 @@ describe('withRetry', () => { expect(result).toBe('ok'); expect(fn).toHaveBeenCalledTimes(1); - expect(logger.warn).not.toHaveBeenCalled(); + expect(logger).not.toHaveBeenCalled(); }); it('retries on retryable HTTP status codes (503)', async () => { @@ -44,7 +40,8 @@ describe('withRetry', () => { await expect(promise).resolves.toBe('ok'); expect(fn).toHaveBeenCalledTimes(2); - expect(logger.warn).toHaveBeenCalledWith( + expect(logger).toHaveBeenCalledWith( + 'Warn', '"test" failed, retrying', expect.objectContaining({ attempt: 1 }), ); @@ -123,7 +120,8 @@ describe('withRetry', () => { await expect(promise).resolves.toBe('ok'); expect(fn).toHaveBeenCalledTimes(2); - expect(logger.warn).toHaveBeenCalledWith( + expect(logger).toHaveBeenCalledWith( + 'Warn', '"test" failed, retrying', expect.objectContaining({ attempt: 1, status: 404 }), ); @@ -135,7 +133,7 @@ describe('withRetry', () => { await expect(withRetry('test', fn, { logger })).rejects.toMatchObject({ status: 404 }); expect(fn).toHaveBeenCalledTimes(1); - expect(logger.warn).not.toHaveBeenCalled(); + expect(logger).not.toHaveBeenCalled(); }); it('throws immediately on non-retryable errors (4xx)', async () => { @@ -144,7 +142,7 @@ describe('withRetry', () => { await expect(withRetry('test', fn, { logger })).rejects.toMatchObject({ status: 400 }); expect(fn).toHaveBeenCalledTimes(1); - expect(logger.warn).not.toHaveBeenCalled(); + expect(logger).not.toHaveBeenCalled(); }); it('throws immediately on errors with no status', async () => { diff --git a/packages/workflow-executor/test/cli.test.ts b/packages/workflow-executor/test/cli.test.ts index a09b44fb39..ca489e6a8b 100644 --- a/packages/workflow-executor/test/cli.test.ts +++ b/packages/workflow-executor/test/cli.test.ts @@ -1,8 +1,6 @@ import type { WorkflowExecutor } from '../src/build-workflow-executor'; import type { CliFactories } from '../src/cli-core'; -import ConsoleLogger from '../src/adapters/console-logger'; -import PrettyLogger from '../src/adapters/pretty-logger'; import { logStartup, parseArgs, @@ -21,6 +19,17 @@ import { DEFAULT_STEP_TIMEOUT_MS, DEFAULT_STOP_TIMEOUT_MS, } from '../src/defaults'; +import { ConfigurationError } from '../src/errors'; + +function isJsonLogger(out: string): boolean { + try { + JSON.parse(out); + + return true; + } catch { + return false; + } +} const baseEnv: NodeJS.ProcessEnv = { FOREST_ENV_SECRET: 'env-secret', @@ -89,29 +98,51 @@ describe('parseArgs', () => { describe('pickLogger', () => { const baseArgs = { help: false, version: false, inMemory: false, pretty: false, json: false }; + let infoSpy: jest.SpyInstance; - it('returns PrettyLogger when stdout is a TTY', () => { - expect(pickLogger(baseArgs, fakeStream(true))).toBeInstanceOf(PrettyLogger); + beforeEach(() => { + infoSpy = jest.spyOn(console, 'info').mockImplementation(() => {}); }); + afterEach(() => infoSpy.mockRestore()); - it('returns ConsoleLogger when stdout is not a TTY', () => { - expect(pickLogger(baseArgs, fakeStream(false))).toBeInstanceOf(ConsoleLogger); + const sample = (logger: ReturnType): string => { + logger('Info', 'sample', { k: 'v' }); + + return infoSpy.mock.calls[0][0] as string; + }; + + it('returns a pretty (formatted) logger when stdout is a TTY', () => { + const out = sample(pickLogger(baseArgs, 'Info', fakeStream(true))); + expect(isJsonLogger(out)).toBe(false); + expect(out).toContain('sample'); }); - it('forces PrettyLogger with --pretty even when stdout is not a TTY', () => { - expect(pickLogger({ ...baseArgs, pretty: true }, fakeStream(false))).toBeInstanceOf( - PrettyLogger, - ); + it('returns a JSON (console) logger when stdout is not a TTY', () => { + const out = sample(pickLogger(baseArgs, 'Info', fakeStream(false))); + expect(isJsonLogger(out)).toBe(true); + }); + + it('forces a pretty logger with --pretty even when stdout is not a TTY', () => { + const out = sample(pickLogger({ ...baseArgs, pretty: true }, 'Info', fakeStream(false))); + expect(isJsonLogger(out)).toBe(false); }); - it('forces ConsoleLogger with --json even when stdout is a TTY', () => { - expect(pickLogger({ ...baseArgs, json: true }, fakeStream(true))).toBeInstanceOf(ConsoleLogger); + it('forces a JSON logger with --json even when stdout is a TTY', () => { + const out = sample(pickLogger({ ...baseArgs, json: true }, 'Info', fakeStream(true))); + expect(isJsonLogger(out)).toBe(true); }); it('gives --json precedence when both flags are set', () => { - expect(pickLogger({ ...baseArgs, pretty: true, json: true }, fakeStream(true))).toBeInstanceOf( - ConsoleLogger, + const out = sample( + pickLogger({ ...baseArgs, pretty: true, json: true }, 'Info', fakeStream(true)), ); + expect(isJsonLogger(out)).toBe(true); + }); + + it('filters log calls below the requested level', () => { + const logger = pickLogger({ ...baseArgs, json: true }, 'Warn', fakeStream(false)); + logger('Info', 'noisy'); + expect(infoSpy).not.toHaveBeenCalled(); }); }); @@ -271,6 +302,42 @@ describe('readEnvConfig', () => { readEnvConfig({ ...baseEnv, AI_PROVIDER: 'bogus', AI_MODEL: 'm', AI_API_KEY: 'k' }, args), ).toThrow('AI_PROVIDER must be "anthropic" or "openai"'); }); + + it.each(['Debug', 'Info', 'Warn', 'Error'] as const)( + 'parses LOG_LEVEL=%s into loggerLevel', + level => { + const config = readEnvConfig({ ...baseEnv, LOG_LEVEL: level }, args); + + expect(config.executorOptions.loggerLevel).toBe(level); + }, + ); + + it('falls back to default loggerLevel (Info) when LOG_LEVEL is unset', () => { + const config = readEnvConfig(baseEnv, args); + + expect(config.executorOptions.loggerLevel).toBe('Info'); + }); + + it('falls back to default loggerLevel when LOG_LEVEL is empty string', () => { + const config = readEnvConfig({ ...baseEnv, LOG_LEVEL: '' }, args); + + expect(config.executorOptions.loggerLevel).toBe('Info'); + }); + + it.each(['debug', 'info', 'trace', 'fatal', 'verbose', 'xxx'])( + 'throws ConfigurationError on invalid LOG_LEVEL=%s', + value => { + expect(() => readEnvConfig({ ...baseEnv, LOG_LEVEL: value }, args)).toThrow( + `LOG_LEVEL must be one of Debug, Info, Warn, Error (got "${value}")`, + ); + }, + ); + + it('LOG_LEVEL error is a ConfigurationError instance (typed boundary error)', () => { + expect(() => readEnvConfig({ ...baseEnv, LOG_LEVEL: 'oops' }, args)).toThrow( + ConfigurationError, + ); + }); }); describe('printHelp / printVersion', () => { @@ -320,7 +387,7 @@ describe('printHelp / printVersion', () => { describe('logStartup', () => { function makeLogger() { - return { info: jest.fn(), warn: jest.fn(), error: jest.fn(), debug: jest.fn() }; + return jest.fn(); } it('logs resolved defaults when env-derived options are undefined', () => { @@ -336,7 +403,8 @@ describe('logStartup', () => { }, }); - expect(logger.info).toHaveBeenCalledWith( + expect(logger).toHaveBeenCalledWith( + 'Info', 'Workflow executor starting', expect.objectContaining({ forestServerUrl: DEFAULT_FOREST_SERVER_URL, @@ -406,20 +474,26 @@ describe('runCli', () => { expect(executor.start).toHaveBeenCalled(); }); - it('injects the picked logger into executorOptions', async () => { + it('injects a JSON logger into executorOptions when --json is set', async () => { const { factories } = makeFactories(); await runCli(['--json'], baseEnv, factories); const call = (factories.buildDatabase as jest.Mock).mock.calls[0][0]; - expect(call.logger).toBeInstanceOf(ConsoleLogger); + expect(typeof call.logger).toBe('function'); + call.logger('Info', 'probe', { k: 'v' }); + const out = infoSpy.mock.calls.at(-1)?.[0] as string; + expect(isJsonLogger(out)).toBe(true); }); - it('injects a PrettyLogger when --pretty is set', async () => { + it('injects a pretty logger when --pretty is set', async () => { const { factories } = makeFactories(); await runCli(['--pretty'], baseEnv, factories); const call = (factories.buildDatabase as jest.Mock).mock.calls[0][0]; - expect(call.logger).toBeInstanceOf(PrettyLogger); + expect(typeof call.logger).toBe('function'); + call.logger('Info', 'probe', { k: 'v' }); + const out = infoSpy.mock.calls.at(-1)?.[0] as string; + expect(isJsonLogger(out)).toBe(false); }); it('builds an in-memory executor with --in-memory', async () => { diff --git a/packages/workflow-executor/test/executors/base-step-executor.test.ts b/packages/workflow-executor/test/executors/base-step-executor.test.ts index bef89c9760..ab80aba113 100644 --- a/packages/workflow-executor/test/executors/base-step-executor.test.ts +++ b/packages/workflow-executor/test/executors/base-step-executor.test.ts @@ -92,7 +92,7 @@ function makeMockRunStore(stepExecutions: StepExecutionData[] = []): RunStore { } function makeMockLogger(): Logger { - return { info: jest.fn(), warn: jest.fn(), error: jest.fn() }; + return jest.fn(); } function makeMockActivityLogPort(): ExecutionContext['activityLogPort'] { @@ -236,7 +236,8 @@ describe('BaseStepExecutor', () => { new Error('db connection refused'), ); await executor.execute(); - expect(logger.error).toHaveBeenCalledWith( + expect(logger).toHaveBeenCalledWith( + 'Error', 'Unexpected error during step execution', expect.objectContaining({ runId: 'run-1', @@ -251,11 +252,13 @@ describe('BaseStepExecutor', () => { const logger = makeMockLogger(); const executor = new TestableExecutor(makeContext({ logger })); await executor.execute(); - expect(logger.info).toHaveBeenCalledWith( + expect(logger).toHaveBeenCalledWith( + 'Info', 'Step execution started', expect.objectContaining({ stepType: StepType.Condition }), ); - expect(logger.info).toHaveBeenCalledWith( + expect(logger).toHaveBeenCalledWith( + 'Info', 'Step execution completed', expect.objectContaining({ stepType: StepType.Condition }), ); @@ -270,7 +273,8 @@ describe('BaseStepExecutor', () => { const logger = makeMockLogger(); const executor = new CachedExecutor(makeContext({ logger })); await executor.execute(); - expect(logger.info).toHaveBeenCalledWith( + expect(logger).toHaveBeenCalledWith( + 'Info', 'Step execution completed (replayed from cache)', expect.objectContaining({ stepType: StepType.Condition }), ); @@ -281,7 +285,8 @@ describe('BaseStepExecutor', () => { const err = new Error('db connection refused'); const executor = new TestableExecutor(makeContext({ logger }), err); await executor.execute(); - expect(logger.error).toHaveBeenCalledWith( + expect(logger).toHaveBeenCalledWith( + 'Error', 'Unexpected error during step execution', expect.objectContaining({ stack: err.stack }), ); @@ -299,7 +304,8 @@ describe('BaseStepExecutor', () => { const error = Object.assign(new Error('wrapper error'), { cause }); const executor = new TestableExecutor(makeContext({ logger }), error); await executor.execute(); - expect(logger.error).toHaveBeenCalledWith( + expect(logger).toHaveBeenCalledWith( + 'Error', 'Unexpected error during step execution', expect.objectContaining({ cause: 'root cause' }), ); @@ -309,7 +315,8 @@ describe('BaseStepExecutor', () => { const logger = makeMockLogger(); const executor = new TestableExecutor(makeContext({ logger }), new Error('no cause')); await executor.execute(); - expect(logger.error).toHaveBeenCalledWith( + expect(logger).toHaveBeenCalledWith( + 'Error', 'Unexpected error during step execution', expect.objectContaining({ cause: undefined }), ); @@ -319,7 +326,8 @@ describe('BaseStepExecutor', () => { const logger = makeMockLogger(); const executor = new TestableExecutor(makeContext({ logger }), new Error('boom')); await executor.execute(); - expect(logger.error).toHaveBeenCalledWith( + expect(logger).toHaveBeenCalledWith( + 'Error', 'Unexpected error during step execution', expect.objectContaining({ stepType: StepType.Condition }), ); @@ -332,7 +340,8 @@ describe('BaseStepExecutor', () => { const error = new RunStorePortError('saveStepExecution', cause); const executor = new TestableExecutor(makeContext({ logger }), error); await executor.execute(); - expect(logger.error).toHaveBeenCalledWith( + expect(logger).toHaveBeenCalledWith( + 'Error', 'Run store "saveStepExecution" failed: db timeout', expect.objectContaining({ cause: 'db timeout', @@ -347,7 +356,8 @@ describe('BaseStepExecutor', () => { const err = new MissingToolCallError(); const executor = new TestableExecutor(makeContext({ logger }), err); await executor.execute(); - expect(logger.error).toHaveBeenCalledWith( + expect(logger).toHaveBeenCalledWith( + 'Error', err.message, expect.not.objectContaining({ cause: expect.anything() }), ); @@ -444,7 +454,8 @@ describe('BaseStepExecutor', () => { jest.advanceTimersByTime(60); await resultPromise; - expect(logger.error).toHaveBeenCalledWith( + expect(logger).toHaveBeenCalledWith( + 'Error', 'Step execution exceeded timeout of 50ms', expect.objectContaining({ runId: 'run-1', @@ -499,7 +510,8 @@ describe('BaseStepExecutor', () => { setTimeout(resolve, 1_100); }); - expect(logger.warn).toHaveBeenCalledWith( + expect(logger).toHaveBeenCalledWith( + 'Warn', 'Step work rejected after timeout — result discarded', expect.objectContaining({ runId: 'run-1', @@ -523,7 +535,8 @@ describe('BaseStepExecutor', () => { await executor.execute(); - expect(logger.warn).not.toHaveBeenCalledWith( + expect(logger).not.toHaveBeenCalledWith( + 'Warn', 'Step work rejected after timeout — result discarded', expect.anything(), ); diff --git a/packages/workflow-executor/test/executors/condition-step-executor.test.ts b/packages/workflow-executor/test/executors/condition-step-executor.test.ts index 83135f3378..e91f8795b1 100644 --- a/packages/workflow-executor/test/executors/condition-step-executor.test.ts +++ b/packages/workflow-executor/test/executors/condition-step-executor.test.ts @@ -72,7 +72,7 @@ function makeContext( }, schemaCache: new SchemaCache(), previousSteps: [], - logger: { info: jest.fn(), warn: jest.fn(), error: jest.fn() }, + logger: jest.fn(), activityLogPort: { createPending: jest.fn().mockResolvedValue({ id: 'log-1', index: '0' }), diff --git a/packages/workflow-executor/test/executors/guidance-step-executor.test.ts b/packages/workflow-executor/test/executors/guidance-step-executor.test.ts index aa5d0b09ee..a554f1e23c 100644 --- a/packages/workflow-executor/test/executors/guidance-step-executor.test.ts +++ b/packages/workflow-executor/test/executors/guidance-step-executor.test.ts @@ -49,7 +49,7 @@ function makeContext( }, schemaCache: new SchemaCache(), previousSteps: [], - logger: { info: jest.fn(), warn: jest.fn(), error: jest.fn() }, + logger: jest.fn(), activityLogPort: { createPending: jest.fn().mockResolvedValue({ id: 'log-1', index: '0' }), diff --git a/packages/workflow-executor/test/executors/load-related-record-step-executor.test.ts b/packages/workflow-executor/test/executors/load-related-record-step-executor.test.ts index 5ffe45226c..abd4bbc154 100644 --- a/packages/workflow-executor/test/executors/load-related-record-step-executor.test.ts +++ b/packages/workflow-executor/test/executors/load-related-record-step-executor.test.ts @@ -164,7 +164,7 @@ function makeContext( }, schemaCache: new SchemaCache(), previousSteps: [], - logger: { info: jest.fn(), warn: jest.fn(), error: jest.fn() }, + logger: jest.fn(), activityLogPort: { createPending: jest.fn().mockResolvedValue({ id: 'log-1', index: '0' }), @@ -1884,7 +1884,7 @@ describe('LoadRelatedRecordStepExecutor', () => { values, })); const { invoke, model } = buildModel(Array.from({ length: 6 }, (_, i) => `F${i}`)); - const logger = { info: jest.fn(), warn: jest.fn(), error: jest.fn() }; + const logger = jest.fn(); const runStore = makeMockRunStore(); const context = makeContext({ model, @@ -1903,7 +1903,8 @@ describe('LoadRelatedRecordStepExecutor', () => { expect(shownRows).toBeGreaterThan(1); expect(shownRows).toBeLessThan(50); // The warn carries the run-correlation context (logCtx) alongside the counters. - expect(logger.warn).toHaveBeenCalledWith( + expect(logger).toHaveBeenCalledWith( + 'Warn', 'load-related-record: candidate list truncated for AI prompt', expect.objectContaining({ total: 50, runId: 'run-1', stepIndex: 0 }), ); @@ -1929,7 +1930,7 @@ describe('LoadRelatedRecordStepExecutor', () => { const runStore = makeMockRunStore(); const context = makeContext({ model, - logger: { info: jest.fn(), warn: jest.fn(), error: jest.fn() }, + logger: jest.fn(), agentPort: makeMockAgentPort(relatedData), runStore, workflowPort: makeMockWorkflowPort({ @@ -2303,7 +2304,7 @@ describe('LoadRelatedRecordStepExecutor', () => { }); it('returns user message and logs cause when agentPort.getRelatedData throws an infra error', async () => { - const logger = { info: jest.fn(), warn: jest.fn(), error: jest.fn() }; + const logger = jest.fn(); const agentPort = makeMockAgentPort(); (agentPort.getRelatedData as jest.Mock).mockRejectedValue( new AgentPortError('getRelatedData', new Error('DB connection lost')), @@ -2323,7 +2324,8 @@ describe('LoadRelatedRecordStepExecutor', () => { expect(result.stepOutcome.error).toBe( 'An error occurred while accessing your data. Please try again.', ); - expect(logger.error).toHaveBeenCalledWith( + expect(logger).toHaveBeenCalledWith( + 'Error', 'Agent port "getRelatedData" failed: DB connection lost', expect.objectContaining({ cause: 'DB connection lost' }), ); diff --git a/packages/workflow-executor/test/executors/mcp-step-executor.test.ts b/packages/workflow-executor/test/executors/mcp-step-executor.test.ts index b057b6394f..4097cb58bb 100644 --- a/packages/workflow-executor/test/executors/mcp-step-executor.test.ts +++ b/packages/workflow-executor/test/executors/mcp-step-executor.test.ts @@ -116,7 +116,7 @@ function makeContext( }, schemaCache: new SchemaCache(), previousSteps: [], - logger: { info: jest.fn(), warn: jest.fn(), error: jest.fn() }, + logger: jest.fn(), activityLogPort: { createPending: jest.fn().mockResolvedValue({ id: 'log-1', index: '0' }), @@ -230,6 +230,68 @@ describe('McpStepExecutor', () => { ); }); + it('returns success and logs when persisting the formatted response fails', async () => { + const toolResult = { result: 'notification sent' }; + const invokeFn = jest.fn().mockResolvedValue(toolResult); + const tool = new MockRemoteTool({ + name: 'send_notification', + sourceId: 'mcp-server-1', + invoke: invokeFn, + }); + const { model, invoke: modelInvoke } = makeMockModel('send_notification', { + message: 'Hello', + }); + modelInvoke + .mockResolvedValueOnce({ + tool_calls: [{ name: 'send_notification', args: { message: 'Hello' }, id: 'call_1' }], + }) + .mockResolvedValueOnce({ + tool_calls: [ + { name: 'summarize-result', args: { summary: 'Found 3 results.' }, id: 'call_2' }, + ], + }); + const persistFailure = new Error('database unreachable'); + // First two saves (executing marker, raw result) succeed; third save (enriched + // with formattedResponse) fails. + const saveStepExecution = jest + .fn() + .mockResolvedValueOnce(undefined) + .mockResolvedValueOnce(undefined) + .mockRejectedValueOnce(persistFailure); + const runStore = makeMockRunStore({ saveStepExecution }); + const logger = jest.fn(); + const context = makeContext({ + model, + runStore, + stepDefinition: makeStep({ executionType: StepExecutionMode.FullyAutomated }), + logger, + }); + const executor = new McpStepExecutor(context, [tool]); + + const result = await executor.execute(); + + // Step does NOT fail — the raw toolResult was already persisted on the + // second save (done marker). The enriched save is best-effort. + expect(result.stepOutcome.status).toBe('success'); + expect(runStore.saveStepExecution).toHaveBeenCalledTimes(3); + expect(runStore.saveStepExecution).toHaveBeenNthCalledWith( + 3, + 'run-1', + expect.objectContaining({ + executionResult: { success: true, toolResult, formattedResponse: 'Found 3 results.' }, + }), + ); + expect(logger).toHaveBeenCalledWith( + 'Error', + 'MCP tool result formatted but enriched state could not be persisted', + expect.objectContaining({ + runId: 'run-1', + toolName: 'send_notification', + cause: 'database unreachable', + }), + ); + }); + it('returns success and logs when AI formatting throws', async () => { const invokeFn = jest.fn().mockResolvedValue({ result: 'ok' }); const tool = new MockRemoteTool({ @@ -244,7 +306,7 @@ describe('McpStepExecutor', () => { tool_calls: [{ name: 'send_notification', args: { message: 'Hi' }, id: 'call_1' }], }) .mockResolvedValueOnce({ tool_calls: [] }); - const logger = { info: jest.fn(), warn: jest.fn(), error: jest.fn() }; + const logger = jest.fn(); const runStore = makeMockRunStore(); const context = makeContext({ model, @@ -266,7 +328,8 @@ describe('McpStepExecutor', () => { executionResult: { success: true, toolResult: { result: 'ok' } }, }), ); - expect(logger.error).toHaveBeenCalledWith( + expect(logger).toHaveBeenCalledWith( + 'Error', 'Failed to format MCP tool result, using generic fallback', expect.objectContaining({ toolName: 'send_notification' }), ); @@ -332,7 +395,7 @@ describe('McpStepExecutor', () => { it('returns error when saveStepExecution fails (Branch C)', async () => { const { model } = makeMockModel('send_notification', { message: 'Hello' }); - const logger = { info: jest.fn(), warn: jest.fn(), error: jest.fn() }; + const logger = jest.fn(); const runStore = makeMockRunStore({ saveStepExecution: jest .fn() @@ -348,7 +411,8 @@ describe('McpStepExecutor', () => { expect(result.stepOutcome.status).toBe('error'); expect(result.stepOutcome.error).toBe('The step state could not be accessed. Please retry.'); - expect(logger.error).toHaveBeenCalledWith( + expect(logger).toHaveBeenCalledWith( + 'Error', 'Run store "saveStepExecution" failed: DB unavailable', expect.objectContaining({ cause: 'DB unavailable', stepId: 'mcp-1' }), ); @@ -521,7 +585,7 @@ describe('McpStepExecutor', () => { }); it('logs the technical message with the requested mcpServerId when tools are empty', async () => { - const logger = { info: jest.fn(), warn: jest.fn(), error: jest.fn() }; + const logger = jest.fn(); const context = makeContext({ logger, stepDefinition: makeStep({ mcpServerId: 'id-missing' }), @@ -532,7 +596,8 @@ describe('McpStepExecutor', () => { // BaseStepExecutor catches NoMcpToolsError and logs error.message (which encodes the // requested mcpServerId) along with the step correlation context. - expect(logger.error).toHaveBeenCalledWith( + expect(logger).toHaveBeenCalledWith( + 'Error', 'No MCP tools available for mcpServerId="id-missing"', expect.objectContaining({ runId: expect.any(String), @@ -581,7 +646,7 @@ describe('McpStepExecutor', () => { invoke: invokeFn, }); const { model } = makeMockModel('send_notification', { message: 'Hello' }); - const logger = { info: jest.fn(), warn: jest.fn(), error: jest.fn() }; + const logger = jest.fn(); const runStore = makeMockRunStore({ saveStepExecution: jest .fn() @@ -599,7 +664,8 @@ describe('McpStepExecutor', () => { expect(result.stepOutcome.status).toBe('error'); expect(result.stepOutcome.error).toBe('The step state could not be accessed. Please retry.'); - expect(logger.error).toHaveBeenCalledWith( + expect(logger).toHaveBeenCalledWith( + 'Error', 'Run store "saveStepExecution" failed: Disk full', expect.objectContaining({ cause: 'Disk full', stepId: 'mcp-1' }), ); @@ -622,7 +688,7 @@ describe('McpStepExecutor', () => { }, userConfirmation: { userConfirmed: true }, }; - const logger = { info: jest.fn(), warn: jest.fn(), error: jest.fn() }; + const logger = jest.fn(); const runStore = makeMockRunStore({ getStepExecutions: jest.fn().mockResolvedValue([execution]), saveStepExecution: jest @@ -636,7 +702,8 @@ describe('McpStepExecutor', () => { expect(result.stepOutcome.status).toBe('error'); expect(result.stepOutcome.error).toBe('The step state could not be accessed. Please retry.'); - expect(logger.error).toHaveBeenCalledWith( + expect(logger).toHaveBeenCalledWith( + 'Error', 'Run store "saveStepExecution" failed: Disk full', expect.objectContaining({ cause: 'Disk full', stepId: 'mcp-1' }), ); @@ -737,7 +804,7 @@ describe('McpStepExecutor', () => { invoke: invokeFn, }); const { model } = makeMockModel('send_notification', {}); - const logger = { info: jest.fn(), warn: jest.fn(), error: jest.fn() }; + const logger = jest.fn(); const context = makeContext({ model, stepDefinition: makeStep({ executionType: StepExecutionMode.FullyAutomated }), @@ -751,7 +818,8 @@ describe('McpStepExecutor', () => { expect(result.stepOutcome.error).toBe( 'The tool failed to execute. Please try again or contact your administrator.', ); - expect(logger.error).toHaveBeenCalledWith( + expect(logger).toHaveBeenCalledWith( + 'Error', 'MCP tool "send_notification" invocation failed: Connection refused', expect.objectContaining({ cause: 'Connection refused' }), ); @@ -986,7 +1054,7 @@ describe('McpStepExecutor', () => { it('includes mcpServerId and mcpServerName in the start and completion log lines', async () => { const tool = new MockRemoteTool({ name: 'send_notification', sourceId: 'mcp-server-1' }); const { model } = makeMockModel('send_notification', { message: 'Hello' }); - const logger = { info: jest.fn(), warn: jest.fn(), error: jest.fn() }; + const logger = jest.fn(); const context = makeContext({ model, logger, @@ -999,14 +1067,16 @@ describe('McpStepExecutor', () => { await executor.execute(); - expect(logger.info).toHaveBeenCalledWith( + expect(logger).toHaveBeenCalledWith( + 'Info', 'Step execution started', expect.objectContaining({ mcpServerId: 'my-mcp-server', mcpServerName: 'Production Slack', }), ); - expect(logger.info).toHaveBeenCalledWith( + expect(logger).toHaveBeenCalledWith( + 'Info', 'Step execution completed', expect.objectContaining({ mcpServerId: 'my-mcp-server', @@ -1016,7 +1086,7 @@ describe('McpStepExecutor', () => { }); it('logs mcpServerName as undefined when no server name was resolved', async () => { - const logger = { info: jest.fn(), warn: jest.fn(), error: jest.fn() }; + const logger = jest.fn(); const context = makeContext({ logger, stepDefinition: makeStep({ mcpServerId: 'id-missing' }), @@ -1025,7 +1095,8 @@ describe('McpStepExecutor', () => { await executor.execute(); - expect(logger.error).toHaveBeenCalledWith( + expect(logger).toHaveBeenCalledWith( + 'Error', 'No MCP tools available for mcpServerId="id-missing"', expect.objectContaining({ mcpServerId: 'id-missing', mcpServerName: undefined }), ); diff --git a/packages/workflow-executor/test/executors/read-record-step-executor.test.ts b/packages/workflow-executor/test/executors/read-record-step-executor.test.ts index d483ce2d37..e83cda084a 100644 --- a/packages/workflow-executor/test/executors/read-record-step-executor.test.ts +++ b/packages/workflow-executor/test/executors/read-record-step-executor.test.ts @@ -131,7 +131,7 @@ function makeContext( }, schemaCache: new SchemaCache(), previousSteps: [], - logger: { info: jest.fn(), warn: jest.fn(), error: jest.fn() }, + logger: jest.fn(), activityLogPort: { createPending: jest.fn().mockResolvedValue({ id: 'log-1', index: '0' }), @@ -676,7 +676,7 @@ describe('ReadRecordStepExecutor', () => { }); it('returns user message and logs cause when agentPort.getRecord throws an infra error', async () => { - const logger = { info: jest.fn(), warn: jest.fn(), error: jest.fn() }; + const logger = jest.fn(); const agentPort = makeMockAgentPort(); // Prod adapter normalizes infra errors into AgentPortError — simulate here. (agentPort.getRecord as jest.Mock).mockRejectedValue( @@ -692,7 +692,8 @@ describe('ReadRecordStepExecutor', () => { expect(result.stepOutcome.error).toBe( 'An error occurred while accessing your data. Please try again.', ); - expect(logger.error).toHaveBeenCalledWith( + expect(logger).toHaveBeenCalledWith( + 'Error', 'Agent port "getRecord" failed: DB connection lost', expect.objectContaining({ cause: 'DB connection lost' }), ); diff --git a/packages/workflow-executor/test/executors/trigger-record-action-step-executor.test.ts b/packages/workflow-executor/test/executors/trigger-record-action-step-executor.test.ts index 59648d2751..bf057704a5 100644 --- a/packages/workflow-executor/test/executors/trigger-record-action-step-executor.test.ts +++ b/packages/workflow-executor/test/executors/trigger-record-action-step-executor.test.ts @@ -133,7 +133,7 @@ function makeContext( }, schemaCache: new SchemaCache(), previousSteps: [], - logger: { info: jest.fn(), warn: jest.fn(), error: jest.fn() }, + logger: jest.fn(), activityLogPort: { createPending: jest.fn().mockResolvedValue({ id: 'log-1', index: '0' }), @@ -622,7 +622,7 @@ describe('TriggerRecordActionStepExecutor', () => { }); it('returns user message and logs cause when agentPort.executeAction throws an infra error', async () => { - const logger = { info: jest.fn(), warn: jest.fn(), error: jest.fn() }; + const logger = jest.fn(); const agentPort = makeMockAgentPort(); (agentPort.executeAction as jest.Mock).mockRejectedValue( new AgentPortError('executeAction', new Error('DB connection lost')), @@ -645,7 +645,8 @@ describe('TriggerRecordActionStepExecutor', () => { expect(result.stepOutcome.error).toBe( 'An error occurred while accessing your data. Please try again.', ); - expect(logger.error).toHaveBeenCalledWith( + expect(logger).toHaveBeenCalledWith( + 'Error', 'Agent port "executeAction" failed: DB connection lost', expect.objectContaining({ cause: 'DB connection lost' }), ); diff --git a/packages/workflow-executor/test/executors/update-record-step-executor.test.ts b/packages/workflow-executor/test/executors/update-record-step-executor.test.ts index 48becbae9f..8ad6931f1b 100644 --- a/packages/workflow-executor/test/executors/update-record-step-executor.test.ts +++ b/packages/workflow-executor/test/executors/update-record-step-executor.test.ts @@ -130,7 +130,7 @@ function makeContext( }, schemaCache: new SchemaCache(), previousSteps: [], - logger: { info: jest.fn(), warn: jest.fn(), error: jest.fn() }, + logger: jest.fn(), activityLogPort: { createPending: jest.fn().mockResolvedValue({ id: 'log-1', index: '0' }), @@ -929,7 +929,7 @@ describe('UpdateRecordStepExecutor', () => { }); it('returns user message and logs cause when agentPort.updateRecord throws an infra error', async () => { - const logger = { info: jest.fn(), warn: jest.fn(), error: jest.fn() }; + const logger = jest.fn(); const agentPort = makeMockAgentPort(); (agentPort.updateRecord as jest.Mock).mockRejectedValue( new AgentPortError('updateRecord', new Error('DB connection lost')), @@ -951,7 +951,8 @@ describe('UpdateRecordStepExecutor', () => { expect(result.stepOutcome.error).toBe( 'An error occurred while accessing your data. Please try again.', ); - expect(logger.error).toHaveBeenCalledWith( + expect(logger).toHaveBeenCalledWith( + 'Error', 'Agent port "updateRecord" failed: DB connection lost', expect.objectContaining({ cause: 'DB connection lost' }), ); diff --git a/packages/workflow-executor/test/http/executor-http-server.test.ts b/packages/workflow-executor/test/http/executor-http-server.test.ts index d4703d7a48..4d98776450 100644 --- a/packages/workflow-executor/test/http/executor-http-server.test.ts +++ b/packages/workflow-executor/test/http/executor-http-server.test.ts @@ -1,3 +1,4 @@ +import type { Logger } from '../../src/ports/logger-port'; import type { WorkflowPort } from '../../src/ports/workflow-port'; import type Runner from '../../src/runner'; @@ -40,7 +41,7 @@ function createServer( overrides: { runner?: Runner; workflowPort?: WorkflowPort; - logger?: { info: jest.Mock; warn: jest.Mock; error: jest.Mock }; + logger?: jest.MockedFunction; } = {}, ) { return new ExecutorHttpServer({ @@ -247,7 +248,7 @@ describe('ExecutorHttpServer', () => { }); it('returns 503 when hasRunAccess throws', async () => { - const logger = { info: jest.fn(), warn: jest.fn(), error: jest.fn() }; + const logger = jest.fn(); const workflowPort = createMockWorkflowPort({ hasRunAccess: jest.fn().mockRejectedValue(new Error('orchestrator down')), }); @@ -260,7 +261,8 @@ describe('ExecutorHttpServer', () => { expect(response.status).toBe(503); expect(response.body).toEqual({ error: 'Service unavailable' }); - expect(logger.error).toHaveBeenCalledWith( + expect(logger).toHaveBeenCalledWith( + 'Error', 'Failed to check run access', expect.objectContaining({ runId: 'run-1', error: 'orchestrator down' }), ); diff --git a/packages/workflow-executor/test/remote-tool-fetcher.test.ts b/packages/workflow-executor/test/remote-tool-fetcher.test.ts index 1820367a41..7527816adc 100644 --- a/packages/workflow-executor/test/remote-tool-fetcher.test.ts +++ b/packages/workflow-executor/test/remote-tool-fetcher.test.ts @@ -13,8 +13,8 @@ function createMockAiModelPort(): jest.Mocked> { - return { info: jest.fn(), warn: jest.fn(), error: jest.fn() }; +function createMockLogger(): jest.MockedFunction { + return jest.fn(); } function makeRemoteTool(sourceId: string, mcpServerId?: string): RemoteTool { @@ -24,7 +24,7 @@ function makeRemoteTool(sourceId: string, mcpServerId?: string): RemoteTool { function makeFetcher(overrides?: { workflowPort?: Partial>>; aiModelPort?: Partial>>; - logger?: jest.Mocked>; + logger?: jest.MockedFunction; }) { const workflowPort = { ...createMockWorkflowPort(), ...overrides?.workflowPort }; const aiModelPort = { ...createMockAiModelPort(), ...overrides?.aiModelPort }; @@ -123,7 +123,8 @@ describe('RemoteToolFetcher.fetch', () => { await fetcher.fetch('id-missing'); - expect(logger.warn).toHaveBeenCalledWith( + expect(logger).toHaveBeenCalledWith( + 'Warn', 'MCP step targets a server not advertised by the orchestrator', { requestedMcpServerId: 'id-missing', @@ -140,11 +141,13 @@ describe('RemoteToolFetcher.fetch', () => { await fetcher.fetch('id-A'); - expect(logger.warn).toHaveBeenCalledWith( + expect(logger).toHaveBeenCalledWith( + 'Warn', 'MCP step targets a server but orchestrator returned no MCP configs', { requestedMcpServerId: 'id-A', mcpServerName: undefined, availableMcpServerIds: [] }, ); - expect(logger.warn).not.toHaveBeenCalledWith( + expect(logger).not.toHaveBeenCalledWith( + 'Warn', 'MCP step targets a server not advertised by the orchestrator', expect.anything(), ); @@ -159,7 +162,7 @@ describe('RemoteToolFetcher.fetch', () => { await fetcher.fetch('id-A'); - expect(logger.warn).not.toHaveBeenCalled(); + expect(logger.mock.calls.find(c => c[0] === 'Warn')).toBeUndefined(); }); it('flags the scoped MCP config when no tool was loaded for its id', async () => { @@ -172,7 +175,7 @@ describe('RemoteToolFetcher.fetch', () => { await fetcher.fetch('id-A'); - expect(logger.error).toHaveBeenCalledWith('MCP servers failed to load tools', { + expect(logger).toHaveBeenCalledWith('Error', 'MCP servers failed to load tools', { requestedMcpServerId: 'id-A', mcpServerName: 'srv-a', failedConfigNames: ['srv-a'], @@ -191,7 +194,7 @@ describe('RemoteToolFetcher.fetch', () => { await fetcher.fetch('id-A'); - expect(logger.error).not.toHaveBeenCalled(); + expect(logger.mock.calls.find(c => c[0] === 'Error')).toBeUndefined(); }); // Forest integrations carry a hardcoded sourceId (e.g. 'zendesk'); the partial-failure check @@ -213,7 +216,7 @@ describe('RemoteToolFetcher.fetch', () => { await fetcher.fetch('id-zendesk'); - expect(logger.error).not.toHaveBeenCalled(); + expect(logger.mock.calls.find(c => c[0] === 'Error')).toBeUndefined(); }); it('flags a Forest connector that fails to load entirely', async () => { @@ -231,7 +234,7 @@ describe('RemoteToolFetcher.fetch', () => { await fetcher.fetch('id-zendesk'); - expect(logger.error).toHaveBeenCalledWith('MCP servers failed to load tools', { + expect(logger).toHaveBeenCalledWith('Error', 'MCP servers failed to load tools', { requestedMcpServerId: 'id-zendesk', mcpServerName: 'zendesk-prod', failedConfigNames: ['zendesk-prod'], @@ -263,7 +266,7 @@ describe('RemoteToolFetcher.fetch', () => { }); await expect(fetcher.fetch('id-A')).rejects.toThrow('MCP unreachable'); - expect(logger.error).not.toHaveBeenCalled(); + expect(logger.mock.calls.find(c => c[0] === 'Error')).toBeUndefined(); }); it('propagates a rejection from getMcpServerConfigs without calling loadRemoteTools', async () => { diff --git a/packages/workflow-executor/test/runner.test.ts b/packages/workflow-executor/test/runner.test.ts index c86f1fd5cb..994195d084 100644 --- a/packages/workflow-executor/test/runner.test.ts +++ b/packages/workflow-executor/test/runner.test.ts @@ -58,8 +58,8 @@ function createMockAiClient() { }; } -function createMockLogger(): jest.Mocked> { - return { info: jest.fn(), warn: jest.fn(), error: jest.fn() }; +function createMockLogger(): jest.MockedFunction { + return jest.fn(); } const VALID_ENV_SECRET = 'a'.repeat(64); @@ -344,7 +344,8 @@ describe('graceful shutdown', () => { await runner.start(); await runner.stop(); - expect(logger.error).toHaveBeenCalledWith( + expect(logger).toHaveBeenCalledWith( + 'Error', 'Resource cleanup failed during shutdown', expect.objectContaining({ error: 'connection leak' }), ); @@ -421,7 +422,8 @@ describe('graceful shutdown', () => { await runner.stop(); jest.useFakeTimers(); - expect(logger.error).toHaveBeenCalledWith( + expect(logger).toHaveBeenCalledWith( + 'Error', 'Drain timeout — runs still in flight', expect.objectContaining({ remainingRuns: ['run-1'], @@ -437,7 +439,7 @@ describe('graceful shutdown', () => { await runner.start(); await runner.stop(); - expect(logger.info).not.toHaveBeenCalledWith('Draining in-flight runs', expect.anything()); + expect(logger).not.toHaveBeenCalledWith('Info', 'Draining in-flight runs', expect.anything()); expect(runner.state).toBe('stopped'); }); @@ -506,11 +508,11 @@ describe('graceful shutdown', () => { resolveStep(); await runner.stop(); - expect(logger.info).toHaveBeenCalledWith('Draining in-flight runs', { + expect(logger).toHaveBeenCalledWith('Info', 'Draining in-flight runs', { count: 1, runs: ['run-1'], }); - expect(logger.info).toHaveBeenCalledWith('All in-flight runs drained', {}); + expect(logger).toHaveBeenCalledWith('Info', 'All in-flight runs drained', {}); }); }); @@ -836,7 +838,8 @@ describe('chain', () => { expect(executeSpy).toHaveBeenCalledTimes(1); expect(workflowPort.updateStepExecution).toHaveBeenCalledTimes(1); - expect(mockLogger.error).toHaveBeenCalledWith( + expect(mockLogger).toHaveBeenCalledWith( + 'Error', 'Server returned non-progressing next step — exiting chain', expect.objectContaining({ runId: 'run-1', @@ -867,7 +870,8 @@ describe('chain', () => { await runner.triggerPoll('run-1'); expect(executeSpy).toHaveBeenCalledTimes(1); - expect(mockLogger.error).toHaveBeenCalledWith( + expect(mockLogger).toHaveBeenCalledWith( + 'Error', 'Server returned non-progressing next step — exiting chain', expect.objectContaining({ runId: 'run-1', returnedRunId: 'run-other' }), ); @@ -897,7 +901,8 @@ describe('chain', () => { // initial + 2 chained = 3 total executions; the 3rd update returns a next we don't chain. expect(executeSpy).toHaveBeenCalledTimes(3); - expect(mockLogger.info).toHaveBeenCalledWith( + expect(mockLogger).toHaveBeenCalledWith( + 'Info', 'Chain depth cap reached — yielding to next poll', expect.objectContaining({ runId: 'run-1', maxDepth: 2 }), ); @@ -990,7 +995,8 @@ describe('chain', () => { await runner.triggerPoll('run-1'); expect(executeSpy).toHaveBeenCalledTimes(2); // initial + 1 chained before the throw - expect(mockLogger.error).toHaveBeenCalledWith( + expect(mockLogger).toHaveBeenCalledWith( + 'Error', 'Failed to report step outcome', expect.objectContaining({ runId: 'run-1', @@ -1035,7 +1041,8 @@ describe('chain', () => { runner = new Runner(createRunnerConfig({ workflowPort, logger: mockLogger })); await runner.triggerPoll('run-1'); - expect(mockLogger.error).toHaveBeenCalledWith( + expect(mockLogger).toHaveBeenCalledWith( + 'Error', 'FATAL: executor contract violated — reporting synthetic error outcome', expect.objectContaining({ runId: 'run-1', @@ -1129,7 +1136,8 @@ describe('chain', () => { // Only the initial step executed — the draining check prevented chaining. expect(executeSpy).toHaveBeenCalledTimes(1); - expect(mockLogger.info).toHaveBeenCalledWith( + expect(mockLogger).toHaveBeenCalledWith( + 'Info', 'Chain interrupted by stop() — yielding', expect.objectContaining({ runId: 'run-1' }), ); @@ -1291,7 +1299,8 @@ describe('MCP fetch scoping', () => { expect(workflowPort.getMcpServerConfigs).toHaveBeenCalledTimes(1); expect(aiClient.loadRemoteTools).not.toHaveBeenCalled(); - expect(logger.warn).toHaveBeenCalledWith( + expect(logger).toHaveBeenCalledWith( + 'Warn', 'MCP step targets a server not advertised by the orchestrator', { requestedMcpServerId: 'id-missing', @@ -1331,11 +1340,13 @@ describe('MCP fetch scoping', () => { await runner.triggerPoll('run-1'); expect(aiClient.loadRemoteTools).not.toHaveBeenCalled(); - expect(logger.warn).toHaveBeenCalledWith( + expect(logger).toHaveBeenCalledWith( + 'Warn', 'MCP step targets a server but orchestrator returned no MCP configs', { requestedMcpServerId: 'id-A', mcpServerName: undefined, availableMcpServerIds: [] }, ); - expect(logger.warn).not.toHaveBeenCalledWith( + expect(logger).not.toHaveBeenCalledWith( + 'Warn', 'MCP step targets a server not advertised by the orchestrator', expect.anything(), ); @@ -1376,7 +1387,7 @@ describe('MCP fetch scoping', () => { ); await runner.triggerPoll('run-1'); - expect(logger.error).toHaveBeenCalledWith('MCP servers failed to load tools', { + expect(logger).toHaveBeenCalledWith('Error', 'MCP servers failed to load tools', { requestedMcpServerId: 'id-A', mcpServerName: 'server-A', failedConfigNames: ['server-A'], @@ -1452,7 +1463,7 @@ describe('StepExecutorFactory.create — factory', () => { workflowPort: {} as WorkflowPort, runStore: {} as RunStore, schemaCache: new SchemaCache(), - logger: { info: jest.fn(), warn: jest.fn(), error: jest.fn() }, + logger: jest.fn(), }); const makeRunLogger = () => ({ @@ -1589,7 +1600,7 @@ describe('StepExecutorFactory.create — factory', () => { const rootCause = new Error('root cause'); const error = new Error('wrapper'); (error as Error & { cause: Error }).cause = rootCause; - const logger = { info: jest.fn(), warn: jest.fn(), error: jest.fn() }; + const logger = jest.fn(); const contextConfig: StepContextConfig = { ...makeContextConfig(), aiModelPort: { @@ -1602,7 +1613,8 @@ describe('StepExecutorFactory.create — factory', () => { await StepExecutorFactory.create(makePendingStep(), contextConfig, makeRunLogger(), jest.fn()); - expect(logger.error).toHaveBeenCalledWith( + expect(logger).toHaveBeenCalledWith( + 'Error', 'Step execution failed unexpectedly', expect.objectContaining({ cause: 'root cause' }), ); @@ -1611,7 +1623,7 @@ describe('StepExecutorFactory.create — factory', () => { it('logs cause as undefined when construction error cause is not an Error instance', async () => { const error = new Error('wrapper'); (error as Error & { cause: string }).cause = 'plain string'; - const logger = { info: jest.fn(), warn: jest.fn(), error: jest.fn() }; + const logger = jest.fn(); const contextConfig: StepContextConfig = { ...makeContextConfig(), aiModelPort: { @@ -1624,7 +1636,8 @@ describe('StepExecutorFactory.create — factory', () => { await StepExecutorFactory.create(makePendingStep(), contextConfig, makeRunLogger(), jest.fn()); - expect(logger.error).toHaveBeenCalledWith( + expect(logger).toHaveBeenCalledWith( + 'Error', 'Step execution failed unexpectedly', expect.objectContaining({ cause: undefined }), ); @@ -1658,7 +1671,8 @@ describe('error handling', () => { ); await runner.triggerPoll('run-1'); - expect(mockLogger.error).toHaveBeenCalledWith( + expect(mockLogger).toHaveBeenCalledWith( + 'Error', 'Step execution failed unexpectedly', expect.objectContaining({ runId: 'run-1', @@ -1726,7 +1740,8 @@ describe('error handling', () => { ); await runner.triggerPoll('run-2'); - expect(mockLogger.error).toHaveBeenCalledWith( + expect(mockLogger).toHaveBeenCalledWith( + 'Error', 'Step execution failed unexpectedly', expect.objectContaining({ runId: 'run-2', @@ -1779,7 +1794,8 @@ describe('error handling', () => { runner = new Runner(createRunnerConfig({ workflowPort, logger: mockLogger })); await runner.triggerPoll('run-1'); - expect(mockLogger.error).toHaveBeenCalledWith( + expect(mockLogger).toHaveBeenCalledWith( + 'Error', 'FATAL: executor contract violated — reporting synthetic error outcome', expect.objectContaining({ runId: 'run-1', @@ -1844,7 +1860,8 @@ describe('error handling', () => { runner = new Runner(createRunnerConfig({ workflowPort, logger: mockLogger })); await expect(runner.triggerPoll('run-1')).resolves.toBeUndefined(); - expect(mockLogger.error).toHaveBeenCalledWith( + expect(mockLogger).toHaveBeenCalledWith( + 'Error', 'FATAL: also failed to report synthetic error outcome', expect.objectContaining({ runId: 'run-1', @@ -1911,7 +1928,7 @@ describe('error handling', () => { jest.advanceTimersByTime(POLLING_INTERVAL_MS); await flushPromises(); - expect(mockLogger.info).toHaveBeenCalledWith('Poll cycle completed', { + expect(mockLogger).toHaveBeenCalledWith('Info', 'Poll cycle completed', { fetched: 0, dispatching: 0, malformed: 0, @@ -1931,7 +1948,8 @@ describe('error handling', () => { jest.advanceTimersByTime(POLLING_INTERVAL_MS); await flushPromises(); - expect(mockLogger.error).toHaveBeenCalledWith( + expect(mockLogger).toHaveBeenCalledWith( + 'Error', 'Poll cycle failed', expect.objectContaining({ error: 'network error' }), ); @@ -1994,7 +2012,8 @@ describe('malformed run reporting', () => { await flushPromises(); expect(workflowPort.updateStepExecution).not.toHaveBeenCalled(); - expect(mockLogger.error).toHaveBeenCalledWith( + expect(mockLogger).toHaveBeenCalledWith( + 'Error', 'Malformed run cannot be reported — no available step identified', expect.objectContaining({ runId: '99' }), ); @@ -2015,7 +2034,8 @@ describe('malformed run reporting', () => { jest.advanceTimersByTime(POLLING_INTERVAL_MS); await flushPromises(); - expect(mockLogger.error).toHaveBeenCalledWith( + expect(mockLogger).toHaveBeenCalledWith( + 'Error', 'Malformed run — also failed to report', expect.objectContaining({ runId: '99', reportError: 'orchestrator unreachable' }), ); diff --git a/packages/workflow-executor/test/stores/database-store.test.ts b/packages/workflow-executor/test/stores/database-store.test.ts index 1f3878a793..cd385b49a0 100644 --- a/packages/workflow-executor/test/stores/database-store.test.ts +++ b/packages/workflow-executor/test/stores/database-store.test.ts @@ -118,9 +118,10 @@ describe('DatabaseStore (SQLite)', () => { .spyOn(badSequelize.getQueryInterface(), 'createTable') .mockRejectedValueOnce(new Error('disk full')); - const logger = { info: jest.fn(), warn: jest.fn(), error: jest.fn() }; + const logger = jest.fn(); await expect(badStore.init(logger)).rejects.toThrow('disk full'); - expect(logger.error).toHaveBeenCalledWith( + expect(logger).toHaveBeenCalledWith( + 'Error', 'Database migration failed', expect.objectContaining({ error: 'disk full' }), ); @@ -129,11 +130,12 @@ describe('DatabaseStore (SQLite)', () => { }); it('close() catches and logs errors instead of throwing', async () => { - const logger = { info: jest.fn(), warn: jest.fn(), error: jest.fn() }; + const logger = jest.fn(); jest.spyOn(sequelize, 'close').mockRejectedValueOnce(new Error('close failed')); await expect(store.close(logger)).resolves.toBeUndefined(); - expect(logger.error).toHaveBeenCalledWith( + expect(logger).toHaveBeenCalledWith( + 'Error', 'Failed to close database connection', expect.objectContaining({ error: 'close failed' }), );