gh-84649: Make TimedRotatingFileHandler use CTIME instead of MTIME

[martonivan]

The TimedRotatingFileHandler previously used MTIME attribute of the log
file to detect whether it has to be rotate yet or not. In cases when the
file is changed within the rotation period the MTIME is also updated
to the current time and the rotation never happens. It's more
appropriate to check the file creation time (CTIME) instead.

https://bugs.python.org/issue40469

• Issue: TimedRotatingFileHandler rotating on use not time #84649

[the-knights-who-say-ni]

Hello, and thanks for your contribution!

I'm a bot set up to make sure that the project can legally accept this contribution by verifying everyone involved has signed the PSF contributor agreement (CLA).

CLA Missing

Our records indicate the following people have not signed the CLA:

@martonivan

For legal reasons we need all the people listed to sign the CLA before we can look at your contribution. Please follow the steps outlined in the CPython devguide to rectify this issue.

If you have recently signed the CLA, please wait at least one business day
before our records are updated.

You can check yourself to see if the CLA has been received.

Thanks again for the contribution, we look forward to reviewing it!

[martonivan]

I've rebased the branch, squashed the recent fix (about the NEWS typo) into the last commit, as it was partially recommended in the bug report about the flawed testing infrastructure: https://bugs.python.org/issue43382

[github-actions]

This PR is stale because it has been open for 30 days with no activity.

[vsajip]

See my suggestion on the issue if you want to progress things further.

[martonivan]

See my suggestion on the issue if you want to progress things further.

Thanks Vinay, I'll implement the suggested and acceptable solution as soon as I get there and will update this merge request.

[serhiy-storchaka]

LGTM. I was just about to create the same issue.

[serhiy-storchaka]

@martonivan, the mechanism for the CLA signing was changed, please sign the CLA again, it is necessary for merging. Thank you for your contribution.

[martonivan]

Unfortunately I cannot access to the email address that stands in the commit anymore. Tried to reword those commits and rebase the whole tree, but I may caused more issue than I solved. Could you please help me what would be the proper way to implement this change in the commits?

[JelleZijlstra]

Either open a new PR, or reapply your changes to main and force-push to this PR branch to get rid of the problematic changes.

[serhiy-storchaka]

Well, it is complicated.

1. First, there are failing tests. They change the modification time to trigger rollover (it is not easy to fake the creation time). It can be fixed if make the code taking the minimum of ctime and mtime.

2. New tests for ctime are needed to test that old files are rolled over even if mtime is fresh. I see two ways:

   • Create a handler with very short interval (3 seconds), emit a log record, close the handler, wait 1.5 seconds, re-create the handler, emit the record, close the handler, check that the file was not rolled over, wait 1.5 seconds, re-create the handler, emit the record, close the handler, check that the file was rolled over. Exact times may need corrections. There may be surprises on Windows with FAT32.
   • Create a modification of one of currently failing tests. Instead changing the modification time to the past time, change it to the future time. You need also to patch time.time() to make it returning the time from future.

   It would be better to implement both ways.

3. ctime is actually not the "creation time", but the "node change time", although in many cases there is no difference between them. But it is worth to use also the real creation time which is available on some platforms. It is exposed as the st_birthtime attribute (note that it is float). So perhaps the code should take the minimum os st_birthtime, st_ctime and st_mtime.

[martonivan]

I've implemented many of the suggested changes, but realized a huge issue: on Linux, since ctime also changes when the data block changes (practically when mtime changes), the test that checks if only the birthdate is old enough for rotation will always fail. It would be nice the have statx implemented and birth date/creation date known there too, but this issue is already staling for a while: #19125
I could restrict this test only for Windows and MacOS, I guess. I didn't find the proper helper scripts yet in test/support, but I assume this could be a workaround until the PR mentioned above is not merged. What would you suggest? What's the best practice to resolve similar issues?

[serhiy-storchaka]

It is okay if this part of the feature is not supported on all platforms. We should do the best of what is currently possible on every platform. The availability of these attributes also depends on the file system.

[martonivan]

All the tests are green on the supported operating systems.

[erlend-aasland]

@martonivan: when sync'ing with main, could you instead please do git merge --no-ff main, and not git rebase? Force-pushes do not play very well with GitHub's UI, and it makes reviewing harder. See also the devguide. Note that all PRs are squashed into a single commit when we merge, so it does not matter if the PR commit history is messy.

[martonivan]

@martonivan: when sync'ing with main, could you instead please do git merge --no-ff main, and not git rebase? Force-pushed do not play very well with GitHub's UI, and it makes reviewing harder. See also the devguide. Note that all PRs are squashed into a single commit when we merge, so it does not matter if the PR commit history is messy.

Noted for further contribution, I'm not sure if any further commits will be necessary for this one.

[github-actions]

This PR is stale because it has been open for 30 days with no activity.

[vstinner]

This change added test_rollover_based_on_st_birthtime_only() to test_logging, but the test fails randomly on Windows, macOS and FreeBSD: I created issue gh-150960 to track this regression.