TimedRotatingFileHandler deletes wrong files

[SamiSalonen]

BPO	46063
Nosy	@vsajip, @miss-islington, @iritkatriel
PRs	bpo-46063: Improve algorithm for computing which rolled-over log file… (GH-30093) #30093 [3.10] bpo-46063: Improve algorithm for computing which rolled-over log file… (GH-30093) (GH-30094) #30094 [3.9] bpo-46063: Improve algorithm for computing which rolled-over log file… (GH-30093) (GH-30095) #30095 bpo-46063: Add 'delay=True' to file handler initialization. (GH-30103) #30103 [3.10] bpo-46063: Add 'delay=True' to file handler initialization. (GH-30103) (GH-30104) #30104 [3.9] bpo-46063: Add 'delay=True' to file handler initialization. (GH-30103) (GH-30105) #30105

^{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 = None
closed_at = <Date 2021-12-14.10:01:53.983>
created_at = <Date 2021-12-13.12:12:03.236>
labels = ['type-bug', 'library', '3.9', '3.10', '3.11']
title = 'TimedRotatingFileHandler deletes wrong files'
updated_at = <Date 2021-12-14.17:27:26.542>
user = 'https://bugs.python.org/SamiSalonen'

bugs.python.org fields:

activity = <Date 2021-12-14.17:27:26.542>
actor = 'vinay.sajip'
assignee = 'none'
closed = True
closed_date = <Date 2021-12-14.10:01:53.983>
closer = 'vinay.sajip'
components = ['Library (Lib)']
creation = <Date 2021-12-13.12:12:03.236>
creator = 'Sami Salonen'
dependencies = []
files = []
hgrepos = []
issue_num = 46063
keywords = ['patch']
message_count = 10.0
messages = ['408445', '408446', '408506', '408509', '408510', '408521', '408522', '408548', '408552', '408553']
nosy_count = 4.0
nosy_names = ['vinay.sajip', 'Sami Salonen', 'miss-islington', 'iritkatriel']
pr_nums = ['30093', '30094', '30095', '30103', '30104', '30105']
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue46063'
versions = ['Python 3.9', 'Python 3.10', 'Python 3.11']

[SamiSalonen]

https://bugs.python.org/issue45628 breaks file rotation.

I name my log files after module name, run the modules in separate processes, use the same log config in them, and store the log files in one common directory. For example, for modules a.b and a.b.c I have the following log files:

a.b.log
a.b.c.log

Now after bpo-45628 fix, getFilesToDelete treats the rotated log files from those modules the same, and deletes wrong files. If backupCount is set to e.g. 7, only total of 7 files are stored instead of 7 of each.

[SamiSalonen]

Breaking PR: #29310

[vsajip]

New changeset cb589d1 by Vinay Sajip in branch 'main':
bpo-46063: Improve algorithm for computing which rolled-over log file… (GH-30093)
cb589d1

[vsajip]

New changeset f84e2f6 by Miss Islington (bot) in branch '3.10':
[3.10] bpo-46063: Improve algorithm for computing which rolled-over log file… (GH-30093) (GH-30094)
f84e2f6

[vsajip]

New changeset 9423422 by Miss Islington (bot) in branch '3.9':
[3.9] bpo-46063: Improve algorithm for computing which rolled-over log file… (GH-30093) (GH-30095)
9423422

[iritkatriel]

% ./python.exe -We -m test -v test_logging -m test_compute_files_to_delete 
Raised RLIMIT_NOFILE: 256 -> 1024
== CPython 3.11.0a3+ (heads/main:9130a4d620, Dec 14 2021, 11:12:05) [Clang 13.0.0 (clang-1300.0.29.3)]
== macOS-11.6-x86_64-i386-64bit little-endian
== cwd: /Users/iritkatriel/src/cpython/build/test_python_86072æ
== CPU count: 12
== encodings: locale=UTF-8, FS=utf-8
0:00:00 load avg: 5.20 Run tests sequentially
0:00:00 load avg: 5.20 [1/1] test_logging
test_compute_files_to_delete (test.test_logging.TimedRotatingFileHandlerTest) ... Warning -- Unraisable exception
Exception ignored in: <_io.FileIO name='/var/folders/kf/0v7kz3ps62dg11v9rq0sz35m0000gn/T/test_logging_w3nn9vsi/d.e.log' mode='ab' closefd=True>
Traceback (most recent call last):
  File "/Users/iritkatriel/src/cpython/Lib/test/test_logging.py", line 5469, in test_compute_files_to_delete
    for i, prefix in enumerate(prefixes):
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
ResourceWarning: unclosed file <_io.TextIOWrapper name='/var/folders/kf/0v7kz3ps62dg11v9rq0sz35m0000gn/T/test_logging_w3nn9vsi/d.e.log' mode='a' encoding='UTF-8'>
Warning -- Unraisable exception
Exception ignored in: <_io.FileIO name='/var/folders/kf/0v7kz3ps62dg11v9rq0sz35m0000gn/T/test_logging_w3nn9vsi/a.b.c.log' mode='ab' closefd=True>
Traceback (most recent call last):
  File "/Users/iritkatriel/src/cpython/Lib/test/test_logging.py", line 5469, in test_compute_files_to_delete
    for i, prefix in enumerate(prefixes):
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
ResourceWarning: unclosed file <_io.TextIOWrapper name='/var/folders/kf/0v7kz3ps62dg11v9rq0sz35m0000gn/T/test_logging_w3nn9vsi/a.b.c.log' mode='a' encoding='UTF-8'>
Warning -- Unraisable exception
Exception ignored in: <_io.FileIO name='/var/folders/kf/0v7kz3ps62dg11v9rq0sz35m0000gn/T/test_logging_w3nn9vsi/a.b.log' mode='ab' closefd=True>
Traceback (most recent call last):
  File "/Users/iritkatriel/src/cpython/Lib/test/test_logging.py", line 5469, in test_compute_files_to_delete
    for i, prefix in enumerate(prefixes):
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
ResourceWarning: unclosed file <_io.TextIOWrapper name='/var/folders/kf/0v7kz3ps62dg11v9rq0sz35m0000gn/T/test_logging_w3nn9vsi/a.b.log' mode='a' encoding='UTF-8'>
Warning -- Unraisable exception
Exception ignored in: <_io.FileIO name='/var/folders/kf/0v7kz3ps62dg11v9rq0sz35m0000gn/T/test_logging_w3nn9vsi/d.e.f.log' mode='ab' closefd=True>
Traceback (most recent call last):
  File "/Users/iritkatriel/src/cpython/Lib/test/test_logging.py", line 5469, in test_compute_files_to_delete
    for i, prefix in enumerate(prefixes):
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
ResourceWarning: unclosed file <_io.TextIOWrapper name='/var/folders/kf/0v7kz3ps62dg11v9rq0sz35m0000gn/T/test_logging_w3nn9vsi/d.e.f.log' mode='a' encoding='UTF-8'>
ok

---

Ran 1 test in 0.016s

OK
test_logging failed (env changed)

== Tests result: SUCCESS ==

1 test altered the execution environment:
test_logging

[vsajip]

Ah ... forgot to set delay=True for the handlers. Will look at this soon.

[vsajip]

New changeset 850aefc by Vinay Sajip in branch 'main':
bpo-46063: Add 'delay=True' to file handler initialization. (GH-30103)
850aefc

[vsajip]

New changeset 908fd69 by Miss Islington (bot) in branch '3.10':
[3.10] bpo-46063: Add 'delay=True' to file handler initialization. (GH-30103) (GH-30104)
908fd69

[vsajip]

New changeset 17260e4 by Miss Islington (bot) in branch '3.9':
[3.9] bpo-46063: Add 'delay=True' to file handler initialization. (GH-30103) (GH-30105)
17260e4