Timestamp format with too little information (missing time components) cannot be parsed

[jb-alvarado]

Hello again,
I think there is bug with removing old files, when old log files exists and the program start again.

You can reproduce this with:

1. create a log file like: logs/file.2022-01-30
2. run test:

#[test]
fn test_file_limit() {
   let log_path = "logs/file";

   let first = get_fake_date_time("2022-02-01T01:00:00");
   let second = get_fake_date_time("2022-02-02T01:00:00");
   let third = get_fake_date_time("2022-02-03T01:00:00");

   let mut log = FileRotate::new(
       &log_path,
       AppendTimestamp::with_format("%Y-%m-%d", FileLimit::MaxFiles(1), DateFrom::DateYesterday),
       ContentLimit::Time(TimeFrequency::Daily),
       Compression::None,
   );

   mock_time::set_mock_time(first);
   writeln!(log, "1").unwrap();
   mock_time::set_mock_time(second);
   writeln!(log, "2").unwrap();
   mock_time::set_mock_time(third);
   writeln!(log, "3").unwrap();
}

Normally the old log file should be deleted, but it stays.

[Ploppz]

I changed it to use TempDir and added an assert:

#[test]
fn test_file_limit() {
    let tmp_dir = TempDir::new("file-rotate-test").unwrap();
    let dir = tmp_dir.path();
    let log_path = dir.join("file");

    std::fs::File::create(dir.join("file.2022-01-30")).unwrap();

    let first = get_fake_date_time("2022-02-01T01:00:00");
    let second = get_fake_date_time("2022-02-02T01:00:00");
    let third = get_fake_date_time("2022-02-03T01:00:00");

    let mut log = FileRotate::new(
        &log_path,
        AppendTimestamp::with_format("%Y-%m-%d", FileLimit::MaxFiles(1), DateFrom::DateYesterday),
        ContentLimit::Time(TimeFrequency::Daily),
        Compression::None,
    );

    mock_time::set_mock_time(first);
    writeln!(log, "1").unwrap();
    mock_time::set_mock_time(second);
    writeln!(log, "2").unwrap();
    mock_time::set_mock_time(third);
    writeln!(log, "3").unwrap();

    assert_eq!(log.log_paths(), [dir.join("file.2022-02-03")]);
}

Is my assert according to your expectation?
I get this assertion error:

thread 'tests::test_file_limit' panicked at 'assertion failed: `(left == right)`
  left: `["/tmp/file-rotate-test.CfYwJakhqd7u/file.2022-02-02"]`,
 right: `["/tmp/file-rotate-test.CfYwJakhqd7u/file.2022-02-03"]`', src/tests.rs:448:5

Is that the same behaviour you are seeing?
It does seem to delete the oldest file. But I'm puzzled why the remaining file is 2022-02-02 and not 2022-02-03

[jb-alvarado]

You can change the test a bit more, then you see the problem:

#[test]
fn test_file_limit() {
    let tmp_dir = TempDir::new("file-rotate-test").unwrap();
    let dir = tmp_dir.path();
    let log_path = dir.join("file");
    let old_file = dir.join("file.2022-02-01");

    std::fs::File::create(&old_file).unwrap();

    let first = get_fake_date_time("2022-02-02T01:00:00");
    let second = get_fake_date_time("2022-02-03T01:00:00");
    let third = get_fake_date_time("2022-02-04T01:00:00");

    let mut log = FileRotate::new(
        &log_path,
        AppendTimestamp::with_format("%Y-%m-%d", FileLimit::MaxFiles(1), DateFrom::DateYesterday),
        ContentLimit::Time(TimeFrequency::Daily),
        Compression::None,
    );

    mock_time::set_mock_time(first);
    writeln!(log, "1").unwrap();
    mock_time::set_mock_time(second);
    writeln!(log, "2").unwrap();
    mock_time::set_mock_time(third);
    writeln!(log, "3").unwrap();

    assert_eq!(log.log_paths(), [dir.join("file.2022-02-03")]);
    assert!(!old_file.is_file());
}

The first assert pass, but the second one fail.

[Ploppz]

I found the culprit.

When FileRotate is created, it seems that when it calls scan_suffixes internally, it does not pick up on the existing files, hence why log_paths() returns an empty array.
Turns out this issue is specific for timestamp formats that have too little information:

Parsing 2022-02-01 with format %Y-%m-%d
    Err(ParseError(NotEnough))

printed here https://github.com/BourgondAries/file-rotate/blob/master/src/suffix.rs#L281
I guess we need to find a way to set the remaining fields to a default value.

[jb-alvarado]

Nice that you found the problem!

How about:

    fn parse(&self, suffix: &str) -> Option<Self::Repr> {
        let (timestamp_str, n) = if let Some(dot) = suffix.find('.') {
            if let Ok(n) = suffix[(dot + 1)..].parse::<usize>() {
                (&suffix[..dot], Some(n))
            } else {
                return None;
            }
        } else {
            (suffix, None)
        };

        if timestamp_str.len() <= 10 {
            NaiveDate::parse_from_str(timestamp_str, self.format)
                .map(|_| TimestampSuffix {
                    timestamp: timestamp_str.to_string(),
                    number: n,
                })
                .ok()
        } else {
            NaiveDateTime::parse_from_str(timestamp_str, self.format)
                .map(|_| TimestampSuffix {
                    timestamp: timestamp_str.to_string(),
                    number: n,
                })
                .ok()
        }
    }

[Ploppz]

That's one possibility. Some thoughts:
In that case, and actually in any case, we should validate the format string. It must:

• have no gaps. e.g. %Y%d (missing %m) (I can't think of any use case where it would make sense with any gaps)
• all format components must be in order of descending significance

I think that's it.
Then, I was about to share some code I wrote for another project, which parses a complete NaiveDateTime from any prefix of a date, filling in the blanks.
BUT, I realized something.
When we get this ParseError(NotEnough) error from chrono, does that mean that the parsing of the input according to the format, was actually successful - it's just the construction of a NaiveDateTime that failed? In that case we could perhaps actually treat that error as success, because all we want is to check whether the suffix adheres to the format, and we don't actually even use the resulting NaiveDateTime

[Ploppz]

I don't have time today, but if you want to look into it, you can try to treat said error as success, and write a test to verify my suspicion about the error. Otherwise I'll continue this later on. I already started writing a test a bit earlier:

#[test]
fn timestamp_scan_suffixes() {
    struct TestCase {
        format: &'static str,
        suffixes: &'static [&'static str],
    }

    let cases = [
        TestCase {
            format: "%Y%m%dT%H%M%S",
            suffixes: &["20220201T101010", "20220202T101010"],
        },
        TestCase {
            format: "%Y-%m-%d",
            suffixes: &["2022-02-01", "2022-02-02"],
        },
    ];

    for (i, case) in cases.iter().enumerate() {
        println!("Case {}", i);
        let tmp_dir = TempDir::new("file-rotate-test").unwrap();
        let dir = tmp_dir.path();
        let log_path = dir.join("file");

        for suffix in case.suffixes {
            std::fs::File::create(dir.join(format!("file.{}", suffix))).unwrap();
        }

        let scheme = AppendTimestamp::with_format(
            case.format,
            FileLimit::MaxFiles(1), // has no effect on this test
            DateFrom::DateYesterday,
        );

        let suffixes = scheme.scan_suffixes(&log_path);
        assert_eq!(suffixes.len(), case.suffixes.len());
        println!("Passed\n");
    }
}

But we should also add something like incorrect_suffixes: &'static [&'static str], to check that suffix parsing fails for suffixes that don't adhere to the format.

[jb-alvarado]

Yes I can try, but I'm still not understand 100% the code. And I'm also not sure which cases we will have in normal use cases. For example when you use yearly or monthly rotations, then you would have maybe formats like %y or %Y%m.

[jb-alvarado]

I came up with this solution:

    fn parse(&self, suffix: &str) -> Option<Self::Repr> {
        let (timestamp_str, n) = if let Some(dot) = suffix.find('.') {
            if let Ok(n) = suffix[(dot + 1)..].parse::<usize>() {
                (&suffix[..dot], Some(n))
            } else {
                return None;
            }
        } else {
            (suffix, None)
        };

        let numbers = timestamp_str
            .chars()
            .filter(|&c| c.is_numeric())
            .map(|c| c.to_string())
            .collect::<Vec<String>>();

        if numbers.len() <= 8 {
            NaiveDateTime::parse_from_str(
                &format!("{:1<8}T000000", numbers.join("")),
                "%Y%m%dT%H%M%S",
            )
        } else {
            NaiveDateTime::parse_from_str(timestamp_str, self.format)
        }
        .map(|_| TimestampSuffix {
            timestamp: timestamp_str.to_string(),
            number: n,
        })
        .ok()
    }

The timestamp format %Y or %Y%m is not allowed by AppendTimestamp::with_format, so maybe it is enough like that?

[jb-alvarado]

I'm having a strange situation now. All the tests working fine, but when I use the lib with this modifications in my program, it still don't delete the old files.

I have no idea, why...

[Ploppz]

In any case, I'll make an attempt myself at an implementation today, I want to try the idea I mentioned about accepting that specific error as success.

[Ploppz]

This seems to work https://github.com/Ploppz/file-rotate/tree/timestamp-parse-fix
It's a simple and general solution. But it relies on the PR in chrono that is not yet merged chronotope/chrono#588 But I expect that it will soon be merged.
Can you check if you get similar problems with this branch?

[jb-alvarado]

Same problem, tests run fine, in real use case failed. I use this lib in combination with simplelog, but I don't think this is a problem.

[Ploppz]

If you can create a minimal reproducible example or another test, I can help you debug it.

[jb-alvarado]

Thank you for your willingness! I created here a example: https://github.com/jb-alvarado/test-rotate

[Ploppz]

I won't have time today, unfortunately, but tomorrow I will probably have time

[Ploppz]

I think the reason you are seeing that behaviour, is because the logic to remove old files is only executed when rotation happens (fn rotate)

[jb-alvarado]

Ah sorry, you are right, I check this with the test program and it works like you say.

[Ploppz]

To summarize this discussion:
It started with one perceived problem which was then solved as invalid. But in the process, we found another problem:

When FileRotate is created, it seems that when it calls scan_suffixes internally, it does not pick up on the existing files, hence why log_paths() returns an empty array. Turns out this issue is specific for timestamp formats that have too little information:

Parsing 2022-02-01 with format %Y-%m-%d
    Err(ParseError(NotEnough))

printed here https://github.com/BourgondAries/file-rotate/blob/master/src/suffix.rs#L281 I guess we need to find a way to set the remaining fields to a default value.

I wrote a fix for this in a branch, but it cannot be included in file-rotate before a new release of chrono happens. The needed chrono PR is merged, just waiting for a release.

This seems to work https://github.com/Ploppz/file-rotate/tree/timestamp-parse-fix It's a simple and general solution. But it relies on the PR in chrono that is not yet merged chronotope/chrono#588 But I expect that it will soon be merged. Can you check if you get similar problems with this branch?

If anyone needs this to be fixed, then I would ask @jb-alvarado to make a PR with their latest solution as a temporary one. (must include test)

[jb-alvarado]

Hi @Ploppz, now chrono 0.4.20-rc.1 is officially out. How about to use it already and make your fix public? The last months I used the git master in my project without any issue.

[Ploppz]

Alright, I published the fix as 0.7.0-rc.0! (I think we need to use rc versioning as long as we depend on some rc version?)

[jb-alvarado]

Thank you! I think is ok to use rc. Hopefully it takes not to long for a final release :-).

[jb-alvarado]

@Ploppz, chrono 0.4.20 is now finally out :-).

[Ploppz]

Thanks for the heads up! I published 0.7.0