Repository navigation
test: sequence the timing-sensitive tests on events, not wall-clock sleeps - #56
Merged
Merged
Conversation
The keyring tests paced themselves with real sleeps (2-30 ms) against a Keyring running real mint timeouts (mintTimeoutMs 15-20), Date.now() for the late-mint TTL, and async disk persistence. On a starved CI runner a reply was pushed before the keyring had sent the frame it answers (the old key's delete only goes out after the new entry is flushed to disk, so "push mint, sleep 10-20 ms, push delete reply" hung until bun's 5 s timeout), or the 2x-mint-timeout TTL expired between the client-side timeout and the late reply, so a late mint for a kicked user was neither attributed nor deleted. Every test in keyring.test.ts and keyring.names.test.ts now runs on a ManualClock (setTimeoutFn/clearTimeoutFn/now): no request timeout fires unless the test calls clock.fire(), and the late-mint TTL never elapses on its own. Each reply is pushed only after FakeControl.waitForSent(n) has seen the frame it answers; adoption is awaited on the entry itself; persistence on drainWrites(). The waits yield to the event loop and fail with a message naming what they waited for (and the frames sent so far) after 3 s instead of hanging. The serialization test settles a few event-loop turns before asserting the queued mint has not gone out. Keyring gains an optional `now` option (defaults to Date.now) so the late-mint TTL clock can be injected; production behaviour is unchanged. Under full CPU contention: before 2/80 runs failed, after 0/200.
…ents Races: the LinkPool and IrohClient reconnect tests ran real 5-20 ms backoff and idle timers and then slept a fixed 20-60 ms (`settle(20)`, `settle(60) // let the redial land`) before asserting connect counts, statuses or the re-sent join; a late timer meant the redial had not happened yet, or a parked redial was not parked when `open()` raced it. The router tests slept 40 ms for a fire-and-forget settings write (real mkdir/writeFile/chmod) and 20 ms for the `.bridge name` mint frame, which under load were not there yet (1/40 runs failed under full CPU load). Now: a shared `src/testkit.ts` (waitFor / settle / ManualClock, which the keyring testkit re-exports) drives every LinkPool and the reconnect IrohClient tests on a ManualClock. Each step waits for the state it needs (the link to go down, the redial connect to start, the re-join to be sent, the released dial to be discarded) and the backoff or idle deadline elapses only when the test advances the clock; negative checks run the clock out instead of hoping a real timer fired. The router tests await `flushSettingsWrites()` and then the failure log, and wait for the mint frame itself. Microtask-only flushes (`settle(0)` against promise-only mocks) are unchanged. LinkPool gains an optional `now` option (defaults to Date.now) so the idle-close bookkeeping can run on the injected clock; production behaviour is unchanged.
…need Races: the OneBot-not-up test flipped NapCat "up" on a real 2.3 s timer and needed that to land after the bridge's 2 s first-connect timeout; a slow startup on a loaded runner put the flip first, the first connect succeeded and the single "waiting" log line never appeared. The QQ Bot entry tests asserted on logs right after fixed 20-40 ms sleeps (GROUP_ADD_ROBOT / GROUP_DEL_ROBOT / FRIEND_ADD over a real WebSocket), and pushed the "active" narrative 20 ms after GROUP_MSG_RECEIVE without knowing the switch had been processed, so the reply could still go out as a passive one. Now: NapCat comes up when the bridge logs that it is waiting (the event the test is about), not at a wall-clock guess. The entry tests wait for the log lines themselves, and subscribe to the transport after the bridge so that once they see GROUP_MSG_RECEIVE the bridge's own handler has already switched the group active. The coalescer's real 5 s window is no longer slept through: the test waits for the POST it produces, with a deadline of the window plus 8 s. Negative checks are unchanged.
Race: the spinner test slept a real 150 ms and expected exactly one 110 ms tick. A stalled event loop let a second overdue tick run between the test's timer and the frame capture, showing the third glyph. Now: Spinner/useSpinner take an optional `timers` interval pair (the real setInterval/clearInterval by default), and the test injects a manual one: it checks the spinner asked for a 110 ms cadence, fires exactly one tick inside act(), and asserts the glyph stepped once. Bun's global fake timers are not an option here: they stall the OpenTUI test renderer. Production behaviour is unchanged.
Race: the reconnect test slept a real 30 ms and expected the second socket after a 5 ms backoff (up to 20 ms), asserting the exact status sequence; a late timer on a loaded runner left only one socket. Now: WsClient's injectable setTimeoutFn captures the backoff instead of scheduling it; the test checks exactly one backoff was armed, fires it, and flushes the mock socket's microtask open before asserting.
Races: - test_tui_server: after closing the connection that filled the cap=1 slot it slept 50 ms for the server handler's `finally` to release the slot; slower than that, the reconnect got too_many_connections. - test_cli_stdin: a 50 ms asyncio.sleep in a task had to finish before a worker thread's independent 300 ms time.sleep, compared by time.monotonic(); a stalled loop could reverse the order. - test_commands `.model login`: polled the background OAuth task's effect for a fixed 0.5 s (2 s in one test, whose flow sleeps the >= 1 s poll interval between its two polls) while it did SQLite and credential-book writes. Now: the cap test waits until the server's active-connection count is back to zero (bounded at 5 s). The stdin test's fake stdin blocks on a threading.Event that only the background task releases once it has seen the read start; the test asserts the read was released by the task rather than by its own 5 s safety timeout, so a loop-blocking reader still fails. The login tests await the login poll task itself (a 30 s hang guard) and then assert the same effects as before.
…y tests Race: the alias-bomb (0.5 s), forge fast-rejection (1.0 s) and command gate (1.0 s) tests asserted a time.monotonic() upper bound; a GC pause or a CPU-starved CI runner can cross that with no regression at all. The alias-bomb and forge tests are guarded by what they assert besides time (the "alias" YAMLError, the rejection error, the empty install dir); plain yaml.safe_load + str() on this bomb takes ~25 ms, so the bound never discriminated. They now use 10 s. The sheet-assignment linearity tests depend on the bound alone, and the old backtracking regex took ~0.7 s on their 8k-character input, under the 1 s bound on a fast machine. Their input is now 80k characters (the linear scan: ~2 ms; the old quadratic regex: over a minute) with a 5 s bound, which a starved runner cannot trip but the regression cannot pass. The router argument-cap test keeps its reply assertion and uses the same 5 s bound, still below the ~8 s the old regex took there.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
The TS CI job failed three times in two days and passed on rerun each time:
keyring > a role change the server refuses as last_keeper…(5 s timeout)Keyring — names > remint…(5 s timeout, twice)Keyring — names > a late mint for a user kicked meanwhile…(wrong last frame)Cause. These tests paced themselves with real 2–30 ms sleeps against code that has its own real 15–20 ms timeouts, async disk writes and
Date.now()TTLs. On a loaded runner, a reply was pushed before the keyring was waiting for it, so the test hung, or a late-mint TTL expired early. Reproduced locally by running 40 copies at once with every core busy: 2–3 failures per 80 runs.Fix. Make the tests deterministic. No sleep was made longer and no retry was added.
clients/tui/src/testkit.tsandbridge/keyring.testkit.ts.An audit of both repos found the same pattern in other tests, fixed here as well:
router.test: settings write,.bridge namemintlinkPool.test,irohClient.test: reconnect backoffprotocol/client.test: backoffbridge/index.test: NapCat coming onlineqqbot/entry.testSpinner.test: two overdue ticks could pass before the frame was capturedtest_tui_server.py: connection-cap slot releasetest_cli_stdin.py,.model loginpollingTiming-bound tests. The "rejected fast" bounds (alias bomb, forge) go from 0.5–1 s to 10 s. The unsafe version they guard against takes ~25 ms, so the bound never caught anything; the exception and no-file assertions do the work. The
.stlinearity test now uses 80k characters with a 5 s bound. The fixed parser takes ~2 ms; the old backtracking regex takes over a minute.Production code. Only optional injection seams were added; the defaults are the previous behaviour:
Keyring({now})LinkPool({now})Spinner({timers})Verification, with every core busy:
qqbot/entry+bridge/index: 20 runs, 0 failures.Note
Low Risk
Mostly test and helper changes; production edits are optional injection hooks with existing defaults, so runtime behavior is unchanged.
Overview
Replaces wall-clock sleeps in timing-sensitive tests with event-driven waits and manual clocks, so flaky CI on loaded runners stops changing test outcomes.
Test infrastructure: Adds shared
testkit.ts(waitFor,settle,ManualClock) andkeyring.testkit.ts(FakeControl.waitForSent,waitForEntry, keyring-specificManualClock.fire). Keyring, link pool, Iroh/WebSocket reconnect, bridge router, qqbot entry, Spinner, and several Python suites now advance time explicitly or wait for frames sent, entries written, logs, or background tasks instead of fixedsetTimeoutdelays.Small production seams (defaults unchanged): Optional injectable
nowonKeyringandLinkPoolfor late-mint TTL and idle-close bookkeeping; optionaltimersonSpinnerfor interval control in tests.Timing-bound tests: YAML alias-bomb and similar “fast rejection” bounds loosen to ~10s (assertions still catch regressions);
.stpathological-input tests use larger payloads with a 5s bound. Python.model logintests await the poll task; TUI server and stdin tests wait on real conditions rather than fixed delays.Reviewed by Cursor Bugbot for commit 89f15ae. Bugbot is set up for automated code reviews on this repo. Configure here.