diff --git a/docs/development.md b/docs/development.md index 6bfdbb829..de90076fd 100644 --- a/docs/development.md +++ b/docs/development.md @@ -39,7 +39,14 @@ In any worktree-style or portless setup, never assume default ports. ### Daemon logs -Check `$PASEO_HOME/daemon.log` for trace-level logs. +Check `$PASEO_HOME/daemon.log` for daemon logs. The default level is `info`; set +`PASEO_LOG_LEVEL=trace` before launching the daemon when you need full provider, +session, and agent-manager traces for stuck-state debugging. + +The supervisor rotates `daemon.log`. Persisted `log.file.rotate` settings in +`$PASEO_HOME/config.json` win first. Without persisted config, the optional +`PASEO_LOG_ROTATE_SIZE` and `PASEO_LOG_ROTATE_COUNT` env vars override the +defaults. The default rotation is `10m` x `3` files everywhere. ## paseo.json service scripts diff --git a/packages/server/scripts/supervisor-entrypoint.ts b/packages/server/scripts/supervisor-entrypoint.ts index 13ae75ebb..ea5b5505c 100644 --- a/packages/server/scripts/supervisor-entrypoint.ts +++ b/packages/server/scripts/supervisor-entrypoint.ts @@ -10,12 +10,9 @@ import { import { resolvePaseoHome } from "../src/server/paseo-home.js"; import { loadPersistedConfig } from "../src/server/persisted-config.js"; import { runSupervisor } from "./supervisor.js"; +import { resolveSupervisorLogFile } from "./supervisor-log-config.js"; import { applySherpaLoaderEnv } from "../src/server/speech/providers/local/sherpa/sherpa-runtime-env.js"; -const DEFAULT_DAEMON_LOG_FILENAME = "daemon.log"; -const DEFAULT_LOG_ROTATE_SIZE = "10m"; -const DEFAULT_LOG_ROTATE_MAX_FILES = 2; - interface DaemonRunnerConfig { devMode: boolean; workerArgs: string[]; @@ -77,28 +74,6 @@ function resolvePackagedNodeEntrypointRunnerPath(currentScriptPath: string): str return existsSync(runnerPath) ? runnerPath : null; } -function resolveSupervisorLogFile( - paseoHome: string, - persistedConfig: ReturnType, -) { - const configuredFile = persistedConfig.log?.file; - const configuredPath = configuredFile?.path; - let logPath = path.join(paseoHome, DEFAULT_DAEMON_LOG_FILENAME); - if (configuredPath) { - logPath = path.isAbsolute(configuredPath) - ? configuredPath - : path.resolve(paseoHome, configuredPath); - } - - return { - path: logPath, - rotate: { - maxSize: configuredFile?.rotate?.maxSize ?? DEFAULT_LOG_ROTATE_SIZE, - maxFiles: configuredFile?.rotate?.maxFiles ?? DEFAULT_LOG_ROTATE_MAX_FILES, - }, - }; -} - async function main(): Promise { const config = parseConfig(process.argv.slice(2)); const workerEntry = config.devMode ? resolveDevWorkerEntry() : resolveWorkerEntry(); @@ -113,7 +88,7 @@ async function main(): Promise { const paseoHome = resolvePaseoHome(workerEnv); const persistedConfig = loadPersistedConfig(paseoHome); - const supervisorLogFile = resolveSupervisorLogFile(paseoHome, persistedConfig); + const supervisorLogFile = resolveSupervisorLogFile(paseoHome, persistedConfig, workerEnv); try { await acquirePidLock(paseoHome, null, { diff --git a/packages/server/scripts/supervisor-log-config.ts b/packages/server/scripts/supervisor-log-config.ts new file mode 100644 index 000000000..f42657baf --- /dev/null +++ b/packages/server/scripts/supervisor-log-config.ts @@ -0,0 +1,42 @@ +import path from "node:path"; + +import type { loadPersistedConfig } from "../src/server/persisted-config.js"; + +const DEFAULT_DAEMON_LOG_FILENAME = "daemon.log"; +const DEFAULT_LOG_ROTATE_SIZE = "10m"; +const DEFAULT_LOG_ROTATE_MAX_FILES = 3; + +export function resolveSupervisorLogFile( + paseoHome: string, + persistedConfig: ReturnType, + env: NodeJS.ProcessEnv = process.env, +) { + const configuredFile = persistedConfig.log?.file; + const configuredPath = configuredFile?.path; + const envRotateSize = env.PASEO_LOG_ROTATE_SIZE?.trim(); + const envRotateMaxFiles = parseOptionalPositiveInteger(env.PASEO_LOG_ROTATE_COUNT); + let logPath = path.join(paseoHome, DEFAULT_DAEMON_LOG_FILENAME); + if (configuredPath) { + logPath = path.isAbsolute(configuredPath) + ? configuredPath + : path.resolve(paseoHome, configuredPath); + } + + return { + path: logPath, + rotate: { + maxSize: configuredFile?.rotate?.maxSize ?? envRotateSize ?? DEFAULT_LOG_ROTATE_SIZE, + maxFiles: + configuredFile?.rotate?.maxFiles ?? envRotateMaxFiles ?? DEFAULT_LOG_ROTATE_MAX_FILES, + }, + }; +} + +function parseOptionalPositiveInteger(value: string | undefined): number | undefined { + if (value === undefined) { + return undefined; + } + + const parsed = Number.parseInt(value.trim(), 10); + return Number.isInteger(parsed) && parsed > 0 ? parsed : undefined; +} diff --git a/packages/server/scripts/supervisor.logging.test.ts b/packages/server/scripts/supervisor.logging.test.ts index 1dca09c47..3d42179fd 100644 --- a/packages/server/scripts/supervisor.logging.test.ts +++ b/packages/server/scripts/supervisor.logging.test.ts @@ -5,6 +5,7 @@ import { fileURLToPath, pathToFileURL } from "node:url"; import { spawn } from "node:child_process"; import { describe, expect, test } from "vitest"; import { isPlatform } from "../src/test-utils/platform.js"; +import { resolveSupervisorLogFile } from "./supervisor-log-config.js"; const repoRoot = path.resolve(fileURLToPath(new URL("../../..", import.meta.url))); const supervisorPath = fileURLToPath(new URL("./supervisor.ts", import.meta.url)); @@ -87,6 +88,57 @@ async function runSupervisorFixture(options: { } describe("supervisor durable logging", () => { + test("resolves rotation defaults", () => { + const paseoHome = path.join(path.sep, "tmp", "paseo-home"); + const logFile = resolveSupervisorLogFile(paseoHome, {}, {}); + + expect(logFile).toEqual({ + path: path.join(paseoHome, "daemon.log"), + rotate: { maxSize: "10m", maxFiles: 3 }, + }); + }); + + test("lets persisted rotation override env rotation defaults", () => { + const paseoHome = path.join(path.sep, "tmp", "paseo-home"); + const logFile = resolveSupervisorLogFile( + paseoHome, + { + log: { + file: { + path: "logs/daemon.log", + rotate: { maxSize: "25m", maxFiles: 4 }, + }, + }, + }, + { + PASEO_LOG_ROTATE_SIZE: "200m", + PASEO_LOG_ROTATE_COUNT: "12", + }, + ); + + expect(logFile).toEqual({ + path: path.resolve(paseoHome, "logs", "daemon.log"), + rotate: { maxSize: "25m", maxFiles: 4 }, + }); + }); + + test("uses env rotation when persisted rotation is absent", () => { + const paseoHome = path.join(path.sep, "tmp", "paseo-home"); + const logFile = resolveSupervisorLogFile( + paseoHome, + {}, + { + PASEO_LOG_ROTATE_SIZE: "50m", + PASEO_LOG_ROTATE_COUNT: "8", + }, + ); + + expect(logFile).toEqual({ + path: path.join(paseoHome, "daemon.log"), + rotate: { maxSize: "50m", maxFiles: 8 }, + }); + }); + test("writes supervised worker stdout and stderr to daemon.log", async () => { const result = await runSupervisorFixture({ workerSource: ` diff --git a/packages/server/src/server/agent/agent-manager.test.ts b/packages/server/src/server/agent/agent-manager.test.ts index d9a96a9ed..705ddbabe 100644 --- a/packages/server/src/server/agent/agent-manager.test.ts +++ b/packages/server/src/server/agent/agent-manager.test.ts @@ -716,6 +716,7 @@ test("createAgent passes daemon launch env through the provider launch context", modeId: "auto", }); expect(client.lastLaunchContext).toEqual({ + agentId: snapshot.id, env: { PASEO_AGENT_ID: snapshot.id, }, @@ -1179,6 +1180,7 @@ test("resumeAgentFromPersistence keeps metadata config, applies overrides, and p }, }); expect(client.lastResumeLaunchContext).toEqual({ + agentId: resumed.id, env: { PASEO_AGENT_ID: resumed.id, }, @@ -1283,6 +1285,7 @@ test("reloadAgentSession passes daemon launch env through the provider launch co }); expect(client.lastCreateLaunchContext).toEqual({ + agentId: snapshot.id, env: { PASEO_AGENT_ID: snapshot.id, }, @@ -1293,6 +1296,7 @@ test("reloadAgentSession passes daemon launch env through the provider launch co }); expect(client.lastResumeLaunchContext).toEqual({ + agentId: snapshot.id, env: { PASEO_AGENT_ID: snapshot.id, }, diff --git a/packages/server/src/server/agent/agent-manager.ts b/packages/server/src/server/agent/agent-manager.ts index 5d047f0f4..4b9c120cb 100644 --- a/packages/server/src/server/agent/agent-manager.ts +++ b/packages/server/src/server/agent/agent-manager.ts @@ -10,30 +10,31 @@ import type { Logger } from "pino"; import { z } from "zod"; import type { TerminalManager } from "../../terminal/terminal-manager.js"; -import type { - AgentCapabilityFlags, - AgentClient, - AgentCreateSessionOptions, - AgentFeature, - AgentLaunchContext, - AgentSlashCommand, - AgentMode, - AgentPermissionRequest, - AgentPermissionResponse, - AgentPermissionResult, - AgentPersistenceHandle, - AgentPromptInput, - AgentProvider, - AgentRunOptions, - AgentRunResult, - AgentSession, - AgentSessionConfig, - AgentStreamEvent, - AgentTimelineItem, - AgentUsage, - AgentRuntimeInfo, - ListPersistedAgentsOptions, - PersistedAgentDescriptor, +import { + getAgentStreamEventTurnId, + type AgentCapabilityFlags, + type AgentClient, + type AgentCreateSessionOptions, + type AgentFeature, + type AgentLaunchContext, + type AgentSlashCommand, + type AgentMode, + type AgentPermissionRequest, + type AgentPermissionResponse, + type AgentPermissionResult, + type AgentPersistenceHandle, + type AgentPromptInput, + type AgentProvider, + type AgentRunOptions, + type AgentRunResult, + type AgentSession, + type AgentSessionConfig, + type AgentStreamEvent, + type AgentTimelineItem, + type AgentUsage, + type AgentRuntimeInfo, + type ListPersistedAgentsOptions, + type PersistedAgentDescriptor, } from "./agent-sdk-types.js"; import { buildArchivedAgentRecord, type ArchivedStoredAgentRecord } from "./agent-archive.js"; import type { StoredAgentRecord, AgentStorage } from "./agent-storage.js"; @@ -1005,18 +1006,28 @@ export class AgentManager { this.logger.trace( { agentId, + provider: agent.provider, + sessionId: agent.persistence?.sessionId ?? undefined, + turnId: agent.activeForegroundTurnId ?? undefined, lifecycle: agent.lifecycle, activeForegroundTurnId: agent.activeForegroundTurnId, pendingPermissions: agent.pendingPermissions.size, }, - "closeAgent: start", + "agent.manager.close.start", ); const closedAgent = this.prepareAgentForClosure(agent, "agent closed"); await agent.session.close(); this.timelineStore.delete(agentId); await this.persistSnapshot(closedAgent); this.emitClosedAgent(closedAgent, { persist: false }); - this.logger.trace({ agentId }, "closeAgent: completed"); + this.logger.trace( + { + agentId, + provider: closedAgent.provider, + sessionId: closedAgent.persistence?.sessionId ?? undefined, + }, + "agent.manager.close.complete", + ); } async archiveAgent(agentId: string): Promise<{ archivedAt: string }> { @@ -1470,22 +1481,28 @@ export class AgentManager { this.logger.trace( { agentId, + provider: existingAgent.provider, + sessionId: existingAgent.persistence?.sessionId ?? undefined, + turnId: existingAgent.activeForegroundTurnId ?? undefined, lifecycle: existingAgent.lifecycle, activeForegroundTurnId: existingAgent.activeForegroundTurnId, hasPendingForegroundRun: this.foregroundRuns.hasPendingRun(agentId), promptType: typeof prompt === "string" ? "string" : "structured", hasRunOptions: Boolean(options), }, - "streamAgent: requested", + "agent.manager.stream.request", ); if (existingAgent.activeForegroundTurnId || this.foregroundRuns.hasPendingRun(agentId)) { this.logger.trace( { agentId, + provider: existingAgent.provider, + sessionId: existingAgent.persistence?.sessionId ?? undefined, + turnId: existingAgent.activeForegroundTurnId ?? undefined, lifecycle: existingAgent.lifecycle, hasPendingForegroundRun: this.foregroundRuns.hasPendingRun(agentId), }, - "streamAgent: rejected because a foreground run is already in flight", + "agent.manager.stream.reject", ); throw new Error(`Agent ${agentId} already has an active run`); } @@ -1522,10 +1539,13 @@ export class AgentManager { this.logger.trace( { agentId, + provider: agent.provider, + sessionId: agent.persistence?.sessionId ?? undefined, + turnId, lifecycle: agent.lifecycle, activeForegroundTurnId: agent.activeForegroundTurnId, }, - "streamAgent: started", + "agent.manager.stream.start", ); turnStream = this.foregroundRuns.createTurnStream(turnId); @@ -1577,11 +1597,14 @@ export class AgentManager { this.logger.trace( { agentId: agent.id, + provider: agent.provider, + sessionId: mutableAgent.persistence?.sessionId ?? undefined, + turnId, lifecycle: mutableAgent.lifecycle, terminalError, pendingReplacement: mutableAgent.pendingReplacement, }, - "finalizeForegroundTurn: applying terminal state", + "agent.manager.finalize", ); if (!shouldHoldBusyForReplacement) { this.touchUpdatedAt(mutableAgent); @@ -2371,6 +2394,16 @@ export class AgentManager { } private enqueueSessionEvent(agentId: string, event: AgentStreamEvent): void { + this.logger.trace( + { + agentId, + provider: event.provider, + sessionId: this.agents.get(agentId)?.persistence?.sessionId ?? undefined, + turnId: getAgentStreamEventTurnId(event), + event, + }, + "agent.manager.enqueue", + ); const previous = this.sessionEventTails.get(agentId) ?? Promise.resolve(); const next = previous .catch(() => undefined) @@ -2382,6 +2415,16 @@ export class AgentManager { if (current.session == null) { return; } + this.logger.trace( + { + agentId, + provider: event.provider, + sessionId: current.persistence?.sessionId ?? undefined, + turnId: getAgentStreamEventTurnId(event), + event, + }, + "agent.manager.dequeue", + ); await this.dispatchSessionEvent(current, event); return; }) @@ -2405,8 +2448,19 @@ export class AgentManager { agent: ActiveManagedAgent, event: AgentStreamEvent, ): Promise { - const turnId = (event as { turnId?: string }).turnId; + const turnId = getAgentStreamEventTurnId(event); const matchingWaiters = this.foregroundRuns.getMatchingWaiters(agent, turnId); + this.logger.trace( + { + agentId: agent.id, + provider: event.provider, + sessionId: agent.persistence?.sessionId ?? undefined, + turnId, + matchingWaiterCount: matchingWaiters.length, + event, + }, + "agent.manager.dispatch_session_event", + ); const shouldNotifyWaiters = await this.handleStreamEvent(agent, event); @@ -2417,6 +2471,18 @@ export class AgentManager { this.foregroundRuns.notifyWaiters(matchingWaiters, event, { terminal: isTurnTerminalEvent(event), }); + this.logger.trace( + { + agentId: agent.id, + provider: event.provider, + sessionId: agent.persistence?.sessionId ?? undefined, + turnId, + notifiedWaiterCount: matchingWaiters.length, + terminal: isTurnTerminalEvent(event), + event, + }, + "agent.manager.notify_waiters", + ); } private async resolveInitialPersistedTitle( @@ -2529,7 +2595,7 @@ export class AgentManager { } private notifyForegroundTurnWaiters(agentId: string, event: AgentStreamEvent): void { - const turnId = (event as { turnId?: string }).turnId; + const turnId = getAgentStreamEventTurnId(event); if (turnId == null) { return; } @@ -2540,6 +2606,16 @@ export class AgentManager { } this.foregroundRuns.notifyAgentWaiters(agent, event); + this.logger.trace( + { + agentId, + provider: event.provider, + sessionId: agent.persistence?.sessionId ?? undefined, + turnId, + event, + }, + "agent.manager.notify_waiters.coalesced", + ); } private async handleStreamEvent( @@ -2547,8 +2623,9 @@ export class AgentManager { event: AgentStreamEvent, options?: HandleStreamEventOptions, ): Promise { - const eventTurnId = (event as { turnId?: string }).turnId; + const eventTurnId = getAgentStreamEventTurnId(event); const isForegroundEvent = Boolean(eventTurnId && agent.activeForegroundTurnId === eventTurnId); + this.traceHandleStreamEventStart(agent, event, eventTurnId, isForegroundEvent); if ( eventTurnId && isTurnTerminalEvent(event) && @@ -2561,6 +2638,7 @@ export class AgentManager { if (!options?.fromHistory) { this.touchUpdatedAt(agent); if (this.agentStreamCoalescer.handle(agent.id, event)) { + this.traceCoalescerBuffered(agent, event, eventTurnId); return false; } this.agentStreamCoalescer.flushFor(agent.id); @@ -2588,9 +2666,71 @@ export class AgentManager { this.dispatchStream(agent.id, event); } + this.traceHandleStreamEventEnd(agent, event, eventTurnId, flags); + return flags.shouldNotifyWaiters; } + private traceHandleStreamEventStart( + agent: ActiveManagedAgent, + event: AgentStreamEvent, + turnId: string | undefined, + isForegroundEvent: boolean, + ): void { + this.logger.trace( + { + agentId: agent.id, + provider: event.provider, + sessionId: agent.persistence?.sessionId ?? undefined, + turnId, + lifecycle: agent.lifecycle, + activeForegroundTurnId: agent.activeForegroundTurnId, + isForegroundEvent, + event, + }, + "agent.manager.handle_stream_event.start", + ); + } + + private traceCoalescerBuffered( + agent: ActiveManagedAgent, + event: AgentStreamEvent, + turnId: string | undefined, + ): void { + this.logger.trace( + { + agentId: agent.id, + provider: event.provider, + sessionId: agent.persistence?.sessionId ?? undefined, + turnId, + event, + }, + "agent.manager.coalescer.buffer", + ); + } + + private traceHandleStreamEventEnd( + agent: ActiveManagedAgent, + event: AgentStreamEvent, + turnId: string | undefined, + flags: StreamEventFlags, + ): void { + this.logger.trace( + { + agentId: agent.id, + provider: event.provider, + sessionId: agent.persistence?.sessionId ?? undefined, + turnId, + lifecycle: agent.lifecycle, + activeForegroundTurnId: agent.activeForegroundTurnId, + shouldDispatchEvent: flags.shouldDispatchEvent, + shouldNotifyWaiters: flags.shouldNotifyWaiters, + event, + }, + "agent.manager.handle_stream_event.end", + ); + } + private dispatchStreamEventByType(params: { agent: ActiveManagedAgent; event: AgentStreamEvent; @@ -2747,11 +2887,13 @@ export class AgentManager { this.logger.trace( { agentId: agent.id, + provider: agent.provider, + sessionId: agent.persistence?.sessionId ?? undefined, + turnId: eventTurnId, lifecycle: agent.lifecycle, activeForegroundTurnId: agent.activeForegroundTurnId, - eventTurnId, }, - "handleStreamEvent: turn_completed", + "agent.manager.turn.completed", ); agent.lastUsage = event.usage; agent.lastError = undefined; @@ -2778,6 +2920,9 @@ export class AgentManager { this.logger.warn( { agentId: agent.id, + provider: agent.provider, + sessionId: agent.persistence?.sessionId ?? undefined, + turnId: eventTurnId, lifecycle: agent.lifecycle, activeForegroundTurnId: agent.activeForegroundTurnId, eventTurnId, @@ -2818,11 +2963,14 @@ export class AgentManager { this.logger.trace( { agentId: agent.id, + provider: agent.provider, + sessionId: agent.persistence?.sessionId ?? undefined, + turnId: eventTurnId, lifecycle: agent.lifecycle, activeForegroundTurnId: agent.activeForegroundTurnId, eventTurnId, }, - "handleStreamEvent: turn_canceled", + "agent.manager.turn.canceled", ); if (!isForegroundEvent && !agent.pendingReplacement) { agent.lifecycle = "idle"; @@ -2843,11 +2991,13 @@ export class AgentManager { this.logger.trace( { agentId: agent.id, + provider: agent.provider, + sessionId: agent.persistence?.sessionId ?? undefined, + turnId: eventTurnId, lifecycle: agent.lifecycle, activeForegroundTurnId: agent.activeForegroundTurnId, - eventTurnId, }, - "handleStreamEvent: turn_started", + "agent.manager.turn.started", ); if (!isForegroundEvent) { agent.lifecycle = "running"; @@ -2993,6 +3143,20 @@ export class AgentManager { this.syncFeaturesFromSession(agent); + this.logger.trace( + { + agentId: agent.id, + provider: agent.provider, + sessionId: agent.persistence?.sessionId ?? undefined, + turnId: agent.activeForegroundTurnId ?? undefined, + lifecycle: agent.lifecycle, + activeForegroundTurnId: agent.activeForegroundTurnId, + pendingPermissions: agent.pendingPermissions.size, + persist: options?.persist !== false, + }, + "agent.manager.emit_state", + ); + this.dispatch({ type: "agent_state", agent: { ...agent }, @@ -3120,6 +3284,18 @@ export class AgentManager { event: AgentStreamEvent, metadata?: { seq?: number; epoch?: string }, ): void { + const agent = this.agents.get(agentId); + this.logger.trace( + { + agentId, + provider: event.provider, + sessionId: agent?.persistence?.sessionId ?? undefined, + turnId: getAgentStreamEventTurnId(event), + metadata, + event, + }, + "agent.manager.dispatch_stream", + ); this.dispatch({ type: "agent_stream", agentId, event, ...metadata }); } @@ -3215,6 +3391,7 @@ export class AgentManager { private buildLaunchContext(agentId: string): AgentLaunchContext { return { + agentId, env: { PASEO_AGENT_ID: agentId, }, diff --git a/packages/server/src/server/agent/agent-prompt.ts b/packages/server/src/server/agent/agent-prompt.ts index 5135c77e1..ed50b9b0e 100644 --- a/packages/server/src/server/agent/agent-prompt.ts +++ b/packages/server/src/server/agent/agent-prompt.ts @@ -17,6 +17,19 @@ export function startAgentRun( logger: Logger, options?: StartAgentRunOptions, ): { outOfBand: boolean } { + const snapshot = agentManager.getAgent(agentId); + logger.trace( + { + agentId, + provider: snapshot?.provider, + providerSessionId: snapshot?.persistence?.sessionId ?? undefined, + turnId: snapshot?.activeForegroundTurnId ?? undefined, + promptType: typeof prompt === "string" ? "string" : "structured", + hasRunOptions: Boolean(options?.runOptions), + replaceRunning: Boolean(options?.replaceRunning), + }, + "agent.session.start_stream.request", + ); // Out-of-band commands (e.g. /goal pause) must run WITHOUT canceling an // in-flight turn — replaceAgentRun would interrupt the running turn. The // intercept lives at this layer so it covers every prompt entrypoint. @@ -28,12 +41,38 @@ export function startAgentRun( const iterator = shouldReplace ? agentManager.replaceAgentRun(agentId, prompt, runOptions) : agentManager.streamAgent(agentId, prompt, runOptions); + logger.trace( + { + agentId, + provider: snapshot?.provider, + providerSessionId: snapshot?.persistence?.sessionId ?? undefined, + shouldReplace, + }, + "agent.session.start_stream.iterator_returned", + ); void (async () => { try { for await (const _ of iterator) { // Events are broadcast via AgentManager subscribers. } + logger.trace( + { + agentId, + provider: snapshot?.provider, + providerSessionId: snapshot?.persistence?.sessionId ?? undefined, + }, + "agent.session.iterator.drained", + ); } catch (error) { + logger.trace( + { + agentId, + provider: snapshot?.provider, + providerSessionId: snapshot?.persistence?.sessionId ?? undefined, + err: error, + }, + "agent.session.iterator.error", + ); logger.error({ err: error, agentId }, "Agent stream failed"); } })(); diff --git a/packages/server/src/server/agent/agent-sdk-types.ts b/packages/server/src/server/agent/agent-sdk-types.ts index a5a03e563..5639bb8b4 100644 --- a/packages/server/src/server/agent/agent-sdk-types.ts +++ b/packages/server/src/server/agent/agent-sdk-types.ts @@ -358,6 +358,10 @@ export type AgentStreamEvent = timestamp: string; }; +export function getAgentStreamEventTurnId(event: AgentStreamEvent): string | undefined { + return "turnId" in event ? event.turnId : undefined; +} + export type AgentPermissionRequestKind = "tool" | "plan" | "question" | "mode" | "other"; export type AgentPermissionUpdate = AgentMetadata; @@ -476,6 +480,7 @@ export interface AgentSessionConfig { } export interface AgentLaunchContext { + agentId?: string; env?: Record; } diff --git a/packages/server/src/server/agent/foreground-run-state.ts b/packages/server/src/server/agent/foreground-run-state.ts index 44d33c045..705c59a38 100644 --- a/packages/server/src/server/agent/foreground-run-state.ts +++ b/packages/server/src/server/agent/foreground-run-state.ts @@ -1,6 +1,6 @@ import { randomUUID } from "node:crypto"; -import type { AgentStreamEvent } from "./agent-sdk-types.js"; +import { getAgentStreamEventTurnId, type AgentStreamEvent } from "./agent-sdk-types.js"; export interface ForegroundTurnWaiter { turnId: string; @@ -105,7 +105,7 @@ export class ForegroundRunState { event: AgentStreamEvent, options?: { terminal?: boolean }, ): void { - const waiters = this.getMatchingWaiters(agent, eventTurnId(event)); + const waiters = this.getMatchingWaiters(agent, getAgentStreamEventTurnId(event)); this.notifyWaiters(waiters, event, { terminal: options?.terminal ?? false }); } @@ -226,7 +226,3 @@ function settlePendingForegroundRun(pendingRun: PendingForegroundRun): void { pendingRun.settled = true; pendingRun.resolveSettled(); } - -function eventTurnId(event: AgentStreamEvent): string | undefined { - return (event as { turnId?: string }).turnId; -} diff --git a/packages/server/src/server/agent/providers/acp-agent.test.ts b/packages/server/src/server/agent/providers/acp-agent.test.ts index ae458e01a..ef0c0776e 100644 --- a/packages/server/src/server/agent/providers/acp-agent.test.ts +++ b/packages/server/src/server/agent/providers/acp-agent.test.ts @@ -266,7 +266,7 @@ function prepareConfiguredOverrideSession( test("ACP setModel only uses config-option fallback when the matching select choice contains the model", async () => { const logger = createTestLogger(); - const childLogger = { warn: vi.fn() }; + const childLogger = { trace: vi.fn(), warn: vi.fn() }; vi.spyOn(logger, "child").mockReturnValue(asInternals(childLogger)); const session = createSessionWithConfig({}, logger); const setSessionConfigOption = vi.fn(async () => ({ @@ -653,7 +653,7 @@ describe("ACPAgentSession Zed parity", () => { expect(await validSession.getCurrentMode()).toBe("default"); const logger = createTestLogger(); - const childLogger = { warn: vi.fn() }; + const childLogger = { trace: vi.fn(), warn: vi.fn() }; vi.spyOn(logger, "child").mockReturnValue(asInternals(childLogger)); const invalidSession = createSessionWithConfig( { modeId: "acceptEdits", model: "opus" }, diff --git a/packages/server/src/server/agent/providers/acp-agent.ts b/packages/server/src/server/agent/providers/acp-agent.ts index a98b57e77..20100d1ae 100644 --- a/packages/server/src/server/agent/providers/acp-agent.ts +++ b/packages/server/src/server/agent/providers/acp-agent.ts @@ -54,35 +54,36 @@ import { } from "@agentclientprotocol/sdk"; import type { Logger } from "pino"; -import type { - AgentCapabilityFlags, - AgentClient, - AgentLaunchContext, - AgentMetadata, - AgentMode, - AgentModelDefinition, - AgentPermissionRequest, - AgentPermissionRequestKind, - AgentPermissionResponse, - AgentPersistenceHandle, - AgentPromptContentBlock, - AgentPromptInput, - AgentRunOptions, - AgentRunResult, - AgentRuntimeInfo, - AgentSession, - AgentSessionConfig, - AgentSlashCommand, - AgentStreamEvent, - AgentTimelineItem, - AgentUsage, - ListModesOptions, - ListModelsOptions, - ListPersistedAgentsOptions, - McpServerConfig, - PersistedAgentDescriptor, - ToolCallDetail, - ToolCallTimelineItem, +import { + getAgentStreamEventTurnId, + type AgentCapabilityFlags, + type AgentClient, + type AgentLaunchContext, + type AgentMetadata, + type AgentMode, + type AgentModelDefinition, + type AgentPermissionRequest, + type AgentPermissionRequestKind, + type AgentPermissionResponse, + type AgentPersistenceHandle, + type AgentPromptContentBlock, + type AgentPromptInput, + type AgentRunOptions, + type AgentRunResult, + type AgentRuntimeInfo, + type AgentSession, + type AgentSessionConfig, + type AgentSlashCommand, + type AgentStreamEvent, + type AgentTimelineItem, + type AgentUsage, + type ListModesOptions, + type ListModelsOptions, + type ListPersistedAgentsOptions, + type McpServerConfig, + type PersistedAgentDescriptor, + type ToolCallDetail, + type ToolCallTimelineItem, } from "../agent-sdk-types.js"; import { createProviderEnvSpec, @@ -265,6 +266,7 @@ interface ACPAgentSessionOptions { ) => Promise; capabilities: AgentCapabilityFlags; handle?: AgentPersistenceHandle; + agentId?: string; launchEnv?: Record; waitForInitialCommands?: boolean; initialCommandsWaitTimeoutMs?: number; @@ -519,7 +521,10 @@ export class ACPAgentClient implements AgentClient { constructor(options: ACPAgentClientOptions) { this.provider = options.provider; this.capabilities = options.capabilities ?? DEFAULT_ACP_CAPABILITIES; - this.logger = options.logger.child({ module: "agent", provider: options.provider }); + this.logger = options.logger.child({ + module: "agent", + provider: options.provider, + }); this.runtimeSettings = options.runtimeSettings; this.defaultCommand = options.defaultCommand; this.defaultModes = options.defaultModes ?? []; @@ -557,6 +562,7 @@ export class ACPAgentClient implements AgentClient { beforeModeWriter: this.beforeModeWriter, thinkingOptionWriter: this.thinkingOptionWriter, capabilities: this.capabilities, + agentId: launchContext?.agentId, launchEnv: launchContext?.env, waitForInitialCommands: this.waitForInitialCommands, initialCommandsWaitTimeoutMs: this.initialCommandsWaitTimeoutMs, @@ -603,6 +609,7 @@ export class ACPAgentClient implements AgentClient { thinkingOptionWriter: this.thinkingOptionWriter, capabilities: this.capabilities, handle, + agentId: launchContext?.agentId, launchEnv: launchContext?.env, waitForInitialCommands: this.waitForInitialCommands, initialCommandsWaitTimeoutMs: this.initialCommandsWaitTimeoutMs, @@ -842,6 +849,7 @@ export class ACPAgentSession implements AgentSession, ACPClient { sessionId: string, thinkingOptionId: string, ) => Promise; + private readonly agentId?: string; private readonly launchEnv?: Record; private readonly subscribers = new Set<(event: AgentStreamEvent) => void>(); private readonly pendingPermissions = new Map(); @@ -894,6 +902,7 @@ export class ACPAgentSession implements AgentSession, ACPClient { this.beforeModeWriter = options.beforeModeWriter; this.thinkingOptionWriter = options.thinkingOptionWriter; this.availableModes = options.defaultModes; + this.agentId = options.agentId; this.launchEnv = options.launchEnv; this.initialHandle = options.handle; this.config = { ...config, provider: options.provider }; @@ -1567,11 +1576,31 @@ export class ACPAgentSession implements AgentSession, ACPClient { } async sessionUpdate(params: SessionNotification): Promise { + this.logger.trace( + { + agentId: this.agentId, + provider: this.provider, + sessionId: params.sessionId, + rawEvent: params, + }, + "provider.acp.raw_event", + ); if (params.sessionId !== this.sessionId) { return; } const events = this.translateSessionUpdate(params.update); + this.logger.trace( + { + agentId: this.agentId, + provider: this.provider, + sessionId: this.sessionId, + turnId: this.activeForegroundTurnId ?? undefined, + rawEvent: params, + events, + }, + "provider.acp.parsed_event", + ); if (this.replayingHistory) { for (const event of events) { if (event.type === "timeline") { @@ -2002,6 +2031,16 @@ export class ACPAgentSession implements AgentSession, ACPClient { } private pushEvent(event: AgentStreamEvent): void { + this.logger.trace( + { + agentId: this.agentId, + provider: this.provider, + sessionId: this.sessionId, + turnId: getAgentStreamEventTurnId(event) ?? this.activeForegroundTurnId ?? undefined, + event, + }, + "provider.acp.event_emit", + ); for (const subscriber of this.subscribers) { subscriber(event); } diff --git a/packages/server/src/server/agent/providers/claude/agent.event-stream.integration.test.ts b/packages/server/src/server/agent/providers/claude/agent.event-stream.integration.test.ts index 8ad45fed4..e03dc2757 100644 --- a/packages/server/src/server/agent/providers/claude/agent.event-stream.integration.test.ts +++ b/packages/server/src/server/agent/providers/claude/agent.event-stream.integration.test.ts @@ -14,7 +14,11 @@ import { tmpdir } from "node:os"; import path from "node:path"; import pino from "pino"; -import type { AgentSession, AgentStreamEvent } from "../../agent-sdk-types.js"; +import { + getAgentStreamEventTurnId, + type AgentSession, + type AgentStreamEvent, +} from "../../agent-sdk-types.js"; import { isProviderAvailable } from "../../../daemon-e2e/agent-configs.js"; import { ClaudeAgentClient } from "./agent.js"; @@ -37,15 +41,14 @@ function isTerminalEvent(event: AgentStreamEvent): boolean { ); } -// turnId is optional on AgentStreamEvent — this narrows to events where it's present. type EventWithTurnId = AgentStreamEvent & { turnId: string }; function hasTurnId(event: AgentStreamEvent): event is EventWithTurnId { - return "turnId" in event && typeof (event as Record).turnId === "string"; + return getAgentStreamEventTurnId(event) !== undefined; } function eventsForTurn(events: AgentStreamEvent[], turnId: string): AgentStreamEvent[] { - return events.filter((e) => hasTurnId(e) && e.turnId === turnId); + return events.filter((e) => getAgentStreamEventTurnId(e) === turnId); } function userMessagesWithText(events: AgentStreamEvent[], text: string): AgentStreamEvent[] { @@ -157,7 +160,7 @@ function assertInvariants(events: AgentStreamEvent[], foregroundTurnIds: string[ // Invariant 2: Every turn_started has exactly one matching terminal const turnStartedIds = events .filter((e) => e.type === "turn_started" && hasTurnId(e)) - .map((e) => (e as EventWithTurnId).turnId); + .map((e) => e.turnId); for (const turnId of turnStartedIds) { const terminals = eventsForTurn(events, turnId).filter(isTerminalEvent); @@ -277,7 +280,7 @@ test("Test 3: Lifecycle doesn't get stuck in running", async () => { // Any turn_started after terminal must have a different turnId for (const ts of afterTerminal.filter((e) => e.type === "turn_started" && hasTurnId(e))) { - expect((ts as EventWithTurnId).turnId).not.toBe(turnId); + expect(ts.turnId).not.toBe(turnId); } assertInvariants(events, [turnId]); @@ -313,8 +316,9 @@ test("Test 4: Autonomous run", async () => { // Autonomous turn_started with a different turnId const autoStarts = afterForeground.filter( - (e) => e.type === "turn_started" && hasTurnId(e) && e.turnId !== fgTurnId, - ) as EventWithTurnId[]; + (e): e is EventWithTurnId => + e.type === "turn_started" && hasTurnId(e) && e.turnId !== fgTurnId, + ); if (autoStarts.length === 0) { assertInvariants(events, [fgTurnId]); return; diff --git a/packages/server/src/server/agent/providers/claude/agent.ts b/packages/server/src/server/agent/providers/claude/agent.ts index e759a3e3b..04b999f52 100644 --- a/packages/server/src/server/agent/providers/claude/agent.ts +++ b/packages/server/src/server/agent/providers/claude/agent.ts @@ -42,34 +42,35 @@ import { appendOrReplaceGrowingAssistantMessage, runProviderTurn } from "../prov import { renderPromptAttachmentAsText } from "../../prompt-attachments.js"; import { claudeQuery, type ClaudeOptions, type ClaudeQueryFactory } from "./query.js"; -import type { - AgentPermissionAction, - AgentCapabilityFlags, - AgentClient, - AgentCreateSessionOptions, - AgentLaunchContext, - AgentMetadata, - AgentMode, - AgentModelDefinition, - AgentPermissionRequest, - AgentPermissionRequestKind, - AgentPermissionResponse, - AgentPermissionUpdate, - AgentPersistenceHandle, - AgentPromptInput, - AgentRunOptions, - AgentRunResult, - AgentSession, - AgentSessionConfig, - AgentSlashCommand, - AgentStreamEvent, - AgentTimelineItem, - AgentUsage, - AgentRuntimeInfo, - ListModelsOptions, - ListPersistedAgentsOptions, - McpServerConfig, - PersistedAgentDescriptor, +import { + getAgentStreamEventTurnId, + type AgentPermissionAction, + type AgentCapabilityFlags, + type AgentClient, + type AgentCreateSessionOptions, + type AgentLaunchContext, + type AgentMetadata, + type AgentMode, + type AgentModelDefinition, + type AgentPermissionRequest, + type AgentPermissionRequestKind, + type AgentPermissionResponse, + type AgentPermissionUpdate, + type AgentPersistenceHandle, + type AgentPromptInput, + type AgentRunOptions, + type AgentRunResult, + type AgentSession, + type AgentSessionConfig, + type AgentSlashCommand, + type AgentStreamEvent, + type AgentTimelineItem, + type AgentUsage, + type AgentRuntimeInfo, + type ListModelsOptions, + type ListPersistedAgentsOptions, + type McpServerConfig, + type PersistedAgentDescriptor, } from "../../agent-sdk-types.js"; import { createProviderEnv, @@ -250,6 +251,7 @@ interface ClaudeAgentSessionOptions { defaults?: { agents?: Record }; runtimeSettings?: ProviderRuntimeSettings; handle?: AgentPersistenceHandle; + agentId?: string; launchEnv?: Record; persistSession?: boolean; logger: Logger; @@ -1152,8 +1154,6 @@ export function readEventIdentifiers(message: SDKMessage): EventIdentifiers { }; } -const claudeDebug = process.env.PASEO_CLAUDE_DEBUG === "1"; - export class ClaudeAgentClient implements AgentClient { readonly provider = "claude" as const; readonly capabilities = CLAUDE_CAPABILITIES; @@ -1181,6 +1181,7 @@ export class ClaudeAgentClient implements AgentClient { return new ClaudeAgentSession(claudeConfig, { defaults: this.defaults, runtimeSettings: this.runtimeSettings, + agentId: launchContext?.agentId, launchEnv: launchContext?.env, persistSession: options?.persistSession, logger: this.logger, @@ -1209,6 +1210,7 @@ export class ClaudeAgentClient implements AgentClient { defaults: this.defaults, runtimeSettings: this.runtimeSettings, handle, + agentId: launchContext?.agentId, launchEnv: launchContext?.env, logger: this.logger, queryFactory: this.queryFactory, @@ -1477,6 +1479,7 @@ class ClaudeAgentSession implements AgentSession { private readonly config: ClaudeAgentConfig; private readonly launchEnv?: Record; + private readonly agentId?: string; private readonly defaults?: { agents?: Record }; private readonly runtimeSettings?: ProviderRuntimeSettings; private readonly persistSession?: boolean; @@ -1526,10 +1529,11 @@ class ClaudeAgentSession implements AgentSession { constructor(config: ClaudeAgentConfig, options: ClaudeAgentSessionOptions) { this.config = config; this.launchEnv = options.launchEnv; + this.agentId = options.agentId; this.defaults = options.defaults; this.runtimeSettings = options.runtimeSettings; this.persistSession = options.persistSession; - this.logger = options.logger; + this.logger = options.logger.child({ agentId: this.agentId }); this.queryFactory = options.queryFactory; this.resolveBinary = options.resolveBinary; const handle = options.handle; @@ -1869,13 +1873,16 @@ class ClaudeAgentSession implements AgentSession { async close(): Promise { this.logger.trace( { - claudeSessionId: this.claudeSessionId, + agentId: this.agentId, + provider: "claude", + sessionId: this.claudeSessionId, + turnId: this.activeForegroundTurnId ?? this.autonomousTurn?.id ?? undefined, turnState: this.turnState, hasQuery: Boolean(this.query), hasInput: Boolean(this.input), hasActiveForegroundTurnId: Boolean(this.activeForegroundTurnId), }, - "Claude session close: start", + "provider.claude.session_close.start", ); this.closed = true; this.rejectAllPendingPermissions(new Error("Claude session closed")); @@ -1910,8 +1917,13 @@ class ClaudeAgentSession implements AgentSession { } } this.logger.trace( - { claudeSessionId: this.claudeSessionId, turnState: this.turnState }, - "Claude session close: completed", + { + agentId: this.agentId, + provider: "claude", + sessionId: this.claudeSessionId, + turnState: this.turnState, + }, + "provider.claude.session_close.complete", ); } @@ -2188,16 +2200,41 @@ class ClaudeAgentSession implements AgentSession { label: string, ): Promise { if (!promise) { - this.logger.trace({ label }, "Claude query operation skipped (no promise)"); + this.logger.trace( + { + agentId: this.agentId, + provider: "claude", + sessionId: this.claudeSessionId, + turnId: this.activeForegroundTurnId ?? this.autonomousTurn?.id ?? undefined, + label, + }, + "provider.claude.query_operation.skip", + ); return; } const startedAt = Date.now(); - this.logger.trace({ label }, "Claude query operation wait start"); + this.logger.trace( + { + agentId: this.agentId, + provider: "claude", + sessionId: this.claudeSessionId, + turnId: this.activeForegroundTurnId ?? this.autonomousTurn?.id ?? undefined, + label, + }, + "provider.claude.query_operation.start", + ); try { await withTimeout(promise, 3_000, "timeout"); this.logger.trace( - { label, durationMs: Date.now() - startedAt }, - "Claude query operation settled", + { + agentId: this.agentId, + provider: "claude", + sessionId: this.claudeSessionId, + turnId: this.activeForegroundTurnId ?? this.autonomousTurn?.id ?? undefined, + label, + durationMs: Date.now() - startedAt, + }, + "provider.claude.query_operation.settled", ); } catch (error) { this.logger.warn({ err: error, label }, "Claude query operation did not settle cleanly"); @@ -2593,7 +2630,16 @@ class ClaudeAgentSession implements AgentSession { } const pump = this.runQueryPump().catch((error) => { - this.logger.trace({ err: error }, "Claude query pump exited unexpectedly"); + this.logger.trace( + { + agentId: this.agentId, + provider: "claude", + sessionId: this.claudeSessionId, + turnId: this.activeForegroundTurnId ?? this.autonomousTurn?.id ?? undefined, + err: error, + }, + "provider.claude.query_pump.exit_unexpected", + ); }); this.queryPumpPromise = pump; @@ -2609,24 +2655,34 @@ class ClaudeAgentSession implements AgentSession { try { activeQuery = await this.ensureQuery(); } catch (error) { - this.logger.trace({ err: error }, "Failed to initialize Claude query pump"); + this.logger.trace( + { + agentId: this.agentId, + provider: "claude", + sessionId: this.claudeSessionId, + turnId: this.activeForegroundTurnId ?? this.autonomousTurn?.id ?? undefined, + err: error, + }, + "provider.claude.query_pump.init_failed", + ); this.failActiveTurns(error instanceof Error ? error.message : "Claude stream failed"); return; } let consecutiveInterruptAbortRecoveries = 0; const logRawMessage = (message: SDKMessage): void => { - if (!claudeDebug) { - return; - } this.logger.trace( { - claudeSessionId: this.claudeSessionId, + agentId: this.agentId, + provider: "claude", + sessionId: this.claudeSessionId, + turnId: this.activeForegroundTurnId ?? this.autonomousTurn?.id ?? undefined, messageType: message.type, messageSubtype: "subtype" in message ? message.subtype : undefined, messageUuid: "uuid" in message ? message.uuid : undefined, + rawEvent: message, }, - "Claude query pump: raw SDK message", + "provider.claude.raw_event", ); }; const handlePumpedMessage = async (message: SDKMessage): Promise => { @@ -2739,16 +2795,18 @@ class ClaudeAgentSession implements AgentSession { const turnId = this.activeForegroundTurnId ?? this.autonomousTurn?.id ?? null; const identifiers = readEventIdentifiers(message); - if (claudeDebug) { - this.logger.trace( - { - claudeSessionId: this.claudeSessionId, - messageType: message.type, - turnId, - }, - "Claude query pump: SDK message", - ); - } + this.logger.trace( + { + agentId: this.agentId, + provider: "claude", + sessionId: this.claudeSessionId, + turnId: turnId ?? undefined, + messageType: message.type, + identifiers, + rawEvent: message, + }, + "provider.claude.parsed_event", + ); const messageEvents = this.translateMessageToEvents(message, { suppressAssistantText: true, @@ -2816,7 +2874,6 @@ class ClaudeAgentSession implements AgentSession { this.logger.warn( { - claudeSessionId: this.claudeSessionId, error: staleResumeError, }, "Claude resumed session no longer exists; invalidating persisted session", @@ -2846,7 +2903,15 @@ class ClaudeAgentSession implements AgentSession { private async interruptActiveTurn(): Promise { const queryToInterrupt = this.query; if (!queryToInterrupt || typeof queryToInterrupt.interrupt !== "function") { - this.logger.trace("interruptActiveTurn: no query to interrupt"); + this.logger.trace( + { + agentId: this.agentId, + provider: "claude", + sessionId: this.claudeSessionId, + turnId: this.activeForegroundTurnId ?? this.autonomousTurn?.id ?? undefined, + }, + "provider.claude.interrupt.no_query", + ); return; } this.pendingInterruptAbort = true; @@ -3455,6 +3520,16 @@ class ClaudeAgentSession implements AgentSession { private notifySubscribers(event: AgentStreamEvent): void { const turnId = this.activeForegroundTurnId ?? this.autonomousTurn?.id; const tagged = turnId ? { ...event, turnId } : event; + this.logger.trace( + { + agentId: this.agentId, + provider: "claude", + sessionId: this.claudeSessionId, + turnId: getAgentStreamEventTurnId(tagged), + event: tagged, + }, + "provider.claude.event_emit", + ); for (const callback of this.subscribers) { try { callback(tagged); diff --git a/packages/server/src/server/agent/providers/codex-app-server-agent.ts b/packages/server/src/server/agent/providers/codex-app-server-agent.ts index 9154898e1..501f84e40 100644 --- a/packages/server/src/server/agent/providers/codex-app-server-agent.ts +++ b/packages/server/src/server/agent/providers/codex-app-server-agent.ts @@ -1,32 +1,33 @@ -import type { - AgentPermissionAction, - AgentCapabilityFlags, - AgentClient, - AgentCreateSessionOptions, - AgentFeature, - AgentLaunchContext, - AgentMode, - AgentModelDefinition, - McpServerConfig, - AgentPersistenceHandle, - AgentPermissionRequest, - AgentPermissionResponse, - AgentPermissionResult, - AgentPromptContentBlock, - AgentPromptInput, - AgentRunOptions, - AgentRunResult, - AgentRuntimeInfo, - AgentSession, - AgentSessionConfig, - AgentSlashCommand, - AgentStreamEvent, - AgentTimelineItem, - ToolCallTimelineItem, - AgentUsage, - ListModelsOptions, - ListPersistedAgentsOptions, - PersistedAgentDescriptor, +import { + getAgentStreamEventTurnId, + type AgentPermissionAction, + type AgentCapabilityFlags, + type AgentClient, + type AgentCreateSessionOptions, + type AgentFeature, + type AgentLaunchContext, + type AgentMode, + type AgentModelDefinition, + type McpServerConfig, + type AgentPersistenceHandle, + type AgentPermissionRequest, + type AgentPermissionResponse, + type AgentPermissionResult, + type AgentPromptContentBlock, + type AgentPromptInput, + type AgentRunOptions, + type AgentRunResult, + type AgentRuntimeInfo, + type AgentSession, + type AgentSessionConfig, + type AgentSlashCommand, + type AgentStreamEvent, + type AgentTimelineItem, + type ToolCallTimelineItem, + type AgentUsage, + type ListModelsOptions, + type ListPersistedAgentsOptions, + type PersistedAgentDescriptor, } from "../agent-sdk-types.js"; import type { Logger } from "pino"; import { homedir } from "node:os"; @@ -55,7 +56,10 @@ import { findExecutable, isCommandAvailable } from "../../../utils/executable.js import { spawnProcess } from "../../../utils/spawn.js"; import { extractCodexTerminalSessionId, nonEmptyString } from "./tool-call-mapper-utils.js"; import { buildCodexFeatures, codexModelSupportsFastMode } from "./codex-feature-definitions.js"; -import { CodexAppServerClient } from "./codex/app-server-transport.js"; +import { + CodexAppServerClient, + type CodexAppServerTraceContext, +} from "./codex/app-server-transport.js"; import { renderProviderImageOutputAsAssistantMarkdown, type ProviderImageOutput, @@ -183,6 +187,7 @@ interface CodexAppServerAgentDeps { _createCodexClient?: ( child: ChildProcessWithoutNullStreams, logger: Logger, + getTraceContext: () => CodexAppServerTraceContext, ) => CodexAppServerClientLike; } @@ -2653,8 +2658,13 @@ class CodexAppServerAgentSession implements AgentSession { private readonly deps: CodexAppServerAgentDeps = {}, private readonly ephemeral: boolean = false, private readonly goalsEnabled: boolean = false, + private readonly agentId?: string, ) { - this.logger = logger.child({ module: "agent", provider: CODEX_PROVIDER }); + this.logger = logger.child({ + module: "agent", + provider: CODEX_PROVIDER, + agentId: this.agentId, + }); if (config.modeId === undefined) { throw new Error("Codex agent requires modeId to be specified"); } @@ -2691,7 +2701,7 @@ class CodexAppServerAgentSession implements AgentSession { async connect(): Promise { if (this.connected) return; const child = await this.spawnAppServer(); - this.client = new CodexAppServerClient(child, this.logger); + this.client = new CodexAppServerClient(child, this.logger, () => this.traceContext()); this.client.setNotificationHandler((method, params) => this.handleNotification(method, params)); this.registerRequestHandlers(); @@ -2709,6 +2719,14 @@ class CodexAppServerAgentSession implements AgentSession { this.connected = true; } + private traceContext(): CodexAppServerTraceContext { + return { + agentId: this.agentId, + sessionId: this.currentThreadId ?? undefined, + turnId: this.activeForegroundTurnId ?? undefined, + }; + } + private async loadCollaborationModes(): Promise { if (!this.client) return; try { @@ -2729,7 +2747,16 @@ class CodexAppServerAgentSession implements AgentSession { }; }); } catch (error) { - this.logger.trace({ error }, "Failed to load collaboration modes"); + this.logger.trace( + { + agentId: this.agentId, + provider: CODEX_PROVIDER, + sessionId: this.currentThreadId, + turnId: this.activeForegroundTurnId ?? undefined, + error, + }, + "provider.codex.metadata.collaboration_modes_failed", + ); this.collaborationModes = []; } this.refreshResolvedCollaborationMode(); @@ -2761,7 +2788,16 @@ class CodexAppServerAgentSession implements AgentSession { } this.cachedSkills = skills; } catch (error) { - this.logger.trace({ error }, "Failed to load skills list"); + this.logger.trace( + { + agentId: this.agentId, + provider: CODEX_PROVIDER, + sessionId: this.currentThreadId, + turnId: this.activeForegroundTurnId ?? undefined, + error, + }, + "provider.codex.metadata.skills_failed", + ); this.cachedSkills = []; } } @@ -3657,6 +3693,16 @@ class CodexAppServerAgentSession implements AgentSession { private notifySubscribers(event: AgentStreamEvent): void { const turnId = this.activeForegroundTurnId; const tagged = turnId ? { ...event, turnId } : event; + this.logger.trace( + { + agentId: this.agentId, + provider: CODEX_PROVIDER, + sessionId: this.currentThreadId, + turnId: getAgentStreamEventTurnId(tagged), + event: tagged, + }, + "provider.codex.event_emit", + ); for (const callback of this.subscribers) { try { callback(tagged); @@ -3672,6 +3718,7 @@ class CodexAppServerAgentSession implements AgentSession { private handleNotification(method: string, params: unknown): void { const parsed = CodexNotificationSchema.parse({ method, params }); + this.traceParsedNotification(method, params, parsed); switch (parsed.kind) { case "thread_started": this.handleThreadStartedNotification(parsed); @@ -3728,6 +3775,25 @@ class CodexAppServerAgentSession implements AgentSession { } } + private traceParsedNotification( + method: string, + params: unknown, + parsed: z.infer, + ): void { + this.logger.trace( + { + agentId: this.agentId, + provider: CODEX_PROVIDER, + sessionId: this.currentThreadId, + turnId: this.activeForegroundTurnId ?? undefined, + method, + params, + parsed, + }, + "provider.codex.parsed_event", + ); + } + private getSubAgentCallIdForThread(threadId: string | null | undefined): string | null { if (!threadId || threadId === this.currentThreadId) { return null; @@ -4320,7 +4386,17 @@ class CodexAppServerAgentSession implements AgentSession { return; } this.warnedUnknownNotificationMethods.add(method); - this.logger.trace({ method, params }, "Unhandled Codex app-server notification method"); + this.logger.trace( + { + agentId: this.agentId, + provider: CODEX_PROVIDER, + sessionId: this.currentThreadId, + turnId: this.activeForegroundTurnId ?? undefined, + method, + params, + }, + "provider.codex.event_unhandled", + ); } private warnInvalidNotificationPayload(method: string, params: unknown): void { @@ -4598,7 +4674,14 @@ export class CodexAppServerAgentClient implements AgentClient { const launchPrefix = await resolveCodexLaunchPrefix(this.runtimeSettings); const versionOutput = await resolveBinaryVersion(launchPrefix.command); const enabled = codexVersionAtLeast(versionOutput, CODEX_GOALS_MIN_VERSION); - this.logger.trace({ versionOutput, enabled }, "Resolved codex goals feature gate"); + this.logger.trace( + { + provider: CODEX_PROVIDER, + versionOutput, + enabled, + }, + "provider.codex.config.goals_resolved", + ); return enabled; } catch (error) { this.logger.warn({ err: error }, "Failed to probe codex version for goals gate"); @@ -4611,7 +4694,7 @@ export class CodexAppServerAgentClient implements AgentClient { private async spawnAppServer( launchEnv?: Record, - options?: { goalsEnabled?: boolean }, + options?: { goalsEnabled?: boolean; agentId?: string }, ): Promise { const launchPrefix = await resolveCodexLaunchPrefix(this.runtimeSettings); const args = [...launchPrefix.args, "app-server"]; @@ -4620,10 +4703,12 @@ export class CodexAppServerAgentClient implements AgentClient { } this.logger.trace( { + agentId: options?.agentId, + provider: CODEX_PROVIDER, launchPrefix, goalsEnabled: options?.goalsEnabled === true, }, - "Spawning Codex app server", + "provider.codex.spawn", ); const child = spawnProcess(launchPrefix.command, args, { detached: process.platform !== "win32", @@ -4655,10 +4740,12 @@ export class CodexAppServerAgentClient implements AgentClient { sessionConfig, null, this.logger, - () => this.spawnAppServer(launchContext?.env, { goalsEnabled }), + () => + this.spawnAppServer(launchContext?.env, { goalsEnabled, agentId: launchContext?.agentId }), this.sessionDeps(), options?.persistSession === false, goalsEnabled, + launchContext?.agentId, ); await session.connect(); return session; @@ -4681,10 +4768,12 @@ export class CodexAppServerAgentClient implements AgentClient { merged, handle, this.logger, - () => this.spawnAppServer(launchContext?.env, { goalsEnabled }), + () => + this.spawnAppServer(launchContext?.env, { goalsEnabled, agentId: launchContext?.agentId }), this.sessionDeps(), false, goalsEnabled, + launchContext?.agentId, ); await session.connect(); return session; @@ -4695,7 +4784,7 @@ export class CodexAppServerAgentClient implements AgentClient { ): Promise { const child = await this.spawnAppServer(); const client = - this.deps._createCodexClient?.(child, this.logger) ?? + this.deps._createCodexClient?.(child, this.logger, () => ({})) ?? new CodexAppServerClient(child, this.logger); try { diff --git a/packages/server/src/server/agent/providers/codex/app-server-transport.ts b/packages/server/src/server/agent/providers/codex/app-server-transport.ts index 27ead31bd..d6d89fd28 100644 --- a/packages/server/src/server/agent/providers/codex/app-server-transport.ts +++ b/packages/server/src/server/agent/providers/codex/app-server-transport.ts @@ -35,6 +35,12 @@ interface PendingRequest { type RequestHandler = (params: unknown) => unknown; type NotificationHandler = (method: string, params: unknown) => void; +export interface CodexAppServerTraceContext { + agentId?: string; + sessionId?: string; + turnId?: string; +} + function isRecord(value: unknown): value is Record { return value != null && typeof value === "object" && !Array.isArray(value); } @@ -54,6 +60,24 @@ function isJsonRpcNotification(msg: unknown): msg is JsonRpcNotification { return typeof msg.method === "string" && msg.id === undefined; } +function readProviderSessionId(params: unknown): string | undefined { + if (!isRecord(params)) { + return undefined; + } + return typeof params.threadId === "string" ? params.threadId : undefined; +} + +function readProviderTurnId(params: unknown): string | undefined { + if (!isRecord(params)) { + return undefined; + } + if (typeof params.turnId === "string") { + return params.turnId; + } + const turn = params.turn; + return isRecord(turn) && typeof turn.id === "string" ? turn.id : undefined; +} + export class CodexAppServerClient { private readonly rl: readline.Interface; private readonly pending = new Map(); @@ -66,6 +90,7 @@ export class CodexAppServerClient { constructor( private readonly child: ChildProcessWithoutNullStreams, private readonly logger: Logger, + private readonly getTraceContext: () => CodexAppServerTraceContext = () => ({}), ) { this.rl = readline.createInterface({ input: child.stdout }); this.rl.on("line", (line) => { @@ -224,6 +249,19 @@ export class CodexAppServerClient { } if (isJsonRpcNotification(raw)) { + const traceContext = this.getTraceContext(); + this.logger.trace( + { + provider: "codex", + agentId: traceContext.agentId, + sessionId: traceContext.sessionId ?? readProviderSessionId(raw.params), + turnId: traceContext.turnId ?? readProviderTurnId(raw.params), + method: raw.method, + params: raw.params, + rawEvent: raw, + }, + "provider.codex.raw_event", + ); this.notificationHandler?.(raw.method, raw.params); } } diff --git a/packages/server/src/server/agent/providers/opencode-agent.ts b/packages/server/src/server/agent/providers/opencode-agent.ts index 83d27c3af..c1d3ae502 100644 --- a/packages/server/src/server/agent/providers/opencode-agent.ts +++ b/packages/server/src/server/agent/providers/opencode-agent.ts @@ -13,33 +13,34 @@ import { findExecutable, isCommandAvailable } from "../../../utils/executable.js import type { Logger } from "pino"; import { z } from "zod"; -import type { - AgentCapabilityFlags, - AgentClient, - AgentCreateSessionOptions, - AgentLaunchContext, - AgentMode, - AgentModelDefinition, - AgentPermissionRequest, - AgentPermissionResponse, - AgentPersistenceHandle, - AgentPromptInput, - AgentRunOptions, - AgentRunResult, - AgentRuntimeInfo, - AgentSession, - AgentSessionConfig, - AgentSlashCommand, - AgentStreamEvent, - AgentTimelineItem, - AgentUsage, - ListModelsOptions, - ListModesOptions, - ListPersistedAgentsOptions, - McpServerConfig, - PersistedAgentDescriptor, - ToolCallDetail, - ToolCallTimelineItem, +import { + getAgentStreamEventTurnId, + type AgentCapabilityFlags, + type AgentClient, + type AgentCreateSessionOptions, + type AgentLaunchContext, + type AgentMode, + type AgentModelDefinition, + type AgentPermissionRequest, + type AgentPermissionResponse, + type AgentPersistenceHandle, + type AgentPromptInput, + type AgentRunOptions, + type AgentRunResult, + type AgentRuntimeInfo, + type AgentSession, + type AgentSessionConfig, + type AgentSlashCommand, + type AgentStreamEvent, + type AgentTimelineItem, + type AgentUsage, + type ListModelsOptions, + type ListModesOptions, + type ListPersistedAgentsOptions, + type McpServerConfig, + type PersistedAgentDescriptor, + type ToolCallDetail, + type ToolCallTimelineItem, } from "../agent-sdk-types.js"; import { createProviderEnvSpec, type ProviderRuntimeSettings } from "../provider-launch-config.js"; import { withTimeout } from "../../../utils/promise-timeout.js"; @@ -966,7 +967,7 @@ export class OpenCodeAgentClient implements AgentClient { async createSession( config: AgentSessionConfig, - _launchContext?: AgentLaunchContext, + launchContext?: AgentLaunchContext, options?: AgentCreateSessionOptions, ): Promise { const openCodeConfig = this.assertConfig(config); @@ -1004,6 +1005,7 @@ export class OpenCodeAgentClient implements AgentClient { new Map(this.modelContextWindows), acquisition.release, options?.persistSession, + launchContext?.agentId, ); } catch (error) { acquisition.release(); @@ -1014,7 +1016,7 @@ export class OpenCodeAgentClient implements AgentClient { async resumeSession( handle: AgentPersistenceHandle, overrides?: Partial, - _launchContext?: AgentLaunchContext, + launchContext?: AgentLaunchContext, ): Promise { const cwd = overrides?.cwd ?? (handle.metadata?.cwd as string); if (!cwd) { @@ -1046,6 +1048,7 @@ export class OpenCodeAgentClient implements AgentClient { new Map(this.modelContextWindows), acquisition.release, undefined, + launchContext?.agentId, ); } catch (error) { acquisition.release(); @@ -1277,6 +1280,28 @@ export interface OpenCodeEventTranslationState { onAssistantModelContextWindowResolved?: (contextWindowMaxTokens: number) => void; } +interface OpenCodeTraceData { + turnId?: string; + [key: string]: unknown; +} + +type OpenCodeTraceMessage = + | "provider.opencode.prompt_async.start" + | "provider.opencode.prompt_async.response" + | "provider.opencode.prompt_async.throw" + | "provider.opencode.subscribe.start" + | "provider.opencode.subscribe.ready" + | "provider.opencode.stream.eof" + | "provider.opencode.turn.fail_eof" + | "provider.opencode.subscribe.error" + | "provider.opencode.raw_event" + | "provider.opencode.event.skip" + | "provider.opencode.parsed_event" + | "provider.opencode.parsed_event.skip_active" + | "provider.opencode.event.terminal" + | "provider.opencode.finish_foreground_turn" + | "provider.opencode.event_emit"; + type OpenCodeToolPartEventPart = Extract< Extract["properties"]["part"], { type: "tool" } @@ -2141,18 +2166,6 @@ function createDeferred(): Deferred { return { promise, resolve, reject }; } -const OPENCODE_TRACE_ENABLED = process.env.PASEO_OPENCODE_TRACE === "1"; - -function traceOpenCode(tag: string, data: Record = {}): void { - if (!OPENCODE_TRACE_ENABLED) return; - const line = JSON.stringify({ ts: new Date().toISOString(), tag, ...data }, (_k, v) => { - if (v instanceof Error) return { name: v.name, message: v.message, stack: v.stack }; - if (typeof v === "bigint") return v.toString(); - return v; - }); - process.stderr.write(`[opencode-trace] ${line}\n`); -} - function unwrapOpenCodeGlobalEvent(event: unknown): OpenCodeEvent | null { const record = readOpenCodeRecord(event); if (!record) { @@ -2217,11 +2230,12 @@ class OpenCodeAgentSession implements AgentSession { modelContextWindowsByModelKey: ReadonlyMap = new Map(), releaseServer?: () => void, persistSession = true, + private readonly agentId?: string, ) { this.config = config; this.client = client; this.sessionId = sessionId; - this.logger = logger; + this.logger = logger.child({ agentId: this.agentId }); this.modelContextWindowsByModelKey = modelContextWindowsByModelKey; this.currentMode = normalizeOpenCodeModeId(config.modeId); this.releaseServer = releaseServer ?? null; @@ -2483,7 +2497,7 @@ class OpenCodeAgentSession implements AgentSession { // SDK input validation) is caught alongside async rejections. A plain // `.then().catch()` chain would let a sync throw escape unhandled. void (async () => { - traceOpenCode("promptAsync.start", { + this.traceOpenCode("provider.opencode.prompt_async.start", { turnId, sessionId: this.sessionId, model, @@ -2509,7 +2523,7 @@ class OpenCodeAgentSession implements AgentSession { ...(effectiveMode ? { agent: effectiveMode } : {}), ...(effectiveVariant ? { variant: effectiveVariant } : {}), }); - traceOpenCode("promptAsync.response", { + this.traceOpenCode("provider.opencode.prompt_async.response", { turnId, hasError: promptResponse.error !== undefined, error: promptResponse.error, @@ -2526,7 +2540,7 @@ class OpenCodeAgentSession implements AgentSession { ); } } catch (error) { - traceOpenCode("promptAsync.throw", { + this.traceOpenCode("provider.opencode.prompt_async.throw", { turnId, error: error instanceof Error @@ -2560,7 +2574,11 @@ class OpenCodeAgentSession implements AgentSession { turnAbortController: AbortController, subscriptionReady: Deferred, ): Promise { - traceOpenCode("subscribe.start", { turnId, sessionId: this.sessionId, cwd: this.config.cwd }); + this.traceOpenCode("provider.opencode.subscribe.start", { + turnId, + sessionId: this.sessionId, + cwd: this.config.cwd, + }); try { const result = await this.client.global.event({ signal: turnAbortController.signal, @@ -2572,7 +2590,10 @@ class OpenCodeAgentSession implements AgentSession { eventCount += 1; if (!subscriptionReadyResolved) { subscriptionReadyResolved = true; - traceOpenCode("subscribe.ready", { turnId, sessionId: this.sessionId }); + this.traceOpenCode("provider.opencode.subscribe.ready", { + turnId, + sessionId: this.sessionId, + }); subscriptionReady.resolve(); } const shouldContinue = await this.consumeOpenCodeStreamEvent({ @@ -2586,7 +2607,7 @@ class OpenCodeAgentSession implements AgentSession { } } - traceOpenCode("stream.eof", { + this.traceOpenCode("provider.opencode.stream.eof", { turnId, eventCount, aborted: turnAbortController.signal.aborted, @@ -2594,7 +2615,7 @@ class OpenCodeAgentSession implements AgentSession { }); if (!turnAbortController.signal.aborted && this.activeForegroundTurnId === turnId) { - traceOpenCode("turn.fail.eof", { turnId, eventCount }); + this.traceOpenCode("provider.opencode.turn.fail_eof", { turnId, eventCount }); if (!subscriptionReadyResolved) { subscriptionReady.reject(new Error("OpenCode event stream ended before it became ready")); } @@ -2608,7 +2629,7 @@ class OpenCodeAgentSession implements AgentSession { ); } } catch (error) { - traceOpenCode("subscribe.error", { + this.traceOpenCode("provider.opencode.subscribe.error", { turnId, error: error instanceof Error ? { name: error.name, message: error.message } : String(error), @@ -2649,19 +2670,20 @@ class OpenCodeAgentSession implements AgentSession { }): Promise { const { rawEvent, eventCount, turnId, turnAbortController } = params; const event = unwrapOpenCodeGlobalEvent(rawEvent); - traceOpenCode("event.raw", { + this.traceOpenCode("provider.opencode.raw_event", { turnId, n: eventCount, type: event?.type, rawType: readOpenCodeRecord(rawEvent)?.type, directory: readOpenCodeRecord(rawEvent)?.directory, - properties: event ? (event as { properties?: unknown }).properties : undefined, + rawEvent, + properties: event?.properties, }); if (!event) { return true; } if (turnAbortController.signal.aborted || this.activeForegroundTurnId !== turnId) { - traceOpenCode("event.skip", { + this.traceOpenCode("provider.opencode.event.skip", { turnId, n: eventCount, aborted: turnAbortController.signal.aborted, @@ -2672,16 +2694,17 @@ class OpenCodeAgentSession implements AgentSession { this.armRetryFailureTimerForStatus(event, turnId); const translated = await this.translateEvent(event); - traceOpenCode("event.translated", { + this.traceOpenCode("provider.opencode.parsed_event", { turnId, n: eventCount, count: translated.length, types: translated.map((t) => t.type), + events: translated, }); for (const e of translated) { if (this.activeForegroundTurnId !== turnId) { - traceOpenCode("event.translated.skip-active", { turnId, type: e.type }); + this.traceOpenCode("provider.opencode.parsed_event.skip_active", { turnId, type: e.type }); return false; } if (e.type === "timeline" && e.item.type === "tool_call") { @@ -2689,7 +2712,10 @@ class OpenCodeAgentSession implements AgentSession { } const terminalEvent = toTerminalTurnEvent(e); if (terminalEvent) { - traceOpenCode("event.terminal", { turnId, type: terminalEvent.type }); + this.traceOpenCode("provider.opencode.event.terminal", { + turnId, + type: terminalEvent.type, + }); this.finishForegroundTurn(terminalEvent, turnId); return false; } @@ -2703,7 +2729,7 @@ class OpenCodeAgentSession implements AgentSession { event: Extract, turnId: string, ): void { - traceOpenCode("finishForegroundTurn", { + this.traceOpenCode("provider.opencode.finish_foreground_turn", { turnId, activeTurnId: this.activeForegroundTurnId, type: event.type, @@ -2803,6 +2829,10 @@ class OpenCodeAgentSession implements AgentSession { private notifySubscribers(event: AgentStreamEvent, turnIdOverride?: string): void { const turnId = turnIdOverride ?? this.activeForegroundTurnId; const tagged = turnId ? { ...event, turnId } : event; + this.traceOpenCode("provider.opencode.event_emit", { + turnId: getAgentStreamEventTurnId(tagged), + event: tagged, + }); for (const callback of this.subscribers) { try { callback(tagged); @@ -2816,6 +2846,19 @@ class OpenCodeAgentSession implements AgentSession { return `opencode-turn-${this.nextTurnOrdinal++}`; } + private traceOpenCode(msg: OpenCodeTraceMessage, data: OpenCodeTraceData = {}): void { + this.logger.trace( + { + agentId: this.agentId, + provider: "opencode", + sessionId: this.sessionId, + turnId: data.turnId ?? this.activeForegroundTurnId ?? undefined, + ...data, + }, + msg, + ); + } + async *streamHistory(): AsyncGenerator { const response = await this.client.session.messages({ sessionID: this.sessionId, diff --git a/packages/server/src/server/agent/providers/pi-direct-agent.ts b/packages/server/src/server/agent/providers/pi-direct-agent.ts index 3501631b4..1c692ef12 100644 --- a/packages/server/src/server/agent/providers/pi-direct-agent.ts +++ b/packages/server/src/server/agent/providers/pi-direct-agent.ts @@ -30,29 +30,30 @@ import type { ThinkingLevel } from "@mariozechner/pi-agent-core"; import type { Api, ImageContent, Model, TextContent } from "@mariozechner/pi-ai"; import { z } from "zod"; -import type { - AgentCapabilityFlags, - AgentClient, - AgentLaunchContext, - AgentMetadata, - AgentMode, - AgentModelDefinition, - AgentPermissionRequest, - AgentPermissionResponse, - AgentPersistenceHandle, - AgentPromptInput, - AgentRunOptions, - AgentRunResult, - AgentRuntimeInfo, - AgentSession, - AgentSessionConfig, - AgentSlashCommand, - AgentStreamEvent, - AgentTimelineItem, - AgentUsage, - ListModesOptions, - ListModelsOptions, - ToolCallDetail, +import { + getAgentStreamEventTurnId, + type AgentCapabilityFlags, + type AgentClient, + type AgentLaunchContext, + type AgentMetadata, + type AgentMode, + type AgentModelDefinition, + type AgentPermissionRequest, + type AgentPermissionResponse, + type AgentPersistenceHandle, + type AgentPromptInput, + type AgentRunOptions, + type AgentRunResult, + type AgentRuntimeInfo, + type AgentSession, + type AgentSessionConfig, + type AgentSlashCommand, + type AgentStreamEvent, + type AgentTimelineItem, + type AgentUsage, + type ListModesOptions, + type ListModelsOptions, + type ToolCallDetail, } from "../agent-sdk-types.js"; import type { ProviderRuntimeSettings } from "../provider-launch-config.js"; import { renderPromptAttachmentAsText } from "../prompt-attachments.js"; @@ -738,21 +739,6 @@ function parsePersistenceMetadata(metadata: AgentMetadata | undefined): PiPersis return {}; } -function getStreamEventTurnId(event: AgentStreamEvent): string | undefined { - switch (event.type) { - case "turn_started": - case "turn_completed": - case "turn_failed": - case "turn_canceled": - case "timeline": - case "permission_requested": - case "permission_resolved": - return event.turnId; - default: - return undefined; - } -} - function isPiRequestAbortError(error: unknown): boolean { if (error instanceof Error && error.name === "AbortError") { return true; @@ -1045,7 +1031,7 @@ export class PiDirectAgentSession implements AgentSession { return; } - const eventTurnId = getStreamEventTurnId(event); + const eventTurnId = getAgentStreamEventTurnId(event); if (turnId && eventTurnId && eventTurnId !== turnId) { return; } diff --git a/packages/server/src/server/agent/providers/provider-runner.ts b/packages/server/src/server/agent/providers/provider-runner.ts index 6b02e65cb..94ec04770 100644 --- a/packages/server/src/server/agent/providers/provider-runner.ts +++ b/packages/server/src/server/agent/providers/provider-runner.ts @@ -1,9 +1,10 @@ -import type { - AgentPromptInput, - AgentRunOptions, - AgentRunResult, - AgentStreamEvent, - AgentTimelineItem, +import { + getAgentStreamEventTurnId, + type AgentPromptInput, + type AgentRunOptions, + type AgentRunResult, + type AgentStreamEvent, + type AgentTimelineItem, } from "../agent-sdk-types.js"; export type ProviderFinalTextReducer = (params: { @@ -44,7 +45,7 @@ export async function runProviderTurn({ if (settled) { return; } - const eventTurnId = "turnId" in event ? event.turnId : undefined; + const eventTurnId = getAgentStreamEventTurnId(event); if (turnId && eventTurnId && eventTurnId !== turnId) { return; } diff --git a/packages/server/src/server/agent/providers/test-utils/session-stream-adapter.ts b/packages/server/src/server/agent/providers/test-utils/session-stream-adapter.ts index 6178de165..5cd550a73 100644 --- a/packages/server/src/server/agent/providers/test-utils/session-stream-adapter.ts +++ b/packages/server/src/server/agent/providers/test-utils/session-stream-adapter.ts @@ -1,8 +1,9 @@ -import type { - AgentPromptInput, - AgentRunOptions, - AgentSession, - AgentStreamEvent, +import { + getAgentStreamEventTurnId, + type AgentPromptInput, + type AgentRunOptions, + type AgentSession, + type AgentStreamEvent, } from "../../agent-sdk-types.js"; function isTerminalEvent(event: AgentStreamEvent): boolean { @@ -29,7 +30,7 @@ export async function* streamSession( }; const matchesTurn = (event: AgentStreamEvent): boolean => { - const eventTurnId = (event as { turnId?: string }).turnId; + const eventTurnId = getAgentStreamEventTurnId(event); return turnId == null || eventTurnId == null || eventTurnId === turnId; }; diff --git a/packages/server/src/server/logger.test.ts b/packages/server/src/server/logger.test.ts index 3f8ed8444..04a54b3ee 100644 --- a/packages/server/src/server/logger.test.ts +++ b/packages/server/src/server/logger.test.ts @@ -106,6 +106,31 @@ describe("resolveLogConfig", () => { }, }); }); + + it("defaults file output to info when log.file is present without a level", () => { + const config: PersistedConfig = { + log: { + console: { + level: "warn", + }, + file: { + path: "daemon.log", + }, + }, + }; + + expect(resolveLogConfig(config, { paseoHome })).toEqual({ + level: "info", + console: { + level: "warn", + format: "json", + }, + file: { + level: "info", + path: path.resolve(paseoHome, "daemon.log"), + }, + }); + }); }); describe("loadConfig logger config", () => { diff --git a/packages/server/src/server/logger.ts b/packages/server/src/server/logger.ts index 669ed4e69..5c1c0522b 100644 --- a/packages/server/src/server/logger.ts +++ b/packages/server/src/server/logger.ts @@ -43,7 +43,7 @@ const LOG_LEVEL_PRIORITIES: Record = { const DEFAULT_CONSOLE_LEVEL: LogLevel = "info"; const DEFAULT_CONSOLE_FORMAT: LogFormat = "json"; -const DEFAULT_FILE_LEVEL: LogLevel = "debug"; +const DEFAULT_FILE_LEVEL: LogLevel = "info"; const DEFAULT_DAEMON_LOG_FILENAME = "daemon.log"; const REDACT_PATHS = [ "authorization", diff --git a/packages/server/src/server/session.ts b/packages/server/src/server/session.ts index ab4b1cd00..37c53a1ef 100644 --- a/packages/server/src/server/session.ts +++ b/packages/server/src/server/session.ts @@ -119,16 +119,17 @@ import { StructuredAgentResponseError, generateStructuredAgentResponseWithFallback, } from "./agent/agent-response-loop.js"; -import type { - AgentPersistenceHandle, - AgentPermissionResponse, - AgentProvider, - AgentPromptContentBlock, - AgentPromptInput, - AgentRunOptions, - AgentSessionConfig, - AgentStreamEvent, - ProviderSnapshotEntry, +import { + getAgentStreamEventTurnId, + type AgentPersistenceHandle, + type AgentPermissionResponse, + type AgentProvider, + type AgentPromptContentBlock, + type AgentPromptInput, + type AgentRunOptions, + type AgentSessionConfig, + type AgentStreamEvent, + type ProviderSnapshotEntry, } from "./agent/agent-sdk-types.js"; import type { StoredAgentRecord } from "./agent/agent-storage.js"; import type { AgentStorage } from "./agent/agent-storage.js"; @@ -895,7 +896,7 @@ export class Session { void this.initializeAgentMcp(); this.subscribeToAgentEvents(); - this.sessionLogger.trace("Session created"); + this.sessionLogger.trace({}, "agent.session.lifecycle.created"); } updateAppVersion(appVersion: string | null): void { @@ -1017,15 +1018,20 @@ export class Session { private async interruptAgentIfRunning(agentId: string): Promise { const snapshot = this.agentManager.getAgent(agentId); if (!snapshot) { - this.sessionLogger.trace({ agentId }, "interruptAgentIfRunning: agent not found"); + this.sessionLogger.trace({ agentId }, "agent.session.interrupt.not_found"); throw new Error(`Agent ${agentId} not found`); } const hasInFlightRun = this.agentManager.hasInFlightRun(agentId); if (!hasInFlightRun) { this.sessionLogger.trace( - { agentId, lifecycle: snapshot.lifecycle, hasInFlightRun }, - "interruptAgentIfRunning: skipping because agent is not running", + { + agentId, + provider: snapshot.provider, + lifecycle: snapshot.lifecycle, + hasInFlightRun, + }, + "agent.session.interrupt.skip_not_running", ); return; } @@ -1070,7 +1076,7 @@ export class Session { promptType: typeof prompt === "string" ? "string" : "structured", hasRunOptions: Boolean(runOptions), }, - "startAgentStream: requested", + "agent.session.start_stream.request", ); let iterator: AsyncGenerator; try { @@ -1080,7 +1086,7 @@ export class Session { : this.agentManager.streamAgent(agentId, prompt, runOptions); this.sessionLogger.trace( { agentId, shouldReplace }, - "startAgentStream: agent iterator returned", + "agent.session.start_stream.iterator_returned", ); } catch (error) { this.handleAgentRunError(agentId, error, "Failed to start agent run"); @@ -1092,9 +1098,9 @@ export class Session { for await (const _ of iterator) { // Events are forwarded via the session's AgentManager subscription. } - this.sessionLogger.trace({ agentId }, "startAgentStream: iterator drained"); + this.sessionLogger.trace({ agentId }, "agent.session.iterator.drained"); } catch (error) { - this.sessionLogger.trace({ agentId, err: error }, "startAgentStream: iterator threw"); + this.sessionLogger.trace({ agentId, err: error }, "agent.session.iterator.error"); this.handleAgentRunError(agentId, error, "Agent stream failed"); } })(); @@ -1135,10 +1141,7 @@ export class Session { this.agentTools = (await this.agentMcpClient.tools()) as ToolSet; const agentToolCount = Object.keys(this.agentTools ?? {}).length; - this.sessionLogger.trace( - { agentToolCount }, - `Agent MCP initialized with ${agentToolCount} tools`, - ); + this.sessionLogger.trace({ agentToolCount }, "agent.session.mcp_init"); } catch (error) { this.sessionLogger.error({ err: error }, "Failed to initialize Agent MCP"); } @@ -1210,6 +1213,16 @@ export class Session { this.unsubscribeAgentEvents = this.agentManager.subscribe( (event) => { if (event.type === "agent_state") { + this.sessionLogger.trace( + { + agentId: event.agent.id, + provider: event.agent.provider, + providerSessionId: event.agent.persistence?.sessionId ?? undefined, + turnId: event.agent.activeForegroundTurnId ?? undefined, + lifecycle: event.agent.lifecycle, + }, + "agent.session.forward_update", + ); void this.forwardAgentUpdate(event.agent); return; } @@ -1260,6 +1273,17 @@ export class Session { if (!serializedEvent) { return; } + this.sessionLogger.trace( + { + agentId: event.agentId, + provider: event.event.provider, + turnId: getAgentStreamEventTurnId(event.event), + seq: event.seq, + epoch: event.epoch, + event: event.event, + }, + "agent.session.forward_stream", + ); const payload = { agentId: event.agentId, @@ -1612,8 +1636,11 @@ export class Session { } try { this.sessionLogger.trace( - { messageType: msg.type, payloadBytes: JSON.stringify(msg).length }, - "inbound message", + { + messageType: msg.type, + payloadBytes: JSON.stringify(msg).length, + }, + "agent.session.inbound", ); try { await this.dispatchInboundMessage(msg); @@ -7180,8 +7207,12 @@ export class Session { const prompt = this.buildAgentPrompt(msg.text, msg.images, msg.attachments); this.sessionLogger.trace( - { agentId, messageId: msg.messageId, textPrefix: msg.text.slice(0, 80) }, - "send_agent_message_request: dispatching shared sendPromptToAgent", + { + agentId, + messageId: msg.messageId, + textPrefix: msg.text.slice(0, 80), + }, + "agent.session.send_agent_message", ); let dispatchResult: { outOfBand: boolean }; try { @@ -7966,8 +7997,11 @@ export class Session { */ private emit(msg: SessionOutboundMessage): void { this.sessionLogger.trace( - { messageType: msg.type, payloadBytes: JSON.stringify(msg).length }, - "outbound message", + { + messageType: msg.type, + payloadBytes: JSON.stringify(msg).length, + }, + "agent.session.outbound", ); if ( msg.type === "audio_output" && @@ -8035,7 +8069,7 @@ export class Session { * Clean up session resources */ public async cleanup(): Promise { - this.sessionLogger.trace("Cleaning up"); + this.sessionLogger.trace({}, "agent.session.lifecycle.cleanup"); if (this.unsubscribeAgentEvents) { this.unsubscribeAgentEvents();