NoiseEncryptionServiceTests handshakes are torn down by their own timeouts when the iOS-sim runner stalls (flaking across unrelated PRs) #1737

Summary

Tests in NoiseEncryptionServiceTests fail intermittently in the Run iOS simulator tests job. The setup handshake expects nil when the responder processes message 3 and gets a 96-byte message 2 instead, because the responder's own handshake timeout fired between message 1 and message 3.

#1483 and #1491 diagnosed this and raised the injected timeouts from 20–60 ms to 1.0 s. It has since outrun 1.0 s twice and the 20 s production default once, so a larger value does not close it. Neither affected PR touches Noise code or its tests: #1721 changes a workflow and a Python test, #1644 adds one unrelated test file.

Sightings

Every failure starts with the same issue, in establishSessions:

NoiseEncryptionServiceTests.swift:1507:9: Expectation failed: (finalMessage → 96 bytes) == nil

The 103-issue failure is that one, then 101 × Unexpected readiness error (the responder never established, so every decrypt throws), then the final decrypt.

Mechanism

1. establishSessions runs the XX handshake as consecutive synchronous calls: alice writes message 1, bob answers with message 2, alice answers with message 3, bob processes message 3 and must return nil.
2. Processing message 1 arms bob's responder timeout (scheduleOrdinaryResponderTimeoutLocked, NoiseSessionManager.swift:910). When it fires, the work item removes sessions[peerID] if that session is still a handshaking responder.
3. If it fires before message 3 arrives, message 3 finds no session. That is one of the isFreshInitiation conditions (:546), so bob treats it as a new initiation and answers with a fresh 96-byte message 2.
4. The initiator has the same exposure. initiateHandshake arms the initiator timeout (:357), which removes alice's session if message 2 has not been processed when it fires.

So any stall between two of those calls that outlasts the timeout breaks the test. The timeout in play is whatever the service was built with: the injected value, or the production defaults of 10 s (initiator) and 20 s (responder).

Reproducing it deterministically

On main, add a stall before the last call in establishSessions:

let message3 = try #require(final, "Expected handshake final")
Thread.sleep(forTimeInterval: 1.2)
let finalMessage = try bob.processHandshakeMessage(from: alicePeerID, message: message3)

With 1.2 s, the three tests that inject a 1.0 s responder timeout fail with the CI signature. timedOutReconnectRestoresQuarantinedTransport fails after 11.2 s with the same two issues as both sightings.

With 23 s, transportReadinessRejectionSpendsNoMessageBudget fails with the same 103 issues as CI. 21 s was not enough locally: asyncAfter allows leeway, and the 20 s timer had not fired yet.

Exposure

• Every handshake in the file on default timeouts, whether it goes through establishSessions (17 call sites) or is written out inline. Window: 10 s.
• Three tests with a 1.0 s responder timeout: timedOutReconnectRestoresQuarantinedTransport, pacedMessageOneCannotHoldOutboundPaused, lostReconnectCompletionGetsOneLocalRetry.
• lostReconnectCompletionGetsOneLocalRetry also gives the initiator 40 ms, and runs setup under it. This is the tightest window in the file. It would fail with a thrown error instead of the :1507 signature, so earlier sightings may have been read as something else.
• ordinaryInitiationTimeoutIsBounded: a 30 ms initiator timeout between initiateHandshakeIfNeeded and claimHandshakeInitiation.
• yieldedResponderRecoversFromLegacyDoubleYield: 1 s on both timers across about ten calls.
• pacedMessageOneCannotHoldOutboundPaused has a second window: it must replay the spoofed initiation within the 0.3 s rollback cooldown.
• BLEServiceCoreTests.timeoutRestoredSessionDefersQueueDrainUntilConvergence: a 0.3 s responder timeout armed during its setup handshake.
• handshakeClaimRearmsDeadline waits out a real 1 s deadline. It fails if more than 0.5 s is lost before the claim.

Why the hygiene test did not catch it

#1491 deliberately left injected production timeouts out of TestTimingHygieneTests, on the grounds that they are the behaviour under test and a short value is correct there. That holds for the scenario under test and not for the handshake steps that run under the same timer.

Where the stall comes from

Not established. The proposed fix does not depend on it. What the CI logs and a local experiment show:

In the 24 s failure the test thread was blocked while the process kept running. Log lines mirrored from the test process carry its own clock. The initiator logged Handshake completed at 21:04:25.214, and the next Noise line is at 21:04:49.943. A CoreAudio thread in the same process logged at 21:04:36.3, inside that gap.

The runner received no output for the same period. Nothing reached the runner between 21:04:29.6 and 21:04:49.6. That is the only gap over 5 s in the test phase of that job. Before it, the log was 3–10 s behind the process.

A slow consumer of xcodebuild's output stalls the test process. Locally (Xcode 26.6, iPhone 17 simulator, main at 5e9287f), with xcodebuild test-without-building piped into a reader:

The machine was otherwise idle in every run.

Under xcodebuild every SecureLogger line is mirrored into the test process's output, so a test thread can block in a log write between two handshake calls. The handshake timers run on dispatch queues and write nothing until they fire, so they keep their deadline.

The last run reproduced the CI failure. timedOutReconnectRestoresQuarantinedTransport failed after 11.530 s with the same two issues as both sightings (:1507 96 bytes, then :1288 restored). Two more tests from the exposure list failed in the same run: ordinaryInitiationTimeoutIsBounded (claimHandshakeInitiation returned nil) and yieldedResponderRecoversFromLegacyDoubleYield.

This does not show that the CI stalls were log backpressure. CPU starvation would produce both the lag and the stall. HALC_ProxyIOContext::IOWorkLoop: skipping cycle due to overload appears in passing runs too, so it does not tell the two apart.

If it is backpressure, writing xcodebuild's output to a file and printing a summary afterwards would remove the path. That needs a CI run to confirm and is separate from the test fix.

Proposed fix

The recipe #1563 used for the completion-grace flake: inject a value no test run can outlive, and fire the deferred work through a DEBUG hook.

1. Build every service in NoiseEncryptionServiceTests through one factory whose handshake timeouts default to an unlosable value.
2. Add DEBUG hooks on NoiseSessionManager that run the pending initiator or responder timeout work item. Tests whose subject is expiry call the hook.
3. Where a test asserts what a deadline is, read the deadline instead of waiting it out.
4. Extend TestTimingHygieneTests to flag a numeric handshake timeout in any test, and direct NoiseEncryptionService( construction in NoiseEncryptionServiceTests.

A change along these lines passes locally:

• the full SwiftPM suite and the iOS simulator suite;
• the 1.2 s and 23 s stalls above;
• the stalled-reader run that failed on main, with the same reader settings. The Noise suite was stalled to 70.7 s again and all 2071 tests passed.

It covers every entry in the exposure list, and the Noise suite drops from 8.6 s to 3.7 s because nothing waits on a real timer.

Not proposed: raising the values again, which scales with a stall that has no bound, or -retry-tests-on-failure, which hides the class.

Prior art

• Harden iOS-sim CI: destination fallback + Noise reconnect test determinism #1483: first diagnosis; 20 ms to 1.0 s.
• Deflake CI, and make the flake class unrepeatable #1491: two siblings, 40 and 60 ms to 1.0 s; settleTimeout, TestTimingHygieneTests.
• Make the completion-grace restart test deterministic #1563: made immediateLegacyRestartDuringCompletionGrace deterministic with an unlosable period and _test_fireSuppressedInitiationRecovery.
• Raise positive waitUntil timeouts to 5s for loaded CI runners #1340: raised positive waitUntil timeouts to 5 s.