Files
gridcraft/apps/gridcraft/src/logging.rs
T
Dylan M. Taylor bdf8b8cc75 Use chrono instead of hand-rolled UTC conversion (#2121)
* Use chrono for UTC/calendar conversion instead of hand-rolled copies

Replaces the hand-rolled civil_from_days / days_from_civil copies and the
is_leap / days_in_month calendar helpers with chrono as a workspace dependency
(default-features = false, std only, so wasm is unaffected). The spreadsheet
serial-date semantics are untouched: Excel's 1900 fictitious leap day (serial
60 = 1900-02-29), the 1899-12-30 / 1904-01-01 serial offsets, Excel's weekday
numbering and the 1900/1904 systems keep their explicit special cases in
serial_from_ymd / datetime_from_serial / days_in_month_in. chrono only backs
the plain proleptic-Gregorian day-number <-> date conversion and the
leap-year / month-length helpers those build on; a small fallback keeps the old
answer for dates outside chrono's NaiveDate range. The duplicate local is_leap
in the financial functions now uses the core one. Output is byte-identical and
pinned by the existing date, parse, financial and logging tests. AGENTS.md now
says time goes through chrono.

Follow-up to storytold/cadcraft#1785

* Never panic on out-of-range clocks or years; keep calendar results outside chrono's range

- logging::timestamp: chrono's From<SystemTime> unwraps, so a clock past year
  262143 panicked inside the logger. Use the fallible DateTime::from_timestamp
  and read such a clock as the epoch, like the old saturating code. Years past
  9999 are written with {:04} (not %Y, which prefixes a '+').
- date::is_leap: restore the Gregorian leap-year rule for years outside chrono's
  NaiveDate range (e.g. is_leap(400000) is true again) via direct arithmetic.
- date::days_in_month: compute the December boundary with checked_add so
  days_in_month(i32::MAX, 12) no longer overflows, and compute month lengths
  through days_from_civil's fallback so out-of-range years keep their real
  lengths (e.g. days_in_month(400000, 2) is 29). Invalid months still return 0.
- civil_from_days: add missing docstring.
- AGENTS.md: note the narrow out-of-range fallback exception to the chrono rule.

* Don't build an unrepresentable SystemTime in the far-future test

UNIX_EPOCH + Duration::from_secs(u64::MAX / 2) overflows Windows'
SystemTime and panicked before timestamp() ran, failing the Windows
test job. Build it with checked_add and only assert where it exists.

* Route out-of-range dates through chrono's 400-year cycle, not hand-rolled copies

The PR kept hand-rolled Hinnant `days_from_civil_fallback`/`civil_from_days_fallback`
copies for dates outside chrono's ±262143-year range, plus a hand-rolled
Gregorian leap rule in `is_leap` and an i32::MAX special-case in `days_in_month`.
AGENTS.md carved a "narrow fallback" exception for them, which left calendar
arithmetic outside chrono after all.

Replace all of it with the Gregorian 400-year cycle (146_097 days): chrono
converts the day/year within one cycle and whole cycles are added back via i128
(so the i32/i64 extremes can't overflow). `is_leap` and `days_in_month` reduce
the year with `rem_euclid(400)` (leap years and month lengths repeat every 400
years), which also removes the December `i32::MAX` overflow special-case.

chrono is now the only calendar logic, and every output is unchanged: verified
the cycle result equals the old formula over wide ranges and at the i32/i64
extremes with a scratch chrono program. The Excel 1900 leap bug (serial 60 =
fictitious 1900-02-29) and 1904 semantics are untouched -- `serial_from_ymd`/
`datetime_from_serial` only ever hand the converters in-range years, so their
serials are byte-for-byte the pre-chrono ones (pinned by a new test).

New tests pin `days_from_civil`/`civil_from_days` past chrono's range on both
sides of the epoch, round-tripping, with values from the old formula; the
existing leap/month-length-beyond-range test still passes unchanged. Removed the
AGENTS.md "narrow fallback" exception.

Tested: cargo test -p gridcraft-core -p gridcraft-functions; fmt --check;
clippy --all-targets -D warnings.

* time: preserve out-of-range years in the log timestamp instead of the epoch

`DateTime::from_timestamp(..).unwrap_or_default()` changed the existing output: a
clock set far ahead (an input the old hand-rolled civil-from-days converted)
collapsed to `1970-01-01`. Restore the old conversion domain with a cycle-based
helper: reduce by whole 400-year Gregorian cycles (146_097 days), convert the
in-range remainder with chrono, and carry the year back as i128. Only the year
leaves chrono's range; month/day/time stay exact. Pre-1970 still clamps to the
epoch as before. chrono stays the only calendar logic (no new features).

apps/gridcraft logging.rs `timestamp` (SystemTime, u64 secs), pinned via a
platform-safe `UNIX_EPOCH.checked_add`:
  u64::MAX/2 s → "292277026596-12-04T15:30:07.000Z" (was "1970-01-01..."),
  10e12 s → "318857-05-20T17:46:40.000Z", 253_402_300_800 s → "10000-01-01...".

* Name the 400-year range extension as the one exception to the time rule

The rule said never to hand-roll calendar math, but the range fix
(shifting by whole 400-year Gregorian cycles so dates past chrono's year
range keep their old output) is cycle arithmetic, so the rule and the code
disagreed. The rule now names that exception: the library still computes
month, day and time, and only whole cycles are carried in the year.

* Say the library computes month and day; time-of-day is plain arithmetic

Narrows the range-extension wording: the date library computes the
calendar fields, and splitting seconds into hours, minutes and seconds
is ordinary arithmetic, which is what the code does.
2026-10-23 11:48:02 -04:00

598 lines
26 KiB
Rust

//! 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 sample that failed to
//! build, a graphics adapter warning, a panic a command's guard recovered from) vanished. A launch
//! from a desktop menu has no terminal, so the file is what a bug report can attach:
//! `<settings dir>/logs/gridcraft.log`, next to `ui.json` and `prefs.json` (`config_dir` in
//! `main.rs`). Each start moves the previous log to `gridcraft.1.log` (and that one to `.2`), so
//! the log of a run that crashed survives the next launch. Runs without preferences
//! (`GRIDCRAFT_NO_PREFS`) log to standard error only.
//!
//! Levels: `info` for GridCraft's own crates, `warn` for everything else (wgpu and naga are
//! chatty). `RUST_LOG` replaces that with env_logger-style directives: `debug`,
//! `warn,gridcraft_engine=trace`, `wgpu_core=info`. A directive ending in `*` matches every target
//! that starts with it (`gridcraft*=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.
//!
//! This is the desktop app's logger only; `gridcraft-cli` and `gridcraft-web` set up their own.
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 = "gridcraft.log";
/// How many previous logs are kept (`gridcraft.1.log` … `gridcraft.<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,gridcraft*=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; a clock
/// set absurdly far ahead keeps its real year (years far outside chrono's own range are preserved)
/// instead of panicking.
pub fn timestamp(t: SystemTime) -> String {
let since = t.duration_since(std::time::UNIX_EPOCH).unwrap_or_default();
let (y, dt) = utc_parts(since.as_secs(), since.subsec_nanos());
// `{:04}` rather than `%Y`, which writes a `+` before years past 9999.
format!("{y:04}-{}", dt.format("%m-%dT%H:%M:%S%.3fZ"))
}
/// Unix seconds (+ nanos) → (proleptic Gregorian year, the same wall-clock instant moved into
/// chrono's range by whole 400-year cycles). The Gregorian calendar repeats every 400 years
/// (146_097 days), so month, day and time of day come from chrono and only the year is carried,
/// which keeps every input exact instead of collapsing out-of-range years to the epoch. `secs` is
/// `u64` (the clock is clamped at the epoch before 1970), so `days` always fits an `i64`.
fn utc_parts(secs: u64, nanos: u32) -> (i64, chrono::NaiveDateTime) {
use chrono::Datelike;
let (days, sod) = ((secs / 86_400) as i64, (secs % 86_400) as i64);
let (cycles, rest) = (days.div_euclid(146_097), days.rem_euclid(146_097));
// `rest + 719_163` (1970-01-01 is CE day 719_163) is always a valid CE day, and `sod` < 86_400.
let date = i32::try_from(rest + 719_163).ok().and_then(chrono::NaiveDate::from_num_days_from_ce_opt);
let time = u32::try_from(sod).ok().and_then(|s| chrono::NaiveTime::from_num_seconds_from_midnight_opt(s, nanos.min(999_999_999)));
match (date, time) {
(Some(d), Some(t)) => {
let y = i128::from(d.year()) + i128::from(cycles) * 400;
(i64::try_from(y).unwrap_or(i64::MAX), d.and_time(t))
}
_ => (1970, chrono::NaiveDateTime::default()), // unreachable
}
}
fn numbered(dir: &Path, n: usize) -> PathBuf {
if n == 0 { dir.join(LOG_FILE) } else { dir.join(format!("gridcraft.{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.capped {
// No file is coming ([`Sink::no_file`]): standard error had the line.
} else 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` (a fresh one: the size cap starts over), first the lines kept so far.
pub fn attach(&mut self, file: File) {
self.file = Some(file);
self.written = 0;
self.capped = false;
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(&note);
}
}
/// There will be no log file: forget the lines kept for it and keep no more.
pub fn no_file(&mut self) {
self.pending = Vec::new();
self.dropped = 0;
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.
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. On an error
/// standard error stays the only sink.
pub fn attach_dir(&self, dir: &Path) -> Result<PathBuf, String> {
// A thread that panicked while logging leaves the sink usable: take it back.
let mut sink = self.sink.lock().unwrap_or_else(PoisonError::into_inner);
match rotate(dir) {
Ok((path, file)) => {
sink.attach(file);
Ok(path)
}
Err(e) => {
sink.no_file();
Err(format!("{}: {e}", dir.display()))
}
}
}
/// No log file for this run (runs without preferences): log to standard error only.
pub fn no_file(&self) {
self.sink.lock().unwrap_or_else(PoisonError::into_inner).no_file();
}
}
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;
}
// Formatted before the sink is locked, so a message that logs while it is formatted can't deadlock.
let thread = std::thread::current();
#[allow(clippy::disallowed_methods)] // the desktop app (native only): wasm never runs it
let line =
format_line(&timestamp(SystemTime::now()), record.level(), thread.name().unwrap_or("?"), record.target(), &record.args().to_string());
if self.stderr {
// No terminal (a Windows GUI build, a closed pipe) is not an error worth reporting.
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!("gridcraft-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: &str, msg: &str) {
use log::Log;
logger.log(&log::Record::builder().level(level).target(target).args(format_args!("{msg}")).build());
}
#[test]
fn the_default_filter_shows_gridcraft_info_and_other_crates_warnings() {
let f = Filter::parse(DEFAULT_FILTER);
assert_eq!(f.level_for("gridcraft"), LevelFilter::Info);
assert_eq!(f.level_for("gridcraft::control_server"), LevelFilter::Info);
assert_eq!(f.level_for("gridcraft_engine::sample"), LevelFilter::Info);
assert_eq!(f.level_for("gridcraft_ui_egui::control"), 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,gridcraft_calc=trace,gridcraft_calc::recalc=off");
assert_eq!(f.level_for("eframe"), LevelFilter::Info);
assert_eq!(f.level_for("wgpu_core::instance"), LevelFilter::Error);
assert_eq!(f.level_for("gridcraft_calc::graph"), LevelFilter::Trace);
assert_eq!(f.level_for("gridcraft_calc::recalc"), 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("gridcraft*=debug").level_for("gridcraft_xlsx::read"), LevelFilter::Debug);
assert_eq!(Filter::parse("gridcraft*=debug").level_for("eframe"), LevelFilter::Error);
// 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 and surrounding blanks are ignored.
assert_eq!(Filter::parse(" WARN , gridcraft = Debug ").level_for("gridcraft"), LevelFilter::Debug);
assert_eq!(Filter::parse(" WARN , gridcraft = Debug ").level_for("eframe"), LevelFilter::Warn);
}
#[test]
fn hostile_specs_never_panic_and_fall_back_sensibly() {
let long = "x".repeat(100_000);
let many = "a=info,".repeat(10_000);
for spec in [
"",
",,,",
"=",
"==",
"=debug",
"gridcraft=",
"nonsense=loud",
"🦀=info",
"*",
"*=",
"=*",
"a=b=c",
"warn,,gridcraft=DEBUG",
"\0",
"é::ü=trace",
&long,
&many,
] {
let f = Filter::parse(spec);
for target in ["", "gridcraft", "🦀", "a::b", "*"] {
let _ = f.level_for(target);
}
let _ = f.max();
}
assert_eq!(Filter::parse("warn,,gridcraft=DEBUG").level_for("gridcraft"), LevelFilter::Debug);
// An unknown level is skipped: that target keeps the default.
assert_eq!(Filter::parse("nonsense=loud").level_for("nonsense"), LevelFilter::Error);
assert_eq!(Filter::parse("gridcraft=").level_for("gridcraft"), LevelFilter::Error);
assert_eq!(Filter::parse("=debug").max(), LevelFilter::Error);
assert_eq!(Filter::parse("🦀=info").level_for("🦀::claw"), LevelFilter::Info);
}
#[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");
// A clock set absurdly far ahead (past chrono's own range) keeps its real year rather than
// collapsing to the epoch. Windows' SystemTime can't hold such an instant, so it is built
// with a checked add and only asserted where it exists.
if let Some(far) = UNIX_EPOCH.checked_add(Duration::from_secs(u64::MAX / 2)) {
assert_eq!(timestamp(far), "292277026596-12-04T15:30:07.000Z");
}
if let Some(far) = UNIX_EPOCH.checked_add(Duration::from_secs(10_000_000_000_000)) {
assert_eq!(timestamp(far), "318857-05-20T17:46:40.000Z");
}
// Years past 9999 keep the plain zero-padded year (no `+`).
assert_eq!(timestamp(UNIX_EPOCH + Duration::from_secs(253_402_300_800)), "10000-01-01T00:00:00.000Z");
}
#[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", "gridcraft", "book.xlsx: file not found"),
"2026-10-08T07:59:17.728Z WARN [main] gridcraft: book.xlsx: file not found\n"
);
// A multi-line message 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 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("gridcraft.1.log")), "run 3");
assert_eq!(read(&dir.join("gridcraft.2.log")), "run 2");
assert!(!dir.join("gridcraft.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 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!(text.contains("5 earlier log lines were dropped"), "{text}");
assert!(text.contains("line 0\n") && !text.contains(&format!("line {MAX_PENDING}\n")));
let _ = std::fs::remove_dir_all(&dir);
}
#[test]
fn exactly_a_full_pending_buffer_drops_nothing() {
let dir = temp_dir("full");
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 without_a_file_nothing_is_kept_in_memory() {
let mut sink = Sink::new(MAX_FILE_BYTES);
sink.write("early\n");
sink.no_file();
sink.write("late\n");
assert!(sink.pending.is_empty() && sink.dropped == 0);
}
#[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").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);
record(&logger, log::Level::Info, "gridcraft", "before the settings directory");
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::Error, "gridcraft", "internal error: boom");
record(&logger, log::Level::Debug, "gridcraft", "below info");
let text = read(&path);
let lines: Vec<&str> = text.lines().collect();
assert_eq!(lines.len(), 3, "{text}");
assert!(lines[0].contains(" INFO [") && lines[0].ends_with("gridcraft: before the settings directory"), "{text}");
assert!(lines[1].ends_with("wgpu_hal::vulkan: a real warning"), "{text}");
assert!(lines[2].contains(" ERROR [") && lines[2].ends_with("gridcraft: internal error: boom"), "{text}");
assert!(logger.enabled(&log::Metadata::builder().level(log::Level::Info).target("gridcraft_ui_egui").build()));
assert!(!logger.enabled(&log::Metadata::builder().level(log::Level::Info).target("naga").build()));
// Attaching again rotates: the first log becomes `.1`.
logger.attach_dir(&dir).expect("attach again");
assert_eq!(read(&dir.join("gridcraft.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 = std::sync::Arc::new(AppLogger::new(Filter::parse("info"), false));
let path = logger.attach_dir(&dir).expect("attach");
let workers: Vec<_> = (0..8)
.map(|t| {
let l = std::sync::Arc::clone(&logger);
std::thread::spawn(move || {
for i in 0..100 {
record(&l, log::Level::Info, "gridcraft", &format!("thread {t} record {i}"));
}
})
})
.collect();
for w in workers {
w.join().expect("worker");
}
let text = read(&path);
assert_eq!(text.lines().count(), 800);
assert!(text.lines().all(|l| l.contains(" gridcraft: thread ")), "{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::create_dir_all(dir.parent().expect("parent")).expect("tmp");
std::fs::write(&dir, "not a directory").expect("block");
let logger = AppLogger::new(Filter::parse("info"), false);
assert!(logger.attach_dir(&dir).is_err());
record(&logger, log::Level::Error, "x", "still fine");
// Nothing waits in memory for a file that won't come.
assert!(logger.sink.lock().expect("sink").pending.is_empty());
let _ = std::fs::remove_file(&dir);
}
#[test]
fn a_poisoned_sink_still_logs() {
let dir = temp_dir("poison");
let logger = std::sync::Arc::new(AppLogger::new(Filter::parse("info"), false));
let l = std::sync::Arc::clone(&logger);
let _ = std::thread::spawn(move || {
let _guard = l.sink.lock().expect("lock");
panic!("poison the sink");
})
.join();
assert!(logger.sink.is_poisoned());
let path = logger.attach_dir(&dir).expect("attach");
record(&logger, log::Level::Warn, "gridcraft", "after the poison");
assert!(read(&path).contains("gridcraft: after the poison"));
let _ = std::fs::remove_dir_all(&dir);
}
}