Slice 126: a retraction, and nothing about an approval is discarded in silence

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

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

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)

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