From 198f3444899d40c1ac2114361f5908840cbf8a90 Mon Sep 17 00:00:00 2001 From: tison Date: Sun, 11 Aug 2024 18:44:01 +0800 Subject: [PATCH 1/8] refactor: use jiff for timestamp Signed-off-by: tison --- Cargo.toml | 15 +++++---------- src/layout/json.rs | 14 ++------------ src/layout/text.rs | 2 +- 3 files changed, 8 insertions(+), 23 deletions(-) diff --git a/Cargo.toml b/Cargo.toml index b667ce9..76f9db3 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -34,27 +34,27 @@ rustdoc-args = ["--cfg", "docs"] [features] fastrace = ["dep:fastrace"] -json = ["dep:serde_json", "dep:serde"] +json = ["dep:serde_json", "dep:serde", "jiff/serde"] no-color = ["colored/no-color"] opentelemetry = [ "dep:opentelemetry", "dep:opentelemetry-otlp", "dep:opentelemetry_sdk", ] -rolling_file = ["dep:crossbeam-channel", "dep:parking_lot", "dep:time"] +rolling_file = ["dep:crossbeam-channel", "dep:parking_lot"] [dependencies] anyhow = { version = "1.0" } colored = { version = "2.1" } -humantime = { version = "2.1" } +jiff = { version = "0.1.5" } log = { version = "0.4", features = ["std", "kv_unstable"] } paste = { version = "1.0" } serde = { version = "1.0", features = ["derive"], optional = true } serde_json = { version = "1.0", optional = true } [dev-dependencies] -rand = "0.8.5" -tempfile = "3.3" +rand = "0.8" +tempfile = "3.12" ## Rolling file dependencies [dependencies.crossbeam-channel] @@ -65,11 +65,6 @@ version = "0.5" optional = true version = "0.12" -[dependencies.time] -features = ["formatting", "parsing", "macros"] -optional = true -version = "0.3" - ## Fastrace dependencies [dependencies.fastrace] optional = true diff --git a/src/layout/json.rs b/src/layout/json.rs index d1f4a1c..b62e8c1 100644 --- a/src/layout/json.rs +++ b/src/layout/json.rs @@ -13,9 +13,7 @@ // limitations under the License. use std::fmt::Arguments; -use std::time::SystemTime; -use humantime::Rfc3339Timestamp; use log::Record; use serde::Serialize; use serde_json::Map; @@ -56,8 +54,7 @@ impl<'a, 'kvs> log::kv::Visitor<'kvs> for KvCollector<'a> { #[derive(Debug, Clone, Serialize)] struct RecordLine<'a> { - #[serde(serialize_with = "serialize_timestamp")] - timestamp: Rfc3339Timestamp, + timestamp: jiff::Zoned, level: &'a str, module_path: &'a str, file: &'a str, @@ -74,13 +71,6 @@ where serializer.collect_str(args) } -fn serialize_timestamp(timestamp: &Rfc3339Timestamp, serializer: S) -> Result -where - S: serde::Serializer, -{ - serializer.collect_str(&format_args!("{timestamp}")) -} - impl JsonLayout { pub(crate) fn format(&self, record: &Record, f: &F) -> anyhow::Result<()> where @@ -91,7 +81,7 @@ impl JsonLayout { record.key_values().visit(&mut visitor)?; let record_line = RecordLine { - timestamp: humantime::format_rfc3339_micros(SystemTime::now()), + timestamp: jiff::Zoned::now(), level: record.level().as_str(), module_path: record.module_path().unwrap_or_default(), file: record.file().unwrap_or_default(), diff --git a/src/layout/text.rs b/src/layout/text.rs index 69d5180..f99a14a 100644 --- a/src/layout/text.rs +++ b/src/layout/text.rs @@ -80,7 +80,7 @@ impl TextLayout { Level::Trace => self.colors.trace, }; - let time = humantime::format_rfc3339_micros(SystemTime::now()); + let time = jiff::Zoned::now(); let level = ColoredString::from(record.level().to_string()).color(color); let module = record.module_path().unwrap_or_default(); let file = record.file().unwrap_or_default(); From 4feefda8c2f9c1303e0f98d69770837f3bed16dd Mon Sep 17 00:00:00 2001 From: tison Date: Sun, 11 Aug 2024 19:59:37 +0800 Subject: [PATCH 2/8] update rolling file Signed-off-by: tison --- src/append/fastrace.rs | 5 +- src/append/mod.rs | 1 - src/append/rolling_file/clock.rs | 36 ++++++------ src/append/rolling_file/rolling.rs | 37 +++++------- src/append/rolling_file/rotation.rs | 87 ++++++++++++++++------------- src/layout/text.rs | 1 - 6 files changed, 83 insertions(+), 84 deletions(-) diff --git a/src/append/fastrace.rs b/src/append/fastrace.rs index e6dd71c..63d2440 100644 --- a/src/append/fastrace.rs +++ b/src/append/fastrace.rs @@ -12,8 +12,7 @@ // See the License for the specific language governing permissions and // limitations under the License. -use std::time::SystemTime; - +use jiff::Zoned; use log::Record; use crate::append::Append; @@ -27,7 +26,7 @@ impl Append for FastraceEvent { fn append(&self, record: &Record) -> anyhow::Result<()> { let message = format!( "{} {:>5} {}{}", - humantime::format_rfc3339_micros(SystemTime::now()), + Zoned::now(), record.level(), record.args(), KvDisplay::new(record.key_values()), diff --git a/src/append/mod.rs b/src/append/mod.rs index 3514b99..b671bc4 100644 --- a/src/append/mod.rs +++ b/src/append/mod.rs @@ -24,7 +24,6 @@ pub use self::opentelemetry::OpentelemetryLog; pub use self::rolling_file::RollingFile; pub use self::stdio::Stderr; pub use self::stdio::Stdout; - use crate::layout::IdenticalLayout; use crate::layout::Layout; diff --git a/src/append/rolling_file/clock.rs b/src/append/rolling_file/clock.rs index d23e2f5..690870b 100644 --- a/src/append/rolling_file/clock.rs +++ b/src/append/rolling_file/clock.rs @@ -12,7 +12,7 @@ // See the License for the specific language governing permissions and // limitations under the License. -use time::OffsetDateTime; +use jiff::Timestamp; #[derive(Debug)] pub enum Clock { @@ -22,16 +22,16 @@ pub enum Clock { } impl Clock { - pub fn now(&self) -> OffsetDateTime { + pub fn now(&self) -> Timestamp { match self { - Clock::DefaultClock => OffsetDateTime::now_utc(), + Clock::DefaultClock => Timestamp::now(), #[cfg(test)] Clock::ManualClock(clock) => clock.now(), } } #[cfg(test)] - pub fn set_now(&mut self, new_time: OffsetDateTime) { + pub fn set_now(&mut self, new_time: Timestamp) { if let Clock::ManualClock(clock) = self { clock.set_now(new_time); } @@ -42,38 +42,38 @@ impl Clock { #[derive(Debug)] #[cfg(test)] pub struct ManualClock { - fixed_time: OffsetDateTime, + now: Timestamp, } #[cfg(test)] impl ManualClock { - pub fn new(fixed_time: OffsetDateTime) -> ManualClock { - ManualClock { fixed_time } + pub fn new(now: Timestamp) -> ManualClock { + ManualClock { now } } - fn now(&self) -> OffsetDateTime { - self.fixed_time + fn now(&self) -> Timestamp { + self.now } - pub fn set_now(&mut self, new_time: OffsetDateTime) { - self.fixed_time = new_time; + pub fn set_now(&mut self, now: Timestamp) { + self.now = now; } } #[cfg(test)] mod tests { - use time::macros::datetime; + use std::str::FromStr; use super::*; #[test] fn test_manual_clock_adjusting() { - let mut clock = ManualClock { - fixed_time: datetime!(2023-01-01 12:00:00 UTC), - }; - assert_eq!(clock.now(), datetime!(2023-01-01 12:00:00 UTC)); + let now = Timestamp::from_str("2023-01-01T12:00:00Z").unwrap(); + let mut clock = ManualClock { now }; + assert_eq!(clock.now(), now); - clock.set_now(datetime!(2024-01-01 12:00:00 UTC)); - assert_eq!(clock.now(), datetime!(2024-01-01 12:00:00 UTC)); + let now = Timestamp::from_str("2024-01-01T12:00:00Z").unwrap(); + clock.set_now(now); + assert_eq!(clock.now(), now); } } diff --git a/src/append/rolling_file/rolling.rs b/src/append/rolling_file/rolling.rs index 8c7242d..5b45b14 100644 --- a/src/append/rolling_file/rolling.rs +++ b/src/append/rolling_file/rolling.rs @@ -21,10 +21,8 @@ use std::path::Path; use std::path::PathBuf; use anyhow::Context; +use jiff::Timestamp; use parking_lot::RwLock; -use time::format_description; -use time::Date; -use time::OffsetDateTime; use crate::append::rolling_file::clock::Clock; use crate::append::rolling_file::Rotation; @@ -166,7 +164,7 @@ struct State { log_dir: PathBuf, log_filename_prefix: Option, log_filename_suffix: Option, - date_format: Vec>, + date_format: &'static str, rotation: Rotation, current_count: usize, current_filesize: usize, @@ -213,11 +211,8 @@ impl State { Ok((state, writer)) } - fn join_date(&self, date: &OffsetDateTime, cnt: usize) -> String { - let date = date.format(&self.date_format).expect( - "failed to format OffsetDateTime; this is a bug in logforth rolling file appender", - ); - + fn join_date(&self, date: &Timestamp, cnt: usize) -> String { + let date = date.strftime(self.date_format); match ( &self.rotation, &self.log_filename_prefix, @@ -235,7 +230,7 @@ impl State { } } - fn create_log_writer(&self, now: OffsetDateTime, cnt: usize) -> anyhow::Result { + fn create_log_writer(&self, now: Timestamp, cnt: usize) -> anyhow::Result { fs::create_dir_all(&self.log_dir).context("failed to create log directory")?; let filename = self.join_date(&now, cnt); if let Some(max_files) = self.max_files { @@ -280,9 +275,8 @@ impl State { } } - if self.log_filename_prefix.is_none() - && self.log_filename_suffix.is_none() - && Date::parse(filename, &self.date_format).is_err() + if self.log_filename_prefix.is_none() && self.log_filename_suffix.is_none() + // && Date::parse(filename, &self.date_format).is_err() { return None; } @@ -309,7 +303,7 @@ impl State { Ok(()) } - fn refresh_writer(&self, now: OffsetDateTime, cnt: usize, file: &mut File) { + fn refresh_writer(&self, now: Timestamp, cnt: usize, file: &mut File) { match self.create_log_writer(now, cnt) { Ok(new_file) => { if let Err(err) = file.flush() { @@ -321,9 +315,9 @@ impl State { } } - fn should_rollover_on_date(&self, date: OffsetDateTime) -> bool { + fn should_rollover_on_date(&self, date: Timestamp) -> bool { self.next_date_timestamp - .is_some_and(|ts| date.unix_timestamp() as usize >= ts) + .is_some_and(|ts| date.as_millisecond() as usize >= ts) } fn should_rollover_on_size(&self) -> bool { @@ -336,24 +330,23 @@ impl State { self.current_count } - fn advance_date(&mut self, now: OffsetDateTime) { + fn advance_date(&mut self, now: Timestamp) { self.current_count = 0; self.current_filesize = 0; self.next_date_timestamp = self.rotation.next_date_timestamp(&now); } } + #[cfg(test)] mod tests { use std::cmp::min; use std::fs; use std::io::Write; use std::ops::Add; - + use std::time::Duration; use rand::distributions::Alphanumeric; use rand::Rng; use tempfile::TempDir; - use time::macros::datetime; - use time::Duration; use crate::append::rolling_file::clock::Clock; use crate::append::rolling_file::clock::ManualClock; @@ -487,8 +480,8 @@ mod tests { ) { let temp_dir = TempDir::new().expect("failed to create a temporary directory"); let max_files = 10; - // Small file size and too many files to ensure both of file size and time rotation can be - // triggered. + // Small file size and too many files to ensure both of file size and time rotation can +be // triggered. let total_files = 100; let file_size = 500; diff --git a/src/append/rolling_file/rotation.rs b/src/append/rolling_file/rotation.rs index 37b25f4..52c650c 100644 --- a/src/append/rolling_file/rotation.rs +++ b/src/append/rolling_file/rotation.rs @@ -12,10 +12,11 @@ // See the License for the specific language governing permissions and // limitations under the License. -use time::format_description; -use time::Duration; -use time::OffsetDateTime; -use time::Time; +use jiff::RoundMode; +use jiff::Timestamp; +use jiff::TimestampRound; +use jiff::ToSpan; +use jiff::Unit; /// Defines a fixed period for rolling of a log file. #[derive(Clone, Eq, PartialEq, Debug)] @@ -31,71 +32,79 @@ pub enum Rotation { } impl Rotation { - pub fn next_date_timestamp(&self, current_date: &OffsetDateTime) -> Option { + pub fn next_date_timestamp(&self, current_date: &Timestamp) -> Option { + let timestamp_round = TimestampRound::new().mode(RoundMode::Trunc); + let next_date = match *self { - Rotation::Minutely => *current_date + Duration::minutes(1), - Rotation::Hourly => *current_date + Duration::hours(1), - Rotation::Daily => *current_date + Duration::days(1), Rotation::Never => return None, - }; - - Some(self.round_date(&next_date).unix_timestamp() as usize) - } - - fn round_date(&self, date: &OffsetDateTime) -> OffsetDateTime { - match *self { Rotation::Minutely => { - let time = Time::from_hms(date.hour(), date.minute(), 0) - .expect("invalid time; this is a bug in logforth rolling file appender"); - date.replace_time(time) + (*current_date + 1.minute()).round(timestamp_round.smallest(Unit::Minute)) } Rotation::Hourly => { - let time = Time::from_hms(date.hour(), 0, 0) - .expect("invalid time; this is a bug in logforth rolling file appender"); - date.replace_time(time) - } - Rotation::Daily => { - let time = Time::from_hms(0, 0, 0) - .expect("invalid time; this is a bug in logforth rolling file appender"); - date.replace_time(time) + (*current_date + 1.hour()).round(timestamp_round.smallest(Unit::Hour)) } - Rotation::Never => unreachable!("Rotation::Never is impossible to round."), + Rotation::Daily => (*current_date + 1.day()).round(timestamp_round.smallest(Unit::Day)), } + .expect("invalid time; this is a bug in logforth rolling file appender"); + + println!("next_date: {:?}", next_date); + + Some(next_date.as_millisecond() as usize) } - pub fn date_format(&self) -> Vec> { + pub fn date_format(&self) -> &'static str { 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]"), + Rotation::Minutely => "%F-%H-%M", + Rotation::Hourly => "%F-%H", + Rotation::Daily => "%F", + Rotation::Never => "%F", } - .expect("failed to create a formatter; this is a bug in logforth rolling file appender") } } #[cfg(test)] mod tests { - use time::macros::datetime; + use jiff::civil::date; + use jiff::tz::Offset; + use jiff::tz::TimeZone; use super::Rotation; #[test] fn test_next_date_timestamp() { - let current_date = datetime!(2024-08-10 17:12:52 +8); + let current_date = date(2024, 8, 10) + .at(17, 12, 52, 0) + .to_zoned(TimeZone::fixed(Offset::constant(8))) + .unwrap(); + let current_date = current_date.timestamp(); + + assert_eq!(Rotation::Never.next_date_timestamp(¤t_date), None); + let expected_date = date(2024, 8, 10) + .at(17, 13, 0, 0) + .to_zoned(TimeZone::fixed(Offset::constant(8))) + .unwrap(); assert_eq!( Rotation::Minutely.next_date_timestamp(¤t_date), - Some(datetime!(2024-08-10 17:13:00 +8).unix_timestamp() as usize) + Some(expected_date.timestamp().as_millisecond() as usize) ); + + let expected_date = date(2024, 8, 10) + .at(18, 0, 0, 0) + .to_zoned(TimeZone::fixed(Offset::constant(8))) + .unwrap(); assert_eq!( Rotation::Hourly.next_date_timestamp(¤t_date), - Some(datetime!(2024-08-10 18:00:00 +8).unix_timestamp() as usize) + Some(expected_date.timestamp().as_millisecond() as usize) ); + + let expected_date = date(2024, 8, 11) + .at(0, 0, 0, 0) + .to_zoned(TimeZone::fixed(Offset::constant(8))) + .unwrap(); assert_eq!( Rotation::Daily.next_date_timestamp(¤t_date), - Some(datetime!(2024-08-11 00:00:00 +8).unix_timestamp() as usize) + Some(expected_date.timestamp().as_millisecond() as usize) ); - assert_eq!(Rotation::Never.next_date_timestamp(¤t_date), None); } } diff --git a/src/layout/text.rs b/src/layout/text.rs index f99a14a..2cfe6c5 100644 --- a/src/layout/text.rs +++ b/src/layout/text.rs @@ -13,7 +13,6 @@ // limitations under the License. use std::fmt::Arguments; -use std::time::SystemTime; use colored::Color; use colored::ColoredString; From 119b03958e54939f8f0211afed5b916eb126de71 Mon Sep 17 00:00:00 2001 From: tison Date: Sun, 11 Aug 2024 21:41:49 +0800 Subject: [PATCH 3/8] fixup Signed-off-by: tison --- src/append/rolling_file/clock.rs | 28 +++++----- src/append/rolling_file/rolling.rs | 82 +++++++++++++++-------------- src/append/rolling_file/rotation.rs | 65 ++++++++--------------- 3 files changed, 80 insertions(+), 95 deletions(-) diff --git a/src/append/rolling_file/clock.rs b/src/append/rolling_file/clock.rs index 690870b..c27d26c 100644 --- a/src/append/rolling_file/clock.rs +++ b/src/append/rolling_file/clock.rs @@ -12,7 +12,7 @@ // See the License for the specific language governing permissions and // limitations under the License. -use jiff::Timestamp; +use jiff::Zoned; #[derive(Debug)] pub enum Clock { @@ -22,18 +22,18 @@ pub enum Clock { } impl Clock { - pub fn now(&self) -> Timestamp { + pub fn now(&self) -> Zoned { match self { - Clock::DefaultClock => Timestamp::now(), + Clock::DefaultClock => Zoned::now(), #[cfg(test)] Clock::ManualClock(clock) => clock.now(), } } #[cfg(test)] - pub fn set_now(&mut self, new_time: Timestamp) { + pub fn set_now(&mut self, now: Zoned) { if let Clock::ManualClock(clock) = self { - clock.set_now(new_time); + clock.set_now(now); } } } @@ -42,20 +42,20 @@ impl Clock { #[derive(Debug)] #[cfg(test)] pub struct ManualClock { - now: Timestamp, + now: Zoned, } #[cfg(test)] impl ManualClock { - pub fn new(now: Timestamp) -> ManualClock { + pub fn new(now: Zoned) -> ManualClock { ManualClock { now } } - fn now(&self) -> Timestamp { - self.now + fn now(&self) -> Zoned { + self.now.clone() } - pub fn set_now(&mut self, now: Timestamp) { + pub fn set_now(&mut self, now: Zoned) { self.now = now; } } @@ -68,12 +68,12 @@ mod tests { #[test] fn test_manual_clock_adjusting() { - let now = Timestamp::from_str("2023-01-01T12:00:00Z").unwrap(); - let mut clock = ManualClock { now }; + let now = Zoned::from_str("2024-08-10T17:12:52+08[+08]").unwrap(); + let mut clock = ManualClock { now: now.clone() }; assert_eq!(clock.now(), now); - let now = Timestamp::from_str("2024-01-01T12:00:00Z").unwrap(); - clock.set_now(now); + let now = Zoned::from_str("2024-01-01T12:00:00+08[+08]").unwrap(); + clock.set_now(now.clone()); assert_eq!(clock.now(), now); } } diff --git a/src/append/rolling_file/rolling.rs b/src/append/rolling_file/rolling.rs index 5b45b14..d021fbf 100644 --- a/src/append/rolling_file/rolling.rs +++ b/src/append/rolling_file/rolling.rs @@ -21,7 +21,7 @@ use std::path::Path; use std::path::PathBuf; use anyhow::Context; -use jiff::Timestamp; +use jiff::Zoned; use parking_lot::RwLock; use crate::append::rolling_file::clock::Clock; @@ -45,13 +45,13 @@ impl Write for RollingFileWriter { fn write(&mut self, buf: &[u8]) -> io::Result { let now = self.state.clock.now(); let writer = self.writer.get_mut(); - if self.state.should_rollover_on_date(now) { - self.state.advance_date(now); - self.state.refresh_writer(now, 0, writer); + if self.state.should_rollover_on_date(&now) { + self.state.advance_date(&now); + self.state.refresh_writer(&now, 0, writer); } if self.state.should_rollover_on_size() { let cnt = self.state.advance_cnt(); - self.state.refresh_writer(now, cnt, writer); + self.state.refresh_writer(&now, cnt, writer); } writer.write(buf).map(|n| { @@ -206,12 +206,12 @@ impl State { clock, }; - let file = state.create_log_writer(now, 0)?; + let file = state.create_log_writer(&now, 0)?; let writer = RwLock::new(file); Ok((state, writer)) } - fn join_date(&self, date: &Timestamp, cnt: usize) -> String { + fn join_date(&self, date: &Zoned, cnt: usize) -> String { let date = date.strftime(self.date_format); match ( &self.rotation, @@ -230,9 +230,9 @@ impl State { } } - fn create_log_writer(&self, now: Timestamp, cnt: usize) -> anyhow::Result { + fn create_log_writer(&self, now: &Zoned, cnt: usize) -> anyhow::Result { fs::create_dir_all(&self.log_dir).context("failed to create log directory")?; - let filename = self.join_date(&now, cnt); + let filename = self.join_date(now, cnt); if let Some(max_files) = self.max_files { if let Err(err) = self.delete_oldest_logs(max_files) { eprintln!("failed to delete oldest logs: {err}"); @@ -303,7 +303,7 @@ impl State { Ok(()) } - fn refresh_writer(&self, now: Timestamp, cnt: usize, file: &mut File) { + fn refresh_writer(&self, now: &Zoned, cnt: usize, file: &mut File) { match self.create_log_writer(now, cnt) { Ok(new_file) => { if let Err(err) = file.flush() { @@ -315,9 +315,9 @@ impl State { } } - fn should_rollover_on_date(&self, date: Timestamp) -> bool { + fn should_rollover_on_date(&self, date: &Zoned) -> bool { self.next_date_timestamp - .is_some_and(|ts| date.as_millisecond() as usize >= ts) + .is_some_and(|ts| date.timestamp().as_millisecond() as usize >= ts) } fn should_rollover_on_size(&self) -> bool { @@ -330,10 +330,10 @@ impl State { self.current_count } - fn advance_date(&mut self, now: Timestamp) { + fn advance_date(&mut self, now: &Zoned) { self.current_count = 0; self.current_filesize = 0; - self.next_date_timestamp = self.rotation.next_date_timestamp(&now); + self.next_date_timestamp = self.rotation.next_date_timestamp(now); } } @@ -343,7 +343,10 @@ mod tests { use std::fs; use std::io::Write; use std::ops::Add; - use std::time::Duration; + use std::str::FromStr; + + use jiff::Span; + use jiff::Zoned; use rand::distributions::Alphanumeric; use rand::Rng; use tempfile::TempDir; @@ -395,37 +398,37 @@ mod tests { fn test_file_rolling_via_time_rotation() { test_file_rolling_for_specific_time_rotation( Rotation::Minutely, - Duration::minutes(1), - Duration::seconds(1), + Span::new().minutes(1), + Span::new().seconds(1), ); test_file_rolling_for_specific_time_rotation( Rotation::Hourly, - Duration::hours(1), - Duration::minutes(1), + Span::new().hours(1), + Span::new().minutes(1), ); test_file_rolling_for_specific_time_rotation( Rotation::Daily, - Duration::days(1), - Duration::hours(1), + Span::new().days(1), + Span::new().hours(1), ); } fn test_file_rolling_for_specific_time_rotation( rotation: Rotation, - rotation_duration: Duration, - write_interval: Duration, + rotation_duration: Span, + write_interval: Span, ) { let temp_dir = TempDir::new().expect("failed to create a temporary directory"); let max_files = 10; - let start_time = datetime!(2024-08-10 00:00:00 +0); + let start_time = Zoned::from_str("2024-08-10T00:00:00[UTC]").unwrap(); let mut writer = RollingFileWriterBuilder::new() .rotation(rotation) .filename_prefix("test_prefix") .filename_suffix("log") .max_log_files(max_files) .max_file_size(usize::MAX) - .clock(Clock::ManualClock(ManualClock::new(start_time))) + .clock(Clock::ManualClock(ManualClock::new(start_time.clone()))) .build(&temp_dir) .unwrap(); @@ -435,11 +438,12 @@ mod tests { let mut expected_file_size = 0; let end_time = cur_time.add(rotation_duration); while cur_time < end_time { - writer.state.clock.set_now(cur_time); + writer.state.clock.set_now(cur_time.clone()); let rand_str = generate_random_string(); expected_file_size += rand_str.len(); + println!("i: {i}, cur_time: {cur_time}, end_time: {end_time}, expected_file_size: {expected_file_size}"); assert_eq!(writer.write(rand_str.as_bytes()).unwrap(), rand_str.len()); assert_eq!(writer.state.current_filesize, expected_file_size); @@ -458,41 +462,41 @@ mod tests { fn test_file_rolling_via_file_size_and_time_rotation() { test_file_size_and_time_rotation_for_specific_time_rotation( Rotation::Minutely, - Duration::minutes(1), - Duration::seconds(1), + Span::new().minutes(1), + Span::new().seconds(1), ); test_file_size_and_time_rotation_for_specific_time_rotation( Rotation::Hourly, - Duration::hours(1), - Duration::minutes(1), + Span::new().hours(1), + Span::new().minutes(1), ); test_file_size_and_time_rotation_for_specific_time_rotation( Rotation::Daily, - Duration::days(1), - Duration::hours(1), + Span::new().days(1), + Span::new().hours(1), ); } fn test_file_size_and_time_rotation_for_specific_time_rotation( rotation: Rotation, - rotation_duration: Duration, - write_interval: Duration, + rotation_duration: Span, + write_interval: Span, ) { let temp_dir = TempDir::new().expect("failed to create a temporary directory"); let max_files = 10; - // Small file size and too many files to ensure both of file size and time rotation can -be // triggered. + // Small file size and too many files to ensure both of file size and time rotation can be + // triggered. let total_files = 100; let file_size = 500; - let start_time = datetime!(2024-08-10 00:00:00 +0); + let start_time = Zoned::from_str("2024-08-10T00:00:00[UTC]").unwrap(); let mut writer = RollingFileWriterBuilder::new() .rotation(rotation) .filename_prefix("test_prefix") .filename_suffix("log") .max_log_files(max_files) .max_file_size(file_size) - .clock(Clock::ManualClock(ManualClock::new(start_time))) + .clock(Clock::ManualClock(ManualClock::new(start_time.clone()))) .build(&temp_dir) .unwrap(); @@ -504,7 +508,7 @@ be // triggered. for i in 1..=total_files { let mut expected_file_size = 0; loop { - writer.state.clock.set_now(cur_time); + writer.state.clock.set_now(cur_time.clone()); let rand_str = generate_random_string(); expected_file_size += rand_str.len(); diff --git a/src/append/rolling_file/rotation.rs b/src/append/rolling_file/rotation.rs index 52c650c..332ed92 100644 --- a/src/append/rolling_file/rotation.rs +++ b/src/append/rolling_file/rotation.rs @@ -12,11 +12,10 @@ // See the License for the specific language governing permissions and // limitations under the License. -use jiff::RoundMode; -use jiff::Timestamp; -use jiff::TimestampRound; -use jiff::ToSpan; +use jiff::{RoundMode, ToSpan}; use jiff::Unit; +use jiff::Zoned; +use jiff::ZonedRound; /// Defines a fixed period for rolling of a log file. #[derive(Clone, Eq, PartialEq, Debug)] @@ -32,24 +31,18 @@ pub enum Rotation { } impl Rotation { - pub fn next_date_timestamp(&self, current_date: &Timestamp) -> Option { - let timestamp_round = TimestampRound::new().mode(RoundMode::Trunc); + pub fn next_date_timestamp(&self, current_date: &Zoned) -> Option { + let timestamp_round = ZonedRound::new().mode(RoundMode::Trunc); let next_date = match *self { Rotation::Never => return None, - Rotation::Minutely => { - (*current_date + 1.minute()).round(timestamp_round.smallest(Unit::Minute)) - } - Rotation::Hourly => { - (*current_date + 1.hour()).round(timestamp_round.smallest(Unit::Hour)) - } - Rotation::Daily => (*current_date + 1.day()).round(timestamp_round.smallest(Unit::Day)), - } - .expect("invalid time; this is a bug in logforth rolling file appender"); - - println!("next_date: {:?}", next_date); - - Some(next_date.as_millisecond() as usize) + Rotation::Minutely => (current_date + 1.minute()).round(timestamp_round.smallest(Unit::Minute)), + Rotation::Hourly => (current_date + 1.hour()).round(timestamp_round.smallest(Unit::Hour)), + Rotation::Daily => (current_date + 1.day()).round(timestamp_round.smallest(Unit::Day)), + }; + let next_date = + next_date.expect("invalid time; this is a bug in logforth rolling file appender"); + Some(next_date.timestamp().as_millisecond() as usize) } pub fn date_format(&self) -> &'static str { @@ -64,47 +57,35 @@ impl Rotation { #[cfg(test)] mod tests { - use jiff::civil::date; - use jiff::tz::Offset; - use jiff::tz::TimeZone; + use std::str::FromStr; + + use jiff::Timestamp; + use jiff::Zoned; use super::Rotation; #[test] fn test_next_date_timestamp() { - let current_date = date(2024, 8, 10) - .at(17, 12, 52, 0) - .to_zoned(TimeZone::fixed(Offset::constant(8))) - .unwrap(); - let current_date = current_date.timestamp(); + let current_date = Zoned::from_str("2024-08-10T17:12:52+08[+08]").unwrap(); assert_eq!(Rotation::Never.next_date_timestamp(¤t_date), None); - let expected_date = date(2024, 8, 10) - .at(17, 13, 0, 0) - .to_zoned(TimeZone::fixed(Offset::constant(8))) - .unwrap(); + let expected_date = "2024-08-10T17:13:00+08".parse::().unwrap(); assert_eq!( Rotation::Minutely.next_date_timestamp(¤t_date), - Some(expected_date.timestamp().as_millisecond() as usize) + Some(expected_date.as_millisecond() as usize) ); - let expected_date = date(2024, 8, 10) - .at(18, 0, 0, 0) - .to_zoned(TimeZone::fixed(Offset::constant(8))) - .unwrap(); + let expected_date = "2024-08-10T18:00:00+08".parse::().unwrap(); assert_eq!( Rotation::Hourly.next_date_timestamp(¤t_date), - Some(expected_date.timestamp().as_millisecond() as usize) + Some(expected_date.as_millisecond() as usize) ); - let expected_date = date(2024, 8, 11) - .at(0, 0, 0, 0) - .to_zoned(TimeZone::fixed(Offset::constant(8))) - .unwrap(); + let expected_date = "2024-08-11T00:00:00+08".parse::().unwrap(); assert_eq!( Rotation::Daily.next_date_timestamp(¤t_date), - Some(expected_date.timestamp().as_millisecond() as usize) + Some(expected_date.as_millisecond() as usize) ); } } From 020aff6011db884d3c80baf2ec4028037de7e5ec Mon Sep 17 00:00:00 2001 From: tison Date: Sun, 11 Aug 2024 22:47:10 +0800 Subject: [PATCH 4/8] use system timezone Signed-off-by: tison --- examples/rolling_file.rs | 2 +- src/append/rolling_file/rolling.rs | 5 +++-- src/append/rolling_file/rotation.rs | 11 +++++++--- src/layout/json.rs | 34 ++++++++++++++++++++++------- src/layout/text.rs | 22 ++++++++++++++----- 5 files changed, 54 insertions(+), 20 deletions(-) diff --git a/examples/rolling_file.rs b/examples/rolling_file.rs index 4686b59..443bcc9 100644 --- a/examples/rolling_file.rs +++ b/examples/rolling_file.rs @@ -38,7 +38,7 @@ fn main() { .dispatch( Dispatch::new() .filter(LevelFilter::Trace) - .layout(JsonLayout) + .layout(JsonLayout::default()) .append(RollingFile::new(writer)), ) .dispatch(Dispatch::new().layout(TextLayout::default()).append(Stdout)) diff --git a/src/append/rolling_file/rolling.rs b/src/append/rolling_file/rolling.rs index d021fbf..c9083e3 100644 --- a/src/append/rolling_file/rolling.rs +++ b/src/append/rolling_file/rolling.rs @@ -275,8 +275,9 @@ impl State { } } - if self.log_filename_prefix.is_none() && self.log_filename_suffix.is_none() - // && Date::parse(filename, &self.date_format).is_err() + if self.log_filename_prefix.is_none() + && self.log_filename_suffix.is_none() + && Zoned::strptime(self.date_format, filename).is_err() { return None; } diff --git a/src/append/rolling_file/rotation.rs b/src/append/rolling_file/rotation.rs index 332ed92..0810306 100644 --- a/src/append/rolling_file/rotation.rs +++ b/src/append/rolling_file/rotation.rs @@ -12,7 +12,8 @@ // See the License for the specific language governing permissions and // limitations under the License. -use jiff::{RoundMode, ToSpan}; +use jiff::RoundMode; +use jiff::ToSpan; use jiff::Unit; use jiff::Zoned; use jiff::ZonedRound; @@ -36,8 +37,12 @@ impl Rotation { let next_date = match *self { Rotation::Never => return None, - Rotation::Minutely => (current_date + 1.minute()).round(timestamp_round.smallest(Unit::Minute)), - Rotation::Hourly => (current_date + 1.hour()).round(timestamp_round.smallest(Unit::Hour)), + Rotation::Minutely => { + (current_date + 1.minute()).round(timestamp_round.smallest(Unit::Minute)) + } + Rotation::Hourly => { + (current_date + 1.hour()).round(timestamp_round.smallest(Unit::Hour)) + } Rotation::Daily => (current_date + 1.day()).round(timestamp_round.smallest(Unit::Day)), }; let next_date = diff --git a/src/layout/json.rs b/src/layout/json.rs index b62e8c1..96632d7 100644 --- a/src/layout/json.rs +++ b/src/layout/json.rs @@ -14,6 +14,8 @@ use std::fmt::Arguments; +use jiff::tz::TimeZone; +use jiff::Zoned; use log::Record; use serde::Serialize; use serde_json::Map; @@ -26,14 +28,19 @@ use crate::layout::Layout; /// Output format: /// /// ```json -/// {"timestamp":"2024-08-01T13:57:05.099261Z","level":"ERROR","module_path":"rolling_file","file":"rolling_file.rs","line":48,"message":"Hello error!","kvs":{}} -/// {"timestamp":"2024-08-01T13:57:05.099313Z","level":"WARN","module_path":"rolling_file","file":"rolling_file.rs","line":49,"message":"Hello warn!","kvs":{}} -/// {"timestamp":"2024-08-01T13:57:05.099338Z","level":"INFO","module_path":"rolling_file","file":"rolling_file.rs","line":50,"message":"Hello info!","kvs":{}} -/// {"timestamp":"2024-08-01T13:57:05.099362Z","level":"DEBUG","module_path":"rolling_file","file":"rolling_file.rs","line":51,"message":"Hello debug!","kvs":{}} -/// {"timestamp":"2024-08-01T13:57:05.099386Z","level":"TRACE","module_path":"rolling_file","file":"rolling_file.rs","line":52,"message":"Hello trace!","kvs":{}} +/// {"timestamp":"2024-08-11T22:44:57.172051+08:00","level":"ERROR","module_path":"rolling_file","file":"examples/rolling_file.rs","line":51,"message":"Hello error!","kvs":{}} +/// {"timestamp":"2024-08-11T22:44:57.172187+08:00","level":"WARN","module_path":"rolling_file","file":"examples/rolling_file.rs","line":52,"message":"Hello warn!","kvs":{}} +/// {"timestamp":"2024-08-11T22:44:57.172246+08:00","level":"INFO","module_path":"rolling_file","file":"examples/rolling_file.rs","line":53,"message":"Hello info!","kvs":{}} +/// {"timestamp":"2024-08-11T22:44:57.172300+08:00","level":"DEBUG","module_path":"rolling_file","file":"examples/rolling_file.rs","line":54,"message":"Hello debug!","kvs":{}} +/// {"timestamp":"2024-08-11T22:44:57.172353+08:00","level":"TRACE","module_path":"rolling_file","file":"examples/rolling_file.rs","line":55,"message":"Hello trace!","kvs":{}} /// ``` +/// +/// You can customize the timezone of the timestamp by setting the `tz` field with a [`TimeZone`] +/// instance. Otherwise, the system timezone is used. #[derive(Default, Debug, Clone)] -pub struct JsonLayout; +pub struct JsonLayout { + pub tz: Option, +} struct KvCollector<'a> { kvs: &'a mut Map, @@ -54,7 +61,8 @@ impl<'a, 'kvs> log::kv::Visitor<'kvs> for KvCollector<'a> { #[derive(Debug, Clone, Serialize)] struct RecordLine<'a> { - timestamp: jiff::Zoned, + #[serde(serialize_with = "serialize_time_zone")] + timestamp: Zoned, level: &'a str, module_path: &'a str, file: &'a str, @@ -64,6 +72,13 @@ struct RecordLine<'a> { kvs: Map, } +fn serialize_time_zone(timestamp: &Zoned, serializer: S) -> Result +where + S: serde::Serializer, +{ + serializer.collect_str(×tamp.strftime("%Y-%m-%dT%H:%M:%S.%6f%:z")) +} + fn serialize_args(args: &Arguments, serializer: S) -> Result where S: serde::Serializer, @@ -81,7 +96,10 @@ impl JsonLayout { record.key_values().visit(&mut visitor)?; let record_line = RecordLine { - timestamp: jiff::Zoned::now(), + timestamp: match self.tz.clone() { + Some(tz) => Zoned::now().with_time_zone(tz), + None => Zoned::now(), + }, level: record.level().as_str(), module_path: record.module_path().unwrap_or_default(), file: record.file().unwrap_or_default(), diff --git a/src/layout/text.rs b/src/layout/text.rs index 2cfe6c5..0237a79 100644 --- a/src/layout/text.rs +++ b/src/layout/text.rs @@ -17,6 +17,8 @@ use std::fmt::Arguments; use colored::Color; use colored::ColoredString; use colored::Colorize; +use jiff::tz::TimeZone; +use jiff::Zoned; use log::Level; use crate::layout::KvDisplay; @@ -27,11 +29,11 @@ use crate::layout::Layout; /// Output format: /// /// ```text -/// 2024-08-02T12:49:03.102343Z ERROR simple_stdio: examples/simple_stdio.rs:32 Hello error! -/// 2024-08-02T12:49:03.102442Z WARN simple_stdio: examples/simple_stdio.rs:33 Hello warn! -/// 2024-08-02T12:49:03.102447Z INFO simple_stdio: examples/simple_stdio.rs:34 Hello info! -/// 2024-08-02T12:49:03.102450Z DEBUG simple_stdio: examples/simple_stdio.rs:35 Hello debug! -/// 2024-08-02T12:49:03.102453Z TRACE simple_stdio: examples/simple_stdio.rs:36 Hello trace! +/// 2024-08-11T22:44:57.172105+08:00 ERROR rolling_file: examples/rolling_file.rs:51 Hello error! +/// 2024-08-11T22:44:57.172219+08:00 WARN rolling_file: examples/rolling_file.rs:52 Hello warn! +/// 2024-08-11T22:44:57.172276+08:00 INFO rolling_file: examples/rolling_file.rs:53 Hello info! +/// 2024-08-11T22:44:57.172329+08:00 DEBUG rolling_file: examples/rolling_file.rs:54 Hello debug! +/// 2024-08-11T22:44:57.172382+08:00 TRACE rolling_file: examples/rolling_file.rs:55 Hello trace! /// ``` /// /// By default, log levels are colored. You can turn on the `no-color` feature flag to disable this @@ -39,9 +41,13 @@ use crate::layout::Layout; /// /// You can also customize the color of each log level by setting the `colors` field with a /// [`LevelColor`] instance. +/// +/// You can customize the timezone of the timestamp by setting the `tz` field with a [`TimeZone`] +/// instance. Otherwise, the system timezone is used. #[derive(Default, Debug, Clone)] pub struct TextLayout { pub colors: LevelColor, + pub tz: Option, } /// Customize the color of each log level. @@ -79,7 +85,11 @@ impl TextLayout { Level::Trace => self.colors.trace, }; - let time = jiff::Zoned::now(); + let time = match self.tz.clone() { + Some(tz) => Zoned::now().with_time_zone(tz), + None => Zoned::now(), + } + .strftime("%Y-%m-%dT%H:%M:%S.%6f%:z"); let level = ColoredString::from(record.level().to_string()).color(color); let module = record.module_path().unwrap_or_default(); let file = record.file().unwrap_or_default(); From b112196894ca1ab2c09b197d29cbef78d10fdc80 Mon Sep 17 00:00:00 2001 From: tison Date: Sun, 11 Aug 2024 22:47:35 +0800 Subject: [PATCH 5/8] bump version for next release Signed-off-by: tison --- Cargo.toml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/Cargo.toml b/Cargo.toml index 76f9db3..2d04392 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -23,7 +23,7 @@ license = "Apache-2.0" readme = "README.md" repository = "https://github.com/cratesland/logforth" rust-version = "1.71.0" -version = "0.8.0" +version = "0.9.0" categories = ["development-tools::debugging"] keywords = ["logging", "log", "opentelemetry", "fastrace"] From 71ad935cec4806046172f1b50bda5e4b7adfb694 Mon Sep 17 00:00:00 2001 From: tison Date: Sun, 11 Aug 2024 22:49:33 +0800 Subject: [PATCH 6/8] fixup Signed-off-by: tison --- examples/json_stdio.rs | 2 +- src/append/rolling_file/rolling.rs | 1 - 2 files changed, 1 insertion(+), 2 deletions(-) diff --git a/examples/json_stdio.rs b/examples/json_stdio.rs index 9f500ab..4eacb07 100644 --- a/examples/json_stdio.rs +++ b/examples/json_stdio.rs @@ -23,7 +23,7 @@ fn main() { .dispatch( Dispatch::new() .filter(LevelFilter::Trace) - .layout(JsonLayout) + .layout(JsonLayout::default()) .append(append::Stdout), ) .apply() diff --git a/src/append/rolling_file/rolling.rs b/src/append/rolling_file/rolling.rs index c9083e3..82e2866 100644 --- a/src/append/rolling_file/rolling.rs +++ b/src/append/rolling_file/rolling.rs @@ -444,7 +444,6 @@ mod tests { let rand_str = generate_random_string(); expected_file_size += rand_str.len(); - println!("i: {i}, cur_time: {cur_time}, end_time: {end_time}, expected_file_size: {expected_file_size}"); assert_eq!(writer.write(rand_str.as_bytes()).unwrap(), rand_str.len()); assert_eq!(writer.state.current_filesize, expected_file_size); From 0d874723576761d99124894876c438a3c27e7a80 Mon Sep 17 00:00:00 2001 From: tison Date: Sun, 11 Aug 2024 22:58:26 +0800 Subject: [PATCH 7/8] make strptime work well Signed-off-by: tison --- src/append/rolling_file/rolling.rs | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/src/append/rolling_file/rolling.rs b/src/append/rolling_file/rolling.rs index 82e2866..4f4ff0d 100644 --- a/src/append/rolling_file/rolling.rs +++ b/src/append/rolling_file/rolling.rs @@ -277,7 +277,11 @@ impl State { if self.log_filename_prefix.is_none() && self.log_filename_suffix.is_none() - && Zoned::strptime(self.date_format, filename).is_err() + && Zoned::strptime( + format!("{} %:z", self.date_format), + format!("{filename} +00:00"), + ) + .is_err() { return None; } From f66c2a38129bc50fc070449c2d470651442686e0 Mon Sep 17 00:00:00 2001 From: tison Date: Mon, 12 Aug 2024 09:42:00 +0800 Subject: [PATCH 8/8] use better impl Signed-off-by: tison --- src/append/rolling_file/rolling.rs | 6 +----- 1 file changed, 1 insertion(+), 5 deletions(-) diff --git a/src/append/rolling_file/rolling.rs b/src/append/rolling_file/rolling.rs index 4f4ff0d..5065698 100644 --- a/src/append/rolling_file/rolling.rs +++ b/src/append/rolling_file/rolling.rs @@ -277,11 +277,7 @@ impl State { if self.log_filename_prefix.is_none() && self.log_filename_suffix.is_none() - && Zoned::strptime( - format!("{} %:z", self.date_format), - format!("{filename} +00:00"), - ) - .is_err() + && jiff::civil::DateTime::strptime(self.date_format, filename).is_err() { return None; }