Repository navigation
cmux-next swift test: a truncated run can no longer read as a pass - #25391
teamleaderleo wants to merge 16 commits into
Conversation
|
cmux status (one comment, edited in place; each line is updated by the job that owns it) Review App of this head (app.zip, kept 1 day)
red: cmux-next checks (god files, concurrency, crash safety, l10n); no finished base run on 3660113 to compare; do not merge until green; see lane-rules |
|
Owned by an agent session · session |
|
Bead |
This comment has been minimized.
This comment has been minimized.
The test process ends while thousands of tests are still running: a stray CFRunLoopStop on the main run loop (AppKit calls it from -[NSEvent _postAtStart:] to wake an event wait) lands on swift-testing's outermost CFRunLoopRun, so swift_task_asyncMainDrainQueue returns and the runtime calls exit(0). The job's stack from #23680: exit + 44 <- swift_task_asyncMainDrainQueue + 92 <- CmuxNextPackageTests main + 132 The wrapper already failed a run with no "Test run with" summary line. But the summary counts the tests that REPORTED, so a run that ends mid-flight can still print one -- and when every test that did report was green, swift test exits 0 and the whole thing reads as a pass. #23680's own log printed no summary, so the earlier check caught that one; a truncation that gets its summary line out is the shape nothing catches, and that is how a job can read green with thousands of tests missing. Now the report also fails when any test the log shows starting never finished, or when the summaries count fewer tests in total than started, and names the unfinished tests in the ::error line and the step summary. Two things hold on a whole run and fail on a truncated one: every test the log shows starting also finishes, and the summaries count at least as many tests as started. Not equality -- a skipped test prints no "started." line, so a legitimate summary runs ahead of the starts. The counts are summed across summary lines, because one log can hold a summary per test target while the starts are counted across all of them. Replayed through the real job logs: the healthy 399-test CmuxNextAppTests run -> report exits 0 the #23680 truncation as it was -> exits 3, "ended early" the same counts in the shape that gets a summary line, with the reds stripped -> exits 3, "the summaries count 2192 tests in total but 4736 started and 2890 of those never finished" The third is the hole: before this it exited 0. Regression cases go in scripts/cmux-next/tests/swift-test-summary.test.sh, which the checks job already runs; no new CI step. They cover the truncation with a summary, a summary that undercounts the log with every started test finished, two whole runs in one log (which must stay green), and a truncation inside the second of two targets. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Agent-Session: https://cmux.com/deeplink/agent?id=aid-9cc710fd4775017aab15
01eccf0 to
b5d5cd8
Compare
|
|
Two ways the new check could have reddened a whole run, both found in review:
A ✘ finish is not only a failure. A test that passes with a known issue reports
"✘ Test f() passed after 0.001 seconds with 1 known issue." and HAS finished;
the finish predicate accepted ✘ only with "failed after", so that test counted
as started-and-never-finished and failed the run. Both verbs are accepted now.
This was a hole in the older no-summary check too.
A test that writes to stderr without a trailing newline runs its own output into
the next reporter line ("progress: ✔ Test a() passed after ..."). Every
predicate was anchored at the start of the line, so such a finish was ignored
while its start still counted -- and catching a start while missing its finish
is exactly what makes a whole run look truncated. Starts, finishes, reds and the
summary are now all read from one normalized form that finds the marker anywhere
on the line; a line with no marker is left alone, so nothing matches less than
before. The summary's count is taken out of the text instead of as a field, so a
shifted line still reads right.
The markers are spelled as whole alternatives, (◇|✔|✘|➜), never as the bracket
expression [◇✔✘➜]: an awk in a byte locale reads that as the set of BYTES those
four characters are made of, and each of them ends in a byte that is also in the
set, so the match landed mid-character and every red went unreported. Caught by
the existing red fixture.
Also written down, because the review was right that the earlier claim was too
strong: names are counted across the whole log, so a truncation that only loses
tests whose names another target already ran and summarized still reads as a
pass. That needs per-summary-block bookkeeping, which this is not.
The reviewer's three repro fixtures now exit 0 (known-issue pass, run-on output,
two whole runs in one log), the real job logs are unchanged (healthy 0 with its
9 reds still named, both truncations 3), and two regression cases were added for
the two shapes above.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Agent-Session: https://cmux.com/deeplink/agent?id=aid-9cc710fd4775017aab15
|
|
|
|
This comment has been minimized.
This comment has been minimized.
Round 2 of review asked for the markers to be matched anywhere on the line, so
that a test writing without a trailing newline ("progress: ✔ Test a() passed
after ...") does not swallow its own finish. Round 3 of review then pointed out
what that buys: a test's own output becomes a reporter event, so a test printing
"debug: ✔ Test hung() passed after ..." can mark ITSELF finished and a truncated
run passes. Both are real, and they point opposite ways on one line.
Measured rather than guessed: across three real job logs -- a healthy
CmuxNextAppTests run, the #23680 truncation, and the live #25364 one from this
morning -- of about 12000 lines carrying a reporter marker, every single one was
anchored at the start of the line. So the run-on shape is hypothetical here,
while the false pass defeats the only thing this check exists to do.
Anchored it is, and the reasoning is in the code so the next reader does not
re-litigate it. The failure mode that remains is the better one: a swallowed
finish fails the run and names the exact test, rather than passing in silence.
Two regression cases, one per side: a test that prints its own finish line must
still be reported as never finished, and a finish line the output ran into must
fail naming that test. The known-issue finish (✘ ... passed after) and the summed
summary counts from the previous commits are unchanged, and the summary count is
still taken out of the text rather than as field $5.
Every fixture re-replayed: healthy 0 with its 9 reds still named, all four
truncations 3, the known-issue and two-whole-runs fixtures 0.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Agent-Session: https://cmux.com/deeplink/agent?id=aid-9cc710fd4775017aab15
My own gate failed a green run. The daemon-tests job of this PR reported the summaries count 386 tests in total but 386 started and 1 of those never finished; swift test exited 1 ... aRunCutOffMidwayFinishesWithoutDuplicates() because that test's finish line is ━ Test aRunCutOffMidwayFinishesWithoutDuplicates() passed after 8.359 seconds with 2 known issues. A known issue carries its own marker. I had accepted "✘ Test f() passed after" as a finish and assumed that covered the known-issue case; it covers only the shape where a test ALSO records a plain issue. Both markers are accepted now, with both verbs, as separate anchored patterns -- never a bracket set, which awk reads as the set of bytes those characters are made of. Replayed both real job logs of this PR's run through the fixed report(): - daemon tests (job 121471396631): the "never finished" error is gone; the one genuine red, aUserRenamedHomeMarkerIsNotUnnamed(), still reports. - swift test (job 121471396706): the truncation still fires, through the new branch, "the summaries count 420 tests in total but 6534 started and 2304 of those never finished". Regression cases use the real line copied from that log, plus the known-issue FAILURE shape, so the gate never adds a second error to a run already red. bash scripts/cmux-next/tests/swift-test-summary.test.sh -> ok swift-test-summary Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Agent-Session: https://cmux.com/deeplink/agent?id=aid-9cc710fd4775017aab15
This is the other half of Leo's ask. The gate in the earlier commits makes a truncated run red; this stops it truncating. The process does not crash. swift-testing's async main runs CFRunLoopRun on the main loop, AppKit calls CFRunLoopStop(CFRunLoopGetMain()) to wake an event wait, the stop lands on that outermost activation, swift_task_asyncMainDrainQueue returns and main falls through to exit(0). The atexit tracer can never name the caller: by the time it runs, the stopper's frames are gone. Attribution, from the swift test job 121471396706 of this PR. The suite is .serialized with exactly two tests: 09:02:16.2173 ✔ Test aClickLeavesTheRunLoopItRanInRunning() passed 09:02:16.2174 ◇ Test openingAConversationFromTheListPutsTheKeyboardInItsMessageBox() started. ... 28 lines ... 09:02:16.2193 cmux-next test process: exit() called The first test wraps its one click in inANestedPass and passes. The second calls click seven times bare, starts, and the process ends 2303 tests short. Nothing else in flight at that instant posts an NSEvent: the other tests that had just started are a socket-router call, two DaemonStore data cases and colour maths. Every raw NSApp.postEvent in Sources was checked too and none is reachable from any test (DebugMouse and DebugKey+Sequence are DEBUG-only and reached only from AppControl's control socket, which no test builds; WindowHintController's is behind a live hints.show session, which no test starts; AddressBarView+Debug's is behind debug.omnibar, likewise). Isolating only the postEvent was never enough. click also runs document.mouseDown, which drives the list's own press-and-drag tracking, and then an NSApp.nextEvent drain loop in .default mode -- "postEvent, then nextEvent, in any run loop mode" is verbatim the shape this repository already blames for ending the process (KeyDownDispatchTests.swift:18, ActionRunTimingTests.swift:324, which both avoid it by poking currentEvent). So the pass moves into click and key rather than staying each caller's job, which removes the whole class of "someone called click bare". The two passes take different run loop modes, because aClickLeavesTheRunLoopItRanInRunning nests one around a click that now nests its own, and a block left in one mode must never be run by the other's activation. That test keeps its assertion and gains its meaning: the pass ends .finished because the click absorbed its own stop, not because this caller remembered to wrap it. Deliberately not added: a guardrail refusing new raw NSApp.postEvent / NSApp.nextEvent / CFRunLoopStop lines. CLAUDE.md says not to add CI gates, and the gate Leo asked for already catches a truncation and names the test that never finished, which is the attribution this took three days to get by hand. Not run here: the suite. Agents never compile or test on a Mac locally; this goes to the fleet, and the PR run is the evidence that every test reports. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Agent-Session: https://cmux.com/deeplink/agent?id=aid-9cc710fd4775017aab15
Bugbot needs on-demand usage enabledBugbot uses usage-based billing for this team and requires on-demand usage to be enabled. A team admin can enable on-demand usage in the Cursor dashboard. |
The review found two places where the gate read a terminal line as an open test. Both came from the same shape: `open_tests()` (the hang watchdog) and `report()` each carried their own copy of the predicate, so a line shape added to one was missing from the other. - `open_tests()` matched only `✔`/`✘`, so a test that finished with `━ Test f() passed after 8.3 seconds with 2 known issues.` or `➜ Test f() was cancelled after 1.2 seconds.` stayed open. The watchdog would then sample and kill a healthy run. Replayed: three such fixtures, all three reported open before this change. - `name_of()` did not strip `was cancelled after …`, so a cancelled test's start and finish hashed to different names. Replayed: a three-line cancelled fixture printed "the summaries count 1 tests in total but 1 started and 1 of those never finished" and failed a run that lost nothing. `is_finish()` now lives in `names_awk` beside `name_of()`, the one definition both readers call. Each arm is proven load-bearing by reverting it alone: without the `━` arm a known-issue pass exits 1; without the cancelled strip the cancelled fixture exits 1. Two regression cases cover the shapes rather than the symptoms: `stuckshapes` puts every terminal shape beside one genuinely stuck test and asserts the gate names only the stuck one, and `cancelled` covers the swift-testing 6.3 `Test.cancel()` line. Reviewer's Swift-6 finding, checked: `Package.swift:140` sets main-actor default isolation for this test target, so the `@escaping () -> Void` closure the nested pass takes is already main-actor isolated at both call sites. bash scripts/cmux-next/tests/swift-test-summary.test.sh → ok swift-test-summary Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Agent-Session: https://cmux.com/deeplink/agent?id=aid-9cc710fd4775017aab15
Bugbot needs on-demand usage enabledBugbot uses usage-based billing for this team and requires on-demand usage to be enabled. A team admin can enable on-demand usage in the Cursor dashboard. |
The review of bd30611 found the last way this gate could still read a truncated run as a pass, and it was reachable by a shape the job itself produces. One log can hold the same test name twice -- the isolated-suite step runs each suite in its own process and appends to one log -- and the gate kept a SET of started and finished names. So the first run of a name finishing covered a second run of it starting, and a truncation that only lost tests an earlier block had already run and summarized left every count intact. Both readers now count occurrences per name and call a name open while its starts outnumber its finishes, and start_count counts runs so it stays comparable with the summed summary totals. Counted per name rather than as two totals on purpose: a parameterized test prints a finish for each case, whose start line the gate deliberately skips, so finishes outnumber starts across the whole log. Per name those case finishes land under a name that never started, where they cannot cover a real loss. The `parameterized` case asserts exactly that: a test lost after a parameterized test's cases is still named, and paramTest itself is not. Red proof, reverting both halves to the pre-fix semantics (unique-name start_count and set-based finishes) on the reviewer's fixture: before -> exit 0, no error line after -> exit 1, "the summaries count 2 tests in total but 3 started and 1 of those never finished ...: duplicate()" Three regression cases, which also pin the two ways this could go wrong: duplicatenames (the loss is caught and names only duplicate(), not other()), duplicategreen (the same name run twice, both finishing, is whole) and parameterized (case finishes cannot cover a loss). The stale comment that recorded this as a known gap is gone with the gap. bash scripts/cmux-next/tests/swift-test-summary.test.sh → ok swift-test-summary Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Agent-Session: https://cmux.com/deeplink/agent?id=aid-9cc710fd4775017aab15
Bugbot needs on-demand usage enabledBugbot uses usage-based billing for this team and requires on-demand usage to be enabled. A team admin can enable on-demand usage in the Cursor dashboard. |
Taking the review of 3cd20f9, whose BLOCK and P2 turned out to be the same root cause: counting finishes per name banked finishes that closed no run. BLOCK, reproduced before fixing: the watchdog remembers when it first saw each open-list KEY, and the key was the bare test name. Once a name had a second run, it never left the open list across the boundary, so run 2 inherited the timestamp of the poll that first saw run 1 -- run 1 seen at t=10 and finishing at t=180, run 2 starting at t=181, and at t=310 the watchdog reports 300 s and samples a run that is 129 s old. A healthy run killed, which is the failure this gate must never cause. Confirmed with the real wrapper: both runs produced the single key `[duplicate()]`; they now produce `[duplicate() (run 2)]` alone. P2, also reproduced: a test skipped before it ran prints `➜ ... skipped.` with no start line, and a parameterized test prints a finish per case whose start line the rule deliberately skips. Banked per name, either could close a later, real run of the same name. On the fixture in the review the skipped duplicate() closed the unfinished one and the run reported nothing: exit 0. So a finish now closes the earliest run of that name still open, and a finish with no open run is ignored rather than banked. `first_open_run`, `open_runs` and `run_key` join `name_of` and `is_finish` in the shared awk, and the start and finish bookkeeping moves there too as `count_awk`: the watchdog and the report now share every rule, not just the markers, which is what let these two disagree in the first place. An awk trap found while writing it, and worth the comment it now carries: naming `first_open[n]` as an assignment target CREATES that key before the right-hand side is evaluated, so `first_open[n] = first_open_run(n) + 1` made first_open_run take its "already set" branch and read the empty value it had just created. Every finish wrote 1, closed nothing, and the green fixture reported its one passing test as unfinished. Red proof, each arm reverted alone: run_key -> the bare name: the error names `duplicate()`, not `duplicate() (run 2)` the no-open-start guard dropped: the skip fixture exits 0 with no error line Two regression cases: duprun (the second run is named, so the watchdog times it on its own) and skipthenlost (a skip cannot close a later run of its name). bash scripts/cmux-next/tests/swift-test-summary.test.sh → ok swift-test-summary Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Agent-Session: https://cmux.com/deeplink/agent?id=aid-9cc710fd4775017aab15
The review of f856fed returned SHIP with one P2, and it is a real false kill, so it goes in before the merge rather than into a follow-up. A run key was readable text, `duplicate (run 2)`, and a display name is whatever the author wrote. name_of truncates at " skipped", so these two legal labels collapse onto one key: A: "duplicate skipped on unsupported platform" -> duplicate B: "duplicate (run 2) skipped on unsupported platform" -> duplicate (run 2) A's run 2 and B's run 1 both keyed as `duplicate (run 2)`, and the watchdog remembers when it first saw each KEY. Replayed on the real parser and the real timer awk, against the parent and this head: parent f856fed: seen at t=10 `duplicate (run 2)`; open at t=181 `duplicate (run 2)` -> inherits t=10 -> at t=310 reported 300 s old and sampled, at an age of 129 s this head: seen at t=10 `duplicate<0x01>2`; open at t=181 `duplicate (run 2)` -> distinct key, seeded at now, age 0 s So the run number now joins the name with byte 0x01, which a test name cannot contain and which is neither a newline (the log is line oriented) nor a tab (the watchdog seen file is tab separated). The key is never shown: run_label turns it back into "name (run N)" for the report and for the stuck message, and the watchdog awk now carries names_awk for that one function. The regression test reads the key out of the script the same way the script builds it, because the key is internal and the report cannot expose it: both open runs in the reviewer's own fixture must have distinct keys, and the keys must read back as words. If the shared awk is restructured the extraction yields nothing and the test fails loudly instead of passing on an empty string. Red proof: run_key reverted to the readable form -> "two different open runs share one watchdog key: duplicate (run 2)". bash scripts/cmux-next/tests/swift-test-summary.test.sh → ok swift-test-summary Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Agent-Session: https://cmux.com/deeplink/agent?id=aid-9cc710fd4775017aab15
Two things, found by running this gate on a real job rather than on fixtures. **The watchdog was killing healthy runs, and that is why the job never reported every test.** On the selected-targets step of cmux#25391 run 40313902783 the complete raw log shows 7159 tests started, 2003 finished, no summary line, and `##[error]Process completed with exit code 143` -- SIGTERM, from this script's own stuck watchdog: ::error ... stuck::3927 tests still running after 300s ... Nothing was wrong with the run. swift-testing prints every test "started." as it enters the run, while SWT_EXPERIMENTAL_MAXIMUM_PARALLELIZATION_WIDTH (6 in cmux-next.yml) lets only a few execute, so thousands of tests are legitimately open and waiting far past 300 s. This is the premise of the check, not the accounting under it: the merge-base parser reports 3925 open on that same log against this head's 3975. So progress is the signal. A run that is stuck stops FINISHING tests; a width-limited run keeps finishing them whatever its open count. Measured on that same log, the largest gap between consecutive finishes was 131 s, inside the 300 s limit, so the new premise would have let it run. The age of an open test now only chooses which tests to NAME in the message. The regression case drives it: one test open for the whole run while others finish every second, asserting no stuck error and no sample. Proven red by the arm alone -- and the first version of this fix used `grep -c` on an alternation pattern, which basic grep reads as literal text, so progress never advanced after the first poll and the watchdog killed the dripping run. That is why the pattern is `grep -cE` and why the test exists. **And the review's BLOCK on run keys, fixed completely.** A suffix form was still ambiguous: a test named `A<0x01>2` on run 1 produced the same key as `A` on run 2, and both read back as `A (run 2)`. The run number is now a PREFIX, on every run, so everything up to the first separator is digits run_key wrote and no two runs can share a key whatever the name holds. The watchdog seen file is also split on its first tab by hand rather than by field, so a name containing a tab keeps its own timer. The probe test drives run_key and run_label over the adversarial names directly -- `A`, `A<0x01>2`, `A (run 2)`, `A<tab>B`, the empty name -- asserting all keys differ and each reads back as its own name. Against the suffix form it prints exactly the reviewer's case: MANGLED: <A^A2> run 1 read back as <A (run 2)> bash scripts/cmux-next/tests/swift-test-summary.test.sh → ok swift-test-summary Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Agent-Session: https://cmux.com/deeplink/agent?id=aid-9cc710fd4775017aab15
The run that proved the reporting gate also named the cause. The exit stack in run 40317841968 was main -> swift_task_asyncMainDrainQueue -> exit, with 2793 tests started and never finished: the main run loop was stopped while its outermost run was the current one, and the drain queue calls exit(0) the moment that run returns. A finished run never ends that way; swift-testing calls exit() itself from its own job on a dispatch worker thread, with its own stack in the same log, so the two are told apart by the stack and not by guesswork. Anything can leave that stop behind: a test ending its own nested pass a turn late, or AppKit waking an event wait (-[NSEvent _postAtStart:] calls CFRunLoopStop). So this fixes the class rather than the callers: an observer sees the outermost run returning and enters the main run loop again, which goes on draining the main-actor jobs the test run is made of. A never-signalled source keeps the common modes from being empty, so a re-entered run waits rather than returning at once, and after 64 re-entries the guard stands aside so a process stopped in a loop ends instead of growing its stack without limit; the reporting gate turns that into a red job. The regression test takes the stop for real, from a timer on the main run loop at a turn with no nested pass open, and its assertions run at all only because the process is still alive. CMUX_NEXT_TEST_RUNLOOP_GUARD=0 turns the guard off on the same binary, which is how it is proven red. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Agent-Session: https://cmux.com/deeplink/agent?id=aid-9cc710fd4775017aab15
Bugbot needs on-demand usage enabledBugbot uses usage-based billing for this team and requires on-demand usage to be enabled. A team admin can enable on-demand usage in the Cursor dashboard. |
…rver callout Run 40321954380 measured the first shape of this guard and showed it was not enough. It re-entered the main run loop from inside a kCFRunLoopExit observer, and it re-entered exactly once: 885 tests started and never finished instead of 2793, the same `main -> swift_task_asyncMainDrainQueue -> exit` stack at the end, and only one "entering it again" line in 11 minutes of tests. A run started from inside an observer's callout cannot get that observer to fire again for its own exit, so the second stray stop unwound everything. So the drain queue's run is simply never the innermost one. A block posted to the main run loop before any test starts runs a nested run and restarts it in a plain `while` loop whenever it returns. A stray CFRunLoopStop ends that nested run, which the loop replaces at once, instead of the run whose return exits the process. No observer re-entrancy, and no stack frame per stop either. The observer that remains only counts depth, for the invariant below. Two ways out, so the guard cannot make a short run into a hang: a restart cap, and a spin cap for a run that returns immediately (an empty mode, a loop stuck stopped) rather than blocking. Both stand aside and let the process end as it would have; the reporting gate turns the short run into a red job. The regression test now also requires the run depth to be at least 2 from a test: the drain queue's run plus the one the guard holds open. That is the assumption the whole design rests on, so a toolchain that stops running the main loop there, or runs it outside the common modes, fails on that line rather than silently returning the guard to a no-op. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Agent-Session: https://cmux.com/deeplink/agent?id=aid-9cc710fd4775017aab15
Both review findings were about the test, not the guard, which is where my own measurement had already failed me once. The probe stopped whatever run was current. Its sibling in this file runs the main loop for 100 ms, so after the regression test armed the probe and suspended, the stop could land on that nested pass instead: the restart count would not move and the regression test would fail after 30 s, or pass because some later unrelated stop moved it. @mainactor does not order those across a suspension, and serializing this suite would not help, because any suite can nest a run. The probe now fires only when the run a stray stop is fatal to is the current one (the depth the guard protects), counts the stops it lands, and is disarmed in a defer whether or not it reached its count. And the red proof proved the wrong thing. With CMUX_NEXT_TEST_RUNLOOP_GUARD=0 the test threw on `#require(installed == 1)` before it ever scheduled a stop, so its red said only "the guard was switched off" -- the switch testing itself. The variable now skips the holding and nothing else: the depth count and the keepalive source stay, which leaves the process exactly as vulnerable as it was, so the test reaches the same stop and the process dies of it. That is the red worth having. Three stops, not one: the first shape of this fix survived exactly one (run 40321954380), and a one-stop test would have called it a pass. Also from the review: the spin detector read CFAbsoluteTimeGetCurrent, a wall clock that can step backwards and make a long run look instant; it now reads CLOCK_MONOTONIC. A `true` without <stdbool.h> compiled only because Darwin's CoreFoundation pulls it in transitively -- found by type-checking this file on Linux against a small stand-in for the CF declarations it uses, which is now how it can be checked at all away from a Mac. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Agent-Session: https://cmux.com/deeplink/agent?id=aid-9cc710fd4775017aab15
Bugbot needs on-demand usage enabledBugbot uses usage-based billing for this team and requires on-demand usage to be enabled. A team admin can enable on-demand usage in the Cursor dashboard. |
|
This PR complements #25391: your runner hardening reports truncation and catches missing summaries; #25504 schedules changed Swift test/source suites in a first narrow shard so their own signal is emitted before the broad target pass. It deliberately leaves your runner changes untouched. Once both land, a broad helper cut-off cannot hide a changed suite, and the truncation remains a red with unfinished-test evidence. |
…r the answer The reporting gate now catches the truncation it was built for, and run 40330489336 shows what you get when it does: "the test helper died on signal 6; crashed thread: no crash report from this run". The signal is known and the cause is not, so the red names a crash nobody can attribute. Two things made it unreadable, and both are in the lookup rather than the crash. The summary searched only $HOME/Library/Logs/DiagnosticReports. A test helper on a CI Mac leaves its report in the SYSTEM /Library/Logs/DiagnosticReports, which a login session's $HOME is not, so for that run it searched a directory the report was never going to be in. It now takes a colon-separated list and the harness passes both, system first. And when it matched nothing it printed nothing, so the caller rendered the empty string as "no crash report from this run" -- which states as a fact that the process left no report, when the truth was that this looked in the wrong place. It now says what it searched: every directory, whether it could be read, and how many reports it passed over as older than the run or as another process's. A busy CI mini has plenty of both, and a count distinguishes "it crashed and ReportCrash has not written yet" from "nothing here was ever ours". scripts/cmux-next/tests/ips-crash-summary.test.sh covers all of it with synthetic .ips files: a report found in the second directory, the no-match line naming both directories, a stale report and another process's each passed over and counted, a missing directory named rather than raised (the summary runs after a crash and must never replace it with its own failure), and the harness's two-directory default. Each arm red-proved: searching only the first directory, dropping the no-match line, and restoring the $HOME-only default each fail exactly their own assertion, and nothing else. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Agent-Session: https://cmux.com/deeplink/agent?id=aid-9cc710fd4775017aab15
|
Found 8 test failures on Blacksmith runners: Failures
|
…port file The gate catches the truncation; the second half of the job is saying what caused it, and that still did not work. At 5dc60d8 the run died on signal 6 with "Attempted to read an unowned reference but object was already destroyed", and the report search -- now looking in both directories and saying so -- found 316 reports, every one older than this run. ReportCrash simply had not written one, so there was a known signal and nothing to attribute it to for the second run in a row. So the crash names itself in the log we already keep. Swift's backtracer prints a symbolicated stack to stderr in-process; its default is `enable=tty`, which under Actions means off, which is why a trap left only its one-line message. The harness turns it on before starting the run. symbolicate=full, not the `symbolicate=off` the xcodebuild jobs carry: an unsymbolicated stack answers none of the question this exists to answer, and it costs only on a run that has already crashed. interactive=no and timeout=0s so it never waits for a keypress that cannot come. An explicit SWIFT_BACKTRACE in the environment still wins. The test runs the harness's own export line rather than matching its text, so a typo in the setting fails there and not on the next crash. Red-proved on four mutations of that line -- enable=tty, symbolicate=off, interactive=yes, and dropping the `:-` that yields to an explicit setting -- each failing only its own assertion. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Agent-Session: https://cmux.com/deeplink/agent?id=aid-9cc710fd4775017aab15
…swift-test-reports-every-test
|
|
|
Review (codex gpt-6-astra xhigh, next-review): BLOCK at b9d88c0
|
|
Closing this in favour of the three PRs it split into. Nothing is dropped: I verified the split is loss-free by recombining both halves of the wrapper's diff and comparing byte-for-byte against this PR's file (identical).
This PR was 1,105 added / 72 removed across 10 files, over Leo's ~800-line rule, and it mixed three changes that want different reviews: a run-loop guard in C, an awk parser, and crash-report plumbing. Each split is rebased onto the current Two things worth keeping from this PR's history, since they are the reason the gate is written the way it is:
Leo's stop condition ("stop when a PR run reports every test; send me the SHA") is not met yet and I am not claiming it here. It needs a |
…ran (#25856) * ci(cmux-next): the swift test job fails when fewer tests report than ran A truncated swift test run could read as a pass. The gate only required a "Test run with N tests" summary line to exist, and that line counts the tests that REPORTED -- so a run that ends while tests are still going still prints one, and when the tests that did report were green the job went green with thousands of tests unreported. The check is now: every test the log shows starting also finishes, and the summaries count at least as many tests as started. Not equality, because a skipped test prints no "started." line. Measured on base's wrapper, a run that starts two tests, finishes neither and prints "Test run with 1 test ... passed" exits 0. With this, it fails. Three parse bugs that would each flip the verdict are handled, and each has a test: - Status words are anchored at the line start, not matched anywhere. A test whose own output contains "✔ Test ... passed after" could otherwise mark itself finished -- the single failure this gate exists to prevent. - Finishes are counted per RUN, not per name. One log can hold the same test name twice (the isolated-suite step appends each suite's process to one log), and keying by name let run 1 finishing cover run 2 starting. - Every finish shape the reporter emits is a finish: both verbs on all four markers, "➜ ... skipped.", "➜ ... was cancelled after" (swift-testing 6.3 Test.cancel()), and the ━ known-issue lines. An earlier revision of this gate missed the cancellation shape, which would have failed every healthy run. The markers are matched as anchored alternations, never a bracket set: awk reads [✔✘➜━] as the set of BYTES those characters are built from, and each ends in a byte another contains, so a set matches every line. The watchdog also stops killing healthy runs. It measured the age of OPEN tests, but swift-testing prints every test "started." as it enters the run while the parallelization width lets only a few execute, so thousands are legitimately open: on cmux#25391 run 40313902783, 7159 started, 2003 finished and 3927 open past 300 s killed a run with nothing wrong. Lack of PROGRESS is the signal that survives any width, so the age of an open test now only decides which tests to name, and stuckness is whether any test finished in the window. Split out of #25391 to stay under the 800-line limit; the exit(0) cause fix and the crash-report diagnosis are separate PRs. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Agent-Session: https://cmux.com/deeplink/agent?id=aid-9cc710fd4775017aab15 * ci(cmux-next): give the swift test pass room once the stall rule is the hang guard Run package tests: CMUX_NEXT_TEST_HANG_SECONDS 900 -> 1500, step timeout 20 -> 30 min, job timeout 60 -> 90 min. Also make the summary test's line counts portable (BSD wc pads) and update the sampler header to the stall rule. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com> Agent-Session: https://cmux.com/deeplink/agent?id=aid-cc8bff1c3ddb4ec353c5 * ci(cmux-next): hold each test run to its own summary; one deadline for both passes Review findings: - the report now also checks each "Test run started." block has its own summary counting at least its own starts, so a truncated later process cannot hide behind an earlier summary that ran ahead of its starts - only the generated parameterized-case start ("case passing N argument(s)") is skipped, so a test named "case passing ..." is still counted - the priority and broad passes share one deadline inside the 30-minute step Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com> Agent-Session: https://cmux.com/deeplink/agent?id=aid-cc8bff1c3ddb4ec353c5 * ci(cmux-next): match starts and finishes within one test run A finish in a later "Test run started." block could close a start an earlier block lost (a skip of the same name), so a lost test read as finished. The names runs are counted under now carry their block number. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com> Agent-Session: https://cmux.com/deeplink/agent?id=aid-cc8bff1c3ddb4ec353c5 * ci(cmux-next): a skip closes no start swift-testing skips a test instead of starting it, so a skip never ends a start; two suites in one process can share a bare test name, and a skip in one closed the lost start of the other. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com> Agent-Session: https://cmux.com/deeplink/agent?id=aid-cc8bff1c3ddb4ec353c5 * ci(cmux-next): shorten the new comments Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com> Agent-Session: https://cmux.com/deeplink/agent?id=aid-cc8bff1c3ddb4ec353c5 * ci(cmux-next): a silent hang with no test open is stuck too; no report is no pass Review findings: the watchdog only fired with an open test to name, so a helper hung before the first start or after its summary ran to the whole-run limit; and a report that failed for any reason other than truncation was ignored when swift test exited 0. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com> Agent-Session: https://cmux.com/deeplink/agent?id=aid-cc8bff1c3ddb4ec353c5 * ci(cmux-next): the silence rule waits for the first test start; trim comments under 800 lines Before any test starts, output has lagged minutes behind a healthy pass (356 s on a real broad pass, then 2,000 lines at once), so silence there is not a hang; the whole-run limit guards that stretch. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com> Agent-Session: https://cmux.com/deeplink/agent?id=aid-cc8bff1c3ddb4ec353c5 --------- Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>
…he run (#25861) The swift test job reported a fraction of its tests and still exited 0. 2,722 tests started and never finished, no crash, no signal, no failure: the process left async main normally, so the job read as a pass. The cause is a test driving AppKit's event queue. HomeOpenFocusesComposerTests' click harness posts events with NSApp.postEvent and pumps them with NSApp.nextEvent. AppKit answers by calling CFRunLoopStop on the run loop it finds running -- and the OUTERMOST run of the main run loop is swift_task_asyncMainDrainQueue's own CFRunLoopRun, which drives the whole Swift Testing run. Stopping it returns from the drain queue, main + 132 falls through into exit(0), and every test that had not yet reported is simply gone. A test must not be able to end the run by using AppKit the way an app does. CmuxNextTestRunLoopGuard installs a run-loop observer that keeps the outermost run alive: when the drain queue's CFRunLoopRun is stopped from underneath it, the guard re-enters it, so AppKit's stop ends the nested run the harness is pumping and nothing else. Measured on the suite: 4 re-entries, 0 "standing aside", and a complete summary line. TestProcessExitTests covers the exit path itself, so an exit() from async main prints its stack rather than ending the run silently. Zero files under Sources/: this is test support only, and the guard is linked into the test target, never the app. Split out of #25391 to stay under the 800-line limit. The gate that makes a truncated run fail instead of passing is #25856; the crash-report diagnosis is #25857. Agent-Session: https://cmux.com/deeplink/agent?id=aid-9cc710fd4775017aab15 Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>
…diagnosed (#25857) * ci(cmux-next): a crashed test helper names itself instead of going undiagnosed A swift test run that died on signal 6 could not be attributed. Two separate reasons, both fixed here. The backtracer was off. Swift prints a symbolicated stack to stderr in-process on a fatal error, but `enable=tty` is the default, so under Actions it was off and a crash left only its one-line message. Run 40330489336 died with "Attempted to read an unowned reference" and nothing to attribute it to. SWIFT_BACKTRACE now enables it with symbolicate=full, interactive=no and timeout=0s so it never waits for a keypress that cannot come. It costs only on a run that has already crashed. The crash reports were looked for in the wrong place. A test helper on a CI Mac leaves its report in the SYSTEM /Library/Logs/DiagnosticReports, not the $HOME one a login session gets, so searching $HOME alone found nothing for a run that had plainly died. ips-crash-summary.py now takes a colon-separated list and searches both, system first. It also stops being silent when it finds nothing: it says which directories it looked in, whether each exists, how many reports each holds and how many were skipped as older than the run or as another process's. "No crash report from this run" and "I looked in the wrong directory" are different facts, and silence made that signal 6 undiagnosable. Split out of #25391 to stay under the 800-line limit. Touches the same wrapper as the reported-vs-discovered gate, so whichever lands second takes a rebase. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Agent-Session: https://cmux.com/deeplink/agent?id=aid-9cc710fd4775017aab15 * ips-crash-summary: count only this run's crash reports, by pid A name and a time are not an identity: on a shared CI Mac another job's swiftpm-testing-helper or PackageTests crash in the same minutes matched both, and could be named as this run's or copied up beside it. The harness now passes the run's pids (the `swift test` pid, a helper's parent, plus the helpers the watcher saw), and a report counts only when its pid or parentPid is one of them; the rest are counted as another process. Regression case: a foreign report in the first directory, this run's in the second, and only this run's is named or copied. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com> Agent-Session: https://cmux.com/deeplink/agent?id=aid-3aa8a14a36831eaec813 --------- Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>
![Fix with [code]smith](https://pr-comments-assets.blacksmith.sh/codesmith/fix-with-codesmith-light-3x.png)
What
Both halves of the ask: the
cmux-next swift testjob can no longer read as a pass when it endedearly, and it no longer ends early.
The process does not crash. swift-testing's async main runs
CFRunLoopRunon the main loop, AppKitcalls
CFRunLoopStop(CFRunLoopGetMain())to wake an event wait, the stop lands on that outermostactivation,
swift_task_asyncMainDrainQueuereturns, andmainfalls through toexit(0). Everytest that had reported is already in the log, so SwiftPM still prints a
Test run with N testssummary — the summary counts only what reported. With
swift testexiting 0 and every reportedtest green, the job read as a pass with thousands of tests missing.
HomeLaunchRevealTestsnever reported for four days and nobody saw it (#23680, #23704, runs back to 2026-10-22: 2192
counted against 4736 started).
The cause
HomeOpenFocusesComposerTestsis@Suite(.serialized)with exactly two tests. From the swift testjob
121471396706of this PR:The first test wraps its one
clickininANestedPassand passes. The second callsclickseventimes bare, starts, and the process ends 2303 tests short. The
atexittracer can never name thecaller — by the time it runs, the stopper's frames are gone — which is why three days of stack
reading got nowhere.
Nothing else in flight at that instant can post an
NSEvent: the other tests that had just startedare a socket-router call (
listWithNoAcpmuxIsEmpty), twoDaemonStoredata cases(
oneStatusChangeVisitsOneWorkspace) and colour maths (aWindowsAccentTakesTheHueOfTheWorkItShows).Every raw
NSApp.postEventinSourceswas traced too and none is reachable from any test:DebugMouse.swift:135andDebugKey+Sequence.swift:47are#if DEBUGand reached only fromAppControl's control socket, which no test builds;WindowHintController.swift:155is behind alive
hints.showsession, which no test starts;AddressBarView+Debug.swift:112is behinddebug.omnibar, likewise. There is no bareCFRunLoopRunin the package, noNSApp.stopanywhere,and the four
CFRunLoopStop(CFRunLoopGetMain())sites inCmuxNextControlTestsare in a targetthis job skips.
The fix
Isolating only the
postEventwas never enough.clickalso runsdocument.mouseDown, whichdrives the list's own press-and-drag tracking, and then an
NSApp.nextEventdrain loop in.defaultmode. "postEvent, then nextEvent, in any run loop mode" is verbatim the shape thisrepository already blames for ending the process (
KeyDownDispatchTests.swift:18,ActionRunTimingTests.swift:324, which both avoid it by pokingcurrentEvent).So the nested pass moves into
clickandkeyinstead of staying each caller's job, whichremoves the whole class of "someone called
clickbare". The two passes take different run loopmodes, because
aClickLeavesTheRunLoopItRanInRunningnests one around a click that now nests itsown, and a block left in one mode must never be run by the other's activation. That test keeps its
assertion and finally gains its meaning: the pass ends
.finishedbecause the click absorbed itsown stop, not because this caller remembered to wrap it.
The gate
report()inscripts/cmux-next/swift-test-with-hang-sampler.shalready caught the no-summaryshape. It now also fails when a summary is present but any test the log shows starting never
finished, or when the summaries total fewer tests than started.
Three traps, each one a false failure I hit and fixed:
started.line, so a legitimate summary runs aheadof the starts.
step holds dozens — while starts are counted across all of them, so comparing the last summary
alone fails a log holding two whole runs.
a test's own output (
debug: ✔ Test hung() passed…) self-report as finished. And a finish is notonly
✔/✘: a known-issue finish carries━. The live daemon-tests job of this PR read━ Test aRunCutOffMidwayFinishesWithoutDuplicates() passed after 8.359 seconds with 2 known issues.as unfinished and failed a run of 386 tests whose own summary counted all 386. Separate anchored
patterns, never one bracket set: awk reads
[✔✘➜━]as the set of bytes those characters aremade of, and each ends in a byte another also contains, so
match()lands mid-character and everyline matches. That bug made the gate report nothing at all, and the existing red fixture caught it.
scripts/cmux-next/tests/swift-test-summary.test.shholds the regression cases, and the checks jobalready runs it.
Deliberately not added
A guardrail refusing new raw
NSApp.postEvent/NSApp.nextEvent/CFRunLoopStoplines. CLAUDE.mdsays not to add CI gates, and the gate above already catches a truncation and names the test that
never finished — the attribution this took three days to get by hand.
Observed / Not run
Ran here, on Linux:
Both real job logs of this PR's earlier run were replayed through the extracted
report():121471396631): the "never finished" false failure is gone; the one genuine red,aUserRenamedHomeMarkerIsNotUnnamed() WorkspaceNameSourceTests.swift:18, still reports.121471396706): the truncation still fires, through the new branch —"the summaries count 420 tests in total but 6534 started and 2304 of those never finished".
Not run here: the Swift suite. Agents never compile or test on a Mac locally. This PR's own
cmux-next swift testrun at this head is the evidence for the cause fix: a run that reportsevery test it started is the thing being claimed.
Base findings at the earlier head, each also failing on #25394, #25395 and #25396 at the same time:
cmux-next generated filesandcmux-next swift test(the truncation itself, which is what thisfixes).
cmux-next daemon testswas the gate's own false positive, fixed here.Changelog
none
🤖 Generated with Claude Code