TimedRotatingFileHandler "midnight" misleading when interval > 1

[mschiess]

BPO	46377
Nosy	@vsajip
PRs	bpo-46377: TimedRotatingFileHandler fix to ignore interval when "midnight" is given #30599

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = None
closed_at = None
created_at = <Date 2022-01-14.13:50:48.156>
labels = ['type-feature', 'library', '3.11']
title = 'TimedRotatingFileHandler "midnight" misleading when interval > 1'
updated_at = <Date 2022-01-14.18:25:21.751>
user = 'https://bugs.python.org/mschiess'

bugs.python.org fields:

activity = <Date 2022-01-14.18:25:21.751>
actor = 'mschiess'
assignee = 'none'
closed = False
closed_date = None
closer = None
components = ['Library (Lib)']
creation = <Date 2022-01-14.13:50:48.156>
creator = 'mschiess'
dependencies = []
files = []
hgrepos = []
issue_num = 46377
keywords = ['patch']
message_count = 5.0
messages = ['410558', '410565', '410567', '410571', '410583']
nosy_count = 3.0
nosy_names = ['vinay.sajip', 'python-dev', 'mschiess']
pr_nums = ['30599']
priority = 'normal'
resolution = None
stage = 'patch review'
status = 'open'
superseder = None
type = 'enhancement'
url = 'https://bugs.python.org/issue46377'
versions = ['Python 3.11']

Linked PRs

• gh-90535: Warn of deprecation of intervals other than 1 with when='MIDNIGHT' #98099
• gh-90535: Fix support of interval>1 in logging.TimedRotatingFileHandler #116220
• [3.12] gh-90535: Fix support of interval>1 in logging.TimedRotatingFileHandler (GH-116220) #116892
• [3.11] gh-90535: Fix support of interval>1 in logging.TimedRotatingFileHandler (GH-116220) #116893

[mschiess]

Using the TimedRotatingFileHandler along with "when='midnight'" and interval > 1, midnight is handled equally to "days" which is a little misleading.

Expectation:
setting when to 'midnight', the file is rotated every midnight (interval value should be ignored)

Current behavior:
If 'midnight' is given alongside with an interval greater than 1 (.e.g 5), the (internal) interval (24*60*60) is calculated with the given interval -> 24*60*60 * 5.

In my case, this led to some unforeseeable and unexpected behavior.

[vsajip]

Making a change without considering backward compatibility is premature. I've closed the PR as there appears to be something wrong with it - it references hundreds of changed files. Did you look at the 'atTime' keyword parameter of TimedRotatingFileHandler?

[mschiess]

i've just checked PR and you're right, something with the PR went wrong.

Anyway, midnight (at least from the wording) specifies the "atTime". (which should be midnight).

Again, if there's (by mistake) an interval bigger than 1 set(which in my mind makes no sense along to be used with midnight) things are getting pretty intransparent. The midnight handler created a logfile dated with 2021-12-15 (last night). Took me some time to get this sorted. (I've discovered, that I've set 30 in a default value file).

Agreed on the backward compatibility, but I would assume someone using "midnight" would not expect any other behavior than "daily at midnight" besides using the atTime to modify the rollover time. (my opinion)

[vsajip]

Unfortunately, you can't rely on people always doing "the sensible thing", for any number of good reasons. If a particular set of parameter values didn't cause failure, it is probably used somewhere.

Anyway, your problem goes away if interval == 1, right? If we were to tighten things up (e.g. disallowing interval > 1 with "midnight"), then it would have to be done on a deprecation cycle at the very least, ISTM.

[mschiess]

Yes, enforcing interval == 1 or interval == None (which pulls the TimedRotatingFileHandler class __init__ default value which is also 1) works perfectly with midnight.

I do not see any urge on that topic - as I personally now know the issue :D - but I really feel this fix could save someones else's time someday ;)

So going the "safe" way via deprecation cycle seems to be the right approach

[serhiy-storchaka]

I see now that the problem is that computeRollover() returns the next nearest "midnight" time, ignoring the interval parameter, while doRollover() computes the file name by stepping back interval days. And there is the same issue with the weekly rotation.

My fix #116191 perhaps affected this issue and made it worse (if you do not consider it better). Previously, in doRollover(), if computeRollover() returned the current time, self.interval was added, so the next rollover time was set after interval days or weeks. But this behavior depended on atTime and the time of running the script.

Perhaps the safest way is to implement the correct support of the interval parameter for "midnight" and weekly rotation.