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 <martin.vogel.tech@gmail.com>
This commit is contained in:
Martin Vogel committed 2026-09-04 15:42:15 +02:00
1 parent ffb5ebe9e8
commit 7e47043acc
3 files changed
+37 -21

No files matched your search

+12
View File
@@ -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(&registry->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(&registry->test_condition_wait_calls, 0, memory_order_relaxed);
atomic_store_explicit(&registry->test_waiter_enqueue_calls, 0, memory_order_relaxed);
atomic_store_explicit(&registry->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(&registry->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(&registry->test_condition_waiters_now, memory_order_relaxed)
+1
View File
@@ -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,
+24 -21
View File
@@ -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);