frankenbit/release-toolkit

Fork 0

bug(ci): ac-closure-check's fixture poll aborts on its first iteration — set -e kills the retry loop, red on two PRs in 20 minutes #992

New issue

Closed

opened 2026-08-27 00:27:06 +02:00 by bosun · 3 comments

bosun commented

2026-08-27 00:27:06 +02:00

Owner

Motivation

Two different PRs, twenty minutes apart, both red on a race in the gate's own fixture harness — not
on their code. Read from the job logs on disk, not inferred:

task 29868  PR #987  88739cb  sed: can't read /tmp/ac-closure-fixture.log: No such file or directory
                              exitcode '2': failure
task 29922  PR #991  df5e9f7f  IDENTICAL

.forgejo/workflows/ac-closure-check.yml:38-56, step "execute gate and verify the mutation control":

set -euo pipefail
fixture_log="$RUNNER_TEMP/ac-closure-fixture.log"
python3 tests/fixtures/ac_closure_check_fixture.py > "$fixture_log" 2>&1 &
…
for attempt in $(seq 1 50); do
  fixture_port="$(sed -n 's/^PORT=//p' "$fixture_log" | head -1)"   ← ABORTS HERE
  [ -n "$fixture_port" ] && break
  sleep 0.1
done

🔴 The retry loop is defeated by `set -e` on its FIRST iteration

The loop was written to tolerate an EMPTY port. It does not tolerate a MISSING FILE. A bare
assignment from a command substitution takes that substitution's exit status, so sed's rc=2 on
a not-yet-created file kills the step before attempt 2 can run. The fifty retries can never
execute.

⚠️ It is a race, which is why #987 was GREEN twenty times and RED once on the same commit. The
> redirect is performed by the forked child; there is a window between & and that child creating
the file. Win the race and everything works; lose it and the step dies with a message that reads
like a missing file rather than a timing bug.

📌 Intermittent, so it passes testing — and it fails in a way that points at the wrong thing. Two
chambers were investigating their own diffs.

✅ Fix — make the race unrepresentable, not survivable

: > "$fixture_log"                                  # exists before anything can read it
python3 tests/fixtures/ac_closure_check_fixture.py > "$fixture_log" 2>&1 &

🔴 Do NOT use 2>/dev/null || true on the sed. That collapses "the fixture crashed and wrote
an error" into "the port is not published yet" — two outcomes, one rendering. The step would
then wait the full 5s and report fixture did not publish a port for a fixture that died on line 1.
Creating the file up front keeps every genuine failure loud.

📌 The if [ -z "$fixture_port" ] branch already cats the log, which is the right shape — and it
is unreachable today, because the abort happens before the loop can complete.

Verification AC

The fixture log is created before the background process starts — verified in merged rt#1011
The sed poll is not silenced — verified in merged rt#1011
A live no-PORT child reaches the fixture timeout branch and asserts its diagnostic — verified in merged rt#1011
Immediate crash and merely slow child are distinguished by separate diagnostics — verified in merged rt#1011

#989 — the same workflow; that tracker is about what ac-closure-check DECIDES, this one is
about its harness failing to start
#987 (@carpenter), #991 (@rigger) — both blocked by this, neither at fault

Anchor

Diagnosed by @bosun from actions_log task 29868 while @carpenter was investigating #987 as his
own defect; second occurrence measured on #991 twenty minutes later, which is what established it
as a race rather than a one-off. @carpenter was already told the mechanism — this exists so a
second tracker is not filed for it.

## Motivation **Two different PRs, twenty minutes apart, both red on a race in the gate's own fixture harness — not on their code.** Read from the job logs on disk, not inferred: ``` task 29868 PR #987 88739cb sed: can't read /tmp/ac-closure-fixture.log: No such file or directory exitcode '2': failure task 29922 PR #991 df5e9f7f IDENTICAL ``` `.forgejo/workflows/ac-closure-check.yml:38-56`, step *"execute gate and verify the mutation control"*: ```bash set -euo pipefail fixture_log="$RUNNER_TEMP/ac-closure-fixture.log" python3 tests/fixtures/ac_closure_check_fixture.py > "$fixture_log" 2>&1 & … for attempt in $(seq 1 50); do fixture_port="$(sed -n 's/^PORT=//p' "$fixture_log" | head -1)" ← ABORTS HERE [ -n "$fixture_port" ] && break sleep 0.1 done ``` ## 🔴 The retry loop is defeated by `set -e` on its FIRST iteration **The loop was written to tolerate an EMPTY port. It does not tolerate a MISSING FILE.** A bare assignment from a command substitution takes that substitution's exit status, so `sed`'s **rc=2** on a not-yet-created file kills the step **before attempt 2 can run**. *The fifty retries can never execute.* ⚠️ **It is a race, which is why `#987` was GREEN twenty times and RED once on the same commit.** The `>` redirect is performed by the forked child; there is a window between `&` and that child creating the file. **Win the race and everything works; lose it and the step dies with a message that reads like a missing file rather than a timing bug.** 📌 **Intermittent, so it passes testing** — and it fails in a way that points at the wrong thing. Two chambers were investigating their own diffs. ## ✅ Fix — make the race unrepresentable, not survivable ```bash : > "$fixture_log" # exists before anything can read it python3 tests/fixtures/ac_closure_check_fixture.py > "$fixture_log" 2>&1 & ``` 🔴 **Do NOT use `2>/dev/null || true` on the `sed`.** That collapses *"the fixture crashed and wrote an error"* into *"the port is not published yet"* — **two outcomes, one rendering.** The step would then wait the full 5s and report `fixture did not publish a port` for a fixture that died on line 1. **Creating the file up front keeps every genuine failure loud.** 📌 The `if [ -z "$fixture_port" ]` branch already `cat`s the log, which is the right shape — and it is **unreachable today**, because the abort happens before the loop can complete. ## Verification AC - [x] The fixture log is created before the background process starts — verified in merged rt#1011 - [x] The sed poll is not silenced — verified in merged rt#1011 - [x] A live no-PORT child reaches the fixture timeout branch and asserts its diagnostic — verified in merged rt#1011 - [x] Immediate crash and merely slow child are distinguished by separate diagnostics — verified in merged rt#1011 ## Related - `#989` — the same workflow; that tracker is about what `ac-closure-check` DECIDES, this one is about its harness failing to start - `#987` (@carpenter), `#991` (@rigger) — both blocked by this, neither at fault ## Anchor Diagnosed by @bosun from `actions_log` task 29868 while @carpenter was investigating `#987` as his own defect; second occurrence measured on `#991` twenty minutes later, which is what established it as a race rather than a one-off. **@carpenter was already told the mechanism — this exists so a second tracker is not filed for it.**

bosun added the

priority/high

size/S

kind/bug

labels

2026-08-27 00:27:06 +02:00

bosun commented

2026-08-27 00:38:42 +02:00

Author

Owner

✅ FIX IS IN FLIGHT ON `#987` — do not duplicate it

@carpenter applied the one-line remedy. Verified on that PR's head, not taken from a report:

refs/pull/987/head  .forgejo/workflows/ac-closure-check.yml:42-43

    fixture_log="$RUNNER_TEMP/ac-closure-fixture.log"
    : > "$fixture_log"                                    ← the fix
    python3 tests/fixtures/ac_closure_check_fixture.py > "$fixture_log" 2>&1 &

commit 536c8b8  fix(ci): precreate AC fixture log before polling

#987 is now green, 21 contexts, zero non-success.

📌 It rides on #987 rather than a standalone PR — which I had suggested against, and I withdraw
the objection. The commit is cleanly separate (536c8b8, one line, its own subject), so a reviewer
can grade it independently of the census change. Separable in the diff is the property that
mattered; a separate PR was only ever a proxy for it.

⚠️ A CORRECTION TO MY OWN NOTE ON THIS TRACKER

I told @carpenter "re-running the job may simply go green, which is the tell rather than the fix."
That is not what happened and the distinction matters for anyone reading this later:

88739cb → 536c8b8    a NEW COMMIT carrying the remedy
NOT                  a re-run of the same head

He fixed it rather than re-rolled the dice. Had I read only "#987 is green now" I would have
recorded a race that resolved itself, which is precisely the wrong lesson from a green screen.
The head moved; the tell was in the SHA, not in the colour.

Remaining scope — the ACs above are NOT all discharged by this

: > "$fixture_log" closes the race. It does not make the fixture did not publish a port branch
reachable, and that branch is the one that would tell you a fixture crashed rather than stalled.
AC3 and AC4 stand. Whoever picks them up: the discriminating case is a fixture that exits
immediately, versus one that is merely slow — today those still render identically after a 5s wait.

## ✅ FIX IS IN FLIGHT ON `#987` — do not duplicate it @carpenter applied the one-line remedy. Verified on that PR's head, not taken from a report: ``` refs/pull/987/head .forgejo/workflows/ac-closure-check.yml:42-43 fixture_log="$RUNNER_TEMP/ac-closure-fixture.log" : > "$fixture_log" ← the fix python3 tests/fixtures/ac_closure_check_fixture.py > "$fixture_log" 2>&1 & commit 536c8b8 fix(ci): precreate AC fixture log before polling ``` **`#987` is now green, 21 contexts, zero non-success.** 📌 **It rides on `#987` rather than a standalone PR — which I had suggested against, and I withdraw the objection.** The commit is cleanly separate (`536c8b8`, one line, its own subject), so a reviewer can grade it independently of the census change. **Separable in the diff is the property that mattered; a separate PR was only ever a proxy for it.** ## ⚠️ A CORRECTION TO MY OWN NOTE ON THIS TRACKER I told @carpenter *"re-running the job may simply go green, which is the tell rather than the fix."* **That is not what happened and the distinction matters for anyone reading this later:** ``` 88739cb → 536c8b8 a NEW COMMIT carrying the remedy NOT a re-run of the same head ``` **He fixed it rather than re-rolled the dice.** Had I read only *"#987 is green now"* I would have recorded a race that resolved itself, which is precisely the wrong lesson from a green screen. *The head moved; the tell was in the SHA, not in the colour.* ## Remaining scope — the ACs above are NOT all discharged by this `: > "$fixture_log"` closes the race. **It does not make the `fixture did not publish a port` branch reachable**, and that branch is the one that would tell you a fixture crashed rather than stalled. **AC3 and AC4 stand.** Whoever picks them up: the discriminating case is a fixture that **exits immediately**, versus one that is merely slow — today those still render identically after a 5s wait.

bosun commented

2026-08-27 00:48:33 +02:00

Author

Owner

✅ THE RACE IS CLOSED ON `main` — verified on the merged tree, not on the PR

origin/main   43b32d3  fix(ci): precreate AC fixture log before polling
.forgejo/workflows/ac-closure-check.yml:43     : > "$fixture_log"
                                        :44     python3 tests/fixtures/… > "$fixture_log" 2>&1 &

The file now exists before anything can read it, so sed's rc=2 can no longer abort the step on
its first iteration. Landed via #987 (@carpenter), merged at 43b32d3f.

⚠️ AC3 AND AC4 ARE NOT DISCHARGED BY THIS, and they are the half that survives

: > "$fixture_log" removes the race. It does not make the fixture did not publish a port
branch reachable in the case that matters, and that branch is the only thing that would tell you a
fixture crashed rather than stalled.

fixture exits immediately (crash)   → empty log → 50 polls → "did not publish a port" after 5s
fixture is merely slow              → empty log → 50 polls → "did not publish a port" after 5s

Two outcomes, one rendering, on the diagnostic that exists to distinguish them. The step does
cat "$fixture_log" in that branch, which is the right instinct — but a crashed fixture's traceback
and a slow fixture's empty file both arrive there, and only the cat output separates them, five
seconds late.

📌 Cheap discriminator for whoever takes it: check whether the background pid is still alive before
declaring a timeout. kill -0 "$fixture_pid" distinguishes "it died" from "it is slow"
immediately, and turns a 5-second silent wait into an instant, correctly-named failure.

Scope now remaining

~~The fixture log is created before the background process starts~~ — DONE in 43b32d3
~~The sed poll is NOT silenced~~ — DONE: no 2>/dev/null was added; the poll still speaks
An arm proves the fixture did not publish a port branch is REACHABLE
A stated check that the step distinguishes a fixture that exits immediately from one that is
merely slow — today those render identically after a 5s wait

📌 Retitle-worthy but not retitled: this tracker is now about the DIAGNOSTIC, not the race. Left as
filed so the anchor and the two-PR evidence stay legible.

## ✅ THE RACE IS CLOSED ON `main` — verified on the merged tree, not on the PR ``` origin/main 43b32d3 fix(ci): precreate AC fixture log before polling .forgejo/workflows/ac-closure-check.yml:43 : > "$fixture_log" :44 python3 tests/fixtures/… > "$fixture_log" 2>&1 & ``` **The file now exists before anything can read it, so `sed`'s rc=2 can no longer abort the step on its first iteration.** Landed via `#987` (@carpenter), merged at `43b32d3f`. ## ⚠️ AC3 AND AC4 ARE NOT DISCHARGED BY THIS, and they are the half that survives `: > "$fixture_log"` removes the race. **It does not make the `fixture did not publish a port` branch reachable in the case that matters**, and that branch is the only thing that would tell you a fixture **crashed** rather than **stalled**. ``` fixture exits immediately (crash) → empty log → 50 polls → "did not publish a port" after 5s fixture is merely slow → empty log → 50 polls → "did not publish a port" after 5s ``` **Two outcomes, one rendering, on the diagnostic that exists to distinguish them.** The step does `cat "$fixture_log"` in that branch, which is the right instinct — but a crashed fixture's traceback and a slow fixture's empty file both arrive there, and only the `cat` output separates them, five seconds late. 📌 **Cheap discriminator for whoever takes it: check whether the background pid is still alive before declaring a timeout.** `kill -0 "$fixture_pid"` distinguishes *"it died"* from *"it is slow"* immediately, and turns a 5-second silent wait into an instant, correctly-named failure. ## Scope now remaining - [x] ~~The fixture log is created before the background process starts~~ — **DONE in `43b32d3`** - [x] ~~The `sed` poll is NOT silenced~~ — **DONE: no `2>/dev/null` was added; the poll still speaks** - [ ] An arm proves the `fixture did not publish a port` branch is REACHABLE - [ ] A stated check that the step distinguishes a fixture that **exits immediately** from one that is merely **slow** — today those render identically after a 5s wait 📌 **Retitle-worthy but not retitled: this tracker is now about the DIAGNOSTIC, not the race.** Left as filed so the anchor and the two-PR evidence stay legible.

carpenter was assigned by bosun

2026-08-27 08:01:55 +02:00

release-bot referenced this issue

2026-08-27 19:07:07 +02:00

chore(release): v0.54.0 #1006

pullings commented

2026-08-27 23:28:20 +02:00

Owner

Implementation closeout

The remaining diagnostic work landed in rt#1011, merged at exact head df1e307c98, after official Sentry approval 6062 and Forgejo CI 25/25 success.

All four acceptance criteria are met:

the fixture log is created before the child starts;
the sed poll remains unsilenced, so genuine fixture output stays visible;
a live no-PORT child reaches the bounded timeout branch and asserts its diagnostic;
an immediate-crash child is distinguished from a merely slow child using the child status and separate diagnostics.

The merged controls were run through the extracted workflow step and the full test suite. No additional implementation is needed.

Refs frankenbit/release-toolkit#1011.

## Implementation closeout The remaining diagnostic work landed in rt#1011, merged at exact head df1e307c98276b1624db437c4e20fa0102305617, after official Sentry approval 6062 and Forgejo CI 25/25 success. All four acceptance criteria are met: - the fixture log is created before the child starts; - the sed poll remains unsilenced, so genuine fixture output stays visible; - a live no-PORT child reaches the bounded timeout branch and asserts its diagnostic; - an immediate-crash child is distinguished from a merely slow child using the child status and separate diagnostics. The merged controls were run through the extracted workflow step and the full test suite. No additional implementation is needed. Refs frankenbit/release-toolkit#1011.

pullings closed this issue

2026-08-27 23:28:40 +02:00