Don't Handle Logging in Your Tests

announcements and community
1

… Because pytest Will Do It For You

If you are using pytest, you probably wonder how it handles the logs of your project. pytest captures logs from your test cases. You can configure how pytest shows them, whether it is live in the terminal, written to a file, or filtered by log level.

There is a slight chance that you are in the same boat as me, spending significant time tweaking these configs to achieve your ideal level of verbosity. Hopefully, this blog post gives you a better understanding of how pytest handles logs and some interesting findings from my work.

The blog assumes familiarity with Python’s logging module.

Motivating Example

Throughout this post we will use a small example: a library for ordering fish and chips that emits logs at two different levels.

# fish_and_chips.py
import logging

logger = logging.getLogger("fish_and_chips")

def order():
    logger.info("Starting order")
    logger.debug("http GET")
    logger.info("Ending order")
    return 10

# test/fish_and_chips.py
def test_order():
    assert order() == 10

According to the Python Logging cookbook, a library is responsible for providing public loggers to be consumed by downstream users. fish_and_chips can decide on the log message, the level of each log message, and the hierarchy of its loggers. Downstream users can handle logging according to their needs. pytest acts like a downstream user. It attaches its own handlers to the root logger of the test session. By doing this, pytest can capture the logs emitted in the tests, and perform magical operations on them.

For example:

By default, pytest doesn’t do anything interesting with logs from the fish_and_chips library:

$ uvx pytest@9.1.1 test/fish_and_chips.py

fish_and_chips.py .                [100%]
=== 1 passed in 0.00s ===

pytest’s Four Log Handlers

Live CLI Handler (live_cli_handler)

This handler prints log messages directly to the terminal while your tests are running. It’s great for debugging during development, when you want to see logs in real time. It is also useful for long running tests, like charm integration tests with Jubilant.

To enable live DEBUG logs, use --log-cli-level=DEBUG:

$ uvx pytest@9.1.1 test/fish_and_chips.py --log-cli-level=DEBUG

fish_and_chips.py::test_order
--- live log call ---
INFO     ... Starting order
DEBUG    ... http GET
INFO     ... Ending order
PASSED
[100%]

=== 1 passed in 0.00s ===

The logs are shown to the terminal in real time, and kept under the live log call section.

If --log-cli-level is not set, the live CLI level falls back to log_level, which is WARNING by default.

File Handler (log_file_handler)

This handler writes logs to a file. It is useful for long-running integration tests (for example, in CI).

To store all DEBUG level logs in a file, use --log-file:

$ uvx pytest@9.1.1 test/fish_and_chips.py --log-file a.log --log-file-level=DEBUG

fish_and_chips.py::test_order
=== 1 passed in 0.00s ===

$ cat a.log
INFO     Starting order
DEBUG    http GET
INFO     Ending order

If --log-file-level is not set, the file log level falls back to log_level, which is WARNING by default.

Capture Log Handler (caplog_handler)

This handler captures logs from the tests, and exposes them to the developer as the caplog fixture. The caplog fixture gives you a clean way to assert on your logging. You cannot configure this handler’s level like the others.

For example, to test if order() emits log messages that contain Starting order:

# test/fish_and_chips.pyimport loggingdef test_order(caplog):
    caplog.set_level(logging.DEBUG, logger="fish_and_chips")
    order()
    assert "Starting order" in caplog.text

We need caplog.set_level(logging.DEBUG, logger="fish_and_chips") to make caplog capture logs with level DEBUG and above, and make the test deterministic.

See more: Caplog fixture

Report Handler (report_handler)

This is the handler behind those familiar Captured log call sections you see when a test fails. pytest uses this handler to report log messages leading up to the failure. You cannot configure this handler’s level like the others.

Let’s modify the example to fail a test, and run the test with log-level DEBUG:

# test/fish_and_chips.pydef test_order():
    assert order() == "This will fail the test"

$ uvx pytest@9.1.1 test/fish_and_chips.py --log-level=DEBUG

fish_and_chips.py F
[100%]
...
fish_and_chips.py:13: AssertionError
--- Captured log call ---
INFO     fish_and_chips:fish_and_chips.py:7 Starting order
DEBUG    fish_and_chips:fish_and_chips.py:8 http GET
INFO     fish_and_chips:fish_and_chips.py:9 Ending order
=== 1 failed in 0.01s ===

Interesting findings

1. Enabling live logging

There are 2 quite different ways to enable live logging.

  • From CLI: --log-cli-level implicitly enables live logging.
  • From the configuration file: in pyproject.toml we can use log_cli = true.

This isn’t a big deal, but it definitely surprised me at first.

2. Interaction between handler levels
From the previous section, we know that there are 3 knobs to configure the log level:

  • --log-cli-level for live_cli_handler
  • --log-file-level for log_file_handler
  • --log-level which set the level of all log messages in the test session

It is very easy to think that --log-cli-level and --log-file-level only apply to their corresponding handlers.

Let’s run the failing example again, this time enable both flags:

# test/fish_and_chips.pydef test_order():
    assert order() == "This will fail the test"

$ uvx pytest@9.1.1 fish_and_chips.py --log-cli-level=INFO --log-file-level=DEBUG
...

fish_and_chips.py::test_order
--- live log call ---
INFO     fish_and_chips:fish_and_chips.py:7 Starting order
INFO     fish_and_chips:fish_and_chips.py:9 Ending order
FAILED
[100%]

=== FAILURES ===
...

fish_and_chips.py:13: AssertionError
--- Captured log call ---
INFO     fish_and_chips:fish_and_chips.py:7 Starting order
DEBUG    fish_and_chips:fish_and_chips.py:8 http GET
INFO     fish_and_chips:fish_and_chips.py:9 Ending order
=== short test summary info ===
FAILED fish_and_chips.py::test_order - AssertionError: assert 10 == 'This will fail the test'
=== 1 failed in 0.02s ===

A-ha! The level of report_handler was set to DEBUG instead of WARNING (the default). Apparently, report_handler‘s level depends on the minimum level between --log-cli-level and --log-file-level. In this case it is DEBUG.

More examples:

# report_handler at DEBUG
pytest fish_and_chips.py --log-cli-level=DEBUG  --log-file-level=INFO

# report_handler at DEBUG
pytest fish_and_chips.py --log-cli-level=WARNING --log-file-level=DEBUG

# report_handler at INFO
pytest fish_and_chips.py --log-cli-level=WARNING --log-file-level=INFO

The detailed explanation of this behaviour is for another day. But as users, you mostly don’t have to worry about it, since it is useful to have more logs when a test fails. Having report_handler at DEBUG level is desirable here.

If you are like me and really want report_handler to stay at INFO, you need to use --log-level:

$ uvx pytest@9.1.1 fish_and_chips.py --log-cli-level=INFO --log-file-level=DEBUG \     
    --log-level=INFO

See more: pytest’s logging plugin

3. Only keep universal pytest configs in pyproject.toml

It’s tempting to put all your logging configs into pyproject.toml:

[tool.pytest.ini_options]
log_cli_level = "INFO"
log_cli = true

These settings apply to every pytest invocation in your project. And it’s not always useful. In the example above, live logging is useful if you are running charm integration tests, but it is unnecessary for running charm unit tests locally. It’s better to use --log-cli-level=INFO in the specific command that runs the integration tests.

Takeaways

  • pytest has a powerful mechanism to capture and handle logs from your tests.
  • Don’t be surprised if --log-cli-level=INFO automatically enables live logging.
  • We should be careful about what goes into the config file, and keep specific configs as CLI arguments.
2 Likes