diff --git a/src/adapters/channel/loadEnabledChannels.ts b/src/adapters/channel/loadEnabledChannels.ts index 77e2adb8..ffaf9d6a 100644 --- a/src/adapters/channel/loadEnabledChannels.ts +++ b/src/adapters/channel/loadEnabledChannels.ts @@ -1,3 +1,5 @@ +import { createLogger } from '../../pilot/logger.js'; +const adapterLog = createLogger('adapters'); import type { ChannelAdapter } from "./protocol/ChannelAdapter.js"; import type { PilotAdaptersConfig, PilotPlatformAdapterConfig } from "../../pilot/config/types.js"; @@ -131,7 +133,7 @@ export async function loadEnabledChannels(adapters: PilotAdaptersConfig | undefi try { channels.push(await loader(cfg)); } catch (e) { - console.error(`[adapters] Failed to load channel "${key}": ${e}`); + adapterLog.error(`Failed to load channel "${key}"`, undefined, { channel: key, error: String(e) }); } } diff --git a/src/cli/pilotdeck.ts b/src/cli/pilotdeck.ts index 0ab0498a..6af6d3ee 100644 --- a/src/cli/pilotdeck.ts +++ b/src/cli/pilotdeck.ts @@ -1,3 +1,5 @@ +const cliLog = createLogger('cli'); +import { createLogger } from '../pilot/logger.js'; #!/usr/bin/env node import { resolve } from "node:path"; import { createAlwaysOnManager, createApplyHandler, SessionConfigOverrides, type AlwaysOnManager, type AlwaysOnConfig } from "../always-on/index.js"; @@ -31,15 +33,15 @@ async function main(argv = process.argv.slice(2)): Promise { const alwaysOnLogger = { info: (message: string, data?: Record) => - console.log(`[always-on] ${message}${data ? ` ${JSON.stringify(data)}` : ""}`), + cliLog.info(message, data), warn: (message: string, data?: Record) => - console.warn(`[always-on] ${message}${data ? ` ${JSON.stringify(data)}` : ""}`), + cliLog.warn(message, data), }; const cronLogger = { info: (message: string, data?: Record) => - console.log(`[cron] ${message}${data ? ` ${JSON.stringify(data)}` : ""}`), + cliLog.info(message, data), warn: (message: string, data?: Record) => - console.warn(`[cron] ${message}${data ? ` ${JSON.stringify(data)}` : ""}`), + cliLog.warn(message, data), }; function buildAlwaysOn(config: AlwaysOnConfig | undefined): AlwaysOnManager | undefined { diff --git a/src/model/providers/anthropic/stream.ts b/src/model/providers/anthropic/stream.ts index eab9c522..4ee84428 100644 --- a/src/model/providers/anthropic/stream.ts +++ b/src/model/providers/anthropic/stream.ts @@ -1,3 +1,5 @@ +import { createLogger } from '../../../../pilot/logger.js'; +const anthropic_stream_log = createLogger('anthropic-stream'); import { jsonrepair } from "jsonrepair"; import type { CanonicalModelEvent, CanonicalToolCall } from "../../protocol/canonical.js"; import { ModelProviderError } from "../../protocol/errors.js"; diff --git a/src/model/providers/openai/stream.ts b/src/model/providers/openai/stream.ts index 1d0cb14f..58938eb7 100644 --- a/src/model/providers/openai/stream.ts +++ b/src/model/providers/openai/stream.ts @@ -1,3 +1,5 @@ +import { createLogger } from '../../../../pilot/logger.js'; +const openai_stream_log = createLogger('openai-stream'); import { jsonrepair } from "jsonrepair"; import type { CanonicalModelEvent, CanonicalToolCall } from "../../protocol/canonical.js"; import { ModelProviderError } from "../../protocol/errors.js"; diff --git a/src/model/streaming/assembleModelMessage.ts b/src/model/streaming/assembleModelMessage.ts index 39c5f1e0..3f517319 100644 --- a/src/model/streaming/assembleModelMessage.ts +++ b/src/model/streaming/assembleModelMessage.ts @@ -1,3 +1,5 @@ +import { createLogger } from '../../../pilot/logger.js'; +const assemble_msg_log = createLogger('assemble-msg'); import type { CanonicalContentBlock, CanonicalFinishReason, @@ -93,7 +95,7 @@ export function assembleAssistantMessage(state: ModelMessageAssemblerState): Ass const textBlock = state.content[textIdx] as CanonicalTextBlock; const { toolCalls, remainingText } = extractTextToolCalls(textBlock.text); if (toolCalls.length > 0) { - console.log(`[text-tool-call-fallback] Extracted ${toolCalls.length} tool call(s) from assistant text`); + assembleMsgLog.info("text-tool-call-fallback", { count: toolCalls.length }); if (remainingText.length > 0) { (state.content[textIdx] as CanonicalTextBlock).text = remainingText; } else { diff --git a/src/model/streaming/streamModel.ts b/src/model/streaming/streamModel.ts index 48b37fe4..43852f19 100644 --- a/src/model/streaming/streamModel.ts +++ b/src/model/streaming/streamModel.ts @@ -1,3 +1,5 @@ +import { createLogger } from '../../../pilot/logger.js'; +const stream_model_log = createLogger('stream-model'); import { normalizeModelError } from "../errors/normalizeModelError.js"; import { buildModelRequest } from "../request/buildModelRequest.js"; import { validateModelRequest } from "../request/validateModelRequest.js"; @@ -68,7 +70,7 @@ export async function* streamModel( const fs = await import("node:fs"); const dumpPath = `/tmp/pilotdeck_request_${Date.now()}.json`; fs.writeFileSync(dumpPath, JSON.stringify(body, null, 2)); - console.log(`[model-debug] Request dumped to ${dumpPath} (model=${currentRequest.model})`); + streamModelLog.info("model-debug request dumped", { dumpPath, model: currentRequest.model }); } let response: Response; try { diff --git a/src/pilot/logger.ts b/src/pilot/logger.ts new file mode 100644 index 00000000..7d13ed10 --- /dev/null +++ b/src/pilot/logger.ts @@ -0,0 +1,158 @@ +import { AsyncLocalStorage } from 'node:async_hooks'; + +/* ------------------------------------------------------------------ */ +/* Log levels */ +/* ------------------------------------------------------------------ */ + +export enum LogLevel { + DEBUG = 0, + INFO = 1, + WARN = 2, + ERROR = 3, +} + +/* ------------------------------------------------------------------ */ +/* Log entry shape */ +/* ------------------------------------------------------------------ */ + +export interface LogEntry { + timestamp: string; + level: LogLevel; + module: string; + message: string; + data?: Record; + error?: { message: string; stack?: string }; + requestId?: string; +} + +/* ------------------------------------------------------------------ */ +/* Request-ID context (AsyncLocalStorage) */ +/* ------------------------------------------------------------------ */ + +export const requestContext = new AsyncLocalStorage<{ requestId: string }>(); + +export function getRequestId(): string { + return requestContext.getStore()?.requestId ?? 'unknown'; +} + +export function withRequestId(requestId: string, fn: () => T): T { + return requestContext.run({ requestId }, fn); +} + +export async function withRequestIdAsync( + requestId: string, + fn: () => Promise, +): Promise { + return requestContext.run({ requestId }, fn); +} + +/* ------------------------------------------------------------------ */ +/* Global level control */ +/* ------------------------------------------------------------------ */ + +let globalLevel: LogLevel | undefined; + +export function setGlobalLogLevel(level: LogLevel): void { + globalLevel = level; +} + +/* ------------------------------------------------------------------ */ +/* Logger class */ +/* ------------------------------------------------------------------ */ + +class PilotLogger { + private readonly module: string; + + constructor(module: string) { + this.module = module; + } + + /* ---- internal -------------------------------------------------- */ + + private shouldLog(level: LogLevel): boolean { + const effective = globalLevel ?? LogLevel.INFO; + return level >= effective; + } + + private format(level: LogLevel, message: string, data?: Record, error?: Error): LogEntry { + const entry: LogEntry = { + timestamp: new Date().toISOString(), + level, + module: this.module, + message, + requestId: getRequestId(), + }; + if (data && Object.keys(data).length > 0) { + entry.data = data; + } + if (error) { + entry.error = { message: error.message, stack: error.stack }; + } + return entry; + } + + private write(entry: LogEntry): void { + const prefix = `[${entry.timestamp}] [${LogLevel[entry.level]}] [${entry.module}]`; + + // Use the appropriate console method based on level. + switch (entry.level) { + case LogLevel.ERROR: { + const args: unknown[] = [prefix, entry.message]; + if (entry.data) args.push(entry.data); + if (entry.error) args.push(entry.error); + console.error(...args); + break; + } + case LogLevel.WARN: { + const args: unknown[] = [prefix, entry.message]; + if (entry.data) args.push(entry.data); + console.warn(...args); + break; + } + case LogLevel.DEBUG: { + const args: unknown[] = [prefix, entry.message]; + if (entry.data) args.push(entry.data); + console.debug(...args); + break; + } + default: { + const args: unknown[] = [prefix, entry.message]; + if (entry.data) args.push(entry.data); + console.log(...args); + break; + } + } + } + + private log(level: LogLevel, message: string, data?: Record, error?: Error): void { + if (!this.shouldLog(level)) return; + const entry = this.format(level, message, data, error); + this.write(entry); + } + + /* ---- public API ------------------------------------------------ */ + + debug(message: string, data?: Record): void { + this.log(LogLevel.DEBUG, message, data); + } + + info(message: string, data?: Record): void { + this.log(LogLevel.INFO, message, data); + } + + warn(message: string, data?: Record): void { + this.log(LogLevel.WARN, message, data); + } + + error(message: string, error?: Error, data?: Record): void { + this.log(LogLevel.ERROR, message, data, error); + } +} + +/* ------------------------------------------------------------------ */ +/* Factory */ +/* ------------------------------------------------------------------ */ + +export function createLogger(module: string): PilotLogger { + return new PilotLogger(module); +} diff --git a/src/router/RouterRuntime.ts b/src/router/RouterRuntime.ts index c54fc47d..d382ea3a 100644 --- a/src/router/RouterRuntime.ts +++ b/src/router/RouterRuntime.ts @@ -13,7 +13,7 @@ import type { PilotDeckCustomRouter, CustomRouterRegistry, } from "./customRouter/customRouter.js"; -import { noopCustomRouterRegistry } from "./customRouter/customRouter.js"; + import { isFallbackEligible, planFallback } from "./fallback/runFallbackChain.js"; import { applyOrchestration } from "./orchestrate/applyOrchestration.js"; import type { @@ -36,6 +36,10 @@ import { import { TokenStatsCollector } from "./stats/TokenStatsCollector.js"; import { classifyAndRoute } from "./tokenSaver/classifyAndRoute.js"; import { countMessagesTokens, countResponseTokens, dispose as disposeTokenizer } from "./utils/countTokens.js"; +import { createLogger } from '../pilot/logger.js'; +import { noopCustomRouterRegistry } from './customRouter/customRouter.js'; + +const routerLog = createLogger('router'); export type RouterRuntimeDeps = { modelRuntime: ModelRuntime; @@ -260,9 +264,13 @@ export function createRouterRuntime( const alreadyOrchestrating = sticky?.orchestrating === true; const tokenSaverActive = config.tokenSaver?.enabled === true && tokenSaverTier != null; const orchGate = tokenSaverActive || alreadyOrchestrating; - console.log( - `[router] decision: tier=${tokenSaverTier}, model=${selection.provider}/${selection.model}, orchGate=${orchGate}, alreadyOrch=${alreadyOrchestrating}, resolvedFrom=${resolvedFrom}`, - ); + routerLog.info('decision', { + tier: tokenSaverTier, + model: `${selection.provider}/${selection.model}`, + orchGate, + alreadyOrch: alreadyOrchestrating, + resolvedFrom, + }); let skillPrompt: string | undefined; if ( @@ -516,10 +524,13 @@ export function createRouterRuntime( outcome.shouldRetryZeroUsage && zeroUsageAttempt < zeroUsageMax ) { - console.warn( - `[PilotDeck] zeroUsageRetry: empty response from ${attempt.provider}/${attempt.model} ` + - `(attempt ${zeroUsageAttempt}/${zeroUsageMax}, session=${ctx.sessionId})`, - ); + routerLog.warn('zeroUsageRetry: empty response', { + provider: attempt.provider, + model: attempt.model, + attempt: zeroUsageAttempt, + max: zeroUsageMax, + session: ctx.sessionId, + }); events.emit({ type: "pilotdeck_router_zero_usage_retry", sessionId: ctx.sessionId, diff --git a/src/router/tokenSaver/classifyAndRoute.ts b/src/router/tokenSaver/classifyAndRoute.ts index 64fe7fba..1b99f6f2 100644 --- a/src/router/tokenSaver/classifyAndRoute.ts +++ b/src/router/tokenSaver/classifyAndRoute.ts @@ -1,3 +1,5 @@ +import { createLogger } from '../../../pilot/logger.js'; +const tokenSaverLog = createLogger('token-saver'); import type { CanonicalMessage, CanonicalModelRequest, @@ -91,7 +93,7 @@ export async function classifyAndRoute( if (attempt < maxAttempts) { continue; } - console.warn("[token-saver] Judge returned empty after retries"); + tokenSaverLog.warn("Judge returned empty after retries"); return { tier: config.defaultTier, selection: defaultTier.model,