TimedRotatingFileHandler overwrite log

[aeg]

BPO	44186
Nosy	@vsajip, @Harry-Lees, @aeg
PRs	bpo-44186: prevent TimedRotatingFileHandler overwriting log files #26553
Files	log.py log_44186.py: Slightly updated Python script test.sh: Test shell script

^{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 = 'https://github.com/vsajip'
closed_at = None
created_at = <Date 2021-05-20.10:21:59.331>
labels = ['type-bug', 'library', '3.9']
title = 'TimedRotatingFileHandler overwrite log'
updated_at = <Date 2021-08-02.07:48:35.356>
user = 'https://github.com/aeg'

bugs.python.org fields:

activity = <Date 2021-08-02.07:48:35.356>
actor = 'vinay.sajip'
assignee = 'vinay.sajip'
closed = False
closed_date = None
closer = None
components = ['Library (Lib)']
creation = <Date 2021-05-20.10:21:59.331>
creator = 'aeg'
dependencies = []
files = ['50053', '50194', '50195']
hgrepos = []
issue_num = 44186
keywords = ['patch']
message_count = 5.0
messages = ['394009', '395141', '398683', '398692', '398732']
nosy_count = 3.0
nosy_names = ['vinay.sajip', 'Harry-Lees', 'aeg']
pr_nums = ['26553']
priority = 'normal'
resolution = None
stage = 'patch review'
status = 'open'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue44186'
versions = ['Python 3.9']

Linked PRs

• gh-88352: Fix logging.TimedRotatingFileHandler #116191
• [3.12] gh-88352: Fix logging.TimedRotatingFileHandler (GH-116191) #116208
• [3.11] gh-88352: Fix logging.TimedRotatingFileHandler (GH-116191) #116209
• gh-88352: Make TimedRotatingFileHandler tests more stable #116409
• [3.12] gh-88352: Make TimedRotatingFileHandler tests more stable (GH-116409) #116585
• [3.11] gh-88352: Make TimedRotatingFileHandler tests more stable (GH-116409) #116586

[aeg]

If you use TimedRotatingFileHandler and specify when='midnight',atTime, the log will always rollover if you start it at the same time as atTime.

For example, if atTime='00:00:00', and you run a script that outputs logs using the logger library twice at 00:00:00, the log that was rolled over the first time will be overwritten by the second rollover, and the 1st rollovered log will be lost.

[Harry-Lees]

This bug seems to come from the fact that the file rollover occurs it removes any files with same name as the destination file.

I believe this bug occurs on all "when" options, but the midnight option truncates the filename so only the date so it's much more likely to be a collision in filename so it's much easier to notice that it's happening.

One way of fixing this is to check if the destination file already exists, and if it does, append the logs to the end of the file instead of overwriting it.

Another potential fix is to check if the destination file already exists, and if it does rename it to something else, or even to choose a different name for the destination file of the log e.g. if the filename would be log.2021-05-05 but there is a collision, call the file log.2021-05-05(1).

Personally I prefer the last option, it seems like the best way to avoid any future issues that could arise from appending. I can open a PR for this in the morning.

[vsajip]

I modified the provided test script (-> test_44186.py) and added a test shell script which runs it twice in succession. What it printed was:

6 51 43
TEST > [INFO] [2021-08-01 06:51:43] : foo 2021-08-01T06:51:43.091681
6 51 43
TEST > [INFO] [2021-08-01 06:51:43] : bar 2021-08-01T06:51:43.138274

and the log files created were

$ more test.log*
::::::::::::::
test.log
::::::::::::::
bar 2021-08-01T06:51:43.138274
::::::::::::::
test.log.2021-07-31
::::::::::::::
foo 2021-08-01T06:51:43.091681

So from what I can see, both logged messages are present and nothing has been lost. Can you describe the problem more clearly? I can't see one.

[Harry-Lees]

The issue appears when the TimedRotatingHandler rolls over to a filename that already exists. Running your bash script, the handler correctly rolls over so you end up with the expected behaviour. This issue arises in the case that there is already a file with the target name, that file will be overwritten when the handler rolls over.

This can be seen clearly if you modify test.sh to contain

python3 log_44186.py foo
python3 log_44186.py bar
python3 log_44186.py baz

results are below:

$ python3 --version
Python 3.9.5
$ bash ./test.sh
10 14 51
TEST > [INFO] [2021-08-01 10:14:51] : foo 2021-08-01T10:14:51.521266
10 14 51
TEST > [INFO] [2021-08-01 10:14:51] : bar 2021-08-01T10:14:51.577802
10 14 51
TEST > [INFO] [2021-08-01 10:14:51] : baz 2021-08-01T10:14:51.634795
$ ls | grep .log
test.log
test.log.2021-07-31
$ cat test.log
baz 2021-08-01T10:14:51.634795
$ cat test.log.2021-07-31 
bar 2021-08-01T10:14:51.577802

as you can see, the logs from foo have been overwritten.

A very similar result can be seen if you manually create a file and then run the test script.

$ python3 --version
Python 3.9.5
$ echo "logging test" > test.log.2021-07-31
$ python3 log_44186.py foo
10 33 25
TEST > [INFO] [2021-08-01 10:33:25] : foo 2021-08-01T10:33:25.003750
$ cat test.log
foo 2021-08-01T10:33:25.003750
$ cat test.log.2021-07-31
$

once again, you can see that the handler overwrote the target file (this time leaving it blank as there were no logs to write).

[vsajip]

OK, I get it now :-)

See my comments on the PR - I think the renaming strategy might need rethinking in the presence of a "namer" routine being set. See bpo-43344, bpo-44753. This area (TimedRotatingFileHandler) is unfortunately not yet well tested, because you would need mocking to avoid delays in test runs. But ideally, we would test in the absence and presence of a renamer routine that moved the ".log" to the end of the filename.