diff --git a/CHANGELOG.md b/CHANGELOG.md index 13845549..5333a744 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -6,6 +6,24 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +### Fixed — test flakiness: sigterm-shutdown readiness + BGSAVE file polling + +- `tests/sigterm_shutdown.rs`: `wait_for_ready` now distinguishes a crashed + child (fails fast via `try_wait()` instead of burning the full deadline) + from a genuinely slow-to-start one, and every readiness panic surfaces the + captured `moon.stdout.log` / `moon.stderr.log` so a real failure stays + diagnosable. The readiness deadline also doubles under `CI` (60s → 120s) — + the observed flake was macOS CI runner startup latency under load, not a + hang in the SIGTERM path under test. +- `tests/integration.rs`: `test_bgsave_creates_rdb_file` and its two siblings + that shut down and restart a server right after `bgsave_with_retry` + (`test_rdb_restore_on_startup`, `test_aof_priority_over_rdb`) asserted + `dump.rdb` existence off a fixed 200ms guess-sleep — BGSAVE queues the + write on a `spawn_blocking` thread and replies before it lands on disk. + Added a `wait_for_file` bounded-poll helper (50ms interval, 10s deadline) + and used it at all three call sites in place of the point-in-time + assumption. The MOON-magic-bytes assertion is unchanged. + ### Docs — Roadmap: native `moon://` / `moons://` connection URI scheme - Define Moon's native connection URI scheme in `docs/roadmap/ROADMAP.md` as a diff --git a/tests/integration.rs b/tests/integration.rs index adb63d3b..f8b96a42 100644 --- a/tests/integration.rs +++ b/tests/integration.rs @@ -1293,13 +1293,21 @@ async fn test_hscan() { // ===== Phase 4: Persistence Integration Tests ===== /// Issue BGSAVE, retrying if another test's save is still in progress (global AtomicBool). +/// +/// The 200ms sleep below is only a brief settle before returning to the +/// caller — BGSAVE queues the write on a `spawn_blocking` thread +/// (`bgsave_start` in `src/command/persistence.rs`) and replies immediately, +/// so the sleep is NOT a completion guarantee. Callers that depend on the RDB +/// file actually being on disk (e.g. before asserting its existence, or +/// before shutting the server down for a restart-and-restore test) MUST poll +/// via `wait_for_file` — a fixed sleep here is a point-in-time guess that +/// flakes under CI host load (thread-pool scheduling delay). async fn bgsave_with_retry(conn: &mut redis::aio::MultiplexedConnection) { for attempt in 0..20 { let result: Result = redis::cmd("BGSAVE").query_async(conn).await; match result { Ok(msg) => { assert_eq!(msg, "Background saving started"); - // Wait for save to complete tokio::time::sleep(std::time::Duration::from_millis(200)).await; return; } @@ -1313,6 +1321,30 @@ async fn bgsave_with_retry(conn: &mut redis::aio::MultiplexedConnection) { } } +/// Poll for a file to exist and be non-empty, with a bounded deadline. +/// +/// Use after `bgsave_with_retry` (or any other command that queues +/// background disk I/O) instead of asserting the file's presence +/// immediately or after a fixed guess-sleep — the write completes on a +/// separate thread whose scheduling is host-load dependent, so a +/// point-in-time check flakes under CI load even though the save always +/// eventually completes. +async fn wait_for_file(path: &std::path::Path, timeout: std::time::Duration) -> bool { + let start = std::time::Instant::now(); + loop { + if std::fs::metadata(path) + .map(|m| m.len() > 0) + .unwrap_or(false) + { + return true; + } + if start.elapsed() >= timeout { + return false; + } + tokio::time::sleep(std::time::Duration::from_millis(50)).await; + } +} + /// Start a server with custom persistence config on a random port. async fn start_server_with_persistence( appendonly: &str, @@ -1442,9 +1474,15 @@ async fn test_bgsave_creates_rdb_file() { // BGSAVE (retry if another test's save is still in progress) bgsave_with_retry(&mut conn).await; - // Verify dump.rdb exists + // Verify dump.rdb exists. BGSAVE replies as soon as the save is queued + // (the write itself happens on a spawn_blocking thread), so poll with a + // bounded deadline instead of asserting immediately -- see + // `wait_for_file` doc comment. let rdb_path = dir.join("dump.rdb"); - assert!(rdb_path.exists(), "dump.rdb should exist after BGSAVE"); + assert!( + wait_for_file(&rdb_path, std::time::Duration::from_secs(10)).await, + "dump.rdb should exist after BGSAVE (timed out waiting for the background save)" + ); // Verify file starts with MOON magic bytes let data = std::fs::read(&rdb_path).unwrap(); @@ -1507,6 +1545,14 @@ async fn test_rdb_restore_on_startup() { // BGSAVE bgsave_with_retry(&mut conn).await; + // Make sure the RDB actually landed on disk before shutting the + // server down -- otherwise the restart-and-restore below can race + // the background save under CI host load. + assert!( + wait_for_file(&dir.join("dump.rdb"), std::time::Duration::from_secs(10)).await, + "dump.rdb should exist after BGSAVE (timed out waiting for the background save)" + ); + shutdown.cancel(); tokio::time::sleep(std::time::Duration::from_millis(100)).await; } @@ -1672,6 +1718,14 @@ async fn test_aof_priority_over_rdb() { let _: () = conn.set("key1", "rdb_value").await.unwrap(); bgsave_with_retry(&mut conn).await; + // Make sure the RDB snapshot ("rdb_value") actually landed on disk + // before shutdown -- otherwise the restart below can race the + // background save under CI host load. + assert!( + wait_for_file(&dir.join("dump.rdb"), std::time::Duration::from_secs(10)).await, + "dump.rdb should exist after BGSAVE (timed out waiting for the background save)" + ); + // Overwrite in AOF (but RDB already has "rdb_value") let _: () = conn.set("key1", "aof_value").await.unwrap(); diff --git a/tests/sigterm_shutdown.rs b/tests/sigterm_shutdown.rs index cd10a097..00de638c 100644 --- a/tests/sigterm_shutdown.rs +++ b/tests/sigterm_shutdown.rs @@ -25,7 +25,8 @@ fn moon_binary() -> std::path::PathBuf { std::path::PathBuf::from(env!("CARGO_BIN_EXE_moon")) } -/// Readiness poll deadline (RSS/CPU wave 5, item C8). +/// Readiness poll deadline (RSS/CPU wave 5, item C8; widened again below for +/// the sigterm-shutdown flake hardening pass). /// /// Was a fixed 15s, hardcoded independently at each `wait_for_ready` call /// site — PR #218 documented this as a flake under host load (shared/ @@ -37,6 +38,33 @@ fn moon_binary() -> std::path::PathBuf { /// tick of it happening), but tolerates a slow CI host without flaking. const READY_TIMEOUT: Duration = Duration::from_secs(60); +/// CI-aware readiness deadline: doubles `READY_TIMEOUT` when the `CI` env var +/// is set (GitHub Actions and effectively every other CI provider sets it). +/// +/// A loaded macOS CI runner just needs longer to fork+exec+bind+listen the +/// spawned `moon` binary — this is startup latency, not a hang, and the poll +/// loop already retries every 100ms rather than sleeping once and giving up. +/// Local `cargo test` runs stay at the already-generous 60s base so a +/// genuinely broken server still fails a local run promptly. +fn ready_timeout() -> Duration { + if std::env::var_os("CI").is_some() { + READY_TIMEOUT * 2 + } else { + READY_TIMEOUT + } +} + +/// Read a captured child-process log file for diagnostics. Tolerates a +/// missing/unreadable file — this runs on a failure path and must never +/// itself panic (that would mask the real failure with a confusing one). +fn read_log(path: &std::path::Path) -> String { + match std::fs::read_to_string(path) { + Ok(s) if s.trim().is_empty() => "".to_string(), + Ok(s) => s, + Err(e) => format!(""), + } +} + /// Pick an ephemeral port by binding :0 and releasing it. /// /// Note: classic TOCTOU race — another process can grab the port between the @@ -49,11 +77,33 @@ fn free_port() -> u16 { p } -/// Poll TCP connect until the server is ready or deadline expires. -/// Returns true if we received a PONG within the deadline. -fn wait_for_ready(port: u16, deadline: Duration) -> bool { +/// Outcome of polling for server readiness. +enum Readiness { + /// TCP connect + PING/PONG round-tripped within the deadline. + Ready, + /// The child process exited (crashed, or exited some other way) before + /// ever becoming ready — a REAL failure, distinct from "just slow". + Exited(std::process::ExitStatus), + /// Neither happened before the deadline. On a loaded CI host this is + /// almost always still-starting-up, not a hang. + TimedOut, +} + +/// Poll TCP connect until the server is ready, the child process exits, or +/// the deadline expires. +/// +/// Checking `try_wait()` every iteration means a genuinely crashed server +/// fails fast (within one 100ms tick) instead of burning the entire +/// `deadline` budget polling a socket nothing will ever bind — the old +/// bool-returning version couldn't distinguish "slow to start" from "already +/// dead", so a real crash looked identical to a loaded CI host and both +/// produced the same uninformative "did not become ready" panic. +fn wait_for_ready(child: &mut std::process::Child, port: u16, deadline: Duration) -> Readiness { let start = Instant::now(); while start.elapsed() < deadline { + if let Ok(Some(status)) = child.try_wait() { + return Readiness::Exited(status); + } let addr = format!("127.0.0.1:{port}"); if let Ok(mut s) = TcpStream::connect_timeout(&addr.parse().expect("addr"), Duration::from_millis(200)) @@ -64,14 +114,40 @@ fn wait_for_ready(port: u16, deadline: Duration) -> bool { let mut buf = [0u8; 16]; if let Ok(n) = s.read(&mut buf) { if buf[..n].windows(4).any(|w| w == b"PONG") { - return true; + return Readiness::Ready; } } } } std::thread::sleep(Duration::from_millis(100)); } - false + Readiness::TimedOut +} + +/// Build a diagnostic panic message for a non-`Ready` outcome, surfacing the +/// child's captured stdout/stderr so a REAL failure (crash, bind error, panic +/// in `main`) is still diagnosable instead of just "did not become ready". +fn readiness_failure_message( + label: &str, + port: u16, + dir: &std::path::Path, + deadline: Duration, + outcome: &Readiness, +) -> String { + let stdout = read_log(&dir.join("moon.stdout.log")); + let stderr = read_log(&dir.join("moon.stderr.log")); + let what = match outcome { + Readiness::Exited(status) => { + format!("server process exited with {status:?} before becoming ready") + } + Readiness::TimedOut => { + format!("server did not become ready within {deadline:?} (process still running)") + } + Readiness::Ready => unreachable!("readiness_failure_message called with Ready"), + }; + format!( + "[{label}] {what} on port {port}\n--- moon.stdout.log ---\n{stdout}\n--- moon.stderr.log ---\n{stderr}" + ) } /// Send SIGTERM to the given PID using `kill -TERM`. @@ -143,16 +219,16 @@ fn assert_sigterm_clean_exit_shards( let pid = child.id(); - // Wait for the server to be ready (load-tolerant deadline; see - // READY_TIMEOUT doc comment). - let ready = wait_for_ready(port, READY_TIMEOUT); - if !ready { + // Wait for the server to be ready (CI-aware, load-tolerant deadline; see + // ready_timeout() doc comment). wait_for_ready also fails fast on an + // early process exit rather than burning the whole budget. + let deadline = ready_timeout(); + let outcome = wait_for_ready(&mut child, port, deadline); + if !matches!(outcome, Readiness::Ready) { + let msg = readiness_failure_message(label, port, &dir, deadline, &outcome); let _ = child.kill(); let _ = child.wait(); - panic!( - "[{}] server did not become ready within {:?} on port {}", - label, READY_TIMEOUT, port - ); + panic!("{msg}"); } // Optionally hold a live client connection across the SIGTERM (verified @@ -287,10 +363,13 @@ fn sigterm_clean_exit_under_write_storm() { .expect("spawn moon"); let pid = child.id(); - if !wait_for_ready(port, READY_TIMEOUT) { + let deadline = ready_timeout(); + let outcome = wait_for_ready(&mut child, port, deadline); + if !matches!(outcome, Readiness::Ready) { + let msg = readiness_failure_message("storm", port, &dir, deadline, &outcome); let _ = child.kill(); let _ = child.wait(); - panic!("[storm] server did not become ready within {READY_TIMEOUT:?} on port {port}"); + panic!("{msg}"); } // 16 writer threads, each pipelining SETs in a tight loop until the