Merge PR #340 (CLI logging; the desktop keeps #286's file logger)

apps/lightcraft-cli/src/main.rs

@@ -124,6 +124,9 @@ fn main() -> ExitCode {
         dhat::Profiler::builder().file_name(file).build()
     };
     alloc_release::install();
+    // Warnings (a GPU render redone on the CPU, an unknown backend name) on stderr; LIGHTCRAFT_LOG
+    // or RUST_LOG picks another level (#168).
+    lightcraft_engine::logging::install("lightcraft-cli");
     let args: Vec<String> = std::env::args().skip(1).collect();
     let r = match args.first().map(String::as_str) {
         Some("run") => run(&args[1..]),

apps/lightcraft-cli/tests/cli.rs

@@ -369,3 +369,29 @@ fn connect_failure_hint_names_the_attempted_port() {
     assert!(err.contains("--control 18437"), "the hint must name the port it tried: {err}");
     assert!(!err.contains("--control 7980"), "{err}");
 }
+
+/// The CLI logs warnings on stderr (#168): with `RUST_LOG=warn` an unknown GPU backend name is
+/// reported, and `RUST_LOG=off` silences it. Before, no logger was installed and nothing appeared.
+#[test]
+fn warnings_are_logged_on_stderr() {
+    let input = tmp("log-in.png");
+    gradient_png(&input);
+    let out = tmp("log-out.jpg");
+    let run = |level: &str| {
+        let o = Command::new(BIN)
+            .args(["render", input.to_str().unwrap(), "-o", out.to_str().unwrap()])
+            .env("LIGHTCRAFT_GPU_BACKEND", "bogus")
+            .env("RUST_LOG", level)
+            .env_remove("LIGHTCRAFT_LOG")
+            .env_remove("LIGHTCRAFT_GPU")
+            .output()
+            .unwrap();
+        let stderr = String::from_utf8_lossy(&o.stderr).into_owned();
+        assert!(o.status.success(), "{stderr}");
+        stderr
+    };
+    let warn = run("warn");
+    assert!(warn.contains("LIGHTCRAFT_GPU_BACKEND=bogus names no known backend"), "{warn}");
+    let off = run("off");
+    assert!(!off.contains("names no known backend"), "{off}");
+}

crates/engine/src/lib.rs

@@ -25,6 +25,7 @@ pub mod guard;
 pub mod import;
 mod import_move;
 pub mod library;
+pub mod logging;
 pub mod media;
 pub mod memory;
 pub mod merge;

crates/engine/src/logging.rs

@@ -0,0 +1,118 @@
+//! `log` records on stderr for the native desktop app and CLI (#168). The web build installs
+//! eframe's `WebLogger` instead.
+//!
+//! Warnings and errors are shown by default. `LIGHTCRAFT_LOG` or `RUST_LOG` picks another level
+//! (`off`, `error`, `warn`, `info`, `debug`, `trace`); `LIGHTCRAFT_LOG` wins when both are set.
+//! `RUST_LOG` also accepts per-target directives (`lightcraft=debug,wgpu=warn`): a bare level
+//! applies to everything, and the most verbose `lightcraft…=level` directive sets LightCraft's.
+//! Below warnings only LightCraft's own records are shown, so `info` and `debug` aren't drowned
+//! out by the GPU and windowing libraries.
+
+use log::{Level, LevelFilter, Metadata, Record};
+
+/// Records shown at a level, written to stderr as `<prefix>: LEVEL target: message`.
+pub struct StderrLog {
+    prefix: &'static str,
+    level: LevelFilter,
+}
+
+impl StderrLog {
+    pub fn new(prefix: &'static str, level: LevelFilter) -> Self {
+        Self { prefix, level }
+    }
+}
+
+impl log::Log for StderrLog {
+    fn enabled(&self, m: &Metadata) -> bool {
+        m.level() <= self.level && (m.level() <= Level::Warn || m.target().starts_with("lightcraft"))
+    }
+    fn log(&self, r: &Record) {
+        if self.enabled(r.metadata()) {
+            eprintln!("{}: {} {}: {}", self.prefix, r.level(), r.target(), r.args());
+        }
+    }
+    fn flush(&self) {}
+}
+
+fn parse_level(s: &str) -> Option<LevelFilter> {
+    match s.trim().to_ascii_lowercase().as_str() {
+        "off" | "none" => Some(LevelFilter::Off),
+        "error" => Some(LevelFilter::Error),
+        "warn" | "warning" => Some(LevelFilter::Warn),
+        "info" => Some(LevelFilter::Info),
+        "debug" => Some(LevelFilter::Debug),
+        "trace" => Some(LevelFilter::Trace),
+        _ => None,
+    }
+}
+
+/// The level that `LIGHTCRAFT_LOG` / `RUST_LOG` ask for; warnings when neither names one.
+pub fn level_from(lightcraft_log: Option<&str>, rust_log: Option<&str>) -> LevelFilter {
+    if let Some(l) = lightcraft_log.and_then(parse_level) {
+        return l;
+    }
+    let Some(rust_log) = rust_log else { return LevelFilter::Warn };
+    let mut bare = None;
+    let mut ours: Option<LevelFilter> = None;
+    for directive in rust_log.split(',') {
+        match directive.split_once('=') {
+            None => bare = parse_level(directive).or(bare),
+            Some((target, level)) if target.trim().starts_with("lightcraft") => {
+                if let Some(l) = parse_level(level) {
+                    ours = Some(ours.map_or(l, |o| o.max(l)));
+                }
+            }
+            Some(_) => {}
+        }
+    }
+    ours.or(bare).unwrap_or(LevelFilter::Warn)
+}
+
+/// Install the stderr logger at the level the environment asks for. Does nothing when a logger is
+/// already installed.
+pub fn install(prefix: &'static str) {
+    let level = level_from(std::env::var("LIGHTCRAFT_LOG").ok().as_deref(), std::env::var("RUST_LOG").ok().as_deref());
+    static LOGGER: std::sync::OnceLock<StderrLog> = std::sync::OnceLock::new();
+    if log::set_logger(LOGGER.get_or_init(|| StderrLog::new(prefix, level))).is_ok() {
+        log::set_max_level(level);
+    }
+}
+
+#[cfg(test)]
+mod tests {
+    use super::*;
+    use log::Log;
+
+    #[test]
+    fn warnings_by_default_and_either_variable_picks_the_level() {
+        assert_eq!(level_from(None, None), LevelFilter::Warn);
+        assert_eq!(level_from(None, Some("")), LevelFilter::Warn);
+        assert_eq!(level_from(None, Some("warn")), LevelFilter::Warn);
+        assert_eq!(level_from(None, Some("TRACE")), LevelFilter::Trace);
+        assert_eq!(level_from(None, Some("off")), LevelFilter::Off);
+        assert_eq!(level_from(Some("info"), None), LevelFilter::Info);
+        assert_eq!(level_from(Some("error"), Some("debug")), LevelFilter::Error, "LIGHTCRAFT_LOG wins");
+        assert_eq!(level_from(Some("nonsense"), Some("debug")), LevelFilter::Debug, "an unknown LIGHTCRAFT_LOG is ignored");
+    }
+
+    #[test]
+    fn rust_log_directives_set_lightcraft_s_level() {
+        assert_eq!(level_from(None, Some("lightcraft=debug,wgpu=warn")), LevelFilter::Debug);
+        assert_eq!(level_from(None, Some("wgpu_core=trace")), LevelFilter::Warn, "other crates' directives don't apply");
+        assert_eq!(level_from(None, Some("error,lightcraft_gpu=info")), LevelFilter::Info);
+        assert_eq!(level_from(None, Some("lightcraft_gpu=info,lightcraft_engine=trace")), LevelFilter::Trace);
+        assert_eq!(level_from(None, Some("info,naga=off")), LevelFilter::Info);
+    }
+
+    #[test]
+    fn only_lightcraft_records_below_warnings() {
+        let log = StderrLog::new("test", LevelFilter::Debug);
+        let meta = |level, target| Metadata::builder().level(level).target(target).build();
+        assert!(log.enabled(&meta(Level::Warn, "wgpu_core::device")));
+        assert!(log.enabled(&meta(Level::Debug, "lightcraft_gpu::ctx")));
+        assert!(!log.enabled(&meta(Level::Info, "wgpu_core::device")));
+        assert!(!log.enabled(&meta(Level::Trace, "lightcraft_gpu::ctx")));
+        let quiet = StderrLog::new("test", LevelFilter::Off);
+        assert!(!quiet.enabled(&meta(Level::Error, "lightcraft_engine")));
+    }
+}