logging: reuse LoggingCaptureHandler instance since it's expensive to create

Previously, a LoggingCaptureHandler was instantiated for each test's
setup/call/teardown which turns out to be expensive.

Instead, only keep one instance and reset it between runs.
This commit is contained in:
Ran Benita 2020-05-13 01:29:25 +03:00
parent 9310d67773
commit d2d11a8bdc
2 changed files with 11 additions and 15 deletions

View File

@ -27,7 +27,7 @@ DEFAULT_LOG_FORMAT = "%(levelname)-8s %(name)s:%(filename)s:%(lineno)d %(message
DEFAULT_LOG_DATE_FORMAT = "%H:%M:%S" DEFAULT_LOG_DATE_FORMAT = "%H:%M:%S"
_ANSI_ESCAPE_SEQ = re.compile(r"\x1b\[[\d;]+m") _ANSI_ESCAPE_SEQ = re.compile(r"\x1b\[[\d;]+m")
catch_log_handler_key = StoreKey["LogCaptureHandler"]() catch_log_handler_key = StoreKey["LogCaptureHandler"]()
catch_log_handlers_key = StoreKey[Dict[str, "LogCaptureHandler"]]() catch_log_records_key = StoreKey[Dict[str, List[logging.LogRecord]]]()
def _remove_ansi_escape_sequences(text): def _remove_ansi_escape_sequences(text):
@ -351,11 +351,7 @@ class LogCaptureFixture:
.. versionadded:: 3.4 .. versionadded:: 3.4
""" """
handler = self._item._store[catch_log_handlers_key].get(when) return self._item._store[catch_log_records_key].get(when, [])
if handler:
return handler.records
else:
return []
@property @property
def text(self): def text(self):
@ -497,6 +493,8 @@ class LoggingPlugin:
get_option_ini(config, "log_auto_indent"), get_option_ini(config, "log_auto_indent"),
) )
self.log_level = get_log_level_for_setting(config, "log_level") self.log_level = get_log_level_for_setting(config, "log_level")
self.log_handler = LogCaptureHandler()
self.log_handler.setFormatter(self.formatter)
# File logging. # File logging.
self.log_file_level = get_log_level_for_setting(config, "log_file_level") self.log_file_level = get_log_level_for_setting(config, "log_file_level")
@ -639,10 +637,9 @@ class LoggingPlugin:
def _runtest_for(self, item: nodes.Item, when: str) -> Generator[None, None, None]: def _runtest_for(self, item: nodes.Item, when: str) -> Generator[None, None, None]:
"""Implements the internals of pytest_runtest_xxx() hook.""" """Implements the internals of pytest_runtest_xxx() hook."""
log_handler = LogCaptureHandler() with catching_logs(self.log_handler, level=self.log_level) as log_handler:
log_handler.setFormatter(self.formatter) log_handler.reset()
with catching_logs(log_handler, level=self.log_level): item._store[catch_log_records_key][when] = log_handler.records
item._store[catch_log_handlers_key][when] = log_handler
item._store[catch_log_handler_key] = log_handler item._store[catch_log_handler_key] = log_handler
yield yield
@ -654,8 +651,7 @@ class LoggingPlugin:
def pytest_runtest_setup(self, item): def pytest_runtest_setup(self, item):
self.log_cli_handler.set_when("setup") self.log_cli_handler.set_when("setup")
empty = {} # type: Dict[str, LogCaptureHandler] item._store[catch_log_records_key] = {}
item._store[catch_log_handlers_key] = empty
yield from self._runtest_for(item, "setup") yield from self._runtest_for(item, "setup")
@pytest.hookimpl(hookwrapper=True) @pytest.hookimpl(hookwrapper=True)
@ -669,7 +665,7 @@ class LoggingPlugin:
self.log_cli_handler.set_when("teardown") self.log_cli_handler.set_when("teardown")
yield from self._runtest_for(item, "teardown") yield from self._runtest_for(item, "teardown")
del item._store[catch_log_handlers_key] del item._store[catch_log_records_key]
del item._store[catch_log_handler_key] del item._store[catch_log_handler_key]
@pytest.hookimpl @pytest.hookimpl

View File

@ -1,7 +1,7 @@
import logging import logging
import pytest import pytest
from _pytest.logging import catch_log_handlers_key from _pytest.logging import catch_log_records_key
logger = logging.getLogger(__name__) logger = logging.getLogger(__name__)
sublogger = logging.getLogger(__name__ + ".baz") sublogger = logging.getLogger(__name__ + ".baz")
@ -137,4 +137,4 @@ def test_caplog_captures_for_all_stages(caplog, logging_during_setup_and_teardow
assert [x.message for x in caplog.get_records("setup")] == ["a_setup_log"] assert [x.message for x in caplog.get_records("setup")] == ["a_setup_log"]
# This reaches into private API, don't use this type of thing in real tests! # This reaches into private API, don't use this type of thing in real tests!
assert set(caplog._item._store[catch_log_handlers_key]) == {"setup", "call"} assert set(caplog._item._store[catch_log_records_key]) == {"setup", "call"}