From 1a3e1321d6ad37602aad379ba7816ca876f6bb7c Mon Sep 17 00:00:00 2001 From: bornmw Date: Mon, 17 Aug 2026 23:40:56 -0400 Subject: [PATCH 1/2] feat(llm): add configurable message logging --- packages/core/src/v1/config/config.ts | 6 ++ packages/llm/src/route/client.ts | 31 +++++-- packages/llm/src/route/index.ts | 1 + packages/llm/src/route/message-logger.ts | 65 +++++++++++++ packages/llm/test/message-logger.test.ts | 91 +++++++++++++++++++ packages/opencode/src/session/llm.ts | 38 +++++++- .../src/session/llm/native-runtime.ts | 2 + 7 files changed, 226 insertions(+), 8 deletions(-) create mode 100644 packages/llm/src/route/message-logger.ts create mode 100644 packages/llm/test/message-logger.test.ts diff --git a/packages/core/src/v1/config/config.ts b/packages/core/src/v1/config/config.ts index 7ebb4b69b023..4fe46f72c7ae 100644 --- a/packages/core/src/v1/config/config.ts +++ b/packages/core/src/v1/config/config.ts @@ -173,6 +173,12 @@ 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: + "'info' logs messages and response text; 'debug' adds generation params; 'trace' adds the raw provider-native request body", + }), 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..5c448950e78c 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 { logEvents as logResponseEvents, logRequest as logOutgoingRequest } 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* logOutgoingRequest(request, logMessages as LogLevel, body) + } + return { request: resolved, route, body, prepared, + logMessages, } }) @@ -375,19 +383,30 @@ 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 events.pipe( + Stream.tap((event) => logResponseEvents(request, [event], logMessages)), + ) }), ) const generateWith = (stream: Interface["stream"]) => Effect.fn("LLM.generate")(function* (request: LLMRequest) { + const logMessages = request.metadata?.logMessages as LogLevel | undefined 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", + ) + } + if (logMessages) { + yield* logResponseEvents(request, response.events, logMessages) + } + 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..773495aa9ebe 100644 --- a/packages/llm/src/route/index.ts +++ b/packages/llm/src/route/index.ts @@ -10,6 +10,7 @@ export type { Service as LLMClientService, } from "./client" export * from "./executor" +export { MessageLogger } 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..4545118b87c1 --- /dev/null +++ b/packages/llm/src/route/message-logger.ts @@ -0,0 +1,65 @@ +import { Effect } 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 texts: Array = [] + for (const event of events) { + if (event.type === "text-delta") texts.push(event.text) + if (event.type === "reasoning-delta") texts.push(`[reasoning]: ${event.text}`) + if (event.type === "tool-call") texts.push(`tool-call(${event.name}): ${JSON.stringify(event.input)}`) + if (event.type === "tool-result") texts.push(`tool-result(${event.name}): ${JSON.stringify(event.result)}`) + if (event.type === "finish" && event.usage) { + texts.push(`usage: ${JSON.stringify(event.usage)}`) + } + } + return texts.join("") +} + +const logAtLevel = (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.logDebug(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 logAtLevel(level, "LLM request", payload) +} + +export const logEvents = (request: LLMRequest, events: ReadonlyArray, level: LogLevel): Effect.Effect => + logAtLevel(level, "LLM response", { + model: `${request.model.provider}/${request.model.id}`, + response: formatEvents(events), + }) + +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..6cba777fe1dd --- /dev/null +++ b/packages/llm/test/message-logger.test.ts @@ -0,0 +1,91 @@ +import { describe, expect, test } from "bun:test" +import { Effect, Layer, Logger, LogLevel } from "effect" +import { LLMClient, MessageLogger } from "../src/route" +import * as OpenAIChat from "../src/protocols/openai-chat" +import { LLM, LLMRequest, 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 }) + +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", () => { + 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 worldusage: {\"inputTokens\":10,\"outputTokens\":5,\"visibleOutputTokens\":3}") + }) + + test("formats reasoning deltas", () => { + const formatted = MessageLogger.formatEvents([ + { type: "reasoning-delta", id: "reason-0", text: "thinking step" }, + ]) + expect(formatted).toContain("[reasoning]: thinking step") + }) + + test("formats tool call events", () => { + const formatted = MessageLogger.formatEvents([ + { type: "tool-call", id: "call_1", name: "lookup", input: { query: "weather" } }, + ]) + expect(formatted).toContain('tool-call(lookup): {"query":"weather"}') + }) + }) + + describe("LLMClient integration", () => { + const helloResponse = sseRaw( + `data: ${JSON.stringify(deltaChunk({ role: "assistant", content: "Hello" }))}`, + `data: ${JSON.stringify(finishChunk("stop"))}`, + ) + + it.effect("does not log when metadata.logMessages is not set", () => + Effect.gen(function* () { + const result = yield* LLMClient.generate(LLM.request({ model, prompt: "Say hello." })) + expect(result.text).toBe("Hello") + }).pipe(Effect.provide(dynamicResponse((input) => Effect.succeed(input.respond(helloResponse))))), + ) + + it.effect("logs request when metadata.logMessages is set to info", () => + Effect.gen(function* () { + const result = yield* LLMClient.generate( + LLM.request({ model, prompt: "Say hello.", metadata: { logMessages: "info" as const } }), + ) + expect(result.text).toBe("Hello") + }).pipe(Effect.provide(dynamicResponse((input) => Effect.succeed(input.respond(helloResponse))))), + ) + }) +}) diff --git a/packages/opencode/src/session/llm.ts b/packages/opencode/src/session/llm.ts index a99f8acff20c..0f8472978b99 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,26 @@ const live: Layer.Layer< }) } + const logMessages = cfg.experimental?.log_messages as MessageLogger.LogLevel | undefined + if (logMessages) { + 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}]`)).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* Effect.logInfo("LLM request", payload) + } + yield* Effect.logInfo("llm runtime selected", { "llm.runtime": "ai-sdk", "llm.provider": input.model.providerID, @@ -277,6 +298,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 +392,24 @@ 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 = events.pipe( + Stream.tap((event) => + Effect.logInfo("LLM response", { + model, + response: MessageLogger.formatEvents([event]), + }), + ), + ) + } + return events }), ), ) diff --git a/packages/opencode/src/session/llm/native-runtime.ts b/packages/opencode/src/session/llm/native-runtime.ts index bac385c59137..918e2dbdc313 100644 --- a/packages/opencode/src/session/llm/native-runtime.ts +++ b/packages/opencode/src/session/llm/native-runtime.ts @@ -41,6 +41,7 @@ type StreamInput = { readonly providerOptions?: Record readonly headers: Record readonly abort: AbortSignal + readonly logMessages?: string } 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( From f0b62b095c8474881fb145eff40305a464d7cf20 Mon Sep 17 00:00:00 2001 From: omikheev Date: Fri, 21 Aug 2026 20:33:44 -0400 Subject: [PATCH 2/2] fix(llm): coalesce message logger output and honor log levels --- packages/core/src/observability/logging.ts | 1 + packages/core/src/v1/config/config.ts | 6 +- packages/llm/src/route/client.ts | 14 +- packages/llm/src/route/index.ts | 1 + packages/llm/src/route/message-logger.ts | 87 ++++++++-- packages/llm/test/message-logger.test.ts | 161 ++++++++++++++++-- packages/opencode/src/session/llm.ts | 32 ++-- .../src/session/llm/native-runtime.ts | 4 +- 8 files changed, 247 insertions(+), 59 deletions(-) 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 4fe46f72c7ae..4e49674c4fdd 100644 --- a/packages/core/src/v1/config/config.ts +++ b/packages/core/src/v1/config/config.ts @@ -173,11 +173,9 @@ 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({ + log_messages: Schema.optional(Schema.Literals(["info", "debug", "trace"])).annotate({ description: - "'info' logs messages and response text; 'debug' adds generation params; 'trace' adds the raw provider-native request body", + "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 5c448950e78c..ed9d4340774b 100644 --- a/packages/llm/src/route/client.ts +++ b/packages/llm/src/route/client.ts @@ -8,7 +8,7 @@ import { HttpTransport } from "./transport" import type { Transport, TransportRuntime } from "./transport" import { WebSocketExecutor } from "./transport" import type { Protocol } from "./protocol" -import { logEvents as logResponseEvents, logRequest as logOutgoingRequest } from "./message-logger" +import { logRequest, responseStream } from "./message-logger" import type { LogLevel } from "./message-logger" import { applyCachePolicy } from "../cache-policy" import * as ProviderShared from "../protocols/shared" @@ -354,7 +354,7 @@ const compile = Effect.fn("LLM.compile")(function* (request: LLMRequest) { const logMessages = request.metadata?.logMessages if (logMessages) { - yield* logOutgoingRequest(request, logMessages as LogLevel, body) + yield* logRequest(request, logMessages as LogLevel, body) } return { @@ -386,15 +386,14 @@ const streamRequestWith = (runtime: TransportRuntime) => (request: LLMRequest) = const events = compiled.route.streamPrepared(compiled.prepared, compiled.request, runtime) const logMessages = request.metadata?.logMessages as LogLevel | undefined if (!logMessages) return events - return events.pipe( - Stream.tap((event) => logResponseEvents(request, [event], logMessages)), - ) + return responseStream(`${request.model.provider}/${request.model.id}`, logMessages)(events) }), ) const generateWith = (stream: Interface["stream"]) => Effect.fn("LLM.generate")(function* (request: LLMRequest) { - const logMessages = request.metadata?.logMessages as LogLevel | undefined + // 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) { @@ -403,9 +402,6 @@ const generateWith = (stream: Interface["stream"]) => "Provider stream ended without a terminal finish event", ) } - if (logMessages) { - yield* logResponseEvents(request, response.events, logMessages) - } return response }) diff --git a/packages/llm/src/route/index.ts b/packages/llm/src/route/index.ts index 773495aa9ebe..e321ffc32edb 100644 --- a/packages/llm/src/route/index.ts +++ b/packages/llm/src/route/index.ts @@ -11,6 +11,7 @@ export type { } 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 index 4545118b87c1..92c95b203ff4 100644 --- a/packages/llm/src/route/message-logger.ts +++ b/packages/llm/src/route/message-logger.ts @@ -1,4 +1,4 @@ -import { Effect } from "effect" +import { Effect, Stream } from "effect" import type { LLMEvent, LLMRequest } from "../schema" export type LogLevel = "info" | "debug" | "trace" @@ -21,24 +21,64 @@ export const formatMessages = (request: LLMRequest): string => { } export const formatEvents = (events: ReadonlyArray): string => { - const texts: Array = [] + 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") texts.push(event.text) - if (event.type === "reasoning-delta") texts.push(`[reasoning]: ${event.text}`) - if (event.type === "tool-call") texts.push(`tool-call(${event.name}): ${JSON.stringify(event.input)}`) - if (event.type === "tool-result") texts.push(`tool-result(${event.name}): ${JSON.stringify(event.result)}`) + 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) { - texts.push(`usage: ${JSON.stringify(event.usage)}`) + flush() + segments.push(`usage: ${JSON.stringify(event.usage)}`) } } - return texts.join("") + flush() + return segments.join("\n") } -const logAtLevel = (level: LogLevel, label: string, data: Record): Effect.Effect => { +// 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.logDebug(label, data) + case "info": + return Effect.logInfo(label, data) + case "debug": + return Effect.logDebug(label, data) + case "trace": + return Effect.logTrace(label, data) } } @@ -53,13 +93,32 @@ export const logRequest = (request: LLMRequest, level: LogLevel, body?: unknown) if (level === "trace" && body !== undefined) { payload.body = JSON.stringify(body) } - return logAtLevel(level, "LLM request", payload) + return log(level, "LLM request", payload) } export const logEvents = (request: LLMRequest, events: ReadonlyArray, level: LogLevel): Effect.Effect => - logAtLevel(level, "LLM response", { + 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 index 6cba777fe1dd..c7b892da4dea 100644 --- a/packages/llm/test/message-logger.test.ts +++ b/packages/llm/test/message-logger.test.ts @@ -1,8 +1,8 @@ import { describe, expect, test } from "bun:test" -import { Effect, Layer, Logger, LogLevel } from "effect" +import { Effect, Layer, Logger, LogLevel, References } from "effect" import { LLMClient, MessageLogger } from "../src/route" import * as OpenAIChat from "../src/protocols/openai-chat" -import { LLM, LLMRequest, Message, Model } from "../src" +import { LLM, Message, Model } from "../src" import { dynamicResponse } from "./lib/http" import { deltaChunk, finishChunk } from "./lib/openai-chunks" import { sseRaw } from "./lib/sse" @@ -11,6 +11,19 @@ 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", () => { @@ -29,9 +42,7 @@ describe("MessageLogger", () => { model, messages: [ Message.user("Check weather"), - Message.assistant([ - { type: "tool-call", id: "call_1", name: "get_weather", input: { city: "Tokyo" } }, - ]), + 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 } }), ], }) @@ -42,27 +53,31 @@ describe("MessageLogger", () => { }) describe("formatEvents", () => { - test("formats text deltas and usage", () => { + 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 worldusage: {\"inputTokens\":10,\"outputTokens\":5,\"visibleOutputTokens\":3}") + expect(formatted).toBe('Hello world\nusage: {"inputTokens":10,"outputTokens":5,"visibleOutputTokens":3}') }) - test("formats reasoning deltas", () => { + test("accumulates reasoning deltas under a single prefix", () => { const formatted = MessageLogger.formatEvents([ - { type: "reasoning-delta", id: "reason-0", text: "thinking step" }, + { 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).toContain("[reasoning]: thinking step") + expect(formatted).toBe("[reasoning]: thinking step\nAnswer") }) - test("formats tool call events", () => { + 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).toContain('tool-call(lookup): {"query":"weather"}') + expect(formatted).toBe('Hello\ntool-call(lookup): {"query":"weather"}') }) }) @@ -71,21 +86,133 @@ describe("MessageLogger", () => { `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 result = yield* LLMClient.generate(LLM.request({ model, prompt: "Say hello." })) + 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") - }).pipe(Effect.provide(dynamicResponse((input) => Effect.succeed(input.respond(helloResponse))))), + 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 request when metadata.logMessages is set to info", () => + 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: "info" as const } }), + 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") - }).pipe(Effect.provide(dynamicResponse((input) => Effect.succeed(input.respond(helloResponse))))), + 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 0f8472978b99..0876d46a6626 100644 --- a/packages/opencode/src/session/llm.ts +++ b/packages/opencode/src/session/llm.ts @@ -269,15 +269,28 @@ const live: Layer.Layer< }) } - const logMessages = cfg.experimental?.log_messages as MessageLogger.LogLevel | undefined + 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}]`)).join("\n") ?? "" + 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") } @@ -286,7 +299,7 @@ const live: Layer.Layer< Object.entries(prepared.params).filter(([, v]) => v !== undefined) as Array<[string, unknown]>, ) } - yield* Effect.logInfo("LLM request", payload) + yield* MessageLogger.log(logMessages, "LLM request", payload) } yield* Effect.logInfo("llm runtime selected", { @@ -400,14 +413,7 @@ const live: Layer.Layer< Stream.flatMap((events) => Stream.fromIterable(events)), ) if (result.logMessages) { - events = events.pipe( - Stream.tap((event) => - Effect.logInfo("LLM response", { - model, - response: MessageLogger.formatEvents([event]), - }), - ), - ) + 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 918e2dbdc313..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,7 +41,7 @@ type StreamInput = { readonly providerOptions?: Record readonly headers: Record readonly abort: AbortSignal - readonly logMessages?: string + readonly logMessages?: LogLevel } export function status(input: Pick): RuntimeStatus {