From 739599e6090494ab452845f63587bf804e046219 Mon Sep 17 00:00:00 2001 From: Serhiy Storchaka Date: Sun, 19 Apr 2020 14:09:00 +0300 Subject: [PATCH 1/6] bpo-40275: Avoid importing logging in test.support * Import logging lazily in assertLogs() in unittest. * Move TestHandler from test.support to test_logging. --- Doc/library/test.rst | 5 ---- Lib/test/support/__init__.py | 34 ---------------------------- Lib/test/test_logging.py | 33 +++++++++++++++++++++++++-- Lib/unittest/case.py | 44 ++++++++++++++++++------------------ 4 files changed, 53 insertions(+), 63 deletions(-) diff --git a/Doc/library/test.rst b/Doc/library/test.rst index c33465d758d574..a5167e30c7fb5b 100644 --- a/Doc/library/test.rst +++ b/Doc/library/test.rst @@ -1460,11 +1460,6 @@ The :mod:`test.support` module defines the following classes: Run *test* and return the result. -.. class:: TestHandler(logging.handlers.BufferingHandler) - - Class for logging support. - - .. class:: FakePath(path) Simple :term:`path-like object`. It implements the :meth:`__fspath__` diff --git a/Lib/test/support/__init__.py b/Lib/test/support/__init__.py index 9f43b4071c044d..2046fe883291cf 100644 --- a/Lib/test/support/__init__.py +++ b/Lib/test/support/__init__.py @@ -16,7 +16,6 @@ import importlib import importlib.util import locale -import logging.handlers import nntplib import os import platform @@ -109,8 +108,6 @@ "bind_unix_socket", # processes 'temp_umask', "reap_children", - # logging - "TestHandler", # threads "threading_setup", "threading_cleanup", "reap_threads", "start_threads", # miscellaneous @@ -2522,37 +2519,6 @@ def optim_args_from_interpreter_flags(): optimization settings in sys.flags.""" return subprocess._optim_args_from_interpreter_flags() -#============================================================ -# Support for assertions about logging. -#============================================================ - -class TestHandler(logging.handlers.BufferingHandler): - def __init__(self, matcher): - # BufferingHandler takes a "capacity" argument - # so as to know when to flush. As we're overriding - # shouldFlush anyway, we can set a capacity of zero. - # You can call flush() manually to clear out the - # buffer. - logging.handlers.BufferingHandler.__init__(self, 0) - self.matcher = matcher - - def shouldFlush(self): - return False - - def emit(self, record): - self.format(record) - self.buffer.append(record.__dict__) - - def matches(self, **kwargs): - """ - Look for a saved dict whose keys/values match the supplied arguments. - """ - result = False - for d in self.buffer: - if self.matcher.matches(d, **kwargs): - result = True - break - return result class Matcher(object): diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py index 99e74ebff60875..36545658c233b5 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -3477,6 +3477,35 @@ def test_logrecord_class(self): ]) +class TestHandler(logging.handlers.BufferingHandler): + def __init__(self, matcher): + # BufferingHandler takes a "capacity" argument + # so as to know when to flush. As we're overriding + # shouldFlush anyway, we can set a capacity of zero. + # You can call flush() manually to clear out the + # buffer. + logging.handlers.BufferingHandler.__init__(self, 0) + self.matcher = matcher + + def shouldFlush(self): + return False + + def emit(self, record): + self.format(record) + self.buffer.append(record.__dict__) + + def matches(self, **kwargs): + """ + Look for a saved dict whose keys/values match the supplied arguments. + """ + result = False + for d in self.buffer: + if self.matcher.matches(d, **kwargs): + result = True + break + return result + + class QueueHandlerTest(BaseTest): # Do not bother with a logger name group. expected_log_pat = r"^[\w.]+ -> (\w+): (\d+)$" @@ -3523,7 +3552,7 @@ def test_formatting(self): @unittest.skipUnless(hasattr(logging.handlers, 'QueueListener'), 'logging.handlers.QueueListener required for this test') def test_queue_listener(self): - handler = support.TestHandler(support.Matcher()) + handler = TestHandler(support.Matcher()) listener = logging.handlers.QueueListener(self.queue, handler) listener.start() try: @@ -3539,7 +3568,7 @@ def test_queue_listener(self): # Now test with respect_handler_level set - handler = support.TestHandler(support.Matcher()) + handler = TestHandler(support.Matcher()) handler.setLevel(logging.CRITICAL) listener = logging.handlers.QueueListener(self.queue, handler, respect_handler_level=True) diff --git a/Lib/unittest/case.py b/Lib/unittest/case.py index d0ee561a3ae93a..94fa36fd1bd29a 100644 --- a/Lib/unittest/case.py +++ b/Lib/unittest/case.py @@ -3,7 +3,6 @@ import sys import functools import difflib -import logging import pprint import re import warnings @@ -300,26 +299,6 @@ def __exit__(self, exc_type, exc_value, tb): _LoggingWatcher = collections.namedtuple("_LoggingWatcher", ["records", "output"]) - -class _CapturingHandler(logging.Handler): - """ - A logging handler capturing all (raw and formatted) logging output. - """ - - def __init__(self): - logging.Handler.__init__(self) - self.watcher = _LoggingWatcher([], []) - - def flush(self): - pass - - def emit(self, record): - self.watcher.records.append(record) - msg = self.format(record) - self.watcher.output.append(msg) - - - class _AssertLogsContext(_BaseTestCaseContext): """A context manager used to implement TestCase.assertLogs().""" @@ -328,6 +307,8 @@ class _AssertLogsContext(_BaseTestCaseContext): def __init__(self, test_case, logger_name, level): _BaseTestCaseContext.__init__(self, test_case) self.logger_name = logger_name + import logging + self.logging = logging if level: self.level = logging._nameToLevel.get(level, level) else: @@ -335,11 +316,30 @@ def __init__(self, test_case, logger_name, level): self.msg = None def __enter__(self): + logging = self.logging if isinstance(self.logger_name, logging.Logger): logger = self.logger = self.logger_name else: logger = self.logger = logging.getLogger(self.logger_name) formatter = logging.Formatter(self.LOGGING_FORMAT) + + class _CapturingHandler(logging.Handler): + """ + A logging handler capturing all (raw and formatted) logging output. + """ + + def __init__(self): + logging.Handler.__init__(self) + self.watcher = _LoggingWatcher([], []) + + def flush(self): + pass + + def emit(self, record): + self.watcher.records.append(record) + msg = self.format(record) + self.watcher.output.append(msg) + handler = _CapturingHandler() handler.setFormatter(formatter) self.watcher = handler.watcher @@ -361,7 +361,7 @@ def __exit__(self, exc_type, exc_value, tb): if len(self.watcher.records) == 0: self._raiseFailure( "no logs of level {} or higher triggered on {}" - .format(logging.getLevelName(self.level), self.logger.name)) + .format(self.logging.getLevelName(self.level), self.logger.name)) class _OrderedChainMap(collections.ChainMap): From 3f1fc37baa7e005e39865f5e2fed172164abb42c Mon Sep 17 00:00:00 2001 From: Serhiy Storchaka Date: Mon, 20 Apr 2020 12:42:15 +0300 Subject: [PATCH 2/6] Move TestHandler to logging_helper. --- Lib/test/support/logging_helper.py | 29 +++++++++++++++++++++++++++++ Lib/test/test_logging.py | 30 +----------------------------- 2 files changed, 30 insertions(+), 29 deletions(-) create mode 100644 Lib/test/support/logging_helper.py diff --git a/Lib/test/support/logging_helper.py b/Lib/test/support/logging_helper.py new file mode 100644 index 00000000000000..12fcca4f0f08d9 --- /dev/null +++ b/Lib/test/support/logging_helper.py @@ -0,0 +1,29 @@ +import logging.handlers + +class TestHandler(logging.handlers.BufferingHandler): + def __init__(self, matcher): + # BufferingHandler takes a "capacity" argument + # so as to know when to flush. As we're overriding + # shouldFlush anyway, we can set a capacity of zero. + # You can call flush() manually to clear out the + # buffer. + logging.handlers.BufferingHandler.__init__(self, 0) + self.matcher = matcher + + def shouldFlush(self): + return False + + def emit(self, record): + self.format(record) + self.buffer.append(record.__dict__) + + def matches(self, **kwargs): + """ + Look for a saved dict whose keys/values match the supplied arguments. + """ + result = False + for d in self.buffer: + if self.matcher.matches(d, **kwargs): + result = True + break + return result diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py index 36545658c233b5..0a4b38579a5717 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -43,6 +43,7 @@ import tempfile from test.support.script_helper import assert_python_ok, assert_python_failure from test import support +from test.support.logging_helper import TestHandler import textwrap import threading import time @@ -3477,35 +3478,6 @@ def test_logrecord_class(self): ]) -class TestHandler(logging.handlers.BufferingHandler): - def __init__(self, matcher): - # BufferingHandler takes a "capacity" argument - # so as to know when to flush. As we're overriding - # shouldFlush anyway, we can set a capacity of zero. - # You can call flush() manually to clear out the - # buffer. - logging.handlers.BufferingHandler.__init__(self, 0) - self.matcher = matcher - - def shouldFlush(self): - return False - - def emit(self, record): - self.format(record) - self.buffer.append(record.__dict__) - - def matches(self, **kwargs): - """ - Look for a saved dict whose keys/values match the supplied arguments. - """ - result = False - for d in self.buffer: - if self.matcher.matches(d, **kwargs): - result = True - break - return result - - class QueueHandlerTest(BaseTest): # Do not bother with a logger name group. expected_log_pat = r"^[\w.]+ -> (\w+): (\d+)$" From 5d59d2380510ac589faa014d81b8ec9513603247 Mon Sep 17 00:00:00 2001 From: Serhiy Storchaka Date: Mon, 20 Apr 2020 19:02:46 +0300 Subject: [PATCH 3/6] Import logging and create _CapturingHandler only once. --- Lib/unittest/case.py | 55 +++++++++++-------- .../2020-04-20-19-06-55.bpo-40275.9UcN2g.rst | 2 + 2 files changed, 35 insertions(+), 22 deletions(-) create mode 100644 Misc/NEWS.d/next/Library/2020-04-20-19-06-55.bpo-40275.9UcN2g.rst diff --git a/Lib/unittest/case.py b/Lib/unittest/case.py index 94fa36fd1bd29a..d8a97ed194e99e 100644 --- a/Lib/unittest/case.py +++ b/Lib/unittest/case.py @@ -15,6 +15,8 @@ from .util import (strclass, safe_repr, _count_diff_all_purpose, _count_diff_hashable, _common_shorten_repr) +logging = None # imported lazily + __unittest = True _subtest_msg_sentinel = object() @@ -299,6 +301,35 @@ def __exit__(self, exc_type, exc_value, tb): _LoggingWatcher = collections.namedtuple("_LoggingWatcher", ["records", "output"]) +# Import logging lazily for assertLogs(). +# assertLogs() is one of the least used assertions, and most tests do +# not need to import logging. + +def _lazy_logging_import(): + global logging + global _CapturingHandler + if logging: + return + + import logging + class _CapturingHandler(logging.Handler): + """ + A logging handler capturing all (raw and formatted) logging output. + """ + + def __init__(self): + logging.Handler.__init__(self) + self.watcher = _LoggingWatcher([], []) + + def flush(self): + pass + + def emit(self, record): + self.watcher.records.append(record) + msg = self.format(record) + self.watcher.output.append(msg) + + class _AssertLogsContext(_BaseTestCaseContext): """A context manager used to implement TestCase.assertLogs().""" @@ -307,8 +338,7 @@ class _AssertLogsContext(_BaseTestCaseContext): def __init__(self, test_case, logger_name, level): _BaseTestCaseContext.__init__(self, test_case) self.logger_name = logger_name - import logging - self.logging = logging + _lazy_logging_import() if level: self.level = logging._nameToLevel.get(level, level) else: @@ -316,30 +346,11 @@ def __init__(self, test_case, logger_name, level): self.msg = None def __enter__(self): - logging = self.logging if isinstance(self.logger_name, logging.Logger): logger = self.logger = self.logger_name else: logger = self.logger = logging.getLogger(self.logger_name) formatter = logging.Formatter(self.LOGGING_FORMAT) - - class _CapturingHandler(logging.Handler): - """ - A logging handler capturing all (raw and formatted) logging output. - """ - - def __init__(self): - logging.Handler.__init__(self) - self.watcher = _LoggingWatcher([], []) - - def flush(self): - pass - - def emit(self, record): - self.watcher.records.append(record) - msg = self.format(record) - self.watcher.output.append(msg) - handler = _CapturingHandler() handler.setFormatter(formatter) self.watcher = handler.watcher @@ -361,7 +372,7 @@ def __exit__(self, exc_type, exc_value, tb): if len(self.watcher.records) == 0: self._raiseFailure( "no logs of level {} or higher triggered on {}" - .format(self.logging.getLevelName(self.level), self.logger.name)) + .format(logging.getLevelName(self.level), self.logger.name)) class _OrderedChainMap(collections.ChainMap): diff --git a/Misc/NEWS.d/next/Library/2020-04-20-19-06-55.bpo-40275.9UcN2g.rst b/Misc/NEWS.d/next/Library/2020-04-20-19-06-55.bpo-40275.9UcN2g.rst new file mode 100644 index 00000000000000..09e0a97f3ed982 --- /dev/null +++ b/Misc/NEWS.d/next/Library/2020-04-20-19-06-55.bpo-40275.9UcN2g.rst @@ -0,0 +1,2 @@ +The :mod:`logging` package is now imported lazily in :mod:`unittest` only +when the :meth:`~unittest.TestCase.assertLogs` assertion is used. From 58ae64560918ad08c9e6d2faaaf3479fea65d7ed Mon Sep 17 00:00:00 2001 From: Serhiy Storchaka Date: Mon, 20 Apr 2020 20:06:12 +0300 Subject: [PATCH 4/6] Move _AssertLogsContext in a private unittest._log submodule. --- Lib/unittest/_log.py | 71 ++++++++++++++++++++++++++++++++++++++ Lib/unittest/case.py | 81 ++------------------------------------------ 2 files changed, 73 insertions(+), 79 deletions(-) create mode 100644 Lib/unittest/_log.py diff --git a/Lib/unittest/_log.py b/Lib/unittest/_log.py new file mode 100644 index 00000000000000..4b5c4d708153f9 --- /dev/null +++ b/Lib/unittest/_log.py @@ -0,0 +1,71 @@ +import logging +import collections + +from .case import _BaseTestCaseContext + + +_LoggingWatcher = collections.namedtuple("_LoggingWatcher", + ["records", "output"]) + +class _CapturingHandler(logging.Handler): + """ + A logging handler capturing all (raw and formatted) logging output. + """ + + def __init__(self): + logging.Handler.__init__(self) + self.watcher = _LoggingWatcher([], []) + + def flush(self): + pass + + def emit(self, record): + self.watcher.records.append(record) + msg = self.format(record) + self.watcher.output.append(msg) + + +class _AssertLogsContext(_BaseTestCaseContext): + """A context manager used to implement TestCase.assertLogs().""" + + LOGGING_FORMAT = "%(levelname)s:%(name)s:%(message)s" + + def __init__(self, test_case, logger_name, level): + _BaseTestCaseContext.__init__(self, test_case) + self.logger_name = logger_name + if level: + self.level = logging._nameToLevel.get(level, level) + else: + self.level = logging.INFO + self.msg = None + + def __enter__(self): + if isinstance(self.logger_name, logging.Logger): + logger = self.logger = self.logger_name + else: + logger = self.logger = logging.getLogger(self.logger_name) + formatter = logging.Formatter(self.LOGGING_FORMAT) + handler = _CapturingHandler() + handler.setFormatter(formatter) + self.watcher = handler.watcher + self.old_handlers = logger.handlers[:] + self.old_level = logger.level + self.old_propagate = logger.propagate + logger.handlers = [handler] + logger.setLevel(self.level) + logger.propagate = False + return handler.watcher + + def __exit__(self, exc_type, exc_value, tb): + self.logger.handlers = self.old_handlers + self.logger.propagate = self.old_propagate + self.logger.setLevel(self.old_level) + if exc_type is not None: + # let unexpected exceptions pass through + return False + if len(self.watcher.records) == 0: + self._raiseFailure( + "no logs of level {} or higher triggered on {}" + .format(logging.getLevelName(self.level), self.logger.name)) + + diff --git a/Lib/unittest/case.py b/Lib/unittest/case.py index d8a97ed194e99e..f8bc865ee82039 100644 --- a/Lib/unittest/case.py +++ b/Lib/unittest/case.py @@ -15,8 +15,6 @@ from .util import (strclass, safe_repr, _count_diff_all_purpose, _count_diff_hashable, _common_shorten_repr) -logging = None # imported lazily - __unittest = True _subtest_msg_sentinel = object() @@ -298,83 +296,6 @@ def __exit__(self, exc_type, exc_value, tb): -_LoggingWatcher = collections.namedtuple("_LoggingWatcher", - ["records", "output"]) - -# Import logging lazily for assertLogs(). -# assertLogs() is one of the least used assertions, and most tests do -# not need to import logging. - -def _lazy_logging_import(): - global logging - global _CapturingHandler - if logging: - return - - import logging - class _CapturingHandler(logging.Handler): - """ - A logging handler capturing all (raw and formatted) logging output. - """ - - def __init__(self): - logging.Handler.__init__(self) - self.watcher = _LoggingWatcher([], []) - - def flush(self): - pass - - def emit(self, record): - self.watcher.records.append(record) - msg = self.format(record) - self.watcher.output.append(msg) - - -class _AssertLogsContext(_BaseTestCaseContext): - """A context manager used to implement TestCase.assertLogs().""" - - LOGGING_FORMAT = "%(levelname)s:%(name)s:%(message)s" - - def __init__(self, test_case, logger_name, level): - _BaseTestCaseContext.__init__(self, test_case) - self.logger_name = logger_name - _lazy_logging_import() - if level: - self.level = logging._nameToLevel.get(level, level) - else: - self.level = logging.INFO - self.msg = None - - def __enter__(self): - if isinstance(self.logger_name, logging.Logger): - logger = self.logger = self.logger_name - else: - logger = self.logger = logging.getLogger(self.logger_name) - formatter = logging.Formatter(self.LOGGING_FORMAT) - handler = _CapturingHandler() - handler.setFormatter(formatter) - self.watcher = handler.watcher - self.old_handlers = logger.handlers[:] - self.old_level = logger.level - self.old_propagate = logger.propagate - logger.handlers = [handler] - logger.setLevel(self.level) - logger.propagate = False - return handler.watcher - - def __exit__(self, exc_type, exc_value, tb): - self.logger.handlers = self.old_handlers - self.logger.propagate = self.old_propagate - self.logger.setLevel(self.old_level) - if exc_type is not None: - # let unexpected exceptions pass through - return False - if len(self.watcher.records) == 0: - self._raiseFailure( - "no logs of level {} or higher triggered on {}" - .format(logging.getLevelName(self.level), self.logger.name)) - - class _OrderedChainMap(collections.ChainMap): def __iter__(self): seen = set() @@ -865,6 +786,8 @@ def assertLogs(self, logger=None, level=None): self.assertEqual(cm.output, ['INFO:foo:first message', 'ERROR:foo.bar:second message']) """ + # Lazy import to avoid importing logging if it is not needed. + from ._log import _AssertLogsContext return _AssertLogsContext(self, logger, level) def _getAssertEqualityFunc(self, first, second): From 3464c9a5195c3034babd65866fb5b9e11ae983a2 Mon Sep 17 00:00:00 2001 From: Serhiy Storchaka Date: Sat, 25 Apr 2020 10:27:51 +0300 Subject: [PATCH 5/6] Remove empty lines at the end. --- Lib/unittest/_log.py | 2 -- 1 file changed, 2 deletions(-) diff --git a/Lib/unittest/_log.py b/Lib/unittest/_log.py index 4b5c4d708153f9..94e7e758bd9a07 100644 --- a/Lib/unittest/_log.py +++ b/Lib/unittest/_log.py @@ -67,5 +67,3 @@ def __exit__(self, exc_type, exc_value, tb): self._raiseFailure( "no logs of level {} or higher triggered on {}" .format(logging.getLevelName(self.level), self.logger.name)) - - From 01ba090032cc8f1c112d3aeb71562fd2d1511570 Mon Sep 17 00:00:00 2001 From: Serhiy Storchaka Date: Sat, 25 Apr 2020 10:42:41 +0300 Subject: [PATCH 6/6] Fix merging error. --- Lib/test/support/__init__.py | 5 ----- 1 file changed, 5 deletions(-) diff --git a/Lib/test/support/__init__.py b/Lib/test/support/__init__.py index 0e768ea0c703f7..f48decc704cb8a 100644 --- a/Lib/test/support/__init__.py +++ b/Lib/test/support/__init__.py @@ -15,11 +15,6 @@ import importlib import importlib.util import locale -<<<<<<< HEAD -import nntplib -======= -import logging.handlers ->>>>>>> master import os import platform import re