Logging: RUST_LOG prints to stderr, and start-up logs its milestones (#234)

The logger kept warnings in memory and wrote to a file only after Help
▸ Enable Logging, and it ignored RUST_LOG. An app that never opens its
window (macOS 27 on Apple Silicon, #234) therefore left no trace. Now
RUST_LOG (a level, or env_logger-style `target=level` directives)
also prints what it lets through to stderr, including eframe, winit
and wgpu. The desktop app logs its start-up milestones: opening the
window, the graphics adapter, the app created, the first frame drawn,
the window being asked to close, and the window closed.

Test: rust_log_filters_by_level_and_target (engine logging). Checked
by running the app with RUST_LOG=info and quitting it over the control
channel.

Co-Authored-By: Claude Opus 5.5 <[email protected]>

apps/effectcraft/src/main.rs

@@ -92,10 +92,17 @@ fn main() -> eframe::Result {
         wgpu_options: wgpu_options(),
         ..Default::default()
     };
+    // Start-up milestones: with `RUST_LOG=info` they go to stderr, so a window that never
+    // appears shows how far start-up got (#234).
+    log::info!("effectcraft {}: opening the window", env!("CARGO_PKG_VERSION"));
     let result = eframe::run_native(
         "EffectCraft",
         options,
         Box::new(move |cc| {
+            match &cc.wgpu_render_state {
+                Some(rs) => log::info!("graphics: {:?}", rs.adapter.get_info()),
+                None => log::info!("graphics: no wgpu device"),
+            }
             // This executable owns the shared device's handlers. Install them before
             // EffectCraft's compositor pipelines are built, without changing handlers from
             // inside Gpu::new. eframe has already constructed its presentation renderer here.
@@ -183,15 +190,18 @@ fn main() -> eframe::Result {
                 let rx = control_server::start(port, cc.egui_ctx.clone());
                 app = app.with_control(rx);
             }
+            log::info!("app created; the window shows after its first frame");
             Ok(Box::new(Desktop {
                 #[cfg(target_os = "macos")]
                 menu: native_menu::NativeBar::new(&cc.egui_ctx),
                 app,
+                drawn: false,
             }))
         }),
     );
-    if let Err(e) = &result {
-        startup_failed(e);
+    match &result {
+        Ok(()) => log::info!("the window closed"),
+        Err(e) => startup_failed(e),
     }
     result
 }
@@ -240,6 +250,8 @@ struct Desktop {
     app: EffectcraftApp,
     #[cfg(target_os = "macos")]
     menu: native_menu::NativeBar,
+    /// The first frame was drawn (logged once).
+    drawn: bool,
 }
 
 impl eframe::App for Desktop {
@@ -251,6 +263,10 @@ impl eframe::App for Desktop {
 
     fn ui(&mut self, ui: &mut egui::Ui, frame: &mut eframe::Frame) {
         self.app.ui(ui, frame);
+        if !self.drawn {
+            self.drawn = true;
+            log::info!("first frame drawn");
+        }
     }
 
     fn on_exit(&mut self) {

crates/engine/src/logging.rs

@@ -4,15 +4,21 @@
 //! Compatibility Report.
 //!
 //! Frontends call [`install`] once at startup; [`set_enabled`] (the `help.enableLogging`
-//! command) turns file logging on and off.
+//! command) turns file logging on and off. `RUST_LOG` (a level such as `debug`, or per target:
+//! `effectcraft=debug,wgpu=warn`) also prints what it lets through to stderr, so a start-up that
+//! fails before the window opens leaves a trace.
 
 use std::collections::VecDeque;
 use std::io::Write;
 use std::path::{Path, PathBuf};
-use std::sync::Mutex;
 use std::sync::atomic::{AtomicBool, Ordering};
+use std::sync::{Mutex, OnceLock};
+
+use log::LevelFilter;
 
 static ENABLED: AtomicBool = AtomicBool::new(false);
+/// The `RUST_LOG` filter for stderr: (target prefix or every target, level).
+static STDERR: OnceLock<Vec<(Option<String>, LevelFilter)>> = OnceLock::new();
 static STATE: Mutex<State> = Mutex::new(State { file: None, recent: VecDeque::new() });
 
 struct State {
@@ -26,13 +32,16 @@ const RECENT: usize = 300;
 
 impl log::Log for Logger {
     fn enabled(&self, m: &log::Metadata) -> bool {
-        m.level() <= log::Level::Warn || (ENABLED.load(Ordering::Relaxed) && m.target().starts_with("effectcraft"))
+        m.level() <= log::Level::Warn || (ENABLED.load(Ordering::Relaxed) && m.target().starts_with("effectcraft")) || to_stderr(m)
     }
     fn log(&self, r: &log::Record) {
         if !self.enabled(r.metadata()) {
             return;
         }
         let line = format!("{} {:<5} {}: {}", unix_secs(), r.level(), r.target(), r.args());
+        if to_stderr(r.metadata()) {
+            eprintln!("{line}");
+        }
         let Ok(mut st) = STATE.lock() else { return };
         if r.level() <= log::Level::Warn {
             st.recent.push_back(line.clone());
@@ -58,10 +67,39 @@ fn unix_secs() -> u64 {
 pub fn install() {
     static LOGGER: Logger = Logger;
     if log::set_logger(&LOGGER).is_ok() {
-        log::set_max_level(log::LevelFilter::Info);
+        let stderr = STDERR.get_or_init(|| std::env::var("RUST_LOG").map(|s| parse_filter(&s)).unwrap_or_default());
+        log::set_max_level(stderr.iter().map(|d| d.1).fold(LevelFilter::Info, Ord::max));
     }
 }
 
+/// Whether `RUST_LOG` lets a record through to stderr.
+fn to_stderr(m: &log::Metadata) -> bool {
+    STDERR.get().is_some_and(|f| m.level() <= level_for(f, m.target()))
+}
+
+/// `RUST_LOG`'s directives, as env_logger reads them: `level`, `target=level` or a bare target
+/// (every level); unknown levels are skipped.
+fn parse_filter(spec: &str) -> Vec<(Option<String>, LevelFilter)> {
+    spec.split(',')
+        .map(str::trim)
+        .filter(|d| !d.is_empty())
+        .filter_map(|d| match d.split_once('=') {
+            Some((t, l)) => Some((Some(t.trim().to_string()), l.trim().parse().ok()?)),
+            None => Some(d.parse().map_or_else(|_| (Some(d.to_string()), LevelFilter::Trace), |l| (None, l))),
+        })
+        .collect()
+}
+
+/// The level of the directive whose target is the longest prefix of `target` (a directive
+/// without a target matches every target); off when none does.
+fn level_for(filter: &[(Option<String>, LevelFilter)], target: &str) -> LevelFilter {
+    filter
+        .iter()
+        .filter(|(t, _)| t.as_deref().is_none_or(|t| target.starts_with(t)))
+        .max_by_key(|(t, _)| t.as_ref().map_or(0, String::len))
+        .map_or(LevelFilter::Off, |d| d.1)
+}
+
 /// Log every panic (message and location) through the logger, then run the previous hook
 /// (which prints it). Panics in commands are then caught by [`crate::guard::guarded`].
 pub fn install_panic_hook() {
@@ -107,3 +145,21 @@ pub fn current_file() -> Option<PathBuf> {
 pub fn recent() -> Vec<String> {
     STATE.lock().map(|s| s.recent.iter().cloned().collect()).unwrap_or_default()
 }
+
+#[cfg(test)]
+mod tests {
+    use super::{LevelFilter, level_for, parse_filter};
+
+    /// `RUST_LOG` picks what start-up prints to stderr (#234).
+    #[test]
+    fn rust_log_filters_by_level_and_target() {
+        let f = parse_filter("info, wgpu=warn,wgpu_core=debug, effectcraft , bogus=loud");
+        assert_eq!(level_for(&f, "eframe::native"), LevelFilter::Info);
+        assert_eq!(level_for(&f, "wgpu_hal::metal"), LevelFilter::Warn);
+        assert_eq!(level_for(&f, "wgpu_core::device"), LevelFilter::Debug, "the longest matching target wins");
+        assert_eq!(level_for(&f, "effectcraft_ui_egui"), LevelFilter::Trace, "a bare target: every level");
+        assert_eq!(f.len(), 4, "an unknown level is skipped");
+        assert_eq!(level_for(&parse_filter("wgpu=debug"), "winit"), LevelFilter::Off);
+        assert!(parse_filter("").is_empty());
+    }
+}

crates/ui-egui/src/panels/unsaved.rs

@@ -49,6 +49,8 @@ pub fn on_close_requested(app: &mut EffectcraftApp, ctx: &egui::Context) {
     if !ctx.input(|i| i.viewport().close_requested()) || app.dialog_state.unsaved.quitting {
         return;
     }
+    // Logged, so a window that closes on its own shows it (#234).
+    log::info!("the window was asked to close");
     if ask(app, "app.quit", &json!({})) {
         ctx.send_viewport_cmd(egui::ViewportCommand::CancelClose);
     }