From ac6c02f1e2229d78609dede5ad96a0a72bdefdc7 Mon Sep 17 00:00:00 2001 From: Ran Benita Date: Sun, 17 May 2020 14:58:04 +0300 Subject: [PATCH 01/12] logging: use item's store for private attributes This makes things type-safe and properly private. --- changelog/7224.breaking.rst | 2 ++ src/_pytest/logging.py | 23 +++++++++++++---------- testing/logging/test_fixture.py | 3 ++- 3 files changed, 17 insertions(+), 11 deletions(-) create mode 100644 changelog/7224.breaking.rst diff --git a/changelog/7224.breaking.rst b/changelog/7224.breaking.rst new file mode 100644 index 000000000..32ab2c073 --- /dev/null +++ b/changelog/7224.breaking.rst @@ -0,0 +1,2 @@ +The `item.catch_log_handler` and `item.catch_log_handlers` attributes, set by the +logging plugin and never meant to be public , are no longer available. diff --git a/src/_pytest/logging.py b/src/_pytest/logging.py index 8cb7b1841..4de5c1b2b 100644 --- a/src/_pytest/logging.py +++ b/src/_pytest/logging.py @@ -17,10 +17,14 @@ from _pytest.config import _strtobool from _pytest.config import Config from _pytest.config import create_terminal_writer from _pytest.pathlib import Path +from _pytest.store import StoreKey + DEFAULT_LOG_FORMAT = "%(levelname)-8s %(name)s:%(filename)s:%(lineno)d %(message)s" DEFAULT_LOG_DATE_FORMAT = "%H:%M:%S" _ANSI_ESCAPE_SEQ = re.compile(r"\x1b\[[\d;]+m") +catch_log_handler_key = StoreKey["LogCaptureHandler"]() +catch_log_handlers_key = StoreKey[Dict[str, "LogCaptureHandler"]]() def _remove_ansi_escape_sequences(text): @@ -317,7 +321,7 @@ class LogCaptureHandler(logging.StreamHandler): class LogCaptureFixture: """Provides access and control of log capturing.""" - def __init__(self, item) -> None: + def __init__(self, item: nodes.Node) -> None: """Creates a new funcarg.""" self._item = item # dict of log name -> log level @@ -338,7 +342,7 @@ class LogCaptureFixture: """ :rtype: LogCaptureHandler """ - return self._item.catch_log_handler # type: ignore[no-any-return] + return self._item._store[catch_log_handler_key] def get_records(self, when: str) -> List[logging.LogRecord]: """ @@ -352,9 +356,9 @@ class LogCaptureFixture: .. versionadded:: 3.4 """ - handler = self._item.catch_log_handlers.get(when) + handler = self._item._store[catch_log_handlers_key].get(when) if handler: - return handler.records # type: ignore[no-any-return] + return handler.records else: return [] @@ -645,16 +649,15 @@ class LoggingPlugin: yield # run the test return - if not hasattr(item, "catch_log_handlers"): - item.catch_log_handlers = {} # type: ignore[attr-defined] - item.catch_log_handlers[when] = log_handler # type: ignore[attr-defined] - item.catch_log_handler = log_handler # type: ignore[attr-defined] + empty = {} # type: Dict[str, LogCaptureHandler] + item._store.setdefault(catch_log_handlers_key, empty)[when] = log_handler + item._store[catch_log_handler_key] = log_handler try: yield # run test finally: if when == "teardown": - del item.catch_log_handler # type: ignore[attr-defined] - del item.catch_log_handlers # type: ignore[attr-defined] + del item._store[catch_log_handlers_key] + del item._store[catch_log_handler_key] if self.print_logs: # Add a captured log section to the report. diff --git a/testing/logging/test_fixture.py b/testing/logging/test_fixture.py index c68866bef..a33b0e80e 100644 --- a/testing/logging/test_fixture.py +++ b/testing/logging/test_fixture.py @@ -1,6 +1,7 @@ import logging import pytest +from _pytest.logging import catch_log_handlers_key logger = logging.getLogger(__name__) sublogger = logging.getLogger(__name__ + ".baz") @@ -136,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"] # This reaches into private API, don't use this type of thing in real tests! - assert set(caplog._item.catch_log_handlers.keys()) == {"setup", "call"} + assert set(caplog._item._store[catch_log_handlers_key]) == {"setup", "call"} From 9effbe7425b2477e1593f8b6ffc6524e587a3be6 Mon Sep 17 00:00:00 2001 From: Ran Benita Date: Sun, 17 May 2020 14:58:04 +0300 Subject: [PATCH 02/12] logging: inline _runtest_for_main into _runtest_for This avoids a little bit of overhead, and makes the code a bit clearer too. --- src/_pytest/logging.py | 38 +++++++++++++++++--------------------- 1 file changed, 17 insertions(+), 21 deletions(-) diff --git a/src/_pytest/logging.py b/src/_pytest/logging.py index 4de5c1b2b..61d689263 100644 --- a/src/_pytest/logging.py +++ b/src/_pytest/logging.py @@ -626,17 +626,8 @@ class LoggingPlugin: yield @contextmanager - def _runtest_for(self, item, when): - with self._runtest_for_main(item, when): - if self.log_file_handler is not None: - with catching_logs(self.log_file_handler, level=self.log_file_level): - yield - else: - yield - - @contextmanager - def _runtest_for_main( - self, item: nodes.Item, when: str + def _runtest_for( + self, item: Optional[nodes.Item], when: str ) -> Generator[None, None, None]: """Implements the internals of pytest_runtest_xxx() hook.""" with catching_logs( @@ -645,21 +636,26 @@ class LoggingPlugin: if self.log_cli_handler: self.log_cli_handler.set_when(when) - if item is None: - yield # run the test - return - - empty = {} # type: Dict[str, LogCaptureHandler] - item._store.setdefault(catch_log_handlers_key, empty)[when] = log_handler - item._store[catch_log_handler_key] = log_handler + if item is not None: + empty = {} # type: Dict[str, LogCaptureHandler] + item._store.setdefault(catch_log_handlers_key, empty)[ + when + ] = log_handler + item._store[catch_log_handler_key] = log_handler try: - yield # run test + if self.log_file_handler is not None: + with catching_logs( + self.log_file_handler, level=self.log_file_level + ): + yield + else: + yield finally: - if when == "teardown": + if item is not None and when == "teardown": del item._store[catch_log_handlers_key] del item._store[catch_log_handler_key] - if self.print_logs: + if item is not None and self.print_logs: # Add a captured log section to the report. log = log_handler.stream.getvalue().strip() item.add_report_section(when, "log", log) From ce0f2187936cebed1a75202530a672249c3f5438 Mon Sep 17 00:00:00 2001 From: Ran Benita Date: Sun, 17 May 2020 14:58:04 +0300 Subject: [PATCH 03/12] logging: yield from _runtest_for instead of contextmanager Avoid the slight overhead of contextmanager. --- src/_pytest/logging.py | 19 ++++++------------- 1 file changed, 6 insertions(+), 13 deletions(-) diff --git a/src/_pytest/logging.py b/src/_pytest/logging.py index 61d689263..55175cec5 100644 --- a/src/_pytest/logging.py +++ b/src/_pytest/logging.py @@ -625,7 +625,6 @@ class LoggingPlugin: with catching_logs(logging.NullHandler()): yield - @contextmanager def _runtest_for( self, item: Optional[nodes.Item], when: str ) -> Generator[None, None, None]: @@ -662,35 +661,29 @@ class LoggingPlugin: @pytest.hookimpl(hookwrapper=True) def pytest_runtest_setup(self, item): - with self._runtest_for(item, "setup"): - yield + yield from self._runtest_for(item, "setup") @pytest.hookimpl(hookwrapper=True) def pytest_runtest_call(self, item): - with self._runtest_for(item, "call"): - yield + yield from self._runtest_for(item, "call") @pytest.hookimpl(hookwrapper=True) def pytest_runtest_teardown(self, item): - with self._runtest_for(item, "teardown"): - yield + yield from self._runtest_for(item, "teardown") @pytest.hookimpl(hookwrapper=True) def pytest_runtest_logstart(self): if self.log_cli_handler: self.log_cli_handler.reset() - with self._runtest_for(None, "start"): - yield + yield from self._runtest_for(None, "start") @pytest.hookimpl(hookwrapper=True) def pytest_runtest_logfinish(self): - with self._runtest_for(None, "finish"): - yield + yield from self._runtest_for(None, "finish") @pytest.hookimpl(hookwrapper=True) def pytest_runtest_logreport(self): - with self._runtest_for(None, "logreport"): - yield + yield from self._runtest_for(None, "logreport") @pytest.hookimpl(hookwrapper=True, tryfirst=True) def pytest_sessionfinish(self): From eceb28e4bedde9ba4dfa8541e7fd92729f33c370 Mon Sep 17 00:00:00 2001 From: Ran Benita Date: Sun, 17 May 2020 14:58:04 +0300 Subject: [PATCH 04/12] logging: set formatter on handler creation, not in catching_logs Conceptually it doesn't check per catching_logs (and catching_logs doesn't restore the older one either). It is just something that is defined for each handler once. --- src/_pytest/logging.py | 19 ++++++++++--------- 1 file changed, 10 insertions(+), 9 deletions(-) diff --git a/src/_pytest/logging.py b/src/_pytest/logging.py index 55175cec5..9360b85c9 100644 --- a/src/_pytest/logging.py +++ b/src/_pytest/logging.py @@ -273,12 +273,10 @@ def pytest_addoption(parser): @contextmanager -def catching_logs(handler, formatter=None, level=None): +def catching_logs(handler, level=None): """Context manager that prepares the whole logging machinery properly.""" root_logger = logging.getLogger() - if formatter is not None: - handler.setFormatter(formatter) if level is not None: handler.setLevel(level) @@ -303,15 +301,17 @@ def catching_logs(handler, formatter=None, level=None): class LogCaptureHandler(logging.StreamHandler): """A logging handler that stores log records and the log text.""" + stream = None # type: StringIO + def __init__(self) -> None: """Creates a new log handler.""" - logging.StreamHandler.__init__(self, StringIO()) + super().__init__(StringIO()) self.records = [] # type: List[logging.LogRecord] def emit(self, record: logging.LogRecord) -> None: """Keep the log records in a list in addition to the log text.""" self.records.append(record) - logging.StreamHandler.emit(self, record) + super().emit(record) def reset(self) -> None: self.records = [] @@ -571,11 +571,12 @@ class LoggingPlugin: get_option_ini(config, "log_cli_date_format", "log_date_format"), get_option_ini(config, "log_auto_indent"), ) + log_cli_handler.setFormatter(log_cli_formatter) log_cli_level = get_log_level_for_setting(config, "log_cli_level", "log_level") self.log_cli_handler = log_cli_handler self.live_logs_context = lambda: catching_logs( - log_cli_handler, formatter=log_cli_formatter, level=log_cli_level + log_cli_handler, level=log_cli_level ) def set_log_path(self, fname): @@ -629,9 +630,9 @@ class LoggingPlugin: self, item: Optional[nodes.Item], when: str ) -> Generator[None, None, None]: """Implements the internals of pytest_runtest_xxx() hook.""" - with catching_logs( - LogCaptureHandler(), formatter=self.formatter, level=self.log_level - ) as log_handler: + log_handler = LogCaptureHandler() + log_handler.setFormatter(self.formatter) + with catching_logs(log_handler, level=self.log_level): if self.log_cli_handler: self.log_cli_handler.set_when(when) From e48ac692dedc11e5c5c8722b426f5b575eeadea0 Mon Sep 17 00:00:00 2001 From: Ran Benita Date: Sun, 17 May 2020 14:58:04 +0300 Subject: [PATCH 05/12] logging: optimize catching_logs slightly Remove usage of `@contextmanager` as it is a bit slower than hand-rolling, and also disallows re-entry which we want to use. Removing protections around addHandler()/removeHandler(), because logging already checks that internally. --- src/_pytest/logging.py | 51 ++++++++++++++++++++---------------------- 1 file changed, 24 insertions(+), 27 deletions(-) diff --git a/src/_pytest/logging.py b/src/_pytest/logging.py index 9360b85c9..fe2015372 100644 --- a/src/_pytest/logging.py +++ b/src/_pytest/logging.py @@ -272,30 +272,31 @@ def pytest_addoption(parser): ) -@contextmanager -def catching_logs(handler, level=None): +# Not using @contextmanager for performance reasons. +class catching_logs: """Context manager that prepares the whole logging machinery properly.""" - root_logger = logging.getLogger() - if level is not None: - handler.setLevel(level) + __slots__ = ("handler", "level", "orig_level") - # Adding the same handler twice would confuse logging system. - # Just don't do that. - add_new_handler = handler not in root_logger.handlers + def __init__(self, handler, level=None): + self.handler = handler + self.level = level - if add_new_handler: - root_logger.addHandler(handler) - if level is not None: - orig_level = root_logger.level - root_logger.setLevel(min(orig_level, level)) - try: - yield handler - finally: - if level is not None: - root_logger.setLevel(orig_level) - if add_new_handler: - root_logger.removeHandler(handler) + def __enter__(self): + root_logger = logging.getLogger() + if self.level is not None: + self.handler.setLevel(self.level) + root_logger.addHandler(self.handler) + if self.level is not None: + self.orig_level = root_logger.level + root_logger.setLevel(min(self.orig_level, self.level)) + return self.handler + + def __exit__(self, type, value, traceback): + root_logger = logging.getLogger() + if self.level is not None: + root_logger.setLevel(self.orig_level) + root_logger.removeHandler(self.handler) class LogCaptureHandler(logging.StreamHandler): @@ -527,15 +528,11 @@ class LoggingPlugin: else: self.log_file_handler = None - self.log_cli_handler = None - - self.live_logs_context = lambda: nullcontext() - # Note that the lambda for the live_logs_context is needed because - # live_logs_context can otherwise not be entered multiple times due - # to limitations of contextlib.contextmanager. - if self._log_cli_enabled(): self._setup_cli_logging() + else: + self.log_cli_handler = None + self.live_logs_context = nullcontext def _create_formatter(self, log_format, log_date_format, auto_indent): # color option doesn't exist if terminal plugin is disabled From 075903dafa6ef6f62e2af67f336ee45f267feaa1 Mon Sep 17 00:00:00 2001 From: Ran Benita Date: Sun, 17 May 2020 14:58:04 +0300 Subject: [PATCH 06/12] logging: simplify log-file handling - Instead of making it optional, always set up a handler, but possibly going to /dev/null. This simplifies the code by removing a lot of conditionals. It also can replace the NullHandler() we already add. - Change `set_log_path` to just change the stream, instead of recreating one. Besides plugging a resource leak, it enables the next item. - Remove the capturing_logs from _runtest_for, since it sufficiently covered by the one in pytest_runtestloop now, which wraps all other _runtest_for calls. The first item alone would have had an adverse performance impact, but the last item removes it. --- src/_pytest/logging.py | 94 ++++++++++++++++++------------------------ 1 file changed, 39 insertions(+), 55 deletions(-) diff --git a/src/_pytest/logging.py b/src/_pytest/logging.py index fe2015372..49f2af2c7 100644 --- a/src/_pytest/logging.py +++ b/src/_pytest/logging.py @@ -1,6 +1,8 @@ """ Access and control log capturing. """ import logging +import os import re +import sys from contextlib import contextmanager from io import StringIO from typing import AbstractSet @@ -503,6 +505,7 @@ class LoggingPlugin: _issue_warning_captured(NO_PRINT_LOGS, self._config.hook, stacklevel=2) + # Report logging. self.formatter = self._create_formatter( get_option_ini(config, "log_format"), get_option_ini(config, "log_date_format"), @@ -510,24 +513,22 @@ class LoggingPlugin: ) self.log_level = get_log_level_for_setting(config, "log_level") + # File logging. self.log_file_level = get_log_level_for_setting(config, "log_file_level") - self.log_file_format = get_option_ini(config, "log_file_format", "log_format") - self.log_file_date_format = get_option_ini( + log_file = get_option_ini(config, "log_file") or os.devnull + self.log_file_handler = logging.FileHandler( + log_file, mode="w", encoding="UTF-8" + ) + log_file_format = get_option_ini(config, "log_file_format", "log_format") + log_file_date_format = get_option_ini( config, "log_file_date_format", "log_date_format" ) - self.log_file_formatter = logging.Formatter( - self.log_file_format, datefmt=self.log_file_date_format + log_file_formatter = logging.Formatter( + log_file_format, datefmt=log_file_date_format ) + self.log_file_handler.setFormatter(log_file_formatter) - log_file = get_option_ini(config, "log_file") - if log_file: - self.log_file_handler = logging.FileHandler( - log_file, mode="w", encoding="UTF-8" - ) # type: Optional[logging.FileHandler] - self.log_file_handler.setFormatter(self.log_file_formatter) - else: - self.log_file_handler = None - + # CLI/live logging. if self._log_cli_enabled(): self._setup_cli_logging() else: @@ -592,10 +593,19 @@ class LoggingPlugin: if not fname.parent.exists(): fname.parent.mkdir(exist_ok=True, parents=True) - self.log_file_handler = logging.FileHandler( - str(fname), mode="w", encoding="UTF-8" - ) - self.log_file_handler.setFormatter(self.log_file_formatter) + stream = fname.open(mode="w", encoding="UTF-8") + if sys.version_info >= (3, 7): + old_stream = self.log_file_handler.setStream(stream) + else: + old_stream = self.log_file_handler.stream + self.log_file_handler.acquire() + try: + self.log_file_handler.flush() + self.log_file_handler.stream = stream + finally: + self.log_file_handler.release() + if old_stream: + old_stream.close() def _log_cli_enabled(self): """Return True if log_cli should be considered enabled, either explicitly @@ -611,17 +621,8 @@ class LoggingPlugin: if self.log_cli_handler: self.log_cli_handler.set_when("collection") - if self.log_file_handler is not None: - with catching_logs(self.log_file_handler, level=self.log_file_level): - yield - else: - # Add a dummy handler to ensure logging.root.handlers is not empty. - # If it were empty, then a `logging.warning()` call (and similar) during collection - # would trigger a `logging.basicConfig()` call, which would add a `StreamHandler` - # handler, which would cause all subsequent logs which reach the root to be also - # printed to stdout, which we don't want (issue #6240). - with catching_logs(logging.NullHandler()): - yield + with catching_logs(self.log_file_handler, level=self.log_file_level): + yield def _runtest_for( self, item: Optional[nodes.Item], when: str @@ -640,13 +641,7 @@ class LoggingPlugin: ] = log_handler item._store[catch_log_handler_key] = log_handler try: - if self.log_file_handler is not None: - with catching_logs( - self.log_file_handler, level=self.log_file_level - ): - yield - else: - yield + yield finally: if item is not None and when == "teardown": del item._store[catch_log_handlers_key] @@ -688,28 +683,20 @@ class LoggingPlugin: with self.live_logs_context(): if self.log_cli_handler: self.log_cli_handler.set_when("sessionfinish") - if self.log_file_handler is not None: - try: - with catching_logs( - self.log_file_handler, level=self.log_file_level - ): - yield - finally: - # Close the FileHandler explicitly. - # (logging.shutdown might have lost the weakref?!) - self.log_file_handler.close() - else: - yield + try: + with catching_logs(self.log_file_handler, level=self.log_file_level): + yield + finally: + # Close the FileHandler explicitly. + # (logging.shutdown might have lost the weakref?!) + self.log_file_handler.close() @pytest.hookimpl(hookwrapper=True, tryfirst=True) def pytest_sessionstart(self): with self.live_logs_context(): if self.log_cli_handler: self.log_cli_handler.set_when("sessionstart") - if self.log_file_handler is not None: - with catching_logs(self.log_file_handler, level=self.log_file_level): - yield - else: + with catching_logs(self.log_file_handler, level=self.log_file_level): yield @pytest.hookimpl(hookwrapper=True) @@ -725,10 +712,7 @@ class LoggingPlugin: self._config.option.verbose = 1 with self.live_logs_context(): - if self.log_file_handler is not None: - with catching_logs(self.log_file_handler, level=self.log_file_level): - yield # run all the tests - else: + with catching_logs(self.log_file_handler, level=self.log_file_level): yield # run all the tests From b13af52bbe65b4273067bdbf7656e01bfa96395d Mon Sep 17 00:00:00 2001 From: Ran Benita Date: Sun, 17 May 2020 14:58:04 +0300 Subject: [PATCH 07/12] logging: call set_when() in a consistent manner --- src/_pytest/logging.py | 32 ++++++++++++++++++++------------ 1 file changed, 20 insertions(+), 12 deletions(-) diff --git a/src/_pytest/logging.py b/src/_pytest/logging.py index 49f2af2c7..3c4bd50e5 100644 --- a/src/_pytest/logging.py +++ b/src/_pytest/logging.py @@ -617,10 +617,10 @@ class LoggingPlugin: @pytest.hookimpl(hookwrapper=True, tryfirst=True) def pytest_collection(self) -> Generator[None, None, None]: - with self.live_logs_context(): - if self.log_cli_handler: - self.log_cli_handler.set_when("collection") + if self.log_cli_handler is not None: + self.log_cli_handler.set_when("collection") + with self.live_logs_context(): with catching_logs(self.log_file_handler, level=self.log_file_level): yield @@ -631,9 +631,6 @@ class LoggingPlugin: log_handler = LogCaptureHandler() log_handler.setFormatter(self.formatter) with catching_logs(log_handler, level=self.log_level): - if self.log_cli_handler: - self.log_cli_handler.set_when(when) - if item is not None: empty = {} # type: Dict[str, LogCaptureHandler] item._store.setdefault(catch_log_handlers_key, empty)[ @@ -654,21 +651,30 @@ class LoggingPlugin: @pytest.hookimpl(hookwrapper=True) def pytest_runtest_setup(self, item): + if self.log_cli_handler is not None: + self.log_cli_handler.set_when("setup") + yield from self._runtest_for(item, "setup") @pytest.hookimpl(hookwrapper=True) def pytest_runtest_call(self, item): + if self.log_cli_handler is not None: + self.log_cli_handler.set_when("call") + yield from self._runtest_for(item, "call") @pytest.hookimpl(hookwrapper=True) def pytest_runtest_teardown(self, item): + if self.log_cli_handler is not None: + self.log_cli_handler.set_when("teardown") + yield from self._runtest_for(item, "teardown") @pytest.hookimpl(hookwrapper=True) def pytest_runtest_logstart(self): - if self.log_cli_handler: + if self.log_cli_handler is not None: self.log_cli_handler.reset() - yield from self._runtest_for(None, "start") + self.log_cli_handler.set_when("start") @pytest.hookimpl(hookwrapper=True) def pytest_runtest_logfinish(self): @@ -680,9 +686,10 @@ class LoggingPlugin: @pytest.hookimpl(hookwrapper=True, tryfirst=True) def pytest_sessionfinish(self): + if self.log_cli_handler is not None: + self.log_cli_handler.set_when("sessionfinish") + with self.live_logs_context(): - if self.log_cli_handler: - self.log_cli_handler.set_when("sessionfinish") try: with catching_logs(self.log_file_handler, level=self.log_file_level): yield @@ -693,9 +700,10 @@ class LoggingPlugin: @pytest.hookimpl(hookwrapper=True, tryfirst=True) def pytest_sessionstart(self): + if self.log_cli_handler is not None: + self.log_cli_handler.set_when("sessionstart") + with self.live_logs_context(): - if self.log_cli_handler: - self.log_cli_handler.set_when("sessionstart") with catching_logs(self.log_file_handler, level=self.log_file_level): yield From bd657bab3f1a90c24f9dc817e93bf8388f89bda3 Mon Sep 17 00:00:00 2001 From: Ran Benita Date: Sun, 17 May 2020 14:58:04 +0300 Subject: [PATCH 08/12] logging: don't use _runtest_for for the pytest_log* hooks The logstart/logreport/logfinish hooks don't need the stuff in _runtest_for. The test capturing catching_logs call is irrelevant for them, and the item-conditional sections are gone. --- src/_pytest/logging.py | 38 +++++++++++++++++--------------------- 1 file changed, 17 insertions(+), 21 deletions(-) diff --git a/src/_pytest/logging.py b/src/_pytest/logging.py index 3c4bd50e5..00bac23df 100644 --- a/src/_pytest/logging.py +++ b/src/_pytest/logging.py @@ -624,27 +624,17 @@ class LoggingPlugin: with catching_logs(self.log_file_handler, level=self.log_file_level): yield - def _runtest_for( - self, item: Optional[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.""" log_handler = LogCaptureHandler() log_handler.setFormatter(self.formatter) with catching_logs(log_handler, level=self.log_level): - if item is not None: - empty = {} # type: Dict[str, LogCaptureHandler] - item._store.setdefault(catch_log_handlers_key, empty)[ - when - ] = log_handler - item._store[catch_log_handler_key] = log_handler - try: - yield - finally: - if item is not None and when == "teardown": - del item._store[catch_log_handlers_key] - del item._store[catch_log_handler_key] + item._store[catch_log_handlers_key][when] = log_handler + item._store[catch_log_handler_key] = log_handler - if item is not None and self.print_logs: + yield + + if self.print_logs: # Add a captured log section to the report. log = log_handler.stream.getvalue().strip() item.add_report_section(when, "log", log) @@ -654,6 +644,8 @@ class LoggingPlugin: if self.log_cli_handler is not None: self.log_cli_handler.set_when("setup") + empty = {} # type: Dict[str, LogCaptureHandler] + item._store[catch_log_handlers_key] = empty yield from self._runtest_for(item, "setup") @pytest.hookimpl(hookwrapper=True) @@ -669,20 +661,24 @@ class LoggingPlugin: self.log_cli_handler.set_when("teardown") yield from self._runtest_for(item, "teardown") + del item._store[catch_log_handlers_key] + del item._store[catch_log_handler_key] - @pytest.hookimpl(hookwrapper=True) + @pytest.hookimpl def pytest_runtest_logstart(self): if self.log_cli_handler is not None: self.log_cli_handler.reset() self.log_cli_handler.set_when("start") - @pytest.hookimpl(hookwrapper=True) + @pytest.hookimpl def pytest_runtest_logfinish(self): - yield from self._runtest_for(None, "finish") + if self.log_cli_handler is not None: + self.log_cli_handler.set_when("finish") - @pytest.hookimpl(hookwrapper=True) + @pytest.hookimpl def pytest_runtest_logreport(self): - yield from self._runtest_for(None, "logreport") + if self.log_cli_handler is not None: + self.log_cli_handler.set_when("logreport") @pytest.hookimpl(hookwrapper=True, tryfirst=True) def pytest_sessionfinish(self): From 43c465c9bf6d40bd579d62e63e883823368e1fde Mon Sep 17 00:00:00 2001 From: Ran Benita Date: Sun, 17 May 2020 14:58:04 +0300 Subject: [PATCH 09/12] logging: use dummy handler when CLI logging is disabled instead of None This makes the code cleaner by removing conditionals and making the CLI and file logging completely analogous. Doesn't affect performance. --- src/_pytest/logging.py | 121 ++++++++++++++++++++--------------------- 1 file changed, 59 insertions(+), 62 deletions(-) diff --git a/src/_pytest/logging.py b/src/_pytest/logging.py index 00bac23df..eca5c240b 100644 --- a/src/_pytest/logging.py +++ b/src/_pytest/logging.py @@ -11,6 +11,7 @@ from typing import Generator from typing import List from typing import Mapping from typing import Optional +from typing import Union import pytest from _pytest import nodes @@ -529,11 +530,24 @@ class LoggingPlugin: self.log_file_handler.setFormatter(log_file_formatter) # CLI/live logging. + self.log_cli_level = get_log_level_for_setting( + config, "log_cli_level", "log_level" + ) if self._log_cli_enabled(): - self._setup_cli_logging() + terminal_reporter = config.pluginmanager.get_plugin("terminalreporter") + capture_manager = config.pluginmanager.get_plugin("capturemanager") + # if capturemanager plugin is disabled, live logging still works. + self.log_cli_handler = _LiveLoggingStreamHandler( + terminal_reporter, capture_manager + ) # type: Union[_LiveLoggingStreamHandler, _LiveLoggingNullHandler] else: - self.log_cli_handler = None - self.live_logs_context = nullcontext + self.log_cli_handler = _LiveLoggingNullHandler() + log_cli_formatter = self._create_formatter( + get_option_ini(config, "log_cli_format", "log_format"), + get_option_ini(config, "log_cli_date_format", "log_date_format"), + get_option_ini(config, "log_auto_indent"), + ) + self.log_cli_handler.setFormatter(log_cli_formatter) def _create_formatter(self, log_format, log_date_format, auto_indent): # color option doesn't exist if terminal plugin is disabled @@ -553,30 +567,6 @@ class LoggingPlugin: return formatter - def _setup_cli_logging(self): - config = self._config - terminal_reporter = config.pluginmanager.get_plugin("terminalreporter") - if terminal_reporter is None: - # terminal reporter is disabled e.g. by pytest-xdist. - return - - capture_manager = config.pluginmanager.get_plugin("capturemanager") - # if capturemanager plugin is disabled, live logging still works. - log_cli_handler = _LiveLoggingStreamHandler(terminal_reporter, capture_manager) - - log_cli_formatter = self._create_formatter( - get_option_ini(config, "log_cli_format", "log_format"), - get_option_ini(config, "log_cli_date_format", "log_date_format"), - get_option_ini(config, "log_auto_indent"), - ) - log_cli_handler.setFormatter(log_cli_formatter) - - log_cli_level = get_log_level_for_setting(config, "log_cli_level", "log_level") - self.log_cli_handler = log_cli_handler - self.live_logs_context = lambda: catching_logs( - log_cli_handler, level=log_cli_level - ) - def set_log_path(self, fname): """Public method, which can set filename parameter for Logging.FileHandler(). Also creates parent directory if @@ -608,19 +598,25 @@ class LoggingPlugin: old_stream.close() def _log_cli_enabled(self): - """Return True if log_cli should be considered enabled, either explicitly - or because --log-cli-level was given in the command-line. - """ - return self._config.getoption( + """Return whether live logging is enabled.""" + enabled = self._config.getoption( "--log-cli-level" ) is not None or self._config.getini("log_cli") + if not enabled: + return False + + terminal_reporter = self._config.pluginmanager.get_plugin("terminalreporter") + if terminal_reporter is None: + # terminal reporter is disabled e.g. by pytest-xdist. + return False + + return True @pytest.hookimpl(hookwrapper=True, tryfirst=True) def pytest_collection(self) -> Generator[None, None, None]: - if self.log_cli_handler is not None: - self.log_cli_handler.set_when("collection") + self.log_cli_handler.set_when("collection") - with self.live_logs_context(): + with catching_logs(self.log_cli_handler, level=self.log_cli_level): with catching_logs(self.log_file_handler, level=self.log_file_level): yield @@ -641,8 +637,7 @@ class LoggingPlugin: @pytest.hookimpl(hookwrapper=True) def pytest_runtest_setup(self, item): - if self.log_cli_handler is not None: - self.log_cli_handler.set_when("setup") + self.log_cli_handler.set_when("setup") empty = {} # type: Dict[str, LogCaptureHandler] item._store[catch_log_handlers_key] = empty @@ -650,15 +645,13 @@ class LoggingPlugin: @pytest.hookimpl(hookwrapper=True) def pytest_runtest_call(self, item): - if self.log_cli_handler is not None: - self.log_cli_handler.set_when("call") + self.log_cli_handler.set_when("call") yield from self._runtest_for(item, "call") @pytest.hookimpl(hookwrapper=True) def pytest_runtest_teardown(self, item): - if self.log_cli_handler is not None: - self.log_cli_handler.set_when("teardown") + self.log_cli_handler.set_when("teardown") yield from self._runtest_for(item, "teardown") del item._store[catch_log_handlers_key] @@ -666,40 +659,34 @@ class LoggingPlugin: @pytest.hookimpl def pytest_runtest_logstart(self): - if self.log_cli_handler is not None: - self.log_cli_handler.reset() - self.log_cli_handler.set_when("start") + self.log_cli_handler.reset() + self.log_cli_handler.set_when("start") @pytest.hookimpl def pytest_runtest_logfinish(self): - if self.log_cli_handler is not None: - self.log_cli_handler.set_when("finish") + self.log_cli_handler.set_when("finish") @pytest.hookimpl def pytest_runtest_logreport(self): - if self.log_cli_handler is not None: - self.log_cli_handler.set_when("logreport") + self.log_cli_handler.set_when("logreport") @pytest.hookimpl(hookwrapper=True, tryfirst=True) def pytest_sessionfinish(self): - if self.log_cli_handler is not None: - self.log_cli_handler.set_when("sessionfinish") + self.log_cli_handler.set_when("sessionfinish") - with self.live_logs_context(): - try: - with catching_logs(self.log_file_handler, level=self.log_file_level): - yield - finally: - # Close the FileHandler explicitly. - # (logging.shutdown might have lost the weakref?!) - self.log_file_handler.close() + with catching_logs(self.log_cli_handler, level=self.log_cli_level): + with catching_logs(self.log_file_handler, level=self.log_file_level): + yield + + # Close the FileHandler explicitly. + # (logging.shutdown might have lost the weakref?!) + self.log_file_handler.close() @pytest.hookimpl(hookwrapper=True, tryfirst=True) def pytest_sessionstart(self): - if self.log_cli_handler is not None: - self.log_cli_handler.set_when("sessionstart") + self.log_cli_handler.set_when("sessionstart") - with self.live_logs_context(): + with catching_logs(self.log_cli_handler, level=self.log_cli_level): with catching_logs(self.log_file_handler, level=self.log_file_level): yield @@ -715,7 +702,7 @@ class LoggingPlugin: # setting verbose flag is needed to avoid messy test progress output self._config.option.verbose = 1 - with self.live_logs_context(): + with catching_logs(self.log_cli_handler, level=self.log_cli_level): with catching_logs(self.log_file_handler, level=self.log_file_level): yield # run all the tests @@ -768,4 +755,14 @@ class _LiveLoggingStreamHandler(logging.StreamHandler): if not self._section_name_shown and self._when: self.stream.section("live log " + self._when, sep="-", bold=True) self._section_name_shown = True - logging.StreamHandler.emit(self, record) + super().emit(record) + + +class _LiveLoggingNullHandler(logging.NullHandler): + """A handler used when live logging is disabled.""" + + def reset(self): + pass + + def set_when(self, when): + pass From bd5e3f042d9b38bc4b37bd4bbd477fcf76a87383 Mon Sep 17 00:00:00 2001 From: Ran Benita Date: Sun, 17 May 2020 14:58:04 +0300 Subject: [PATCH 10/12] logging: move log_file_handler cleanup from sessionend to unconfigure It is set-up in configure, so match it. --- src/_pytest/logging.py | 10 ++++++---- 1 file changed, 6 insertions(+), 4 deletions(-) diff --git a/src/_pytest/logging.py b/src/_pytest/logging.py index eca5c240b..39523d0a3 100644 --- a/src/_pytest/logging.py +++ b/src/_pytest/logging.py @@ -678,10 +678,6 @@ class LoggingPlugin: with catching_logs(self.log_file_handler, level=self.log_file_level): yield - # Close the FileHandler explicitly. - # (logging.shutdown might have lost the weakref?!) - self.log_file_handler.close() - @pytest.hookimpl(hookwrapper=True, tryfirst=True) def pytest_sessionstart(self): self.log_cli_handler.set_when("sessionstart") @@ -706,6 +702,12 @@ class LoggingPlugin: with catching_logs(self.log_file_handler, level=self.log_file_level): yield # run all the tests + @pytest.hookimpl + def pytest_unconfigure(self): + # Close the FileHandler explicitly. + # (logging.shutdown might have lost the weakref?!) + self.log_file_handler.close() + class _LiveLoggingStreamHandler(logging.StreamHandler): """ From 3f8200676f12846b74289f9b2e35747623fc768a Mon Sep 17 00:00:00 2001 From: Ran Benita Date: Sun, 17 May 2020 14:58:04 +0300 Subject: [PATCH 11/12] logging: remove deprecated --no-print-logs option/ini This option was deprecated in 5.4.0 and was marked for removal in 6.0.0. --- changelog/7224.breaking.rst | 2 ++ doc/en/deprecations.rst | 4 +-- src/_pytest/deprecated.py | 5 --- src/_pytest/logging.py | 22 ++----------- testing/deprecated_test.py | 41 ----------------------- testing/logging/test_reporting.py | 54 ------------------------------- 6 files changed, 6 insertions(+), 122 deletions(-) diff --git a/changelog/7224.breaking.rst b/changelog/7224.breaking.rst index 32ab2c073..32592695a 100644 --- a/changelog/7224.breaking.rst +++ b/changelog/7224.breaking.rst @@ -1,2 +1,4 @@ The `item.catch_log_handler` and `item.catch_log_handlers` attributes, set by the logging plugin and never meant to be public , are no longer available. + +The deprecated ``--no-print-logs`` option is removed. Use ``--show-capture`` instead. diff --git a/doc/en/deprecations.rst b/doc/en/deprecations.rst index fbcaf2ce4..0b7d3fecd 100644 --- a/doc/en/deprecations.rst +++ b/doc/en/deprecations.rst @@ -37,10 +37,10 @@ a public API and may break in the future. ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ .. deprecated:: 5.4 +.. versionremoved:: 6.0 -Option ``--no-print-logs`` is deprecated and meant to be removed in a future release. If you use ``--no-print-logs``, please try out ``--show-capture`` and -provide feedback. +Option ``--no-print-logs`` is removed. If you used ``--no-print-logs``, please use ``--show-capture`` instead. ``--show-capture`` command-line option was added in ``pytest 3.5.0`` and allows to specify how to display captured output when tests fail: ``no``, ``stdout``, ``stderr``, ``log`` or ``all`` (the default). diff --git a/src/_pytest/deprecated.py b/src/_pytest/deprecated.py index 9f4570f85..f981a4a4b 100644 --- a/src/_pytest/deprecated.py +++ b/src/_pytest/deprecated.py @@ -54,11 +54,6 @@ JUNIT_XML_DEFAULT_FAMILY = PytestDeprecationWarning( "for more information." ) -NO_PRINT_LOGS = PytestDeprecationWarning( - "--no-print-logs is deprecated and scheduled for removal in pytest 6.0.\n" - "Please use --show-capture instead." -) - COLLECT_DIRECTORY_HOOK = PytestDeprecationWarning( "The pytest_collect_directory hook is not working.\n" "Please use collect_ignore in conftests or pytest_collection_modifyitems." diff --git a/src/_pytest/logging.py b/src/_pytest/logging.py index 39523d0a3..d875879a9 100644 --- a/src/_pytest/logging.py +++ b/src/_pytest/logging.py @@ -190,15 +190,6 @@ def pytest_addoption(parser): ) group.addoption(option, dest=dest, **kwargs) - add_option_ini( - "--no-print-logs", - dest="log_print", - action="store_const", - const=False, - default=True, - type="bool", - help="disable printing caught logs on failed tests.", - ) add_option_ini( "--log-level", dest="log_level", @@ -499,13 +490,6 @@ class LoggingPlugin: """ self._config = config - self.print_logs = get_option_ini(config, "log_print") - if not self.print_logs: - from _pytest.warnings import _issue_warning_captured - from _pytest.deprecated import NO_PRINT_LOGS - - _issue_warning_captured(NO_PRINT_LOGS, self._config.hook, stacklevel=2) - # Report logging. self.formatter = self._create_formatter( get_option_ini(config, "log_format"), @@ -630,10 +614,8 @@ class LoggingPlugin: yield - if self.print_logs: - # Add a captured log section to the report. - log = log_handler.stream.getvalue().strip() - item.add_report_section(when, "log", log) + log = log_handler.stream.getvalue().strip() + item.add_report_section(when, "log", log) @pytest.hookimpl(hookwrapper=True) def pytest_runtest_setup(self, item): diff --git a/testing/deprecated_test.py b/testing/deprecated_test.py index edd5505c0..93264f3fc 100644 --- a/testing/deprecated_test.py +++ b/testing/deprecated_test.py @@ -117,47 +117,6 @@ def test_node_direct_ctor_warning(): assert w[0].filename == __file__ -def assert_no_print_logs(testdir, args): - result = testdir.runpytest(*args) - result.stdout.fnmatch_lines( - [ - "*--no-print-logs is deprecated and scheduled for removal in pytest 6.0*", - "*Please use --show-capture instead.*", - ] - ) - - -@pytest.mark.filterwarnings("default") -def test_noprintlogs_is_deprecated_cmdline(testdir): - testdir.makepyfile( - """ - def test_foo(): - pass - """ - ) - - assert_no_print_logs(testdir, ("--no-print-logs",)) - - -@pytest.mark.filterwarnings("default") -def test_noprintlogs_is_deprecated_ini(testdir): - testdir.makeini( - """ - [pytest] - log_print=False - """ - ) - - testdir.makepyfile( - """ - def test_foo(): - pass - """ - ) - - assert_no_print_logs(testdir, ()) - - def test__fillfuncargs_is_deprecated() -> None: with pytest.warns( pytest.PytestDeprecationWarning, diff --git a/testing/logging/test_reporting.py b/testing/logging/test_reporting.py index ad7af9370..c1335b180 100644 --- a/testing/logging/test_reporting.py +++ b/testing/logging/test_reporting.py @@ -166,60 +166,6 @@ def test_teardown_logging(testdir): ) -def test_disable_log_capturing(testdir): - testdir.makepyfile( - """ - import sys - import logging - - logger = logging.getLogger(__name__) - - def test_foo(): - sys.stdout.write('text going to stdout') - logger.warning('catch me if you can!') - sys.stderr.write('text going to stderr') - assert False - """ - ) - result = testdir.runpytest("--no-print-logs") - print(result.stdout) - assert result.ret == 1 - result.stdout.fnmatch_lines(["*- Captured stdout call -*", "text going to stdout"]) - result.stdout.fnmatch_lines(["*- Captured stderr call -*", "text going to stderr"]) - with pytest.raises(pytest.fail.Exception): - result.stdout.fnmatch_lines(["*- Captured *log call -*"]) - - -def test_disable_log_capturing_ini(testdir): - testdir.makeini( - """ - [pytest] - log_print=False - """ - ) - testdir.makepyfile( - """ - import sys - import logging - - logger = logging.getLogger(__name__) - - def test_foo(): - sys.stdout.write('text going to stdout') - logger.warning('catch me if you can!') - sys.stderr.write('text going to stderr') - assert False - """ - ) - result = testdir.runpytest() - print(result.stdout) - assert result.ret == 1 - result.stdout.fnmatch_lines(["*- Captured stdout call -*", "text going to stdout"]) - result.stdout.fnmatch_lines(["*- Captured stderr call -*", "text going to stderr"]) - with pytest.raises(pytest.fail.Exception): - result.stdout.fnmatch_lines(["*- Captured *log call -*"]) - - @pytest.mark.parametrize("enabled", [True, False]) def test_log_cli_enabled_disabled(testdir, enabled): msg = "critical message logged by test" From f71ec8cc907ad8f105631abdc6fd3aff365fb887 Mon Sep 17 00:00:00 2001 From: Ran Benita Date: Sun, 17 May 2020 14:58:04 +0300 Subject: [PATCH 12/12] logging: order hookimpl's in chronological order Makes it easier to understand what's going on. --- src/_pytest/logging.py | 66 +++++++++++++++++++++--------------------- 1 file changed, 33 insertions(+), 33 deletions(-) diff --git a/src/_pytest/logging.py b/src/_pytest/logging.py index d875879a9..f69bcba89 100644 --- a/src/_pytest/logging.py +++ b/src/_pytest/logging.py @@ -596,6 +596,14 @@ class LoggingPlugin: return True + @pytest.hookimpl(hookwrapper=True, tryfirst=True) + def pytest_sessionstart(self): + self.log_cli_handler.set_when("sessionstart") + + with catching_logs(self.log_cli_handler, level=self.log_cli_level): + with catching_logs(self.log_file_handler, level=self.log_file_level): + yield + @pytest.hookimpl(hookwrapper=True, tryfirst=True) def pytest_collection(self) -> Generator[None, None, None]: self.log_cli_handler.set_when("collection") @@ -604,6 +612,31 @@ class LoggingPlugin: with catching_logs(self.log_file_handler, level=self.log_file_level): yield + @pytest.hookimpl(hookwrapper=True) + def pytest_runtestloop(self, session): + """Runs all collected test items.""" + + if session.config.option.collectonly: + yield + return + + if self._log_cli_enabled() and self._config.getoption("verbose") < 1: + # setting verbose flag is needed to avoid messy test progress output + self._config.option.verbose = 1 + + with catching_logs(self.log_cli_handler, level=self.log_cli_level): + with catching_logs(self.log_file_handler, level=self.log_file_level): + yield # run all the tests + + @pytest.hookimpl + def pytest_runtest_logstart(self): + self.log_cli_handler.reset() + self.log_cli_handler.set_when("start") + + @pytest.hookimpl + def pytest_runtest_logreport(self): + self.log_cli_handler.set_when("logreport") + def _runtest_for(self, item: nodes.Item, when: str) -> Generator[None, None, None]: """Implements the internals of pytest_runtest_xxx() hook.""" log_handler = LogCaptureHandler() @@ -639,19 +672,10 @@ class LoggingPlugin: del item._store[catch_log_handlers_key] del item._store[catch_log_handler_key] - @pytest.hookimpl - def pytest_runtest_logstart(self): - self.log_cli_handler.reset() - self.log_cli_handler.set_when("start") - @pytest.hookimpl def pytest_runtest_logfinish(self): self.log_cli_handler.set_when("finish") - @pytest.hookimpl - def pytest_runtest_logreport(self): - self.log_cli_handler.set_when("logreport") - @pytest.hookimpl(hookwrapper=True, tryfirst=True) def pytest_sessionfinish(self): self.log_cli_handler.set_when("sessionfinish") @@ -660,30 +684,6 @@ class LoggingPlugin: with catching_logs(self.log_file_handler, level=self.log_file_level): yield - @pytest.hookimpl(hookwrapper=True, tryfirst=True) - def pytest_sessionstart(self): - self.log_cli_handler.set_when("sessionstart") - - with catching_logs(self.log_cli_handler, level=self.log_cli_level): - with catching_logs(self.log_file_handler, level=self.log_file_level): - yield - - @pytest.hookimpl(hookwrapper=True) - def pytest_runtestloop(self, session): - """Runs all collected test items.""" - - if session.config.option.collectonly: - yield - return - - if self._log_cli_enabled() and self._config.getoption("verbose") < 1: - # setting verbose flag is needed to avoid messy test progress output - self._config.option.verbose = 1 - - with catching_logs(self.log_cli_handler, level=self.log_cli_level): - with catching_logs(self.log_file_handler, level=self.log_file_level): - yield # run all the tests - @pytest.hookimpl def pytest_unconfigure(self): # Close the FileHandler explicitly.