diff --git a/CHANGELOG.md b/CHANGELOG.md index 11f4072..190d063 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -24,6 +24,33 @@ evidence for each increment is retained by the maintainers and summarised here. ## 2026-09-26 +### `slice/126`: nothing about an approval is discarded in silence + +A decision the owner makes that arrives when there is no held call to apply it to used to be thrown +away without a word. It is now logged, and receipted on the session chain as `outcome=dropped` with +the reason naming the state it arrived in, so "the owner answered and nothing happened" can never be +something only a live trace would reveal. A request broadcast arriving the same way stays routine and +is deliberately not given a second path into the approval flow: which calls are held is learned in +one place, and learning it twice is how a call gets held twice. + +This increment was opened to fix a defect that turned out not to exist. The approval handshake is +correct: a decision arriving while the session is still waiting on its tools is held and redelivered, +and a decision made directly against the permission gate, with no interface in the loop, is applied. +The stall that prompted the work was caused by a development screenshot script, which left the +receipts database on the test sandbox pool; outside the suite that pool blocks, and because a +decision is receipted before it is dispatched, the tool task stopped after the approval existed and +the card was on screen but before it could answer the session. The visible result was an approval the +owner had granted, reported as a timeout. The script is fixed and the browser path now completes five +runs out of five. + +Three tests were added covering the ordering a browser actually produces, which the suite had never +exercised because every approval test waits for internal session state that no real caller can +observe. They pass against unchanged application code and are recorded as regression cover rather +than as a fix. + +Verified: gate green at exit 0; 825 tests passing; coverage 80.31%, level with the previous +increment. + ### `slice/124`: What the receipts are, in the standard's words IETF RFC 9943 (SCITT) standardises the class of object Trinity's receipts belong to, and it splits diff --git a/lib/trinity/sessions/session.ex b/lib/trinity/sessions/session.ex index c47e385..c9e0941 100644 --- a/lib/trinity/sessions/session.ex +++ b/lib/trinity/sessions/session.ex @@ -268,7 +268,33 @@ defmodule Trinity.Sessions.Session do def handle_event(:info, {:approval, :decided, _}, :tool_wait, _data), do: {:keep_state_and_data, [:postpone]} - def handle_event(:info, {:approval, _, _}, _state, _data), do: :keep_state_and_data + # Slice 126: nothing about an approval is discarded quietly. + # + # A `:requested` reaching here is routine and stays routine. The Session learns which calls are + # held from `tools_done` and never from this broadcast, so acting on it would be a second path to + # the same fact and a way for a call to be held twice. It is logged and dropped, deliberately. + def handle_event(:info, {:approval, :requested, approval}, state, %State{id: id}) do + Logger.debug(fn -> + "session #{id}: approval #{approval.id} requested in #{inspect(state)}. Held calls come " <> + "from tools_done, so this broadcast is not acted on." + end) + + :keep_state_and_data + end + + # Anything else reaching here is an answer with no held call to apply it to, which is the one + # shape that can lose a decision the owner made. Before this slice it returned + # `:keep_state_and_data` and said nothing, so "the owner answered and nothing happened" was + # visible only to someone tracing a live process. It is now a warning and a receipt. + def handle_event(:info, {:approval, kind, approval}, state, %State{} = data) do + Logger.warning( + "session #{data.id}: approval #{approval.id} #{kind} in #{inspect(state)} with no held " <> + "call to apply it to. Dropped, and receipted as outcome=dropped." + ) + + receipt_dropped_approval(data, kind, approval, state) + :keep_state_and_data + end # Slice 023: the compaction row is written here, in the Session (a row, then a broadcast), # from what the Task's model call answered; then the turn goes on, or forks past the hard @@ -714,6 +740,31 @@ defmodule Trinity.Sessions.Session do end end + # Written off the session's own task supervisor rather than inline. `Trinity.Receipts.append/2` + # is a call into the scope's ChainWriter, and blocking the Session on a receipt write is the + # precise shape of the stall this slice was opened to explain. + defp receipt_dropped_approval(%State{id: id, task_sup: sup}, kind, approval, state) do + Task.Supervisor.start_child(sup, fn -> + Trinity.Receipts.append("session:" <> id, %{ + kind: "decision", + subject: %{ + "session_id" => id, + "approval_id" => approval.id, + "tool" => approval.tool + }, + decision: %{ + "outcome" => "dropped", + "basis" => "session", + "reason" => "approval #{kind} in #{inspect(state)} with no held call to apply it to" + }, + fingerprint: approval.fingerprint, + subject_ref: "approval_dropped:#{id}:#{approval.id}" + }) + end) + + :ok + end + defp start_tools(%State{turn: turn} = data), do: start_tools(data, turn.pending) defp start_tools(%State{id: id, session: session, task_sup: sup, turn: turn} = data, calls) do diff --git a/scripts/dev_demo_approval.sh b/scripts/dev_demo_approval.sh index 212930d..a0fee2b 100755 --- a/scripts/dev_demo_approval.sh +++ b/scripts/dev_demo_approval.sh @@ -13,6 +13,18 @@ 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) +# The receipts repo needs the same two changes and was not getting them. Left on +# `pool: Ecto.Adapters.SQL.Sandbox` outside the suite, the sandbox is in auto mode and, as +# config/test.exs says in its own comment, the first long-lived process to query holds the +# connection until it exits. Every `Receipts.append/2` then queues behind it, and since the effect +# membrane receipts the decision *before* it dispatches, the tool task blocks after the approval row +# exists and the card is on screen but before it can answer the Session. The turn never leaves +# tool_wait, the allow the owner issued is never consumed, and the call finally reports a timeout. +# That is a harness defect and it looked exactly like a product one. +# The database also has to move: without this, a screenshot run writes into the receipts file +# belonging to the test suite. +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, :permissions, expiry_ms: 600_000, session_grant_ms: 3_600_000) diff --git a/test/trinity_web/live/approval_resume_test.exs b/test/trinity_web/live/approval_resume_test.exs new file mode 100644 index 0000000..985424d --- /dev/null +++ b/test/trinity_web/live/approval_resume_test.exs @@ -0,0 +1,203 @@ +# SPDX-FileCopyrightText: Sudo Apt Holdings LLC +# SPDX-License-Identifier: Apache-2.0 +defmodule TrinityWeb.ApprovalResumeTest do + @moduledoc """ + Slice 126: an allow the owner issued always consumes its approval and runs the call. + + The invariant, set by the owner before work started: an allow either consumes the row, runs the + tool and leaves the allow receipt on the same chain as the ask, or it fails closed with a receipt + naming why it could not be consumed. `consumed_at: nil` after a granted allow is a defect and + never a timeout. + + Every approval test before this one calls `collect(id, &match?({:state, :approval_wait}, &1))` + before clicking. That is a synchronisation the product does not have: the card is rendered from the + gate's `:requested` broadcast, which is emitted from inside the tool task, before the Session has + returned from `start_tools`. So the suite only ever exercised the ordering that works. These tests + deliberately do not wait. + """ + use TrinityWeb.ConnCase, async: false + @moduletag :capture_log + + import Phoenix.LiveViewTest + import Trinity.SessionCase, only: [script_deltas: 2] + + alias Trinity.Factory + alias Trinity.LLM.Providers.Fake + alias Trinity.Permissions + alias Trinity.Permissions.Approval + alias Trinity.Receipts + + setup do + Fake.clear() + on_exit(fn -> Trinity.SessionCase.stop_all_sessions() end) + row = Factory.session!() + :ok = Trinity.Sessions.subscribe(row.id) + :ok = Permissions.subscribe(row.id) + {:ok, id: row.id} + end + + @args %{"path" => "/home/me/notes/a.md", "text" => "hi"} + + defp write_turn do + Fake.scripts([ + [ + {:tool_call_start, "c1", "write_note"}, + {:tool_call_end, "c1", @args}, + {:usage, %{input_tokens: 1, output_tokens: 1}}, + {:done, :tool_calls} + ], + script_deltas(2, "written ") + ]) + end + + defp send_message(view, text), + do: view |> form("#composer", %{"content" => text}) |> render_submit() + + # A deadline, not a synchronisation with the session's internals. `collect/3` cannot be used to + # wait for the end of the turn here: it reads the mailbox, and an `{:state, :idle}` broadcast from + # before the message was sent is already sitting in it, so it returns at once and the assertion + # runs while the turn is still in flight. That mistake made an early version of this file fail for + # a reason that had nothing to do with the defect. + defp wait_until(fun, timeout \\ 8_000) do + deadline = System.monotonic_time(:millisecond) + timeout + do_wait(fun, deadline) + end + + defp do_wait(fun, deadline) do + cond do + fun.() -> + true + + System.monotonic_time(:millisecond) >= deadline -> + false + + true -> + Process.sleep(50) + do_wait(fun, deadline) + end + end + + # The turn has settled when it has produced an outcome for the call, whichever outcome that is. + defp settled?(view), do: render(view) =~ "wrote 2 bytes" or render(view) =~ "timed out" + + test "AC1: an allow clicked on the requested broadcast, with no wait for approval_wait, consumes the row and runs the call", + %{conn: conn, id: id} do + write_turn() + {:ok, view, _} = live(conn, ~p"/s/#{id}") + send_message(view, "write it") + + # The only synchronisation a browser has: the card is on the page. Waiting for it is not the + # same as waiting for `approval_wait`. The test process and the LiveView subscribe to the same + # topic, so the test can win that race and look before the view has re-rendered; a browser + # cannot click a card that is not painted yet either way. + assert_receive {:approval, :requested, %Approval{id: aid}}, 5_000 + + assert wait_until(fn -> has_element?(view, "#approval-#{aid}") end), + "the approval card never rendered" + + view |> element("#approval-#{aid} button", "Allow once") |> render_click() + + _ = wait_until(fn -> settled?(view) end) + + approval = Permissions.get_approval(aid) + assert approval.status == "allowed" + assert approval.decision == "once" + + assert approval.consumed_at, + "the owner allowed this call and the grant was never consumed. consumed_at is nil, " <> + "which is the signature of the decision being dropped rather than applied: the click " <> + "landed before the session had left tool_wait" + + html = render(view) + + assert html =~ "wrote 2 bytes", + "the approved call did not run. Rendered instead: " <> + (html |> String.replace(~r/<[^>]*>/, " ") |> String.replace(~r/\s+/, " ")) + + refute html =~ "timed out", + "an allow the owner issued was reported as a timeout" + end + + test "AC3/AC4: the chain reads ask then allow, both on the same scope, and neither is a timeout", + %{conn: conn, id: id} do + write_turn() + {:ok, view, _} = live(conn, ~p"/s/#{id}") + send_message(view, "write it") + + assert_receive {:approval, :requested, %Approval{id: aid}}, 5_000 + assert wait_until(fn -> has_element?(view, "#approval-#{aid}") end) + view |> element("#approval-#{aid} button", "Allow once") |> render_click() + _ = wait_until(fn -> settled?(view) end) + + rows = Receipts.list("session:" <> id) + decisions = Enum.filter(rows, &(&1.kind == "decision")) + + outcomes = + for r <- decisions, {:ok, body} <- [JSON.decode(r.signed_payload)] do + get_in(body, ["decision", "outcome"]) + end + + assert "ask" in outcomes, "no ask receipt on the session chain: #{inspect(outcomes)}" + + assert "allow" in outcomes, + "the ask was receipted and the allow was not, on chain #{inspect(outcomes)}. The owner " <> + "answered and the chain does not carry the answer" + + assert Enum.find_index(outcomes, &(&1 == "ask")) < + Enum.find_index(outcomes, &(&1 == "allow")), + "the allow is not after the ask on the chain: #{inspect(outcomes)}" + end + + test "AC5: at the instant the requested broadcast is observable, the session can already accept a decision", + %{conn: conn, id: id} do + write_turn() + {:ok, view, _} = live(conn, ~p"/s/#{id}") + send_message(view, "write it") + + assert_receive {:approval, :requested, %Approval{id: aid}}, 5_000 + + # Decide straight through the gate, with no LiveView in the way at all, at the first instant + # the request is observable by anyone. Nothing in the product may require the caller to know + # what state the Session is in. + assert {:ok, _} = Permissions.decide_request(aid, :once, decided_by: "test") + + _ = wait_until(fn -> Permissions.get_approval(aid).consumed_at != nil end) + + assert Permissions.get_approval(aid).consumed_at, + "a decision made through the gate at the first observable instant was not applied" + end + + test "AC6: an approval event with no held call to apply it to is logged and receipted, never dropped in silence", + %{id: id} do + # No turn at all: the session is idle, so a decision broadcast to it has nothing to apply. That + # is the shape that used to return :keep_state_and_data and say nothing. + {:ok, _pid} = Trinity.Sessions.ensure_started(id) + + {:ok, approval} = + Permissions.request_approval(id, "write_note", @args, risk: :write, cwd: nil) + + log = + ExUnit.CaptureLog.capture_log(fn -> + {:ok, _} = Permissions.decide_request(approval.id, :once, decided_by: "test") + + wait_until(fn -> + ("session:" <> id) + |> Receipts.list() + |> Enum.any?(&(&1.subject_ref == "approval_dropped:#{id}:#{approval.id}")) + end) + end) + + assert log =~ "with no held call to apply it to", + "the drop was not logged. A decision the owner made went nowhere and said nothing." + + row = + ("session:" <> id) + |> Receipts.list() + |> Enum.find(&(&1.subject_ref == "approval_dropped:#{id}:#{approval.id}")) + + assert row, "the drop was not receipted" + assert {:ok, body} = JSON.decode(row.signed_payload) + assert get_in(body, ["decision", "outcome"]) == "dropped" + assert get_in(body, ["decision", "reason"]) =~ "no held call" + end +end