From 5ad1313b8a18fa3862623d2360cbeb39c202b838 Mon Sep 17 00:00:00 2001 From: Bruno Oliveira Date: Mon, 15 Jan 2018 19:02:34 -0200 Subject: [PATCH 01/22] log_cli must now be enabled explicitly Ref: #3013 --- _pytest/logging.py | 46 +++++++++++++++++++------------ testing/logging/test_reporting.py | 29 +++++++++++++++++++ 2 files changed, 57 insertions(+), 18 deletions(-) diff --git a/_pytest/logging.py b/_pytest/logging.py index 27cea1667..ecd50f128 100644 --- a/_pytest/logging.py +++ b/_pytest/logging.py @@ -48,6 +48,9 @@ def pytest_addoption(parser): '--log-date-format', dest='log_date_format', default=DEFAULT_LOG_DATE_FORMAT, help='log date format as used by the logging module.') + parser.addini( + 'log_cli', default=False, type='bool', + help='enable log display during test run (also known as "live logging").') add_option_ini( '--log-cli-level', dest='log_cli_level', default=None, @@ -234,8 +237,12 @@ def get_actual_log_level(config, *setting_names): def pytest_configure(config): - config.pluginmanager.register(LoggingPlugin(config), - 'logging-plugin') + config.pluginmanager.register(LoggingPlugin(config), 'logging-plugin') + + +@contextmanager +def _dummy_context_manager(): + yield class LoggingPlugin(object): @@ -248,26 +255,29 @@ class LoggingPlugin(object): The formatter can be safely shared across all handlers so create a single one for the entire test session here. """ - self.log_cli_level = get_actual_log_level( - config, 'log_cli_level', 'log_level') or logging.WARNING - self.print_logs = get_option_ini(config, 'log_print') self.formatter = logging.Formatter( get_option_ini(config, 'log_format'), get_option_ini(config, 'log_date_format')) - log_cli_handler = logging.StreamHandler(sys.stderr) - log_cli_format = get_option_ini( - config, 'log_cli_format', 'log_format') - log_cli_date_format = get_option_ini( - config, 'log_cli_date_format', 'log_date_format') - log_cli_formatter = logging.Formatter( - log_cli_format, - datefmt=log_cli_date_format) - self.log_cli_handler = log_cli_handler # needed for a single unittest - self.live_logs = catching_logs(log_cli_handler, - formatter=log_cli_formatter, - level=self.log_cli_level) + if config.getini('log_cli'): + log_cli_handler = logging.StreamHandler(sys.stderr) + log_cli_format = get_option_ini( + config, 'log_cli_format', 'log_format') + log_cli_date_format = get_option_ini( + config, 'log_cli_date_format', 'log_date_format') + log_cli_formatter = logging.Formatter( + log_cli_format, + datefmt=log_cli_date_format) + log_cli_level = get_actual_log_level( + config, 'log_cli_level', 'log_level') or logging.WARNING + self.log_cli_handler = log_cli_handler # needed for a single unittest + self.live_logs_context = catching_logs(log_cli_handler, + formatter=log_cli_formatter, + level=log_cli_level) + else: + self.log_cli_handler = None + self.live_logs_context = _dummy_context_manager() log_file = get_option_ini(config, 'log_file') if log_file: @@ -328,7 +338,7 @@ class LoggingPlugin(object): @pytest.hookimpl(hookwrapper=True) def pytest_runtestloop(self, session): """Runs all collected test items.""" - with self.live_logs: + with self.live_logs_context: if self.log_file_handler is not None: with closing(self.log_file_handler): with catching_logs(self.log_file_handler, diff --git a/testing/logging/test_reporting.py b/testing/logging/test_reporting.py index c02ee2172..d10967a5e 100644 --- a/testing/logging/test_reporting.py +++ b/testing/logging/test_reporting.py @@ -141,6 +141,26 @@ def test_disable_log_capturing_ini(testdir): 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' + testdir.makepyfile(''' + import logging + def test_log_cli(): + logging.critical("{}") + '''.format(msg)) + if enabled: + testdir.makeini(''' + [pytest] + log_cli=true + ''') + result = testdir.runpytest('-s') + if enabled: + assert msg in result.stderr.str() + else: + assert msg not in result.stderr.str() + + def test_log_cli_default_level(testdir): # Default log file level testdir.makepyfile(''' @@ -153,6 +173,10 @@ def test_log_cli_default_level(testdir): logging.getLogger('catchlog').warning("This log message will be shown") print('PASSED') ''') + testdir.makeini(''' + [pytest] + log_cli=true + ''') result = testdir.runpytest('-s') @@ -186,6 +210,10 @@ def test_log_cli_level(testdir): logging.getLogger('catchlog').info("This log message will be shown") print('PASSED') ''') + testdir.makeini(''' + [pytest] + log_cli=true + ''') result = testdir.runpytest('-s', '--log-cli-level=INFO') @@ -230,6 +258,7 @@ def test_log_cli_ini_level(testdir): testdir.makeini( """ [pytest] + log_cli=true log_cli_level = INFO """) testdir.makepyfile(''' From 8dcd2718aa90620d9fdc872f49ba8ccbe9c9dd13 Mon Sep 17 00:00:00 2001 From: Bruno Oliveira Date: Tue, 16 Jan 2018 20:00:27 -0200 Subject: [PATCH 02/22] No longer change the level of any logger unless requested explicitly Ref: #3013 --- _pytest/logging.py | 32 +++++++++++++--------------- testing/logging/test_reporting.py | 35 ++++++++++++++++++------------- 2 files changed, 35 insertions(+), 32 deletions(-) diff --git a/_pytest/logging.py b/_pytest/logging.py index ecd50f128..88a50e22c 100644 --- a/_pytest/logging.py +++ b/_pytest/logging.py @@ -82,13 +82,14 @@ def pytest_addoption(parser): @contextmanager -def catching_logs(handler, formatter=None, level=logging.NOTSET): +def catching_logs(handler, formatter=None, level=None): """Context manager that prepares the whole logging machinery properly.""" root_logger = logging.getLogger() if formatter is not None: handler.setFormatter(formatter) - handler.setLevel(level) + if level is not None: + handler.setLevel(level) # Adding the same handler twice would confuse logging system. # Just don't do that. @@ -96,12 +97,14 @@ def catching_logs(handler, formatter=None, level=logging.NOTSET): if add_new_handler: root_logger.addHandler(handler) - orig_level = root_logger.level - root_logger.setLevel(min(orig_level, level)) + if level is not None: + orig_level = root_logger.level + root_logger.setLevel(level) try: yield handler finally: - root_logger.setLevel(orig_level) + if level is not None: + root_logger.setLevel(orig_level) if add_new_handler: root_logger.removeHandler(handler) @@ -166,14 +169,10 @@ class LogCaptureFixture(object): def set_level(self, level, logger=None): """Sets the level for capturing of logs. - By default, the level is set on the handler used to capture - logs. Specify a logger name to instead set the level of any - logger. + :param int level: the logger to level. + :param str logger: the logger to update the level. If not given, the root logger level is updated. """ - if logger is None: - logger = self.handler - else: - logger = logging.getLogger(logger) + logger = logging.getLogger(logger) logger.setLevel(level) @contextmanager @@ -259,6 +258,7 @@ class LoggingPlugin(object): self.formatter = logging.Formatter( get_option_ini(config, 'log_format'), get_option_ini(config, 'log_date_format')) + self.log_level = get_actual_log_level(config, 'log_level') if config.getini('log_cli'): log_cli_handler = logging.StreamHandler(sys.stderr) @@ -269,8 +269,7 @@ class LoggingPlugin(object): log_cli_formatter = logging.Formatter( log_cli_format, datefmt=log_cli_date_format) - log_cli_level = get_actual_log_level( - config, 'log_cli_level', 'log_level') or logging.WARNING + log_cli_level = get_actual_log_level(config, 'log_cli_level', 'log_level') self.log_cli_handler = log_cli_handler # needed for a single unittest self.live_logs_context = catching_logs(log_cli_handler, formatter=log_cli_formatter, @@ -281,8 +280,7 @@ class LoggingPlugin(object): log_file = get_option_ini(config, 'log_file') if log_file: - self.log_file_level = get_actual_log_level( - config, 'log_file_level') or logging.WARNING + self.log_file_level = get_actual_log_level(config, 'log_file_level') log_file_format = get_option_ini( config, 'log_file_format', 'log_format') @@ -303,7 +301,7 @@ class LoggingPlugin(object): def _runtest_for(self, item, when): """Implements the internals of pytest_runtest_xxx() hook.""" with catching_logs(LogCaptureHandler(), - formatter=self.formatter) as log_handler: + formatter=self.formatter, level=self.log_level) as log_handler: if not hasattr(item, 'catch_log_handlers'): item.catch_log_handlers = {} item.catch_log_handlers[when] = log_handler diff --git a/testing/logging/test_reporting.py b/testing/logging/test_reporting.py index d10967a5e..1a896514a 100644 --- a/testing/logging/test_reporting.py +++ b/testing/logging/test_reporting.py @@ -35,7 +35,7 @@ def test_messages_logged(testdir): logger.info('text going to logger') assert False ''') - result = testdir.runpytest() + result = testdir.runpytest('--log-level=INFO') assert result.ret == 1 result.stdout.fnmatch_lines(['*- Captured *log call -*', '*text going to logger*']) @@ -58,7 +58,7 @@ def test_setup_logging(testdir): logger.info('text going to logger from call') assert False ''') - result = testdir.runpytest() + result = testdir.runpytest('--log-level=INFO') assert result.ret == 1 result.stdout.fnmatch_lines(['*- Captured *log setup -*', '*text going to logger from setup*', @@ -79,7 +79,7 @@ def test_teardown_logging(testdir): logger.info('text going to logger from teardown') assert False ''') - result = testdir.runpytest() + result = testdir.runpytest('--log-level=INFO') assert result.ret == 1 result.stdout.fnmatch_lines(['*- Captured *log call -*', '*text going to logger from call*', @@ -168,9 +168,9 @@ def test_log_cli_default_level(testdir): import logging def test_log_cli(request): plugin = request.config.pluginmanager.getplugin('logging-plugin') - assert plugin.log_cli_handler.level == logging.WARNING - logging.getLogger('catchlog').info("This log message won't be shown") - logging.getLogger('catchlog').warning("This log message will be shown") + assert plugin.log_cli_handler.level == logging.NOTSET + logging.getLogger('catchlog').info("INFO message won't be shown") + logging.getLogger('catchlog').warning("WARNING message will be shown") print('PASSED') ''') testdir.makeini(''' @@ -185,15 +185,9 @@ def test_log_cli_default_level(testdir): 'test_log_cli_default_level.py PASSED', ]) result.stderr.fnmatch_lines([ - "* This log message will be shown" + '*WARNING message will be shown*', ]) - for line in result.errlines: - try: - assert "This log message won't be shown" in line - pytest.fail("A log message was shown and it shouldn't have been") - except AssertionError: - continue - + assert "INFO message won't be shown" not in result.stderr.str() # make sure that that we get a '0' exit code for the testsuite assert result.ret == 0 @@ -307,7 +301,7 @@ def test_log_file_cli(testdir): log_file = testdir.tmpdir.join('pytest.log').strpath - result = testdir.runpytest('-s', '--log-file={0}'.format(log_file)) + result = testdir.runpytest('-s', '--log-file={0}'.format(log_file), '--log-file-level=WARNING') # fnmatch_lines does an assertion internally result.stdout.fnmatch_lines([ @@ -356,6 +350,16 @@ def test_log_file_cli_level(testdir): assert "This log message won't be shown" not in contents +def test_log_level_not_changed_by_default(testdir): + testdir.makepyfile(''' + import logging + def test_log_file(): + assert logging.getLogger().level == logging.WARNING + ''') + result = testdir.runpytest('-s') + result.stdout.fnmatch_lines('* 1 passed in *') + + def test_log_file_ini(testdir): log_file = testdir.tmpdir.join('pytest.log').strpath @@ -363,6 +367,7 @@ def test_log_file_ini(testdir): """ [pytest] log_file={0} + log_file_level=WARNING """.format(log_file)) testdir.makepyfile(''' import pytest From aca1b06747a432e4a7bc3b8b3f98a2a59192c785 Mon Sep 17 00:00:00 2001 From: Bruno Oliveira Date: Tue, 16 Jan 2018 20:32:59 -0200 Subject: [PATCH 03/22] Undo log level set by caplog.set_level at the end of the test Otherwise this leaks the log level information to other tests Ref: #3013 --- _pytest/logging.py | 50 ++++++++++++++++++++++----------- testing/logging/test_fixture.py | 28 ++++++++++++++++++ 2 files changed, 61 insertions(+), 17 deletions(-) diff --git a/_pytest/logging.py b/_pytest/logging.py index 88a50e22c..1568d3f08 100644 --- a/_pytest/logging.py +++ b/_pytest/logging.py @@ -129,6 +129,17 @@ class LogCaptureFixture(object): def __init__(self, item): """Creates a new funcarg.""" self._item = item + self._initial_log_levels = {} # type: Dict[str, int] # dict of log name -> log level + + def _finalize(self): + """Finalizes the fixture. + + This restores the log levels changed by :meth:`set_level`. + """ + # restore log levels + for logger_name, level in self._initial_log_levels.items(): + logger = logging.getLogger(logger_name) + logger.setLevel(level) @property def handler(self): @@ -167,27 +178,30 @@ class LogCaptureFixture(object): self.handler.records = [] def set_level(self, level, logger=None): - """Sets the level for capturing of logs. + """Sets the level for capturing of logs. The level will be restored to its previous value at the end of + the test. + + :param int level: the logger to level. + :param str logger: the logger to update the level. If not given, the root logger level is updated. + + .. versionchanged:: 3.4 + The levels of the loggers changed by this function will be restored to their initial values at the + end of the test. + """ + logger_name = logger + logger = logging.getLogger(logger_name) + self._initial_log_levels.setdefault(logger_name, logger.level) + logger.setLevel(level) + + @contextmanager + def at_level(self, level, logger=None): + """Context manager that sets the level for capturing of logs. After the end of the 'with' statement the + level is restored to its original value. :param int level: the logger to level. :param str logger: the logger to update the level. If not given, the root logger level is updated. """ logger = logging.getLogger(logger) - logger.setLevel(level) - - @contextmanager - def at_level(self, level, logger=None): - """Context manager that sets the level for capturing of logs. - - By default, the level is set on the handler used to capture - logs. Specify a logger name to instead set the level of any - logger. - """ - if logger is None: - logger = self.handler - else: - logger = logging.getLogger(logger) - orig_level = logger.level logger.setLevel(level) try: @@ -206,7 +220,9 @@ def caplog(request): * caplog.records() -> list of logging.LogRecord instances * caplog.record_tuples() -> list of (logger_name, level, message) tuples """ - return LogCaptureFixture(request.node) + result = LogCaptureFixture(request.node) + yield result + result._finalize() def get_actual_log_level(config, *setting_names): diff --git a/testing/logging/test_fixture.py b/testing/logging/test_fixture.py index 1357dcf36..fcd231867 100644 --- a/testing/logging/test_fixture.py +++ b/testing/logging/test_fixture.py @@ -27,6 +27,30 @@ def test_change_level(caplog): assert 'CRITICAL' in caplog.text +def test_change_level_undo(testdir): + """Ensure that 'set_level' is undone after the end of the test""" + testdir.makepyfile(''' + import logging + + def test1(caplog): + caplog.set_level(logging.INFO) + # using + operator here so fnmatch_lines doesn't match the code in the traceback + logging.info('log from ' + 'test1') + assert 0 + + def test2(caplog): + # using + operator here so fnmatch_lines doesn't match the code in the traceback + logging.info('log from ' + 'test2') + assert 0 + ''') + result = testdir.runpytest_subprocess() + result.stdout.fnmatch_lines([ + '*log from test1*', + '*2 failed in *', + ]) + assert 'log from test2' not in result.stdout.str() + + def test_with_statement(caplog): with caplog.at_level(logging.INFO): logger.debug('handler DEBUG level') @@ -43,6 +67,7 @@ def test_with_statement(caplog): def test_log_access(caplog): + caplog.set_level(logging.INFO) logger.info('boo %s', 'arg') assert caplog.records[0].levelname == 'INFO' assert caplog.records[0].msg == 'boo %s' @@ -50,6 +75,7 @@ def test_log_access(caplog): def test_record_tuples(caplog): + caplog.set_level(logging.INFO) logger.info('boo %s', 'arg') assert caplog.record_tuples == [ @@ -58,6 +84,7 @@ def test_record_tuples(caplog): def test_unicode(caplog): + caplog.set_level(logging.INFO) logger.info(u'bū') assert caplog.records[0].levelname == 'INFO' assert caplog.records[0].msg == u'bū' @@ -65,6 +92,7 @@ def test_unicode(caplog): def test_clear(caplog): + caplog.set_level(logging.INFO) logger.info(u'bū') assert len(caplog.records) caplog.clear() From 8d735f3e1d3ff24ea15759c4a8abb0bc5776b811 Mon Sep 17 00:00:00 2001 From: Bruno Oliveira Date: Tue, 16 Jan 2018 20:47:27 -0200 Subject: [PATCH 04/22] Live log option now writes to the terminal reporter Ref: #3013 --- _pytest/logging.py | 45 ++++++++++++++++++------------- testing/logging/test_reporting.py | 32 ++++++++++++---------- 2 files changed, 44 insertions(+), 33 deletions(-) diff --git a/_pytest/logging.py b/_pytest/logging.py index 1568d3f08..f7b4dc383 100644 --- a/_pytest/logging.py +++ b/_pytest/logging.py @@ -2,7 +2,6 @@ from __future__ import absolute_import, division, print_function import logging from contextlib import closing, contextmanager -import sys import six import pytest @@ -270,30 +269,13 @@ class LoggingPlugin(object): The formatter can be safely shared across all handlers so create a single one for the entire test session here. """ + self._config = config self.print_logs = get_option_ini(config, 'log_print') self.formatter = logging.Formatter( get_option_ini(config, 'log_format'), get_option_ini(config, 'log_date_format')) self.log_level = get_actual_log_level(config, 'log_level') - if config.getini('log_cli'): - log_cli_handler = logging.StreamHandler(sys.stderr) - log_cli_format = get_option_ini( - config, 'log_cli_format', 'log_format') - log_cli_date_format = get_option_ini( - config, 'log_cli_date_format', 'log_date_format') - log_cli_formatter = logging.Formatter( - log_cli_format, - datefmt=log_cli_date_format) - log_cli_level = get_actual_log_level(config, 'log_cli_level', 'log_level') - self.log_cli_handler = log_cli_handler # needed for a single unittest - self.live_logs_context = catching_logs(log_cli_handler, - formatter=log_cli_formatter, - level=log_cli_level) - else: - self.log_cli_handler = None - self.live_logs_context = _dummy_context_manager() - log_file = get_option_ini(config, 'log_file') if log_file: self.log_file_level = get_actual_log_level(config, 'log_file_level') @@ -352,6 +334,7 @@ class LoggingPlugin(object): @pytest.hookimpl(hookwrapper=True) def pytest_runtestloop(self, session): """Runs all collected test items.""" + self._setup_cli_logging() with self.live_logs_context: if self.log_file_handler is not None: with closing(self.log_file_handler): @@ -360,3 +343,27 @@ class LoggingPlugin(object): yield # run all the tests else: yield # run all the tests + + def _setup_cli_logging(self): + """Setups the handler and logger for the Live Logs feature, if enabled. + + This must be done right before starting the loop so we can access the terminal reporter plugin. + """ + terminal_reporter = self._config.pluginmanager.get_plugin('terminalreporter') + if self._config.getini('log_cli') and terminal_reporter is not None: + log_cli_handler = logging.StreamHandler(terminal_reporter._tw) + log_cli_format = get_option_ini( + self._config, 'log_cli_format', 'log_format') + log_cli_date_format = get_option_ini( + self._config, 'log_cli_date_format', 'log_date_format') + log_cli_formatter = logging.Formatter( + log_cli_format, + datefmt=log_cli_date_format) + log_cli_level = get_actual_log_level(self._config, 'log_cli_level', 'log_level') + self.log_cli_handler = log_cli_handler # needed for a single unittest + self.live_logs_context = catching_logs(log_cli_handler, + formatter=log_cli_formatter, + level=log_cli_level) + else: + self.log_cli_handler = None + self.live_logs_context = _dummy_context_manager() diff --git a/testing/logging/test_reporting.py b/testing/logging/test_reporting.py index 1a896514a..24f015d09 100644 --- a/testing/logging/test_reporting.py +++ b/testing/logging/test_reporting.py @@ -156,9 +156,9 @@ def test_log_cli_enabled_disabled(testdir, enabled): ''') result = testdir.runpytest('-s') if enabled: - assert msg in result.stderr.str() + assert msg in result.stdout.str() else: - assert msg not in result.stderr.str() + assert msg not in result.stdout.str() def test_log_cli_default_level(testdir): @@ -182,12 +182,13 @@ def test_log_cli_default_level(testdir): # fnmatch_lines does an assertion internally result.stdout.fnmatch_lines([ - 'test_log_cli_default_level.py PASSED', + 'test_log_cli_default_level.py*', + 'PASSED', # 'PASSED' on its own line because the log message prints a new line ]) - result.stderr.fnmatch_lines([ + result.stdout.fnmatch_lines([ '*WARNING message will be shown*', ]) - assert "INFO message won't be shown" not in result.stderr.str() + assert "INFO message won't be shown" not in result.stdout.str() # make sure that that we get a '0' exit code for the testsuite assert result.ret == 0 @@ -213,12 +214,13 @@ def test_log_cli_level(testdir): # fnmatch_lines does an assertion internally result.stdout.fnmatch_lines([ - 'test_log_cli_level.py PASSED', + 'test_log_cli_level.py*', + 'PASSED', # 'PASSED' on its own line because the log message prints a new line ]) - result.stderr.fnmatch_lines([ + result.stdout.fnmatch_lines([ "* This log message will be shown" ]) - for line in result.errlines: + for line in result.outlines: try: assert "This log message won't be shown" in line pytest.fail("A log message was shown and it shouldn't have been") @@ -232,12 +234,13 @@ def test_log_cli_level(testdir): # fnmatch_lines does an assertion internally result.stdout.fnmatch_lines([ - 'test_log_cli_level.py PASSED', + 'test_log_cli_level.py*', + 'PASSED', # 'PASSED' on its own line because the log message prints a new line ]) - result.stderr.fnmatch_lines([ + result.stdout.fnmatch_lines([ "* This log message will be shown" ]) - for line in result.errlines: + for line in result.outlines: try: assert "This log message won't be shown" in line pytest.fail("A log message was shown and it shouldn't have been") @@ -270,12 +273,13 @@ def test_log_cli_ini_level(testdir): # fnmatch_lines does an assertion internally result.stdout.fnmatch_lines([ - 'test_log_cli_ini_level.py PASSED', + 'test_log_cli_ini_level.py*', + 'PASSED', # 'PASSED' on its own line because the log message prints a new line ]) - result.stderr.fnmatch_lines([ + result.stdout.fnmatch_lines([ "* This log message will be shown" ]) - for line in result.errlines: + for line in result.outlines: try: assert "This log message won't be shown" in line pytest.fail("A log message was shown and it shouldn't have been") From 6bb739516fe86fb3d66d04f6ad354ab37e781b66 Mon Sep 17 00:00:00 2001 From: Bruno Oliveira Date: Tue, 16 Jan 2018 21:25:39 -0200 Subject: [PATCH 05/22] Update logging docs with the new changes in 3.4 Ref: #3013 --- doc/en/logging.rst | 106 ++++++++++++++++++++++++++++++++------------- 1 file changed, 75 insertions(+), 31 deletions(-) diff --git a/doc/en/logging.rst b/doc/en/logging.rst index 9a6df8484..534ac5687 100644 --- a/doc/en/logging.rst +++ b/doc/en/logging.rst @@ -3,21 +3,8 @@ Logging ------- -.. versionadded 3.3.0 - -.. note:: - - This feature is a drop-in replacement for the `pytest-catchlog - `_ plugin and they will conflict - with each other. The backward compatibility API with ``pytest-capturelog`` - has been dropped when this feature was introduced, so if for that reason you - still need ``pytest-catchlog`` you can disable the internal feature by - adding to your ``pytest.ini``: - - .. code-block:: ini - - [pytest] - addopts=-p no:logging +.. versionadded:: 3.3 +.. versionchanged:: 3.4 Log messages are captured by default and for each failed test will be shown in the same manner as captured stdout and stderr. @@ -29,7 +16,7 @@ Running without options:: Shows failed tests like so:: ----------------------- Captured stdlog call ---------------------- - test_reporting.py 26 INFO text going to logger + test_reporting.py 26 WARNING text going to logger ----------------------- Captured stdout call ---------------------- text going to stdout ----------------------- Captured stderr call ---------------------- @@ -49,7 +36,7 @@ Running pytest specifying formatting options:: Shows failed tests like so:: ----------------------- Captured stdlog call ---------------------- - 2010-04-10 14:48:44 INFO text going to logger + 2010-04-10 14:48:44 WARNING text going to logger ----------------------- Captured stdout call ---------------------- text going to stdout ----------------------- Captured stderr call ---------------------- @@ -92,7 +79,7 @@ messages. This is supported by the ``caplog`` fixture:: caplog.set_level(logging.INFO) pass -By default the level is set on the handler used to catch the log messages, +By default the level is set on the root logger, however as a convenience it is also possible to set the log level of any logger:: @@ -100,14 +87,16 @@ logger:: caplog.set_level(logging.CRITICAL, logger='root.baz') pass +The log levels set are restored automatically at the end of the test. + It is also possible to use a context manager to temporarily change the log -level:: +level inside a ``with`` block:: def test_bar(caplog): with caplog.at_level(logging.INFO): pass -Again, by default the level of the handler is affected but the level of any +Again, by default the level of the root logger is affected but the level of any logger can be changed instead with:: def test_bar(caplog): @@ -115,7 +104,7 @@ logger can be changed instead with:: pass Lastly all the logs sent to the logger during the test run are made available on -the fixture in the form of both the LogRecord instances and the final log text. +the fixture in the form of both the ``logging.LogRecord`` instances and the final log text. This is useful for when you want to assert on the contents of a message:: def test_baz(caplog): @@ -146,12 +135,31 @@ You can call ``caplog.clear()`` to reset the captured log records in a test:: your_test_method() assert ['Foo'] == [rec.message for rec in caplog.records] + +Accessing logs from other test stages +^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ + +The ``caplop.records`` fixture contains records from the current stage only. So +inside the setup phase it contains only setup logs, same with the call and +teardown phases. To access logs from other stages you can use +``caplog.get_handler('setup').records``. Valid stages are ``setup``, ``call`` +and ``teardown``. + + +.. _live_logs: + + +caplog fixture API +^^^^^^^^^^^^^^^^^^ + +.. autoclass:: _pytest.logging.LogCaptureFixture + :members: + Live Logs ^^^^^^^^^ -By default, pytest will output any logging records with a level higher or -equal to WARNING. In order to actually see these logs in the console you have to -disable pytest output capture by passing ``-s``. +By setting the :confval:`log_cli` configuration option to ``true``, pytest will output +logging records as they are emitted directly into the console. You can specify the logging level for which log records with equal or higher level are printed to the console by passing ``--log-cli-level``. This setting @@ -191,11 +199,47 @@ option names are: * ``log_file_format`` * ``log_file_date_format`` -Accessing logs from other test stages -^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ +.. _log_release_notes: -The ``caplop.records`` fixture contains records from the current stage only. So -inside the setup phase it contains only setup logs, same with the call and -teardown phases. To access logs from other stages you can use -``caplog.get_handler('setup').records``. Valid stages are ``setup``, ``call`` -and ``teardown``. +Release notes +^^^^^^^^^^^^^ + +This feature was introduced as a drop-in replacement for the `pytest-catchlog +`_ plugin and they conflict +with each other. The backward compatibility API with ``pytest-capturelog`` +has been dropped when this feature was introduced, so if for that reason you +still need ``pytest-catchlog`` you can disable the internal feature by +adding to your ``pytest.ini``: + +.. code-block:: ini + + [pytest] + addopts=-p no:logging + + +.. _log_changes_3_4: + +Incompatible changes in pytest 3.4 +^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ + +This feature was introduced in ``3.3`` and some **incompatible changes** have been +made in ``3.4`` after community feedback: + +* Log levels are no longer changed unless explicitly requested by the :confval:`log_level` configuration + or ``--log-level`` command-line options. This allows users to configure logger objects themselves. +* :ref:`Live Logs ` is now disabled by default and can be enabled setting the + :confval:`log_cli` configuration option to ``true``. +* :ref:`Live Logs ` are now sent to ``sys.stdout`` and no longer require the ``-s`` command-line option + to work. + +If you want to partially restore the logging behavior of version ``3.3``, you can add this options to your ``ini`` +file: + +.. code-block:: ini + + [pytest] + log_cli=true + log_level=NOTSET + +More details about the discussion that lead to this changes can be read in +issue `#3013 `_. From c53b72fd7b05793b091eb334de1224f15278993b Mon Sep 17 00:00:00 2001 From: Bruno Oliveira Date: Tue, 16 Jan 2018 21:25:51 -0200 Subject: [PATCH 06/22] Add CHANGELOG for 3013 --- changelog/3013.feature | 1 + 1 file changed, 1 insertion(+) create mode 100644 changelog/3013.feature diff --git a/changelog/3013.feature b/changelog/3013.feature new file mode 100644 index 000000000..b690961db --- /dev/null +++ b/changelog/3013.feature @@ -0,0 +1 @@ +**Incompatible change**: after community feedback the `logging `_ functionality has undergone some changes. Please consult the `logging documentation `_ for details. From 5d89a939779a0aafdf99dd9f5e60ec306a53cddd Mon Sep 17 00:00:00 2001 From: Bruno Oliveira Date: Wed, 17 Jan 2018 18:00:52 -0200 Subject: [PATCH 07/22] Small improvements to tests suggested during review --- _pytest/logging.py | 1 + testing/logging/test_reporting.py | 24 +++++------------------- 2 files changed, 6 insertions(+), 19 deletions(-) diff --git a/_pytest/logging.py b/_pytest/logging.py index f7b4dc383..8d6208f1a 100644 --- a/_pytest/logging.py +++ b/_pytest/logging.py @@ -189,6 +189,7 @@ class LogCaptureFixture(object): """ logger_name = logger logger = logging.getLogger(logger_name) + # save the original log-level to restore it during teardown self._initial_log_levels.setdefault(logger_name, logger.level) logger.setLevel(level) diff --git a/testing/logging/test_reporting.py b/testing/logging/test_reporting.py index 24f015d09..044088e1e 100644 --- a/testing/logging/test_reporting.py +++ b/testing/logging/test_reporting.py @@ -171,22 +171,17 @@ def test_log_cli_default_level(testdir): assert plugin.log_cli_handler.level == logging.NOTSET logging.getLogger('catchlog').info("INFO message won't be shown") logging.getLogger('catchlog').warning("WARNING message will be shown") - print('PASSED') ''') testdir.makeini(''' [pytest] log_cli=true ''') - result = testdir.runpytest('-s') + result = testdir.runpytest() # fnmatch_lines does an assertion internally result.stdout.fnmatch_lines([ - 'test_log_cli_default_level.py*', - 'PASSED', # 'PASSED' on its own line because the log message prints a new line - ]) - result.stdout.fnmatch_lines([ - '*WARNING message will be shown*', + 'test_log_cli_default_level.py*WARNING message will be shown*', ]) assert "INFO message won't be shown" not in result.stdout.str() # make sure that that we get a '0' exit code for the testsuite @@ -214,12 +209,9 @@ def test_log_cli_level(testdir): # fnmatch_lines does an assertion internally result.stdout.fnmatch_lines([ - 'test_log_cli_level.py*', + 'test_log_cli_level.py*This log message will be shown', 'PASSED', # 'PASSED' on its own line because the log message prints a new line ]) - result.stdout.fnmatch_lines([ - "* This log message will be shown" - ]) for line in result.outlines: try: assert "This log message won't be shown" in line @@ -234,12 +226,9 @@ def test_log_cli_level(testdir): # fnmatch_lines does an assertion internally result.stdout.fnmatch_lines([ - 'test_log_cli_level.py*', + 'test_log_cli_level.py* This log message will be shown', 'PASSED', # 'PASSED' on its own line because the log message prints a new line ]) - result.stdout.fnmatch_lines([ - "* This log message will be shown" - ]) for line in result.outlines: try: assert "This log message won't be shown" in line @@ -273,12 +262,9 @@ def test_log_cli_ini_level(testdir): # fnmatch_lines does an assertion internally result.stdout.fnmatch_lines([ - 'test_log_cli_ini_level.py*', + 'test_log_cli_ini_level.py* This log message will be shown', 'PASSED', # 'PASSED' on its own line because the log message prints a new line ]) - result.stdout.fnmatch_lines([ - "* This log message will be shown" - ]) for line in result.outlines: try: assert "This log message won't be shown" in line From 8f6a5928f76f37323ea9cabf1c58472c3f1ac400 Mon Sep 17 00:00:00 2001 From: Bruno Oliveira Date: Wed, 17 Jan 2018 18:38:30 -0200 Subject: [PATCH 08/22] Add newline before log messages and enable -v output when log_cli is enabled --- _pytest/logging.py | 24 +++++++++++++++++++++++- doc/en/logging.rst | 3 ++- testing/logging/test_reporting.py | 7 ++++++- 3 files changed, 31 insertions(+), 3 deletions(-) diff --git a/_pytest/logging.py b/_pytest/logging.py index 8d6208f1a..5633e4ffc 100644 --- a/_pytest/logging.py +++ b/_pytest/logging.py @@ -271,6 +271,13 @@ class LoggingPlugin(object): create a single one for the entire test session here. """ self._config = config + + # enable verbose output automatically if live logging is enabled + if self._config.getini('log_cli') and not config.getoption('verbose'): + # sanity check: terminal reporter should not have been loaded at this point + assert self._config.pluginmanager.get_plugin('terminalreporter') is None + config.option.verbose = 1 + self.print_logs = get_option_ini(config, 'log_print') self.formatter = logging.Formatter( get_option_ini(config, 'log_format'), @@ -352,7 +359,7 @@ class LoggingPlugin(object): """ terminal_reporter = self._config.pluginmanager.get_plugin('terminalreporter') if self._config.getini('log_cli') and terminal_reporter is not None: - log_cli_handler = logging.StreamHandler(terminal_reporter._tw) + log_cli_handler = _LiveLoggingStreamHandler(terminal_reporter._tw) log_cli_format = get_option_ini( self._config, 'log_cli_format', 'log_format') log_cli_date_format = get_option_ini( @@ -368,3 +375,18 @@ class LoggingPlugin(object): else: self.log_cli_handler = None self.live_logs_context = _dummy_context_manager() + + +class _LiveLoggingStreamHandler(logging.StreamHandler): + """ + Custom StreamHandler used by the live logging feature: it will write a newline before the first log message + in each test. + """ + + def emit(self, record): + if not getattr(self, '_first_record_emitted', False): + self.stream.write('\n') + # we might consider adding a header at this point using self.stream.sep('-', 'live log') or something + # similar when we improve live logging output + self._first_record_emitted = True + logging.StreamHandler.emit(self, record) diff --git a/doc/en/logging.rst b/doc/en/logging.rst index 534ac5687..9fdc6ffe5 100644 --- a/doc/en/logging.rst +++ b/doc/en/logging.rst @@ -228,7 +228,8 @@ made in ``3.4`` after community feedback: * Log levels are no longer changed unless explicitly requested by the :confval:`log_level` configuration or ``--log-level`` command-line options. This allows users to configure logger objects themselves. * :ref:`Live Logs ` is now disabled by default and can be enabled setting the - :confval:`log_cli` configuration option to ``true``. + :confval:`log_cli` configuration option to ``true``. When enabled, the verbosity is increased so logging for each + test is visible. * :ref:`Live Logs ` are now sent to ``sys.stdout`` and no longer require the ``-s`` command-line option to work. diff --git a/testing/logging/test_reporting.py b/testing/logging/test_reporting.py index 044088e1e..9bfda325a 100644 --- a/testing/logging/test_reporting.py +++ b/testing/logging/test_reporting.py @@ -156,7 +156,11 @@ def test_log_cli_enabled_disabled(testdir, enabled): ''') result = testdir.runpytest('-s') if enabled: - assert msg in result.stdout.str() + result.stdout.fnmatch_lines([ + 'test_log_cli_enabled_disabled.py::test_log_cli ', + 'test_log_cli_enabled_disabled.py* CRITICAL critical message logged by test', + 'PASSED', + ]) else: assert msg not in result.stdout.str() @@ -181,6 +185,7 @@ def test_log_cli_default_level(testdir): # fnmatch_lines does an assertion internally result.stdout.fnmatch_lines([ + 'test_log_cli_default_level.py::test_log_cli ', 'test_log_cli_default_level.py*WARNING message will be shown*', ]) assert "INFO message won't be shown" not in result.stdout.str() From 97a4967b036fdbf71ad30cf6505cf459b40d8a78 Mon Sep 17 00:00:00 2001 From: Bruno Oliveira Date: Wed, 17 Jan 2018 18:40:02 -0200 Subject: [PATCH 09/22] Improve code formatting --- _pytest/logging.py | 35 +++++++++++------------------------ 1 file changed, 11 insertions(+), 24 deletions(-) diff --git a/_pytest/logging.py b/_pytest/logging.py index 5633e4ffc..9e806e106 100644 --- a/_pytest/logging.py +++ b/_pytest/logging.py @@ -279,26 +279,19 @@ class LoggingPlugin(object): config.option.verbose = 1 self.print_logs = get_option_ini(config, 'log_print') - self.formatter = logging.Formatter( - get_option_ini(config, 'log_format'), - get_option_ini(config, 'log_date_format')) + self.formatter = logging.Formatter(get_option_ini(config, 'log_format'), + get_option_ini(config, 'log_date_format')) self.log_level = get_actual_log_level(config, 'log_level') log_file = get_option_ini(config, 'log_file') if log_file: self.log_file_level = get_actual_log_level(config, 'log_file_level') - 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_handler = logging.FileHandler( - log_file, - # Each pytest runtests session will write to a clean logfile - mode='w') - log_file_formatter = logging.Formatter( - log_file_format, - datefmt=log_file_date_format) + 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') + # Each pytest runtests session will write to a clean logfile + self.log_file_handler = logging.FileHandler(log_file, mode='w') + log_file_formatter = logging.Formatter(log_file_format, datefmt=log_file_date_format) self.log_file_handler.setFormatter(log_file_formatter) else: self.log_file_handler = None @@ -360,18 +353,12 @@ class LoggingPlugin(object): terminal_reporter = self._config.pluginmanager.get_plugin('terminalreporter') if self._config.getini('log_cli') and terminal_reporter is not None: log_cli_handler = _LiveLoggingStreamHandler(terminal_reporter._tw) - log_cli_format = get_option_ini( - self._config, 'log_cli_format', 'log_format') - log_cli_date_format = get_option_ini( - self._config, 'log_cli_date_format', 'log_date_format') - log_cli_formatter = logging.Formatter( - log_cli_format, - datefmt=log_cli_date_format) + log_cli_format = get_option_ini(self._config, 'log_cli_format', 'log_format') + log_cli_date_format = get_option_ini(self._config, 'log_cli_date_format', 'log_date_format') + log_cli_formatter = logging.Formatter(log_cli_format, datefmt=log_cli_date_format) log_cli_level = get_actual_log_level(self._config, 'log_cli_level', 'log_level') self.log_cli_handler = log_cli_handler # needed for a single unittest - self.live_logs_context = catching_logs(log_cli_handler, - formatter=log_cli_formatter, - level=log_cli_level) + self.live_logs_context = catching_logs(log_cli_handler, formatter=log_cli_formatter, level=log_cli_level) else: self.log_cli_handler = None self.live_logs_context = _dummy_context_manager() From 4a436572a85c9f13fba9f242f87b456f54349a32 Mon Sep 17 00:00:00 2001 From: Bruno Oliveira Date: Wed, 17 Jan 2018 18:41:20 -0200 Subject: [PATCH 10/22] Simplify test assertions a bit --- testing/logging/test_reporting.py | 21 +++------------------ 1 file changed, 3 insertions(+), 18 deletions(-) diff --git a/testing/logging/test_reporting.py b/testing/logging/test_reporting.py index 9bfda325a..c34d5f7dc 100644 --- a/testing/logging/test_reporting.py +++ b/testing/logging/test_reporting.py @@ -217,12 +217,7 @@ def test_log_cli_level(testdir): 'test_log_cli_level.py*This log message will be shown', 'PASSED', # 'PASSED' on its own line because the log message prints a new line ]) - for line in result.outlines: - try: - assert "This log message won't be shown" in line - pytest.fail("A log message was shown and it shouldn't have been") - except AssertionError: - continue + assert "This log message won't be shown" not in result.stdout.str() # make sure that that we get a '0' exit code for the testsuite assert result.ret == 0 @@ -234,12 +229,7 @@ def test_log_cli_level(testdir): 'test_log_cli_level.py* This log message will be shown', 'PASSED', # 'PASSED' on its own line because the log message prints a new line ]) - for line in result.outlines: - try: - assert "This log message won't be shown" in line - pytest.fail("A log message was shown and it shouldn't have been") - except AssertionError: - continue + assert "This log message won't be shown" not in result.stdout.str() # make sure that that we get a '0' exit code for the testsuite assert result.ret == 0 @@ -270,12 +260,7 @@ def test_log_cli_ini_level(testdir): 'test_log_cli_ini_level.py* This log message will be shown', 'PASSED', # 'PASSED' on its own line because the log message prints a new line ]) - for line in result.outlines: - try: - assert "This log message won't be shown" in line - pytest.fail("A log message was shown and it shouldn't have been") - except AssertionError: - continue + assert "This log message won't be shown" not in result.stdout.str() # make sure that that we get a '0' exit code for the testsuite assert result.ret == 0 From 9dbcac9af39a032e9ea224d6979a859568b277fd Mon Sep 17 00:00:00 2001 From: Bruno Oliveira Date: Thu, 18 Jan 2018 21:10:35 -0200 Subject: [PATCH 11/22] Suspend stdout/stderr capturing when emitting live logging messages --- _pytest/logging.py | 40 ++++++++++++--- testing/logging/test_reporting.py | 85 +++++++++++++++++++++++++++++++ 2 files changed, 117 insertions(+), 8 deletions(-) diff --git a/_pytest/logging.py b/_pytest/logging.py index 9e806e106..254740188 100644 --- a/_pytest/logging.py +++ b/_pytest/logging.py @@ -319,6 +319,8 @@ class LoggingPlugin(object): @pytest.hookimpl(hookwrapper=True) def pytest_runtest_setup(self, item): + if self.log_cli_handler is not None: + self.log_cli_handler.reset() with self._runtest_for(item, 'setup'): yield @@ -352,12 +354,13 @@ class LoggingPlugin(object): """ terminal_reporter = self._config.pluginmanager.get_plugin('terminalreporter') if self._config.getini('log_cli') and terminal_reporter is not None: - log_cli_handler = _LiveLoggingStreamHandler(terminal_reporter._tw) + capture_manager = self._config.pluginmanager.get_plugin('capturemanager') + log_cli_handler = _LiveLoggingStreamHandler(terminal_reporter, capture_manager) log_cli_format = get_option_ini(self._config, 'log_cli_format', 'log_format') log_cli_date_format = get_option_ini(self._config, 'log_cli_date_format', 'log_date_format') log_cli_formatter = logging.Formatter(log_cli_format, datefmt=log_cli_date_format) log_cli_level = get_actual_log_level(self._config, 'log_cli_level', 'log_level') - self.log_cli_handler = log_cli_handler # needed for a single unittest + self.log_cli_handler = log_cli_handler self.live_logs_context = catching_logs(log_cli_handler, formatter=log_cli_formatter, level=log_cli_level) else: self.log_cli_handler = None @@ -368,12 +371,33 @@ class _LiveLoggingStreamHandler(logging.StreamHandler): """ Custom StreamHandler used by the live logging feature: it will write a newline before the first log message in each test. + + During live logging we must also explicitly disable stdout/stderr capturing otherwise it will get captured + and won't appear in the terminal. """ + def __init__(self, terminal_reporter, capture_manager): + """ + :param _pytest.terminal.TerminalReporter terminal_reporter: + :param _pytest.capture.CaptureManager capture_manager: + """ + logging.StreamHandler.__init__(self, stream=terminal_reporter) + self.capture_manager = capture_manager + self._first_record_emitted = False + + def reset(self): + self._first_record_emitted = False + def emit(self, record): - if not getattr(self, '_first_record_emitted', False): - self.stream.write('\n') - # we might consider adding a header at this point using self.stream.sep('-', 'live log') or something - # similar when we improve live logging output - self._first_record_emitted = True - logging.StreamHandler.emit(self, record) + if self.capture_manager is not None: + self.capture_manager.suspend_global_capture() + try: + if not self._first_record_emitted: + self.stream.write('\n') + # we might consider adding a header at this point using self.stream.section('live log', sep='-') + # or something similar when we improve live logging output + self._first_record_emitted = True + logging.StreamHandler.emit(self, record) + finally: + if self.capture_manager is not None: + self.capture_manager.resume_global_capture() diff --git a/testing/logging/test_reporting.py b/testing/logging/test_reporting.py index c34d5f7dc..0bd017057 100644 --- a/testing/logging/test_reporting.py +++ b/testing/logging/test_reporting.py @@ -1,5 +1,8 @@ # -*- coding: utf-8 -*- import os + +import six + import pytest @@ -193,6 +196,36 @@ def test_log_cli_default_level(testdir): assert result.ret == 0 +def test_log_cli_default_level_multiple_tests(testdir): + """Ensure we reset the first newline added by the live logger between tests""" + # Default log file level + testdir.makepyfile(''' + import pytest + import logging + + def test_log_1(request): + logging.warning("log message from test_log_1") + + def test_log_2(request): + logging.warning("log message from test_log_2") + ''') + testdir.makeini(''' + [pytest] + log_cli=true + ''') + + result = testdir.runpytest() + result.stdout.fnmatch_lines([ + 'test_log_cli_default_level_multiple_tests.py::test_log_1 ', + '*WARNING*log message from test_log_1*', + 'PASSED *50%*', + 'test_log_cli_default_level_multiple_tests.py::test_log_2 ', + '*WARNING*log message from test_log_2*', + 'PASSED *100%*', + '=* 2 passed in *=', + ]) + + def test_log_cli_level(testdir): # Default log file level testdir.makepyfile(''' @@ -410,3 +443,55 @@ def test_log_file_ini_level(testdir): contents = rfh.read() assert "This log message will be shown" in contents assert "This log message won't be shown" not in contents + + +@pytest.mark.parametrize('has_capture_manager', [True, False]) +def test_live_logging_suspends_capture(has_capture_manager, request): + """Test that capture manager is suspended when we emitting messages for live logging. + + This tests the implementation calls instead of behavior because it is difficult/impossible to do it using + ``testdir`` facilities because they do their own capturing. + + We parametrize the test to also make sure _LiveLoggingStreamHandler works correctly if no capture manager plugin + is installed. + """ + import logging + from functools import partial + from _pytest.capture import CaptureManager + from _pytest.logging import _LiveLoggingStreamHandler + + if six.PY2: + # need to use the 'generic' StringIO instead of io.StringIO because we might receive both bytes + # and unicode objects; io.StringIO only accepts unicode + from StringIO import StringIO + else: + from io import StringIO + + class MockCaptureManager: + calls = [] + + def suspend_global_capture(self): + self.calls.append('suspend_global_capture') + + def resume_global_capture(self): + self.calls.append('resume_global_capture') + + # sanity check + assert CaptureManager.suspend_capture_item + assert CaptureManager.resume_global_capture + + capture_manager = MockCaptureManager() if has_capture_manager else None + out_file = StringIO() + + handler = _LiveLoggingStreamHandler(out_file, capture_manager) + + logger = logging.getLogger(__file__ + '.test_live_logging_suspends_capture') + logger.addHandler(handler) + request.addfinalizer(partial(logger.removeHandler, handler)) + + logger.critical('some message') + if has_capture_manager: + assert MockCaptureManager.calls == ['suspend_global_capture', 'resume_global_capture'] + else: + assert MockCaptureManager.calls == [] + assert out_file.getvalue() == '\nsome message\n' From 18e053546c6798dc801956433087cafde9986121 Mon Sep 17 00:00:00 2001 From: Bruno Oliveira Date: Sat, 20 Jan 2018 11:59:23 -0200 Subject: [PATCH 12/22] Use six.StringIO and __name__ in test_live_logging_suspends_capture --- testing/logging/test_reporting.py | 11 ++--------- 1 file changed, 2 insertions(+), 9 deletions(-) diff --git a/testing/logging/test_reporting.py b/testing/logging/test_reporting.py index 0bd017057..4f605209c 100644 --- a/testing/logging/test_reporting.py +++ b/testing/logging/test_reporting.py @@ -460,13 +460,6 @@ def test_live_logging_suspends_capture(has_capture_manager, request): from _pytest.capture import CaptureManager from _pytest.logging import _LiveLoggingStreamHandler - if six.PY2: - # need to use the 'generic' StringIO instead of io.StringIO because we might receive both bytes - # and unicode objects; io.StringIO only accepts unicode - from StringIO import StringIO - else: - from io import StringIO - class MockCaptureManager: calls = [] @@ -481,11 +474,11 @@ def test_live_logging_suspends_capture(has_capture_manager, request): assert CaptureManager.resume_global_capture capture_manager = MockCaptureManager() if has_capture_manager else None - out_file = StringIO() + out_file = six.StringIO() handler = _LiveLoggingStreamHandler(out_file, capture_manager) - logger = logging.getLogger(__file__ + '.test_live_logging_suspends_capture') + logger = logging.getLogger(__name__ + '.test_live_logging_suspends_capture') logger.addHandler(handler) request.addfinalizer(partial(logger.removeHandler, handler)) From 2e40a8b3ca520fbb53cdb0a6239a0d03c8fd27bc Mon Sep 17 00:00:00 2001 From: Bruno Oliveira Date: Sat, 20 Jan 2018 12:04:28 -0200 Subject: [PATCH 13/22] Fix test_caplog_captures_for_all_stages by setting log level --- testing/logging/test_fixture.py | 1 + 1 file changed, 1 insertion(+) diff --git a/testing/logging/test_fixture.py b/testing/logging/test_fixture.py index fcd231867..68953a257 100644 --- a/testing/logging/test_fixture.py +++ b/testing/logging/test_fixture.py @@ -101,6 +101,7 @@ def test_clear(caplog): @pytest.fixture def logging_during_setup_and_teardown(caplog): + caplog.set_level('INFO') logger.info('a_setup_log') yield logger.info('a_teardown_log') From 27ae270159dc027ba6622ca43be3681204e84e2b Mon Sep 17 00:00:00 2001 From: Bruno Oliveira Date: Sat, 20 Jan 2018 12:08:51 -0200 Subject: [PATCH 14/22] Mention in docs that log messages of level WARNING or above are captured --- doc/en/logging.rst | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/doc/en/logging.rst b/doc/en/logging.rst index 9fdc6ffe5..98b80453a 100644 --- a/doc/en/logging.rst +++ b/doc/en/logging.rst @@ -6,8 +6,8 @@ Logging .. versionadded:: 3.3 .. versionchanged:: 3.4 -Log messages are captured by default and for each failed test will be shown in -the same manner as captured stdout and stderr. +Pytest captures log messages of level ``WARNING`` or above automatically and displays them in their own section +for each failed test in the same manner as captured stdout and stderr. Running without options:: From 29a7b5e064d57f510dba92861e7977eb4a7cbb22 Mon Sep 17 00:00:00 2001 From: Bruno Oliveira Date: Sat, 20 Jan 2018 14:19:45 -0200 Subject: [PATCH 15/22] Initialize log_cli_handler to None during LoggingPlugin init Some of testdir's functionality bypasses pytest_runtestloop so this attribute needs to be set early --- _pytest/logging.py | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/_pytest/logging.py b/_pytest/logging.py index 254740188..8086ea386 100644 --- a/_pytest/logging.py +++ b/_pytest/logging.py @@ -296,6 +296,9 @@ class LoggingPlugin(object): else: self.log_file_handler = None + # initialized during pytest_runtestloop + self.log_cli_handler = None + @contextmanager def _runtest_for(self, item, when): """Implements the internals of pytest_runtest_xxx() hook.""" @@ -363,7 +366,6 @@ class LoggingPlugin(object): self.log_cli_handler = log_cli_handler self.live_logs_context = catching_logs(log_cli_handler, formatter=log_cli_formatter, level=log_cli_level) else: - self.log_cli_handler = None self.live_logs_context = _dummy_context_manager() From 0df42b44265b7b03dd897f1f3ddc33018acf0957 Mon Sep 17 00:00:00 2001 From: Bruno Oliveira Date: Mon, 22 Jan 2018 21:00:52 -0200 Subject: [PATCH 16/22] Show a header for each testing phase during live logging As suggested during review --- _pytest/logging.py | 24 ++++++++--- testing/logging/test_reporting.py | 72 +++++++++++++++++++++++++++---- 2 files changed, 80 insertions(+), 16 deletions(-) diff --git a/_pytest/logging.py b/_pytest/logging.py index 8086ea386..9b290c390 100644 --- a/_pytest/logging.py +++ b/_pytest/logging.py @@ -304,6 +304,8 @@ class LoggingPlugin(object): """Implements the internals of pytest_runtest_xxx() hook.""" with catching_logs(LogCaptureHandler(), formatter=self.formatter, level=self.log_level) as log_handler: + if self.log_cli_handler: + self.log_cli_handler.reset(item, when) if not hasattr(item, 'catch_log_handlers'): item.catch_log_handlers = {} item.catch_log_handlers[when] = log_handler @@ -322,8 +324,6 @@ class LoggingPlugin(object): @pytest.hookimpl(hookwrapper=True) def pytest_runtest_setup(self, item): - if self.log_cli_handler is not None: - self.log_cli_handler.reset() with self._runtest_for(item, 'setup'): yield @@ -387,18 +387,28 @@ class _LiveLoggingStreamHandler(logging.StreamHandler): self.capture_manager = capture_manager self._first_record_emitted = False - def reset(self): - self._first_record_emitted = False + self._section_name_shown = False + self._when = None + self._run_tests = set() + + def reset(self, item, when): + self._when = when + self._section_name_shown = False + if item.name not in self._run_tests: + self._first_record_emitted = False + self._run_tests.add(item.name) def emit(self, record): if self.capture_manager is not None: self.capture_manager.suspend_global_capture() try: - if not self._first_record_emitted: + if not self._first_record_emitted or self._when == 'teardown': self.stream.write('\n') - # we might consider adding a header at this point using self.stream.section('live log', sep='-') - # or something similar when we improve live logging output self._first_record_emitted = True + if not self._section_name_shown: + header = 'live log' if self._when == 'call' else 'live log ' + self._when + self.stream.section(header, sep='-', bold=True) + self._section_name_shown = True logging.StreamHandler.emit(self, record) finally: if self.capture_manager is not None: diff --git a/testing/logging/test_reporting.py b/testing/logging/test_reporting.py index 4f605209c..492723ff6 100644 --- a/testing/logging/test_reporting.py +++ b/testing/logging/test_reporting.py @@ -196,17 +196,16 @@ def test_log_cli_default_level(testdir): assert result.ret == 0 -def test_log_cli_default_level_multiple_tests(testdir): +def test_log_cli_default_level_multiple_tests(testdir, request): """Ensure we reset the first newline added by the live logger between tests""" - # Default log file level + filename = request.node.name + '.py' testdir.makepyfile(''' - import pytest import logging - def test_log_1(request): + def test_log_1(): logging.warning("log message from test_log_1") - def test_log_2(request): + def test_log_2(): logging.warning("log message from test_log_2") ''') testdir.makeini(''' @@ -216,16 +215,63 @@ def test_log_cli_default_level_multiple_tests(testdir): result = testdir.runpytest() result.stdout.fnmatch_lines([ - 'test_log_cli_default_level_multiple_tests.py::test_log_1 ', + '{}::test_log_1 '.format(filename), '*WARNING*log message from test_log_1*', 'PASSED *50%*', - 'test_log_cli_default_level_multiple_tests.py::test_log_2 ', + '{}::test_log_2 '.format(filename), '*WARNING*log message from test_log_2*', 'PASSED *100%*', '=* 2 passed in *=', ]) +def test_log_cli_default_level_sections(testdir, request): + """Check that with live logging enable we are printing the correct headers during setup/call/teardown.""" + filename = request.node.name + '.py' + testdir.makepyfile(''' + import pytest + import logging + + @pytest.fixture + def fix(request): + logging.warning("log message from setup of {}".format(request.node.name)) + yield + logging.warning("log message from teardown of {}".format(request.node.name)) + + def test_log_1(fix): + logging.warning("log message from test_log_1") + + def test_log_2(fix): + logging.warning("log message from test_log_2") + ''') + testdir.makeini(''' + [pytest] + log_cli=true + ''') + + result = testdir.runpytest() + result.stdout.fnmatch_lines([ + '{}::test_log_1 '.format(filename), + '*-- live log setup --*', + '*WARNING*log message from setup of test_log_1*', + '*-- live log --*', + '*WARNING*log message from test_log_1*', + 'PASSED *50%*', + '*-- live log teardown --*', + '*WARNING*log message from teardown of test_log_1*', + + '{}::test_log_2 '.format(filename), + '*-- live log setup --*', + '*WARNING*log message from setup of test_log_2*', + '*-- live log --*', + '*WARNING*log message from test_log_2*', + 'PASSED *100%*', + '*-- live log teardown --*', + '*WARNING*log message from teardown of test_log_2*', + '=* 2 passed in *=', + ]) + + def test_log_cli_level(testdir): # Default log file level testdir.makepyfile(''' @@ -473,11 +519,19 @@ def test_live_logging_suspends_capture(has_capture_manager, request): assert CaptureManager.suspend_capture_item assert CaptureManager.resume_global_capture - capture_manager = MockCaptureManager() if has_capture_manager else None - out_file = six.StringIO() + class DummyTerminal(six.StringIO): + def section(self, *args, **kwargs): + pass + + out_file = DummyTerminal() + capture_manager = MockCaptureManager() if has_capture_manager else None handler = _LiveLoggingStreamHandler(out_file, capture_manager) + class DummyItem: + name = 'test_foo' + handler.reset(DummyItem(), 'call') + logger = logging.getLogger(__name__ + '.test_live_logging_suspends_capture') logger.addHandler(handler) request.addfinalizer(partial(logger.removeHandler, handler)) From 3a9d0b26d5700be58bde067e6d8d4ca2e80406de Mon Sep 17 00:00:00 2001 From: Bruno Oliveira Date: Mon, 22 Jan 2018 21:20:48 -0200 Subject: [PATCH 17/22] Use pytest_runtest_logstart to signal the start of a new test This also simplifies the code a bit because we don't need to keep a set of ids anymore --- _pytest/logging.py | 21 ++++++++++++--------- testing/logging/test_reporting.py | 5 +---- 2 files changed, 13 insertions(+), 13 deletions(-) diff --git a/_pytest/logging.py b/_pytest/logging.py index 9b290c390..46d447326 100644 --- a/_pytest/logging.py +++ b/_pytest/logging.py @@ -305,7 +305,7 @@ class LoggingPlugin(object): with catching_logs(LogCaptureHandler(), formatter=self.formatter, level=self.log_level) as log_handler: if self.log_cli_handler: - self.log_cli_handler.reset(item, when) + self.log_cli_handler.set_when(when) if not hasattr(item, 'catch_log_handlers'): item.catch_log_handlers = {} item.catch_log_handlers[when] = log_handler @@ -337,6 +337,10 @@ class LoggingPlugin(object): with self._runtest_for(item, 'teardown'): yield + def pytest_runtest_logstart(self): + if self.log_cli_handler: + self.log_cli_handler.reset() + @pytest.hookimpl(hookwrapper=True) def pytest_runtestloop(self, session): """Runs all collected test items.""" @@ -385,18 +389,17 @@ class _LiveLoggingStreamHandler(logging.StreamHandler): """ logging.StreamHandler.__init__(self, stream=terminal_reporter) self.capture_manager = capture_manager + self.reset() + self.set_when(None) + + def reset(self): + """Reset the handler; should be called before the start of each test""" self._first_record_emitted = False - self._section_name_shown = False - self._when = None - self._run_tests = set() - - def reset(self, item, when): + def set_when(self, when): + """Prepares for the given test phase (setup/call/teardown)""" self._when = when self._section_name_shown = False - if item.name not in self._run_tests: - self._first_record_emitted = False - self._run_tests.add(item.name) def emit(self, record): if self.capture_manager is not None: diff --git a/testing/logging/test_reporting.py b/testing/logging/test_reporting.py index 492723ff6..ea3c5835f 100644 --- a/testing/logging/test_reporting.py +++ b/testing/logging/test_reporting.py @@ -527,10 +527,7 @@ def test_live_logging_suspends_capture(has_capture_manager, request): out_file = DummyTerminal() capture_manager = MockCaptureManager() if has_capture_manager else None handler = _LiveLoggingStreamHandler(out_file, capture_manager) - - class DummyItem: - name = 'test_foo' - handler.reset(DummyItem(), 'call') + handler.set_when('call') logger = logging.getLogger(__name__ + '.test_live_logging_suspends_capture') logger.addHandler(handler) From 9f4688e549cb2688f667ff951f9f28a869f6bf07 Mon Sep 17 00:00:00 2001 From: Bruno Oliveira Date: Mon, 22 Jan 2018 21:26:14 -0200 Subject: [PATCH 18/22] Remove unnecessary -s from test_log_cli_enabled_disabled --- testing/logging/test_reporting.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/testing/logging/test_reporting.py b/testing/logging/test_reporting.py index ea3c5835f..5e8cd33e5 100644 --- a/testing/logging/test_reporting.py +++ b/testing/logging/test_reporting.py @@ -157,12 +157,12 @@ def test_log_cli_enabled_disabled(testdir, enabled): [pytest] log_cli=true ''') - result = testdir.runpytest('-s') + result = testdir.runpytest() if enabled: result.stdout.fnmatch_lines([ 'test_log_cli_enabled_disabled.py::test_log_cli ', 'test_log_cli_enabled_disabled.py* CRITICAL critical message logged by test', - 'PASSED', + 'PASSED*', ]) else: assert msg not in result.stdout.str() From 113bfb6be88523df3983c358fbed5bb75f234b0c Mon Sep 17 00:00:00 2001 From: Bruno Oliveira Date: Mon, 22 Jan 2018 21:43:35 -0200 Subject: [PATCH 19/22] Report 'call' phase as 'live log call' As commented in review, this makes it consistent with the headers shown by stdout/stderr capturing ("Captured log call") --- _pytest/logging.py | 3 +-- testing/logging/test_reporting.py | 4 ++-- 2 files changed, 3 insertions(+), 4 deletions(-) diff --git a/_pytest/logging.py b/_pytest/logging.py index 46d447326..44db8ea90 100644 --- a/_pytest/logging.py +++ b/_pytest/logging.py @@ -409,8 +409,7 @@ class _LiveLoggingStreamHandler(logging.StreamHandler): self.stream.write('\n') self._first_record_emitted = True if not self._section_name_shown: - header = 'live log' if self._when == 'call' else 'live log ' + self._when - self.stream.section(header, sep='-', bold=True) + self.stream.section('live log ' + self._when, sep='-', bold=True) self._section_name_shown = True logging.StreamHandler.emit(self, record) finally: diff --git a/testing/logging/test_reporting.py b/testing/logging/test_reporting.py index 5e8cd33e5..f5272aa09 100644 --- a/testing/logging/test_reporting.py +++ b/testing/logging/test_reporting.py @@ -254,7 +254,7 @@ def test_log_cli_default_level_sections(testdir, request): '{}::test_log_1 '.format(filename), '*-- live log setup --*', '*WARNING*log message from setup of test_log_1*', - '*-- live log --*', + '*-- live log call --*', '*WARNING*log message from test_log_1*', 'PASSED *50%*', '*-- live log teardown --*', @@ -263,7 +263,7 @@ def test_log_cli_default_level_sections(testdir, request): '{}::test_log_2 '.format(filename), '*-- live log setup --*', '*WARNING*log message from setup of test_log_2*', - '*-- live log --*', + '*-- live log call --*', '*WARNING*log message from test_log_2*', 'PASSED *100%*', '*-- live log teardown --*', From b4e8861aa583e9fc365e5bb4769e3a6e5c94f78a Mon Sep 17 00:00:00 2001 From: Bruno Oliveira Date: Tue, 23 Jan 2018 19:02:32 -0200 Subject: [PATCH 20/22] Fix typos --- _pytest/logging.py | 2 +- doc/en/logging.rst | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/_pytest/logging.py b/_pytest/logging.py index 44db8ea90..308c203ea 100644 --- a/_pytest/logging.py +++ b/_pytest/logging.py @@ -355,7 +355,7 @@ class LoggingPlugin(object): yield # run all the tests def _setup_cli_logging(self): - """Setups the handler and logger for the Live Logs feature, if enabled. + """Sets up the handler and logger for the Live Logs feature, if enabled. This must be done right before starting the loop so we can access the terminal reporter plugin. """ diff --git a/doc/en/logging.rst b/doc/en/logging.rst index 98b80453a..ff819bf50 100644 --- a/doc/en/logging.rst +++ b/doc/en/logging.rst @@ -6,7 +6,7 @@ Logging .. versionadded:: 3.3 .. versionchanged:: 3.4 -Pytest captures log messages of level ``WARNING`` or above automatically and displays them in their own section +pytest captures log messages of level ``WARNING`` or above automatically and displays them in their own section for each failed test in the same manner as captured stdout and stderr. Running without options:: From 2f955e0c99d10fc90f103c14aff70b1382295f5f Mon Sep 17 00:00:00 2001 From: Bruno Oliveira Date: Wed, 24 Jan 2018 18:42:59 -0200 Subject: [PATCH 21/22] Update documentation: rewording and move things for better reading flow --- doc/en/logging.rst | 33 ++++++++++++++++----------------- 1 file changed, 16 insertions(+), 17 deletions(-) diff --git a/doc/en/logging.rst b/doc/en/logging.rst index ff819bf50..ce4c3bb7e 100644 --- a/doc/en/logging.rst +++ b/doc/en/logging.rst @@ -24,11 +24,10 @@ Shows failed tests like so:: ==================== 2 failed in 0.02 seconds ===================== By default each captured log message shows the module, line number, log level -and message. Showing the exact module and line number is useful for testing and -debugging. If desired the log format and date format can be specified to -anything that the logging module supports. +and message. -Running pytest specifying formatting options:: +If desired the log and date format can be specified to +anything that the logging module supports by passing specific formatting options:: pytest --log-format="%(asctime)s %(levelname)s %(message)s" \ --log-date-format="%Y-%m-%d %H:%M:%S" @@ -43,7 +42,7 @@ Shows failed tests like so:: text going to stderr ==================== 2 failed in 0.02 seconds ===================== -These options can also be customized through a configuration file: +These options can also be customized through ``pytest.ini`` file: .. code-block:: ini @@ -56,7 +55,7 @@ with:: pytest --no-print-logs -Or in you ``pytest.ini``: +Or in the ``pytest.ini`` file: .. code-block:: ini @@ -72,6 +71,10 @@ Shows failed tests in the normal manner as no logs were captured:: text going to stderr ==================== 2 failed in 0.02 seconds ===================== + +caplog fixture +^^^^^^^^^^^^^^ + Inside tests it is possible to change the log level for the captured log messages. This is supported by the ``caplog`` fixture:: @@ -136,25 +139,21 @@ You can call ``caplog.clear()`` to reset the captured log records in a test:: assert ['Foo'] == [rec.message for rec in caplog.records] -Accessing logs from other test stages -^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ +The ``caplop.records`` attribute contains records from the current stage only, so +inside the ``setup`` phase it contains only setup logs, same with the ``call`` and +``teardown`` phases. -The ``caplop.records`` fixture contains records from the current stage only. So -inside the setup phase it contains only setup logs, same with the call and -teardown phases. To access logs from other stages you can use -``caplog.get_handler('setup').records``. Valid stages are ``setup``, ``call`` -and ``teardown``. - - -.. _live_logs: +It is possible to access logs from other stages with ``caplog.get_handler('setup').records``. caplog fixture API -^^^^^^^^^^^^^^^^^^ +~~~~~~~~~~~~~~~~~~ .. autoclass:: _pytest.logging.LogCaptureFixture :members: +.. _live_logs: + Live Logs ^^^^^^^^^ From 15cbd6115987ced2e9ae9cd598cc80f0bf07b71c Mon Sep 17 00:00:00 2001 From: Bruno Oliveira Date: Wed, 24 Jan 2018 18:59:08 -0200 Subject: [PATCH 22/22] Change caplog.get_handler(when) to caplog.get_records(when) While updating the docs I noticed that caplog.get_handler() exposes the underlying Handler object, which I think it is a bit too much detail at this stage. Update to return the records directly instead. --- _pytest/logging.py | 19 +++++++++++++++---- changelog/3117.feature | 2 +- doc/en/logging.rst | 16 +++++++++++++++- testing/logging/test_fixture.py | 8 ++++---- 4 files changed, 35 insertions(+), 10 deletions(-) diff --git a/_pytest/logging.py b/_pytest/logging.py index 308c203ea..f92b4c75e 100644 --- a/_pytest/logging.py +++ b/_pytest/logging.py @@ -144,12 +144,23 @@ class LogCaptureFixture(object): def handler(self): return self._item.catch_log_handler - def get_handler(self, when): + def get_records(self, when): """ - Get the handler for a specified state of the tests. - Valid values for the when parameter are: 'setup', 'call' and 'teardown'. + Get the logging records for one of the possible test phases. + + :param str when: + Which test phase to obtain the records from. Valid values are: "setup", "call" and "teardown". + + :rtype: List[logging.LogRecord] + :return: the list of captured records at the given stage + + .. versionadded:: 3.4 """ - return self._item.catch_log_handlers.get(when) + handler = self._item.catch_log_handlers.get(when) + if handler: + return handler.records + else: + return [] @property def text(self): diff --git a/changelog/3117.feature b/changelog/3117.feature index 17c64123f..f428ed75d 100644 --- a/changelog/3117.feature +++ b/changelog/3117.feature @@ -1 +1 @@ -New ``caplog.get_handler(when)`` method which provides access to the underlying ``Handler`` class used to capture logging during each testing stage, allowing users to obtain the captured records during ``"setup"`` and ``"teardown"`` stages. +New ``caplog.get_records(when)`` method which provides access the captured records during each testing stage: ``"setup"``, ``"call"`` and ``"teardown"`` stages. diff --git a/doc/en/logging.rst b/doc/en/logging.rst index ce4c3bb7e..82119043b 100644 --- a/doc/en/logging.rst +++ b/doc/en/logging.rst @@ -143,7 +143,21 @@ The ``caplop.records`` attribute contains records from the current stage only, s inside the ``setup`` phase it contains only setup logs, same with the ``call`` and ``teardown`` phases. -It is possible to access logs from other stages with ``caplog.get_handler('setup').records``. +To access logs from other stages, use the ``caplog.get_records(when)`` method. As an example, +if you want to make sure that tests which use a certain fixture never log any warnings, you can inspect +the records for the ``setup`` and ``call`` stages during teardown like so: + +.. code-block:: python + + + @pytest.fixture + def window(caplog): + window = create_window() + yield window + for when in ('setup', 'call'): + messages = [x.message for x in caplog.get_records(when) if x.level == logging.WARNING] + if messages: + pytest.fail('warning messages encountered during testing: {}'.format(messages)) caplog fixture API diff --git a/testing/logging/test_fixture.py b/testing/logging/test_fixture.py index 68953a257..204472c80 100644 --- a/testing/logging/test_fixture.py +++ b/testing/logging/test_fixture.py @@ -105,16 +105,16 @@ def logging_during_setup_and_teardown(caplog): logger.info('a_setup_log') yield logger.info('a_teardown_log') - assert [x.message for x in caplog.get_handler('teardown').records] == ['a_teardown_log'] + assert [x.message for x in caplog.get_records('teardown')] == ['a_teardown_log'] def test_caplog_captures_for_all_stages(caplog, logging_during_setup_and_teardown): assert not caplog.records - assert not caplog.get_handler('call').records + assert not caplog.get_records('call') logger.info('a_call_log') - assert [x.message for x in caplog.get_handler('call').records] == ['a_call_log'] + assert [x.message for x in caplog.get_records('call')] == ['a_call_log'] - assert [x.message for x in caplog.get_handler('setup').records] == ['a_setup_log'] + assert [x.message for x in caplog.get_records('setup')] == ['a_setup_log'] # This reachers into private API, don't use this type of thing in real tests! assert set(caplog._item.catch_log_handlers.keys()) == {'setup', 'call'}