I have a problem understanding why things were designed as they are in the TimedRotatingFileHandler.
It says there:
When computing the next rollover time for the first time (when the handler is created), the last modification time of an existing log file, or else the current time, is used to compute when the next rotation will occur.
Consider this use case: A script gets started frequently (say every 5 minutes) and only runs for a few seconds, logging some lines to the log file in each run.
If the TimedRotatingFileHandler is configured to rotate every hour, the log file will never be rotated in this case!
Every run will update the st_mtime of the file so the next run considers it too new to rotate.
To trigger a rotation we need a break of the configured interval, where the script does not run.
Is this really the intended behaviour?
If we used st_ctime instead of st_mtime , rotation would happen when the file gets older than the configured interval, no matter how often it was changed in between.
For scripts running continuously, this wouldn’t make a big difference, but for scripts that get started frequently it may be the difference between a rotation that works an one that never rotates at all.
This problem seems to be the same for values of when in ['S', 'M', 'H', 'D']. It does not matter for midnight or W{0-6}, because those use other algorithms to determine rotation times.
What do you think about this?
Is this something that should be improved or am I missing a point?
Won’t it? Suppose the latest entry was made around 10:58. At 11:03 the script runs again, sees the modification time 10:58 and computes a rollover time of 11:00, sees that the rollover time is in the past and rolls over.
Yes, I have tried it. I also have looked into the code of TimedRotatingFileHandler.
The problem is that computeRollover() simply returns currentTime + self.interval, with currentTime beeing the file modification time. So for your example you would get 11:58 for the next rollover.
st_ctime is not the file creation time on Unix systems.
I’m not an expert on logging, but your logic makes sense to me. Perhaps it is out of a desire to avoid platform-dependent behaviour, where the same code behaves very differently on Unix and Windows systems?
Thanks for pointing me to this bug report!
It describes exactly the problem I was talking about
Also, I found out that file creation times don’t really work as expected in Windows, too, because of “file system tunnelling”, which is described nicely in this blog post:
The simple action “delete a file and create a new one with the original name a current timestamp”
is not simple at all!
We would at least need to touch the file after it’s creation.
Unfortunately I wasn’t able to find a working implementation of touch in Python, since the obvious one in pathlib only creates the file, but doesn’t update it’s timestamp (which I always considered to be the main point of touch).
I guess the reason for this is that different OS make it very hard to implement such stuff in a platform independent and consistent manner.
So now I am at a point where I can see what’s going wrong, but I am not sure if and how this can be fixed at all
I have to correct myself:
On Linux or similar systems, touch only changes access and modification times of a file, creation time stays literally “untouched”.
So this wouldn’t help us at all.
The result is this handler class that changes the TimedRotatingFileHandler to use ctime instead of mtime.
It imports the small package win32_setctime that solves the problem of setting the ctime of a file on Windows.
It’s not very elegant to do the rollover calculation twice, but it’s the only way I found without copying lots of code from the original class. Implementing this as an option directly inside TimedRotatingFileHandler would be a much better solution. But this might take more effort than it seems, because then we would also need an official version of the setctime builtin function, which should probably belong into os.path.
import sys
import os
from time import time
from stat import ST_CTIME
from logging.handlers import TimedRotatingFileHandler
from logging import FileHandler
platform_win = sys.platform.startswith("win")
if platform_win:
from win32_setctime import setctime
class CTimedRotatingFileHandler(TimedRotatingFileHandler):
"""
TimedRotatingFileHandler using ctime instead of mtime to determine rollover times.
This subclass of TimedRotatingFileHandler uses file creation time instead of file modification time to calculate
the next rollover time.
It also contains a workaround for file system tunneling on Windows, which prevents new files from having new
creation times if they have already existed a short time ago.
"""
def __init__(self, filename, when='h', interval=1, backupCount=0, encoding=None, delay=False, utc=False,
atTime=None):
# Call parent __init__ with delay=True to make sure the file is not created at this point.
TimedRotatingFileHandler.__init__(self, filename, when, interval, backupCount, encoding, True, utc, atTime)
# This has been done in the parent class using ST_MTIME.
# Do it again using ST_CTIME and overwriting the previous result.
if os.path.exists(filename):
t = os.stat(filename)[ST_CTIME]
self.rolloverAt = self.computeRollover(t)
# This opens the file if delay=False
FileHandler.__init__(self, filename, 'a', encoding, delay)
# Overwrite _open() to make sure we set the correct ctime to work around Windows file system tunneling.
def _open(self):
need_to_set_ctime = platform_win and not os.path.exists(self.baseFilename)
stream = super()._open()
if need_to_set_ctime:
setctime(self.baseFilename, time(), follow_symlinks=True)
return stream
I only tested this code superficially on Windows and not at all on other OS!
