Skip to content

Commit

Permalink
Respect local timezone when rotating files by time point
Browse files Browse the repository at this point in the history
  • Loading branch information
@SpriteOvO
SpriteOvO committed Aug 28, 2024
1 parent adf6c0d commit 6dbbbf2
Show file tree
Hide file tree
Showing 2 changed files with 138 additions and 44 deletions.
180 changes: 137 additions & 43 deletions spdlog/src/sink/rotating_file_sink.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -450,12 +450,13 @@ impl RotatorFileSizeInner {

impl RotatorTimePoint {
fn new(
override_now: Option<SystemTime>,
base_path: PathBuf,
time_point: TimePoint,
max_files: usize,
truncate: bool,
) -> Result<Self> {
let now = SystemTime::now();
let now = override_now.unwrap_or_else(SystemTime::now);
let file_path = Self::calc_file_path(base_path.as_path(), time_point, now);
let file = utils::open_file(file_path, truncate)?;

Expand Down Expand Up @@ -500,8 +501,8 @@ impl RotatorTimePoint {
// constructor.
#[must_use]
fn next_rotation_time_point(time_point: TimePoint, now: SystemTime) -> SystemTime {
let now: DateTime<Utc> = now.into();
let mut rotation_time: DateTime<Utc> = now;
let now: DateTime<Local> = now.into();
let mut rotation_time = now;

match time_point {
TimePoint::Daily { hour, minute } => {
Expand Down Expand Up @@ -768,6 +769,10 @@ impl RotatingFileSinkBuilder<PathBuf, RotationPolicy> {
/// the file, [`Error::CreateDirectory`] or [`Error::OpenFile`] will be
/// returned.
pub fn build(self) -> Result<RotatingFileSink> {
self.build_with_initial_time(None)
}

fn build_with_initial_time(self, override_now: Option<SystemTime>) -> Result<RotatingFileSink> {
self.rotation_policy
.validate()
.map_err(|err| Error::InvalidArgument(InvalidArgumentError::RotationPolicy(err)))?;
Expand All @@ -781,13 +786,15 @@ impl RotatingFileSinkBuilder<PathBuf, RotationPolicy> {
)?),
RotationPolicy::Daily { hour, minute } => {
RotatorKind::TimePoint(RotatorTimePoint::new(
override_now,
self.base_path,
TimePoint::Daily { hour, minute },
self.max_files,
self.rotate_on_open,
)?)
}
RotationPolicy::Hourly => RotatorKind::TimePoint(RotatorTimePoint::new(
override_now,
self.base_path,
TimePoint::Hourly,
self.max_files,
Expand All @@ -811,7 +818,7 @@ mod tests {

static BASE_LOGS_PATH: Lazy<PathBuf> = Lazy::new(|| {
let path = TEST_LOGS_PATH.join("rotating_file_sink");
fs::create_dir(&path).unwrap();
_ = fs::create_dir(&path);
path
});

Expand Down Expand Up @@ -1036,10 +1043,32 @@ mod tests {

static LOGS_PATH: Lazy<PathBuf> = Lazy::new(|| {
let path = BASE_LOGS_PATH.join("policy_time_point");
_ = fs::remove_dir_all(&path);
fs::create_dir_all(&path).unwrap();
path
});

const SECOND_1: Duration = Duration::from_secs(1);
const HOUR_1: Duration = Duration::from_secs(60 * 60);
const DAY_1: Duration = Duration::from_secs(60 * 60 * 24);

#[track_caller]
fn assert_files_count(file_name_prefix: &str, expected: usize) {
let paths = fs::read_dir(LOGS_PATH.clone()).unwrap();

let mut filenames = Vec::new();
let actual = paths.fold(0_usize, |mut count, entry| {
let filename = entry.unwrap().file_name();
if filename.to_string_lossy().starts_with(file_name_prefix) {
count += 1;
filenames.push(filename);
}
count
});
println!("found files: {:?}", filenames);
assert_eq!(actual, expected)
}

#[test]
fn calc_file_path() {
let system_time = Local.with_ymd_and_hms(2012, 3, 4, 5, 6, 7).unwrap().into();
Expand Down Expand Up @@ -1087,9 +1116,6 @@ mod tests {
#[test]
fn rotate() {
let build = |rotate_on_open| {
fs::remove_dir_all(LOGS_PATH.as_path()).unwrap();
fs::create_dir(LOGS_PATH.as_path()).unwrap();

let hourly_sink = RotatingFileSink::builder()
.base_path(LOGS_PATH.join("hourly.log"))
.rotation_policy(RotationPolicy::Hourly)
Expand All @@ -1114,61 +1140,129 @@ mod tests {
logger
};

let exist_files = |file_name_prefix| {
let paths = fs::read_dir(LOGS_PATH.clone()).unwrap();

paths.fold(0_usize, |count, entry| {
if entry
.unwrap()
.file_name()
.to_string_lossy()
.starts_with(file_name_prefix)
{
count + 1
} else {
count
}
})
};

let exist_hourly_files = || exist_files("hourly");
let exist_daily_files = || exist_files("daily");

const SECOND_1: Duration = Duration::from_secs(1);
const HOUR_1: Duration = Duration::from_secs(60 * 60);
const DAY_1: Duration = Duration::from_secs(60 * 60 * 24);

{
let logger = build(true);
let mut record = Record::new(Level::Info, "test log message");
let initial_time = record.time();

assert_eq!(exist_hourly_files(), 1);
assert_eq!(exist_daily_files(), 1);
assert_files_count("hourly", 1);
assert_files_count("daily", 1);

logger.log(&record);
assert_eq!(exist_hourly_files(), 1);
assert_eq!(exist_daily_files(), 1);
assert_files_count("hourly", 1);
assert_files_count("daily", 1);

record.set_time(record.time() + HOUR_1 + SECOND_1);
logger.log(&record);
assert_eq!(exist_hourly_files(), 2);
assert_eq!(exist_daily_files(), 1);
assert_files_count("hourly", 2);
assert_files_count("daily", 1);

record.set_time(record.time() + HOUR_1 + SECOND_1);
logger.log(&record);
assert_eq!(exist_hourly_files(), 3);
assert_eq!(exist_daily_files(), 1);
assert_files_count("hourly", 3);
assert_files_count("daily", 1);

record.set_time(record.time() + SECOND_1);
logger.log(&record);
assert_eq!(exist_hourly_files(), 3);
assert_eq!(exist_daily_files(), 1);
assert_files_count("hourly", 3);
assert_files_count("daily", 1);

record.set_time(initial_time + DAY_1 + SECOND_1);
logger.log(&record);
assert_eq!(exist_hourly_files(), 4);
assert_eq!(exist_daily_files(), 2);
assert_files_count("hourly", 4);
assert_files_count("daily", 2);
}
}

// This test may only detect issues if the system time zone is not UTC.
// TODO: Consider mocking the system time zone?
#[test]
fn respect_local_tz() {
let prefix = "respect_local_tz";

let initial_time = Local // FixedOffset::east_opt(8 * 3600).unwrap()
.with_ymd_and_hms(2024, 8, 29, 11, 45, 14)
.unwrap();

let logger = {
let daily_sink = RotatingFileSink::builder()
.base_path(LOGS_PATH.join(format!("{prefix}.log")))
.rotation_policy(RotationPolicy::Daily { hour: 0, minute: 0 })
.rotate_on_open(true)
.build_with_initial_time(Some(initial_time.to_utc().into()))
.unwrap();

build_test_logger(|b| b.sink(Arc::new(daily_sink)).level_filter(LevelFilter::All))
};

{
let mut record = Record::new(Level::Info, "test log message");

assert_files_count(prefix, 1);

record.set_time(initial_time.to_utc().into());
logger.log(&record);
assert_files_count(prefix, 1);

record.set_time(record.time() + HOUR_1 + SECOND_1);
logger.log(&record);
assert_files_count(prefix, 1);

record.set_time(record.time() + HOUR_1 + SECOND_1);
logger.log(&record);
assert_files_count(prefix, 1);

record.set_time(
initial_time
.with_day(30)
.unwrap()
.with_hour(0)
.unwrap()
.with_minute(1)
.unwrap()
.to_utc()
.into(),
);
logger.log(&record);
assert_files_count(prefix, 2);

record.set_time(record.time() + HOUR_1 + SECOND_1);
logger.log(&record);
assert_files_count(prefix, 2);

record.set_time(
initial_time
.with_day(30)
.unwrap()
.with_hour(8)
.unwrap()
.with_minute(2)
.unwrap()
.to_utc()
.into(),
);
logger.log(&record);
assert_files_count(prefix, 2);

record.set_time(record.time() + HOUR_1 + SECOND_1);
logger.log(&record);
assert_files_count(prefix, 2);

record.set_time(
initial_time
.with_day(31)
.unwrap()
.with_hour(0)
.unwrap()
.to_utc()
.into(),
);
logger.log(&record);
assert_files_count(prefix, 3);

record.set_time(record.time() + HOUR_1 + SECOND_1);
logger.log(&record);
assert_files_count(prefix, 3);
}
}
}
Expand Down
2 changes: 1 addition & 1 deletion spdlog/src/test_utils/unit_test.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -12,6 +12,6 @@ use crate::sync::*;

pub static TEST_LOGS_PATH: Lazy<PathBuf> = Lazy::new(|| {
let path = Path::new(env!("OUT_DIR")).join("test_logs");
fs::create_dir(&path).unwrap();
_ = fs::create_dir(&path);
path
});

0 comments on commit 6dbbbf2

Please sign in to comment.