diff --git a/tracing-appender/Cargo.toml b/tracing-appender/Cargo.toml index c7716a2564..97d1e7d0ca 100644 --- a/tracing-appender/Cargo.toml +++ b/tracing-appender/Cargo.toml @@ -22,7 +22,7 @@ rust-version = "1.53.0" [dependencies] crossbeam-channel = "0.5.6" -time = { version = "0.3.2", default-features = false, features = ["formatting"] } +time = { version = "0.3.2", default-features = false, features = ["formatting", "parsing"] } parking_lot = { optional = true, version = "0.12.1" } thiserror = "1" @@ -33,10 +33,8 @@ default-features = false features = ["fmt", "std"] [dev-dependencies] - criterion = { version = "0.3.6", default-features = false } tracing = { path = "../tracing", version = "0.1.35" } -time = { version = "0.3.2", default-features = false, features = ["formatting", "parsing"] } tempfile = "3" [[bench]] diff --git a/tracing-appender/src/rolling.rs b/tracing-appender/src/rolling.rs index 8e9597c29a..8e630cc9e1 100644 --- a/tracing-appender/src/rolling.rs +++ b/tracing-appender/src/rolling.rs @@ -34,7 +34,7 @@ use std::{ path::{Path, PathBuf}, sync::atomic::{AtomicUsize, Ordering}, }; -use time::{format_description, Duration, OffsetDateTime, Time}; +use time::{format_description, Date, Duration, OffsetDateTime, Time}; mod builder; pub use builder::{Builder, InitError}; @@ -104,8 +104,10 @@ struct Inner { log_directory: PathBuf, log_filename_prefix: Option, log_filename_suffix: Option, + date_format: Vec>, rotation: Rotation, next_date: AtomicUsize, + max_files: Option, } // === impl RollingFileAppender === @@ -187,6 +189,7 @@ impl RollingFileAppender { ref rotation, ref prefix, ref suffix, + ref max_files, } = builder; let directory = directory.as_ref().to_path_buf(); let now = OffsetDateTime::now_utc(); @@ -196,6 +199,7 @@ impl RollingFileAppender { directory, prefix.clone(), suffix.clone(), + *max_files, )?; Ok(Self { state, @@ -242,7 +246,7 @@ impl<'a> tracing_subscriber::fmt::writer::MakeWriter<'a> for RollingFileAppender // Did we get the right to lock the file? If not, another thread // did it and we can just make a writer. if self.state.advance_date(now, current_time) { - self.state.refresh_writer(now, &mut *self.writer.write()); + self.state.refresh_writer(now, &mut self.writer.write()); } } RollingWriter(self.writer.read()) @@ -488,32 +492,14 @@ impl Rotation { } } - pub(crate) fn join_date( - &self, - filename: Option<&str>, - date: &OffsetDateTime, - suffix: Option<&str>, - ) -> String { - let format = match *self { + fn date_format(&self) -> Vec> { + match *self { Rotation::MINUTELY => format_description::parse("[year]-[month]-[day]-[hour]-[minute]"), Rotation::HOURLY => format_description::parse("[year]-[month]-[day]-[hour]"), Rotation::DAILY => format_description::parse("[year]-[month]-[day]"), Rotation::NEVER => format_description::parse("[year]-[month]-[day]"), } - .expect("Unable to create a formatter; this is a bug in tracing-appender"); - let date = date - .format(&format) - .expect("Unable to format OffsetDateTime; this is a bug in tracing-appender"); - - match (self, filename, suffix) { - (&Rotation::NEVER, Some(filename), None) => filename.to_string(), - (&Rotation::NEVER, Some(filename), Some(suffix)) => format!("{}.{}", filename, suffix), - (&Rotation::NEVER, None, Some(suffix)) => suffix.to_string(), - (_, Some(filename), Some(suffix)) => format!("{}.{}.{}", filename, date, suffix), - (_, Some(filename), None) => format!("{}.{}", filename, date), - (_, None, Some(suffix)) => format!("{}.{}", date, suffix), - (_, None, None) => date, - } + .expect("Unable to create a formatter; this is a bug in tracing-appender") } } @@ -538,36 +524,122 @@ impl Inner { directory: impl AsRef, log_filename_prefix: Option, log_filename_suffix: Option, + max_files: Option, ) -> Result<(Self, RwLock), builder::InitError> { let log_directory = directory.as_ref().to_path_buf(); - let filename = rotation.join_date( - log_filename_prefix.as_deref(), - &now, - log_filename_suffix.as_deref(), - ); + let date_format = rotation.date_format(); let next_date = rotation.next_date(&now); - let writer = RwLock::new(create_writer(log_directory.as_ref(), &filename)?); let inner = Inner { log_directory, log_filename_prefix, log_filename_suffix, + date_format, next_date: AtomicUsize::new( next_date .map(|date| date.unix_timestamp() as usize) .unwrap_or(0), ), rotation, + max_files, }; + let filename = inner.join_date(&now); + let writer = RwLock::new(create_writer(inner.log_directory.as_ref(), &filename)?); Ok((inner, writer)) } + pub(crate) fn join_date(&self, date: &OffsetDateTime) -> String { + let date = date + .format(&self.date_format) + .expect("Unable to format OffsetDateTime; this is a bug in tracing-appender"); + + match ( + &self.rotation, + &self.log_filename_prefix, + &self.log_filename_suffix, + ) { + (&Rotation::NEVER, Some(filename), None) => filename.to_string(), + (&Rotation::NEVER, Some(filename), Some(suffix)) => format!("{}.{}", filename, suffix), + (&Rotation::NEVER, None, Some(suffix)) => suffix.to_string(), + (_, Some(filename), Some(suffix)) => format!("{}.{}.{}", filename, date, suffix), + (_, Some(filename), None) => format!("{}.{}", filename, date), + (_, None, Some(suffix)) => format!("{}.{}", date, suffix), + (_, None, None) => date, + } + } + + fn prune_old_logs(&self, max_files: usize) { + let files = fs::read_dir(&self.log_directory).map(|dir| { + dir.filter_map(|entry| { + let entry = entry.ok()?; + let metadata = entry.metadata().ok()?; + + // the appender only creates files, not directories or symlinks, + // so we should never delete a dir or symlink. + if !metadata.is_file() { + return None; + } + + let filename = entry.file_name(); + // if the filename is not a UTF-8 string, skip it. + let filename = filename.to_str()?; + if let Some(prefix) = &self.log_filename_prefix { + if !filename.starts_with(prefix) { + return None; + } + } + + if let Some(suffix) = &self.log_filename_suffix { + if !filename.ends_with(suffix) { + return None; + } + } + + if self.log_filename_prefix.is_none() + && self.log_filename_suffix.is_none() + && Date::parse(filename, &self.date_format).is_err() + { + return None; + } + + let created = metadata.created().ok()?; + Some((entry, created)) + }) + .collect::>() + }); + + let mut files = match files { + Ok(files) => files, + Err(error) => { + eprintln!("Error reading the log directory/files: {}", error); + return; + } + }; + if files.len() < max_files { + return; + } + + // sort the files by their creation timestamps. + files.sort_by_key(|(_, created_at)| *created_at); + + // delete files, so that (n-1) files remain, because we will create another log file + for (file, _) in files.iter().take(files.len() - (max_files - 1)) { + if let Err(error) = fs::remove_file(file.path()) { + eprintln!( + "Failed to remove old log file {}: {}", + file.path().display(), + error + ); + } + } + } + fn refresh_writer(&self, now: OffsetDateTime, file: &mut File) { - let filename = self.rotation.join_date( - self.log_filename_prefix.as_deref(), - &now, - self.log_filename_suffix.as_deref(), - ); + let filename = self.join_date(&now); + + if let Some(max_files) = self.max_files { + self.prune_old_logs(max_files); + } match create_writer(&self.log_directory, &filename) { Ok(new_file) => { @@ -727,66 +799,212 @@ mod test { } #[test] - fn test_path_concatination() { + fn test_path_concatenation() { let format = format_description::parse( "[year]-[month]-[day] [hour]:[minute]:[second] [offset_hour \ sign:mandatory]:[offset_minute]:[offset_second]", ) .unwrap(); + let directory = tempfile::tempdir().expect("failed to create tempdir"); let now = OffsetDateTime::parse("2020-02-01 10:01:00 +00:00:00", &format).unwrap(); - // per-minute - let path = Rotation::MINUTELY.join_date(Some("app.log"), &now, None); - assert_eq!("app.log.2020-02-01-10-01", path); + struct TestCase { + expected: &'static str, + rotation: Rotation, + prefix: Option<&'static str>, + suffix: Option<&'static str>, + } - // per-hour - let path = Rotation::HOURLY.join_date(Some("app.log"), &now, None); - assert_eq!("app.log.2020-02-01-10", path); + let test = |TestCase { + expected, + rotation, + prefix, + suffix, + }| { + let (inner, _) = Inner::new( + now, + rotation.clone(), + directory.path(), + prefix.map(ToString::to_string), + suffix.map(ToString::to_string), + None, + ) + .unwrap(); + let path = inner.join_date(&now); + assert_eq!( + expected, path, + "rotation = {:?}, prefix = {:?}, suffix = {:?}", + rotation, prefix, suffix + ); + }; - // per-day - let path = Rotation::DAILY.join_date(Some("app.log"), &now, None); - assert_eq!("app.log.2020-02-01", path); + let test_cases = vec![ + // prefix only + TestCase { + expected: "app.log.2020-02-01-10-01", + rotation: Rotation::MINUTELY, + prefix: Some("app.log"), + suffix: None, + }, + TestCase { + expected: "app.log.2020-02-01-10", + rotation: Rotation::HOURLY, + prefix: Some("app.log"), + suffix: None, + }, + TestCase { + expected: "app.log.2020-02-01", + rotation: Rotation::DAILY, + prefix: Some("app.log"), + suffix: None, + }, + TestCase { + expected: "app.log", + rotation: Rotation::NEVER, + prefix: Some("app.log"), + suffix: None, + }, + // prefix and suffix + TestCase { + expected: "app.2020-02-01-10-01.log", + rotation: Rotation::MINUTELY, + prefix: Some("app"), + suffix: Some("log"), + }, + TestCase { + expected: "app.2020-02-01-10.log", + rotation: Rotation::HOURLY, + prefix: Some("app"), + suffix: Some("log"), + }, + TestCase { + expected: "app.2020-02-01.log", + rotation: Rotation::DAILY, + prefix: Some("app"), + suffix: Some("log"), + }, + TestCase { + expected: "app.log", + rotation: Rotation::NEVER, + prefix: Some("app"), + suffix: Some("log"), + }, + // suffix only + TestCase { + expected: "2020-02-01-10-01.log", + rotation: Rotation::MINUTELY, + prefix: None, + suffix: Some("log"), + }, + TestCase { + expected: "2020-02-01-10.log", + rotation: Rotation::HOURLY, + prefix: None, + suffix: Some("log"), + }, + TestCase { + expected: "2020-02-01.log", + rotation: Rotation::DAILY, + prefix: None, + suffix: Some("log"), + }, + TestCase { + expected: "log", + rotation: Rotation::NEVER, + prefix: None, + suffix: Some("log"), + }, + ]; + for test_case in test_cases { + test(test_case) + } + } - // never - let path = Rotation::NEVER.join_date(Some("app.log"), &now, None); - assert_eq!("app.log", path); + #[test] + fn test_make_writer() { + use std::sync::{Arc, Mutex}; + use tracing_subscriber::prelude::*; - // per-minute with suffix - let path = Rotation::MINUTELY.join_date(Some("app"), &now, Some("log")); - assert_eq!("app.2020-02-01-10-01.log", path); + let format = format_description::parse( + "[year]-[month]-[day] [hour]:[minute]:[second] [offset_hour \ + sign:mandatory]:[offset_minute]:[offset_second]", + ) + .unwrap(); - // per-hour with suffix - let path = Rotation::HOURLY.join_date(Some("app"), &now, Some("log")); - assert_eq!("app.2020-02-01-10.log", path); + let now = OffsetDateTime::parse("2020-02-01 10:01:00 +00:00:00", &format).unwrap(); + let directory = tempfile::tempdir().expect("failed to create tempdir"); + let (state, writer) = Inner::new( + now, + Rotation::HOURLY, + directory.path(), + Some("test_make_writer".to_string()), + None, + None, + ) + .unwrap(); + + let clock = Arc::new(Mutex::new(now)); + let now = { + let clock = clock.clone(); + Box::new(move || *clock.lock().unwrap()) + }; + let appender = RollingFileAppender { state, writer, now }; + let default = tracing_subscriber::fmt() + .without_time() + .with_level(false) + .with_target(false) + .with_max_level(tracing_subscriber::filter::LevelFilter::TRACE) + .with_writer(appender) + .finish() + .set_default(); + + tracing::info!("file 1"); - // per-day with suffix - let path = Rotation::DAILY.join_date(Some("app"), &now, Some("log")); - assert_eq!("app.2020-02-01.log", path); + // advance time by one second + (*clock.lock().unwrap()) += Duration::seconds(1); - // never with suffix - let path = Rotation::NEVER.join_date(Some("app"), &now, Some("log")); - assert_eq!("app.log", path); + tracing::info!("file 1"); - // per-minute without prefix - let path = Rotation::MINUTELY.join_date(None, &now, Some("app.log")); - assert_eq!("2020-02-01-10-01.app.log", path); + // advance time by one hour + (*clock.lock().unwrap()) += Duration::hours(1); - // per-hour without prefix - let path = Rotation::HOURLY.join_date(None, &now, Some("app.log")); - assert_eq!("2020-02-01-10.app.log", path); + tracing::info!("file 2"); - // per-day without prefix - let path = Rotation::DAILY.join_date(None, &now, Some("app.log")); - assert_eq!("2020-02-01.app.log", path); + // advance time by one second + (*clock.lock().unwrap()) += Duration::seconds(1); + + tracing::info!("file 2"); + + drop(default); + + let dir_contents = fs::read_dir(directory.path()).expect("Failed to read directory"); + println!("dir={:?}", dir_contents); + for entry in dir_contents { + println!("entry={:?}", entry); + let path = entry.expect("Expected dir entry").path(); + let file = fs::read_to_string(&path).expect("Failed to read file"); + println!("path={}\nfile={:?}", path.display(), file); - // never without prefix - let path = Rotation::NEVER.join_date(None, &now, Some("app.log")); - assert_eq!("app.log", path); + match path + .extension() + .expect("found a file without a date!") + .to_str() + .expect("extension should be UTF8") + { + "2020-02-01-10" => { + assert_eq!("file 1\nfile 1\n", file); + } + "2020-02-01-11" => { + assert_eq!("file 2\nfile 2\n", file); + } + x => panic!("unexpected date {}", x), + } + } } #[test] - fn test_make_writer() { + fn test_max_log_files() { use std::sync::{Arc, Mutex}; use tracing_subscriber::prelude::*; @@ -802,8 +1020,9 @@ mod test { now, Rotation::HOURLY, directory.path(), - Some("test_make_writer".to_string()), + Some("test_max_log_files".to_string()), None, + Some(2), ) .unwrap(); @@ -832,6 +1051,11 @@ mod test { // advance time by one hour (*clock.lock().unwrap()) += Duration::hours(1); + // depending on the filesystem, the creation timestamp's resolution may + // be as coarse as one second, so we need to wait a bit here to ensure + // that the next file actually is newer than the old one. + std::thread::sleep(std::time::Duration::from_secs(1)); + tracing::info!("file 2"); // advance time by one second @@ -839,10 +1063,24 @@ mod test { tracing::info!("file 2"); + // advance time by one hour + (*clock.lock().unwrap()) += Duration::hours(1); + + // again, sleep to ensure that the creation timestamps actually differ. + std::thread::sleep(std::time::Duration::from_secs(1)); + + tracing::info!("file 3"); + + // advance time by one second + (*clock.lock().unwrap()) += Duration::seconds(1); + + tracing::info!("file 3"); + drop(default); let dir_contents = fs::read_dir(directory.path()).expect("Failed to read directory"); println!("dir={:?}", dir_contents); + for entry in dir_contents { println!("entry={:?}", entry); let path = entry.expect("Expected dir entry").path(); @@ -856,11 +1094,14 @@ mod test { .expect("extension should be UTF8") { "2020-02-01-10" => { - assert_eq!("file 1\nfile 1\n", file); + panic!("this file should have been pruned already!"); } "2020-02-01-11" => { assert_eq!("file 2\nfile 2\n", file); } + "2020-02-01-12" => { + assert_eq!("file 3\nfile 3\n", file); + } x => panic!("unexpected date {}", x), } } diff --git a/tracing-appender/src/rolling/builder.rs b/tracing-appender/src/rolling/builder.rs index ea5d39cd5f..8c92ca1238 100644 --- a/tracing-appender/src/rolling/builder.rs +++ b/tracing-appender/src/rolling/builder.rs @@ -10,6 +10,7 @@ pub struct Builder { pub(super) rotation: Rotation, pub(super) prefix: Option, pub(super) suffix: Option, + pub(super) max_files: Option, } /// Errors returned by [`Builder::build`]. @@ -39,15 +40,20 @@ impl Builder { /// | :-------- | :------------ | :---- | /// | [`rotation`] | [`Rotation::NEVER`] | By default, log files will never be rotated. | /// | [`filename_prefix`] | `""` | By default, log file names will not have a prefix. | + /// | [`filename_suffix`] | `""` | By default, log file names will not have a suffix. | + /// | [`max_log_files`] | `None` | By default, there is no limit for maximum log file count. | /// /// [`rotation`]: Self::rotation /// [`filename_prefix`]: Self::filename_prefix + /// [`filename_suffix`]: Self::filename_suffix + /// [`max_log_files`]: Self::max_log_files #[must_use] pub const fn new() -> Self { Self { rotation: Rotation::NEVER, prefix: None, suffix: None, + max_files: None, } } @@ -181,6 +187,52 @@ impl Builder { Self { suffix, ..self } } + /// Keeps the last `n` log files on disk. + /// + /// When a new log file is created, if there are `n` or more + /// existing log files in the directory, the oldest will be deleted. + /// If no value is supplied, the `RollingAppender` will not remove any files. + /// + /// Files are considered candidates for deletion based on the following + /// criteria: + /// + /// * The file must not be a directory or symbolic link. + /// * If the appender is configured with a [`filename_prefix`], the file + /// name must start with that prefix. + /// * If the appender is configured with a [`filename_suffix`], the file + /// name must end with that suffix. + /// * If the appender has neither a filename prefix nor a suffix, then the + /// file name must parse as a valid date based on the appender's date + /// format. + /// + /// Files matching these criteria may be deleted if the maximum number of + /// log files in the directory has been reached. + /// + /// [`filename_prefix`]: Self::filename_prefix + /// [`filename_suffix`]: Self::filename_suffix + /// + /// # Examples + /// + /// ``` + /// use tracing_appender::rolling::RollingFileAppender; + /// + /// # fn docs() { + /// let appender = RollingFileAppender::builder() + /// .max_log_files(5) // only the most recent 5 log files will be kept + /// // ... + /// .build("/var/log") + /// .expect("failed to initialize rolling file appender"); + /// # drop(appender) + /// # } + /// ``` + #[must_use] + pub fn max_log_files(self, n: usize) -> Self { + Self { + max_files: Some(n), + ..self + } + } + /// Builds a new [`RollingFileAppender`] with the configured parameters, /// emitting log files to the provided directory. ///