logging TimedRotatingFileHandler must not rename devices like /dev/null

[vstinner]

BPO	45401
Nosy	@vsajip, @vstinner, @serhiy-storchaka, @miss-islington
PRs	bpo-45401: Change shouldRollover() methods to only rollover regular f… #28822 bpo-45401: Fix a resource warning in test_logging #28864 bpo-45401: Fix ResourceWarning in test_logging #28865 [3.9] bpo-45401: Change shouldRollover() methods to only rollover regular f… (GH-28822) #28866 [3.10] bpo-45401: Change shouldRollover() methods to only rollover regular f… (GH-28822) #28867 [3.10] bpo-45401: Fix a resource warning in test_logging (GH-28864) #28872 [3.9] bpo-45401: Fix a resource warning in test_logging (GH-28864) #28873

^{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-10-12.08:42:08.646>
created_at = <Date 2021-10-07.09:47:34.223>
labels = ['library', '3.9', '3.10', '3.11']
title = 'logging TimedRotatingFileHandler must not rename devices like /dev/null'
updated_at = <Date 2021-10-12.08:42:08.645>
user = 'https://github.com/vstinner'

bugs.python.org fields:

activity = <Date 2021-10-12.08:42:08.645>
actor = 'vstinner'
assignee = 'none'
closed = True
closed_date = <Date 2021-10-12.08:42:08.646>
closer = 'vstinner'
components = ['Library (Lib)']
creation = <Date 2021-10-07.09:47:34.223>
creator = 'vstinner'
dependencies = []
files = []
hgrepos = []
issue_num = 45401
keywords = ['patch']
message_count = 15.0
messages = ['403371', '403433', '403593', '403604', '403606', '403607', '403608', '403627', '403629', '403636', '403643', '403644', '403711', '403712', '403717']
nosy_count = 4.0
nosy_names = ['vinay.sajip', 'vstinner', 'serhiy.storchaka', 'miss-islington']
pr_nums = ['28822', '28864', '28865', '28866', '28867', '28872', '28873']
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = None
url = 'https://bugs.python.org/issue45401'
versions = ['Python 3.9', 'Python 3.10', 'Python 3.11']

[vstinner]

One way to disable logging in a configuration file is to use /dev/null as the filename for logs. It is fine to use that with FileHandler.

The problem is when TimedRotatingFileHandler is used. When Python decides to rotate the "file", it calls os.rename() on /dev/null *device* and create a new /dev/null *file* which will be quickly filled by all applications on the system writing into /dev/null.

The problem is only possible if the process is allowed to rename the device /dev/null. For example, a regular user gets a permission error.

I see different options:

• TimedRotatingFileHandler should disable rotation if it detects that the file is a device (not a regular file)
• logging should switch to NullHandler if filename is equal to os.path.devnull.

I guess that the problem is the same if the filename points to a socket or a named pipe.

RotatingFileHandler may also be affected, I didn't check.

... I'm quite sure that I had the same issue with Twisted years ago, but I don't recall the details :-) Twisted didn't use the logging module if I recall correctly.

RHEL downstream issue: https://bugzilla.redhat.com/show_bug.cgi?id=2009200

[vsajip]

RotatingFileHandler is also affected by the same issue.

Both RotatingFileHandler and TimedRotatingFileHandler have a shouldRollover method which, if it returns False, should prevent rollover.

I would think that putting something like

 if not os.path.isfile(self.baseFilename):
 return False

at the top of each of these methods should avoid rolling over any thing that isn't a regular file - devices, pipes etc. Would you agree? Can you see any drawbacks?

I'm not sure this would cover sockets, but there are separate handlers for using sockets so there would be no reason for people to use sockets with file handlers. And of course sockets are a completely different sort of beast on Windows.

[miss-islington]

New changeset 62a6677 by Vinay Sajip in branch 'main':
bpo-45401: Change shouldRollover() methods to only rollover regular f… (GH-28822)
62a6677

[serhiy-storchaka]

Seems it introduced a resource warning in tests.

[vsajip]

Where did you see the warnings? I didn't spot anything in the GitHub Actions logs.

[serhiy-storchaka]

test_should_not_rollover (test.test_logging.TimedRotatingFileHandlerTest) ... /home/serhiy/py/cpython/Lib/unittest/case.py:547: ResourceWarning: unclosed file <_io.TextIOWrapper name='/dev/null' mode='a' encoding='utf-8'>
if method() is not None:
ResourceWarning: Enable tracemalloc to get the object allocation traceback
ok

[serhiy-storchaka]

With tracemalloc enabled:

$ ./python -X tracemalloc -m test -v test_logging -m test_should_not_rollover
...
test_should_not_rollover (test.test_logging.TimedRotatingFileHandlerTest) ... /home/serhiy/py/cpython/Lib/unittest/case.py:547: ResourceWarning: unclosed file <_io.TextIOWrapper name='/dev/null' mode='a' encoding='utf-8'>
 if method() is not None:
Object allocated at (most recent call last):
 File "/home/serhiy/py/cpython/Lib/logging/__init__.py", lineno 1205
 return open_func(self.baseFilename, self.mode,
ok