Kimirock/metabase
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Bot 1729 eval tracing (#77169)

Browse Source 
* Add ai-tracing: eval-time trace capture for the Metabot agent

Introduce a new `ai-tracing` module that captures complete, per-run agent
traces during benchmark/eval runs and exports them to an external eval
backend (Confident AI) over OTLP — separate from production observability.

- Capture is gated by a per-run dynamic binding (`*capture*`), orthogonal to
  MB_TRACING_*, so it never fires on organic traffic. Enabled via the
  env-only MB_AI_EVAL_CAPTURE setting; the API path emits the trace as an
  `eval_trace` data part and exports it.
- Captures the full agent.turn -> llm.call -> tool.* tree with prompts,
  completions, tool args/results, durations, and concurrent-tool nesting
  (conveyed across the agent's virtual threads).
- OTLP export uses a dedicated TracerProvider (SimpleSpanProcessor +
  force-flush, never the production one), replaying the in-memory tree
  post-hoc. The domain -> Confident `confident.*` semconv mapping lives in a
  single chokepoint (`node->semconv-attrs`); vendor/schema swaps are one edit.
- Wires capture into run-agent-loop, loop-step, call-llm, and run-tool.
- Trace-level input/output (user question + final answer) set on the root.
- Export failures are logged loudly instead of swallowed.
- Tests cover the gate, nesting, enrichment, timing, concurrency, the
  semconv mapping, and a metadata-size regression guard.

* Make ai-tracing export more idiomatic; refresh stale docs

- export.clj: replace node->semconv-attrs's nested cond-> of repeated
  type checks + json/encode with :ai/keys destructuring and a flat
  medley/assoc-some table; compose final-llm-output as transducers;
  extract event->attributes; tidy parse-headers (for-comprehension),
  build-provider! (doto), and ensure-provider! (fresh? helper).
- core.clj: drop the stale "seam not wired" comment block and the
  outdated ns docstring (it referenced the abandoned gen_ai/OpenInference
  schema and "single namespace" framing); describe the shipped export.

No behavior change; 14 tests / 56 assertions still pass.

* Replace ai-tracing OTLP export with per-session JSONL log files

Switch the eval-trace collection method from OpenTelemetry/OTLP export to a
dedicated file-based logger, and extend instrumentation to the MCP server and
agent-api in addition to the Metabot agent loop.

- Rip out all OTLP/Confident code (export.clj, the OTLP settings, the OTel
  provider/semconv mapping, the eval_trace SSE part).
- New metabase.ai-tracing.log sink: each span streams one JSON line on a
  dedicated logger, routed per session to its own <session-id>.jsonl by a
  Log4j2 RoutingAppender keyed on mb-eval-session-id. Pure JSONL (%m%n), full
  payloads, no size limits.
- Session model = OTel trace-id analog: *session-id* minted at a fresh
  capture's root, or supplied by the caller, conveyed across virtual threads
  by bound-fn*. Nodes carry :id/:parent-id for tree reconstruction.
- Generic with-eval-session entrypoint (gated by MB_AI_EVAL_CAPTURE, inherits
  when nested) reused by run-agent-loop, MCP dispatch-request (keyed on the
  Mcp-Session-Id so a conversation lands in one file), and agent-api routes.
- MB_AI_EVAL_CAPTURE is the single on/off switch; the logger sits at info and
  writes nothing unless a capture is active.
- run-agent-loop emits a tiny eval_session SSE part so the HTTP harness can
  locate the session file.

Verified end-to-end: real agent run writes a per-session JSONL file with the
correct span tree (parent chain, full structured + normal tool output);
sessions route to separate files. 14 tests / 51 assertions pass.

* ai-tracing: capture full request/response context and add trace read API

Enrich eval spans so a captured trace is a self-contained record of a run:

- agent-api: record HTTP request body, user id, and the response status/body
  via a wrapping respond fn that fires inside the span.
- mcp: record JSON-RPC params, user id, scopes, and the materialized result.
- metabot agent: thread an optional eval-session-id through run-agent-loop so
  the harness can name and read back the per-session trace file; record the
  full request (messages/context/state), turn-level token usage, finish reason,
  and final agent state (link registry / generated entities). Surface the loop
  finish-reason out of loop-step instead of only logging it.
- log: guard span serialization so a non-encodable attribute can never break a
  traced run.

Add metabase.ai-tracing.api: a superuser-only GET /api/eval-trace/:session-id
that returns the captured JSONL, mounted only when MB_AI_EVAL_CAPTURE is on.
Filenames are validated against path traversal. Wire the module into routes and
the kondo module config.

* ai-tracing: preserve OpenAPI spec on agent-api routes; harden trace sink

The eval-tracing wrapper turned agent-api `routes` into a plain fn, which no
longer implemented OpenAPISpec — full-API spec generation (openapi.json,
endpoint-dox, the openapi-all-routes test) threw when the walk reached
/api/agent. Wrap it in `handler-with-open-api-spec`, delegating the spec to the
underlying ns-handler.

Also: narrow the trace-sink catch to Exception so Errors/InterruptedException
propagate; stream the trace file instead of slurping it into heap; and correct
the "single nil-check" docstring claim.

* ai-tracing: validate eval-session-id at mint time to prevent path traversal

The trace read endpoint sanitized the session-id before touching disk, but the
write path fed the raw, caller-supplied eval_session_id straight into the
RoutingAppender's `<session-id>.jsonl` file name — a value like `../../foo` on
an eval instance escaped the trace dir (arbitrary .jsonl write).

Hoist the safety regex to a single `safe-session-id-re` in ai-tracing.core and
add `checked-session-id`, which mints a uuid when none is supplied and throws on
an unsafe supplied id. `with-eval-session` now validates every caller-supplied
id before it can reach the log-file path; ai-tracing.api references the shared
regex so read/write validation can't drift.

* ai-tracing: gate span-macro arg construction on capture-active?

The span macros expanded to an eval-span* call, so span-name and attrs
were built on every invocation and discarded on the nil-check when no
capture was live. Hoist the capture-active? guard into a `spanning`
helper macro (and an inlined variant in with-tool-call, whose name
derives from attrs) so organic traffic never builds the span name string
or attrs map — it pays only the *capture* nil-check plus one thunk
closure. with-tool-call now evaluates attrs exactly once, and only when
capturing.

* ai-tracing: test cross-module span nesting; make agent tests capture-agnostic

Add eval-tracing-nesting-test: drives the real run-agent-loop under
capture-reducible with only the LLM + search backend mocked, and asserts
the emitted span tree nests agent.turn -> llm.call -> tool.search. This
covers the wiring the ai-tracing docstrings promise — the turn/llm spans
opened in metabot.agent.core, the tool span in metabot.self.core, and
*parent* conveyed across bound-fn* into the virtual-thread tool executor
— which the ai-tracing unit tests exercised only at the primitive level.

Also pin eval-capture off for the namespace via a fixture. run-agent-loop
appends an eval_session data part to the stream whenever capture is active,
so every exact-match assertion on its output broke under MB_AI_EVAL_CAPTURE
(which dedicated eval instances set). The fixture keeps those assertions on
the production stream shape; the new test forces capture independently.

* ai-tracing: key MCP eval session on UUID correlator; complete finish-reason

Key the MCP eval-trace session on the session id's UUID prefix rather than
the full <uuid>.<base64> id: the prefix is stable across the conversation and
always filesystem/URL-safe, so a base64 payload that require-valid-session
accepts but safe-session-id-re rejects (e.g. `=` padding) can no longer make
checked-session-id throw ahead of the JSON-RPC try/catch and 500 the request.

Record :finish-reason on the empty-response and reduced (early-termination)
loop terminations too, so the turn span's :ai/finish-reason is populated on
every path, not just natural completion.

* ai-tracing: harden trace sink serialization and error capture

- emit!: fall back to a JSON-safe copy when an attribute value isn't
  encodable, so one bad value no longer drops the span (and, for a root
  span, orphans its children).
- span error events now carry the exception class and ex-data, not just
  the message.
- rename JSONL :start-ns/:end-ns to :start-epoch-ns/:end-epoch-ns (they
  hold wall-clock epoch nanos, not System/nanoTime).
- test the api trace-file path-traversal guard directly.

* ai-tracing: bound session ids, gate user-input build, snapshot finish-node

- Cap supplied eval-session-id at 200 chars on the API schemas and in
  checked-session-id, so a supplied id can't produce a filename that fails
  creation and silently drops the trace (charset was already enforced).
- Compute the turn span's :ai/user-input inside the capture-gated attrs map
  instead of unconditionally on every run-agent-loop call.
- finish-node takes a single consistent snapshot of the node atom.

* ai-tracing: enforce session-id cap+charset at API boundaries

Route the 200-char cap through ait/max-session-id-length everywhere (read
endpoint, run-agent-loop opts, POST /api/metabot params) instead of
hardcoding the literal, and bound the previously-unbounded read-endpoint
:session-id path segment.

Validate the charset via safe-session-id-re in the Malli schemas so a bad
eval-session-id 400s at the boundary rather than throwing deep in
checked-session-id and surfacing as a generic agent error. Anchor
safe-session-id-re with \A/\z so it stays exact under both re-matches (mint/
read checks) and re-find (Malli :re) — unanchored, :re accepted any string
containing a safe run (e.g. ../../etc/passwd).

* ai-tracing: key MCP eval trace on a harness-supplied session id

Let an eval harness name and later fetch an MCP conversation's trace. The MCP
endpoint honors an `x-eval-session-id` header — `dispatch-request` keys
`with-eval-session` on it (validated through `checked-session-id`, the single
source of truth for the safe-id contract), falling back to the `Mcp-Session-Id`
correlator when absent. This is the MCP analogue of metabot's `eval_session_id`,
needed because the client owns the `Mcp-Session-Id` and never exposes it.

Also record the resolved query on the construct-query endpoints as `ai/query`
(inert unless capturing): the MCP `construct_query` tool returns only an opaque
handle, so this is the only place a harness can recover the agent's query off
the trace to grade it.

* ai-tracing: address review — guard :reduced append, cover the read API

- run-agent-loop: on a :reduced stop (client disconnect / cancellation) the
  reducing fn has already terminated, so don't step it again to append the
  eval-session pointer or debug part — that violates the transducer contract.
  Fold both trailing appends into one capture-gated cond-> that no-ops on
  :reduced (also fixes the latent debug-branch case). The harness reads the
  JSONL file, not the stream, so a skipped pointer on disconnect costs nothing.
- agent-api: record :http/user-id in the respond closure, where +auth has bound
  *current-user-id* — it is unbound when the span opens, so direct HTTP callers
  previously recorded nil.
- ai-tracing.api: add endpoint integration tests — capture-gated 404,
  superuser-gated 403, missing-trace 404, and existing-trace 200.
- log: mark node->entry ^:private; document that trace-file retention is the
  operator's responsibility (append-only, no rollover, re-runs accumulate).
- mcp: extract the dispatch lambda (line length) and note the fresh-file-per-
  request fallback when neither session id is present. Mark pure tests ^:parallel.

* ai-tracing: drop dead exports, document capture id, harden json-safe

- Remove the `sanitize-sql` re-export and `event!`: neither has a
  non-test caller. Dropping `sanitize-sql` also removes ai-tracing's only
  dependency on the `tracing` module (trimmed from `:uses`). The sites that
  put a query in a span record the raw value on purpose (a scorer wants the
  real SQL/MBQL), so the sanitizer was advertising an inconsistency the
  design doesn't want.
- Document that `capturing`/`capture-reducible` is return-value-based: a
  session id supplied to an inner `with-eval-session` is ignored because
  capture is already active, so no `<id>.jsonl` is written on that path.
- `json-safe` now stringifies non-scalar map keys too, so the fallback can
  never itself throw and orphan the root span it exists to save. Covered by
  a vector-keyed-map regression test.

* ai-tracing: address review — gate pointers, bound json-safe, drop indirection

Correctness:
- capturing/capture-reducible no longer mint a session id, so the in-process
  path is truly file-less (read :trace) instead of writing a stray <uuid>.jsonl
- gate the trailing eval_session pointer on a non-nil *session-id* so the
  file-less path doesn't emit a pointer to a <nil>.jsonl
- add *retain-tree* so the in-memory span tree is only built when a caller
  reads it back (capturing); the file-routed path no longer pins heap for the
  whole run
- depth-bound json-safe so a deep/cyclic attr degrades to a string instead of a
  StackOverflowError escaping emit!'s catch
- agent-api trace wrapper: only record a plain-data :http/response (skip a
  streaming/opaque body rather than stringifying it); fix the stale comment

Cleanup:
- drop the eval-capture-enabled? indirection; entrypoints and tests consult the
  ai-eval-capture setting directly
- with-eval-session: inline supplied-id, ^:once, generic 404 gate message
- extract mcp dispatch-method to de-nest the JSON-RPC case
- remove the dead ai-tracing.core/event! kondo entry
- keep eval JSONL spans out of the shared test log (log4j2-test.xml)

Tests: cover the agent-api trace wrapper, the file-less no-pointer/no-file
behaviour, and drive the log-sink assertions through with-eval-session.

* ai-tracing: fix route sort order and wire settings through init

Two structural test failures on the branch:

- Move the `/eval-trace` route into sorted position in the route-map
  (keep-routes-sorted-test reads the file and asserts the keys are sorted).
- Add `metabase.ai-tracing.init` (requiring the settings ns), require it from
  `metabase.core.init`, and add it to the module's `:api` — so
  settings-namespaces-should-be-required-by-init-namespaces-test passes and the
  `MB_AI_EVAL_CAPTURE` setting is registered deterministically at startup rather
  than only when some instrumented namespace happens to load `ai-tracing.core`.

* ai-tracing: store span wall-clock timestamps as epoch millis, not nanos

Review: the epoch fields were nanos synthesized from currentTimeMillis (ms-
granular anyway), and precise sub-ms duration already lives in :dur-ms — so nanos
bought nothing. Rename :start-epoch-nanos/:end-epoch-nanos → :start-epoch-ms/
:end-epoch-ms (and the JSONL keys :start-epoch-ns/:end-epoch-ns → :start-epoch-ms/
:end-epoch-ms). End is still start + the monotonic duration (rounded to ms), so it
never reads a second, possibly backward-jumping wall clock.
This commit is contained in:
Mihael Konjević
2026-07-14 17:30:50 +02:00
committed by GitHub
parent 85485ed925
commit 2ca895407f
23 changed files with 1326 additions and 107 deletions
Download Patch File Download Diff File Expand all files Collapse all files

1
.clj-kondo/config.edn
View File

@@ -179,6 +179,7 @@
clojure.core.async/take!
clojure.core.async/to-chan!
clojure.core.async/to-chan!!
metabase.ai-tracing.core/record!
metabase.api.macros.defendpoint.tools-manifest/assert-optional-fields-nullable!
metabase.channel.core/send!
metabase.channel.render.pdf/draw-too-large!

14
.clj-kondo/config/modules/config.edn
View File

@@ -159,7 +159,8 @@
{:team "Metabot"
:api #{metabase.agent-api.api
metabase.agent-api.init}
:uses #{api
:uses #{ai-tracing
api
auth-identity
channel
collections
@@ -194,6 +195,15 @@
models
util}}
ai-tracing
{:team "Metabot"
:api #{metabase.ai-tracing.api
metabase.ai-tracing.core
metabase.ai-tracing.init}
:uses #{api
settings
util}}
analytics
{:team "UX West"
:api #{metabase.analytics.api
@@ -1254,6 +1264,7 @@
:model-exports #{:model/McpSessionLog
:model/McpToolCallLog}
:uses #{agent-api
ai-tracing
api
app-db
config
@@ -1299,6 +1310,7 @@
slackbot}
:uses #{activity-feed
agent-lib
ai-tracing
analytics
analytics-interface
api

28
resources/log4j2.xml
View File

@@ -19,6 +19,26 @@
</PatternLayout>
</RollingFile>
-->
<!-- Eval-trace sink (metabase.ai-tracing): one JSONL file per eval session, keyed on the
mb-eval-session-id ThreadContext value. Inert unless that key is set (i.e. only during a
capture). NOTE: the `$$` in the Routes pattern is REQUIRED — a single `$` resolves once at
config-parse time and collapses every session into one file. `%m%n` keeps each line pure
JSON. No redaction: traces intentionally contain full prompts; keep this off in prod. -->
<Routing name="EVAL_TRACE_ROUTING">
<Routes pattern="$${ctx:mb-eval-session-id}">
<Route>
<File name="eval-trace-${ctx:mb-eval-session-id}"
fileName="${sys:logfile.path:-target/log}/eval-traces/${ctx:mb-eval-session-id}.jsonl"
append="true">
<PatternLayout pattern="%m%n"/>
</File>
</Route>
<!-- Required default route: fires when the ctx key is absent. -->
<Route key="$${ctx:mb-eval-session-id}" ref="STDOUT"/>
</Routes>
<IdlePurgePolicy timeToLive="15" timeUnit="MINUTES"/>
</Routing>
</Appenders>
<Loggers>
@@ -27,6 +47,14 @@
<Logger name="metabase" level="INFO"/>
<Logger name="metabase-enterprise" level="INFO"/>
<Logger name="metabase.metabot" level="DEBUG"/>
<!-- Eval-trace sink. The single on/off switch is MB_AI_EVAL_CAPTURE (off by default): this
logger only ever receives events while a capture is active, so on a normal instance it
writes nothing even though it sits at INFO. additivity=false keeps these lines out of the
main app log. Set level="off" here as a hard kill if you ever need to mute it regardless
of the capture flag. -->
<Logger name="metabase.ai-tracing.log" level="info" additivity="false">
<AppenderRef ref="EVAL_TRACE_ROUTING"/>
</Logger>
<Logger name="metabase.plugins" level="DEBUG"/>
<Logger name="metabase.query-processor.async" level="DEBUG"/>
<Logger name="metabase.server.middleware" level="DEBUG"/>

60
src/metabase/agent_api/api.clj
View File

@@ -5,9 +5,11 @@
[clojure.string :as str]
[metabase.agent-api.settings :as agent-api.settings]
[metabase.agent-api.validation :as agent-api.validation]
[metabase.ai-tracing.core :as ait]
[metabase.api.common :as api]
[metabase.api.macros :as api.macros]
[metabase.api.macros.scope :as scope]
[metabase.api.open-api :as open-api]
[metabase.api.routes.common :as api.routes.common]
[metabase.auth-identity.core :as auth-identity]
[metabase.channel.urls :as channel.urls]
@@ -291,6 +293,11 @@
_query-params
{:keys [prompt] :as body} :- ::construct-query-request]
(let [query (evaluate-external-query-for-execution body)]
;; Record the resolved query for eval tracing (inert unless capturing). The MCP `construct_query`
;; tool only returns an opaque handle, so this span attribute is how an eval harness recovers the
;; agent's actual query off the trace to grade it. `query` is already serialization-ready (no
;; `:lib/metadata`), so it stays small.
(ait/record! {:ai/query query})
(cond-> {:query (-> query json/encode u/encode-base64)}
prompt (assoc :prompt prompt))))
@@ -330,11 +337,11 @@
;; target database so a bogus/inaccessible database_id fails here rather than at save time.
(api/read-check :model/Database database_id)
;; Emit MBQL 5 (via `lib/native-query` + `prepare-for-serialization`, same as `construct_query`)
(let [mp (lib-be/application-database-metadata-provider database_id)]
{:query (-> (lib/native-query mp sql)
lib/prepare-for-serialization
json/encode
u/encode-base64)}))
(let [mp (lib-be/application-database-metadata-provider database_id)
query (-> (lib/native-query mp sql) lib/prepare-for-serialization)]
;; See /v2/construct-query: record the resolved query so an eval harness can grade it off the trace.
(ait/record! {:ai/query query})
{:query (-> query json/encode u/encode-base64)}))
;;; ------------------------------------------------- Combined Query -------------------------------------------------
@@ -1799,6 +1806,47 @@
;;; ---------------------------------------------------- Routes ------------------------------------------------------
(def ^:private base-routes
(api.macros/ns-handler *ns* +auth))
(def ^{:arglists '([request respond raise])} routes
"`/api/agent/` routes."
(api.macros/ns-handler *ns* +auth))
;; Wrapped in `handler-with-open-api-spec` so the handler still implements `OpenAPISpec` for
;; full-API spec generation (openapi.json, endpoint-dox); the spec is delegated to `base-routes`,
;; the underlying `ns-handler`, since the eval-tracing wrapper below carries no route metadata.
(open-api/handler-with-open-api-spec
;; Eval tracing (inert unless MB_AI_EVAL_CAPTURE). Direct callers get a fresh session;
;; the synthetic in-process call from MCP inherits the MCP session and nests under it.
;; Agent-API endpoints are synchronous, so `respond` fires inside the span and the span
;; closes after the handler returns.
(fn [request respond raise]
(ait/with-eval-session nil
(ait/eval-span (str "agent-api." (some-> (:request-method request) name) " " (:uri request))
{:http/method (some-> (:request-method request) name)
:http/uri (:uri request)
:http/request (:body request)
:http/user-id (or (:metabase-user-id request) api/*current-user-id*)}
(base-routes request
;; Relies on `respond` firing synchronously on this thread (see
;; above): if an endpoint ever responds async, `*parent*` is
;; unbound there and this `record!` no-ops, so the span captures
;; no status/response. Both fail soft; the trace is just incomplete
;; for async agent-api responses.
(fn eval-traced-respond [response]
(when (ait/capture-active?)
;; `+auth` binds `*current-user-id*` inside `base-routes`, so it
;; is unbound when the span opened above but set by the time this
;; respond fires — record the user id here so direct HTTP callers
;; (not just the MCP path, which carries `:metabase-user-id`) get it.
(ait/record! {:http/status (:status response)
;; Only record a plain data body. A streaming/opaque
;; body (not a coll) would otherwise be stringified
;; by the log sink into a useless `#object[…]`, so
;; skip it — the trace just omits the response there.
:http/response (when (coll? (:body response))
(:body response))
:http/user-id (or (:metabase-user-id request)
api/*current-user-id*)}))
(respond response))
raise))))
(fn [prefix] (open-api/open-api-spec base-routes prefix))))

69
src/metabase/ai_tracing/api.clj Normal file
View File

@@ -0,0 +1,69 @@
(ns metabase.ai-tracing.api
"HTTP endpoint for reading captured eval traces by session id.
Gated two ways: the route is only mounted/served when `MB_AI_EVAL_CAPTURE` is enabled
(`+eval-capture-enabled`, mirroring `+agent-api-enabled` / `+mcp-enabled`), and each request
additionally requires a superuser — traces contain full, unredacted prompts and content, so this
is intended for dedicated eval instances only."
(:require
[clojure.java.io :as io]
[metabase.ai-tracing.core :as ait]
[metabase.ai-tracing.settings :as ai-tracing.settings]
[metabase.api.common :as api]
[metabase.api.macros :as api.macros]
[metabase.api.routes.common :as routes.common]
[metabase.util.i18n :refer [tru]])
(:import
(java.io File)))
(set! *warn-on-reflection* true)
(defn- trace-dir
"Directory the eval-trace RoutingAppender writes to — mirrors the log4j2 path
`${sys:logfile.path:-target/log}/eval-traces`."
^File []
(io/file (or (System/getProperty "logfile.path") "target/log") "eval-traces"))
(defn- trace-file
"Resolve the JSONL file for `session-id`, or nil if the id is unsafe or would escape the trace dir.
`ait/safe-session-id-re` is the same pattern enforced at write time when the id is minted."
^File [session-id]
(when (re-matches ait/safe-session-id-re (str session-id))
(let [dir (.getCanonicalFile (trace-dir))
f (.getCanonicalFile (io/file dir (str session-id ".jsonl")))]
;; defense in depth: the resolved file must sit directly inside the trace dir
(when (= dir (.getParentFile f))
f))))
(api.macros/defendpoint :get "/:session-id" :- :any
"Return the captured eval trace as JSONL (one span per line) for `session-id`. Superuser-only;
served only when `MB_AI_EVAL_CAPTURE` is enabled."
;; Bound the length here too (not only via `trace-file`): `session-id` is a raw user-supplied path
;; segment, and `ait/max-session-id-length` is the single cap enforced at both write and read.
[{:keys [session-id]} :- [:map [:session-id [:string {:min 1, :max ait/max-session-id-length}]]]]
(api/check-superuser)
(let [f (trace-file session-id)]
(api/check (and f (.exists ^File f)) [404 (tru "Eval trace not found")])
;; Return the File directly so Ring streams it — a per-session trace can be many MB of full
;; prompts/completions, which we don't want to slurp into the heap.
{:status 200
:headers {"Content-Type" "application/x-ndjson"}
:body ^File f}))
(defn- enforce-eval-capture-enabled
"Ring middleware: 404 when eval capture is disabled. Uses a generic not-found message (rather than
naming the feature) so the endpoint is indistinguishable from an unmounted route to a caller who
isn't allowed to know it exists."
[handler]
(fn [request respond raise]
(if (ai-tracing.settings/ai-eval-capture)
(handler request respond raise)
(raise (ex-info (tru "Not found.") {:status-code 404})))))
(def ^{:arglists '([handler])} +eval-capture-enabled
"Wrap routes so they may only be accessed when eval capture is enabled."
(routes.common/wrap-middleware-for-open-api-spec-generation enforce-eval-capture-enabled))
(def ^{:arglists '([request respond raise])} routes
"`/api/eval-trace/` routes."
(api.macros/ns-handler *ns*))

293
src/metabase/ai_tracing/core.clj Normal file
View File

@@ -0,0 +1,293 @@
(ns metabase.ai-tracing.core
"Eval-time tracing for the AI / Metabot agentic system.
This layer is **separate from production observability** (`metabase.tracing`). It exists
to capture rich, complete agent traces *during benchmark/eval runs* so a scorer can read
the data back — full prompts/completions, tool I/O, and ad-hoc debug spans.
## The separate gate (production safety)
All ops here are gated on [[*capture*]], a per-run dynamic binding established ONLY by the
eval entrypoints ([[with-eval-session]] / [[capturing]]). It is orthogonal to
`metabase.tracing`'s `MB_TRACING_ENABLED` + group gates:
- In production — even with `metabase.tracing` fully enabled — ai-tracing does no work:
each span's body runs behind a nil-check on [[*capture*]] (the span macros still build
their `span-name`/`attrs` args, which just reference already-computed values). Eval spans,
which carry full prompts and verbose internals, can NEVER fire on organic traffic.
`MB_AI_EVAL_CAPTURE` is off by default.
- In an eval run, an entrypoint binds [[*capture*]] and the spans fire.
## What it captures
An in-memory span tree (`agent.turn → llm.call → tool.*`, or `mcp.<method> → …`) with full
attributes, durations, and events. Nesting + the session id are tracked through dynamic
bindings ([[*parent*]], [[*session-id*]]) that Clojure conveys across the agent's
virtual-thread tool execution (`bound-fn*`), so concurrent tool spans nest correctly.
## Session id (the OTel trace-id analog)
[[*session-id*]] groups all of a run's spans and names its log file. It is minted at the root
of a fresh capture, or *supplied* by the caller (e.g. MCP passes its `Mcp-Session-Id`), so a
multi-request MCP conversation all lands in one file.
## Sink
Each span, on finish, is streamed as one JSON line to the dedicated `metabase.ai-tracing.log`
logger (off by default), routed per-session to its own JSONL file. See
`metabase.ai-tracing.log`."
(:require
[metabase.ai-tracing.log :as ai-tracing.log]
[metabase.ai-tracing.settings :as ai-tracing.settings]))
(set! *warn-on-reflection* true)
;;;; ----------------------------------------- Gate (separate axis) -----------------------------------------
(def ^:dynamic *capture*
"Per-run capture sink: an atom holding the vector of root span maps, or nil.
Bound ONLY by an entrypoint. nil ⇒ ai-tracing is inert (the production safety gate)."
nil)
(def ^:dynamic *parent*
"The current in-flight span node (an atom), or nil at top level. Conveyed across the
agent's virtual-thread tool execution via `bound-fn*`, so concurrent tool spans nest
under the correct parent."
nil)
(def ^:dynamic *session-id*
"The eval session id (OTel trace-id analog). Minted at the root of a fresh capture, or supplied
by the caller (e.g. MCP's `Mcp-Session-Id`). Conveyed across virtual threads via `bound-fn*`;
drives the per-session log file routing."
nil)
(def ^:dynamic *retain-tree*
"When true, each finished span is also retained in the in-memory tree ([[*capture*]] / its parent's
`:children`) so an in-process caller can read the whole trace back as a return value (see
[[capturing]]). Left false on the file-routed path ([[with-eval-session]]): there every span is
already streamed to its JSONL file on finish and the in-memory tree is never read, so retaining it
would only pin heap proportional to the whole run. Off by default."
false)
(def safe-session-id-re
"A session id becomes BOTH a log-file name (the RoutingAppender's `${ctx:mb-eval-session-id}.jsonl`)
and a URL path segment on the read endpoint, so it must be filesystem/URL safe: start alphanumeric
(rejects `.`/`..`), then only alphanumerics / `.` `_` `-` (no `/` ⇒ no path traversal). This is the
single source of truth — enforced at the mint/supply boundary ([[checked-session-id]], via
[[with-eval-session]]) AND at the read boundary (`metabase.ai-tracing.api`).
Anchored with `\\A`/`\\z` so it's an exact, newline-safe match under BOTH `re-matches` (the mint/read
checks) and `re-find` (Malli's `:re` schema on the `eval[_-]session[_-]id` API params). Without the
anchors, `re-find` would accept any string merely CONTAINING a safe run (e.g. `../../etc/passwd`)."
#"\A[A-Za-z0-9][A-Za-z0-9._-]*\z")
(def ^:const max-session-id-length
"Cap on a supplied session id. It becomes `<id>.jsonl` on disk, so this keeps the filename well
under the ~255-byte filesystem limit. Also mirrored as a `:max` on the API schemas (defense in
depth for non-API callers: MCP, direct invocation)."
200)
(defn checked-session-id
"Return a safe session id: mint a fresh uuid when `supplied` is nil, otherwise validate it against
[[safe-session-id-re]] and [[max-session-id-length]]. Throws on a supplied id that isn't safe — the
id names a file written by the RoutingAppender, so an unsafe value (e.g. `../../etc/x`) or an
over-long one (which would fail filesystem creation and silently drop the trace) must never reach
it. We throw rather than silently substituting a uuid so a caller that named a trace file gets an
error instead of a trace it can't find."
^String [supplied]
(if (nil? supplied)
(str (random-uuid))
(let [id (str supplied)]
(when-not (re-matches safe-session-id-re id)
(throw (ex-info "Invalid eval-session-id: must start alphanumeric and contain only [A-Za-z0-9._-]"
{:session-id id})))
(when (> (count id) max-session-id-length)
(throw (ex-info (str "Invalid eval-session-id: must be at most " max-session-id-length " characters")
{:session-id-length (count id)})))
id)))
(defn capture-active?
"True when an eval capture is in progress on this thread."
[]
(some? *capture*))
;;;; ----------------------------------------- In-memory span tree ------------------------------------------
(defn- now-ns ^long [] (System/nanoTime))
(defn- now-epoch-ms ^long [] (System/currentTimeMillis))
(defn- new-node [span-type span-name attrs parent-id]
;; :start-ns (monotonic) drives duration; :start-epoch-ms (wall clock) drives the log line.
(atom {:type span-type
:name span-name
:id (str (random-uuid))
:parent-id parent-id
:attributes (or attrs {})
:events []
:children []
:start-ns (now-ns)
:start-epoch-ms (now-epoch-ms)}))
(defn- finish-node [node]
;; one deref ⇒ a consistent snapshot (duration, start, and :children all from the same state).
(let [{:keys [start-ns start-epoch-ms] :as snapshot} @node
dur-ns (- (now-ns) start-ns)]
(-> snapshot
(assoc :duration-ms (/ (double dur-ns) 1e6)
;; wall-clock end derived from the monotonic duration (no second, possibly
;; backward-jumping clock read); ms-granular — sub-ms precision is in :duration-ms.
:end-epoch-ms (+ (long start-epoch-ms) (Math/round (/ (double dur-ns) 1e6))))
(dissoc :start-ns))))
(defn- attach! [parent finished]
;; Only build the in-memory tree when a caller will read it back ([[capturing]]). On the file-routed
;; path emit! has already streamed this span, so retaining it here would pin heap for the whole run.
;; swap! is atomic, so concurrent tool spans appending to the same parent are safe.
(when *retain-tree*
(if parent
(swap! parent update :children conj finished)
(swap! *capture* conj finished))))
(defn eval-span*
"Functional core behind the span macros. Runs `thunk` inside a captured span of `span-type`
named `span-name` with `attrs`, recording nesting + duration, attaching the finished node to
the tree, and streaming it to the log sink. No-op (just the nil-check) unless a capture is
active. Errors are recorded as an event and re-thrown."
[span-type span-name attrs thunk]
(if-not (capture-active?)
(thunk)
(let [parent *parent*
node (new-node span-type span-name attrs (when parent (:id @parent)))]
(try
(binding [*parent* node]
(thunk))
(catch Throwable t
;; Capture class + ex-data, not just the message: agent-validation `ex-info`s carry their
;; signal in ex-data and a bare NPE has a nil message. The log sink JSON-safe-coerces
;; :data, so a non-encodable value here never breaks emission.
(swap! node update :events conj {:event :error
:message (ex-message t)
:class (.getName (class t))
:data (ex-data t)})
(throw t))
(finally
(let [finished (finish-node node)]
(attach! parent finished)
;; Stream this span as one JSONL line. Runs on whatever thread the span finished on
;; (incl. tool virtual threads) — *session-id* is conveyed there by `bound-fn*`.
(ai-tracing.log/emit! finished *session-id*)))))))
;;;; ----------------------------------------- Enrichment of current span -----------------------------------
(defn record!
"Merge `attrs` (namespaced keyword → value) onto the current eval span. Use for
outputs/results/health signals known mid- or post-body. No-op when inactive or outside a span."
[attrs]
(when (and (capture-active?) *parent* (seq attrs))
(swap! *parent* update :attributes merge attrs))
nil)
;;;; ----------------------------------------- Span macros --------------------------------------------------
(defmacro spanning
"Implementation detail of the span macros below — not intended for direct use (it must be public
only so the public span macros can expand to it from other namespaces).
Runs `body` directly when no capture is live (the production no-op), else inside a captured span.
Guarding `capture-active?` HERE — ahead of the `eval-span*` call — means `span-name`/`attrs` are
only constructed when a capture is active, so organic traffic never builds the span name string or
the attrs map (it pays only the `*capture*` nil-check). `body` is emitted once, behind a `thunk#`,
so a large body isn't duplicated into both branches; the disabled path's only residual cost is that
one small closure."
{:style/indent 3}
[span-type span-name attrs & body]
`(let [thunk# (^:once fn* [] ~@body)]
(if (capture-active?)
(eval-span* ~span-type ~span-name ~attrs thunk#)
(thunk#))))
(defmacro eval-span
"Generic eval-only span. Usable from any subsystem. `attrs` is a map of namespaced keyword → value."
{:style/indent 2}
[span-name attrs & body]
`(spanning :span ~span-name ~attrs ~@body))
(defmacro with-agent-turn
"Root span for one agentic turn."
{:style/indent 1}
[attrs & body]
`(spanning :turn "agent.turn" ~attrs ~@body))
(defmacro with-llm-call
"Span around one LLM round-trip. Record the completion/usage via [[record!]] once known."
{:style/indent 1}
[attrs & body]
`(spanning :llm "llm.call" ~attrs ~@body))
(defmacro with-tool-call
"Span around one tool invocation. Expects `:ai/tool-name` in `attrs`."
{:style/indent 1}
[attrs & body]
;; Can't route through `spanning`: the span name derives from `attrs`, and we want `attrs` built
;; only when a capture is active AND only once (not twice — for the name and for the span). So we
;; inline the gate and bind `attrs#` inside the active branch. Tool calls run on the organic agent
;; path, so keeping this build behind `capture-active?` is the point.
`(let [thunk# (^:once fn* [] ~@body)]
(if (capture-active?)
(let [attrs# ~attrs]
(eval-span* :tool (str "tool." (:ai/tool-name attrs#)) attrs# thunk#))
(thunk#))))
;;;; ----------------------------------------- Entrypoints --------------------------------------------------
(defmacro with-eval-session
"Generic eval-session entrypoint. When capture is enabled and not already active, establish a
FRESH capture: bind [[*capture*]] (the in-memory tree), [[*session-id*]] (a [[checked-session-id]]
of `supplied-id`, or a fresh uuid), and reset [[*parent*]] to nil. When already [[capture-active?]],
INHERIT the outer bindings (nesting). Inert (body only) when eval-capture is disabled. Throws if
`supplied-id` is present but not [[safe-session-id-re]] (it names a file — no path traversal).
Session-id is minted eagerly here so callers can read [[*session-id*]] before the first span.
(with-eval-session nil (with-agent-turn {…} …)) ; agent loop — mint
(with-eval-session mcp-session (eval-span \"mcp.tools/call\" {…} …)) ; MCP — supplied"
{:style/indent 1}
[supplied-id & body]
`(cond
(capture-active?) (do ~@body) ; inherit / nest
(ai-tracing.settings/ai-eval-capture) (binding [*capture* (atom [])
*session-id* (checked-session-id ~supplied-id)
*parent* nil]
~@body)
:else (do ~@body))) ; inert
(defmacro capturing
"In-process capture, UNCONDITIONAL (ignores the gate). Establishes a fresh capture that RETAINS the
span tree ([[*retain-tree*]]) and returns `{:result <body value> :trace <root spans>}`. Used by
[[capture-reducible]] and tests. The harness must fully realize any lazy result inside `body`.
This path is RETURN-VALUE-based, not file-routed: the trace comes back as `:trace`. It deliberately
does NOT mint a session id — [[*session-id*]] is left as-is (nil at top level), so
[[metabase.ai-tracing.log/emit!]] no-ops and NO `<id>.jsonl` is written; read `:trace` instead. A
session id supplied to an inner [[with-eval-session]] (e.g. `:eval-session-id` threaded through
`run-agent-loop`) is IGNORED — capture is already active, so the inner form inherits these bindings
rather than re-minting. (A capture nested inside a live file-routed session inherits that session
and still streams to its file.)"
[& body]
`(let [sink# (atom [])]
(binding [*capture* sink#
*parent* nil
*retain-tree* true]
;; bind result# in a let so the body (which populates sink#) is forced BEFORE @sink#
(let [result# (do ~@body)]
{:result result# :trace @sink#}))))
(defn capture-reducible
"In-process eval entrypoint. Realizes `reducible` (e.g. the value of
`metabase.metabot.agent.core/run-agent-loop`) with capture active, collecting every reduced item
into a vector. Returns `{:result [items…] :trace [root-spans]}`.
(ai-tracing/capture-reducible (run-agent-loop opts))"
[reducible]
(capturing (into [] reducible)))

3
src/metabase/ai_tracing/init.clj Normal file
View File

@@ -0,0 +1,3 @@
(ns metabase.ai-tracing.init
(:require
[metabase.ai-tracing.settings]))

106
src/metabase/ai_tracing/log.clj Normal file
View File

@@ -0,0 +1,106 @@
(ns metabase.ai-tracing.log
"File-based JSONL sink for eval traces.
One JSON object per span is emitted on THIS dedicated logger (`metabase.ai-tracing.log` — the
logger name equals the namespace), routed per-session to its own `<session-id>.jsonl` file by a
Log4j2 `RoutingAppender` keyed on the `mb-eval-session-id` ThreadContext value.
Each line is the message only (the appender uses `%m%n`), so the file is pure JSONL: an external
script joins lines by `:session` and rebuilds the tree by chaining `:id`/`:parent`.
`:start-epoch-ms`/`:end-epoch-ms` are wall-clock epoch milliseconds (`currentTimeMillis`), NOT
`System/nanoTime`; `:dur-ms` carries the precise (sub-ms, monotonic) duration. The end is the start
plus that duration, so it never reads a second, possibly backward-jumping wall clock.
The single on/off switch is `MB_AI_EVAL_CAPTURE` (off by default): [[emit!]] is only reached while
a capture is active, so on a normal instance this logger writes nothing even though it sits at
INFO. (`resources/log4j2.xml` also lets you set the logger to `off` as a hard kill.) Traces contain
full, unredacted user content — intended for dedicated eval instances only.
Retention is the operator's responsibility. Files are append-only with no rollover, no size cap,
and no expiry — a long session grows unbounded, and re-running the same session id appends to the
same file. The `RoutingAppender`'s IdlePurgePolicy only reclaims idle *appenders* (open file
handles), never the files on disk. An eval host should periodically prune
`${logfile.path}/eval-traces/` (the harness has usually consumed each `<id>.jsonl` by then)."
(:require
[metabase.util.json :as json]
[metabase.util.log :as log]))
(set! *warn-on-reflection* true)
(defn- node->entry
"Pure: a finished span node + `session-id` → the JSONL map. No semantic-convention mapping and no
size limits — full payloads. The reconstruction script joins on `:session` and chains
`:id`/`:parent`. `:start-epoch-ms`/`:end-epoch-ms` are wall-clock epoch milliseconds (see ns
docstring); sub-ms precision lives in `:dur-ms`."
[{:keys [type name id parent-id attributes events duration-ms start-epoch-ms end-epoch-ms]}
session-id]
{:session session-id
:id id
:parent parent-id
:type type
:name name
:start-epoch-ms start-epoch-ms
:end-epoch-ms end-epoch-ms
:dur-ms duration-ms
:attributes attributes
:events events})
(def ^:private json-safe-max-depth
"Recursion cap for [[json-safe]]. Attribute values are arbitrary request context / agent state, so a
pathologically deep — or cyclic — value would otherwise overflow the stack. A `StackOverflowError` is
an `Error`, not an `Exception`, so it would escape [[emit!]]'s `catch Exception` net and break the
traced run. Past this depth we stringify instead of recursing."
200)
(defn- json-safe
"Best-effort coercion of a value into something the JSON encoder can handle: recurse through plain
collections, keep scalars, and stringify anything else. Used ONLY as a fallback after a direct
encode throws, so it never touches values (UUIDs, dates, …) that already encode fine. Bounded by
[[json-safe-max-depth]] so a deep/cyclic value degrades to a string rather than overflowing the stack."
([v] (json-safe v 0))
([v depth]
(if (>= depth json-safe-max-depth)
(str v)
(let [d (inc depth)]
(cond
;; Coerce KEYS too, not just values: the JSON encoder rejects a non-scalar map key (a
;; vector/map key), so leaving it intact would let the fallback re-encode throw — orphaning
;; the very root span this fallback exists to save.
(map? v) (into {} (map (fn [[k val]]
[(if (or (string? k) (keyword? k) (number? k)) k (str k))
(json-safe val d)]))
v)
(set? v) (mapv #(json-safe % d) v)
(sequential? v) (mapv #(json-safe % d) v)
(or (nil? v) (string? v) (number? v) (boolean? v) (keyword? v) (symbol? v)) v
:else (str v))))))
(defn emit!
"Stream one finished span `node` as a single JSONL line, routed to `session-id`'s file. No-op when
`session-id` is nil.
`log/with-context` sets `mb-eval-session-id` in the Log4j2 ThreadContext for the duration of the
single `log/info` call, on whatever thread the span finished on. Because `*session-id*` is conveyed
across the agent's virtual-thread tool executor by `bound-fn*`, the routing key is always correct,
and `with-context` restores/removes it afterward so it never leaks onto a pooled thread."
[node session-id]
(when session-id
(try
(let [entry (node->entry node session-id)
line (try
(json/encode entry)
(catch Exception _
;; The attributes carry arbitrary request context / agent state, which could
;; contain a non-encodable value. Dropping the line here would lose the span —
;; and for a root span, orphan every child that references its `:id`. Degrade
;; to a JSON-safe copy so the span still emits.
(json/encode (json-safe entry))))]
(log/with-context {:eval-session-id session-id}
(log/info line)))
;; Ultimate safety net: never let trace serialization/emission break the traced run. Catch
;; `Exception`, not `Throwable`, so JVM `Error`s and `InterruptedException` still propagate —
;; this runs in the span's `finally`, often on a tool virtual thread.
(catch Exception t
(log/warn t "ai-tracing: failed to serialize/emit eval span"))))
nil)

21
src/metabase/ai_tracing/settings.clj Normal file
View File

@@ -0,0 +1,21 @@
(ns metabase.ai-tracing.settings
"Env-var-only settings for the eval-time AI tracing module.
Configured exclusively via environment variables (`:setter :none`)."
(:require
[metabase.settings.core :refer [defsetting]]
[metabase.util.i18n :refer [deferred-tru]]))
(set! *warn-on-reflection* true)
(defsetting ai-eval-capture
(deferred-tru
(str "Enable eval-time AI agent trace capture. When true, agent / MCP / agent-api runs capture a "
"full trace (prompts, completions, tool I/O, custom spans) and write it as structured JSONL to "
"a per-session file via the dedicated `metabase.ai-tracing.log` logger. Separate from "
"MB_TRACING_ENABLED. Off by default; intended for dedicated eval instances, NOT production "
"(traces contain full, unredacted user content)."))
:type :boolean
:default false
:visibility :internal
:export? false
:setter :none)

3
src/metabase/api_routes/routes.clj
View File

@@ -4,6 +4,7 @@
[metabase.actions-rest.api]
[metabase.activity-feed.api]
[metabase.agent-api.api]
[metabase.ai-tracing.api]
[metabase.analytics.api]
[metabase.analytics.api.proxy]
[metabase.api-keys.api]
@@ -80,6 +81,7 @@
(comment metabase.actions-rest.api/keep-me
metabase.activity-feed.api/keep-me
metabase.agent-api.api/keep-me
metabase.ai-tracing.api/keep-me
metabase.analytics.api/keep-me
metabase.analytics.api.proxy/keep-me
metabase.api-keys.api/keep-me
@@ -193,6 +195,7 @@
"/embed" (+message-only-exceptions metabase.embedding-rest.api/embedding-routes)
"/embed-mcp" (+auth metabase.mcp.callback-api/routes)
"/embed-theme" (+auth metabase.embedding-rest.api/theme-routes)
"/eval-trace" (metabase.ai-tracing.api/+eval-capture-enabled metabase.ai-tracing.api/routes)
"/field" (+auth metabase.warehouse-schema-rest.api/field-routes)
"/frontend-errors" metabase.frontend-errors.api/routes
"/geojson" 'metabase.geojson.api

1
src/metabase/core/init.clj
View File

@@ -9,6 +9,7 @@
[metabase.actions.init]
[metabase.activity-feed.init]
[metabase.agent-api.init]
[metabase.ai-tracing.init]
[metabase.analytics.init]
[metabase.api-scope.init]
[metabase.api.init]

61
src/metabase/mcp/api.clj
View File

@@ -5,6 +5,7 @@
[clojure.core.async :as a]
[clojure.string :as str]
[compojure.response :as compojure.response]
[metabase.ai-tracing.core :as ait]
[metabase.api.common :as api]
[metabase.api.macros.scope :as scope]
[metabase.api.open-api :as open-api]
@@ -109,9 +110,24 @@
(defn- handle-ping [id _params]
(jsonrpc-response id {}))
(defn- dispatch-request
"Dispatch a single JSON-RPC request. Returns a response map or nil for notifications."
[{:keys [id method params] :as _msg} session-id token-scopes request-context]
(defn- eval-session-override
"An eval-session id the harness supplies via the `x-eval-session-id` header so it can name (and
later fetch) the trace itself — the MCP analogue of metabot's `eval_session_id`. opencode negotiates
the `Mcp-Session-Id` internally, so without this the harness can't know which `<uuid>.jsonl` to read.
Validates through `ait/checked-session-id` — the mint-time boundary, and the single source of truth
for the safe-id contract — and maps its throw on an unsafe/over-long id to nil, so a bad header falls
back to the Mcp-Session-Id correlator rather than 500ing ahead of `dispatch-request`'s try/catch. The
`when-let` guards the absent-header case, so we never reach `checked-session-id`'s nil -> fresh-uuid
branch (which would invent a trace file the harness never named)."
[request]
(when-let [id (get-in request [:headers "x-eval-session-id"])]
(try (ait/checked-session-id id) (catch Exception _ nil))))
(defn- dispatch-method
"Route a single JSON-RPC `method` to its handler, returning a response map or nil (notifications).
A handler that throws is turned into a JSON-RPC internal error rather than propagating."
[id method params session-id token-scopes request-context]
(try
(case method
"notifications/initialized" nil
@@ -127,6 +143,33 @@
(log/error e "Error dispatching JSON-RPC method" method)
(jsonrpc-error id -32603 (or (ex-message e) "Internal error")))))
(defn- dispatch-request
"Dispatch a single JSON-RPC request. Returns a response map or nil for notifications."
[{:keys [id method params] :as _msg} session-id token-scopes request-context eval-session-id]
;; Eval tracing (inert unless MB_AI_EVAL_CAPTURE): establish a session and open a per-request root
;; span; tool/resource/agent-api spans nest under it automatically. Key on the harness-supplied
;; `eval-session-id` when given (so it owns the trace file name), else the MCP session's UUID
;; correlator so an entire conversation's requests append to one `<uuid>.jsonl`. We key on the UUID
;; prefix (not the full `<uuid>.<base64>` id): it's stable across the conversation AND always
;; filesystem/URL-safe, whereas the full id can carry a base64 payload that `require-valid-session`
;; accepts but `safe-session-id-re` rejects (e.g. `=` padding) — passing that to `with-eval-session`
;; would throw out here, ahead of the try/catch.
;;
;; When BOTH are absent (a stateless / pre-initialize request with no header), this is nil and
;; `with-eval-session` mints a fresh uuid — so such requests get their own `<uuid>.jsonl` rather than
;; grouping. That's fine for the eval flow, which always supplies `eval-session-id`; the ungrouped
;; files are reaped by the appender's IdlePurgePolicy.
(ait/with-eval-session (or eval-session-id (some-> session-id (str/split #"\.") first))
(ait/eval-span (str "mcp." method) {:mcp/method method
:mcp/request-id id
:mcp/params params
:mcp/user-id api/*current-user-id*
:mcp/scopes token-scopes}
(let [response (dispatch-method id method params session-id token-scopes request-context)]
;; record the materialized JSON-RPC result/error (the request's output)
(ait/record! {:mcp/response response})
response))))
;;; ----------------------------------------------------- SSE ------------------------------------------------------
(defn- accepts-sse?
@@ -222,9 +265,10 @@
(defn- handle-post
"Handle a POST request containing one or more JSON-RPC messages."
[user-id request]
(let [body (:body request)
session-id (get-in request [:headers "mcp-session-id"])
batch? (sequential? body)]
(let [body (:body request)
session-id (get-in request [:headers "mcp-session-id"])
eval-session-id (eval-session-override request)
batch? (sequential? body)]
(cond
(nil? body)
(json-response 400 (jsonrpc-error nil -32700 "Parse error: empty body"))
@@ -270,7 +314,10 @@
;; (gated PII) alongside client identity — the view no longer joins the session.
request-context {:user-agent (get-in request [:headers "user-agent"])
:ip-address (request/ip-address request)}
responses (into [] (keep #(dispatch-request % session-id (:token-scopes request) request-context)) messages)]
dispatch-msg (fn [msg]
(dispatch-request msg session-id (:token-scopes request)
request-context eval-session-id))
responses (into [] (keep dispatch-msg) messages)]
(cond
(empty? responses)
{:status 202 :headers {} :body ""}

72
src/metabase/mcp/tools.clj
View File

@@ -6,6 +6,7 @@
[clojure.set :as set]
[clojure.string :as str]
[metabase.agent-api.api :as agent-api]
[metabase.ai-tracing.core :as ait]
[metabase.api.common :as api]
[metabase.api.macros.defendpoint.tools-manifest :as tools-manifest]
[metabase.config.core :as config]
@@ -539,36 +540,41 @@
([token-scopes session-id tool-name arguments]
(call-tool token-scopes session-id tool-name arguments {:supports-mcp-ui? true}))
([token-scopes session-id tool-name arguments options]
(let [start (System/nanoTime)
record! (fn [status error-code error-message]
(mcp.usage/record-mcp-tool-call!
{:tool-name tool-name
:user-id api/*current-user-id*
:session-id session-id
:status status
:duration-ms (quot (- (System/nanoTime) start) 1000000)
:error-code error-code
:error-message error-message
;; Identity + PII are denormalized onto the row (the view no longer joins the
;; session): client from the call's `_meta`, tenant from the current user,
;; IP/UA from the request. The recorder falls back to the session row's stored
;; client when `_meta` carries none, and gates the PII columns.
:client-info (:client-info options)
:tenant-id (some-> api/*current-user* deref :tenant_id)
:user-agent (get-in options [:request-context :user-agent])
:ip-address (get-in options [:request-context :ip-address])}))]
(try
(let [result (dispatch-tool-call token-scopes session-id tool-name arguments options)
error? (boolean (:isError result))]
(record! (if error? "error" "success")
(when error? (or (::error-code result) error-code-internal))
(when error? (some-> result :content first :text)))
;; `::error-code` is an internal classification marker — never expose it to the client.
(dissoc result ::error-code))
(catch Throwable e
;; A handler that throws instead of returning error content (notably a UI tool
;; `:response-fn`, whose path isn't wrapped in `dispatch-tool-call`) would otherwise
;; skip instrumentation and under-report errors. Record the failure, then rethrow so the
;; transport layer still surfaces it to the client.
(record! "error" error-code-internal (ex-message e))
(throw e))))))
;; Eval span (inert unless capturing) nesting under the MCP request span; records the tool
;; name + args, and the resulting content as output.
(ait/with-tool-call {:ai/tool-name tool-name :ai/tool-args arguments}
(let [start (System/nanoTime)
record! (fn [status error-code error-message]
(mcp.usage/record-mcp-tool-call!
{:tool-name tool-name
:user-id api/*current-user-id*
:session-id session-id
:status status
:duration-ms (quot (- (System/nanoTime) start) 1000000)
:error-code error-code
:error-message error-message
;; Identity + PII are denormalized onto the row (the view no longer joins the
;; session): client from the call's `_meta`, tenant from the current user,
;; IP/UA from the request. The recorder falls back to the session row's stored
;; client when `_meta` carries none, and gates the PII columns.
:client-info (:client-info options)
:tenant-id (some-> api/*current-user* deref :tenant_id)
:user-agent (get-in options [:request-context :user-agent])
:ip-address (get-in options [:request-context :ip-address])}))]
(try
(let [result (dispatch-tool-call token-scopes session-id tool-name arguments options)
error? (boolean (:isError result))]
(record! (if error? "error" "success")
(when error? (or (::error-code result) error-code-internal))
(when error? (some-> result :content first :text)))
;; `::error-code` is an internal classification marker — never expose it to the client.
(let [result (dissoc result ::error-code)]
(ait/record! {:ai/tool-output result})
result))
(catch Throwable e
;; A handler that throws instead of returning error content (notably a UI tool
;; `:response-fn`, whose path isn't wrapped in `dispatch-tool-call`) would otherwise
;; skip instrumentation and under-report errors. Record the failure, then rethrow so the
;; transport layer still surfaces it to the client.
(record! "error" error-code-internal (ex-message e))
(throw e)))))))

113
src/metabase/metabot/agent/core.clj
View File

@@ -3,6 +3,7 @@
(:require
[clojure.java.io :as io]
[clojure.string :as str]
[metabase.ai-tracing.core :as ait]
[metabase.analytics-interface.core :as analytics]
[metabase.api-scope.core :as api-scope]
[metabase.api.common :as api]
@@ -260,6 +261,10 @@
:system (:content system-msg)
:parts input-parts
:tools (vec tools)}))
(when (ait/capture-active?)
(ait/record! {:ai/system (:content system-msg)
:ai/input-parts input-parts
:ai/tool-count (count tools)}))
(eduction (streaming/post-process-xf (get-in memory [:state :queries] {})
(get-in memory [:state :charts] {})
link-registry-atom)
@@ -505,14 +510,24 @@
memory @memory-atom
parts-atom (atom [])
link-registry-atom (atom (get-in memory [:state :link-registry] {}))
llm-call (call-llm memory context profile tools iteration tracking-opts link-registry-atom)
xf (comp (accumulate-usage-xf usage-atom (:model profile))
(u/tee-xf parts-atom))
;; We use `reduce` instead of `transduce` because rf is the outer reducing
;; function (e.g. parts->aisdk-sse-xf wrapping streaming-writer-rf) whose completion
;; arity emits a finish message — that must only fire once, at the end of the
;; entire agent loop, not after every iteration.
result' (reduce (xf rf) result llm-call)
;; `call-llm` runs inside the eval span so the request attrs it records attach here.
result' (ait/with-llm-call {:ai/iteration iteration
:ai/model (:model profile)}
(let [llm-call (call-llm memory context profile tools iteration
tracking-opts link-registry-atom)
reduced-result (reduce (xf rf) result llm-call)]
(when (ait/capture-active?)
(ait/record! {:ai/output-text (collect-text-from-parts @parts-atom)
:ai/tool-io (summarize-tool-ios @parts-atom)
;; preserve data parts (e.g. generated_entity) emitted this iteration
:ai/data-parts (filterv #(= :data (:type %)) @parts-atom)}))
reduced-result))
parts @parts-atom]
;; Sync link registry back to memory after streaming completes
(swap! memory-atom assoc-in [:state :link-registry] @link-registry-atom)
@@ -525,25 +540,28 @@
:all-parts parts}))
(log/debug "Iteration" {:n iteration :parts-count (count parts)})
(if (empty? parts)
(assoc loop-state :status :done :result (rf result (final-state-part @memory-atom)))
;; LLM returned nothing this iteration — a natural stop, surfaced for the turn span.
(assoc loop-state :status :done :finish-reason :empty-response
:result (rf result (final-state-part @memory-atom)))
(do
(log/debug "Got parts" {:count (count parts) :types (mapv :type parts)})
(swap! memory-atom update-memory parts)
(cond
(reduced? result')
(assoc loop-state :status :reduced :result @result')
;; consumer signalled early termination (e.g. client disconnect / cancellation)
(assoc loop-state :status :reduced :finish-reason :reduced :result @result')
(should-continue? iteration max-iter terminal-tools parts)
(assoc loop-state :result result' :iteration (inc iteration))
:else
(do (log/info "Agent loop complete"
{:iterations iteration
;; TODO: decide if we want this reason to float up to frontend
:reason (finish-reason iteration max-iter terminal-tools parts)})
(assoc loop-state
:status :done
:result (rf result' (final-state-part @memory-atom))))))))))
(let [reason (finish-reason iteration max-iter terminal-tools parts)]
(log/info "Agent loop complete" {:iterations iteration :reason reason})
(assoc loop-state
:status :done
;; surfaced so run-agent-loop can record it on the turn span
:finish-reason reason
:result (rf result' (final-state-part @memory-atom))))))))))
;;; Public API
@@ -573,6 +591,16 @@
:version 1
:data debug-log})
(defn- eval-session-part
"Create a data part carrying just the eval session id. Emitted at the end of the stream when
`MB_AI_EVAL_CAPTURE` is enabled, so the benchmark/eval harness can locate the per-session
`<session-id>.jsonl` trace file written by `metabase.ai-tracing.log`."
[session-id]
{:type :data
:data-type "eval_session"
:version 1
:data {:session-id session-id}})
(def ^:private profile-id->required-permission
"Map from profile-id to the metabot permission that must be `:yes` for a user
to use that profile. Profiles not listed here have no profile-level permission gate."
@@ -612,6 +640,13 @@
[:state {:optional true} [:maybe ::state]]
[:context {:optional true} [:maybe ::context]]
[:tracking-opts {:optional true} [:maybe ::tracking-opts]]
;; eval-only: when supplied (e.g. by the benchmark harness), names the per-session
;; trace file so the caller can read it back without parsing the stream. Length + charset
;; are enforced here (rather than only deep in `ait/checked-session-id`) so a bad id 400s
;; at the boundary instead of surfacing as a generic agent error. `ait/max-session-id-length`
;; and `ait/safe-session-id-re` are the single source of truth for the cap and the charset.
[:eval-session-id {:optional true}
[:maybe [:and [:string {:max ait/max-session-id-length}] [:re ait/safe-session-id-re]]]]
[:debug? {:optional true} [:maybe :boolean]]]]
(let [profile-id (:profile-id opts)
debug? (:debug? opts)
@@ -637,17 +672,51 @@
scope/*current-user-capabilities* (get-in opts [:context :capabilities] #{})
scope/*current-loadable-skill-ids* (atom #{})]
(try
(let [agent (init-agent opts)
{result :result
iteration :iteration} (->> (initial-loop-state agent rf init (atom {}))
(iterate loop-step)
(drop-while #(= :continue (:status %)))
first)]
(analytics/observe! :metabase-metabot/agent-iterations labels iteration)
;; Emit debug log as a data part if debug mode was active
(if (and debug? (seq @*debug-log*))
(rf result (debug-log-part @*debug-log*))
result))
;; `with-eval-session` establishes the eval capture (gated by MB_AI_EVAL_CAPTURE,
;; inherited when an in-process `capture-reducible` already bound one). Spans stream
;; to the per-session JSONL file as they finish.
(ait/with-eval-session (:eval-session-id opts)
(let [turn-result
(ait/with-agent-turn {:ai/profile-id (name profile-id)
:ai/msg-count (count (:messages opts))
;; the user's latest question — trace-level input for evals
:ai/user-input (some->> (:messages opts)
(filter #(= "user" (some-> % :role name)))
last :content)
;; full request — makes the trace a self-contained record
:ai/messages (:messages opts)
:ai/context (:context opts)
:ai/state (:state opts)}
(let [agent (init-agent opts)
usage-atom (atom {})
{result :result
iteration :iteration
finish-reason :finish-reason} (->> (initial-loop-state agent rf init usage-atom)
(iterate loop-step)
(drop-while #(= :continue (:status %)))
first)]
(analytics/observe! :metabase-metabot/agent-iterations labels iteration)
;; Materialized turn-level outputs for evals: token usage, why the loop
;; stopped, and the final agent state (link registry / generated entities).
(when (ait/capture-active?)
(ait/record! {:ai/finish-reason finish-reason
:ai/usage @usage-atom
:ai/final-state (some-> (:memory-atom agent) deref :state)}))
;; A :reduced stop (client disconnect / cancellation) has already terminated
;; the reducing fn — stepping it again would violate the transducer contract.
;; Append trailing parts only on a normal finish: the debug log, and the
;; eval-session pointer that lets the harness locate the per-session
;; `<session-id>.jsonl` (it reads that file, not the stream, so a skipped
;; pointer on disconnect costs nothing). Gate the pointer on a non-nil
;; `*session-id*` too: the in-process `capture-reducible`/`capturing` path is
;; capture-active but deliberately file-less (session id nil, read `:trace`),
;; so emitting a pointer there would name a `<nil>.jsonl` that never exists.
(if (= :reduced finish-reason)
result
(cond-> result
(and debug? (seq @*debug-log*)) (rf (debug-log-part @*debug-log*))
(and (ait/capture-active?) ait/*session-id*) (rf (eval-session-part ait/*session-id*))))))]
turn-result))
(catch Exception e
(analytics/inc! :metabase-metabot/agent-errors labels)
(let [{:keys [api-error status provider body]} (ex-data e)

25
src/metabase/metabot/api.clj
View File

@@ -4,6 +4,7 @@
[clojure.core.async :as a]
[clojure.string :as str]
[medley.core :as m]
[metabase.ai-tracing.core :as ait]
[metabase.analytics.core :as analytics.core]
[metabase.api.common :as api]
[metabase.api.macros :as api.macros]
@@ -102,7 +103,7 @@
`start` event's `messageId` so the client can correlate streamed messages
with feedback."
[{:keys [metabot-id profile-id message context history conversation-id state debug?
assistant-msg-id external-id]}]
eval-session-id assistant-msg-id external-id]}]
(let [enriched-context (metabot.context/create-context context {:metabot-id metabot-id
:profile-id (keyword profile-id)})
messages (concat history [message])]
@@ -121,12 +122,13 @@
(transduce xf
(streaming-writer-rf os canceled-chan canceled?)
(agent/run-agent-loop
(cond-> {:messages messages
:state state
:metabot-id metabot-id
:profile-id (keyword profile-id)
:context enriched-context
:tracking-opts {:session-id conversation-id}}
(cond-> {:messages messages
:state state
:metabot-id metabot-id
:profile-id (keyword profile-id)
:context enriched-context
:eval-session-id eval-session-id
:tracking-opts {:session-id conversation-id}}
debug? (assoc :debug? true))))
(catch org.eclipse.jetty.io.EofException _
(vreset! canceled? true)
@@ -186,7 +188,7 @@
it into:
- `hostname`: extracted from the origin URL, always recorded.
- `pii-info`: gated by `analytics-pii-retention-enabled` — nil when off."
[{:keys [metabot_id profile_id message context history conversation_id state debug]} request-info]
[{:keys [metabot_id profile_id message context history conversation_id state debug eval_session_id]} request-info]
(let [message (metabot.envelope/user-message message)
metabot-id (metabot.config/resolve-dynamic-metabot-id metabot_id)
_ (metabot.config/check-metabot-enabled! metabot-id)
@@ -211,6 +213,7 @@
:conversation-id conversation_id
:state state
:debug? debug?
:eval-session-id eval_session_id
:assistant-msg-id assistant-msg-id
:external-id assistant-external-id}))))
@@ -255,6 +258,12 @@
[:queries {:optional true} [:map-of :string :any]]
[:charts {:optional true} [:map-of :string :any]]
[:chart-configs {:optional true} [:map-of :string :any]]]]
;; eval-only: lets the benchmark harness name the per-session trace file it will read back.
;; Length + charset enforced at this HTTP boundary so a bad id 400s cleanly instead of
;; throwing deep in `ait/checked-session-id` and surfacing as a generic agent error.
;; `ait/max-session-id-length` / `ait/safe-session-id-re` are the single source of truth.
[:eval_session_id {:optional true}
[:maybe [:and [:string {:max ait/max-session-id-length}] [:re ait/safe-session-id-re]]]]
[:debug {:optional true} [:maybe :boolean]]]
req]
(metabot.context/log body :llm.log/fe->be)

65
src/metabase/metabot/self/core.clj
View File

@@ -4,6 +4,7 @@
[clojure.java.io :as io]
[clojure.string :as str]
[clojure.walk :as walk]
[metabase.ai-tracing.core :as ait]
[metabase.llm.settings :as llm]
[metabase.metabot.schema.v2 :as schema.v2]
[metabase.premium-features.core :as premium-features]
@@ -521,35 +522,41 @@
Chunks have a ::duration-ms key added for internal use which is not part of the aisdk spec."
[tool-call-id tool-name tool chunks]
(with-span :info {:name :metabot.agent/run-tool
:tool-name tool-name
:tool-call-id tool-call-id}
(let [start-ms (u/start-timer)
assoc-ms (fn [duration-ms]
(fn [chunk]
(cond-> chunk
(= (:type chunk) :tool-output-available) (assoc ::duration-ms duration-ms))))
results (try
(let [{:keys [arguments]} (into {} (aisdk-xf) chunks)
arguments (or (coerce-stringified-json arguments) {})
decode (tool-decode-fn tool)
arguments (cond-> arguments decode decode)]
(log/debug "Executing tool" {:tool-name tool-name :arguments arguments})
(let [tool-fn (tool-call-fn tool)
result (tool-fn arguments)]
(log/debug "Tool returned" {:tool-name tool-name :result-type (type result)})
(collect-tool-result tool-call-id tool-name result)))
(catch Exception e
(if (:agent-error? (ex-data e))
(log/debugf "Tool %s: agent validation error: %s" tool-name (ex-message e))
(log/warn e "Tool execution failed" {:tool-name tool-name}))
[{:type :tool-output-available
:toolCallId tool-call-id
:toolName tool-name
:error {:message (concise-tool-error e)
:type (str (type e))}}]))]
(mapv (assoc-ms (u/since-ms start-ms))
results))))
(ait/with-tool-call {:ai/tool-name tool-name
:ai/tool-call-id tool-call-id}
(with-span :info {:name :metabot.agent/run-tool
:tool-name tool-name
:tool-call-id tool-call-id}
(let [start-ms (u/start-timer)
assoc-ms (fn [duration-ms]
(fn [chunk]
(cond-> chunk
(= (:type chunk) :tool-output-available) (assoc ::duration-ms duration-ms))))
results (try
(let [{:keys [arguments]} (into {} (aisdk-xf) chunks)
arguments (or (coerce-stringified-json arguments) {})
decode (tool-decode-fn tool)
arguments (cond-> arguments decode decode)]
(log/debug "Executing tool" {:tool-name tool-name :arguments arguments})
(when (ait/capture-active?)
(ait/record! {:ai/tool-args arguments}))
(let [tool-fn (tool-call-fn tool)
result (tool-fn arguments)]
(log/debug "Tool returned" {:tool-name tool-name :result-type (type result)})
(collect-tool-result tool-call-id tool-name result)))
(catch Exception e
(if (:agent-error? (ex-data e))
(log/debugf "Tool %s: agent validation error: %s" tool-name (ex-message e))
(log/warn e "Tool execution failed" {:tool-name tool-name}))
[{:type :tool-output-available
:toolCallId tool-call-id
:toolName tool-name
:error {:message (concise-tool-error e)
:type (str (type e))}}]))]
(when (ait/capture-active?)
(ait/record! {:ai/tool-output results}))
(mapv (assoc-ms (u/since-ms start-ms))
results)))))
(defn tool-executor-xf
"Transducer that executes tool calls in parallel on virtual threads.

21
test/metabase/agent_api/api_test.clj
View File

@@ -8,6 +8,8 @@
[java-time.api :as t]
[metabase.agent-api.api :as agent-api.api]
[metabase.agent-api.settings :as agent-api.settings]
[metabase.ai-tracing.log :as ait.log]
[metabase.ai-tracing.settings :as ai-tracing.settings]
[metabase.collections.models.collection :as collection]
[metabase.lib.core :as lib]
[metabase.lib.metadata :as lib.metadata]
@@ -93,6 +95,25 @@
(is (= "AI features are not enabled."
(mt/user-http-request :rasta :get 403 "agent/v1/ping"))))))
(deftest eval-tracing-wraps-agent-api-requests-test
(testing "with capture on, the routes wrapper opens a span recording status/response/user-id"
(let [nodes (atom [])]
;; Force capture on and collect the emitted spans in-memory (redef the sink so no file is
;; written). The wrapper mints a fresh session per direct HTTP request.
(mt/with-dynamic-fn-redefs [ai-tracing.settings/ai-eval-capture (constantly true)
ait.log/emit! (fn [node _session-id]
(swap! nodes conj node)
nil)]
(is (= {:message "pong"} (mt/user-http-request :rasta :get 200 "agent/v1/ping")))
(let [span (first (filter #(str/starts-with? (str (:name %)) "agent-api.") @nodes))]
(is (some? span) "an agent-api.* span was emitted for the request")
(is (= "agent-api.get /api/agent/v1/ping" (:name span)))
(is (= 200 (get-in span [:attributes :http/status])))
;; the plain-data body is recorded (a streaming body would be omitted, not stringified)
(is (= {:message "pong"} (get-in span [:attributes :http/response])))
;; +auth binds *current-user-id* inside the handler, so the respond-time record! sees rasta
(is (= (mt/user->id :rasta) (get-in span [:attributes :http/user-id]))))))))
;;; ------------------------------------------------- Functional Tests --------------------------------------------------
(deftest search-test

57
test/metabase/ai_tracing/api_test.clj Normal file
View File

@@ -0,0 +1,57 @@
(ns metabase.ai-tracing.api-test
(:require
[clojure.java.io :as io]
[clojure.string :as str]
[clojure.test :refer [deftest is testing use-fixtures]]
[metabase.ai-tracing.api :as ait.api]
[metabase.ai-tracing.settings :as ai-tracing.settings]
[metabase.test :as mt]
[metabase.test.fixtures :as fixtures])
(:import
(java.io File)))
(set! *warn-on-reflection* true)
(use-fixtures :once (fixtures/initialize :db :test-users))
(deftest ^:parallel trace-file-rejects-unsafe-ids-test
(testing "trace-file returns nil for any id that could escape the trace dir (path traversal)"
(doseq [bad ["../../etc/passwd" "a/b" ".." "." ".hidden" "has space" "" "foo/../bar" "/abs"]]
(is (nil? (#'ait.api/trace-file bad))
(str "should reject " (pr-str bad))))))
(deftest ^:parallel trace-file-resolves-safe-id-test
(testing "a safe id resolves to a <id>.jsonl file sitting directly inside the trace dir"
(let [^File f (#'ait.api/trace-file "abc-123.def_4")]
(is (some? f))
(is (= "abc-123.def_4.jsonl" (.getName f)))
(is (= (.getCanonicalFile ^File (#'ait.api/trace-dir))
(.getParentFile f))
"defense in depth: the resolved file's parent is the canonical trace dir"))))
;;; -------------------------------------------- Endpoint (integration) ---------------------------------------------
;; Not ^:parallel: redefs the capture setting and writes to the real trace dir.
(deftest endpoint-gated-on-capture-then-superuser-test
(testing "the route is invisible (404) when MB_AI_EVAL_CAPTURE is off — the default"
(mt/user-http-request :crowberto :get 404 "eval-trace/some-id"))
(mt/with-dynamic-fn-redefs [ai-tracing.settings/ai-eval-capture (constantly true)]
(testing "with capture on, a non-superuser is forbidden (traces hold unredacted content)"
(mt/user-http-request :rasta :get 403 "eval-trace/some-id"))
(testing "with capture on, a superuser gets 404 for a session with no trace file"
(is (re-find #"Eval trace not found"
(str (mt/user-http-request :crowberto :get 404 "eval-trace/no-such-session")))))))
(deftest endpoint-streams-the-trace-file-test
(mt/with-dynamic-fn-redefs [ai-tracing.settings/ai-eval-capture (constantly true)]
(let [sid (str "eval-api-test-" (random-uuid))
^File f (#'ait.api/trace-file sid)]
(io/make-parents f)
(spit f "{\"session\":\"s\",\"id\":\"n1\"}\n{\"session\":\"s\",\"id\":\"n2\"}\n")
(try
(testing "a superuser gets a 200 resolving to that session's <id>.jsonl (Ring streams the file)"
;; The test client surfaces the File body as its path rather than streaming its bytes, so we
;; assert the endpoint resolved to the right file at 200 — the byte-streaming is Ring's job.
(let [body (str (mt/user-http-request :crowberto :get 200 (str "eval-trace/" sid)))]
(is (str/includes? body (str sid ".jsonl")))))
(finally (.delete f))))))

142
test/metabase/ai_tracing/core_test.clj Normal file
View File

@@ -0,0 +1,142 @@
(ns metabase.ai-tracing.core-test
(:require
[clojure.test :refer [deftest is testing]]
[metabase.ai-tracing.core :as ait]
[metabase.ai-tracing.log :as ait.log]
[metabase.ai-tracing.settings :as ai-tracing.settings]
[metabase.test :as mt]))
(set! *warn-on-reflection* true)
(deftest ^:parallel gate-inert-without-binding-test
(testing "with no capture binding, ops are inert (production safety) but the body still runs"
(is (false? (ait/capture-active?)))
(let [ran (atom false)]
(is (= 42 (ait/with-agent-turn {:ai/profile-id "p"}
(reset! ran true)
(ait/record! {:ai/x 1}) ; no-op, must not throw
42)))
(is (true? @ran) "body ran"))
(is (false? (ait/capture-active?)) "binding did not leak")))
(deftest ^:parallel capture-nesting-test
(testing "capturing builds a nested turn -> llm -> tool tree"
(let [{:keys [result trace]}
(ait/capturing
(ait/with-agent-turn {:ai/profile-id "internal"}
(ait/with-llm-call {:ai/model "m" :ai/iteration 0}
(ait/record! {:ai/output-text "hi"})
(ait/with-tool-call {:ai/tool-name "search"}
(ait/record! {:ai/tool-args {:q "x"} :ai/tool-output [{:r 1}]})
:tool-done))
:turn-done))]
(is (= :turn-done result))
(is (= 1 (count trace)))
(let [turn (first trace)
llm (first (:children turn))
tool (first (:children llm))]
(is (= :turn (:type turn)))
(is (= "agent.turn" (:name turn)))
(is (= :llm (:type llm)))
(is (= "hi" (get-in llm [:attributes :ai/output-text])))
(is (= :tool (:type tool)))
(is (= "tool.search" (:name tool)))
(is (= {:q "x"} (get-in tool [:attributes :ai/tool-args])))))))
(deftest ^:parallel record-test
(testing "record! merges attrs onto the current span"
(let [{:keys [trace]}
(ait/capturing
(ait/with-llm-call {:ai/model "m"}
(ait/record! {:ai/output-text "a"})
(ait/record! {:ai/iteration 2})
:ok))
llm (first trace)]
(is (= "a" (get-in llm [:attributes :ai/output-text])))
(is (= 2 (get-in llm [:attributes :ai/iteration]))))))
(deftest ^:parallel timing-fields-test
(testing "finished spans carry a precise duration + wall-clock epoch millis"
(let [{:keys [trace]} (ait/capturing (ait/with-llm-call {} (Thread/sleep 2) :ok))
llm (first trace)]
(is (number? (:duration-ms llm)))
(is (<= 0 (:duration-ms llm)))
(is (integer? (:start-epoch-ms llm)))
(is (integer? (:end-epoch-ms llm)))
(is (<= (long (:start-epoch-ms llm)) (long (:end-epoch-ms llm))))
(is (nil? (:start-ns llm)) "internal monotonic marker stripped from finished node"))))
(deftest ^:parallel error-recorded-and-rethrown-test
(testing "an exception in a span body is recorded as an event, attaches the node, and re-throws"
(let [sink (atom [])]
(is (thrown? Exception
(binding [ait/*capture* sink ait/*parent* nil ait/*retain-tree* true]
(ait/with-llm-call {:ai/model "m"}
(throw (ex-info "boom" {}))))))
(let [llm (first @sink)]
(is (= :llm (:type llm)))
(is (= [:error] (mapv :event (:events llm))))))))
(deftest ^:parallel concurrent-tools-nest-correctly-test
(testing "tools on separate threads (bound-fn conveyance) nest under the right parent"
(let [{:keys [trace]}
(ait/capturing
(ait/with-llm-call {:ai/model "m"}
(let [fs (mapv (fn [i]
(let [f (bound-fn []
(ait/with-tool-call {:ai/tool-name (str "t" i)}
(Thread/sleep 3) i))]
(future (f))))
(range 4))]
(mapv deref fs))))
llm (first trace)]
(is (= :llm (:type llm)))
(is (= 4 (count (:children llm))))
(is (= #{"tool.t0" "tool.t1" "tool.t2" "tool.t3"}
(set (map :name (:children llm))))))))
;; Not ^:parallel: references the destructive `emit!` (redef'd to a no-op here), which the
;; `validate-deftest` lint disallows in parallel tests regardless of the thread-local redef.
(deftest capture-reducible-test
(testing "capture-reducible realizes a reducible and returns {:result :trace}"
;; redef the sink so the test never writes a trace file
(mt/with-dynamic-fn-redefs [ait.log/emit! (constantly nil)]
(let [reducible (reify clojure.lang.IReduceInit
(reduce [_ rf init]
(ait/with-agent-turn {:ai/profile-id "p"}
(-> init (rf {:type :text :text "a"}) (rf {:type :text :text "b"})))))
{:keys [result trace]} (ait/capture-reducible reducible)]
(is (= [{:type :text :text "a"} {:type :text :text "b"}] result))
(is (= 1 (count trace)))
(is (= "agent.turn" (:name (first trace))))))))
;; Not ^:parallel: redefs the destructive `emit!` to a spy.
(deftest capturing-writes-no-file-test
(testing "capturing does NOT mint a session id, so emit! gets nil and writes no <id>.jsonl"
(let [sessions (atom [])]
(mt/with-dynamic-fn-redefs [ait.log/emit! (fn [_node session-id] (swap! sessions conj session-id) nil)]
(let [{:keys [trace]} (ait/capturing (ait/with-llm-call {:ai/model "m"} :ok))]
(is (= 1 (count trace)) "the span still comes back in :trace")
(is (= [nil] @sessions)
"emit! received a nil session-id (no file routing); the trace is the return value only"))))))
(deftest ^:parallel checked-session-id-test
(testing "supplied ids that name a safe file pass through verbatim"
(is (= "abc-123.def_4" (ait/checked-session-id "abc-123.def_4"))))
(testing "a nil supplied id mints a fresh uuid"
(let [id (ait/checked-session-id nil)]
(is (string? id))
(is (uuid? (parse-uuid id)))))
(testing "unsafe ids throw rather than reaching the log-file path (no traversal)"
(doseq [bad ["../../etc/passwd" ".." "a/b" ".hidden" "has space" ""]]
(is (thrown? clojure.lang.ExceptionInfo (ait/checked-session-id bad))
(str "should reject " (pr-str bad))))))
(deftest ^:parallel with-eval-session-rejects-unsafe-id-test
(testing "with-eval-session validates a caller-supplied id when capture is enabled"
(mt/with-dynamic-fn-redefs [ai-tracing.settings/ai-eval-capture (constantly true)]
(is (thrown? clojure.lang.ExceptionInfo
(ait/with-eval-session "../../pwned" :body)))))
(testing "with the gate off it stays inert — the body runs, no validation"
(mt/with-dynamic-fn-redefs [ai-tracing.settings/ai-eval-capture (constantly false)]
(is (= :body (ait/with-eval-session "../../pwned" :body))))))

160
test/metabase/ai_tracing/log_test.clj Normal file
View File

@@ -0,0 +1,160 @@
(ns metabase.ai-tracing.log-test
(:require
[clojure.test :refer [deftest is testing]]
;; needed to install a recording logger factory for the MDC-routing probe; no util.log equivalent
^{:clj-kondo/ignore [:discouraged-namespace]}
[clojure.tools.logging]
^{:clj-kondo/ignore [:discouraged-namespace]}
[clojure.tools.logging.impl]
[metabase.ai-tracing.core :as ait]
[metabase.ai-tracing.log :as ait.log]
[metabase.ai-tracing.settings :as ai-tracing.settings]
[metabase.test :as mt]
[metabase.util.json :as json]
[metabase.util.log.capture :as log.capture])
(:import
(org.apache.logging.log4j ThreadContext)))
(set! *warn-on-reflection* true)
(defn- entries
"Parse captured `metabase.ai-tracing.log` messages (raw JSONL) into maps with string keys."
[messages-fn]
(mapv (comp json/decode :message) (messages-fn)))
(deftest ^:parallel node->entry-shape-test
(testing "node->entry serializes a finished node + session into the JSONL map (string keys after encode)"
(let [node {:type :llm :name "llm.call" :id "n1" :parent-id "p0"
:attributes {:ai/model "claude" :ai/output-text "hi"}
:events [{:event :note}]
:duration-ms 12.5 :start-epoch-ms 1000 :end-epoch-ms 2000}
e (#'ait.log/node->entry node "sess-1")]
(is (= {:session "sess-1" :id "n1" :parent "p0" :type :llm :name "llm.call"
:start-epoch-ms 1000 :end-epoch-ms 2000 :dur-ms 12.5
:attributes {:ai/model "claude" :ai/output-text "hi"}
:events [{:event :note}]}
e))
(testing "round-trips through JSON cleanly"
(let [j (json/decode (json/encode e))]
(is (= "sess-1" (get j "session")))
(is (= "llm" (get j "type")))
(is (= "claude" (get-in j ["attributes" "ai/model"]))))))))
(deftest emit-degrades-non-encodable-attrs-test
(testing "a non-encodable attribute value degrades to a string instead of dropping the whole span"
(log.capture/with-log-messages-for-level [messages [metabase.ai-tracing.log :info]]
;; a bare Object has no JSON encoding — the direct encode throws and we fall back to json-safe
(ait.log/emit! {:type :turn :name "agent.turn" :id "n" :parent-id nil
:attributes {:ai/final-state (Object.) :ai/model "m"} :events []
:duration-ms 1.0 :start-epoch-ms 1 :end-epoch-ms 2}
"sess-x")
(let [es (entries messages)]
(is (= 1 (count es)) "span still emitted despite the non-encodable attribute")
(is (= "agent.turn" (get (first es) "name")))
(is (= "m" (get-in (first es) ["attributes" "ai/model"])) "encodable attrs are preserved")
(is (string? (get-in (first es) ["attributes" "ai/final-state"]))
"the non-encodable value degraded to a string")))))
(deftest emit-degrades-non-encodable-map-key-test
(testing "a map attribute with a non-scalar KEY still emits — json-safe must not itself throw"
(log.capture/with-log-messages-for-level [messages [metabase.ai-tracing.log :info]]
;; A vector-keyed map is rejected by the JSON encoder AND by json-safe's value-only recursion
;; before the fix — the re-encode would throw and drop the (root) span. The key must stringify.
(ait.log/emit! {:type :turn :name "agent.turn" :id "n" :parent-id nil
:attributes {:ai/data {[1 2] "v"}} :events []
:duration-ms 1.0 :start-epoch-ms 1 :end-epoch-ms 2}
"sess-x")
(let [es (entries messages)]
(is (= 1 (count es)) "span still emitted despite the non-scalar map key")
(is (= "v" (get-in (first es) ["attributes" "ai/data" "[1 2]"]))
"the non-scalar key degraded to a string, value preserved")))))
(deftest one-entry-per-span-test
(testing "each finished span streams exactly one JSONL line, carrying the session id in the payload"
;; Drive the file-routed path (with-eval-session), which is what emits to the sink. `capturing`
;; deliberately leaves *session-id* nil so emit! no-ops (its trace comes back as :trace instead).
(mt/with-dynamic-fn-redefs [ai-tracing.settings/ai-eval-capture (constantly true)]
(log.capture/with-log-messages-for-level [messages [metabase.ai-tracing.log :info]]
(ait/with-eval-session "one-per-span-sid"
(ait/with-agent-turn {:ai/profile-id "p"}
(ait/with-llm-call {:ai/model "m"}
(ait/with-tool-call {:ai/tool-name "search"} :ok))))
(let [es (entries messages)]
(is (= 3 (count es)) "one line per span (turn, llm, tool)")
(is (= #{"agent.turn" "llm.call" "tool.search"} (set (map #(get % "name") es))))
(is (= ["one-per-span-sid"] (distinct (map #(get % "session") es))) "all share one session")
(is (every? #(get % "session") es)))))))
(deftest nesting-parent-chain-test
(testing "parent ids chain turn -> llm -> tool; root has no parent"
(mt/with-dynamic-fn-redefs [ai-tracing.settings/ai-eval-capture (constantly true)]
(log.capture/with-log-messages-for-level [messages [metabase.ai-tracing.log :info]]
(ait/with-eval-session "nesting-sid"
(ait/with-agent-turn {}
(ait/with-llm-call {}
(ait/with-tool-call {:ai/tool-name "t"} :ok))))
(let [by-name (into {} (map (juxt #(get % "name") identity)) (entries messages))
turn (by-name "agent.turn")
llm (by-name "llm.call")
tool (by-name "tool.t")]
(is (nil? (get turn "parent")))
(is (= (get turn "id") (get llm "parent")))
(is (= (get llm "id") (get tool "parent"))))))))
(deftest session-mint-vs-supplied-test
(mt/with-dynamic-fn-redefs [ai-tracing.settings/ai-eval-capture (constantly true)]
(testing "with-eval-session supplies the session id verbatim"
(log.capture/with-log-messages-for-level [messages [metabase.ai-tracing.log :info]]
(ait/with-eval-session "supplied-sid"
(ait/with-llm-call {} :ok))
(is (= ["supplied-sid"] (distinct (map #(get % "session") (entries messages)))))))
(testing "with-eval-session mints a fresh uuid when none supplied"
(log.capture/with-log-messages-for-level [messages [metabase.ai-tracing.log :info]]
(ait/with-eval-session nil
(ait/with-llm-call {} :ok))
(let [sid (get (first (entries messages)) "session")]
(is (string? sid))
(is (not= "supplied-sid" sid)))))))
(deftest session-inheritance-test
(testing "a nested with-eval-session inherits the outer session (no re-mint)"
(mt/with-dynamic-fn-redefs [ai-tracing.settings/ai-eval-capture (constantly true)]
(log.capture/with-log-messages-for-level [messages [metabase.ai-tracing.log :info]]
(ait/with-eval-session "outer"
(ait/with-agent-turn {}
(ait/with-eval-session "inner-should-be-ignored"
(ait/with-llm-call {} :ok))))
(is (= ["outer"] (distinct (map #(get % "session") (entries messages)))))))))
(deftest inert-when-disabled-test
(testing "with-eval-session emits nothing when capture is disabled"
(mt/with-dynamic-fn-redefs [ai-tracing.settings/ai-eval-capture (constantly false)]
(log.capture/with-log-messages-for-level [messages [metabase.ai-tracing.log :info]]
(is (= :ok (ait/with-eval-session nil (ait/with-llm-call {} :ok))))
(is (= [] (entries messages)))))))
#_{:clj-kondo/ignore [:metabase/test-helpers-use-non-thread-safe-functions]}
(defn- recording-logger-factory
"A tools.logging factory that records the Log4j2 ThreadContext present at each write."
[sink]
(reify clojure.tools.logging.impl/LoggerFactory
(name [_] "recording")
(get-logger [_ _logger-ns]
(reify clojure.tools.logging.impl/Logger
(enabled? [_ _level] true)
(write! [_ _level _throwable message]
(swap! sink conj {:mdc (into {} (ThreadContext/getImmutableContext))
:message message}))))))
(deftest mdc-routing-key-test
(testing "emit! sets mb-eval-session-id in the ThreadContext at log time (drives RoutingAppender)"
(let [sink (atom [])]
(binding [clojure.tools.logging/*logger-factory* (recording-logger-factory sink)]
(ait.log/emit! {:type :llm :name "llm.call" :id "n" :parent-id nil
:attributes {} :events [] :duration-ms 1.0
:start-epoch-ms 1 :end-epoch-ms 2}
"route-me"))
(is (= 1 (count @sink)))
(is (= "route-me" (get-in (first @sink) [:mdc "mb-eval-session-id"]))
"the routing key is set on the logging thread")
(is (= "route-me" (get (json/decode (:message (first @sink))) "session"))))))

28
test/metabase/mcp/api_test.clj
View File

@@ -4,6 +4,7 @@
[clojure.test :refer :all]
[clojure.walk :as walk]
[metabase.agent-api.settings :as agent-api.settings]
[metabase.ai-tracing.core :as ait]
[metabase.api.macros.scope :as scope]
[metabase.collections.models.collection :as collection]
[metabase.lib.core :as lib]
@@ -269,6 +270,29 @@
delete-response (mcp-delete {"mcp-session-id" session-id})]
(is (= 200 (:status delete-response))))))
(deftest ^:parallel eval-session-override-test
(testing "the x-eval-session-id header is honored only when it's a safe trace-file name"
(let [override #'mcp.api/eval-session-override]
(testing "a bare uuid (what the harness mints) is honored"
(is (= "1ae768c9-5773-48dd-afca-c75780dae84c"
(override {:headers {"x-eval-session-id" "1ae768c9-5773-48dd-afca-c75780dae84c"}}))))
(testing "a safe slug is honored"
(is (= "evalprobe_1.2" (override {:headers {"x-eval-session-id" "evalprobe_1.2"}}))))
(testing "path traversal / unsafe chars are rejected (fall back to the Mcp-Session-Id)"
(is (nil? (override {:headers {"x-eval-session-id" "../etc/passwd"}})))
(is (nil? (override {:headers {"x-eval-session-id" "a/b"}})))
(is (nil? (override {:headers {"x-eval-session-id" ".hidden"}}))))
(testing "a value over max-session-id-length is rejected even though every char is safe"
;; 201 chars: regex-safe but one past the real cap — the boundary a looser copy of the
;; contract would wrongly accept (and then 500 downstream in checked-session-id).
(is (= 200 ait/max-session-id-length))
(is (nil? (override {:headers {"x-eval-session-id" (apply str (repeat 201 "a"))}})))
(testing "the id exactly at the cap is honored, returned verbatim"
(let [id (apply str (repeat 200 "a"))]
(is (= id (override {:headers {"x-eval-session-id" id}}))))))
(testing "absent header yields nil"
(is (nil? (override {:headers {}})))))))
(def ^:private all-tool-names
#{"construct_query"
"construct_native_query"
@@ -1318,7 +1342,7 @@
(defn- dispatch-initialized-request [msg token-scopes]
(let [session-id (str (random-uuid))]
(#'mcp.api/dispatch-request msg session-id token-scopes nil)))
(#'mcp.api/dispatch-request msg session-id token-scopes nil nil)))
(defn- with-scoped-test-resource! [f]
(let [registry @#'mcp.resources/registry
@@ -1365,6 +1389,7 @@
(jsonrpc-request "resources/list")
"session-id"
#{"agent:other"}
nil
nil)
uris (set (map :uri (get-in response [:result :resources])))]
(is (contains? uris construct-query-uri)
@@ -1378,6 +1403,7 @@
(jsonrpc-request "resources/list")
"session-id"
#{"agent:search"}
nil
nil)
uris (set (map :uri (get-in response [:result :resources])))]
(is (contains? uris scoped-test-uri)))))))

84
test/metabase/metabot/agent/core_test.clj
View File

@@ -1,6 +1,9 @@
(ns metabase.metabot.agent.core-test
(:require
[clojure.test :refer :all]
[metabase.ai-tracing.core :as ait]
[metabase.ai-tracing.log :as ait.log]
[metabase.ai-tracing.settings :as ai-tracing.settings]
[metabase.analytics-interface.core :as analytics]
[metabase.analytics.snowplow-test :as snowplow-test]
[metabase.lib.core :as lib]
@@ -19,6 +22,15 @@
(def ^:private test-provider "openrouter/anthropic/claude-haiku-4-5")
;; Pin eval-capture OFF for the whole namespace so the exact stream-shape assertions below are
;; deterministic regardless of the ambient MB_AI_EVAL_CAPTURE — a dedicated eval instance sets it,
;; which would otherwise append an extra `eval_session` data part to every agent stream and break
;; every `=?` on `run-agent-loop` output. The capture-ON path is covered by `eval-tracing-nesting-test`,
;; which forces capture via `capture-reducible` (independent of this gate) and is unaffected here.
(use-fixtures :each (fn [thunk]
(mt/with-dynamic-fn-redefs [ai-tracing.settings/ai-eval-capture (constantly false)]
(thunk))))
(defn- run-agent-loop!
"run-agent-loop for side effects, discarding results.
Runs as admin so the base metabot permission check passes."
@@ -371,6 +383,78 @@
(is (= 3 @llm-call-count)
"Should have exactly 3 LLM calls (search, construct, final text)")))))))))
(deftest eval-tracing-nesting-test
(testing "capture-reducible over the real agent loop builds a turn -> llm -> tool span tree"
;; This exercises the cross-module wiring the ai-tracing docstrings promise: the turn/llm spans
;; are opened in metabase.metabot.agent.core, the tool span in metabase.metabot.self.core, and
;; the tool runs on the virtual-thread executor — so this also proves *parent* is conveyed across
;; `bound-fn*` into the tool thread. Only the LLM + search backend are mocked; everything else is
;; real. `capture-reducible` binds the capture unconditionally (ignores MB_AI_EVAL_CAPTURE), and
;; we redef `emit!` to a no-op so the test never writes a per-session JSONL file.
(mt/with-current-user (mt/user->id :crowberto)
(mt/with-temporary-setting-values [llm-metabot-provider test-provider]
(let [llm-call-count (atom 0)
llm-responses [;; Iteration 1: call the search tool (produces a real tool span)
[{:type :start :id "msg-1"}
{:type :tool-input
:id "call-search-1"
:function "search"
:arguments {:semantic_queries ["orders table"]
:keyword_queries ["orders"]
:entity_types ["table"]}}
{:type :usage :usage {:promptTokens 100 :completionTokens 20}
:model "test" :id "msg-1"}]
;; Iteration 2: final text (no tool)
[{:type :start :id "msg-2"}
{:type :text :text "Here are your orders."}
{:type :usage :usage {:promptTokens 200 :completionTokens 10}
:model "test" :id "msg-2"}]]]
(mt/with-dynamic-fn-redefs [ait.log/emit! (fn [& _] nil)
openrouter/openrouter (fn [_opts]
(let [n (swap! llm-call-count inc)]
(mut/mock-llm-response (get llm-responses (dec n) []))))
metabot-search/search (fn [_args]
[{:id (mt/id :orders)
:type "table"
:name "orders"
:display_name "Orders"
:description "Confirmed orders."
:database_id (mt/id)}])]
(let [{:keys [trace result]} (mt/with-log-level [metabase.metabot.agent.core :warn]
(ait/capture-reducible
(agent/run-agent-loop
{:messages [{:role :user :content "Show me orders"}]
:state {}
:profile-id :internal
:context {}})))]
(is (= 2 @llm-call-count) "search iteration + final text iteration")
(is (= 1 (count trace)) "single root span")
(testing "the in-process (file-less) path emits no eval_session pointer into the stream"
;; capture-reducible leaves *session-id* nil (trace comes back as :trace, no file), so
;; a pointer here would name a <nil>.jsonl that never exists.
(is (empty? (filter #(= "eval_session" (:data-type %)) result))))
(let [turn (first trace)
llms (:children turn)
tool-spans (mapcat :children llms)
search (first (filter #(= "tool.search" (:name %)) tool-spans))]
(testing "root is the agent turn"
(is (= :turn (:type turn)))
(is (= "agent.turn" (:name turn)))
(is (nil? (:parent-id turn))))
(testing "each iteration is an llm.call child of the turn"
(is (= 2 (count llms)))
(is (every? #(= :llm (:type %)) llms))
(is (every? #(= (:id turn) (:parent-id %)) llms)))
(testing "the search tool span nests under the llm.call it ran in"
(is (= :tool (:type search)))
;; the decoded tool arguments are recorded on the span (metabase.metabot.self.core)
(is (= {:semantic_queries ["orders table"]
:keyword_queries ["orders"]
:entity_types ["table"]}
(get-in search [:attributes :ai/tool-args])))
(let [parent-llm (first (filter #(= (:parent-id search) (:id %)) llms))]
(is (some? parent-llm) "tool's parent-id resolves to an llm.call in the tree")))))))))))
(deftest cumulative-usage-test
(mt/as-admin
(mt/with-temporary-setting-values [llm-metabot-provider test-provider]

6
test_config/log4j2-test.xml
View File

@@ -25,6 +25,12 @@
<Logger name="metabase" level="INFO"/>
<Logger name="metabase-enterprise" level="INFO"/>
<!-- Eval-trace sink (metabase.ai-tracing): additivity=false with no appender keeps the JSONL
spans out of the shared test log. Tests that assert on emitted spans attach their own
appender via metabase.util.log.capture, so this does not hide them. Mirrors the prod
resources/log4j2.xml, minus the per-session RoutingAppender (tests don't read the files). -->
<Logger name="metabase.ai-tracing.log" level="info" additivity="false"/>
<Logger name="metabase.test.gentest" level="INFO" additivity="false">
<AppenderRef ref="ConsoleInfoLevel"/>
<AppenderRef ref="Console"/>