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..842af939 100644 --- a/atomic-cli/README.md +++ b/atomic-cli/README.md @@ -47,6 +47,40 @@ 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=…`). + +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 | +| `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 +896,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/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/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..6909b545 --- /dev/null +++ b/atomic-cli/src/logging/mod.rs @@ -0,0 +1,490 @@ +//! 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,\ +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. +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"; + +/// 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"; + +/// 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" + ), + } + } +} + +/// 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 +/// 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,{PRINTED_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,atomic::printed=off" + ); + assert_eq!( + terminal_directives(None, true), + "atomic=debug,atomic_core=info,\ + atomic::logging::command=warn,atomic::git::import=warn,\ + 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,atomic::printed=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::commands::git::hooks", + "atomic::logging", + "atomic::output::colors", + "atomic_core::output", + "atomic_repository::repository::observability", + ]; + 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}"); + } + } + } + + #[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,atomic::printed=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..3f159ac0 --- /dev/null +++ b/atomic-cli/src/logging/redact.rs @@ -0,0 +1,82 @@ +//! Strip credentials from URLs before text reaches the log file. + +/// `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; + 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); + push_redacted(&mut out, url); + rest = tail; + } + out.push_str(rest); + out +} + +/// 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, + }; + let end = host_and_rest + .find(['?', '#']) + .unwrap_or(host_and_rest.len()); + out.push_str(&host_and_rest[..end]); +} + +#[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 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" + ); + } + + #[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..9f49d7d6 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 @@ -1111,7 +1073,7 @@ fn main() { }; // 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, @@ -1121,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-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)); +} 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())