diff --git a/PARITY.md b/PARITY.md index ee33ba3a1..8cfabb262 100644 --- a/PARITY.md +++ b/PARITY.md @@ -43,6 +43,19 @@ on any SDK: the root-joining Rust `DirSQL::from_config(root)` / TypeScript never had a root-joiner — only the explicit `config=` — so nothing was removed there. This **restores parity** with the CLI's no-`-c` behavior (#602). +**Progress on construction — at parity across all three SDKs (#957), no drift.** +Building an index reports the walk and the ingest pass on stderr while they +run, then erases the live line and leaves one summary of what each cost. The +reporter lives in the shared core (`progress`, driven from +`DirSQL::prepare_resolved` and `finish_build`), so all three SDKs got it in the +same commit and no SDK carries its own copy. It is terminal-only and +slow-work-only by default (nothing on a pipe, nothing under half a second); +`DIRSQL_PROGRESS=always` / `=never` overrides it, and the variable is read by +the core rather than by any launcher, so it behaves identically from the CLI, +Python, Rust and TypeScript. No SDK exposes a knob for it: an SDK-level +`progress=` argument would be exactly the kind of per-SDK surface this table +exists to prevent. + | API | Python | Rust | TypeScript | |----------------------------|------------------------------------------------|------------------------------------------------------|---------------------------------------------------------| | Constructor | `DirSQL(root=None, *, tables=None, ignore=None, no_ignore=False, config=None, persist=False, persist_path=None, extensions=None)` | `DirSQL::builder().root(..).tables(..).ignore(..).config(..).persist(Option).extensions(..).build()` (also `DirSQL::new`/`with_ignore` shortcuts) | `new DirSQL(configPath)` or `new DirSQL({ root?, tables?, ignore?, config?, persist?, persistPath?, extensions?, noIgnore? })` + `await db.ready` | diff --git a/docs/reference/cli.md b/docs/reference/cli.md index d6676bbbe..f8f521242 100644 --- a/docs/reference/cli.md +++ b/docs/reference/cli.md @@ -460,3 +460,47 @@ Turn discovery off with either: A plugin that declares itself but is missing its module or its `dirsql.toml` fragment is a launcher error naming the package — never a silent skip. + +## Progress reporting + +Building the index over a large tree is not instant: the walk visits every +file, then each matched file costs one `on-file` round trip plus whatever the +table's `ddl` fires on insert. On a big corpus that is minutes. dirsql reports +the two phases on **stderr** while they run: + +``` +dirsql: scanning 128413 files +dirsql: indexing 9204/41231 files (22%) +``` + +Each line is rewritten in place. When a phase ends its line is erased and +replaced by one summary of what it cost: + +``` +dirsql: scanned 128413 files in 4.2s +dirsql: indexed 41231 files in 3m12s +``` + +stdout is untouched — it carries the query result and nothing else. + +By default this is **terminal-only, and only for work slow enough to wonder +about**: a phase that finishes in under half a second prints nothing at all, +and a run whose stderr is a pipe or a file prints nothing regardless of how +long it takes. `dirsql "…" 2>run.log` and `dirsql "…" | jq` are byte-for-byte +what they were before. + +Override with `DIRSQL_PROGRESS`: + +| Value | Effect | +|---|---| +| unset, or `auto` | Report only on a terminal, and only once a phase has run for half a second. The default. | +| `always`, `1`, `true` | Report from the first update, terminal or not. Use it to watch a scan whose stderr is redirected. | +| `never`, `0`, `false` | Report nothing, ever. | + +Values are case-insensitive and surrounding whitespace is ignored; anything +unrecognized reads as `auto`, so a typo cannot stop a scan from running. + +The setting is read by the **core**, not the CLI, so it governs an index built +from any SDK as well — a Python or TypeScript program that builds a `DirSQL` +with a terminal attached gets the same two phases on stderr, and the same +silence when piped. diff --git a/docs/reference/sdk.md b/docs/reference/sdk.md index 21cf19821..05799bdff 100644 --- a/docs/reference/sdk.md +++ b/docs/reference/sdk.md @@ -396,3 +396,22 @@ not fit that range is a hard error, not a lossy conversion: Python raises A TypeScript `bigint` **within** `i64` range maps to `INTEGER`. Only a real `bytes`/`bytearray` (Python) or `Buffer`/`Uint8Array` (TypeScript) maps to `BLOB` — a list/array of integers does not. + +## Progress on construction + +Constructing a `DirSQL` walks the tree and ingests every matched file, which +on a large corpus is the slowest thing your program does. The core reports +both phases on **stderr** while they run, then erases the live line and leaves +one summary of what each cost: + +``` +dirsql: indexed 41231 files in 3m12s +``` + +This is terminal-only by default, and only for a phase that runs longer than +half a second — a program whose stderr is a pipe, a file, or a log collector +sees nothing, whatever the scan costs. Set `DIRSQL_PROGRESS=never` to +guarantee silence even on a terminal, or `DIRSQL_PROGRESS=always` to report +regardless. The full table is in the +[CLI reference](cli.md#progress-reporting); the setting lives in the shared +core, so it behaves identically from all three SDKs. diff --git a/packages/python/e2e-attestations/claude-tackle-957-lrm0z6.json b/packages/python/e2e-attestations/claude-tackle-957-lrm0z6.json new file mode 100644 index 000000000..fda925f0f --- /dev/null +++ b/packages/python/e2e-attestations/claude-tackle-957-lrm0z6.json @@ -0,0 +1,7 @@ +{ + "command": "uv run python -m pytest tests/e2e/ -x -q", + "ran_at": 1787261032, + "exit_code": 0, + "commit": "eed954811817292c5c3dad0577eb90ab551e2e73", + "branch": "claude/tackle-957-lrm0z6" +} diff --git a/packages/rust/changelog.d/2026-08-20-scan-progress-reporting.md b/packages/rust/changelog.d/2026-08-20-scan-progress-reporting.md new file mode 100644 index 000000000..56c645023 --- /dev/null +++ b/packages/rust/changelog.d/2026-08-20-scan-progress-reporting.md @@ -0,0 +1,3 @@ +**Added** + +- **The startup scan reports its progress on stderr.** A cold scan over a large corpus was silent: the walk visits every file, then each matched file costs an `on-file` round trip plus whatever the table's `ddl` fires on insert, and on a big tree that is minutes with nothing on the terminal — no way to tell a slow scan from a wedged one. Both phases now draw a counter that is rewritten in place (`dirsql: indexing 9204/41231 files (22%)`), erased when the phase ends and replaced by one summary of what it cost (`dirsql: indexed 41231 files in 3m12s`). It is **terminal-only and slow-work-only** by default: a phase finishing in under half a second prints nothing, and a run whose stderr is a pipe or a file prints nothing at any duration, so `| jq` pipelines, `2>` redirects and CI logs are byte-for-byte unchanged. `DIRSQL_PROGRESS=always` reports regardless of terminal and from the first update; `DIRSQL_PROGRESS=never` guarantees silence. The reporter lives in the core (`progress`), so it governs an index built from any SDK, not just the CLI, and it adds no dependency — the line is a `\r`-rewritten counter rather than a drawn bar, which needs the terminal width and therefore a crate. (#957) diff --git a/packages/rust/migrations.d/2026-08-20-scan-progress-reporting.md b/packages/rust/migrations.d/2026-08-20-scan-progress-reporting.md new file mode 100644 index 000000000..a4165986e --- /dev/null +++ b/packages/rust/migrations.d/2026-08-20-scan-progress-reporting.md @@ -0,0 +1,62 @@ +### The startup scan reports progress on stderr (#957) + +#### Summary + +Building an index — from the CLI or from any SDK — now writes a progress +counter to stderr while the directory walk and the ingest pass run, and one +summary line when each finishes. Nothing about the API changes; what changes is +that a process that used to write nothing to stderr on a successful build may +now write to it. The behavior is gated on stderr being a terminal *and* the +phase running longer than half a second, so a piped, redirected or fast run is +unaffected. + +#### Required changes + +_None._ No signature changed and no configuration is required. The +`DIRSQL_PROGRESS` environment variable is the opt-out for a program that +insists on an empty stderr. + +#### Deprecations removed + +_None._ + +#### Behavior changes without code changes + +- **stderr may carry progress lines on a terminal.** A build whose walk or + ingest phase runs longer than 500 ms and whose stderr is a terminal draws + `dirsql: scanning files` / `dirsql: indexing / files (

%)`, + rewritten in place, then erases the line and prints + `dirsql: scanned files in ` / `dirsql: indexed files in `. + Set `DIRSQL_PROGRESS=never` to restore an unconditionally empty stderr. +- **Non-terminal stderr is unchanged.** A pipe, a file, a log collector or a + CI runner gets nothing, at any duration — the default mode consults + `stderr.is_terminal()` before writing a byte. Anything asserting on captured + stderr keeps passing. +- **stdout is unchanged**, on every path. Progress never shares the stream the + query result is printed on. +- **`dirsql::scanner::scan_directory` is unchanged.** The reporting walk is a + new sibling, `scan_directory_reporting(root, matcher, &mut on_file)`, which + the existing two-argument function now delegates to with a no-op callback. + Direct callers (benches, in-workspace tools) compile as before. + +#### Verification + +```bash +# A slow scan on a terminal: the counter is drawn, erased, and summarized. +dirsql query "SELECT count(*) FROM items" -c ./.dirsql.toml +# dirsql: indexing 40/41 files (97%) (rewritten in place, then erased) +# dirsql: indexed 41 files in 2.2s +# [{"count(*)":41}] + +# Piped: stderr is empty, exactly as before. +dirsql query "SELECT count(*) FROM items" -c ./.dirsql.toml 2>err.txt | jq . +wc -c err.txt # -> 0 + +# Forced on without a terminal, for watching a redirected run. +DIRSQL_PROGRESS=always dirsql query "SELECT 1" -c ./.dirsql.toml 2>&1 >/dev/null | tail -1 +# -> dirsql: indexed 41 files in 2.2s + +# Opted out, even on a terminal. +DIRSQL_PROGRESS=never dirsql query "SELECT count(*) FROM items" -c ./.dirsql.toml +# -> [{"count(*)":41}] (nothing on stderr) +``` diff --git a/packages/rust/src/lib.rs b/packages/rust/src/lib.rs index 3f515a66c..2e2079943 100644 --- a/packages/rust/src/lib.rs +++ b/packages/rust/src/lib.rs @@ -30,6 +30,8 @@ pub mod path_table; #[doc(hidden)] pub mod persist; #[doc(hidden)] +pub mod progress; +#[doc(hidden)] pub mod scanner; #[doc(hidden)] pub mod sql_literal; @@ -52,7 +54,8 @@ use crate::persist::{ hash_file, is_trusted, meta_is_compatible, now_ns, read_cached_files, read_meta, resolve_persist_path, upsert_file, write_meta, }; -use crate::scanner::scan_directory; +use crate::progress::Progress; +use crate::scanner::scan_directory_reporting; use crate::watcher::{FileEvent, Watcher}; use futures_channel::mpsc::{UnboundedReceiver, UnboundedSender, unbounded}; use std::collections::HashMap; @@ -328,8 +331,9 @@ pub struct DirSQL { /// Internal scan seam: the startup directory walk, injectable so unit tests /// can observe whether it ran. The walk has no result a caller can tell apart /// from not walking, so *whether* it ran takes a seam. Production always -/// passes [`scan_directory`]. -type ScanFn<'a> = &'a dyn Fn(&Path, &TableMatcher) -> Vec<(PathBuf, String)>; +/// passes [`scan_directory_reporting`]; the third argument is the walk's +/// running file count, which drives the progress line. +type ScanFn<'a> = &'a dyn Fn(&Path, &TableMatcher, &mut dyn FnMut(u64)) -> Vec<(PathBuf, String)>; impl DirSQL { /// Start building a `DirSQL`. See [`DirSQLBuilder`] for the available @@ -711,7 +715,7 @@ impl DirSQL { /// JS main thread for the napi-rs TypeScript binding). #[doc(hidden)] pub fn prepare_resolved(resolved: ResolvedBuild) -> Result { - Self::prepare_resolved_with(resolved, &scan_directory) + Self::prepare_resolved_with(resolved, &scan_directory_reporting) } fn prepare_resolved_with(resolved: ResolvedBuild, scan: ScanFn<'_>) -> Result { @@ -751,7 +755,16 @@ impl DirSQL { let scanned = if table_names.is_empty() { Vec::new() } else { - scan(&root, &matcher) + // The walk reports a running count rather than a fraction: it does + // not know how many files there are until it has found them all. + let mut progress = Progress::scanning(); + let mut seen = 0; + let scanned = scan(&root, &matcher, &mut |count| { + seen = count; + progress.update(count, None); + }); + progress.finish(seen); + scanned }; // When persist is enabled, files whose stat tuple matches the cache @@ -953,12 +966,21 @@ impl DirSQL { let snapshot_ns = now_ns(); let mut on_file_failures: Vec = Vec::new(); - for ScannedFile { - rel_path, - table_name, - stat, - } in scanned_files + // The phase a user actually waits on: one `on_file` round trip per + // file, plus whatever the table's DDL triggers on insert. The count is + // known up front, so this one reports a fraction. + let total_files = scanned_files.len() as u64; + let mut progress = Progress::indexing(); + for ( + done, + ScannedFile { + rel_path, + table_name, + stat, + }, + ) in scanned_files.into_iter().enumerate() { + progress.update(done as u64, Some(total_files)); let on_file = on_file_map.get(&table_name).ok_or_else(|| { DirSqlError::Ddl(format!("missing on-file function for table {table_name}")) })?; @@ -1028,6 +1050,8 @@ impl DirSQL { } } + progress.finish(total_files); + // Write the meta block last; ingest and meta commit atomically in the // single transaction opened above. A crash mid-build leaves the cache // exactly as it was before the build started (detected via meta on @@ -2268,8 +2292,18 @@ mod internal_tests { } } - fn scan(&self, _root: &Path, _matcher: &TableMatcher) -> Vec<(PathBuf, String)> { + /// Mirrors the real walk closely enough for the seam: it reports a + /// running file count as it goes, then returns what it found. + fn scan( + &self, + _root: &Path, + _matcher: &TableMatcher, + on_file: &mut dyn FnMut(u64), + ) -> Vec<(PathBuf, String)> { self.calls.set(self.calls.get() + 1); + for (index, _) in self.found.iter().enumerate() { + on_file(index as u64 + 1); + } self.found.clone() } } @@ -2308,7 +2342,7 @@ mod internal_tests { let prepared = DirSQL::prepare_resolved_with( resolved_over(dir.path(), Vec::new(), false), - &|root, matcher| scan.scan(root, matcher), + &|root, matcher, on_file| scan.scan(root, matcher, on_file), ) .unwrap(); @@ -2329,7 +2363,7 @@ mod internal_tests { let prepared = DirSQL::prepare_resolved_with( resolved_over(dir.path(), vec![txt_table()], false), - &|root, matcher| scan.scan(root, matcher), + &|root, matcher, on_file| scan.scan(root, matcher, on_file), ) .unwrap(); @@ -2351,7 +2385,7 @@ mod internal_tests { let prepared = DirSQL::prepare_resolved_with( resolved_over(dir.path(), Vec::new(), true), - &|root, matcher| scan.scan(root, matcher), + &|root, matcher, on_file| scan.scan(root, matcher, on_file), ) .unwrap(); diff --git a/packages/rust/src/progress.rs b/packages/rust/src/progress.rs new file mode 100644 index 000000000..909f76092 --- /dev/null +++ b/packages/rust/src/progress.rs @@ -0,0 +1,590 @@ +//! Progress reporting for the startup scan. +//! +//! A cold scan over a large corpus can run for minutes -- the walk, then one +//! `on_file` round trip per file, then whatever the table's DDL triggers on +//! insert. None of that produced a byte of output before dirsql#957, so a user +//! had a hung-looking terminal and no way to tell a slow scan from a wedged +//! one. +//! +//! Two rules shape everything here: +//! +//! - **A pipe stays silent.** stdout carries query results and stderr carries +//! diagnostics; a progress line is neither. Under the default the reporter +//! writes nothing at all unless stderr is a terminal, so `| jq` pipelines, +//! `2>` redirects and CI logs are byte-for-byte unchanged. +//! - **No new dependencies.** The line is a `\r`-rewritten counter, not a +//! drawn bar: a bar wants the terminal width, and every portable way to ask +//! for it is a crate. A counter reads the same at any width. +//! +//! [`Mode`] is the user's knob, read from `DIRSQL_PROGRESS`. [`Progress`] is +//! one phase's reporter: [`update`](Progress::update) while it runs and +//! [`finish`](Progress::finish) when it ends, which erases the live line and +//! leaves a single summary of what the phase cost -- the point of showing it. + +use std::io::{IsTerminal, Write}; +use std::time::{Duration, Instant}; + +/// The environment variable deciding whether progress is drawn. +pub const PROGRESS_ENV: &str = "DIRSQL_PROGRESS"; + +/// Redraw at most this often. The live line exists to prove the scan is +/// moving, which ten frames a second says as well as a thousand -- and a +/// thousand is a measurable cost of its own on a slow terminal. +const REDRAW_INTERVAL: Duration = Duration::from_millis(100); + +/// Under [`Mode::Auto`], draw nothing until the phase has run this long. A +/// scan that finishes in a blink should leave the terminal exactly as it found +/// it; only work long enough to wonder about is worth reporting. +const WARMUP: Duration = Duration::from_millis(500); + +/// Whether progress is drawn, and on what evidence. +#[derive(Clone, Copy, Debug, PartialEq, Eq)] +pub enum Mode { + /// Draw only on a terminal, and only after [`WARMUP`]. The default. + Auto, + /// Draw regardless of terminal, from the first update. What a user sets to + /// watch a scan whose stderr is redirected, and what makes the drawn + /// output assertable from a test without a pty. + Always, + /// Draw nothing, ever. The opt-out for an embedder that owns its own + /// terminal output. + Never, +} + +impl Mode { + /// Parse the `DIRSQL_PROGRESS` value. Unset, `auto`, and anything + /// unrecognized all mean [`Auto`](Mode::Auto): a typo in an environment + /// variable should not decide whether a scan runs. + pub fn parse(value: Option<&str>) -> Self { + match value + .map(str::trim) + .unwrap_or_default() + .to_ascii_lowercase() + .as_str() + { + "always" | "1" | "true" => Mode::Always, + "never" | "0" | "false" => Mode::Never, + _ => Mode::Auto, + } + } +} + +/// The clock [`Progress`] throttles against. A seam so the unit tier can drive +/// the warmup and redraw thresholds from both sides instead of sleeping. +pub trait Clock { + fn now(&self) -> Instant; +} + +/// The production clock. +pub struct SystemClock; + +impl Clock for SystemClock { + fn now(&self) -> Instant { + Instant::now() + } +} + +/// One phase's progress reporter. +/// +/// Construct with [`scanning`](Progress::scanning) or +/// [`indexing`](Progress::indexing), call [`update`](Progress::update) as the +/// phase advances, and [`finish`](Progress::finish) when it ends. Every method +/// is a no-op when the mode or the terminal says not to draw, so callers need +/// no gating of their own. +pub struct Progress { + /// Present participle for the live line ("indexing 3/9 files"). + label: &'static str, + /// Past participle for the summary ("indexed 9 files in 4.2s"). + summary_label: &'static str, + out: Box, + clock: Box, + mode: Mode, + /// Whether the sink is a terminal. Only consulted under [`Mode::Auto`]. + terminal: bool, + started: Instant, + /// When the live line was last redrawn; `None` until the first draw, which + /// is also what says whether a summary is owed. + last_draw: Option, + /// Width of the line currently on screen, so the next one can overwrite + /// its tail rather than leaving the trailing characters of a longer line + /// behind. + drawn_width: usize, +} + +impl Progress { + /// Reporter for the directory walk, which counts files as it finds them. + pub fn scanning() -> Self { + Self::to_stderr("scanning", "scanned") + } + + /// Reporter for the ingest pass, which counts files against a known total. + pub fn indexing() -> Self { + Self::to_stderr("indexing", "indexed") + } + + fn to_stderr(label: &'static str, summary_label: &'static str) -> Self { + let terminal = std::io::stderr().is_terminal(); + Self::new( + label, + summary_label, + Box::new(std::io::stderr()), + Box::new(SystemClock), + Mode::parse(std::env::var(PROGRESS_ENV).ok().as_deref()), + terminal, + ) + } + + /// The constructor every seam goes through. `terminal` is the sink's + /// terminal-ness, already resolved by the caller. + pub fn new( + label: &'static str, + summary_label: &'static str, + out: Box, + clock: Box, + mode: Mode, + terminal: bool, + ) -> Self { + let started = clock.now(); + Self { + label, + summary_label, + out, + clock, + mode, + terminal, + started, + last_draw: None, + drawn_width: 0, + } + } + + /// Whether this reporter draws at all. [`Mode::Auto`] defers to the sink. + fn enabled(&self) -> bool { + match self.mode { + Mode::Always => true, + Mode::Never => false, + Mode::Auto => self.terminal, + } + } + + /// Report `done` items complete, out of `total` when a total is known. + /// Throttled, and under [`Mode::Auto`] silent until [`WARMUP`] has passed. + pub fn update(&mut self, done: u64, total: Option) { + if !self.enabled() { + return; + } + let now = self.clock.now(); + match self.last_draw { + Some(last) if now.duration_since(last) < REDRAW_INTERVAL => return, + // The warmup gates only the FIRST draw: once a phase has proven + // itself slow, it keeps reporting. + None if self.mode == Mode::Auto && now.duration_since(self.started) < WARMUP => return, + _ => {} + } + self.last_draw = Some(now); + let line = render(self.label, done, total); + self.draw(&line); + } + + /// End the phase: erase the live line and leave one summary line behind. + /// Silent when nothing was ever drawn, so a fast phase leaves no trace. + pub fn finish(&mut self, done: u64) { + if self.last_draw.is_none() { + return; + } + self.erase(); + let elapsed = self.clock.now().duration_since(self.started); + let _ = writeln!( + self.out, + "dirsql: {} {done} files in {}", + self.summary_label, + format_duration(elapsed) + ); + let _ = self.out.flush(); + } + + fn draw(&mut self, line: &str) { + let width = line.chars().count(); + let pad = self.drawn_width.saturating_sub(width); + let _ = write!(self.out, "\r{line}{:pad$}", ""); + let _ = self.out.flush(); + self.drawn_width = width; + } + + fn erase(&mut self) { + if self.drawn_width == 0 { + return; + } + let _ = write!(self.out, "\r{:width$}\r", "", width = self.drawn_width); + self.drawn_width = 0; + } +} + +/// A phase that ends early -- a SQLite error mid-ingest, a hook that could not +/// be found -- must not leave a half-drawn counter under the error message the +/// caller is about to print. [`Progress::finish`] has already erased by the +/// time this runs, so on the normal path it does nothing. +impl Drop for Progress { + fn drop(&mut self) { + self.erase(); + let _ = self.out.flush(); + } +} + +/// The live line's text. With a total it carries a percentage; the walk has no +/// total to divide by until it is over, so it reports a running count. +fn render(label: &str, done: u64, total: Option) -> String { + match total { + Some(total) => format!( + "dirsql: {label} {done}/{total} files ({}%)", + percent(done, total) + ), + None => format!("dirsql: {label} {done} files"), + } +} + +/// `done` as a percentage of `total`, floored. An empty total is complete by +/// definition rather than a division by zero. +fn percent(done: u64, total: u64) -> u64 { + if total == 0 { + return 100; + } + done.saturating_mul(100) / total +} + +/// Elapsed time at the precision a human reads: tenths under a minute, whole +/// seconds above it. +fn format_duration(elapsed: Duration) -> String { + let secs = elapsed.as_secs(); + if secs >= 60 { + format!("{}m{:02}s", secs / 60, secs % 60) + } else { + format!("{:.1}s", elapsed.as_secs_f64()) + } +} + +#[cfg(test)] +mod tests { + use super::*; + use std::cell::{Cell, RefCell}; + use std::rc::Rc; + + /// A `Write` the test can read back. Shares one buffer with the `Progress` + /// that owns its clone. + #[derive(Clone, Default)] + struct Sink(Rc>>); + + impl Sink { + fn text(&self) -> String { + String::from_utf8(self.0.borrow().clone()).unwrap() + } + } + + impl Write for Sink { + fn write(&mut self, buf: &[u8]) -> std::io::Result { + self.0.borrow_mut().extend_from_slice(buf); + Ok(buf.len()) + } + + fn flush(&mut self) -> std::io::Result<()> { + Ok(()) + } + } + + /// A clock the test advances by hand, so the warmup and redraw thresholds + /// can be driven from both sides without sleeping. + #[derive(Clone)] + struct FakeClock { + base: Instant, + offset: Rc>, + } + + impl FakeClock { + fn new() -> Self { + Self { + base: Instant::now(), + offset: Rc::new(Cell::new(Duration::ZERO)), + } + } + + fn advance(&self, delta: Duration) { + self.offset.set(self.offset.get() + delta); + } + } + + impl Clock for FakeClock { + fn now(&self) -> Instant { + self.base + self.offset.get() + } + } + + fn reporter(mode: Mode, terminal: bool) -> (Progress, Sink, FakeClock) { + let sink = Sink::default(); + let clock = FakeClock::new(); + let progress = Progress::new( + "indexing", + "indexed", + Box::new(sink.clone()), + Box::new(clock.clone()), + mode, + terminal, + ); + (progress, sink, clock) + } + + #[test] + fn an_unset_variable_means_auto() { + assert_eq!(Mode::parse(None), Mode::Auto); + } + + #[test] + fn auto_is_spellable() { + assert_eq!(Mode::parse(Some("auto")), Mode::Auto); + } + + #[test] + fn always_has_three_spellings() { + assert_eq!(Mode::parse(Some("always")), Mode::Always); + assert_eq!(Mode::parse(Some("1")), Mode::Always); + assert_eq!(Mode::parse(Some("true")), Mode::Always); + } + + #[test] + fn never_has_three_spellings() { + assert_eq!(Mode::parse(Some("never")), Mode::Never); + assert_eq!(Mode::parse(Some("0")), Mode::Never); + assert_eq!(Mode::parse(Some("false")), Mode::Never); + } + + #[test] + fn parsing_ignores_case_and_surrounding_space() { + assert_eq!(Mode::parse(Some(" ALWAYS ")), Mode::Always); + assert_eq!(Mode::parse(Some("\tNever\n")), Mode::Never); + } + + /// A typo in an environment variable decides nothing: the scan runs, with + /// the default policy. + #[test] + fn an_unrecognized_value_falls_back_to_auto() { + assert_eq!(Mode::parse(Some("banana")), Mode::Auto); + assert_eq!(Mode::parse(Some("")), Mode::Auto); + } + + #[test] + fn the_system_clock_moves_forward() { + let clock = SystemClock; + let first = clock.now(); + assert!(clock.now() >= first); + } + + /// The headline default: a piped run writes nothing, which is what keeps + /// progress out of `| jq` pipelines and CI logs. + #[test] + fn auto_draws_nothing_when_the_sink_is_not_a_terminal() { + let (mut progress, sink, clock) = reporter(Mode::Auto, false); + + clock.advance(Duration::from_secs(30)); + progress.update(5, Some(10)); + progress.finish(10); + + assert_eq!(sink.text(), ""); + } + + #[test] + fn never_draws_nothing_even_on_a_terminal() { + let (mut progress, sink, clock) = reporter(Mode::Never, true); + + clock.advance(Duration::from_secs(30)); + progress.update(5, Some(10)); + progress.finish(10); + + assert_eq!(sink.text(), ""); + } + + /// Under `auto` a phase must prove itself slow before it draws: a scan + /// that finishes in a blink leaves the terminal exactly as it found it. + #[test] + fn auto_stays_silent_until_the_warmup_has_elapsed() { + let (mut progress, sink, clock) = reporter(Mode::Auto, true); + + progress.update(1, Some(10)); + clock.advance(WARMUP - Duration::from_millis(1)); + progress.update(2, Some(10)); + + assert_eq!(sink.text(), "", "nothing is drawn before the warmup"); + + clock.advance(Duration::from_millis(1)); + progress.update(3, Some(10)); + + assert_eq!(sink.text(), "\rdirsql: indexing 3/10 files (30%)"); + } + + /// `always` is the explicit ask, so it skips the warmup entirely -- and it + /// is what makes the drawn output observable from a test without a pty. + #[test] + fn always_draws_from_the_first_update() { + let (mut progress, sink, _clock) = reporter(Mode::Always, false); + + progress.update(3, Some(10)); + + assert_eq!(sink.text(), "\rdirsql: indexing 3/10 files (30%)"); + } + + /// The live line proves the scan is moving; redrawing it faster than the + /// eye reads costs the terminal and says nothing new. + #[test] + fn updates_inside_the_redraw_interval_are_dropped() { + let (mut progress, sink, clock) = reporter(Mode::Always, false); + + progress.update(1, Some(10)); + clock.advance(REDRAW_INTERVAL - Duration::from_millis(1)); + progress.update(2, Some(10)); + + assert_eq!( + sink.text(), + "\rdirsql: indexing 1/10 files (10%)", + "the second update is throttled away" + ); + + clock.advance(Duration::from_millis(1)); + progress.update(2, Some(10)); + + assert_eq!( + sink.text(), + "\rdirsql: indexing 1/10 files (10%)\rdirsql: indexing 2/10 files (20%)" + ); + } + + /// A shorter line must cover the tail of the longer one it replaces, or + /// the terminal keeps showing digits from the previous count. + #[test] + fn a_shorter_line_is_padded_over_the_one_it_replaces() { + let (mut progress, sink, clock) = reporter(Mode::Always, false); + + progress.update(1000, Some(1000)); + clock.advance(REDRAW_INTERVAL); + progress.update(1, None); + + let long = "dirsql: indexing 1000/1000 files (100%)"; + let short = "dirsql: indexing 1 files"; + let pad = " ".repeat(long.len() - short.len()); + assert_eq!(sink.text(), format!("\r{long}\r{short}{pad}")); + } + + /// A phase that never drew leaves no trace -- no erase, no summary. + #[test] + fn finishing_without_a_draw_writes_nothing() { + let (mut progress, sink, _clock) = reporter(Mode::Always, false); + + progress.finish(10); + + assert_eq!(sink.text(), ""); + } + + /// What survives the phase is one line saying what it cost. Erasing first + /// keeps the live counter from being left behind mid-count. + #[test] + fn finishing_erases_the_live_line_and_summarizes_the_cost() { + let (mut progress, sink, clock) = reporter(Mode::Always, false); + + progress.update(1, Some(10)); + clock.advance(Duration::from_millis(4500)); + progress.finish(10); + + assert_eq!( + sink.text(), + "\rdirsql: indexing 1/10 files (10%)\ + \r \r\ + dirsql: indexed 10 files in 4.5s\n" + ); + } + + #[test] + fn a_phase_with_no_known_total_reports_a_running_count() { + assert_eq!(render("scanning", 42, None), "dirsql: scanning 42 files"); + } + + #[test] + fn a_phase_with_a_known_total_reports_a_percentage() { + assert_eq!( + render("indexing", 3, Some(8)), + "dirsql: indexing 3/8 files (37%)" + ); + } + + #[test] + fn a_percentage_floors_rather_than_rounds() { + assert_eq!(percent(3, 8), 37); + assert_eq!(percent(1, 3), 33); + assert_eq!(percent(9, 10), 90); + } + + /// An empty total is complete by definition rather than a division by + /// zero. + #[test] + fn an_empty_total_is_a_hundred_percent() { + assert_eq!(percent(0, 0), 100); + } + + /// The multiplication is saturating, so a count near the integer ceiling + /// reports a bounded number instead of wrapping to a small one. + #[test] + fn an_enormous_count_does_not_wrap() { + assert_eq!(percent(u64::MAX, u64::MAX), 1); + } + + #[test] + fn a_short_duration_reads_in_tenths_of_a_second() { + assert_eq!(format_duration(Duration::from_millis(40)), "0.0s"); + assert_eq!(format_duration(Duration::from_millis(4500)), "4.5s"); + assert_eq!(format_duration(Duration::from_millis(59_900)), "59.9s"); + } + + #[test] + fn a_long_duration_reads_in_minutes_and_seconds() { + assert_eq!(format_duration(Duration::from_secs(60)), "1m00s"); + assert_eq!(format_duration(Duration::from_secs(125)), "2m05s"); + assert_eq!(format_duration(Duration::from_secs(3725)), "62m05s"); + } + + /// An error mid-phase must not leave a half-drawn counter behind for the + /// error message to land on top of. + #[test] + fn dropping_mid_phase_erases_the_live_line() { + let (mut progress, sink, _clock) = reporter(Mode::Always, false); + + progress.update(1, Some(10)); + drop(progress); + + let line = "dirsql: indexing 1/10 files (10%)"; + let blanks = " ".repeat(line.len()); + assert_eq!(sink.text(), format!("\r{line}\r{blanks}\r")); + } + + /// ...and a phase that already finished has nothing left to erase, so the + /// summary is the last thing written. + #[test] + fn dropping_after_finishing_writes_nothing_further() { + let (mut progress, sink, _clock) = reporter(Mode::Always, false); + + progress.update(1, Some(10)); + progress.finish(10); + let after_finish = sink.text(); + drop(progress); + + assert_eq!(sink.text(), after_finish); + } + + /// The two production reporters differ only in wording, and the wording is + /// what a user reads to tell the walk from the ingest. + #[test] + fn the_production_reporters_carry_the_phase_wording() { + let scanning = Progress::scanning(); + assert_eq!(scanning.label, "scanning"); + assert_eq!(scanning.summary_label, "scanned"); + + let indexing = Progress::indexing(); + assert_eq!(indexing.label, "indexing"); + assert_eq!(indexing.summary_label, "indexed"); + } +} diff --git a/packages/rust/src/scanner.rs b/packages/rust/src/scanner.rs index deab76629..2fc12d06c 100644 --- a/packages/rust/src/scanner.rs +++ b/packages/rust/src/scanner.rs @@ -15,7 +15,28 @@ pub const RESERVED_DIR: &str = ".dirsql"; /// /// The top-level `.dirsql/` directory is unconditionally excluded. pub fn scan_directory(root: &Path, matcher: &TableMatcher) -> Vec<(PathBuf, String)> { + scan_directory_reporting(root, matcher, &mut |_| {}) +} + +/// [`scan_directory`], calling `on_file` with the running count of files the +/// walk has reached. +/// +/// The walk is the one phase of a startup scan with no total to measure +/// against — it does not know how many files there are until it has found them +/// all — so what it can report is a count, not a fraction. See +/// [`crate::progress`], which turns that count into the line a user watching a +/// cold scan sees. +/// +/// The count is files *visited*, not the pairs returned: a file matching two +/// tables' globs is one file the walk paid for, and two rows of work for the +/// phase after it. +pub fn scan_directory_reporting( + root: &Path, + matcher: &TableMatcher, + on_file: &mut dyn FnMut(u64), +) -> Vec<(PathBuf, String)> { let mut results = Vec::new(); + let mut seen: u64 = 0; for entry in walk(root, matcher, Path::new(""), false) { let path = entry.path(); @@ -32,6 +53,9 @@ pub fn scan_directory(root: &Path, matcher: &TableMatcher) -> Vec<(PathBuf, Stri continue; } + seen += 1; + on_file(seen); + // Fan-out: a file matching N tables' globs yields N (path, table) // pairs, one per matching table, in declaration order. for m in matcher.match_all(rel_path) { diff --git a/packages/rust/tests/scan_progress_e2e.rs b/packages/rust/tests/scan_progress_e2e.rs new file mode 100644 index 000000000..8297253e3 --- /dev/null +++ b/packages/rust/tests/scan_progress_e2e.rs @@ -0,0 +1,163 @@ +//! End-to-end tests for progress reporting on the startup scan. +//! +//! A cold scan over a large corpus can run for minutes with nothing on the +//! terminal (dirsql#957). These spawn the real compiled `dirsql` binary over a +//! temp directory and assert the two things only the process boundary can +//! show: what reaches stderr while the index is built, and that stdout stays +//! the query result alone. Nothing is mocked. +//! +//! The gate is `DIRSQL_PROGRESS`: `auto` (the default) draws only on a +//! terminal, so a piped run -- which is what these tests capture, and what a +//! `| jq` pipeline is -- must stay byte-for-byte silent. `always` forces the +//! reporting on regardless, which is what makes the drawn output assertable +//! here without a pty. +//! +//! Gated behind `--features cli` (the `dirsql` bin needs it) and Unix (the +//! fixtures shell out to `sh`); the Rust CI test job runs on Linux. + +#![cfg(all(feature = "cli", unix))] + +use std::fs; +use std::process::Output; + +use assert_cmd::prelude::*; +use tempfile::TempDir; + +const CONFIG: &str = r#" +[[table]] +name = "items" +ddl = "CREATE TABLE items (name TEXT)" +glob = "*.txt" +on-file = '''sh -c 'printf "[{\"name\":\"%s\"}]" "${1##*/}"' sh {path}''' +"#; + +/// A root with `count` matching files and a config that indexes them. +fn fixture(count: usize) -> TempDir { + let root = TempDir::new().unwrap(); + fs::write(root.path().join(".dirsql.toml"), CONFIG).unwrap(); + for i in 0..count { + fs::write(root.path().join(format!("file{i}.txt")), "x\n").unwrap(); + } + root +} + +/// Run `dirsql -c .dirsql.toml query ` with an explicit `DIRSQL_PROGRESS` +/// setting (or none), capturing both streams. +fn run(dir: &std::path::Path, progress: Option<&str>) -> Output { + let mut cmd = std::process::Command::cargo_bin("dirsql").expect("binary must exist"); + cmd.arg("query") + .arg("SELECT count(*) AS n FROM items") + .arg("-c") + .arg(".dirsql.toml") + .current_dir(dir) + .env_remove("DIRSQL_PROGRESS"); + if let Some(value) = progress { + cmd.env("DIRSQL_PROGRESS", value); + } + cmd.output().expect("spawning `dirsql query` failed") +} + +fn stderr(out: &Output) -> String { + String::from_utf8_lossy(&out.stderr).into_owned() +} + +/// The headline: with reporting forced on, the ingest phase names how many +/// files it has indexed out of how many it found, so a user watching a long +/// scan can see it moving. +#[test] +fn forced_progress_reports_the_ingest_phase_on_stderr() { + let root = fixture(3); + + let out = run(root.path(), Some("always")); + + let err = stderr(&out); + assert!( + err.contains("dirsql: indexing"), + "the ingest phase draws a labeled progress line: {err:?}" + ); + assert!( + err.contains("/3 files"), + "the line carries the scan's total: {err:?}" + ); +} + +/// The walk runs before anything can be counted against a total, so it reports +/// a running count of the files it has found -- and the count has to be the +/// files it actually reached. Asserting the number, not just the label, is +/// what catches a walk that reports a frozen counter (a surviving +/// `seen += 1` mutant did exactly that). +#[test] +fn forced_progress_reports_the_walk_phase_on_stderr() { + let root = fixture(3); + + let out = run(root.path(), Some("always")); + + let err = stderr(&out); + assert!( + err.contains("dirsql: scanning"), + "the directory walk draws a labeled progress line: {err:?}" + ); + // Four: the three fixture files plus the `.dirsql.toml` the walk also + // visits. The walk counts files it reached, not rows it matched. + assert!( + err.contains("dirsql: scanned 4 files in "), + "the walk summarizes the files it actually reached: {err:?}" + ); +} + +/// Progress is erased when the phase ends, so what survives is one summary +/// line saying what the run cost -- the point of showing it at all. +#[test] +fn forced_progress_leaves_a_summary_of_what_the_scan_cost() { + let root = fixture(3); + + let out = run(root.path(), Some("always")); + + let err = stderr(&out); + assert!( + err.contains("dirsql: indexed 3 files in "), + "the ingest phase summarizes its file count and elapsed time: {err:?}" + ); +} + +/// stdout is the query result alone: progress never contaminates the stream a +/// `| jq` pipeline reads. +#[test] +fn forced_progress_never_touches_stdout() { + let root = fixture(3); + + let out = run(root.path(), Some("always")); + + let stdout = String::from_utf8_lossy(&out.stdout); + let value: serde_json::Value = serde_json::from_str(stdout.trim()) + .unwrap_or_else(|e| panic!("stdout is JSON: {e}: {stdout:?}")); + assert_eq!(value[0]["n"], 3, "the query still returns its rows"); +} + +/// The default is `auto`, which means "a terminal or nothing". These tests +/// capture stderr through a pipe, so the run must be silent -- the property +/// that keeps progress out of logs, CI output and `2>` redirects. +#[test] +fn progress_is_silent_by_default_when_stderr_is_not_a_terminal() { + let root = fixture(3); + + let out = run(root.path(), None); + + let err = stderr(&out); + assert_eq!(err, "", "a piped run writes nothing to stderr: {err:?}"); +} + +/// `never` is the opt-out an embedder sets to guarantee silence even on a +/// terminal. +#[test] +fn progress_is_silent_when_explicitly_disabled() { + let root = fixture(3); + + let out = run(root.path(), Some("never")); + + let err = stderr(&out); + assert_eq!( + err, "", + "an opted-out run writes nothing to stderr: {err:?}" + ); +} diff --git a/packages/ts/e2e-attestations/claude-tackle-957-lrm0z6.json b/packages/ts/e2e-attestations/claude-tackle-957-lrm0z6.json new file mode 100644 index 000000000..8fd6002fb --- /dev/null +++ b/packages/ts/e2e-attestations/claude-tackle-957-lrm0z6.json @@ -0,0 +1,7 @@ +{ + "command": "pnpm test:e2e", + "ran_at": 1787261155, + "exit_code": 0, + "commit": "2947e1c5ba24090d07a2bc8a8c92779fa6506a08", + "branch": "claude/tackle-957-lrm0z6" +}