diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 039a26d..a68c57a 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -108,6 +108,7 @@ jobs: bash -n ./tests/acceptance/tc_stats_01.sh bash -n ./tests/acceptance/tc_stats_02.sh bash -n ./tests/acceptance/tc_recovery_01.sh + bash -n ./tests/acceptance/tc_recovery_05.sh bash -n ./tests/acceptance/tc_cache_02.sh bash -n ./tests/acceptance/tc_container_01.sh bash -n ./tests/acceptance/tc_container_02.sh @@ -598,6 +599,15 @@ jobs: cargo build --locked --release cargo build --locked --release --example torrentfs-selfseed-env + - name: Create the daemon user + # tc_recovery_05 drives the rootful entrypoint, which drops torrentfs + # to TORRENTFS_UID (1000); fusermount3 resolves that uid through NSS, + # and debian:sid-slim has no uid-1000 user, so the mount would fail + # with "could not determine username". + run: | + groupadd --gid 1000 torrentfs + useradd --uid 1000 --gid 1000 --home-dir /home/torrentfs --create-home --shell /bin/sh torrentfs + - name: Run acceptance FUSE cases # Case exit codes: 0 = PASS, 1 = FAIL, 2 = SKIP (the case self-gated: # no /dev/fuse or no fusermount3). A bare `set -e` loop would turn a @@ -606,7 +616,7 @@ jobs: # fuse3 and runs as root with /dev/fuse, so the passing path is real. run: | set -euo pipefail - for tc in tc_ingest_01 tc_ingest_03 tc_ingest_06 tc_rofs_01 tc_read_04 tc_stats_01 tc_stats_02 tc_recovery_01 tc_cache_02; do + for tc in tc_ingest_01 tc_ingest_03 tc_ingest_06 tc_rofs_01 tc_read_04 tc_stats_01 tc_stats_02 tc_recovery_01 tc_cache_02 tc_recovery_05; do rc=0 ./tests/acceptance/$tc.sh ./target/release/torrentfs "/tmp/torrentfs_acceptance_$tc" || rc=$? if [ "$rc" -eq 2 ]; then @@ -624,6 +634,12 @@ jobs: - name: Run negative acceptance carrier (FUSE-dependent half) run: cargo test --locked --release --test acceptance -- tc_negative_03 --nocapture + - name: Run acceptance recovery cases (FUSE) + # The Rust carriers skip themselves without /dev/fuse, so the plain + # `cargo test` job (no device) never executes them; this is the job + # that has the device and the capability to mount. + run: cargo test --locked --release --test acceptance -- tc_recovery_0 + bindings-drift: name: Bindings Drift (regenerate + diff) runs-on: ubuntu-24.04 diff --git a/ci/tests/session_recovery_e2e.sh b/ci/tests/session_recovery_e2e.sh index cd5637d..94f6587 100755 --- a/ci/tests/session_recovery_e2e.sh +++ b/ci/tests/session_recovery_e2e.sh @@ -107,30 +107,11 @@ fail() { exit 1 } -# Print the FUSE connection minor (the /sys/fs/fuse/connections id) of the FUSE -# mount at $1, or nothing when the path carries no FUSE mount. -fuse_minor() { - awk -v mp="$1" ' - $5 == mp { - for (i = 7; i < NF; i++) { - if ($i == "-" && $(i + 1) ~ /^fuse/) { - split($3, a, ":") - print a[2] - exit - } - } - } - ' /proc/self/mountinfo -} - -wait_for_fuse_mount() { - local target="$1" deadline=$((SECONDS + 30)) - while [ "$SECONDS" -lt "$deadline" ]; do - [ -n "$(fuse_minor "$target")" ] && return 0 - sleep 0.5 - done - return 1 -} +# The FUSE mount probe (mountinfo minor + bounded wait) is shared with the +# acceptance cases, so there is one parser for the kernel's mount table. +TORRENTFS_FUSE_HARNESS_LIB_ONLY=1 +# shellcheck source=/dev/null +source "$ROOT_DIR/tests/acceptance/lib_fuse_harness.sh" wait_for_data_file() { local deadline=$((SECONDS + 60)) found="" @@ -165,7 +146,7 @@ PATH="$WORK/bin:$PATH" "$ROOT_DIR/entrypoint.sh" "$MNT" \ --cache "$WORK/cache" --db "$WORK/db/metadata.db" >"$LOG" 2>&1 & ENTRYPOINT_PID=$! -wait_for_fuse_mount "$MNT" || fail "FUSE mount at $MNT did not appear" +wait_for_fuse "$MNT" 30 || fail "FUSE mount at $MNT did not appear" cp "$SELFSEED_OUT/selfseed.torrent" "$MNT/metadata/" DATA_FILE="$(wait_for_data_file)" || fail "data file did not appear under $MNT/data" @@ -186,7 +167,7 @@ if umount "$MNT" 2>/dev/null; then fail "reader did not hold $MNT busy (a plain umount succeeded) — detach policy untested" fi -MINOR="$(fuse_minor "$INTERNAL_MNT")" +MINOR="$(fuse_minor_at "$INTERNAL_MNT")" [ -n "$MINOR" ] || fail "no FUSE connection found at $INTERNAL_MNT" ABORT_FILE="/sys/fs/fuse/connections/$MINOR/abort" echo "[session_recovery_e2e] severing the FUSE connection (minor=$MINOR)…" diff --git a/tests/acceptance/common.rs b/tests/acceptance/common.rs index 9095b9d..dce9d02 100644 --- a/tests/acceptance/common.rs +++ b/tests/acceptance/common.rs @@ -15,6 +15,9 @@ pub use base::{ }; use std::collections::BTreeSet; +use std::fs; +use std::path::{Path, PathBuf}; +use std::process::{Child, Command, ExitStatus, Stdio}; use std::sync::atomic::{AtomicUsize, Ordering}; use std::thread; use std::time::{Duration, Instant}; @@ -673,3 +676,359 @@ fn join_path(prefix: &str, name: &str) -> String { format!("{}/{}", prefix, name) } } + +// ── daemon-level helpers ───────────────────────────────────────────────────── +// +// The lifecycle cases need the real binary: a signal, an exit status and the +// kernel mount table are invisible to the in-process engine harness. One +// `Daemon` owns a private mountpoint, cache, state database and log, and +// tears all of it down on drop, so an assertion panic never leaves a mount +// behind for the next test. + +/// How long one daemon-side operation may take before the case fails instead +/// of hanging. Waiting forever would make a wedged mount look like CI +/// slowness rather than a broken contract. +pub const DAEMON_MOUNT_TIMEOUT: Duration = Duration::from_secs(60); + +/// The fusermount helper on `PATH` (`fusermount3` first, then `fusermount`). +fn fusermount_binary() -> Option<&'static str> { + ["fusermount3", "fusermount"].into_iter().find(|name| { + std::env::var_os("PATH") + .map(|paths| std::env::split_paths(&paths).any(|dir| dir.join(name).is_file())) + .unwrap_or(false) + }) +} + +/// Why this environment cannot mount FUSE at all, or `None` when it can. +/// +/// The recovery cases are FUSE-level by design; an environment without the +/// device or the mount helper cannot execute them. The case reports that as +/// a skip with the reason instead of a false pass. +pub fn fuse_mount_blocker() -> Option { + if !Path::new("/dev/fuse").exists() { + return Some("/dev/fuse is absent".to_string()); + } + if fusermount_binary().is_none() { + return Some("neither fusermount3 nor fusermount is on PATH".to_string()); + } + None +} + +/// Escape a path the way `/proc/self/mountinfo` does. +fn mountinfo_escape(path: &str) -> String { + path.replace('\\', "\\\\") + .replace(' ', "\\040") + .replace('\t', "\\011") + .replace('\n', "\\012") +} + +/// Number of FUSE mounts whose mountpoint is exactly `path`. +pub fn mountinfo_fuse_count(path: &Path) -> usize { + let escaped = mountinfo_escape(&path.to_string_lossy()); + let Ok(mountinfo) = fs::read_to_string("/proc/self/mountinfo") else { + return 0; + }; + mountinfo + .lines() + .filter(|line| { + let fields: Vec<&str> = line.split(' ').collect(); + if fields.len() < 5 || fields[4] != escaped { + return false; + } + match fields.iter().position(|field| *field == "-") { + Some(sep) => fields + .get(sep + 1) + .is_some_and(|kind| kind.starts_with("fuse")), + None => false, + } + }) + .count() +} + +/// Outcome of waiting for the daemon's mount. +pub enum MountGate { + Mounted, + /// This environment refused the mount; the case cannot execute here. + Environment(String), + /// The daemon failed for a reason that is not environmental. + Failed(String), +} + +/// A torrentfs daemon process with its own FUSE mountpoint and state. +pub struct Daemon { + child: Option, + work: tempfile::TempDir, + log_path: PathBuf, + stderr_path: PathBuf, +} + +impl Daemon { + /// Start `target/debug/torrentfs` on a private mountpoint. + /// + /// `config_toml` is written into the work directory and passed as + /// `--config`; `log_level` feeds `--log-level`. The daemon's own stderr + /// is captured separately file so the frozen read-failure diagnostics are + /// readable, while tracing output goes to `--log-file`. + pub fn start(config_toml: Option<&str>, log_level: &str) -> Self { + let base = std::env::var_os("CARGO_TARGET_TMPDIR") + .map(PathBuf::from) + .unwrap_or_else(std::env::temp_dir); + let work = tempfile::TempDir::new_in(&base).expect("create daemon work dir"); + let mountpoint = work.path().join("mnt"); + fs::create_dir_all(&mountpoint).expect("create mountpoint"); + let cache = work.path().join("cache"); + fs::create_dir_all(&cache).expect("create cache dir"); + let db_dir = work.path().join("db"); + fs::create_dir_all(&db_dir).expect("create db dir"); + + let log_path = work.path().join("daemon.log"); + let stderr_path = work.path().join("daemon.stderr"); + let stderr = fs::File::create(&stderr_path).expect("create daemon stderr file"); + + let mut cmd = Command::new(env!("CARGO_BIN_EXE_torrentfs")); + cmd.arg(&mountpoint) + .arg("--cache") + .arg(&cache) + .arg("--db") + .arg(db_dir.join("metadata.db")) + .arg("--log-level") + .arg(log_level) + .arg("--log-file") + .arg(&log_path); + if let Some(toml) = config_toml { + let config_path = work.path().join("config.toml"); + fs::write(&config_path, toml).expect("write daemon config"); + cmd.arg("--config").arg(&config_path); + } + cmd.stdout(Stdio::null()).stderr(Stdio::from(stderr)); + + let child = cmd.spawn().expect("spawn torrentfs daemon"); + Daemon { + child: Some(child), + work, + log_path, + stderr_path, + } + } + + pub fn mountpoint(&self) -> PathBuf { + self.work.path().join("mnt") + } + + pub fn cache_dir(&self) -> PathBuf { + self.work.path().join("cache") + } + + pub fn log_path(&self) -> PathBuf { + self.log_path.clone() + } + + /// Everything the daemon wrote to its log file and its stderr, for a + /// failure message. + pub fn output(&self) -> String { + let log = fs::read_to_string(&self.log_path).unwrap_or_default(); + let err = fs::read_to_string(&self.stderr_path).unwrap_or_default(); + format!("--- daemon log ---\n{log}\n--- daemon stderr ---\n{err}") + } + + fn poll_exit(&mut self) -> Option { + let child = self.child.as_mut()?; + match child.try_wait().expect("poll daemon") { + Some(status) => { + self.child = None; + Some(status) + } + None => None, + } + } + + /// Wait for the FUSE mount, classifying an early exit. + pub fn wait_for_mount(&mut self, timeout: Duration) -> MountGate { + let deadline = std::time::Instant::now() + timeout; + loop { + if mountinfo_fuse_count(&self.mountpoint()) > 0 { + return MountGate::Mounted; + } + if let Some(status) = self.poll_exit() { + let output = self.output(); + // A refused mount, not any startup failure. The exit status + // says the daemon reached the mount (2 = refused, 3 = /dev/fuse + // vanished, 100 = the device could not be opened, C-1.2.3..5) + // and the line must name a refusal only a mount attempt + // writes. The `user_allow_other` warning is printed before + // every mount, so on its own it would turn a state-database, + // engine-init or instance-lock failure into a skip. + let mount_refused = [ + "Mount failed: Operation not permitted", + "Mount failed and /dev/fuse cannot be opened", + "mountpoint is not empty", + "fusermount:", + "/dev/fuse not found", + ] + .iter() + .any(|marker| output.contains(marker)); + let mount_stage_exit = matches!(status.code(), Some(2) | Some(3) | Some(100)); + return if mount_refused && mount_stage_exit { + MountGate::Environment(output) + } else { + MountGate::Failed(format!( + "daemon exited with {status} before mounting\n{output}" + )) + }; + } + if std::time::Instant::now() >= deadline { + return MountGate::Failed(format!( + "FUSE mount did not appear within {timeout:?}\n{}", + self.output() + )); + } + thread::sleep(Duration::from_millis(50)); + } + } + + /// Deliver a signal to the daemon. Returns false when it already exited. + pub fn signal(&self, signal: libc::c_int) -> bool { + match self.child.as_ref() { + Some(child) => unsafe { libc::kill(child.id() as libc::pid_t, signal) == 0 }, + None => false, + } + } + + /// Wait for the daemon to exit, polling until `timeout`. + pub fn wait_for_exit(&mut self, timeout: Duration) -> Option { + let deadline = std::time::Instant::now() + timeout; + loop { + if let Some(status) = self.poll_exit() { + return Some(status); + } + if std::time::Instant::now() >= deadline { + return None; + } + thread::sleep(Duration::from_millis(20)); + } + } +} + +impl Drop for Daemon { + fn drop(&mut self) { + if let Some(mut child) = self.child.take() { + let _ = child.kill(); + let _ = child.wait(); + } + // A killed daemon leaves its mount attached; lazy-detach so the work + // directory can be removed and no later test sees a stale mount. + if mountinfo_fuse_count(&self.mountpoint()) > 0 { + if let Some(bin) = fusermount_binary() { + let _ = Command::new(bin) + .arg("-u") + .arg("-z") + .arg("--") + .arg(self.mountpoint()) + .status(); + } + } + } +} + +/// The config the lifecycle cases use: ephemeral listen port (several test +/// daemons run in parallel), no DHT, tracker discovery kept on, and the three +/// read windows set by the caller. +pub fn daemon_config(read_timeout_secs: u64, no_seeder_secs: u64, discovery_secs: u64) -> String { + format!( + r#" +[connections] +listen_interfaces = "127.0.0.1:0" +allow_multiple_connections_per_ip = true +peer_connect_timeout = 5 + +[dht] +enabled = false + +[local_discovery] +lsd_enabled = true +upnp_enabled = false +natpmp_enabled = false + +[tracker] +announce_to_all_trackers = true +announce_to_all_tiers = true +min_announce_interval = 5 + +[timeouts] +read_timeout_secs = {read_timeout_secs} +no_seeder_read_timeout_secs = {no_seeder_secs} +peer_discovery_wait_secs = {discovery_secs} +"# + ) +} + +/// Write a `.torrent` into the mount's `metadata/` namespace. +pub fn ingest_torrent_through_mount(mountpoint: &Path, filename: &str, torrent_data: &[u8]) { + fs::write(mountpoint.join("metadata").join(filename), torrent_data) + .unwrap_or_else(|e| panic!("write metadata/{filename}: {e}")); +} + +/// Read a file through the mount with a wall-clock ceiling, so a wedged +/// request fails the case instead of stalling the suite. +pub fn read_with_deadline(path: &Path, timeout: Duration) -> std::io::Result> { + let (sender, receiver) = std::sync::mpsc::channel(); + let read_path = path.to_path_buf(); + thread::spawn(move || { + let _ = sender.send(fs::read(&read_path)); + }); + receiver.recv_timeout(timeout).unwrap_or_else(|_| { + panic!( + "read of {} did not return within {timeout:?} (the mount is hanging)", + path.display() + ) + }) +} + +/// Read a file that was just ingested, retrying while the torrent is still in +/// the delivery window. +/// +/// C-2.5.3 keeps a freshly closed `.torrent` listed as a temporary projection +/// until the background persist finishes; that projection has no download +/// handle yet, so its first reads answer `ENOENT`. Retrying `ENOENT` for up +/// to `timeout` waits out that window, and every other error is returned at +/// once. +pub fn read_when_ready(path: &Path, timeout: Duration) -> std::io::Result> { + let deadline = std::time::Instant::now() + timeout; + loop { + match read_with_deadline(path, timeout) { + Ok(bytes) => return Ok(bytes), + Err(error) + if error.kind() == std::io::ErrorKind::NotFound + && std::time::Instant::now() < deadline => + { + thread::sleep(Duration::from_millis(100)); + } + Err(error) => return Err(error), + } + } +} + +/// Wait for the projection of `filename` to appear under `data/`. +pub fn wait_for_projection(mountpoint: &Path, filename: &str, timeout: Duration) -> bool { + let path = mountpoint.join("data").join(filename); + let deadline = std::time::Instant::now() + timeout; + while std::time::Instant::now() < deadline { + if path.is_dir() { + return true; + } + thread::sleep(Duration::from_millis(100)); + } + false +} + +/// Wait for `path` to exist (a projected file appears after its directory). +pub fn wait_for_path(path: &Path, timeout: Duration) -> bool { + let deadline = std::time::Instant::now() + timeout; + while std::time::Instant::now() < deadline { + if path.exists() { + return true; + } + thread::sleep(Duration::from_millis(100)); + } + false +} diff --git a/tests/acceptance/lib_fuse_harness.sh b/tests/acceptance/lib_fuse_harness.sh index 906c176..78ad02f 100755 --- a/tests/acceptance/lib_fuse_harness.sh +++ b/tests/acceptance/lib_fuse_harness.sh @@ -1,9 +1,14 @@ #!/usr/bin/env bash # Shared FUSE harness for the acceptance scripts. # -# Mounts torrentfs on a fresh mountpoint with a fresh state/cache, waits for -# the mount, and tears it down on exit. Source this file from an acceptance -# script after setting: +# The helpers at the top are the one implementation of "is there a FUSE mount +# here, and wait for one": cases that drive their own daemons or the container +# entrypoint source this file with TORRENTFS_FUSE_HARNESS_LIB_ONLY=1 and use +# them without the single-daemon harness below. +# +# Sourcing it plainly mounts torrentfs on a fresh mountpoint with a fresh +# state/cache, waits for the mount, and tears it down on exit. Source this +# file from an acceptance script after setting: # # ROOT_DIR (repo root), BIN (torrentfs binary), MNT (mountpoint) # @@ -20,6 +25,40 @@ # source "$ROOT_DIR/tests/acceptance/lib_fuse_harness.sh" set -euo pipefail +# Print the FUSE connection minor of the mount at $1 (the id under +# /sys/fs/fuse/connections), empty when the path carries no FUSE mount. +fuse_minor_at() { + awk -v mp="$1" ' + $5 == mp { + for (i = 7; i < NF; i++) { + if ($i == "-" && $(i + 1) ~ /^fuse/) { + split($3, a, ":") + print a[2] + exit + } + } + } + ' /proc/self/mountinfo +} + +# Wait for a FUSE mount at $1, bounded by $2 seconds (default 30). +wait_for_fuse() { + local target="$1" timeout="${2:-30}" + local deadline=$((SECONDS + timeout)) + while [ "$SECONDS" -lt "$deadline" ]; do + [ -n "$(fuse_minor_at "$target")" ] && return 0 + sleep 0.2 + done + return 1 +} + +# A case that manages its own daemons (or the entrypoint) wants the helpers +# above and owns its own state and EXIT trap: it sources this file with +# TORRENTFS_FUSE_HARNESS_LIB_ONLY=1, which stops before the harness mounts. +if [ "${TORRENTFS_FUSE_HARNESS_LIB_ONLY:-0}" = 1 ]; then + return 0 2>/dev/null || exit 0 +fi + LOG_FILE="$(mktemp)" CACHE_DIR="$(mktemp -d)" DB_DIR="$(mktemp -d)" diff --git a/tests/acceptance/main.rs b/tests/acceptance/main.rs index b3b862c..d629026 100644 --- a/tests/acceptance/main.rs +++ b/tests/acceptance/main.rs @@ -60,6 +60,9 @@ mod test_tc_read_07; mod test_tc_read_08; mod test_tc_read_09; mod test_tc_read_10; +mod test_tc_recovery_02; +mod test_tc_recovery_03; +mod test_tc_recovery_04; mod test_tc_rofs_02; mod test_tc_rofs_03; mod test_tc_seeding_01; @@ -175,6 +178,9 @@ pub const LANDED: &[&str] = &[ test_tc_read_08::TC_ID, test_tc_read_09::TC_ID, test_tc_read_10::TC_ID, + test_tc_recovery_02::TC_ID, + test_tc_recovery_03::TC_ID, + test_tc_recovery_04::TC_ID, test_tc_rofs_02::TC_ID, test_tc_rofs_03::TC_ID, test_tc_seeding_01::TC_ID, @@ -208,6 +214,7 @@ pub const SCRIPT_FORM: &[&str] = &[ "TC-ingest-06", "TC-read-04", "TC-recovery-01", + "TC-recovery-05", "TC-rofs-01", "TC-stats-01", "TC-stats-02", diff --git a/tests/acceptance/tc_recovery_05.sh b/tests/acceptance/tc_recovery_05.sh new file mode 100755 index 0000000..38dcc80 --- /dev/null +++ b/tests/acceptance/tc_recovery_05.sh @@ -0,0 +1,399 @@ +#!/usr/bin/env bash +# Design acceptance case TC-recovery-05: a severed FUSE session whose mount is +# still attached makes the daemon exit 104; the container entry restarts it +# within budget (at most 3 recoveries, 1 s backoff each, a log line naming the +# recovery number) and exits 104 on the fourth consecutive loss; an external +# unmount makes the daemon exit 102 and is never restarted +# (`docs/03-acceptance.md` §I AC-84, contracts C-9.3 / C-10.7 / C-10.8). +# +# case TC-recovery-05 +# +# FUSE- and process-level executable form: severing a connection means writing +# /sys/fs/fuse/connections//abort, and the restart loop lives in +# `entrypoint.sh`, so neither is reachable from the in-process Rust harness. +# +# Each section reports its own environment requirement instead of weakening a +# criterion: the external-unmount matrix needs only a FUSE mount, while the +# severed-session matrix needs root so fusectl exposes the abort file. A +# section the environment cannot run makes the whole case SKIP (exit 2). +# +# Usage: sudo ./tests/acceptance/tc_recovery_05.sh [torrentfs_binary] +# Exit: 0 = pass, 1 = fail, 2 = the environment cannot execute the case. +# +# The backoff is measured from the recovery log line to the restarted daemon's +# own start time (`/proc//stat`), so the 1 s of C-10.7 is witnessed on its +# own instead of being padded by the mount that follows it. +# +# Every external wait is bounded: a wedged mount or a stuck entrypoint fails +# the case with a diagnostic instead of stalling the job. +set -euo pipefail + +ROOT_DIR="$(cd "$(dirname "${BASH_SOURCE[0]}")/../.." && pwd)" +BIN="${1:-$ROOT_DIR/target/release/torrentfs}" + +WORK="$(mktemp -d)" +# The rootful entrypoint drops the daemon to TORRENTFS_UID (1000), so it must +# be able to traverse the work tree to reach the `torrentfs` placed on PATH. +chmod 0755 "$WORK" +ENTRY_MNT="$WORK/entry-mnt" +INTERNAL_MNT="/mnt-inner" # the entrypoint's two-stage publish target +DAEMON_PID="" +ENTRY_PID="" +FUSERMOUNT="" +INTERNAL_MNT_USED=0 + +# The mount helpers live in the shared harness; this case runs its own daemons +# and the entrypoint, so it takes the functions without the single-daemon +# harness (and its EXIT trap). +TORRENTFS_FUSE_HARNESS_LIB_ONLY=1 +# shellcheck source=/dev/null +source "$ROOT_DIR/tests/acceptance/lib_fuse_harness.sh" + +skip() { + echo "TC-recovery-05: SKIP — $*" >&2 + exit 2 +} + +fail() { + echo "TC-recovery-05: FAIL — $*" >&2 + exit 1 +} + +cleanup() { + if [ -n "$ENTRY_PID" ]; then + kill "$ENTRY_PID" 2>/dev/null || true + wait "$ENTRY_PID" 2>/dev/null || true + fi + if [ -n "$DAEMON_PID" ]; then + kill "$DAEMON_PID" 2>/dev/null || true + wait "$DAEMON_PID" 2>/dev/null || true + fi + for mnt in "$WORK/a-mnt" "$WORK/c-mnt" "$ENTRY_MNT"; do + umount "$mnt" 2>/dev/null || true + [ -n "$FUSERMOUNT" ] && "$FUSERMOUNT" -u -z "$mnt" >/dev/null 2>&1 || true + done + rm -rf "$WORK" + # The fixed publish target is not this case's to reclaim: touch it only + # after this run published through it. + if [ "$INTERNAL_MNT_USED" -eq 1 ]; then + if [ -n "$(fuse_minor_at "$INTERNAL_MNT")" ]; then + umount "$INTERNAL_MNT" 2>/dev/null || true + [ -n "$FUSERMOUNT" ] && "$FUSERMOUNT" -u -z "$INTERNAL_MNT" >/dev/null 2>&1 || true + fi + # The entrypoint leaves its mountpoint lock inside that target. + rm -f "$INTERNAL_MNT/.torrentfs.lock" 2>/dev/null || true + rmdir "$INTERNAL_MNT" 2>/dev/null || true + fi +} +trap cleanup EXIT + +# Wait for a fixed string to appear in $1, bounded by $2 seconds. +wait_for_log() { + local log="$1" needle="$2" timeout="${3:-30}" + local deadline=$((SECONDS + timeout)) + while [ "$SECONDS" -lt "$deadline" ]; do + grep -qF -- "$needle" "$log" 2>/dev/null && return 0 + sleep 0.05 + done + return 1 +} + +# Wait until $2 occurrences of $3 are in $1, bounded by $4 seconds. +wait_for_log_count() { + local log="$1" count="$2" needle="$3" timeout="${4:-60}" + local deadline=$((SECONDS + timeout)) + while [ "$SECONDS" -lt "$deadline" ]; do + [ "$(grep -cF -- "$needle" "$log" 2>/dev/null || true)" -ge "$count" ] && return 0 + sleep 0.1 + done + return 1 +} + +# Decide a mount that never appeared. Only a status a mount attempt can +# produce (2 = the mount was refused, 3 = /dev/fuse vanished, 100 = the device +# could not be opened, C-1.2.3..C-1.2.5) together with a line only a mount +# attempt writes means this environment cannot mount FUSE. A hang, a state +# database, engine or instance-lock failure is a failure, not a skip: the +# daemon warns about `/etc/fuse.conf` before every mount, so that line alone +# says nothing. +mount_unavailable() { + local log="$1" pid="$2" who="$3" status=0 + if ! wait_pid "$pid" 5; then + fail "$who kept running without mounting: $(tail -n 3 "$log" | tr '\n' ' ')" + fi + status="$WAIT_STATUS" + if { [ "$status" -eq 2 ] || [ "$status" -eq 3 ] || [ "$status" -eq 100 ]; } && + grep -qE "Mount failed: Operation not permitted|Mount failed and /dev/fuse cannot be opened|mountpoint is not empty|fusermount:|/dev/fuse not found" \ + "$log" 2>/dev/null; then + skip "this environment cannot mount FUSE ($who exited $status): $(tail -n 3 "$log" | tr '\n' ' ')" + fi + fail "$who exited $status before mounting: $(tail -n 8 "$log" | tr '\n' ' ')" +} + +# Milliseconds since boot, with the fraction `/proc/stat`'s integer `btime` +# lacks. Both endpoints of the backoff are read on this one clock: the stamp +# below and field 22 of `/proc//stat` (clock ticks since boot). Mixing +# epochs — `btime` floored to the second against an exact wall-clock stamp — +# placed the restart up to a second early and under-reported the interval. +uptime_ms() { + awk '{ printf "%d\n", ($1 * 1000) + 0.5 }' /proc/uptime 2>/dev/null +} + +# Milliseconds-since-boot at which process $1 started: field 22 of +# `/proc//stat`, on the same boot clock as `uptime_ms`. The kernel writes +# it at creation, so it is the restart moment itself rather than the later +# moment the mount is published. +proc_started_uptime_ms() { + local pid="$1" stat starttime hz + stat="$(cat "/proc/$pid/stat" 2>/dev/null)" || return 1 + starttime="$(printf '%s\n' "$stat" | awk '{ sub(/.*\) /, ""); split($0, f, " "); print f[20] }')" + hz="$(getconf CLK_TCK 2>/dev/null || echo 100)" + [ -n "$starttime" ] || return 1 + echo $(( starttime * 1000 / hz )) +} + +# The daemon the entrypoint is running right now: `run_daemon` execs after +# setpriv, so torrentfs is the entrypoint's direct child. +entry_daemon_pid() { + local child + for child in $(cat "/proc/$ENTRY_PID/task/$ENTRY_PID/children" 2>/dev/null || true); do + [ "$(cat "/proc/$child/comm" 2>/dev/null)" = "torrentfs" ] && { echo "$child"; return 0; } + done + return 1 +} + +# Milliseconds-since-boot at the first 10ms poll that finds no torrentfs child +# under the entrypoint; returns 1 when one is still there after $1 seconds. +# This is the start of the backoff window: the abort only marks the request, +# the daemon still runs its engine shutdown and cache flush before exiting, +# and the entrypoint prints the recovery line only after reaping that daemon — +# stamping at either of those would fold that shutdown into the interval and +# let a backoff shorter than the contract's 1s pass. +wait_for_daemon_exit() { + local timeout="${1:-30}" + local deadline=$((SECONDS + timeout)) + while [ "$SECONDS" -lt "$deadline" ]; do + if ! entry_daemon_pid >/dev/null; then + uptime_ms + return 0 + fi + sleep 0.01 + done + return 1 +} + +# Config shared by every daemon here: an ephemeral listen port (the runner may +# already own 6881) and no discovery channels besides the tracker. +CONFIG="$WORK/torrentfs.toml" +cat > "$CONFIG" <<'TOML' +[connections] +listen_interfaces = "127.0.0.1:0" + +[dht] +enabled = false + +[local_discovery] +lsd_enabled = false +upnp_enabled = false +natpmp_enabled = false +TOML + +# Start a daemon on $1 with cache $2 and state db $3, logging to $4. The +# caller reads `$!`: a command substitution would make the subshell the +# daemon's parent, and `wait` on a non-child reports 127 instead of the exit +# status the case judges. +start_daemon() { + local mnt="$1" cache="$2" db="$3" log="$4" + mkdir -p "$mnt" "$cache" "$(dirname "$db")" + "$BIN" "$mnt" --cache "$cache" --db "$db" --config "$CONFIG" --log-level info >"$log" 2>&1 & +} + +# Wait for a background pid, bounded by $2 seconds. Its status lands in +# WAIT_STATUS; returns 1 on timeout. +wait_pid() { + local pid="$1" timeout="${2:-60}" + local deadline=$((SECONDS + timeout)) + WAIT_STATUS=0 + while kill -0 "$pid" 2>/dev/null; do + if [ "$SECONDS" -ge "$deadline" ]; then + return 1 + fi + sleep 0.1 + done + wait "$pid" 2>/dev/null || WAIT_STATUS=$? + return 0 +} + +# The daemon's own mountpoint: the fixed internal target under the rootful +# entrypoint's two-stage publish, otherwise the entrypoint's mountpoint +# itself. The fixed path counts only when this run is rootful — a rootless +# entrypoint never mounts there, so a FUSE mount found on it belongs to +# another run and must not be adopted (adopting it would detach a foreign +# mount in the external-unmount section and reclaim its lock directory). +# The caller records the choice in the main shell: a command substitution runs +# in a subshell, so anything set in here would never reach cleanup. +daemon_mountpoint() { + if [ "$ROOTFUL" -eq 1 ] && [ -n "$(fuse_minor_at "$INTERNAL_MNT")" ]; then + echo "$INTERNAL_MNT" + else + echo "$ENTRY_MNT" + fi +} + +[ -x "$BIN" ] || fail "torrentfs binary not found or not executable: $BIN" +# The entrypoint puts this binary on PATH through a symlink in the work tree, +# so a relative argument would resolve against $WORK/bin instead of the caller. +BIN="$(cd "$(dirname "$BIN")" && pwd)/$(basename "$BIN")" +[ -c /dev/fuse ] || skip "/dev/fuse is absent" +for helper in fusermount3 fusermount; do + if command -v "$helper" >/dev/null 2>&1; then + FUSERMOUNT="$helper" + break + fi +done +[ -n "$FUSERMOUNT" ] || skip "neither fusermount3 nor fusermount is on PATH" +command -v flock >/dev/null 2>&1 || skip "flock is required by the entrypoint" + +# ── A. external unmount → daemon exits 102 ────────────────────────────────── +# `fusermount -u` removes the mount from the table; the session ends with no +# signal, which the contract classifies as final (102), not recoverable (104). +A_MNT="$WORK/a-mnt" +A_LOG="$WORK/a.log" +start_daemon "$A_MNT" "$WORK/a-cache" "$WORK/a-db/metadata.db" "$A_LOG" +DAEMON_PID=$! +wait_for_fuse "$A_MNT" 30 || mount_unavailable "$A_LOG" "$DAEMON_PID" "the daemon" +"$FUSERMOUNT" -u "$A_MNT" 2>/dev/null || fail "could not externally unmount $A_MNT" +wait_pid "$DAEMON_PID" 30 || fail "daemon still running 30s after the external unmount" +DAEMON_PID="" +[ "$WAIT_STATUS" -eq 102 ] || fail "external unmount made the daemon exit $WAIT_STATUS, expected 102" +[ -z "$(fuse_minor_at "$A_MNT")" ] || fail "the external unmount left a FUSE mount behind" +echo "[TC-recovery-05] external unmount → daemon exit 102" + +# ── B. entrypoint-managed external unmount → 102, never restarted ─────────── +ROOTFUL=0 +if [ "$(id -u)" -eq 0 ]; then + command -v setpriv >/dev/null 2>&1 || skip "setpriv is required by the rootful entrypoint path" + ROOTFUL=1 +fi +# The fixed publish target belongs to the rootful two-stage publish: a FUSE +# mount already sitting there is another run's, never this one's. Rootful has +# nowhere else to publish and skips; a rootless run mounts directly on +# $ENTRY_MNT, so it only has to leave the foreign mount alone (which +# `daemon_mountpoint` enforces below). +if [ -n "$(fuse_minor_at "$INTERNAL_MNT")" ] && [ "$ROOTFUL" -eq 1 ]; then + skip "$INTERNAL_MNT already carries a FUSE mount (another run)" +fi +mkdir -p "$WORK/bin" "$ENTRY_MNT" "$WORK/entry-cache" "$WORK/entry-db" +ln -sf "$BIN" "$WORK/bin/torrentfs" +ENTRY_LOG="$WORK/entry.log" +PATH="$WORK/bin:$PATH" bash "$ROOT_DIR/entrypoint.sh" "$ENTRY_MNT" \ + --cache "$WORK/entry-cache" --db "$WORK/entry-db/metadata.db" --config "$CONFIG" >"$ENTRY_LOG" 2>&1 & +ENTRY_PID=$! +wait_for_fuse "$ENTRY_MNT" 90 || mount_unavailable "$ENTRY_LOG" "$ENTRY_PID" "the entrypoint" +DAEMON_MNT="$(daemon_mountpoint)" +# Recorded here, in the main shell: the value above comes from a command +# substitution, so anything set inside it would never reach cleanup. +if [ "$DAEMON_MNT" = "$INTERNAL_MNT" ]; then + INTERNAL_MNT_USED=1 +fi +echo "[TC-recovery-05] entrypoint mountpoint $DAEMON_MNT (rootful=$ROOTFUL, internal target in use: $INTERNAL_MNT_USED)" +# Release the published bind first, then detach the daemon's mount: together +# they are the operator's external unmount, and with no mount left the daemon +# reports the final status instead of the recoverable one. +umount "$ENTRY_MNT" 2>/dev/null || umount -l "$ENTRY_MNT" 2>/dev/null || true +# On the direct path the published path *is* the daemon's mount, so the +# release above may already have removed it; only detach the internal mount +# when the two-stage publish left one. +if [ -n "$(fuse_minor_at "$DAEMON_MNT")" ]; then + "$FUSERMOUNT" -u "$DAEMON_MNT" 2>/dev/null || "$FUSERMOUNT" -u -z "$DAEMON_MNT" 2>/dev/null || + fail "could not externally unmount the entrypoint-managed mount at $DAEMON_MNT" +fi +wait_pid "$ENTRY_PID" 60 || fail "the entrypoint still ran 60s after the external unmount" +ENTRY_PID="" +[ "$WAIT_STATUS" -eq 102 ] || fail "external unmount must make the entrypoint exit 102, got $WAIT_STATUS" +if grep -qF "restarting torrentfs" "$ENTRY_LOG"; then + fail "the entrypoint restarted the daemon after an external unmount (102 is final)" +fi +echo "[TC-recovery-05] entrypoint external unmount → exit 102, no restart" + +# ── C. severed session (mount still attached) → 104 + bounded recovery ────── +[ "$(id -u)" -eq 0 ] || skip "severing a FUSE connection needs root (writes /sys/fs/fuse/connections)" +if ! mountpoint -q /sys/fs/fuse/connections; then + mount -t fusectl fusectl /sys/fs/fuse/connections 2>/dev/null || + skip "cannot mount fusectl on /sys/fs/fuse/connections" +fi + +# C1: the daemon itself reports the loss as recoverable. +C_MNT="$WORK/c-mnt" +C_LOG="$WORK/c.log" +start_daemon "$C_MNT" "$WORK/c-cache" "$WORK/c-db/metadata.db" "$C_LOG" +DAEMON_PID=$! +wait_for_fuse "$C_MNT" 30 || mount_unavailable "$C_LOG" "$DAEMON_PID" "the daemon" +C_MINOR="$(fuse_minor_at "$C_MNT")" +[ -n "$C_MINOR" ] || fail "no FUSE connection at $C_MNT" +echo 1 >"/sys/fs/fuse/connections/$C_MINOR/abort" 2>/dev/null || + skip "cannot sever connection $C_MINOR (fusectl does not expose abort)" +wait_pid "$DAEMON_PID" 30 || fail "daemon still running 30s after its session was severed" +DAEMON_PID="" +[ "$WAIT_STATUS" -eq 104 ] || fail "a severed session with the mount attached exits 104, got $WAIT_STATUS" +echo "[TC-recovery-05] severed session → daemon exit 104" + +# C2: the entrypoint recovers at most three times, one second apart, naming +# the recovery number, then exits 104 on the fourth consecutive loss. +ENTRY2_LOG="$WORK/entry2.log" +PATH="$WORK/bin:$PATH" bash "$ROOT_DIR/entrypoint.sh" "$ENTRY_MNT" \ + --cache "$WORK/entry-cache" --db "$WORK/entry-db/metadata.db" --config "$CONFIG" >"$ENTRY2_LOG" 2>&1 & +ENTRY_PID=$! +wait_for_fuse "$ENTRY_MNT" 90 || mount_unavailable "$ENTRY2_LOG" "$ENTRY_PID" "the entrypoint" + +# C-10.7 is 1 s of backoff. The window runs from the previous daemon's exit +# to the replacement's exec, so it contains the detach of the dead mounts, the +# backoff and the exec — not the aborted daemon's shutdown (that happens before +# the window opens) and not the mount that follows the restart. The floor +# leaves ~90ms for the 10ms poll granularity and the 10ms tick rounding; the +# ceiling bounds the same window on a slow runner. +BACKOFF_MIN_MS=900 +BACKOFF_MAX_MS=6000 +for attempt in 1 2 3 4; do + daemon_mnt="$(daemon_mountpoint)" + if [ "$daemon_mnt" = "$INTERNAL_MNT" ]; then + INTERNAL_MNT_USED=1 + fi + minor="$(fuse_minor_at "$daemon_mnt")" + [ -n "$minor" ] || fail "attempt $attempt: no FUSE connection at $daemon_mnt" + echo 1 >"/sys/fs/fuse/connections/$minor/abort" 2>/dev/null || + fail "attempt $attempt: cannot sever connection $minor" + + if [ "$attempt" -le 3 ]; then + recovery_line="restarting torrentfs (recovery $attempt/3)" + # Window start: the daemon is gone (see `wait_for_daemon_exit`). From + # here C-10.7 schedules the detach of the dead mounts, the 1s backoff + # and the exec of the new daemon — nothing else is in the interval. + exit_at_ms="$(wait_for_daemon_exit 30)" || + fail "attempt $attempt: the daemon was still running 30s after the abort" + wait_for_log "$ENTRY2_LOG" "$recovery_line" 30 || + fail "attempt $attempt: the entrypoint logged no '$recovery_line'" + wait_for_log_count "$ENTRY2_LOG" "$((attempt + 1))" "available at $ENTRY_MNT" 60 || + fail "attempt $attempt: the recovered mount was never republished" + restart_pid="$(entry_daemon_pid)" || + fail "attempt $attempt: the entrypoint is not running a torrentfs process after the recovery" + restart_at_ms="$(proc_started_uptime_ms "$restart_pid")" || + fail "attempt $attempt: cannot read the start time of pid $restart_pid" + backoff_ms=$((restart_at_ms - exit_at_ms)) + echo "[TC-recovery-05] recovery $attempt/3: daemon restarted ${backoff_ms}ms after the previous daemon exited" + [ "$backoff_ms" -ge "$BACKOFF_MIN_MS" ] || + fail "attempt $attempt: restart came ${backoff_ms}ms after the previous daemon exited; C-10.7 requires a 1s backoff" + [ "$backoff_ms" -le "$BACKOFF_MAX_MS" ] || + fail "attempt $attempt: restart came ${backoff_ms}ms after the previous daemon exited; C-10.7 requires a 1s backoff" + kill -0 "$ENTRY_PID" 2>/dev/null || fail "attempt $attempt: the entrypoint exited instead of recovering" + fi +done +# C2 tail: the fourth consecutive loss exhausts the budget. +wait_pid "$ENTRY_PID" 60 || fail "the entrypoint still ran after the fourth consecutive 104" +ENTRY_PID="" +[ "$WAIT_STATUS" -eq 104 ] || fail "after 3 recoveries a fourth 104 must make the entrypoint exit 104, got $WAIT_STATUS" +restarts="$(grep -cF "restarting torrentfs" "$ENTRY2_LOG" || true)" +[ "$restarts" -eq 3 ] || fail "the entrypoint restarted $restarts times, the budget is 3" +echo "[TC-recovery-05] 3 recoveries then exit 104 on the fourth severed session" + +echo "TC-recovery-05: PASS (102 final on external unmount; 104 recovery budget, 1s backoff, exit 104 on budget exhaustion)" diff --git a/tests/acceptance/test_tc_recovery_02.rs b/tests/acceptance/test_tc_recovery_02.rs new file mode 100644 index 0000000..87bc4f6 --- /dev/null +++ b/tests/acceptance/test_tc_recovery_02.rs @@ -0,0 +1,349 @@ +//! Design acceptance case TC-recovery-02: a torrent directory holding +//! thousands of files lists, descends, recurses and resolves by name within +//! seconds, without hanging (`docs/03-acceptance.md` §I AC-81). +//! +//! The fixture is one multi-file torrent: 3000 files directly in the torrent +//! directory plus 20 subdirectories of 50 files each. A listing that scans +//! the directory per entry — or materialises it before answering a lookup — +//! turns the root readdir into hours of work at this size (F2), so the +//! per-operation ceilings below separate "seconds" from "hung". +//! +//! The case drives the real binary through a FUSE mount: "enter, list, +//! recurse, find" are namespace operations, not engine calls. Environments +//! that cannot mount FUSE report a skip with the reason. + +use crate::common::{ + fuse_mount_blocker, ingest_torrent_through_mount, mountinfo_fuse_count, wait_for_projection, + wave_slot, Daemon, MountGate, DAEMON_MOUNT_TIMEOUT, +}; +use std::collections::BTreeSet; +use std::fs; +use std::path::Path; +use std::thread; +use std::time::{Duration, Instant}; + +pub const TC_ID: &str = "TC-recovery-02"; + +/// Files directly inside the torrent directory. +const FILES_AT_ROOT: usize = 3000; +/// Subdirectories inside the torrent directory. +const SUBDIRS: usize = 20; +/// Files inside each subdirectory. +const FILES_PER_SUBDIR: usize = 50; +/// Declared size of every fixture file. +const FILE_BYTES: usize = 32; +/// Piece length of the fixture torrent. +const PIECE_LEN: usize = 16 * 1024; +/// The `.torrent` file name dropped into `metadata/`. +const TORRENT_FILE: &str = "many-files.torrent"; +/// The torrent's internal name; the projection appears as +/// `data/many-files.torrent/`. +const TORRENT_NAME: &str = "many-files"; +/// Upper bound for parsing and persisting a 4000-file torrent. +const PROJECTION_TIMEOUT: Duration = Duration::from_secs(180); + +/// One `stat`-level namespace operation (entering the directory, resolving a +/// file by name) must finish in seconds. The failure this excludes — a +/// per-entry linear scan — takes hours here, so the ceiling is generous by +/// design while still being seconds. +const SINGLE_OP_BUDGET: Duration = Duration::from_secs(2); +/// How long to wait before a timed namespace operation, so the kernel's +/// one-second entry and attribute cache (C-1.3.4) has certainly expired: a +/// measurement inside that window is answered from the dcache, not by the +/// daemon. The 200 ms margin keeps the expiry from being observed a tick +/// early. +const CACHE_EXPIRY_WAIT: Duration = Duration::from_millis(1200); +/// Listing the 3000-entry torrent directory once. +const LIST_BUDGET: Duration = Duration::from_secs(5); +/// Walking the whole projection: 4000 files across 21 directories. +const WALK_BUDGET: Duration = Duration::from_secs(5); +/// Entries in the settled torrent directory: every file plus every +/// subdirectory. (`.stats` sits on the projection root, not on the torrent's +/// own directory.) +const EXPECTED_ENTRIES: usize = FILES_AT_ROOT + SUBDIRS; + +/// Deterministic content for fixture file `index` (hash-only fixture: the +/// daemon never downloads it, but a real piece hash keeps the metadata +/// honest). +fn file_content(index: usize) -> [u8; FILE_BYTES] { + let mut content = [0u8; FILE_BYTES]; + for (offset, byte) in content.iter_mut().enumerate() { + *byte = (index as u8) + .wrapping_mul(31) + .wrapping_add((offset as u8).wrapping_mul(7)) + .wrapping_add(11); + } + content +} + +/// Build the multi-file fixture torrent: bencode v1, one `files` entry per +/// projected file, SHA-1 piece hashes over the concatenated content in the +/// canonical path order libtorrent concatenates a torrent's files. +fn build_many_files_torrent() -> Vec { + let mut paths: Vec<(String, usize)> = + Vec::with_capacity(FILES_AT_ROOT + SUBDIRS * FILES_PER_SUBDIR); + for index in 0..FILES_AT_ROOT { + paths.push((format!("f{index:04}.bin"), index)); + } + for dir in 0..SUBDIRS { + for file in 0..FILES_PER_SUBDIR { + paths.push(( + format!("d{dir:02}/f{file:04}.bin"), + FILES_AT_ROOT + dir * FILES_PER_SUBDIR + file, + )); + } + } + + // `files` is path-ordered (BEP 3 names are byte-sorted) and the piece + // hashes cover the concatenation in that same order, so the fixture is a + // consistent torrent rather than merely a list of entries. + paths.sort_by(|left, right| left.0.as_bytes().cmp(right.0.as_bytes())); + + let mut content = Vec::with_capacity(paths.len() * FILE_BYTES); + for (_, index) in &paths { + content.extend_from_slice(&file_content(*index)); + } + let mut pieces = Vec::new(); + for chunk in content.chunks(PIECE_LEN) { + use sha1_smol::Sha1; + let mut hasher = Sha1::new(); + hasher.update(chunk); + pieces.extend_from_slice(&hasher.digest().bytes()); + } + + let announce_url = "http://127.0.0.1:1/announce"; + let mut torrent = Vec::new(); + torrent.push(b'd'); + torrent.extend_from_slice(b"8:announce"); + torrent.extend_from_slice(announce_url.len().to_string().as_bytes()); + torrent.push(b':'); + torrent.extend_from_slice(announce_url.as_bytes()); + torrent.extend_from_slice(b"4:infod"); + torrent.extend_from_slice(b"5:filesl"); + for (path, _) in &paths { + torrent.extend_from_slice(b"d6:lengthi"); + torrent.extend_from_slice(FILE_BYTES.to_string().as_bytes()); + torrent.push(b'e'); + torrent.extend_from_slice(b"4:pathl"); + for component in path.split('/') { + torrent.extend_from_slice(component.len().to_string().as_bytes()); + torrent.push(b':'); + torrent.extend_from_slice(component.as_bytes()); + } + torrent.push(b'e'); + torrent.push(b'e'); + } + torrent.push(b'e'); + torrent.extend_from_slice(format!("4:name{}:{}", TORRENT_NAME.len(), TORRENT_NAME).as_bytes()); + torrent.extend_from_slice(b"12:piece lengthi"); + torrent.extend_from_slice(PIECE_LEN.to_string().as_bytes()); + torrent.push(b'e'); + torrent.extend_from_slice(b"6:pieces"); + torrent.extend_from_slice(pieces.len().to_string().as_bytes()); + torrent.push(b':'); + torrent.extend_from_slice(&pieces); + torrent.extend_from_slice(b"ee"); + torrent +} + +/// Run `operation`, returning its duration. +fn timed(operation: impl FnOnce() -> T) -> (T, Duration) { + let started = Instant::now(); + let value = operation(); + (value, started.elapsed()) +} + +/// Wait until `directory` lists the torrent's own file table. +/// +/// C-2.5.3 lists a freshly delivered torrent in a temporary state from close +/// to the background persist landing: the projection exists, but its entries +/// are not yet the torrent's file table. AC-81 judges the settled namespace, +/// so this bounded wait skips only that contract-sanctioned window; the +/// measurements after it stay exact. +fn wait_for_file_table(directory: &Path, expected: usize, timeout: Duration) -> usize { + let deadline = Instant::now() + timeout; + let mut seen = 0; + while Instant::now() < deadline { + seen = fs::read_dir(&directory) + .map(|entries| entries.count()) + .unwrap_or(0); + if seen >= expected { + return seen; + } + thread::sleep(Duration::from_millis(100)); + } + seen +} + +/// Directories under `root` plus every file name, walked breadth-first. +fn recursive_walk(root: &Path) -> (BTreeSet, BTreeSet, Duration) { + let (result, elapsed) = timed(|| { + let mut pending = vec![root.to_path_buf()]; + let mut directories = BTreeSet::new(); + let mut files = BTreeSet::new(); + while let Some(directory) = pending.pop() { + for entry in fs::read_dir(&directory) + .unwrap_or_else(|e| panic!("read_dir {}: {e}", directory.display())) + { + let entry = entry.expect("directory entry"); + let path = entry.path(); + let file_type = entry.file_type().expect("entry file type"); + let relative = path + .strip_prefix(root) + .expect("walked path under root") + .to_string_lossy() + .to_string(); + if file_type.is_dir() { + directories.insert(relative); + pending.push(path); + } else if relative != ".stats" { + files.insert(relative); + } + } + } + (directories, files) + }); + let (directories, files) = result; + (directories, files, elapsed) +} + +#[test] +fn tc_recovery_02_large_directory_answers_within_seconds() { + if let Some(blocker) = fuse_mount_blocker() { + eprintln!("SKIP TC-recovery-02: this environment cannot mount FUSE ({blocker})"); + return; + } + let _slot = wave_slot(); + + let mut daemon = Daemon::start(Some(&crate::common::daemon_config(30, 15, 30)), "info"); + match daemon.wait_for_mount(DAEMON_MOUNT_TIMEOUT) { + MountGate::Mounted => {} + MountGate::Environment(detail) => { + eprintln!("SKIP TC-recovery-02: the environment refused the FUSE mount\n{detail}"); + return; + } + MountGate::Failed(detail) => panic!("daemon did not mount:\n{detail}"), + } + let mountpoint = daemon.mountpoint(); + + ingest_torrent_through_mount(&mountpoint, TORRENT_FILE, &build_many_files_torrent()); + assert!( + wait_for_projection(&mountpoint, TORRENT_FILE, PROJECTION_TIMEOUT), + "projection of a {} file torrent never appeared\n{}", + FILES_AT_ROOT + SUBDIRS * FILES_PER_SUBDIR, + daemon.output() + ); + // The projection root holds the torrent's own entry: `.stats` plus the + // directory named after the torrent, which is where a multi-file torrent's + // relative paths start (a single-file torrent puts the file there). + let projection_root = mountpoint.join("data").join(TORRENT_FILE); + let torrent_root = projection_root.join(TORRENT_NAME); + // The projection exists before the background persist lands (C-2.5.3: it + // is listed in a temporary state, then switches to the real tree). The + // measurements below judge the settled namespace, so wait for the file + // table — the wait is bounded and changes no assertion. + let settled = wait_for_file_table(&torrent_root, EXPECTED_ENTRIES, PROJECTION_TIMEOUT); + assert!( + settled >= EXPECTED_ENTRIES, + "{} never listed the torrent's file table ({settled} of {EXPECTED_ENTRIES} entries; \ + the temporary listing of C-2.5.3 never gave way to the real tree)\n{}", + torrent_root.display(), + daemon.output() + ); + + // ── enter ──────────────────────────────────────────────────────────────── + // Every probe above resolved this dentry, and the kernel caches the answer + // for one second (C-1.3.4): measured now, the stat below would be a cache + // hit that says nothing about the filesystem. Waiting the cache out makes + // the entry cost a LOOKUP, which is the operation a per-entry scan would + // make take hours. + thread::sleep(CACHE_EXPIRY_WAIT); + let (metadata, entered) = timed(|| fs::metadata(&torrent_root)); + let metadata = metadata.unwrap_or_else(|e| panic!("stat {}: {e}", torrent_root.display())); + assert!(metadata.is_dir(), "{} is not a directory", torrent_root.display()); + assert!( + entered <= SINGLE_OP_BUDGET, + "entering the torrent directory took {entered:?} (budget {SINGLE_OP_BUDGET:?}, cold lookup)" + ); + + // ── list ───────────────────────────────────────────────────────────────── + let (listed, listing) = timed(|| { + fs::read_dir(&torrent_root) + .unwrap_or_else(|e| panic!("read_dir {}: {e}", torrent_root.display())) + .map(|entry| entry.expect("directory entry").file_name()) + .collect::>() + }); + let mut expected: BTreeSet = (0..FILES_AT_ROOT) + .map(|index| format!("f{index:04}.bin").into()) + .collect(); + expected.extend((0..SUBDIRS).map(|dir| format!("d{dir:02}").into())); + assert_eq!( + listed.len(), + expected.len(), + "torrent directory listed {} entries, expected {} (complete output is required); \ + listed: {:?}", + listed.len(), + expected.len(), + listed.iter().take(10).collect::>() + ); + assert_eq!(listed, expected, "torrent directory listing is incomplete or renamed"); + assert!( + listing <= LIST_BUDGET, + "listing {} entries took {listing:?} (budget {LIST_BUDGET:?})", + listed.len() + ); + + // ── recursive listing ──────────────────────────────────────────────────── + let (directories, files, walked) = recursive_walk(&torrent_root); + assert_eq!( + directories.len(), + SUBDIRS, + "recursive listing found {} directories, expected {SUBDIRS}", + directories.len() + ); + assert_eq!( + files.len(), + FILES_AT_ROOT + SUBDIRS * FILES_PER_SUBDIR, + "recursive listing found {} files, expected {} (output complete)", + files.len(), + FILES_AT_ROOT + SUBDIRS * FILES_PER_SUBDIR + ); + assert!( + walked <= WALK_BUDGET, + "recursive listing took {walked:?} (budget {WALK_BUDGET:?})" + ); + + // ── find by name ───────────────────────────────────────────────────────── + // The walk above listed d07 with plain READDIR, which does not instantiate + // entries: this is the first name resolution of the file, so it is a real + // LOOKUP rather than a dcache hit. + let nested = torrent_root.join("d07").join("f0042.bin"); + let (nested_metadata, found) = timed(|| fs::metadata(&nested)); + let nested_metadata = + nested_metadata.unwrap_or_else(|e| panic!("stat {}: {e}", nested.display())); + assert!(nested_metadata.is_file(), "{} is not a regular file", nested.display()); + assert_eq!( + nested_metadata.len(), + FILE_BYTES as u64, + "looked-up file reports the wrong size" + ); + assert!( + found <= SINGLE_OP_BUDGET, + "resolving {} took {found:?} (budget {SINGLE_OP_BUDGET:?})", + nested.display() + ); + + // Teardown is part of the criterion's "does not hang": the graceful stop + // must still work on a mount carrying thousands of entries. + assert!(daemon.signal(libc::SIGTERM), "daemon already exited before SIGTERM"); + let status = daemon + .wait_for_exit(Duration::from_secs(60)) + .unwrap_or_else(|| panic!("daemon did not exit after SIGTERM\n{}", daemon.output())); + assert_eq!(status.code(), Some(0), "daemon exited with {status}"); + assert_eq!( + mountinfo_fuse_count(&mountpoint), + 0, + "the large-directory mount was left behind\n{}", + daemon.output() + ); +} diff --git a/tests/acceptance/test_tc_recovery_03.rs b/tests/acceptance/test_tc_recovery_03.rs new file mode 100644 index 0000000..1a6e5e8 --- /dev/null +++ b/tests/acceptance/test_tc_recovery_03.rs @@ -0,0 +1,136 @@ +//! Design acceptance case TC-recovery-03: SIGTERM stops the daemon with exit +//! code 0, drains the download engine, flushes the cache metadata and +//! unmounts FUSE (`docs/03-acceptance.md` §I AC-82). +//! +//! Observable criteria: exit code 0; no FUSE mount left in the mount table; +//! the cache metadata read *after* the process is gone records the piece the +//! mount served (C-5.2.2 makes shutdown the authoritative flush point, and +//! C-5.2.4 forbids judging the live daemon's metadata by a single read). + +use crate::common::{ + daemon_config, fuse_mount_blocker, ingest_torrent_through_mount, mountinfo_fuse_count, + read_when_ready, unique_torrent, wait_for_path, wait_for_projection, wave_slot, Daemon, + MountGate, TestHarness, DAEMON_MOUNT_TIMEOUT, +}; +use std::fs; +use std::time::Duration; + +pub const TC_ID: &str = "TC-recovery-03"; + +/// Parsing and persisting one fixture torrent. +const PROJECTION_TIMEOUT: Duration = Duration::from_secs(60); +/// Reading the seeded file through the mount (peer discovery included). +const READ_TIMEOUT: Duration = Duration::from_secs(120); +/// A graceful stop on an idle mount. +const EXIT_TIMEOUT: Duration = Duration::from_secs(60); + +#[test] +fn tc_recovery_03_sigterm_exits_zero_and_persists_cache_metadata() { + if let Some(blocker) = fuse_mount_blocker() { + eprintln!("SKIP TC-recovery-03: this environment cannot mount FUSE ({blocker})"); + return; + } + let _slot = wave_slot(); + let harness = TestHarness::with_torrent(unique_torrent("recovery-03-graceful.txt")); + + let mut daemon = Daemon::start(Some(&daemon_config(30, 15, 30)), "info"); + match daemon.wait_for_mount(DAEMON_MOUNT_TIMEOUT) { + MountGate::Mounted => {} + MountGate::Environment(detail) => { + eprintln!("SKIP TC-recovery-03: the environment refused the FUSE mount\n{detail}"); + return; + } + MountGate::Failed(detail) => panic!("daemon did not mount:\n{detail}"), + } + let mountpoint = daemon.mountpoint(); + + ingest_torrent_through_mount(&mountpoint, "graceful.torrent", &harness.torrent_data); + assert!( + wait_for_projection(&mountpoint, "graceful.torrent", PROJECTION_TIMEOUT), + "projection never appeared\n{}", + daemon.output() + ); + + // Serve one piece through the mount so the cache has metadata to flush. + let data_file = mountpoint + .join("data") + .join("graceful.torrent") + .join(harness.info.name()); + assert!( + wait_for_path(&data_file, PROJECTION_TIMEOUT), + "projected file {} never appeared\n{}", + data_file.display(), + daemon.output() + ); + let content = read_when_ready(&data_file, READ_TIMEOUT).unwrap_or_else(|e| { + panic!( + "read {} before SIGTERM: {e}\n{}", + data_file.display(), + daemon.output() + ) + }); + assert_eq!( + content.len(), + harness.file_content.len(), + "read the wrong byte count before SIGTERM" + ); + + // ── SIGTERM ────────────────────────────────────────────────────────────── + assert!(daemon.signal(libc::SIGTERM), "daemon already exited before SIGTERM"); + let status = daemon.wait_for_exit(EXIT_TIMEOUT).unwrap_or_else(|| { + panic!( + "daemon did not exit within {EXIT_TIMEOUT:?} after SIGTERM\n{}", + daemon.output() + ) + }); + assert_eq!( + status.code(), + Some(0), + "a graceful SIGTERM shutdown must exit 0, got {status}\n{}", + daemon.output() + ); + + // ── no mount residue ───────────────────────────────────────────────────── + assert_eq!( + mountinfo_fuse_count(&mountpoint), + 0, + "SIGTERM left the FUSE mount in the mount table\n{}", + daemon.output() + ); + + // ── cache metadata is the shutdown flush ───────────────────────────────── + let metadata_path = daemon.cache_dir().join("cache_metadata.txt"); + let metadata = fs::read_to_string(&metadata_path).unwrap_or_else(|e| { + panic!( + "cache metadata {} unreadable after shutdown: {e}\n{}", + metadata_path.display(), + daemon.output() + ) + }); + let info_hash = hex::encode( + harness + .info + .info_hash() + .expect("fixture torrent has an info hash"), + ); + let piece_key = format!("{info_hash}:piece:0"); + let recorded = metadata.lines().find_map(|line| { + let mut fields = line.split('\t'); + (fields.next() == Some(piece_key.as_str())).then(|| { + ( + fields.next().map(str::to_string), + fields.next().map(str::to_string), + ) + }) + }); + let (_, size) = recorded.unwrap_or_else(|| { + panic!( + "shutdown flush did not persist piece {piece_key}; cache metadata holds:\n{metadata}" + ) + }); + assert_eq!( + size.as_deref(), + Some("16384"), + "the persisted piece carries the wrong size; cache metadata holds:\n{metadata}" + ); +} diff --git a/tests/acceptance/test_tc_recovery_04.rs b/tests/acceptance/test_tc_recovery_04.rs new file mode 100644 index 0000000..17e9e88 --- /dev/null +++ b/tests/acceptance/test_tc_recovery_04.rs @@ -0,0 +1,297 @@ +//! Design acceptance case TC-recovery-04: debug logging stays lean during +//! reads — a read summary exists, no per-piece flood, and the abnormal path +//! warns (`docs/03-acceptance.md` §I AC-83). +//! +//! The assertions are shape-based, not wording-based: they classify each line +//! by its tracing level and by whether it names a single piece index or +//! reports a byte count, so a reworded message keeps passing and a per-piece +//! message stream does not. The fixture spans 32 pieces, so "one line per +//! piece" is distinguishable from "a handful of anomaly diagnostics". + +use crate::common::{ + base, build_multipiece_torrent_pieces, daemon_config, fuse_mount_blocker, + ingest_torrent_through_mount, read_when_ready, wait_for_path, wait_for_projection, wave_slot, + Daemon, MountGate, TestHarness, DAEMON_MOUNT_TIMEOUT, +}; +use std::fs; +use std::path::Path; +use std::thread; +use std::time::{Duration, Instant}; + +pub const TC_ID: &str = "TC-recovery-04"; + +/// Piece count of the served fixture: enough that a per-piece line stream +/// would be unmistakable. +const FIXTURE_PIECES: usize = 32; +/// The served fixture's file name (also its torrent name). +const FIXTURE_NAME: &str = "recovery-04-log-volume.bin"; +/// A read that spans `FIXTURE_PIECES` pieces may still log an anomaly per +/// affected piece; what the criterion forbids is a line per piece. +const MAX_PER_PIECE_LINES: usize = 3; + +/// Reading the served fixture across the local swarm. +const READ_BUDGET: Duration = Duration::from_secs(120); +/// The sourceless read fails after the configured short windows. +const ABSENT_READ_BUDGET: Duration = Duration::from_secs(30); +/// Time the daemon gets to meet the local seeder before the cold read. +const SEED_DISCOVERY_TIMEOUT: Duration = Duration::from_secs(120); +/// Parsing and persisting one fixture torrent. +const PROJECTION_TIMEOUT: Duration = Duration::from_secs(60); +/// A graceful stop after the reads. +const EXIT_TIMEOUT: Duration = Duration::from_secs(60); + +/// Remove ANSI colour sequences so level and message classification does not +/// depend on whether the writer emitted a TTY stream. +fn strip_ansi(line: &str) -> String { + let mut out = String::with_capacity(line.len()); + let mut chars = line.chars(); + while let Some(ch) = chars.next() { + if ch != '\u{1b}' { + out.push(ch); + continue; + } + // CSI: ESC '[' parameters final-byte. A non-CSI escape ends here. + let mut introduced = false; + for next in chars.by_ref() { + if !introduced { + introduced = true; + if next != '[' { + break; + } + continue; + } + if next.is_ascii_alphabetic() { + break; + } + } + } + out +} + +/// The tracing level token of a formatted log line. +fn level_of(line: &str) -> Option<&'static str> { + for token in line.split_whitespace().take(4) { + match token { + "TRACE" => return Some("TRACE"), + "DEBUG" => return Some("DEBUG"), + "INFO" => return Some("INFO"), + "WARN" => return Some("WARN"), + "ERROR" => return Some("ERROR"), + _ => {} + } + } + None +} + +/// A read summary reports how many bytes one read served. +fn is_read_summary(line: &str) -> bool { + let lower = line.to_ascii_lowercase(); + matches!(level_of(line), Some("DEBUG") | Some("INFO")) + && lower.contains("bytes") + && lower.contains("read") + && lower.chars().any(|ch| ch.is_ascii_digit()) +} + +/// A per-piece line names one piece index (`piece 12`, `piece=12`, +/// `pieces 12-13`); such a line repeating per piece is the flood the +/// criterion excludes. +fn mentions_piece_index(line: &str) -> bool { + let lower = line.to_ascii_lowercase(); + let bytes = lower.as_bytes(); + let mut cursor = 0; + while let Some(offset) = lower[cursor..].find("piece") { + let mut index = cursor + offset + "piece".len(); + while index < bytes.len() && !bytes[index].is_ascii_alphanumeric() { + index += 1; + } + if index < bytes.len() && bytes[index].is_ascii_digit() { + return true; + } + cursor = cursor + offset + "piece".len(); + } + false +} + +/// The `Seeds:` count of the `Peers: N Seeds: M` line of a `.stats` file. +fn seeds_in(stats: &str) -> Option { + stats.lines().find_map(|line| { + let rest = line.trim().strip_prefix("Peers:")?; + let (_, seeds) = rest.split_once("Seeds:")?; + seeds.trim().parse().ok() + }) +} + +/// Wait until the daemon's own `.stats` reports a seed for the fixture. +/// +/// The fixture is served by an in-process seeder announcing to the same +/// tracker as the daemon. A cold read issued before the daemon has met that +/// seeder spends the whole no-seeder window and answers `ENODATA`, which says +/// nothing about the logging this case judges: the windows are short so the +/// abnormal read below fails fast. Waiting for the seed keeps "there is a +/// source" a precondition instead of part of the measurement. +fn wait_for_seed(projection: &Path, timeout: Duration) -> bool { + let stats = projection.join(".stats"); + let deadline = Instant::now() + timeout; + while Instant::now() < deadline { + if let Ok(text) = fs::read_to_string(&stats) { + if seeds_in(&text).is_some_and(|seeds| seeds >= 1) { + return true; + } + } + thread::sleep(Duration::from_millis(200)); + } + false +} + +/// The abnormal read path must leave a warning behind. +fn is_read_warning(line: &str) -> bool { + matches!(level_of(line), Some("WARN") | Some("ERROR")) + && line.to_ascii_lowercase().contains("read") +} + +#[test] +fn tc_recovery_04_debug_logging_stays_lean_during_reads() { + if let Some(blocker) = fuse_mount_blocker() { + eprintln!("SKIP TC-recovery-04: this environment cannot mount FUSE ({blocker})"); + return; + } + let _slot = wave_slot(); + let harness = TestHarness::with_torrent(|announce_url| { + build_multipiece_torrent_pieces(announce_url, FIXTURE_NAME, FIXTURE_PIECES) + }); + assert_eq!( + harness.info.num_pieces() as usize, + FIXTURE_PIECES, + "fixture must span {FIXTURE_PIECES} pieces for the flood bound to mean anything" + ); + + // Debug level is the surface the case judges. The read window is wide: + // this fixture is 8 MiB and the swarm is local, so a loaded machine can + // legitimately spend more than a few seconds fetching the first pieces, + // and a read timing out would judge the machine instead of the logging. + // The empty-swarm windows stay short, so the abnormal read below still + // fails quickly. + let mut daemon = Daemon::start(Some(&daemon_config(120, 5, 10)), "debug"); + match daemon.wait_for_mount(DAEMON_MOUNT_TIMEOUT) { + MountGate::Mounted => {} + MountGate::Environment(detail) => { + eprintln!("SKIP TC-recovery-04: the environment refused the FUSE mount\n{detail}"); + return; + } + MountGate::Failed(detail) => panic!("daemon did not mount:\n{detail}"), + } + let mountpoint = daemon.mountpoint(); + + // ── served fixture: one cold read, one cache-hit read ─────────────────── + ingest_torrent_through_mount(&mountpoint, "log-volume.torrent", &harness.torrent_data); + assert!( + wait_for_projection(&mountpoint, "log-volume.torrent", PROJECTION_TIMEOUT), + "projection never appeared\n{}", + daemon.output() + ); + let data_file = mountpoint + .join("data") + .join("log-volume.torrent") + .join(FIXTURE_NAME); + assert!( + wait_for_path(&data_file, PROJECTION_TIMEOUT), + "projected file {} never appeared\n{}", + data_file.display(), + daemon.output() + ); + assert!( + wait_for_seed( + &mountpoint.join("data").join("log-volume.torrent"), + SEED_DISCOVERY_TIMEOUT + ), + "the daemon never met the local seeder; the cold read below would answer ENODATA for \ + the swarm rather than exercise the read path\n{}", + daemon.output() + ); + let cold = read_when_ready(&data_file, READ_BUDGET) + .unwrap_or_else(|e| panic!("cold read failed: {e}\n{}", daemon.output())); + assert_eq!( + cold.len(), + harness.file_content.len(), + "cold read returned the wrong byte count\n{}", + daemon.output() + ); + let warm = read_when_ready(&data_file, READ_BUDGET) + .unwrap_or_else(|e| panic!("warm read failed: {e}\n{}", daemon.output())); + assert_eq!( + warm.len(), + harness.file_content.len(), + "warm read returned the wrong byte count\n{}", + daemon.output() + ); + + // ── abnormal path: a torrent whose swarm is empty ─────────────────────── + let (absent_torrent, _) = base::create_single_piece_torrent( + "http://127.0.0.1:1/announce", + "recovery-04-absent-swarm.bin", + ); + ingest_torrent_through_mount(&mountpoint, "absent-swarm.torrent", &absent_torrent); + assert!( + wait_for_projection(&mountpoint, "absent-swarm.torrent", PROJECTION_TIMEOUT), + "sourceless projection never appeared\n{}", + daemon.output() + ); + let absent_file = mountpoint + .join("data") + .join("absent-swarm.torrent") + .join("recovery-04-absent-swarm.bin"); + assert!( + wait_for_path(&absent_file, PROJECTION_TIMEOUT), + "sourceless file {} never appeared\n{}", + absent_file.display(), + daemon.output() + ); + let absent = read_when_ready(&absent_file, ABSENT_READ_BUDGET); + assert_eq!( + absent.as_ref().err().and_then(|error| error.raw_os_error()), + Some(libc::ENODATA), + "a read from an empty swarm must settle as ENODATA (C-2.3.7), got {absent:?}\n{}", + daemon.output() + ); + + // ── stop and inspect the log ──────────────────────────────────────────── + assert!(daemon.signal(libc::SIGTERM), "daemon already exited before SIGTERM"); + let status = daemon.wait_for_exit(EXIT_TIMEOUT).unwrap_or_else(|| { + panic!( + "daemon did not exit within {EXIT_TIMEOUT:?} after SIGTERM\n{}", + daemon.output() + ) + }); + assert_eq!(status.code(), Some(0), "daemon exited with {status}\n{}", daemon.output()); + + let log = fs::read_to_string(daemon.log_path()).expect("read daemon log"); + let lines: Vec = log.lines().map(strip_ansi).collect(); + + let summaries = lines.iter().filter(|line| is_read_summary(line)).count(); + assert!( + summaries >= 1, + "no read summary line (byte count) in a debug log covering cold and warm reads:\n{log}" + ); + + let per_piece: Vec<&String> = lines + .iter() + .filter(|line| mentions_piece_index(line)) + .collect(); + assert!( + per_piece.len() <= MAX_PER_PIECE_LINES, + "{} per-piece lines for a {FIXTURE_PIECES}-piece read (max {MAX_PER_PIECE_LINES}); the \ + piece stream is the flood the criterion forbids:\n{}", + per_piece.len(), + per_piece + .iter() + .map(|line| line.as_str()) + .collect::>() + .join("\n") + ); + + let warnings = lines.iter().filter(|line| is_read_warning(line)).count(); + assert!( + warnings >= 1, + "the sourceless read left no WARN/ERROR line about the failed read:\n{log}" + ); +}