From 7d5c10a2de1c4c3a804f6f501873b7f9a63ea257 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=C3=96zg=C3=BCn=20=C3=96zerk?= Date: Sat, 24 Sep 2022 23:57:01 +0300 Subject: [PATCH] appender: add option to automatically delete old log files (#2323) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ## Motivation `tracing-appender` does not have `Rotation` based on size yet. Also, it doesn't have the feature of keeping the most recent `N` log files I believe the second feature is more easy to implement, and also will partially solve the `Rotation` based on size problem. Because people may choose `hourly` or `daily` rotation based on their needs, and put an extra boundary of `keep the last 5 files` for example. Of course it won't handle all the edge cases for `Rotation` based on size. But it will cover most of the scenarios. And also, it is a good feature to have on its own :) ## Solution Introduce another field called `max_files: Option` to the `Inner` of `RollingFileAppender` struct. I managed to did not touch any of the existing functions, so it **WON'T BE A BREAKING CHANGE**. Yay :) The solution is, whenever the rotation should happen, the `refresh_writer()` is called. So I embed the following logic into that function: 1- check the log folder and detect the log files 2- if there are more log files than the `max_files` amount 3- store the filenames in a vector, and sort them by their dates (dates are already present in the filename) 4- keep deleting the oldest ones, till we have desired amount of log files in the log folder P.S. this PR was opened before, but got closed since it would be easier for the maintainers to target `master` branch instead of `v0.1.x` Also, @CBenoit contributed to this PR, it would be great to give credit to him :) Co-authored-by: Benoît Cortier Co-authored-by: Eliza Weisman --- tracing-appender/Cargo.toml | 4 +- tracing-appender/src/rolling.rs | 389 +++++++++++++++++++----- tracing-appender/src/rolling/builder.rs | 52 ++++ 3 files changed, 368 insertions(+), 77 deletions(-) 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. ///