mirror of
https://github.com/storytold/pdfcraft.git
synced 2026-10-14 19:27:04 -04:00
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 <settings dir>/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).
This commit is contained in:
1 parent
eb46a993bf
commit
1d31c230c9
6 files changed
+550
-12
No files matched your search
Generated
+1
@@ -3452,6 +3452,7 @@ dependencies = [
|
||||
"eframe",
|
||||
"egui",
|
||||
"fmv-macos-events",
|
||||
"log",
|
||||
"pdfcraft-ui-egui",
|
||||
"rustls-native-certs",
|
||||
"serde_json",
|
||||
|
||||
@@ -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.
|
||||
|
||||
@@ -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
|
||||
|
||||
@@ -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:
|
||||
//! `<settings dir>/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.<KEEP>.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<LevelFilter> {
|
||||
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` → … → `.<KEEP>.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: `<timestamp> <LEVEL> [<thread>] <target>: <message>\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<File>,
|
||||
pending: Vec<String>,
|
||||
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<Sink>,
|
||||
}
|
||||
|
||||
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<PathBuf, String> {
|
||||
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<AppLogger> = 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);
|
||||
}
|
||||
}
|
||||
+38
-12
@@ -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<std::path::PathBuf> {
|
||||
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))
|
||||
|
||||
@@ -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) |
|
||||
Reference in new issue
Block a user