Repository navigation
test: replace sleeps and fixed-window negative assertions with deterministic synchronization - #1592
Conversation
…00ms sleep TestClient_ConcurrentCallersShareOneBuild relied on a resolver that slept 100ms so the 20 racing callers would overlap the build. It now parks the resolver on a gate channel inside a synctest bubble: synctest.Wait proves every caller is blocked (one in the resolver, the rest on the build slot) before the test checks that only one build started, then opens the gate and checks the waiters reused the cached client. Removing the semaphore or the re-check after acquire fails it 50 out of 50 runs. The frontend index test waited 10ms for an init call the DOMContentLoaded listener makes synchronously; it now asserts directly. The no-wallclock- sleeps guard missed that form (assertions inside a setTimeout block that then resolves), so it now flags it too. Closes LeanerCloud#36 Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
|
Caution Review failedThe pull request is closed. Finishing Touches
Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out. Comment |
|
Independent review (IAmJSD's agent, fresh context, given only the diff, the issue and the PR text): VERDICT: APPROVE Blocking:
Non-blocking:
Attacked:
Body-stale:
Reviewer: rQ1. Bar while the maintainers are away (set by IAmJSD as acting owner): one approving independent review on the head, two for money, auth and security paths. |
…ree race tests The claim, direct-finalize and purchase-history race tests proved "the contender waits on the uncommitted holder" by checking that it had not returned after 300-500ms. A contender that never contends but is slow to run (a loaded runner) passed that window and then answered after the holder committed. Verified: a claim that sleeps 400ms and answers from a read passes the old test and fails the new one; the same holds for the finalize and the history save. testhelpers.AwaitBlockedBy now polls pg_locks until a backend waits on a lock the holder's session holds (pg_blocking_pids), and fails at once if the contender returns first. testhelpers.AwaitArrivalsOrLockWaits and LockWaiters back the race barriers converted next. Refs LeanerCloud#36 Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
…and submit race tests TestRetry_TrancheLockBlocksReconciler and TestLadderReconcile_TailLockBlocksRealRetryLink proved "the other side waits on the held row" by checking it had not returned after 1.5s. They now record the paused transaction's backend and wait until a backend is blocked by it (testhelpers.AwaitBlockedBy), failing at once if the other side returns first. Dropping FOR UPDATE from LockLadderTrancheForRetryTx or from the chain lock fails the matching test. insertBarrierStore opened its barrier after a fixed 300ms/1s wait, so on a slow runner an unguarded second submit could miss it and see the first one's committed row. It now opens once both submits arrived or the missing one is observed parked on the per-creator advisory lock. Dropping that lock fails both tests that use the barrier. Refs LeanerCloud#36 Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
… waits TestPlanProviderLock_AttachedNeverExceedsShown and TestAttachIntegration_PlansOnOneAccountNeverOverAttach held each tick at a barrier that gave up after 500ms. On a slow runner an unlocked tick could miss the barrier and see the first tick's committed suppression, hiding the over-commit the tests (and the lock-free control) depend on. The barrier now opens once every tick has resolved or is observed waiting on the per-provider advisory lock. A no-op LockPlanProvidersTx fails the attach test (12 attached against 10 shown). The locked runs no longer spend 500ms per waiting tick. Refs LeanerCloud#36 Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
…t windows Four unit tests asserted that something did NOT happen by waiting a fixed time (200ms to 2s) and seeing nothing. A goroutine a loaded runner had not yet scheduled passed that window. - scheduler: the stale-hours-0 refresh check, the auth no-booking check on ValidateUserAPIKey and the server exactly-once usage booking checks now run in a synctest bubble. synctest.Wait returns only once every goroutine the call started has finished or is durably blocked, so a non-blocking receive afterwards is exact. Ignoring the disable sentinel, or booking usage on the validation path, fails every run (50/50). - server: the reinit cleanup-worker test replaced assert.Never(300ms) after canceling the request ctx with the positive half: Close must stop the worker while the request ctx is still live. Starting the worker with the request ctx (the LeanerCloud#1137 call-site bug) fails it 10/10. The three usage-booking tests and the no-booking check drop from about 2s each to near zero. Closes LeanerCloud#36 Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
|
Independent review (IAmJSD's agent, fresh context, given only the diff, the issue and the PR text): VERDICT: APPROVE Blocking:
Non-blocking:
Attacked:
Body-stale:
Reviewer: rR1. Bar while the maintainers are away (set by IAmJSD as acting owner): one approving independent review on the head, two for money, auth and security paths. |
|
Independent review (IAmJSD's agent, fresh context, given only the diff, the issue and the PR text): VERDICT: APPROVE Blocking:
Non-blocking:
Attacked:
Body-stale:
Reviewer: rR2. Bar while the maintainers are away (set by IAmJSD as acting owner): one approving independent review on the head, two for money, auth and security paths. |
|
Local verification at |
|
Merged by IAmJSD's agent at IAmJSD's request (IAmJSD is acting owner while the maintainers are away), under the bar IAmJSD set: 2 approving independent review(s) on |
Summary
Finishes #36. #1298, #1568 and #1569 removed most of the wall-clock sleeps. This PR handles what was left:
internal/archera/provider_cancel_test.go(named in the issue's last status update) is replaced by a gate channel.assert.Never, and 8 real-Postgres integration windows/barriers of 300ms to 1.5s.time.Afterand timer wait in the Go tests is listed below with the reason it stays.Root cause (archera)
TestClient_ConcurrentCallersShareOneBuildused aslowResolverthat slept 100ms so the 20 racing callers would overlap the in-flight build. The test got its overlap from timing: on a slow runner a late caller could arrive after the build finished, take the cached-client fast path, and never test the serialization. It also spent 100ms on every run.Fix (archera and frontend)
internal/archera/provider_cancel_test.go: the resolver is now agatedResolverthat parks on areleasechannel. The test runs in atesting/synctestbubble.synctest.Wait()returns only when every caller is durably blocked: one inside the resolver and 19 on the build semaphore, both on channels created inside the bubble. The test then:acquire).A deferred
openGate(); wg.Wait()drains the callers when an assertion fails, so a failure shows up as a test failure and not as a synctest "blocked goroutines remain" panic that would kill the whole package binary.frontend/src/__tests__/index.test.ts:calls init on DOMContentLoadedwaited 10ms (new Promise(resolve => setTimeout(() => { expect(...); resolve(); }, 10))) for aninit()that the listener calls synchronously (document.addEventListener('DOMContentLoaded', () => void init())). It now asserts directly, like the next test in the file.frontend/src/__tests__/no-wallclock-sleeps.test.ts: the test(frontend): wait for async handlers instead of sleeping in unit tests #1569 guard only matchedsetTimeout(r, N)andsetTimeout(() => r(), N), so it missed the form above, where the assertions sit inside a timer block. A second pattern (SLEEP_BLOCK) now flags that form with a non-zero delay. Two matcher samples cover it: the 10ms form is flagged and the 0ms flush is allowed.No production code changed. No frontend source changed (only files under
frontend/src/__tests__/). The only non-test Go change is the shared test helperinternal/database/postgres/testhelpers/lockwait.go.Fixed-window negative assertions (the issue's main Go concern)
The pattern was
select { case <-done: t.Fatal(...); case <-time.After(N): }, anassert.Never, or a race barrier that gave up after N ms. Each one cannot tell "the event will never happen" from "the event has not happened yet", so a slow runner turns a real regression into a pass. Each site now waits on an observed state that proves the event can no longer happen, and keeps a timeout only as a failure deadline.New helpers in
internal/database/postgres/testhelpers/lockwait.go, next to the existingWaitForLockWait/Await:BackendPID(ctx, t, tx)returns the holder transaction's backend PID.AwaitBlockedBy(ctx, t, db, holderPID, done)pollspg_locksuntil some backend waits on a lock the holder holds (holderPID = ANY(pg_blocking_pids(pid))). It returns(v, true)at once if the contender returns first, and fails after 30s if neither happens. Once the contender is observed blocked by the holder, it provably cannot finish before the holder ends.LockWaitersandAwaitArrivalsOrLockWaits(ctx, db, parties, arrived, queryLike)form a race-test barrier. It opens once every party has either arrived or is observed waiting on a lock in a matching statement, never on a timeout. It readsarrived()before the lock query, so a party that moves between the two reads is missed for a round rather than counted twice.origin/main)internal/scheduler/scheduler_test.go:1006StaleHoursZeroDisablesBackgroundRefreshsynctestbubble.synctest.Wait()returns only once any refresh goroutine the call started has finished or is durably blocked, so a non-blocking receive afterwards is exact.finishCacheRead: 50/50 FAILinternal/auth/service_apikeys_test.go:719ValidateUserAPIKey/successfully validatesynctestpattern; the case body moved intovalidateBooksNoUsageso it runs inside the bubble.s.RecordUsageAsync(key.ID)added toValidateUserAPIKey: 50/50 FAILinternal/server/apikey_usage_booking_test.go:176(3 tests viarequireExactlyOneBooking)synctest.Wait(), every flush has reached the store, so the test drains the channel and requires exactly[1].flushes wrote [3])internal/server/app_rl_cleanup_test.go:104CleanupWorkerOutlivesRequestCtxassert.Never300msClosemust stop the worker while the request ctx is still live (then assertsreqCtx.Err() == nil).dbRL.StartCleanupWorker(ctx)instead ofapp.startRateLimiterCleanup(dbRL)): 10/10 FAILinternal/config/store_postgres_db_test.go:1499claim races an uncommitted claimAwaitBlockedByon the holder transaction.internal/config/store_postgres_ri_exchange_direct_db_test.go:160finalize races an uncommitted finalizeAwaitBlockedByinternal/config/store_postgres_history_dedupe_integration_test.go:111save races an uncommitted twinAwaitBlockedByinternal/api/handler_purchases_retry_ladder_integration_test.go:137TrancheLockBlocksReconcilerAwaitBlockedBy.FOR UPDATEdropped fromLockLadderTrancheForRetryTx: FAIL (reconciler finished while Retry held the tranche row)internal/api/handler_ladder_reconcile_retry_integration_test.go:139TailLockBlocksRealRetryLinkFOR UPDATEdropped from the chain locks: FAIL (retry linked while the reconciler held the tail row)internal/api/handler_purchases_submit_dedupe_integration_test.go:36-41insertBarrierStore(used byConcurrentIdenticalSubmitsCreateOneRowandRetrySuccessorRacesFreshSubmit/forced)AwaitArrivalsOrLockWaitson the per-creatorpg_advisory_xact_lock; thewaitfield is removed.ListRecentSubmitsTxreplaced bySELECT 1: both tests FAIL (2 rows / 2 pending rows)internal/purchase/plan_provider_lock_integration_test.go:56AttachedNeverExceedsShownAwaitArrivalsOrLockWaitson the provider advisory lock (runProviderTicksnow takes the pool).-race)internal/purchase/plan_step_attach_integration_test.go:193PlansOnOneAccountNeverOverAttachLockPlanProvidersTxmade a no-op: FAIL (12 attached against 10 shown)The slow-runner probes are the direct demonstration of the old false pass: each makes the contender non-contending and slower than the old window, the old test passes, and the new test fails. A side benefit: the locked runs no longer spend the full window on every waiting party (the attach race went from about 1.5s of barrier waits to 0.3s total), and the usage-booking and validate tests went from about 2s each to near zero.
The
synctestconversions needtesting/synctest(Go 1.25+;go.modis 1.26.10), the same package the archera change uses.Closes #36
Remaining sleeps, and why each stays
Re-grepped on this branch after merging
origin/main(d71af683):grep -rn --include=*_test.go 'time\.Sleep': 23 code hits, plus comments saying "no time.Sleep".time.After(,time.NewTimer(andtime.Tick(in*_test.go(about 80). An awk pass flagged each timeoutcasewhose body does not fail the test; after this PR it flags only the two sites justified under "Remainingtime.Afterand timer waits".assert.Never/Consistently: none left.lock_timeout/statement_timeoutand shortcontext.WithTimeoutdeadlines in tests.For the frontend I grepped every
setTimeout/waitForTimeoutunderfrontend/srcandfrontend/tests-e2e, leaving out the zero-delay flushes.Go: deadline-bounded poll loops (poll for a condition, fail at a deadline)
tests/e2e/e2e_test.go:60/healthreports healthy (2s poll interval against a deployed app)internal/server/http_shutdown_test.go:84internal/server/http_scheduled_context_test.go:173internal/server/scheduledauth/kidguard_test.go:216internal/purchase/plan_step_fail_atomic_integration_test.go:151pg_stat_activityshows the approval waiting on the row lockinternal/auth/store_postgres_admin_lock_db_test.go:94pg_locksshows a backend queued on the advisory lockinternal/config/store_postgres_token_pin_cancel_db_test.go:131pg_stat_activityshows a backend waiting on a row lockinternal/config/store_postgres_ri_exchange_approved_reservation_integration_test.go:158internal/testutil/testutil.go:149(WaitFor, non-test file)Each loop exits as soon as the observed state appears. The sleep is only the poll interval, so a slow runner makes the loop take longer instead of making the test fail.
Go: deliberate race staggers (the stagger is the input that varies interleavings)
internal/api/ladder_resolve_race_integration_test.go:113,117internal/api/handler_purchases_retry_submit_race_integration_test.go:55,61internal/purchase/plan_step_fail_atomic_integration_test.go:247internal/purchase/token_rotation_pin_integration_test.go:152,158internal/config/store_postgres_token_pin_cancel_db_test.go:215,221internal/database/postgres/migrations/000139_..._test.go:350None of these sleeps waits for work to finish. Each start is coordinated by a
startgate channel or aWaitGroup, and the sleep only spreads out the start times.Go: database-clock aging (the DB's
NOW()must move forward; a Go fake clock cannot do this)internal/database/advisory_lock_holder_integration_test.go:94(1.2s)internal/config/store_postgres_no_submission_integration_test.go:72(1.1s)updated_atis set by a trigger, so the row has to age pastListStuckExecutions's 1s floorinternal/config/store_postgres_service_config_stamps_integration_test.go:52(5ms)NOW()is the transaction start, so the second save needs a later transaction to get a later stampinternal/config/store_postgres_revocation_return_integration_test.go:107(5ms)return_posted_atstamp is keptGo: simulated slow work against a real
net/httptimeoutinternal/server/http_scheduled_context_test.go:96: the mock handler takes 400ms, longer than the server'sWriteTimeout, which the test shortens to 100ms. The test checks that the per-route write deadline lets the response through.net/httpenforcesWriteTimeoutagainst the real clock, so the handler really has to take longer than the timeout.Go: remaining
time.Afterand timer waitst.Fatal, and a passing run returns as soon as the event arrives): every othercase <-time.After(...)in the Go tests, for exampleinternal/execution/fanout_test.go:157,internal/api/handler_history_test.go:467and the 2-5s waits throughout the suites.internal/purchase/execution_test.go:1276: a parallelism barrier whose timeout setsbarrierTimedOut, which the test then asserts is false. The timeout only bounds the failure path.internal/api/handler_purchases_revoke_claim_integration_test.go:79: inside the fake Azure Return client, waiting up to 10s for the other request to finish so the two interleave. If the timeout path is taken, the final assertions fail (one revoked, one in flight, exactly one Return), so it cannot hide a regression.internal/config/store_postgres_ri_exchange_reservation_integration_test.go:143: the 10ms poll interval of a deadline-boundedpg_stat_activitypoll that also fails at once if the reservation returns early. This is the same shape asAwaitBlockedBy.internal/purchase/execute_detached_test.go:109(callTime1.2s): simulated provider-call duration measured against the real save budget. The time is the input.internal/email/smtp_server_test.go:714(a real stalled SMTP socket),internal/database/postgres/migrations/migrate_cancel_test.go:68(a server that never finishes the handshake),internal/archera/provider_cancel_test.go:45, andinternal/api/handler_insurance_comparison_test.go:356,415(the resolver or vendor call blocks until the ctx ends, so ordering is guaranteed). Each asserts the code returns because of the deadline, with a failure-only outer timeout.lock_timeoutininternal/auth/store_postgres_admin_lock_db_test.go:272andinternal/config/store_postgres_ladder_lock_integration_test.go:197: production lock timeouts under test (the expected55P03, or a hang fails fast). These are not quiet windows.Frontend
setTimeoutlines are zero-delay flushes (flushPromisesand localflushhelpers),jest.spyOn(global, 'setTimeout')assertions (archera-comparison,auth-mfa-login,history-deeplink), fake-timer tests, or comments.frontend/tests-e2e/fixtures/recs.ts:304: a one-shot response delay that a spec can set to simulate a slow backend (the loading state under test). It is the input, not a wait.frontend/tests-e2e/ri-exchange-confirmation.spec.ts:224,309(page.waitForTimeout(2200/2500)): these are negative assertions. Before fix(frontend): announce RI exchange results and keep the exchange ID #1375 the exchange modal closed itself after 2s. These waits prove it now stays open past that window, so the test has to let the time pass. Playwright'spage.clockcould fast-forward instead; I did not change it because these specs cannot be run on this VM (see below), and TEST-04: Wall-clock sleeps for async synchronization (~90 frontend setTimeout waits, several Go sleeps) #36 covers unit tests.Verification
Unit-level evidence (Go unit tests, jest with jsdom) for the archera and frontend changes. Real-Postgres integration evidence (testcontainers, Docker on this VM) for the converted race tests, run narrowly by name.
Runtime of the test itself: 0.10s before (the sleep), 0.00s after.
Mutation probes. Each was applied to
internal/archera/provider.golocally, run, and reverted; none is committed:-count=50)release := func() {}instead ofp.acquire(ctx))only one caller may build while the others wait(expected 1, actual 20)p.client.Load()re-check afteracquirewaiters reuse the built client instead of rebuilding(expected 1, actual 20)Mutation A first panicked with
deadlock: main bubble goroutine has exited but blocked goroutines remainand took the package binary down (1 of 50 reported). The deferred drain fixes that, so both mutations now fail cleanly on every run.Fixed-window conversions (after merging
origin/maind71af683; final head is this PR's head):The integration
-race -count=20runs were made on the pre-merge headb655a563. The merge touched none of these files, and the merged tree builds and vets with-tags integration. Mutation and slow-runner evidence is in the table above. All probes were applied locally, run, and reverted; none is committed.Frontend (jest, with
npm ciinfrontend/):index.test.tsrestored fromorigin/main, the guard fails with"index.test.ts:121 sleeps 10ms". It passes on this branch.DOMContentLoaded -> init()listener insrc/index.tscommented out locally (reverted, not committed),calls init on DOMContentLoadedfails.Combined-tree verification (earlier head
2d229863, the archera and frontend commit only). Tested on a local, never-pushed tree:queue/platform@594ac3ec= origin/mainae6854b3plus:Linux, Go 1.26.9,
AWS_CONFIG_FILE=/dev/null AWS_SHARED_CREDENTIALS_FILE=/dev/null AWS_EC2_METADATA_DISABLED=true; Docker Postgres via testcontainers.go build ./...,go vet ./...,go vet -tags integration ./...and the fullgo test -race -short -count=1 ./....--build-tags integration.gocyclo -over 10is silent on the changed non-test files.-tags integration -count=1, one package at a time):internal/api,internal/auth,internal/config,internal/scheduler,internal/serverandinternal/testutilpass.scripts/test-git-secrets-allowlist.shpasses.Combined-tree verification (head 7fc2b00). Tested on a local, never-pushed tree:
queue/platform@e0b2dcd0= origin/mainfd45080fplusfix/issue-36-archera-gate@7fc2b006.Linux, Go 1.26.9,
AWS_CONFIG_FILE=/dev/null AWS_SHARED_CREDENTIALS_FILE=/dev/null AWS_EC2_METADATA_DISABLED=true; Docker Postgres via testcontainers.go build ./...,go vet ./...,go vet -tags integration ./...and the fullgo test -race -short -count=1 ./....--build-tags integration.gocyclo -over 10is silent on the changed non-test files.-tags integration -count=1, one package at a time):internal/api,internal/auth,internal/config,internal/database/postgres/testhelpers,internal/purchase,internal/schedulerandinternal/serverpass.scripts/test-git-secrets-allowlist.shpasses.Out of scope / not done
waitForTimeoutnegative assertions inri-exchange-confirmation.spec.tscould move topage.clockin a follow-up if wanted.internal/testutil.WaitForpolls every 100ms, which is coarse. It is a correct deadline-bounded poll, so I left it alone.internal/server/app_rl_cleanup_test.gono longer checks behaviorally that canceling the request ctx leaves the worker running; no deterministic signal exists for "a goroutine would have exited". The two failure modes are covered instead: the call-site regression is caught by the Close ordering, andstartRateLimiterCleanuptakes no ctx (pinned byTestStartRateLimiterCleanup_SurvivesRequestCtxAndStopsOnClose).Maintainers: please mirror the issue's triage labels onto this PR:
impact/internal,type/chore,triaged,priority/p3,severity/low,urgency/eventually,effort/m.🤖 Generated with Claude Code