diff --git a/packages/opencode/src/cli/cmd/tui/thread.ts b/packages/opencode/src/cli/cmd/tui/thread.ts index 05714268545..53ecfc61098 100644 --- a/packages/opencode/src/cli/cmd/tui/thread.ts +++ b/packages/opencode/src/cli/cmd/tui/thread.ts @@ -94,6 +94,7 @@ export const TuiThreadCommand = cmd({ env: Object.fromEntries( Object.entries(process.env).filter((entry): entry is [string, string] => entry[1] !== undefined), ), + argv: process.argv, }) worker.onerror = (e) => { Log.Default.error(e) diff --git a/packages/opencode/src/cli/cmd/tui/worker.ts b/packages/opencode/src/cli/cmd/tui/worker.ts index e63f10ba80c..b1cee82f123 100644 --- a/packages/opencode/src/cli/cmd/tui/worker.ts +++ b/packages/opencode/src/cli/cmd/tui/worker.ts @@ -18,6 +18,7 @@ await Log.init({ if (Installation.isLocal()) return "DEBUG" return "INFO" })(), + requestLog: process.argv.includes("--request-log"), }) process.on("unhandledRejection", (e) => { diff --git a/packages/opencode/src/index.ts b/packages/opencode/src/index.ts index 6dc5e99e91e..8dd8778738c 100644 --- a/packages/opencode/src/index.ts +++ b/packages/opencode/src/index.ts @@ -56,6 +56,10 @@ const cli = yargs(hideBin(process.argv)) type: "string", choices: ["DEBUG", "INFO", "WARN", "ERROR"], }) + .option("request-log", { + describe: "log provider requests and responses to a separate file", + type: "boolean", + }) .middleware(async (opts) => { await Log.init({ print: process.argv.includes("--print-logs"), @@ -65,6 +69,7 @@ const cli = yargs(hideBin(process.argv)) if (Installation.isLocal()) return "DEBUG" return "INFO" })(), + requestLog: process.argv.includes("--request-log"), }) process.env.AGENT = "1" @@ -151,6 +156,8 @@ try { } process.exitCode = 1 } finally { + // Flush any pending request logs before exiting + await Log.flushRequestLog() // Some subprocesses don't react properly to SIGTERM and similar signals. // Most notably, some docker-container-based MCP servers don't handle such signals unless // run using `docker run --init`. diff --git a/packages/opencode/src/provider/provider.ts b/packages/opencode/src/provider/provider.ts index e01c583ff34..aac1d74fe28 100644 --- a/packages/opencode/src/provider/provider.ts +++ b/packages/opencode/src/provider/provider.ts @@ -991,6 +991,7 @@ export namespace Provider { // Preserve custom fetch if it exists, wrap it with timeout logic const fetchFn = customFetch ?? fetch const opts = init ?? {} + const startTime = Date.now() if (options["timeout"] !== undefined && options["timeout"] !== null) { const signals: AbortSignal[] = [] @@ -1002,6 +1003,10 @@ export namespace Provider { opts.signal = combined } + const url = typeof input === "string" ? input : input.url + + const requestId = Math.random().toString(36).substring(2, 15) + // Strip openai itemId metadata following what codex does // Codex uses #[serde(skip_serializing)] on id fields for all item types: // Message, Reasoning, FunctionCall, LocalShellCall, CustomToolCall, WebSearchCall @@ -1020,11 +1025,223 @@ export namespace Provider { } } - return fetchFn(input, { - ...opts, - // @ts-ignore see here: https://github.com/oven-sh/bun/issues/16682 - timeout: false, - }) + // Log request if enabled + if (Log.isRequestLoggingEnabled()) { + const requestData: any = { + type: "REQUEST", + requestId, + provider: model.providerID, + model: model.id, + url, + method: opts.method ?? "GET", + } + + const requestRaw: any = { + type: "REQUEST", + requestId, + provider: model.providerID, + model: model.id, + url, + method: opts.method ?? "GET", + headers: opts.headers, + body: opts.body, + } + + // Parse and filter the request body + if (opts.body) { + try { + const body = typeof opts.body === "string" ? JSON.parse(opts.body) : opts.body + const filteredBody: any = {} + + // Extract messages (OpenCode format uses 'input', OpenAI uses 'messages') + const messages = body.input || body.messages + if (messages && Array.isArray(messages)) { + filteredBody.messages = messages.map((msg: any) => { + const role = msg.role + let content: string + + // Handle different content formats + if (typeof msg.content === "string") { + content = msg.content + } else if (Array.isArray(msg.content)) { + const textPart = msg.content.find((p: any) => p.type === "text" || p.text) + content = textPart?.text ?? textPart?.content ?? "[complex content]" + } else { + content = "[complex content]" + } + + return { role, content } + }) + } + + if (body.tools && Array.isArray(body.tools)) { + filteredBody.tools_count = body.tools.length + filteredBody.tools_summary = body.tools + .map((t: any) => t.function?.name || t.name) + .filter((name: any): name is string => typeof name === "string" && name.length > 0) + .join(", ") + } + + // Keep other useful fields + if (body.model) filteredBody.model = body.model + if (body.max_tokens) filteredBody.max_tokens = body.max_tokens + if (body.max_output_tokens) filteredBody.max_output_tokens = body.max_output_tokens + if (body.temperature !== undefined) filteredBody.temperature = body.temperature + if (body.stream !== undefined) filteredBody.stream = body.stream + + requestData.body = filteredBody + } catch { + requestData.body = "[parse error]" + } + } + + await Log.logRequest(requestData) + await Log.logRequestRaw(requestRaw) + } + + try { + const response = await fetchFn(input, { + ...opts, + // @ts-ignore see here: https://github.com/oven-sh/bun/issues/16682 + timeout: false, + }) + + // Log response if enabled + if (Log.isRequestLoggingEnabled()) { + const clonedResponse = response.clone() + const responseText = await clonedResponse.text().catch(() => "[stream or unreadable]") + const responseData: any = { + type: "RESPONSE", + requestId, + provider: model.providerID, + model: model.id, + url, + status: response.status, + duration: Date.now() - startTime, + } + + const responseRaw: any = { + type: "RESPONSE", + requestId, + provider: model.providerID, + model: model.id, + url, + status: response.status, + duration: Date.now() - startTime, + headers: Object.fromEntries(response.headers.entries()), + body: responseText, + } + + // Parse and extract useful information from response + let completion = "" + let tokenUsage: any = null + + // Try to parse as JSON first (non-streaming response) + try { + const jsonResponse = JSON.parse(responseText) + + // Extract completion text + if (jsonResponse.choices && Array.isArray(jsonResponse.choices)) { + const firstChoice = jsonResponse.choices[0] + completion = firstChoice?.message?.content || firstChoice?.text || "" + } else if (jsonResponse.content) { + completion = jsonResponse.content + } else if (jsonResponse.text) { + completion = jsonResponse.text + } + + // Extract token usage + if (jsonResponse.usage) { + tokenUsage = jsonResponse.usage + } + } catch { + // If not JSON, try parsing as SSE stream + if (responseText.includes("data:")) { + const lines = responseText.split("\n") + + for (const line of lines) { + if (!line.startsWith("data:")) continue + + const dataStr = line.substring(5).trim() + if (dataStr === "[DONE]") continue + + try { + const data = JSON.parse(dataStr) + + // OpenAI format: extract delta content + if (data.choices?.[0]?.delta?.content) { + completion += data.choices[0].delta.content + } + + // OpenAI format: final message + if (data.choices?.[0]?.message?.content) { + completion = data.choices[0].message.content + } + + // OpenCode format: extract text from various event types + if (data.type === "response.output_text.done" && data.text) { + completion = data.text + } + if (data.type === "content.delta" && data.delta?.text) { + completion += data.delta.text + } + if (data.type === "response.done" && data.response?.output?.[0]?.content?.[0]?.text) { + completion = data.response.output[0].content[0].text + } + + // Extract token usage from various formats + if (data.usage) { + tokenUsage = data.usage + } + if (data.response?.usage) { + tokenUsage = data.response.usage + } + } catch { + // Skip lines that can't be parsed + } + } + } + } + + // Add completion text (no truncation) + if (completion) { + responseData.completion = completion + } else { + responseData.completion = "[no text extracted]" + } + + // Add token usage if found + if (tokenUsage) { + responseData.input_tokens = tokenUsage.input_tokens || tokenUsage.prompt_tokens + responseData.output_tokens = tokenUsage.output_tokens || tokenUsage.completion_tokens + responseData.total_tokens = + tokenUsage.total_tokens || + (tokenUsage.input_tokens || tokenUsage.prompt_tokens || 0) + + (tokenUsage.output_tokens || tokenUsage.completion_tokens || 0) + } + + await Log.logRequest(responseData) + await Log.logRequestRaw(responseRaw) + } + + return response + } catch (error) { + // Log error if enabled + if (Log.isRequestLoggingEnabled()) { + const errorData = { + type: "ERROR", + requestId, + provider: model.providerID, + model: model.id, + url, + error: error instanceof Error ? error.message : String(error), + duration: Date.now() - startTime, + } + await Log.logRequest(errorData) + await Log.logRequestRaw(errorData) + } + throw error + } } const bundledFn = BUNDLED_PROVIDERS[model.api.npm] diff --git a/packages/opencode/src/util/log.ts b/packages/opencode/src/util/log.ts index 6941310bbbd..1ae8f50f549 100644 --- a/packages/opencode/src/util/log.ts +++ b/packages/opencode/src/util/log.ts @@ -1,6 +1,8 @@ import path from "path" import fs from "fs/promises" +import fsSync from "fs" import { Global } from "../global" +import { iife } from "./iife" import z from "zod" export namespace Log { @@ -44,17 +46,35 @@ export namespace Log { print: boolean dev?: boolean level?: Level + requestLog?: boolean } let logpath = "" export function file() { return logpath } - let write = (msg: any) => { + let write = (msg: any): number | Promise => { process.stderr.write(msg) return msg.length } + let requestLogPath = "" + let requestLogEnabled = false + export function requestFile() { + return requestLogPath + } + let requestWrite = (msg: any): number | Promise => { + return 0 + } + + let requestRawLogPath = "" + export function requestRawFile() { + return requestRawLogPath + } + let requestRawWrite = (msg: string): number | Promise => { + return 0 + } + export async function init(options: Options) { if (options.level) level = options.level cleanup(Global.Path.log) @@ -71,20 +91,154 @@ export namespace Log { writer.flush() return num } + + if (options.requestLog) { + requestLogEnabled = true + requestLogPath = path.join( + Global.Path.log, + options.dev ? "dev.request.log" : new Date().toISOString().split(".")[0].replace(/:/g, "") + ".request.log", + ) + requestRawLogPath = path.join( + Global.Path.log, + options.dev + ? "dev.request.raw.jsonl" + : new Date().toISOString().split(".")[0].replace(/:/g, "") + ".request.raw.jsonl", + ) + await fs.writeFile(requestLogPath, "").catch(() => {}) + await fs.writeFile(requestRawLogPath, "").catch(() => {}) + + requestWrite = (msg: any) => { + try { + fsSync.appendFileSync(requestLogPath, msg) + return msg.length + } catch (e) { + console.error("Failed to write request log:", e) + return 0 + } + } + requestRawWrite = (msg: string) => { + try { + fsSync.appendFileSync(requestRawLogPath, msg) + return msg.length + } catch (e) { + console.error("Failed to write raw request log:", e) + return 0 + } + } + } + } + + export function isRequestLoggingEnabled() { + return requestLogEnabled + } + + function formatRequestLog(data: any): string { + const timestamp = new Date().toISOString() + const time = timestamp.substring(11, 19) + + // ANSI color codes + const RESET = "\x1b[0m" + const BOLD = "\x1b[1m" + const DIM = "\x1b[2m" + const CYAN = "\x1b[36m" + const GREEN = "\x1b[32m" + const YELLOW = "\x1b[33m" + const RED = "\x1b[31m" + const BLUE = "\x1b[34m" + const MAGENTA = "\x1b[35m" + const GRAY = "\x1b[90m" + + const lines: string[] = [] + const separator = GRAY + "─".repeat(100) + RESET + const requestId = data.requestId ? `${GRAY}[${data.requestId}]${RESET}` : "" + + if (data.type === "REQUEST") { + const statusLine = `${CYAN}${BOLD}▶ REQUEST${RESET} ${DIM}${time}${RESET} ${requestId} ${GRAY}|${RESET} ${data.provider}${GRAY}/${RESET}${BLUE}${BOLD}${data.model}${RESET} ${GRAY}|${RESET} ${DIM}${data.url}${RESET}` + lines.push(separator) + lines.push(statusLine) + lines.push("") + + if (data.body?.messages) { + for (const msg of data.body.messages) { + const roleColor = msg.role === "user" ? GREEN : msg.role === "assistant" ? BLUE : MAGENTA + const content = msg.content.trim() + + lines.push(`${roleColor}${BOLD}[${msg.role}]${RESET} ${content}`) + } + } + + if (data.body?.tools_count) { + lines.push(`${DIM}Tools: ${data.body.tools_count} (${data.body.tools_summary})${RESET}`) + } + } else if (data.type === "RESPONSE") { + const statusColor = data.status >= 200 && data.status < 300 ? GREEN : RED + const tokenInfo = data.total_tokens + ? `${GRAY}|${RESET} Tokens: ${CYAN}${data.input_tokens}${RESET}/${YELLOW}${data.output_tokens}${RESET}=${BOLD}${data.total_tokens}${RESET}` + : "" + + const statusLine = `${GREEN}${BOLD}◀ RESPONSE${RESET} ${DIM}${time}${RESET} ${requestId} ${GRAY}|${RESET} ${statusColor}${data.status}${RESET} ${GRAY}|${RESET} ${data.duration}ms ${tokenInfo}` + lines.push(separator) + lines.push(statusLine) + lines.push("") + + if (data.completion) { + const modelName = data.model || "model" + lines.push(`${BLUE}${BOLD}[${modelName}]${RESET} ${data.completion}`) + } + } else if (data.type === "ERROR") { + const statusLine = `${RED}${BOLD}✖ ERROR${RESET} ${DIM}${time}${RESET} ${requestId} ${GRAY}|${RESET} ${data.provider}${GRAY}/${RESET}${data.model} ${GRAY}|${RESET} ${data.duration}ms` + lines.push(separator) + lines.push(statusLine) + lines.push("") + lines.push(`${RED}${data.error}${RESET}`) + } + + lines.push("") + return lines.join("\n") + } + + export async function logRequest(data: any) { + if (!requestLogEnabled) return + requestWrite(formatRequestLog(data)) + } + + export async function logRequestRaw(data: unknown) { + if (!requestLogEnabled) return + const text = iife(() => { + const seen = new WeakSet() + const json = JSON.stringify(data, (_key, value) => { + if (typeof value === "bigint") return value.toString() + if (typeof value === "object" && value !== null) { + if (seen.has(value)) return "[circular]" + seen.add(value) + } + return value + }) + if (json !== undefined) return json + return "null" + }) + requestRawWrite(text + "\n") + } + + export async function flushRequestLog() { + // No-op since we're using synchronous writes } async function cleanup(dir: string) { - const glob = new Bun.Glob("????-??-??T??????.log") - const files = await Array.fromAsync( - glob.scan({ - cwd: dir, - absolute: true, - }), - ) - if (files.length <= 5) return + async function cleanupPattern(pattern: string) { + const glob = new Bun.Glob(pattern) + const files = await Array.fromAsync(glob.scan({ cwd: dir, absolute: true })) + if (files.length > 5) { + const filesToDelete = files.slice(0, -10) + await Promise.all(filesToDelete.map((file) => fs.unlink(file).catch(() => {}))) + } + } - const filesToDelete = files.slice(0, -10) - await Promise.all(filesToDelete.map((file) => fs.unlink(file).catch(() => {}))) + await Promise.all([ + cleanupPattern("????-??-??T??????.log"), + cleanupPattern("????-??-??T??????.request.log"), + cleanupPattern("????-??-??T??????.request.raw.jsonl"), + ]) } function formatError(error: Error, depth = 0): string {