diff --git a/.github/workflows/scoreboard.yml b/.github/workflows/scoreboard.yml index 7be39c77..1a68fadc 100644 --- a/.github/workflows/scoreboard.yml +++ b/.github/workflows/scoreboard.yml @@ -12,6 +12,11 @@ name: Scale scoreboard # Nightly with the full ten-minute stream; on pull requests that touch # locking, watching, saving or limits with a two-minute stream, and the # table in the job summary. +# +# The second job kills the server with SIGKILL at random moments (during a +# build, a load, a stream of edits, a burst, a shutdown save), starts it +# again and checks the index comes back right (examples/chaos.rs). Pull +# requests use a fixed seed; other runs a new one, printed in the log. on: schedule: @@ -30,7 +35,10 @@ on: - "src/diagnostics/**" - "src/config.rs" - "src/main.rs" + - "src/index/persistence.rs" + - "src/index_lock.rs" - "examples/scoreboard.rs" + - "examples/chaos.rs" - "examples/support/**" - "benches/scoreboard/**" - ".github/workflows/scoreboard.yml" @@ -93,3 +101,48 @@ jobs: scoreboard.json ${{ runner.temp }}/score/run/server-*.log if-no-files-found: ignore + + chaos: + name: Kill and restart + runs-on: ubuntu-latest + timeout-minutes: 90 + steps: + - uses: actions/checkout@v4 + + - name: Install Protoc + run: sudo apt-get update && sudo apt-get install -y protobuf-compiler + + - name: Setup Rust toolchain (pinned by rust-toolchain.toml) + uses: dtolnay/rust-toolchain@master + with: + toolchain: "1.98.1" + + - name: Cache cargo + uses: Swatinem/rust-cache@v2 + + - name: Build the server and the harness + run: cargo build --release --bins --example chaos + + - name: Kill and restart + run: | + target/release/examples/chaos --dir "$RUNNER_TEMP/chaos" \ + --files 20000 --rounds "$ROUNDS" --seed "$SEED" \ + --markdown chaos.md --json chaos.json + env: + ROUNDS: ${{ github.event_name == 'pull_request' && '40' || '100' }} + SEED: ${{ github.event_name == 'pull_request' && '1' || github.run_id }} + + - name: Report + if: always() + run: test -f chaos.md && cat chaos.md >> "$GITHUB_STEP_SUMMARY" || true + + - name: Keep the rounds and the logs of failed ones + if: always() + uses: actions/upload-artifact@v7 + with: + name: chaos + path: | + chaos.md + chaos.json + ${{ runner.temp }}/chaos/run/failed-*.log + if-no-files-found: ignore diff --git a/CHANGELOG.md b/CHANGELOG.md index db180721..90f0d4ec 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -8,6 +8,26 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] ### Fixed +- **Every save killed half way left a file as large as the index.** A + save writes a temp file next to the index and renames it into place; a + server killed during the save (`kill -9`, a power cut, the OOM killer) + left the temp file, and nothing removed it. The server now removes them + when it starts. +- **A save that failed was forgotten.** With `save_after_updates`, the + count of unsaved updates was reset whether the save worked or not, so + after a save onto a full disk the shutdown skipped its save and the + saved index lacked those updates (the next start re-read the files, so + no search was wrong, but it took longer). The count now stays until a + save works. +- **A failed rename could delete the index.** When moving the new index + into place failed, the old index was deleted before trying again, so a + second failure left no index at all. The old index is now moved aside + and put back if the second try fails. +- **A panic while reading a file left it out of the index without a + word.** During the build, a file whose reading or parsing panicked was + skipped and not reported. It is now tried again at the end of the + build, and reported as unreadable if it keeps failing, like a file that + cannot be read. - **Every search waited 4 to 5 s soon after a restart.** An index loaded from disk keeps its unresolved imports (`import os`, packages outside the indexed folders) but not each file's import list. At the end of the @@ -142,6 +162,18 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 made up from the corpus (`--generate-regex`), and `tests/discovery_oracle.rs` compares the indexed files and the FILES box with `rg`. +- **Kill and restart.** `examples/chaos.rs` kills the server binary with + SIGKILL at random moments (during a build, a load from disk, a stream of + edits, a periodic save, a burst of changes, and the save at shutdown), + starts it again and checks that it loads the saved index, leaves no temp + file, catches up with every change and passes `/api/check`. The "Scale + scoreboard" workflow runs it nightly and on pull requests that touch + saving or watching (job "Kill and restart"). +- **More fault points** (`--features failpoints`, `src/faults.rs`): out of + file handles, a file gone between listing and reading, a slow disk, a + panic while reading or parsing a file, events lost by the OS, a save + onto a full disk and a failed rename, each with a test in + `tests/fault_injection.rs`. - **A scale scoreboard.** `examples/scoreboard.rs` runs the server binary over HTTP in seven scenarios (cold build, warm restart, branch switch, a ten-minute stream of edits, overloaded searching, saves under load, and diff --git a/docs/book/src/how-it-works/persistence.md b/docs/book/src/how-it-works/persistence.md index abc7ceb3..4851cabf 100644 --- a/docs/book/src/how-it-works/persistence.md +++ b/docs/book/src/how-it-works/persistence.md @@ -12,6 +12,26 @@ named temporary file next to the target, fsynced, and renamed into place. Two saves cannot interleave, and a crash at any point leaves the previous file intact. Checkpoints during a long build use the same path. +- **A save that is killed** (`kill -9`, a power cut, the out-of-memory + killer) leaves its temporary file (`` with `.tmp..` + in place of its extension, as large as the index). The next server to + take the index lock removes them before it loads ("Removed temp files + left by an index save that did not finish" in the log). +- **A failed rename** (Windows refuses to replace a file another process + has open) is tried once more with the old index moved aside; if that + fails too, the old index is put back. The save fails, and the index on + disk is the previous one. +- **A failed save** (disk full) is logged as an error, and with + `save_after_updates` the updates it held still count: the next save, + after more updates or at shutdown, writes them. The index on disk is + older until then, so the next start re-reads the files changed since. + +`tests/fault_injection.rs` fails the write and the rename on purpose +(fault points `save.write` and `save.rename`), and `examples/chaos.rs` +kills the server binary during saves, builds and shutdowns and checks that +the next start loads the index and catches up (see +[How fcs is tested](testing.md#killed-at-any-moment)). + ## One server per index A server takes an exclusive lock on `.lock` before it loads diff --git a/docs/book/src/how-it-works/testing.md b/docs/book/src/how-it-works/testing.md index bb29b2bb..5cd52d57 100644 --- a/docs/book/src/how-it-works/testing.md +++ b/docs/book/src/how-it-works/testing.md @@ -26,11 +26,12 @@ wrote every line and knows the answer. | `tests/rank_snapshot.rs` | the first 20 hits and the total of about a hundred searches; the same corpus at two places on disk must rank the same | `tests/snapshots/rank_order.txt`, changed only on purpose | `cargo test --test rank_snapshot` | | `tests/discovery_oracle.rs` | which files are indexed (the build and the watcher's per-file check) on random trees of `.gitignore`, `.ignore`, `.rgignore` and `.git/info/exclude` rules; the FILES box with a regex | `rg --files`, and `rg` over the path list | `cargo test --test discovery_oracle` (needs `rg`) | | `tests/lock_sim.rs` | the engine lock and the watcher's install steps under minutes of made-up load (back-to-back half-second searches, one 20 s search among quick ones, a busy server during a branch switch): every search answered, no search waits past its hold-back plus one step, backlogs drain at half speed or better, a slow search delays only the writer | bounds derived from the protocol, on a simulated clock (`fast_code_search::sim`): the real lock code, the same schedule on every run and OS, four minutes in about a second | `cargo test --test lock_sim` (`-- --ignored --nocapture` prints the tuning table) | -| `tests/fault_injection.rs` | failed reads, panics while applying changes, lost changes: each is retried, reported and repaired | expected recovery | `cargo test --features failpoints --test fault_injection` | +| `tests/fault_injection.rs` | failed reads (permission, out of file handles, a file gone between listing and reading), a slow disk, panics while reading, parsing or applying changes, lost changes and lost events, a save onto a full disk or a failed rename: each is retried, reported or repaired, searches are not held up, and the saved index stays whole | expected recovery | `cargo test --features failpoints --test fault_injection` (fault points are listed in `src/faults.rs`) | | `examples/rg_backtest.rs` | fixed and generated queries and regexes on tokio, Django and fixtures, with paging and default limits, on an index built in one go, restarted from disk (`--history reload`) and filled by the watcher (`--history watch`) | `rg` | see [Correctness against ripgrep](../benchmarks/correctness.md) | | `examples/graph_oracle.rs` | the import graph on Django, Vite and generated deep trees | grimp, TypeScript's resolver | CI job "graph oracle" | | `examples/ref_oracle.rs`, `examples/impact_oracle.rs` | Python references and diff impact on real repositories | Jedi | CI jobs "ref oracle", "impact oracle" | | `examples/scoreboard.rs` | the server binary over HTTP in seven scenarios (cold build, warm restart, branch switch, ten-minute stream, slow mix, saves under load, event-queue overflow): searches turned away, latency, time until the index matches the disk, memory, CPU, diagnostic captures, crashes, `/api/check` | targets in `benches/scoreboard/targets.toml` | nightly and on pull requests that touch locking or watching (workflow "Scale scoreboard"), see [Scale scoreboard](../benchmarks/scoreboard.md) | +| `examples/chaos.rs` | `kill -9` of the server binary at random moments during a build, a load, a stream of edits, a periodic save, a burst and the shutdown save; after each, a restart must load the saved index (never reject it), leave no temp file, catch up with every change and pass `/api/check` | the files on disk | nightly and on pull requests that touch saving or watching (workflow "Scale scoreboard", job "Kill and restart"), see [below](#killed-at-any-moment) | | `examples/watch_load.rs`, `examples/limits_bench.rs` | searches answered and latency while a large tree changes; where limits bite | measured numbers | by hand, see [Incremental updates](incremental.md#how-this-is-tested) | Every test that drives the index also runs its self-checks @@ -90,6 +91,51 @@ NODE_PATH=/tmp/pw/node_modules FCS_REQUIRE_BROWSER=1 cargo test --release --test Without Playwright the leg prints a note and is skipped; CI's Linux test job sets `FCS_REQUIRE_BROWSER`, so there it fails instead. +## Killed at any moment + +`examples/chaos.rs` starts the server binary on a generated tree of 20,000 +files and kills it with SIGKILL, round after round, at a random moment of +one of these: + +| Kind | Killed | +|---|---| +| `build` | during a build from scratch, which saves a checkpoint every quarter of the tree | +| `load` | while it loads the saved index and checks the tree | +| `stream` | while 300 files a second are rewritten, created and removed, and saved every 300 updates; the edits go on for a second after the kill | +| `save` | 0 to 20 ms after one of those saves begins (it watches for the save's temp file every millisecond) | +| `burst` | while the watcher installs a tenth of the files rewritten at once | +| `shutdown` | 0 to 20 ms after the save at shutdown (SIGTERM) begins | + +After each kill it starts the server again and requires: the saved index +is loaded, or there was none (a kill must never leave one the next start +rejects); no temp file of a killed save is left once the server answers; +the server becomes ready and catches up (nothing pending, the changed +files indexed as they are on disk); `/api/check?all=true` finds nothing; +and it does not crash. The seed is printed, and `--seed N` replays the +same kill moments; a failing round keeps its server log as +`failed-.log`. + +60 rounds on a 4 vCPU VM, 2026-10-23 (seed 4): + +| Killed during | Rounds | Killed mid save | No index after | Index rejected | Temp files left | Slowest ready | Slowest catch-up | Check problems | +|---|---|---|---|---|---|---|---|---| +| build | 10 | 1 | 3 | 0 | 0 | 1.8 s | 1.8 s | 0 | +| load | 10 | 0 | 0 | 0 | 0 | 0.3 s | 0.5 s | 0 | +| stream | 10 | 1 | 0 | 0 | 0 | 0.4 s | 0.8 s | 0 | +| save | 10 | 10 | 0 | 0 | 0 | 0.3 s | 0.8 s | 0 | +| burst | 10 | 0 | 0 | 0 | 0 | 0.3 s | 0.8 s | 0 | +| shutdown | 10 | 10 | 0 | 0 | 0 | 0.4 s | 0.8 s | 0 | + +"No index after" is a build killed before its first checkpoint: the next +start builds from scratch. A build killed later loads the checkpoint and +indexes the rest. CI runs 40 rounds on pull requests (seed 1) and 100 +nightly (a new seed). + +This tests a killed process, not a power cut: the kernel still writes out +what the process wrote. A save fsyncs its file before the rename and, on +Linux and macOS, the folder after it, so a power cut should leave either +the old index or the new one; nothing here simulates that. + ## Reproducing a failure - proptest suites print the shrunk sequence or query that failed, which is @@ -133,6 +179,11 @@ generated Python trees with grimp (job "graph oracle"). while the import graph's parked imports were retried in one lock hold; a `backlog` diagnostic fired under steady edits the watcher kept up with (scale scoreboard). +- A save killed half way left a temp file as large as the index, for + good; a save that failed (disk full) was forgotten, so the shutdown + skipped its save; a failed rename deleted the index before trying + again; and a panic while reading a file during the build left it out + without a word (fault points and the kill-and-restart run). - Earlier probes found a crash when a large file was rewritten during a search, "server unavailable" at the end of a build, and lost changes after failed reads or a panic; the fault and watch tests cover them. diff --git a/docs/book/src/reference/index-format.md b/docs/book/src/reference/index-format.md index 3bc672c2..57c3e62d 100644 --- a/docs/book/src/reference/index-format.md +++ b/docs/book/src/reference/index-format.md @@ -35,7 +35,8 @@ live ids on load, so ids stay stable across restarts. - **Atomic.** A save writes a unique temporary file next to the target, fsyncs it, and renames it into place; saves are serialized within the - process. A crash leaves the previous index intact. + process. A crash leaves the previous index intact, and the next start + removes the temporary file a killed save left. - **Detects drift.** Each file's mtime and size at read time are stored; on load a file whose stat differs is re-read. - **Pinned.** `tests/fixtures/index-v8.fcsidx` is compared byte for byte diff --git a/examples/chaos.rs b/examples/chaos.rs new file mode 100644 index 00000000..84246cdc --- /dev/null +++ b/examples/chaos.rs @@ -0,0 +1,634 @@ +//! Chaos: `kill -9` the real server at random moments, restart it, and +//! check that the index comes back right. +//! +//! Each round starts `fast_code_search_server` on a generated tree (see +//! `examples/support/load_tree.rs`), does one of the things below, and +//! kills the process with SIGKILL at a random moment while it works: +//! +//! - `build`: a build from scratch, with checkpoint saves along the way; +//! - `load`: a start from the saved index, while it loads and checks the +//! tree; +//! - `stream`: files rewritten, created and removed while the watcher +//! applies them and saves every few hundred updates; the edits go on for +//! a second after the kill, as they would while a server is down; +//! - `save`: the same stream, killed a moment (0 to 20 ms) after one of +//! the periodic saves begins; +//! - `burst`: a tenth of the files rewritten at once, killed while the +//! watcher installs them; +//! - `shutdown`: a graceful stop (SIGTERM), killed a moment after its save +//! begins. +//! +//! Then it starts the server again, unharmed, and checks: +//! +//! - the saved index was loaded, or there was none: a kill must never leave +//! an index the next start has to reject (the save writes a temp file, +//! fsyncs it and renames it over the old one); +//! - no temp file of a killed save is left once the server has started; +//! - the server becomes ready, catches up with every change (nothing +//! pending, and the changed files indexed as they are on disk), and +//! `GET /api/check?all=true` finds nothing wrong: invariants, every +//! file's content, and the file set against a fresh walk; +//! - it did not crash. +//! +//! ```text +//! cargo build --release --bins --example chaos +//! target/release/examples/chaos --dir /tmp/fcs-chaos --files 20000 --rounds 40 \ +//! [--seed N] [--markdown OUT] [--json OUT] +//! ``` +//! +//! Any failed check fails the run (exit code 1). The report holds numbers +//! only. The seed is printed so a failing run can be repeated; the server +//! logs of a failing round are kept in `--dir`. + +#[path = "support/load_tree.rs"] +mod load_tree; +#[path = "support/server.rs"] +mod server; + +use anyhow::{bail, Context, Result}; +use clap::Parser; +use load_tree::{generate, path_of, script}; +use rand::rngs::StdRng; +use rand::{Rng, SeedableRng}; +use serde::Serialize; +use server::{free_port, Server}; +use std::collections::BTreeMap; +use std::fmt::Write as _; +use std::path::{Path, PathBuf}; +use std::sync::atomic::{AtomicBool, AtomicU64, Ordering}; +use std::sync::{Arc, Mutex}; +use std::time::{Duration, Instant}; + +const KINDS: &[&str] = &["build", "load", "stream", "save", "burst", "shutdown"]; + +#[derive(Parser, Debug)] +#[command(about = "kill -9 the server at random moments and check it recovers")] +struct Args { + /// Working directory: the generated tree, the index and the logs. + #[arg(long, default_value = "/tmp/fcs-chaos")] + dir: PathBuf, + /// Files in the generated tree. + #[arg(long, default_value_t = 20_000)] + files: usize, + /// Rounds (each one kill and one check), taking the kinds in turn. + #[arg(long, default_value_t = 40)] + rounds: usize, + /// Seed for the kill moments (default: the time). + #[arg(long)] + seed: Option, + /// Only these kinds (comma separated). + #[arg(long, value_delimiter = ',')] + kinds: Vec, + /// The server binary (default: next to this example's folder). + #[arg(long)] + server: Option, + /// Files changed per second in `stream`. + #[arg(long, default_value_t = 300)] + stream_rate: usize, + /// Save the index after this many watcher updates. + #[arg(long, default_value_t = 300)] + save_after_updates: usize, + /// Give up on a restart catching up after this long. + #[arg(long, default_value_t = 600)] + settle_seconds: u64, + #[arg(long)] + markdown: Option, + #[arg(long)] + json: Option, +} + +/// One round: what was killed when, and what the restart found. +#[derive(Debug, Default, Clone, Serialize)] +struct Round { + round: usize, + kind: String, + /// From the start of the server (or of the shutdown) to the kill. + kill_after_ms: u64, + /// A save's temp file was there when the process died. + killed_mid_save: bool, + /// The index file was there after the kill. + index_left: bool, + /// Files changed since the last check. + changed: usize, + /// The restart loaded the saved index ("loaded"), had none ("none"), + /// or rejected it ("rejected"). + load: String, + /// Temp files still there once the restarted server answered. + temp_files_after_start: usize, + ready_secs: f64, + /// From ready until the index matched the disk. + fresh_secs: Option, + not_settled: bool, + check_problems: usize, + crashed: bool, + failures: Vec, +} + +fn main() -> Result<()> { + let args = Args::parse(); + let kinds: Vec = if args.kinds.is_empty() { + KINDS.iter().map(|s| s.to_string()).collect() + } else { + args.kinds.clone() + }; + for k in &kinds { + if !KINDS.contains(&k.as_str()) { + bail!("unknown kind {k:?}; known: {}", KINDS.join(", ")); + } + } + let server = match &args.server { + Some(p) => p.clone(), + None => { + let exe = std::env::current_exe()?; + let bin_dir = exe.parent().and_then(Path::parent).context("exe path")?; + bin_dir.join(format!( + "fast_code_search_server{}", + std::env::consts::EXE_SUFFIX + )) + } + }; + if !server.exists() { + bail!( + "no server binary at {} (cargo build --release --bins, or --server)", + server.display() + ); + } + let seed = args.seed.unwrap_or_else(|| { + std::time::SystemTime::now() + .duration_since(std::time::UNIX_EPOCH) + .unwrap() + .as_secs() + }); + eprintln!("seed {seed}"); + std::fs::create_dir_all(&args.dir)?; + let tree = args.dir.join("tree"); + generate(&tree, args.files); + let tree = tree.canonicalize()?; + let work = args.dir.canonicalize()?.join("run"); + let _ = std::fs::remove_dir_all(&work); + std::fs::create_dir_all(&work)?; + let chaos = Chaos { + args: &args, + server, + tree, + work, + rev: AtomicU64::new(1), + created: Mutex::new(Vec::new()), + changed: Mutex::new(Vec::new()), + }; + chaos.remove_created_files(); + + // A clean build first, to time it and have an index to start from. + let t = Instant::now(); + let s = chaos.start(true)?; + s.wait_settled(Duration::from_secs(3600))?; + s.stop()?; + let build = t.elapsed(); + let t = Instant::now(); + let s = chaos.start(false)?; + s.wait_settled(Duration::from_secs(3600))?; + let restart = t.elapsed(); + s.stop()?; + eprintln!("build {build:.1?}, restart {restart:.1?}"); + + let mut rng = StdRng::seed_from_u64(seed); + let mut rounds = Vec::new(); + for round in 0..args.rounds { + let kind = &kinds[round % kinds.len()]; + let mut r = Round { + round, + kind: kind.clone(), + ..Default::default() + }; + chaos + .kill_round(&mut r, &mut rng, build, restart) + .with_context(|| format!("round {round} ({kind})"))?; + chaos + .check_round(&mut r) + .with_context(|| format!("checking round {round} ({kind})"))?; + eprintln!( + "round {round:>3} {kind:<8} killed at {:>6} ms{} load {:<8} ready {:>5.1} s fresh {} problems {}{}", + r.kill_after_ms, + if r.killed_mid_save { " (mid save)" } else { "" }, + r.load, + r.ready_secs, + r.fresh_secs.map_or("-".into(), |f| format!("{f:.1} s")), + r.check_problems, + if r.failures.is_empty() { + String::new() + } else { + format!(" FAILED: {}", r.failures.join("; ")) + } + ); + rounds.push(r); + } + + let table = render_markdown(&rounds, seed, args.files); + println!("{table}"); + if let Some(p) = &args.markdown { + std::fs::write(p, &table)?; + } + if let Some(p) = &args.json { + std::fs::write(p, serde_json::to_string_pretty(&rounds)?)?; + } + let failed: Vec<&Round> = rounds.iter().filter(|r| !r.failures.is_empty()).collect(); + if !failed.is_empty() { + for r in failed { + eprintln!( + "FAILED round {} ({}): {}", + r.round, + r.kind, + r.failures.join("; ") + ); + } + eprintln!("seed {seed}"); + std::process::exit(1); + } + eprintln!("every round recovered"); + Ok(()) +} + +struct Chaos<'a> { + args: &'a Args, + server: PathBuf, + tree: PathBuf, + work: PathBuf, + /// The next revision written. + rev: AtomicU64, + /// Files created by streams and not removed yet. + created: Mutex>, + /// Files changed since the last check. + changed: Mutex>, +} + +impl Chaos<'_> { + fn index(&self) -> PathBuf { + self.work.join("index.bin") + } + + fn start(&self, cold: bool) -> Result { + if cold { + let _ = std::fs::remove_file(self.index()); + } + let port = free_port()?; + let config = format!( + "[server]\nenable_grpc = false\nweb_address = \"127.0.0.1:{port}\"\n\n\ + [indexer]\npaths = [{tree:?}]\nindex_path = {index:?}\nwatch = true\n\ + save_after_updates = {save}\ncheckpoint_interval_files = {checkpoint}\n", + tree = self.tree.to_string_lossy(), + index = self.index().to_string_lossy(), + save = self.args.save_after_updates, + checkpoint = (self.args.files / 4).max(1), + ); + Server::spawn( + &self.server, + &self.work, + port, + &config, + &self.work.join("server.log"), + ) + } + + /// Temp files of index saves in the work directory. + fn temp_files(&self) -> usize { + std::fs::read_dir(&self.work) + .into_iter() + .flatten() + .flatten() + .filter(|e| { + e.file_name() + .to_string_lossy() + .starts_with("index.bin.tmp.") + }) + .count() + } + + /// Start the server, do what `r.kind` says, and kill it at a random + /// moment. + fn kill_round( + &self, + r: &mut Round, + rng: &mut StdRng, + build: Duration, + restart: Duration, + ) -> Result<()> { + let at = |rng: &mut StdRng, max: Duration| { + Duration::from_millis(rng.random_range(0..max.as_millis().max(1) as u64)) + }; + match r.kind.as_str() { + "build" => { + let s = self.start(true)?; + let wait = at(rng, build); + self.kill_after(r, &s, s.started, wait)?; + } + "load" => { + let s = self.start(false)?; + let wait = at(rng, restart.mul_f64(1.2)); + self.kill_after(r, &s, s.started, wait)?; + } + "stream" => { + let s = self.start(false)?; + s.wait_settled(Duration::from_secs(3600))?; + let stop = Arc::new(AtomicBool::new(false)); + let started = Instant::now(); + std::thread::scope(|scope| -> Result<()> { + let stop2 = stop.clone(); + scope.spawn(move || self.stream(&stop2)); + let wait = Duration::from_millis(500) + at(rng, Duration::from_secs(8)); + let res = self.kill_after(r, &s, started, wait); + // Edits go on while the server is down. + std::thread::sleep(Duration::from_secs(1)); + stop.store(true, Ordering::Release); + res + })?; + } + "burst" => { + let s = self.start(false)?; + s.wait_settled(Duration::from_secs(3600))?; + let started = Instant::now(); + self.rewrite_share(10); + let wait = at(rng, Duration::from_secs(5)); + self.kill_after(r, &s, started, wait)?; + } + "save" => { + let s = self.start(false)?; + s.wait_settled(Duration::from_secs(3600))?; + let stop = Arc::new(AtomicBool::new(false)); + let started = Instant::now(); + std::thread::scope(|scope| -> Result<()> { + let stop2 = stop.clone(); + scope.spawn(move || self.stream(&stop2)); + // Into the second save or later, a moment after it begins. + let skip = 1 + rng.random_range(0..3); + let res = self.kill_while_saving(r, &s, started, rng, skip); + std::thread::sleep(Duration::from_secs(1)); + stop.store(true, Ordering::Release); + res + })?; + } + "shutdown" => { + let s = self.start(false)?; + s.wait_settled(Duration::from_secs(3600))?; + // Something unsaved for the shutdown to save: fewer + // updates than start a save of their own. + let every = (self.args.files * 2 / self.args.save_after_updates.max(1)).max(2); + self.rewrite_share(every); + std::thread::sleep(Duration::from_secs(2)); + s.terminate(); + self.kill_while_saving(r, &s, Instant::now(), rng, 0)?; + } + _ => unreachable!(), + } + r.index_left = self.index().exists(); + r.changed = self.changed.lock().unwrap().len(); + Ok(()) + } + + /// Kill `s` a moment (0 to 20 ms) after a save begins, past `skip` + /// earlier saves: the moment a save's temp file appears is watched for + /// every millisecond. Without a save within 60 s, it is killed then. + fn kill_while_saving( + &self, + r: &mut Round, + s: &Server, + from: Instant, + rng: &mut StdRng, + mut skip: usize, + ) -> Result<()> { + let mut saving = false; + while from.elapsed() < Duration::from_secs(60) && !s.crashed() { + let now = self.temp_files() > 0; + if now && !saving { + if skip == 0 { + std::thread::sleep(Duration::from_millis(rng.random_range(0..=20))); + break; + } + skip -= 1; + } + saving = now; + std::thread::sleep(Duration::from_millis(1)); + } + self.kill_after(r, s, from, Duration::ZERO) + } + + /// Kill `s` once `wait` has passed since `from`, noting whether a save + /// was under way. + fn kill_after(&self, r: &mut Round, s: &Server, from: Instant, wait: Duration) -> Result<()> { + if let Some(rest) = wait.checked_sub(from.elapsed()) { + std::thread::sleep(rest); + } + r.kill_after_ms = from.elapsed().as_millis() as u64; + r.killed_mid_save = self.temp_files() > 0; + s.kill9() + } + + /// Start the server again and check it recovered. + fn check_round(&self, r: &mut Round) -> Result<()> { + let s = self.start(false)?; + let ready = s.wait_ready(Duration::from_secs(self.args.settle_seconds)); + r.ready_secs = s.started.elapsed().as_secs_f64(); + r.temp_files_after_start = self.temp_files(); + let log = std::fs::read_to_string(self.work.join("server.log")).unwrap_or_default(); + r.load = if log.contains("Failed to load persisted index") { + "rejected" + } else if log.contains("Loaded persisted index") { + "loaded" + } else { + "none" + } + .into(); + if let Err(e) = ready { + r.crashed = s.crashed(); + r.failures.push(format!("not ready: {e}")); + } else { + let ready_at = Instant::now(); + // Some of the changed files, and a few others (the status + // check needs at least one path). + let paths = { + let changed = self.changed.lock().unwrap(); + let step = (changed.len() / 90).max(1); + let mut paths: Vec = + changed.iter().step_by(step).take(90).cloned().collect(); + let every = (self.args.files / 10).max(1); + paths.extend( + (0..self.args.files) + .step_by(every) + .map(|i| path_of(&self.tree, i)), + ); + paths + }; + let settle = Duration::from_secs(self.args.settle_seconds); + let settled = s.wait_settled(settle).is_ok(); + let fresh = settled.then(|| s.wait_fresh(&paths, settle)).flatten(); + r.fresh_secs = fresh.map(|_| ready_at.elapsed().as_secs_f64()); + r.not_settled = fresh.is_none(); + if fresh.is_some() { + let report = s.check()?; + r.check_problems = report.problems(); + } + r.crashed = s.crashed(); + if !r.crashed { + s.stop()?; + } + } + if r.load == "rejected" { + r.failures.push("the saved index was rejected".into()); + } + if r.temp_files_after_start > 0 { + r.failures + .push(format!("{} temp files left", r.temp_files_after_start)); + } + if r.not_settled { + r.failures.push("never matched the disk".into()); + } + if r.check_problems > 0 { + r.failures + .push(format!("{} check problems", r.check_problems)); + } + if r.crashed { + r.failures.push("crashed".into()); + } + if !r.failures.is_empty() { + let _ = std::fs::copy( + self.work.join("server.log"), + self.work.join(format!("failed-{}.log", r.round)), + ); + } + self.changed.lock().unwrap().clear(); + Ok(()) + } + + fn next_rev(&self) -> u64 { + self.rev.fetch_add(1, Ordering::Relaxed) + } + + fn changed(&self, p: PathBuf) { + self.changed.lock().unwrap().push(p); + } + + /// Rewrite one file in `every`. + fn rewrite_share(&self, every: usize) { + let rev = self.next_rev(); + for i in (rev as usize % every..self.args.files).step_by(every) { + let p = path_of(&self.tree, i); + if std::fs::write(&p, script(i, rev)).is_ok() { + self.changed(p); + } + } + } + + /// Rewrite, create and remove files at `stream_rate` until `stop`. + fn stream(&self, stop: &AtomicBool) { + let per_tick = (self.args.stream_rate / 10).max(1); + let t = Instant::now(); + let mut tick = 0u32; + while !stop.load(Ordering::Acquire) { + let rev = self.next_rev(); + for k in 0..per_tick { + let i = + (rev as usize).wrapping_mul(104_729).wrapping_add(k * 7_919) % self.args.files; + let p = path_of(&self.tree, i); + if std::fs::write(&p, script(i, rev)).is_ok() { + self.changed(p); + } + } + let new = path_of(&self.tree, rev as usize * 997 % self.args.files) + .with_file_name(format!("new_{rev}.py")); + if std::fs::write(&new, script(rev as usize, rev)).is_ok() { + self.changed(new.clone()); + let mut created = self.created.lock().unwrap(); + created.push(new); + if created.len() > 50 { + let old = created.remove(0); + if std::fs::remove_file(&old).is_ok() { + self.changed(old); + } + } + } + tick += 1; + if let Some(wait) = (Duration::from_millis(100) * tick).checked_sub(t.elapsed()) { + std::thread::sleep(wait); + } + } + } + + /// Files earlier runs created, so every run starts from the generated + /// tree (rewritten revisions aside). + fn remove_created_files(&self) { + for dir in std::fs::read_dir(&self.tree) + .into_iter() + .flatten() + .flatten() + { + for f in std::fs::read_dir(dir.path()) + .into_iter() + .flatten() + .flatten() + { + if f.file_name().to_string_lossy().starts_with("new_") { + let _ = std::fs::remove_file(f.path()); + } + } + } + } +} + +fn render_markdown(rounds: &[Round], seed: u64, files: usize) -> String { + #[derive(Default)] + struct Sum { + rounds: usize, + mid_save: usize, + no_index: usize, + rejected: usize, + temp_left: usize, + max_ready: f64, + max_fresh: f64, + not_settled: usize, + problems: usize, + crashed: usize, + failed: usize, + } + let mut by_kind: BTreeMap<&str, Sum> = BTreeMap::new(); + for r in rounds { + let s = by_kind.entry(&r.kind).or_default(); + s.rounds += 1; + s.mid_save += usize::from(r.killed_mid_save); + s.no_index += usize::from(r.load == "none"); + s.rejected += usize::from(r.load == "rejected"); + s.temp_left += r.temp_files_after_start; + s.max_ready = s.max_ready.max(r.ready_secs); + s.max_fresh = s.max_fresh.max(r.fresh_secs.unwrap_or(0.0)); + s.not_settled += usize::from(r.not_settled); + s.problems += r.check_problems; + s.crashed += usize::from(r.crashed); + s.failed += usize::from(!r.failures.is_empty()); + } + let mut out = String::new(); + let _ = writeln!( + out, + "Chaos: {} rounds on {files} files, seed {seed}.\n", + rounds.len() + ); + out.push_str( + "| Killed during | Rounds | Mid save | No index | Rejected | Temp files left | Max ready | Max catch-up | Not settled | Check problems | Crashes | Failed |\n\ + |---|---|---|---|---|---|---|---|---|---|---|---|\n", + ); + for (kind, s) in &by_kind { + let _ = writeln!( + out, + "| {kind} | {} | {} | {} | {} | {} | {:.1} s | {:.1} s | {} | {} | {} | {} |", + s.rounds, + s.mid_save, + s.no_index, + s.rejected, + s.temp_left, + s.max_ready, + s.max_fresh, + s.not_settled, + s.problems, + s.crashed, + s.failed + ); + } + out +} diff --git a/examples/scoreboard.rs b/examples/scoreboard.rs index 157fa1c1..c41b9914 100644 --- a/examples/scoreboard.rs +++ b/examples/scoreboard.rs @@ -32,16 +32,17 @@ #[path = "support/load_tree.rs"] mod load_tree; +#[path = "support/server.rs"] +mod server; use anyhow::{bail, Context, Result}; use clap::Parser; -use fast_code_search::search::integrity::IntegrityReport; use load_tree::{generate, path_of, script, MIXED}; use rayon::prelude::*; use serde::Serialize; +use server::{client, free_port, Server}; use std::fmt::Write as _; use std::path::{Path, PathBuf}; -use std::process::{Child, Command, Stdio}; use std::sync::atomic::{AtomicBool, AtomicU64, Ordering}; use std::sync::{Arc, Mutex}; use std::time::{Duration, Instant}; @@ -430,26 +431,13 @@ impl Run<'_> { captures = captures.to_string_lossy(), save = setup.save_after_updates, ); - let config_path = self.work.join("config.toml"); - std::fs::write(&config_path, config)?; - let log = std::fs::File::create(self.work.join("server.log"))?; - let child = Command::new(&self.server) - .arg("--config") - .arg(&config_path) - .current_dir(&self.work) - .env("RUST_LOG", "info") - .stdin(Stdio::null()) - .stdout(log.try_clone()?) - .stderr(log) - .spawn() - .with_context(|| format!("starting {}", self.server.display()))?; - Ok(Server { - pid: child.id(), - child: Mutex::new(child), - base: format!("http://127.0.0.1:{port}"), - started: Instant::now(), - http: client(Duration::from_secs(600)), - }) + Server::spawn( + &self.server, + &self.work, + port, + &config, + &self.work.join("server.log"), + ) } fn next_rev(&self) -> u64 { @@ -532,172 +520,6 @@ fn sample(items: &[usize], n: usize) -> Vec { items.iter().step_by(step).take(n).copied().collect() } -fn free_port() -> Result { - let l = std::net::TcpListener::bind("127.0.0.1:0")?; - Ok(l.local_addr()?.port()) -} - -fn client(timeout: Duration) -> reqwest::blocking::Client { - reqwest::blocking::Client::builder() - .timeout(timeout) - .connect_timeout(Duration::from_secs(5)) - .build() - .unwrap() -} - -struct Server { - pid: u32, - child: Mutex, - base: String, - started: Instant, - http: reqwest::blocking::Client, -} - -impl Server { - fn get(&self, path: &str) -> Result { - Ok(self.http.get(format!("{}{path}", self.base)).send()?) - } - - fn crashed(&self) -> bool { - matches!(self.child.lock().unwrap().try_wait(), Ok(Some(_))) - } - - /// (until it answered anything, until it was ready), from the start. - fn wait_listening_and_ready(&self, limit: Duration) -> Result<(Duration, Duration)> { - let mut listening = None; - loop { - if self.crashed() { - bail!("the server exited while starting"); - } - if let Ok(r) = self.get("/api/ready") { - let now = self.started.elapsed(); - listening.get_or_insert(now); - if r.status().is_success() { - return Ok((listening.unwrap(), now)); - } - } - if self.started.elapsed() > limit { - bail!("the server was not ready in {limit:?}"); - } - std::thread::sleep(Duration::from_millis(50)); - } - } - - fn wait_ready(&self, limit: Duration) -> Result<()> { - self.wait_listening_and_ready(limit).map(|_| ()) - } - - /// Ready, and the build or the restart's check of the tree finished. - fn wait_settled(&self, limit: Duration) -> Result<()> { - self.wait_ready(limit)?; - while self.started.elapsed() < limit { - let indexing = self - .get("/api/status") - .ok() - .filter(|r| r.status().is_success()) - .and_then(|r| r.json::().ok()) - .map(|v| v["is_indexing"].as_bool().unwrap_or(true)); - if indexing == Some(false) { - return Ok(()); - } - std::thread::sleep(Duration::from_millis(250)); - } - bail!("the server was still indexing after {limit:?}") - } - - /// Seconds until no change is pending and every path in `paths` is - /// indexed as it is on disk, polled every 250 ms. - fn wait_fresh(&self, paths: &[PathBuf], limit: Duration) -> Option { - let t = Instant::now(); - let wanted: Vec = paths - .iter() - .map(|p| p.to_string_lossy().into_owned()) - .collect(); - let query = wanted.join(";"); - while t.elapsed() < limit { - let fresh = self - .http - .get(format!("{}/api/status", self.base)) - .query(&[("paths", query.as_str())]) - .send() - .ok() - .filter(|r| r.status().is_success()) - .and_then(|r| r.json::().ok()) - .is_some_and(|v| { - let index = &v["index"]; - let pending = index["pending_changes"].as_u64().unwrap_or(0); - let current = v["paths"].as_array().is_some_and(|ps| { - ps.len() == wanted.len() - && ps.iter().all(|p| { - let state = p["state"].as_str().unwrap_or(""); - // A file a stream removed again is fine. - state == "current" || state == "not_found" - }) - }); - !index.is_null() && pending == 0 && current - }); - if fresh { - return Some(t.elapsed()); - } - std::thread::sleep(Duration::from_millis(250)); - } - None - } - - fn check(&self) -> Result { - // One check at a time; the scrub's own does not use this lock, but - // be patient with a 429 anyway. - for _ in 0..30 { - let r = self.get("/api/check?all=true&examples=0")?; - if r.status().as_u16() == 429 { - std::thread::sleep(Duration::from_secs(1)); - continue; - } - if !r.status().is_success() { - bail!("check answered {}", r.status()); - } - return Ok(r.json()?); - } - bail!("a check was always running") - } - - /// SIGTERM (a graceful stop that saves the index), then wait. - fn stop(&self) -> Result<()> { - let mut child = self.child.lock().unwrap(); - #[cfg(unix)] - unsafe { - libc::kill(self.pid as i32, libc::SIGTERM); - } - #[cfg(not(unix))] - let _ = child.kill(); - let t = Instant::now(); - loop { - if let Some(status) = child.try_wait()? { - if !status.success() { - eprintln!("the server exited with {status}"); - } - return Ok(()); - } - if t.elapsed() > Duration::from_secs(300) { - let _ = child.kill(); - bail!("the server did not stop within 300 s of SIGTERM"); - } - std::thread::sleep(Duration::from_millis(100)); - } - } -} - -impl Drop for Server { - fn drop(&mut self) { - if let Ok(mut c) = self.child.lock() { - if matches!(c.try_wait(), Ok(None)) { - let _ = c.kill(); - let _ = c.wait(); - } - } - } -} - /// Threads searching back to back over HTTP, with `MIXED` queries, plus /// (with `sweeper`) one regex that reads every file, every 3 s. struct Load { diff --git a/examples/support/server.rs b/examples/support/server.rs new file mode 100644 index 00000000..c3c77404 --- /dev/null +++ b/examples/support/server.rs @@ -0,0 +1,228 @@ +//! The server binary under test, started and stopped by the load tools +//! (`scoreboard`, `chaos`), and the HTTP calls they make to it. + +#![allow(dead_code)] + +use anyhow::{bail, Context, Result}; +use fast_code_search::search::integrity::IntegrityReport; +use std::path::{Path, PathBuf}; +use std::process::{Child, Command, Stdio}; +use std::sync::Mutex; +use std::time::{Duration, Instant}; + +pub fn free_port() -> Result { + let l = std::net::TcpListener::bind("127.0.0.1:0")?; + Ok(l.local_addr()?.port()) +} + +pub fn client(timeout: Duration) -> reqwest::blocking::Client { + reqwest::blocking::Client::builder() + .timeout(timeout) + .connect_timeout(Duration::from_secs(5)) + .build() + .unwrap() +} + +/// A running server. +pub struct Server { + pub pid: u32, + child: Mutex, + /// `http://127.0.0.1:`. + pub base: String, + pub started: Instant, + http: reqwest::blocking::Client, +} + +impl Server { + /// Start `binary` with `config` (written to `work/config.toml`; it must + /// listen on `port`), in `work`, logging to `log`. + pub fn spawn( + binary: &Path, + work: &Path, + port: u16, + config: &str, + log: &Path, + ) -> Result { + let config_path = work.join("config.toml"); + std::fs::write(&config_path, config)?; + let log = std::fs::File::create(log)?; + let child = Command::new(binary) + .arg("--config") + .arg(&config_path) + .current_dir(work) + .env("RUST_LOG", "info") + .stdin(Stdio::null()) + .stdout(log.try_clone()?) + .stderr(log) + .spawn() + .with_context(|| format!("starting {}", binary.display()))?; + Ok(Server { + pid: child.id(), + child: Mutex::new(child), + base: format!("http://127.0.0.1:{port}"), + started: Instant::now(), + http: client(Duration::from_secs(600)), + }) + } + + /// `kill -9`, then wait for the process to go. + pub fn kill9(&self) -> Result<()> { + let mut child = self.child.lock().unwrap(); + child.kill()?; + child.wait()?; + Ok(()) + } + + /// SIGTERM without waiting (see [`Self::stop`]). + pub fn terminate(&self) { + #[cfg(unix)] + unsafe { + libc::kill(self.pid as i32, libc::SIGTERM); + } + #[cfg(not(unix))] + let _ = self.child.lock().unwrap().kill(); + } + + pub fn get(&self, path: &str) -> Result { + Ok(self.http.get(format!("{}{path}", self.base)).send()?) + } + + pub fn crashed(&self) -> bool { + matches!(self.child.lock().unwrap().try_wait(), Ok(Some(_))) + } + + /// (until it answered anything, until it was ready), from the start. + pub fn wait_listening_and_ready(&self, limit: Duration) -> Result<(Duration, Duration)> { + let mut listening = None; + loop { + if self.crashed() { + bail!("the server exited while starting"); + } + if let Ok(r) = self.get("/api/ready") { + let now = self.started.elapsed(); + listening.get_or_insert(now); + if r.status().is_success() { + return Ok((listening.unwrap(), now)); + } + } + if self.started.elapsed() > limit { + bail!("the server was not ready in {limit:?}"); + } + std::thread::sleep(Duration::from_millis(50)); + } + } + + pub fn wait_ready(&self, limit: Duration) -> Result<()> { + self.wait_listening_and_ready(limit).map(|_| ()) + } + + /// Ready, and the build or the restart's check of the tree finished. + pub fn wait_settled(&self, limit: Duration) -> Result<()> { + self.wait_ready(limit)?; + while self.started.elapsed() < limit { + let indexing = self + .get("/api/status") + .ok() + .filter(|r| r.status().is_success()) + .and_then(|r| r.json::().ok()) + .map(|v| v["is_indexing"].as_bool().unwrap_or(true)); + if indexing == Some(false) { + return Ok(()); + } + std::thread::sleep(Duration::from_millis(250)); + } + bail!("the server was still indexing after {limit:?}") + } + + /// Seconds until no change is pending and every path in `paths` is + /// indexed as it is on disk, polled every 250 ms. + pub fn wait_fresh(&self, paths: &[PathBuf], limit: Duration) -> Option { + let t = Instant::now(); + let wanted: Vec = paths + .iter() + .map(|p| p.to_string_lossy().into_owned()) + .collect(); + let query = wanted.join(";"); + while t.elapsed() < limit { + let fresh = self + .http + .get(format!("{}/api/status", self.base)) + .query(&[("paths", query.as_str())]) + .send() + .ok() + .filter(|r| r.status().is_success()) + .and_then(|r| r.json::().ok()) + .is_some_and(|v| { + let index = &v["index"]; + let pending = index["pending_changes"].as_u64().unwrap_or(0); + let current = v["paths"].as_array().is_some_and(|ps| { + ps.len() == wanted.len() + && ps.iter().all(|p| { + let state = p["state"].as_str().unwrap_or(""); + // A file a stream removed again is fine. + state == "current" || state == "not_found" + }) + }); + !index.is_null() && pending == 0 && current + }); + if fresh { + return Some(t.elapsed()); + } + std::thread::sleep(Duration::from_millis(250)); + } + None + } + + pub fn check(&self) -> Result { + // One check at a time; the scrub's own does not use this lock, but + // be patient with a 429 anyway. + for _ in 0..30 { + let r = self.get("/api/check?all=true&examples=0")?; + if r.status().as_u16() == 429 { + std::thread::sleep(Duration::from_secs(1)); + continue; + } + if !r.status().is_success() { + bail!("check answered {}", r.status()); + } + return Ok(r.json()?); + } + bail!("a check was always running") + } + + /// SIGTERM (a graceful stop that saves the index), then wait. + pub fn stop(&self) -> Result<()> { + let mut child = self.child.lock().unwrap(); + #[cfg(unix)] + unsafe { + libc::kill(self.pid as i32, libc::SIGTERM); + } + #[cfg(not(unix))] + let _ = child.kill(); + let t = Instant::now(); + loop { + if let Some(status) = child.try_wait()? { + if !status.success() { + eprintln!("the server exited with {status}"); + } + return Ok(()); + } + if t.elapsed() > Duration::from_secs(300) { + let _ = child.kill(); + bail!("the server did not stop within 300 s of SIGTERM"); + } + std::thread::sleep(Duration::from_millis(100)); + } + } +} + +impl Drop for Server { + fn drop(&mut self) { + if let Ok(mut c) = self.child.lock() { + if matches!(c.try_wait(), Ok(None)) { + let _ = c.kill(); + let _ = c.wait(); + } + } + } +} diff --git a/src/faults.rs b/src/faults.rs index 51c78555..595b2f48 100644 --- a/src/faults.rs +++ b/src/faults.rs @@ -12,10 +12,20 @@ //! `cargo test --features failpoints --test fault_injection`. //! //! Points: -//! - `parse.read`: reading a file to index it (initial build and watcher). +//! - `parse.read`: reading a file to index it (initial build and watcher), +//! after its size and mtime were read: `NotFound` here is a file that +//! vanished in between, [`Action::Delay`] a slow disk. +//! - `parse.panic`: the same place, panicking (a bug in reading or +//! transcoding one file). +//! - `parse.symbols`: inside symbol extraction (a tree-sitter panic). //! - `watch.apply`: installing a parsed watcher burst (panics). //! - `watch.lose`: the watch loop drops a change event, as a backend that //! loses events would (the background scrub must find and fix it). +//! - `watch.overflow`: the watcher drops an event and asks for a rescan, +//! as when the OS queue overflows. +//! - `save.write`: writing the index's temp file (disk full is +//! `StorageFull`). +//! - `save.rename`: each attempt to move the temp file over the index. use std::path::Path; @@ -24,6 +34,11 @@ use std::path::Path; pub enum Action { /// Return an I/O error of this kind. IoError(std::io::ErrorKind), + /// Return the OS error with this code (`EMFILE` is 24 on Linux and + /// macOS), for errors that have no [`std::io::ErrorKind`] of their own. + OsError(i32), + /// Wait this long, then go on as normal (a slow disk). + Delay(std::time::Duration), /// Panic. Panic, } @@ -90,7 +105,8 @@ pub fn clear(name: &str, path_contains: Option<&str>) { } /// An I/O fault point: `Err` when `name` is armed for `path` with an -/// [`Action::IoError`]; panics when armed with [`Action::Panic`]. +/// [`Action::IoError`] or [`Action::OsError`]; waits for an +/// [`Action::Delay`]; panics when armed with [`Action::Panic`]. #[inline] pub fn io(name: &str, path: &Path) -> std::io::Result<()> { #[cfg(feature = "failpoints")] @@ -98,6 +114,8 @@ pub fn io(name: &str, path: &Path) -> std::io::Result<()> { Some(Action::IoError(kind)) => { return Err(std::io::Error::new(kind, format!("injected fault {name}"))) } + Some(Action::OsError(code)) => return Err(std::io::Error::from_raw_os_error(code)), + Some(Action::Delay(d)) => std::thread::sleep(d), Some(Action::Panic) => panic!("injected fault {name} at {}", path.display()), None => {} } diff --git a/src/index/persistence.rs b/src/index/persistence.rs index c53068e2..029a4406 100644 --- a/src/index/persistence.rs +++ b/src/index/persistence.rs @@ -41,6 +41,56 @@ static SAVE_LOCK: std::sync::Mutex<()> = std::sync::Mutex::new(()); /// Makes every temp file name unique within the process. static TMP_COUNTER: std::sync::atomic::AtomicU64 = std::sync::atomic::AtomicU64::new(0); +/// Where a save of `path` writes before it renames: this prefix, then the +/// process id and a counter (`index.bin.tmp..`). +fn temp_prefix(path: &Path) -> std::path::PathBuf { + let mut name = path.with_extension("bin.tmp").into_os_string(); + name.push("."); + name.into() +} + +/// Move a finished temp file over the index. +fn replace(tmp_path: &Path, path: &Path) -> std::io::Result<()> { + crate::faults::io("save.rename", path)?; + std::fs::rename(tmp_path, path) +} + +/// Remove the temp files earlier saves of `path` left behind, and return +/// how many there were and their size in bytes. +/// +/// A save that is killed (`kill -9`, a power cut) leaves its temp file, as +/// large as the index, and nothing used to remove it: each kill during a +/// save cost that much disk for good. Call it only while holding the index +/// lock (`crate::index_lock`) and before this process saves, so no other +/// save can be writing one of these files. +pub fn remove_stale_temp_files(path: &Path) -> (usize, u64) { + let prefix = temp_prefix(path); + let (Some(dir), Some(prefix)) = (prefix.parent(), prefix.file_name()) else { + return (0, 0); + }; + let dir = if dir.as_os_str().is_empty() { + Path::new(".") + } else { + dir + }; + let prefix = prefix.to_string_lossy(); + let Ok(entries) = std::fs::read_dir(dir) else { + return (0, 0); + }; + let (mut count, mut bytes) = (0, 0); + for entry in entries.flatten() { + if !entry.file_name().to_string_lossy().starts_with(&*prefix) { + continue; + } + let size = entry.metadata().map(|m| m.len()).unwrap_or(0); + if std::fs::remove_file(entry.path()).is_ok() { + count += 1; + bytes += size; + } + } + (count, bytes) +} + /// The posting lists of a *loaded* index: the directory plus the mapped /// bitmap region they point into. Bitmaps are deserialized straight from /// the mapping by [`PersistedIndex::restore_trigram_index`]; nothing is @@ -285,11 +335,13 @@ impl PersistedIndex { // Unique per process and per call so a concurrent writer (another // process sharing `index_path`) can never truncate our in-flight file. - let tmp_path = path.with_extension(format!( - "bin.tmp.{}.{}", + let mut tmp_path = temp_prefix(path).into_os_string(); + tmp_path.push(format!( + "{}.{}", std::process::id(), TMP_COUNTER.fetch_add(1, std::sync::atomic::Ordering::Relaxed) )); + let tmp_path = std::path::PathBuf::from(tmp_path); let result = self.write_then_rename(path, &tmp_path, trigrams); if result.is_err() { @@ -367,6 +419,7 @@ impl PersistedIndex { // Flush the BufWriter explicitly so I/O errors (e.g. disk full) surface // here instead of being silently swallowed when the writer is dropped. + crate::faults::io("save.write", path).with_context(|| err("body"))?; writer.flush().with_context(|| err("body"))?; drop(writer); @@ -385,11 +438,12 @@ impl PersistedIndex { // Exclusive lock released as `file` drops at end of scope. } - // Atomic replace. On Windows, rename onto an existing file can fail, so - // fall back to remove-then-rename — but only while our temp file still - // exists; if the source is gone there is nothing to put in place of - // the target and removing it would destroy the last good index. - if let Err(e) = std::fs::rename(tmp_path, path) { + // Atomic replace. On Windows, rename onto an existing file can fail + // (the file is open elsewhere), so the old index is moved aside and + // the rename tried again; if that fails too the old index is put + // back. It used to be deleted first, so a second failure left no + // index at all. + if let Err(e) = replace(tmp_path, path) { if !tmp_path.exists() { return Err(anyhow::Error::new(e).context(format!( "Failed to atomically replace index file: {} (temp file {} vanished)", @@ -397,14 +451,31 @@ impl PersistedIndex { tmp_path.display() ))); } - tracing::debug!(error = %e, "Direct rename failed; retrying after removing target"); - let _ = std::fs::remove_file(path); - std::fs::rename(tmp_path, path).with_context(|| { - format!( + tracing::debug!(error = %e, "Direct rename failed; retrying with the old index moved aside"); + let aside = tmp_path.with_extension("old"); + if std::fs::rename(path, &aside).is_err() { + return Err(anyhow::Error::new(e).context(format!( "Failed to atomically replace index file: {}", path.display() - ) - })?; + ))); + } + if let Err(e) = replace(tmp_path, path) { + let _ = std::fs::rename(&aside, path); + return Err(anyhow::Error::new(e).context(format!( + "Failed to atomically replace index file: {}", + path.display() + ))); + } + let _ = std::fs::remove_file(&aside); + } + // Make the rename itself durable: without this a power cut soon + // after the save could bring back the previous index (never a torn + // one). Best effort; Windows cannot open a folder this way. + #[cfg(unix)] + if let Some(dir) = path.parent().filter(|d| !d.as_os_str().is_empty()) { + if let Ok(d) = std::fs::File::open(dir) { + let _ = d.sync_all(); + } } Ok(()) @@ -1062,6 +1133,29 @@ mod tests { assert!(PersistedIndex::load(&index_path).is_ok()); } + /// A save killed half way leaves its temp file; the next start removes + /// it (and only it: other files next to the index stay). + #[test] + fn test_stale_temp_files_are_removed() { + let temp_dir = TempDir::new().expect("temp dir"); + let index_path = temp_dir.path().join("index.bin"); + save_sample(&index_path); + let dead = temp_dir.path().join("index.bin.tmp.4242.0"); + let aside = temp_dir.path().join("index.bin.tmp.4242.old"); + std::fs::write(&dead, vec![0u8; 1000]).unwrap(); + std::fs::write(&aside, vec![0u8; 24]).unwrap(); + let other = temp_dir.path().join("index.bin.lock"); + std::fs::write(&other, b"").unwrap(); + let other_index = temp_dir.path().join("other.bin.tmp.1.0"); + std::fs::write(&other_index, b"x").unwrap(); + + assert_eq!(remove_stale_temp_files(&index_path), (2, 1024)); + assert!(!dead.exists() && !aside.exists()); + assert!(other.exists() && other_index.exists() && index_path.exists()); + assert!(PersistedIndex::load(&index_path).is_ok()); + assert_eq!(remove_stale_temp_files(&index_path), (0, 0)); + } + fn leftover_temp_files(dir: &Path) -> Vec { std::fs::read_dir(dir) .unwrap() diff --git a/src/main.rs b/src/main.rs index 2257884b..0b6df3da 100644 --- a/src/main.rs +++ b/src/main.rs @@ -590,6 +590,18 @@ fn lock_index( match IndexLock::acquire(std::path::Path::new(&index_path), &owner) { Ok(lock) => { tracing::debug!(lock = %lock.path().display(), "Index lock acquired"); + // Only a server holding the lock saves, so any temp file is a + // save that was killed half way. + let (files, bytes) = fast_code_search::index::persistence::remove_stale_temp_files( + std::path::Path::new(&index_path), + ); + if files > 0 { + tracing::info!( + files, + bytes, + "Removed temp files left by an index save that did not finish" + ); + } Some(lock) } Err(e @ LockError::HeldByAnother { .. }) => { diff --git a/src/search/background_indexer.rs b/src/search/background_indexer.rs index 5dcc7ef3..e8e5506b 100644 --- a/src/search/background_indexer.rs +++ b/src/search/background_indexer.rs @@ -939,10 +939,13 @@ fn process_batch( None } Err(_) => { + // Tried again and reported like a file that could not + // be read; it used to be left out without a word. tracing::error!( path = %path.display(), - "Phase1 panicked during read/trigram extraction; skipping file" + "Phase1 panicked during read/trigram extraction; will retry" ); + read_failures.failed(path, Instant::now()); None } } @@ -973,8 +976,9 @@ fn process_batch( Err(_) => { tracing::error!( path = %path_for_log.display(), - "Phase2 panicked during symbol extraction" + "Phase2 panicked during symbol extraction; will retry" ); + read_failures.failed(&path_for_log, Instant::now()); None } } @@ -1131,21 +1135,18 @@ fn log_completion_stats( /// Called by the file-watcher loop after each applied batch with the number /// of file updates (indexed + removed) since the last save. Saves once that -/// reaches `save_after_updates` and returns whether it did, so the caller -/// can reset its counter. +/// reaches `save_after_updates` and returns whether it saved, so the caller +/// can reset its counter. A save that failed (disk full) returns false, so +/// the updates still count and the next batch, or the shutdown, tries +/// again; they used to be forgotten, and the shutdown skipped its save. pub fn save_on_watcher_update( indexer_config: &IndexerConfig, engine: &Arc>, updates_since_save: usize, ) -> bool { - if indexer_config.save_after_updates > 0 + indexer_config.save_after_updates > 0 && updates_since_save >= indexer_config.save_after_updates - { - save_index_if_needed(indexer_config, engine, true, updates_since_save, 0); - true - } else { - false - } + && save_index_if_needed(indexer_config, engine, true, updates_since_save, 0) } /// Save the index on shutdown if any watcher updates were applied since the @@ -1166,23 +1167,24 @@ pub fn save_after_watcher_shutdown( save_index_if_needed(indexer_config, engine, true, updates_since_save, 0); } -/// Save the index to disk if configured and appropriate. +/// Save the index to disk if configured and appropriate. False when a +/// save was due and failed. fn save_index_if_needed( indexer_config: &IndexerConfig, index_engine: &Arc>, loaded_from_persistence: bool, total_indexed: usize, removed_files_count: usize, -) { +) -> bool { let Some(ref index_path_str) = indexer_config.index_path else { - return; + return true; }; if indexer_config.index_read_only { info!( path = %index_path_str, "Not saving the index: another server holds its lock (see the error at startup)" ); - return; + return true; } // Only save if the index actually changed since it was loaded. @@ -1199,7 +1201,7 @@ fn save_index_if_needed( if !should_save { info!("Index unchanged, skipping save"); - return; + return true; } let index_path = Path::new(index_path_str); @@ -1220,16 +1222,19 @@ fn save_index_if_needed( path = %index_path.display(), "Failed to save index. {hint}" ); + false } else { info!( path = %index_path.display(), files = engine.get_stats().num_files, "Index saved successfully" ); + true } } Err(e) => { tracing::error!(error = %e, "Failed to acquire read lock to save index"); + false } } } diff --git a/src/search/engine/mod.rs b/src/search/engine/mod.rs index 32e7be86..881f089a 100644 --- a/src/search/engine/mod.rs +++ b/src/search/engine/mod.rs @@ -858,6 +858,7 @@ impl PartialIndexedFile { let racy = modified.is_none_or(is_racy); crate::faults::io("parse.read", path)?; + crate::faults::panic_point("parse.panic", path); let raw_bytes = std::fs::read(path)?; // Attempt zero-copy consume: String::from_utf8 reuses the Vec allocation when valid. let (content, transcoded) = match String::from_utf8(raw_bytes) { @@ -1040,6 +1041,7 @@ impl PreIndexedFile { // panic protection: tree-sitter can stack overflow on deeply // nested or malformed files. std::panic::catch_unwind(std::panic::AssertUnwindSafe(|| { + crate::faults::panic_point("parse.symbols", &partial.path); extractor .extract_all_with_refs(&partial.content) .unwrap_or_default() diff --git a/src/search/watcher.rs b/src/search/watcher.rs index 9744a29d..a4e1157b 100644 --- a/src/search/watcher.rs +++ b/src/search/watcher.rs @@ -151,6 +151,17 @@ impl FileWatcher { let mut watcher = notify::recommended_watcher(move |result: notify::Result| { match result { Ok(event) => { + if cfg!(feature = "failpoints") + && event + .paths + .iter() + .any(|p| crate::faults::fires("watch.overflow", p)) + { + // As if the OS queue overflowed: this event is lost. + warn!("File watcher lost events; the watched paths will be rescanned"); + handler_rescan.store(true, Ordering::Release); + return; + } if event.need_rescan() { warn!("File watcher lost events; the watched paths will be rescanned"); handler_rescan.store(true, Ordering::Release); diff --git a/tests/fault_injection.rs b/tests/fault_injection.rs index ef07c7d6..09362d20 100644 --- a/tests/fault_injection.rs +++ b/tests/fault_injection.rs @@ -12,6 +12,7 @@ use fast_code_search::config::IndexerConfig; use fast_code_search::faults::{self, Action, Fault}; +use fast_code_search::index::PersistedIndex; use fast_code_search::search::{ create_progress_broadcaster, run_background_indexer, watch_loop, BackgroundIndexerConfig, IndexingProgress, ReadFailures, SearchEngine, WatchLoopConfig, @@ -31,6 +32,8 @@ const FIRST_RETRY: Duration = Duration::from_millis(50); struct Rig { _temp: TempDir, + /// Outside the watched tree. + index_dir: TempDir, root: PathBuf, config: IndexerConfig, engine: Arc>, @@ -57,6 +60,7 @@ impl Rig { ..Default::default() }, _temp: temp, + index_dir: TempDir::new().unwrap(), root, engine, shutdown: Arc::new(AtomicBool::new(false)), @@ -64,6 +68,38 @@ impl Rig { } } + /// Save the index to (and after watcher updates, every + /// `save_after_updates`) a file of this rig's own. + fn saving(mut self, save_after_updates: usize) -> Self { + self.config.index_path = Some(self.index_path().to_string_lossy().to_string()); + self.config.save_after_updates = save_after_updates; + self + } + + fn index_path(&self) -> PathBuf { + self.index_dir.path().join("index.bin") + } + + /// Files next to the index other than the index itself. + fn index_leftovers(&self) -> Vec { + let mut names: Vec = std::fs::read_dir(self.index_dir.path()) + .unwrap() + .filter_map(|e| e.ok()) + .map(|e| e.file_name().to_string_lossy().to_string()) + .filter(|n| n != "index.bin") + .collect(); + names.sort(); + names + } + + /// Stop the watcher (it saves on the way out) and wait for it. + fn stop_watching(&mut self) { + self.shutdown.store(true, Ordering::Release); + if let Some(h) = self.watch.take() { + h.join().unwrap(); + } + } + /// Text that names one file of this rig only, for arming a fault. fn key(&self, name: &str) -> String { self.root.join(name).to_string_lossy().to_string() @@ -84,6 +120,22 @@ impl Rig { faults::clear(point, Some(&self.key(name))); } + /// Arm `point` for this rig's index file. + fn arm_save(&self, point: &str, action: Action, times: Option) { + faults::set( + point, + Fault { + action, + path_contains: Some(self.index_path().to_string_lossy().to_string()), + times, + }, + ); + } + + fn disarm_save(&self, point: &str) { + faults::clear(point, Some(&self.index_path().to_string_lossy())); + } + fn build(&self) { run_background_indexer(BackgroundIndexerConfig { indexer_config: self.config.clone(), @@ -407,3 +459,249 @@ fn scrub_finds_and_fixes_a_lost_change() { rig.shutdown.store(true, Ordering::Release); scrub.join().unwrap(); } + +/// A file that vanishes between being listed and being read is simply +/// not indexed: it is not reported as unreadable. +#[test] +fn file_that_vanishes_before_it_is_read_is_not_reported() { + let rig = Rig::new(&[("a.py", "x = 'buildword'\n"), ("b.py", "y = 1\n")], false); + rig.arm( + "parse.read", + "a.py", + Action::IoError(std::io::ErrorKind::NotFound), + None, + ); + rig.build(); + rig.disarm("parse.read", "a.py"); + assert_eq!(rig.indexed(), ["b.py"]); + assert_eq!(rig.unreadable(), 0); + assert!(!rig.note().contains("could not be read"), "{}", rig.note()); +} + +/// Out of file handles (`EMFILE`, which has no `ErrorKind` of its own): +/// the build and the watcher both try again. +#[test] +fn out_of_file_handles_is_retried() { + // EMFILE on Linux and macOS (on Windows 24 is some other error, which + // is retried the same way). + const EMFILE: i32 = 24; + let mut rig = Rig::new(&[("a.py", "x = 'buildword'\n"), ("b.py", "y = 1\n")], true); + rig.arm("parse.read", "a.py", Action::OsError(EMFILE), Some(1)); + rig.build(); + assert_eq!(rig.found_in("buildword"), ["a.py"]); + rig.start_watching(); + rig.arm("parse.read", "b.py", Action::OsError(EMFILE), Some(2)); + rig.write("b.py", "y = 'newword'\n"); + rig.wait_for("the change to be applied", |r| { + r.found_in("newword") == ["b.py"] + }); + rig.wait_for("nothing pending", |r| r.pending() == 0); + assert_eq!(rig.unreadable(), 0); +} + +/// A panic while reading one file during the build is tried again; it +/// used to leave the file out of the index without a word. +#[test] +fn build_retries_a_file_whose_read_panicked() { + let rig = Rig::new(&[("a.py", "x = 'buildword'\n"), ("b.py", "y = 1\n")], false); + rig.arm("parse.panic", "a.py", Action::Panic, Some(1)); + rig.build(); + assert_eq!(rig.found_in("buildword"), ["a.py"]); + assert_eq!(rig.unreadable(), 0); +} + +/// A file whose read panics every time is reported, like one that cannot +/// be read. +#[test] +fn build_reports_a_file_whose_read_always_panics() { + let rig = Rig::new(&[("a.py", "x = 'buildword'\n"), ("b.py", "y = 1\n")], false); + rig.arm("parse.panic", "a.py", Action::Panic, None); + rig.build(); + rig.disarm("parse.panic", "a.py"); + assert_eq!(rig.indexed(), ["b.py"]); + assert_eq!(rig.unreadable(), 1); + assert!( + rig.note().contains("1 file could not be read"), + "{}", + rig.note() + ); +} + +/// A change whose read panics once is applied on the next try. +#[test] +fn watcher_retries_a_change_whose_read_panicked() { + let mut rig = Rig::new(&[("a.py", "x = 'oldword'\n"), ("b.py", "y = 1\n")], true); + rig.build(); + rig.start_watching(); + rig.arm("parse.panic", "a.py", Action::Panic, Some(1)); + rig.write("a.py", "x = 'newword'\n"); + rig.write("b.py", "y = 'newword'\n"); + rig.wait_for("both changes to be applied", |r| { + r.found_in("newword") == ["a.py", "b.py"] + }); + rig.wait_for("nothing pending", |r| r.pending() == 0); + assert_eq!(rig.unreadable(), 0); +} + +/// Symbol extraction that panics (tree-sitter on a pathological file) +/// leaves the file searchable as text. +#[test] +fn file_whose_parser_panics_stays_searchable() { + let rig = Rig::new( + &[ + ("a.py", "def parsed_fn():\n return 'buildword'\n"), + ("b.py", "y = 1\n"), + ], + false, + ); + rig.arm("parse.symbols", "a.py", Action::Panic, None); + rig.build(); + rig.disarm("parse.symbols", "a.py"); + assert_eq!(rig.found_in("buildword"), ["a.py"]); + assert_eq!(rig.unreadable(), 0); +} + +/// Events the OS lost (its queue overflowed) are made up by a rescan of +/// the watched paths: an edit and a removal it never reported are both in +/// the index afterwards. +#[test] +fn lost_events_are_made_up_by_a_rescan() { + let mut rig = Rig::new( + &[ + ("a.py", "x = 'oldword'\n"), + ("b.py", "y = 1\n"), + ("c.py", "z = 'goneword'\n"), + ], + true, + ); + rig.build(); + rig.start_watching(); + rig.arm("watch.overflow", "a.py", Action::Panic, None); + rig.arm("watch.overflow", "c.py", Action::Panic, None); + // Not the same second as the build, so the change shows in the mtime. + std::thread::sleep(Duration::from_millis(1100)); + rig.write("a.py", "x = 'newword'\n"); + std::fs::remove_file(rig.root.join("c.py")).unwrap(); + rig.wait_for("the rescan to apply both changes", |r| { + r.found_in("newword") == ["a.py"] && r.indexed() == ["a.py", "b.py"] + }); + rig.disarm("watch.overflow", "a.py"); + rig.disarm("watch.overflow", "c.py"); + assert!(rig.found_in("oldword").is_empty()); + rig.wait_for("nothing pending", |r| r.pending() == 0); +} + +/// A slow disk slows the watcher, not searches: the watcher reads files +/// without holding the index lock, and the change counts as pending while +/// it waits. +#[test] +fn slow_disk_does_not_hold_up_searches() { + let mut rig = Rig::new(&[("a.py", "x = 'oldword'\n"), ("b.py", "y = 1\n")], true); + rig.build(); + rig.start_watching(); + rig.arm( + "parse.read", + "a.py", + Action::Delay(Duration::from_secs(2)), + Some(1), + ); + rig.write("a.py", "x = 'newword'\n"); + rig.wait_for("the change to count as pending", |r| r.pending() > 0); + let started = Instant::now(); + let mut slowest = Duration::ZERO; + while started.elapsed() < Duration::from_millis(1000) { + let t = Instant::now(); + let _ = rig.found_in("oldword"); + slowest = slowest.max(t.elapsed()); + } + assert!( + slowest < Duration::from_millis(500), + "a search waited {slowest:?} for a slow read" + ); + rig.wait_for("the change to be applied", |r| { + r.found_in("newword") == ["a.py"] + }); + rig.wait_for("nothing pending", |r| r.pending() == 0); +} + +/// Saving onto a full disk, or failing to move the new index into place, +/// leaves the previous index as it was and no temp file behind. +#[test] +fn failed_save_keeps_the_previous_index() { + let rig = Rig::new(&[("a.py", "x = 'buildword'\n")], false).saving(0); + rig.build(); + let saved = std::fs::read(rig.index_path()).expect("the build saved the index"); + let engine = rig.engine.read().unwrap(); + for (point, action) in [ + ( + "save.write", + Action::IoError(std::io::ErrorKind::StorageFull), + ), + ( + "save.rename", + Action::IoError(std::io::ErrorKind::PermissionDenied), + ), + ] { + rig.arm_save(point, action, None); + let result = engine.save_index(&rig.index_path(), &rig.config); + rig.disarm_save(point); + assert!(result.is_err(), "{point}: the save should fail"); + assert!( + std::fs::read(rig.index_path()).unwrap() == saved, + "{point}: the previous index changed" + ); + assert_eq!(rig.index_leftovers(), Vec::::new(), "{point}"); + } + // A rename that fails once is tried again with the old index moved + // aside, which is put back if that fails too (above). + rig.arm_save( + "save.rename", + Action::IoError(std::io::ErrorKind::PermissionDenied), + Some(1), + ); + engine + .save_index(&rig.index_path(), &rig.config) + .expect("the second rename works"); + rig.disarm_save("save.rename"); + assert_eq!(rig.index_leftovers(), Vec::::new()); + assert!(PersistedIndex::load(&rig.index_path()).is_ok()); +} + +/// Updates whose save failed still count: the next save (here, at +/// shutdown) writes them. They used to be forgotten, so the shutdown +/// skipped its save and the saved index lacked them. +#[test] +fn updates_whose_save_failed_are_saved_at_shutdown() { + let mut rig = Rig::new(&[("a.py", "x = 'oldword'\n"), ("b.py", "y = 1\n")], true).saving(1); + rig.build(); + rig.start_watching(); + rig.arm_save( + "save.write", + Action::IoError(std::io::ErrorKind::StorageFull), + None, + ); + std::thread::sleep(Duration::from_millis(1100)); + // A new size, so the saved index shows which version it holds. + let new_text = "x = 'a longer newword'\n"; + rig.write("a.py", new_text); + rig.wait_for("the change to be applied", |r| { + r.found_in("newword") == ["a.py"] + }); + // The save after the update has failed by the time nothing is pending. + rig.wait_for("nothing pending", |r| r.pending() == 0); + std::thread::sleep(Duration::from_millis(300)); + rig.disarm_save("save.write"); + rig.stop_watching(); + + let saved = PersistedIndex::load(&rig.index_path()).unwrap(); + let a = saved + .files + .iter() + .find(|f| f.path.ends_with("a.py")) + .expect("a.py in the saved index"); + assert_eq!( + a.size, + new_text.len() as u64, + "the saved index is out of date" + ); +}