scripts/e2e-local.sh readiness probe hangs on a reused config dir #533

Closed
opened 2026-07-21 17:31:12 +02:00 by timothy · 3 comments
Owner

Problem

scripts/e2e-local.sh waits for a single fixed readiness line:

READY_LINE="Done migrating search index"

RebuildSearchIndexHandler emits that line only when the search index actually migrates — i.e. on a
fresh config dir. A reused config dir logs Search index is already version {Version} instead,
so READY_LINE never appears, the probe times out, and the script kills a perfectly healthy server.

docs/e2e-local.md documents the ready line and recommends a fresh config dir, but does not document
this failure mode. It cost a session two failed launches before the cause was found.

Fix

Accept either line:

grep -Eq "Done migrating search index|Search index is already version"

Provenance

Surfaced during the #502 session, recorded only in a comment on the closed tracker #237, and
recovered by the #524 triage — it was one of exactly two facts in #237 with no home anywhere else.

Done-when

  • The probe succeeds against both a fresh and a reused config dir.
  • docs/e2e-local.md documents the reuse path.
  • Adversarial review passed.

Resolved in PR #591 (scripts/e2e-local.sh, docs/e2e-local.md).

Verified with a negative control rather than just asserting the regex matches:

Config dir Ready via Time
fresh Done migrating search index in 482 milliseconds 5.4s
reused Search index is already version 50 2s

The control: the old probe string is genuinely absent from the reused-dir run's log, so the old code would have waited out the full 120s and killed the server. The fix is load-bearing, not incidentally passing.

Also confirmed the alternation is exhaustive by reading RebuildSearchIndexHandler — the two lines come from an if/else immediately before SystemStartup.SearchIndexIsReady(), so there is no third path to readiness. And the other consumer of this script is unaffected: scripts/e2e-functional.sh still passes 45/45.

Two things found while in here, both fixed in the same PR:

  • $! was the subshell, not the dotnet process, on bash 3.2 (stock macOS /bin/bash) because the script backgrounds a two-command subshell — so every PID-based kill and liveness check silently targeted the wrong process. Fixed with exec. (Measured: bash 3.2 → subshell; bash 5.3 → leaf; with exec → leaf on both.)
  • Two e2e-local.sh instances must never run concurrently, even on different ports: each rm -rfs and re-copies the same build-output wwwroot, so the second yanks the static files out from under a still-starting first. Now documented — the symptom (readiness timeout, or /app 404ing) looks nothing like a shared-directory race.

The "prefer a fresh config dir" guidance stays, on state-bleed grounds. The now-obsolete rationale in the testing.e2e-local-fresh-config-dir decision record was corrected in the same PR — it had still been asserting, as an active record, that this bug existed.

## Problem `scripts/e2e-local.sh` waits for a single fixed readiness line: ``` READY_LINE="Done migrating search index" ``` `RebuildSearchIndexHandler` emits that line only when the search index actually migrates — i.e. on a **fresh** config dir. A **reused** config dir logs `Search index is already version {Version}` instead, so `READY_LINE` never appears, the probe times out, and the script kills a perfectly healthy server. `docs/e2e-local.md` documents the ready line and recommends a fresh config dir, but does not document this failure mode. It cost a session two failed launches before the cause was found. ## Fix Accept either line: ```bash grep -Eq "Done migrating search index|Search index is already version" ``` ## Provenance Surfaced during the #502 session, recorded only in a comment on the closed tracker #237, and recovered by the #524 triage — it was one of exactly two facts in #237 with no home anywhere else. ## Done-when - [x] The probe succeeds against both a fresh and a reused config dir. - [x] `docs/e2e-local.md` documents the reuse path. - [x] Adversarial review passed. --- **Resolved in PR #591** (`scripts/e2e-local.sh`, `docs/e2e-local.md`). Verified with a **negative control** rather than just asserting the regex matches: | Config dir | Ready via | Time | |---|---|---| | fresh | `Done migrating search index in 482 milliseconds` | 5.4s | | **reused** | `Search index is already version 50` | **2s** | The control: the *old* probe string is genuinely **absent** from the reused-dir run's log, so the old code would have waited out the full 120s and killed the server. The fix is load-bearing, not incidentally passing. Also confirmed the alternation is **exhaustive** by reading `RebuildSearchIndexHandler` — the two lines come from an `if`/`else` immediately before `SystemStartup.SearchIndexIsReady()`, so there is no third path to readiness. And the other consumer of this script is unaffected: `scripts/e2e-functional.sh` still passes 45/45. Two things found while in here, both fixed in the same PR: - `$!` was the **subshell**, not the dotnet process, on bash 3.2 (stock macOS `/bin/bash`) because the script backgrounds a *two-command* subshell — so every PID-based kill and liveness check silently targeted the wrong process. Fixed with `exec`. (Measured: bash 3.2 → subshell; bash 5.3 → leaf; with `exec` → leaf on both.) - Two `e2e-local.sh` instances must never run concurrently, even on different ports: each `rm -rf`s and re-copies the *same* build-output `wwwroot`, so the second yanks the static files out from under a still-starting first. Now documented — the symptom (readiness timeout, or `/app` 404ing) looks nothing like a shared-directory race. The "prefer a fresh config dir" guidance stays, on **state-bleed** grounds. The now-obsolete rationale in the `testing.e2e-local-fresh-config-dir` decision record was corrected in the same PR — it had still been asserting, as an `active` record, that this bug existed.
timothy added the priority: low label 2026-07-21 17:31:12 +02:00
Author
Owner

🔗 Session bundle — E2E / test-harness infra: #445, #533, #563

Test-harness infrastructure: #445 (UI-interactive Playwright headless flows for functional-E2E), #533 (e2e-local.sh readiness probe hangs on a reused config dir), #563 (scripted-playout integration harness deferred from #381). Sibling to the just-landed #381 golden work; all live in the E2E/test tooling.

When you claim any member, check this cluster for co-workable siblings and sweep the disjoint set in one session (per docs/handoffs/chicorytv-issue-queue.md → bundles).

🔗 **Session bundle — E2E / test-harness infra:** #445, #533, #563 Test-harness infrastructure: #445 (UI-interactive Playwright headless flows for functional-E2E), #533 (e2e-local.sh readiness probe hangs on a reused config dir), #563 (scripted-playout integration harness deferred from #381). Sibling to the just-landed #381 golden work; all live in the E2E/test tooling. When you claim any member, check this cluster for co-workable siblings and sweep the disjoint set in one session (per docs/handoffs/chicorytv-issue-queue.md → bundles).
timothy added the in-progress label 2026-07-25 10:53:45 +02:00
Author
Owner

Claiming — swept into this session alongside #445 (both members of the 🔗 E2E / test-harness bundle; #563 deferred to a later session as a second large lift).

Approach is the fix in the body: widen the readiness probe in scripts/e2e-local.sh to a grep -Eq alternation over both lines (Done migrating search index on a fresh index migration, Search index is already version on a reused config dir), and document the reuse path in docs/e2e-local.md. The "prefer a fresh config dir" recommendation stays — that guards against state bleed, which is a separate concern from the probe hanging.

Will verify against both a fresh and a reused config dir (the Done-when criterion) rather than only asserting the regex matches.

Claiming — swept into this session alongside #445 (both members of the 🔗 E2E / test-harness bundle; #563 deferred to a later session as a second large lift). Approach is the fix in the body: widen the readiness probe in `scripts/e2e-local.sh` to a `grep -Eq` alternation over both lines (`Done migrating search index` on a fresh index migration, `Search index is already version` on a reused config dir), and document the reuse path in `docs/e2e-local.md`. The "prefer a fresh config dir" recommendation stays — that guards against *state bleed*, which is a separate concern from the probe hanging. Will verify against both a fresh and a reused config dir (the Done-when criterion) rather than only asserting the regex matches.
Author
Owner

Closing record

Outcome: Shipped in PR #591 (with #445, its bundle sibling). scripts/e2e-local.sh's readiness probe now matches a READY_REGEX alternation over both ready lines, so a reused config dir no longer times out and kills a healthy server. Two adjacent defects in the same script were fixed while in there (see Reusable knowledge).

Root cause: RebuildSearchIndexHandler has an if/else immediately before SystemStartup.SearchIndexIsReady() that logs one of two mutually-exclusive lines — Done migrating search index only when the index actually migrates (fresh config), Search index is already version {Version} when there is nothing to migrate (reused config). The probe hard-coded only the first. So the bug was not a race or a timing issue: the watched line is structurally unreachable on a reused dir, making the 120s timeout and the subsequent kill of a perfectly healthy server the guaranteed outcome. It read as a broken build, which is why it cost the #502 session two launches before anyone looked at the branch.

Decisions/conventions changed: No new key. testing.e2e-local-fresh-config-dir amended — it was still status: active while asserting this bug existed ("a reused one never emits the probe's ready line", "there is no 'wait for either line' option today", "widening the probe … is tracked as #533"), and READY_LINE survived only in that record, nowhere in code. Amended rather than superseded because the operative Rule (use a fresh config dir) never reversed — only its rationale moved from "the probe hangs" to "state bleed" — and the key is cited from docs/handoffs/chicorytv-issue-queue.md plus two docs/superpowers/ files that a supersession would have aimed at an archived record.

Reusable knowledge:

  1. $! can be the SUBSHELL, not the process you launched. ( cd X; cmd ) & backgrounds a two-command subshell, and bash only collapses that to the leaf on newer versions. Measured: bash 3.2.57 (stock macOS /bin/bash, which #!/usr/bin/env bash picks up without Homebrew bash on PATH) → $! is the subshell; bash 5.3 → leaf; with exec → leaf on both. Consequence when it bites: every PID-based kill and kill -0 liveness check silently targets the wrong process, so cleanup "succeeds" while the real server keeps the port. Fix is exec in the subshell. Note a single-command subshell is collapsed on both versions — so a naive test of this reproduces nothing and wrongly clears the bug.
  2. Two e2e-local.sh instances must never run concurrently, even on different ports. Each run rm -rfs and re-copies the same ErsatzTV/bin/<config>/net10.0/wwwroot, so the second pulls the static files out from under a still-starting first. Symptom is a readiness timeout or /app 404ing — nothing that suggests a shared-directory race. Found by accident when a badly-written verification of mine overlapped two instances.
  3. A negative control is what distinguishes "fixed" from "incidentally passing" here: the old probe string is genuinely absent from the reused-dir run's log, which is the proof the old code would have hung.

Verification: Fresh dir → ready in 5.4s via Done migrating search index in 482 milliseconds; reused dir → ready in 2s via Search index is already version 50, with the old probe string confirmed absent (negative control). Other consumer unaffected: scripts/e2e-functional.sh 45/45 PASS, re-checked after the exec change. CI green on head 7030bd28 — all six docker-build jobs plus all three PR gates.

Deferred: none for this issue.

Docs updated: docs/e2e-local.md (step-4 two-line readiness table + the never-run-concurrently warning + ETV_PIDFILE), docs/decisions/workflow-process.md (testing.e2e-local-fresh-config-dir amended), docs/decisions/README.md (regenerated).

## Closing record **Outcome:** Shipped in PR #591 (with #445, its bundle sibling). `scripts/e2e-local.sh`'s readiness probe now matches a `READY_REGEX` alternation over both ready lines, so a reused config dir no longer times out and kills a healthy server. Two adjacent defects in the same script were fixed while in there (see Reusable knowledge). **Root cause:** `RebuildSearchIndexHandler` has an `if`/`else` immediately before `SystemStartup.SearchIndexIsReady()` that logs one of **two** mutually-exclusive lines — `Done migrating search index` only when the index actually migrates (fresh config), `Search index is already version {Version}` when there is nothing to migrate (reused config). The probe hard-coded only the first. So the bug was not a race or a timing issue: the watched line is *structurally unreachable* on a reused dir, making the 120s timeout and the subsequent kill of a perfectly healthy server the guaranteed outcome. It read as a broken build, which is why it cost the #502 session two launches before anyone looked at the branch. **Decisions/conventions changed:** No new key. `testing.e2e-local-fresh-config-dir` **amended** — it was still `status: active` while asserting this bug existed ("a reused one never emits the probe's ready line", "there is no 'wait for either line' option today", "widening the probe … is tracked as #533"), and `READY_LINE` survived *only* in that record, nowhere in code. Amended rather than superseded because the operative Rule (use a fresh config dir) never reversed — only its rationale moved from "the probe hangs" to "state bleed" — and the key is cited from `docs/handoffs/chicorytv-issue-queue.md` plus two `docs/superpowers/` files that a supersession would have aimed at an archived record. **Reusable knowledge:** 1. **`$!` can be the SUBSHELL, not the process you launched.** `( cd X; cmd ) &` backgrounds a *two-command* subshell, and bash only collapses that to the leaf on newer versions. Measured: bash 3.2.57 (stock macOS `/bin/bash`, which `#!/usr/bin/env bash` picks up without Homebrew bash on PATH) → `$!` is the **subshell**; bash 5.3 → leaf; with `exec` → leaf on both. Consequence when it bites: every PID-based `kill` and `kill -0` liveness check silently targets the wrong process, so cleanup "succeeds" while the real server keeps the port. Fix is `exec` in the subshell. Note a single-command subshell is collapsed on *both* versions — so a naive test of this reproduces nothing and wrongly clears the bug. 2. **Two `e2e-local.sh` instances must never run concurrently, even on different ports.** Each run `rm -rf`s and re-copies the *same* `ErsatzTV/bin/<config>/net10.0/wwwroot`, so the second pulls the static files out from under a still-starting first. Symptom is a readiness timeout or `/app` 404ing — nothing that suggests a shared-directory race. Found by accident when a badly-written verification of mine overlapped two instances. 3. **A negative control is what distinguishes "fixed" from "incidentally passing"** here: the old probe string is genuinely *absent* from the reused-dir run's log, which is the proof the old code would have hung. **Verification:** Fresh dir → ready in 5.4s via `Done migrating search index in 482 milliseconds`; **reused dir → ready in 2s** via `Search index is already version 50`, with the old probe string confirmed absent (negative control). Other consumer unaffected: `scripts/e2e-functional.sh` **45/45 PASS**, re-checked after the `exec` change. CI green on head `7030bd28` — all six `docker-build` jobs plus all three PR gates. **Deferred:** none for this issue. **Docs updated:** `docs/e2e-local.md` (step-4 two-line readiness table + the never-run-concurrently warning + `ETV_PIDFILE`), `docs/decisions/workflow-process.md` (`testing.e2e-local-fresh-config-dir` amended), `docs/decisions/README.md` (regenerated).
timothy removed the in-progress label 2026-07-25 14:55:22 +02:00
Sign in to join this conversation.
1 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: timothy/ersatztv#533