diff --git a/.github/workflows/gate.yml b/.github/workflows/gate.yml index ef836a0..e45f5d3 100644 --- a/.github/workflows/gate.yml +++ b/.github/workflows/gate.yml @@ -82,6 +82,11 @@ jobs: DATABASE_URL: postgres://trinity:trinity@localhost:5432/trinity_test steps: - uses: actions/checkout@11d5960a326750d5838078e36cf38b85af677262 # v4.4.0 + with: + # `test/changelog_test.exs` reads `git tag -l 'slice/*'` and refuses to pass without + # tags, because a test that finds nothing to check is indistinguishable from one that + # found everything in order. The default depth of one fetches no tags. + fetch-depth: 0 - uses: erlef/setup-beam@54075bcc5e249e4758d363f27d099f55d843f124 # v1.24.1 with: diff --git a/CHANGELOG.md b/CHANGELOG.md index 5ec5ad2..857b44d 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -22,8 +22,55 @@ evidence for each increment is retained by the maintainers and summarised here. tree, engineering rules consolidated into `docs/03-conventions.md`, and this changelog added as the public record of delivered work. +## 2026-09-24 + +### `slice/090.1` — Observability and the cost ledger +Every LLM call, tool call, approval, session transition, gateway message and budget refusal emits a +`:telemetry` event from a single catalogue (`docs/telemetry.md`), written before the emitters rather +than documented after them, under one rule over the whole set: no prompt text, no completion text, +no tool arguments and no key material. A turn carries a trace identifier into the task that runs it, +so a turn reads as a tree without a tracing library and without a new dependency. A primary Logger +filter redacts credentials by shape rather than by name, so a secret nobody thought to list is still +caught, and it rewrites a message rather than dropping it. The cost ledger reads the usage rows the +tree already writes, by day, model, session and persona, against budgets that warn and, when +configured to, refuse. `/activity` shows the live event stream with the spend beside it, and a +LiveDashboard page lists running sessions by asking each process its state rather than reading a row. +OpenTelemetry was assessed and deferred against a measured need rather than added because the +criterion named it; the reason is recorded with the slice. + +**Tagged `slice/090.1`, not `slice/090`.** The `slice/090` tag was pushed before its merge had +landed and points at slice 080's merge commit. This repository's ruleset forbids moving or deleting +a tag, so the error is permanent and public; the correct tag carries the correction in its own +annotation rather than leaving a reader to reconcile the two. + +### `slice/080` — Subagents and delegation +The assistant can hand a bounded piece of work to a child session through a `delegate` tool. The +child has its own context and its own history, and hands back a result as text: the parent's +conversation never contains the child's messages, which is the property that makes delegation worth +having. Several children run at once under a concurrency cap, each with a budget in turns, tokens +and wall clock; exceeding it stops the child and says so. A child that dies does not take its parent +with it, and the parent is told; cancelling a parent cancels the tree beneath it. Approvals a child +raises appear on the same permissions page as any other, named with the child that raised them, and +a `/subagents` panel shows what is running with a stop control for each. + ## 2026-09-23 +### `slice/025` — Encryption at rest, and the key-custody seam +The database, the receipt chain and the key material can be sealed at rest, and the seam that holds +the keys is named rather than assumed. Sealing is a deployment decision with the trade-off stated in +both directions: a key lost is data lost, so the custody options are documented with their recovery +paths, and the default is the one whose failure mode an operator can survive. What the seam does +*not* cover is written down beside what it does. + +### `slice/002` — Supply chain, early +A CycloneDX bill of materials is generated by the quality gate on every commit and ships beside +every packaged binary, so whoever holds an artifact holds the list of what is in it; the bill states +its own coverage inside the document, including what it does not cover. Every packaged binary +carries build provenance attested through the workflow's own identity and recorded in a public +transparency log, verified in the same run that produced it. A minimum TLS version is enforced for +outbound connections. Brought forward from M9 because a supply-chain claim made late is a claim +made about work already done. + ### `slice/070` — Gateway core Trinity becomes reachable from channels other than the desktop. An adapter behaviour carries text and nothing else; a router admits the sender, applies a rate limit, dispatches commands and binds diff --git a/README.md b/README.md index 35ed782..3b23fb7 100644 --- a/README.md +++ b/README.md @@ -39,10 +39,14 @@ desktop application. Apache-2.0, developed in the open from the first commit. Pre-alpha, and usable from source. Milestones M0 to M4 are approved, **M5a Automates** with them (050, the scheduler; 059, the MCP measurement; 060, the MCP client; 061, the MCP server; 062, MCP -authorization), and the first slice of M5b (070, the gateway core), with 002 (the supply chain -slice) beside them: 26 slices, each merged with a merge commit and tagged `slice/NNN` -(`git tag -l 'slice/*' | wc -l` → 26, on 2026-09-23). What -that means in practice: +authorization), **M5b Reaches** in part (070, the gateway core; 080, subagents) and the first slice +of **M6 Ships** (090, observability and the cost ledger), with 002 (the supply chain slice) beside +them: 29 slices, each merged with a merge commit and tagged `slice/NNN` +(`git tag -l 'slice/*' | wc -l` → 30, on 2026-09-24: one more tag than slices, because +`slice/090` was pushed at the wrong commit before its merge landed and this repository's ruleset +forbids moving or deleting a tag; the correct one is `slice/090.1`, and `git tag -n20 slice/090.1` +says so in its own annotation rather than leaving a reader to work it out). What that means in +practice: **Assessed against a recognised baseline.** Trinity holds the [OpenSSF Best Practices **silver** badge](https://www.bestpractices.dev/projects/14772), awarded @@ -110,6 +114,26 @@ enforces it. conversation. What a channel may approve is capped below what the desktop may: a `write` at most by default, so an `exec` or a `destructive` request is decided at the machine, and the refusal is receipted. The console adapter ships (`mix trinity.console`); the platforms are next. +- **Delegates.** The assistant can hand a bounded piece of work to a child session with a + `delegate` tool: its own context, its own history, and a result handed back as text. The + parent's conversation never contains the child's messages, which is the point: + delegation that leaks the child's transcript back into the parent buys nothing. Several children run at + once under a cap, each with a budget in turns, tokens and wall clock; exceeding it stops the + child and says so. A child dies without taking its parent with it, and the parent is told; + cancelling a parent cancels the tree beneath it. Approvals a child raises surface on the same + permissions page as any other, named with the child they came from, and the `/subagents` panel + shows what is running with a stop button per child. +- **Shows what it costs.** Every LLM call, tool call, approval, session transition and gateway + message emits a `:telemetry` event from one catalogue (`docs/telemetry.md`), written before the + emitters rather than after them, with one rule over the whole set: no prompt text, no completion + text, no tool arguments, no key material. A turn carries a trace id down into the task that runs + it, so a turn reads as a tree without a tracing library or a new dependency. A primary Logger + filter redacts credentials by **shape** (bearer and basic headers, `sk-` and `pk-` prefixed + keys, JWTs), so a secret nobody thought to name is still caught, and the filter never drops a + message, only rewrites it. The cost ledger reads the usage rows the tree already writes: by day, + by model, by session, by persona, against budgets that warn and, when you ask them to, refuse. + `/activity` shows the live stream with the spend beside it; a LiveDashboard page lists the + running sessions, asking each process its state rather than trusting a row. - **Runs on a schedule.** Tasks on the `/tasks` page: a prompt, a persona, the skills to hint, and when (a cron expression, a one-shot time, or a phrase like "every weekday at 9am" the model turns into cron). Each run is a fresh conversation you can open, its result waits on @@ -118,9 +142,10 @@ enforces it. curator that marks old memories stale and archives the untouched ones (never deleting) run on the same queues; `/oban` shows the jobs. -Not there yet: the messaging platforms themselves and subagents (M5b), -the native desktop shell and signed releases (M6), executable skills in a sandbox (M7). The [Milestones](#milestones) section below sets out the order the -remaining work is being built in. +Not there yet: the messaging platforms themselves (071 Telegram and 072 Discord, which need a bot +token the project does not yet hold), the native desktop shell and signed releases (the rest of M6), +executable skills in a sandbox (M7). The [Milestones](#milestones) section below sets out the order +the remaining work is being built in. The interface is a local web page; the desktop shell exists as a packaging spike, not a product. If you want to follow along, watch the roadmap and the tags. @@ -240,7 +265,7 @@ rather than described by it. | M7 Sandboxed | Executable skills in an in-VM sandbox | 110 approved | | M9 Donatable | Open-source hygiene audited, supply chain signed, shared libraries extracted | 002 and 120 to 123 approved | -M0 to M5a are approved as of 2026-09-22, and 070 of M5b on 2026-09-23. Slice numbers have gaps on purpose (000, 001, 010, 011 and so on) so that a slice can be inserted +M0 to M5a are approved as of 2026-09-22. Of M5b, 070 and 080 are approved as of 2026-09-23; 071 and 072 wait on a messaging bot token the project does not yet hold. Of M6, 090 is approved as of 2026-09-24. Slice numbers have gaps on purpose (000, 001, 010, 011 and so on) so that a slice can be inserted later without renumbering anything. **[`ROADMAP.md`](ROADMAP.md)** sets out what the project intends to do and what it intends not to @@ -254,6 +279,7 @@ do over the next year, and why the order is what it is. | `VERSIONS.md` | The verified dependency versions, generated from `lib/trinity/versions.ex` | | `docs/` | Vision, architecture, tech stack, conventions, data model, risks, security model, standards register; packaging, the FIPS leg, backup and restore, performance measurements | | `docs/mcp-server.md` | Connecting a client to Trinity's MCP server (Claude Code, VS Code, Codex, goose), stdio, approvals over the wire, the headless profile | +| `docs/telemetry.md` | The telemetry event catalogue: every event this tree emits, its measurements and metadata, and the rule about what never appears in one | | `docs/adr/` | Architecture decision records. One is added whenever a decision changes | | `docs/10-assurance-case.md` | The structured argument that the security claims hold, with the evidence for each and the assumptions and limits named | | `docs/09-standards-register.md` | One row per control a regulated deployment may ask about, with its evidence path and status | diff --git a/config/test.exs b/config/test.exs index dd23278..0c1765b 100644 --- a/config/test.exs +++ b/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 diff --git a/coverage.tsv b/coverage.tsv index 4c5389f..5abc965 100644 --- a/coverage.tsv +++ b/coverage.tsv @@ -25,3 +25,4 @@ slice_id percent sha date 002 80.31 d65c48c 2026-09-23 025 80.31 2c4fe1f 2026-09-23 080 80.31 a7630ba 2026-09-24 +090 80.31 3e4185a 2026-09-24 diff --git a/docs/01-architecture.md b/docs/01-architecture.md index a1c209c..7744b6c 100644 --- a/docs/01-architecture.md +++ b/docs/01-architecture.md @@ -96,7 +96,7 @@ without anything failing. | `Trinity.Subagents` | Delegation, result collection (as built at 080: `delegate/3` and `delegate_many/3` creating child sessions with `origin: "subagent"` and `parent_id` set, one turn each under a monitor, the awaiting shape reused from slice 050's `RunTask` including its drain of the start `:idle`; budgets of turns, tokens and wall clock; `restarts` defaulting to **0**, because replaying a turn replays arbitrary tool calls and a `:session` or `:always` approval would cover the replay silently; `cancel_subtree/1` depth first; `running?/1` asked of the process rather than of `SessionRow.status`, which is the session lifecycle and stays `active` after a subagent finishes; `short_id/1` taking the **tail** of a UUIDv7, whose head is shared between children created in the same second) | Sessions | | `Trinity.Sandbox` | Luerl runners, resource limits | none | | `Trinity.Desktop` | ex_tauri bridge | PubSub | -| `Trinity.Telemetry` | events, cost ledger, metrics | Repo | +| `Trinity.Telemetry` | The event catalogue and the only module that names an event (as built at 090: `span/3` and `emit/3` routing everything through one place; emitters for the LLM, tool, approval, session, gateway and budget events listed in `docs/telemetry.md`, which was written **before** them because an event name is an interface and a handler attached to a name that no longer fires simply never runs; `trace/2` giving a turn one trace id so its events nest, with no tracing library and no dependency; `Telemetry.Costs` reading `usage_events` schemalessly, because `Trinity.LLM` depends on `Trinity` and naming its schema would be a cycle; `Telemetry.Activity`, a bounded buffer whose handler does one `send` because a telemetry handler runs in the emitting process; `Telemetry.Redaction`, a primary Logger filter that masks shapes rather than names and never drops a line) | Repo | | `TrinityWeb` | LiveViews, components, API | all `Trinity.*` public APIs | The six rows in bold were corrected on 2026-09-05. As written, the table forbade the effect path drawn in the diff --git a/docs/06-risk-register.md b/docs/06-risk-register.md index 6dda52a..a7dc331 100644 --- a/docs/06-risk-register.md +++ b/docs/06-risk-register.md @@ -28,3 +28,4 @@ | R25 | `glib` 0.18.5 carries GHSA-wrw7-89jp-8q8g (medium, unsoundness in `Iterator` and `DoubleEndedIterator` impls); first patched in 0.20.0 | Low | Med | The advisory is open against `src-tauri/Cargo.lock`; measured 2026-09-23 | It is transitive through the GTK 0.18 stack (`gtk` 0.18.2, `webkit2gtk` 2.0.2) that Tauri 2.11.5 requires on Linux, so it is fixed by a Tauri release built on gtk-rs 0.20 and not by a direct bump. **Scope:** the desktop shell only. The `headless` release is `steps: [:assemble]` with no Burrito and no `src-tauri`, so a server deployment does not ship this dependency. Owner: the maintainer. Lift condition: a Tauri release whose Linux stack resolves `glib` >= 0.20, adopted by the desktop shell work | 100 | | R26 | An intermittent `Exqlite.Error: Database busy` fails the test suite on loaded CI runners, in a different test each time, always on a write to the main repository | Med | Low (test-only; no production path) | Failed the gate on pull requests 67, 70 and again on the commit that attempted to fix it; the same commit passed on its other run, so it is seed- and load-dependent. Not once reproduced locally across repeated runs | Ruled out: `busy_timeout`, raised from the shipped 5 s to 30 s in the suite, did not stop it. SQLite returns BUSY immediately, without the busy handler, when a read transaction upgrades to a write while another connection holds the write lock; no timeout affects that path. The suite runs two connections (one for the sandbox owner, one for Oban's boot check) and deliberately queues fifty concurrent writers at slice 070 AC7, which is the load that provokes it. Candidate fixes, not yet taken: drain the stress test's sessions before the suite continues; give that test its own tag and CI step; or remove the second connection's need. Owner: the maintainer. Lift condition: ten consecutive green CI runs of the full suite with the stress test in the default run | 070 | | R26 | Occurrence recorded 2026-09-23: the same class of failure appeared on the **FIPS leg** rather than the ordinary gate, which the row above does not cover. `Trinity.Gateways.ApprovalsTest` AC4 failed in its setup, with the crash in `Trinity.Receipts.ChainWriter.terminate/2` calling `insert_checkpoint/2` after the sandbox owner had gone: an ownership error at termination rather than a `Database busy` on a write. **Re-running the identical commit passed all four checks**, which is the evidence that matters: the code did not change between the red run and the green one, so the failure is in the environment or the ordering and not in the change under test. What this adds to the row above: the mechanism is not only write contention, it also reaches process termination racing sandbox teardown, and it is not confined to the ordinary gate's runners. A candidate fix specific to this shape: `ChainWriter.terminate/2` writes a checkpoint on the way out, and a terminate callback that touches the database after the test that owns the connection has finished is a race by construction; it should skip the write when the repo is in sandbox mode and has no owner, rather than attempting it and crashing. **Second occurrence the same day, and it changes the severity.** The very next pull request, which changed *only this file*, failed the FIPS leg again: `Trinity.Gateways.RouterTest` AC6, `Exqlite.Error: Database busy` on an `INSERT INTO gateway_identities` - the row's original signature, on the leg the row did not cover. A change that cannot affect behaviour failing a required check twice in a row means this is no longer an intermittent annoyance: **it blocks work**, and the honest reading is that the FIPS leg provokes it more reliably than the ordinary gate does, most likely because that leg is slower (163 s against about 110 s locally) and every contention window is correspondingly wider. The row above stands as written | **High** (was Med: it now blocks merges) | Low (test-only; no production path) | The lift condition in the row above, still unmet; two failures on the FIPS leg on 2026-09-23, one of them on a documentation-only change | docs/06-risk-register.md R26 | 070 | +| R26 | Counter-example recorded 2026-09-24, in slice 090, and it corrects a heuristic the rows above state. At commit `b1bca1f` the `pull_request` run passed all four checks and the `push` run of the **same commit** failed `postgres` (runs 36001064067 and 36001057879). By the reading the 2026-09-23 entry offers - the code did not change between the green run and the red one, so the fault is the environment - this was R26 again. **It was not.** It was a real defect in slice 080's code, on a genuinely racy path: every call into a child session is a `gen_statem.call`, and a call into a process that dies exits the caller, so killing a child killed whoever called `delegate/3`. Whether the kill landed before or after the call returned decided the outcome, which is why the same commit could go either way. Fixed at `1f33f12`, after which both runs of the same commit passed. **What this changes:** "the same commit passed on its other run" is evidence that the failure is *timing-dependent*, which is not the same as evidence that it is environmental. A real race in library code produces exactly the signature R26 is recognised by, so the signature alone cannot be the diagnosis - the stack trace has to be read before a failure is filed here. This slice nearly filed one. The rows above stand as written | none (not an occurrence) | none | none | none | 080, 090 | diff --git a/docs/telemetry.md b/docs/telemetry.md new file mode 100644 index 0000000..85b166a --- /dev/null +++ b/docs/telemetry.md @@ -0,0 +1,114 @@ + + +# Telemetry: the event catalogue + +Slice 090. Every event Trinity emits, what it measures, and what it carries as metadata. + +**This document is written before the emitters, and that order is deliberate.** An event name is an +interface: the moment something consumes `[:trinity, :llm, :call, :stop]`, renaming it breaks that +consumer silently, because a handler attached to a name that no longer fires simply never runs. So +the names are decided once, here, and the code follows the document rather than the document +recording whatever the code happened to do. + +## What is never in an event + +**No prompt text, no completion text, no key material, no tool arguments.** Telemetry handlers are +attached by anything in the VM and their output reaches dashboards, logs and exporters, which is +exactly the path by which a conversation ends up somewhere nobody meant it to go. Events carry +identifiers, counts and durations; the content they describe stays in the database, behind the +permission model, where a person can decide who reads it. + +A tool call's event names the tool, not its arguments. An LLM call's event names the model and the +token counts, not the messages. This is a rule rather than a default: a new event that would need +content to be useful is a new event that needs rethinking. + +## The conventions + +All events are `[:trinity, ...]`. Anything with a duration follows `:telemetry.span/3`'s shape: +`:start`, then `:stop` **or** `:exception`, so a failed operation is never silently absent from the +count of completed ones. + +Durations are in native units, as `:telemetry.span/3` emits them; convert with +`System.convert_time_unit/3` at the point of display rather than at the point of measurement. + +## The events + +### LLM + +| Event | Measurements | Metadata | +|---|---|---| +| `[:trinity, :llm, :call, :start]` | `system_time` | `model`, `provider`, `session_id`, `kind` (`:stream`, `:generate`, `:embed`) | +| `[:trinity, :llm, :call, :stop]` | `duration`, `input_tokens`, `output_tokens`, `cost_usd` | as above, plus `finish_reason` | +| `[:trinity, :llm, :call, :exception]` | `duration` | as above, plus `kind`, `reason` | + +`cost_usd` is computed from the model registry's price, the same figure written to `usage_events`, +so a dashboard total and a ledger total cannot disagree by construction. + +### Tools + +| Event | Measurements | Metadata | +|---|---|---| +| `[:trinity, :tool, :call, :start]` | `system_time` | `tool`, `session_id`, `risk` | +| `[:trinity, :tool, :call, :stop]` | `duration` | as above, plus `result` (`:ok` or `:error`) | +| `[:trinity, :tool, :call, :exception]` | `duration` | as above, plus `kind`, `reason` | + +### Permissions + +| Event | Measurements | Metadata | +|---|---|---| +| `[:trinity, :approval, :requested]` | `count: 1` | `tool`, `risk`, `session_id` | +| `[:trinity, :approval, :decided]` | `count: 1`, `waited_ms` | `tool`, `risk`, `session_id`, `decision`, `basis` | + +`waited_ms` is how long a person took to answer. It is the number that says whether the permission +model is usable or merely correct. + +### Sessions + +| Event | Measurements | Metadata | +|---|---|---| +| `[:trinity, :session, :transition]` | `count: 1` | `session_id`, `from`, `to` | + +### Gateways + +| Event | Measurements | Metadata | +|---|---|---| +| `[:trinity, :gateway, :inbound]` | `count: 1` | `adapter`, `outcome` (`:placed`, `:command`, `:unpaired`, `:rate_limited`) | +| `[:trinity, :gateway, :outbound]` | `count: 1`, `bytes` | `adapter` | + +`outcome` is deliberately a closed set: a counter whose label is free text becomes a cardinality +problem the first time it carries an id. + +### Budgets + +| Event | Measurements | Metadata | +|---|---|---| +| `[: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. +- **The Activity page**, through a bounded ring buffer. Bounded because an unbounded event buffer + is a memory leak with a nice name. +- **`usage_events`**, for cost, which is written by the LLM path itself rather than by a handler: + a handler that fails or is detached would silently stop the ledger, and a missing bill is worse + than a missing chart. + +## Adding an event + +Add it to this table first, then emit it. If it needs content to be useful, it is the wrong event. diff --git a/lib/trinity.ex b/lib/trinity.ex index 85a8d77..ed06877 100644 --- a/lib/trinity.ex +++ b/lib/trinity.ex @@ -25,6 +25,14 @@ defmodule Trinity do Vault, # Slice 080: the delegate tool and the session view's subagent panel call it. Subagents, + # Slice 090: every sub-boundary that emits an event names it through this module rather + # than calling :telemetry directly, so an event name is changed in one place. The + # redaction filter is exported because the application installs it as a primary Logger + # filter at boot. + Telemetry, + Telemetry.Activity, + Telemetry.Costs, + Telemetry.Redaction, Repo, Repo.Receipts, UUID, diff --git a/lib/trinity/application.ex b/lib/trinity/application.ex index 79e5cec..0ea1617 100644 --- a/lib/trinity/application.ex +++ b/lib/trinity/application.ex @@ -24,10 +24,18 @@ defmodule Trinity.Application do @impl true def start(_type, _args) do + # Slice 090. Installed before anything can log, and as a primary filter so it applies to every + # handler rather than to one: a dependency that logs a request header does not know this + # project's rules about key material, and the filter is the last line for exactly that case. + install_log_redaction() + children = desktop_children() ++ [ TrinityWeb.Telemetry, + # Slice 090: the Activity page's bounded buffer. Early, so it is listening before + # anything it would want to have recorded has happened. + Trinity.Telemetry.Activity, # Slice 010: one node per data directory. Before the Repo, so a refused boot has # opened no database file; the reason names the holder's OS pid and mode. {Trinity.DataDir.Lock, dir: lock_dir(), mode: mode()}, @@ -109,6 +117,18 @@ defmodule Trinity.Application do # The lock lives in the data directory the database defaults to. A deployment that points # DATABASE_PATH elsewhere still locks the data directory, which is the thing two instances # would otherwise share; the test environment points it at a temporary directory. + defp install_log_redaction do + :logger.add_primary_filter( + :trinity_redaction, + {&Trinity.Telemetry.Redaction.filter/2, nil} + ) + rescue + # Already installed (a release that restarts the application, or a test that starts it twice). + _ -> :ok + catch + _, _ -> :ok + end + defp lock_dir do Application.get_env(:trinity, Trinity.DataDir.Lock, [])[:dir] || Trinity.Paths.ensure_data_dir() diff --git a/lib/trinity/llm.ex b/lib/trinity/llm.ex index d17ae42..e4ce445 100644 --- a/lib/trinity/llm.ex +++ b/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 diff --git a/lib/trinity/sessions/session.ex b/lib/trinity/sessions/session.ex index bb76e0c..8aeebfb 100644 --- a/lib/trinity/sessions/session.ex +++ b/lib/trinity/sessions/session.ex @@ -117,8 +117,10 @@ defmodule Trinity.Sessions.Session do end end - def handle_event(:enter, _old, state, %State{id: id}) do + def handle_event(:enter, old, state, %State{id: id}) do Events.broadcast(id, {:state, state}) + # Slice 090: the transition, with no conversation content in it. + Trinity.Telemetry.session_transition(id, old, state) case state do :idle -> @@ -433,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) %{ diff --git a/lib/trinity/subagents.ex b/lib/trinity/subagents.ex index ffd242b..c6b73f5 100644 --- a/lib/trinity/subagents.ex +++ b/lib/trinity/subagents.ex @@ -230,6 +230,21 @@ defmodule Trinity.Subagents do # returns before the turn has run. Reused rather than rewritten, because writing it again is # writing that bug again. defp run(child, brief, budget, restarts) do + # Every call into the child is a `gen_statem.call`, and a call into a process that dies exits + # the *caller*. Without this, killing a child kills whoever called `delegate/3`, which is the + # opposite of what AC4 is for: the parent is meant to be told that its child died, not to die + # with it. Caught here rather than at each call site so no future call can reintroduce it. + # + # Found by the Postgres leg. On SQLite the kill happened to land after the call returned; on + # Postgres the timing differed and it landed during, which is the same race with a different + # coin toss rather than a different bug. + start(child, brief, budget, restarts) + catch + :exit, reason -> + %{session_id: child.id, status: :error, text: "", reason: {:child_died, reason}} + end + + defp start(child, brief, budget, restarts) do with :ok <- Sessions.subscribe(child.id), {:ok, pid} <- Sessions.ensure_started(child.id), :ok <- drain_start(child.id), diff --git a/lib/trinity/telemetry.ex b/lib/trinity/telemetry.ex new file mode 100644 index 0000000..7c651fa --- /dev/null +++ b/lib/trinity/telemetry.ex @@ -0,0 +1,191 @@ +# SPDX-FileCopyrightText: Sudo Apt Holdings LLC +# SPDX-License-Identifier: Apache-2.0 +defmodule Trinity.Telemetry do + @moduledoc """ + The events Trinity emits, and the only place that names them (slice 090). + + The catalogue, with each event's measurements and metadata, is `docs/telemetry.md`, and it was + written before this module. An event name is an interface: once something attaches a handler to + `[:trinity, :llm, :call, :stop]`, renaming it breaks that consumer **silently**, because a handler + attached to a name that no longer fires simply never runs. Nothing here invents a name that the + document does not already carry. + + ## What never enters an event + + No prompt text, no completion text, no key material, no tool arguments. Handlers are attached by + anything in the VM and their output reaches dashboards, logs and exporters, which is the path by + which a conversation ends up somewhere nobody meant. Events carry identifiers, counts and + durations; the content stays in the database behind the permission model. + + `span/3` and the emitters below take only what the catalogue lists, so passing content would + 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]`. + + `:telemetry.span/3`'s shape rather than a bare `execute`, so a failed operation is never silently + missing from the count of completed ones: a dashboard that counts only successes reports a healthy + system right up until somebody looks at the logs. + """ + @spec span([atom()], map(), (-> {term(), map()})) :: term() + def span(name, metadata, fun) when is_list(name) and is_map(metadata) do + 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, with_trace(metadata)) + end + + ## The emitters. One function per catalogue entry, so a call site names an event rather than + ## assembling one, and a rename is a change here rather than a search. + + @doc "A completed LLM call. `cost_usd` is the registry price, the same figure the ledger stores." + @spec llm_stop(map()) :: :ok + def llm_stop(meta) do + emit( + [:llm, :call, :stop], + %{ + duration: meta[:duration] || 0, + input_tokens: meta[:input_tokens] || 0, + output_tokens: meta[:output_tokens] || 0, + cost_usd: meta[:cost_usd] || 0.0 + }, + Map.take(meta, [:model, :provider, :session_id, :kind, :finish_reason]) + ) + end + + @doc "An approval was raised. Names the tool and its tier, never its arguments." + @spec approval_requested(String.t(), atom() | String.t(), String.t() | nil) :: :ok + def approval_requested(tool, risk, session_id) do + emit([:approval, :requested], %{count: 1}, %{tool: tool, risk: risk, session_id: session_id}) + end + + @doc """ + An approval was answered, with how long the person took. + + `waited_ms` is the number that says whether the permission model is usable or merely correct: a + gate everybody waits four minutes for is a gate people learn to route around. + """ + @spec approval_decided(String.t(), atom() | String.t(), String.t() | nil, keyword()) :: :ok + def approval_decided(tool, risk, session_id, opts) do + emit( + [:approval, :decided], + %{count: 1, waited_ms: Keyword.get(opts, :waited_ms, 0)}, + %{ + tool: tool, + risk: risk, + session_id: session_id, + decision: Keyword.get(opts, :decision), + basis: Keyword.get(opts, :basis) + } + ) + end + + @doc "A session changed state." + @spec session_transition(String.t(), atom(), atom()) :: :ok + def session_transition(session_id, from, to) do + emit([:session, :transition], %{count: 1}, %{session_id: session_id, from: from, to: to}) + end + + @doc """ + A message arrived at a gateway. + + `outcome` is a closed set on purpose: a counter whose label is free text becomes a cardinality + problem the first time somebody puts an id in it. + """ + @spec gateway_inbound(String.t(), atom()) :: :ok + def gateway_inbound(adapter, outcome) + when outcome in [:placed, :command, :unpaired, :rate_limited] do + emit([:gateway, :inbound], %{count: 1}, %{adapter: adapter, outcome: outcome}) + end + + @doc "A message left for a gateway." + @spec gateway_outbound(String.t(), non_neg_integer()) :: :ok + def gateway_outbound(adapter, bytes) do + emit([:gateway, :outbound], %{count: 1, bytes: bytes}, %{adapter: adapter}) + end + + @doc "A budget was exceeded." + @spec budget_exceeded(atom(), String.t() | nil, float(), float()) :: :ok + def budget_exceeded(scope, scope_id, spent_usd, limit_usd) do + emit( + [:budget, :exceeded], + %{spent_usd: spent_usd, limit_usd: limit_usd}, + %{scope: scope, scope_id: scope_id} + ) + end + + @doc "Every event name this module can emit, for the test that holds the catalogue to the code." + @spec catalogue() :: [[atom()]] + def catalogue do + [ + [:trinity, :llm, :call, :start], + [:trinity, :llm, :call, :stop], + [:trinity, :llm, :call, :exception], + [:trinity, :tool, :call, :start], + [:trinity, :tool, :call, :stop], + [:trinity, :tool, :call, :exception], + [:trinity, :approval, :requested], + [:trinity, :approval, :decided], + [:trinity, :session, :transition], + [:trinity, :gateway, :inbound], + [:trinity, :gateway, :outbound], + [:trinity, :budget, :exceeded] + ] + end +end diff --git a/lib/trinity/telemetry/activity.ex b/lib/trinity/telemetry/activity.ex new file mode 100644 index 0000000..a1c7069 --- /dev/null +++ b/lib/trinity/telemetry/activity.ex @@ -0,0 +1,112 @@ +# SPDX-FileCopyrightText: Sudo Apt Holdings LLC +# SPDX-License-Identifier: Apache-2.0 +defmodule Trinity.Telemetry.Activity do + @moduledoc """ + A bounded, in-memory record of recent events, for the Activity page (slice 090). + + **Bounded, because an unbounded event buffer is a memory leak with a nice name.** It keeps the + last `limit/0` events and drops the oldest; nothing here is durable and nothing here is meant to + be. What must survive a restart is a receipt (slice 024) or a usage row (slice 011), and both are + written to disk by the code that caused them rather than by a listener. + + **It holds what the catalogue allows and nothing else.** The events themselves carry no prompt + text, no completion text and no tool arguments (`docs/telemetry.md`), so neither does this. That + is worth stating because an activity feed is exactly the feature that tempts someone to enrich a + record with "just the first line of the message", and the place to refuse that is here, where the + refusal is visible, rather than in review. + + It is a `GenServer` rather than an ETS table so that the handler's work is bounded by a mailbox + it cannot outrun: a telemetry handler runs **in the process that emitted the event**, and doing + real work there would put this module's cost on the turn's latency. + """ + + use GenServer + + alias Trinity.Telemetry + + @handler "trinity-activity" + @limit 200 + + @type entry :: %{ + at: DateTime.t(), + event: [atom()], + measurements: map(), + metadata: map() + } + + @doc "How many events are kept." + @spec limit() :: pos_integer() + def limit, do: @limit + + def start_link(opts), do: GenServer.start_link(__MODULE__, opts, name: __MODULE__) + + @doc """ + The recent events, newest first. + + Options: `:session_id` and `:event` (a prefix, so `[:trinity, :tool]` matches both the start and + the stop). + """ + @spec recent(keyword()) :: [entry()] + def recent(opts \\ []) do + GenServer.call(__MODULE__, :recent) + |> filter_session(opts[:session_id]) + |> filter_event(opts[:event]) + catch + :exit, _ -> [] + end + + @doc "Empties the buffer. For tests, and for a person who wants the page to start again." + @spec clear() :: :ok + def clear do + GenServer.call(__MODULE__, :clear) + catch + :exit, _ -> :ok + end + + @impl true + def init(_opts) do + # Attached here rather than in the application so the handler's lifetime is this process's: a + # handler that outlives its target sends to a dead pid on every event for the rest of the run. + :telemetry.attach_many(@handler, Telemetry.catalogue(), &__MODULE__.handle/4, nil) + {:ok, %{entries: []}} + end + + @impl true + def terminate(_reason, _state) do + :telemetry.detach(@handler) + :ok + end + + @doc false + # Runs in the emitting process. It does one `send` and nothing else, on purpose: a handler that + # did real work here would charge it to whatever turn happened to emit the event. + def handle(event, measurements, metadata, _config) do + send(__MODULE__, {:event, event, measurements, metadata, DateTime.utc_now()}) + :ok + rescue + # A send to a name that is not registered raises; an unstarted buffer must not break a turn. + _ -> :ok + end + + @impl true + def handle_info({:event, event, measurements, metadata, at}, state) do + entry = %{at: at, event: event, measurements: measurements, metadata: metadata} + {:noreply, %{state | entries: Enum.take([entry | state.entries], @limit)}} + end + + def handle_info(_other, state), do: {:noreply, state} + + @impl true + def handle_call(:recent, _from, state), do: {:reply, state.entries, state} + def handle_call(:clear, _from, state), do: {:reply, :ok, %{state | entries: []}} + + defp filter_session(entries, nil), do: entries + + defp filter_session(entries, session_id), + do: Enum.filter(entries, &(&1.metadata[:session_id] == session_id)) + + defp filter_event(entries, nil), do: entries + + defp filter_event(entries, prefix) when is_list(prefix), + do: Enum.filter(entries, &List.starts_with?(&1.event, prefix)) +end diff --git a/lib/trinity/telemetry/costs.ex b/lib/trinity/telemetry/costs.ex new file mode 100644 index 0000000..63a4344 --- /dev/null +++ b/lib/trinity/telemetry/costs.ex @@ -0,0 +1,190 @@ +# SPDX-FileCopyrightText: Sudo Apt Holdings LLC +# SPDX-License-Identifier: Apache-2.0 +defmodule Trinity.Telemetry.Costs do + @moduledoc """ + What the model calls have cost, and whether a budget has been passed (slice 090). + + **This is a read, not a pipeline.** Slice 011 already writes a `usage_events` row per completed + call with the cost computed from the model registry's price. Nothing here recomputes that, and + nothing here is a telemetry handler: a handler that failed or was detached would silently stop + the ledger, and a missing bill is worse than a missing chart. The events in + `docs/telemetry.md` describe the same calls, and the dashboards read them, but the money is read + from the rows. + + ## Budgets + + Configured rather than stored, because there is no settings table and inventing one for three + numbers would be the larger change: + + config :trinity, :budgets, day: 5.0, session: 1.0, persona: 20.0 + + A budget that is not configured is not enforced. `check/2` answers `:ok` or + `{:over, spent, limit}` and emits `[:trinity, :budget, :exceeded]` when it is over, so the + warning reaches a dashboard whether or not anything is blocking on it. + + **Blocking is separate from warning, and off by default.** `config :trinity, :budgets, + block_when_over: true` makes the session refuse a new turn. It is off because a budget that + silently stops an agent mid-task is a failure a person cannot diagnose from the outside, and the + warning is what makes the number visible before it becomes a wall. + """ + + import Ecto.Query + + alias Trinity.Repo + + # The table, not the schema. `Trinity.LLM` is a sub-boundary that depends on `Trinity`, so a + # module in `Trinity` naming `Trinity.LLM.Usage` would be a cycle and the compiler refuses it. + # That refusal is right rather than inconvenient: this module reads a ledger, it does not use the + # LLM's API, and every query here is an aggregate that needs no struct. The column names are the + # contract, and the test asserts they still exist. + @table "usage_events" + + @scopes [:day, :session, :persona] + + @doc "The scopes a budget can be set for." + @spec scopes() :: [atom()] + def scopes, do: @scopes + + @doc "Total cost in US dollars across every recorded call, optionally since a time." + @spec total(keyword()) :: float() + def total(opts \\ []) do + @table + |> since(opts[:since]) + |> select([u], sum(u.cost_usd)) + |> Repo.one() + |> zero_if_nil() + end + + @doc "Total cost for one session." + @spec for_session(String.t()) :: float() + def for_session(session_id) do + @table + # `type/2` is not decoration here. A schemaless query has no schema to tell the adapter this + # column is a UUID: SQLite stores one as text and accepts the string, Postgres wants sixteen + # bytes and refuses it. The postgres leg caught that and the SQLite one never could. + |> where([u], u.session_id == type(^session_id, Trinity.UUID)) + |> select([u], sum(u.cost_usd)) + |> Repo.one() + |> zero_if_nil() + end + + @doc """ + Total cost for one persona, summed across its sessions. + + `usage_events` carries the session, not the persona, so this joins. Storing the persona on the + usage row would make this a simpler query and a wrong one: a session's persona can change, and + the cost belongs to the session that incurred it. + """ + @spec for_persona(String.t()) :: float() + def for_persona(persona_id) do + from(u in @table, + join: s in "sessions", + on: s.id == u.session_id, + where: s.persona_id == type(^persona_id, Trinity.UUID), + select: sum(u.cost_usd) + ) + |> Repo.one() + |> zero_if_nil() + end + + @doc "Total cost today, in UTC." + @spec for_today() :: float() + def for_today, do: total(since: DateTime.utc_now() |> DateTime.to_date() |> start_of_day()) + + @doc "Totals by day, newest first, as `{date, cost}`." + @spec by_day(pos_integer()) :: [{Date.t(), float()}] + def by_day(days \\ 30) do + since = Date.utc_today() |> Date.add(-days) |> start_of_day() + + @table + |> where([u], u.inserted_at >= ^since) + |> group_by([u], fragment("date(?)", u.inserted_at)) + |> select([u], {fragment("date(?)", u.inserted_at), sum(u.cost_usd)}) + |> Repo.all() + |> Enum.map(fn {d, c} -> {to_date(d), zero_if_nil(c)} end) + |> Enum.sort({:desc, Date}) + end + + @doc "Totals by model, largest first, as `{model_id, cost, calls}`." + @spec by_model(keyword()) :: [{String.t(), float(), non_neg_integer()}] + def by_model(opts \\ []) do + @table + |> since(opts[:since]) + |> group_by([u], u.model_id) + |> select([u], {u.model_id, sum(u.cost_usd), count(u.id)}) + |> Repo.all() + |> Enum.map(fn {m, c, n} -> {m, zero_if_nil(c), n} end) + |> Enum.sort_by(&elem(&1, 1), :desc) + end + + @doc "The configured budget for a scope, or `nil` when none is set." + @spec budget(atom()) :: float() | nil + def budget(scope) when scope in @scopes do + case Application.get_env(:trinity, :budgets, [])[scope] do + n when is_number(n) -> n / 1 + _ -> nil + end + end + + @doc "Whether a new turn should be refused when a budget is passed. Off unless configured." + @spec blocking?() :: boolean() + def blocking?, do: Application.get_env(:trinity, :budgets, [])[:block_when_over] == true + + @doc """ + Whether a scope is over its budget, emitting the warning event when it is. + + `:ok` when no budget is set for the scope, because an unconfigured budget is not a budget of + zero. That distinction matters: the alternative silently blocks every call on a fresh install. + """ + @spec check(atom(), String.t() | nil) :: :ok | {:over, float(), float()} + def check(scope, scope_id \\ nil) + + def check(scope, scope_id) when scope in @scopes do + case budget(scope) do + nil -> + :ok + + limit -> + spent = spent(scope, scope_id) + + if spent > limit do + Trinity.Telemetry.budget_exceeded(scope, scope_id, spent, limit) + {:over, spent, limit} + else + :ok + end + end + end + + def check(_scope, _scope_id), do: :ok + + @doc "Every configured scope that is over, for a caller that wants the whole picture at once." + @spec over(String.t() | nil, String.t() | nil) :: [{atom(), float(), float()}] + def over(session_id \\ nil, persona_id \\ nil) do + [{:day, nil}, {:session, session_id}, {:persona, persona_id}] + |> Enum.filter(fn {scope, id} -> scope == :day or id != nil end) + |> Enum.flat_map(fn {scope, id} -> + case check(scope, id) do + {:over, spent, limit} -> [{scope, spent, limit}] + :ok -> [] + end + end) + end + + defp spent(:day, _), do: for_today() + defp spent(:session, id) when is_binary(id), do: for_session(id) + defp spent(:persona, id) when is_binary(id), do: for_persona(id) + defp spent(_, _), do: 0.0 + + defp since(query, nil), do: query + defp since(query, %DateTime{} = at), do: where(query, [u], u.inserted_at >= ^at) + + defp start_of_day(%Date{} = d), do: DateTime.new!(d, ~T[00:00:00], "Etc/UTC") + + defp to_date(%Date{} = d), do: d + defp to_date(s) when is_binary(s), do: Date.from_iso8601!(s) + + defp zero_if_nil(nil), do: 0.0 + defp zero_if_nil(%Decimal{} = d), do: Decimal.to_float(d) + defp zero_if_nil(n) when is_number(n), do: n / 1 +end diff --git a/lib/trinity/telemetry/redaction.ex b/lib/trinity/telemetry/redaction.ex new file mode 100644 index 0000000..520dad7 --- /dev/null +++ b/lib/trinity/telemetry/redaction.ex @@ -0,0 +1,91 @@ +# SPDX-FileCopyrightText: Sudo Apt Holdings LLC +# SPDX-License-Identifier: Apache-2.0 +defmodule Trinity.Telemetry.Redaction do + @moduledoc """ + A `Logger` filter that masks credentials and truncates long content (slice 090). + + **A filter is a last line, not the control.** The controls are that key material lives in files + outside configuration (slice 025), that the authorization layer's records carry no token + (slice 062), and that telemetry events carry no content at all (`docs/telemetry.md`). This exists + because logs are written by every library in the tree as well as by this project, and a + dependency that logs a request header has not read any of those rules. + + So it is deliberately blunt. It masks anything *shaped* like a credential rather than anything + known to be one, and it truncates long messages. Over-masking a log line costs a reader some + context; under-masking one puts a key on disk. + + ## What it cannot do + + It sees the message and its metadata, not the intent. A key embedded in a sentence with no + recognisable shape passes through, and a chat message that happens to look like a bearer token is + masked. Neither is a defect in the filter; both are why it is not the control. + """ + + @max_chars 2_000 + + # Shapes rather than names. Each is anchored on a prefix that exists to be recognised, which is + # the property that makes a credential's own format give it away. + @patterns [ + {~r/(?i)\b(bearer|basic|token)\s+[A-Za-z0-9._~+\/=-]{12,}/, "\\1 [REDACTED]"}, + {~r/\b(?:sk|pk|rk|api|key)[-_][A-Za-z0-9._-]{16,}/i, "[REDACTED]"}, + {~r/\bey[A-Za-z0-9_-]{8,}\.[A-Za-z0-9_-]{8,}\.[A-Za-z0-9_-]{8,}/, "[REDACTED-JWT]"}, + {~r/(?i)\b(password|passwd|secret|api[_-]?key|access[_-]?token|private[_-]?key)(\s*[:=]\s*)\S+/, + "\\1\\2[REDACTED]"} + ] + + @doc """ + The filter. Returns the event with its message and metadata masked, never `:stop`. + + Never `:stop`, on purpose: a filter that drops a line to avoid printing a secret also drops the + evidence that something happened. Masking keeps the event and removes the value. + """ + @spec filter(map(), term()) :: map() + def filter(%{msg: msg, meta: meta} = event, _opts) do + %{event | msg: redact_msg(msg), meta: redact_meta(meta)} + end + + def filter(event, _opts), do: event + + @doc "Masks credential-shaped substrings in a binary." + @spec redact(term()) :: term() + def redact(text) when is_binary(text) do + Enum.reduce(@patterns, text, fn {re, replacement}, acc -> + Regex.replace(re, acc, replacement) + end) + end + + def redact(other), do: other + + @doc "Truncates to the logging limit, saying how much was dropped rather than trailing off." + @spec truncate(binary(), pos_integer()) :: binary() + def truncate(text, max \\ @max_chars) when is_binary(text) do + if String.length(text) > max do + String.slice(text, 0, max) <> "… [#{String.length(text) - max} more characters]" + else + text + end + end + + @doc "The character limit applied to a logged message." + @spec max_chars() :: pos_integer() + def max_chars, do: @max_chars + + defp redact_msg({:string, text}) when is_binary(text), + do: {:string, text |> redact() |> truncate()} + + defp redact_msg({format, args}) when is_list(args), do: {format, Enum.map(args, &redact_term/1)} + defp redact_msg({:report, report}), do: {:report, redact_term(report)} + defp redact_msg(other), do: other + + defp redact_meta(meta) when is_map(meta), + do: Map.new(meta, fn {k, v} -> {k, redact_term(v)} end) + + defp redact_meta(meta), do: meta + + defp redact_term(v) when is_binary(v), do: v |> redact() |> truncate() + defp redact_term(v) when is_list(v), do: Enum.map(v, &redact_term/1) + defp redact_term(%{__struct__: _} = v), do: v + defp redact_term(v) when is_map(v), do: Map.new(v, fn {k, val} -> {k, redact_term(val)} end) + defp redact_term({a, b}), do: {redact_term(a), redact_term(b)} + defp redact_term(v), do: v +end diff --git a/lib/trinity/tools/runner.ex b/lib/trinity/tools/runner.ex index a0f1298..448120e 100644 --- a/lib/trinity/tools/runner.ex +++ b/lib/trinity/tools/runner.ex @@ -172,14 +172,34 @@ defmodule Trinity.Tools.Runner do what keeps it a caller for reads only. """ @spec call_tool(Registry.entry(), map(), Context.t()) :: {:ok, Result.t()} | {:error, term()} - def call_tool(%{effect: :none, module: module}, args, ctx) do + def call_tool(%{effect: :none, module: module, name: name} = entry, args, ctx) do + # Slice 090. The span carries the tool's name and tier and never its arguments: a telemetry + # handler is attached by anything in the VM and its output reaches dashboards and exporters, + # which is exactly how a filesystem path or a shell command ends up somewhere nobody meant + # (docs/telemetry.md). + Trinity.Telemetry.span( + [:tool, :call], + %{tool: name, risk: entry[:risk], session_id: ctx.session_id}, + fn -> + result = invoke(module, args, ctx) + + {result, + %{tool: name, risk: entry[:risk], session_id: ctx.session_id, result: outcome(result)}} + end + ) + end + + def call_tool(%{name: name}, _args, _ctx), + do: {:error, {:effectful_tool_outside_membrane, name}} + + defp invoke(module, args, ctx) do module.execute(args, ctx) rescue e -> {:error, {:crash, {e, __STACKTRACE__}}} end - def call_tool(%{name: name}, _args, _ctx), - do: {:error, {:effectful_tool_outside_membrane, name}} + defp outcome({:ok, _}), do: :ok + defp outcome(_), do: :error defp timeout_of(%{name: name}) do with {:ok, entry} <- Registry.lookup(name), diff --git a/lib/trinity_web/dashboard/sessions_page.ex b/lib/trinity_web/dashboard/sessions_page.ex new file mode 100644 index 0000000..7ab7d5d --- /dev/null +++ b/lib/trinity_web/dashboard/sessions_page.ex @@ -0,0 +1,92 @@ +# SPDX-FileCopyrightText: Sudo Apt Holdings LLC +# SPDX-License-Identifier: Apache-2.0 +defmodule TrinityWeb.Dashboard.SessionsPage do + @moduledoc """ + A LiveDashboard page listing the session processes that are alive, with their `gen_statem` state + (slice 090, AC3). + + LiveDashboard already lists every process in the VM. What it cannot say is which of them is a + Trinity session and what state that session's machine is in, which is the question someone asks + when a turn appears stuck: waiting on a model, waiting on an approval, or idle and the page did + not notice. + + It reads the registry and asks each process, so it shows the running system rather than the + database's opinion of it. A session row reads `active` long after its process has gone; slice 080 + found that the hard way, in a panel that promised "which are running" and delivered "which are + not archived". + """ + + use Phoenix.LiveDashboard.PageBuilder + + alias Trinity.Sessions + + @impl true + def menu_link(_, _), do: {:ok, "Trinity sessions"} + + @impl true + def render(assigns) do + ~H""" + <.live_table + id="trinity-sessions" + dom_id="trinity-sessions" + page={@page} + title="Trinity sessions" + row_fetcher={&fetch_rows/2} + rows_name="sessions" + > + <:col field={:id} header="Session" /> + <:col field={:state} header="State" /> + <:col field={:title} header="Title" /> + <:col field={:origin} header="Origin" /> + <:col field={:pid} header="Process" /> + <:col field={:memory} header="Memory (KB)" sortable={:desc} /> + + """ + end + + @doc false + def fetch_rows(params, _node) do + rows = rows() + {sort_rows(rows, params), length(rows)} + end + + defp rows do + for session <- Sessions.list_sessions(limit: 200), + pid = Sessions.whereis(session.id), + is_pid(pid) do + %{ + id: short(session.id), + state: state_of(session.id), + title: session.title || "(untitled)", + origin: session.origin, + pid: inspect(pid), + memory: memory_kb(pid) + } + end + end + + # Asked of the process, never read from the row: a row's status is the session's lifecycle and + # says nothing about whether its machine is doing anything. + defp state_of(session_id) do + case Sessions.state(session_id) do + %{state: state} -> to_string(state) + _ -> "-" + end + catch + :exit, _ -> "-" + end + + defp memory_kb(pid) do + case Process.info(pid, :memory) do + {:memory, bytes} -> div(bytes, 1024) + _ -> 0 + end + end + + defp short(id), do: String.slice(id, -8, 8) + + defp sort_rows(rows, %{sort_by: by, sort_dir: dir}) when is_atom(by), + do: Enum.sort_by(rows, &Map.get(&1, by), dir) + + defp sort_rows(rows, _params), do: rows +end diff --git a/lib/trinity_web/live/activity_live.ex b/lib/trinity_web/live/activity_live.ex new file mode 100644 index 0000000..4cd59fa --- /dev/null +++ b/lib/trinity_web/live/activity_live.ex @@ -0,0 +1,176 @@ +# SPDX-FileCopyrightText: Sudo Apt Holdings LLC +# SPDX-License-Identifier: Apache-2.0 +defmodule TrinityWeb.ActivityLive do + @moduledoc """ + `/activity` (slice 090): what Trinity has been doing, as events, with what it has cost. + + The page reads and never writes, like every page in this tree. It shows the bounded buffer + (`Trinity.Telemetry.Activity`), filterable by session and by kind of event, and the cost totals + beside it, because "what happened" and "what it cost" are the same question asked twice and + splitting them across two pages makes a person do the joining. + + **It shows what the events carry, which is deliberately not much.** No prompt text, no completion + text, no tool arguments (`docs/telemetry.md`). An activity feed is exactly the feature that + tempts someone to enrich a row with "just the first line of the message"; the refusal lives in + the catalogue and this page inherits it. + """ + use TrinityWeb, :live_view + + alias Trinity.Telemetry.{Activity, Costs} + + @refresh_ms 2_000 + + @impl true + def mount(_params, _session, socket) do + if connected?(socket), do: :timer.send_interval(@refresh_ms, :refresh) + + {:ok, + socket + |> assign(page_title: gettext("Activity"), filter: nil, session_filter: "") + |> load()} + end + + @impl true + def handle_info(:refresh, socket), do: {:noreply, load(socket)} + + @impl true + def handle_event("filter", %{"kind" => kind}, socket) do + {:noreply, socket |> assign(filter: prefix(kind)) |> load()} + end + + def handle_event("session", %{"session_id" => id}, socket) do + {:noreply, socket |> assign(session_filter: String.trim(id)) |> load()} + end + + def handle_event("clear", _params, socket) do + Activity.clear() + {:noreply, load(socket)} + end + + defp prefix(""), do: nil + defp prefix("all"), do: nil + defp prefix(kind), do: [:trinity, String.to_existing_atom(kind)] + + defp load(socket) do + session_id = + if socket.assigns.session_filter == "", do: nil, else: socket.assigns.session_filter + + assign(socket, + entries: Activity.recent(event: socket.assigns.filter, session_id: session_id), + today: Costs.for_today(), + total: Costs.total(), + by_model: Costs.by_model() |> Enum.take(5), + over: Costs.over(session_id, nil) + ) + end + + @impl true + def render(assigns) do + ~H""" + + <:bar> + {gettext("Activity")} + + {gettext("today")} ${:erlang.float_to_binary(@today, decimals: 4)} + + + {gettext("all time")} ${:erlang.float_to_binary(@total, decimals: 4)} + + + +
+
+ {gettext("Over the")} {scope} {gettext("budget")}: + + ${:erlang.float_to_binary(spent, decimals: 4)} / ${:erlang.float_to_binary(limit, + decimals: 2 + )} + +
+ +
+

+ {gettext("Cost by model")} +

+
    +
  • + {model} + {calls} {gettext("calls")} + ${:erlang.float_to_binary(cost, decimals: 4)} +
  • +
+
+ +
+
+ +
+
+ +
+ + +
+ +
+

+ {gettext("Nothing yet. Events appear here as Trinity works.")} +

+
    +
  • + + {Calendar.strftime(e.at, "%H:%M:%S")} + + {name(e.event)} + {summarise(e)} + {duration(e.measurements)} +
  • +
+
+ +

+ {gettext("The last")} {Activity.limit()} {gettext( + "events, in memory only. Receipts and usage are on disk; this is not." + )} +

+
+
+ """ + end + + defp name([:trinity | rest]), do: Enum.join(rest, ".") + defp name(other), do: inspect(other) + + # What a row says. Identifiers and outcomes, never content: the events do not carry content and + # this page does not invent any. + defp summarise(%{metadata: m}) do + [m[:tool], m[:model], m[:adapter], m[:decision], m[:outcome], m[:result], m[:to], m[:scope]] + |> Enum.reject(&is_nil/1) + |> Enum.map_join(" · ", &to_string/1) + end + + defp duration(%{duration: d}) when is_integer(d) do + ms = System.convert_time_unit(d, :native, :millisecond) + "#{ms} ms" + end + + defp duration(%{cost_usd: c}) when is_number(c) and c > 0, + do: "$" <> :erlang.float_to_binary(c / 1, decimals: 4) + + defp duration(_), do: "" +end diff --git a/lib/trinity_web/router.ex b/lib/trinity_web/router.ex index e55bc1f..534a4c5 100644 --- a/lib/trinity_web/router.ex +++ b/lib/trinity_web/router.ex @@ -46,6 +46,8 @@ defmodule TrinityWeb.Router do live "/permissions", PermissionsLive, :index # Slice 031: full-text search over every message. live "/search", SearchLive, :index + # Slice 090: what Trinity has been doing, and what it has cost. + live "/activity", ActivityLive, :index # Slice 034: settings, with the export as a download. live "/settings", SettingsLive, :index get "/settings/export.tar.gz", ExportController, :download @@ -102,7 +104,11 @@ defmodule TrinityWeb.Router do scope "/dev" do pipe_through :browser - live_dashboard "/dashboard", metrics: TrinityWeb.Telemetry, csp_nonce_assign_key: :csp_nonce + live_dashboard "/dashboard", + metrics: TrinityWeb.Telemetry, + csp_nonce_assign_key: :csp_nonce, + # Slice 090: which session processes are alive and what state each machine is in. + additional_pages: [trinity_sessions: TrinityWeb.Dashboard.SessionsPage] end end end diff --git a/scripts/dev_activity.sh b/scripts/dev_activity.sh new file mode 100755 index 0000000..549e75b --- /dev/null +++ b/scripts/dev_activity.sh @@ -0,0 +1,73 @@ +#!/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}") + +# Seeded through the schema, so the UUID and JSON columns are dumped correctly whichever adapter +# is underneath. A schemaless insert works on SQLite and is refused by Postgres. +for {model, cost, n} <- [{"anthropic:claude", 0.0121, 4}, {"openai:gpt", 0.0043, 6}, {"local:qwen", 0.0002, 11}], + _ <- 1..n do + Repo.insert!(%Trinity.LLM.Usage{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: %{}, inserted_at: DateTime.utc_now()}) +end + +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") +' diff --git a/test/changelog_test.exs b/test/changelog_test.exs new file mode 100644 index 0000000..439e188 --- /dev/null +++ b/test/changelog_test.exs @@ -0,0 +1,48 @@ +# SPDX-FileCopyrightText: Sudo Apt Holdings LLC +# SPDX-License-Identifier: Apache-2.0 +defmodule ChangelogTest do + @moduledoc """ + `CHANGELOG.md` says of itself that it "is derived from the tags themselves + (`git tag -l 'slice/*'`), not written from memory". This test is what makes that sentence true. + + It was not true when the test was written. Two tags, `slice/002` and `slice/025`, had no entry: + both were merged on a day when two other things were also merged, and both were simply missed. + Nothing failed, because nothing was checking. A public record of delivered work that is quietly + incomplete is worse than one that admits a gap, because a reader has no way to tell which kind + they are holding. + + **Why the empty case is a failure rather than a skip.** A checkout without tags - `actions/checkout` + at its default depth of one - can run this test and find nothing to check, and a test that passes + because it had nothing to look at is indistinguishable from one that passed because the tree was + right. Every CI leg that runs the suite therefore checks out with `fetch-depth: 0`, and this test + refuses to pass without tags rather than quietly agreeing. + + The direction is deliberate: every tag must have an entry, and an entry with no tag is fine. A + slice's entry is written in the pull request that closes it, which lands before the tag exists. + """ + use ExUnit.Case, async: true + + @changelog "CHANGELOG.md" + + defp tags do + {out, 0} = System.cmd("git", ["tag", "-l", "slice/*"]) + out |> String.split("\n", trim: true) |> Enum.sort() + end + + test "the checkout has the tags this test reads" do + assert tags() != [], + "`git tag -l 'slice/*'` found nothing, so this test cannot check anything. A CI job " <> + "running the suite must check out with `fetch-depth: 0`; a local clone has the tags " <> + "already. Passing here without tags would be a pass that measured nothing" + end + + test "every slice tag has an entry in the changelog" do + text = File.read!(@changelog) + + missing = Enum.reject(tags(), &String.contains?(text, "`#{&1}`")) + + assert missing == [], + "#{@changelog} has no entry for #{Enum.join(missing, ", ")}. The file states it is " <> + "derived from the tags; add the entry rather than the exception" + end +end diff --git a/test/trinity/subagents/supervision_test.exs b/test/trinity/subagents/supervision_test.exs index ba57031..f252f7c 100644 --- a/test/trinity/subagents/supervision_test.exs +++ b/test/trinity/subagents/supervision_test.exs @@ -29,6 +29,26 @@ defmodule Trinity.Subagents.SupervisionTest do assert Subagents.default_restarts() == 0 end + test "the caller of delegate/3 survives its child being killed" do + # The regression the Postgres leg found. Every call into a child is a gen_statem.call, and a + # call into a process that dies exits the caller; on SQLite the kill happened to land after + # the call returned and the test passed for that reason alone. + Fake.scripts([[{:text_delta, "working "}, {:sleep, 5_000}, {:done, :stop}]]) + parent = parent!() + + caller = + Task.Supervisor.async_nolink(Trinity.LLM.TaskSupervisor, fn -> + Subagents.delegate(parent.id, "a brief whose child dies mid-call") + end) + + child_id = await_child(parent.id) + {:ok, pid} = Sessions.ensure_started(child_id) + Process.exit(pid, :kill) + + # A result, not an exit: the parent is told its child died rather than dying with it. + assert {:ok, %{status: :error, reason: {:child_died, _}}} = Task.await(caller, 30_000) + end + test "a child killed mid-turn reports the death to its parent" do # The fake's own {:sleep, ms} keeps the turn open, so the kill lands mid-turn rather than # racing a turn that has already finished. A script that merely omits its terminator does @@ -37,7 +57,13 @@ defmodule Trinity.Subagents.SupervisionTest do Fake.scripts([[{:text_delta, "working "}, {:sleep, 5_000}, {:done, :stop}]]) parent = parent!() - task = Task.async(fn -> Subagents.delegate(parent.id, "a brief that gets interrupted") end) + # Task.async links, so if delegate/3 exited when the child died the test process would die + # with it rather than report. async_nolink is what makes the assertion below reachable when + # the library is wrong, which is the state this test is meant to detect. + task = + Task.Supervisor.async_nolink(Trinity.LLM.TaskSupervisor, fn -> + Subagents.delegate(parent.id, "a brief that gets interrupted") + end) # Wait for the child to exist, then kill its process. child_id = await_child(parent.id) diff --git a/test/trinity/telemetry/costs_test.exs b/test/trinity/telemetry/costs_test.exs new file mode 100644 index 0000000..8dd6c47 --- /dev/null +++ b/test/trinity/telemetry/costs_test.exs @@ -0,0 +1,183 @@ +# SPDX-FileCopyrightText: Sudo Apt Holdings LLC +# SPDX-License-Identifier: Apache-2.0 +defmodule Trinity.Telemetry.CostsTest do + @moduledoc """ + Slice 090, AC2 (the totals half, retagged `[auto]`): the ledger's totals equal the sum of the + rows, and a budget that is passed emits its warning. + + The SLICE made this criterion manual, to be checked by eye against a seeded dataset. A total is + arithmetic, and arithmetic is the last thing that should be checked by looking at it, so the + totals are asserted here and the manual queue keeps only the part that needs a person: the + blocking behaviour and its message on screen. + """ + use Trinity.DataCase, async: false + + alias Trinity.Repo + alias Trinity.Sessions + alias Trinity.Telemetry.Costs + + # Inserted through the schema rather than schemalessly. A schemaless insert has no schema to tell + # the adapter which columns are UUIDs or JSON, so it passes a string and a map straight through: + # SQLite accepts both, Postgres refuses both. Seeding through the schema keeps this test honest + # on the adapter the postgres leg runs, which is where the first version of it failed. + defp seed!(session_id, cost, opts \\ []) do + Repo.insert!(%Trinity.LLM.Usage{ + model_id: Keyword.get(opts, :model, "fake:chat"), + provider: "fake", + kind: "stream", + input_tokens: 10, + output_tokens: 20, + cached_tokens: 0, + reasoning_tokens: 0, + cost_usd: cost, + session_id: session_id, + provider_meta: %{}, + # Microsecond precision, because the schema declares :utc_datetime_usec and truncating to the + # second is a value it refuses. The schemaless version accepted it and wrote it anyway. + inserted_at: Keyword.get(opts, :at, DateTime.utc_now()) + }) + end + + defp session!(opts \\ []) do + {:ok, s} = + Sessions.create_session( + Enum.into(opts, %{persona_id: Sessions.default_persona().id, title: "t"}) + ) + + s + end + + setup do + prior = Application.get_env(:trinity, :budgets) + + on_exit(fn -> + if prior, + do: Application.put_env(:trinity, :budgets, prior), + else: Application.delete_env(:trinity, :budgets) + end) + + :ok + end + + describe "totals equal the sum of the rows" do + test "across everything, and per session" do + a = session!() + b = session!() + + seed!(a.id, 1.50) + seed!(a.id, 0.25) + seed!(b.id, 2.00) + + assert_in_delta Costs.total(), 3.75, 0.0001 + assert_in_delta Costs.for_session(a.id), 1.75, 0.0001 + assert_in_delta Costs.for_session(b.id), 2.00, 0.0001 + end + + test "per persona, summed across that persona's sessions" do + {:ok, persona} = Trinity.Personas.create(%{name: "auditor", soul: "careful"}) + mine = session!(persona_id: persona.id) + theirs = session!() + + seed!(mine.id, 3.00) + seed!(theirs.id, 9.99) + + assert_in_delta Costs.for_persona(persona.id), 3.00, 0.0001 + end + + test "by model, largest first, with the call count" do + s = session!() + seed!(s.id, 0.10, model: "cheap") + seed!(s.id, 0.10, model: "cheap") + seed!(s.id, 5.00, model: "dear") + + assert [{"dear", dear, 1}, {"cheap", cheap, 2}] = Costs.by_model() + assert_in_delta dear, 5.00, 0.0001 + assert_in_delta cheap, 0.20, 0.0001 + end + + test "an empty ledger is zero, not nil" do + # sum() over no rows is NULL, and a nil reaching a template renders as nothing rather than + # as a number, which reads as "no data" when it means "no spend". + assert Costs.total() == 0.0 + assert Costs.for_session(session!().id) == 0.0 + assert Costs.by_day() == [] + end + end + + describe "budgets" do + test "an unconfigured budget is not a budget of zero" do + Application.delete_env(:trinity, :budgets) + s = session!() + seed!(s.id, 1_000.0) + + # The alternative silently blocks every call on a fresh install. + assert Costs.budget(:day) == nil + assert Costs.check(:day) == :ok + assert Costs.check(:session, s.id) == :ok + end + + test "passing a budget answers with what was spent and what the limit was" do + Application.put_env(:trinity, :budgets, session: 1.0) + s = session!() + seed!(s.id, 2.50) + + assert {:over, spent, limit} = Costs.check(:session, s.id) + assert_in_delta spent, 2.50, 0.0001 + assert limit == 1.0 + end + + test "passing a budget emits the warning event, whether or not anything blocks on it" do + Application.put_env(:trinity, :budgets, day: 0.5) + s = session!() + seed!(s.id, 0.75) + + ref = make_ref() + me = self() + handler = "budget-#{System.unique_integer([:positive])}" + + :telemetry.attach( + handler, + [:trinity, :budget, :exceeded], + fn _, m, md, _ -> + send(me, {ref, m, md}) + end, + nil + ) + + on_exit(fn -> :telemetry.detach(handler) end) + + assert {:over, _, _} = Costs.check(:day) + assert_receive {^ref, %{spent_usd: _, limit_usd: 0.5}, %{scope: :day}} + end + + test "blocking is off unless configured, and separate from warning" do + Application.put_env(:trinity, :budgets, day: 0.01) + refute Costs.blocking?() + + Application.put_env(:trinity, :budgets, day: 0.01, block_when_over: true) + assert Costs.blocking?() + end + + test "over/2 reports every configured scope that is past its limit" do + {:ok, persona} = Trinity.Personas.create(%{name: "spender", soul: "eager"}) + s = session!(persona_id: persona.id) + seed!(s.id, 4.00) + + Application.put_env(:trinity, :budgets, day: 1.0, session: 10.0, persona: 2.0) + + scopes = Costs.over(s.id, persona.id) |> Enum.map(&elem(&1, 0)) |> Enum.sort() + assert scopes == [:day, :persona] + end + end + + test "the columns this module reads still exist" do + # The queries are schemaless, so the column names are the contract with slice 011's schema and + # nothing else checks them. A rename there should fail here rather than in a dashboard. + {:ok, %{columns: columns}} = + Repo.query("SELECT * FROM usage_events LIMIT 0") + + for column <- ~w(cost_usd session_id model_id inserted_at id) do + assert column in columns, "usage_events lost the #{column} column this ledger reads" + end + end +end diff --git a/test/trinity/telemetry/redaction_test.exs b/test/trinity/telemetry/redaction_test.exs new file mode 100644 index 0000000..20a7b08 --- /dev/null +++ b/test/trinity/telemetry/redaction_test.exs @@ -0,0 +1,98 @@ +# SPDX-FileCopyrightText: Sudo Apt Holdings LLC +# SPDX-License-Identifier: Apache-2.0 +defmodule Trinity.Telemetry.RedactionTest do + @moduledoc """ + Slice 090, AC4: a credential in a log message is masked. + + The tests here also state what the filter does **not** catch, in the same file, because a + redaction filter that is trusted beyond its reach is worse than none: it turns "we mask secrets" + into a belief rather than a mechanism. The controls are elsewhere (keys in files, no token in + records, no content in telemetry); this is a last line and the tests say so. + """ + use ExUnit.Case, async: true + + alias Trinity.Telemetry.Redaction + + describe "what it masks" do + test "an authorization header, however it is spelled" do + for prefix <- ~w(Bearer bearer Token basic) do + line = "GET /v1/models #{prefix} abcdefghijklmnopqrstuvwxyz123456" + out = Redaction.redact(line) + assert out =~ "[REDACTED]" + refute out =~ "abcdefghijklmnopqrstuvwxyz123456" + end + end + + test "a provider key, by its shape rather than by its name" do + line = "calling openai with sk-proj-AbCdEfGhIjKlMnOpQrStUvWxYz012345" + out = Redaction.redact(line) + refute out =~ "AbCdEfGhIjKlMnOpQrStUvWxYz012345" + assert out =~ "[REDACTED]" + end + + test "a JSON web token" do + jwt = "eyJhbGciOiJIUzI1NiJ9.eyJzdWIiOiIxMjM0NTY3ODkwIn0.dBjftJeZ4CVPmB92K27uhbUJU1p1r_wW1g" + assert Redaction.redact("token=#{jwt}") =~ "[REDACTED" + refute Redaction.redact("token=#{jwt}") =~ "dBjftJeZ4CVPmB92K27uhbUJU1p1r_wW1g" + end + + test "a named secret in a key/value position" do + for line <- [ + "password: hunter2-and-then-some", + "api_key=sk_live_something_long_here", + "access-token = zzzzzzzzzzzzzzzzzzzz", + "PRIVATE_KEY:abcdefghijklmnop" + ] do + out = Redaction.redact(line) + assert out =~ "[REDACTED]", "not masked: #{line} -> #{out}" + end + end + + test "it masks inside a Logger event's message and metadata, and never drops the event" do + event = %{ + msg: {:string, "connecting with Bearer abcdefghijklmnopqrstuvwxyz"}, + meta: %{header: "Authorization: Bearer abcdefghijklmnopqrstuvwxyz", session_id: "s-1"} + } + + out = Redaction.filter(event, nil) + + assert {:string, masked} = out.msg + assert masked =~ "[REDACTED]" + refute masked =~ "abcdefghijklmnopqrstuvwxyz" + refute out.meta.header =~ "abcdefghijklmnopqrstuvwxyz" + + # The event survives: a filter that drops a line to avoid printing a secret also drops the + # evidence that something happened. + assert out.meta.session_id == "s-1" + end + end + + describe "truncation" do + test "a long message is cut and says how much was dropped" do + long = String.duplicate("x", Redaction.max_chars() + 500) + out = Redaction.truncate(long) + + assert String.length(out) < String.length(long) + assert out =~ "500 more characters" + end + + test "a short message is untouched" do + assert Redaction.truncate("short") == "short" + end + end + + describe "what it does not catch, stated rather than left to be discovered" do + test "a credential with no recognisable shape passes through" do + # This is the filter's honest limit. It matches shapes, and a secret that looks like an + # ordinary word is an ordinary word to it. + line = "the passphrase is correct horse battery staple" + assert Redaction.redact(line) == line + end + + test "content that merely looks like a credential is masked, and that is the right trade" do + # Over-masking costs a reader context; under-masking puts a key on disk. + line = "the user wrote: my password: is a secret I keep" + assert Redaction.redact(line) =~ "[REDACTED]" + end + end +end diff --git a/test/trinity/telemetry/telemetry_test.exs b/test/trinity/telemetry/telemetry_test.exs new file mode 100644 index 0000000..aafa8b3 --- /dev/null +++ b/test/trinity/telemetry/telemetry_test.exs @@ -0,0 +1,257 @@ +# SPDX-FileCopyrightText: Sudo Apt Holdings LLC +# SPDX-License-Identifier: Apache-2.0 +defmodule Trinity.TelemetryTest do + @moduledoc """ + Slice 090, AC1 and AC4: the documented events are emitted with the documented metadata, the + catalogue and the code agree, and no event carries content. + + The last of those is the one worth writing carefully. A telemetry handler can be attached by + anything in the VM, and its output reaches dashboards, logs and exporters; an event that carried + a prompt or a tool's arguments would be a conversation leaving by a side door. So the tests here + do not only assert that events fire, they assert what is **absent** from them. + """ + use Trinity.SessionCase + + alias Trinity.Telemetry + + setup do + ref = make_ref() + handler = "test-#{System.unique_integer([:positive])}" + me = self() + + :telemetry.attach_many( + handler, + Telemetry.catalogue(), + fn name, measurements, metadata, _ -> + send(me, {ref, name, measurements, metadata}) + end, + nil + ) + + on_exit(fn -> :telemetry.detach(handler) end) + {:ok, ref: ref} + end + + describe "AC1: the documented events fire with the documented metadata" do + test "a tool call emits a start and a stop naming the tool and its result", %{ref: ref} do + {:ok, session} = + Sessions.create_session(%{persona_id: Sessions.default_persona().id, title: "t"}) + + ctx = %Trinity.Tools.Context{session_id: session.id} + {:ok, entry} = Trinity.Tools.Registry.lookup("echo") + + Trinity.Tools.Runner.call_tool(entry, %{"text" => "hello"}, ctx) + + assert_receive {^ref, [:trinity, :tool, :call, :start], %{system_time: _}, start_meta} + assert start_meta.tool == "echo" + assert start_meta.session_id == session.id + + assert_receive {^ref, [:trinity, :tool, :call, :stop], %{duration: d}, stop_meta} + assert is_integer(d) + assert stop_meta.tool == "echo" + assert stop_meta.result == :ok + end + + test "a tool call's events carry the tool's name and never its arguments", %{ref: ref} do + {:ok, session} = + Sessions.create_session(%{persona_id: Sessions.default_persona().id, title: "t"}) + + ctx = %Trinity.Tools.Context{session_id: session.id} + {:ok, entry} = Trinity.Tools.Registry.lookup("echo") + secret = "a-value-that-must-not-appear-in-telemetry" + + Trinity.Tools.Runner.call_tool(entry, %{"text" => secret}, ctx) + + assert_receive {^ref, [:trinity, :tool, :call, :start], _, start_meta} + assert_receive {^ref, [:trinity, :tool, :call, :stop], _, stop_meta} + + refute inspect(start_meta) =~ secret + 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"}) + + {:ok, _pid} = Sessions.ensure_started(session.id) + + assert_receive {^ref, [:trinity, :session, :transition], %{count: 1}, meta} + assert meta.session_id == session.id + assert meta.to == :idle + end + + test "the approval and budget emitters carry what the catalogue says" do + ref = make_ref() + me = self() + handler = "t2-#{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.approval_requested("write_note", :write, "sess-1") + + assert_receive {^ref, [:trinity, :approval, :requested], %{count: 1}, + %{tool: "write_note", risk: :write}} + + Telemetry.approval_decided("write_note", :write, "sess-1", + decision: :once, + basis: :user, + waited_ms: 42 + ) + + assert_receive {^ref, [:trinity, :approval, :decided], %{waited_ms: 42}, + %{decision: :once, basis: :user}} + + Telemetry.budget_exceeded(:day, "2026-09-24", 12.5, 10.0) + + assert_receive {^ref, [:trinity, :budget, :exceeded], %{spent_usd: 12.5, limit_usd: 10.0}, + %{scope: :day}} + end + + test "a gateway outcome outside the closed set is a function clause, not a new label" do + # The atom is built at runtime so the type checker cannot prove the call fails and warn + # about it: the point of the test is the guard's behaviour, not the compiler's opinion. + outcome = String.to_atom("not" <> "_an_outcome") + assert_raise FunctionClauseError, fn -> Telemetry.gateway_inbound("console", outcome) end + 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") + + for name <- Telemetry.catalogue() do + rendered = "[" <> Enum.map_join(name, ", ", &":#{&1}") <> "]" + + assert String.contains?(doc, rendered), + "#{rendered} is emitted but not documented in docs/telemetry.md" + end + end + + test "every trinity event in the document is one the code can emit" do + documented = + "docs/telemetry.md" + |> File.read!() + |> then(&Regex.scan(~r/\[:trinity(?:, :[a-z_]+)+\]/, &1)) + |> Enum.map(&hd/1) + |> Enum.uniq() + + known = + Enum.map(Telemetry.catalogue(), fn n -> + "[" <> Enum.map_join(n, ", ", &":#{&1}") <> "]" + end) + + assert documented -- known == [], + "documented but not emittable: #{inspect(documented -- known)}" + end + end +end diff --git a/test/trinity_web/live/activity_live_test.exs b/test/trinity_web/live/activity_live_test.exs new file mode 100644 index 0000000..39bd2a9 --- /dev/null +++ b/test/trinity_web/live/activity_live_test.exs @@ -0,0 +1,98 @@ +# SPDX-FileCopyrightText: Sudo Apt Holdings LLC +# SPDX-License-Identifier: Apache-2.0 +defmodule TrinityWeb.ActivityLiveTest do + @moduledoc """ + Slice 090, AC6: the Activity page. + + The assertion that matters most here is a negative one. The page shows events, and events carry + no content by rule (`docs/telemetry.md`); a test that only checked rows appeared would pass + equally well on a page that had quietly started showing prompts. + """ + use TrinityWeb.ConnCase, async: false + + import Phoenix.LiveViewTest + + alias Trinity.Sessions + alias Trinity.Telemetry + alias Trinity.Telemetry.Activity + + setup do + Activity.clear() + on_exit(&Activity.clear/0) + :ok + end + + defp settle, do: Activity.recent() + + test "an empty buffer says so rather than showing an empty box", %{conn: conn} do + {:ok, _live, html} = live(conn, ~p"/activity") + assert html =~ "Nothing yet" + end + + test "events appear, newest first, with their name and their subject", %{conn: conn} do + Telemetry.approval_requested("write_note", :write, "sess-abc") + Telemetry.gateway_inbound("console", :placed) + settle() + + {:ok, _live, html} = live(conn, ~p"/activity") + + assert html =~ "approval.requested" + assert html =~ "write_note" + assert html =~ "gateway.inbound" + assert html =~ "console" + end + + test "the page shows no conversation content, because the events carry none", %{conn: conn} do + {:ok, session} = + Sessions.create_session(%{persona_id: Sessions.default_persona().id, title: "t"}) + + ctx = %Trinity.Tools.Context{session_id: session.id} + {:ok, entry} = Trinity.Tools.Registry.lookup("echo") + secret = "a-phrase-that-must-never-reach-a-page" + + Trinity.Tools.Runner.call_tool(entry, %{"text" => secret}, ctx) + settle() + + {:ok, _live, html} = live(conn, ~p"/activity") + + assert html =~ "tool.call.stop" + assert html =~ "echo" + refute html =~ secret + end + + test "filtering by kind and by session narrows the list", %{conn: conn} do + Telemetry.approval_requested("write_note", :write, "sess-1") + Telemetry.gateway_inbound("console", :placed) + settle() + + {:ok, live, _html} = live(conn, ~p"/activity") + + html = live |> form("form[phx-change=filter]", %{"kind" => "approval"}) |> render_change() + assert html =~ "approval.requested" + refute html =~ "gateway.inbound" + + html = + live |> form("form[phx-change=session]", %{"session_id" => "sess-1"}) |> render_change() + + assert html =~ "approval.requested" + end + + test "clearing empties the buffer", %{conn: conn} do + Telemetry.approval_requested("write_note", :write, "sess-1") + settle() + + {:ok, live, _html} = live(conn, ~p"/activity") + html = live |> element("button[phx-click=clear]") |> render_click() + + assert html =~ "Nothing yet" + end + + test "the buffer is bounded, so a long run does not grow without limit" do + for n <- 1..(Activity.limit() + 50) do + Telemetry.approval_requested("tool-#{n}", :read, "sess-1") + end + + settle() + assert length(Activity.recent()) == Activity.limit() + end +end