diff --git a/_pytest/logging.py b/_pytest/logging.py index 27cea16678e..f92b4c75e17 100644 --- a/_pytest/logging.py +++ b/_pytest/logging.py @@ -2,7 +2,6 @@ import logging from contextlib import closing, contextmanager -import sys import six import pytest @@ -48,6 +47,9 @@ def add_option_ini(option, dest, default=None, type=None, **kwargs): '--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, @@ -79,13 +81,14 @@ def add_option_ini(option, dest, default=None, type=None, **kwargs): @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. @@ -93,12 +96,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) @@ -123,17 +128,39 @@ 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): 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): @@ -161,31 +188,31 @@ def clear(self): 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. - 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. + + .. 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. """ - if logger is None: - logger = self.handler - else: - logger = logging.getLogger(logger) + 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) @contextmanager def at_level(self, level, logger=None): - """Context manager that sets the level for capturing of logs. + """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. - 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) orig_level = logger.level logger.setLevel(level) try: @@ -204,7 +231,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): @@ -234,8 +263,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,52 +281,42 @@ def __init__(self, config): 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._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'), - 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) + 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') or logging.WARNING - - 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) + 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') + # 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 + # initialized during pytest_runtestloop + self.log_cli_handler = None + @contextmanager 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 self.log_cli_handler: + 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 @@ -325,10 +348,15 @@ def pytest_runtest_teardown(self, item): 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.""" - with self.live_logs: + self._setup_cli_logging() + 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, @@ -336,3 +364,65 @@ def pytest_runtestloop(self, session): yield # run all the tests else: yield # run all the tests + + def _setup_cli_logging(self): + """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. + """ + terminal_reporter = self._config.pluginmanager.get_plugin('terminalreporter') + if self._config.getini('log_cli') and terminal_reporter is not None: + 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 + self.live_logs_context = catching_logs(log_cli_handler, formatter=log_cli_formatter, level=log_cli_level) + else: + 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. + + 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.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 + + def set_when(self, when): + """Prepares for the given test phase (setup/call/teardown)""" + self._when = when + self._section_name_shown = False + + def emit(self, record): + if self.capture_manager is not None: + self.capture_manager.suspend_global_capture() + try: + if not self._first_record_emitted or self._when == 'teardown': + self.stream.write('\n') + self._first_record_emitted = True + if not self._section_name_shown: + self.stream.section('live log ' + self._when, sep='-', bold=True) + self._section_name_shown = True + logging.StreamHandler.emit(self, record) + finally: + if self.capture_manager is not None: + self.capture_manager.resume_global_capture() diff --git a/changelog/3013.feature b/changelog/3013.feature new file mode 100644 index 00000000000..b690961db9f --- /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. diff --git a/changelog/3117.feature b/changelog/3117.feature index 17c64123fdd..f428ed75dbd 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 9a6df84844f..82119043b01 100644 --- a/doc/en/logging.rst +++ b/doc/en/logging.rst @@ -3,24 +3,11 @@ Logging ------- -.. versionadded 3.3.0 +.. versionadded:: 3.3 +.. versionchanged:: 3.4 -.. 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 - -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:: @@ -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 ---------------------- @@ -37,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" @@ -49,14 +35,14 @@ 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 ---------------------- 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 @@ -69,7 +55,7 @@ with:: pytest --no-print-logs -Or in you ``pytest.ini``: +Or in the ``pytest.ini`` file: .. code-block:: ini @@ -85,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:: @@ -92,7 +82,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 +90,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 +107,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 +138,41 @@ 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] + +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. + +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 +~~~~~~~~~~~~~~~~~~ + +.. autoclass:: _pytest.logging.LogCaptureFixture + :members: + +.. _live_logs: + 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 +212,48 @@ option names are: * ``log_file_format`` * ``log_file_date_format`` -Accessing logs from other test stages -^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ +.. _log_release_notes: + +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``. 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. + +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 -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``. +More details about the discussion that lead to this changes can be read in +issue `#3013 `_. diff --git a/testing/logging/test_fixture.py b/testing/logging/test_fixture.py index 1357dcf361b..204472c8094 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() @@ -73,19 +101,20 @@ 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') - 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'} diff --git a/testing/logging/test_reporting.py b/testing/logging/test_reporting.py index c02ee217227..f5272aa0983 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 @@ -35,7 +38,7 @@ def test_foo(): 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 +61,7 @@ def test_foo(): 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 +82,7 @@ def teardown_function(function): 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*', @@ -141,6 +144,30 @@ def test_foo(): 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() + 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*', + ]) + else: + assert msg not in result.stdout.str() + + def test_log_cli_default_level(testdir): # Default log file level testdir.makepyfile(''' @@ -148,32 +175,103 @@ 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") - print('PASSED') + 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") + ''') + 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', + 'test_log_cli_default_level.py::test_log_cli ', + 'test_log_cli_default_level.py*WARNING message will be shown*', ]) - result.stderr.fnmatch_lines([ - "* This log 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.stdout.str() # make sure that that we get a '0' exit code for the testsuite assert result.ret == 0 +def test_log_cli_default_level_multiple_tests(testdir, request): + """Ensure we reset the first newline added by the live logger between tests""" + filename = request.node.name + '.py' + testdir.makepyfile(''' + import logging + + def test_log_1(): + logging.warning("log message from test_log_1") + + def test_log_2(): + 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), + '*WARNING*log message from test_log_1*', + 'PASSED *50%*', + '{}::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 call --*', + '*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 call --*', + '*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(''' @@ -186,22 +284,19 @@ def test_log_cli(request): 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') # fnmatch_lines does an assertion internally result.stdout.fnmatch_lines([ - 'test_log_cli_level.py PASSED', + '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.stderr.fnmatch_lines([ - "* This log 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 "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 @@ -210,17 +305,10 @@ def test_log_cli(request): # fnmatch_lines does an assertion internally result.stdout.fnmatch_lines([ - 'test_log_cli_level.py PASSED', - ]) - result.stderr.fnmatch_lines([ - "* This log message will be shown" + '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.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 "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 @@ -230,6 +318,7 @@ def test_log_cli_ini_level(testdir): testdir.makeini( """ [pytest] + log_cli=true log_cli_level = INFO """) testdir.makepyfile(''' @@ -247,17 +336,10 @@ def test_log_cli(request): # fnmatch_lines does an assertion internally result.stdout.fnmatch_lines([ - 'test_log_cli_ini_level.py PASSED', + '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.stderr.fnmatch_lines([ - "* This log 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 "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 @@ -278,7 +360,7 @@ def test_log_file(request): 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([ @@ -327,6 +409,16 @@ def test_log_file(request): 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 @@ -334,6 +426,7 @@ def test_log_file_ini(testdir): """ [pytest] log_file={0} + log_file_level=WARNING """.format(log_file)) testdir.makepyfile(''' import pytest @@ -396,3 +489,53 @@ def test_log_file(request): 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 + + 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 + + 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) + handler.set_when('call') + + logger = logging.getLogger(__name__ + '.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'