Skip to content

test(teardown): report pid and process state when cleanup fails, without naming the holder (#1036) - #1049

Open
fujibee wants to merge 5 commits into
mainfrom
fix/1036-teardown-forensics
Open

test(teardown): report pid and process state when cleanup fails, without naming the holder (#1036)#1049
fujibee wants to merge 5 commits into
mainfrom
fix/1036-teardown-forensics

Conversation

@fujibee

@fujibee fujibee commented Sep 5, 2026

Copy link
Copy Markdown
Owner

Three windows-latest jobs failed with

rm: cannot remove '/tmp/tmp.XXXXXXXXXX': Directory not empty

on runs where every test passed. The message names the directory and not the
holder, so each red cost a rerun and left the next one no better informed.

What this establishes — and what it does not

It records the pids this teardown called kill and a wait on — not the
pids it killed. The producer discards both statuses (kill … || true,
wait_for_pid_exit … || true), so a pid that was already gone and one whose
wait timed out are both in that column; it is an intent, and the STILL ALIVE
marker printed beside each pid is the outcome. It also records a process
inventory taken at the moment the removal failed.

It does not identify the holder. Nothing here binds an open handle to the
remaining path, and neither ps nor tasklist can. The pids and the inventory
are correlation material for whoever reads the next red; the holder's identity
stays unproven until something can name it.

That boundary is deliberate. An earlier draft of this PR said the next failure
would answer the question outright, which was more than the dump can support.

The pid set is captured before the removal

A recursive delete can unlink part of the tree before it fails. On the arm where
the pid files go first and the directory survives, a reporter that re-scanned
them afterwards would print nothing — while its heading still said "the pids
teardown knew about". A label with no content reads as an answer.

The file-level teardown also hands over the pids it called kill on, which is
more than is inferable from what remains on disk — and the two sets are printed
in separate columns, the second marked "NOT known to have been signalled",
because a pid FILE that merely existed is not a pid anything acted on.

Why the teardown and not a workflow step

The suspected holder exits on its own 60-second timer. By the time a post-job
step runs, the photograph is of an empty room. The failing cleanup is the only
moment it is still there.

Reports, never repairs

  • rm's status is returned unchanged — a failure stays a failure
  • the probe body is a subshell, so its set +e cannot leak into the state
    the framework runs in afterwards
  • every probe may fail without consequence
  • no head in the pipelines — it SIGPIPEs the writer, the same reason the
    workflow's forensics step avoids it
  • tasklist is included because a native Windows process is absent from the
    MSYS ps entirely

Verified with controls

case result
normal teardown returns 0, prints zero bytes
unremovable dir whose pid file the rm already deleted returns non-zero, still names that pid and reports it alive
errexit set by the caller still set after the probe returns

Only Windows can confirm the diagnosis this enables; POSIX unlinks a directory
whose files are open, which is why this has never reproduced locally.

What was wrong before, recorded so nobody retraces it

Two earlier diagnoses of mine were wrong: I read a comment present on one of two
identical fakes as evidence of a mechanism absent from the other, and I proposed
adding a pid-file teardown loop that was already there.

The controls are enforceable, and each was broken to prove it

tests/test_teardown_forensics.bats pins the properties above. A first draft of
it made three of its central claims with a non-last [[ ]], which on bash 3.2 —
what CI's macOS leg runs — reports ok with a false claim inside it (#670).
check-enforced-assertions.sh names them: it read 638 against a baseline of 635
and exited 1. Every claim is now a plain command or a [ ], and the checker is
back at the baseline.

The partial-delete arm no longer depends on rm walking the tree in name order
or on chmod 500 refusing a delete — two assumptions about the platform, and
neither is what the file is asking about. A seam replaces rm for that one
call: it unlinks the pid file, then returns non-zero.

Six mutations, one per property, each red:

mutation result
scan the pid files after the rm instead of before 1 failing
merge both sets into the acted column 1 failing
drop the dedupe 1 failing
let the probe leak set +e 1 failing
report on a successful removal too 1 failing
drop the STILL ALIVE liveness marker 1 failing

Root cause of the CI red (codex-monitor 357/359), and the fix at b5aedd5

The Directory not empty red on codex-monitor: never kills a non-codex process recorded under a reused pid / reuses a live app-server when tasklist cannot see it (#567) is a teardown race whose writer is now named:

  • codex-monitor.sh:240 spawns codex-bridge-launcher.sh detached (… &, comment: "the launcher is detached on purpose and outlives this script").
  • The launcher resolves its own SKILL_DIR from its script path (codex-bridge-launcher.sh:31), which under test is TEST_SKILL_DIR, so it writes into TEST_SKILL_DIR/run — including mkdir -p "$RUN_DIR" (recreates the dir), an atomic-rename temp ${prefix}${now}.$$.$RANDOM, a bridge pidfile, and an identity-cache marker.
  • The test teardown kills only the codex-app-server.*.pid set — never this launcher — so it outlives the test and, under shard load, is still writing run/ when teardown_test_env removes the tree → rm: … Directory not empty. Its temp is gone by the time the windows runtime (#567): the job fails in teardown while every test passes — a file is still held under the temp dir #1036 forensic reporter runs, which is why the report shows an empty run/.
  • Confirmed the launcher fires: stubbing it to a probe showed 3 invocations in 357/359 (codex <proj> ws://127.0.0.1:PORT <ppid>).

Why #1049 and not main: #1049 adds ~3k lines across 39 test files; the shard split (weighted by @test count) rebalances and the codex-monitor shard gets heavier, so the launcher is slower under that load and overlaps the rm. No single line of #1049 introduces the race — it exposes a pre-existing latent race in the codex-monitor teardown via shard load.

Fix (b5aedd5): stub AGMSG_CODEX_BRIDGE_LAUNCHER_CMD to a no-op in test_codex_monitor.bats setup, so the detached launcher never spawns. These tests assert app-server pid handling and the codex handoff in CALL_LOG, not the bridge, so coverage is unchanged. Verified: 10/10 green, no bridge process lingers.

Reproduction status (honest)

The natural timing race did not reproduce locally — isolation (2/2), 4× CPU load (3/3), and bats --jobs 4 (4/4) were all clean. A fast machine finishes the launcher before teardown. "Did not reproduce" is a result, not proof of absence; the mechanism is established by the code path plus the confirmed launcher spawn.

Deterministic reproduction the next person can add (seam, not sleep)

Rather than chase the timing, pin the timepoint with a barrier seam like inbox.sh:82's AGMSG_TEST_MARK_BARRIER (.reached / .release, no-op when unset; siblings in check-inbox.sh, remote.sh). Concretely: point AGMSG_CODEX_BRIDGE_LAUNCHER_CMD at a stub that (given the run dir via env) writes a run/ file, touches <barrier>.reached, and blocks on <barrier>.release; have the test wait for .reached, then run the teardown rm while the launcher's file is present — a deterministic Directory not empty. The b5aedd5 fix (no-op launcher) then turns it green. That converts this from a load-flake into a controlled regression test.

Priority note: base is main, not on the 1.3.0 path; left at b5aedd5 with the above so the next person need not redo the investigation.

…lding it (#1036)

Three windows-latest jobs failed with

    rm: cannot remove '/tmp/tmp.XXXXXXXXXX': Directory not empty

on runs where every test passed. That message names the directory and not the
holder, so each red cost a rerun and left the next one no better informed.

This does not fix the failure. It makes the next one answer the question three
reds could not: is the pid the teardown killed and waited for the same pid that
is still holding the directory? The pid files record the process
codex-monitor.sh backgrounded; the handle may belong to a CHILD of it, which no
wait on the parent covers. Until that is observed, any fix is a guess — an
earlier one of mine was, and it was wrong twice over: the kill-forwarding I
proposed to add is already in both fakes, and the pid-file teardown that was
supposed to solve exactly this is already there too.

Placed in the teardown rather than a workflow step because the holder exits on
its own 60-second timer: by the time a post-job step runs, the photograph is of
an empty room. The failure itself is the only moment the holder is still there.

Reports, never repairs. `rm`'s status is returned unchanged, so a failure stays
a failure and nothing is swallowed; the probes are all allowed to fail, so a
dump cannot become a second thing to debug. `tasklist` is included because a
native Windows process does not appear in the MSYS `ps` at all — and the
suspected holder, a node started by a wrapper, is exactly that kind.

Verified both directions, since a probe that only ever runs on red is easy to
get backwards: a normal teardown returns 0 and prints zero bytes, and a
deliberately unremovable directory returns non-zero AND names the pid the
teardown knew about.
…g the holder (#1036)

Three blocking points from review, all of them right.

1. The pid set was re-scanned AFTER the failed `rm -rf`. A recursive delete can
   unlink part of the tree before it fails, so on the arm where the pid files go
   first and the directory survives, the report would have printed nothing —
   while its heading still said "the pids teardown knew about". A label with no
   content reads as an answer. The set is now captured BEFORE the removal, and
   the file-level teardown hands over the pids it actually signalled, which is
   not recoverable from disk afterwards.

2. `ps -ef` / `tasklist` is a whole-machine inventory; nothing here binds an open
   handle to the remaining path. The old wording ("the holder is in here") and
   the PR body's "the next failure answers the question" claimed an
   identification the dump cannot make. Both are narrowed to what is true: the
   waited pids' liveness plus an inventory taken at the same moment, offered as
   correlation, with the holder explicitly unproven.

3. `set +e` leaked into the caller and was never restored — a report-only probe
   must not change the state the framework runs in afterwards. The body is now a
   subshell.

Verified with controls rather than by reading: a normal teardown still returns 0
and prints zero bytes; an unremovable directory whose pid file the rm has
already deleted still names that pid and reports it alive; and errexit survives
the probe.

(One of those controls first reported an overclaim that was not in the file — the
`ps` dump had captured the fixture's own command line, grep pattern and all.)
…ke (#1036)

Review, second round, both points right.

The handover of the pids a file-level teardown actually signalled was sound, but
`teardown_test_env` then re-scanned `run/*.pid` and merged the result into the
same list — so a pid file nobody ever waited on could be reported under a
heading that said "killed and waited for". That is the same defect the previous
commit fixed, one layer along: a label wider than the thing it names. The two
sets now print separately, with the second explicitly marked as "NOT known to
have been waited on", and duplicates removed.

The reporter only runs on a red that appears about once a day on one platform,
so nothing else in the suite would notice it rotting. tests/test_teardown_
forensics.bats pins what makes it worth having: silence on green, the partial-
delete arm (the removal unlinks the pid file and THEN fails, and the pid is
still named), provenance kept apart, no duplicates, and no shell-option leak.

Each was checked by mutation rather than by reading — scanning after the rm,
merging the sets, dropping the dedupe, and un-subshelling the probe each turn
one or more of them red.

The last of those did NOT go red at first. `set -e` leaking out of the probe is
invisible inside a bats @test, because bats manages that option around every
command it runs — verified by watching the same mutation leak for real in a
plain bash and pass in here. The control now asks a plain bash instead, which is
where the property actually matters, and it fails on the mutation as it should.
…ake the controls enforceable (#1036)

Review, third round, both points right again.

The column heading said the pids had been SIGNALLED AND WAITED FOR. The producer
does `kill "$pid" || true` and `wait_for_pid_exit "$pid" || true`, discarding
both statuses — so a pid already gone, and one whose wait timed out, are in that
set too. The heading, the source comment and the PR body now say what is true of
every member: the teardown CALLED kill and a wait on it. The outcome is the
STILL ALIVE marker printed beside each pid, and that one is measured.

Third round on the same axis, one layer further in each time: sets mixed ->
columns split but the label wider than its content -> the label matched to what
the producer actually guarantees.

The controls added last round to fix "a claim that is never checked" were
themselves not checking. Three of their central claims were non-last `[[ ]]`,
which on bash 3.2 — CI's macOS leg — reports ok with a false claim inside it
(#670). check-enforced-assertions.sh names exactly those three: 638 against a
baseline of 635, exit 1. It was in the tree the whole time and nobody ran it.
Every claim is now a plain command or a `[ ]`; the checker is back at 635.

The partial-delete arm no longer leans on `rm` walking the tree in name order or
on chmod 500 refusing a delete. Neither is what this file asks about, and both
can produce a red that means nothing. A seam replaces `rm` for that one call: it
unlinks the pid file, then returns non-zero.

Six mutations, one per property, each red: scanning after the rm, merging the
sets, dropping the dedupe, leaking set +e, reporting on success, and dropping
the liveness marker.
@fujibee fujibee changed the title test(teardown): name the process holding the temp dir when cleanup fails (#1036) test(teardown): report pid and process state when cleanup fails, without naming the holder (#1036) Sep 5, 2026
…ace teardown (#1049 CI)

codex-monitor.sh spawns codex-bridge-launcher.sh DETACHED ("outlives this
script"), and it resolves its own SKILL_DIR from its script path -> TEST_SKILL_DIR
under test, so it writes into TEST_SKILL_DIR/run (temp files, a bridge pidfile,
and a `mkdir -p run/` that recreates the dir). The test teardown kills only the
codex-app-server.*.pid set, never this launcher, so under shard load it is still
writing run/ when teardown_test_env removes the tree -> "rm: cannot remove ...:
Directory not empty" -- and its atomic-rename temp is gone by the time the #1036
forensic reporter runs, which is why the report saw an empty run/. It surfaced
with #1049 only because #1049 added ~3k lines of tests, shifting this shard's
load enough to lose a race that main's lighter shard did not; no single line of
#1049 introduces it.

None of these tests exercise the bridge (they assert app-server pid handling and
the codex handoff in CALL_LOG), so a no-op launcher removes the racer without
changing coverage. Confirmed: the real launcher fires in tests 357/359 (three
invocations, each with a real ws:// url and the app-server ppid); with the stub
all 10 tests pass and no bridge process lingers.

The natural timing race did not reproduce locally (isolation, 4x CPU load, and
--jobs 4 all clean): a fast machine finishes the launcher before teardown. The
fix targets the confirmed mechanism, not a reproduced timing.
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