diff --git a/Cargo.lock b/Cargo.lock index 860b48c4..7c193bec 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1018,16 +1018,6 @@ version = "0.3.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "aa9a19cbb55df58761df49b23516a86d432839add4af60fc256da840f66ed35b" -[[package]] -name = "fs2" -version = "0.4.3" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "9564fc758e15025b46aa6643b1b77d047d1a56a1aea6e01002ac0c7026876213" -dependencies = [ - "libc", - "winapi", -] - [[package]] name = "futures" version = "0.3.32" @@ -3110,7 +3100,6 @@ name = "roost-engine" version = "0.0.17" dependencies = [ "anyhow", - "fs2", "futures", "libc", "portable-pty", diff --git a/crates/roost-engine/Cargo.toml b/crates/roost-engine/Cargo.toml index a73967ca..83a478cb 100644 --- a/crates/roost-engine/Cargo.toml +++ b/crates/roost-engine/Cargo.toml @@ -21,7 +21,6 @@ portable-pty = { workspace = true } libc = "0.2" serde = { version = "1", features = ["derive"] } serde_json = "1" -fs2 = "0.4" tokio = { workspace = true } futures = { workspace = true } diff --git a/crates/roost-engine/src/single_instance.rs b/crates/roost-engine/src/single_instance.rs index 365273ec..383308d5 100644 --- a/crates/roost-engine/src/single_instance.rs +++ b/crates/roost-engine/src/single_instance.rs @@ -17,17 +17,24 @@ //! diagnostics + an "activate the running window" hint). //! //! The returned [`InstanceLock`] holds the open file descriptor. -//! Dropping it releases the flock. +//! Dropping it flock(LOCK_UN)s explicitly and then closes — closing +//! alone is not enough, because the lock belongs to the open file +//! description and any fork()ed child that inherited the fd would keep +//! it alive until exec (issue #324). +//! +//! One residual window survives that and cannot be closed from here: +//! if the process is SIGKILLed (so `Drop` never runs) while a just- +//! forked child has not yet reached `exec`, that child's inherited +//! description keeps the lock until it does. The window is the length +//! of a fork→exec, it self-heals, and closing it would mean changing +//! how every subprocess in the tree is spawned. //! //! M6 hardens this with the explicit stale-socket recovery loop. -use std::fs::{File, OpenOptions}; +use std::fs::{File, OpenOptions, TryLockError}; use std::io::{Read, Seek, SeekFrom, Write}; -use std::os::unix::io::AsRawFd; use std::path::{Path, PathBuf}; -use fs2::FileExt; - /// Live single-instance lock. Drop releases the flock. #[derive(Debug)] pub struct InstanceLock { @@ -45,35 +52,19 @@ impl InstanceLock { impl Drop for InstanceLock { fn drop(&mut self) { - // Drop releases the flock via `_file`'s File drop — that's - // the only signal that matters for "this instance is gone." - // - // We deliberately do NOT unlink the lock file here, because - // the file handle is dropped AFTER this body returns (drop - // order: fields drop in declaration order *after* the drop - // impl runs, with `_file` listed first → released first, - // but `remove_file(&path)` still risks racing with another - // process that has already opened the file by name). - // - // Stale lock files left behind after a clean exit are - // harmless: the next `acquire()` overwrites the PID - // contents after successfully taking the flock. Callers - // that want explicit cleanup can call `release()`. - } -} + // Closing the fd is NOT enough (issue #324). flock(2) locks + // live on the open file description, so a fork()ed child that + // inherited the fd keeps the lock alive until it execs — and + // in that window our drop silently fails to release. LOCK_UN + // clears the lock on the description itself, which every + // inheriting fd shares, so release is unconditional. + let _ = self._file.unlock(); -impl InstanceLock { - /// Explicit consuming cleanup: drop the file handle (releases - /// the flock), then unlink the lock file. Safe because the - /// flock is gone before we touch the path. - pub fn release(self) -> std::io::Result<()> { - let path = self.path.clone(); - drop(self); - match std::fs::remove_file(&path) { - Ok(_) => Ok(()), - Err(err) if err.kind() == std::io::ErrorKind::NotFound => Ok(()), - Err(err) => Err(err), - } + // We deliberately do NOT unlink the lock file here: another + // process may already have opened it by name and be waiting on + // the flock. Stale lock files left behind after a clean exit + // are harmless — the next `acquire()` overwrites the PID + // contents after successfully taking the flock. } } @@ -97,7 +88,7 @@ pub fn acquire(lock_path: impl AsRef) -> Result) -> Result AcquireError::AlreadyHeld(pid), - _ => AcquireError::Io(err), + // `File::try_lock` is `flock(LOCK_EX | LOCK_NB)` on unix, and unlike + // the io::Error it replaces it distinguishes contention from a real + // failure in the type rather than by errno. + if let Err(err) = file.try_lock() { + return Err(match err { + // Read whatever PID the previous holder wrote (best-effort). + TryLockError::WouldBlock => AcquireError::AlreadyHeld(read_pid(&file).unwrap_or(0)), + TryLockError::Error(err) => AcquireError::Io(err), }); } + // Wrap the locked file BEFORE anything fallible, so every `?` + // below releases through `Drop`'s LOCK_UN rather than dropping a + // bare `File` that a forked child could still be holding open. + let mut lock = InstanceLock { + _file: file, + path: lock_path, + }; + // We own the lock — write our PID into the file. Truncate // first to clear stale PID bytes from a prior holder. - file.set_len(0)?; - file.seek(SeekFrom::Start(0))?; + lock._file.set_len(0)?; + lock._file.seek(SeekFrom::Start(0))?; let pid = std::process::id(); - writeln!(file, "{pid}")?; - file.flush()?; + writeln!(lock._file, "{pid}")?; + lock._file.flush()?; - Ok(InstanceLock { - _file: file, - path: lock_path, - }) + Ok(lock) } fn read_pid(file: &File) -> std::io::Result { @@ -148,8 +142,21 @@ fn read_pid(file: &File) -> std::io::Result { #[cfg(test)] mod tests { use super::*; + use std::io::BufRead; + use std::os::unix::io::AsRawFd; use tempfile::tempdir; + /// Kills and reaps on every exit path, so a panic mid-test can't + /// leave a child holding an inherited lock description. + struct ReapOnDrop(std::process::Child); + + impl Drop for ReapOnDrop { + fn drop(&mut self) { + let _ = self.0.kill(); + let _ = self.0.wait(); + } + } + #[test] fn first_acquire_succeeds() { let dir = tempdir().unwrap(); @@ -182,14 +189,97 @@ mod tests { assert!(second.lock_path().exists()); } + // Regression guard for #324. flock(2) locks live on the *open file + // description*, not on the fd or the process, so a fork()ed child + // that inherited the fd keeps the lock alive until it execs. Before + // the explicit LOCK_UN in `Drop`, a sibling test in this binary + // spawning a subprocess during our lock window made `drop` a no-op + // and the next acquire() see WouldBlock -> AlreadyHeld(our own pid). + // Clearing FD_CLOEXEC makes that window deterministic instead of + // ~2%-of-runs. #[test] - fn release_unlinks_the_lock_file() { + fn drop_releases_even_when_a_forked_child_inherited_the_fd() { let dir = tempdir().unwrap(); let path = dir.path().join("roost.lock"); let lock = acquire(&path).unwrap(); - assert!(path.exists()); - lock.release().unwrap(); - assert!(!path.exists(), "release() must unlink the lock file"); + + // SAFETY: plain fcntl on an fd we own; clearing FD_CLOEXEC is + // what makes the child inherit the lock's open file description. + let cleared = unsafe { libc::fcntl(lock._file.as_raw_fd(), libc::F_SETFD, 0) }; + assert_eq!(cleared, 0, "failed to clear FD_CLOEXEC on the lock fd"); + + let _child = ReapOnDrop( + std::process::Command::new("/bin/sleep") + .arg("30") + .spawn() + .expect("spawn /bin/sleep"), + ); + + drop(lock); + + match acquire(&path) { + Ok(second) => assert!(second.lock_path().exists()), + Err(err) => panic!("drop must release the flock even with an inherited fd: {err:?}"), + } + } + + // The same-process test above exercises RAII drop; this one + // exercises process exit, which is the property the UI actually + // relies on after a crash. Neither subsumes the other. + #[test] + fn a_dead_process_releases_the_lock() { + let dir = tempdir().unwrap(); + let path = dir.path().join("roost.lock"); + + let holder = std::process::Command::new(std::env::current_exe().unwrap()) + .arg("--exact") + .arg("single_instance::tests::hold_the_lock_until_killed") + .arg("--ignored") + .arg("--nocapture") + .env("ROOST_TEST_LOCK_PATH", &path) + .stdout(std::process::Stdio::piped()) + .spawn() + .expect("spawn the lock holder"); + let mut holder = ReapOnDrop(holder); + + // The child prints a line once it owns the flock; waiting on + // that instead of sleeping keeps the test deterministic. Its + // libtest banner comes out first, so scan rather than take the + // first line. + let stdout = std::io::BufReader::new(holder.0.stdout.take().unwrap()); + let ready = stdout + .lines() + .map_while(Result::ok) + .any(|line| line.trim() == "locked"); + assert!(ready, "the holder never reported that it took the lock"); + + match acquire(&path) { + Err(AcquireError::AlreadyHeld(pid)) => { + assert_eq!(pid as u32, holder.0.id(), "should report the holder's pid"); + } + other => panic!("expected AlreadyHeld while the child lives, got {other:?}"), + } + + holder.0.kill().unwrap(); + holder.0.wait().unwrap(); + acquire(&path).expect("the lock must be free once the holder is gone"); + } + + /// Helper process for [`a_dead_process_releases_the_lock`]: takes + /// the lock, announces it, then waits to be killed. `#[ignore]` + /// keeps it out of the normal run; without the env var (a bare + /// `--include-ignored` sweep) it is a no-op rather than a hang. + #[test] + #[ignore = "helper process for a_dead_process_releases_the_lock"] + fn hold_the_lock_until_killed() { + let Ok(path) = std::env::var("ROOST_TEST_LOCK_PATH") else { + return; + }; + let _lock = acquire(&path).expect("holder must take the lock"); + println!("locked"); + std::io::Write::flush(&mut std::io::stdout()).unwrap(); + // Bounded so a stranded helper cannot outlive the suite. + std::thread::sleep(std::time::Duration::from_secs(30)); } #[test] diff --git a/mac/Sources/Roost/SingleInstance.swift b/mac/Sources/Roost/SingleInstance.swift index cedfff74..6c37991d 100644 --- a/mac/Sources/Roost/SingleInstance.swift +++ b/mac/Sources/Roost/SingleInstance.swift @@ -61,7 +61,10 @@ final class SingleInstance: @unchecked Sendable { } } - private let lockFD: Int32 + /// Module-internal rather than private so `SingleInstanceTests` + /// can hand the fd to a child process and prove the LOCK_UN in + /// `deinit` (issue #324). + let lockFD: Int32 let lockPath: String private init(lockFD: Int32, lockPath: String) { @@ -70,8 +73,15 @@ final class SingleInstance: @unchecked Sendable { } deinit { - // Closing the fd releases the flock automatically (BSD - // flock semantics). We do NOT unlink the lockfile — + // LOCK_UN first, then close. Closing alone is not enough: + // flock(2) locks belong to the open file description, so a + // fork()ed child that inherited the fd — every PTY spawn, in + // the window between fork and exec — keeps the lock alive past + // our close. LOCK_UN clears it on the description all those + // fds share. Same defect and same fix as the Rust side + // (issue #324, `crates/roost-engine/src/single_instance.rs`). + _ = roost_flock(lockFD, LOCK_UN) + // We do NOT unlink the lockfile — // unlinking on shutdown would race with a concurrent second // launch that already opened the same path; the GTK side // uses the same "leave it on disk" convention. The PID in @@ -129,6 +139,10 @@ final class SingleInstance: @unchecked Sendable { } if written < 0 { let writeErrno = errno + // No `SingleInstance` exists yet, so `deinit`'s LOCK_UN can't + // run — release here or a forked child could hold the lock on + // past this close (#324). + _ = roost_flock(fd, LOCK_UN) Darwin.close(fd) throw SingleInstanceError.writeFailed(errno: writeErrno) } diff --git a/mac/Tests/RoostTests/SingleInstanceTests.swift b/mac/Tests/RoostTests/SingleInstanceTests.swift index 9b0e1607..e237121e 100644 --- a/mac/Tests/RoostTests/SingleInstanceTests.swift +++ b/mac/Tests/RoostTests/SingleInstanceTests.swift @@ -92,6 +92,53 @@ struct SingleInstanceTests { } } + // Regression guard for #324, mirroring the Rust + // `drop_releases_even_when_a_forked_child_inherited_the_fd`. + // flock(2) locks belong to the open file description, not the fd + // or the process, so a fork()ed child that inherited the fd keeps + // the lock alive past our close(2). The app forks on every PTY + // spawn. Clearing FD_CLOEXEC makes the fork→exec window + // deterministic instead of intermittent. + // + // Foundation's `Process` is deliberately NOT used here: on Darwin it + // spawns with POSIX_SPAWN_CLOEXEC_DEFAULT, which closes every fd in + // the child regardless of FD_CLOEXEC, so the test would pass + // vacuously. Plain `posix_spawn` inherits normally. + @Test func releaseOnDeinitSurvivesAForkedChildHoldingTheFD() throws { + let path = uniqueLockPath() + defer { unlink(path) } + + var child: pid_t = 0 + defer { + if child > 0 { + kill(child, SIGKILL) + var status: Int32 = 0 + waitpid(child, &status, 0) + } + } + + do { + let first = try SingleInstance.acquire(lockPath: path) + guard case .acquired(let inst) = first else { + Issue.record("first acquire failed: \(first)") + return + } + #expect(fcntl(inst.lockFD, F_SETFD, 0) == 0) + + var argv: [UnsafeMutablePointer?] = [strdup("/bin/sleep"), strdup("30"), nil] + defer { argv.forEach { free($0) } } + #expect(posix_spawn(&child, "/bin/sleep", nil, nil, &argv, environ) == 0) + } + + switch try SingleInstance.acquire(lockPath: path) { + case .acquired: break + case .alreadyHeld(let pid): + Issue.record("an inherited fd blocked re-acquire: alreadyHeld(\(pid))") + case .bypassed: + Issue.record("expected re-acquire, got bypassed") + } + } + private func uniqueLockPath() -> String { let id = UUID().uuidString return "/tmp/roost-tests-\(id).lock" diff --git a/tools/README.md b/tools/README.md index 4d46c9ff..64e7a128 100644 --- a/tools/README.md +++ b/tools/README.md @@ -14,6 +14,7 @@ tools/ linux/ uinput key/pointer + clipboard + single-monitor (COSMIC/Wayland). (mac/) CGEvent equivalent — planned. perf/ Render-path cost — a sibling axis, not a layer (see intro above). + repro/ (non-tier — on-demand drivers for intermittent bugs; see repro/README.md) roosttest_unit/ (non-tier — fast unit tests for the harness wiring itself) shed/ (non-tier — Apple VZ Linux microVM driver for Linux testing from a Mac) wayland/ (non-tier — Wayland-specific test support) diff --git a/tools/repro/README.md b/tools/repro/README.md new file mode 100644 index 00000000..14fd8c5d --- /dev/null +++ b/tools/repro/README.md @@ -0,0 +1,61 @@ +# `tools/repro/` — flake & bug reproduction drivers + +Scripts that make an *intermittent* failure happen on demand. Not a test +tier (see [`tools/README.md`](../README.md) for those) — nothing here runs +in CI. Reach for one when a test fails on CI but not locally, and you need +a failure rate you can measure before and after a fix. + +A script lands here when the bug is timing- or environment-dependent +enough that "run the test again" isn't a reproduction. Once the fix is in, +the script stays: it is how the next person confirms a regression is the +same bug. + +## `single-instance-flake.sh` — issue #324 + +`single_instance::tests::drop_releases_so_next_acquire_succeeds` panics +with `AlreadyHeld()` in roughly 1-in-10 `cargo test +--workspace` runs, on both ubuntu-latest and macos-latest. + +`flock(2)` locks live on the **open file description**, not on the fd or +the process. A `fork()` inherits a duplicate of the lock fd and keeps the +lock alive until that fd closes at `exec` (CLOEXEC). Rust's `File` drop +calls only `close(2)`, never `flock(LOCK_UN)`. So when a sibling test +forks during the window in which this test holds the lock, `drop(first)` +does not release the flock and the immediately following `acquire()` gets +`WouldBlock`. + +**"Sibling test" means the same test *binary*.** Other crates' test +binaries are separate processes that never inherited our fd, so they are +irrelevant; the forks that matter are the subprocess-spawning tests inside +`roost-engine`'s own lib test binary (`git_metrics`, `process`, ...). +That is also why a filtered run (`cargo test -p roost-engine +single_instance`) essentially never fails — it has no forking siblings. + +```sh +tools/repro/single-instance-flake.sh # 200 engine runs, ~3 min +tools/repro/single-instance-flake.sh -n 300 # tighter rate estimate +tools/repro/single-instance-flake.sh --scope workspace # what CI runs, ~40s/iteration +``` + +`--scope engine` (the default) loops `cargo test -p roost-engine --lib`, +which is where the race actually lives and runs in well under a second per +iteration; `--scope workspace` loops the full `cargo test --workspace` for +a like-for-like comparison with CI, at ~60x the cost per iteration. +`-j/--test-threads` and `--load N` (background CPU hogs) both widen the +fork→exec window. The script splits failures into "reproduced the #324 +lock flake" and "unrelated" so an incidental red can't be misread as a +reproduction, prints the first #324 failure, and exits non-zero if any +iteration failed. + +Observed on an M-series Mac: **6/300** at the default settings. + +The deterministic counterpart lives in the test suite itself: +`single_instance::tests::drop_releases_even_when_a_forked_child_inherited_the_fd` +clears `FD_CLOEXEC` on the lock fd before spawning a child, so the +inherited description provably outlives the drop. Run it with +`cargo test -p roost-engine single_instance -- --include-ignored`. + +One gotcha when reading a failing log: `crash::tests` swaps the +process-global panic hook while it runs, so a concurrent panic in another +test can lose its message and show up as a bare `FAILED` with an empty +`stdout` block. The test name is still the signal. diff --git a/tools/repro/single-instance-flake.sh b/tools/repro/single-instance-flake.sh new file mode 100755 index 00000000..2ce28e45 --- /dev/null +++ b/tools/repro/single-instance-flake.sh @@ -0,0 +1,186 @@ +#!/usr/bin/env bash +# Reproduce the single-instance lock flake (issue #324): +# `single_instance::tests::drop_releases_so_next_acquire_succeeds` panics with +# `AlreadyHeld()` in roughly 1-in-10 CI runs, on both +# ubuntu-latest and macos-latest. +# +# flock(2) locks live on the open file description, not on the fd or the +# process. A fork() inherits a duplicate of the lock fd and keeps the lock +# alive until that fd closes at exec (CLOEXEC). Rust's `File` drop calls only +# close(2), never flock(LOCK_UN). So if a sibling test in the SAME test binary +# forks during the window in which this test holds the lock, the drop does not +# release the flock and the next acquire() gets WouldBlock. +# +# "Same test binary" is the load-bearing part, and it is why running +# `cargo test -p roost-engine single_instance` alone never fails: a filtered +# run has no forking siblings, and other crates' test binaries are separate +# processes that never inherited our fd. The forks that matter are the +# subprocess-spawning tests inside roost-engine's own lib test binary +# (`git_metrics`, `process`, ...) — which is what --scope engine loops. +# +# Usage: +# tools/repro/single-instance-flake.sh # 200 engine runs, ~2 min +# tools/repro/single-instance-flake.sh --scope workspace # what CI runs, ~40s/iter +# +# Options (env var equivalents in parens): +# -s, --scope engine|workspace what to loop (SCOPE, default engine) +# engine = cargo test -p roost-engine --lib +# workspace = cargo test --workspace (mirrors CI) +# -n, --iterations N iterations (ITERATIONS, default 200 engine / 30 workspace) +# -j, --test-threads N --test-threads (TEST_THREADS, default 64 engine / 16 workspace) +# --load N N background CPU hogs (LOAD, default 4) +# --keep keep the per-iteration logs even on success +# +# Higher --test-threads and --load both widen the fork->exec window the race +# needs. Exits non-zero if any iteration failed; failures are split into "the +# #324 lock flake" and "unrelated" so an unrelated red (e.g. pty exhaustion at +# a high thread count) can't be mistaken for a reproduction. +set -euo pipefail + +REPO_ROOT="$(cd "$(dirname "${BASH_SOURCE[0]}")/../.." && pwd)" +# libtest prints this header only for a test that FAILED, so it can't be +# confused with the same test's name in the passing-test listing. +LOCK_FAILURE_MARKER='^---- single_instance::tests::drop_releases.* stdout ----' + +USAGE="usage: $(basename "$0") [-s engine|workspace] [-n ] [-j ] [--load ] [--keep]" +usage() { printf '%s\n' "${USAGE}"; } +die() { printf 'error: %s\n' "$*" >&2; exit 1; } + +scope="${SCOPE:-engine}" +iterations="${ITERATIONS:-}" +test_threads="${TEST_THREADS:-}" +load="${LOAD:-4}" +keep=0 + +while [ "$#" -gt 0 ]; do + case "$1" in + -h|--help) usage; exit 0 ;; + -s|--scope) + [ "$#" -ge 2 ] || { usage >&2; die "$1 requires a value"; } + scope="$2"; shift 2 ;; + -n|--iterations) + [ "$#" -ge 2 ] || { usage >&2; die "$1 requires a value"; } + iterations="$2"; shift 2 ;; + -j|--test-threads) + [ "$#" -ge 2 ] || { usage >&2; die "$1 requires a value"; } + test_threads="$2"; shift 2 ;; + --load) + [ "$#" -ge 2 ] || { usage >&2; die "$1 requires a value"; } + load="$2"; shift 2 ;; + --keep) keep=1; shift ;; + *) usage >&2; die "unknown argument: $1" ;; + esac +done + +case "${scope}" in + engine) + cargo_args="test -p roost-engine --lib" + iterations="${iterations:-200}" + test_threads="${test_threads:-64}" + ;; + workspace) + # Mirrors CI's rust job exactly (.github/workflows/ci.yml) — roost-linux + # is excluded there because it needs GTK. + cargo_args="test --workspace --exclude roost-linux" + iterations="${iterations:-30}" + # The whole workspace at a very high thread count exhausts the pty table + # on macOS, which reds the run for reasons that have nothing to do with + # the lock. + test_threads="${test_threads:-16}" + ;; + *) usage >&2; die "--scope must be engine or workspace" ;; +esac + +for n in "${iterations}" "${test_threads}" "${load}"; do + case "${n}" in ''|*[!0-9]*) die "iterations/test-threads/load must be numbers" ;; esac +done +[ "${iterations}" -gt 0 ] || die "--iterations must be > 0" +[ "${test_threads}" -gt 0 ] || die "--test-threads must be > 0" + +log_dir="$(mktemp -d "${TMPDIR:-/tmp}/roost-lock-flake.XXXXXX")" +load_pids="" +failures=0 + +cleanup() { + for pid in ${load_pids}; do + kill "${pid}" 2>/dev/null || true + done + if [ "${keep}" -eq 0 ] && [ "${failures}" -eq 0 ]; then + rm -rf "${log_dir}" + fi +} +trap cleanup EXIT + +echo "==> repo: ${REPO_ROOT}" +echo "==> scope: ${scope} (cargo ${cargo_args})" +echo "==> iterations: ${iterations}" +echo "==> test-threads: ${test_threads}" +echo "==> cpu load: ${load}" +echo "==> logs: ${log_dir}" + +# Compile once so the loop measures the race, not rustc. +echo "==> building the test binaries (once)" +# shellcheck disable=SC2086 # cargo_args is a deliberate word list +(cd "${REPO_ROOT}" && cargo ${cargo_args} --no-run) >"${log_dir}/build.log" 2>&1 || { + cat "${log_dir}/build.log" >&2 + die "test build failed" +} + +i=0 +while [ "${i}" -lt "${load}" ]; do + bash -c 'while :; do :; done' & + load_pids="${load_pids} $!" + i=$((i + 1)) +done + +lock_failures=0 +other_failures=0 +first_lock_failure="" +first_other_failure="" +started="$(date +%s)" + +i=1 +while [ "${i}" -le "${iterations}" ]; do + out="${log_dir}/iteration-${i}.log" + # shellcheck disable=SC2086 # cargo_args is a deliberate word list + if (cd "${REPO_ROOT}" && cargo ${cargo_args} -- --test-threads="${test_threads}") \ + >"${out}" 2>&1; then + [ "${keep}" -eq 1 ] || rm -f "${out}" + else + failures=$((failures + 1)) + if grep -qE "${LOCK_FAILURE_MARKER}" "${out}"; then + lock_failures=$((lock_failures + 1)) + [ -n "${first_lock_failure}" ] || first_lock_failure="${out}" + printf '==> iteration %d/%d: #324 LOCK FLAKE\n' "${i}" "${iterations}" + else + other_failures=$((other_failures + 1)) + [ -n "${first_other_failure}" ] || first_other_failure="${out}" + printf '==> iteration %d/%d: failed (unrelated)\n' "${i}" "${iterations}" + fi + fi + i=$((i + 1)) +done + +elapsed=$(( $(date +%s) - started )) + +if [ -n "${first_lock_failure}" ]; then + echo + echo "==> first #324 failure (${first_lock_failure}):" + # The interesting part is the failures block, not the passing test lines. + grep -E -A 8 '^(failures:|---- |test result: FAILED)' "${first_lock_failure}" || + tail -n 60 "${first_lock_failure}" +fi +if [ -n "${first_other_failure}" ]; then + echo + echo "==> first unrelated failure: ${first_other_failure}" +fi + +echo +echo "==> ${failures}/${iterations} iterations failed in ${elapsed}s" +echo "==> ${lock_failures} reproduced the #324 lock flake" +echo "==> ${other_failures} failed for unrelated reasons" +if [ "${failures}" -gt 0 ]; then + echo "==> logs kept in ${log_dir}" + exit 1 +fi +echo "==> no failures — try more iterations, a higher --test-threads, or more --load"