Skip to content

Commit 7e47043

Browse files
committed
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>
1 parent ffb5ebe commit 7e47043

3 files changed

Lines changed: 37 additions & 21 deletions

File tree

‎src/foundation/lock_registry.c‎

Lines changed: 12 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -66,6 +66,7 @@ struct cbm_lock_registry {
6666
cbm_lock_registry_abort_failure_t test_abort_failure;
6767
bool test_abort_failure_armed;
6868
atomic_uint_fast64_t test_condition_wait_calls;
69+
atomic_uint_fast64_t test_waiter_enqueue_calls;
6970
atomic_size_t test_condition_waiters_now;
7071
struct cbm_lock_registry *next_live;
7172
struct cbm_lock_registry *next_retired;
@@ -228,6 +229,7 @@ static void lock_registry_waiter_push(cbm_lock_registry_t *registry, lock_regist
228229
}
229230
entry->waiter_tail = waiter;
230231
registry->waiter_count++;
232+
(void)atomic_fetch_add_explicit(&registry->test_waiter_enqueue_calls, 1, memory_order_relaxed);
231233
}
232234

233235
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
914916
registry->test_abort_failure = 0;
915917
registry->test_abort_failure_armed = false;
916918
atomic_store_explicit(&registry->test_condition_wait_calls, 0, memory_order_relaxed);
919+
atomic_store_explicit(&registry->test_waiter_enqueue_calls, 0, memory_order_relaxed);
917920
atomic_store_explicit(&registry->test_condition_waiters_now, 0, memory_order_relaxed);
918921
registry->next_retired = lock_registry_retired;
919922
lock_registry_retired = registry;
@@ -987,6 +990,15 @@ uint64_t cbm_lock_registry_condition_wait_call_count_for_test(const cbm_lock_reg
987990
: 0;
988991
}
989992

993+
/* Enqueue is monotonic, so a test can observe that a waiter joined the queue
994+
* after the fact instead of catching a queue depth that the waiter's own
995+
* deadline erases again. */
996+
uint64_t cbm_lock_registry_waiter_enqueue_count_for_test(const cbm_lock_registry_t *registry) {
997+
return registry
998+
? atomic_load_explicit(&registry->test_waiter_enqueue_calls, memory_order_relaxed)
999+
: 0;
1000+
}
1001+
9901002
size_t cbm_lock_registry_condition_waiter_count_for_test(const cbm_lock_registry_t *registry) {
9911003
return registry
9921004
? atomic_load_explicit(&registry->test_condition_waiters_now, memory_order_relaxed)

‎src/foundation/lock_registry_internal.h‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -25,6 +25,7 @@ bool cbm_lock_registry_is_retired_for_test(const cbm_lock_registry_t *registry);
2525
size_t cbm_lock_registry_attempting_waiter_count_for_test(cbm_lock_registry_t *registry);
2626
uint64_t cbm_lock_registry_condition_wait_call_count_for_test(const cbm_lock_registry_t *registry);
2727
size_t cbm_lock_registry_condition_waiter_count_for_test(const cbm_lock_registry_t *registry);
28+
uint64_t cbm_lock_registry_waiter_enqueue_count_for_test(const cbm_lock_registry_t *registry);
2829

2930
typedef enum {
3031
CBM_LOCK_REGISTRY_RELEASE_RW = 1,

‎tests/test_lock_registry.c‎

Lines changed: 24 additions & 21 deletions
Original file line numberDiff line numberDiff line change
@@ -33,6 +33,7 @@ enum {
3333
LOCK_REGISTRY_STRESS_THREADS = 8,
3434
LOCK_REGISTRY_STRESS_ITERATIONS = 160,
3535
LOCK_REGISTRY_PARKING_WAITERS = 64,
36+
LOCK_REGISTRY_DEADLINE_WAIT_MS = 200,
3637
};
3738

3839
typedef struct {
@@ -1020,7 +1021,8 @@ typedef struct {
10201021
atomic_bool ready;
10211022
atomic_bool go;
10221023
atomic_bool finished;
1023-
uint64_t deadline_ms;
1024+
uint64_t wait_ms;
1025+
uint64_t started_ms;
10241026
uint64_t returned_ms;
10251027
cbm_private_file_lock_status_t status;
10261028
cbm_lock_lease_t *lease;
@@ -1033,9 +1035,14 @@ static void *lock_registry_deadline_waiter_run(void *opaque) {
10331035
while (!atomic_load_explicit(&waiter->go, memory_order_acquire)) {
10341036
lock_registry_test_yield();
10351037
}
1036-
waiter->status =
1037-
cbm_lock_registry_acquire(waiter->registry, "absolute-deadline", CBM_PRIVATE_FILE_LOCK_EX,
1038-
waiter->deadline_ms, &waiter->cancel_token, &waiter->lease);
1038+
/* The absolute deadline is anchored here, in the thread it bounds, right
1039+
* before the call it bounds. An anchor taken by the observer is already
1040+
* running while this thread is still waiting to be scheduled, so on a
1041+
* loaded host it can expire before the acquire even starts. */
1042+
waiter->started_ms = cbm_now_ms();
1043+
waiter->status = cbm_lock_registry_acquire(
1044+
waiter->registry, "absolute-deadline", CBM_PRIVATE_FILE_LOCK_EX,
1045+
waiter->started_ms + waiter->wait_ms, &waiter->cancel_token, &waiter->lease);
10391046
waiter->returned_ms = cbm_now_ms();
10401047
atomic_store_explicit(&waiter->finished, true, memory_order_release);
10411048
return NULL;
@@ -1066,7 +1073,7 @@ TEST(lock_registry_absolute_deadline_survives_repeated_wakes) {
10661073
bool head_started = holder_status == CBM_PRIVATE_FILE_LOCK_OK &&
10671074
cbm_thread_create(&head_thread, 0, lock_registry_waiter_run, &head) == 0;
10681075
bool head_attempting = false;
1069-
uint64_t head_deadline = cbm_now_ms() + 500;
1076+
uint64_t head_deadline = cbm_now_ms() + LOCK_REGISTRY_TEST_TIMEOUT_MS;
10701077
while (head_started && cbm_now_ms() < head_deadline) {
10711078
head_attempting = cbm_lock_registry_waiter_count(fixture.registry) == 1 &&
10721079
cbm_lock_registry_attempting_waiter_count_for_test(fixture.registry) == 1;
@@ -1077,6 +1084,7 @@ TEST(lock_registry_absolute_deadline_survives_repeated_wakes) {
10771084
}
10781085

10791086
lock_registry_deadline_waiter_t tail = {.registry = fixture.registry,
1087+
.wait_ms = LOCK_REGISTRY_DEADLINE_WAIT_MS,
10801088
.status = CBM_PRIVATE_FILE_LOCK_IO};
10811089
atomic_init(&tail.cancel_token, false);
10821090
atomic_init(&tail.ready, false);
@@ -1086,31 +1094,20 @@ TEST(lock_registry_absolute_deadline_survives_repeated_wakes) {
10861094
bool tail_started =
10871095
head_attempting &&
10881096
cbm_thread_create(&tail_thread, 0, lock_registry_deadline_waiter_run, &tail) == 0;
1089-
uint64_t ready_deadline = cbm_now_ms() + 500;
1097+
uint64_t ready_deadline = cbm_now_ms() + LOCK_REGISTRY_TEST_TIMEOUT_MS;
10901098
while (tail_started && !atomic_load_explicit(&tail.ready, memory_order_acquire) &&
10911099
cbm_now_ms() < ready_deadline) {
10921100
lock_registry_test_yield();
10931101
}
10941102
bool tail_ready = tail_started && atomic_load_explicit(&tail.ready, memory_order_acquire);
1095-
uint64_t deadline_start = cbm_now_ms();
1096-
tail.deadline_ms = deadline_start + 200;
1103+
uint64_t enqueues_before_tail =
1104+
cbm_lock_registry_waiter_enqueue_count_for_test(fixture.registry);
10971105
atomic_store_explicit(&tail.go, true, memory_order_release);
10981106

1099-
bool tail_queued = false;
1100-
uint64_t queue_deadline = deadline_start + 100;
1101-
while (tail_ready && cbm_now_ms() < queue_deadline) {
1102-
tail_queued = cbm_lock_registry_waiter_count(fixture.registry) == 2 &&
1103-
cbm_lock_registry_attempting_waiter_count_for_test(fixture.registry) == 1;
1104-
if (tail_queued) {
1105-
break;
1106-
}
1107-
lock_registry_test_yield();
1108-
}
1109-
11101107
cbm_lock_cancel_token_t unrelated_token;
11111108
atomic_init(&unrelated_token, false);
11121109
bool broadcasts_ok = true;
1113-
uint64_t observe_deadline = deadline_start + 600;
1110+
uint64_t observe_deadline = cbm_now_ms() + LOCK_REGISTRY_TEST_TIMEOUT_MS;
11141111
while (tail_ready && !atomic_load_explicit(&tail.finished, memory_order_acquire) &&
11151112
cbm_now_ms() < observe_deadline) {
11161113
broadcasts_ok = cbm_lock_registry_request_cancel(fixture.registry, &unrelated_token) ==
@@ -1120,7 +1117,13 @@ TEST(lock_registry_absolute_deadline_survives_repeated_wakes) {
11201117
}
11211118
bool returned_at_deadline =
11221119
tail_ready && atomic_load_explicit(&tail.finished, memory_order_acquire);
1123-
uint64_t elapsed_ms = returned_at_deadline ? tail.returned_ms - deadline_start : UINT64_MAX;
1120+
/* The enqueue count only ever grows, so this stays true once the tail has
1121+
* joined the queue behind the attempting head. Reading it after the tail
1122+
* has returned removes the window the observer used to have to catch. */
1123+
uint64_t enqueues_after_tail =
1124+
cbm_lock_registry_waiter_enqueue_count_for_test(fixture.registry);
1125+
bool tail_queued = returned_at_deadline && enqueues_after_tail > enqueues_before_tail;
1126+
uint64_t elapsed_ms = returned_at_deadline ? tail.returned_ms - tail.started_ms : UINT64_MAX;
11241127

11251128
if (!returned_at_deadline && tail_started) {
11261129
(void)cbm_lock_registry_request_cancel(fixture.registry, &tail.cancel_token);

0 commit comments

Comments
 (0)