Build and test are two calls now, and three more assertions race no more
ci / secret-sweep (pull_request) Successful in 15s
ci / vectors-head (pull_request) Successful in 11s
ci / parity-scrub (pull_request) Successful in 15s
ci / unit-tests (pull_request) Failing after 1h1m45s
ci / ui-tests (pull_request) Failing after 4m33s

The 2026-10-16 run gave the first real diagnostic in six attempts.
ci-test.log reached 889,595 bytes and ended at
PruneExplicitPrecompiledModules, which is the end of a clean build, and
then xcodebuild sat for 150 minutes without printing "Testing started".
The watchdog killed it and the gate printed that tail. So on pauls-imac
the build succeeds and the test phase never begins; the same commit
builds and runs 1289 XCTest plus 578 Swift Testing tests in about 7
minutes on an M3.

One xcodebuild call cannot tell a slow compile from a test phase that
never starts. build-for-testing and test-without-building each run under
their own cap, and the log says which one stopped.

Running test-without-building against a warm build exposed a second race
in BridgeFailoverTests, of the same kind as the first: onWorked and
onAllFailed append to a plain `var` from the transport's queue while the
test reads it, which races the callback and shares a variable across two
threads. Three assertions read a locked box on a 5-second deadline now.

Verified: build-for-testing reports ** TEST BUILD SUCCEEDED **,
test-without-building runs all 1289, and BridgeFailoverTests passed 11 of
11 three times in a row.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
This commit is contained in:
Paul Hitt
2026-10-16 15:14:53 -04:00
co-authored by Claude Opus 5
parent 0e949b38ac
commit d04c398f69
2 changed files with 134 additions and 69 deletions
+98 -60
View File
@@ -113,41 +113,60 @@ jobs:
# the runner host to a load average in the hundreds.
mkdir -p ci-build && touch ci-build/.metadata_never_index
# A cap INSIDE the job, so a hang is reported here with the tail of the
# log instead of being cancelled by the job deadline with no output.
# Build and test are two xcodebuild calls, each under its own cap, so
# the log says which phase stopped. The 2026-10-16 run proved why:
# ci-test.log reached 889,595 bytes and ended at
# PruneExplicitPrecompiledModules, which is the end of a clean build,
# and then xcodebuild sat for 150 minutes without printing "Testing
# started". One call could not tell a slow compile from a test phase
# that never begins. Two can.
#
# Not `timeout`: coreutils is on one of the two Mac runners and not
# the other, and the run that printed "runs uncapped" then burned the
# whole 180-minute deadline and uploaded a log nobody read. This
# needs nothing but the shell, and it holds xcodebuild's own pid
# because the log is written by a redirect rather than a pipe.
# The watchdog needs nothing but the shell: coreutils is on one Mac
# runner and not the other, and the run that printed "runs uncapped"
# burned the whole 180-minute deadline and uploaded a log nobody
# read. It holds xcodebuild's own pid because the log is a redirect
# rather than a pipe.
#
# `-collect-test-diagnostics never`: the default is on-failure, and on
# a failure xcodebuild runs `simctl diagnose` (a sysdiagnose plus 8
# minutes of simulator logs, 600s timeout each) before it reports
# anything. That is what the 2026-10-14 and 2026-10-15 runs were doing
# when the deadline cancelled them: one test had already failed, the
# suite was over, and the collection outlasted the job. Reproduced on
# an M3 by watching the `simctl diagnose` pid.
xcodebuild -project FlamenetMessenger.xcodeproj -scheme FlamenetMessenger \
-sdk iphonesimulator -destination "platform=iOS Simulator,name=iPhone 17" \
-collect-test-diagnostics never \
-derivedDataPath ci-build test -only-testing:FlamenetMessengerTests \
> ci-test.log 2>&1 &
XCB=$!
( sleep 9000
kill -0 "$XCB" 2>/dev/null || exit 0
echo "GATE: no result after 9000s, killing xcodebuild"
kill -TERM "$XCB" 2>/dev/null
sleep 20
kill -KILL "$XCB" 2>/dev/null ) &
DOG=$!
# `-collect-test-diagnostics never`: the default is on-failure, and
# on a failure xcodebuild runs `simctl diagnose`, a sysdiagnose plus
# 8 minutes of simulator logs with a 600s timeout each, before it
# reports anything. Reproduced on an M3 by watching that pid.
capped() {
local limit=$1 label=$2; shift 2
"$@" >> ci-test.log 2>&1 &
local xcb=$!
( sleep "$limit"
kill -0 "$xcb" 2>/dev/null || exit 0
echo "GATE: $label gave no result after ${limit}s, killing xcodebuild"
kill -TERM "$xcb" 2>/dev/null
sleep 20
kill -KILL "$xcb" 2>/dev/null ) &
local dog=$!
wait "$xcb"; local rc=$?
kill "$dog" 2>/dev/null || true
return $rc
}
XC=(xcodebuild -project FlamenetMessenger.xcodeproj -scheme FlamenetMessenger
-sdk iphonesimulator -destination "platform=iOS Simulator,name=iPhone 17"
-collect-test-diagnostics never -derivedDataPath ci-build)
: > ci-test.log
# Progress in the job log while it runs; ci-test.log keeps everything.
( tail -f ci-test.log 2>/dev/null \
| grep --line-buffered -E "Executed|TEST (SUCCEEDED|FAILED)" ) &
| grep --line-buffered -E "Executed|TEST (SUCCEEDED|FAILED)|TEST BUILD" ) &
TAIL=$!
wait "$XCB" || true
kill "$DOG" "$TAIL" 2>/dev/null || true
capped 5400 build-for-testing "${XC[@]}" build-for-testing || true
if ! grep -q '\*\* TEST BUILD SUCCEEDED \*\*' ci-test.log; then
kill "$TAIL" 2>/dev/null || true
echo "GATE: the test build did not succeed"
tail -40 ci-test.log; exit 1
fi
echo "GATE: test build succeeded, running FlamenetMessengerTests"
capped 3600 test-without-building "${XC[@]}" test-without-building -only-testing:FlamenetMessengerTests || true
kill "$TAIL" 2>/dev/null || true
# Assert on the LOG, never on grep's exit status: a failing run
# prints "TEST FAILED", grep matches it and exits 0.
@@ -213,41 +232,60 @@ jobs:
fi
Scripts/generate.sh
mkdir -p ci-build && touch ci-build/.metadata_never_index
# A cap INSIDE the job, so a hang is reported here with the tail of the
# log instead of being cancelled by the job deadline with no output.
# Build and test are two xcodebuild calls, each under its own cap, so
# the log says which phase stopped. The 2026-10-16 run proved why:
# ci-test.log reached 889,595 bytes and ended at
# PruneExplicitPrecompiledModules, which is the end of a clean build,
# and then xcodebuild sat for 150 minutes without printing "Testing
# started". One call could not tell a slow compile from a test phase
# that never begins. Two can.
#
# Not `timeout`: coreutils is on one of the two Mac runners and not
# the other, and the run that printed "runs uncapped" then burned the
# whole 180-minute deadline and uploaded a log nobody read. This
# needs nothing but the shell, and it holds xcodebuild's own pid
# because the log is written by a redirect rather than a pipe.
# The watchdog needs nothing but the shell: coreutils is on one Mac
# runner and not the other, and the run that printed "runs uncapped"
# burned the whole 180-minute deadline and uploaded a log nobody
# read. It holds xcodebuild's own pid because the log is a redirect
# rather than a pipe.
#
# `-collect-test-diagnostics never`: the default is on-failure, and on
# a failure xcodebuild runs `simctl diagnose` (a sysdiagnose plus 8
# minutes of simulator logs, 600s timeout each) before it reports
# anything. That is what the 2026-10-14 and 2026-10-15 runs were doing
# when the deadline cancelled them: one test had already failed, the
# suite was over, and the collection outlasted the job. Reproduced on
# an M3 by watching the `simctl diagnose` pid.
xcodebuild -project FlamenetMessenger.xcodeproj -scheme FlamenetMessenger \
-sdk iphonesimulator -destination "platform=iOS Simulator,name=iPhone 17" \
-collect-test-diagnostics never \
-derivedDataPath ci-build test -only-testing:FlamenetMessengerUITests \
> ci-ui.log 2>&1 &
XCB=$!
( sleep 6000
kill -0 "$XCB" 2>/dev/null || exit 0
echo "GATE: no result after 6000s, killing xcodebuild"
kill -TERM "$XCB" 2>/dev/null
sleep 20
kill -KILL "$XCB" 2>/dev/null ) &
DOG=$!
# `-collect-test-diagnostics never`: the default is on-failure, and
# on a failure xcodebuild runs `simctl diagnose`, a sysdiagnose plus
# 8 minutes of simulator logs with a 600s timeout each, before it
# reports anything. Reproduced on an M3 by watching that pid.
capped() {
local limit=$1 label=$2; shift 2
"$@" >> ci-ui.log 2>&1 &
local xcb=$!
( sleep "$limit"
kill -0 "$xcb" 2>/dev/null || exit 0
echo "GATE: $label gave no result after ${limit}s, killing xcodebuild"
kill -TERM "$xcb" 2>/dev/null
sleep 20
kill -KILL "$xcb" 2>/dev/null ) &
local dog=$!
wait "$xcb"; local rc=$?
kill "$dog" 2>/dev/null || true
return $rc
}
XC=(xcodebuild -project FlamenetMessenger.xcodeproj -scheme FlamenetMessenger
-sdk iphonesimulator -destination "platform=iOS Simulator,name=iPhone 17"
-collect-test-diagnostics never -derivedDataPath ci-build)
: > ci-ui.log
# Progress in the job log while it runs; ci-ui.log keeps everything.
( tail -f ci-ui.log 2>/dev/null \
| grep --line-buffered -E "Executed|TEST (SUCCEEDED|FAILED)" ) &
| grep --line-buffered -E "Executed|TEST (SUCCEEDED|FAILED)|TEST BUILD" ) &
TAIL=$!
wait "$XCB" || true
kill "$DOG" "$TAIL" 2>/dev/null || true
capped 4200 build-for-testing "${XC[@]}" build-for-testing || true
if ! grep -q '\*\* TEST BUILD SUCCEEDED \*\*' ci-ui.log; then
kill "$TAIL" 2>/dev/null || true
echo "GATE: the test build did not succeed"
tail -40 ci-ui.log; exit 1
fi
echo "GATE: test build succeeded, running FlamenetMessengerUITests"
capped 2400 test-without-building "${XC[@]}" test-without-building -only-testing:FlamenetMessengerUITests || true
kill "$TAIL" 2>/dev/null || true
grep -q '\*\* TEST SUCCEEDED \*\*' ci-ui.log || {
echo "GATE: xcodebuild did not report '** TEST SUCCEEDED **'"
tail -60 ci-ui.log; exit 1; }
+36 -9
View File
@@ -53,6 +53,29 @@ final class BridgeFailoverTests: XCTestCase {
return (reply, httpGet(over: fd))
}
/// What `onWorked` and `onAllFailed` reported, read on a deadline.
///
/// Both fire on the transport's own queue when a tunnel ends, which is
/// after `fetch` has the body in hand, so reading a plain `var` straight
/// afterwards both races the callback and shares a variable across two
/// threads. This serialises the writes and waits for the count the test
/// expects.
private final class Reported<T> {
private let lock = NSLock()
private var items: [T] = []
func add(_ item: T) {
lock.lock(); items.append(item); lock.unlock()
}
var all: [T] {
lock.lock(); defer { lock.unlock() }; return items
}
func settles(to count: Int, timeout: TimeInterval = 5) -> [T] {
let deadline = Date().addingTimeInterval(timeout)
while all.count < count, Date() < deadline { usleep(20_000) }
return all
}
}
/// The proxy's state once the transport has told it what happened, or the
/// state at `timeout`. `onWorked` and `onAllFailed` run on the transport's
/// own queue when a tunnel ends, not when the body arrives, so one read of
@@ -75,15 +98,17 @@ final class BridgeFailoverTests: XCTestCase {
let good = try InProcessBridge(upstreamPort: upstream.port)
defer { good.stop() }
var worked: [UInt16] = []
let t = try transport([try refusing(), good.descriptor], worked: { worked.append($0.port) })
let worked = Reported<UInt16>()
let t = try transport([try refusing(), good.descriptor], worked: { worked.add($0.port) })
defer { t.stop() }
let (reply, body) = try fetch(through: t)
XCTAssertEqual(reply, 0)
XCTAssertTrue(body.contains("second line"), body)
XCTAssertEqual(good.completedSessions, 1)
XCTAssertEqual(worked, [good.descriptor.port], "the line that answered was not reported")
XCTAssertEqual(
worked.settles(to: 1), [good.descriptor.port],
"the line that answered was not reported")
}
/// No handshake within the limit is a failure (§24.6).
@@ -120,26 +145,28 @@ final class BridgeFailoverTests: XCTestCase {
let good = try InProcessBridge(upstreamPort: upstream.port)
defer { good.stop() }
var worked: [UInt16] = []
let worked = Reported<UInt16>()
let t = try transport(
[cutOff.descriptor, good.descriptor], timeout: 3,
worked: { worked.append($0.port) })
worked: { worked.add($0.port) })
defer { t.stop() }
let (reply, body) = try fetch(through: t)
XCTAssertEqual(reply, 0)
XCTAssertTrue(body.contains("the relay answered"), body)
XCTAssertEqual(cutOff.completedSessions, 1, "the first line was never tried")
XCTAssertEqual(good.completedSessions, 1)
XCTAssertEqual(worked, [good.descriptor.port], "a bridge that answered nothing counted as working")
XCTAssertEqual(
worked.settles(to: 1), [good.descriptor.port],
"a bridge that answered nothing counted as working")
}
/// §24.6: when every line fails, stop. Never a direct connection.
func testWhenEveryLineFailsNothingGoesDirect() throws {
let upstream = try TinyHTTPServer(body: "direct")
defer { upstream.stop() }
var failedAll = 0
let failedAll = Reported<Void>()
let t = try transport(
[try refusing(), try refusing()], allFailed: { failedAll += 1 })
[try refusing(), try refusing()], allFailed: { failedAll.add(()) })
defer { t.stop() }
let fd = try socksClient(toProxyOn: t.localPort)
@@ -149,7 +176,7 @@ final class BridgeFailoverTests: XCTestCase {
let reply = socksConnectReply(fd, host: [127, 0, 0, 1], port: upstream.port)
XCTAssertNotEqual(reply, 0, "the proxy reported success with no bridge reachable")
XCTAssertEqual(upstream.hits, 0, "traffic went direct")
XCTAssertEqual(failedAll, 1)
XCTAssertEqual(failedAll.settles(to: 1).count, 1)
}
/// One at a time: the second line is not dialled while the first is still