diff --git a/README.md b/README.md index 6d6db7e..62553f6 100644 --- a/README.md +++ b/README.md @@ -119,6 +119,24 @@ echo 'app-office/deckcraft-bin ~amd64' >> /etc/portage/package.accept_keywords/d emerge --ask app-office/deckcraft-bin ``` +### Logs + +The desktop app writes its `log` records to standard error and to `logs/deckcraft.log` in the +settings directory, beside `ui.json` and `prefs.json` (Linux `~/.config/deckcraft/logs/`, or +`$XDG_CONFIG_HOME/deckcraft/logs/`; macOS `~/Library/Application Support/DeckCraft/logs/`; Windows +`%APPDATA%\DeckCraft\logs\`). A start from a desktop menu or the Dock has no terminal, so this file +is what to attach to a bug report: the crash guard's panic report, a failed crash-recovery save, +PowerPoint parts skipped on import and audio output problems land there. Each launch moves the +previous log to `deckcraft.1.log` (and that one to `deckcraft.2.log`), so the log of a run that +crashed survives the next start. The file stops growing at 16 MiB. `--version` writes no file. + +| Variable | Effect | +|---|---| +| `RUST_LOG` | Log levels for standard error and the log file. Default: `info` for DeckCraft's own crates, `warn` for everything else. env_logger-style directives replace that, e.g. `RUST_LOG=debug`, `RUST_LOG=warn,deckcraft_pptx=trace` or `RUST_LOG=info,wgpu_core=warn`; a directive ending in `*` covers every target starting with it (`deckcraft*=debug`). | + +The logger is `apps/deckcraft/src/logging.rs`; the realtime audio callback does not log. The web +app logs to the browser console instead. + ## Agents, CLI and MCP Every action in DeckCraft is a command with a stable id, so people, scripts and AI agents use the diff --git a/apps/deckcraft/src/audio.rs b/apps/deckcraft/src/audio.rs index 86682ad..53aa48c 100644 --- a/apps/deckcraft/src/audio.rs +++ b/apps/deckcraft/src/audio.rs @@ -1,12 +1,50 @@ //! cpal audio output for media playback: the device pulls mixed samples from the //! `deckcraft_media::Player`, which makes it the playback clock video frames follow. +use std::sync::{Arc, Mutex, PoisonError}; + use cpal::traits::{DeviceTrait, HostTrait, StreamTrait}; use deckcraft_media::AudioOut; +/// The first stream error since it was last reported. cpal calls the error callback on its +/// realtime audio thread (on ALSA in a loop while the device stays broken), which must not log: +/// the callback only keeps the first error, and the UI thread logs it when the stream stops. +type ErrorSlot = Arc>>; + +/// Keep `e` unless an error is already kept. Never blocks: a busy slot drops the error. +fn keep_stream_error(slot: &ErrorSlot, e: &dyn std::fmt::Display) { + if let Ok(mut kept) = slot.try_lock() + && kept.is_none() + { + *kept = Some(e.to_string()); + } +} + +/// The kept error, once (a poisoned lock is tolerated). +fn take_stream_error(slot: &ErrorSlot) -> Option { + slot.lock().unwrap_or_else(PoisonError::into_inner).take() +} + #[derive(Default)] pub struct CpalOut { stream: Option, + error: ErrorSlot, +} + +impl CpalOut { + /// Log the stream error the realtime callback kept (UI thread). + fn report(&self) { + if let Some(e) = take_stream_error(&self.error) { + log::warn!("audio stream error: {e}"); + } + } +} + +impl Drop for CpalOut { + fn drop(&mut self) { + self.stream = None; + self.report(); + } } impl AudioOut for CpalOut { @@ -17,7 +55,8 @@ impl AudioOut for CpalOut { let channels = cfg.channels() as usize; let rate = cfg.sample_rate().0; let config: cpal::StreamConfig = cfg.clone().into(); - let err = |e| log::warn!("audio stream error: {e}"); + let slot = self.error.clone(); + let err = move |e: cpal::StreamError| keep_stream_error(&slot, &e); let stream = match cfg.sample_format() { cpal::SampleFormat::F32 => dev.build_output_stream(&config, move |buf: &mut [f32], _| fill(buf, channels, rate), err, None), cpal::SampleFormat::I16 => { @@ -45,5 +84,37 @@ impl AudioOut for CpalOut { fn stop(&mut self) { self.stream = None; + self.report(); + } +} + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn only_the_first_stream_error_is_kept_and_it_is_taken_once() { + let slot = ErrorSlot::default(); + assert_eq!(take_stream_error(&slot), None); + keep_stream_error(&slot, &"device unplugged"); + keep_stream_error(&slot, &"device unplugged again"); + assert_eq!(take_stream_error(&slot).as_deref(), Some("device unplugged")); + assert_eq!(take_stream_error(&slot), None); + keep_stream_error(&slot, &"a later error"); + assert_eq!(take_stream_error(&slot).as_deref(), Some("a later error")); + } + + #[test] + fn a_poisoned_slot_still_reports() { + let slot = ErrorSlot::default(); + keep_stream_error(&slot, &"lost"); + let s = slot.clone(); + let _ = std::thread::spawn(move || { + let _g = s.lock(); + panic!("poison the slot"); + }) + .join(); + assert!(slot.is_poisoned()); + assert_eq!(take_stream_error(&slot).as_deref(), Some("lost")); } } diff --git a/apps/deckcraft/src/control_server.rs b/apps/deckcraft/src/control_server.rs index c2ad876..f50de02 100644 --- a/apps/deckcraft/src/control_server.rs +++ b/apps/deckcraft/src/control_server.rs @@ -14,11 +14,11 @@ pub fn start(port: u16, ctx: egui::Context) -> Receiver { let listener = match TcpListener::bind(("127.0.0.1", port)) { Ok(l) => l, Err(e) => { - eprintln!("deckcraft: control server failed to bind 127.0.0.1:{port}: {e}"); + log::error!("control server failed to bind 127.0.0.1:{port}: {e}"); return rx; } }; - eprintln!("deckcraft: control server listening on 127.0.0.1:{port}"); + log::info!("control server listening on 127.0.0.1:{port}"); std::thread::spawn(move || { for stream in listener.incoming().flatten() { let tx = tx.clone(); diff --git a/apps/deckcraft/src/logging.rs b/apps/deckcraft/src/logging.rs new file mode 100644 index 0000000..a0ca504 --- /dev/null +++ b/apps/deckcraft/src/logging.rs @@ -0,0 +1,567 @@ +//! The desktop app's logger: `log::` records go to standard error and to a log file. +//! +//! Without a logger every `log::warn!`/`log::error!` in the workspace (the crash guard's panic +//! report, a failed crash-recovery save, PowerPoint parts that were skipped on import, audio output +//! problems) vanished. A launch from a desktop menu has no terminal, so the file is what a bug report +//! can attach: `/logs/deckcraft.log`, beside `ui.json` and `prefs.json`. Each start +//! moves the previous log to `deckcraft.1.log` (and that one to `.2`), so the log of a run that +//! crashed survives the next launch. +//! +//! Levels: `info` for DeckCraft's own crates, `warn` for everything else (wgpu and naga are +//! chatty). `RUST_LOG` replaces that with env_logger-style directives: `debug`, +//! `warn,deckcraft_pptx=trace`, `wgpu_core=info`. A directive ending in `*` matches every target +//! that starts with it (`deckcraft*=debug`). +//! +//! Records logged before the settings directory is known are kept (up to [`MAX_PENDING`]) and +//! written once the file is attached. Writing never panics: a file that can't be created or written +//! leaves standard error as the only sink. +//! +//! Realtime audio: the cpal callbacks (`audio.rs`) do not log; a stream error is kept and logged +//! from the UI thread when the stream stops. A record takes the sink lock only for one `write_all` +//! of an already formatted line (standard error is written outside the lock). + +use std::fs::File; +use std::io::Write; +use std::path::{Path, PathBuf}; +use std::sync::{Mutex, OnceLock, PoisonError}; +use std::time::SystemTime; + +use log::LevelFilter; + +/// The current log file's name inside the log directory. +pub const LOG_FILE: &str = "deckcraft.log"; +/// The log directory inside the settings directory. +pub const LOG_DIR: &str = "logs"; +/// How many previous logs are kept (`deckcraft.1.log` … `deckcraft..log`). +pub const KEEP: usize = 2; +/// The log file stops growing past this size (a runaway warning can't fill the disk). +pub const MAX_FILE_BYTES: u64 = 16 * 1024 * 1024; +/// Records kept in memory until the log file is attached. +pub const MAX_PENDING: usize = 512; +/// The built-in filter when `RUST_LOG` is unset or empty. +pub const DEFAULT_FILTER: &str = "warn,deckcraft*=info"; + +/// Per-target level filter parsed from env_logger-style directives. +#[derive(Clone, Debug, PartialEq, Eq)] +pub struct Filter { + default: LevelFilter, + directives: Vec<(String, LevelFilter)>, +} + +impl Filter { + /// Parse `spec`; unknown levels and empty parts are skipped. Without a bare level, targets no + /// directive names log errors only. + pub fn parse(spec: &str) -> Filter { + let mut f = Filter { default: LevelFilter::Error, directives: Vec::new() }; + for part in spec.split(',').map(str::trim).filter(|p| !p.is_empty()) { + match part.split_once('=') { + Some((name, level)) => { + let name = name.trim(); + if let (false, Some(level)) = (name.is_empty(), parse_level(level)) { + f.directives.push((name.to_owned(), level)); + } + } + None => match parse_level(part) { + Some(level) => f.default = level, + // A bare target name: everything from it (env_logger does the same). + None => f.directives.push((part.to_owned(), LevelFilter::Trace)), + }, + } + } + f + } + + /// The level that applies to `target` (the most specific matching directive wins). + pub fn level_for(&self, target: &str) -> LevelFilter { + self.directives.iter().filter(|(name, _)| matches(name, target)).max_by_key(|(name, _)| name.len()).map_or(self.default, |(_, level)| *level) + } + + /// The most verbose level any target can reach (for `log::set_max_level`). + pub fn max(&self) -> LevelFilter { + self.directives.iter().map(|(_, level)| *level).fold(self.default, Ord::max) + } +} + +fn parse_level(s: &str) -> Option { + s.trim().parse().ok() +} + +/// `name` matches `target` itself and its submodules (`a` matches `a` and `a::b`, not `ab`); +/// `name*` matches every target starting with `name`. +fn matches(name: &str, target: &str) -> bool { + match name.strip_suffix('*') { + Some(prefix) => target.starts_with(prefix), + None => target.strip_prefix(name).is_some_and(|rest| rest.is_empty() || rest.starts_with("::")), + } +} + +/// `2026-10-08T07:59:17.728Z` (UTC, milliseconds). A clock before 1970 reads as the epoch. +pub fn timestamp(t: SystemTime) -> String { + let since = t.duration_since(std::time::UNIX_EPOCH).unwrap_or_default(); + let secs = since.as_secs(); + let (days, rem) = (secs / 86_400, secs % 86_400); + let (y, m, d) = civil_from_days(days); + format!("{y:04}-{m:02}-{d:02}T{:02}:{:02}:{:02}.{:03}Z", rem / 3600, rem % 3600 / 60, rem % 60, since.subsec_millis()) +} + +/// Days since 1970-01-01 to a proleptic Gregorian (year, month, day) (Howard Hinnant's +/// `civil_from_days`, unsigned because `timestamp` clamps at the epoch; saturating so an absurd +/// clock can't overflow). +fn civil_from_days(days: u64) -> (u64, u64, u64) { + let z = days.saturating_add(719_468); + let era = z / 146_097; + let doe = z % 146_097; + let yoe = (doe - doe / 1460 + doe / 36_524 - doe / 146_096) / 365; + let doy = doe - (365 * yoe + yoe / 4 - yoe / 100); + let mp = (5 * doy + 2) / 153; + let d = doy - (153 * mp + 2) / 5 + 1; + let m = if mp < 10 { mp + 3 } else { mp - 9 }; + let y = era.saturating_mul(400).saturating_add(yoe).saturating_add(u64::from(m <= 2)); + (y, m, d) +} + +fn numbered(dir: &Path, n: usize) -> PathBuf { + if n == 0 { dir.join(LOG_FILE) } else { dir.join(format!("deckcraft.{n}.log")) } +} + +/// Shift the previous logs up one (`.log` → `.1.log` → … → `..log`, the oldest dropped) +/// and create a fresh, empty log file in `dir` (created if missing). +pub fn rotate(dir: &Path) -> std::io::Result<(PathBuf, File)> { + std::fs::create_dir_all(dir)?; + for n in (1..=KEEP).rev() { + match std::fs::rename(numbered(dir, n - 1), numbered(dir, n)) { + Err(e) if e.kind() != std::io::ErrorKind::NotFound => return Err(e), + _ => {} + } + } + let path = numbered(dir, 0); + let file = File::create(&path)?; + Ok((path, file)) +} + +/// One formatted log line: ` [] : \n`. +pub fn format_line(ts: &str, level: log::Level, thread: &str, target: &str, message: &str) -> String { + let message = message.strip_suffix('\n').unwrap_or(message); + format!("{ts} {level:<5} [{thread}] {target}: {message}\n") +} + +/// Where formatted lines go besides standard error: kept in memory until a file is attached, +/// then appended to it until it reaches its size cap. +pub struct Sink { + file: Option, + pending: Vec, + dropped: usize, + written: u64, + max_bytes: u64, + capped: bool, +} + +impl Sink { + pub fn new(max_bytes: u64) -> Sink { + Sink { file: None, pending: Vec::new(), dropped: 0, written: 0, max_bytes, capped: false } + } + + /// Append `line` to the file, or keep it until [`Sink::attach`]. + pub fn write(&mut self, line: &str) { + if self.file.is_none() { + if self.capped { + return; + } + if self.pending.len() < MAX_PENDING { + self.pending.push(line.to_owned()); + } else { + self.dropped = self.dropped.saturating_add(1); + } + return; + } + self.append(line); + } + + /// Start writing to `file`, first the lines kept so far. + pub fn attach(&mut self, file: File) { + self.file = Some(file); + for line in std::mem::take(&mut self.pending) { + self.append(&line); + } + if self.dropped > 0 { + let note = format!("{} earlier log lines were dropped before the log file was opened\n", self.dropped); + self.dropped = 0; + self.append(¬e); + } + } + + /// No file will come: drop the kept lines and keep none from now on. + pub fn close(&mut self) { + self.file = None; + self.pending = Vec::new(); + self.capped = true; + } + + fn append(&mut self, line: &str) { + if self.capped { + return; + } + let Some(file) = self.file.as_mut() else { return }; + let len = u64::try_from(line.len()).unwrap_or(u64::MAX); + let text = if self.written.saturating_add(len) > self.max_bytes { + self.capped = true; + format!("log file reached {} bytes; later records go to standard error only\n", self.max_bytes) + } else { + self.written = self.written.saturating_add(len); + line.to_owned() + }; + // A full disk or a vanished file must not take the app down: drop the file sink (and + // stop buffering, since no file will come). + if file.write_all(text.as_bytes()).is_err() { + self.file = None; + self.capped = true; + } + } +} + +/// The installed logger: a [`Filter`], standard error and a [`Sink`]. +pub struct AppLogger { + filter: Filter, + stderr: bool, + sink: Mutex, +} + +impl AppLogger { + pub fn new(filter: Filter, stderr: bool) -> AppLogger { + AppLogger { filter, stderr, sink: Mutex::new(Sink::new(MAX_FILE_BYTES)) } + } + + /// Rotate the logs in `dir` and send records to the fresh file; returns its path. + /// An unusable directory leaves standard error as the only sink ([`AppLogger::stderr_only`]). + pub fn attach_dir(&self, dir: &Path) -> Result { + match rotate(dir) { + Ok((path, file)) => { + self.sink.lock().unwrap_or_else(PoisonError::into_inner).attach(file); + Ok(path) + } + Err(e) => { + self.stderr_only(); + Err(format!("{}: {e}", dir.display())) + } + } + } + + /// No log file this run (no settings directory, or it can't be used): stop keeping records for one. + pub fn stderr_only(&self) { + self.sink.lock().unwrap_or_else(PoisonError::into_inner).close(); + } +} + +impl log::Log for AppLogger { + fn enabled(&self, metadata: &log::Metadata<'_>) -> bool { + metadata.level() <= self.filter.level_for(metadata.target()) + } + + fn log(&self, record: &log::Record<'_>) { + if !self.enabled(record.metadata()) { + return; + } + // Format before taking the lock, so the lock covers one write only. + let thread = std::thread::current(); + let line = + format_line(×tamp(SystemTime::now()), record.level(), thread.name().unwrap_or("?"), record.target(), &record.args().to_string()); + if self.stderr { + let _ = std::io::stderr().write_all(line.as_bytes()); + } + self.sink.lock().unwrap_or_else(PoisonError::into_inner).write(&line); + } + + fn flush(&self) {} +} + +/// Install the logger (filter from `RUST_LOG`, else [`DEFAULT_FILTER`]); `None` when another +/// logger was installed first. Call [`AppLogger::attach_dir`] once the settings directory is known. +pub fn install() -> Option<&'static AppLogger> { + static LOGGER: OnceLock = OnceLock::new(); + let spec = std::env::var("RUST_LOG").ok().filter(|s| !s.trim().is_empty()); + let filter = Filter::parse(spec.as_deref().unwrap_or(DEFAULT_FILTER)); + let max = filter.max(); + let logger = LOGGER.get_or_init(|| AppLogger::new(filter, true)); + log::set_logger(logger).ok()?; + log::set_max_level(max); + Some(logger) +} + +#[cfg(test)] +mod tests { + use super::*; + use log::Log; + use std::sync::atomic::{AtomicUsize, Ordering}; + use std::time::{Duration, UNIX_EPOCH}; + + fn temp_dir(tag: &str) -> PathBuf { + static N: AtomicUsize = AtomicUsize::new(0); + let d = std::env::temp_dir().join(format!("deckcraft-logging-{tag}-{}-{}", std::process::id(), N.fetch_add(1, Ordering::Relaxed))); + let _ = std::fs::remove_dir_all(&d); + d + } + + fn read(path: &Path) -> String { + std::fs::read_to_string(path).expect("read log") + } + + fn record(logger: &AppLogger, level: log::Level, target: &'static str, msg: &'static str) { + logger.log(&log::Record::builder().level(level).target(target).args(format_args!("{msg}")).build()); + } + + #[test] + fn the_default_filter_shows_deckcraft_info_and_other_crates_warnings() { + let f = Filter::parse(DEFAULT_FILTER); + assert_eq!(f.level_for("deckcraft"), LevelFilter::Info); + assert_eq!(f.level_for("deckcraft::audio"), LevelFilter::Info); + assert_eq!(f.level_for("deckcraft_engine::guard"), LevelFilter::Info); + assert_eq!(f.level_for("deckcraft_pptx::read"), LevelFilter::Info); + assert_eq!(f.level_for("wgpu_core::device"), LevelFilter::Warn); + assert_eq!(f.level_for("naga"), LevelFilter::Warn); + assert_eq!(f.max(), LevelFilter::Info); + } + + #[test] + fn directives_follow_env_logger_and_the_most_specific_one_wins() { + let f = Filter::parse("info,wgpu_core=error,deckcraft_pptx=trace,deckcraft_pptx::opc=off"); + assert_eq!(f.level_for("eframe"), LevelFilter::Info); + assert_eq!(f.level_for("wgpu_core::instance"), LevelFilter::Error); + assert_eq!(f.level_for("deckcraft_pptx::read"), LevelFilter::Trace); + assert_eq!(f.level_for("deckcraft_pptx::opc"), LevelFilter::Off); + assert_eq!(f.max(), LevelFilter::Trace); + // A module name is matched at `::` boundaries, not as a bare prefix. + assert_eq!(f.level_for("wgpu_core_extra"), LevelFilter::Info); + // A trailing `*` is a prefix. + assert_eq!(Filter::parse("warn,deckcraft_ui*=debug").level_for("deckcraft_ui_egui::canvas"), LevelFilter::Debug); + assert_eq!(Filter::parse("warn,deckcraft_ui*=debug").level_for("deckcraft_engine"), LevelFilter::Warn); + // A bare target name sets that target to the most verbose level, as env_logger does. + assert_eq!(Filter::parse("naga").level_for("naga::front"), LevelFilter::Trace); + assert_eq!(Filter::parse("naga").level_for("eframe"), LevelFilter::Error); + // Levels are case-insensitive; the last bare level wins. + assert_eq!(Filter::parse("debug,WARN").level_for("x"), LevelFilter::Warn); + } + + #[test] + fn hostile_specs_never_panic_and_fall_back_sensibly() { + let long = "a".repeat(100_000); + let specs = [ + "", + ",,,", + "=", + "==", + "=debug", + "deckcraft=", + "nonsense=loud", + "🦀=info", + "*", + "*=debug", + "a=b=c", + "warn,,deckcraft=DEBUG", + " \t ", + "\u{0}", + "é*=trace", + &long, + ]; + for spec in specs { + let f = Filter::parse(spec); + for target in ["deckcraft", "", "🦀", "é", "a::b"] { + let _ = f.level_for(target); + } + let _ = f.max(); + } + assert_eq!(Filter::parse("warn,,deckcraft=DEBUG").level_for("deckcraft"), LevelFilter::Debug); + assert_eq!(Filter::parse("nonsense=loud").level_for("nonsense"), LevelFilter::Error); + assert_eq!(Filter::parse("=debug").max(), LevelFilter::Error, "a directive without a name is skipped"); + assert_eq!(Filter::parse("*=debug").level_for("anything"), LevelFilter::Debug, "a lone `*` matches every target"); + assert_eq!(Filter::parse("é*=trace").level_for("éa"), LevelFilter::Trace); + } + + #[test] + fn timestamps_are_utc_with_milliseconds() { + assert_eq!(timestamp(UNIX_EPOCH), "1970-01-01T00:00:00.000Z"); + assert_eq!(timestamp(UNIX_EPOCH + Duration::from_millis(1_791_446_357_728)), "2026-10-08T07:59:17.728Z"); + // Leap day, and the day after it. + assert_eq!(timestamp(UNIX_EPOCH + Duration::from_secs(1_709_164_800)), "2024-02-29T00:00:00.000Z"); + assert_eq!(timestamp(UNIX_EPOCH + Duration::from_secs(1_709_251_199)), "2024-02-29T23:59:59.000Z"); + assert_eq!(timestamp(UNIX_EPOCH + Duration::from_secs(1_709_251_200)), "2024-03-01T00:00:00.000Z"); + // 2000 is a leap year (divisible by 400), 2100 is not. + assert_eq!(timestamp(UNIX_EPOCH + Duration::from_secs(951_782_400)), "2000-02-29T00:00:00.000Z"); + assert_eq!(timestamp(UNIX_EPOCH + Duration::from_secs(4_107_542_400)), "2100-03-01T00:00:00.000Z"); + // Before the epoch (a clock set wrong) clamps instead of panicking. + assert_eq!(timestamp(UNIX_EPOCH - Duration::from_secs(5)), "1970-01-01T00:00:00.000Z"); + } + + #[test] + fn rotation_keeps_the_previous_logs_and_starts_an_empty_file() { + let dir = temp_dir("rotate"); + for run in 1..=4 { + let (path, _file) = rotate(&dir).expect("rotate"); + assert_eq!(path, dir.join(LOG_FILE)); + assert_eq!(read(&path), ""); + std::fs::write(&path, format!("run {run}")).expect("write"); + } + assert_eq!(read(&dir.join(LOG_FILE)), "run 4"); + assert_eq!(read(&dir.join("deckcraft.1.log")), "run 3"); + assert_eq!(read(&dir.join("deckcraft.2.log")), "run 2"); + assert!(!dir.join("deckcraft.3.log").exists(), "only {KEEP} old logs are kept"); + let _ = std::fs::remove_dir_all(&dir); + } + + #[test] + fn rotation_into_an_unusable_directory_is_an_error_not_a_panic() { + let dir = temp_dir("blocked"); + std::fs::create_dir_all(dir.parent().expect("parent")).expect("tmp"); + std::fs::write(&dir, "a file where the directory should be").expect("block"); + assert!(rotate(&dir).is_err()); + assert!(rotate(&dir.join("below")).is_err()); + let _ = std::fs::remove_file(&dir); + } + + #[test] + fn a_line_carries_time_level_thread_target_and_message() { + assert_eq!( + format_line( + "2026-10-08T07:59:17.728Z", + log::Level::Warn, + "main", + "deckcraft_pptx::opc", + "pptx: skipping oversized part ppt/media/image1.png" + ), + "2026-10-08T07:59:17.728Z WARN [main] deckcraft_pptx::opc: pptx: skipping oversized part ppt/media/image1.png\n" + ); + // A multi-line message keeps its lines; the record still ends in exactly one newline. + assert!(format_line("t", log::Level::Error, "w", "x", "a\nb\n").ends_with("x: a\nb\n")); + } + + #[test] + fn lines_logged_before_the_file_exists_are_written_when_it_is_attached() { + let dir = temp_dir("pending"); + let (path, file) = rotate(&dir).expect("rotate"); + let mut sink = Sink::new(MAX_FILE_BYTES); + sink.write("early 1\n"); + sink.write("early 2\n"); + sink.attach(file); + sink.write("late\n"); + assert_eq!(read(&path), "early 1\nearly 2\nlate\n"); + let _ = std::fs::remove_dir_all(&dir); + } + + #[test] + fn the_pending_buffer_is_bounded_and_says_how_much_it_dropped() { + let dir = temp_dir("bounded"); + let (path, file) = rotate(&dir).expect("rotate"); + let mut sink = Sink::new(MAX_FILE_BYTES); + for i in 0..MAX_PENDING + 5 { + sink.write(&format!("line {i}\n")); + } + sink.attach(file); + let text = read(&path); + assert_eq!(text.lines().filter(|l| l.starts_with("line ")).count(), MAX_PENDING); + assert_eq!(text.matches("5 earlier log lines were dropped").count(), 1, "{text}"); + assert!(text.contains("line 0\n") && !text.contains(&format!("line {MAX_PENDING}\n"))); + let _ = std::fs::remove_dir_all(&dir); + } + + #[test] + fn exactly_max_pending_lines_drop_nothing() { + let dir = temp_dir("exact"); + let (path, file) = rotate(&dir).expect("rotate"); + let mut sink = Sink::new(MAX_FILE_BYTES); + for i in 0..MAX_PENDING { + sink.write(&format!("line {i}\n")); + } + sink.attach(file); + let text = read(&path); + assert_eq!(text.lines().count(), MAX_PENDING); + assert!(!text.contains("dropped"), "{text}"); + let _ = std::fs::remove_dir_all(&dir); + } + + #[test] + fn the_file_stops_at_its_size_cap_with_one_note() { + let dir = temp_dir("cap"); + let (path, file) = rotate(&dir).expect("rotate"); + let mut sink = Sink::new(100); + sink.attach(file); + for i in 0..50 { + sink.write(&format!("line {i:02} with some padding\n")); + } + let text = read(&path); + assert_eq!(text.lines().filter(|l| l.starts_with("line ")).count(), 3, "{text}"); + assert_eq!(text.matches("log file reached 100 bytes").count(), 1, "{text}"); + let _ = std::fs::remove_dir_all(&dir); + } + + #[test] + fn the_logger_filters_records_and_writes_them_to_the_attached_file() { + let dir = temp_dir("logger"); + let logger = AppLogger::new(Filter::parse(DEFAULT_FILTER), false); + record(&logger, log::Level::Info, "deckcraft", "DeckCraft starting"); + record(&logger, log::Level::Info, "wgpu_core::device", "too chatty"); + let path = logger.attach_dir(&dir).expect("attach"); + assert_eq!(path, dir.join(LOG_FILE)); + record(&logger, log::Level::Warn, "wgpu_hal::vulkan", "a real warning"); + record(&logger, log::Level::Debug, "deckcraft", "below info"); + let text = read(&path); + let lines: Vec<&str> = text.lines().collect(); + assert_eq!(lines.len(), 2, "{text}"); + assert!(lines.first().is_some_and(|l| l.contains(" INFO [") && l.ends_with("deckcraft: DeckCraft starting")), "{text}"); + assert!(lines.get(1).is_some_and(|l| l.ends_with("wgpu_hal::vulkan: a real warning")), "{text}"); + assert!(logger.enabled(&log::Metadata::builder().level(log::Level::Info).target("deckcraft_engine::recovery").build())); + assert!(!logger.enabled(&log::Metadata::builder().level(log::Level::Info).target("naga").build())); + // A second launch rotates: the first log becomes `.1`. + let second = AppLogger::new(Filter::parse(DEFAULT_FILTER), false); + assert_eq!(second.attach_dir(&dir).expect("attach again"), dir.join(LOG_FILE)); + assert_eq!(read(&dir.join("deckcraft.1.log")), text); + let _ = std::fs::remove_dir_all(&dir); + } + + #[test] + fn records_from_many_threads_are_whole_lines() { + let dir = temp_dir("threads"); + let logger = AppLogger::new(Filter::parse("info"), false); + let path = logger.attach_dir(&dir).expect("attach"); + std::thread::scope(|s| { + for _ in 0..4 { + s.spawn(|| { + for _ in 0..100 { + record(&logger, log::Level::Info, "deckcraft", "from a worker"); + } + }); + } + }); + let text = read(&path); + assert_eq!(text.lines().count(), 400); + assert!(text.lines().all(|l| l.ends_with("deckcraft: from a worker")), "{text}"); + let _ = std::fs::remove_dir_all(&dir); + } + + #[test] + fn attaching_to_an_unusable_directory_reports_an_error_and_keeps_logging() { + let dir = temp_dir("unusable"); + std::fs::write(&dir, "not a directory").expect("block"); + let logger = AppLogger::new(Filter::parse("info"), false); + let e = logger.attach_dir(&dir).expect_err("a file is not a log directory"); + assert!(e.contains(&dir.display().to_string()), "{e}"); + record(&logger, log::Level::Error, "x", "still fine"); + let sink = logger.sink.lock().expect("sink"); + assert!(sink.file.is_none() && sink.pending.is_empty(), "nothing is kept for a file that will not come"); + drop(sink); + let _ = std::fs::remove_file(&dir); + } + + #[test] + fn a_poisoned_lock_does_not_stop_logging() { + let dir = temp_dir("poison"); + let logger = AppLogger::new(Filter::parse("info"), false); + let path = logger.attach_dir(&dir).expect("attach"); + let _ = std::panic::catch_unwind(std::panic::AssertUnwindSafe(|| { + let _guard = logger.sink.lock(); + panic!("poison the sink"); + })); + assert!(logger.sink.is_poisoned()); + record(&logger, log::Level::Info, "deckcraft", "after the panic"); + assert!(read(&path).contains("after the panic")); + let _ = std::fs::remove_dir_all(&dir); + } +} diff --git a/apps/deckcraft/src/main.rs b/apps/deckcraft/src/main.rs index d9b5587..3d64655 100644 --- a/apps/deckcraft/src/main.rs +++ b/apps/deckcraft/src/main.rs @@ -5,12 +5,16 @@ //! `--control ` (or `DECKCRAFT_CONTROL_PORT`) starts a localhost JSON-lines control server: //! `{"id":1,"method":"ui.inspect","params":{}}` → `{"id":1,"ok":true,"result":…}`. //! See `deckcraft_ui_egui::control` for the methods. +//! +//! `log` records go to standard error and `/logs/deckcraft.log` (`RUST_LOG` sets the +//! levels); see [`logging`]. #![cfg_attr(all(target_os = "windows", not(debug_assertions)), windows_subsystem = "windows")] #![deny(clippy::unwrap_used, clippy::expect_used, clippy::panic, clippy::unimplemented, clippy::todo, clippy::unreachable)] #![forbid(unsafe_code)] mod audio; mod control_server; +mod logging; use deckcraft_engine::Session; use deckcraft_ui_egui::{Services, SlideApp}; @@ -32,8 +36,9 @@ impl eframe::App for App { } } -fn prefs_path() -> Option { - let base = if cfg!(target_os = "macos") { +/// The per-user settings directory: `ui.json`, `prefs.json` and `logs/` live here. +fn config_dir() -> Option { + if cfg!(target_os = "macos") { std::env::var_os("HOME").map(|h| std::path::PathBuf::from(h).join("Library/Application Support/DeckCraft")) } else if cfg!(windows) { std::env::var_os("APPDATA").map(|a| std::path::PathBuf::from(a).join("DeckCraft")) @@ -42,8 +47,11 @@ fn prefs_path() -> Option { .map(std::path::PathBuf::from) .or_else(|| std::env::var_os("HOME").map(|h| std::path::PathBuf::from(h).join(".config"))) .map(|c| c.join("deckcraft")) - }; - base.map(|b| b.join("ui.json")) + } +} + +fn prefs_path() -> Option { + config_dir().map(|b| b.join("ui.json")) } fn load_prefs(app: &mut SlideApp) { @@ -125,6 +133,9 @@ fn app_icon() -> Option { } fn main() -> eframe::Result { + // First, so every start-up record (and the engine's panic hook, installed with the first + // Session) is captured; see `logging`. + let logger = logging::install(); let mut control_port: Option = std::env::var("DECKCRAFT_CONTROL_PORT").ok().and_then(|p| p.parse().ok()); let mut files = Vec::new(); let mut sample = false; @@ -142,6 +153,19 @@ fn main() -> eframe::Result { _ => files.push(a), } } + log::info!("DeckCraft {} ({} {})", env!("CARGO_PKG_VERSION"), std::env::consts::OS, std::env::consts::ARCH); + // The log file lives under the settings directory; opened after the arguments, so `--version` + // leaves no file behind. Records logged until now are written to it first. + if let Some(logger) = logger { + match config_dir().map(|d| logger.attach_dir(&d.join(logging::LOG_DIR))) { + Some(Ok(path)) => log::info!("log file {}", path.display()), + Some(Err(e)) => log::warn!("no log file: {e}"), + None => { + logger.stderr_only(); + log::warn!("no log file: no settings directory (HOME, XDG_CONFIG_HOME or APPDATA is not set)"); + } + } + } let mut options = eframe::NativeOptions { viewport: egui::ViewportBuilder::default() .with_title("DeckCraft") @@ -185,11 +209,11 @@ fn main() -> eframe::Result { app = app.with_control(rx); } if sample && let Err(e) = deckcraft_engine::sample::open_sample(&mut app.session) { - eprintln!("deckcraft: sample: {e}"); + log::error!("sample: {e}"); } for f in files { if let Err(e) = app.open_path(&f) { - eprintln!("deckcraft: {f}: {e}"); + log::error!("{f}: {e}"); } } if show {