Skip to content

Commit 685abe8

Browse files
committed
fix(s090): the trace test waits for the turn, not for the model call
The FIPS leg failed on slice 014's branch while its sibling run of the same commit passed. That is R26's signature, and R26's own counter-example entry says the signature is not the diagnosis, so the stack trace was read first. It was not R26. Trinity.TelemetryTest, two turns are two traces, sent its second user message as soon as it received the llm call stop event from the first. That event fires when the model call ends, not when the turn does: the session is still thinking while it writes the result, so the second message returned {:error, {:busy, :thinking}}. It has been racy since slice 090 and passed on the ordinary gate for days because that leg is faster where it matters. The FIPS leg is about half again as slow, which is enough to lose the race reliably. The test now waits for idle, which is what it meant: two turns is a claim about two turns, and the end of a model call is not the end of a turn. A poll against a deadline rather than a sleep, so it flunks naming the state it was stuck in rather than trading one race for a slower one. Signed-off-by: Ayla Croft <aylacroft@proton.me>
1 parent cdf33a5 commit 685abe8

1 file changed

Lines changed: 26 additions & 0 deletions

File tree

‎test/trinity/telemetry/telemetry_test.exs‎

Lines changed: 26 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -170,12 +170,38 @@ defmodule Trinity.TelemetryTest do
170170
{:ok, _} = Sessions.send_user_message(session.id, "first")
171171
assert_receive {^ref, [:trinity, :llm, :call, :stop], _, first}, 5_000
172172

173+
# The stop event fires when the model call ends, and the session is still `:thinking` while it
174+
# writes the result. Sending the next message on that event is a race: it passed on the
175+
# ordinary gate for weeks and failed on the FIPS leg, which is slower, with
176+
# `{:error, {:busy, :thinking}}`. Waiting for idle is what the test meant all along.
177+
await_idle(session.id)
178+
173179
{:ok, _} = Sessions.send_user_message(session.id, "second")
174180
assert_receive {^ref, [:trinity, :llm, :call, :stop], _, second}, 5_000
175181

176182
refute first.trace_id == second.trace_id
177183
end
178184

185+
defp await_idle(id, timeout \\ 5_000) do
186+
deadline = System.monotonic_time(:millisecond) + timeout
187+
await_idle(id, deadline, :first)
188+
end
189+
190+
defp await_idle(id, deadline, _) do
191+
case Sessions.state(id) do
192+
%{state: :idle} ->
193+
:ok
194+
195+
other ->
196+
if System.monotonic_time(:millisecond) > deadline do
197+
flunk("session #{id} was #{inspect(other)} and never became idle")
198+
else
199+
Process.sleep(10)
200+
await_idle(id, deadline, :again)
201+
end
202+
end
203+
end
204+
179205
test "outside a trace an event carries no trace id, rather than an invented one" do
180206
ref = make_ref()
181207
me = self()

0 commit comments

Comments
 (0)