Merge pull request #3124 from nicoddemus/logging-3013
Changes in the logging plugin for 3.4
This commit is contained in:
Bruno Oliveira
GitHub
commit
a58099022a
|
|
@ -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
|
||||
|
|
@ -48,6 +47,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,
|
||||
|
|
@ -79,13 +81,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.
|
||||
|
|
@ -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 @@ 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.
|
||||
|
||||
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 @@ 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._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
|
||||
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
|
||||
|
||||
# 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 @@ 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."""
|
||||
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 @@ class LoggingPlugin(object):
|
|||
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()
|
||||
|
|
|
|||
|
|
@ -0,0 +1 @@
|
|||
**Incompatible change**: after community feedback the `logging <https://docs.pytest.org/en/latest/logging.html>`_ functionality has undergone some changes. Please consult the `logging documentation <https://docs.pytest.org/en/latest/logging.html#incompatible-changes-in-pytest-3-4>`_ for details.
|
||||
|
|
@ -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.
|
||||
|
|
|
|||
|
|
@ -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
|
||||
<https://pypi.org/project/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:
|
||||
|
||||
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
|
||||
<https://pypi.org/project/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 <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 <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 <https://github.com/pytest-dev/pytest/issues/3013>`_.
|
||||
|
|
|
|||
|
|
@ -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'}
|
||||
|
|
|
|||
|
|
@ -1,5 +1,8 @@
|
|||
# -*- coding: utf-8 -*-
|
||||
import os
|
||||
|
||||
import six
|
||||
|
||||
import pytest
|
||||
|
||||
|
||||
|
|
@ -35,7 +38,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 +61,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 +82,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*',
|
||||
|
|
@ -141,6 +144,30 @@ 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()
|
||||
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_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')
|
||||
|
||||
# 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_level(testdir):
|
|||
|
||||
# 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
|
||||
|
|
@ -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_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* 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_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([
|
||||
|
|
@ -327,6 +409,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
|
||||
|
||||
|
|
@ -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_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
|
||||
|
||||
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'
|
||||
|
|
|
|||
Loading…
Reference in New Issue