From 2c4dfabab3aa286ec17955a201adde939ed08a4b Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Beno=C3=AEt=20CORTIER?= Date: Tue, 5 Sep 2023 19:12:22 -0400 Subject: [PATCH] Format date according to `Timed` and do not create too many files Follow the date format induced by the selected `Timed`. An index is inserted into the file name so we can rotate when the max size is reached. Also, when the most recent file does not exceed the max size, we simply reuse it instead of creating yet another file. --- tracing-appender/src/rolling.rs | 422 +++++++++++++++++++++++++------- 1 file changed, 337 insertions(+), 85 deletions(-) diff --git a/tracing-appender/src/rolling.rs b/tracing-appender/src/rolling.rs index b9bd86de65..8ccc3a2608 100644 --- a/tracing-appender/src/rolling.rs +++ b/tracing-appender/src/rolling.rs @@ -111,6 +111,7 @@ struct Inner { log_directory: PathBuf, log_filename_prefix: Option, log_filename_suffix: Option, + log_filename_index: Option, date_format: Vec>, rotation: Rotation, next_date: AtomicUsize, @@ -232,7 +233,7 @@ impl io::Write for RollingFileAppender { let now = self.now(); let writer = self.writer.get_mut(); if let Some(current_time) = self.state.should_rollover(now) { - let did_cas = self.state.advance_date(now, current_time); + let did_cas = self.state.advance_date_and_index(now, current_time); debug_assert!(did_cas, "if we have &mut access to the appender, no other thread can have advanced the timestamp..."); self.state.refresh_writer(now, writer); } @@ -262,7 +263,7 @@ impl<'a> tracing_subscriber::fmt::writer::MakeWriter<'a> for RollingFileAppender if let Some(current_time) = self.state.should_rollover(now) { // 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) { + if self.state.advance_date_and_index(now, current_time) { self.state.refresh_writer(now, &mut self.writer.write()); } } @@ -606,18 +607,11 @@ impl Rotation { } fn date_format(&self) -> Vec> { - if self.max_bytes.is_some() { - // Very specific format description to avoid conflicts in case logs are filled very quickly - format_description::parse("[year]-[month]-[day]-[hour]-[minute]-[second]") - } else { - match self.timed { - Timed::Minutely => { - format_description::parse("[year]-[month]-[day]-[hour]-[minute]") - } - Timed::Hourly => format_description::parse("[year]-[month]-[day]-[hour]"), - Timed::Daily => format_description::parse("[year]-[month]-[day]"), - Timed::Never => format_description::parse("[year]-[month]-[day]"), - } + match self.timed { + Timed::Minutely => format_description::parse("[year]-[month]-[day]-[hour]-[minute]"), + Timed::Hourly => format_description::parse("[year]-[month]-[day]-[hour]"), + Timed::Daily => format_description::parse("[year]-[month]-[day]"), + Timed::Never => format_description::parse("[year]-[month]-[day]"), } .expect("Unable to create a formatter; this is a bug in tracing-appender") } @@ -659,6 +653,7 @@ impl Inner { log_directory, log_filename_prefix, log_filename_suffix, + log_filename_index: None, date_format, next_date: AtomicUsize::new( next_date @@ -670,6 +665,11 @@ impl Inner { current_size: Arc::new(AtomicU64::new(0)), }; + if let Some(max_bytes) = inner.rotation.max_bytes { + let next_index = inner.find_filename_index(max_bytes); + inner.log_filename_index = Some(AtomicU64::new(next_index)); + } + let filename = inner.join_date(&now); let file = create_writer(inner.log_directory.as_ref(), &filename)?; @@ -685,64 +685,186 @@ impl Inner { } pub(crate) fn join_date(&self, date: &OffsetDateTime) -> String { + macro_rules! insert_dot { + ($name:ident) => { + if !$name.is_empty() { + $name.push_str("."); + } + }; + } + let date = date .format(&self.date_format) .expect("Unable to format OffsetDateTime; this is a bug in tracing-appender"); - match ( - self.rotation.timed, - self.rotation.max_bytes, - &self.log_filename_prefix, - &self.log_filename_suffix, - ) { - (Timed::Never, None, Some(filename), None) => filename.to_string(), - (Timed::Never, None, Some(filename), Some(suffix)) => { - format!("{}.{}", filename, suffix) + let mut filename = String::new(); + + if let Some(prefix) = &self.log_filename_prefix { + filename.push_str(prefix); + }; + + match self.rotation.timed { + // Insert the date when there is time-based rotations + Timed::Minutely | Timed::Hourly | Timed::Daily => { + insert_dot!(filename); + filename.push_str(&date); } - (Timed::Never, None, 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, + // "Never" but no prefix and no suffix means we should use the date anyway + // The date is always included when there is a filename index (size-based rotation) + Timed::Never + if (self.log_filename_prefix.is_none() && self.log_filename_suffix.is_none()) + || self.log_filename_index.is_some() => + { + insert_dot!(filename); + filename.push_str(&date); + } + // Otherwise, the date must not be inserted + Timed::Never => {} + } + + if let Some(index) = &self.log_filename_index { + insert_dot!(filename); + filename.push_str(&index.load(Ordering::Acquire).to_string()); + } + + if let Some(suffix) = &self.log_filename_suffix { + insert_dot!(filename); + filename.push_str(suffix); } + + // Sanity check: we should never end up with an empty filename + assert!( + !filename.is_empty(), + "log file name should never be empty; this is a bug in tracing-appender" + ); + + filename } - 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()?; + fn filter_log_file(&self, entry: &fs::DirEntry) -> Option { + 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; - } + // 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; - } - } + let filename = entry.file_name(); - if let Some(suffix) = &self.log_filename_suffix { - if !filename.ends_with(suffix) { - return None; - } - } + // if the filename is not a UTF-8 string, skip it. + let mut filename = filename.to_str()?; - if self.log_filename_prefix.is_none() - && self.log_filename_suffix.is_none() - && Date::parse(filename, &self.date_format).is_err() - { - return None; + if let Some(prefix) = &self.log_filename_prefix { + let striped = filename.strip_prefix(prefix)?; + filename = striped; + } + + if let Some(suffix) = &self.log_filename_suffix { + let striped = filename.strip_suffix(suffix)?; + filename = striped; + } + + let mut first_generation_date = None; + let mut found_index = None; + + match (self.rotation.timed, &self.log_filename_index) { + (Timed::Never, None) + if self.log_filename_prefix.is_none() && self.log_filename_suffix.is_none() => + { + let date = Date::parse(filename, &self.date_format).ok()?; + first_generation_date = Some(date); + } + (Timed::Never, Some(_)) => { + let index = filename.parse::().ok()?; + found_index = Some(index); + } + (_, None) => { + let date = Date::parse(filename, &self.date_format).ok(); + first_generation_date = date; + } + (_, Some(_)) => { + // Check for . pattern + + let dot_idx = filename.find('.')?; + + let date_segment = &filename[..dot_idx]; + let index_segment = &filename[dot_idx + 1..]; + + let date = Date::parse(date_segment, &self.date_format).ok()?; + let index = index_segment.parse::().ok()?; + + first_generation_date = Some(date); + found_index = Some(index); + } + } + + if self.log_filename_prefix.is_none() + && self.log_filename_suffix.is_none() + && found_index.is_none() + && first_generation_date.is_none() + { + return None; + } + + let created_at = metadata.created().ok()?; + + Some(FilteredLogFile { + path: entry.path(), + metadata, + created_at, + rounded_date: first_generation_date, + index: found_index, + }) + } + + fn find_filename_index(&self, max_bytes: u64) -> u64 { + macro_rules! unwrap_or_zero { + ($value:expr) => { + if let Some(value) = $value { + value + } else { + return 0; } + }; + } + + let read_dir = unwrap_or_zero!(fs::read_dir(&self.log_directory).ok()); + + let mut files: Vec = read_dir + .filter_map(|entry| { + let entry = entry.ok()?; + self.filter_log_file(&entry) + }) + .collect(); - let created = metadata.created().ok()?; - Some((entry, created)) + files.sort_unstable_by_key(|file| file.created_at); + + let most_recent_file = unwrap_or_zero!(files.last().cloned()); + + let most_recent_rounded_date = &most_recent_file.rounded_date; + + let latest_file = files + .into_iter() + .filter(|log_file| log_file.rounded_date.eq(most_recent_rounded_date)) + .max_by_key(|log_file| log_file.index); + let latest_file = unwrap_or_zero!(latest_file); + + let index = unwrap_or_zero!(latest_file.index); + + // Increase the index if the latest file was too big + if latest_file.metadata.len() > max_bytes { + index + 1 + } else { + index + } + } + + 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()?; + self.filter_log_file(&entry) }) .collect::>() }); @@ -759,14 +881,14 @@ impl Inner { } // sort the files by their creation timestamps. - files.sort_by_key(|(_, created_at)| *created_at); + files.sort_by_key(|log_file| log_file.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()) { + 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(), + file.path.display(), error ); } @@ -803,14 +925,16 @@ impl Inner { fn should_rollover(&self, date: OffsetDateTime) -> Option { let next_date = self.next_date.load(Ordering::Acquire); + // if there is a maximum size for the file, check that it is not exceeded match self.rotation.max_bytes { Some(max_bytes) if self.current_size.load(Ordering::Acquire) > max_bytes => { + // maximum size is exceeded, the appender should rotate immediately return Some(next_date); } _ => {} } - // if the next date is 0, this appender *never* rotates log files. + // otherwise, if the next date is 0, this appender *never* rotates log files. if next_date == 0 { return None; } @@ -822,15 +946,30 @@ impl Inner { None } - fn advance_date(&self, now: OffsetDateTime, current: usize) -> bool { + fn advance_date_and_index(&self, now: OffsetDateTime, current: usize) -> bool { let next_date = self .rotation .next_date(&now) .map(|date| date.unix_timestamp() as usize) .unwrap_or(0); - self.next_date + let next_date_updated = self + .next_date .compare_exchange(current, next_date, Ordering::AcqRel, Ordering::Acquire) - .is_ok() + .is_ok(); + + if next_date_updated { + if let Some(index) = &self.log_filename_index { + if current == next_date { + index.fetch_add(1, Ordering::SeqCst); + } else { + index.store(0, Ordering::Release); + } + } + + true + } else { + false + } } } @@ -852,11 +991,22 @@ fn create_writer(directory: &Path, filename: &str) -> Result { new_file.map_err(InitError::ctx("failed to create initial log file")) } +#[derive(Clone)] +struct FilteredLogFile { + path: PathBuf, + metadata: fs::Metadata, + created_at: std::time::SystemTime, + /// This is the date found in the filename, rounded (as opposed to `created_at`) + rounded_date: Option, + index: Option, +} + #[cfg(test)] mod test { use super::*; use std::fs; use std::io::Write; + use std::ops::Deref; fn find_str_in_log(dir_path: &Path, expected_value: &str) -> bool { let dir_contents = fs::read_dir(dir_path).expect("Failed to read directory"); @@ -990,13 +1140,25 @@ mod test { let test_cases = vec![ // prefix only TestCase { - expected: "app.log.2020-02-01-10-01-00", + expected: "app.log.2020-02-01-10-01.0", + rotation: Rotation::minutely_with_max_bytes(1024), + prefix: Some("app.log"), + suffix: None, + }, + TestCase { + expected: "app.log.2020-02-01-10.0", + rotation: Rotation::hourly_with_max_bytes(1024), + prefix: Some("app.log"), + suffix: None, + }, + TestCase { + expected: "app.log.2020-02-01.0", rotation: Rotation::daily_with_max_bytes(1024), prefix: Some("app.log"), suffix: None, }, TestCase { - expected: "app.log.2020-02-01-10-01-00", + expected: "app.log.2020-02-01.0", rotation: Rotation::max_bytes(1024), prefix: Some("app.log"), suffix: None, @@ -1027,13 +1189,25 @@ mod test { }, // prefix and suffix TestCase { - expected: "app.2020-02-01-10-01-00.log", + expected: "app.2020-02-01-10-01.0.log", + rotation: Rotation::minutely_with_max_bytes(1024), + prefix: Some("app"), + suffix: Some("log"), + }, + TestCase { + expected: "app.2020-02-01-10.0.log", + rotation: Rotation::hourly_with_max_bytes(1024), + prefix: Some("app"), + suffix: Some("log"), + }, + TestCase { + expected: "app.2020-02-01.0.log", rotation: Rotation::daily_with_max_bytes(1024), prefix: Some("app"), suffix: Some("log"), }, TestCase { - expected: "app.2020-02-01-10-01-00.log", + expected: "app.2020-02-01.0.log", rotation: Rotation::max_bytes(1024), prefix: Some("app"), suffix: Some("log"), @@ -1064,13 +1238,25 @@ mod test { }, // suffix only TestCase { - expected: "2020-02-01-10-01-00.log", + expected: "2020-02-01-10-01.0.log", + rotation: Rotation::minutely_with_max_bytes(1024), + prefix: None, + suffix: Some("log"), + }, + TestCase { + expected: "2020-02-01-10.0.log", + rotation: Rotation::hourly_with_max_bytes(1024), + prefix: None, + suffix: Some("log"), + }, + TestCase { + expected: "2020-02-01.0.log", rotation: Rotation::daily_with_max_bytes(1024), prefix: None, suffix: Some("log"), }, TestCase { - expected: "2020-02-01-10-01-00.log", + expected: "2020-02-01.0.log", rotation: Rotation::max_bytes(1024), prefix: None, suffix: Some("log"), @@ -1099,6 +1285,55 @@ mod test { prefix: None, suffix: Some("log"), }, + // no suffix nor prefix + TestCase { + expected: "2020-02-01-10-01.0", + rotation: Rotation::minutely_with_max_bytes(1024), + prefix: None, + suffix: None, + }, + TestCase { + expected: "2020-02-01-10.0", + rotation: Rotation::hourly_with_max_bytes(1024), + prefix: None, + suffix: None, + }, + TestCase { + expected: "2020-02-01.0", + rotation: Rotation::daily_with_max_bytes(1024), + prefix: None, + suffix: None, + }, + TestCase { + expected: "2020-02-01.0", + rotation: Rotation::max_bytes(1024), + prefix: None, + suffix: None, + }, + TestCase { + expected: "2020-02-01-10-01", + rotation: Rotation::MINUTELY, + prefix: None, + suffix: None, + }, + TestCase { + expected: "2020-02-01-10", + rotation: Rotation::HOURLY, + prefix: None, + suffix: None, + }, + TestCase { + expected: "2020-02-01", + rotation: Rotation::DAILY, + prefix: None, + suffix: None, + }, + TestCase { + expected: "2020-02-01", + rotation: Rotation::NEVER, + prefix: None, + suffix: None, + }, ]; for test_case in test_cases { @@ -1294,29 +1529,46 @@ mod test { #[test] fn size_based_rotation() { + let format = format_description::parse("size_based_rotation.[year]-[month]-[day]").unwrap(); + let now = OffsetDateTime::now_utc(); + let directory = tempfile::tempdir().expect("failed to create tempdir"); let mut appender = max_size(&directory, "size_based_rotation", 8); - writeln!(appender, "more than 8 bytes").unwrap(); - std::thread::sleep(std::time::Duration::from_secs(1)); - writeln!(appender, "more than 8 bytes again").unwrap(); - std::thread::sleep(std::time::Duration::from_secs(1)); - writeln!(appender, "and here is a third file").unwrap(); - std::thread::sleep(std::time::Duration::from_secs(1)); + writeln!(appender, "(file1) more than 8 bytes").unwrap(); + writeln!(appender, "(file2) more than 8 bytes again").unwrap(); + writeln!(appender, "(file3) and here is a third file").unwrap(); - let dir_contents = fs::read_dir(&directory).expect("Failed to read directory"); + let dir_contents = fs::read_dir(&directory).expect("read directory"); println!("dir={:?}", dir_contents); - let mut count = 0; + let expected_files = [ + format!("{}.0", now.format(&format).unwrap()), + format!("{}.1", now.format(&format).unwrap()), + format!("{}.2", now.format(&format).unwrap()), + ]; + let mut expected_files: std::collections::HashSet<&str> = + expected_files.iter().map(|s| s.deref()).collect(); + 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); - count += 1; + + let path = entry.expect("dir entry").path(); + let contents = fs::read_to_string(&path).expect("read file"); + println!("path={}\ncontents={:?}", path.display(), contents); + + let filename = path.file_name().unwrap().to_str().unwrap(); + expected_files + .remove(filename) + .then_some(()) + .expect("filename"); } - assert_eq!(count, 3); + assert!( + expected_files.is_empty(), + "missing file(s): {:?}", + expected_files + ); } }