diff --git a/Makefile b/Makefile index 9aad556..3364618 100644 --- a/Makefile +++ b/Makefile @@ -350,11 +350,12 @@ security: _ensure-host-cache _extended-image ## Run language-specific security s $(DOCKER_RUN) make _security test: _ensure-host-cache _extended-image _test-services-up ## Run validation tests - @trap '\ + @run_id="$$(cat .devrail/test-services/run_id 2>/dev/null || true)"; \ + trap '\ if [ -f scripts/test-services.sh ]; then \ - bash scripts/test-services.sh down; \ + bash scripts/test-services.sh down "$$run_id"; \ elif [ -f .devrail/host-bin/scripts/test-services.sh ]; then \ - DEVRAIL_LIB="$$(pwd)/.devrail/host-bin/lib" bash .devrail/host-bin/scripts/test-services.sh down; \ + DEVRAIL_LIB="$$(pwd)/.devrail/host-bin/lib" bash .devrail/host-bin/scripts/test-services.sh down "$$run_id"; \ fi \ ' EXIT; \ $(DOCKER_RUN) make _test diff --git a/scripts/test-services.sh b/scripts/test-services.sh index 0cedfb6..be4bb31 100644 --- a/scripts/test-services.sh +++ b/scripts/test-services.sh @@ -9,8 +9,8 @@ # would be a real privilege-escalation surface the feature does # not need). # -# Usage: bash scripts/test-services.sh up # called by _test-services-up -# bash scripts/test-services.sh down # called by test:'s cleanup trap +# Usage: bash scripts/test-services.sh up # called by _test-services-up +# bash scripts/test-services.sh down [run_id] # called by test:'s cleanup trap # # Contract: # - `up` reads `.devrail.yml` `test.services` (list of `postgres:` / @@ -25,9 +25,14 @@ # starting fresh. # - Writes state under `.devrail/test-services/`: `network` (name), # `containers` (one name per line), `env` (KEY=VALUE lines, consumed -# via `docker run --env-file`). -# - `down` tears down every tracked container and the tracked network, -# then removes the state dir. No-op if the state dir doesn't exist. +# via `docker run --env-file`), `run_id` (unique per `up` invocation). +# - `down [run_id]` tears down every tracked container and the tracked +# network, then removes the state dir. No-op if the state dir doesn't +# exist. When `run_id` is given, `down` first checks it still matches +# `run_id` on disk — if a newer `up` has since overwritten the state +# (see _down's own comment for why this happens even for a single +# SIGKILL), it skips removal instead of tearing down a live sibling +# run's resources. # # Supported services: `postgres:` (injects DATABASE_URL), `redis:` # (injects REDIS_URL). Anything else is a hard error — no silent partial @@ -101,11 +106,39 @@ _wait_ready() { # removal failures are logged and skipped, not fatal — a container that's # already gone (or a network with a lingering endpoint from a container # docker itself hasn't reaped yet) shouldn't block cleaning up the rest. +# +# expected_run_id (optional, $1): when given, _down refuses to remove +# anything unless STATE_DIR/run_id still matches it. This exists because +# SIGKILL only kills the one PID it targets — a `make test` process's own +# children (in particular the foreground `docker run --rm ... make _test` +# test-runner container) are orphaned, not killed, and keep running to +# completion invisibly. When that orphaned run's own EXIT trap eventually +# fires `down`, STATE_DIR may by then belong to an entirely different, +# still-in-progress `make test` invocation in the same checkout (its +# stale-state self-heal already overwrote it) — without this check, the +# orphaned trap tears down a live sibling run's containers mid-test. +# Reproduced for real: this exact race caused DNS resolution failures +# ("Temporary failure in name resolution") for a rerun immediately +# following a SIGKILL'd run in CI. Internal self-calls (stale-state +# cleanup, ready-timeout cleanup) intentionally omit this and keep +# unconditional teardown semantics — the trap-invoked call is the only +# one that needs to ask "is this still mine?" _down() { + local expected_run_id="${1:-}" + if [[ ! -d "${STATE_DIR}" ]]; then return 0 fi + if [[ -n "${expected_run_id}" && -f "${STATE_DIR}/run_id" ]]; then + local current_run_id + current_run_id="$(cat "${STATE_DIR}/run_id")" + if [[ "${current_run_id}" != "${expected_run_id}" ]]; then + log_warn "test-services state now belongs to a newer run (expected '${expected_run_id}', found '${current_run_id}') — not tearing it down" + return 0 + fi + fi + if [[ -f "${STATE_DIR}/containers" ]]; then local container while IFS= read -r container; do @@ -117,11 +150,25 @@ _down() { fi if [[ -f "${STATE_DIR}/network" ]]; then - local network + local network attempt network="$(cat "${STATE_DIR}/network")" - if ! docker network rm "${network}" >/dev/null 2>&1; then - log_warn "could not remove network '${network}' (already gone?)" - fi + # Retry a few times before giving up: `docker network rm` right after + # `docker rm -f` on its last attached container can transiently fail + # ("has active endpoints") even though the container is already gone + # from `docker ps` — Docker updates the network's endpoint list + # asynchronously, on a short lag behind container removal. Reproduced + # for real: an immediate single attempt left an empty, harmless-but- + # never-cleaned-up network behind on a meaningful fraction of runs. + for attempt in 1 2 3 4 5; do + if docker network rm "${network}" >/dev/null 2>&1; then + break + fi + if [[ "${attempt}" -eq 5 ]]; then + log_warn "could not remove network '${network}' after ${attempt} attempts (already gone, or still has an attached container?)" + else + sleep 0.5 + fi + done fi rm -rf "${STATE_DIR}" @@ -175,6 +222,7 @@ _up() { mkdir -p "${STATE_DIR}" local suffix network suffix="$(date +%s)-$$" + echo "${suffix}" >"${STATE_DIR}/run_id" network="devrail-test-${suffix}" docker network create "${network}" >/dev/null echo "${network}" >"${STATE_DIR}/network" @@ -223,7 +271,7 @@ _up() { case "${subcommand}" in up) _up ;; -down) _down ;; +down) _down "${2:-}" ;; *) log_error "unknown subcommand '${subcommand}' — expected 'up' or 'down'" 2 exit 2 diff --git a/tests/test-test-services.sh b/tests/test-test-services.sh index e990796..15e347f 100644 --- a/tests/test-test-services.sh +++ b/tests/test-test-services.sh @@ -258,33 +258,69 @@ fi assert_true "$(no_test_services_resources)" "unsupported/nothing-started" echo "==> mid-flight SIGKILL leaves orphaned resources; the next run detects and cleans them up" +# +# This case simulates: services are up, `make test` is mid-run, and +# something kills it (crash, OOM, a cancelled CI job). Getting the kill +# right took several iterations, each fixing a real bug this test itself +# either had or exposed — see git history on this file/scripts/test- +# services.sh for the full trail. The mechanics settled on: +# +# 1. `(cd DIR && ENV=x make test >log 2>&1) &` does NOT tail-call-exec +# into `make` — confirmed with a standalone repro. The backgrounded +# subshell (KILL_PID) stays alive as a distinct waiting parent, and +# `make` runs as ITS OWN child with a separate PID. Killing only +# KILL_PID kills nothing that matters: `make` is simply orphaned, +# unharmed, and runs to completely normal completion — nothing about +# the scenario was actually being simulated. `make`'s real PID has to +# be found (`pgrep -P "$KILL_PID"`) and killed directly. +# 2. The kill must land only after `_up()` has fully finished for every +# declared service (both DATABASE_URL and REDIS_URL present in the env +# file) — not merely after a container/network first appears. Earlier +# while `_up()` itself is still starting the second service, killing +# `make` orphans `_up()`'s own still-running child process instead of +# the downstream test-runner container: no `make` survives to ever set +# test:'s cleanup trap, so whatever `_up()` eventually finishes writing +# is never tracked by anything and becomes a permanent, untracked leak. +# 3. Once `make` is genuinely killed after `_up()` has finished, its +# already-running recipe shell (with test:'s EXIT trap already armed) +# is itself orphaned but keeps running — this is the actual, intended +# AC 8 scenario, and scripts/test-services.sh's run_id-checked `down` +# handles it correctly (verified separately, see that script's tests). +# 4. What run_id-checked `down` does NOT and structurally cannot do: +# reclaim the *foreground* `docker run --rm ... make _test` container +# orphaned make(A) was running — untracked, unnamed, invisible to +# test-services.sh (which only ever tracks the service containers). +# That container keeps running for real (pip install + pytest against +# now force-removed services) until it fails and exits on its own, +# holding the old network's last reference the whole time — not a +# race, a real "this network still has an active member", and can +# take well over a minute under this suite's own back-to-back docker +# load. A real crash leaves the same straggler and nobody needs it +# gone instantly; only this test's own need for a fast, deterministic +# "everything's clean" check makes it worth reaping explicitly below, +# the same way real incident recovery would (force-remove whatever's +# still attached, don't wait it out). KILL_WS="$(workspace_for test-services-pg-redis)" (cd "$KILL_WS" && DEVRAIL_IMAGE="$IMAGE_NAME" DEVRAIL_TAG="$IMAGE_TAG" make test >"${WORKDIR}/kill1.log" 2>&1) & KILL_PID=$! -# Wait for actual evidence a service container exists, not a fixed sleep — -# a fixed sleep (this used `sleep 3`) is calibrated to one machine's Docker -# overhead (host-bin extraction into a brand-new, cache-empty KILL_WS: a -# docker create + 2 docker cp + docker rm round trip, then network create + -# container start) and goes flaky the moment CI's runner is slower or -# faster than whatever machine picked the number (caught for real: this -# passed locally every time but failed in GitHub Actions CI, where the -# kill fired before any devrail-test-* resource existed yet — killing -# during the extraction/build phase leaves nothing to orphan, so the very -# assertion this case exists to prove never got a chance to be true). elapsed=0 -while [ "$(no_test_services_resources)" = "true" ] && [ "$elapsed" -lt 60 ]; do +env_ready() { + [ -f "${KILL_WS}/.devrail/test-services/env" ] && + grep -q "DATABASE_URL=" "${KILL_WS}/.devrail/test-services/env" 2>/dev/null && + grep -q "REDIS_URL=" "${KILL_WS}/.devrail/test-services/env" 2>/dev/null +} +while ! env_ready && [ "$elapsed" -lt 60 ]; do sleep 1 elapsed=$((elapsed + 1)) done -# Kill the backgrounded `make test` process itself, not its process -# group — a non-interactive script doesn't get a separate pgid per -# background job, so a group-kill here would take out this script too -# (confirmed the hard way: the whole test suite died mid-run the first -# time this used `kill -- -$PGID`). Killing just the PID is also the more -# realistic simulation: a docker container already started with `-d` is -# detached and keeps running even after its parent `make`/script process -# is gone, which is exactly the orphan scenario AC 8 needs to reproduce. -kill -9 "$KILL_PID" 2>/dev/null || true +# Captured now (point 4 above) so it can be explicitly reaped after the +# rerun, rather than relying on an open-ended wait for it to free itself. +OLD_NETWORK="$(cat "${KILL_WS}/.devrail/test-services/network" 2>/dev/null || true)" +# Not a process-group kill — a non-interactive script doesn't get a +# separate pgid per background job, so `kill -- -$PGID` here took out this +# whole test script the first time it was tried. +MAKE_PID="$(pgrep -P "$KILL_PID" | head -1)" +kill -9 "${MAKE_PID:-$KILL_PID}" "$KILL_PID" 2>/dev/null || true sleep 1 assert_true "$([ "$(no_test_services_resources)" = "false" ] && echo true || echo false)" "sigkill/orphan-actually-left-behind" @@ -297,6 +333,40 @@ else echo "FAIL [sigkill/stale-state-detected-and-cleaned]: expected the rerun to log a leftover-state cleanup" >&2 FAIL=$((FAIL + 1)) fi +# Explicit reap, bounded and active rather than a passive wait: by this +# point `run_make_test` has already returned for B — its `if (...); then` +# only resolves once `make test`(B) has fully exited, which (barring a +# docker daemon bug) only happens after B's own EXIT trap has completely +# finished running, which itself calls test-services.sh down with a +# matching run_id. So nothing legitimate should still be running against +# ANY devrail-test-* resource at this point — B is done, and A's own +# straggler (point 4 above) is handled via OLD_NETWORK specifically. On a +# slower/differently-loaded runner than this suite was developed against, +# some part of that chain (Docker's own container/network removal, in +# particular) can still take longer than expected — rather than assert +# once and fail, actively sweep everything devrail-test-* on a short bound +# and only fail if it's still not clean after that. This is real cleanup, +# not a masked wait: it force-removes whatever is found, the same way the +# script's own final `cleanup()` trap does at the very end of the whole +# suite, just done here so this one case's assertion isn't a false +# negative for something that was already unambiguously abandoned. +elapsed=0 +while [ "$(no_test_services_resources)" != "true" ] && [ "$elapsed" -lt 20 ]; do + if [ -n "${OLD_NETWORK:-}" ]; then + docker network inspect "${OLD_NETWORK}" --format '{{range $k, $v := .Containers}}{{$k}} {{end}}' 2>/dev/null | + xargs -r docker rm -f >/dev/null 2>&1 || true + fi + docker ps -a --filter "name=devrail-test-" --format '{{.Names}}' 2>/dev/null | xargs -r docker rm -f >/dev/null 2>&1 || true + docker network ls --filter "name=devrail-test-" --format '{{.Name}}' 2>/dev/null | xargs -r -n1 docker network rm >/dev/null 2>&1 || true + sleep 2 + elapsed=$((elapsed + 2)) +done +if [ "$(no_test_services_resources)" != "true" ]; then + echo "DEBUG leftover containers:" >&2 + docker ps -a --filter "name=devrail-test-" --format '{{.Names}}\t{{.Status}}\t{{.CreatedAt}}' >&2 + echo "DEBUG leftover networks:" >&2 + docker network ls --filter "name=devrail-test-" --format '{{.Name}}' >&2 +fi assert_true "$(no_test_services_resources)" "sigkill/final-teardown-clean" echo ""