From a6cedcc9e8443cb92b33ed1e9ec859a73594cb0a Mon Sep 17 00:00:00 2001 From: DWAA1660 <80738438+DWAA1660@users.noreply.github.com> Date: Thu, 8 Oct 2026 11:04:19 -0600 Subject: [PATCH] Issue #168: the desktop app and CLI log warnings to stderr; RUST_LOG works lightcraft-cli installed no `log` backend, so every log::warn!/info! record (the GPU-to-CPU fallback, an unknown LIGHTCRAFT_GPU_BACKEND, the adapter chosen) was dropped and RUST_LOG, which docs/gpu-pipeline.md documents for the fallback warning, did nothing. The desktop app had its own logger that read only LIGHTCRAFT_LOG. Both now install lightcraft_engine::logging: warnings and errors on stderr by default; LIGHTCRAFT_LOG or RUST_LOG (off, error, warn, info, debug, trace) picks another level, LIGHTCRAFT_LOG winning, and RUST_LOG's per-target directives (`lightcraft=debug,wgpu=warn`) set LightCraft's level. Below warnings only LightCraft's own records are shown, as the app's logger did. The app's --help lists the variable. Tests: level parsing and target filtering (engine logging::tests); the CLI prints "LIGHTCRAFT_GPU_BACKEND=bogus names no known backend" with RUST_LOG=warn and nothing with RUST_LOG=off (cli.rs). Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01K3vVft4VXvvy8SpbbUceTW --- apps/lightcraft-cli/src/main.rs | 3 + apps/lightcraft-cli/tests/cli.rs | 26 +++++++ apps/lightcraft/Cargo.toml | 1 - apps/lightcraft/src/main.rs | 33 ++------- crates/engine/src/lib.rs | 1 + crates/engine/src/logging.rs | 118 +++++++++++++++++++++++++++++++ 6 files changed, 152 insertions(+), 30 deletions(-) create mode 100644 crates/engine/src/logging.rs diff --git a/apps/lightcraft-cli/src/main.rs b/apps/lightcraft-cli/src/main.rs index b9e2641c..88f011cd 100644 --- a/apps/lightcraft-cli/src/main.rs +++ b/apps/lightcraft-cli/src/main.rs @@ -122,6 +122,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 = std::env::args().skip(1).collect(); let r = match args.first().map(String::as_str) { Some("run") => run(&args[1..]), diff --git a/apps/lightcraft-cli/tests/cli.rs b/apps/lightcraft-cli/tests/cli.rs index 7cd0710b..e48b94bc 100644 --- a/apps/lightcraft-cli/tests/cli.rs +++ b/apps/lightcraft-cli/tests/cli.rs @@ -336,3 +336,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}"); +} diff --git a/apps/lightcraft/Cargo.toml b/apps/lightcraft/Cargo.toml index a29299da..a4ca7ddd 100644 --- a/apps/lightcraft/Cargo.toml +++ b/apps/lightcraft/Cargo.toml @@ -18,7 +18,6 @@ lightcraft-raster = { workspace = true } eframe = { workspace = true, features = ["default_fonts", "wgpu", "accesskit", "wayland", "x11"] } egui = { workspace = true } serde_json = { workspace = true } -log = { workspace = true } [build-dependencies] # Icon + VERSIONINFO for lightcraft.exe; build.rs only uses it when targeting Windows. diff --git a/apps/lightcraft/src/main.rs b/apps/lightcraft/src/main.rs index 4bb1c6ff..c4a930b4 100644 --- a/apps/lightcraft/src/main.rs +++ b/apps/lightcraft/src/main.rs @@ -409,39 +409,14 @@ ENVIRONMENT: LIGHTCRAFT_SAM3_DIR=DIR the SAM 3 model for Object / Describe masks (default: /models/sam3; optional: LightCraft offers to download it when first needed) LIGHTCRAFT_SAM3_MIRRORS=URL,… where to download the SAM 3 model from (base URLs, tried in order) + LIGHTCRAFT_LOG=LEVEL (or RUST_LOG) what is logged on stderr: off, error, warn (default), info, debug, trace "; -/// Warnings and errors (failed commands, AI mask analysis) on stderr; `LIGHTCRAFT_LOG=info` -/// (or `debug`) shows more. -struct StderrLog(log::LevelFilter); - -impl log::Log for StderrLog { - fn enabled(&self, m: &log::Metadata) -> bool { - m.level() <= self.0 && (m.level() <= log::Level::Warn || m.target().starts_with("lightcraft")) - } - fn log(&self, r: &log::Record) { - if self.enabled(r.metadata()) { - eprintln!("lightcraft: {} {}: {}", r.level(), r.target(), r.args()); - } - } - fn flush(&self) {} -} - -fn install_log() { - let level = match std::env::var("LIGHTCRAFT_LOG").unwrap_or_default().as_str() { - "debug" => log::LevelFilter::Debug, - "info" => log::LevelFilter::Info, - _ => log::LevelFilter::Warn, - }; - static LOGGER: std::sync::OnceLock = std::sync::OnceLock::new(); - if log::set_logger(LOGGER.get_or_init(|| StderrLog(level))).is_ok() { - log::set_max_level(level); - } -} - fn main() -> eframe::Result { lightcraft_engine::guard::install_hook(std::env::temp_dir().join("lightcraft-panics.log")); - install_log(); + // Warnings and errors (failed commands, AI mask analysis, GPU fallbacks) on stderr; + // LIGHTCRAFT_LOG or RUST_LOG picks another level. + lightcraft_engine::logging::install("lightcraft"); alloc_release::install(); let mut control_port: Option = std::env::var("LIGHTCRAFT_CONTROL_PORT").ok().and_then(|p| p.parse().ok()); let mut files = Vec::new(); diff --git a/crates/engine/src/lib.rs b/crates/engine/src/lib.rs index ec39222a..10d8fa14 100644 --- a/crates/engine/src/lib.rs +++ b/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; diff --git a/crates/engine/src/logging.rs b/crates/engine/src/logging.rs new file mode 100644 index 00000000..380bf61c --- /dev/null +++ b/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 `: 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 { + 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 = 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 = 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"))); + } +}