From 80e8a0fe53294afa115b2775ad2bc286fc7786fb Mon Sep 17 00:00:00 2001 From: Gert Pellin - GPE Date: Fri, 9 Oct 2026 16:29:47 +0200 Subject: [PATCH] Desktop: write log records to standard error and a rotating log file (#7) The desktop app installed no logger, so every log::warn!/log::error! in the workspace was discarded: the crash guard's panic report, a failed crash-recovery save, PowerPoint parts skipped on import, audio output problems. A launch from a desktop menu has no terminal either, so there was nothing to attach to a bug report. apps/deckcraft/src/logging.rs (no new dependency): - standard error plus /logs/deckcraft.log (beside ui.json and prefs.json); each launch rotates the previous log to deckcraft.1.log and .2.log, so the log of a run that crashed survives the next start; the file is capped at 16 MiB - records logged before the settings directory is known are buffered (bounded) and written once the file is attached - default levels: info for deckcraft*, warn for everything else; RUST_LOG replaces them with env_logger-style directives - never panics: an unusable directory or a failed write leaves standard error as the only sink; a poisoned lock is tolerated - a record holds the lock for one write of an already formatted line The cpal error callback runs on the realtime audio thread (on ALSA in a loop while the device stays broken), so it no longer logs: it keeps the first error without blocking, and the UI thread logs it when the stream stops. The logger is installed first in main (before the engine's panic hook) and the file is opened after argument parsing (--version leaves no file). The settings directory moves out of prefs_path into config_dir. The start-up eprintln!s (sample, files that fail to open, control server) now go through the logger. Documented in README.md (Getting started > Logs). Co-authored-by: Brandon Thomas --- README.md | 18 + apps/deckcraft/src/audio.rs | 73 +++- apps/deckcraft/src/control_server.rs | 4 +- apps/deckcraft/src/logging.rs | 567 +++++++++++++++++++++++++++ apps/deckcraft/src/main.rs | 36 +- 5 files changed, 689 insertions(+), 9 deletions(-) create mode 100644 apps/deckcraft/src/logging.rs 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 {