Logging displays wrong "processName" if "sys.modules" is cleared in child process

[Delgan]

BPO	38762
Nosy	@vsajip, @serhiy-storchaka, @Delgan, @iritkatriel
PRs	bpo-38762: Fix edge case where logging records an incorrect processNa… #22063 bpo-38762: Extend logging.test_multiprocessing to cover missing cases. #22142
Files	test.py: Reproducible example

^{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 2020-09-09.07:54:04.172>
created_at = <Date 2019-11-10.21:53:15.587>
labels = ['type-bug', 'library', '3.10']
title = 'Logging displays wrong "processName" if "sys.modules" is cleared in child process'
updated_at = <Date 2020-09-09.07:54:04.172>
user = 'https://github.com/Delgan'

bugs.python.org fields:

activity = <Date 2020-09-09.07:54:04.172>
actor = 'vinay.sajip'
assignee = 'none'
closed = True
closed_date = <Date 2020-09-09.07:54:04.172>
closer = 'vinay.sajip'
components = ['Library (Lib)']
creation = <Date 2019-11-10.21:53:15.587>
creator = 'Delgan'
dependencies = []
files = ['48705']
hgrepos = []
issue_num = 38762
keywords = ['patch']
message_count = 8.0
messages = ['356338', '356357', '376295', '376517', '376522', '376523', '376579', '376591']
nosy_count = 4.0
nosy_names = ['vinay.sajip', 'serhiy.storchaka', 'Delgan', 'iritkatriel']
pr_nums = ['22063', '22142']
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue38762'
versions = ['Python 3.10']

[Delgan]

Hi.

In order to display the process name in logs, the "logging" module checks for the presence of "multiprocessing" in "sys.modules" before calling "current_process()". If "multiprocessing" is not found in "sys.modules", it assumes that the current process is the main one.

See :

cpython/Lib/logging/__init__.py

Lines 340 to 341 in af46450

	self.processName = 'MainProcess'
	mp = sys.modules.get('multiprocessing')

However, nothing prevents a child process to delete "sys.module['multiprocessing']", which causes the process name to be wrongly displayed as "MainProcess".

I attached a reproducible example, but this is straightforward to understand. Although it should not happen very often in practice, it is still theoretically possible. Obviously, one could say "just don't clear sys.modules", but I suppose there might exist tools doing such thing for good reasons (like resetting the test environment).

Issues which lead to the current implementation:

• bpo-4301
• bpo-7120
• bpo-8200

Possible fixes:

• Force import "multiprocessing.current_process()" even if not already loaded
• Add function "os.main_pid()" and set "processName" to "MainProcess" only if "os.getpid() == os.main_pid()"

[vsajip]

This will be a rare use case, and I would expect anyone clearing sys.modules in the child process to handle this consequence themselves (e.g. by reimporting multiprocessing after clearing out the other modules, since they apparently still want some of multiprocessing's functionality in the child process). I'll certainly look at PRs to address the issue using an import of multiprocessing if it's not already there. I'm not so keen on the other approaches you've suggested.

[vsajip]

See also bpo-8200, which relates to the way the code is currently.

[serhiy-storchaka]

So this will make logging depending on the multiprocess module? Even if you do not use multiprocessing it will be imported in any case when you use logging.

[iritkatriel]

As the PR currently is, it will, unless you turn this off by setting logging.logMultiprocessing=False.

The other alternative we are discussing is: revert back to not importing multiprocessing if it's not there.

If it's there we use it, but if it's not we set processName to something like f"pid={os.getpid()}" instead of "MainThread".

(1) os is already imported in logging.

(2) In most cases where multiprocessing is not imported it's because there is only one process, so processName will not likely be used as all.

(3) In the edge case of shutdown or someone clearing sys.modules the processName will not be pretty, but it will at least be correct.

[iritkatriel]

I just pushed a second PR with the alternative solution - it calculates the name on a best-effort basis, and doesn't import anything that's not already there.

[iritkatriel]

We've decided for now to leave the code's behavior as it is (the alternatives are worse) and to keep only the test improvements. See discussion on PR 22142.

[vsajip]

New changeset 3fd6999 by Irit Katriel in branch 'master':
bpo-38762: Extend logging.test_multiprocessing to cover missing cases. (GH-22142)
3fd6999