How Do You Capture the Machine State When a Flaky Test Fails?

# server.py: a tiny service that keeps a session token and a hit count in memory
import faulthandler, os, random, signal, sys, time, secrets
from http.server import BaseHTTPRequestHandler, HTTPServer

faulthandler.register(signal.SIGUSR1, file=sys.stderr)  # kill -USR1 <pid> dumps Python stacks, process keeps running
seed = int(os.environ.get("FLAKY_SEED", "0"))
time.sleep(random.Random(seed).uniform(0.0, 0.4))         # slow, variable startup (cold caches, imports, a busy CPU)
token, hits = secrets.token_hex(4), 0

class H(BaseHTTPRequestHandler):
    def do_GET(self):
        global hits
        hits += 1
        body = f"token={token} hits={hits}\n".encode()
        self.send_response(200); self.end_headers(); self.wfile.write(body)
    def log_message(self, fmt, *args):
        print(f"{time.strftime('%H:%M:%S')} {fmt % args}", file=sys.stderr, flush=True)

print(f"listening seed={seed} pid={os.getpid()}", file=sys.stderr, flush=True)
HTTPServer(("127.0.0.1", 8765), H).serve_forever()

# test_server.py: sleeps a fixed 300 ms instead of waiting until the server is ready
import os, subprocess, sys, time, urllib.request

log = open("logs/server.log", "a")
srv = subprocess.Popen([sys.executable, "server.py"], stderr=log, env=os.environ)
time.sleep(0.3)                                            # the race
body = urllib.request.urlopen("http://127.0.0.1:8765/", timeout=2).read().decode()
assert body.startswith("token="), body
srv.terminate(); srv.wait()                                # cleanup only runs when the test passes
print("ok", body.strip())

#!/bin/bash
# run-until-fail.sh: run the flaky test until it fails, capture the machine state, then leave a marker
cd ~/flaky && mkdir -p logs ~/failure
max=${MAX_RUNS:-500}
for n in $(seq 1 "$max"); do
  seed=$RANDOM
  echo "$n $seed" > ~/failure/progress
  if FLAKY_SEED=$seed python3 test_server.py > "logs/run.log" 2>&1; then continue; fi

  # Failed: capture before anything changes. Everything goes under ~/failure (not /tmp).
  f=~/failure
  date -u +%FT%T.%3NZ > $f/failed-at
  cp logs/run.log $f/test-output.log; cp logs/server.log $f/server.log
  ps -eo pid,ppid,etimes,stat,rss,args --forest > $f/ps.txt
  ss -ltnp > $f/listening.txt 2>&1
  pid=$(pgrep -f 'python3 server.py' | head -1)
  if [ -n "$pid" ]; then
    echo "$pid" > $f/server.pid
    lsof -p "$pid" > $f/lsof.txt 2>&1
    kill -USR1 "$pid"; sleep 0.2                       # Python stacks into server.log; process keeps running
    cp logs/server.log $f/server.log
    command -v gcore >/dev/null && sudo gcore -o $f/core "$pid" > $f/gcore.log 2>&1
  fi
  echo "run=$n seed=$seed" > $f/FAILED                  # the outside loop watches for this file
  exit 1
done
echo "no failure in $max runs" > ~/failure/PASSED

sbx exec $id --timeout 300 "sudo apt-get update -qq >/dev/null 2>&1; sudo apt-get install -y -qq gdb >/dev/null 2>&1; which gcore"

/usr/bin/gcore

#!/bin/bash
# watch-and-capture.sh <sandbox-id>
set -u
id=$1
sbx exec $id --detach "bash ~/flaky/run-until-fail.sh" > /dev/null
until sbx exec $id "test -f ~/failure/FAILED -o -f ~/failure/PASSED"; do sleep 2; done
echo "$(date -u +%T) marker: $(sbx exec $id 'cat ~/failure/FAILED ~/failure/PASSED 2>/dev/null')"

# 1. Fork: a copy of the disk right now, to debug on without touching the original.
fork=$(sbx --json fork $id --name flaky-fork --ttl 3600 | jq -r '.id // .sandbox.id')
echo "$(date -u +%T) fork: $fork"

# 2. Artifacts out, while the leaked process is still running.
sbx exec $id "tar czf ~/failure.tgz -C ~ failure flaky/logs" && sbx scp $id:/home/user/failure.tgz .
echo "$(date -u +%T) artifacts: $(du -h failure.tgz | cut -f1)"

# 3. A named snapshot of the failing disk, to start new sandboxes from later.
sbx snapshot $id flaky-fail > /dev/null
echo "$(date -u +%T) named snapshot saved"

# 4. Stop: memory and processes are written to disk, the meter stops.
sbx stop $id --wait > /dev/null
echo "$(date -u +%T) stopped"

21:00:22 marker: run=3 seed=20005
21:00:22 fork:
21:00:25 artifacts: 2.5M
21:00:27 named snapshot saved
21:00:29 stopped

tar xzf failure.tgz && tail -1 failure/test-output.log && cat failure/server.log

urllib.error.URLError: <urlopen error [Errno 111] Connection refused>
listening seed=22682 pid=1063
21:00:20 "GET / HTTP/1.1" 200 -
listening seed=5225 pid=1070
21:00:21 "GET / HTTP/1.1" 200 -
listening seed=20005 pid=1072
Current thread 0x00007fb3f42f4080 (most recent call first):
  File "/usr/lib/python3.12/selectors.py", line 415 in select
  File "/usr/lib/python3.12/socketserver.py", line 235 in serve_forever
  File "/home/user/flaky/server.py", line 20 in <module>

    PID    PPID ELAPSED STAT   RSS COMMAND
    259       1   18310 Ssl  10332 /usr/local/bin/sbx-guest serve
   1055     259       1 S     3780  \_ bash /home/user/flaky/run-until-fail.sh
   1076    1055       0 R     4392      \_ ps -eo pid,ppid,etimes,stat,rss,args --forest
…
   1072       1       0 S    20612 /usr/bin/python3 server.py

LISTEN 0      5          127.0.0.1:8765      0.0.0.0:*    users:(("python3",pid=1072,fd=3))

sbx exec $fork --timeout 60 "cd ~/failure && gdb -batch -ex bt /usr/bin/python3 core.1072 2>&1 | grep -E '^#' | head -4"

#0  0x00007fb3f411b764 in __GI___poll (fds=0x7fb3f3f787b0, nfds=1, timeout=454) at ../sysdeps/unix/sysv/linux/poll.c:29
#1  0x00000000006d4935 in ?? ()
#2  0x0000000000551922 in ?? ()
#3  0x00000000005499b5 in PyObject_Vectorcall ()

sbx exec $fork "cat ~/failure/FAILED; ls ~/failure; curl -s -m 2 127.0.0.1:8765/ || echo connection refused"

run=3 seed=20005
core.1072
FAILED
failed-at
gcore.log
listening.txt
lsof.txt
progress
ps.txt
server.log
server.pid
test-output.log
connection refused