Desktop: write log records to standard error and a rotating log file
The desktop app installed no logger, so every log::warn!/log::error! in the workspace was discarded: GPU compositor fallbacks, audio output problems, a panicked frame job or audio mixer, container warnings. A launch from a desktop menu has no terminal either, so there was nothing to attach to a bug report. apps/filmcraft/src/logging.rs (no new dependency): - standard error plus <data dir>/Logs/filmcraft.log, next to the crash logs (--data-dir / FILMCRAFT_DATA_DIR respected, Help > Reveal Log Files opens the folder); each launch rotates the previous log to filmcraft.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 data directory is known are buffered (bounded) and written once the file is attached - default levels: info for filmcraft*, 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 - the realtime audio callbacks do not log; a record holds the lock for one write of an already formatted line The logger is installed first in main (before the panic hook) and the file is opened after argument parsing (--help, --version and usage errors leave no file). The start-up eprintln!s in main (auto-save unavailable, open/recovery errors, no window) now go through the logger. Documented in docs/contributing.md (environment variables, Logs).
This commit is contained in:
Gert Pellin
parent
61238bf8fc
commit
2d6c4d3a3d
|
|
@ -0,0 +1,562 @@
|
|||
//! 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 (GPU compositor fallbacks,
|
||||
//! audio output problems, a panicked frame job or audio mixer, container warnings) vanished. A
|
||||
//! launch from a desktop menu has no terminal, so the file is what a bug report can attach:
|
||||
//! `<data dir>/Logs/filmcraft.log`, next to the crash logs (`--data-dir`, `FILMCRAFT_DATA_DIR` or
|
||||
//! `filmcraft_engine::autosave::default_data_dir`; Help ▸ Reveal Log Files opens the folder). Each
|
||||
//! start moves the previous log to `filmcraft.1.log` (and that one to `.2`), so the log of a run
|
||||
//! that crashed survives the next launch.
|
||||
//!
|
||||
//! Levels: `info` for FilmCraft's own crates, `warn` for everything else (wgpu and naga are
|
||||
//! chatty). `RUST_LOG` replaces that with env_logger-style directives: `debug`,
|
||||
//! `warn,filmcraft_codecs=trace`, `wgpu_core=info`. A directive ending in `*` matches every target
|
||||
//! that starts with it (`filmcraft*=debug`).
|
||||
//!
|
||||
//! Records logged before the data 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`, `audio_in.rs`, the play-ahead reader) do not
|
||||
//! log; they report through flags and a one-time `eprintln!`. A record takes the sink lock only for
|
||||
//! one `write_all` of an already formatted line (standard error is written outside the lock), so a
|
||||
//! logging thread such as the audio mixer never waits on more than one other line being written.
|
||||
|
||||
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 = "filmcraft.log";
|
||||
/// The log directory inside the data directory (shared with the crash logs and Reveal Log Files).
|
||||
pub const LOG_DIR: &str = "Logs";
|
||||
/// How many previous logs are kept (`filmcraft.1.log` … `filmcraft.<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,filmcraft*=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; 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!("filmcraft.{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 {
|
||||
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<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.
|
||||
/// An unusable directory leaves standard error as the only sink ([`AppLogger::stderr_only`]).
|
||||
pub fn attach_dir(&self, dir: &Path) -> Result<PathBuf, String> {
|
||||
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 data 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 data 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 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!("filmcraft-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_filmcraft_info_and_other_crates_warnings() {
|
||||
let f = Filter::parse(DEFAULT_FILTER);
|
||||
assert_eq!(f.level_for("filmcraft"), LevelFilter::Info);
|
||||
assert_eq!(f.level_for("filmcraft::audio"), LevelFilter::Info);
|
||||
assert_eq!(f.level_for("filmcraft_ui_egui::play_ahead"), LevelFilter::Info);
|
||||
assert_eq!(f.level_for("filmcraft_codecs::mxf"), 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,filmcraft_codecs=trace,filmcraft_codecs::mxf=off");
|
||||
assert_eq!(f.level_for("eframe"), LevelFilter::Info);
|
||||
assert_eq!(f.level_for("wgpu_core::instance"), LevelFilter::Error);
|
||||
assert_eq!(f.level_for("filmcraft_codecs::ogg"), LevelFilter::Trace);
|
||||
assert_eq!(f.level_for("filmcraft_codecs::mxf"), 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,filmcraft_ui*=debug").level_for("filmcraft_ui_egui::frames"), LevelFilter::Debug);
|
||||
assert_eq!(Filter::parse("warn,filmcraft_ui*=debug").level_for("filmcraft_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",
|
||||
"filmcraft=",
|
||||
"nonsense=loud",
|
||||
"🦀=info",
|
||||
"*",
|
||||
"*=debug",
|
||||
"a=b=c",
|
||||
"warn,,filmcraft=DEBUG",
|
||||
" \t ",
|
||||
"\u{0}",
|
||||
"é*=trace",
|
||||
&long,
|
||||
];
|
||||
for spec in specs {
|
||||
let f = Filter::parse(spec);
|
||||
for target in ["filmcraft", "", "🦀", "é", "a::b"] {
|
||||
let _ = f.level_for(target);
|
||||
}
|
||||
let _ = f.max();
|
||||
}
|
||||
assert_eq!(Filter::parse("warn,,filmcraft=DEBUG").level_for("filmcraft"), 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("filmcraft.1.log")), "run 3");
|
||||
assert_eq!(read(&dir.join("filmcraft.2.log")), "run 2");
|
||||
assert!(!dir.join("filmcraft.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", "filmcraft_ui_egui", "audio output unavailable: no output device"),
|
||||
"2026-10-08T07:59:17.728Z WARN [main] filmcraft_ui_egui: audio output unavailable: no output device\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, "filmcraft", "FilmCraft 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, "filmcraft", "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("filmcraft: FilmCraft 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("filmcraft_engine::autosave").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("filmcraft.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, "filmcraft", "from a worker");
|
||||
}
|
||||
});
|
||||
}
|
||||
});
|
||||
let text = read(&path);
|
||||
assert_eq!(text.lines().count(), 400);
|
||||
assert!(text.lines().all(|l| l.ends_with("filmcraft: 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, "filmcraft", "after the panic");
|
||||
assert!(read(&path).contains("after the panic"));
|
||||
let _ = std::fs::remove_dir_all(&dir);
|
||||
}
|
||||
}
|
||||
|
|
@ -16,6 +16,9 @@
|
|||
//! with unsaved changes the app asks to recover them; `--recover` recovers the newest without
|
||||
//! asking, `--no-recover` starts without asking (the changes stay available via File ▸ Recover
|
||||
//! Unsaved Changes…).
|
||||
//!
|
||||
//! `log` records go to standard error and `<data dir>/Logs/filmcraft.log` (`RUST_LOG` sets the
|
||||
//! levels); see [`logging`].
|
||||
#![cfg_attr(all(target_os = "windows", not(debug_assertions)), windows_subsystem = "windows")]
|
||||
#![cfg_attr(not(test), deny(clippy::unwrap_used, clippy::expect_used, clippy::panic, clippy::unimplemented, clippy::todo, clippy::unreachable))]
|
||||
|
||||
|
|
@ -24,6 +27,7 @@ mod args;
|
|||
mod audio;
|
||||
mod audio_in;
|
||||
mod control_server;
|
||||
mod logging;
|
||||
#[cfg(target_os = "macos")]
|
||||
mod native_menu;
|
||||
mod window_raise;
|
||||
|
|
@ -66,6 +70,8 @@ fn tell(text: &str, error: bool) {
|
|||
}
|
||||
|
||||
fn main() -> eframe::Result {
|
||||
// First, so the panic hook and every start-up record are logged (`logging`).
|
||||
let logger = logging::install();
|
||||
// lossy, so a value that is not Unicode is reported like any other bad port instead of ignored
|
||||
let env_port = std::env::var_os("FILMCRAFT_CONTROL_PORT").map(|p| p.to_string_lossy().into_owned());
|
||||
let Launch { control_port, files, demo, startup_flag, recover, data_dir } = match args::parse(env_port, std::env::args().skip(1)) {
|
||||
|
|
@ -83,10 +89,24 @@ fn main() -> eframe::Result {
|
|||
std::process::exit(2);
|
||||
}
|
||||
};
|
||||
let log_dir = data_dir.clone().or_else(default_data_dir).map(|d| d.join(logging::LOG_DIR));
|
||||
log::info!("FilmCraft {} ({} {})", env!("CARGO_PKG_VERSION"), std::env::consts::OS, std::env::consts::ARCH);
|
||||
// The log file lives next to the crash logs; opened after the arguments, so `--help`,
|
||||
// `--version` and usage errors leave no file behind. Records logged until now go in first.
|
||||
if let Some(logger) = logger {
|
||||
match log_dir.as_deref().map(|d| logger.attach_dir(d)) {
|
||||
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 data directory (set FILMCRAFT_DATA_DIR or --data-dir)");
|
||||
}
|
||||
}
|
||||
}
|
||||
app_nap::disable();
|
||||
// Panics anywhere go to <data dir>/Logs/crash-<day>.log with a backtrace; the UI pass and
|
||||
// frame workers catch them and keep running (see filmcraft_ui_egui::crash).
|
||||
filmcraft_ui_egui::crash::install(data_dir.clone().or_else(default_data_dir).map(|d| d.join("Logs")));
|
||||
filmcraft_ui_egui::crash::install(log_dir);
|
||||
// OS hardware video decoders (VideoToolbox on macOS) in front of our own; Settings ▸ Playback ▸
|
||||
// Hardware decoding switches them off. Unsupported streams and failures use our decoders.
|
||||
register_hardware_decoders();
|
||||
|
|
@ -116,7 +136,7 @@ fn main() -> eframe::Result {
|
|||
let mut cfg = AutosaveConfig::new(dir);
|
||||
cfg.local_offset = local_offset;
|
||||
if let Err(e) = session.start_autosave(cfg) {
|
||||
eprintln!("filmcraft: auto-save and crash recovery unavailable: {e}");
|
||||
log::warn!("auto-save and crash recovery unavailable: {e}");
|
||||
}
|
||||
}
|
||||
// voice-over recording reads the microphone through cpal
|
||||
|
|
@ -124,7 +144,7 @@ fn main() -> eframe::Result {
|
|||
let project = files.iter().find(|f| f.ends_with(".fcproj")).cloned();
|
||||
if let Some(p) = project {
|
||||
if let Err(e) = session.execute("file.open", json!({"path": p})) {
|
||||
eprintln!("filmcraft: {e}");
|
||||
log::error!("{e}");
|
||||
}
|
||||
} else if !startup_flag && session.prefs.general.at_startup == "openMostRecent" {
|
||||
// Settings ▸ General ▸ At Startup ▸ Open Most Recent
|
||||
|
|
@ -132,7 +152,7 @@ fn main() -> eframe::Result {
|
|||
match recent {
|
||||
Some(p) => {
|
||||
if let Err(e) = session.execute("file.open", json!({"path": p})) {
|
||||
eprintln!("filmcraft: {e}");
|
||||
log::error!("{e}");
|
||||
}
|
||||
}
|
||||
None => {
|
||||
|
|
@ -150,8 +170,8 @@ fn main() -> eframe::Result {
|
|||
if recover == Some(true) && !session.recovery_candidates().is_empty() {
|
||||
let id = session.recovery_candidates()[0].id.clone();
|
||||
match session.execute("file.recover", json!({"id": id})) {
|
||||
Ok(r) => eprintln!("filmcraft: recovered {r}"),
|
||||
Err(e) => eprintln!("filmcraft: recovery failed: {e}"),
|
||||
Ok(r) => log::info!("recovered {r}"),
|
||||
Err(e) => log::error!("recovery failed: {e}"),
|
||||
}
|
||||
}
|
||||
let mut app = FilmcraftApp::new(session);
|
||||
|
|
@ -207,7 +227,7 @@ fn main() -> eframe::Result {
|
|||
// instead of exiting silently, and keep the reason in the crash log.
|
||||
if let Err(e) = &started {
|
||||
let msg = format!("FilmCraft could not start its window: {e}\n\nUpdating the graphics driver usually fixes this.");
|
||||
eprintln!("filmcraft: {msg}");
|
||||
log::error!("{msg}");
|
||||
filmcraft_ui_egui::crash::record(&msg);
|
||||
let _ = rfd::MessageDialog::new().set_title("FilmCraft").set_description(&msg).set_level(rfd::MessageLevel::Error).show();
|
||||
}
|
||||
|
|
|
|||
|
|
@ -36,8 +36,13 @@ cargo run --release -p filmcraft-cli -- mcp --demo # headless MCP server on s
|
|||
cargo xtask web --serve 8765 # the web app on http://127.0.0.1:8765/ (docs/web.md)
|
||||
```
|
||||
|
||||
`FILMCRAFT_CONTROL_PORT=9876` works like `--control 9876`, and `FILMCRAFT_CPU_COMPOSITE=1`
|
||||
disables the GPU compositor.
|
||||
| Variable | Effect |
|
||||
|---|---|
|
||||
| `FILMCRAFT_CONTROL_PORT` | Same as `--control <port>` |
|
||||
| `FILMCRAFT_CPU_COMPOSITE=1` | Disables the GPU compositor |
|
||||
| `FILMCRAFT_DATA_DIR` | Same as `--data-dir <dir>`: auto-save, crash recovery, settings and logs |
|
||||
| `RUST_LOG` | Log levels for standard error and the log file (see [Logs](#logs)) |
|
||||
|
||||
`filmcraft --help` lists the app's options. An option it does not know, or a control port that is
|
||||
not a number (from `--control` or from `FILMCRAFT_CONTROL_PORT`), is an error on stderr with exit
|
||||
code 2 instead of a window.
|
||||
|
|
@ -45,6 +50,25 @@ code 2 instead of a window.
|
|||
Dev builds compile dependencies at `opt-level = 2` and workspace crates at `opt-level = 1`. For
|
||||
playback and codec speed, use `--release`.
|
||||
|
||||
### Logs
|
||||
|
||||
The desktop app writes its `log` records to standard error and to `Logs/filmcraft.log` in the data
|
||||
directory (`~/.local/share/filmcraft/Logs/` or `$XDG_DATA_HOME/filmcraft/Logs/` on Linux,
|
||||
`~/Library/Application Support/FilmCraft/Logs/` on macOS, `%APPDATA%\FilmCraft\Logs\` on Windows,
|
||||
or under `--data-dir` / `FILMCRAFT_DATA_DIR`), next to the crash logs; Help ▸ Reveal Log Files opens
|
||||
the folder. A start from a desktop menu or the Dock has no terminal, so this file is what to attach
|
||||
to a bug report: GPU compositor fallbacks, audio output problems, panicked frame jobs and container
|
||||
warnings all land there. Each launch moves the previous log to `filmcraft.1.log` (and that one to
|
||||
`filmcraft.2.log`), so the log of a run that crashed survives the next start. The file stops growing
|
||||
at 16 MiB. `--help`, `--version` and command-line errors write no file.
|
||||
|
||||
By default FilmCraft's own crates 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,filmcraft_codecs=trace` or `RUST_LOG=info,wgpu_core=warn`; a directive ending in `*`
|
||||
covers every target starting with it (`filmcraft*=debug`). The logger is
|
||||
`apps/filmcraft/src/logging.rs`; the realtime audio callbacks do not log. The web app logs to the
|
||||
browser console instead.
|
||||
|
||||
### Building with craft-fonts
|
||||
|
||||
Font assets live in [storytold/craft-fonts](https://github.com/storytold/craft-fonts), never in this
|
||||
|
|
|
|||
Loading…
Reference in New Issue