[issue40469] TimedRotatingFileHandler rotating on use not time
Ivan Marton added the comment:
The assumed behaviour of TimedRotatingFileHandler is to rotate log files older
than configured. Even when the script is executed multiple times.
self.rolloverAt (the variable that defines when the rollover should be
performed) is set after each rollover and right after initializing the file
handler instance.
If the instance is initialized once (like in your script) and a rollover is
performed without having the object destroyed, the logger works fine, the
rollover is done and the next round is scheduled properly.
The case is not so lucky if the script runs multiple time or the logger itself
is initialized multiple times during one execution. In this case, since the
MTIME is read each time when the TimedRotatingFileHandler's init is called, and
the file is modified (by having a new line added to the end of the file). The
next execution will read the new MTIME and will never perform any rollover.
I've slightly modified your example script to demonstrate these use-cases.
Example 1: Log a single line with the script, but execute it multiple times
with delays between the execution!
In bash: for i in {1..101}; do python log_40469_single.py $i; sleep 30; done
Example 2: Log multiple lines, but reinitiate the logger object between the
events!
See log_40469_new_instance.py
--
Added file: https://bugs.python.org/file50208/log_40469_new_instance.py
___
Python tracker
<https://bugs.python.org/issue40469>
___
___
Python-bugs-list mailing list
Unsubscribe:
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com
[issue40469] TimedRotatingFileHandler rotating on use not time
Change by Ivan Marton : Added file: https://bugs.python.org/file50209/log_40469_single.py ___ Python tracker <https://bugs.python.org/issue40469> ___ ___ Python-bugs-list mailing list Unsubscribe: https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com
[issue40469] TimedRotatingFileHandler rotating on use not time
Ivan Marton added the comment: Well, there is nothing in the documentation that would say the logrotation can be only performed by continously running scripts, thats why. :) There are scripts or even daemons written in Python that need to be restarted from time to time. If the logrotate period is greater than restart period the log files will never be rotated, however they could be. We were looking for something that works like the logrotate do, but without involving any external logic, but the one written in python. And TimedLogrotateHandler appears to be one of those, unless it checks the MTIME of the files instead of the CTIME. What is the logic behind checking the MTIME instead of CTIME when one is calculating the age of a file when tries to calculate whether it has to be rotated or not? If the only purpose of this initial rollover calculation would be to start a predefined long period (as you suggest), now() (time of execution) should used instead and no file attribute should be involved. From the code I have to assume that the original author also tried to prepare for the cases where the execution is interrupted and/or restarted and (s)he wanted the TimedLogrotateHandler to be resumed where it was during the previous execution. Dnn't you agree? -- ___ Python tracker <https://bugs.python.org/issue40469> ___ ___ Python-bugs-list mailing list Unsubscribe: https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com
[issue40469] TimedRotatingFileHandler rotating on use not time
Ivan Marton added the comment: > Well, what's the need to rotate based on time when you just run scripts > sporadically or they're very short-lived? Not trying to argue, just trying to > understand. > Yes, but generally daemons are long-lived relative to the rotation interval, > aren't they? "From time to time" certainly implies that to me. In one of our use-cases, where I faced with this bug/behaviour of TimedRotatingFileHandler, we are using it in a daemon for daily logrotate. The aim is to have the logs separated day by day, just like the majority of our other components running on a linux. We've just realized that some days are missing from the series of logs and the investigation led to the service restart and the MTIME checking that we are talking about here. When a logger is configured to rotate daily one just simply assume that it will rotate daily regardless the daemon restart. (As en extreme(?) example, when a the system - and the daemon of course - is restarted each day - or just never running for a whole day - and btw it logs often, the log file won't be ever rotated and can inrease over every limits.) I've quickly googled around and found someone who execute some logic from cron and expects the loghandler to rotate his files, that wouldn't happened for the same reason: https://stackoverflow.com/questions/30569164/logging-handler-timedrotatingfilehandler-never-rotates-the-log > I just checked - the relevant code (using MTIME) was added in 2010, as a fix > for bpo-8117 - around the time that Python 2.6 was released. As I understand bpo-8117, the goal was to do the rollover even after script restarts. (To be frank, only an extreme case was mentioned in the issue opener entry, when the rollover period had been reached when the script wasn't running.) I believe for this purpose MTIME wasn't the best choice, but using CTIME instead would make the script do what is expected to. > I take it you mean TimedRotatingFileHandler. Certainly it assumes that the > script might be restarted, which is why it opens the file in append mode. > If the computation using MTIME were changed to use CTIME, that would be a > behaviour change, which could conceivably break someone's code that relied on > current behaviour (unlikely, but you just never know). I've no other > objection to using CTIME rather than MTIME - perhaps I'm just being > hyper-cautious about breakage? You are far better and more experienced in maintaining widely used opensource codebases so I wouldn't argue with you, but... :) - In case of scripts that create the log file for themselves the change would have no effect. - In case of scripts that are using already existing files for logging (by opening them for append) could change the behaviour, but just slighly. The first rollover would happen before adding the first new log line if the file age reached the configured time, and not when the age of last log line written to the file before having the script started reached the same value. No further rotation would be effected. I _believe_ no one expects the current initial behaviour in case of resumed log files, and for sure, the documentation doesn't cover this part so I don't know how to proceed. I _believe_ (again) that changing the behaviour wouldn't break the script outside, but rather would help them working the way how the developers originally assumed they did. -- ___ Python tracker <https://bugs.python.org/issue40469> ___ ___ Python-bugs-list mailing list Unsubscribe: https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com
[issue40469] TimedRotatingFileHandler rotating on use not time
Change by Ivan Marton : -- keywords: +patch nosy: +martonivan nosy_count: 1.0 -> 2.0 pull_requests: +23445 stage: -> patch review pull_request: https://github.com/python/cpython/pull/24660 ___ Python tracker <https://bugs.python.org/issue40469> ___ ___ Python-bugs-list mailing list Unsubscribe: https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com
[issue43382] github CI blocked by the Ubuntu CI with an SSL error
Change by Ivan Marton : -- nosy: +martonivan ___ Python tracker <https://bugs.python.org/issue43382> ___ ___ Python-bugs-list mailing list Unsubscribe: https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com
