diff --git a/packages/core/src/observability/logging.ts b/packages/core/src/observability/logging.ts index 0047d8d5e3fd..c2abb81634a2 100644 --- a/packages/core/src/observability/logging.ts +++ b/packages/core/src/observability/logging.ts @@ -56,6 +56,7 @@ const stderrLogger = Logger.make((options) => process.stderr.write(formatter().l export function minimumLogLevel() { const value = process.env.OPENCODE_LOG_LEVEL?.toUpperCase() const levels = { + TRACE: "Trace", DEBUG: "Debug", INFO: "Info", WARN: "Warn", diff --git a/packages/core/src/v1/config/config.ts b/packages/core/src/v1/config/config.ts index 7ebb4b69b023..4e49674c4fdd 100644 --- a/packages/core/src/v1/config/config.ts +++ b/packages/core/src/v1/config/config.ts @@ -173,6 +173,10 @@ export const Info = Schema.Struct({ openTelemetry: Schema.optional(Schema.Boolean).annotate({ description: "Enable OpenTelemetry spans for AI SDK calls (using the 'experimental_telemetry' flag)", }), + log_messages: Schema.optional(Schema.Literals(["info", "debug", "trace"])).annotate({ + description: + "Verbosity for LLM request/response logging: 'info' logs messages and response text; 'debug' adds generation params at Effect debug level; 'trace' adds the raw provider-native request body at Effect trace level (native runtime only; requires OPENCODE_LOG_LEVEL=DEBUG or TRACE). Logs can contain full transcripts, including tool results — treat log destinations as sensitive.", + }), primary_tools: Schema.optional(Schema.mutable(Schema.Array(Schema.String))).annotate({ description: "Tools that should only be available to primary agents.", }), diff --git a/packages/llm/src/route/client.ts b/packages/llm/src/route/client.ts index d3b41f5817f1..ed9d4340774b 100644 --- a/packages/llm/src/route/client.ts +++ b/packages/llm/src/route/client.ts @@ -8,6 +8,8 @@ import { HttpTransport } from "./transport" import type { Transport, TransportRuntime } from "./transport" import { WebSocketExecutor } from "./transport" import type { Protocol } from "./protocol" +import { logRequest, responseStream } from "./message-logger" +import type { LogLevel } from "./message-logger" import { applyCachePolicy } from "../cache-policy" import * as ProviderShared from "../protocols/shared" import type { LLMError, LLMEvent, PreparedRequestOf, ProtocolID, ProviderOptions } from "../schema" @@ -350,11 +352,17 @@ const compile = Effect.fn("LLM.compile")(function* (request: LLMRequest) { .pipe(Effect.flatMap(ProviderShared.validateWith(Schema.decodeUnknownEffect(route.body.schema)))) const prepared = yield* route.prepareTransport(body, resolved) + const logMessages = request.metadata?.logMessages + if (logMessages) { + yield* logRequest(request, logMessages as LogLevel, body) + } + return { request: resolved, route, body, prepared, + logMessages, } }) @@ -375,19 +383,26 @@ const streamRequestWith = (runtime: TransportRuntime) => (request: LLMRequest) = Stream.unwrap( Effect.gen(function* () { const compiled = yield* compile(request) - return compiled.route.streamPrepared(compiled.prepared, compiled.request, runtime) + const events = compiled.route.streamPrepared(compiled.prepared, compiled.request, runtime) + const logMessages = request.metadata?.logMessages as LogLevel | undefined + if (!logMessages) return events + return responseStream(`${request.model.provider}/${request.model.id}`, logMessages)(events) }), ) const generateWith = (stream: Interface["stream"]) => Effect.fn("LLM.generate")(function* (request: LLMRequest) { + // The stream pipeline emits the single coalesced "LLM response" log at the + // terminal event, which runs before this fold completes. const state = yield* stream(request).pipe(Stream.runFold(LLMResponse.empty, LLMResponse.reduce)) const response = LLMResponse.complete(state) - if (response) return response - return yield* ProviderShared.eventError( - `${request.model.provider}/${request.model.route.id}`, - "Provider stream ended without a terminal finish event", - ) + if (!response) { + return yield* ProviderShared.eventError( + `${request.model.provider}/${request.model.route.id}`, + "Provider stream ended without a terminal finish event", + ) + } + return response }) export const prepare = (request: LLMRequest) => diff --git a/packages/llm/src/route/index.ts b/packages/llm/src/route/index.ts index 48f4b7bc3392..e321ffc32edb 100644 --- a/packages/llm/src/route/index.ts +++ b/packages/llm/src/route/index.ts @@ -10,6 +10,8 @@ export type { Service as LLMClientService, } from "./client" export * from "./executor" +export { MessageLogger } from "./message-logger" +export type { LogLevel } from "./message-logger" export { Auth } from "./auth" export { AuthOptions } from "./auth-options" export { Endpoint } from "./endpoint" diff --git a/packages/llm/src/route/message-logger.ts b/packages/llm/src/route/message-logger.ts new file mode 100644 index 000000000000..92c95b203ff4 --- /dev/null +++ b/packages/llm/src/route/message-logger.ts @@ -0,0 +1,124 @@ +import { Effect, Stream } from "effect" +import type { LLMEvent, LLMRequest } from "../schema" + +export type LogLevel = "info" | "debug" | "trace" + +export const formatMessages = (request: LLMRequest): string => { + const parts: Array = [] + for (const part of request.system) { + if (part.type === "text") parts.push(`system: ${part.text}`) + } + for (const message of request.messages) { + const texts: Array = [] + for (const part of message.content) { + if (part.type === "text") texts.push(part.text) + if (part.type === "tool-call") texts.push(`tool-call(${part.name}): ${JSON.stringify(part.input)}`) + if (part.type === "tool-result") texts.push(`tool-result(${part.name}): ${JSON.stringify(part.result)}`) + } + parts.push(`${message.role}: ${texts.join("\n")}`) + } + return parts.join("\n") +} + +export const formatEvents = (events: ReadonlyArray): string => { + const segments: Array = [] + let pending = "" + let kind: "text" | "reasoning" = "text" + const flush = () => { + if (!pending) return + segments.push(kind === "reasoning" ? `[reasoning]: ${pending}` : pending) + pending = "" + } + for (const event of events) { + if (event.type === "text-delta") { + if (kind !== "text") { + flush() + kind = "text" + } + pending += event.text + continue + } + if (event.type === "reasoning-delta") { + if (kind !== "reasoning") { + flush() + kind = "reasoning" + } + pending += event.text + continue + } + if (event.type === "tool-call" || event.type === "tool-result") { + flush() + segments.push( + event.type === "tool-call" + ? `tool-call(${event.name}): ${JSON.stringify(event.input)}` + : `tool-result(${event.name}): ${JSON.stringify(event.result)}`, + ) + continue + } + if (event.type === "provider-error") { + flush() + segments.push(`error: ${event.message}`) + continue + } + if (event.type === "finish" && event.usage) { + flush() + segments.push(`usage: ${JSON.stringify(event.usage)}`) + } + } + flush() + return segments.join("\n") +} + +// Trace severity sits above Debug, so runtimes configured at Debug still pass +// trace entries through while keeping the three tiers distinguishable. +export const log = (level: LogLevel, label: string, data: Record): Effect.Effect => { + switch (level) { + case "info": + return Effect.logInfo(label, data) + case "debug": + return Effect.logDebug(label, data) + case "trace": + return Effect.logTrace(label, data) + } +} + +export const logRequest = (request: LLMRequest, level: LogLevel, body?: unknown): Effect.Effect => { + const model = `${request.model.provider}/${request.model.id}` + const payload: Record = { model, messages: formatMessages(request) } + if (level !== "info" && request.generation) { + payload.generation = Object.fromEntries( + Object.entries(request.generation).filter(([, value]) => value !== undefined), + ) + } + if (level === "trace" && body !== undefined) { + payload.body = JSON.stringify(body) + } + return log(level, "LLM request", payload) +} + +export const logEvents = (request: LLMRequest, events: ReadonlyArray, level: LogLevel): Effect.Effect => + log(level, "LLM response", { + model: `${request.model.provider}/${request.model.id}`, + response: formatEvents(events), + }) + +// Accumulates the response in the stream itself so a single "LLM response" +// entry is emitted once, when the terminal event (finish or provider-error) +// passes through, instead of one entry per streamed delta. +export const responseStream = (model: string, level: LogLevel) => { + const collected: Array = [] + return (events: Stream.Stream): Stream.Stream => + events.pipe( + Stream.mapEffect((event) => + Effect.gen(function* () { + collected.push(event) + if (event.type === "finish" || event.type === "provider-error") { + yield* log(level, "LLM response", { model, response: formatEvents(collected) }) + } + return event + }), + ), + ) +} + +export * as MessageLogger from "./message-logger" diff --git a/packages/llm/test/message-logger.test.ts b/packages/llm/test/message-logger.test.ts new file mode 100644 index 000000000000..c7b892da4dea --- /dev/null +++ b/packages/llm/test/message-logger.test.ts @@ -0,0 +1,218 @@ +import { describe, expect, test } from "bun:test" +import { Effect, Layer, Logger, LogLevel, References } from "effect" +import { LLMClient, MessageLogger } from "../src/route" +import * as OpenAIChat from "../src/protocols/openai-chat" +import { LLM, Message, Model } from "../src" +import { dynamicResponse } from "./lib/http" +import { deltaChunk, finishChunk } from "./lib/openai-chunks" +import { sseRaw } from "./lib/sse" +import { it } from "./lib/effect" + +const chatRoute = OpenAIChat.route.with({ endpoint: { baseURL: "https://api.openai.test/v1" } }) +const model = Model.make({ id: "gpt-4o-mini", provider: "openai", route: chatRoute }) + +type LogEntry = { readonly level: LogLevel.LogLevel; readonly message: unknown } +type LabeledEntry = { readonly level: LogLevel.LogLevel; readonly payload: Record } + +const captureLogs = (entries: Array) => + Logger.make((options) => { + entries.push({ level: options.logLevel, message: options.message }) + }) + +const labeled = (entries: Array, label: string): Array => + entries + .filter((entry) => Array.isArray(entry.message) && entry.message[0] === label) + .map((entry) => ({ level: entry.level, payload: (entry.message as Array)[1] as Record })) + +describe("MessageLogger", () => { + describe("formatMessages", () => { + test("formats system and user messages", () => { + const request = LLM.request({ + model, + system: "You are helpful.", + prompt: "Say hello.", + }) + const formatted = MessageLogger.formatMessages(request) + expect(formatted).toContain("system: You are helpful.") + expect(formatted).toContain("user: Say hello.") + }) + + test("formats messages with tool calls and results", () => { + const request = LLM.request({ + model, + messages: [ + Message.user("Check weather"), + Message.assistant([{ type: "tool-call", id: "call_1", name: "get_weather", input: { city: "Tokyo" } }]), + Message.tool({ id: "call_1", name: "get_weather", result: { temperature: 72 } }), + ], + }) + const formatted = MessageLogger.formatMessages(request) + expect(formatted).toContain('tool-call(get_weather): {"city":"Tokyo"}') + expect(formatted).toContain('tool-result(get_weather): {"type":"json","value":{"temperature":72}}') + }) + }) + + describe("formatEvents", () => { + test("formats text deltas and usage on separate lines", () => { + const formatted = MessageLogger.formatEvents([ + { type: "text-delta", id: "text-0", text: "Hello" }, + { type: "text-delta", id: "text-0", text: " world" }, + { type: "finish", reason: "stop", usage: { inputTokens: 10, outputTokens: 5, visibleOutputTokens: 3 } }, + ]) + expect(formatted).toBe('Hello world\nusage: {"inputTokens":10,"outputTokens":5,"visibleOutputTokens":3}') + }) + + test("accumulates reasoning deltas under a single prefix", () => { + const formatted = MessageLogger.formatEvents([ + { type: "reasoning-delta", id: "reason-0", text: "thinking" }, + { type: "reasoning-delta", id: "reason-0", text: " step" }, + { type: "text-delta", id: "text-0", text: "Answer" }, + ]) + expect(formatted).toBe("[reasoning]: thinking step\nAnswer") + }) + + test("separates deltas, tool events and usage with newlines", () => { + const formatted = MessageLogger.formatEvents([ + { type: "text-delta", id: "text-0", text: "Hello" }, + { type: "tool-call", id: "call_1", name: "lookup", input: { query: "weather" } }, + { type: "finish", reason: "stop" }, + ]) + expect(formatted).toBe('Hello\ntool-call(lookup): {"query":"weather"}') + }) + }) + + describe("LLMClient integration", () => { + const helloResponse = sseRaw( + `data: ${JSON.stringify(deltaChunk({ role: "assistant", content: "Hello" }))}`, + `data: ${JSON.stringify(finishChunk("stop"))}`, + ) + const streamedResponse = sseRaw( + `data: ${JSON.stringify(deltaChunk({ role: "assistant", content: "Hello" }))}`, + `data: ${JSON.stringify(deltaChunk({ role: "assistant", content: " world" }))}`, + `data: ${JSON.stringify(finishChunk("stop"))}`, + ) + + it.effect("does not log when metadata.logMessages is not set", () => + Effect.gen(function* () { + const entries: Array = [] + const result = yield* LLMClient.generate(LLM.request({ model, prompt: "Say hello." })).pipe( + Effect.provide( + Layer.mergeAll( + dynamicResponse((input) => Effect.succeed(input.respond(helloResponse))), + Logger.layer([captureLogs(entries)]), + ), + ), + ) + expect(result.text).toBe("Hello") + expect(labeled(entries, "LLM request")).toEqual([]) + expect(labeled(entries, "LLM response")).toEqual([]) + }), + ) + + it.effect("logs the request and response once each at info", () => + Effect.gen(function* () { + const entries: Array = [] + const result = yield* LLMClient.generate( + LLM.request({ model, prompt: "Say hello.", metadata: { logMessages: "info" } }), + ).pipe( + Effect.provide( + Layer.mergeAll( + dynamicResponse((input) => Effect.succeed(input.respond(helloResponse))), + Logger.layer([captureLogs(entries)]), + ), + ), + ) + expect(result.text).toBe("Hello") + const requests = labeled(entries, "LLM request") + expect(requests).toHaveLength(1) + expect(requests[0].level).toBe("Info") + expect(requests[0].payload).toMatchObject({ + model: "openai/gpt-4o-mini", + messages: expect.stringContaining("user: Say hello."), + }) + const responses = labeled(entries, "LLM response") + expect(responses).toHaveLength(1) + expect(responses[0].level).toBe("Info") + expect(responses[0].payload).toMatchObject({ model: "openai/gpt-4o-mini", response: "Hello" }) + }), + ) + + it.effect("logs a single coalesced response for streamed deltas", () => + Effect.gen(function* () { + const entries: Array = [] + const result = yield* LLMClient.generate( + LLM.request({ model, prompt: "Say hello.", metadata: { logMessages: "info" } }), + ).pipe( + Effect.provide( + Layer.mergeAll( + dynamicResponse((input) => Effect.succeed(input.respond(streamedResponse))), + Logger.layer([captureLogs(entries)]), + ), + ), + ) + expect(result.text).toBe("Hello world") + const responses = labeled(entries, "LLM response") + expect(responses).toHaveLength(1) + expect(responses[0].payload).toMatchObject({ model: "openai/gpt-4o-mini", response: "Hello world" }) + }), + ) + + it.effect("logs generation params at debug level", () => + Effect.gen(function* () { + const entries: Array = [] + const result = yield* LLMClient.generate( + LLM.request({ + model, + prompt: "Say hello.", + generation: { temperature: 0.3 }, + metadata: { logMessages: "debug" }, + }), + ).pipe( + Effect.provide( + Layer.mergeAll( + dynamicResponse((input) => Effect.succeed(input.respond(helloResponse))), + Logger.layer([captureLogs(entries)]), + Layer.succeed(References.MinimumLogLevel, "Trace"), + ), + ), + ) + expect(result.text).toBe("Hello") + const requests = labeled(entries, "LLM request") + expect(requests).toHaveLength(1) + expect(requests[0].level).toBe("Debug") + expect(requests[0].payload).toMatchObject({ + model: "openai/gpt-4o-mini", + generation: expect.objectContaining({ temperature: 0.3 }), + }) + }), + ) + + it.effect("logs the raw request body at trace level", () => + Effect.gen(function* () { + const entries: Array = [] + const result = yield* LLMClient.generate( + LLM.request({ model, prompt: "Say hello.", metadata: { logMessages: "trace" } }), + ).pipe( + Effect.provide( + Layer.mergeAll( + dynamicResponse((input) => Effect.succeed(input.respond(helloResponse))), + Logger.layer([captureLogs(entries)]), + Layer.succeed(References.MinimumLogLevel, "Trace"), + ), + ), + ) + expect(result.text).toBe("Hello") + const requests = labeled(entries, "LLM request") + expect(requests).toHaveLength(1) + expect(requests[0].level).toBe("Trace") + expect(requests[0].payload).toMatchObject({ model: "openai/gpt-4o-mini" }) + expect(typeof requests[0].payload.body).toBe("string") + expect(requests[0].payload.body).toContain('"messages"') + const responses = labeled(entries, "LLM response") + expect(responses).toHaveLength(1) + expect(responses[0].level).toBe("Trace") + expect(responses[0].payload).toMatchObject({ response: "Hello" }) + }), + ) + }) +}) diff --git a/packages/opencode/src/session/llm.ts b/packages/opencode/src/session/llm.ts index a99f8acff20c..0876d46a6626 100644 --- a/packages/opencode/src/session/llm.ts +++ b/packages/opencode/src/session/llm.ts @@ -8,7 +8,7 @@ import { Context, Effect, Layer } from "effect" import * as Stream from "effect/Stream" import { streamText, wrapLanguageModel, type ModelMessage, type Tool } from "ai" import type { LLMEvent } from "@opencode-ai/llm" -import { LLMClient } from "@opencode-ai/llm/route" +import { LLMClient, MessageLogger, RequestExecutor, WebSocketExecutor } from "@opencode-ai/llm/route" import type { LLMClientService } from "@opencode-ai/llm/route" import { GitLabWorkflowLanguageModel } from "gitlab-ai-provider" import { ProviderTransform } from "@/provider/transform" @@ -239,6 +239,7 @@ const live: Layer.Layer< providerOptions: prepared.params.options, headers: prepared.headers, abort: input.abort, + logMessages: cfg.experimental?.log_messages, }) if (native.type === "supported") { yield* Effect.logInfo("llm runtime selected", { @@ -268,6 +269,39 @@ const live: Layer.Layer< }) } + const logMessages = cfg.experimental?.log_messages + if (logMessages) { + // The AI SDK runtime has no access to the provider-native request body, + // so "trace" carries the same payload as "debug" on this path. + const model = `${input.model.providerID}/${input.model.id}` + const texts: Array = [] + for (const s of prepared.system) texts.push(`system: ${s}`) + for (const m of prepared.messages) { + const content = + typeof m.content === "string" + ? m.content + : (m.content + ?.map((p) => + p.type === "text" + ? p.text + : p.type === "tool-call" + ? `tool-call(${p.toolName}): ${JSON.stringify(p.input)}` + : p.type === "tool-result" + ? `tool-result(${p.toolName}): ${JSON.stringify(p.output)}` + : `[${p.type}]`, + ) + .join("\n") ?? "") + texts.push(`${m.role}: ${content}`) + } + const payload: Record = { model, messages: texts.join("\n") } + if (logMessages !== "info") { + payload.generation = Object.fromEntries( + Object.entries(prepared.params).filter(([, v]) => v !== undefined) as Array<[string, unknown]>, + ) + } + yield* MessageLogger.log(logMessages, "LLM request", payload) + } + yield* Effect.logInfo("llm runtime selected", { "llm.runtime": "ai-sdk", "llm.provider": input.model.providerID, @@ -277,6 +311,7 @@ const live: Layer.Layer< // LLMAISDK.toLLMEvents below normalizes fullStream parts for the processor. return { type: "ai-sdk" as const, + logMessages, result: streamText({ onError(error) { bridge.fork( @@ -370,12 +405,17 @@ const live: Layer.Layer< // Adapter seam: both runtimes expose the same LLMEvent stream. Native // already returns one; AI SDK streams are converted here. const state = LLMAISDK.adapterState() - return Stream.fromAsyncIterable(result.result.fullStream, (e) => + const model = `${input.model.providerID}/${input.model.id}` + let events = Stream.fromAsyncIterable(result.result.fullStream, (e) => e instanceof Error ? e : new Error(String(e)), ).pipe( Stream.mapEffect((event) => LLMAISDK.toLLMEvents(state, event)), Stream.flatMap((events) => Stream.fromIterable(events)), ) + if (result.logMessages) { + events = MessageLogger.responseStream(model, result.logMessages)(events) + } + return events }), ), ) diff --git a/packages/opencode/src/session/llm/native-runtime.ts b/packages/opencode/src/session/llm/native-runtime.ts index bac385c59137..5512d5f98f60 100644 --- a/packages/opencode/src/session/llm/native-runtime.ts +++ b/packages/opencode/src/session/llm/native-runtime.ts @@ -16,7 +16,7 @@ import { type JsonSchema, type LLMEvent, } from "@opencode-ai/llm" -import type { LLMClientShape } from "@opencode-ai/llm/route" +import type { LLMClientShape, LogLevel } from "@opencode-ai/llm/route" import { LLMNative } from "./native-request" export type RuntimeStatus = @@ -41,6 +41,7 @@ type StreamInput = { readonly providerOptions?: Record readonly headers: Record readonly abort: AbortSignal + readonly logMessages?: LogLevel } export function status(input: Pick): RuntimeStatus { @@ -109,6 +110,7 @@ export function stream(input: StreamInput): StreamResult { .stream( LLMRequest.update(request, { tools: [...request.tools, ...toDefinitions(tools)], + metadata: input.logMessages ? { ...request.metadata, logMessages: input.logMessages } : request.metadata, }), ) .pipe(