From 772a742244ad634d2f325848cf9b689ba704a522 Mon Sep 17 00:00:00 2001 From: Xu Song Date: Sat, 23 Dec 2023 14:22:15 +0800 Subject: [PATCH 1/8] Fix multiprocessing logger --- Lib/multiprocessing/util.py | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/Lib/multiprocessing/util.py b/Lib/multiprocessing/util.py index 28c77df1c32ea8..32871850ddec8b 100644 --- a/Lib/multiprocessing/util.py +++ b/Lib/multiprocessing/util.py @@ -43,19 +43,19 @@ def sub_debug(msg, *args): if _logger: - _logger.log(SUBDEBUG, msg, *args) + _logger.log(SUBDEBUG, msg, *args, stacklevel=2) def debug(msg, *args): if _logger: - _logger.log(DEBUG, msg, *args) + _logger.log(DEBUG, msg, *args, stacklevel=2) def info(msg, *args): if _logger: - _logger.log(INFO, msg, *args) + _logger.log(INFO, msg, *args, stacklevel=2) def sub_warning(msg, *args): if _logger: - _logger.log(SUBWARNING, msg, *args) + _logger.log(SUBWARNING, msg, *args, stacklevel=2) def get_logger(): ''' From 0c71144bc79a7434a9ca506ba0efab73b912f59a Mon Sep 17 00:00:00 2001 From: xu-song Date: Sat, 23 Dec 2023 16:13:23 +0800 Subject: [PATCH 2/8] add news entry --- .../next/Library/2023-12-23-16-10-07.gh-issue-113421.w7vs08.rst | 1 + 1 file changed, 1 insertion(+) create mode 100644 Misc/NEWS.d/next/Library/2023-12-23-16-10-07.gh-issue-113421.w7vs08.rst diff --git a/Misc/NEWS.d/next/Library/2023-12-23-16-10-07.gh-issue-113421.w7vs08.rst b/Misc/NEWS.d/next/Library/2023-12-23-16-10-07.gh-issue-113421.w7vs08.rst new file mode 100644 index 00000000000000..2082fe6391d261 --- /dev/null +++ b/Misc/NEWS.d/next/Library/2023-12-23-16-10-07.gh-issue-113421.w7vs08.rst @@ -0,0 +1 @@ +Fix multiprocessing logger for ``%(filename)s``. From 493414b0ad953892bd01b8f5796581b2d0aba9ba Mon Sep 17 00:00:00 2001 From: xu-song Date: Sat, 23 Dec 2023 18:04:06 +0800 Subject: [PATCH 3/8] Add format unittest for multiprocessing logger --- Lib/test/_test_multiprocessing.py | 12 ++++++++++++ 1 file changed, 12 insertions(+) diff --git a/Lib/test/_test_multiprocessing.py b/Lib/test/_test_multiprocessing.py index a94eb6c0ae4b8e..21e03bc4dd93f0 100644 --- a/Lib/test/_test_multiprocessing.py +++ b/Lib/test/_test_multiprocessing.py @@ -4724,6 +4724,18 @@ def test_level(self): root_logger.setLevel(root_level) logger.setLevel(level=LOG_LEVEL) + def test_format(self): + logger = multiprocessing.get_logger() + logger.setLevel(util.DEBUG) + handler = logging.StreamHandler() + logging_format = '[%(levelname)s] [%(processName)s] [%(filename)s:%(lineno)d:%(funcName)s] %(message)s' + handler.setFormatter(logging.Formatter(logging_format)) + logger.addHandler(handler) + logger.info('print info') + logger.debug('print debug') + pool_in_process() + logger.setLevel(LOG_LEVEL) + # class _TestLoggingProcessName(BaseTestCase): # From 5313957f97d78140f09f2c53e4254842dbb61b91 Mon Sep 17 00:00:00 2001 From: xu-song Date: Sat, 23 Dec 2023 18:54:45 +0800 Subject: [PATCH 4/8] Initialize handler with io.StringIO() --- Lib/test/_test_multiprocessing.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/Lib/test/_test_multiprocessing.py b/Lib/test/_test_multiprocessing.py index 21e03bc4dd93f0..3e144aafec1c0c 100644 --- a/Lib/test/_test_multiprocessing.py +++ b/Lib/test/_test_multiprocessing.py @@ -4727,7 +4727,7 @@ def test_level(self): def test_format(self): logger = multiprocessing.get_logger() logger.setLevel(util.DEBUG) - handler = logging.StreamHandler() + handler = logging.StreamHandler(io.StringIO()) logging_format = '[%(levelname)s] [%(processName)s] [%(filename)s:%(lineno)d:%(funcName)s] %(message)s' handler.setFormatter(logging.Formatter(logging_format)) logger.addHandler(handler) From f42181a3e73266550538023e550021f90a05be62 Mon Sep 17 00:00:00 2001 From: xu-song Date: Sun, 24 Dec 2023 14:24:56 +0800 Subject: [PATCH 5/8] Add assert; Remove handler after test --- Lib/test/_test_multiprocessing.py | 27 +++++++++++++++++++++++---- 1 file changed, 23 insertions(+), 4 deletions(-) diff --git a/Lib/test/_test_multiprocessing.py b/Lib/test/_test_multiprocessing.py index 3e144aafec1c0c..9556622ec95aa1 100644 --- a/Lib/test/_test_multiprocessing.py +++ b/Lib/test/_test_multiprocessing.py @@ -12,6 +12,7 @@ import sys import os import gc +import re import errno import functools import signal @@ -4724,17 +4725,35 @@ def test_level(self): root_logger.setLevel(root_level) logger.setLevel(level=LOG_LEVEL) - def test_format(self): + def assert_log_lines(self, expected_values, stream=None): + stream = stream or self.stream + actual_lines = stream.getvalue().splitlines() + self.assertEqual(len(actual_lines), len(expected_values)) + for actual, expected in zip(actual_lines, expected_values): + self.assertEqual(actual, expected) + s = stream.read() + if s: + self.fail("Remaining output at end of log stream:\n" + s) + + def test_filename(self): logger = multiprocessing.get_logger() logger.setLevel(util.DEBUG) - handler = logging.StreamHandler(io.StringIO()) - logging_format = '[%(levelname)s] [%(processName)s] [%(filename)s:%(lineno)d:%(funcName)s] %(message)s' + stream = io.StringIO() + handler = logging.StreamHandler(stream) + logging_format = '[%(levelname)s] [%(filename)s] %(message)s' handler.setFormatter(logging.Formatter(logging_format)) logger.addHandler(handler) logger.info('print info') + util.info('print info again') logger.debug('print debug') - pool_in_process() + self.assert_log_lines([ + '[INFO] [_test_multiprocessing.py] print info', + '[INFO] [_test_multiprocessing.py] print info again', + '[DEBUG] [_test_multiprocessing.py] print debug', + ], stream) logger.setLevel(LOG_LEVEL) + logger.removeHandler(handler) + handler.close() # class _TestLoggingProcessName(BaseTestCase): From 9705a0bef4a42a674b96692605b5bf8da83f8446 Mon Sep 17 00:00:00 2001 From: xu-song Date: Sun, 24 Dec 2023 15:13:58 +0800 Subject: [PATCH 6/8] Add try finnaly block; Restore logger level --- Lib/test/_test_multiprocessing.py | 38 +++++++++++++++++-------------- 1 file changed, 21 insertions(+), 17 deletions(-) diff --git a/Lib/test/_test_multiprocessing.py b/Lib/test/_test_multiprocessing.py index 9556622ec95aa1..bc872d832c4032 100644 --- a/Lib/test/_test_multiprocessing.py +++ b/Lib/test/_test_multiprocessing.py @@ -4737,23 +4737,27 @@ def assert_log_lines(self, expected_values, stream=None): def test_filename(self): logger = multiprocessing.get_logger() - logger.setLevel(util.DEBUG) - stream = io.StringIO() - handler = logging.StreamHandler(stream) - logging_format = '[%(levelname)s] [%(filename)s] %(message)s' - handler.setFormatter(logging.Formatter(logging_format)) - logger.addHandler(handler) - logger.info('print info') - util.info('print info again') - logger.debug('print debug') - self.assert_log_lines([ - '[INFO] [_test_multiprocessing.py] print info', - '[INFO] [_test_multiprocessing.py] print info again', - '[DEBUG] [_test_multiprocessing.py] print debug', - ], stream) - logger.setLevel(LOG_LEVEL) - logger.removeHandler(handler) - handler.close() + default_level = logger.level + try: + logger.setLevel(util.DEBUG) + stream = io.StringIO() + handler = logging.StreamHandler(stream) + logging_format = '[%(levelname)s] [%(filename)s] %(message)s' + handler.setFormatter(logging.Formatter(logging_format)) + logger.addHandler(handler) + logger.info('1') + util.info('2') + logger.debug('3') + filename = os.path.basename(__file__) + self.assert_log_lines([ + f'[INFO] [{filename}] 1', + f'[INFO] [{filename}] 2', + f'[DEBUG] [{filename}] 3', + ], stream) + finally: + logger.setLevel(default_level) + logger.removeHandler(handler) + handler.close() # class _TestLoggingProcessName(BaseTestCase): From 04509a74a54b5b8f1fc8cd62db19fe748c9cf3f4 Mon Sep 17 00:00:00 2001 From: xu-song Date: Sun, 24 Dec 2023 15:15:22 +0800 Subject: [PATCH 7/8] remove unused import --- Lib/test/_test_multiprocessing.py | 1 - 1 file changed, 1 deletion(-) diff --git a/Lib/test/_test_multiprocessing.py b/Lib/test/_test_multiprocessing.py index bc872d832c4032..d7b1211928c88b 100644 --- a/Lib/test/_test_multiprocessing.py +++ b/Lib/test/_test_multiprocessing.py @@ -12,7 +12,6 @@ import sys import os import gc -import re import errno import functools import signal From a49b3998234e3e17b10730e04125519c380b95e7 Mon Sep 17 00:00:00 2001 From: xu-song Date: Sun, 24 Dec 2023 15:49:01 +0800 Subject: [PATCH 8/8] Simplify unittest --- Lib/test/_test_multiprocessing.py | 23 ++++++----------------- 1 file changed, 6 insertions(+), 17 deletions(-) diff --git a/Lib/test/_test_multiprocessing.py b/Lib/test/_test_multiprocessing.py index d7b1211928c88b..8e4e0765d46809 100644 --- a/Lib/test/_test_multiprocessing.py +++ b/Lib/test/_test_multiprocessing.py @@ -4724,19 +4724,9 @@ def test_level(self): root_logger.setLevel(root_level) logger.setLevel(level=LOG_LEVEL) - def assert_log_lines(self, expected_values, stream=None): - stream = stream or self.stream - actual_lines = stream.getvalue().splitlines() - self.assertEqual(len(actual_lines), len(expected_values)) - for actual, expected in zip(actual_lines, expected_values): - self.assertEqual(actual, expected) - s = stream.read() - if s: - self.fail("Remaining output at end of log stream:\n" + s) - def test_filename(self): logger = multiprocessing.get_logger() - default_level = logger.level + original_level = logger.level try: logger.setLevel(util.DEBUG) stream = io.StringIO() @@ -4748,13 +4738,12 @@ def test_filename(self): util.info('2') logger.debug('3') filename = os.path.basename(__file__) - self.assert_log_lines([ - f'[INFO] [{filename}] 1', - f'[INFO] [{filename}] 2', - f'[DEBUG] [{filename}] 3', - ], stream) + log_record = stream.getvalue() + self.assertIn(f'[INFO] [{filename}] 1', log_record) + self.assertIn(f'[INFO] [{filename}] 2', log_record) + self.assertIn(f'[DEBUG] [{filename}] 3', log_record) finally: - logger.setLevel(default_level) + logger.setLevel(original_level) logger.removeHandler(handler) handler.close()