#1621

SimulatedMeshTests storm bound fails on wall-clock speed, not relay behaviour (flaking across unrelated PRs)

Openecgangopened 2mo ago

Symptom

SimulatedMeshTests.publicMessageRelaysAcrossLineTopologyWithinTTLBudget fails intermittently in CI:

SimulatedMeshTests.swift:75:9: Expectation failed:
  (mesh.deliveredFrameCount - baseline → 16) <= 12

Always 16. Never 13, never 21.

It is not caused by the PR under test

Observed on seven unrelated PRs in ~24h, none of which touch BLE, the mesh, or any transport code:

PR branchsubject
feat/thread-message-searchin-thread message search
feat/message-deep-link-copycopy deep links
feat/clear-unread-conversationclear unread badge
feat/l10n-catalog-key-scanCI lint for missing l10n keys
feat/export-chat-plaintextexport chat as plaintext
feat/people-sheet-name-filterfilter nicknames in people sheet

feat/thread-message-search produced the byte-identical assertion, same line, same value 16.

Root cause

The harness is deterministic in scheduler time but the announce admission decision reads wall-clock time.

  • BLEService.performMaintenance() runs on the manual scheduler (so mesh.advanceTime(_:) drives it), but computes announceThrottle.elapsed(since: Date()) — real time.
  • BLEService.swift:2760 — announceThrottle.shouldSend(force:, now: Date()).
  • Gate: TransportConfig.bleForceAnnounceMinIntervalSeconds = 0.15.

So whether the maintenance announce is emitted depends on how long the test took in real seconds:

  • Fast machine: the whole test runs in ~34 ms. Real elapsed never reaches 0.15 s, every maintenance announce is throttled away, count is 12, passes.
  • Loaded CI runner: pumping and engine fences across three nodes cross 0.15 s, all three nodes emit a maintenance announce.

The +4 is exactly those three announces, counted per (packet, receiver, link):

a → b            = 1 frame
b → a, b → c     = 2 frames
c → b            = 1 frame
                 = 4    →   12 + 4 = 16

The test file already acknowledges the gap, at line 133, for the opposite case:

// (The announce throttle runs on wall clock; model elapsed time.)
b.service._test_resetAnnounceThrottle()

_test_resetAnnounceThrottle() can force an announce through the throttle. Nothing can hold one back, and the storm bound depends on them being held back.

Reproduction (local, deterministic)

On an unmodified checkout the test passes 19/19. Insert a real sleep past the 0.15 s gate — changing nothing else — and it fails with the exact CI value:

a.service.sendMessage("hello line", mentions: [])
mesh.pump()
Thread.sleep(forTimeInterval: 0.2)   // <-- only change
mesh.advanceTime(by: 2)
mesh.advanceTime(by: 2)

Result: (mesh.deliveredFrameCount - baseline → 16) <= 12 — identical to CI.

Conditionframesresult
unmodified, 19 consecutive runs12pass
+ 0.2 s wall-clock sleep16fail

Suggested fix

Two options, not mutually exclusive.

1. Make the storm bound measure what it claims (small, test-only). The assertion is about a single public message not multiplying across a relay hop. Counting unrelated maintenance announces in that budget conflates two things. Filtering the counted frames to the message packet — or exposing a per-type count on SimulatedMesh — makes the bound immune to announce timing and tightens what it actually asserts.

2. Put announce admission on scheduler time (deeper). shouldSend(force:now:) already takes now as a parameter; only the call sites hardcode Date(). Threading an injectable date provider through performMaintenance / sendAnnounceNow — defaulting to Date.init — would close the last wall-clock leak in an otherwise deterministic harness and retire the _test_resetAnnounceThrottle workaround.

Option 1 unblocks the PR queue immediately. Option 2 is the real fix.

Activity

2
ecgang2mo ago

Correction to the analysis above — the mechanism I named was wrong.

I attributed the extra frames to maintenance announces. That is impossible in this harness: startMaintenanceTimer guards on meshBackgroundEnabled, which SimulatedMesh disables by constructing every node with initializeBluetoothManagers: false, so performMaintenance() never runs. It is also a 5.0s DispatchSource on bleQueue, which advanceTime could not drive regardless. My "exactly four extra frames" arithmetic was wrong too — I fitted it to 16 - 12 using the budget as if it were the measurement.

What the measurement actually shows. Burning 0.2s of wall clock mid-test, changing nothing else:

packet typefaststarved
announce2430
message44
noiseHandshake1616
noiseEncrypted1616
prekeyBundle1212
post-baseline delta1016

So the passing delta is 10, not 12, and the gap is six announce frames. Every other packet type is identical.

The part that survives, because it was measured rather than reasoned: announce admission is gated on wall clock at BLEService.swift:2760 — announceThrottle.shouldSend(force:now: Date()) — while the harness controls only scheduler time, and the forced-announce window is 0.15s. That is enough to make the total frame count environment-dependent, which is why this fails on PRs with no transport code in them.

I have not isolated which scheduled announce path emits under starvation, and I am not going to guess a third time. The admission gate is common to all of them.

#1622 is updated to match; its diff is unchanged, since message stays at 4 under exactly the perturbation that moves the total.

peppywolfym-lab1mo ago

.