2017-09-27 06:39:41 +08:00
|
|
|
.. _logging:
|
|
|
|
|
2021-03-15 16:22:11 +08:00
|
|
|
How to manage logging
|
|
|
|
---------------------
|
2017-09-27 06:39:41 +08:00
|
|
|
|
2018-01-24 05:02:32 +08:00
|
|
|
pytest captures log messages of level ``WARNING`` or above automatically and displays them in their own section
|
2018-01-20 22:08:51 +08:00
|
|
|
for each failed test in the same manner as captured stdout and stderr.
|
2017-09-27 06:39:41 +08:00
|
|
|
|
2019-02-15 21:10:37 +08:00
|
|
|
Running without options:
|
|
|
|
|
|
|
|
.. code-block:: bash
|
2017-09-27 06:39:41 +08:00
|
|
|
|
|
|
|
pytest
|
|
|
|
|
2019-02-15 21:10:37 +08:00
|
|
|
Shows failed tests like so:
|
|
|
|
|
|
|
|
.. code-block:: pytest
|
2017-09-27 06:39:41 +08:00
|
|
|
|
|
|
|
----------------------- Captured stdlog call ----------------------
|
2018-01-17 07:25:39 +08:00
|
|
|
test_reporting.py 26 WARNING text going to logger
|
2017-09-27 06:39:41 +08:00
|
|
|
----------------------- Captured stdout call ----------------------
|
|
|
|
text going to stdout
|
|
|
|
----------------------- Captured stderr call ----------------------
|
|
|
|
text going to stderr
|
|
|
|
==================== 2 failed in 0.02 seconds =====================
|
|
|
|
|
|
|
|
By default each captured log message shows the module, line number, log level
|
2018-01-25 04:42:59 +08:00
|
|
|
and message.
|
2017-09-27 06:39:41 +08:00
|
|
|
|
2018-01-25 04:42:59 +08:00
|
|
|
If desired the log and date format can be specified to
|
2019-02-15 21:10:37 +08:00
|
|
|
anything that the logging module supports by passing specific formatting options:
|
|
|
|
|
|
|
|
.. code-block:: bash
|
2017-09-27 06:39:41 +08:00
|
|
|
|
|
|
|
pytest --log-format="%(asctime)s %(levelname)s %(message)s" \
|
|
|
|
--log-date-format="%Y-%m-%d %H:%M:%S"
|
|
|
|
|
2019-02-15 21:10:37 +08:00
|
|
|
Shows failed tests like so:
|
|
|
|
|
|
|
|
.. code-block:: pytest
|
2017-09-27 06:39:41 +08:00
|
|
|
|
|
|
|
----------------------- Captured stdlog call ----------------------
|
2018-01-17 07:25:39 +08:00
|
|
|
2010-04-10 14:48:44 WARNING text going to logger
|
2017-09-27 06:39:41 +08:00
|
|
|
----------------------- Captured stdout call ----------------------
|
|
|
|
text going to stdout
|
|
|
|
----------------------- Captured stderr call ----------------------
|
|
|
|
text going to stderr
|
|
|
|
==================== 2 failed in 0.02 seconds =====================
|
|
|
|
|
2018-01-25 04:42:59 +08:00
|
|
|
These options can also be customized through ``pytest.ini`` file:
|
2017-09-27 06:39:41 +08:00
|
|
|
|
|
|
|
.. code-block:: ini
|
|
|
|
|
|
|
|
[pytest]
|
|
|
|
log_format = %(asctime)s %(levelname)s %(message)s
|
|
|
|
log_date_format = %Y-%m-%d %H:%M:%S
|
|
|
|
|
2018-02-19 03:48:07 +08:00
|
|
|
Further it is possible to disable reporting of captured content (stdout,
|
2019-02-15 21:10:37 +08:00
|
|
|
stderr and logs) on failed tests completely with:
|
|
|
|
|
|
|
|
.. code-block:: bash
|
2017-09-27 06:39:41 +08:00
|
|
|
|
2018-02-19 03:48:07 +08:00
|
|
|
pytest --show-capture=no
|
2017-09-27 06:39:41 +08:00
|
|
|
|
2018-01-25 04:42:59 +08:00
|
|
|
|
|
|
|
caplog fixture
|
|
|
|
^^^^^^^^^^^^^^
|
|
|
|
|
2017-09-27 06:39:41 +08:00
|
|
|
Inside tests it is possible to change the log level for the captured log
|
2019-08-07 07:20:06 +08:00
|
|
|
messages. This is supported by the ``caplog`` fixture:
|
2017-09-27 06:39:41 +08:00
|
|
|
|
2019-08-07 04:25:54 +08:00
|
|
|
.. code-block:: python
|
|
|
|
|
2017-09-27 06:39:41 +08:00
|
|
|
def test_foo(caplog):
|
|
|
|
caplog.set_level(logging.INFO)
|
|
|
|
pass
|
|
|
|
|
2018-01-17 07:25:39 +08:00
|
|
|
By default the level is set on the root logger,
|
2017-09-27 06:39:41 +08:00
|
|
|
however as a convenience it is also possible to set the log level of any
|
2019-08-07 07:20:06 +08:00
|
|
|
logger:
|
2017-09-27 06:39:41 +08:00
|
|
|
|
2019-08-07 04:25:54 +08:00
|
|
|
.. code-block:: python
|
|
|
|
|
2017-09-27 06:39:41 +08:00
|
|
|
def test_foo(caplog):
|
2019-08-07 04:34:58 +08:00
|
|
|
caplog.set_level(logging.CRITICAL, logger="root.baz")
|
2017-09-27 06:39:41 +08:00
|
|
|
pass
|
|
|
|
|
2018-01-17 07:25:39 +08:00
|
|
|
The log levels set are restored automatically at the end of the test.
|
|
|
|
|
2017-09-27 06:39:41 +08:00
|
|
|
It is also possible to use a context manager to temporarily change the log
|
2019-08-07 07:20:06 +08:00
|
|
|
level inside a ``with`` block:
|
2017-09-27 06:39:41 +08:00
|
|
|
|
2019-08-07 04:25:54 +08:00
|
|
|
.. code-block:: python
|
|
|
|
|
2017-09-27 06:39:41 +08:00
|
|
|
def test_bar(caplog):
|
|
|
|
with caplog.at_level(logging.INFO):
|
|
|
|
pass
|
|
|
|
|
2018-01-17 07:25:39 +08:00
|
|
|
Again, by default the level of the root logger is affected but the level of any
|
2019-08-07 07:20:06 +08:00
|
|
|
logger can be changed instead with:
|
2017-09-27 06:39:41 +08:00
|
|
|
|
2019-08-07 04:25:54 +08:00
|
|
|
.. code-block:: python
|
|
|
|
|
2017-09-27 06:39:41 +08:00
|
|
|
def test_bar(caplog):
|
2019-08-07 04:34:58 +08:00
|
|
|
with caplog.at_level(logging.CRITICAL, logger="root.baz"):
|
2017-09-27 06:39:41 +08:00
|
|
|
pass
|
|
|
|
|
|
|
|
Lastly all the logs sent to the logger during the test run are made available on
|
2018-01-17 07:25:39 +08:00
|
|
|
the fixture in the form of both the ``logging.LogRecord`` instances and the final log text.
|
2019-08-07 07:20:06 +08:00
|
|
|
This is useful for when you want to assert on the contents of a message:
|
2017-09-27 06:39:41 +08:00
|
|
|
|
2019-08-07 04:25:54 +08:00
|
|
|
.. code-block:: python
|
|
|
|
|
2017-09-27 06:39:41 +08:00
|
|
|
def test_baz(caplog):
|
|
|
|
func_under_test()
|
|
|
|
for record in caplog.records:
|
2019-08-07 04:34:58 +08:00
|
|
|
assert record.levelname != "CRITICAL"
|
|
|
|
assert "wally" not in caplog.text
|
2017-09-27 06:39:41 +08:00
|
|
|
|
|
|
|
For all the available attributes of the log records see the
|
|
|
|
``logging.LogRecord`` class.
|
|
|
|
|
|
|
|
You can also resort to ``record_tuples`` if all you want to do is to ensure,
|
|
|
|
that certain messages have been logged under a given logger name with a given
|
2019-08-07 07:20:06 +08:00
|
|
|
severity and message:
|
2017-09-27 06:39:41 +08:00
|
|
|
|
2019-08-07 04:25:54 +08:00
|
|
|
.. code-block:: python
|
|
|
|
|
2017-09-27 06:39:41 +08:00
|
|
|
def test_foo(caplog):
|
2019-08-07 04:34:58 +08:00
|
|
|
logging.getLogger().info("boo %s", "arg")
|
2017-09-27 06:39:41 +08:00
|
|
|
|
2019-08-07 04:34:58 +08:00
|
|
|
assert caplog.record_tuples == [("root", logging.INFO, "boo arg")]
|
2017-09-27 06:39:41 +08:00
|
|
|
|
2019-08-07 07:20:06 +08:00
|
|
|
You can call ``caplog.clear()`` to reset the captured log records in a test:
|
2017-09-27 06:39:41 +08:00
|
|
|
|
2019-08-07 04:25:54 +08:00
|
|
|
.. code-block:: python
|
|
|
|
|
2017-09-27 06:39:41 +08:00
|
|
|
def test_something_with_clearing_records(caplog):
|
|
|
|
some_method_that_creates_log_records()
|
|
|
|
caplog.clear()
|
|
|
|
your_test_method()
|
2019-08-07 04:34:58 +08:00
|
|
|
assert ["Foo"] == [rec.message for rec in caplog.records]
|
2017-09-27 06:39:41 +08:00
|
|
|
|
2018-01-17 07:25:39 +08:00
|
|
|
|
2018-05-21 02:14:06 +08:00
|
|
|
The ``caplog.records`` attribute contains records from the current stage only, so
|
2018-01-25 04:42:59 +08:00
|
|
|
inside the ``setup`` phase it contains only setup logs, same with the ``call`` and
|
|
|
|
``teardown`` phases.
|
2018-01-17 07:25:39 +08:00
|
|
|
|
2018-01-25 04:59:08 +08:00
|
|
|
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
|
2018-06-03 11:29:28 +08:00
|
|
|
for when in ("setup", "call"):
|
|
|
|
messages = [
|
2019-09-21 01:36:25 +08:00
|
|
|
x.message for x in caplog.get_records(when) if x.levelno == logging.WARNING
|
2018-06-03 11:29:28 +08:00
|
|
|
]
|
2018-01-25 04:59:08 +08:00
|
|
|
if messages:
|
2018-06-03 11:29:28 +08:00
|
|
|
pytest.fail(
|
|
|
|
"warning messages encountered during testing: {}".format(messages)
|
|
|
|
)
|
2018-01-17 07:25:39 +08:00
|
|
|
|
|
|
|
|
|
|
|
|
2021-04-20 21:18:53 +08:00
|
|
|
The full API is available at :class:`pytest.LogCaptureFixture`.
|
2018-02-28 04:32:34 +08:00
|
|
|
|
2018-01-17 07:25:39 +08:00
|
|
|
|
2018-01-25 04:42:59 +08:00
|
|
|
.. _live_logs:
|
|
|
|
|
2017-09-27 06:39:41 +08:00
|
|
|
Live Logs
|
|
|
|
^^^^^^^^^
|
|
|
|
|
2018-01-17 07:25:39 +08:00
|
|
|
By setting the :confval:`log_cli` configuration option to ``true``, pytest will output
|
|
|
|
logging records as they are emitted directly into the console.
|
2017-09-27 06:39:41 +08:00
|
|
|
|
|
|
|
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
|
|
|
|
accepts the logging level names as seen in python's documentation or an integer
|
|
|
|
as the logging level num.
|
|
|
|
|
|
|
|
Additionally, you can also specify ``--log-cli-format`` and
|
|
|
|
``--log-cli-date-format`` which mirror and default to ``--log-format`` and
|
|
|
|
``--log-date-format`` if not provided, but are applied only to the console
|
|
|
|
logging handler.
|
|
|
|
|
|
|
|
All of the CLI log options can also be set in the configuration INI file. The
|
|
|
|
option names are:
|
|
|
|
|
|
|
|
* ``log_cli_level``
|
|
|
|
* ``log_cli_format``
|
|
|
|
* ``log_cli_date_format``
|
|
|
|
|
|
|
|
If you need to record the whole test suite logging calls to a file, you can pass
|
|
|
|
``--log-file=/path/to/log/file``. This log file is opened in write mode which
|
|
|
|
means that it will be overwritten at each run tests session.
|
2022-04-23 02:15:27 +08:00
|
|
|
Note that relative paths for the log-file location, whether passed on the CLI or declared in a
|
|
|
|
config file, are always resolved relative to the current working directory.
|
2017-09-27 06:39:41 +08:00
|
|
|
|
|
|
|
You can also specify the logging level for the log file by passing
|
|
|
|
``--log-file-level``. This setting accepts the logging level names as seen in
|
|
|
|
python's documentation(ie, uppercased level names) or an integer as the logging
|
|
|
|
level num.
|
|
|
|
|
|
|
|
Additionally, you can also specify ``--log-file-format`` and
|
|
|
|
``--log-file-date-format`` which are equal to ``--log-format`` and
|
|
|
|
``--log-date-format`` but are applied to the log file logging handler.
|
|
|
|
|
|
|
|
All of the log file options can also be set in the configuration INI file. The
|
|
|
|
option names are:
|
|
|
|
|
|
|
|
* ``log_file``
|
|
|
|
* ``log_file_level``
|
|
|
|
* ``log_file_format``
|
|
|
|
* ``log_file_date_format``
|
2018-01-15 22:01:01 +08:00
|
|
|
|
2019-02-09 05:35:50 +08:00
|
|
|
You can call ``set_log_path()`` to customize the log_file path dynamically. This functionality
|
|
|
|
is considered **experimental**.
|
|
|
|
|
2021-08-09 21:48:47 +08:00
|
|
|
.. _log_colors:
|
|
|
|
|
|
|
|
Customizing Colors
|
|
|
|
^^^^^^^^^^^^^^^^^^
|
|
|
|
|
|
|
|
Log levels are colored if colored terminal output is enabled. Changing
|
|
|
|
from default colors or putting color on custom log levels is supported
|
|
|
|
through ``add_color_level()``. Example:
|
|
|
|
|
|
|
|
.. code-block:: python
|
|
|
|
|
|
|
|
@pytest.hookimpl
|
|
|
|
def pytest_configure(config):
|
|
|
|
logging_plugin = config.pluginmanager.get_plugin("logging-plugin")
|
|
|
|
|
|
|
|
# Change color on existing log level
|
|
|
|
logging_plugin.log_cli_handler.formatter.add_color_level(logging.INFO, "cyan")
|
|
|
|
|
|
|
|
# Add color to a custom log level (a custom log level `SPAM` is already set up)
|
|
|
|
logging_plugin.log_cli_handler.formatter.add_color_level(logging.SPAM, "blue")
|
|
|
|
.. warning::
|
|
|
|
|
|
|
|
This feature and its API are considered **experimental** and might change
|
|
|
|
between releases without a deprecation notice.
|
2018-01-17 07:25:39 +08:00
|
|
|
.. _log_release_notes:
|
2018-01-15 22:01:01 +08:00
|
|
|
|
2018-01-17 07:25:39 +08:00
|
|
|
Release notes
|
|
|
|
^^^^^^^^^^^^^
|
|
|
|
|
2021-10-22 20:47:57 +08:00
|
|
|
This feature was introduced as a drop-in replacement for the
|
|
|
|
:pypi:`pytest-catchlog` plugin and they conflict
|
2018-01-17 07:25:39 +08:00
|
|
|
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.
|
2020-06-09 09:05:46 +08:00
|
|
|
Setting :confval:`log_level` will set the level that is captured globally so if a specific test requires
|
|
|
|
a lower level than this, use the ``caplog.set_level()`` functionality otherwise that test will be prone to
|
|
|
|
failure.
|
2018-01-17 07:25:39 +08:00
|
|
|
* :ref:`Live Logs <live_logs>` is now disabled by default and can be enabled setting the
|
2018-01-18 04:38:30 +08:00
|
|
|
:confval:`log_cli` configuration option to ``true``. When enabled, the verbosity is increased so logging for each
|
|
|
|
test is visible.
|
2018-01-17 07:25:39 +08:00
|
|
|
* :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
|
|
|
|
|
2021-11-06 17:16:11 +08:00
|
|
|
More details about the discussion that lead to this changes can be read in :issue:`3013`.
|