Skip to content

fix(tests): make the lock-registry absolute-deadline fixture deterministic - #2043

Merged
DeusData merged 1 commit into
mainfrom
fix/lock-registry-deadline-test-deterministic
Sep 4, 2026
Merged

fix(tests): make the lock-registry absolute-deadline fixture deterministic#2043
DeusData merged 1 commit into
mainfrom
fix/lock-registry-deadline-test-deterministic

Conversation

@DeusData

@DeusData DeusData commented Sep 3, 2026

Copy link
Copy Markdown
Owner

The flake

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,
always with the same signature:

FAIL tests/test_lock_registry.c:1153: ASSERT(tail_queued)
7648 passed / 1 failed
When PR Evidence
2026-08-28 #1342 test-unix (macos-15-intel)
2026-09-02 #1811 test-unix (macos-15-intel)
2026-09-03 #1819 run 33799475629, job 100823626965

Attribution: the registry is fine, the fixture is not

cbm_lock_registry_acquire enqueues the waiter synchronously under the registry
mutex, before any wait
(lock_registry_waiter_push in
lock_registry_acquire_internal), so waiter_count and the attempting count are
exact. There is no production race here.

The defect is that the fixture 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:

uint64_t deadline_start = cbm_now_ms();
tail.deadline_ms = deadline_start + 200;   /* the tail's acquire deadline */
...
uint64_t queue_deadline = deadline_start + 100;  /* the observer's budget */

Neither window is anchored to the tail's actual registration, so a loaded runner
breaks the test two different ways:

  1. The state existed, nobody was looking any more. The tail is scheduled inside
    its own deadline but after the observer's 100 ms budget has expired.
  2. The state can never exist at all. The tail is scheduled more than 200 ms
    late; its absolute deadline has already passed when it finally calls acquire, so
    the pre-registration deadline check returns BUSY immediately and the tail never
    enqueues. No amount of extra observer patience would help.

lock_registry sits 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.

RED first, with production untouched

Delaying only the tail thread after its start gate — a faithful model of "this
thread did not get scheduled promptly", with production untouched — reproduces the
CI signature exactly, one failure and nothing else:

CBM_TEST_TAIL_STARVE_MS=120 -> lock_registry_absolute_deadline_survives_repeated_wakes
    FAIL tests/test_lock_registry.c:1160: ASSERT(tail_queued)      15 passed, 1 failed
CBM_TEST_TAIL_STARVE_MS=250 -> lock_registry_absolute_deadline_survives_repeated_wakes
    FAIL tests/test_lock_registry.c:1160: ASSERT(tail_queued)      15 passed, 1 failed

(120 ms exercises path 1, 250 ms exercises path 2; line 1160 rather than 1153
because the temporary delay hook adds seven lines. The hook is not part of this PR.)

The rebuild: wait for states that cannot evaporate

Widening the observer's budget would only paper over path 1, 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 now observes states that cannot disappear:

  • The tail anchors its own absolute deadline, 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, so it times the registry instead of timing the scheduler.
  • Enqueue becomes a monotonic counter,
    cbm_lock_registry_waiter_enqueue_count_for_test, modelled on the existing
    test_condition_wait_calls counter right next to it. Because the count only ever
    grows, the observer reads it once, after the tail has returned, instead of
    polling for a live queue depth. The polling loop — and with it the window — is gone.
  • The remaining 500 ms / 600 ms fixture budgets become the file's
    LOCK_REGISTRY_TEST_TIMEOUT_MS backstop
    , and every loop exits on the state it is
    waiting for rather than on the clock, so the backstop only fires when the product
    is actually broken.

No budget was tuned, and no assertion was relaxed. The contract still holds: the tail
must return at its absolute deadline (150 <= elapsed < 350 ms for a 200 ms
deadline) despite ~40 unrelated cancel broadcasts, still BUSY, still 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 before.

Production changes are three lines and one accessor: a relaxed atomic increment under
a mutex already held, a scrub on retirement, and the _for_test reader. No behaviour
changes.

Verification (macOS arm64, sanitized runner)

Check Result
Baseline before the fix, 20 runs 20/20 green (the flake is CI-only on this host)
Injected tail delay 120 / 250 ms, before RED, ASSERT(tail_queued), 1 failure each
Injected tail delay 120 / 250 / 400 / 900 ms, after green — arbitrary delay no longer decides the verdict
lock_registry x30, plain 30/30 green
lock_registry x30, under 4 CPU hogs 30/30 green
lock_registry in the saturated 18-job wave rc=0 pass=16 fail=0
private_file_lock lock_registry daemon project_lock daemon_* 222 passed, 1 skipped
Full run-tests-parallel.sh, 141 suites, 18 jobs 7815 passed, 0 failed, 7 skipped
make -f Makefile.cbm lint-ci passed (cppcheck + clang-format + NOLINT)

…istic

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>
@DeusData
DeusData force-pushed the fix/lock-registry-deadline-test-deterministic branch from 7109e5e to 7e47043 Compare September 4, 2026 13:42
@DeusData
DeusData merged commit 5c8ce58 into main Sep 4, 2026
35 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant