diff --git a/scripts/pm/os-verify-lock.sh b/scripts/pm/os-verify-lock.sh index 1fe6537357..2a042f09b7 100755 --- a/scripts/pm/os-verify-lock.sh +++ b/scripts/pm/os-verify-lock.sh @@ -411,6 +411,41 @@ human_s() { if ((s >= 60)); then printf '%ss (%dm%02ds)' "$s" $((s / 60)) $((s % 60)); else printf '%ss' "$s"; fi } +# The ORDINARY refusal: the budget elapsed and we never got the lock. One +# function because more than one check can be the one that notices, and a +# timeout that describes itself differently depending on WHICH check noticed is +# exactly how an ordinary full-budget wait came to be reported as a clock fault. +# The optional note is the only thing that varies, and it says where the wait +# was spent — never why the deadline passed, which is not in question here. +verdict_queue_timeout() { + local waited="$1" note="${2:-}" + if [[ -n "$note" ]]; then + log "VERDICT queue-timeout (exit 99) · never acquired · waited $(human_s "$waited") · ${note} · $(holder_line)" + else + log "VERDICT queue-timeout (exit 99) · never acquired · waited $(human_s "$waited") · $(holder_line)" + fi +} + +# Does a count-based backstop have grounds to blame the CLOCK? +# +# Both backstops below bound this script by counting something that cannot lie +# about the passage of time (seconds handed to `flock`, or polling passes that +# each sleep). Reaching such a bound proves the loop ran; it does NOT by itself +# prove anything about the clock. So the accusation gets its own predicate, and +# it is the comparison the accusation has always claimed to have made: the +# counted real seconds against what the polled clock says elapsed over the SAME +# stretch. `2 * elapsed < counted` — the clock accounted for less than half the +# time the count proves went by. +# +# Scale-free on purpose (no tolerance constant to tune): a stalled clock reports +# ~0 whatever the budget, while the benign disagreements — whole-second +# truncation at each read, a `flock -w N` returning a hair early — are a few +# seconds against a budget of hundreds and can never reach half of it. +clock_disagrees() { + local counted="$1" elapsed="$2" + ((elapsed * 2 < counted)) +} + # --- host preflight --------------------------------------------------------- # What this entry point needs from the host, checked ONCE, before any waiting. @@ -544,26 +579,39 @@ mode_run() { # where `now` was the empty string on every pass and `now >= deadline` was # `0 >= 540` forever. One pass costs at least POLL_S of sleep, so a run that # burns through the whole budget's worth of passes and more has learned - # something about the clock, not about the lock. + # something the deadline check could not. + # + # ORDER MATTERS, and it is the same order as in the flock-slice loop below: + # read the clock, test the DEADLINE, and only then the count. A backstop that + # gets to answer first answers for the ordinary case too, and then an ordinary + # timeout is reported as an infrastructure fault. With the deadline first, a + # working clock always ends this loop by the ordinary route (it reaches the + # budget in BUDGET seconds, long before BUDGET+60 passes), and reaching the + # count at all means the clock did not get there — which the wording then + # states as the measured disagreement rather than as an assertion. local -a q q=() - local last_report=0 now pos i qline + local last_report=0 now pos i qline elapsed local passes=0 remints=0 local max_passes=$((BUDGET / POLL_S + 60)) local max_remints=5 while ((ordered == 1)); do passes=$((passes + 1)) - if ((passes > max_passes)); then - log "VERDICT lock-unusable (exit 99) · never acquired · the queue loop ran ${passes} passes inside a ${BUDGET}s budget, so the clock this script polls is not advancing · refusing to spin · nothing was built or tested" - exit 99 - fi now="$(now_s)" || { log "VERDICT lock-unusable (exit 99) · never acquired · the seconds clock stopped answering mid-wait · refusing to spin · nothing was built or tested" exit 99 } + elapsed=$((now - started)) if ((now >= deadline)); then - waited=$((now - started)) - log "VERDICT queue-timeout (exit 99) · never acquired · waited $(human_s "$waited") · never reached the head of the queue · $(holder_line)" + verdict_queue_timeout "$elapsed" 'never reached the head of the queue' + exit 99 + fi + if ((passes > max_passes)); then + if clock_disagrees $((passes * POLL_S)) "$elapsed"; then + log "VERDICT lock-unusable (exit 99) · never acquired · the queue loop ran ${passes} passes, each sleeping ${POLL_S}s, while the clock this script polls advanced only ${elapsed}s over the same stretch — the two accounts disagree, so the ${BUDGET}s deadline could never expire · refusing to spin · nothing was built or tested" + exit 99 + fi + verdict_queue_timeout "$elapsed" "gave up after ${passes} queue passes inside a ${BUDGET}s budget" exit 99 fi q=() @@ -616,16 +664,40 @@ mode_run() { # trust the clock. The deadline check below is computed from `now_s`; if that # clock is frozen or running backwards, `remaining` stays positive forever and # this loop retries `flock -w` for as long as the process is left alive — an - # unbounded wait that prints no verdict, which is the exact failure this card - # is about, merely relocated from the queue loop into this one. Measured while - # fixing it: with the clock frozen and the lock held, this loop was still - # running when a 40s timeout killed it, having printed zero VERDICT lines. + # unbounded wait that prints no verdict, which is the exact failure that + # bound was added for, merely relocated from the queue loop into this one. + # Measured while fixing it: with the clock frozen and the lock held, this loop + # was still running when a 40s timeout killed it, having printed zero VERDICT + # lines. # # So elapsed time is ALSO accumulated from the one ruler here that cannot lie: # the timeout just handed to `flock`, which really did block for that long. It # rises by at least 1 each pass, so the loop terminates within BUDGET passes # whatever the clock claims. A flock that fails EARLY over-counts, which errs # toward terminating — the safe direction. + # + # WHAT THAT BOUND MUST NOT DO IS EXPLAIN THE ORDINARY CASE. + # + # It used to. A waiter that reaches the head of the queue and then spends its + # whole budget here spends it ENTIRELY in slices — 18 × 30s = 540s = BUDGET — + # so `slices_spent >= BUDGET` came true at the bottom of pass 18, one check + # before `remaining <= 0` would have come true at the top of pass 19. The + # backstop won that tie by position and printed "the clock this script polls + # reported none of it" for a completely healthy clock: the same run's own 18 + # progress lines, decrementing 510 → 30 in exact 30s steps with the holder's + # `held` counter rising in lockstep, are proof the clock answered every poll. + # That reads as an infrastructure fault no retry can fix, when the truth was + # the mundane and actionable one — a sibling held the lock longer than one + # full budget. The two readings lead to opposite next moves, and the misread + # has already cost a seat an agent. + # + # Hence the order below, which is the whole fix: check the WALL-CLOCK DEADLINE + # after each slice, BEFORE the slice backstop, so a budget that genuinely + # elapsed always reports the ordinary timeout. The backstop keeps its job of + # terminating the loop, but it only gets to blame the clock when the clock is + # actually caught out — `clock_disagrees`, the comparison the old sentence + # asserted it had made and never made. When the two accounts agree, hitting + # the backstop means nothing more than "the budget is spent", and it says so. local remaining flock_rc slices_spent=0 exec 9>> "$LOCK_FILE" || { log "✗ cannot open ${LOCK_FILE} for locking." @@ -639,26 +711,54 @@ mode_run() { } remaining=$((deadline - now)) if ((remaining <= 0)); then - waited=$((now - started)) - log "VERDICT queue-timeout (exit 99) · never acquired · waited $(human_s "$waited") · $(holder_line)" + verdict_queue_timeout $((now - started)) exit 99 fi ((remaining > SLICE_S)) && remaining="$SLICE_S" flock_rc=0 "$FLOCK_BIN" -w "$remaining" 9 || flock_rc=$? ((flock_rc == 0)) && break - slices_spent=$((slices_spent + remaining)) - if ((slices_spent >= BUDGET)); then - log "VERDICT queue-timeout (exit 99) · never acquired · spent ${slices_spent}s of a ${BUDGET}s budget in flock slices while the clock this script polls reported none of it, so the deadline could never expire · refusing to spin · nothing was built or tested · $(holder_line)" - exit 99 - fi # 126/127 is "the primitive is gone", not "someone else holds it". Retrying - # that costs a fork per slice and can never succeed, so it is a verdict. + # that costs a fork per slice and can never succeed, so it is a verdict — + # and it is tested BEFORE the two bounds below, because it is a cause this + # script has actually established. A cause that is KNOWN outranks one that + # is inferred: left underneath, a flock that returns instantly every pass + # ran the accounting up to BUDGET in no time at all and was reported as a + # clock that had stopped. Same misattribution as the one above, one branch + # over. if ((flock_rc == 126 || flock_rc == 127)); then log "VERDICT lock-unusable (exit 99) · never acquired · \`${FLOCK_BIN}\` exited ${flock_rc} (not found / not executable) · nothing was built or tested" exit 99 fi - now="$(now_s)" || now="$deadline" + slices_spent=$((slices_spent + remaining)) + # Re-read the clock now that the slice has really gone by, and let the + # DEADLINE answer first. This is the check whose absence made the backstop + # below the default explanation for an ordinary full-budget wait. + now="$(now_s)" || { + log "VERDICT lock-unusable (exit 99) · never acquired · the seconds clock stopped answering mid-wait · refusing to spin · nothing was built or tested" + exit 99 + } + elapsed=$((now - started)) + if ((elapsed >= BUDGET)); then + verdict_queue_timeout "$elapsed" + exit 99 + fi + if ((slices_spent >= BUDGET)); then + if clock_disagrees "$slices_spent" "$elapsed"; then + log "VERDICT lock-unusable (exit 99) · never acquired · spent ${slices_spent}s of a ${BUDGET}s budget in flock slices while the clock this script polls advanced only ${elapsed}s over the same stretch — the two accounts disagree, so the deadline could never expire · refusing to spin · nothing was built or tested · $(holder_line)" + exit 99 + fi + # The count is spent and the clock agrees it is: an ordinary timeout that + # whole-second rounding kept a hair short of the deadline test above. + # Report the larger of the two accounts — both are lower bounds on the + # real wait, and understating it is what invites a pointless retry. + if ((elapsed > slices_spent)); then + verdict_queue_timeout "$elapsed" + else + verdict_queue_timeout "$slices_spent" + fi + exit 99 + fi if ((now - last_report >= PROGRESS_EVERY_S)); then last_report="$now" log "waiting: at the head of the queue, $((deadline - now))s of budget left · $(holder_line)" @@ -862,6 +962,53 @@ mode_self_test() { "$([[ -e "$franfile" ]] && echo yes || echo no)" no st_case 'and gives up in bounded wall time (<= 20s on a 3s budget)' \ "$((fz1 - fz0 <= 20))" 1 + # CASE 2 OF THE PAIR BELOW: this is the ONE situation entitled to the + # clock-fault wording, and it must still fire — a message that can never fire + # is its own defect, and the fix that stopped it firing for ordinary timeouts + # would be worthless if it also silenced the case it guards. The frozen shim + # pins both numbers: `started` and `now` are the same constant, so the clock + # reports exactly 0s against a slice account of 3s. + st_case 'and the clock-fault wording DOES still fire when the clock really stalls' \ + "$([[ "$froze" == *'the clock this script polls advanced only 0s over the same stretch'* ]] && echo yes || echo no)" yes + st_case 'and prints both accounts, so the accusation can be checked rather than believed' \ + "$([[ "$froze" == *'spent 3s of a 3s budget in flock slices'*'the two accounts disagree'* ]] && echo yes || echo no)" yes + st_case 'and calls a stalled clock lock-unusable, not a timeout (nothing timed out)' \ + "$([[ "$froze" == *'VERDICT lock-unusable'* ]] && echo yes || echo no)" yes + + # CASE 1 OF THE PAIR: an ORDINARY full-budget wait, healthy clock, real + # holder — the situation that used to print the clock-fault sentence above. + # + # The shape is the whole point: a waiter that reaches the HEAD of the queue + # spends its entire budget inside the flock-slice loop, so slice accounting + # reaches BUDGET at the bottom of a pass one check before the deadline test at + # the top of the next one would have. The backstop won that tie by position + # and accused a clock that the same run's own progress lines proved was + # answering every poll. An agent reading that concludes the container is + # broken and no retry can help; the truth was that a sibling held the lock for + # longer than one full budget, which is ordinary and actionable. Both readings + # cannot be right, and this case is what keeps them apart. + # + # Budget 3s reproduces it exactly at 1/180th of the size: one 3s slice fills + # the budget in slices with nothing left over, which is what 18 × 30s did. + local ordhold ordout ordrc ordranfile + ordranfile="${tmp}/ordinary-command-ran" + rm -f "$ordranfile" + bash "$SELF" -c 'sleep 25' > /dev/null 2>&1 & + ordhold=$! + sleep 1.5 + ordout="$(OS_VERIFY_LOCK_WAIT=3 bash "$SELF" -c ": > '${ordranfile}'" 2>&1)" + ordrc=$? + kill "$ordhold" 2> /dev/null + wait "$ordhold" 2> /dev/null + st_case 'an ordinary full-budget wait at the head of the queue exits 99' "$ordrc" 99 + st_case 'and reports the ORDINARY timeout' \ + "$([[ "$ordout" == *'VERDICT queue-timeout'*'never acquired · waited'* ]] && echo yes || echo no)" yes + st_case 'and accuses no clock — the fault this branch used to assert by default' \ + "$([[ "$ordout" == *clock* ]] && echo ACCUSED-THE-CLOCK || echo no)" no + st_case 'and names the holder instead, which is the half an agent can act on' \ + "$([[ "$ordout" == *'holder pid '* ]] && echo yes || echo no)" yes + st_case 'and does not run the command' \ + "$([[ -e "$ordranfile" ]] && echo yes || echo no)" no # every exit path prints a verdict, argument errors included. st_case 'a usage error prints a verdict too' \