TimedRotatingFileHandler overwrite log #88352
Comments
|
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. |
aeg
mannequin
added
3.9
|
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. |
|
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 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.091681So 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. |
|
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 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.577802as 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). |
|
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. |
|
Adding arbitrary suffixes will break algorithm for computing files to delete on roll over, especially the most reliable variant proposed in #115809. I think that the best alternative is to check if the destination file already exists, and if it does, do not roll over. If it exists, it means that it was already rolled over. In worst case the logging records will be added in the next snapshot, it is better than losing data. But it should be very rare case, and it means that there is an error in determining the roll over time. |
* Do not overwrite already rolled over files. It happened at midnight or during the DST change and caused the loss of data. * computeRollover() now always return the timestamp larger than the specified time. * Fix computation of the rollover time during the DST change.
|
There are several bugs here, and #116191 fixes some of them.
There are other bugs, but I'll open separate issues for them. |
* Do not overwrite already rolled over files. It happened at midnight or during the DST change and caused the loss of data. * computeRollover() now always return the timestamp larger than the specified time. * Fix computation of the rollover time during the DST change.
* Do not overwrite already rolled over files. It happened at midnight or during the DST change and caused the loss of data. * computeRollover() now always return the timestamp larger than the specified time. * Fix computation of the rollover time during the DST change. (cherry picked from commit fee86fd) Co-authored-by: Serhiy Storchaka <storchaka@gmail.com>
* Do not overwrite already rolled over files. It happened at midnight or during the DST change and caused the loss of data. * computeRollover() now always return the timestamp larger than the specified time. * Fix computation of the rollover time during the DST change. (cherry picked from commit fee86fd) Co-authored-by: Serhiy Storchaka <storchaka@gmail.com>
…-116208) * Do not overwrite already rolled over files. It happened at midnight or during the DST change and caused the loss of data. * computeRollover() now always return the timestamp larger than the specified time. * Fix computation of the rollover time during the DST change. (cherry picked from commit fee86fd) Co-authored-by: Serhiy Storchaka <storchaka@gmail.com>
…-116209) * Do not overwrite already rolled over files. It happened at midnight or during the DST change and caused the loss of data. * computeRollover() now always return the timestamp larger than the specified time. * Fix computation of the rollover time during the DST change. (cherry picked from commit fee86fd) Co-authored-by: Serhiy Storchaka <storchaka@gmail.com>
* Do not overwrite already rolled over files. It happened at midnight or during the DST change and caused the loss of data. * computeRollover() now always return the timestamp larger than the specified time. * Fix computation of the rollover time during the DST change.
The tests failed (with less than 1% probability) if for example the file was created at 11:46:03.999, but the record was emitted at 11:46:04.001, with atTime=11:46:04, which caused an unexpected rollover. Ensure that the tests are always run within the range of the same whole second.
The tests failed (with less than 1% probability) if for example the file was created at 11:46:03.999, but the record was emitted at 11:46:04.001, with atTime=11:46:04, which caused an unexpected rollover. Ensure that the tests are always run within the range of the same whole second. Also share code between test_rollover_at_midnight and test_rollover_at_weekday.
…onGH-116409) The tests failed (with less than 1% probability) if for example the file was created at 11:46:03.999, but the record was emitted at 11:46:04.001, with atTime=11:46:04, which caused an unexpected rollover. Ensure that the tests are always run within the range of the same whole second. Also share code between test_rollover_at_midnight and test_rollover_at_weekday. (cherry picked from commit d8712fa) Co-authored-by: Serhiy Storchaka <storchaka@gmail.com>
…onGH-116409) The tests failed (with less than 1% probability) if for example the file was created at 11:46:03.999, but the record was emitted at 11:46:04.001, with atTime=11:46:04, which caused an unexpected rollover. Ensure that the tests are always run within the range of the same whole second. Also share code between test_rollover_at_midnight and test_rollover_at_weekday. (cherry picked from commit d8712fa) Co-authored-by: Serhiy Storchaka <storchaka@gmail.com>
…116409) (GH-116585) The tests failed (with less than 1% probability) if for example the file was created at 11:46:03.999, but the record was emitted at 11:46:04.001, with atTime=11:46:04, which caused an unexpected rollover. Ensure that the tests are always run within the range of the same whole second. Also share code between test_rollover_at_midnight and test_rollover_at_weekday. (cherry picked from commit d8712fa) Co-authored-by: Serhiy Storchaka <storchaka@gmail.com>
…116409) (GH-116586) The tests failed (with less than 1% probability) if for example the file was created at 11:46:03.999, but the record was emitted at 11:46:04.001, with atTime=11:46:04, which caused an unexpected rollover. Ensure that the tests are always run within the range of the same whole second. Also share code between test_rollover_at_midnight and test_rollover_at_weekday. (cherry picked from commit d8712fa) Co-authored-by: Serhiy Storchaka <storchaka@gmail.com>
* Do not overwrite already rolled over files. It happened at midnight or during the DST change and caused the loss of data. * computeRollover() now always return the timestamp larger than the specified time. * Fix computation of the rollover time during the DST change.
…onGH-116409) The tests failed (with less than 1% probability) if for example the file was created at 11:46:03.999, but the record was emitted at 11:46:04.001, with atTime=11:46:04, which caused an unexpected rollover. Ensure that the tests are always run within the range of the same whole second. Also share code between test_rollover_at_midnight and test_rollover_at_weekday.
* Do not overwrite already rolled over files. It happened at midnight or during the DST change and caused the loss of data. * computeRollover() now always return the timestamp larger than the specified time. * Fix computation of the rollover time during the DST change.
…onGH-116409) The tests failed (with less than 1% probability) if for example the file was created at 11:46:03.999, but the record was emitted at 11:46:04.001, with atTime=11:46:04, which caused an unexpected rollover. Ensure that the tests are always run within the range of the same whole second. Also share code between test_rollover_at_midnight and test_rollover_at_weekday.
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:
bugs.python.org fields:
Linked PRs
The text was updated successfully, but these errors were encountered: