Skip to content

Commit 6bb2a54

Browse files
committed
fix: slice 040 AC3 measures the watcher, not the machine
The skills AC3 test was red on one machine and green on CI, and the reason was different in each place. Neither was the watcher misbehaving. On CI there is no inotifywait, so the registry takes the fs_poll backend: a poll every second over mtimes at one-second resolution, whose worst case is about two seconds. AC3's bound is two seconds. There was no margin at all, and a loaded shared runner closed it. Measured here, with the backend forced: interval 1000 ms (shipped) 1222 ms, 1223 ms interval 100 ms (suite) 339 ms, 312 ms, 338 ms The interval is now configurable and the suite sets 100 ms. The shipped default is unchanged: a desktop does not need a tenth-of-a-second poll, and the criterion it has to meet is the same either way. The suite also pins the backend. Which one the registry picks otherwise depends on the machine, so the test measured a different mechanism in each place. Worse, on a box already at its inotify instance ceiling (128 here, 119 in use) the native backend obtains no watch and fails silently: the test then fails for a reason that has nothing to do with the product, and the old assertion could only report it as AC3: the edit was in the registry after ms because the poll window and the criterion were the same 2000 ms budget and an exhausted loop was indistinguishable from a late arrival. They are separate now. The loop waits 15 s so a failure says which of the two happened, and the criterion is asserted against the latency actually measured. Verified on the machine where it was failing: three runs, 338, 338 and 312 ms, and a full gate at 951 passed. R26 inside the sandbox, which is the other test Gateways.IdentitiesTest fails on CI with Database busy on an insert, and config/test.exs sets default_transaction_mode: :immediate on both test repos, which reads as though slice 005 had covered the suite. It has not. Ecto.Adapters.SQL.Sandbox.post_checkout/3 begins each test's transaction with handle_begin([mode: :transaction] ++ opts, ...), and Exqlite.Connection resolves the mode as Keyword.get(options, :mode, state.default_transaction_mode), so the explicit option wins over the configuration and :transaction is a plain DEFERRED BEGIN. Every sandboxed test is a DEFERRED transaction, and one that reads before it writes is on R26's unguarded upgrade path, where no busy_timeout applies. Identities.admit/3 reads and then inserts, with no transaction of its own. That is diagnosis, not a fix, and it is recorded as such: the comment in config/test.exs no longer implies the suite is covered, and test/trinity/repo/sandbox_transaction_mode_test.exs asserts both dependency lines so the paragraph fails rather than rots if an upgrade moves them. The identities test is not changed, because the concurrent writer that completes the mechanism is still unidentified and the failure does not reproduce here. Signed-off-by: Ayla Croft <aylacroft@proton.me>
1 parent dc8d459 commit 6bb2a54

4 files changed

Lines changed: 135 additions & 11 deletions

File tree

‎config/test.exs‎

Lines changed: 23 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -174,6 +174,17 @@ else
174174
# a write while another connection holds the write lock, because waiting there could deadlock.
175175
# No timeout affects that path. The raise is kept because it does help ordinary lock waiting,
176176
# but it is not the fix for what is recorded as R26 in docs/06-risk-register.md.
177+
#
178+
# And the line below does not reach a sandboxed test at all, which is worth knowing before
179+
# trusting it. `Ecto.Adapters.SQL.Sandbox.post_checkout/3` begins each test's transaction with
180+
# `handle_begin([mode: :transaction] ++ opts, ...)`, and `Exqlite.Connection` resolves the mode
181+
# as `Keyword.get(options, :mode, state.default_transaction_mode)`, so the explicit option wins
182+
# over this setting and `:transaction` is a plain DEFERRED `BEGIN`. Every sandboxed test is
183+
# therefore a DEFERRED transaction, and one that reads before it writes is on R26's unguarded
184+
# upgrade path with no timeout able to help. `default_transaction_mode` below still governs the
185+
# transactions the application itself opens, which is why it stays.
186+
# `test/trinity/repo/sandbox_transaction_mode_test.exs` asserts both dependency lines so this
187+
# paragraph fails rather than rots.
177188
config :trinity, Trinity.Repo,
178189
database: Path.expand("../trinity_test.db", __DIR__),
179190
pool: Ecto.Adapters.SQL.Sandbox,
@@ -260,6 +271,18 @@ config :trinity, :skills,
260271
# user_dir at a temporary directory first.
261272
pending_dir: Path.join(System.tmp_dir!(), "trinity-test-pending-skills"),
262273
watch: true,
274+
# The shipped poll is every second (lib/trinity/skills/registry.ex) and it compares mtimes at
275+
# one-second resolution, so its worst case is about two seconds, which is the whole of slice
276+
# 040 AC3's bound. With no margin, the test asserting that bound failed intermittently on a
277+
# loaded runner while the watcher was behaving exactly as designed. A shorter interval here
278+
# leaves the mechanism under test, the fs_poll backend over mtimes, and takes the runner's
279+
# scheduler out of the measurement. The shipped default is unchanged.
280+
# One backend everywhere, so slice 040 AC3 measures the same mechanism on every machine. The
281+
# gate's runners have no `inotifywait` and already take this path; a developer box takes the
282+
# native one, and takes it badly when the machine is at its inotify instance ceiling, where the
283+
# watch is never established and no edit ever arrives.
284+
poll: true,
285+
poll_interval_ms: 100,
263286
index_tokens: 338
264287

265288
# Slice 060: no MCP client boots from rows in the suite (each test starts the clients it

‎lib/trinity/skills/registry.ex‎

Lines changed: 21 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -304,13 +304,30 @@ defmodule Trinity.Skills.Registry do
304304
# has no native backend for, poll once a second (AC3's 2 s still holds; the poll compares
305305
# mtimes at one-second resolution). `TRINITY_SKILLS_POLL=1` forces the poll, so the
306306
# fallback can be exercised on a machine that has inotifywait.
307+
#
308+
# The interval is configurable because AC3's bound and this default leave no margin. A poll
309+
# every second over mtimes at one-second resolution has a worst case of about two seconds all
310+
# by itself, which is the whole of the criterion, so on a loaded shared runner the test that
311+
# asserts it failed intermittently while the product was behaving exactly as designed. The
312+
# default is unchanged and is what ships; the suite sets a shorter one so that what it measures
313+
# is the watcher noticing rather than the runner's scheduler.
307314
defp backend do
308-
poll = [backend: :fs_poll, interval: 1_000]
315+
poll = [backend: :fs_poll, interval: poll_interval_ms()]
309316

310317
cond do
311318
System.get_env("TRINITY_SKILLS_POLL") == "1" ->
312319
poll
313320

321+
# Same switch, from configuration rather than the environment, so the suite can pin one
322+
# backend. Which backend the registry picks otherwise depends on the machine: a developer
323+
# box has `inotifywait` and the gate's runners do not, so AC3's test measured a different
324+
# mechanism in each place, and on a box already at its inotify **instance** ceiling
325+
# (`/proc/sys/fs/inotify/max_user_instances`, 128 here with 119 in use) the native backend
326+
# obtains no watch and fails silently, which the test could only report as an edit that
327+
# never arrived.
328+
Keyword.get(Application.get_env(:trinity, :skills, []), :poll, false) ->
329+
poll
330+
314331
match?({:unix, :linux}, :os.type()) ->
315332
if System.find_executable("inotifywait"), do: [], else: poll
316333

@@ -327,6 +344,9 @@ defmodule Trinity.Skills.Registry do
327344

328345
defp watch?, do: Application.get_env(:trinity, :skills, []) |> Keyword.get(:watch, true)
329346

347+
defp poll_interval_ms,
348+
do: Application.get_env(:trinity, :skills, []) |> Keyword.get(:poll_interval_ms, 1_000)
349+
330350
## Helpers
331351

332352
defp ensure_project(nil), do: :ok
Lines changed: 68 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,68 @@
1+
# SPDX-FileCopyrightText: Sudo Apt Holdings LLC
2+
# SPDX-License-Identifier: Apache-2.0
3+
defmodule Trinity.Repo.SandboxTransactionModeTest do
4+
@moduledoc """
5+
R26's residual half: `default_transaction_mode: :immediate` does **not** reach a sandboxed test.
6+
7+
Slice 005 reproduced R26 and demonstrated the fix, deliberately outside the sandbox, because
8+
"the sandbox wraps each test in one connection's transaction and cannot express two contending
9+
writers" (`test/trinity/repo/sqlite_transaction_mode_test.exs`). `config/test.exs` then sets
10+
`default_transaction_mode: :immediate` on both test repos, which reads as though the suite were
11+
covered too.
12+
13+
It is not, and this file is here so that sentence cannot quietly stay wrong.
14+
15+
`Ecto.Adapters.SQL.Sandbox.post_checkout/3` begins the per-test transaction with
16+
`conn_mod.handle_begin([mode: :transaction] ++ opts, conn_state)`. `Exqlite.Connection` resolves
17+
the mode as `Keyword.get(options, :mode, state.default_transaction_mode)`, so an explicit
18+
`:mode` in the options **wins over the configured default**, and `:transaction` maps to a plain
19+
`BEGIN TRANSACTION`, which is DEFERRED.
20+
21+
So every sandboxed test runs in a DEFERRED transaction. A test whose first statements read and
22+
then write is doing exactly what R26 describes: the read makes the transaction a reader, the
23+
write tries to upgrade, and if another connection has written in between SQLite answers
24+
`SQLITE_BUSY` **without consulting the busy handler**, so neither the 30 s `busy_timeout` nor
25+
the `:immediate` setting can help. `Trinity.Gateways.IdentitiesTest` is such a test and has
26+
failed this way on CI (gate run 36742943477, while the other run on the same commit passed).
27+
28+
This is a fact about a dependency, so it is asserted against the dependency's source rather than
29+
described. If an upgrade changes either line, this fails and the reasoning above gets revisited
30+
instead of rotting.
31+
"""
32+
use ExUnit.Case, async: true
33+
34+
@sandbox "deps/ecto_sql/lib/ecto/adapters/sql/sandbox.ex"
35+
@exqlite "deps/exqlite/lib/exqlite/connection.ex"
36+
37+
test "the sandbox begins its per-test transaction with an explicit mode, and that mode is DEFERRED" do
38+
sandbox = File.read!(@sandbox)
39+
40+
assert sandbox =~ "handle_begin([mode: :transaction] ++ opts",
41+
"""
42+
#{@sandbox} no longer begins the sandbox transaction with `mode: :transaction`.
43+
44+
That is the line this project's understanding of R26-inside-the-suite rests on. Re-read
45+
it: if the sandbox now begins IMMEDIATE, or takes the mode from the repo's
46+
configuration, then `default_transaction_mode: :immediate` in config/test.exs finally
47+
does reach sandboxed tests, and the moduledoc here and the comment in config/test.exs
48+
should say so.
49+
"""
50+
end
51+
52+
test "an explicit :mode option wins over the configured default_transaction_mode" do
53+
exqlite = File.read!(@exqlite)
54+
55+
assert exqlite =~ "Keyword.get(options, :mode, state.default_transaction_mode)",
56+
"""
57+
#{@exqlite} no longer resolves the transaction mode by preferring an explicit `:mode`
58+
option over the configured default. If the precedence has reversed, the sandbox's
59+
`mode: :transaction` no longer overrides `default_transaction_mode: :immediate`.
60+
"""
61+
62+
# And `:transaction` is the plain BEGIN, not the IMMEDIATE one: the two are separate clauses
63+
# and only one of them takes the write lock up front.
64+
assert exqlite =~ ~s|:transaction when transaction_status == :idle ->|
65+
assert exqlite =~ ~s|handle_transaction(:begin, "BEGIN TRANSACTION", state)|
66+
assert exqlite =~ ~s|handle_transaction(:begin, "BEGIN IMMEDIATE TRANSACTION", state)|
67+
end
68+
end

‎test/trinity/skills/registry_test.exs‎

Lines changed: 23 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -136,15 +136,28 @@ defmodule Trinity.Skills.RegistryTest do
136136

137137
started = System.monotonic_time(:millisecond)
138138

139-
assert Enum.find_value(1..100, fn _ ->
140-
Process.sleep(20)
141-
142-
if Skills.get("watched").description == "After.",
143-
do: System.monotonic_time(:millisecond) - started
144-
end)
145-
|> then(fn ms ->
146-
IO.puts("\nAC3: the edit was in the registry after #{ms} ms")
147-
ms
148-
end) <= 2_000
139+
# The poll window and the criterion used to be the same 2 000 ms: `1..100` with a 20 ms sleep
140+
# is a 2 s budget, asserted against a 2 s bound, so there was no way to tell "it never
141+
# arrived" from "it arrived late", and a slow scheduler turned one into the other. They are
142+
# separate now. The loop waits far longer than the criterion so that a failure says which of
143+
# the two happened, and the criterion is then asserted against the time actually measured.
144+
latency_ms =
145+
Enum.find_value(1..600, fn _ ->
146+
Process.sleep(25)
147+
148+
if Skills.get("watched").description == "After.",
149+
do: System.monotonic_time(:millisecond) - started
150+
end)
151+
152+
assert latency_ms,
153+
"the edit never reached the registry at all, in 15 s of waiting, and no rescan was " <>
154+
"called. That is not AC3's 2 s bound being missed; it is the watcher not working."
155+
156+
IO.puts("\nAC3: the edit was in the registry after #{latency_ms} ms")
157+
158+
assert latency_ms <= 2_000,
159+
"AC3 gives 2 000 ms and the edit took #{latency_ms} ms. The suite runs the fs_poll " <>
160+
"backend at the interval config/test.exs sets, so this is the watcher being slow " <>
161+
"rather than the poll interval leaving no margin."
149162
end
150163
end

0 commit comments

Comments
 (0)