Skip to content

test: wait for conditions instead of fixed sleeps in the watcher suites - #503

Merged
fujibee merged 5 commits into
mainfrom
ci/poll-not-sleep
Jul 27, 2026
Merged

test: wait for conditions instead of fixed sleeps in the watcher suites#503
fujibee merged 5 commits into
mainfrom
ci/poll-not-sleep

Conversation

@fujibee

@fujibee fujibee commented Jul 27, 2026

Copy link
Copy Markdown
Owner

CI speedup, part 2 of 2 (part 1 was #501, sharding). Replaces fixed settling
sleeps in the watcher suites with bounded condition waits, and hoists the
polling helpers that already existed ad hoc in three files into
tests/test_helper.bash.

Measured, not estimated

sleep was replaced with a logging shim on PATH and the suite re-run, so the
targets came from what actually blocks rather than from what the source says.

The literal totals are misleading, in two separate ways.

First, the suite contains ~3400s of sleep literals, and 96% of that never
blocks anything
: it is sleep 30 3>&- & background stand-ins used as
long-lived fake processes. Deleting them would save nothing.

Second, the shim attributes a sleep by BATS_TEST_FILENAME, and that variable
is inherited by the scripts under test. So part of the remaining ~140s is the
watcher's own poll interval (scripts/watch.sh:488, sleep "$INTERVAL"), not
a test-side wait at all. test_watch.bats has zero bare sleep 1 in its
source yet logged 27 of them — every one from watch.sh. No amount of
test-side work removes those.

What was actually addressable is therefore a good deal smaller than the raw
number suggests, and the A/B below is the honest measure of it.

A/B, two rounds, same machine, git stash between runs

before after
test_delivery.bats alone, r1 / r2 86s / 86s 75s / 76s
test_watch.bats + test_delivery.bats, r1 / r2 151s / 151s 135s / 143s

Roughly -12s mean on the pair (~8%). Note the "after" column varies (135 vs
143) where "before" does not: fixed sleeps are deterministic, condition waits
finish when the machine lets them. That is the intended trade.

A single non-A/B run early on read 106s against an 86s baseline and looked like
a regression. It was load from a concurrent job. Nothing was reported until the
stash-based A/B was in hand.

Two negative assertions got stronger, not weaker

Both subscription tests asserted that a message does not arrive, after a
fixed sleep 3 presumed to be "enough poll iterations". That is not an
assertion, it is a guess about timing.

They now wait for a later row to be delivered, which proves the watcher has
already scanned past the row the assertion denies. In the static-subscription
test the existing rows would not carry that proof — the alice row precedes the
bob row, so seeing alice says nothing about bob — so a sentinel row is inserted
after bob's and waited on instead.

A trap worth naming

Tightening a poll from sleep 0.5 to sleep 0.1 while leaving the loop at 10
iterations silently cuts the timeout budget from 5s to 1s. That passes locally
and invents a new flake on a loaded runner. Iteration counts were raised to
keep every ceiling exactly where it was. Faster and less tolerant are not the
same change.

Deliberately left alone

Two fixed sleeps stay, each with a comment saying why, so a future sweep
does not "fix" them:

  • test_delivery.bats — separating two mtimes. The thing being waited on is
    the clock; filesystem timestamp granularity is a whole second on some CI
    filesystems. There is no condition to poll.
  • test_watch.bats — asserting that nothing further is emitted after one poll
    interval. When the expected outcome is the absence of an event, there is no
    event to wait for.

test_codex_bridge_launcher.bats is not touched here. It is the most
expensive file per test (8.2s), and none of that is settling waits:

sleep 10 3>&- & local parent_a=$!    # stand-in parent
export MOCK_BRIDGE_SLEEP=8           # mock bridge lifetime
...assertions complete in well under 1s...
wait "$parent_a"                     # blocks for the remaining ~10s

Per-test timings confirm it: the five tests with sleep 10/sleep 14 parents
run 10.3-11.3s, the five with sleep 6 run 7.2-7.8s. Duration tracks fixture
lifetime, not work.

Shortening those fixtures is the tempting fix and the dangerous one. The mock
has to outlive the window in which a duplicate dispatcher could appear; if it
exits first, the singleton assertion passes because nothing was left to race —
a falsely green test, not a flaky one. Killing the stand-ins after the
assertions instead of waiting them out looks safe, but it changes the teardown
ordering the lock protocol is being exercised under.

Either way it is a scope call rather than a mechanical conversion, so it is
reported rather than taken unilaterally.

Verification

bats tests/test_watch.bats tests/test_delivery.bats — exit 0, 27/27 and
140/140 locally.


What CI caught after the first round (added at head 95da913)

Two failures, only one of them mine.

The conversion introduced a real race (test_watch.bats)

The restart test kills the first watcher, restarts it, and asserts the second
does not re-deliver what the first already streamed. I made it wait for the
message to appear on stdout — but watch.sh writes the line first and
persists the watermark after. Killing on the line can drop the mark, so the
restart re-delivers, which is precisely what the test denies. It failed on
macOS.

It now waits for the watermark file to hold the delivered row's id. Same
mistake in kind as the global-stop finding: waiting for the observable event
is not the same as waiting for the durable one.
The sleep 2 it replaced did
not guarantee the write either — it just usually won the race.

A test on main was asserting nothing (test_delivery.bats)

session-end.sh only kills a pid whose command line still looks like
watch.sh — deliberate protection against pid recycling. The fixture was
sleep 30, which can never satisfy that guard, so the kill could never fire.

Measured against main's own code:

BEFORE assertion: ps=[sleep 30]        <- alive
! kill -0 "$target_pid" 2>/dev/null    -> passes
AFTER  assertion: ps=[sleep 30]        <- still alive

The process is alive on both sides of an assertion that claims it is gone. The
test has never verified the behaviour in its own name.

Converting the wait to a poll is what surfaced it: a single check after a fixed
sleep missed it, repeated checking did not. The fixture is now a real watcher, so the guard is
satisfied and the kill actually happens.

To be exact about what was and was not established: the behaviour above is
measured. The mechanism by which kill -0 reports failure for a live process
in that position is not explained here — a reduced bash repro of the same
shape returns 0 three times in a row. Fixing the fixture removes the dependence
on it either way.

Carried in its own commit, per review request.

Retracted: the helper was not evidence of anything yet

An earlier revision of this description said wait_for_pid_exit returning
promptly was the evidence that the process had really died. That was wrong,
and review caught it: the helper read any failed kill -0 as "exited". A
failed kill -0 is ESRCH (dead) or EPERM (alive, but not signalable by us —
sandboxes do this, and a live instance was found in delivery.sh status the
same day). So the helper could report "gone" for a running process, which is
the defect the session-end fixture was just fixed for, reintroduced one level
down inside the helper written to prevent it.

Saying "gone" now requires kill(2) and the process table to agree, mirroring
_agmsg_pid_alive. The loop also reaps first: an unreaped zombie still answers
kill -0, so a process that had exited could look alive for the whole
timeout — a separate path to the same class of lie.

tests/test_wait_helpers.bats pins this. The EPERM branch cannot be produced
portably in-suite, so the decision rule itself is pinned: with kill stubbed to
report "Operation not permitted" and ps giving no evidence either way, the
answer must still be ALIVE.

The mechanism behind the original observation is not explained. Three
controlled probes — consecutive calls in the test shell, calls in a subshell,
and stderr captured to files — all had kill -0 return 0 correctly. That it
does not reproduce on demand is itself the argument for not depending on it.

fujibee added 5 commits July 27, 2026 12:54
A fixed `sleep 1` after launching a watcher is wrong in both directions at
once: it costs a whole second when the watcher was ready in 40ms, and it still
races on a loaded runner that needed 1.2s. Wait for the condition instead --
the watermark file for "the mark is taken", the delivered line for "the row
was processed", process exit for "it is gone".

Two negative assertions gain rigour rather than losing it. Where the old code
slept and hoped enough poll iterations had gone by, it now waits for a later
row to arrive, which proves the watcher already scanned the row the assertion
denies. One of the two needed a sentinel row for that ordering to hold.

Two fixed sleeps stay and are marked deliberate: one separates two mtimes, the
other asserts nothing further is emitted. Neither has an event to poll for.
`delivery.sh stop` sends TERM to each watcher and returns; the order they
actually die in is not guaranteed. Waiting on A and asserting B in the same
breath races B's exit trap, so the condition-wait conversion was incomplete
exactly where the contract under test is "stops ALL of them". The `sleep 1`
this replaced happened to cover both.

The two project-scoped tests above stay at one wait on purpose: their second
watcher is asserted to still be ALIVE, which needs no grace period.
The restart test kills the first watcher and asserts the second does not
re-deliver what the first already streamed. Waiting for the message to appear
on stdout is the wrong signal for that: watch.sh writes the line first and
persists the watermark after, so killing on the line can drop the mark and make
the restart re-deliver -- the exact thing the test denies. It failed on macOS
in CI for that reason.

Wait for the watermark file to hold the delivered row's id instead. The fixed
`sleep 2` this replaced never guaranteed the write either; it just usually won.
session-end.sh only kills a pid whose command line still looks like watch.sh,
which is deliberate (pid recycling). The fixture was `sleep 30`, so the kill
could never fire -- and the assertion passed anyway: with main's code, `ps`
shows the process alive immediately before and after `! kill -0` succeeds. The
test never checked what its name claims.

Converting the wait to a poll is what exposed it. One check after a fixed sleep
missed it; checking repeatedly did not.

Launch a real watcher as the fixture so the command-line guard is satisfied and
the kill actually happens.
wait_for_pid_exit read a failed `kill -0` as "exited". That failure is ESRCH
(dead) or EPERM (alive, but not signalable by us — sandboxes do this, and a
live instance of it was found in delivery.sh status the same day). Reading
every failure as death is how a wait-for-exit helper reports success for a
running process, which is the defect the session-end test was just fixed for,
reintroduced one level down in the helper meant to prevent it.

Saying "gone" now needs kill(2) and the process table to agree, mirroring
_agmsg_pid_alive. The loop also reaps first, since an unreaped zombie still
answers kill -0 and would otherwise look alive for the whole timeout.

Covered by tests/test_wait_helpers.bats. The EPERM branch cannot be produced
portably in-suite, so the decision rule is pinned instead: anything other than
"no such process" counts as alive.
@fujibee
fujibee merged commit e9a5fc2 into main Jul 27, 2026
14 checks passed
fujibee added a commit that referenced this pull request Jul 28, 2026
…one (#505)

* fix(liveness): make kill(2) and ps agree before calling a pid dead

_agmsg_pid_alive already read the ESRCH/EPERM distinction. Add the ps
cross-check #503 settled on, so "dead" needs a source that does not depend on
signalling permission at all, and a fork-free fast path, so the common answer
still costs no subshell — callers poll this in loops that exist to be fork-free.

* fix(liveness): route every liveness check through the EPERM-aware helper

`kill -0` answers "can I signal this", not "is this running". Under a sandbox
a live watcher, bridge or app-server fails it, and every shipped caller read
the exit status directly: status printed live processes as stale pidfiles,
session-start and codex-monitor started a second bridge and app-server beside
the running ones, and the launcher reclaimed a live owner's lock — the #485
duplicate-children shape.

All seventeen sites now call _agmsg_pid_alive; instance-id.sh is sourced where
it was only reachable transitively, or not at all.

* test(liveness): pin EPERM as alive, and sweep for bare kill -0

pid 1 is a live process this user cannot signal, so it stages the distinction
directly; the suite skips where no such pid exists. A dead-pid case guards the
other direction, since "assume alive" must not make everything look alive.

The sweep is #500's lesson as a test: a partially-hardened file reads like a
fixed one, so no shipped script may call kill -0 outside the helper.

* fix(liveness): reject 0 as a pid — it names this process group, not a process

`kill -0 0` succeeds because 0 addresses the caller's own process group, so a
digits-only check called it alive, and callers kill what liveness reports
alive: `kill 0` TERMs the group, the caller included. A pidfile holding 0 was
all it took. Leading zeros go too — nothing writes them and kill(1) may read
them as octal.

The check is split out as _agmsg_pid_valid and also gates the two launcher
sites that kill a recorded pid without asking about liveness first.

Reported by review of #505.

* fix(liveness): bound a pid to pid_t, and stop testing liveness against a number

Past INT32_MAX kill(1) rejects the ARGUMENT rather than reporting ESRCH, and
everything that is not ESRCH reads as EPERM, i.e. alive. An oversized value in
a pidfile was therefore alive forever: lock never reclaimed, bridge never
restarted. Bounding the input is what keeps "not ESRCH" meaning "EPERM".

The ESRCH tests stubbed kill and passed the literal 999, which is a RUNNING
process on some CI hosts — so the new ps cross-check correctly called it alive
and the tests failed there and only there. They now use a pid that is genuinely
gone, and the cross-check gets a test of its own.

Reported by review of #505.

* fix(liveness): make the pid ceiling the platform's, not one number

A Windows process id is a DWORD, and liveness there reads the native process
table through tasklist rather than kill(1)'s signed pid_t. The INT32_MAX bound
sat in front of that branch, so 2147483648..4294967295 — legitimate native pids
— were called dead, and a live watcher or lock owner stale.

Reported by review of #505.

* docs(liveness): describe both pid ceilings, not just pid_t

The comment under the ceiling selection still explained only the POSIX side,
which reads as if the Windows branch were an exception to a rule rather than
the other half of it.

Reported by review of #505.
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