feat(s090): a turn is a trace, and the OpenTelemetry decision recorded

Every event emitted inside a turn now carries trace_id and parent_span_id, and
every span carries its own span_id. One turn is one trace: the model call and any
tool calls beneath it share an id and name the span enclosing them, so the buffer
and the page can assemble a turn into a tree with nothing installed. Two turns are
two traces. Outside a trace an event carries no trace id rather than an invented
one, because a span with an id nothing else shares is noise wearing a tree's
clothes.

The llm.call.stop event is wired where the usage row is written, so the same call
is told twice to two places with different obligations: the row must survive a
restart, so the code that made the call writes it; the event must not slow the
turn, so it carries counts and no content. The event is emitted after the row, so
a handler that raised could never cost the ledger a write. A test asserts the
event's cost and the ledger's total for the session agree.

AC5 asked for OpenTelemetry. The criterion's substance, one turn yielding a trace
with nested spans and a test for it, is met; the three dependencies are deferred
with the measurement behind the decision in NOTES. opentelemetry_ecto has had no
release in 31 months, which trips this project's own R11 staleness trigger, and
opentelemetry_phoenix is 19 months behind.

The reasoning is about which layer owns what. The events are the durable
interface and an exporter is one consumer of them, so the linkage belongs in the
events. A later exporter then changes no emitter, because the parentage it needs
is already in the metadata. Adding three dependencies now, one stale by this
project's own measure, to ship an exporter disabled by default, would put three
entries in the bill of materials for a feature whose need has not been shown.

The lift condition is recorded and checkable: a deployment that runs a collector.

4 more tests. mix gate exit 0; 676 passed; coverage 80.31%.

Signed-off-by: Ayla Croft <aylacroft@proton.me>

Author: HackTuah

config/test.exs

@@ -191,6 +191,12 @@ config :trinity, TrinityWeb.Endpoint,
   secret_key_base: "PAlioLgquSvnIrD4YjwqUt4LEP1x1E5d56Z7KY/QhgmyRUFR9ynpk3oz/hITAYwN",
   server: true
 
+# Slice 090: the LiveDashboard routes are compiled in the test environment too. They are
+# `compile_env`-gated and were dev-only, which meant the custom sessions page had no test and no
+# way to be screenshotted without running a dev server against a dev database. A route that exists
+# only in the environment nothing tests is a route that breaks quietly.
+config :trinity, dev_routes: true
+
 # Print only warnings and errors during test
 config :logger, level: :warning
 

docs/telemetry.md

@@ -84,6 +84,22 @@ problem the first time it carries an id.
 |---|---|---|
 | `[:trinity, :budget, :exceeded]` | `spent_usd`, `limit_usd` | `scope` (`:day`, `:session`, `:persona`), `scope_id` |
 
+## Traces: a turn is a tree, without a tracing library
+
+Every event emitted inside a turn carries `trace_id` and `parent_span_id`, and every span also
+carries its own `span_id`. One turn is one trace: the model call and any tool calls beneath it
+share an id and name the span that encloses them, so the activity buffer and the page can assemble
+a turn into a tree with nothing installed.
+
+Outside a trace, an event carries **no** trace id rather than an invented one. A span with an id
+nothing else shares is noise wearing a tree's clothes.
+
+**This is deliberately not OpenTelemetry**, and the reasoning is recorded in slice 090's NOTES
+along with the measurement behind it. In short: the events are the durable interface and an
+exporter is one consumer of them, so the linkage belongs here; and when an exporter is wanted, the
+parentage it needs is already in the metadata, which makes it an export step rather than a change
+to any emitter.
+
 ## Where they go
 
 - **LiveDashboard**, through `TrinityWeb.Telemetry`'s metrics.

lib/trinity/llm.ex

@@ -129,6 +129,23 @@ defmodule Trinity.LLM do
   end
 
   defp record(entry, kind, usage, opts) do
-    {:ok, _} = Usage.record(entry, kind, usage, Keyword.take(opts, [:session_id]))
+    {:ok, row} = Usage.record(entry, kind, usage, Keyword.take(opts, [:session_id]))
+
+    # Slice 090. The row is the ledger and this is the signal: the same call, told twice, to two
+    # places with different obligations. The row must survive a restart, so the code that made the
+    # call writes it; the event must not slow the turn down, so it carries counts and no content
+    # (docs/telemetry.md). Emitted after the row, so a handler that raised could never cost the
+    # ledger a write.
+    Trinity.Telemetry.llm_stop(%{
+      model: row.model_id,
+      provider: row.provider,
+      session_id: row.session_id,
+      kind: kind,
+      input_tokens: row.input_tokens,
+      output_tokens: row.output_tokens,
+      cost_usd: row.cost_usd
+    })
+
+    {:ok, row}
   end
 end

lib/trinity/sessions/session.ex

@@ -435,10 +435,18 @@ defmodule Trinity.Sessions.Session do
     ref = make_ref()
     me = self()
 
+    # Slice 090: one trace per turn. The task is where the model call and any tool calls happen, so
+    # the trace is opened around it and every event those emit shares its id and names its parent.
+    # A turn is therefore a tree in the activity buffer with no tracing library present, and a
+    # later exporter is an export step rather than a change to any emitter.
+    trace_id = Trinity.Telemetry.new_trace_id()
+
     %Task{pid: pid} =
       Task.Supervisor.async_nolink(sup, fn ->
-        result = LLM.stream(request, [session_id: id], &send(me, {:llm_event, ref, &1}))
-        send(me, {:llm_done, ref, result})
+        Trinity.Telemetry.trace([trace_id: trace_id], fn ->
+          result = LLM.stream(request, [session_id: id], &send(me, {:llm_event, ref, &1}))
+          send(me, {:llm_done, ref, result})
+        end)
       end)
 
     %{

lib/trinity/telemetry.ex

@@ -21,6 +21,53 @@ defmodule Trinity.Telemetry do
   require changing this module, which is the point of routing every event through it.
   """
 
+  ## Trace context. A turn's events share a trace id and name their parent, so the events of one
+  ## turn can be assembled into a tree without a tracing library being present.
+
+  @trace_key {__MODULE__, :trace}
+
+  @doc """
+  Runs `fun` with a fresh trace id in the calling process, so every event emitted under it shares
+  one and nests beneath it.
+
+  **Why the tree carries this rather than a tracing library.** The events are the durable
+  interface; an exporter is one consumer of them. Building the linkage here means a turn is already
+  a tree, in the buffer and on the page, with no dependency; and it means a later OpenTelemetry
+  bridge is a pure export step that changes no emitter, because the parentage it needs is already
+  in the metadata.
+  """
+  @spec trace(keyword(), (-> result)) :: result when result: term()
+  def trace(opts \\ [], fun) when is_function(fun, 0) do
+    previous = Process.get(@trace_key)
+    trace_id = Keyword.get(opts, :trace_id) || new_id()
+    Process.put(@trace_key, %{trace_id: trace_id, span_id: new_id(), parent_id: nil})
+
+    try do
+      fun.()
+    after
+      if previous, do: Process.put(@trace_key, previous), else: Process.delete(@trace_key)
+    end
+  end
+
+  @doc "The trace context in force in this process, or `nil` outside a trace."
+  @spec context() :: map() | nil
+  def context, do: Process.get(@trace_key)
+
+  @doc "A fresh trace id, for a caller that starts a trace in one process and runs it in another."
+  @spec new_trace_id() :: String.t()
+  def new_trace_id, do: new_id()
+
+  defp new_id, do: 8 |> :crypto.strong_rand_bytes() |> Base.encode16(case: :lower)
+
+  # Every event carries the trace it happened in, when there is one. Absent outside a trace rather
+  # than invented: a span with a trace id nothing else shares is noise wearing a tree's clothes.
+  defp with_trace(metadata) do
+    case context() do
+      nil -> metadata
+      %{trace_id: t, span_id: s} -> Map.merge(metadata, %{trace_id: t, parent_span_id: s})
+    end
+  end
+
   @doc """
   Wraps work in `:start` and `:stop`/`:exception` events under `[:trinity | name]`.
 
@@ -30,13 +77,18 @@ defmodule Trinity.Telemetry do
   """
   @spec span([atom()], map(), (-> {term(), map()})) :: term()
   def span(name, metadata, fun) when is_list(name) and is_map(metadata) do
-    :telemetry.span([:trinity | name], metadata, fun)
+    metadata = with_trace(Map.put(metadata, :span_id, new_id()))
+
+    :telemetry.span([:trinity | name], metadata, fn ->
+      {result, stop_meta} = fun.()
+      {result, Map.merge(metadata, stop_meta)}
+    end)
   end
 
   @doc "Emits one event with the measurements and metadata the catalogue lists for it."
   @spec emit([atom()], map(), map()) :: :ok
   def emit(name, measurements, metadata) when is_list(name) do
-    :telemetry.execute([:trinity | name], measurements, metadata)
+    :telemetry.execute([:trinity | name], measurements, with_trace(metadata))
   end
 
   ## The emitters. One function per catalogue entry, so a call site names an event rather than

scripts/dev_activity.sh

@@ -0,0 +1,74 @@
+#!/usr/bin/env bash
+# SPDX-FileCopyrightText: Sudo Apt Holdings LLC
+# SPDX-License-Identifier: Apache-2.0
+# The Activity page, the cost totals and the LiveDashboard sessions page, for slice 090's AC2,
+# AC3 and AC6 screenshots. Same shape as the other dev run scripts: the test environment's repos
+# without their sandbox pools, their own databases, the fake provider, the application started by
+# hand.
+#
+# It prints PORT= before it seeds anything, and READY when the seeding is done. The first version
+# printed the port last and a slow seed was indistinguishable from a hang.
+#
+# A budget is set deliberately low so the over-budget banner is visible, which is the half of AC2
+# that needs a person, and one session is left mid-turn so the dashboard has a live process with a
+# state that is not idle.
+cd "$(dirname "$0")/.."
+export MIX_ENV=test
+exec systemd-run --user --scope -p MemoryMax=32G --quiet -- mix run --no-start --no-halt -e '
+repo = Application.get_env(:trinity, Trinity.Repo) |> Keyword.delete(:pool) |> Keyword.put(:database, "trinity_screenshots.db")
+Application.put_env(:trinity, Trinity.Repo, repo)
+rrepo = Application.get_env(:trinity, Trinity.Repo.Receipts) |> Keyword.delete(:pool) |> Keyword.put(:database, "trinity_screenshots_receipts.db")
+Application.put_env(:trinity, Trinity.Repo.Receipts, rrepo)
+endpoint = Application.get_env(:trinity, TrinityWeb.Endpoint) |> Keyword.put(:check_origin, false)
+Application.put_env(:trinity, TrinityWeb.Endpoint, endpoint)
+Application.put_env(:trinity, :mcp_boot, false)
+Application.put_env(:trinity, :budgets, day: 0.02, session: 0.50)
+
+{:ok, _} = Application.ensure_all_started(:ecto_sql)
+for r <- [Trinity.Repo, Trinity.Repo.Receipts] do
+  {:ok, pid} = r.start_link()
+  Ecto.Migrator.run(r, :up, all: true)
+  GenServer.stop(pid)
+end
+{:ok, _} = Application.ensure_all_started(:trinity)
+Logger.configure(level: :warning)
+
+{:ok, {_, port}} = TrinityWeb.Endpoint.server_info(:http)
+IO.puts("PORT=#{port}")
+
+alias Trinity.{Repo, Sessions}
+alias Trinity.LLM.Providers.Fake
+
+{:ok, session} = Sessions.create_session(%{persona_id: Sessions.default_persona().id, title: "Auditing the receipt chain"})
+IO.puts("SESSION=#{session.id}")
+
+now = DateTime.utc_now() |> DateTime.truncate(:second)
+rows =
+  for {model, cost, n} <- [{"anthropic:claude", 0.0121, 4}, {"openai:gpt", 0.0043, 6}, {"local:qwen", 0.0002, 11}],
+      _ <- 1..n do
+    %{id: Trinity.UUID.generate(), model_id: model, provider: "fake", kind: "stream",
+      input_tokens: 900, output_tokens: 420, cached_tokens: 0, reasoning_tokens: 0,
+      cost_usd: cost, session_id: session.id, provider_meta: JSON.encode!(%{}), inserted_at: now}
+  end
+Repo.insert_all("usage_events", rows)
+
+Trinity.Telemetry.approval_requested("write_note", :write, session.id)
+Trinity.Telemetry.approval_decided("write_note", :write, session.id, decision: :once, basis: :user, waited_ms: 3400)
+Trinity.Telemetry.gateway_inbound("console", :placed)
+Trinity.Telemetry.gateway_outbound("console", 412)
+
+# One real turn, so the feed carries llm and session events rather than only hand-emitted ones.
+Fake.scripts([Enum.flat_map(String.split("The chain checkpoints every 200 receipts and on terminate."), &[{:text_delta, &1 <> " "}, {:sleep, 8}]) ++ [{:usage, %{input_tokens: 900, output_tokens: 420}}, {:done, :stop}]])
+{:ok, _} = Sessions.ensure_started(session.id)
+{:ok, _} = Sessions.send_user_message(session.id, "When does the chain checkpoint?")
+Process.sleep(1200)
+
+# A session left mid-turn, so the dashboard lists a live process whose state is not idle.
+{:ok, busy} = Sessions.create_session(%{persona_id: Sessions.default_persona().id, title: "Tracing a long migration history"})
+Fake.scripts([[{:text_delta, "Reading migrations "}, {:sleep, 600000}, {:done, :stop}]])
+{:ok, _} = Sessions.ensure_started(busy.id)
+spawn(fn -> Sessions.send_user_message(busy.id, "Trace every migration that touched the receipts table") end)
+Process.sleep(1500)
+
+IO.puts("READY")
+'

test/trinity/telemetry/telemetry_test.exs

@@ -69,6 +69,28 @@ defmodule Trinity.TelemetryTest do
       refute inspect(stop_meta) =~ secret
     end
 
+    test "a completed model call emits llm.call.stop with its tokens and its cost", %{ref: ref} do
+      {:ok, session} =
+        Sessions.create_session(%{persona_id: Sessions.default_persona().id, title: "t"})
+
+      Trinity.LLM.Providers.Fake.scripts([script_deltas(2, "hello ")])
+      {:ok, _pid} = Sessions.ensure_started(session.id)
+      {:ok, _} = Sessions.send_user_message(session.id, "say hello")
+
+      assert_receive {^ref, [:trinity, :llm, :call, :stop], measurements, meta}, 5_000
+
+      assert is_integer(measurements.input_tokens)
+      assert is_number(measurements.cost_usd)
+      assert meta.session_id == session.id
+      assert is_binary(meta.model)
+
+      # The event describes the call the ledger row describes, so a dashboard total and a bill
+      # cannot disagree by construction.
+      assert_in_delta measurements.cost_usd,
+                      Trinity.Telemetry.Costs.for_session(session.id),
+                      0.0001
+    end
+
     test "a session transition names where it went", %{ref: ref} do
       {:ok, session} =
         Sessions.create_session(%{persona_id: Sessions.default_persona().id, title: "t"})
@@ -122,6 +144,87 @@ defmodule Trinity.TelemetryTest do
     end
   end
 
+  describe "AC5: a turn is a trace, without a tracing library" do
+    test "the events of one turn share a trace id and name a parent", %{ref: ref} do
+      {:ok, session} =
+        Sessions.create_session(%{persona_id: Sessions.default_persona().id, title: "t"})
+
+      Trinity.LLM.Providers.Fake.scripts([script_deltas(1, "hi ")])
+      {:ok, _pid} = Sessions.ensure_started(session.id)
+      {:ok, _} = Sessions.send_user_message(session.id, "hello")
+
+      assert_receive {^ref, [:trinity, :llm, :call, :stop], _, meta}, 5_000
+
+      assert is_binary(meta.trace_id)
+      assert byte_size(meta.trace_id) == 16
+      assert is_binary(meta.parent_span_id)
+    end
+
+    test "two turns are two traces, so a tree is one turn rather than all of them", %{ref: ref} do
+      {:ok, session} =
+        Sessions.create_session(%{persona_id: Sessions.default_persona().id, title: "t"})
+
+      Trinity.LLM.Providers.Fake.scripts([script_deltas(1, "a "), script_deltas(1, "b ")])
+      {:ok, _pid} = Sessions.ensure_started(session.id)
+
+      {:ok, _} = Sessions.send_user_message(session.id, "first")
+      assert_receive {^ref, [:trinity, :llm, :call, :stop], _, first}, 5_000
+
+      {:ok, _} = Sessions.send_user_message(session.id, "second")
+      assert_receive {^ref, [:trinity, :llm, :call, :stop], _, second}, 5_000
+
+      refute first.trace_id == second.trace_id
+    end
+
+    test "outside a trace an event carries no trace id, rather than an invented one" do
+      ref = make_ref()
+      me = self()
+      handler = "t3-#{System.unique_integer([:positive])}"
+
+      :telemetry.attach(
+        handler,
+        [:trinity, :approval, :requested],
+        fn _, m, md, _ -> send(me, {ref, m, md}) end,
+        nil
+      )
+
+      on_exit(fn -> :telemetry.detach(handler) end)
+
+      Telemetry.approval_requested("write_note", :write, "sess-1")
+
+      assert_receive {^ref, _, meta}
+      # A span with a trace id nothing else shares is noise wearing a tree's clothes.
+      refute Map.has_key?(meta, :trace_id)
+    end
+
+    test "a nested span names the enclosing one as its parent" do
+      ref = make_ref()
+      me = self()
+      handler = "t4-#{System.unique_integer([:positive])}"
+
+      :telemetry.attach_many(
+        handler,
+        Telemetry.catalogue(),
+        fn n, m, md, _ -> send(me, {ref, n, m, md}) end,
+        nil
+      )
+
+      on_exit(fn -> :telemetry.detach(handler) end)
+
+      Telemetry.trace(fn ->
+        outer = Telemetry.context()
+
+        Telemetry.span([:tool, :call], %{tool: "echo"}, fn -> {:ok, %{result: :ok}} end)
+
+        assert_receive {^ref, [:trinity, :tool, :call, :stop], _, meta}
+        assert meta.trace_id == outer.trace_id
+        assert meta.parent_span_id == outer.span_id
+        assert is_binary(meta.span_id)
+        refute meta.span_id == outer.span_id
+      end)
+    end
+  end
+
   describe "the catalogue and the code agree" do
     test "every event the catalogue lists appears in docs/telemetry.md" do
       doc = File.read!("docs/telemetry.md")