Skip to content

feat(opencode): Message logger - #43165

Open
bornmw wants to merge 9 commits into
anomalyco:devfrom
bornmw:message-logger
Open

bornmw wants to merge 9 commits into
anomalyco:devfrom
bornmw:message-logger

Conversation

@bornmw

@bornmw bornmw commented Aug 18, 2026

Copy link
Copy Markdown

Issue for this PR

Closes #29186

Type of change

  • Bug fix
  • New feature
  • Refactor / code improvement
  • Documentation

What does this PR do?

Adds configurable LLM request/response logging via experimental.log_messages ("info", "debug", "trace") and wires it into both the native and AI SDK runtimes.

  • "info" — logs messages + response text (Effect info level)
  • "debug" — adds generation params (Effect debug level)
  • "trace" — adds the raw provider-native request body (native runtime only) at Effect trace level; requires OPENCODE_LOG_LEVEL=DEBUG or TRACE to be visible

Responses are coalesced: one LLM response entry per provider turn (emitted when the terminal event passes), not one per streamed delta — on both runtimes. Requests are logged once per call in both runtimes.

Notes:

  • The AI SDK runtime never sees the provider-native wire body (the AI SDK builds it internally), so on that path "trace" carries the same payload as "debug".
  • Logs can contain full transcripts (prompts, tool I/O) — the config option now says to treat log destinations as sensitive.
  • Adds TRACE as a valid OPENCODE_LOG_LEVEL value (needed for the trace tier to be reachable; the runtime's minimum level previously capped at DEBUG).

Also fixes a crash on --continue where a "dummy" session ID placeholder triggered a server-side validation error — the fake route was removed and the App component's existing --continue effect handles navigation once sync loads.

How did you verify your code works?

  • Typecheck passes (llm, opencode, core)
  • Built and tested locally with OPENCODE_LOG_LEVEL=DEBUG/TRACE — one LLM request and one coalesced LLM response entry per turn at all three verbosity levels, distinguishable by log level
  • --continue no longer shows the "ses" validation error
  • New tests assert the logged level, payload, once-per-response emission, coalesced text, and the trace-level raw body

Checklist

  • I have tested my changes locally
  • I have not included unrelated changes in this PR

If you do not follow this template your PR will be automatically rejected.

@github-actions github-actions Bot added needs:compliance This means the issue will auto-close after 2 hours. and removed needs:compliance This means the issue will auto-close after 2 hours. labels Aug 18, 2026
@github-actions

Copy link
Copy Markdown
Contributor

Thanks for updating your PR! It now meets our contributing guidelines. 👍

@github-actions github-actions Bot added the needs:compliance This means the issue will auto-close after 2 hours. label Aug 18, 2026
@github-actions github-actions Bot removed the needs:compliance This means the issue will auto-close after 2 hours. label Aug 18, 2026
@github-actions

Copy link
Copy Markdown
Contributor

Thanks for updating your PR! It now meets our contributing guidelines. 👍

@Enough1122

Copy link
Copy Markdown

AI code review — automated review for reference; please use your judgment.

  • packages/llm/src/route/client.ts:388 — With logMessages enabled, generate() double-logs every response: stream() already taps each event through logResponseEvents, and generateWith then logs the accumulated response.events again — every completion appears twice in logs; either drop the tap inside the stream used by generate, or remove the explicit post-hoc log and rely solely on the tap.
  • packages/llm/src/route/client.ts:392 — Stream.tap fires logResponseEvents per event, meaning one log line per text/reasoning delta — a single streamed answer produces hundreds of fragmented "LLM response" entries and measurable overhead on the hot path; buffer deltas and emit once at finish (or coalesce on a timer) before this ships as an opt-in default users will actually enable.
  • packages/opencode/src/session/llm.ts:272 — The AI-SDK runtime path re-implements request/response logging inline with a different format and IGNORES the level contract: it always Effect.logInfo, never emits the raw provider body promised for "trace", and duplicates MessageLogger.formatMessages poorly (tool parts collapse to "[tool-call]" placeholders) — route both runtimes through MessageLogger so config semantics stay identical regardless of runtime.
  • packages/llm/test/message-logger.test.ts:85 — Neither integration test observes actual log output; the "logs request when set to info" case only asserts result.text, so a regression that silently disables logging would pass green — install a test logger (Logger.replace / Logger.test) and assert the emitted level plus payload contains "LLM request"/"LLM response".
  • packages/llm/src/route/message-logger.ts:31 — trace falls back to logDebug although Effect provides a distinct Trace level (Effect.logTrace), losing the intended three-tier separation; also formatEvents joins with "" so usage concatenates directly onto text ("Hello worldusage: ...") — use "\n" between segments.

— AI code review (automated)

@Enough1122

Copy link
Copy Markdown

AI code review — automated review for reference; please use your judgment.

  • packages/llm/src/route/client.ts:386 (generateWith) — likely double logging: stream(request) already taps every event via streamRequestWith, then the folded response's full event list is logged again via logResponseEvents. On the generate path, each response will appear twice (once as deltas, once aggregated). Consider skipping the post-hoc log when the underlying stream was already tapped, or only tapping in one place.
  • packages/llm/src/route/message-logger.ts:44 (logAtLevel) — "trace" maps to Effect.logDebug, identical to debug; if the runtime log filter excludes debug, enabling trace silently yields nothing. Worth a comment (or a distinct mechanism) since users will expect trace > debug verbosity.
  • packages/opencode/src/session/llm.ts:272 — AI-SDK fallback path ignores the configured level: always Effect.logInfo, never emits the trace-time raw body, and duplicates formatting logic that MessageLogger.formatMessages nearly covers. At minimum note that debug/trace only fully apply to the native runtime.
  • packages/llm/test/message-logger.test.ts:74 — the integration test named "logs request when metadata.logMessages is set to info" doesn't assert any log output; without a Logger assertion it passes even if logging regresses completely. Consider capturing test loggers (Logger.replace/test layer) and asserting a "LLM request" entry exists.
  • Privacy note: info already logs full message text including tool results — fine for an experimental opt-in flag, but the config description should maybe warn about sensitive transcript content ending up in logs.

@bornmw

bornmw commented Aug 22, 2026

Copy link
Copy Markdown
Author

Thanks — both reviews were helpful. Addressed in f0b62b095 (fix(llm): coalesce message logger output and honor log levels) with a few deliberate deviations noted below.

1. Double logging in generate() — fixed. Dropped the post-fold log in generateWith; the response is now logged exactly once when the terminal event passes the stream pipeline, which also covers stream() consumers (the session's native runtime). Verified by test: exactly one LLM request and one LLM response entry per generate() call.

2. Per-event fragmentation — fixed, with a twist: the AI SDK path had the same bug. packages/opencode/src/session/llm.ts:~415 had an identical per-event Stream.tap (always at logInfo, one entry per delta) that neither review flagged. Both paths now use a new MessageLogger.responseStream(model, level) combinator: deltas accumulate and a single coalesced LLM response entry is emitted when the terminal event (finish or provider-error) passes through. I chose terminal-triggered emission over timer coalescing: it's exact (one entry per response, no tail loss, no cross-turn attribution) and non-terminal events pay only for an array push.

3. AI SDK path through MessageLogger — addressed as far as the data shapes allow:

  • The AI SDK request log now uses the same MessageLogger.log(level, label, payload) dispatcher (no more hard-coded Effect.logInfo) and the response log the same responseStream coalescing, over the LLMEvent stream the AI SDK parts are converted to via toLLMEvents — identical labels, payload shapes, and level semantics on both runtimes.
  • Tool parts no longer collapse to [tool-call] placeholders: tool-call(name): JSON(input) / tool-result(name): JSON(output).
  • Where I'm pushing back: the raw provider body for trace is not obtainable on the AI SDK path — the AI SDK constructs the wire body internally and opencode never sees it (the Copilot includeRawChunks is a different, provider-specific thing). So on that runtime tracedebug content, now documented in a comment at the site and in the config description. Similarly formatMessages itself can't be shared there: the AI SDK path formats ModelMessage[], a different data shape from LLMRequest content parts, and there is no LLMRequest on that path to build one from.

4. Tests don't observe log output — fixed. The integration tests now install a capture logger (Logger.make sink + Logger.layer) and assert the emitted level, payload shape, exactly-once emission, coalesced delta text, generation params at debug, and the raw body at trace.

5. tracelogDebug — fixed with one extra finding. Tracing now maps to Effect.logTrace. But the runtime gap the second review suspected was real and worse than described: minimumLogLevel() in packages/core/src/observability/logging.ts had no TRACE env mapping (capped at DEBUG), and Effect's filter drops entries less severe than the minimum — so logTrace output would have been invisible even at OPENCODE_LOG_LEVEL=DEBUG. Added TRACE to the env map; the config description now states the level requirements explicitly.

6. formatEvents join — fixed, not the literal \n between segments. Straight \n-joining would corrupt the response text, because text/reasoning deltas are fragments of one text ("Hello" + " world""Hello\n world"). It now accumulates consecutive deltas of the same kind (joined with "") and separates distinct segments (text, [reasoning]:, tool events, usage, error:) with \n — so usage: no longer glues onto the text and interleaved reasoning/text stays ordered. Unit-test expectation updated. One new behavior worth noting: provider-error terminal events now render as error: <message> in the response entry.

7. Privacy note — done. Config description now warns that logs can contain full transcripts including tool results.

Two small behavioral notes:

  • If a provider stream fails before any terminal event, the response entry is skipped (the request entry is still logged) — same as the pre-change generate() path.
  • The redundant as MessageLogger.LogLevel cast in session/llm.ts and the logMessages?: string type in native-runtime.ts are gone (config already resolves the literal union); LogLevel is now exported from the route barrel.

Verified: bun typecheck clean (llm, opencode, core); llm suite 308 pass / 0 fail; opencode session suite 419 tests pass / 0 fail; core observability + config tests pass; bunx prettier --check clean.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

[FEATURE]: Log LLM API request/response body at DEBUG log level

2 participants