feat(tracing): add MUJINA_LOG filter variable

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

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

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
 ```
 

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())?;

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"),
+            },
+        ],
     },
 ];
 

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<String> = 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<Item = &str> {
+    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::<LevelFilter>().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::<EnvFilter>()
+                .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}");
+    }
+}