diff --git a/apps/effectcraft/src/main.rs b/apps/effectcraft/src/main.rs index 353d6f22..9389ad06 100644 --- a/apps/effectcraft/src/main.rs +++ b/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) { diff --git a/crates/engine/src/logging.rs b/crates/engine/src/logging.rs index 04c0ab41..f5750372 100644 --- a/crates/engine/src/logging.rs +++ b/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, LevelFilter)>> = OnceLock::new(); static STATE: Mutex = 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, 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, 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 { pub fn recent() -> Vec { 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()); + } +} diff --git a/crates/ui-egui/src/panels/unsaved.rs b/crates/ui-egui/src/panels/unsaved.rs index a2ef7e4d..696da1a7 100644 --- a/crates/ui-egui/src/panels/unsaved.rs +++ b/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); }