[issue44186] TimedRotatingFileHandler overwrite log

[Vinay Sajip]

Vinay Sajip  added the comment:

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.

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue44186] TimedRotatingFileHandler overwrite log

[Harry]

Harry  added the comment:

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).

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue44186] TimedRotatingFileHandler overwrite log

[Vinay Sajip]

Vinay Sajip  added the comment:

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.

--
Added file: https://bugs.python.org/file50195/test.sh

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue44186] TimedRotatingFileHandler overwrite log

[Vinay Sajip]

Change by Vinay Sajip :


Added file: https://bugs.python.org/file50194/log_44186.py

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue44186] TimedRotatingFileHandler overwrite log

[Raymond Hettinger]

Change by Raymond Hettinger :


--
assignee:  -> vinay.sajip
nosy: +vinay.sajip

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue44186] TimedRotatingFileHandler overwrite log

[Harry]

Change by Harry :


--
keywords: +patch
pull_requests: +25140
stage:  -> patch review
pull_request: https://github.com/python/cpython/pull/26553

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue44186] TimedRotatingFileHandler overwrite log

[Harry]

Harry  added the comment:

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.

--
nosy: +Harry-Lees

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue44186] TimedRotatingFileHandler overwrite log

[Eiji Ito]

Change by Eiji Ito :


Added file: https://bugs.python.org/file50053/log.py

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue44186] TimedRotatingFileHandler overwrite log

[Eiji Ito]

New submission from Eiji Ito :

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.

--
components: Library (Lib)
messages: 394009
nosy: aeg
priority: normal
severity: normal
status: open
title: TimedRotatingFileHandler overwrite log
type: behavior
versions: Python 3.9

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com