diff --git a/CODING_GUIDELINES.md b/CODING_GUIDELINES.md index b7ca9752..f96928a2 100644 --- a/CODING_GUIDELINES.md +++ b/CODING_GUIDELINES.md @@ -287,26 +287,26 @@ info!(voltage = %volts, "Voltage set"); trace!(register = ?reg, "Register read"); ``` -### RUST_LOG Filtering [L.filter](#L.filter) +### Log Filtering [L.filter](#L.filter) -The `RUST_LOG` environment variable provides powerful runtime filtering, -which means you can log liberally without performance concerns: +The `MUJINA_LOG` and `RUST_LOG` environment variables provide powerful +runtime filtering, which means you can log liberally without +performance concerns. `MUJINA_LOG` filters Mujina's own modules, named +as the log output shows them; `RUST_LOG` has its usual Rust meaning +and covers third-party crates: ```bash -# Show only errors from all modules -RUST_LOG=error cargo run +# Debug for all of Mujina; third-party crates stay at warn +MUJINA_LOG=debug cargo run -# Show info and above for entire application -RUST_LOG=info cargo run +# Trace one module; the rest of Mujina stays at its info default +MUJINA_LOG=asic::bm13xx=trace cargo run -# Show trace logging for specific module, info for rest -RUST_LOG=mujina_miner::asic::bm13xx=trace,info cargo run +# Debug one module, trace another +MUJINA_LOG=board::bitaxe=debug,peripheral::tps546=trace cargo run -# Debug one module, trace another, warn for everything else -RUST_LOG=mujina_miner::board::bitaxe=debug,mujina_miner::peripheral::tps546=trace,warn cargo run - -# Multiple specific modules at trace level -RUST_LOG=mujina_miner::asic::bm13xx=trace,mujina_miner::board=trace cargo run +# Trace a third-party crate; Mujina's defaults are unaffected +RUST_LOG=nusb=trace cargo run ``` Disabled log statements have **minimal runtime cost**---just a branch check diff --git a/README.md b/README.md index 6b9d8679..b5a26f0e 100644 --- a/README.md +++ b/README.md @@ -150,20 +150,29 @@ cargo run --bin mujina-minerd ### Controlling log output The default filter emits Mujina log entries at info level and -third-party crates at warn. `RUST_LOG` directives are additive: set -per-module levels to dig into specific subsystems without flooding the -rest of the log. +third-party crates at warn. Two environment variables adjust it. +`MUJINA_LOG` filters Mujina's own modules, named exactly as the log +output shows them, and a bare level applies to Mujina as a whole. +`RUST_LOG` keeps its usual Rust meaning: a directive that names a +crate adds to the defaults, and a bare level takes full control of +the filter. `MUJINA_LOG` wins where the two overlap. ```bash # Default: info for Mujina, warn for third-party crates cargo run --bin mujina-minerd +# Trace all of Mujina, third-party crates stay at warn +MUJINA_LOG=trace cargo run --bin mujina-minerd + # Trace the Stratum v1 client, everything else unchanged -RUST_LOG=mujina_miner::stratum_v1=trace cargo run --bin mujina-minerd +MUJINA_LOG=stratum_v1=trace cargo run --bin mujina-minerd # Debug Stratum v1 and trace BM13xx at the same time -RUST_LOG=mujina_miner::stratum_v1=debug,mujina_miner::asic::bm13xx=trace \ +MUJINA_LOG=stratum_v1=debug,asic::bm13xx=trace \ cargo run --bin mujina-minerd + +# Trace a third-party crate, Mujina's defaults unchanged +RUST_LOG=nusb=trace cargo run --bin mujina-minerd ``` Debug shows logical stages and summaries: chip initialization, jobs diff --git a/docs/cpu-mining.md b/docs/cpu-mining.md index d95b98a6..1f903e15 100644 --- a/docs/cpu-mining.md +++ b/docs/cpu-mining.md @@ -88,7 +88,7 @@ synthetic work: ```bash MUJINA_CPUMINER_THREADS=2 \ MUJINA_USB_DISABLE=1 \ -RUST_LOG=mujina_miner=debug \ +MUJINA_LOG=debug \ cargo run ``` diff --git a/mujina-miner/src/daemon.rs b/mujina-miner/src/daemon.rs index ea916aa0..f14ad225 100644 --- a/mujina-miner/src/daemon.rs +++ b/mujina-miner/src/daemon.rs @@ -279,7 +279,7 @@ impl Daemon { self.tracker.close(); info!("Started."); - info!("For debugging, set RUST_LOG=mujina_miner=debug or trace."); + info!("For debugging, set MUJINA_LOG=debug or trace."); // Install signal handlers let mut sigint = unix::signal(SignalKind::interrupt())?; diff --git a/mujina-miner/src/env_help.rs b/mujina-miner/src/env_help.rs index f46cf92f..7ee08b19 100644 --- a/mujina-miner/src/env_help.rs +++ b/mujina-miner/src/env_help.rs @@ -157,13 +157,26 @@ const GROUPS: &[EnvGroup] = &[ }, EnvGroup { title: "Logging", - vars: &[EnvVar { - name: "RUST_LOG", - summary: "Log filter in tracing-subscriber EnvFilter syntax, appended \ - after the built-in defaults so its directives win.", - default: Some("warn,mujina_miner=info"), - example: Some("mujina_miner=trace"), - }], + vars: &[ + EnvVar { + name: "MUJINA_LOG", + summary: "Log filter for Mujina's own modules, overriding \ + RUST_LOG. Module names are written as the log output \ + shows them, without a crate prefix. A bare level like \ + 'debug' applies to all of Mujina.", + default: None, + example: Some("asic::bm13xx=trace"), + }, + EnvVar { + name: "RUST_LOG", + summary: "Log filter in tracing-subscriber EnvFilter syntax. \ + A directive that names a crate adds to the built-in \ + defaults; a bare level like 'debug' replaces them, \ + as in any Rust program.", + default: Some("warn,mujina_miner=info"), + example: Some("nusb=debug"), + }, + ], }, ]; diff --git a/mujina-miner/src/tracing.rs b/mujina-miner/src/tracing.rs index 42333f0e..821cfc3a 100644 --- a/mujina-miner/src/tracing.rs +++ b/mujina-miner/src/tracing.rs @@ -12,7 +12,7 @@ use time::OffsetDateTime; use tracing::field::{Field, Visit}; use tracing::{Event, Level, Subscriber}; use tracing_subscriber::{ - filter::EnvFilter, + filter::{EnvFilter, LevelFilter}, fmt::{ FmtContext, FormatEvent, FormatFields, format::{DefaultFields, Writer as FmtWriter}, @@ -40,17 +40,66 @@ pub fn init() { /// Default log filter: WARN for third-party crates, INFO for ours. const DEFAULT_LOG_FILTER: &str = "warn,mujina_miner=info"; -/// Build an `EnvFilter` with our defaults, overridable by RUST_LOG. -/// -/// EnvFilter has no API to add default per-target directives -/// that RUST_LOG can override. Build a base string with our -/// defaults and append RUST_LOG so its directives win. +/// Build an `EnvFilter` from the defaults, RUST_LOG, and MUJINA_LOG. fn build_env_filter() -> EnvFilter { - let filter_str = match std::env::var("RUST_LOG") { - Ok(env) => format!("{DEFAULT_LOG_FILTER},{env}"), - Err(_) => DEFAULT_LOG_FILTER.to_string(), + let rust_log = std::env::var("RUST_LOG").ok(); + let mujina_log = std::env::var("MUJINA_LOG").ok(); + filter_string(rust_log.as_deref(), mujina_log.as_deref()) + .parse() + .expect("invalid directive in RUST_LOG or MUJINA_LOG") +} + +/// Combine the built-in defaults, RUST_LOG, and MUJINA_LOG into one +/// EnvFilter directive string. +/// +/// RUST_LOG keeps its ecosystem meaning. A directive that names a +/// target adds to the built-in defaults, so a third-party crate can +/// be traced without repeating the defaults. A bare level +/// takes full control of the filter, as it would in any Rust +/// program; layered on the defaults it would lose to the more +/// specific per-crate default and never reach this crate. +/// +/// MUJINA_LOG holds directives for this crate alone, interpreted +/// relative to the crate root: a bare level applies to the whole +/// crate, and module names are written as the log output displays +/// them, without the crate prefix. Its directives come last, and +/// EnvFilter keeps the later of two directives for the same target, +/// so MUJINA_LOG wins over RUST_LOG and the defaults. +fn filter_string(rust_log: Option<&str>, mujina_log: Option<&str>) -> String { + let rust_log: Vec<&str> = elements(rust_log).collect(); + + let mut directives: Vec = if rust_log.iter().any(|d| is_bare_level(d)) { + Vec::new() + } else { + vec![DEFAULT_LOG_FILTER.to_string()] }; - filter_str.parse().unwrap() + + directives.extend(rust_log.iter().map(|d| d.to_string())); + + for directive in elements(mujina_log) { + if is_bare_level(directive) { + directives.push(format!("mujina_miner={directive}")); + } else { + directives.push(format!("mujina_miner::{directive}")); + } + } + + directives.join(",") +} + +/// Split a filter variable into its comma-separated elements, +/// dropping empties. +fn elements(var: Option<&str>) -> impl Iterator { + var.unwrap_or_default() + .split(',') + .map(str::trim) + .filter(|e| !e.is_empty()) +} + +/// Report whether a directive is a bare level like `debug`, naming +/// no target. +fn is_bare_level(directive: &str) -> bool { + directive.parse::().is_ok() } #[cfg(target_os = "linux")] @@ -291,3 +340,135 @@ impl FormatTime for LocalTimer { ) } } + +#[cfg(test)] +mod tests { + use super::*; + + /// Mujina's own directive within the built-in defaults. + fn default_mujina_directive() -> &'static str { + DEFAULT_LOG_FILTER + .split(',') + .find(|d| d.starts_with("mujina_miner=")) + .expect("defaults contain a miner directive") + } + + #[test] + fn no_variables_use_defaults() { + assert_eq!(filter_string(None, None), DEFAULT_LOG_FILTER); + assert_eq!(filter_string(Some(""), Some("")), DEFAULT_LOG_FILTER); + } + + #[test] + fn bare_mujina_log_level_scopes_to_crate() { + assert_eq!( + filter_string(None, Some("trace")), + format!("{DEFAULT_LOG_FILTER},mujina_miner=trace") + ); + } + + #[test] + fn mujina_log_modules_get_crate_prefix() { + assert_eq!( + filter_string(None, Some("asic::bm13xx=trace,board=debug")), + format!( + "{DEFAULT_LOG_FILTER},mujina_miner::asic::bm13xx=trace,\ + mujina_miner::board=debug" + ) + ); + } + + #[test] + fn named_rust_log_directive_adds_to_defaults() { + assert_eq!( + filter_string(Some("nusb=trace"), None), + format!("{DEFAULT_LOG_FILTER},nusb=trace") + ); + } + + #[test] + fn bare_rust_log_level_takes_full_control() { + assert_eq!(filter_string(Some("trace"), None), "trace"); + assert_eq!( + filter_string(Some("debug,nusb=trace"), None), + "debug,nusb=trace" + ); + } + + #[test] + fn both_variables_combine() { + assert_eq!( + filter_string(Some("nusb=trace"), Some("debug")), + format!("{DEFAULT_LOG_FILTER},nusb=trace,mujina_miner=debug") + ); + // A bare RUST_LOG level takes full control, and MUJINA_LOG + // still carves Mujina out of it. + assert_eq!( + filter_string(Some("trace"), Some("warn")), + "trace,mujina_miner=warn" + ); + } + + #[test] + fn results_parse_as_env_filters() { + let cases = [ + (None, None), + (Some("trace"), None), + (Some("debug,nusb=trace,foo::bar=info"), None), + (None, Some("trace")), + (None, Some("asic::bm13xx=trace,info")), + (Some("nusb=trace"), Some("debug")), + ]; + for (rust_log, mujina_log) in cases { + filter_string(rust_log, mujina_log) + .parse::() + .unwrap(); + } + } + + // A module directive coexists with the crate-wide default rather + // than replacing it: the rest of Mujina keeps its info default. + #[test] + fn module_directive_leaves_crate_default_intact() { + let filter: EnvFilter = filter_string(None, Some("asic::bm13xx=trace")) + .parse() + .unwrap(); + let rendered = format!("{filter}"); + assert!(rendered.contains(default_mujina_directive()), "{rendered}"); + assert!( + rendered.contains("mujina_miner::asic::bm13xx=trace"), + "{rendered}" + ); + } + + // A bare level given alongside a module directive replaces the + // built-in crate default without disturbing the module directive. + #[test] + fn module_directive_and_bare_level_combine() { + let filter: EnvFilter = filter_string(None, Some("asic::bm13xx=trace,warn")) + .parse() + .unwrap(); + let rendered = format!("{filter}"); + assert!(rendered.contains("mujina_miner=warn"), "{rendered}"); + assert!(!rendered.contains(default_mujina_directive()), "{rendered}"); + assert!( + rendered.contains("mujina_miner::asic::bm13xx=trace"), + "{rendered}" + ); + } + + // The layering relies on EnvFilter keeping the later of two + // directives for the same target. Verify against the real + // EnvFilter so an upstream change breaks loudly, including a + // level quieter than the built-in default. + #[test] + fn mujina_log_wins_for_same_target() { + let filter: EnvFilter = filter_string(Some("mujina_miner=debug"), Some("error")) + .parse() + .unwrap(); + let rendered = format!("{filter}"); + assert!(rendered.contains("mujina_miner=error"), "{rendered}"); + assert!(!rendered.contains(default_mujina_directive()), "{rendered}"); + assert!(!rendered.contains("mujina_miner=debug"), "{rendered}"); + } +}