From 000e0e9fabd551350343735536176079587128ce Mon Sep 17 00:00:00 2001 From: arpan Date: Tue, 15 Sep 2026 17:07:19 +0530 Subject: [PATCH] T558b measured its own patience, not the child's blocking Red on `main`, on 3.12: `the child did not block on the lock: waited 0.135s`. The test starts a child, sleeps 1.5s, and checks the child has not finished. But until its first statement the child is importing `ctrlrun` and opening a Postgres connection, and on a loaded runner that can outlast the whole sleep. So `child.poll() is None` meant *still booting* as easily as *blocked on the lock*, and the 0.135s is the child reaching `put_hold` after the prune had already released. The test failed because it could not prove the property, not because the property was false. That is the safe direction to fail in, and it is still a flaky test. The comment above the assertion said the measurement starts after the interpreter and imports. It identified the confound and the assertion did not account for it. Fixed with a handshake: the child prints `ready` once it is connected and its next statement is the one that must block, and the parent does not start its clock until it reads that. The floor is now half the hold rather than a constant picked to be small enough to usually pass. Verified both directions. Three consecutive runs pass. Removing the `SELECT ... FOR UPDATE` from `put_hold` fails it in 0.002s on the *security* assertion, "a hold landed while a prune held the lock", which is the one that should fire. Signed-off-by: arpan --- tests/test_retention.py | 26 +++++++++++++++++++------- 1 file changed, 19 insertions(+), 7 deletions(-) diff --git a/tests/test_retention.py b/tests/test_retention.py index 690f11e5..6f64eef9 100644 --- a/tests/test_retention.py +++ b/tests/test_retention.py @@ -1437,9 +1437,16 @@ def test_T558b_a_hold_cannot_land_while_a_prune_holds_the_lock() -> None: "from ctrlrun.postgres import PostgresStateStore\n" "from ctrlrun.retention import Hold\n" f"s = PostgresStateStore({POSTGRES_URL!r}, schema={schema!r})\n" + # **The handshake, and why it is not optional.** Until this line the child is importing + # `ctrlrun` and opening a Postgres connection, and on a loaded runner that can outlast + # the parent's whole sleep. Without it the parent measures its own patience rather than + # the child's blocking: CI saw `waited 0.135s` on a run where the child reached the lock + # only after the prune had released it, and the test failed because it could not prove + # the property rather than because the property was false. + "print('ready', flush=True)\n" "start = time.time()\n" "s.put_hold(Hold('late', 1, 3, 'litigation', 'cli:bob', datetime.now(UTC)))\n" - "print('%.3f' % (time.time() - start))\n" + "print('%.3f' % (time.time() - start), flush=True)\n" "s.close()\n" ) try: @@ -1459,7 +1466,12 @@ def test_T558b_a_hold_cannot_land_while_a_prune_holds_the_lock() -> None: stdout=subprocess.PIPE, stderr=subprocess.STDOUT, ) - time.sleep(1.5) + # Read the child's `ready` before starting the clock: after this it is connected + # and its next statement is the one that must block. + handshake = child.stdout.readline().strip() if child.stdout else "" + assert handshake == "ready", f"the child never reached the lock: {handshake!r}" + held_for = 1.0 + time.sleep(held_for) still_waiting = child.poll() is None output, _ = child.communicate(timeout=60) parent.close() @@ -1468,12 +1480,12 @@ def test_T558b_a_hold_cannot_land_while_a_prune_holds_the_lock() -> None: "a hold landed while a prune held the lock, so it can be placed over receipts the " f"prune is about to delete: {output}" ) - # The child's own measurement starts after its interpreter and imports, so it is - # necessarily less than the parent's sleep. `still_waiting` above is the real proof; - # this is the coarse floor that separates blocking from an unblocked call, which takes - # single-digit milliseconds. + # With the handshake above, the child's clock starts at the lock rather than at its + # interpreter, so this is now a measurement of blocking and not of startup. The floor is + # half the hold, which leaves room for scheduling on a busy runner while staying far + # above the single-digit milliseconds an uncontended `put_hold` takes. waited = float(output.strip().splitlines()[-1]) - assert waited >= 0.25, f"the child did not block on the lock: waited {waited}s" + assert waited >= held_for / 2, f"the child did not block on the lock: waited {waited}s" finally: PostgresStateStore.drop_schema(POSTGRES_URL, schema)