From 7e47043acce9bdfd87e7becc7fe7a348b02753ec Mon Sep 17 00:00:00 2001 From: Martin Vogel Date: Fri, 4 Sep 2026 01:30:53 +0200 Subject: [PATCH] fix(tests): make the lock-registry absolute-deadline fixture deterministic lock_registry_absolute_deadline_survives_repeated_wakes has failed on the test-unix (macos-15-intel) leg of three unrelated pull requests in one week -- #1342 (08-28), #1811 (09-02) and #1819 (09-03, run 33799475629, job 100823626965) -- always with the same signature: FAIL tests/test_lock_registry.c:1153: ASSERT(tail_queued) 7648 passed / 1 failed The registry is not racy. cbm_lock_registry_acquire enqueues the waiter synchronously under the registry mutex before any wait, so waiter_count and the attempting count are exact. The defect is in the fixture: it raced two wall-clock windows against each other, both anchored to a timestamp the observer thread took before the tail thread had even been scheduled. deadline_start = cbm_now_ms(); tail.deadline_ms = deadline_start + 200; /* the tail's acquire deadline */ queue_deadline = deadline_start + 100; /* the observer's budget */ Because both windows start before the tail runs, a loaded runner breaks the fixture two different ways: * the tail is scheduled inside its deadline but after the observer's 100 ms budget has expired -- the queued state existed and was simply no longer being looked at; or * the tail is scheduled more than 200 ms late, in which case its deadline has already passed when it finally calls acquire, the pre-registration deadline check in lock_registry_acquire_internal returns BUSY immediately, and the tail never enqueues at all -- the asserted state can then never occur, however long the observer waits. lock_registry is in the parallel wave of run-tests-parallel.sh, not the serial tail, so on a small CI runner it competes with a full wave of sanitized suites -- exactly the scheduling delay both paths need. Widening the observer's budget would only paper over the first path, and the state it waits for is transient by construction: it exists only between the tail's enqueue and the tail's own deadline. So the fixture is rebuilt to observe states that cannot evaporate. * The tail anchors its absolute deadline itself, in its own thread, immediately before the acquire it bounds. Scheduling delay can no longer consume the deadline before the call starts, so the enqueue is unconditional, and elapsed is measured from the tail's own anchor -- it now times the registry instead of timing the scheduler. * Enqueue is exposed as a monotonic counter, cbm_lock_registry_waiter_enqueue_count_for_test, next to the existing test_condition_wait_calls counter it is modelled on. Because the count only ever grows, the observer reads it once after the tail has returned rather than trying to catch a live queue depth: the polling loop, and with it the window, is gone. * The fixture's remaining 500 ms and 600 ms budgets become the file's LOCK_REGISTRY_TEST_TIMEOUT_MS backstop, and each loop exits on the state it waits for instead of on the clock, so the backstop only fires when the product is actually broken. The contract is unchanged: the tail must still return at its absolute deadline (150 <= elapsed < 350 ms for a 200 ms deadline) despite ~40 unrelated cancel broadcasts, still with BUSY and no lease, with the head still holding the attempt. The broadcast loop now starts immediately after the tail is released, so it overlaps the tail's wait at least as much as it did before. Verification, all on macOS arm64 with the sanitized runner: * The mechanism was reproduced locally by delaying only the tail thread after its start gate, with production untouched. A 120 ms delay (the state exists, outside the observer's budget) and a 250 ms delay (the tail never enqueues) each produced exactly one failure, ASSERT(tail_queued) -- the CI signature. * After the rebuild the same injections are green at 120, 250, 400 and 900 ms: an arbitrary scheduling delay no longer decides the verdict. * lock_registry 30/30 green plain and 30/30 green under four CPU hogs; 16/16 inside the saturated 18-job parallel wave. * private_file_lock, lock_registry, daemon, project_lock and the daemon_* suites: 222 passed, 1 skipped. Signed-off-by: Martin Vogel --- src/foundation/lock_registry.c | 12 +++++++ src/foundation/lock_registry_internal.h | 1 + tests/test_lock_registry.c | 45 +++++++++++++------------ 3 files changed, 37 insertions(+), 21 deletions(-) diff --git a/src/foundation/lock_registry.c b/src/foundation/lock_registry.c index 11439a0d2..4e128e102 100644 --- a/src/foundation/lock_registry.c +++ b/src/foundation/lock_registry.c @@ -66,6 +66,7 @@ struct cbm_lock_registry { cbm_lock_registry_abort_failure_t test_abort_failure; bool test_abort_failure_armed; atomic_uint_fast64_t test_condition_wait_calls; + atomic_uint_fast64_t test_waiter_enqueue_calls; atomic_size_t test_condition_waiters_now; struct cbm_lock_registry *next_live; struct cbm_lock_registry *next_retired; @@ -228,6 +229,7 @@ static void lock_registry_waiter_push(cbm_lock_registry_t *registry, lock_regist } entry->waiter_tail = waiter; registry->waiter_count++; + (void)atomic_fetch_add_explicit(®istry->test_waiter_enqueue_calls, 1, memory_order_relaxed); } static bool lock_registry_waiter_remove(cbm_lock_registry_t *registry, lock_registry_entry_t *entry, @@ -914,6 +916,7 @@ cbm_private_file_lock_status_t cbm_lock_registry_free(cbm_lock_registry_t **regi registry->test_abort_failure = 0; registry->test_abort_failure_armed = false; atomic_store_explicit(®istry->test_condition_wait_calls, 0, memory_order_relaxed); + atomic_store_explicit(®istry->test_waiter_enqueue_calls, 0, memory_order_relaxed); atomic_store_explicit(®istry->test_condition_waiters_now, 0, memory_order_relaxed); registry->next_retired = lock_registry_retired; lock_registry_retired = registry; @@ -987,6 +990,15 @@ uint64_t cbm_lock_registry_condition_wait_call_count_for_test(const cbm_lock_reg : 0; } +/* Enqueue is monotonic, so a test can observe that a waiter joined the queue + * after the fact instead of catching a queue depth that the waiter's own + * deadline erases again. */ +uint64_t cbm_lock_registry_waiter_enqueue_count_for_test(const cbm_lock_registry_t *registry) { + return registry + ? atomic_load_explicit(®istry->test_waiter_enqueue_calls, memory_order_relaxed) + : 0; +} + size_t cbm_lock_registry_condition_waiter_count_for_test(const cbm_lock_registry_t *registry) { return registry ? atomic_load_explicit(®istry->test_condition_waiters_now, memory_order_relaxed) diff --git a/src/foundation/lock_registry_internal.h b/src/foundation/lock_registry_internal.h index 0b35712d0..0ec856c01 100644 --- a/src/foundation/lock_registry_internal.h +++ b/src/foundation/lock_registry_internal.h @@ -25,6 +25,7 @@ bool cbm_lock_registry_is_retired_for_test(const cbm_lock_registry_t *registry); size_t cbm_lock_registry_attempting_waiter_count_for_test(cbm_lock_registry_t *registry); uint64_t cbm_lock_registry_condition_wait_call_count_for_test(const cbm_lock_registry_t *registry); size_t cbm_lock_registry_condition_waiter_count_for_test(const cbm_lock_registry_t *registry); +uint64_t cbm_lock_registry_waiter_enqueue_count_for_test(const cbm_lock_registry_t *registry); typedef enum { CBM_LOCK_REGISTRY_RELEASE_RW = 1, diff --git a/tests/test_lock_registry.c b/tests/test_lock_registry.c index c1f823696..0ae21d61d 100644 --- a/tests/test_lock_registry.c +++ b/tests/test_lock_registry.c @@ -33,6 +33,7 @@ enum { LOCK_REGISTRY_STRESS_THREADS = 8, LOCK_REGISTRY_STRESS_ITERATIONS = 160, LOCK_REGISTRY_PARKING_WAITERS = 64, + LOCK_REGISTRY_DEADLINE_WAIT_MS = 200, }; typedef struct { @@ -1020,7 +1021,8 @@ typedef struct { atomic_bool ready; atomic_bool go; atomic_bool finished; - uint64_t deadline_ms; + uint64_t wait_ms; + uint64_t started_ms; uint64_t returned_ms; cbm_private_file_lock_status_t status; cbm_lock_lease_t *lease; @@ -1033,9 +1035,14 @@ static void *lock_registry_deadline_waiter_run(void *opaque) { while (!atomic_load_explicit(&waiter->go, memory_order_acquire)) { lock_registry_test_yield(); } - waiter->status = - cbm_lock_registry_acquire(waiter->registry, "absolute-deadline", CBM_PRIVATE_FILE_LOCK_EX, - waiter->deadline_ms, &waiter->cancel_token, &waiter->lease); + /* The absolute deadline is anchored here, in the thread it bounds, right + * before the call it bounds. An anchor taken by the observer is already + * running while this thread is still waiting to be scheduled, so on a + * loaded host it can expire before the acquire even starts. */ + waiter->started_ms = cbm_now_ms(); + waiter->status = cbm_lock_registry_acquire( + waiter->registry, "absolute-deadline", CBM_PRIVATE_FILE_LOCK_EX, + waiter->started_ms + waiter->wait_ms, &waiter->cancel_token, &waiter->lease); waiter->returned_ms = cbm_now_ms(); atomic_store_explicit(&waiter->finished, true, memory_order_release); return NULL; @@ -1066,7 +1073,7 @@ TEST(lock_registry_absolute_deadline_survives_repeated_wakes) { bool head_started = holder_status == CBM_PRIVATE_FILE_LOCK_OK && cbm_thread_create(&head_thread, 0, lock_registry_waiter_run, &head) == 0; bool head_attempting = false; - uint64_t head_deadline = cbm_now_ms() + 500; + uint64_t head_deadline = cbm_now_ms() + LOCK_REGISTRY_TEST_TIMEOUT_MS; while (head_started && cbm_now_ms() < head_deadline) { head_attempting = cbm_lock_registry_waiter_count(fixture.registry) == 1 && cbm_lock_registry_attempting_waiter_count_for_test(fixture.registry) == 1; @@ -1077,6 +1084,7 @@ TEST(lock_registry_absolute_deadline_survives_repeated_wakes) { } lock_registry_deadline_waiter_t tail = {.registry = fixture.registry, + .wait_ms = LOCK_REGISTRY_DEADLINE_WAIT_MS, .status = CBM_PRIVATE_FILE_LOCK_IO}; atomic_init(&tail.cancel_token, false); atomic_init(&tail.ready, false); @@ -1086,31 +1094,20 @@ TEST(lock_registry_absolute_deadline_survives_repeated_wakes) { bool tail_started = head_attempting && cbm_thread_create(&tail_thread, 0, lock_registry_deadline_waiter_run, &tail) == 0; - uint64_t ready_deadline = cbm_now_ms() + 500; + uint64_t ready_deadline = cbm_now_ms() + LOCK_REGISTRY_TEST_TIMEOUT_MS; while (tail_started && !atomic_load_explicit(&tail.ready, memory_order_acquire) && cbm_now_ms() < ready_deadline) { lock_registry_test_yield(); } bool tail_ready = tail_started && atomic_load_explicit(&tail.ready, memory_order_acquire); - uint64_t deadline_start = cbm_now_ms(); - tail.deadline_ms = deadline_start + 200; + uint64_t enqueues_before_tail = + cbm_lock_registry_waiter_enqueue_count_for_test(fixture.registry); atomic_store_explicit(&tail.go, true, memory_order_release); - bool tail_queued = false; - uint64_t queue_deadline = deadline_start + 100; - while (tail_ready && cbm_now_ms() < queue_deadline) { - tail_queued = cbm_lock_registry_waiter_count(fixture.registry) == 2 && - cbm_lock_registry_attempting_waiter_count_for_test(fixture.registry) == 1; - if (tail_queued) { - break; - } - lock_registry_test_yield(); - } - cbm_lock_cancel_token_t unrelated_token; atomic_init(&unrelated_token, false); bool broadcasts_ok = true; - uint64_t observe_deadline = deadline_start + 600; + uint64_t observe_deadline = cbm_now_ms() + LOCK_REGISTRY_TEST_TIMEOUT_MS; while (tail_ready && !atomic_load_explicit(&tail.finished, memory_order_acquire) && cbm_now_ms() < observe_deadline) { broadcasts_ok = cbm_lock_registry_request_cancel(fixture.registry, &unrelated_token) == @@ -1120,7 +1117,13 @@ TEST(lock_registry_absolute_deadline_survives_repeated_wakes) { } bool returned_at_deadline = tail_ready && atomic_load_explicit(&tail.finished, memory_order_acquire); - uint64_t elapsed_ms = returned_at_deadline ? tail.returned_ms - deadline_start : UINT64_MAX; + /* The enqueue count only ever grows, so this stays true once the tail has + * joined the queue behind the attempting head. Reading it after the tail + * has returned removes the window the observer used to have to catch. */ + uint64_t enqueues_after_tail = + cbm_lock_registry_waiter_enqueue_count_for_test(fixture.registry); + bool tail_queued = returned_at_deadline && enqueues_after_tail > enqueues_before_tail; + uint64_t elapsed_ms = returned_at_deadline ? tail.returned_ms - tail.started_ms : UINT64_MAX; if (!returned_at_deadline && tail_started) { (void)cbm_lock_registry_request_cancel(fixture.registry, &tail.cancel_token);