From 8f0a2e988de55b1f1cfd295bae2109ed3f9d9a85 Mon Sep 17 00:00:00 2001 From: Vincent Date: Mon, 28 Sep 2026 18:50:26 -0400 Subject: [PATCH 1/2] feat: log every command to a daily file with tracing Replace env_logger with tracing-subscriber. The terminal keeps env_logger's behaviour; every command also appends info and above to ~/.atomic/logs/atomic.YYYY-MM-DD.log, one line per event with the pid and spans. git import logs each commit in a commit{n, of, sha} span with its duration, and the write loop's decisions. --- Cargo.lock | 160 ++++++- Cargo.toml | 4 + atomic-cli/Cargo.toml | 5 +- atomic-cli/README.md | 24 +- atomic-cli/src/commands/git/parallel.rs | 38 +- atomic-cli/src/logging/file_format.rs | 115 +++++ atomic-cli/src/logging/mod.rs | 453 +++++++++++++++++++ atomic-cli/src/logging/redact.rs | 67 +++ atomic-cli/src/logging/retention.rs | 128 ++++++ atomic-cli/src/logging/terminal.rs | 106 +++++ atomic-cli/src/main.rs | 48 +- atomic-cli/tests/logging_integration_test.rs | 290 ++++++++++++ 12 files changed, 1391 insertions(+), 47 deletions(-) create mode 100644 atomic-cli/src/logging/file_format.rs create mode 100644 atomic-cli/src/logging/mod.rs create mode 100644 atomic-cli/src/logging/redact.rs create mode 100644 atomic-cli/src/logging/retention.rs create mode 100644 atomic-cli/src/logging/terminal.rs create mode 100644 atomic-cli/tests/logging_integration_test.rs diff --git a/Cargo.lock b/Cargo.lock index 0277396e..45004821 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -192,7 +192,6 @@ dependencies = [ "data-encoding", "dialoguer", "dirs", - "env_logger", "fs2", "git2", "indicatif", @@ -207,6 +206,10 @@ dependencies = [ "tempfile", "thiserror 1.0.69", "tokio", + "tracing", + "tracing-appender", + "tracing-log", + "tracing-subscriber", "url", "uuid", "windows-sys 0.61.2", @@ -727,6 +730,15 @@ version = "1.2.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "790eea4361631c5e7d22598ecd5723ff611904e3344ce8720784c93e3d83d40b" +[[package]] +name = "crossbeam-channel" +version = "0.5.17" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "98b0cc327b5bc766e7fda9c9260cc0fa81b43a8e240440422dff70788e3f9ef1" +dependencies = [ + "crossbeam-utils", +] + [[package]] name = "crossbeam-deque" version = "0.8.8" @@ -836,6 +848,12 @@ dependencies = [ "zeroize", ] +[[package]] +name = "deranged" +version = "0.5.8" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "7cd812cc2bc1d69d4764bd80df88b4317eaef9e773c75226407d9bc0876b211c" + [[package]] name = "dialoguer" version = "0.11.0" @@ -1724,6 +1742,12 @@ dependencies = [ "wasm-bindgen", ] +[[package]] +name = "lazy_static" +version = "1.5.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "bbd2bcb4c963f2ddae06a2efc7e9f3591312473c50c6685e1f298068316e66fe" + [[package]] name = "libc" version = "0.2.189" @@ -1829,6 +1853,15 @@ version = "1.0.2" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "3e2e65a1a2e43cfcb47a895c4c8b10d1f4a61097f9f254f183aee60cad9c651d" +[[package]] +name = "matchers" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d1525a2a28c7f4fa0fc98bb91ae755d1e2d1505079e05539e35bc876b5d65ae9" +dependencies = [ + "regex-automata", +] + [[package]] name = "memchr" version = "2.8.3" @@ -1915,6 +1948,12 @@ dependencies = [ "tempfile", ] +[[package]] +name = "num-conv" +version = "0.2.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "521739c6d2bac4aa25192232afe6841231376b2b26d4d9fae5ecf8ca5772e441" + [[package]] name = "num-traits" version = "0.2.19" @@ -2105,6 +2144,12 @@ dependencies = [ "zerovec", ] +[[package]] +name = "powerfmt" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "439ee305def115ba05938db6eb1644ff94165c5ab5e9420d1c1bcedbba909391" + [[package]] name = "ppv-lite86" version = "0.2.21" @@ -2755,6 +2800,15 @@ dependencies = [ "digest", ] +[[package]] +name = "sharded-slab" +version = "0.1.7" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f40ca3c46823713e0d4209592e8d6e826aa57e928f09752619fc696c499637f6" +dependencies = [ + "lazy_static", +] + [[package]] name = "shell-words" version = "1.1.1" @@ -2869,6 +2923,12 @@ version = "2.6.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "13c2bddecc57b384dee18652358fb23172facb8a2c51ccc10d74c157bdea3292" +[[package]] +name = "symlink" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "a7973cce6668464ea31f176d85b13c7ab3bba2cb3b77a2ed26abd7801688010a" + [[package]] name = "syn" version = "2.0.119" @@ -3028,6 +3088,45 @@ dependencies = [ "syn 3.0.6", ] +[[package]] +name = "thread_local" +version = "1.1.10" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "1ad99c4c6d32803332c548b1af0540b357b3f5fc0be8f6c6bfe8b2e6ae784070" +dependencies = [ + "cfg-if", +] + +[[package]] +name = "time" +version = "0.3.55" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "cdb87b95ec50ddfa440816d227a17b2ccbdda963a316a727fda0fc4334f7d134" +dependencies = [ + "deranged", + "num-conv", + "powerfmt", + "serde_core", + "time-core", + "time-macros", +] + +[[package]] +name = "time-core" +version = "0.1.9" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "9e1c906769ad99c88eaa54e728060edef082f8e358ff32030cb7c7d315e81109" + +[[package]] +name = "time-macros" +version = "0.2.32" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "7e689342a48d2ea927c87ea50cabf8594854bf940e9310208848d680d668ed85" +dependencies = [ + "num-conv", + "time-core", +] + [[package]] name = "tinystr" version = "0.8.4" @@ -3220,9 +3319,34 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "63e71662fa4b2a2c3a26f570f037eb95bb1f85397f3cd8076caed2f026a6d100" dependencies = [ "pin-project-lite", + "tracing-attributes", "tracing-core", ] +[[package]] +name = "tracing-appender" +version = "0.2.5" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "050686193eb999b4bb3bc2acfa891a13da00f79734704c4b8b4ef1a10b368a3c" +dependencies = [ + "crossbeam-channel", + "symlink", + "thiserror 2.0.20", + "time", + "tracing-subscriber", +] + +[[package]] +name = "tracing-attributes" +version = "0.1.31" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "7490cfa5ec963746568740651ac6781f701c9c5ea257c58e057f3ba8cf69e8da" +dependencies = [ + "proc-macro2", + "quote", + "syn 2.0.119", +] + [[package]] name = "tracing-core" version = "0.1.36" @@ -3230,6 +3354,34 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "db97caf9d906fbde555dd62fa95ddba9eecfd14cb388e4f491a66d74cd5fb79a" dependencies = [ "once_cell", + "valuable", +] + +[[package]] +name = "tracing-log" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ee855f1f400bd0e5c02d150ae5de3840039a3f54b025156404e34c23c03f47c3" +dependencies = [ + "log", + "once_cell", + "tracing-core", +] + +[[package]] +name = "tracing-subscriber" +version = "0.3.23" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "cb7f578e5945fb242538965c2d0b04418d38ec25c79d160cd279bf0731c8d319" +dependencies = [ + "matchers", + "once_cell", + "regex-automata", + "sharded-slab", + "thread_local", + "tracing", + "tracing-core", + "tracing-log", ] [[package]] @@ -3423,6 +3575,12 @@ dependencies = [ "wasm-bindgen", ] +[[package]] +name = "valuable" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ba73ea9cf16a25df0c8caa16c51acb937d5712a8429db78a3ee29d5dcacd3a65" + [[package]] name = "vcpkg" version = "0.2.15" diff --git a/Cargo.toml b/Cargo.toml index 36780037..6a06c529 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -100,6 +100,10 @@ tempfile = "3.10" parking_lot = "0.12" log = "0.4" env_logger = "0.11" +tracing = "0.1" +tracing-subscriber = { version = "0.3", default-features = false, features = ["std", "fmt", "env-filter", "registry", "tracing-log"] } +tracing-appender = "0.2" +tracing-log = "0.2" xxhash-rust = { version = "0.8", features = ["xxh3"] } # Diff algorithms diff --git a/atomic-cli/Cargo.toml b/atomic-cli/Cargo.toml index 52125a82..5fa0407d 100644 --- a/atomic-cli/Cargo.toml +++ b/atomic-cli/Cargo.toml @@ -53,7 +53,10 @@ thiserror = { workspace = true } # Logging log = { workspace = true } -env_logger = { workspace = true } +tracing = { workspace = true } +tracing-subscriber = { workspace = true } +tracing-appender = { workspace = true } +tracing-log = { workspace = true } # Time chrono = { workspace = true } diff --git a/atomic-cli/README.md b/atomic-cli/README.md index e7cec696..a3fbd245 100644 --- a/atomic-cli/README.md +++ b/atomic-cli/README.md @@ -47,6 +47,26 @@ atomic push origin | `-h, --help` | Print help information | | `-V, --version` | Print version | +## Logging + +The terminal shows warnings; `-v` or `RUST_LOG` shows more. Every command also +writes `info` and above to a daily file, `~/.atomic/logs/atomic.YYYY-MM-DD.log` +(UTC date; `logs/` under `ATOMIC_CONFIG_DIR` when that is set), in a directory +only you can read. The last seven files are kept. Each line starts with the +time and process id, then names the command and the spans it ran in: + +``` +2026-09-28T21:30:23.133637Z pid=4242 INFO ThreadId(01) atomic{cmd=git import}:import{branch="main" commits=50}:write{commits=50}:commit{n=3 of=50 sha=1b9c1fec}: atomic::git::import: write 1b9c1fec … +``` + +Each span also logs its duration when it closes (`close time.busy=…`). + +| Variable | Effect | +|----------|--------| +| `ATOMIC_LOG` | The file's filter, in `RUST_LOG` syntax (default `warn,atomic=info`); `off` turns the file off | +| `ATOMIC_LOG_DIR` | Write the file to this directory instead; it must be an absolute path | +| `RUST_LOG` | The terminal's filter | + --- ## Command Reference @@ -862,7 +882,9 @@ Global identity configuration is stored in `~/.config/atomic/` (or platform equi | Variable | Description | |----------|-------------| -| `ATOMIC_LOG` | Set log level (`trace`, `debug`, `info`, `warn`, `error`) | +| `ATOMIC_LOG` | The log file's filter, in `RUST_LOG` syntax; `off` turns the file off (see [Logging](#logging)) | +| `ATOMIC_LOG_DIR` | Directory for the log file, an absolute path | +| `RUST_LOG` | The terminal's log filter | | `NO_COLOR` | Disable colored output (standard convention) | --- diff --git a/atomic-cli/src/commands/git/parallel.rs b/atomic-cli/src/commands/git/parallel.rs index 7dc9aab7..9bb28a56 100644 --- a/atomic-cli/src/commands/git/parallel.rs +++ b/atomic-cli/src/commands/git/parallel.rs @@ -2495,9 +2495,17 @@ pub(crate) fn trace_git_import_enabled() -> bool { std::env::var_os("ATOMIC_TRACE_GIT_IMPORT").is_some() } +/// Log target of `git import`'s progress lines, so a filter can pick them +/// out: `ATOMIC_LOG=warn,atomic::git::import=info`. +pub(crate) const GIT_IMPORT_LOG_TARGET: &str = "atomic::git::import"; + +/// A `git import` progress line: always in the log file, and on the terminal +/// with `ATOMIC_TRACE_GIT_IMPORT`. pub(crate) fn trace_git_import(message: impl AsRef) { + let message = message.as_ref(); + tracing::info!(target: GIT_IMPORT_LOG_TARGET, "{message}"); if trace_git_import_enabled() { - eprintln!("[git-import] {}", message.as_ref()); + eprintln!("[git-import] {message}"); } } @@ -3958,6 +3966,7 @@ impl ParallelImporter { /// Same prospective validation with an explicit tip override (§7.5): the /// commits behind `tip` import into the view named `branch_name` even when /// no local branch carries that tip. + #[tracing::instrument(name = "preflight", skip_all, fields(branch = branch_name))] pub(crate) fn validate_branch_prospectively_for_tip( &self, branch_name: &str, @@ -4345,6 +4354,11 @@ impl ParallelImporter { self.import_prevalidated(branch_name, repo, plan) } + #[tracing::instrument( + name = "import", + skip_all, + fields(branch = branch_name, commits = plan.commits.len()) + )] pub(crate) fn import_prevalidated( &self, branch_name: &str, @@ -4670,6 +4684,7 @@ impl ParallelImporter { // ═══════════════════════════════════════════════════════════════════════ /// Phase 1: Parse all commits in parallel using rayon. + #[tracing::instrument(name = "parse", skip_all, fields(commits = commit_oids.len()))] fn phase1_parse(&self, commit_oids: &[Oid]) -> CliResult> { // Build a map from OID to index for parent lookups let oid_to_index: std::collections::HashMap = commit_oids @@ -4684,12 +4699,15 @@ impl ParallelImporter { // Share the repo path for thread-local repo opening let repo_path = self.git_repo_path.clone(); + // Rayon's threads don't inherit the span; log their lines inside it. + let parse_span = tracing::Span::current(); // Parse commits in parallel - each thread opens its own git repo let results: Vec> = commit_oids .par_iter() .enumerate() .map(|(idx, oid)| { + let _span = parse_span.enter(); // Progress reporting (every 100 commits) let count = progress.fetch_add(1, Ordering::Relaxed); if total > 100 && count.is_multiple_of(100) { @@ -4712,6 +4730,7 @@ impl ParallelImporter { match result { Ok(commit) => parsed.push(commit), Err(e) => { + tracing::info!(target: GIT_IMPORT_LOG_TARGET, idx, error = %e, "parse failed; commit skipped"); print_warning(&format!("Skipping commit {}: {}", idx, e)); } } @@ -4734,6 +4753,7 @@ impl ParallelImporter { // ═══════════════════════════════════════════════════════════════════════ /// Phase 2: Write changes sequentially with hash chaining. + #[tracing::instrument(name = "write", skip_all, fields(commits = commits.len()))] fn phase2_write( &self, repo: &mut Repository, @@ -4754,9 +4774,17 @@ impl ParallelImporter { for (idx, candidate) in commits.iter().enumerate() { let parsed = &candidate.parsed; + let _commit_span = tracing::info_span!( + "commit", + n = idx + 1, + of = total, + sha = %parsed.short_sha + ) + .entered(); // Commits created by `atomic git push` whose referenced view // state is already present add nothing — skip them entirely. if should_skip_self_push(parsed, &self.options) { + tracing::info!(target: GIT_IMPORT_LOG_TARGET, "skip: written by atomic git push, view state already present"); stats.self_push_skipped += 1; continue; } @@ -4769,12 +4797,14 @@ impl ParallelImporter { if self.options.incremental { match self.try_squash_insert(repo, parsed)? { SquashDecision::Inserted(info) => { + tracing::info!(target: GIT_IMPORT_LOG_TARGET, "squash: inserted the original changes"); stats.squash_inserted += 1; stats.files_processed += parsed.files.len(); imported_commits.push(info); continue; } SquashDecision::Skipped => { + tracing::info!(target: GIT_IMPORT_LOG_TARGET, "squash: skipped"); stats.squash_skipped += 1; continue; } @@ -4786,6 +4816,7 @@ impl ParallelImporter { // resurrection over synthesis. Trailers, names, and index rows // cannot reach this path: only crypto + Git-content verification. if let Some(binding) = self.verified_binding_for(repo, &git, parsed)? { + tracing::info!(target: GIT_IMPORT_LOG_TARGET, "resurrect from its verified binding"); let info = self.resurrect_commit(repo, &git, parsed, &binding)?; stats.changes_written += 1; stats.resurrected_exact += 1; @@ -4830,6 +4861,7 @@ impl ParallelImporter { ) { Ok(info) => info, Err(error) => { + tracing::info!(target: GIT_IMPORT_LOG_TARGET, error = %error, "write failed; the import stops at this commit"); stats.failure = Some(format!("{error}")); break; } @@ -4879,7 +4911,9 @@ impl ParallelImporter { } if !index_entries.is_empty() { - let _ = repo.update_file_index(working_copy, &index_entries); + if let Err(error) = repo.update_file_index(working_copy, &index_entries) { + tracing::info!(target: GIT_IMPORT_LOG_TARGET, error = %error, "file index update failed"); + } } Ok((stats, imported_commits)) diff --git a/atomic-cli/src/logging/file_format.rs b/atomic-cli/src/logging/file_format.rs new file mode 100644 index 00000000..c18c8a72 --- /dev/null +++ b/atomic-cli/src/logging/file_format.rs @@ -0,0 +1,115 @@ +//! The log file's line: `time pid=N LEVEL ThreadId(N) spans: target: message`. + +use std::borrow::Cow; +use std::fmt; + +use tracing::{Event, Subscriber}; +use tracing_subscriber::fmt::format::{Format, Full, Writer}; +use tracing_subscriber::fmt::time::{FormatTime, SystemTime}; +use tracing_subscriber::fmt::{FmtContext, FormatEvent, FormatFields}; +use tracing_subscriber::registry::LookupSpan; + +/// `tracing`'s full format with the process id after the time, since many +/// processes append to the same file and some threads (tokio workers, +/// watchers) run outside the command's span. Every event is one line. +pub(super) struct FileFormat { + pid: u32, + inner: Format, +} + +impl FileFormat { + pub(super) fn new() -> Self { + Self { + pid: std::process::id(), + inner: tracing_subscriber::fmt::format() + .without_time() + .with_thread_ids(true), + } + } +} + +impl FormatEvent for FileFormat +where + S: Subscriber + for<'a> LookupSpan<'a>, + N: for<'a> FormatFields<'a> + 'static, +{ + fn format_event( + &self, + ctx: &FmtContext<'_, S, N>, + mut writer: Writer<'_>, + event: &Event<'_>, + ) -> fmt::Result { + let mut line = String::new(); + self.inner + .format_event(ctx, Writer::new(&mut line), event)?; + SystemTime.format_time(&mut writer)?; + write!(writer, " pid={} ", self.pid)?; + writeln!(writer, "{}", one_line(line.trim_end_matches('\n'))) + } +} + +/// Newlines and carriage returns inside an event become `\n` and `\r`, so +/// every event is exactly one line: text from Git, such as a tag annotation, +/// cannot forge log lines, and a line is appended with a single write. +fn one_line(text: &str) -> Cow<'_, str> { + if text.contains(['\n', '\r']) { + Cow::Owned(text.replace('\n', "\\n").replace('\r', "\\r")) + } else { + Cow::Borrowed(text) + } +} + +#[cfg(test)] +mod tests { + use std::io; + use std::sync::{Arc, Mutex}; + + use tracing_subscriber::layer::SubscriberExt; + + use super::*; + + #[derive(Clone, Default)] + struct Captured(Arc>>); + + impl io::Write for Captured { + fn write(&mut self, bytes: &[u8]) -> io::Result { + self.0.lock().unwrap().extend_from_slice(bytes); + Ok(bytes.len()) + } + + fn flush(&mut self) -> io::Result<()> { + Ok(()) + } + } + + #[test] + fn each_event_is_one_line_with_the_pid_and_its_spans() { + let captured = Captured::default(); + let writer = captured.clone(); + let subscriber = tracing_subscriber::registry().with( + tracing_subscriber::fmt::layer() + .with_writer(move || writer.clone()) + .event_format(FileFormat::new()), + ); + tracing::subscriber::with_default(subscriber, || { + let _span = tracing::info_span!("atomic", cmd = %"git import").entered(); + tracing::info!( + target: "atomic::git::import", + "tag 'v1' annotation: fixed\n2026-01-01T00:00:00Z INFO forged" + ); + }); + + let bytes = captured.0.lock().unwrap().clone(); + let text = String::from_utf8(bytes).unwrap(); + assert_eq!(text.lines().count(), 1, "{text}"); + let pid = format!(" pid={} INFO ThreadId(", std::process::id()); + assert!(text.contains(&pid), "{text}"); + assert!( + text.ends_with( + "atomic{cmd=git import}: atomic::git::import: tag 'v1' annotation: \ + fixed\\n2026-01-01T00:00:00Z INFO forged\n" + ), + "{text}" + ); + } +} diff --git a/atomic-cli/src/logging/mod.rs b/atomic-cli/src/logging/mod.rs new file mode 100644 index 00000000..9aad622d --- /dev/null +++ b/atomic-cli/src/logging/mod.rs @@ -0,0 +1,453 @@ +//! Logging: warnings on the terminal, `info` and above in a daily file. +//! +//! The terminal shows what it showed under `env_logger`: warnings by default, +//! more with `--verbose` or `RUST_LOG`, one `[time LEVEL target] message` line +//! each. Every command also appends `info` and above to `atomic.YYYY-MM-DD.log` +//! (UTC date) in `~/.atomic/logs`, or in `logs/` under `ATOMIC_CONFIG_DIR` +//! when that is set. Each event is one line, appended with a single write, so +//! it is on disk when the call returns, and processes sharing the file (agent +//! hooks run concurrently) never interleave within a line. Each line names its +//! process and the spans it ran in. +//! +//! - `ATOMIC_LOG` sets the file's filter, in `RUST_LOG` syntax; `off` turns +//! the file off. +//! - `ATOMIC_LOG_DIR` moves the file; it must be an absolute path. +//! +//! The `log` macros the crates already use reach both outputs unchanged. + +mod file_format; +mod redact; +mod retention; +mod terminal; + +use std::ffi::OsString; +use std::fmt; +use std::path::{Path, PathBuf}; + +use tracing_appender::rolling::{InitError, RollingFileAppender, Rotation}; +use tracing_subscriber::filter::EnvFilter; +use tracing_subscriber::fmt::format::FmtSpan; +use tracing_subscriber::layer::SubscriberExt; +use tracing_subscriber::util::SubscriberInitExt; +use tracing_subscriber::{Layer, Registry}; + +use crate::error::CliError; + +/// The terminal filter `--verbose` turns on. +/// +/// Scoped to the Atomic crates on purpose: a bare `debug` also unleashes +/// `reqwest`/`hyper` wire logging, which buries the one line the user wanted. +/// +/// `atomic` is a prefix match, so it covers this binary (whose module paths +/// are `atomic::…`, after the `[[bin]]` name rather than the `atomic-cli` +/// package) along with every `atomic_*` library crate. `atomic_core` is pegged +/// back to `info`: its per-vertex graph logging is far below the level anyone +/// reaching for `--verbose` is asking about. +const VERBOSE_FILTER: &str = "atomic=debug,atomic_core=info"; + +/// The terminal filter without `--verbose` or `RUST_LOG`. +const TERMINAL_FILTER: &str = "warn"; + +/// Targets written for the log file. `--verbose` keeps them off the +/// terminal, where a large import's lines would bury the ones it is for. +/// (Targets match by string prefix, so neither may prefix a module path.) +const FILE_ONLY_TARGETS: &str = "atomic::logging::command=warn,atomic::git::import=warn"; + +/// Crates that log through `tracing` itself. Nothing collected their events +/// under `env_logger`, so they stay off the terminal unless `RUST_LOG` asks. +const TRACING_NATIVE_DEPENDENCIES: &str = "h2=off,hyper=off,hyper_util=off"; + +/// The file filter without `ATOMIC_LOG`: `info` from Atomic's crates and +/// warnings from everything else, so dependencies' own chatter stays out. +const FILE_FILTER: &str = "warn,atomic=info"; + +/// A command's start and finish. +const COMMAND_TARGET: &str = "atomic::logging::command"; + +/// Panics are logged under this target for the file only: the panic hook +/// already prints them on the terminal. +const PANIC_TARGET: &str = "atomic::panic"; + +const LOG_FILE_PREFIX: &str = "atomic"; +const LOG_FILE_SUFFIX: &str = "log"; + +/// Daily files kept, today's included. +const KEPT_LOG_FILES: usize = 7; + +type BoxedLayer = Box + Send + Sync>; + +/// Install logging for this process. Call once, before anything logs. +pub(crate) fn init() { + let mut layers = vec![terminal_layer()]; + let mut unusable = None; + let mut opened = None; + if let Some((directives, dir)) = file_settings() { + match open_file(dir.path()) { + Ok(appender) => { + layers.push(file_layer(appender, &directives)); + opened = Some(dir); + } + Err(error) => unusable = Some((dir, error)), + } + } + if tracing_subscriber::registry() + .with(layers) + .try_init() + .is_err() + { + return; + } + log_panics(); + if let Some((dir, error)) = unusable { + report_unusable(&dir, &error); + } + if let Some(dir) = opened { + prune_old_files(dir.path()); + } +} + +/// A command's run in the log: every line inside it carries +/// `atomic{cmd=git import}`, and its start and end are logged. +pub(crate) struct CommandLog { + _span: tracing::span::EnteredSpan, +} + +impl CommandLog { + pub(crate) fn start(matches: &clap::ArgMatches) -> Self { + let span = tracing::info_span!("atomic", cmd = %command_path(matches)).entered(); + let cwd = std::env::current_dir() + .map(|dir| dir.display().to_string()) + .unwrap_or_default(); + tracing::info!( + target: COMMAND_TARGET, + version = env!("CARGO_PKG_VERSION"), + cwd = %cwd, + "command started" + ); + Self { _span: span } + } + + /// Log the outcome. The span closes when `self` drops here, logging how + /// long the command took. URLs in the error lose their credentials. + pub(crate) fn finish(self, error: Option<&CliError>) { + match error { + None => tracing::info!(target: COMMAND_TARGET, outcome = %"ok", "command finished"), + Some(error) => tracing::info!( + target: COMMAND_TARGET, + outcome = %"error", + exit_code = error.exit_code(), + error = %redact::urls(&error.to_string()), + "command finished" + ), + } + } +} + +/// Detect the global `--verbose` flag straight from `argv`. +/// +/// Logging has to be live before clap runs, because argument parsing itself +/// can fail and we want the debug trail for that too. `--verbose` is a global +/// flag, so its position is unconstrained — scanning argv is both simpler and +/// more faithful than trying to parse twice. +fn verbose_requested() -> bool { + std::env::args_os().any(|a| a == "-v" || a == "--verbose") +} + +/// The terminal's filter: `RUST_LOG` wins, then `--verbose`, then warnings. +/// Every command advertises `-v, --verbose`, and the debug lines that explain +/// which identity a request authenticated as are only reachable through it. +/// Like `env_logger`, a `RUST_LOG` with no usable directive shows errors +/// rather than nothing. +fn terminal_directives(rust_log: Option, verbose: bool) -> String { + let directives = match rust_log.filter(|value| !value.trim().is_empty()) { + Some(value) if parses(&value) => value, + Some(_) => "error".to_string(), + None if verbose => { + format!("{VERBOSE_FILTER},{FILE_ONLY_TARGETS},{TRACING_NATIVE_DEPENDENCIES}") + } + None => format!("{TERMINAL_FILTER},{TRACING_NATIVE_DEPENDENCIES}"), + }; + format!("{directives},{PANIC_TARGET}=off") +} + +fn parses(directives: &str) -> bool { + directives + .split(',') + .any(|directive| !directive.trim().is_empty()) + && EnvFilter::builder().parse(directives).is_ok() +} + +/// The file's filter from `ATOMIC_LOG`, or `None` when it is `off`. +fn file_directives(atomic_log: Option) -> Option { + match atomic_log.map(|value| value.trim().to_string()) { + Some(value) if value.eq_ignore_ascii_case("off") => None, + Some(value) if !value.is_empty() => Some(value), + _ => Some(FILE_FILTER.to_string()), + } +} + +/// Where the log file goes, and whether the user chose it. +#[derive(Debug, PartialEq, Eq)] +enum LogDir { + /// `ATOMIC_LOG_DIR`: failing to open it is worth a warning. + Chosen(PathBuf), + /// Under the global config dir. Failing quietly keeps a read-only home + /// from putting a warning on every command. + Default(PathBuf), +} + +impl LogDir { + fn path(&self) -> &Path { + match self { + Self::Chosen(path) | Self::Default(path) => path, + } + } +} + +fn log_dir(chosen: Option, config_dir: Option) -> Option { + match chosen.filter(|dir| !dir.is_empty()) { + Some(dir) => Some(LogDir::Chosen(PathBuf::from(dir))), + None => config_dir + .filter(|dir| !dir.as_os_str().is_empty()) + .map(|dir| LogDir::Default(dir.join("logs"))), + } +} + +fn file_settings() -> Option<(String, LogDir)> { + let directives = file_directives(std::env::var("ATOMIC_LOG").ok())?; + let dir = log_dir( + std::env::var_os("ATOMIC_LOG_DIR"), + atomic_config::global_config_dir(), + )?; + Some((directives, dir)) +} + +/// The command path clap matched, such as `git import`. +fn command_path(matches: &clap::ArgMatches) -> String { + let mut names = Vec::new(); + let mut current = matches; + while let Some((name, sub)) = current.subcommand() { + names.push(name); + current = sub; + } + names.join(" ") +} + +fn terminal_layer() -> BoxedLayer { + let directives = terminal_directives(std::env::var("RUST_LOG").ok(), verbose_requested()); + tracing_subscriber::fmt::layer() + .with_writer(std::io::stderr) + .event_format(terminal::EnvLoggerFormat) + .with_filter(EnvFilter::builder().parse_lossy(directives)) + .boxed() +} + +/// Why the log file could not be opened. +#[derive(Debug)] +enum OpenError { + /// A relative directory would land in whatever directory the command + /// runs in, usually a repository. + Relative, + Create(std::io::Error), + Init(InitError), +} + +impl fmt::Display for OpenError { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + match self { + Self::Relative => f.write_str("not an absolute path"), + Self::Create(error) => write!(f, "{error}"), + Self::Init(error) => write!(f, "{error}"), + } + } +} + +fn open_file(dir: &Path) -> Result { + if !dir.is_absolute() { + return Err(OpenError::Relative); + } + create_private_dir(dir).map_err(OpenError::Create)?; + RollingFileAppender::builder() + .rotation(Rotation::DAILY) + .filename_prefix(LOG_FILE_PREFIX) + .filename_suffix(LOG_FILE_SUFFIX) + .build(dir) + .map_err(OpenError::Init) +} + +/// Create the log directory readable by its owner only: the file records +/// working directories, paths and error text. An existing directory keeps +/// its permissions. +#[cfg(unix)] +fn create_private_dir(dir: &Path) -> std::io::Result<()> { + use std::os::unix::fs::DirBuilderExt; + std::fs::DirBuilder::new() + .recursive(true) + .mode(0o700) + .create(dir) +} + +#[cfg(not(unix))] +fn create_private_dir(dir: &Path) -> std::io::Result<()> { + std::fs::create_dir_all(dir) +} + +/// The file layer, with a line for each span's duration when it closes. +fn file_layer(appender: RollingFileAppender, directives: &str) -> BoxedLayer { + tracing_subscriber::fmt::layer() + .with_writer(appender) + .with_span_events(FmtSpan::CLOSE) + .event_format(file_format::FileFormat::new()) + .with_filter(EnvFilter::builder().parse_lossy(directives)) + .boxed() +} + +fn report_unusable(dir: &LogDir, error: &OpenError) { + match dir { + LogDir::Chosen(path) => tracing::warn!( + "ATOMIC_LOG_DIR {} is unusable ({error}); file logging is off for this command", + path.display() + ), + LogDir::Default(path) => tracing::debug!( + "log directory {} is unusable ({error}); file logging is off for this command", + path.display() + ), + } +} + +fn prune_old_files(dir: &Path) { + let failures = retention::prune(dir, LOG_FILE_PREFIX, LOG_FILE_SUFFIX, KEPT_LOG_FILES); + for (path, error) in failures { + tracing::debug!("could not remove old log file {}: {error}", path.display()); + } +} + +/// Log panics to the file; the previous hook still prints them. +fn log_panics() { + let previous = std::panic::take_hook(); + std::panic::set_hook(Box::new(move |info| { + tracing::error!(target: PANIC_TARGET, "{info}"); + previous(info); + })); +} + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn rust_log_wins_over_verbose_on_the_terminal() { + assert_eq!( + terminal_directives(Some("atomic_remote=trace".into()), true), + "atomic_remote=trace,atomic::panic=off" + ); + assert_eq!( + terminal_directives(None, true), + "atomic=debug,atomic_core=info,\ + atomic::logging::command=warn,atomic::git::import=warn,\ + h2=off,hyper=off,hyper_util=off,atomic::panic=off" + ); + assert_eq!( + terminal_directives(None, false), + "warn,h2=off,hyper=off,hyper_util=off,atomic::panic=off" + ); + assert_eq!( + terminal_directives(Some(" ".into()), false), + terminal_directives(None, false) + ); + } + + #[test] + fn file_only_targets_do_not_prefix_real_modules() { + let modules = [ + "atomic::commands::git::parallel", + "atomic::logging", + "atomic_core::output", + ]; + for directive in FILE_ONLY_TARGETS.split(',') { + let target = directive.split('=').next().unwrap(); + for module in modules { + assert!(!module.starts_with(target), "{target} prefixes {module}"); + } + } + } + + #[test] + fn an_unusable_rust_log_still_shows_errors() { + for rust_log in ["atomic=loud", ",", " , "] { + assert_eq!( + terminal_directives(Some(rust_log.into()), true), + "error,atomic::panic=off", + "{rust_log:?}" + ); + } + } + + #[test] + fn atomic_log_sets_or_disables_the_file_filter() { + assert_eq!(file_directives(None).as_deref(), Some(FILE_FILTER)); + assert_eq!( + file_directives(Some("".into())).as_deref(), + Some(FILE_FILTER) + ); + assert_eq!(file_directives(Some("off".into())), None); + assert_eq!(file_directives(Some(" OFF ".into())), None); + assert_eq!( + file_directives(Some("atomic::git::import=debug".into())).as_deref(), + Some("atomic::git::import=debug") + ); + } + + #[test] + fn atomic_log_dir_wins_over_the_config_dir() { + let config = Some(PathBuf::from("/home/me/.atomic")); + assert_eq!( + log_dir(Some("/tmp/logs".into()), config.clone()), + Some(LogDir::Chosen(PathBuf::from("/tmp/logs"))) + ); + assert_eq!( + log_dir(None, config.clone()), + Some(LogDir::Default(PathBuf::from("/home/me/.atomic/logs"))) + ); + assert_eq!( + log_dir(Some("".into()), config), + Some(LogDir::Default(PathBuf::from("/home/me/.atomic/logs"))) + ); + assert_eq!(log_dir(None, Some(PathBuf::new())), None); + assert_eq!(log_dir(None, None), None); + } + + #[test] + fn a_relative_log_dir_is_refused() { + let error = open_file(Path::new("logs")).unwrap_err(); + assert!(matches!(error, OpenError::Relative), "{error}"); + } + + #[cfg(unix)] + #[test] + fn a_new_log_dir_is_private() { + use std::os::unix::fs::PermissionsExt; + let home = tempfile::tempdir().unwrap(); + let dir = home.path().join("new").join("logs"); + open_file(&dir).unwrap(); + for created in [home.path().join("new"), dir] { + let mode = std::fs::metadata(&created).unwrap().permissions().mode(); + assert_eq!(mode & 0o777, 0o700, "{}", created.display()); + } + } + + #[test] + fn command_path_names_every_subcommand_level() { + let cli = clap::Command::new("atomic").subcommand( + clap::Command::new("git") + .subcommand(clap::Command::new("import").arg(clap::Arg::new("branch"))), + ); + let matches = cli + .clone() + .try_get_matches_from(["atomic", "git", "import", "main"]) + .unwrap(); + assert_eq!(command_path(&matches), "git import"); + let bare = cli.try_get_matches_from(["atomic"]).unwrap(); + assert_eq!(command_path(&bare), ""); + } +} diff --git a/atomic-cli/src/logging/redact.rs b/atomic-cli/src/logging/redact.rs new file mode 100644 index 00000000..56934be1 --- /dev/null +++ b/atomic-cli/src/logging/redact.rs @@ -0,0 +1,67 @@ +//! Strip credentials from URLs before text reaches the log file. + +/// `text` with every URL's `user:password@`, query and fragment removed. +/// Remote errors name the URL they failed on, and remote URLs can carry +/// credentials in either place. +pub(super) fn urls(text: &str) -> String { + let mut out = String::with_capacity(text.len()); + let mut rest = text; + while let Some(at) = rest.find("://") { + let (before, after) = rest.split_at(at + "://".len()); + out.push_str(before); + let end = after.find(char::is_whitespace).unwrap_or(after.len()); + let (url, tail) = after.split_at(end); + out.push_str(host_and_path(url)); + rest = tail; + } + out.push_str(rest); + out +} + +/// The part of `url` (what follows `scheme://`) before its query or +/// fragment, with any `userinfo@` dropped. +fn host_and_path(url: &str) -> &str { + let url = &url[..host_and_path_end(url)]; + let authority_end = url.find('/').unwrap_or(url.len()); + match url[..authority_end].rfind('@') { + Some(at) => &url[at + 1..], + None => url, + } +} + +fn host_and_path_end(url: &str) -> usize { + url.find(['?', '#']).unwrap_or(url.len()) +} + +#[cfg(test)] +mod tests { + use super::urls; + + #[test] + fn credentials_leave_urls() { + assert_eq!( + urls("Authentication failed for https://alice:s3cret@example.com/org/repo: 401"), + "Authentication failed for https://example.com/org/repo: 401" + ); + assert_eq!( + urls("Failed to connect to remote: https://example.com/api?token=abc&x=1"), + "Failed to connect to remote: https://example.com/api" + ); + assert_eq!( + urls("fetch https://tok@example.com#frag and ssh://git@host/x.git\nthen"), + "fetch https://example.com and ssh://host/x.git\nthen" + ); + } + + #[test] + fn text_without_credentials_is_unchanged() { + for text in [ + "no url here", + "https://example.com/repo failed", + "path a@b/c is not a url", + "", + ] { + assert_eq!(urls(text), text); + } + } +} diff --git a/atomic-cli/src/logging/retention.rs b/atomic-cli/src/logging/retention.rs new file mode 100644 index 00000000..d802c126 --- /dev/null +++ b/atomic-cli/src/logging/retention.rs @@ -0,0 +1,128 @@ +//! Keep the newest few daily log files. + +use std::fs; +use std::io; +use std::path::{Path, PathBuf}; + +/// Delete all but the newest `keep` `.YYYY-MM-DD.` files in +/// `dir`, leaving every other file alone. Several processes can prune at once, +/// so a file that is already gone is not a failure; other failures are +/// returned for the caller to report. +pub(super) fn prune( + dir: &Path, + prefix: &str, + suffix: &str, + keep: usize, +) -> Vec<(PathBuf, io::Error)> { + let entries = match fs::read_dir(dir) { + Ok(entries) => entries, + Err(error) => return vec![(dir.to_path_buf(), error)], + }; + let mut daily: Vec = entries + .filter_map(Result::ok) + .filter(|entry| entry.file_type().is_ok_and(|kind| kind.is_file())) + .map(|entry| entry.path()) + .filter(|path| is_daily_file(path, prefix, suffix)) + .collect(); + // ISO dates sort by name. + daily.sort(); + let excess = daily.len().saturating_sub(keep); + daily + .into_iter() + .take(excess) + .filter_map(|path| match fs::remove_file(&path) { + Ok(()) => None, + Err(error) if error.kind() == io::ErrorKind::NotFound => None, + Err(error) => Some((path, error)), + }) + .collect() +} + +fn is_daily_file(path: &Path, prefix: &str, suffix: &str) -> bool { + let Some(name) = path.file_name().and_then(|name| name.to_str()) else { + return false; + }; + let date = name + .strip_prefix(prefix) + .and_then(|rest| rest.strip_prefix('.')) + .and_then(|rest| rest.strip_suffix(suffix)) + .and_then(|rest| rest.strip_suffix('.')); + date.is_some_and(is_iso_date) +} + +fn is_iso_date(text: &str) -> bool { + text.len() == 10 + && text.bytes().enumerate().all(|(index, byte)| match index { + 4 | 7 => byte == b'-', + _ => byte.is_ascii_digit(), + }) +} + +#[cfg(test)] +mod tests { + use super::*; + + fn names(dir: &Path) -> Vec { + let mut names: Vec = fs::read_dir(dir) + .unwrap() + .map(|entry| entry.unwrap().file_name().to_string_lossy().into_owned()) + .collect(); + names.sort(); + names + } + + #[test] + fn keeps_the_newest_daily_files_and_nothing_else_is_touched() { + let dir = tempfile::tempdir().unwrap(); + for day in 1..=9 { + fs::write(dir.path().join(format!("atomic.2026-09-{day:02}.log")), "").unwrap(); + } + for other in [ + "notes.txt", + "atomic.log", + "atomic.2026-9-1.log", + "other.2026-09-01.log", + ] { + fs::write(dir.path().join(other), "").unwrap(); + } + fs::create_dir(dir.path().join("atomic.2026-08-01.log")).unwrap(); + + let failures = prune(dir.path(), "atomic", "log", 7); + + assert!(failures.is_empty(), "{failures:?}"); + let expected: Vec = [ + "atomic.2026-08-01.log", + "atomic.2026-09-03.log", + "atomic.2026-09-04.log", + "atomic.2026-09-05.log", + "atomic.2026-09-06.log", + "atomic.2026-09-07.log", + "atomic.2026-09-08.log", + "atomic.2026-09-09.log", + "atomic.2026-9-1.log", + "atomic.log", + "notes.txt", + "other.2026-09-01.log", + ] + .map(String::from) + .to_vec(); + assert_eq!(names(dir.path()), expected); + } + + #[test] + fn fewer_files_than_kept_is_a_no_op() { + let dir = tempfile::tempdir().unwrap(); + fs::write(dir.path().join("atomic.2026-09-28.log"), "").unwrap(); + assert!(prune(dir.path(), "atomic", "log", 7).is_empty()); + assert_eq!(names(dir.path()), ["atomic.2026-09-28.log"]); + } + + #[test] + fn a_missing_directory_is_reported() { + let dir = tempfile::tempdir().unwrap(); + let missing = dir.path().join("missing"); + let failures = prune(&missing, "atomic", "log", 7); + assert_eq!(failures.len(), 1); + assert_eq!(failures[0].0, missing); + } +} diff --git a/atomic-cli/src/logging/terminal.rs b/atomic-cli/src/logging/terminal.rs new file mode 100644 index 00000000..b8381c69 --- /dev/null +++ b/atomic-cli/src/logging/terminal.rs @@ -0,0 +1,106 @@ +//! The terminal line format `env_logger` used: `[time LEVEL target] message`. + +use std::fmt; + +use tracing::{Event, Level, Subscriber}; +use tracing_log::NormalizeEvent; +use tracing_subscriber::fmt::format::Writer; +use tracing_subscriber::fmt::time::{FormatTime, SystemTime}; +use tracing_subscriber::fmt::{FmtContext, FormatEvent, FormatFields}; +use tracing_subscriber::registry::LookupSpan; + +/// `[2026-09-28T10:00:00.000000Z WARN atomic::commands::git] message`, with +/// the level colored when stderr takes colors. Spans are left out: this line +/// is for the person at the terminal, and the log file carries them. +pub(super) struct EnvLoggerFormat; + +impl FormatEvent for EnvLoggerFormat +where + S: Subscriber + for<'a> LookupSpan<'a>, + N: for<'a> FormatFields<'a> + 'static, +{ + fn format_event( + &self, + ctx: &FmtContext<'_, S, N>, + mut writer: Writer<'_>, + event: &Event<'_>, + ) -> fmt::Result { + // Records from the `log` macros carry their real level and target + // in the normalized metadata. + let normalized = event.normalized_metadata(); + let metadata = normalized.as_ref().unwrap_or_else(|| event.metadata()); + write!(writer, "[")?; + SystemTime.format_time(&mut writer)?; + write!( + writer, + " {} {}] ", + level_label(metadata.level()), + metadata.target() + )?; + ctx.field_format().format_fields(writer.by_ref(), event)?; + writeln!(writer) + } +} + +/// The level padded to five columns, in `env_logger`'s colors. +fn level_label(level: &Level) -> console::StyledObject { + let style = match *level { + Level::ERROR => console::Style::new().red(), + Level::WARN => console::Style::new().yellow(), + Level::INFO => console::Style::new().green(), + Level::DEBUG => console::Style::new().blue(), + Level::TRACE => console::Style::new().cyan(), + }; + style + .for_stderr() + .apply_to(format!("{:<5}", level.as_str())) +} + +#[cfg(test)] +mod tests { + use std::io; + use std::sync::{Arc, Mutex}; + + use tracing_subscriber::layer::SubscriberExt; + + use super::*; + + #[derive(Clone, Default)] + struct Captured(Arc>>); + + impl io::Write for Captured { + fn write(&mut self, bytes: &[u8]) -> io::Result { + self.0.lock().unwrap().extend_from_slice(bytes); + Ok(bytes.len()) + } + + fn flush(&mut self) -> io::Result<()> { + Ok(()) + } + } + + #[test] + fn lines_keep_env_loggers_shape_without_spans() { + let captured = Captured::default(); + let writer = captured.clone(); + let subscriber = tracing_subscriber::registry().with( + tracing_subscriber::fmt::layer() + .with_writer(move || writer.clone()) + .event_format(EnvLoggerFormat), + ); + tracing::subscriber::with_default(subscriber, || { + let _span = tracing::info_span!("atomic", cmd = "git import").entered(); + tracing::warn!(target: "atomic::commands::git", paths = 3, "disk is full"); + }); + + let bytes = captured.0.lock().unwrap().clone(); + let line = console::strip_ansi_codes(std::str::from_utf8(&bytes).unwrap()).into_owned(); + assert!(line.starts_with('['), "{line}"); + assert!( + line.ends_with(" WARN atomic::commands::git] disk is full paths=3\n"), + "{line}" + ); + assert!(!line.contains("git import"), "{line}"); + assert_eq!(line.lines().count(), 1, "{line}"); + } +} diff --git a/atomic-cli/src/main.rs b/atomic-cli/src/main.rs index 7dcb9509..3fa9d90f 100644 --- a/atomic-cli/src/main.rs +++ b/atomic-cli/src/main.rs @@ -58,6 +58,7 @@ mod agent_error; mod commands; mod error; +mod logging; mod output; use clap::{CommandFactory, FromArgMatches, Parser, Subcommand}; @@ -928,47 +929,6 @@ enum Commands { // Main Entry Point -/// The log filter `--verbose` turns on. -/// -/// Scoped to the Atomic crates on purpose: a bare `debug` also unleashes -/// `reqwest`/`hyper` wire logging, which buries the one line the user wanted. -/// -/// `atomic` is a prefix match, so it covers this binary (whose module paths -/// are `atomic::…`, after the `[[bin]]` name rather than the `atomic-cli` -/// package) along with every `atomic_*` library crate. `atomic_core` is pegged -/// back to `info`: its per-vertex graph logging is far below the level anyone -/// reaching for `--verbose` is asking about. -const VERBOSE_FILTER: &str = "atomic=debug,atomic_core=info"; - -/// Detect the global `--verbose` flag straight from `argv`. -/// -/// Logging has to be live before clap runs, because argument parsing itself -/// can fail and we want the debug trail for that too. `--verbose` is a global -/// flag, so its position is unconstrained — scanning argv is both simpler and -/// more faithful than trying to parse twice. -fn verbose_requested() -> bool { - std::env::args_os().any(|a| a == "-v" || a == "--verbose") -} - -/// Install the logger, honouring `--verbose`. -/// -/// Every command advertises `-v, --verbose Emit extra diagnostic output`, but -/// the flag was parsed into a field nothing ever read: logging was initialised -/// before parsing and only `RUST_LOG` could raise the level. The debug lines -/// that explain *which identity a request authenticated as* already existed — -/// they were simply unreachable through the documented flag, which turned an -/// identity misconfiguration into an opaque server-side 401. -/// -/// `RUST_LOG` still wins when set, so existing workflows are untouched. -fn init_logging() { - let default = if verbose_requested() { - VERBOSE_FILTER - } else { - "warn" - }; - env_logger::Builder::from_env(env_logger::Env::default().default_filter_or(default)).init(); -} - fn main() { // Unix CLI convention: a closed downstream pipe is a silent exit, not a // Rust panic. Shells routinely run `atomic … | head`/`awk` pipelines that @@ -981,7 +941,7 @@ fn main() { } // Initialize logging - init_logging(); + logging::init(); // Dynamic shell completion. When invoked in completion mode (the `COMPLETE` // env var is set by the installed shell hook), this emits candidates — @@ -1010,6 +970,8 @@ fn main() { Err(err) => agent_error::render_and_exit(err, &cmd, &args), }; + let command_log = logging::CommandLog::start(&matches); + // Configure color output if cli.no_color { // Disable colors globally @@ -1110,6 +1072,8 @@ fn main() { Commands::Triage(triage) => triage.run(), }; + command_log.finish(result.as_ref().err()); + // Handle errors with user-friendly output if let Err(err) = result { print_error(&err.to_string()); diff --git a/atomic-cli/tests/logging_integration_test.rs b/atomic-cli/tests/logging_integration_test.rs new file mode 100644 index 00000000..f38d2137 --- /dev/null +++ b/atomic-cli/tests/logging_integration_test.rs @@ -0,0 +1,290 @@ +//! Process-level coverage for the CLI log file. +//! +//! Every command writes `info` and above to a daily file under the global +//! config directory, one line per event, each naming the process and the +//! spans it ran in. The terminal keeps showing warnings only, as it did +//! before, and `--verbose` still shows the `log` macros' debug lines. + +use std::ffi::OsStr; +use std::fs; +use std::path::{Path, PathBuf}; +use std::process::{Command, Output}; + +const ATOMIC_BIN: &str = env!("CARGO_BIN_EXE_atomic"); + +/// Run `atomic` in `dir` with an isolated config dir (`home/.atomic`) and a +/// clean logging environment, plus `envs`. `ATOMIC_CONFIG_DIR` rather than +/// `HOME` alone: on Windows the home directory ignores `HOME`. +fn atomic(dir: &Path, home: &Path, envs: &[(&str, &OsStr)], args: &[&str]) -> Output { + let mut command = Command::new(ATOMIC_BIN); + command + .args(args) + .current_dir(dir) + .env("HOME", home) + .env("ATOMIC_CONFIG_DIR", home.join(".atomic")) + .env_remove("ATOMIC_LOG") + .env_remove("ATOMIC_LOG_DIR") + .env_remove("RUST_LOG"); + for (key, value) in envs { + command.env(key, value); + } + command.output().expect("run atomic") +} + +fn git(dir: &Path, args: &[&str]) -> String { + let output = Command::new("git") + .args(args) + .current_dir(dir) + .env("GIT_AUTHOR_NAME", "Logging Tests") + .env("GIT_AUTHOR_EMAIL", "logging@example.com") + .env("GIT_COMMITTER_NAME", "Logging Tests") + .env("GIT_COMMITTER_EMAIL", "logging@example.com") + .output() + .expect("run git"); + assert!(output.status.success(), "git {args:?}: {output:?}"); + String::from_utf8(output.stdout).unwrap().trim().to_string() +} + +fn default_log_dir(home: &Path) -> PathBuf { + home.join(".atomic").join("logs") +} + +/// The daily log files in `dir`: `atomic.YYYY-MM-DD.log`. +fn log_files(dir: &Path) -> Vec { + let Ok(entries) = fs::read_dir(dir) else { + return Vec::new(); + }; + let mut files: Vec = entries + .map(|entry| entry.unwrap().path()) + .filter(|path| { + let name = path.file_name().unwrap().to_string_lossy(); + name.starts_with("atomic.") && name.ends_with(".log") + }) + .collect(); + files.sort(); + files +} + +fn log_text(dir: &Path) -> String { + log_files(dir) + .iter() + .map(|path| fs::read_to_string(path).unwrap()) + .collect() +} + +fn stderr(output: &Output) -> String { + String::from_utf8_lossy(&output.stderr).into_owned() +} + +#[test] +fn info_goes_to_the_daily_log_file_and_not_to_the_terminal() { + let dir = tempfile::tempdir().unwrap(); + let home = tempfile::tempdir().unwrap(); + + let output = atomic(dir.path(), home.path(), &[], &["init"]); + assert!(output.status.success(), "{output:?}"); + + let files = log_files(&default_log_dir(home.path())); + assert_eq!(files.len(), 1, "one daily file: {files:?}"); + let name = files[0].file_name().unwrap().to_string_lossy().into_owned(); + assert_eq!(name.len(), "atomic.2026-09-28.log".len(), "{name}"); + + let text = log_text(&default_log_dir(home.path())); + assert!( + text.lines().all(|line| line.contains(" pid=")), + "every line names its process:\n{text}" + ); + assert!(text.contains(" INFO "), "{text}"); + assert!(text.contains("atomic{cmd=init}"), "{text}"); + assert!(text.contains("command started"), "{text}"); + assert!(text.contains("command finished"), "{text}"); + assert!(text.contains("outcome=ok"), "{text}"); + + let stderr = stderr(&output); + assert!(!stderr.contains("INFO"), "{stderr}"); + assert!(!stderr.contains("command started"), "{stderr}"); +} + +#[test] +fn a_failing_command_logs_its_error_and_exit_code() { + let dir = tempfile::tempdir().unwrap(); + let home = tempfile::tempdir().unwrap(); + + let output = atomic(dir.path(), home.path(), &[], &["status"]); + assert!(!output.status.success(), "{output:?}"); + let code = output.status.code().unwrap(); + + let text = log_text(&default_log_dir(home.path())); + assert!(text.contains("atomic{cmd=status}"), "{text}"); + assert!(text.contains("outcome=error"), "{text}"); + assert!(text.contains(&format!("exit_code={code}")), "{text}"); +} + +#[test] +fn atomic_log_off_writes_no_file() { + let dir = tempfile::tempdir().unwrap(); + let home = tempfile::tempdir().unwrap(); + + let output = atomic( + dir.path(), + home.path(), + &[("ATOMIC_LOG", OsStr::new("off"))], + &["init"], + ); + assert!(output.status.success(), "{output:?}"); + assert!(!default_log_dir(home.path()).exists()); +} + +#[test] +fn atomic_log_dir_moves_the_file() { + let dir = tempfile::tempdir().unwrap(); + let home = tempfile::tempdir().unwrap(); + let custom = tempfile::tempdir().unwrap(); + let custom_logs = custom.path().join("logs"); + + let output = atomic( + dir.path(), + home.path(), + &[("ATOMIC_LOG_DIR", custom_logs.as_os_str())], + &["init"], + ); + assert!(output.status.success(), "{output:?}"); + assert!(log_text(&custom_logs).contains("atomic{cmd=init}")); + assert!(log_files(&default_log_dir(home.path())).is_empty()); +} + +#[test] +fn atomic_config_dir_moves_the_default_location() { + let dir = tempfile::tempdir().unwrap(); + let home = tempfile::tempdir().unwrap(); + let config = tempfile::tempdir().unwrap(); + + let output = atomic( + dir.path(), + home.path(), + &[("ATOMIC_CONFIG_DIR", config.path().as_os_str())], + &["init"], + ); + assert!(output.status.success(), "{output:?}"); + assert!(log_text(&config.path().join("logs")).contains("atomic{cmd=init}")); +} + +#[test] +fn an_unusable_log_dir_warns_and_the_command_still_runs() { + let dir = tempfile::tempdir().unwrap(); + let home = tempfile::tempdir().unwrap(); + let blocker = home.path().join("not-a-dir"); + fs::write(&blocker, b"file").unwrap(); + let unusable = blocker.join("logs"); + + let output = atomic( + dir.path(), + home.path(), + &[("ATOMIC_LOG_DIR", unusable.as_os_str())], + &["init"], + ); + assert!(output.status.success(), "{output:?}"); + let stderr = stderr(&output); + assert!(stderr.contains("file logging is off"), "{stderr}"); + assert!(stderr.contains(&unusable.display().to_string()), "{stderr}"); +} + +#[test] +fn a_relative_log_dir_warns_and_writes_nothing_into_the_working_tree() { + let dir = tempfile::tempdir().unwrap(); + let home = tempfile::tempdir().unwrap(); + + let output = atomic( + dir.path(), + home.path(), + &[("ATOMIC_LOG_DIR", OsStr::new("logs"))], + &["init"], + ); + assert!(output.status.success(), "{output:?}"); + let stderr = stderr(&output); + assert!(stderr.contains("not an absolute path"), "{stderr}"); + assert!(!dir.path().join("logs").exists()); +} + +#[test] +fn verbose_still_shows_the_log_macros_debug_lines_on_the_terminal() { + let dir = tempfile::tempdir().unwrap(); + let home = tempfile::tempdir().unwrap(); + let init = atomic(dir.path(), home.path(), &[], &["init"]); + assert!(init.status.success(), "{init:?}"); + + let verbose = atomic(dir.path(), home.path(), &[], &["-v", "status"]); + assert!(verbose.status.success(), "{verbose:?}"); + let stderr = stderr(&verbose); + let line = stderr + .lines() + .find(|line| line.contains(" DEBUG atomic_repository::")) + .unwrap_or_else(|| panic!("no debug line from the `log` macros:\n{stderr}")); + assert!(line.starts_with('['), "env_logger's shape: {line}"); + assert!(line.contains("] "), "env_logger's shape: {line}"); + assert!( + !stderr.contains("command started"), + "file-only lines stay off the terminal under -v:\n{stderr}" + ); + + let rust_log = atomic( + dir.path(), + home.path(), + &[("RUST_LOG", OsStr::new("off"))], + &["-v", "status"], + ); + assert!(rust_log.status.success(), "{rust_log:?}"); + assert!( + !stderr_has_debug(&rust_log), + "RUST_LOG wins over -v:\n{}", + String::from_utf8_lossy(&rust_log.stderr) + ); +} + +fn stderr_has_debug(output: &Output) -> bool { + String::from_utf8_lossy(&output.stderr).contains(" DEBUG ") +} + +#[test] +fn git_import_logs_each_commit_inside_its_span() { + let root = tempfile::tempdir().unwrap(); + let home = tempfile::tempdir().unwrap(); + let dir = root.path(); + git(dir, &["init", "-q", "-b", "main"]); + fs::write(dir.join("README.md"), b"readme\n").unwrap(); + git(dir, &["add", "."]); + git(dir, &["commit", "-q", "-m", "first"]); + let first = git(dir, &["rev-parse", "HEAD"]); + fs::write(dir.join("README.md"), b"readme\nmore\n").unwrap(); + git(dir, &["commit", "-q", "-am", "second"]); + let second = git(dir, &["rev-parse", "HEAD"]); + + let output = atomic( + dir, + home.path(), + &[], + &["git", "import", "--all", "--no-vault"], + ); + assert!(output.status.success(), "{output:?}"); + + let text = log_text(&default_log_dir(home.path())); + assert!(text.contains("atomic{cmd=git import}"), "{text}"); + for (n, sha) in [(1, &first), (2, &second)] { + let span = format!("commit{{n={n} of=2 sha={}}}", &sha[..8]); + let in_span = |needle: &str| { + text.lines() + .find(|line| line.contains(&span) && line.contains(needle)) + .unwrap_or_else(|| panic!("no {needle:?} line in {span}:\n{text}")) + .to_string() + }; + assert!(in_span("write ").contains(" INFO ")); + // Each commit reports how long it took when its span closes. + in_span("close time.busy"); + } + assert!( + text.lines() + .any(|line| line.contains("import{") && line.contains("close time.busy")), + "{text}" + ); + assert!(!stderr(&output).contains("INFO"), "{}", stderr(&output)); +} From fdd2192ebc9313c425598d449daaebedfa8a6843 Mon Sep 17 00:00:00 2001 From: Vincent Date: Tue, 29 Sep 2026 14:27:24 -0400 Subject: [PATCH 2/2] feat: log the git shim's decisions, hook evidence and bridge events Add spans to bridge reconcile, switch, import_head, export, verify and pre-push, with the reconcile observation and direction and each switch step. Copy the evidence Git's hooks journal, every consented bridge event, and the CLI's status messages into the log file. None of these change what the commands do or print. --- atomic-cli/README.md | 14 + atomic-cli/src/commands/git/bridge.rs | 32 +++ atomic-cli/src/commands/git/hooks.rs | 84 ++++++ atomic-cli/src/logging/mod.rs | 51 +++- atomic-cli/src/logging/redact.rs | 51 ++-- atomic-cli/src/main.rs | 9 +- atomic-cli/src/output/mod.rs | 7 + atomic-cli/tests/git_shim_logging_test.rs | 260 ++++++++++++++++++ .../src/repository/observability.rs | 15 + 9 files changed, 495 insertions(+), 28 deletions(-) create mode 100644 atomic-cli/tests/git_shim_logging_test.rs diff --git a/atomic-cli/README.md b/atomic-cli/README.md index a3fbd245..842af939 100644 --- a/atomic-cli/README.md +++ b/atomic-cli/README.md @@ -61,6 +61,20 @@ time and process id, then names the command and the spans it ran in: Each span also logs its duration when it closes (`close time.busy=…`). +Besides each crate's own lines, the file carries these targets, which you can +filter on (for example `ATOMIC_LOG=warn,atomic::git::hook=info`): + +| Target | What it records | +|--------|-----------------| +| `atomic::logging::command` | Each command's start (version, cwd) and finish (outcome, exit code, error) | +| `atomic::printed` | The ✓/ℹ/⚠/✗ status messages a command printed for you, at their level (file only) | +| `atomic::git::import` | `git import` progress: per-commit parse/write lines, phase timings, decisions | +| `atomic::git::hook` | The evidence each Git hook journaled: checkouts, ref transactions, rewrites, deferred observations | +| `atomic::bridge::event` | Every bridge event the repository's event journal records (reconcile outcomes, refusals, recoveries, binding transfers), as JSON; like the journal, only once the bridge is enabled or from an explicit bridge command | + +Git bridge operations run in spans too: `reconcile`, `import_head`, `export`, +`verify`, `switch` (with a line per step reached) and `pre_push`. + | Variable | Effect | |----------|--------| | `ATOMIC_LOG` | The file's filter, in `RUST_LOG` syntax (default `warn,atomic=info`); `off` turns the file off | diff --git a/atomic-cli/src/commands/git/bridge.rs b/atomic-cli/src/commands/git/bridge.rs index 36694e96..2ebf44ce 100644 --- a/atomic-cli/src/commands/git/bridge.rs +++ b/atomic-cli/src/commands/git/bridge.rs @@ -921,6 +921,7 @@ pub(crate) fn record_last_bridge_operation(root: &Path) { } } +#[tracing::instrument(name = "reconcile", skip_all, fields(budget = ?budget))] pub(crate) fn reconcile_transaction_budgeted( root: &Path, budget: ReconcileEffectBudget, @@ -1059,6 +1060,13 @@ pub(crate) fn reconcile_transaction_budgeted( return Err(error); } }; + tracing::info!( + view = %current.view, + git_head = %current.git_head, + checkpoint = ?direction, + mapping = ?mapping_outcome.as_ref().map(|(_, decision, _)| decision), + "reconcile observation" + ); // CB-13C F3: whether this run journaled a baseline mapping (a // mutation). Every post-observation terminal outcome must be truthful: // `Refused` promises before-any-mutation, so a run that journaled the @@ -1164,6 +1172,7 @@ pub(crate) fn reconcile_transaction_budgeted( (Some(_), ReconcileDirection::Diverged) => ReconcileDirection::Diverged, (None, direction) => direction, }; + tracing::info!(direction = ?direction, "reconcile direction"); match direction { ReconcileDirection::Neither => { @@ -1359,6 +1368,7 @@ fn switch(target: &str) -> CliResult<()> { ) } +#[tracing::instrument(name = "switch", skip_all, fields(view = target))] fn switch_transaction(root: &Path, target: &str) -> CliResult<()> { let checkpoint = read_workspace_metadata(root)? .ok_or_else(|| git_error("bridge switch requires an existing checkpoint; run 'atomic git bridge reconcile' first"))?; @@ -1381,6 +1391,11 @@ fn switch_transaction(root: &Path, target: &str) -> CliResult<()> { "current Git and Atomic state does not match the bridge checkpoint; reconcile before switching", )); } + tracing::info!( + from = %current.view, + git_head = %current.git_head, + "switch: checkpoint matches; planning the target" + ); let target_state = repo .get_view_info(target) @@ -1390,6 +1405,11 @@ fn switch_transaction(root: &Path, target: &str) -> CliResult<()> { let current_paths = git_head_paths(&git)?; let target_paths = git_branch_paths(&git, target)?; plan_switch_collisions(root, ¤t_paths, &target_paths).map_err(git_error)?; + tracing::info!( + current_paths = current_paths.len(), + target_paths = target_paths.len(), + "switch: no path collisions" + ); let policy = conversion_policy(&git)?; let target_project = repo.project_tree(target, &policy).map_err(|error| { git_error(format!( @@ -1417,6 +1437,7 @@ fn switch_transaction(root: &Path, target: &str) -> CliResult<()> { // target exactly once, verify Atomic considers it clean, then project that // result into Git. The full RFC replaces this with a view-scoped manifest // so Git can be prepared before filesystem mutation. + tracing::info!("switch: materializing the target view"); repo.switch_view(working_copy, target) .map_err(CliError::from)?; let atomic_status = repo @@ -1432,6 +1453,11 @@ fn switch_transaction(root: &Path, target: &str) -> CliResult<()> { let target_tree_oid = write_project_tree(&git, &target_project)?; let target_commit_oid = find_or_create_target_commit(&git, target, target_tree_oid, &target_state)?; + tracing::info!( + tree = %target_tree_oid, + commit = %target_commit_oid, + "switch: target view materialized clean; projecting it to Git" + ); let target_ref = format!("refs/heads/{target}"); update_target_branch(&repo, working_copy, &git, &target_ref, target_commit_oid)?; git.set_head(&target_ref) @@ -1446,6 +1472,7 @@ fn switch_transaction(root: &Path, target: &str) -> CliResult<()> { .read_tree(&target_tree) .and_then(|_| index.write()) .map_err(|error| git_error(format!("cannot reset Git index to target tree: {error}")))?; + tracing::info!(reference = %target_ref, "switch: Git HEAD attached and index reset"); drop(index); drop(target_tree); drop(git); @@ -1650,6 +1677,7 @@ fn import_git_to_atomic(root: &Path) -> CliResult<()> { /// admin files, and never materializes: those are command-boundary effects. /// Every writable open in the path carries the budget so pending recovery /// defers instead of replaying. +#[tracing::instrument(name = "import_head", skip_all, fields(budget = ?budget))] fn import_git_to_atomic_budgeted(root: &Path, budget: ReconcileEffectBudget) -> CliResult<()> { let git = open_git(root)?; let head = observe_head(&git).map_err(observation_error)?; @@ -2178,6 +2206,7 @@ fn operation_layer_verdict( } } +#[tracing::instrument(name = "verify", skip_all)] fn verify() -> CliResult { let root = find_repository_root()?; // CB-13A R2: diagnosis is a read-only observation boundary. Opening for @@ -2397,6 +2426,7 @@ fn verify() -> CliResult { }) } +#[tracing::instrument(name = "verify", skip_all)] fn verify_at(root: &Path) -> CliResult { // CB-13A R2: the same read-only diagnostic boundary as `verify` — the // repository is observed for operation inspection without recovery. @@ -2459,6 +2489,7 @@ pub(crate) fn verify_at_detached_ok(root: &Path) -> CliResult { /// Verify against an already-open repository handle (same-process redb opens /// are exclusive, so callers holding a writable handle must reuse it). +#[tracing::instrument(name = "verify", skip_all)] pub(crate) fn verify_with( repo: &Repository, working_copy: WorkingCopyId, @@ -2708,6 +2739,7 @@ fn require_matching_clean_workspaces<'repo>( Ok((branch, oid, tree)) } +#[tracing::instrument(name = "export", skip_all)] pub(crate) fn project_atomic_to_git( root: &Path, repo: &Repository, diff --git a/atomic-cli/src/commands/git/hooks.rs b/atomic-cli/src/commands/git/hooks.rs index 4358d567..938c107e 100644 --- a/atomic-cli/src/commands/git/hooks.rs +++ b/atomic-cli/src/commands/git/hooks.rs @@ -783,6 +783,7 @@ pub(crate) fn run_pre_push_verification(root: &Path) -> CliResult<()> { /// The exact-OID-bound pre-push verification over caller-supplied stdin /// lines (the hook entry point drains the real stdin; tests inject). +#[tracing::instrument(name = "pre_push", skip_all, fields(proposed = input.lines().count()))] pub(crate) fn run_pre_push_verification_with_input(root: &Path, input: &str) -> CliResult<()> { let root = canonical_root(root)?; @@ -1587,9 +1588,57 @@ fn append_journal_record(root: &Path, record: &T) -> CliResult<()> path.display() )) })?; + log_evidence(record); Ok(()) } +/// Log target of the evidence the hooks journal. +const HOOK_EVIDENCE_LOG_TARGET: &str = "atomic::git::hook"; + +/// Items of a logged evidence list; a first fetch can move thousands of refs. +const LOGGED_EVIDENCE_ITEMS: usize = 20; + +/// Log one journaled record without the fields every record repeats (the +/// fixed interpretation text, the format version, and the worktree root the +/// command's `cwd` already names), without its capture token, which +/// authenticates operation linkage, and with long lists cut short. +fn log_evidence(record: &T) { + if !tracing::enabled!(target: HOOK_EVIDENCE_LOG_TARGET, tracing::Level::INFO) { + return; + } + let Ok(serde_json::Value::Object(fields)) = serde_json::to_value(record) else { + return; + }; + tracing::info!( + target: HOOK_EVIDENCE_LOG_TARGET, + evidence = %serde_json::Value::Object(loggable_evidence(fields)), + "journaled Git hook evidence" + ); +} + +fn loggable_evidence( + mut fields: serde_json::Map, +) -> serde_json::Map { + for repeated in ["interpretation", "version", "worktree_root"] { + fields.remove(repeated); + } + if fields.remove("capture_token").is_some() { + fields.insert("capture_token_present".into(), true.into()); + } + let long_lists: Vec<(String, usize)> = fields + .iter() + .filter_map(|(name, value)| value.as_array().map(|items| (name.clone(), items.len()))) + .filter(|(_, len)| *len > LOGGED_EVIDENCE_ITEMS) + .collect(); + for (name, len) in long_lists { + if let Some(serde_json::Value::Array(items)) = fields.get_mut(&name) { + items.truncate(LOGGED_EVIDENCE_ITEMS); + } + fields.insert(format!("{name}_total"), len.into()); + } + fields +} + fn write_immutable_json(path: &Path, value: &T) -> CliResult<()> { let mut bytes = serde_json::to_vec(value) .map_err(|error| git_error(format!("cannot encode deferred request: {error}")))?; @@ -1815,6 +1864,41 @@ mod tests { const OLD: &str = "1111111111111111111111111111111111111111"; const NEW: &str = "2222222222222222222222222222222222222222"; + #[test] + fn logged_evidence_drops_the_capture_token_and_caps_long_lists() { + let refs: Vec = (0..25) + .map(|index| serde_json::json!({ "ref_name": format!("refs/heads/b{index}") })) + .collect(); + let serde_json::Value::Object(fields) = serde_json::json!({ + "version": 1, + "record_type": "post-rewrite", + "interpretation": "fixed text", + "worktree_root": "/repo", + "capture_token": "ab".repeat(32), + "transactions": refs, + }) else { + unreachable!() + }; + let logged = loggable_evidence(fields); + let mut keys: Vec<&str> = logged.keys().map(String::as_str).collect(); + keys.sort_unstable(); + assert_eq!( + keys, + [ + "capture_token_present", + "record_type", + "transactions", + "transactions_total" + ] + ); + assert_eq!(logged["capture_token_present"], true); + assert_eq!(logged["transactions"].as_array().unwrap().len(), 20); + assert_eq!(logged["transactions_total"], 25); + assert!(!serde_json::Value::Object(logged) + .to_string() + .contains("abab")); + } + #[test] fn dispatcher_uses_absolute_binary_and_keeps_every_failure_advisory() { let script = diff --git a/atomic-cli/src/logging/mod.rs b/atomic-cli/src/logging/mod.rs index 9aad622d..6909b545 100644 --- a/atomic-cli/src/logging/mod.rs +++ b/atomic-cli/src/logging/mod.rs @@ -51,7 +51,8 @@ const TERMINAL_FILTER: &str = "warn"; /// Targets written for the log file. `--verbose` keeps them off the /// terminal, where a large import's lines would bury the ones it is for. /// (Targets match by string prefix, so neither may prefix a module path.) -const FILE_ONLY_TARGETS: &str = "atomic::logging::command=warn,atomic::git::import=warn"; +const FILE_ONLY_TARGETS: &str = "atomic::logging::command=warn,atomic::git::import=warn,\ +atomic::git::hook=warn,atomic::bridge::event=warn"; /// Crates that log through `tracing` itself. Nothing collected their events /// under `env_logger`, so they stay off the terminal unless `RUST_LOG` asks. @@ -68,6 +69,11 @@ const COMMAND_TARGET: &str = "atomic::logging::command"; /// already prints them on the terminal. const PANIC_TARGET: &str = "atomic::panic"; +/// The messages the CLI printed for the user, copied into the file so it +/// shows what each command reported. Never on the terminal, which printed +/// them already. +const PRINTED_TARGET: &str = "atomic::printed"; + const LOG_FILE_PREFIX: &str = "atomic"; const LOG_FILE_SUFFIX: &str = "log"; @@ -143,6 +149,32 @@ impl CommandLog { } } +/// How a message was printed for the user. +#[derive(Debug, Clone, Copy)] +pub(crate) enum Printed { + Success, + Info, + Warning, + Error, +} + +/// Copy a message the CLI printed for the user into the log file, at the +/// level it was printed at, so `ATOMIC_LOG=warn` keeps the warnings and +/// errors. URLs lose their credentials first. +pub(crate) fn printed(kind: Printed, message: &str) { + match kind { + Printed::Error => { + tracing::error!(target: PRINTED_TARGET, ?kind, "{}", redact::urls(message)) + } + Printed::Warning => { + tracing::warn!(target: PRINTED_TARGET, ?kind, "{}", redact::urls(message)) + } + Printed::Success | Printed::Info => { + tracing::info!(target: PRINTED_TARGET, ?kind, "{}", redact::urls(message)) + } + } +} + /// Detect the global `--verbose` flag straight from `argv`. /// /// Logging has to be live before clap runs, because argument parsing itself @@ -167,7 +199,7 @@ fn terminal_directives(rust_log: Option, verbose: bool) -> String { } None => format!("{TERMINAL_FILTER},{TRACING_NATIVE_DEPENDENCIES}"), }; - format!("{directives},{PANIC_TARGET}=off") + format!("{directives},{PANIC_TARGET}=off,{PRINTED_TARGET}=off") } fn parses(directives: &str) -> bool { @@ -339,17 +371,18 @@ mod tests { fn rust_log_wins_over_verbose_on_the_terminal() { assert_eq!( terminal_directives(Some("atomic_remote=trace".into()), true), - "atomic_remote=trace,atomic::panic=off" + "atomic_remote=trace,atomic::panic=off,atomic::printed=off" ); assert_eq!( terminal_directives(None, true), "atomic=debug,atomic_core=info,\ atomic::logging::command=warn,atomic::git::import=warn,\ - h2=off,hyper=off,hyper_util=off,atomic::panic=off" + atomic::git::hook=warn,atomic::bridge::event=warn,\ + h2=off,hyper=off,hyper_util=off,atomic::panic=off,atomic::printed=off" ); assert_eq!( terminal_directives(None, false), - "warn,h2=off,hyper=off,hyper_util=off,atomic::panic=off" + "warn,h2=off,hyper=off,hyper_util=off,atomic::panic=off,atomic::printed=off" ); assert_eq!( terminal_directives(Some(" ".into()), false), @@ -361,10 +394,14 @@ mod tests { fn file_only_targets_do_not_prefix_real_modules() { let modules = [ "atomic::commands::git::parallel", + "atomic::commands::git::hooks", "atomic::logging", + "atomic::output::colors", "atomic_core::output", + "atomic_repository::repository::observability", ]; - for directive in FILE_ONLY_TARGETS.split(',') { + let file_only = format!("{FILE_ONLY_TARGETS},{PANIC_TARGET}=off,{PRINTED_TARGET}=off"); + for directive in file_only.split(',') { let target = directive.split('=').next().unwrap(); for module in modules { assert!(!module.starts_with(target), "{target} prefixes {module}"); @@ -377,7 +414,7 @@ mod tests { for rust_log in ["atomic=loud", ",", " , "] { assert_eq!( terminal_directives(Some(rust_log.into()), true), - "error,atomic::panic=off", + "error,atomic::panic=off,atomic::printed=off", "{rust_log:?}" ); } diff --git a/atomic-cli/src/logging/redact.rs b/atomic-cli/src/logging/redact.rs index 56934be1..3f159ac0 100644 --- a/atomic-cli/src/logging/redact.rs +++ b/atomic-cli/src/logging/redact.rs @@ -1,8 +1,10 @@ //! Strip credentials from URLs before text reaches the log file. -/// `text` with every URL's `user:password@`, query and fragment removed. -/// Remote errors name the URL they failed on, and remote URLs can carry -/// credentials in either place. +/// `text` with every URL's credentials removed: everything up to the last +/// `@` becomes `***@`, and the query and fragment are dropped. Remote errors +/// name the URL they failed on, remote URLs can carry credentials in either +/// place, and an "invalid URL" error may quote one too malformed to parse, +/// so this over-redacts rather than parsing. pub(super) fn urls(text: &str) -> String { let mut out = String::with_capacity(text.len()); let mut rest = text; @@ -11,26 +13,27 @@ pub(super) fn urls(text: &str) -> String { out.push_str(before); let end = after.find(char::is_whitespace).unwrap_or(after.len()); let (url, tail) = after.split_at(end); - out.push_str(host_and_path(url)); + push_redacted(&mut out, url); rest = tail; } out.push_str(rest); out } -/// The part of `url` (what follows `scheme://`) before its query or -/// fragment, with any `userinfo@` dropped. -fn host_and_path(url: &str) -> &str { - let url = &url[..host_and_path_end(url)]; - let authority_end = url.find('/').unwrap_or(url.len()); - match url[..authority_end].rfind('@') { - Some(at) => &url[at + 1..], +/// Push `url` (what follows `scheme://`, up to whitespace) without its +/// credentials. +fn push_redacted(out: &mut String, url: &str) { + let host_and_rest = match url.rfind('@') { + Some(at) => { + out.push_str("***@"); + &url[at + 1..] + } None => url, - } -} - -fn host_and_path_end(url: &str) -> usize { - url.find(['?', '#']).unwrap_or(url.len()) + }; + let end = host_and_rest + .find(['?', '#']) + .unwrap_or(host_and_rest.len()); + out.push_str(&host_and_rest[..end]); } #[cfg(test)] @@ -41,7 +44,7 @@ mod tests { fn credentials_leave_urls() { assert_eq!( urls("Authentication failed for https://alice:s3cret@example.com/org/repo: 401"), - "Authentication failed for https://example.com/org/repo: 401" + "Authentication failed for https://***@example.com/org/repo: 401" ); assert_eq!( urls("Failed to connect to remote: https://example.com/api?token=abc&x=1"), @@ -49,7 +52,19 @@ mod tests { ); assert_eq!( urls("fetch https://tok@example.com#frag and ssh://git@host/x.git\nthen"), - "fetch https://example.com and ssh://host/x.git\nthen" + "fetch https://***@example.com and ssh://***@host/x.git\nthen" + ); + } + + #[test] + fn malformed_urls_still_lose_their_credentials() { + assert_eq!( + urls("invalid URL https://alice:s3c?ret@host/r"), + "invalid URL https://***@host/r" + ); + assert_eq!( + urls("invalid URL https://alice:p/ss@host/x"), + "invalid URL https://***@host/x" ); } diff --git a/atomic-cli/src/main.rs b/atomic-cli/src/main.rs index 3fa9d90f..9f49d7d6 100644 --- a/atomic-cli/src/main.rs +++ b/atomic-cli/src/main.rs @@ -1072,10 +1072,8 @@ fn main() { Commands::Triage(triage) => triage.run(), }; - command_log.finish(result.as_ref().err()); - // Handle errors with user-friendly output - if let Err(err) = result { + if let Err(err) = &result { print_error(&err.to_string()); // Print suggestion if available — to STDERR, alongside the error itself, @@ -1085,7 +1083,12 @@ fn main() { eprintln!(); eprintln!("{}", hint(&format!("Hint: {}", suggestion))); } + } + // After the error is printed, so its log copy is inside the command span. + command_log.finish(result.as_ref().err()); + + if let Err(err) = result { // Exit with appropriate code std::process::exit(err.exit_code()); } diff --git a/atomic-cli/src/output/mod.rs b/atomic-cli/src/output/mod.rs index 852a864e..23281253 100644 --- a/atomic-cli/src/output/mod.rs +++ b/atomic-cli/src/output/mod.rs @@ -67,6 +67,9 @@ pub use table::{Alignment, Column, KeyValueTable, Row, Table}; pub use progress::{create_progress_bar, create_spinner, finish_error, finish_success}; // Convenience Print Functions +// +// `print_success`, `print_error`, `print_warning` and `print_info` also copy +// their message into the log file (`crate::logging::printed`). /// Print a success message to stdout. /// @@ -83,6 +86,7 @@ pub use progress::{create_progress_bar, create_spinner, finish_error, finish_suc /// // Output: ✓ Repository initialized successfully! /// ``` pub fn print_success(message: &str) { + crate::logging::printed(crate::logging::Printed::Success, message); println!("{} {}", success("✓"), success(message)); } @@ -101,6 +105,7 @@ pub fn print_success(message: &str) { /// // Output: ✗ Failed to read file /// ``` pub fn print_error(message: &str) { + crate::logging::printed(crate::logging::Printed::Error, message); eprintln!("{} {}", error("✗"), error(message)); } @@ -119,6 +124,7 @@ pub fn print_error(message: &str) { /// // Output: ⚠ File will be overwritten /// ``` pub fn print_warning(message: &str) { + crate::logging::printed(crate::logging::Printed::Warning, message); eprintln!("{} {}", warning("⚠"), warning(message)); } @@ -137,6 +143,7 @@ pub fn print_warning(message: &str) { /// // Output: ℹ Processing 42 files... /// ``` pub fn print_info(message: &str) { + crate::logging::printed(crate::logging::Printed::Info, message); println!("{} {}", info("ℹ"), info(message)); } diff --git a/atomic-cli/tests/git_shim_logging_test.rs b/atomic-cli/tests/git_shim_logging_test.rs new file mode 100644 index 00000000..ba94bb9c --- /dev/null +++ b/atomic-cli/tests/git_shim_logging_test.rs @@ -0,0 +1,260 @@ +//! Process-level coverage for what the git shim writes to the log file: +//! bridge events, the evidence Git's hooks journal, the reconcile and switch +//! spans with their decisions, and the messages each command printed, all +//! inside the command's span. + +use std::fs; +use std::path::{Path, PathBuf}; +use std::process::{Command, Output}; +use std::thread; +use std::time::{Duration, Instant}; + +use tempfile::TempDir; + +const ATOMIC_BIN: &str = env!("CARGO_BIN_EXE_atomic"); + +/// A Git repository with an isolated home. Git passes the environment on to +/// the hooks it runs, so the dispatched `atomic` processes log to the same +/// file. +struct Sandbox { + root: TempDir, + home: TempDir, +} + +impl Sandbox { + fn new() -> Self { + Self { + root: TempDir::new().unwrap(), + home: TempDir::new().unwrap(), + } + } + + fn dir(&self) -> &Path { + self.root.path() + } + + fn command(&self, program: &str) -> Command { + let mut command = Command::new(program); + command + .current_dir(self.dir()) + .env("HOME", self.home.path()) + .env("ATOMIC_CONFIG_DIR", self.home.path().join(".atomic")) + .env("GIT_CONFIG_NOSYSTEM", "1") + .env("GIT_AUTHOR_NAME", "Shim Logging") + .env("GIT_AUTHOR_EMAIL", "shim@example.com") + .env("GIT_COMMITTER_NAME", "Shim Logging") + .env("GIT_COMMITTER_EMAIL", "shim@example.com") + .env_remove("ATOMIC_LOG") + .env_remove("ATOMIC_LOG_DIR") + .env_remove("RUST_LOG"); + command + } + + fn atomic(&self, args: &[&str]) -> Output { + self.command(ATOMIC_BIN) + .args(args) + .output() + .expect("run atomic") + } + + fn atomic_ok(&self, args: &[&str]) -> Output { + let output = self.atomic(args); + assert!(output.status.success(), "atomic {args:?}: {output:?}"); + output + } + + fn git(&self, args: &[&str]) { + let output = self.command("git").args(args).output().expect("run git"); + assert!(output.status.success(), "git {args:?}: {output:?}"); + } + + fn commit(&self, path: &str, content: &str, message: &str) { + fs::write(self.dir().join(path), content).unwrap(); + self.git(&["add", path]); + self.git(&["commit", "-q", "-m", message]); + } + + fn log_dir(&self) -> PathBuf { + self.home.path().join(".atomic").join("logs") + } + + fn log(&self) -> String { + let mut files: Vec = fs::read_dir(self.log_dir()) + .unwrap() + .map(|entry| entry.unwrap().path()) + .collect(); + files.sort(); + files + .iter() + .map(|path| fs::read_to_string(path).unwrap()) + .collect() + } +} + +impl Sandbox { + /// Wait until a log line contains every needle. + fn wait_for_log(&self, needles: &[&str]) { + let deadline = Instant::now() + Duration::from_secs(20); + while Instant::now() < deadline { + let log = self.log(); + if log + .lines() + .any(|line| needles.iter().all(|needle| line.contains(needle))) + { + return; + } + thread::sleep(Duration::from_millis(50)); + } + panic!("no line with {needles:?} in:\n{}", self.log()); + } +} + +/// The first log line containing every needle. +fn line_with<'a>(log: &'a str, needles: &[&str]) -> &'a str { + log.lines() + .find(|line| needles.iter().all(|needle| line.contains(needle))) + .unwrap_or_else(|| panic!("no line with {needles:?} in:\n{log}")) +} + +/// A bridge-enabled repository on `main`, then a commit on `feature` made +/// through Git so its hooks run, reconciled into Atomic. +fn bridged_feature_commit() -> Sandbox { + let sandbox = Sandbox::new(); + sandbox.git(&["init", "-q", "-b", "main"]); + sandbox.commit("a.txt", "a\n", "one"); + sandbox.atomic_ok(&["init"]); + sandbox.atomic_ok(&["git", "import"]); + sandbox.atomic_ok(&["git", "bridge", "enable"]); + + // With -v, whose `atomic=debug` would show an `info` line, so the copy + // stays off the terminal only because its target is file-only. + let aligned = sandbox.atomic_ok(&["-v", "git", "bridge", "reconcile"]); + let stdout = String::from_utf8_lossy(&aligned.stdout); + let stderr = String::from_utf8_lossy(&aligned.stderr); + assert_eq!( + stdout.matches("Git HEAD already matches").count(), + 1, + "printed once: {stdout}" + ); + assert!( + !stderr.contains("Git HEAD already matches"), + "the file copy never reaches the terminal: {stderr}" + ); + + sandbox.git(&["checkout", "-q", "-b", "feature"]); + // post-checkout starts a detached observer; let it finish inside the + // sandbox before going on. + sandbox.wait_for_log(&["cmd=git bridge observe-deferred", "command finished"]); + sandbox.commit("b.txt", "b\n", "two"); + sandbox.atomic_ok(&["git", "bridge", "reconcile"]); + sandbox +} + +#[test] +fn reconcile_logs_its_decision_and_outcome_inside_its_span() { + let sandbox = bridged_feature_commit(); + let log = sandbox.log(); + + // The aligned run: the bridge event, and the message it printed. + line_with( + &log, + &[ + "cmd=git bridge reconcile", + "reconcile{", + "atomic::bridge::event", + r#""event":"reconcile""#, + r#""direction":"neither""#, + r#""outcome":"no_change""#, + ], + ); + line_with( + &log, + &[ + "cmd=git bridge reconcile", + "atomic::printed", + "Git HEAD already matches the current Atomic view", + ], + ); + + // The run after the Git commit: the direction is logged before the + // import runs, and the import happens inside the reconcile span. + line_with( + &log, + &["reconcile{", "reconcile direction", "direction=GitToAtomic"], + ); + line_with(&log, &["reconcile{", "import_head{", "close time.busy"]); + line_with( + &log, + &[ + "reconcile{", + r#""direction":"git_to_atomic""#, + r#""outcome":"applied""#, + ], + ); +} + +#[test] +fn git_hooks_log_the_evidence_they_journal() { + let sandbox = bridged_feature_commit(); + let log = sandbox.log(); + + line_with( + &log, + &[ + "cmd=git bridge hook-post-checkout", + "atomic::git::hook", + r#""record_type":"post-checkout""#, + r#""checkout_kind":"branch""#, + ], + ); + line_with( + &log, + &[ + "cmd=git bridge hook-reference-transaction", + "atomic::git::hook", + r#""state":"committed""#, + "refs/heads/feature", + ], + ); + // The observer post-checkout scheduled logs what it saw of Git. + line_with( + &log, + &[ + "cmd=git bridge observe-deferred", + "atomic::git::hook", + r#""record_type":"deferred-observation""#, + r#""head_kind":"attached""#, + ], + ); + assert!( + !log.contains("ref-movement-only"), + "the fixed interpretation text stays in the journal" + ); +} + +#[test] +fn bridge_switch_logs_the_steps_it_reached() { + let sandbox = bridged_feature_commit(); + // Whatever the outcome, the log shows how far the switch got. + let switched = sandbox.atomic(&["git", "bridge", "switch", "main"]); + let log = sandbox.log(); + + line_with( + &log, + &[ + "cmd=git bridge switch", + r#"switch{view="main"}"#, + "checkpoint matches", + ], + ); + let outcome = if switched.status.success() { + "outcome=ok" + } else { + "outcome=error" + }; + line_with( + &log, + &["cmd=git bridge switch", "command finished", outcome], + ); + line_with(&log, &[r#"switch{view="main"}"#, "close time.busy"]); +} diff --git a/atomic-repository/src/repository/observability.rs b/atomic-repository/src/repository/observability.rs index 3d445433..a9654baf 100644 --- a/atomic-repository/src/repository/observability.rs +++ b/atomic-repository/src/repository/observability.rs @@ -72,6 +72,10 @@ pub const MAX_BRIDGE_EVENT_RECORD_BYTES: usize = 64 * 1024; /// Dot-directory-relative location of the event journal. pub const BRIDGE_EVENT_JOURNAL_RELATIVE_PATH: &str = "bridge/events.jsonl"; +/// Target under which every event past the consent gate also reaches the +/// process log (the `atomic` CLI's log file). +const BRIDGE_EVENT_LOG_TARGET: &str = "atomic::bridge::event"; + /// Bounded nonblocking retry budget for the append lock. Contended writers /// drop the event after this budget instead of blocking bridge operations. const APPEND_LOCK_ATTEMPTS: u32 = 24; @@ -751,6 +755,7 @@ impl BridgeEventJournal { if !self.consented.load(std::sync::atomic::Ordering::Relaxed) { return Ok(()); } + log_event(&kind); // Serialize and bound the record before touching the filesystem: // no oversized allocation or append can happen. let event = BridgeEvent { @@ -949,6 +954,16 @@ impl BridgeEventJournal { } } +/// Copy an event into the process log. It runs after the consent gate, so an +/// un-opted repository's events reach neither the journal nor the log. +fn log_event(kind: &BridgeEventKind) { + if log::log_enabled!(target: BRIDGE_EVENT_LOG_TARGET, log::Level::Info) { + if let Ok(json) = serde_json::to_string(kind) { + log::info!(target: BRIDGE_EVENT_LOG_TARGET, "{json}"); + } + } +} + fn config_mtime_nanos(dot_dir: &Path) -> u64 { std::fs::metadata(dot_dir.join("config.toml")) .and_then(|metadata| metadata.modified())