Skip to content

CI flakes: remove each timing cause - #268

Merged
deepfates merged 4 commits into
mainfrom
claude/ci-flakes
Sep 29, 2026
Merged

deepfates merged 4 commits into
mainfrom
claude/ci-flakes

Conversation

@deepfates

@deepfates deepfates commented Sep 29, 2026 •

Copy link
Copy Markdown
Owner

Part of #267

Every failed CI run since 2026-09-27 was read with gh run view <id> --log-failed (no run in that window had a re-run attempt except 36361631807, whose two attempts failed the same way). Five test failures were intermittent. Each had a timing cause, listed below with its fix. Everything else that failed did so on every run of that commit, and is listed after the table.

Intermittent failures

Test Run (job) Error Cause Fix
req_llm_stream_end_test.exs:191 36501812974 (stranger.check) Task.await exited after 5000 ms ReqLLM's model catalog (LLMDB) loads lazily on first use, under a :global.trans lock. A process that finds the lock taken sleeps a random backoff that doubles up to 8 s before it tries again. The async tests at the start of the suite all make their first lookup at the same moment. Both failures came within 6 s of Running ExUnit. Measured locally: a 1.4 s load, and waits of up to 4.6 s among 16 simultaneous first lookups on an idle machine. With the catalog already loaded, each lookup took 9 ms. test_helper.exs loads the catalog (LLMDB.load()) before any test runs. The slowest stream-end test dropped from 1509 ms to 35 ms.
req_llm_stream_end_test.exs:217 36514520298 (check) Task.await exited after 5000 ms Same as above Same as above
timed_out_connection_test.exs:32 36488635687 (check) second call {:error, %Imp.LMError{message: "API request failed: timeout"}} The second call had a 200 ms receive timeout, too short on a loaded runner. #253 raised it to 5 s, which is still a timer, and the first request was held by a 2 s timer. The first request is held until the test process exits, so the first call times out however slow the machine is. The second call keeps ReqLLM's own receive timeout. No timer in the test decides the result.
parity_sidecar_test.exs:79 36353581023 (stranger.check) output.text was "", not "tree ready" A 150 ms timeout, counted from the start, fired before Python had started up, spawned its child and printed. The two other tree tests (:97, :112) have the same race. These three tests run the tree with no timer, wait for its process ids, and then send the port owner :command_timeout, the message its timer sends. "tree ready" is printed before the pid file is written, so it is always in the pipe by then. A new test checks the real timer on a command that sleeps. await_pids has no attempt limit.
datasets_contract_test.exs:203 36423475872 (stranger.check) no {:DOWN, …, :killed} within 1000 ms; walk = #PID<0.53.0> The helper took the first process the caller monitored. That was the file server, which the caller monitors while it reads the file. #245 had already fixed this on main before this PR. What was left: a 2.5 s budget to find the walk, which starts only after the caller has parsed the whole file; a 1 s window for the DOWN; and a race with the walk finishing on its own. The test waits for the walk for as long as the caller is alive. It suspends the walk, so the walk cannot finish before the kill, and asserts that the walk's exit reason is :killed.

Failures that were not intermittent

  • property_invariants_test.exs:46 (36432281651): a real defect that the property test found by chance, a signature field named nil. Fixed in Signature fields named nil, true or false keep their names #248.
  • hover_papillon_calibration_pilot_test.exs (5 tests, differential.check: 36350561245, 36352551929, 36359159692, 36361631807 both attempts): Imp candidate tracked tree is dirty. The branch's example mix.lock files lacked nimble_csv, so deps.get rewrote them. Fixed on that branch in cc42aa9. This is also where the assert_raise came from (:654).
  • deployment_reference_test.exs:453 (36430185896, 36434502372, 36437298490): the version assertion failed on the release branch until the version was set.
  • docs.check (36351718943, 36353066316, 36366312511, 36368989849, 36381928160, 36384556732, 36494101494, 36495421822, 36496822989), dialyzer.check (36490477815, 36492467243, 36515908598), quality.check (36420473732, cowlib advisory): each failed deterministically on its commit.
  • The issue also lists reasoning_continuity, silent_failure_regressions P03, local_mlx_campaign_test.exs:26, avatar_persistence_test.exs:24 and req_llm_batch_test.exs:273/:780. None of these failed in any CI run from 2026-09-24 on. They show up in the logs only as stack frames printed under ReqLLM's Using unverified model warning (IO.warn), not as failures.

Evidence

The tests still fail when the behaviour they check is broken. Each code change below was made briefly, the test was run, and the code was restored:

  • Finch closing a timed-out connection was reverted (deps/finch/lib/finch/http1/conn.ex:260, returning the connection unclosed, as 0.23 did). timed_out_connection_test then fails at :76 after ReqLLM's 30 s receive timeout.
  • Imp.Datasets.walk_csv's guard was changed to not kill the walk. The CSV walk test then fails: it times out waiting for the DOWN.
  • The :command_timeout branch in Imp.ExternalCommand.Lifecycle was changed to skip terminate_group. All three tree tests then fail. When it returned an empty capture instead, the two "tree ready" assertions fail.
  • Imp.Core.response was changed to drop the reported cost. req_llm_stream_end_test :191 and :217 then fail.

Local repeats (MIX_ENV=test ELIXIR_ERL_OPTIONS="+S 4" mix test <file> --repeat-until-failure 50, one at a time):

test/req_llm_stream_end_test.exs      51 of 51 runs: 10 tests, 0 failures
test/timed_out_connection_test.exs    51 of 51 runs: 1 test, 0 failures
test/datasets_contract_test.exs       51 of 51 runs: 22 tests, 0 failures
test/parity_sidecar_test.exs          51 of 51 runs: 11 tests, 0 failures

(51 = the first run plus 50 repeats.)

CI: three consecutive runs of the PR are linked in a comment below.

LLMDB loads ReqLLM's model catalog on first use under a :global.trans
lock, and a process that finds the lock taken sleeps a random backoff
that doubles up to 8 s. Async tests making their first model lookup
together at the start of the suite waited several times the 1.4 s load,
and on a loaded runner past a 5 s Task.await in ReqLLMStreamEndTest.
The first request is held until the test ends rather than for 2 s, so
the first call times out however slow the machine is, and the second
call keeps ReqLLM's own receive timeout instead of one the test picks.
A second request on the stuck connection is still never answered.
The walk is found for as long as the caller is alive, since the caller
parses the whole file before it starts it. The walk is then suspended,
so it cannot finish and exit on its own before the caller is killed,
and the test asserts that it ended killed.
A 150 ms timeout fired on a loaded runner before Python had started
the tree, so the output held no "tree ready". The three tree tests run
with no timer, wait for the tree, and send the port owner the message
its timer sends; a separate test checks that the timeout option ends a
command. Waiting for the process ids has no attempt limit.
@deepfates

Copy link
Copy Markdown
Owner Author

CI on 31eda09, run 36621743611, re-run with gh run rerun:

Attempt Result
1 success, all jobs
2 failure: check, test/avatar_test.exs:283 (see below)
3 success, all jobs
4 success, all jobs
5 success, all jobs

Attempts 3, 4 and 5 are three consecutive green runs.

An intermittent failure this PR does not explain. In attempt 2, "a tool that traps exits still ends when its caller is killed" (AvatarTest) failed. The test received {:tool_started, tool_pid}, then monitored tool_pid, and got {:DOWN, …, :noproc}: the tool process was already dead before the test killed the caller. The one place in the code that kills a tool task is Imp.Predict.Avatar.watch_caller/1, and it does so only when the caller goes down. So on this reading, the spawned caller ended before the test killed it. I have not found what would end it. The failure happened 36 s into the async phase, so the application-stopping tests, which are all async: false, were not running. None of the async tests change Imp.Settings or kill processes of Imp.UnlinkedTaskSupervisor. The test passed 200 times in a row locally (--repeat-until-failure 200). This PR leaves that test alone. It needs its own look.

@deepfates

Copy link
Copy Markdown
Owner Author

Review (fresh-eyes reviewer, checked by me), at 31eda09. I read the failing runs' logs (36501812974, 36514520298, 36488635687, 36353581023, 36423475872), and the table's causes match them.

  • The preload. The two stream_end failures landed about 5.7 s after Running ExUnit, which fits the :global.trans backoff in LLMDB.Catalog.with_load_lock. LLMDB.load() goes through the same __lazy_load__([]) as the lazy path and reads the packaged snapshot, so preloading uses no network and hides nothing a test checks.

  • Falsification, reproduced:

    • Finch not closing the timed-out connection: timed_out_connection_test:76 fails at 30.2 s.
    • The datasets guard not killing the walk: it fails at ExUnit's 60 s limit.
    • :command_timeout skipping terminate_group: the three tree tests fail.
    • start_timer not scheduling: only the new timeout test fails, so the real timer is still covered.

    None of the rewritten tests can hang past ExUnit's limit.

Not blocking:

  • req_llm_stream_end_test still uses Task.await's default 5000 ms.
  • In the CSV walk test, the walk could in principle finish between wait_for_walk and suspend_process. The test would fail loudly, not pass.

Changed to "Part of #267". avatar_test.exs:283 failed in attempt 2 of this PR's own run and has no cause yet, so #267's first criterion isn't met and #267 stays open for it. Ruled out so far: the 30 s tool timeout, the tool's link, and the shared task supervisors (all users are async: false). Next step: have the test also monitor the caller, to show whether the watcher killed the tool.

@deepfates
deepfates merged commit cf9e45f into main Sep 29, 2026
49 of 50 checks passed
@deepfates
deepfates deleted the claude/ci-flakes branch September 29, 2026 21:02
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant