diff --git a/.gitignore b/.gitignore index 6fa1d5aad..f9a77a016 100644 --- a/.gitignore +++ b/.gitignore @@ -9,6 +9,7 @@ screenshot.png .env downloads/ dist/ +.browserbase/ packages/evals/**/public packages/core/lib/dom/build/ packages/core/lib/v3/dom/build/ diff --git a/packages/core/lib/v3/agent/AnthropicCUAClient.ts b/packages/core/lib/v3/agent/AnthropicCUAClient.ts index e1fbe5a1a..f47cb9265 100644 --- a/packages/core/lib/v3/agent/AnthropicCUAClient.ts +++ b/packages/core/lib/v3/agent/AnthropicCUAClient.ts @@ -19,6 +19,12 @@ import { mapKeyToPlaywright } from "./utils/cuaKeyMapping"; import { compressConversationImages } from "./utils/imageCompression"; import { toJsonSchema } from "../zodCompat"; import type { StagehandZodSchema } from "../zodCompat"; +import { + SessionFileLogger, + formatCuaPromptPreview, + formatCuaResponsePreview, +} from "../flowLogger"; +import { v7 as uuidv7 } from "uuid"; export type ResponseInputItem = AnthropicMessage | AnthropicToolResult; @@ -481,6 +487,15 @@ export class AnthropicCUAClient extends AgentClient { requestParams.thinking = thinking; } + // Log LLM request + const llmRequestId = uuidv7(); + SessionFileLogger.logLlmRequest({ + requestId: llmRequestId, + model: this.modelName, + operation: "CUA.getAction", + prompt: formatCuaPromptPreview(messages), + }); + const startTime = Date.now(); // Create the message using the Anthropic Messages API // @ts-expect-error - The Anthropic SDK types are stricter than what we need @@ -493,6 +508,16 @@ export class AnthropicCUAClient extends AgentClient { inference_time_ms: elapsedMs, }; + // Log LLM response + SessionFileLogger.logLlmResponse({ + requestId: llmRequestId, + model: this.modelName, + operation: "CUA.getAction", + output: formatCuaResponsePreview(response.content), + inputTokens: response.usage.input_tokens, + outputTokens: response.usage.output_tokens, + }); + // Store the message ID for future use this.lastMessageId = response.id; diff --git a/packages/core/lib/v3/agent/GoogleCUAClient.ts b/packages/core/lib/v3/agent/GoogleCUAClient.ts index 62df670dc..ee651da5e 100644 --- a/packages/core/lib/v3/agent/GoogleCUAClient.ts +++ b/packages/core/lib/v3/agent/GoogleCUAClient.ts @@ -30,6 +30,12 @@ import { convertToolSetToFunctionDeclarations, } from "./utils/googleCustomToolHandler"; import { ToolSet } from "ai"; +import { + SessionFileLogger, + formatCuaPromptPreview, + formatCuaResponsePreview, +} from "../flowLogger"; +import { v7 as uuidv7 } from "uuid"; /** * Client for Google's Computer Use Assistant API @@ -300,6 +306,15 @@ export class GoogleCUAClient extends AgentClient { let lastError: Error | null = null; let response: GenerateContentResponse | null = null; + // Log LLM request + const llmRequestId = uuidv7(); + SessionFileLogger.logLlmRequest({ + requestId: llmRequestId, + model: this.modelName, + operation: "CUA.generateContent", + prompt: formatCuaPromptPreview(compressedHistory), + }); + for (let attempt = 0; attempt < maxRetries; attempt++) { try { // Add exponential backoff delay for retries @@ -357,6 +372,16 @@ export class GoogleCUAClient extends AgentClient { const elapsedMs = endTime - startTime; const { usageMetadata } = response; + // Log LLM response + SessionFileLogger.logLlmResponse({ + requestId: llmRequestId, + model: this.modelName, + operation: "CUA.generateContent", + output: formatCuaResponsePreview(response), + inputTokens: usageMetadata?.promptTokenCount, + outputTokens: usageMetadata?.candidatesTokenCount, + }); + // Process the response const result = await this.processResponse(response, logger); diff --git a/packages/core/lib/v3/agent/OpenAICUAClient.ts b/packages/core/lib/v3/agent/OpenAICUAClient.ts index 94ac18aa7..8c0b76ceb 100644 --- a/packages/core/lib/v3/agent/OpenAICUAClient.ts +++ b/packages/core/lib/v3/agent/OpenAICUAClient.ts @@ -14,6 +14,12 @@ import { ClientOptions } from "../types/public/model"; import { AgentClient } from "./AgentClient"; import { AgentScreenshotProviderError } from "../types/public/sdkErrors"; import { ToolSet } from "ai"; +import { + SessionFileLogger, + formatCuaPromptPreview, + formatCuaResponsePreview, +} from "../flowLogger"; +import { v7 as uuidv7 } from "uuid"; /** * Client for OpenAI's Computer Use Assistant API @@ -409,6 +415,15 @@ export class OpenAICUAClient extends AgentClient { requestParams.previous_response_id = previousResponseId; } + // Log LLM request + const llmRequestId = uuidv7(); + SessionFileLogger.logLlmRequest({ + requestId: llmRequestId, + model: this.modelName, + operation: "CUA.getAction", + prompt: formatCuaPromptPreview(inputItems), + }); + const startTime = Date.now(); // Create the response using the OpenAI Responses API // @ts-expect-error - Force type to match what the OpenAI SDK expects @@ -423,6 +438,16 @@ export class OpenAICUAClient extends AgentClient { inference_time_ms: elapsedMs, }; + // Log LLM response + SessionFileLogger.logLlmResponse({ + requestId: llmRequestId, + model: this.modelName, + operation: "CUA.getAction", + output: formatCuaResponsePreview(response.output), + inputTokens: response.usage.input_tokens, + outputTokens: response.usage.output_tokens, + }); + // Store the response ID for future use this.lastResponseId = response.id; diff --git a/packages/core/lib/v3/flowLogger.ts b/packages/core/lib/v3/flowLogger.ts new file mode 100644 index 000000000..7adce0a00 --- /dev/null +++ b/packages/core/lib/v3/flowLogger.ts @@ -0,0 +1,1191 @@ +import { AsyncLocalStorage } from "node:async_hooks"; +import fs from "node:fs"; +import { Writable } from "node:stream"; +import { v7 as uuidv7 } from "uuid"; +import path from "node:path"; +import pino from "pino"; +import type { LanguageModelMiddleware } from "ai"; +import type { V3Options } from "./types/public"; + +// ============================================================================= +// Constants +// ============================================================================= + +const MAX_LINE_LENGTH = 160; + +// Flow logging config dir - empty string disables logging entirely +const CONFIG_DIR = process.env.BROWSERBASE_CONFIG_DIR || ""; + +const NOISY_CDP_EVENTS = new Set([ + "Target.targetInfoChanged", + "Runtime.executionContextCreated", + "Runtime.executionContextDestroyed", + "Runtime.executionContextsCleared", + "Page.lifecycleEvent", + "Network.dataReceived", + "Network.loadingFinished", + "Network.requestWillBeSentExtraInfo", + "Network.responseReceivedExtraInfo", + "Network.requestWillBeSent", + "Network.responseReceived", +]); + +// ============================================================================= +// Types +// ============================================================================= + +type EventCategory = + | "AgentTask" + | "StagehandStep" + | "UnderstudyAction" + | "CDP" + | "LLM"; + +interface FlowEvent { + // Core identifiers (set via mixin from child logger bindings) + eventId: string; + sessionId: string; + taskId?: string | null; + stepId?: string | null; + stepLabel?: string | null; + actionId?: string | null; + actionLabel?: string | null; + + // Event classification + category: EventCategory; + event: "started" | "completed" | "call" | "message" | "request" | "response"; + method?: string; + msg?: string; + + // Event-specific payload (not truncated) + params?: unknown; + targetId?: string | null; + + // LLM event fields (for individual LLM request/response events only) + requestId?: string; // Correlation ID linking LLM request to response + model?: string; + prompt?: unknown; + output?: unknown; + inputTokens?: number; // Tokens for THIS specific LLM call + outputTokens?: number; // Tokens for THIS specific LLM call + + // Aggregate metrics (for completion events only - task/step/action) + metrics?: { + durationMs?: number; + llmRequests?: number; // Total LLM calls in this span + inputTokens?: number; // Total input tokens across all LLM calls + outputTokens?: number; // Total output tokens across all LLM calls + cdpEvents?: number; // Total CDP events in this span + }; +} + +interface FlowLoggerMetrics { + taskStartTime?: number; + stepStartTime?: number; + actionStartTime?: number; + llmRequests: number; + llmInputTokens: number; + llmOutputTokens: number; + cdpEvents: number; +} + +export interface FlowLoggerContext { + logger: pino.Logger; + metrics: FlowLoggerMetrics; + sessionId: string; + sessionDir: string; + configDir: string; + initPromise: Promise; + initialized: boolean; + // Current span context (mutable, injected via mixin) + taskId: string | null; + stepId: string | null; + stepLabel: string | null; + actionId: string | null; + actionLabel: string | null; + // File handles for pretty streams + fileStreams: { + agent: fs.WriteStream | null; + stagehand: fs.WriteStream | null; + understudy: fs.WriteStream | null; + cdp: fs.WriteStream | null; + llm: fs.WriteStream | null; + jsonl: fs.WriteStream | null; + }; +} + +const loggerContext = new AsyncLocalStorage(); + +// ============================================================================= +// Formatting Utilities (used by pretty streams) +// ============================================================================= + +/** Calculate base64 data size in KB */ +const dataToKb = (data: string): string => + ((data.length * 0.75) / 1024).toFixed(1); + +/** Truncate CDP IDs: frameId:363F03EB...EF8 → frameId:363F…5EF8 */ +function truncateCdpIds(value: string): string { + return value.replace( + /([iI]d:?"?)([0-9A-F]{32})(?="?[,})\s]|$)/g, + (_, pre: string, id: string) => `${pre}${id.slice(0, 4)}…${id.slice(-4)}`, + ); +} + +/** Truncate line showing start...end */ +function truncateLine(value: string, maxLen: number): string { + const collapsed = value.replace(/\s+/g, " "); + if (collapsed.length <= maxLen) return collapsed; + const endLen = Math.floor(maxLen * 0.3); + const startLen = maxLen - endLen - 1; + return `${collapsed.slice(0, startLen)}…${collapsed.slice(-endLen)}`; +} + +function formatValue(value: unknown): string { + if (typeof value === "string") return `'${value}'`; + if (value == null || typeof value !== "object") return String(value); + try { + return JSON.stringify(value); + } catch { + return "[unserializable]"; + } +} + +function formatArgs(args?: unknown | unknown[]): string { + if (args === undefined) return ""; + return (Array.isArray(args) ? args : [args]) + .filter((e) => e !== undefined) + .map(formatValue) + .filter((e) => e.length > 0) + .join(", "); +} + +const shortId = (id: string | null | undefined): string => + id ? id.slice(-4) : "-"; + +function formatTag( + label: string | null | undefined, + id: string | null | undefined, + icon: string, +): string { + return id ? `[${icon} #${shortId(id)}${label ? " " + label : ""}]` : "⤑"; +} + +let nonce = 0; +function formatTimestamp(): string { + const d = new Date(); + const pad = (n: number, w = 2) => String(n).padStart(w, "0"); + return `${d.getFullYear()}-${pad(d.getMonth() + 1)}-${pad(d.getDate())} ${pad(d.getHours())}:${pad(d.getMinutes())}:${pad(d.getSeconds())}.${pad(d.getMilliseconds(), 3)}${pad(nonce++ % 100)}`; +} + +const SENSITIVE_KEYS = + /apikey|api_key|key|secret|token|password|passwd|pwd|credential|auth/i; + +function sanitizeOptions(options: V3Options): Record { + const sanitize = (obj: unknown): unknown => { + if (typeof obj !== "object" || obj === null) return obj; + if (Array.isArray(obj)) return obj.map(sanitize); + const result: Record = {}; + for (const [key, value] of Object.entries(obj)) { + result[key] = SENSITIVE_KEYS.test(key) ? "******" : sanitize(value); + } + return result; + }; + return sanitize({ ...options }) as Record; +} + +/** Remove unescaped quotes for cleaner log output */ +function removeQuotes(str: string): string { + return str + .replace(/([^\\])["']/g, "$1") + .replace(/^["']|["']$/g, "") + .trim(); +} + +// ============================================================================= +// Pretty Formatting (converts FlowEvent to human-readable log line) +// ============================================================================= + +function prettifyEvent(event: FlowEvent): string | null { + const parts: string[] = []; + + // Build context tags - always add parent span tags (formatTag returns ⤑ for null IDs) + if (event.category === "AgentTask") { + parts.push(formatTag("", event.taskId, "🅰")); + } else if (event.category === "StagehandStep") { + parts.push(formatTag("", event.taskId, "🅰")); + parts.push(formatTag(event.stepLabel, event.stepId, "🆂")); + } else if (event.category === "UnderstudyAction") { + parts.push(formatTag("", event.taskId, "🅰")); + parts.push(formatTag(event.stepLabel, event.stepId, "🆂")); + parts.push(formatTag(event.actionLabel, event.actionId, "🆄")); + } else if (event.category === "CDP") { + parts.push(formatTag("", event.taskId, "🅰")); + parts.push(formatTag(event.stepLabel, event.stepId, "🆂")); + parts.push(formatTag(event.actionLabel, event.actionId, "🆄")); + parts.push(formatTag("CDP", event.targetId, "🅲")); + } else if (event.category === "LLM") { + parts.push(formatTag("", event.taskId, "🅰")); + parts.push(formatTag(event.stepLabel, event.stepId, "🆂")); + parts.push(formatTag("LLM", event.requestId, "🧠")); + } + + // Build details based on event type + let details = ""; + const argsStr = event.params ? formatArgs(event.params) : ""; + + if (event.category === "AgentTask") { + if (event.event === "started") { + details = `▷ ${event.method}(${argsStr})`; + } else if (event.event === "completed") { + const m = event.metrics; + const durationSec = m?.durationMs + ? (m.durationMs / 1000).toFixed(1) + : "?"; + const llmStats = `${m?.llmRequests ?? 0} LLM calls ꜛ${m?.inputTokens ?? 0} ꜜ${m?.outputTokens ?? 0} tokens`; + const cdpStats = `${m?.cdpEvents ?? 0} CDP msgs`; + details = `✓ Agent.execute() DONE in ${durationSec}s | ${llmStats} | ${cdpStats}`; + } + } else if (event.category === "StagehandStep") { + if (event.event === "started") { + details = `▷ ${event.method}(${argsStr})`; + } else if (event.event === "completed") { + const durationSec = event.metrics?.durationMs + ? (event.metrics.durationMs / 1000).toFixed(2) + : "?"; + details = `✓ ${event.stepLabel || "STEP"} completed in ${durationSec}s`; + } + } else if (event.category === "UnderstudyAction") { + if (event.event === "started") { + details = `▷ ${event.method}(${argsStr})`; + } else if (event.event === "completed") { + const durationSec = event.metrics?.durationMs + ? (event.metrics.durationMs / 1000).toFixed(2) + : "?"; + details = `✓ ${event.actionLabel || "ACTION"} completed in ${durationSec}s`; + } + } else if (event.category === "CDP") { + const icon = event.event === "call" ? "⏵" : "⏴"; + details = `${icon} ${event.method}(${argsStr})`; + } else if (event.category === "LLM") { + if (event.event === "request") { + const promptStr = event.prompt ? " " + String(event.prompt) : ""; + details = `${event.model} ⏴${promptStr}`; + } else if (event.event === "response") { + const hasTokens = + event.inputTokens !== undefined || event.outputTokens !== undefined; + const tokenStr = hasTokens + ? ` ꜛ${event.inputTokens ?? 0} ꜜ${event.outputTokens ?? 0} |` + : ""; + const outputStr = event.output ? " " + String(event.output) : ""; + details = `${event.model} ↳${tokenStr}${outputStr}`; + } + } + + if (!details) return null; + + // Assemble line and apply final truncation + const fullLine = `${formatTimestamp()} ${parts.join(" ")} ${details}`; + const cleaned = removeQuotes(fullLine); + const processed = + event.category === "CDP" ? truncateCdpIds(cleaned) : cleaned; + return truncateLine(processed, MAX_LINE_LENGTH); +} + +/** Check if a CDP event should be filtered from pretty output */ +function shouldFilterCdpEvent(event: FlowEvent): boolean { + if (event.category !== "CDP") return false; + if (event.method?.endsWith(".enable") || event.method === "enable") + return true; + return event.event === "message" && NOISY_CDP_EVENTS.has(event.method!); +} + +// ============================================================================= +// Stream Creation +// ============================================================================= + +const isWritable = (s: fs.WriteStream | null): s is fs.WriteStream => + !!(s && !s.destroyed && s.writable); + +function createJsonlStream(ctx: FlowLoggerContext): Writable { + return new Writable({ + objectMode: true, + write(chunk: string, _, cb) { + if (ctx.initialized && isWritable(ctx.fileStreams.jsonl)) { + ctx.fileStreams.jsonl.write(chunk, cb); + } else cb(); + }, + }); +} + +function createPrettyStream( + ctx: FlowLoggerContext, + category: EventCategory, + streamKey: keyof FlowLoggerContext["fileStreams"], +): Writable { + return new Writable({ + objectMode: true, + write(chunk: string, _, cb) { + const stream = ctx.fileStreams[streamKey]; + if (!ctx.initialized || !isWritable(stream)) return cb(); + try { + const event = JSON.parse(chunk) as FlowEvent; + if (event.category !== category || shouldFilterCdpEvent(event)) + return cb(); + const line = prettifyEvent(event); + if (line) stream.write(line + "\n", cb); + else cb(); + } catch { + cb(); + } + }, + }); +} + +// ============================================================================= +// Public Helpers (used by external callers) +// ============================================================================= + +/** + * Get the config directory. Returns empty string if logging is disabled. + */ +export function getConfigDir(): string { + return CONFIG_DIR ? path.resolve(CONFIG_DIR) : ""; +} + +// ============================================================================= +// Prompt Preview Helpers +// ============================================================================= + +type ContentPart = { + type?: string; + text?: string; + content?: unknown[]; + source?: { data?: string }; + image_url?: { url?: string }; + inlineData?: { data?: string }; +}; + +/** Extract text and image info from a content array (handles nested tool_result) */ +function extractFromContent( + content: unknown[], + result: { text?: string; extras: string[] }, +): void { + for (const part of content) { + const p = part as ContentPart; + // Text + if (!result.text && p.text) { + result.text = p.type === "text" || !p.type ? p.text : undefined; + } + // Images - various formats + if (p.type === "image" || p.type === "image_url") { + const url = p.image_url?.url; + if (url?.startsWith("data:")) + result.extras.push(`${dataToKb(url)}kb image`); + else if (p.source?.data) + result.extras.push(`${dataToKb(p.source.data)}kb image`); + else result.extras.push("image"); + } else if (p.source?.data) { + result.extras.push(`${dataToKb(p.source.data)}kb image`); + } else if (p.inlineData?.data) { + result.extras.push(`${dataToKb(p.inlineData.data)}kb image`); + } + // Recurse into tool_result content + if (p.type === "tool_result" && Array.isArray(p.content)) { + extractFromContent(p.content, result); + } + } +} + +/** Build final preview string with extras */ +function buildPreview( + text: string | undefined, + extras: string[], + maxLen?: number, +): string | undefined { + if (!text && extras.length === 0) return undefined; + let result = text || ""; + if (maxLen && result.length > maxLen) + result = result.slice(0, maxLen) + "..."; + if (extras.length > 0) { + const extrasStr = extras.map((e) => `+{${e}}`).join(" "); + result = result ? `${result} ${extrasStr}` : extrasStr; + } + return result || undefined; +} + +/** + * Format a prompt preview from LLM messages for logging. + * Returns format like: "some text... +{5.8kb image} +{schema} +{12 tools}" + */ +export function formatLlmPromptPreview( + messages: Array<{ role: string; content: unknown }>, + options?: { toolCount?: number; hasSchema?: boolean }, +): string | undefined { + try { + const lastUserMsg = messages.filter((m) => m.role === "user").pop(); + if (!lastUserMsg) return undefined; + + const result = { + text: undefined as string | undefined, + extras: [] as string[], + }; + + if (typeof lastUserMsg.content === "string") { + result.text = lastUserMsg.content; + } else if (Array.isArray(lastUserMsg.content)) { + extractFromContent(lastUserMsg.content, result); + } else { + return undefined; + } + + // Clean instruction prefix + if (result.text) { + result.text = result.text.replace(/^[Ii]nstruction: /, ""); + } + + if (options?.hasSchema) result.extras.push("schema"); + if (options?.toolCount) result.extras.push(`${options.toolCount} tools`); + + return buildPreview(result.text, result.extras); + } catch { + return undefined; + } +} + +/** + * Extract a text preview from CUA-style messages. + * Accepts various message formats (Anthropic, OpenAI, Google). + */ +export function formatCuaPromptPreview( + messages: unknown[], + maxLen = 100, +): string | undefined { + try { + const lastMsg = messages + .filter((m) => { + const msg = m as { role?: string; type?: string }; + return msg.role === "user" || msg.type === "tool_result"; + }) + .pop() as + | { content?: unknown; parts?: unknown[]; text?: string } + | undefined; + + if (!lastMsg) return undefined; + + const result = { + text: undefined as string | undefined, + extras: [] as string[], + }; + + if (typeof lastMsg.content === "string") { + result.text = lastMsg.content; + } else if (typeof lastMsg.text === "string") { + result.text = lastMsg.text; + } else if (Array.isArray(lastMsg.parts)) { + extractFromContent(lastMsg.parts, result); + } else if (Array.isArray(lastMsg.content)) { + extractFromContent(lastMsg.content, result); + } + + return buildPreview(result.text, result.extras, maxLen); + } catch { + return undefined; + } +} + +/** Format CUA response output for logging */ +export function formatCuaResponsePreview( + output: unknown, + maxLen = 100, +): string { + try { + // Handle Google format or array + const items: unknown[] = + (output as { candidates?: [{ content?: { parts?: unknown[] } }] }) + ?.candidates?.[0]?.content?.parts ?? + (Array.isArray(output) ? output : []); + + const preview = items + .map((item) => { + const i = item as { + type?: string; + text?: string; + name?: string; + functionCall?: { name?: string }; + }; + if (i.text) return i.text.slice(0, 50); + if (i.functionCall?.name) return `fn:${i.functionCall.name}`; + if (i.type === "tool_use" && i.name) return `tool_use:${i.name}`; + return i.type ? `[${i.type}]` : "[item]"; + }) + .join(" "); + + return preview.slice(0, maxLen); + } catch { + return "[error]"; + } +} + +// ============================================================================= +// SessionFileLogger - Main API +// ============================================================================= + +export class SessionFileLogger { + /** + * Initialize a new logging context. Call this at the start of a session. + * If BROWSERBASE_CONFIG_DIR is not set, logging is disabled. + */ + static init(sessionId: string, v3Options?: V3Options): void { + const configDir = getConfigDir(); + if (!configDir) return; // Logging disabled + + const sessionDir = path.join(configDir, "sessions", sessionId); + + // Create context with placeholder logger (will be replaced after streams init) + const ctx: FlowLoggerContext = { + logger: pino({ level: "silent" }), // Placeholder, replaced below + metrics: { + llmRequests: 0, + llmInputTokens: 0, + llmOutputTokens: 0, + cdpEvents: 0, + }, + sessionId, + sessionDir, + configDir, + initPromise: Promise.resolve(), + initialized: false, + // Span context - mutable, injected into every log via mixin + taskId: null, + stepId: null, + stepLabel: null, + actionId: null, + actionLabel: null, + fileStreams: { + agent: null, + stagehand: null, + understudy: null, + cdp: null, + llm: null, + jsonl: null, + }, + }; + + // Store init promise for awaiting in log methods + ctx.initPromise = SessionFileLogger.initAsync(ctx, v3Options); + + loggerContext.enterWith(ctx); + } + + private static async initAsync( + ctx: FlowLoggerContext, + v3Options?: V3Options, + ): Promise { + try { + await fs.promises.mkdir(ctx.sessionDir, { recursive: true }); + + if (v3Options) { + const sanitizedOptions = sanitizeOptions(v3Options); + const sessionJsonPath = path.join(ctx.sessionDir, "session.json"); + await fs.promises.writeFile( + sessionJsonPath, + JSON.stringify(sanitizedOptions, null, 2), + "utf-8", + ); + } + + // Create symlink to latest session + const latestLink = path.join(ctx.configDir, "sessions", "latest"); + try { + try { + await fs.promises.unlink(latestLink); + } catch { + // Ignore if doesn't exist + } + await fs.promises.symlink(ctx.sessionId, latestLink, "dir"); + } catch { + // Symlink creation can fail on Windows or due to permissions + } + + // Create file streams + const dir = ctx.sessionDir; + ctx.fileStreams.agent = fs.createWriteStream( + path.join(dir, "agent_events.log"), + { flags: "a" }, + ); + ctx.fileStreams.stagehand = fs.createWriteStream( + path.join(dir, "stagehand_events.log"), + { flags: "a" }, + ); + ctx.fileStreams.understudy = fs.createWriteStream( + path.join(dir, "understudy_events.log"), + { flags: "a" }, + ); + ctx.fileStreams.cdp = fs.createWriteStream( + path.join(dir, "cdp_events.log"), + { flags: "a" }, + ); + ctx.fileStreams.llm = fs.createWriteStream( + path.join(dir, "llm_events.log"), + { flags: "a" }, + ); + ctx.fileStreams.jsonl = fs.createWriteStream( + path.join(dir, "session_events.jsonl"), + { flags: "a" }, + ); + + ctx.initialized = true; + + // Create pino multistream: JSONL + pretty streams per category + const streams: pino.StreamEntry[] = [ + { stream: createJsonlStream(ctx) }, + { stream: createPrettyStream(ctx, "AgentTask", "agent") }, + { stream: createPrettyStream(ctx, "StagehandStep", "stagehand") }, + { stream: createPrettyStream(ctx, "UnderstudyAction", "understudy") }, + { stream: createPrettyStream(ctx, "CDP", "cdp") }, + { stream: createPrettyStream(ctx, "LLM", "llm") }, + ]; + + // Create logger with mixin that injects span context from AsyncLocalStorage + ctx.logger = pino( + { + level: "info", + // Mixin adds eventId and current span context to every log + mixin() { + const store = loggerContext.getStore(); + return { + eventId: uuidv7(), + sessionId: store?.sessionId, + taskId: store?.taskId, + stepId: store?.stepId, + stepLabel: store?.stepLabel, + actionId: store?.actionId, + actionLabel: store?.actionLabel, + }; + }, + }, + pino.multistream(streams), + ); + } catch { + // Fail silently + } + } + + static async close(): Promise { + const ctx = loggerContext.getStore(); + if (!ctx) return; + await ctx.initPromise; + SessionFileLogger.logAgentTaskCompleted(); + await Promise.all( + Object.values(ctx.fileStreams) + .filter(Boolean) + .map((s) => new Promise((r) => s!.end(r))), + ).catch(() => {}); + } + + static get sessionId(): string | null { + return loggerContext.getStore()?.sessionId ?? null; + } + + static get sessionDir(): string | null { + return loggerContext.getStore()?.sessionDir ?? null; + } + + /** + * Get the current logger context object. + */ + static getContext(): FlowLoggerContext | null { + return loggerContext.getStore() ?? null; + } + + // =========================================================================== + // Agent Task Events + // =========================================================================== + + /** + * Start a new task and log it. + */ + static logAgentTaskStarted({ + invocation, + args, + }: { + invocation: string; + args?: unknown | unknown[]; + }): void { + const ctx = loggerContext.getStore(); + if (!ctx) return; + + // Set up task context + ctx.taskId = uuidv7(); + ctx.stepId = null; + ctx.stepLabel = null; + ctx.actionId = null; + ctx.actionLabel = null; + + // Reset metrics for new task + ctx.metrics = { + taskStartTime: Date.now(), + llmRequests: 0, + llmInputTokens: 0, + llmOutputTokens: 0, + cdpEvents: 0, + }; + + ctx.logger.info({ + category: "AgentTask", + event: "started", + method: invocation, + params: args, + } as FlowEvent); + } + + /** + * Log task completion with metrics summary. + */ + static logAgentTaskCompleted(options?: { cacheHit?: boolean }): void { + const ctx = loggerContext.getStore(); + if (!ctx || !ctx.metrics.taskStartTime) return; + + const durationMs = Date.now() - ctx.metrics.taskStartTime; + + const event: Partial = { + category: "AgentTask", + event: "completed", + method: "Agent.execute", + metrics: { + durationMs, + llmRequests: ctx.metrics.llmRequests, + inputTokens: ctx.metrics.llmInputTokens, + outputTokens: ctx.metrics.llmOutputTokens, + cdpEvents: ctx.metrics.cdpEvents, + }, + }; + + if (options?.cacheHit) { + event.msg = "CACHE HIT, NO LLM NEEDED"; + } + + ctx.logger.info(event); + + // Clear task context + ctx.taskId = null; + ctx.stepId = null; + ctx.stepLabel = null; + ctx.actionId = null; + ctx.actionLabel = null; + ctx.metrics.taskStartTime = undefined; + } + + // =========================================================================== + // Stagehand Step Events + // =========================================================================== + + static logStagehandStepEvent({ + invocation, + args, + label, + }: { + invocation: string; + args?: unknown | unknown[]; + label: string; + }): string { + const ctx = loggerContext.getStore(); + if (!ctx) return uuidv7(); + + // Set up step context + ctx.stepId = uuidv7(); + ctx.stepLabel = label.toUpperCase(); + ctx.actionId = null; + ctx.actionLabel = null; + ctx.metrics.stepStartTime = Date.now(); + + ctx.logger.info({ + category: "StagehandStep", + event: "started", + method: invocation, + params: args, + } as FlowEvent); + + return ctx.stepId; + } + + static logStagehandStepCompleted(): void { + const ctx = loggerContext.getStore(); + if (!ctx || !ctx.stepId) return; + + const durationMs = ctx.metrics.stepStartTime + ? Date.now() - ctx.metrics.stepStartTime + : 0; + + ctx.logger.info({ + category: "StagehandStep", + event: "completed", + metrics: { durationMs }, + } as FlowEvent); + + // Clear step context + ctx.stepId = null; + ctx.stepLabel = null; + ctx.actionId = null; + ctx.actionLabel = null; + ctx.metrics.stepStartTime = undefined; + } + + // =========================================================================== + // Understudy Action Events + // =========================================================================== + + static logUnderstudyActionEvent({ + actionType, + target, + args, + }: { + actionType: string; + target?: string; + args?: unknown | unknown[]; + }): string { + const ctx = loggerContext.getStore(); + if (!ctx) return uuidv7(); + + // Set up action context + ctx.actionId = uuidv7(); + ctx.actionLabel = actionType + .toUpperCase() + .replace("UNDERSTUDY.", "") + .replace("PAGE.", ""); + ctx.metrics.actionStartTime = Date.now(); + + const params: Record = {}; + if (target) params.target = target; + if (args) params.args = args; + + ctx.logger.info({ + category: "UnderstudyAction", + event: "started", + method: actionType, + params: Object.keys(params).length > 0 ? params : undefined, + } as FlowEvent); + + return ctx.actionId; + } + + static logUnderstudyActionCompleted(): void { + const ctx = loggerContext.getStore(); + if (!ctx || !ctx.actionId) return; + + const durationMs = ctx.metrics.actionStartTime + ? Date.now() - ctx.metrics.actionStartTime + : 0; + + ctx.logger.info({ + category: "UnderstudyAction", + event: "completed", + metrics: { durationMs }, + } as FlowEvent); + + // Clear action context + ctx.actionId = null; + ctx.actionLabel = null; + ctx.metrics.actionStartTime = undefined; + } + + // =========================================================================== + // CDP Events + // =========================================================================== + + private static logCdpEvent( + eventType: "call" | "message", + { + method, + params, + targetId, + }: { method: string; params?: unknown; targetId?: string | null }, + explicitCtx?: FlowLoggerContext | null, + ): void { + const ctx = explicitCtx ?? loggerContext.getStore(); + if (!ctx) return; + if (eventType === "call") ctx.metrics.cdpEvents++; + ctx.logger.info({ + category: "CDP", + event: eventType, + method, + params, + targetId, + } as FlowEvent); + } + + static logCdpCallEvent( + data: { method: string; params?: object; targetId?: string | null }, + ctx?: FlowLoggerContext | null, + ): void { + SessionFileLogger.logCdpEvent("call", data, ctx); + } + + static logCdpMessageEvent( + data: { method: string; params?: unknown; targetId?: string | null }, + ctx?: FlowLoggerContext | null, + ): void { + SessionFileLogger.logCdpEvent("message", data, ctx); + } + + // =========================================================================== + // LLM Events + // =========================================================================== + + static logLlmRequest( + { + requestId, + model, + prompt, + }: { + requestId: string; + model: string; + operation: string; + prompt?: string; + }, + explicitCtx?: FlowLoggerContext | null, + ): void { + const ctx = explicitCtx ?? loggerContext.getStore(); + if (!ctx) return; + + // Track LLM requests for task metrics + ctx.metrics.llmRequests++; + + ctx.logger.info({ + category: "LLM", + event: "request", + requestId, + method: "LLM.request", + model, + prompt, + }); + } + + static logLlmResponse( + { + requestId, + model, + output, + inputTokens, + outputTokens, + }: { + requestId: string; + model: string; + operation: string; + output?: string; + inputTokens?: number; + outputTokens?: number; + }, + explicitCtx?: FlowLoggerContext | null, + ): void { + const ctx = explicitCtx ?? loggerContext.getStore(); + if (!ctx) return; + + // Track tokens for task metrics + ctx.metrics.llmInputTokens += inputTokens ?? 0; + ctx.metrics.llmOutputTokens += outputTokens ?? 0; + + ctx.logger.info({ + category: "LLM", + event: "response", + requestId, + method: "LLM.response", + model, + output, + inputTokens, + outputTokens, + }); + } + + // =========================================================================== + // LLM Logging Middleware + // =========================================================================== + + /** + * Create middleware for wrapping language models with LLM call logging. + * Returns a no-op middleware when logging is disabled. + */ + static createLlmLoggingMiddleware( + modelId: string, + ): Pick { + // No-op middleware when logging is disabled + if (!CONFIG_DIR) { + return { + wrapGenerate: async ({ doGenerate }) => doGenerate(), + }; + } + + return { + wrapGenerate: async ({ doGenerate, params }) => { + const ctx = SessionFileLogger.getContext(); + // Skip logging overhead if no context (shouldn't happen but be safe) + if (!ctx) { + return doGenerate(); + } + const llmRequestId = uuidv7(); + const toolCount = Array.isArray(params.tools) ? params.tools.length : 0; + + // Extract prompt preview from last non-system message + const messages = (params.prompt ?? []) as Array<{ + role?: string; + content?: unknown; + }>; + const lastMsg = messages.filter((m) => m.role !== "system").pop(); + const extracted = { + text: undefined as string | undefined, + extras: [] as string[], + }; + + let rolePrefix = lastMsg?.role ?? "?"; + if (lastMsg) { + if (typeof lastMsg.content === "string") { + extracted.text = lastMsg.content; + } else if (Array.isArray(lastMsg.content)) { + // Check for tool-result first + const toolResult = ( + lastMsg.content as Array<{ + type?: string; + toolName?: string; + output?: { type?: string; value?: unknown }; + }> + ).find((p) => p.type === "tool-result"); + if (toolResult) { + rolePrefix = `tool result: ${toolResult.toolName}()`; + const out = toolResult.output; + if (out?.type === "json" && out.value) { + extracted.text = JSON.stringify(out.value).slice(0, 150); + } else if (Array.isArray(out?.value)) { + extractFromContent(out.value as unknown[], extracted); + } + } else { + extractFromContent(lastMsg.content as unknown[], extracted); + } + } + } + + const promptText = extracted.text || "(no text)"; + const promptPreview = `${rolePrefix}: ${promptText} +{${toolCount} tools}`; + + SessionFileLogger.logLlmRequest( + { + requestId: llmRequestId, + model: modelId, + operation: "generateText", + prompt: promptPreview, + }, + ctx, + ); + + const result = await doGenerate(); + + // Extract output preview + const res = result as { + text?: string; + content?: unknown; + toolCalls?: unknown[]; + }; + let outputPreview = res.text || ""; + if (!outputPreview && res.content) { + if (typeof res.content === "string") { + outputPreview = res.content; + } else if (Array.isArray(res.content)) { + outputPreview = ( + res.content as Array<{ + type?: string; + text?: string; + toolName?: string; + }> + ) + .map( + (c) => + c.text || + (c.type === "tool-call" + ? `tool call: ${c.toolName}()` + : `[${c.type}]`), + ) + .join(" "); + } + } + if (!outputPreview && res.toolCalls?.length) { + outputPreview = `[${res.toolCalls.length} tool calls]`; + } + + SessionFileLogger.logLlmResponse( + { + requestId: llmRequestId, + model: modelId, + operation: "generateText", + output: outputPreview || "[empty]", + inputTokens: result.usage?.inputTokens, + outputTokens: result.usage?.outputTokens, + }, + ctx, + ); + + return result; + }, + }; + } +} + +/** + * Method decorator for logging understudy actions with automatic start/complete. + * Logs all arguments automatically. No-op when CONFIG_DIR is empty. + */ +export function logAction(actionType: string) { + return function Promise>( + originalMethod: T, + ): T { + // No-op when logging is disabled + if (!CONFIG_DIR) { + return originalMethod; + } + + return async function (this: unknown, ...args: unknown[]) { + SessionFileLogger.logUnderstudyActionEvent({ + actionType, + args: args.length > 0 ? args : undefined, + }); + + try { + return await originalMethod.apply(this, args as never[]); + } finally { + SessionFileLogger.logUnderstudyActionCompleted(); + } + } as T; + }; +} + +/** + * Method decorator for logging Stagehand step events (act, extract, observe). + * Only adds logging - does NOT wrap with withInstanceLogContext (caller handles that). + * No-op when CONFIG_DIR is empty. + */ +export function logStagehandStep(invocation: string, label: string) { + return function Promise>( + originalMethod: T, + ): T { + // No-op when logging is disabled + if (!CONFIG_DIR) { + return originalMethod; + } + + return async function ( + this: unknown, + ...args: unknown[] + ): Promise { + SessionFileLogger.logStagehandStepEvent({ + invocation, + args: args.length > 0 ? args : undefined, + label, + }); + + try { + return await originalMethod.apply(this, args as never[]); + } finally { + SessionFileLogger.logStagehandStepCompleted(); + } + } as T; + }; +} diff --git a/packages/core/lib/v3/handlers/handlerUtils/actHandlerUtils.ts b/packages/core/lib/v3/handlers/handlerUtils/actHandlerUtils.ts index a5f2bc155..1b4334ba8 100644 --- a/packages/core/lib/v3/handlers/handlerUtils/actHandlerUtils.ts +++ b/packages/core/lib/v3/handlers/handlerUtils/actHandlerUtils.ts @@ -5,6 +5,7 @@ import { Locator } from "../../understudy/locator"; import { resolveLocatorWithHops } from "../../understudy/deepLocator"; import type { Page } from "../../understudy/page"; import { v3Logger } from "../../logger"; +import { SessionFileLogger } from "../../flowLogger"; import { StagehandClickError } from "../../types/public/sdkErrors"; export class UnderstudyCommandException extends Error { @@ -73,6 +74,12 @@ export async function performUnderstudyMethod( domSettleTimeoutMs, }; + SessionFileLogger.logUnderstudyActionEvent({ + actionType: `Understudy.${method}`, + target: selectorRaw, + args: Array.from(args), + }); + try { const handler = METHOD_HANDLER_MAP[method] ?? null; @@ -120,6 +127,8 @@ export async function performUnderstudyMethod( }, }); throw new UnderstudyCommandException(msg); + } finally { + SessionFileLogger.logUnderstudyActionCompleted(); } } diff --git a/packages/core/lib/v3/handlers/v3AgentHandler.ts b/packages/core/lib/v3/handlers/v3AgentHandler.ts index 6648256bf..37162011f 100644 --- a/packages/core/lib/v3/handlers/v3AgentHandler.ts +++ b/packages/core/lib/v3/handlers/v3AgentHandler.ts @@ -13,6 +13,7 @@ import { } from "ai"; import { processMessages } from "../agent/utils/messageProcessing"; import { LLMClient } from "../llm/LLMClient"; +import { SessionFileLogger } from "../flowLogger"; import { AgentExecuteOptions, AgentStreamExecuteOptions, @@ -86,6 +87,7 @@ export class V3AgentHandler { const { processedPrompt } = processMessages(params); return { ...params, prompt: processedPrompt } as typeof params; }, + ...SessionFileLogger.createLlmLoggingMiddleware(baseModel.modelId), }, }); diff --git a/packages/core/lib/v3/handlers/v3CuaAgentHandler.ts b/packages/core/lib/v3/handlers/v3CuaAgentHandler.ts index 33b67721b..f06b99c3e 100644 --- a/packages/core/lib/v3/handlers/v3CuaAgentHandler.ts +++ b/packages/core/lib/v3/handlers/v3CuaAgentHandler.ts @@ -13,6 +13,7 @@ import { } from "../types/public/agent"; import { LogLine } from "../types/public/logs"; import { type Action, V3FunctionName } from "../types/public/methods"; +import { SessionFileLogger } from "../flowLogger"; export class V3CuaAgentHandler { private v3: V3; @@ -73,7 +74,21 @@ export class V3CuaAgentHandler { } } await new Promise((r) => setTimeout(r, 300)); - await this.executeAction(action); + // Skip logging for screenshot actions - they're no-ops, the actual + // Page.screenshot in captureAndSendScreenshot() is logged separately + const shouldLog = action.type !== "screenshot"; + if (shouldLog) { + SessionFileLogger.logUnderstudyActionEvent({ + actionType: `v3CUA.${action.type}`, + target: this.computePointerTarget(action), + args: [action], + }); + } + try { + await this.executeAction(action); + } finally { + if (shouldLog) SessionFileLogger.logUnderstudyActionCompleted(); + } action.timestamp = Date.now(); @@ -371,7 +386,7 @@ export class V3CuaAgentHandler { return { success: true }; } case "screenshot": { - // Already handled around actions + // No-op - screenshot is captured by captureAndSendScreenshot() after all actions return { success: true }; } case "goto": { @@ -424,6 +439,19 @@ export class V3CuaAgentHandler { } } + // helper to make pointer target human-readable for logging + private computePointerTarget(action: AgentAction): string | undefined { + return typeof action.x === "number" && typeof action.y === "number" + ? `(${action.x}, ${action.y})` + : typeof action.selector === "string" + ? action.selector + : typeof action.input === "string" + ? action.input + : typeof action.description === "string" + ? action.description + : undefined; + } + private ensureXPath(value: unknown): string | null { if (typeof value !== "string") return null; const trimmed = value.trim(); diff --git a/packages/core/lib/v3/llm/aisdk.ts b/packages/core/lib/v3/llm/aisdk.ts index d437766fc..354eb107c 100644 --- a/packages/core/lib/v3/llm/aisdk.ts +++ b/packages/core/lib/v3/llm/aisdk.ts @@ -13,9 +13,11 @@ import { } from "ai"; import type { LanguageModelV2 } from "@ai-sdk/provider"; import { ChatCompletion } from "openai/resources"; +import { v7 as uuidv7 } from "uuid"; import { LogLine } from "../types/public/logs"; import { AvailableModel } from "../types/public/model"; import { CreateChatCompletionOptions, LLMClient } from "./LLMClient"; +import { SessionFileLogger, formatLlmPromptPreview } from "../flowLogger"; export class AISdkClient extends LLMClient { public type = "aisdk" as const; @@ -129,6 +131,18 @@ export class AISdkClient extends LLMClient { const isGPT5 = this.model.modelId.includes("gpt-5"); const isGPT51 = this.model.modelId.includes("gpt-5.1"); if (options.response_model) { + // Log LLM request for generateObject (extract) + const llmRequestId = uuidv7(); + const promptPreview = formatLlmPromptPreview(options.messages, { + hasSchema: true, + }); + SessionFileLogger.logLlmRequest({ + requestId: llmRequestId, + model: this.model.modelId, + operation: "generateObject", + prompt: promptPreview, + }); + try { objectResponse = await generateObject({ model: this.model, @@ -145,6 +159,14 @@ export class AISdkClient extends LLMClient { : undefined, }); } catch (err) { + // Log error response to maintain request/response pairing + SessionFileLogger.logLlmResponse({ + requestId: llmRequestId, + model: this.model.modelId, + operation: "generateObject", + output: `[error: ${err instanceof Error ? err.message : "unknown"}]`, + }); + if (NoObjectGeneratedError.isInstance(err)) { this.logger?.({ category: "AISDK error", @@ -194,6 +216,16 @@ export class AISdkClient extends LLMClient { }, } as T; + // Log LLM response for generateObject + SessionFileLogger.logLlmResponse({ + requestId: llmRequestId, + model: this.model.modelId, + operation: "generateObject", + output: JSON.stringify(objectResponse.object), + inputTokens: objectResponse.usage.inputTokens, + outputTokens: objectResponse.usage.outputTokens, + }); + this.logger?.({ category: "aisdk", message: "response", @@ -228,21 +260,46 @@ export class AISdkClient extends LLMClient { } } - const textResponse = await generateText({ - model: this.model, - messages: formattedMessages, - tools: Object.keys(tools).length > 0 ? tools : undefined, - toolChoice: - Object.keys(tools).length > 0 - ? options.tool_choice === "required" - ? "required" - : options.tool_choice === "none" - ? "none" - : "auto" - : undefined, - temperature: options.temperature, + // Log LLM request for generateText (act/observe) + const llmRequestId = uuidv7(); + const toolCount = Object.keys(tools).length; + const promptPreview = formatLlmPromptPreview(options.messages, { + toolCount, + }); + SessionFileLogger.logLlmRequest({ + requestId: llmRequestId, + model: this.model.modelId, + operation: "generateText", + prompt: promptPreview, }); + let textResponse: Awaited>; + try { + textResponse = await generateText({ + model: this.model, + messages: formattedMessages, + tools: Object.keys(tools).length > 0 ? tools : undefined, + toolChoice: + Object.keys(tools).length > 0 + ? options.tool_choice === "required" + ? "required" + : options.tool_choice === "none" + ? "none" + : "auto" + : undefined, + temperature: options.temperature, + }); + } catch (err) { + // Log error response to maintain request/response pairing + SessionFileLogger.logLlmResponse({ + requestId: llmRequestId, + model: this.model.modelId, + operation: "generateText", + output: `[error: ${err instanceof Error ? err.message : "unknown"}]`, + }); + throw err; + } + // Transform AI SDK response to match LLMResponse format expected by operator handler const transformedToolCalls = (textResponse.toolCalls || []).map( (toolCall) => ({ @@ -282,6 +339,20 @@ export class AISdkClient extends LLMClient { }, } as T; + // Log LLM response for generateText + SessionFileLogger.logLlmResponse({ + requestId: llmRequestId, + model: this.model.modelId, + operation: "generateText", + output: + textResponse.text || + (transformedToolCalls.length > 0 + ? `[${transformedToolCalls.length} tool calls]` + : ""), + inputTokens: textResponse.usage.inputTokens, + outputTokens: textResponse.usage.outputTokens, + }); + this.logger?.({ category: "aisdk", message: "response", diff --git a/packages/core/lib/v3/understudy/cdp.ts b/packages/core/lib/v3/understudy/cdp.ts index c6e82e3c3..9ab81f665 100644 --- a/packages/core/lib/v3/understudy/cdp.ts +++ b/packages/core/lib/v3/understudy/cdp.ts @@ -45,9 +45,25 @@ export class CdpConnection implements CDPSessionLike { private inflight = new Map(); private eventHandlers = new Map>(); private sessions = new Map(); + /** Maps sessionId -> targetId (1:1 mapping) */ + private sessionToTarget = new Map(); public readonly id: string | null = null; // root private transportCloseHandlers = new Set<(why: string) => void>(); + /** Optional CDP logger - set this to receive all outgoing CDP method calls */ + public cdpLogger?: (info: { + method: string; + params?: object; + targetId?: string | null; + }) => void; + + /** Optional CDP event logger - set this to receive all incoming CDP events */ + public cdpEventLogger?: (info: { + method: string; + params?: unknown; + targetId?: string | null; + }) => void; + public onTransportClosed(handler: (why: string) => void): void { this.transportCloseHandlers.add(handler); } @@ -118,6 +134,7 @@ export class CdpConnection implements CDPSessionLike { ts: Date.now(), }); }); + this.cdpLogger?.({ method, params, targetId: null }); this.ws.send(JSON.stringify(payload)); return p; } @@ -155,6 +172,7 @@ export class CdpConnection implements CDPSessionLike { session = new CdpSession(this, sessionId); this.sessions.set(sessionId, session); } + this.sessionToTarget.set(sessionId, targetId); return session; } @@ -189,6 +207,7 @@ export class CdpConnection implements CDPSessionLike { if (!this.sessions.has(p.sessionId)) { this.sessions.set(p.sessionId, new CdpSession(this, p.sessionId)); } + this.sessionToTarget.set(p.sessionId, p.targetInfo.targetId); } else if (msg.method === "Target.detachedFromTarget") { const p = (msg as { params: Protocol.Target.DetachedFromTargetEvent }) .params; @@ -199,9 +218,24 @@ export class CdpConnection implements CDPSessionLike { } } this.sessions.delete(p.sessionId); + this.sessionToTarget.delete(p.sessionId); + } else if (msg.method === "Target.targetDestroyed") { + const p = (msg as { params: { targetId: string } }).params; + // Remove any session mapping for this target + for (const [sessionId, targetId] of this.sessionToTarget.entries()) { + if (targetId === p.targetId) { + this.sessionToTarget.delete(sessionId); + break; + } + } } const { method, params, sessionId } = msg; + + // Log incoming CDP events + const targetId = this.sessionToTarget.get(sessionId) || sessionId; + this.cdpEventLogger?.({ method, params, targetId }); + if (sessionId) { const session = this.sessions.get(sessionId); session?.dispatch(method, params); @@ -232,6 +266,8 @@ export class CdpConnection implements CDPSessionLike { ts: Date.now(), }); }); + const targetId = this.sessionToTarget.get(sessionId) ?? null; + this.cdpLogger?.({ method, params, targetId }); this.ws.send(JSON.stringify(payload)); return p; } diff --git a/packages/core/lib/v3/understudy/page.ts b/packages/core/lib/v3/understudy/page.ts index f558659a3..9d315e803 100644 --- a/packages/core/lib/v3/understudy/page.ts +++ b/packages/core/lib/v3/understudy/page.ts @@ -1,6 +1,7 @@ import { Protocol } from "devtools-protocol"; import { promises as fs } from "fs"; import { v3Logger } from "../logger"; +import { logAction } from "../flowLogger"; import type { CDPSessionLike } from "./cdp"; import { CdpConnection } from "./cdp"; import { Frame } from "./frame"; @@ -624,6 +625,7 @@ export class Page { /** * Close this top-level page (tab). Best-effort via Target.closeTarget. */ + @logAction("Page.close") public async close(): Promise { try { await this.conn.send("Target.closeTarget", { targetId: this._targetId }); @@ -758,6 +760,7 @@ export class Page { * Navigate the page; optionally wait for a lifecycle state. * Waits on the **current** main frame and follows root swaps during navigation. */ + @logAction("Page.goto") async goto( url: string, options?: { waitUntil?: LoadState; timeoutMs?: number }, @@ -820,6 +823,7 @@ export class Page { /** * Reload the page; optionally wait for a lifecycle state. */ + @logAction("Page.reload") async reload(options?: { waitUntil?: LoadState; timeoutMs?: number; @@ -866,6 +870,7 @@ export class Page { /** * Navigate back in history if possible; optionally wait for a lifecycle state. */ + @logAction("Page.goBack") async goBack(options?: { waitUntil?: LoadState; timeoutMs?: number; @@ -918,6 +923,7 @@ export class Page { /** * Navigate forward in history if possible; optionally wait for a lifecycle state. */ + @logAction("Page.goForward") async goForward(options?: { waitUntil?: LoadState; timeoutMs?: number; @@ -1047,6 +1053,7 @@ export class Page { * timeout error is thrown. * @param options.type Image format (`"png"` by default). */ + @logAction("Page.screenshot") async screenshot(options?: ScreenshotOptions): Promise { const opts = options ?? {}; const type = opts.type ?? "png"; @@ -1169,6 +1176,7 @@ export class Page { * Wait until the page reaches a lifecycle state on the current main frame. * Mirrors Playwright's API signatures. */ + @logAction("Page.waitForLoadState") async waitForLoadState(state: LoadState, timeoutMs?: number): Promise { await this.waitForMainLoadState(state, timeoutMs ?? 15000); } @@ -1180,6 +1188,7 @@ export class Page { * - The return value should be JSON-serializable. Non-serializable objects will * best-effort serialize via JSON.stringify inside the page context. */ + @logAction("Page.evaluate") async evaluate( pageFunctionOrExpression: string | ((arg: Arg) => R | Promise), arg?: Arg, @@ -1194,19 +1203,17 @@ export class Page { expression = String(pageFunctionOrExpression); } else { const fnSrc = pageFunctionOrExpression.toString(); - // Build an IIFE that calls the user's function with the argument and - // attempts to deep-serialize the result for returnByValue. const argJson = JSON.stringify(arg); expression = `(() => { - const __fn = ${fnSrc}; - const __arg = ${argJson}; - try { - const __res = __fn(__arg); - return Promise.resolve(__res).then(v => { - try { return JSON.parse(JSON.stringify(v)); } catch { return v; } - }); - } catch (e) { throw e; } - })()`; + const __fn = ${fnSrc}; + const __arg = ${argJson}; + try { + const __res = __fn(__arg); + return Promise.resolve(__res).then(v => { + try { return JSON.parse(JSON.stringify(v)); } catch { return v; } + }); + } catch (e) { throw e; } + })()`; } const { result, exceptionDetails } = @@ -1235,6 +1242,7 @@ export class Page { * Force the page viewport to an exact CSS size and device scale factor. * Ensures screenshots match width x height pixels when deviceScaleFactor = 1. */ + // @logAction("Page.setViewportSize") // disabled because it's pretty noisy, can always re-enable if needed for debugging async setViewportSize( width: number, height: number, @@ -1294,6 +1302,7 @@ export class Page { returnXpath: boolean; }, ): Promise; + @logAction("Page.click") async click( x: number, y: number, @@ -1390,6 +1399,7 @@ export class Page { deltaY: number, options: { returnXpath: boolean }, ): Promise; + @logAction("Page.scroll") async scroll( x: number, y: number, @@ -1468,6 +1478,7 @@ export class Page { returnXpath: boolean; }, ): Promise; + @logAction("Page.dragAndDrop") async dragAndDrop( fromX: number, fromY: number, @@ -1572,6 +1583,7 @@ export class Page { * and never falls back to Input.insertText. Optional delay applies between * successive characters. */ + @logAction("Page.type") async type( text: string, options?: { delay?: number; withMistakes?: boolean }, @@ -1669,6 +1681,7 @@ export class Page { * For printable characters, uses the text path on keyDown; for named keys, sets key/code/VK. * Supports key combinations with modifiers like "Cmd+A", "Ctrl+C", "Shift+Tab", etc. */ + @logAction("Page.keyPress") async keyPress(key: string, options?: { delay?: number }): Promise { const delay = Math.max(0, options?.delay ?? 0); const sleep = (ms: number) => diff --git a/packages/core/lib/v3/v3.ts b/packages/core/lib/v3/v3.ts index e564cebbb..22b66bb55 100644 --- a/packages/core/lib/v3/v3.ts +++ b/packages/core/lib/v3/v3.ts @@ -3,6 +3,7 @@ import fs from "fs"; import os from "os"; import path from "path"; import process from "process"; +import { v7 as uuidv7 } from "uuid"; import { z } from "zod"; import type { InferStagehandSchema, StagehandZodSchema } from "./zodCompat"; import { loadApiKeyFromEnv } from "../utils"; @@ -72,6 +73,7 @@ import { V3Context } from "./understudy/context"; import { Page } from "./understudy/page"; import { resolveModel } from "../modelUtils"; import { StagehandAPIClient } from "./api"; +import { SessionFileLogger, logStagehandStep } from "./flowLogger"; import { createTimeoutGuard } from "./handlers/handlerUtils/timeoutGuard"; import { ActTimeoutError } from "./types/public/sdkErrors"; @@ -207,9 +209,7 @@ export class V3 { V3._installProcessGuards(); this.externalLogger = opts.logger; this.verbose = opts.verbose ?? 1; - this.instanceId = - (globalThis.crypto as Crypto | undefined)?.randomUUID?.() ?? - `${Date.now()}-${Math.floor(Math.random() * 1e9)}`; + this.instanceId = uuidv7(); // Create per-instance StagehandLogger (handles usePino, verbose, externalLogger) // This gives each V3 instance independent logger configuration @@ -310,6 +310,10 @@ export class V3 { }); this.opts = opts; + + // Initialize session file logger + SessionFileLogger.init(this.instanceId, opts); + // Track instance for global process guard handling V3._instances.add(this); } @@ -688,6 +692,11 @@ export class V3 { this.ctx = await V3Context.create(lbo.cdpUrl, { env: "LOCAL", }); + const logCtx = SessionFileLogger.getContext(); + this.ctx.conn.cdpLogger = (info) => + SessionFileLogger.logCdpCallEvent(info, logCtx); + this.ctx.conn.cdpEventLogger = (info) => + SessionFileLogger.logCdpMessageEvent(info, logCtx); this.ctx.conn.onTransportClosed(this._onCdpClosed); this.state = { kind: "LOCAL", @@ -777,6 +786,11 @@ export class V3 { env: "LOCAL", localBrowserLaunchOptions: lbo, }); + const logCtx = SessionFileLogger.getContext(); + this.ctx.conn.cdpLogger = (info) => + SessionFileLogger.logCdpCallEvent(info, logCtx); + this.ctx.conn.cdpEventLogger = (info) => + SessionFileLogger.logCdpMessageEvent(info, logCtx); this.ctx.conn.onTransportClosed(this._onCdpClosed); this.state = { kind: "LOCAL", @@ -854,6 +868,11 @@ export class V3 { env: "BROWSERBASE", apiClient: this.apiClient, }); + const logCtx = SessionFileLogger.getContext(); + this.ctx.conn.cdpLogger = (info) => + SessionFileLogger.logCdpCallEvent(info, logCtx); + this.ctx.conn.cdpEventLogger = (info) => + SessionFileLogger.logCdpMessageEvent(info, logCtx); this.ctx.conn.onTransportClosed(this._onCdpClosed); this.state = { kind: "BROWSERBASE", sessionId, ws, bb }; this.browserbaseSessionId = sessionId; @@ -964,6 +983,7 @@ export class V3 { async act(instruction: string, options?: ActOptions): Promise; async act(action: Action, options?: ActOptions): Promise; + @logStagehandStep("Stagehand.act", "ACT") async act(input: string | Action, options?: ActOptions): Promise { return await withInstanceLogContext(this.instanceId, async () => { if (!this.actHandler) throw new StagehandNotInitializedError("act()"); @@ -1116,6 +1136,7 @@ export class V3 { options?: ExtractOptions, ): Promise>; + @logStagehandStep("Stagehand.extract", "EXTRACT") async extract( a?: string | ExtractOptions, b?: StagehandZodSchema | ExtractOptions, @@ -1196,6 +1217,7 @@ export class V3 { instruction: string, options?: ObserveOptions, ): Promise; + @logStagehandStep("Stagehand.observe", "OBSERVE") async observe( a?: string | ObserveOptions, b?: ObserveOptions, @@ -1274,6 +1296,13 @@ export class V3 { this._isClosing = true; try { + // Close session file logger + try { + await SessionFileLogger.close(); + } catch { + // Fail silently + } + // Unhook CDP transport close handler if context exists try { if (this.ctx?.conn && this._onCdpClosed) { @@ -1392,7 +1421,7 @@ export class V3 { } if (this.isPuppeteerPage(page)) { - const cdp = await page.target().createCDPSession(); + const cdp = await page.createCDPSession(); const { frameTree } = await cdp.send("Page.getFrameTree"); this.logger({ category: "v3", @@ -1650,6 +1679,10 @@ export class V3 { return { execute: async (instructionOrOptions: string | AgentExecuteOptions) => withInstanceLogContext(this.instanceId, async () => { + SessionFileLogger.logAgentTaskStarted({ + invocation: "Agent.execute", + args: [instructionOrOptions], + }); if (options?.integrations && !this.experimental) { throw new ExperimentalNotConfiguredError("MCP integrations"); } @@ -1696,6 +1729,7 @@ export class V3 { if (cacheContext) { const replayed = await this.agentCache.tryReplay(cacheContext); if (replayed) { + SessionFileLogger.logAgentTaskCompleted({ cacheHit: true }); return replayed; } } @@ -1735,6 +1769,7 @@ export class V3 { if (recording) { this.discardAgentReplayRecording(); } + SessionFileLogger.logAgentTaskCompleted(); } }), }; @@ -1752,6 +1787,10 @@ export class V3 { | AgentStreamExecuteOptions, ): Promise => withInstanceLogContext(this.instanceId, async () => { + SessionFileLogger.logAgentTaskStarted({ + invocation: "Agent.execute", + args: [instructionOrOptions], + }); if ( typeof instructionOrOptions === "object" && instructionOrOptions.callbacks && @@ -1776,6 +1815,7 @@ export class V3 { const replayed = await this.agentCache.tryReplayAsStream(cacheContext); if (replayed) { + SessionFileLogger.logAgentTaskCompleted({ cacheHit: true }); return replayed; } } @@ -1785,15 +1825,20 @@ export class V3 { ); if (cacheContext) { - return this.agentCache.wrapStreamForCaching( + const wrappedStream = this.agentCache.wrapStreamForCaching( cacheContext, streamResult, () => this.beginAgentReplayRecording(), () => this.endAgentReplayRecording(), () => this.discardAgentReplayRecording(), ); + // Log completion when stream is returned (stream completes asynchronously) + SessionFileLogger.logAgentTaskCompleted(); + return wrappedStream; } + // Log completion when stream is returned (stream completes asynchronously) + SessionFileLogger.logAgentTaskCompleted(); return streamResult; } @@ -1808,6 +1853,7 @@ export class V3 { if (cacheContext) { const replayed = await this.agentCache.tryReplay(cacheContext); if (replayed) { + SessionFileLogger.logAgentTaskCompleted({ cacheHit: true }); return replayed; } } @@ -1848,6 +1894,7 @@ export class V3 { if (recording) { this.discardAgentReplayRecording(); } + SessionFileLogger.logAgentTaskCompleted(); } }), }; diff --git a/packages/core/package.json b/packages/core/package.json index 621e16f7c..cbf70b663 100644 --- a/packages/core/package.json +++ b/packages/core/package.json @@ -44,6 +44,7 @@ }, "dependencies": { "@ai-sdk/provider": "^2.0.0", + "uuid": "^11.1.0", "@anthropic-ai/sdk": "0.39.0", "@browserbasehq/sdk": "^2.4.0", "@google/genai": "^1.22.0", diff --git a/pnpm-lock.yaml b/pnpm-lock.yaml index f563ab992..dd40f412b 100644 --- a/pnpm-lock.yaml +++ b/pnpm-lock.yaml @@ -67,7 +67,7 @@ importers: version: 1.2.0 chromium-bidi: specifier: ^0.10.0 - version: 0.10.2(devtools-protocol@0.0.1312386) + version: 0.10.2(devtools-protocol@0.0.1464554) esbuild: specifier: ^0.21.4 version: 0.21.5 @@ -161,6 +161,9 @@ importers: playwright: specifier: ^1.52.0 version: 1.54.2 + uuid: + specifier: ^11.1.0 + version: 11.1.0 ws: specifier: ^8.18.0 version: 8.18.3(bufferutil@4.0.9) @@ -6209,6 +6212,10 @@ packages: resolution: {integrity: sha512-8XkAphELsDnEGrDxUOHB3RGvXz6TeuYSGEZBOjtTtPm2lwhGBjLgOzLHB63IUWfBpNucQjND6d3AOudO+H3RWQ==} hasBin: true + uuid@11.1.0: + resolution: {integrity: sha512-0/A9rDy9P7cJ+8w1c9WD9V//9Wj15Ce2MPz8Ri6032usz+NfePxx5AcN3bN+r6ZL6jEo066/yNYB3tn4pQEx+A==} + hasBin: true + uuid@9.0.1: resolution: {integrity: sha512-b+1eJOlsR9K8HJpow9Ok3fiWOWSIcIzXodvv0rQjVoOVNpWMpxf1wZNpt4y9h10odCNrqnYp1OBzRktckBe3sA==} hasBin: true @@ -6496,18 +6503,18 @@ packages: snapshots: - '@ai-sdk/anthropic@2.0.34(zod@3.25.67)': + '@ai-sdk/anthropic@2.0.34(zod@4.1.12)': dependencies: '@ai-sdk/provider': 2.0.0 - '@ai-sdk/provider-utils': 3.0.12(zod@3.25.67) - zod: 3.25.67 + '@ai-sdk/provider-utils': 3.0.12(zod@4.1.12) + zod: 4.1.12 optional: true - '@ai-sdk/anthropic@2.0.34(zod@4.1.12)': + '@ai-sdk/anthropic@2.0.53(zod@3.25.67)': dependencies: '@ai-sdk/provider': 2.0.0 - '@ai-sdk/provider-utils': 3.0.12(zod@4.1.12) - zod: 4.1.12 + '@ai-sdk/provider-utils': 3.0.18(zod@3.25.67) + zod: 3.25.67 optional: true '@ai-sdk/anthropic@2.0.53(zod@4.1.12)': @@ -6591,18 +6598,18 @@ snapshots: - supports-color optional: true - '@ai-sdk/google@2.0.23(zod@3.25.67)': + '@ai-sdk/google@2.0.23(zod@4.1.12)': dependencies: '@ai-sdk/provider': 2.0.0 - '@ai-sdk/provider-utils': 3.0.12(zod@3.25.67) - zod: 3.25.67 + '@ai-sdk/provider-utils': 3.0.12(zod@4.1.12) + zod: 4.1.12 optional: true - '@ai-sdk/google@2.0.23(zod@4.1.12)': + '@ai-sdk/google@2.0.44(zod@3.25.67)': dependencies: '@ai-sdk/provider': 2.0.0 - '@ai-sdk/provider-utils': 3.0.12(zod@4.1.12) - zod: 4.1.12 + '@ai-sdk/provider-utils': 3.0.18(zod@3.25.67) + zod: 3.25.67 optional: true '@ai-sdk/google@2.0.44(zod@4.1.12)': @@ -6696,6 +6703,14 @@ snapshots: eventsource-parser: 3.0.6 zod: 4.1.12 + '@ai-sdk/provider-utils@3.0.18(zod@3.25.67)': + dependencies: + '@ai-sdk/provider': 2.0.0 + '@standard-schema/spec': 1.0.0 + eventsource-parser: 3.0.6 + zod: 3.25.67 + optional: true + '@ai-sdk/provider-utils@3.0.18(zod@4.1.12)': dependencies: '@ai-sdk/provider': 2.0.0 @@ -6851,11 +6866,11 @@ snapshots: zod: 3.25.67 zod-to-json-schema: 3.25.0(zod@3.25.67) optionalDependencies: - '@ai-sdk/anthropic': 2.0.34(zod@3.25.67) + '@ai-sdk/anthropic': 2.0.53(zod@3.25.67) '@ai-sdk/azure': 2.0.54(zod@3.25.67) '@ai-sdk/cerebras': 1.0.25(zod@3.25.67) '@ai-sdk/deepseek': 1.0.23(zod@3.25.67) - '@ai-sdk/google': 2.0.23(zod@3.25.67) + '@ai-sdk/google': 2.0.44(zod@3.25.67) '@ai-sdk/groq': 2.0.24(zod@3.25.67) '@ai-sdk/mistral': 2.0.19(zod@3.25.67) '@ai-sdk/openai': 2.0.53(zod@3.25.67) @@ -9184,9 +9199,9 @@ snapshots: transitivePeerDependencies: - supports-color - chromium-bidi@0.10.2(devtools-protocol@0.0.1312386): + chromium-bidi@0.10.2(devtools-protocol@0.0.1464554): dependencies: - devtools-protocol: 0.0.1312386 + devtools-protocol: 0.0.1464554 mitt: 3.0.1 zod: 3.23.8 @@ -13615,6 +13630,8 @@ snapshots: uuid@10.0.0: {} + uuid@11.1.0: {} + uuid@9.0.1: {} validate.io-array@1.0.6: {}