From 1d31c230c993f15aa6d206fb167236a15c259dfb Mon Sep 17 00:00:00 2001 From: Gert Pellin - GPE Date: Thu, 8 Oct 2026 11:48:52 +0200 Subject: [PATCH] Desktop: write log records to standard error and a rotating log file (#239) The desktop app installed no logger, so every log::warn!/log::error! in the workspace was discarded: a failed autosave, a page that would not render, a render worker that could not start. A launch from a desktop menu has no terminal either, so there was nothing to attach to a bug report. apps/pdfcraft/src/logging.rs (no new dependency besides log): - standard error plus /logs/pdfcraft.log, next to app.ron (Linux $XDG_DATA_HOME/pdfcraft); each launch rotates the previous log to pdfcraft.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 pdfcraft*, 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 The logger is installed first in main, so the panic hook's report is recorded too; the start-up messages in main go through it. The file is opened after argument parsing (--version leaves no file) and after the PrintCraft folder migration, which a fresh settings folder would block. Documented in docs/development.md (Logs, environment variables). --- Cargo.lock | 1 + README.md | 2 + apps/pdfcraft/Cargo.toml | 2 + apps/pdfcraft/src/logging.rs | 474 +++++++++++++++++++++++++++++++++++ apps/pdfcraft/src/main.rs | 50 +++- docs/development.md | 33 +++ 6 files changed, 550 insertions(+), 12 deletions(-) create mode 100644 apps/pdfcraft/src/logging.rs create mode 100644 docs/development.md diff --git a/Cargo.lock b/Cargo.lock index 7b66287d..dce2a05a 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3452,6 +3452,7 @@ dependencies = [ "eframe", "egui", "fmv-macos-events", + "log", "pdfcraft-ui-egui", "rustls-native-certs", "serde_json", diff --git a/README.md b/README.md index 7374e26b..5fbc07fe 100644 --- a/README.md +++ b/README.md @@ -381,6 +381,8 @@ echo 'app-text/pdfcraft-bin ~amd64' >> /etc/portage/package.accept_keywords/pdfc emerge --ask app-text/pdfcraft-bin ``` +Logs, environment variables and other development notes are in [docs/development.md](docs/development.md). + ## What's next PdfCraft is young and moving fast. The aim is a workbench where you can view, organize, annotate, fill, sign and edit PDFs, at parity with Acrobat Pro. diff --git a/apps/pdfcraft/Cargo.toml b/apps/pdfcraft/Cargo.toml index df5cc75f..78d9fb5c 100644 --- a/apps/pdfcraft/Cargo.toml +++ b/apps/pdfcraft/Cargo.toml @@ -17,6 +17,8 @@ pdfcraft-ui-egui = { workspace = true } eframe = { workspace = true, features = ["default_fonts", "wgpu", "accesskit", "wayland", "x11", "persistence", "links"] } egui = { workspace = true } serde_json = { workspace = true } +# Records from every crate go to standard error and the log file (src/logging.rs). +log = { workspace = true } [target.'cfg(target_os = "macos")'.dependencies] # Finder double-click / Open With / Dock drops arrive as Apple events (#73); this small audited diff --git a/apps/pdfcraft/src/logging.rs b/apps/pdfcraft/src/logging.rs new file mode 100644 index 00000000..a62d300f --- /dev/null +++ b/apps/pdfcraft/src/logging.rs @@ -0,0 +1,474 @@ +//! 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 (a failed autosave, a page +//! that would not render, a render worker that could not start, the panic hook's report) vanished. +//! A launch from a desktop menu has no terminal, so the file is what a bug report can attach: +//! `/logs/pdfcraft.log`, next to `app.ron` (see `settings_dir` in `main.rs`). Each +//! start moves the previous log to `pdfcraft.1.log` (and that one to `.2`), so the log of a run +//! that crashed survives the next launch. +//! +//! Levels: `info` for PdfCraft's own crates, `warn` for everything else (wgpu and naga are +//! chatty). `RUST_LOG` replaces that with env_logger-style directives: `debug`, +//! `warn,pdfcraft_render=trace`, `wgpu_core=info`. A directive ending in `*` matches every target +//! that starts with it (`pdfcraft*=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. Never log the control-channel token or a +//! document password. + +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 = "pdfcraft.log"; +/// How many previous logs are kept (`pdfcraft.1.log` … `pdfcraft..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,pdfcraft*=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). `days` is at most +/// `u64::MAX / 86_400`, so none of the arithmetic below can overflow. +fn civil_from_days(days: u64) -> (u64, u64, u64) { + let z = days + 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 = yoe + era * 400 + 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!("pdfcraft.{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.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); + } + } + + 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. + 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. + pub fn attach_dir(&self, dir: &Path) -> Result { + let (path, file) = rotate(dir).map_err(|e| format!("{}: {e}", dir.display()))?; + self.sink.lock().unwrap_or_else(PoisonError::into_inner).attach(file); + Ok(path) + } +} + +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; + } + 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 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!("pdfcraft-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") + } + + #[test] + fn the_default_filter_shows_pdfcraft_info_and_other_crates_warnings() { + let f = Filter::parse(DEFAULT_FILTER); + assert_eq!(f.level_for("pdfcraft"), LevelFilter::Info); + assert_eq!(f.level_for("pdfcraft::updates"), LevelFilter::Info); + assert_eq!(f.level_for("pdfcraft_ui_egui::recovery"), LevelFilter::Info); + assert_eq!(f.level_for("pdfcraft_render::raster"), LevelFilter::Info); + assert_eq!(f.level_for("wgpu_core::device"), LevelFilter::Warn); + assert_eq!(f.level_for("naga"), LevelFilter::Warn); + assert_eq!(f.level_for("printcraft"), 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,pdfcraft_render=trace,pdfcraft_render::raster=off"); + assert_eq!(f.level_for("eframe"), LevelFilter::Info); + assert_eq!(f.level_for("wgpu_core::instance"), LevelFilter::Error); + assert_eq!(f.level_for("pdfcraft_render::text"), LevelFilter::Trace); + assert_eq!(f.level_for("pdfcraft_render::raster"), 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); + assert_eq!(f.level_for("pdfcraft_render_extra"), LevelFilter::Info); + // 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); + // A trailing `*` is a plain prefix match. + assert_eq!(Filter::parse("pdfcraft*=debug").level_for("pdfcraft_ui_egui::canvas"), LevelFilter::Debug); + assert_eq!(Filter::parse("pdfcraft*=debug").level_for("eframe"), LevelFilter::Error); + } + + #[test] + fn hostile_specs_never_panic_and_fall_back_sensibly() { + let long = "x".repeat(100_000); + let odd = ["", ",,,", "=", "=debug", "pdfcraft=", "nonsense=loud", "🦀=info", "*", "**=info", "a=b=c", " = ", "é*=warn"]; + for spec in odd.into_iter().chain([long.as_str(), "warn,,pdfcraft=DEBUG"]) { + let f = Filter::parse(spec); + let _ = f.level_for("pdfcraft"); + let _ = f.level_for(""); + let _ = f.level_for("🦀::x"); + let _ = f.max(); + } + assert_eq!(Filter::parse("warn,,pdfcraft=DEBUG").level_for("pdfcraft"), LevelFilter::Debug); + assert_eq!(Filter::parse("nonsense=loud").level_for("nonsense"), LevelFilter::Error); + assert_eq!(Filter::parse("pdfcraft=").level_for("pdfcraft"), LevelFilter::Error); + assert_eq!(Filter::parse("=debug").max(), LevelFilter::Error); + // `*` alone is a prefix of everything. + assert_eq!(Filter::parse("*").level_for("anything"), LevelFilter::Trace); + } + + #[test] + fn timestamps_are_utc_with_milliseconds() { + assert_eq!(timestamp(UNIX_EPOCH), "1970-01-01T00:00:00.000Z"); + // 2026-10-08T07:59:17.728Z + assert_eq!(timestamp(UNIX_EPOCH + Duration::from_millis(1_791_446_357_728)), "2026-10-08T07:59:17.728Z"); + // Leap days, including the 400-year rule. + 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(951_782_400)), "2000-02-29T00:00:00.000Z"); + // The last second of a year. + assert_eq!(timestamp(UNIX_EPOCH + Duration::from_secs(1_767_225_599)), "2025-12-31T23:59:59.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("pdfcraft.1.log")), "run 3"); + assert_eq!(read(&dir.join("pdfcraft.2.log")), "run 2"); + assert!(!dir.join("pdfcraft.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()); + 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", "pdfcraft_ui_egui::recovery", "autosave failed: disk full"), + "2026-10-08T07:59:17.728Z WARN [main] pdfcraft_ui_egui::recovery: autosave failed: disk full\n" + ); + // A multi-line message (a panic with a backtrace) keeps its lines; the record still ends in 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 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!(text.lines().filter(|l| l.starts_with("line ")).count() < 5, "{text}"); + assert_eq!(text.matches("log file reached").count(), 1, "{text}"); + let _ = std::fs::remove_dir_all(&dir); + } + + #[test] + fn the_logger_filters_records_and_writes_them_to_the_attached_file() { + use log::Log; + let dir = temp_dir("logger"); + let logger = AppLogger::new(Filter::parse(DEFAULT_FILTER), false); + let record = |level, target: &'static str, msg: &'static str| { + logger.log(&log::Record::builder().level(level).target(target).args(format_args!("{msg}")).build()); + }; + record(log::Level::Info, "pdfcraft", "moved the PrintCraft settings"); + record(log::Level::Info, "wgpu_core::device", "too chatty"); + let path = logger.attach_dir(&dir).expect("attach"); + assert_eq!(path, dir.join(LOG_FILE)); + record(log::Level::Warn, "wgpu_hal::vulkan", "a real warning"); + record(log::Level::Debug, "pdfcraft", "below info"); + let text = read(&path); + assert!(text.contains(" INFO [") && text.contains("pdfcraft: moved the PrintCraft settings\n"), "{text}"); + assert!(text.contains("wgpu_hal::vulkan: a real warning\n"), "{text}"); + assert!(!text.contains("too chatty") && !text.contains("below info"), "{text}"); + assert!(logger.enabled(&log::Metadata::builder().level(log::Level::Info).target("pdfcraft_ui_egui").build())); + assert!(!logger.enabled(&log::Metadata::builder().level(log::Level::Info).target("naga").build())); + let _ = std::fs::remove_dir_all(&dir); + } + + #[test] + fn attaching_to_an_unusable_directory_reports_an_error_and_keeps_logging() { + use log::Log; + let dir = temp_dir("unusable"); + std::fs::write(&dir, "not a directory").expect("block"); + let logger = AppLogger::new(Filter::parse("info"), false); + assert!(logger.attach_dir(&dir).is_err()); + logger.log(&log::Record::builder().level(log::Level::Error).target("x").args(format_args!("still fine")).build()); + let _ = std::fs::remove_file(&dir); + } + + #[test] + fn a_poisoned_lock_does_not_stop_logging() { + use log::Log; + let dir = temp_dir("poison"); + let logger = AppLogger::new(Filter::parse("info"), false); + let path = logger.attach_dir(&dir).expect("attach"); + std::thread::scope(|s| { + let _ = s + .spawn(|| { + let _guard = logger.sink.lock(); + panic!("poison the sink"); + }) + .join(); + }); + assert!(logger.sink.is_poisoned()); + logger.log(&log::Record::builder().level(log::Level::Warn).target("pdfcraft").args(format_args!("after the panic")).build()); + assert!(read(&path).contains("pdfcraft: after the panic\n")); + let _ = std::fs::remove_dir_all(&dir); + } +} diff --git a/apps/pdfcraft/src/main.rs b/apps/pdfcraft/src/main.rs index ff746770..3dd792fa 100644 --- a/apps/pdfcraft/src/main.rs +++ b/apps/pdfcraft/src/main.rs @@ -22,6 +22,7 @@ use pdfcraft_ui_egui::PdfCraftApp; #[cfg(target_os = "macos")] mod apple_events; +mod logging; mod updates; /// Freedesktop app id: the `.desktop` file name and the hicolor icon name. @@ -37,11 +38,17 @@ const APP_ICON_PNG: &[u8] = include_bytes!("../../../assets/app-icon/hicolor/256 /// The app was called PrintCraft before; settings saved then are under this key. const LEGACY_STORAGE_KEY: &str = "printcraft"; +/// The settings folder: `app.ron` and the `logs` folder (docs/development.md). eframe would +/// otherwise derive it from the app id; keep it under "PdfCraft". +fn settings_dir() -> Option { + eframe::storage_dir("PdfCraft") +} + /// Move the settings and crash-recovery folders of the app's former name, PrintCraft, to the new /// name once, so an upgrade keeps recent files, preferences and unsaved work. Best effort: a /// folder is left alone when the new one already exists or the move fails. fn migrate_legacy_folders() { - let mut moves = vec![(eframe::storage_dir("PrintCraft"), eframe::storage_dir("PdfCraft"))]; + let mut moves = vec![(eframe::storage_dir("PrintCraft"), settings_dir())]; // Recovery lives in the settings folder except on Windows, where it is under %LOCALAPPDATA%. if cfg!(windows) { let local = std::env::var_os("LOCALAPPDATA").filter(|v| !v.is_empty()).map(std::path::PathBuf::from); @@ -55,20 +62,30 @@ fn migrate_legacy_folders() { if let Some(parent) = new.parent() { let _ = std::fs::create_dir_all(parent); } - if let Err(e) = std::fs::rename(&old, &new) { - eprintln!("pdfcraft: moving {} to {}: {e}", old.display(), new.display()); + match std::fs::rename(&old, &new) { + Ok(()) => log::info!("moved {} to {}", old.display(), new.display()), + Err(e) => log::warn!("moving {} to {}: {e}", old.display(), new.display()), } } } fn main() -> eframe::Result { + // First, so the panic hook and every start-up warning are recorded (`logging`). + let logger = logging::install(); // Last-resort guard (AGENTS.md §4): commands, edits, opens and saves catch panics and report // them; this hook logs every panic, caught or not, with a backtrace when RUST_BACKTRACE is set. std::panic::set_hook(Box::new(|info| { - eprintln!("pdfcraft: internal error: {info}"); let trace = std::backtrace::Backtrace::capture(); - if trace.status() == std::backtrace::BacktraceStatus::Captured { - eprintln!("{trace}"); + let report = if trace.status() == std::backtrace::BacktraceStatus::Captured { + format!("internal error: {info}\n{trace}") + } else { + format!("internal error: {info}") + }; + // Standard error and the log file; standard error alone when RUST_LOG turned errors off. + if log::log_enabled!(log::Level::Error) { + log::error!("{report}"); + } else { + eprintln!("pdfcraft: {report}"); } })); let mut files = Vec::new(); @@ -102,14 +119,22 @@ fn main() -> eframe::Result { // Dock, taskbar, Alt-Tab and launcher icon when running unbundled. match eframe::icon_data::from_png_bytes(APP_ICON_PNG) { Ok(icon) => viewport = viewport.with_icon(icon), - Err(e) => eprintln!("pdfcraft: app icon: {e}"), + Err(e) => log::warn!("app icon: {e}"), } if integrated { viewport = viewport.with_fullsize_content_view(true).with_titlebar_shown(false).with_title_shown(false); } migrate_legacy_folders(); - // eframe would otherwise derive the settings folder from the app id: keep it under "PdfCraft". - let persistence_path = eframe::storage_dir("PdfCraft").map(|d| d.join("app.ron")); + // The log file lives in the settings folder; opened after the arguments (so `--version` leaves + // no file behind) and after the PrintCraft migration (which a fresh folder would block). + // Records logged until now are written to it first. + if let (Some(logger), Some(dir)) = (logger, settings_dir()) { + match logger.attach_dir(&dir.join("logs")) { + Ok(path) => log::info!("PdfCraft {}, log file {}", env!("CARGO_PKG_VERSION"), path.display()), + Err(e) => eprintln!("pdfcraft: no log file: {e}"), + } + } + let persistence_path = settings_dir().map(|d| d.join("app.ron")); let mut native = eframe::NativeOptions { viewport, persistence_path, ..Default::default() }; configure_gpu(&mut native); // Finder, Open With and the Dock deliver files as Apple events, not arguments; catch the one @@ -136,8 +161,9 @@ fn main() -> eframe::Result { if let Some(file) = &control_file { let client = app.attach_control(&cc.egui_ctx); match pdfcraft_ui_egui::control::serve(client).and_then(|ep| write_control_file(file, ep.port, &ep.token).map(|()| ep.port)) { - Ok(port) => eprintln!("pdfcraft: UI control channel on 127.0.0.1:{port} (connection details in {file})"), - Err(e) => eprintln!("pdfcraft: --control {file}: {e}"), + // Never the token (AGENTS.md §3): it stays in the owner-only file. + Ok(port) => log::info!("UI control channel on 127.0.0.1:{port} (connection details in {file})"), + Err(e) => log::error!("--control {file}: {e}"), } } // Autosave unsaved changes; offer to recover documents a crashed session left behind. @@ -155,7 +181,7 @@ fn main() -> eframe::Result { } for (k, v) in options { if let Err(e) = app.set_option(&k, &v) { - eprintln!("pdfcraft: --{k} {v}: {e}"); + log::warn!("--{k} {v}: {e}"); } } Ok(Box::new(app)) diff --git a/docs/development.md b/docs/development.md new file mode 100644 index 00000000..ec88ae13 --- /dev/null +++ b/docs/development.md @@ -0,0 +1,33 @@ +# Developing PdfCraft + +Working instructions for agents and contributors are in `AGENTS.md` and `CLAUDE.md`. This page +collects what the desktop app reads from its environment and where it writes its diagnostics. + +## Logs + +The desktop app writes its `log` records to standard error and to `logs/pdfcraft.log` in its +settings folder, next to `app.ron`: Linux and FreeBSD `~/.local/share/pdfcraft/logs/` (or +`$XDG_DATA_HOME/pdfcraft/logs/`), macOS `~/Library/Application Support/PdfCraft/logs/`, Windows +`%APPDATA%\PdfCraft\data\logs\`. A start from a desktop menu, Finder or the Start menu has no +terminal, so this file is what to attach to a bug report: a failed autosave, a page that would not +render, a render worker that could not start and the report of an internal error all land there. +Each launch moves the previous log to `pdfcraft.1.log` (and that one to `pdfcraft.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. + +By default PdfCraft's own crates (`pdfcraft*`) log at `info` and everything else at `warn`. +`RUST_LOG` replaces that with env_logger-style directives, for example `RUST_LOG=debug`, +`RUST_LOG=warn,pdfcraft_render=trace` or `RUST_LOG=info,wgpu_core=warn`; a directive ending in `*` +covers every target starting with it (`pdfcraft*=debug`). The logger is +`apps/pdfcraft/src/logging.rs`. It never records the control-channel token or document passwords. + +## Environment variables + +| Variable | Effect | +|---|---| +| `RUST_LOG` | Log levels for standard error and the log file (see [Logs](#logs)) | +| `RUST_BACKTRACE` | `1` adds a backtrace to the report of an internal error | +| `XDG_DATA_HOME` | Linux/FreeBSD: base of the settings folder (`pdfcraft/`), the log folder and crash recovery | +| `WGPU_POWER_PREF` | GPU choice; by default PdfCraft prefers the low-power (integrated) GPU | +| `WGPU_BACKEND` | Graphics backend; by default Windows uses Direct3D 12, falling back to OpenGL | +| `CRAFT_FONTS_DIR` | Build time: a [craft-fonts](https://github.com/storytold/craft-fonts) checkout to embed (Japanese fonts) |