Skip to content

Commit e67c383

Browse files
committed
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 <aylacroft@proton.me>
1 parent b6304db commit e67c383

4 files changed

Lines changed: 165 additions & 8 deletions

File tree

‎CHANGELOG.md‎

Lines changed: 27 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -24,6 +24,33 @@ evidence for each increment is retained by the maintainers and summarised here.
2424

2525
## 2026-09-26
2626

27+
### `slice/126`: nothing about an approval is discarded in silence
28+
29+
A decision the owner makes that arrives when there is no held call to apply it to used to be thrown
30+
away without a word. It is now logged, and receipted on the session chain as `outcome=dropped` with
31+
the reason naming the state it arrived in, so "the owner answered and nothing happened" can never be
32+
something only a live trace would reveal. A request broadcast arriving the same way stays routine and
33+
is deliberately not given a second path into the approval flow: which calls are held is learned in
34+
one place, and learning it twice is how a call gets held twice.
35+
36+
This increment was opened to fix a defect that turned out not to exist. The approval handshake is
37+
correct: a decision arriving while the session is still waiting on its tools is held and redelivered,
38+
and a decision made directly against the permission gate, with no interface in the loop, is applied.
39+
The stall that prompted the work was caused by a development screenshot script, which left the
40+
receipts database on the test sandbox pool; outside the suite that pool blocks, and because a
41+
decision is receipted before it is dispatched, the tool task stopped after the approval existed and
42+
the card was on screen but before it could answer the session. The visible result was an approval the
43+
owner had granted, reported as a timeout. The script is fixed and the browser path now completes five
44+
runs out of five.
45+
46+
Three tests were added covering the ordering a browser actually produces, which the suite had never
47+
exercised because every approval test waits for internal session state that no real caller can
48+
observe. They pass against unchanged application code and are recorded as regression cover rather
49+
than as a fix.
50+
51+
Verified: gate green at exit 0; 825 tests passing; coverage 80.31%, level with the previous
52+
increment.
53+
2754
### `slice/124`: What the receipts are, in the standard's words
2855

2956
IETF RFC 9943 (SCITT) standardises the class of object Trinity's receipts belong to, and it splits

‎lib/trinity/sessions/session.ex‎

Lines changed: 52 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -268,7 +268,33 @@ defmodule Trinity.Sessions.Session do
268268
def handle_event(:info, {:approval, :decided, _}, :tool_wait, _data),
269269
do: {:keep_state_and_data, [:postpone]}
270270

271-
def handle_event(:info, {:approval, _, _}, _state, _data), do: :keep_state_and_data
271+
# Slice 126: nothing about an approval is discarded quietly.
272+
#
273+
# A `:requested` reaching here is routine and stays routine. The Session learns which calls are
274+
# held from `tools_done` and never from this broadcast, so acting on it would be a second path to
275+
# the same fact and a way for a call to be held twice. It is logged and dropped, deliberately.
276+
def handle_event(:info, {:approval, :requested, approval}, state, %State{id: id}) do
277+
Logger.debug(fn ->
278+
"session #{id}: approval #{approval.id} requested in #{inspect(state)}. Held calls come " <>
279+
"from tools_done, so this broadcast is not acted on."
280+
end)
281+
282+
:keep_state_and_data
283+
end
284+
285+
# Anything else reaching here is an answer with no held call to apply it to, which is the one
286+
# shape that can lose a decision the owner made. Before this slice it returned
287+
# `:keep_state_and_data` and said nothing, so "the owner answered and nothing happened" was
288+
# visible only to someone tracing a live process. It is now a warning and a receipt.
289+
def handle_event(:info, {:approval, kind, approval}, state, %State{} = data) do
290+
Logger.warning(
291+
"session #{data.id}: approval #{approval.id} #{kind} in #{inspect(state)} with no held " <>
292+
"call to apply it to. Dropped, and receipted as outcome=dropped."
293+
)
294+
295+
receipt_dropped_approval(data, kind, approval, state)
296+
:keep_state_and_data
297+
end
272298

273299
# Slice 023: the compaction row is written here, in the Session (a row, then a broadcast),
274300
# 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
714740
end
715741
end
716742

743+
# Written off the session's own task supervisor rather than inline. `Trinity.Receipts.append/2`
744+
# is a call into the scope's ChainWriter, and blocking the Session on a receipt write is the
745+
# precise shape of the stall this slice was opened to explain.
746+
defp receipt_dropped_approval(%State{id: id, task_sup: sup}, kind, approval, state) do
747+
Task.Supervisor.start_child(sup, fn ->
748+
Trinity.Receipts.append("session:" <> id, %{
749+
kind: "decision",
750+
subject: %{
751+
"session_id" => id,
752+
"approval_id" => approval.id,
753+
"tool" => approval.tool
754+
},
755+
decision: %{
756+
"outcome" => "dropped",
757+
"basis" => "session",
758+
"reason" => "approval #{kind} in #{inspect(state)} with no held call to apply it to"
759+
},
760+
fingerprint: approval.fingerprint,
761+
subject_ref: "approval_dropped:#{id}:#{approval.id}"
762+
})
763+
end)
764+
765+
:ok
766+
end
767+
717768
defp start_tools(%State{turn: turn} = data), do: start_tools(data, turn.pending)
718769

719770
defp start_tools(%State{id: id, session: session, task_sup: sup, turn: turn} = data, calls) do

‎scripts/dev_demo_approval.sh‎

Lines changed: 12 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -13,6 +13,18 @@ export MIX_ENV=test
1313
exec systemd-run --user --scope -p MemoryMax=32G --quiet -- mix run --no-start --no-halt -e '
1414
repo = Application.get_env(:trinity, Trinity.Repo) |> Keyword.delete(:pool) |> Keyword.put(:database, "trinity_screenshots.db")
1515
Application.put_env(:trinity, Trinity.Repo, repo)
16+
# The receipts repo needs the same two changes and was not getting them. Left on
17+
# `pool: Ecto.Adapters.SQL.Sandbox` outside the suite, the sandbox is in auto mode and, as
18+
# config/test.exs says in its own comment, the first long-lived process to query holds the
19+
# connection until it exits. Every `Receipts.append/2` then queues behind it, and since the effect
20+
# membrane receipts the decision *before* it dispatches, the tool task blocks after the approval row
21+
# exists and the card is on screen but before it can answer the Session. The turn never leaves
22+
# tool_wait, the allow the owner issued is never consumed, and the call finally reports a timeout.
23+
# That is a harness defect and it looked exactly like a product one.
24+
# The database also has to move: without this, a screenshot run writes into the receipts file
25+
# belonging to the test suite.
26+
rrepo = Application.get_env(:trinity, Trinity.Repo.Receipts) |> Keyword.delete(:pool) |> Keyword.put(:database, "trinity_screenshots_receipts.db")
27+
Application.put_env(:trinity, Trinity.Repo.Receipts, rrepo)
1628
endpoint = Application.get_env(:trinity, TrinityWeb.Endpoint) |> Keyword.put(:check_origin, false)
1729
Application.put_env(:trinity, TrinityWeb.Endpoint, endpoint)
1830
Application.put_env(:trinity, :permissions, expiry_ms: 600_000, session_grant_ms: 3_600_000)

‎test/trinity_web/live/approval_resume_test.exs‎

Lines changed: 74 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -19,7 +19,7 @@ defmodule TrinityWeb.ApprovalResumeTest do
1919
@moduletag :capture_log
2020

2121
import Phoenix.LiveViewTest
22-
import Trinity.SessionCase, only: [script_deltas: 2, collect: 3]
22+
import Trinity.SessionCase, only: [script_deltas: 2]
2323

2424
alias Trinity.Factory
2525
alias Trinity.LLM.Providers.Fake
@@ -53,19 +53,51 @@ defmodule TrinityWeb.ApprovalResumeTest do
5353
defp send_message(view, text),
5454
do: view |> form("#composer", %{"content" => text}) |> render_submit()
5555

56+
# A deadline, not a synchronisation with the session's internals. `collect/3` cannot be used to
57+
# wait for the end of the turn here: it reads the mailbox, and an `{:state, :idle}` broadcast from
58+
# before the message was sent is already sitting in it, so it returns at once and the assertion
59+
# runs while the turn is still in flight. That mistake made an early version of this file fail for
60+
# a reason that had nothing to do with the defect.
61+
defp wait_until(fun, timeout \\ 8_000) do
62+
deadline = System.monotonic_time(:millisecond) + timeout
63+
do_wait(fun, deadline)
64+
end
65+
66+
defp do_wait(fun, deadline) do
67+
cond do
68+
fun.() ->
69+
true
70+
71+
System.monotonic_time(:millisecond) >= deadline ->
72+
false
73+
74+
true ->
75+
Process.sleep(50)
76+
do_wait(fun, deadline)
77+
end
78+
end
79+
80+
# The turn has settled when it has produced an outcome for the call, whichever outcome that is.
81+
defp settled?(view), do: render(view) =~ "wrote 2 bytes" or render(view) =~ "timed out"
82+
5683
test "AC1: an allow clicked on the requested broadcast, with no wait for approval_wait, consumes the row and runs the call",
5784
%{conn: conn, id: id} do
5885
write_turn()
5986
{:ok, view, _} = live(conn, ~p"/s/#{id}")
6087
send_message(view, "write it")
6188

62-
# The only synchronisation a browser has: the card is on the page.
89+
# The only synchronisation a browser has: the card is on the page. Waiting for it is not the
90+
# same as waiting for `approval_wait`. The test process and the LiveView subscribe to the same
91+
# topic, so the test can win that race and look before the view has re-rendered; a browser
92+
# cannot click a card that is not painted yet either way.
6393
assert_receive {:approval, :requested, %Approval{id: aid}}, 5_000
64-
assert has_element?(view, "#approval-#{aid}")
94+
95+
assert wait_until(fn -> has_element?(view, "#approval-#{aid}") end),
96+
"the approval card never rendered"
6597

6698
view |> element("#approval-#{aid} button", "Allow once") |> render_click()
6799

68-
_ = collect(id, &match?({:state, :idle}, &1), 15_000)
100+
_ = wait_until(fn -> settled?(view) end)
69101

70102
approval = Permissions.get_approval(aid)
71103
assert approval.status == "allowed"
@@ -83,7 +115,7 @@ defmodule TrinityWeb.ApprovalResumeTest do
83115
(html |> String.replace(~r/<[^>]*>/, " ") |> String.replace(~r/\s+/, " "))
84116

85117
refute html =~ "timed out",
86-
"an allow the owner issued was reported as a timeout"
118+
"an allow the owner issued was reported as a timeout"
87119
end
88120

89121
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
93125
send_message(view, "write it")
94126

95127
assert_receive {:approval, :requested, %Approval{id: aid}}, 5_000
128+
assert wait_until(fn -> has_element?(view, "#approval-#{aid}") end)
96129
view |> element("#approval-#{aid} button", "Allow once") |> render_click()
97-
_ = collect(id, &match?({:state, :idle}, &1), 15_000)
130+
_ = wait_until(fn -> settled?(view) end)
98131

99132
rows = Receipts.list("session:" <> id)
100133
decisions = Enum.filter(rows, &(&1.kind == "decision"))
@@ -128,9 +161,43 @@ defmodule TrinityWeb.ApprovalResumeTest do
128161
# what state the Session is in.
129162
assert {:ok, _} = Permissions.decide_request(aid, :once, decided_by: "test")
130163

131-
_ = collect(id, &match?({:state, :idle}, &1), 15_000)
164+
_ = wait_until(fn -> Permissions.get_approval(aid).consumed_at != nil end)
132165

133166
assert Permissions.get_approval(aid).consumed_at,
134167
"a decision made through the gate at the first observable instant was not applied"
135168
end
169+
170+
test "AC6: an approval event with no held call to apply it to is logged and receipted, never dropped in silence",
171+
%{id: id} do
172+
# No turn at all: the session is idle, so a decision broadcast to it has nothing to apply. That
173+
# is the shape that used to return :keep_state_and_data and say nothing.
174+
{:ok, _pid} = Trinity.Sessions.ensure_started(id)
175+
176+
{:ok, approval} =
177+
Permissions.request_approval(id, "write_note", @args, risk: :write, cwd: nil)
178+
179+
log =
180+
ExUnit.CaptureLog.capture_log(fn ->
181+
{:ok, _} = Permissions.decide_request(approval.id, :once, decided_by: "test")
182+
183+
wait_until(fn ->
184+
("session:" <> id)
185+
|> Receipts.list()
186+
|> Enum.any?(&(&1.subject_ref == "approval_dropped:#{id}:#{approval.id}"))
187+
end)
188+
end)
189+
190+
assert log =~ "with no held call to apply it to",
191+
"the drop was not logged. A decision the owner made went nowhere and said nothing."
192+
193+
row =
194+
("session:" <> id)
195+
|> Receipts.list()
196+
|> Enum.find(&(&1.subject_ref == "approval_dropped:#{id}:#{approval.id}"))
197+
198+
assert row, "the drop was not receipted"
199+
assert {:ok, body} = JSON.decode(row.signed_payload)
200+
assert get_in(body, ["decision", "outcome"]) == "dropped"
201+
assert get_in(body, ["decision", "reason"]) =~ "no held call"
202+
end
136203
end

0 commit comments

Comments
 (0)