From b6304db2263b321bf10694ee10931ab8dbf89d40 Mon Sep 17 00:00:00 2001 From: Ayla Croft Date: Sat, 26 Sep 2026 10:21:08 -0400 Subject: [PATCH 1/2] test(s126): red first, an allow the owner issued is dropped and never consumed Three failing tests, committed before any fix, by name: AC1: an allow clicked on the requested broadcast, with no wait for approval_wait, consumes the row and runs the call -> consumed_at is nil after status "allowed", decision "once" AC3/AC4: the chain reads ask then allow, both on the same scope, and neither is a timeout -> the chain carries ["ask"] and nothing else. The owner answered and the chain does not carry the answer. AC5: at the instant the requested broadcast is observable, the session can already accept a decision -> decided straight through the gate, no LiveView involved at all, and the grant is still not applied The difference from every approval test that passes is one line those tests have and a browser does not: collect(id, &match?({:state, :approval_wait}, &1)) 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 has only ever exercised the ordering that works, and the synchronisation it relies on is not something any real caller can perform. AC5 is the one that rules out "the LiveView should wait": it decides through Permissions.decide_request/3 with no view in the loop and fails the same way. Note on reading the failing output: these runs also log a DBConnection ownership crash from the tool task. That is a consequence, not the defect. The assertions on status and decision pass before consumed_at fails, so the decision is recorded and never consumed; the ownership report is in-flight work colliding with sandbox teardown after the assertion has already failed. The existing approval_live_test.exs produces none of it and stays green. Signed-off-by: Ayla Croft --- .../trinity_web/live/approval_resume_test.exs | 136 ++++++++++++++++++ 1 file changed, 136 insertions(+) create mode 100644 test/trinity_web/live/approval_resume_test.exs 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..b623530 --- /dev/null +++ b/test/trinity_web/live/approval_resume_test.exs @@ -0,0 +1,136 @@ +# 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, collect: 3] + + 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() + + 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. + assert_receive {:approval, :requested, %Approval{id: aid}}, 5_000 + assert has_element?(view, "#approval-#{aid}") + + view |> element("#approval-#{aid} button", "Allow once") |> render_click() + + _ = collect(id, &match?({:state, :idle}, &1), 15_000) + + 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 + view |> element("#approval-#{aid} button", "Allow once") |> render_click() + _ = collect(id, &match?({:state, :idle}, &1), 15_000) + + 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") + + _ = collect(id, &match?({:state, :idle}, &1), 15_000) + + assert Permissions.get_approval(aid).consumed_at, + "a decision made through the gate at the first observable instant was not applied" + end +end From e67c3830918b4e64331503f3e8e970d39ccf1936 Mon Sep 17 00:00:00 2001 From: Ayla Croft Date: Sat, 26 Sep 2026 11:19:30 -0400 Subject: [PATCH 2/2] fix(s126): complete slice 126 (nothing about an approval is discarded in silence) This slice is a retraction. The defect it was opened for does not exist. The approval handshake is correct. A decision arriving while the Session is in tool_wait is postponed and redelivered on the next state change, exactly as the comment in session.ex claims, and a decision made straight through Permissions.decide_request/3, with no LiveView in the loop, is applied. The owner's invariant already held. Both reproductions I reported are withdrawn. The suite one was my own test bug. It ended with collect(id, &match?({:state, :idle}, &1), 15_000) and collect/3 reads the mailbox, where an {:state, :idle} broadcast from before the message was sent was already waiting. It returned at once and every assertion ran mid-turn. The tell was in the output all along: "Finished in 0.2 seconds" for a test nominally waiting fifteen. The live one was scripts/dev_demo_approval.sh, which I wrote the previous day for the README assets. It stripped the sandbox pool from Trinity.Repo and did nothing for Trinity.Repo.Receipts, so outside the suite that pool sat in auto mode and, as config/test.exs warns in its own comment about the other repo, the first long-lived process to query held the connection until it exited. Effects.Runner.execute/3 receipts a decision before it dispatches, which is what makes "nothing fails open" true, so every Receipts.append/2 queued behind that holder and the tool task blocked after the approval row existed and the card was painted but before it could answer the Session. Hence consumed_at nil, a chain carrying the ask and not the allow, and a visible "error: the tool timed out". Every symptom was real and the cause was mine. The intermittency was the sandbox connection sometimes being free. What lands: - scripts/dev_demo_approval.sh: the sandbox pool stripped from both repos, the receipts database pointed at its own file rather than the test suite's, and no apostrophes inside the -e block. That last one is not cosmetic: a single apostrophe terminates the quoted string and the script dies with no output. Browser drives go from stalling in tool_wait at 14s and counting to reaching approval_wait at t=0s and completing 5 of 5, with the chain reading ask, allow, effect admit, effect done. - One change under lib/, and only one, because the instruction was explicit that no product bug be invented to fill the slice. The catch-all for {:approval, _, _} discarded any unmatched approval event without a word, and a trace showed :requested discarded in tool_wait on every single turn. A :requested stays routine and is deliberately not given a second path into the approval flow. Anything else is an answer with no held call to apply it to, which is the one shape that can lose a decision, so it is logged and receipted as outcome=dropped. The receipt is written off the session's task supervisor, never inline, because blocking the Session on a receipt write is the precise shape of the stall this slice was opened to explain. Red first: AC6 fails against the old clause at 3/4 and passes at 4/4. - Three LiveView tests as regression cover. They pass against unmodified lib/ and PROOF.md says so rather than dressing them as a fix. They exist because every approval test in the tree synchronises on {:state, :approval_wait} before clicking, which no real caller can do, so the ordering a browser actually produces had never been exercised. Signed-off-by: Ayla Croft --- CHANGELOG.md | 27 +++++++ lib/trinity/sessions/session.ex | 53 +++++++++++- scripts/dev_demo_approval.sh | 12 +++ .../trinity_web/live/approval_resume_test.exs | 81 +++++++++++++++++-- 4 files changed, 165 insertions(+), 8 deletions(-) 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 index b623530..985424d 100644 --- a/test/trinity_web/live/approval_resume_test.exs +++ b/test/trinity_web/live/approval_resume_test.exs @@ -19,7 +19,7 @@ defmodule TrinityWeb.ApprovalResumeTest do @moduletag :capture_log import Phoenix.LiveViewTest - import Trinity.SessionCase, only: [script_deltas: 2, collect: 3] + import Trinity.SessionCase, only: [script_deltas: 2] alias Trinity.Factory alias Trinity.LLM.Providers.Fake @@ -53,19 +53,51 @@ defmodule TrinityWeb.ApprovalResumeTest do 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. + # 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 has_element?(view, "#approval-#{aid}") + + assert wait_until(fn -> has_element?(view, "#approval-#{aid}") end), + "the approval card never rendered" view |> element("#approval-#{aid} button", "Allow once") |> render_click() - _ = collect(id, &match?({:state, :idle}, &1), 15_000) + _ = wait_until(fn -> settled?(view) end) approval = Permissions.get_approval(aid) assert approval.status == "allowed" @@ -83,7 +115,7 @@ defmodule TrinityWeb.ApprovalResumeTest do (html |> String.replace(~r/<[^>]*>/, " ") |> String.replace(~r/\s+/, " ")) refute html =~ "timed out", - "an allow the owner issued was reported as a timeout" + "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", @@ -93,8 +125,9 @@ defmodule TrinityWeb.ApprovalResumeTest do 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() - _ = collect(id, &match?({:state, :idle}, &1), 15_000) + _ = wait_until(fn -> settled?(view) end) rows = Receipts.list("session:" <> id) decisions = Enum.filter(rows, &(&1.kind == "decision")) @@ -128,9 +161,43 @@ defmodule TrinityWeb.ApprovalResumeTest do # what state the Session is in. assert {:ok, _} = Permissions.decide_request(aid, :once, decided_by: "test") - _ = collect(id, &match?({:state, :idle}, &1), 15_000) + _ = 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