# Logging is expensive in tests

> DEBUG logging in tests creates, formats and captures a record for every log call. Raise the log level in test settings, drop extra handlers, use caplog only where needed.

A log call that's filtered out by its level costs almost nothing: `logger.debug()` checks the level and returns. A log call that gets through costs a lot more: Python builds a `LogRecord`, looks up the caller's file and line, formats the message and hands it to every handler on the way up to the root logger, and each handler formats it again and writes it somewhere.

Test settings are often copied from development settings, where `DEBUG` logging is on for your own loggers and maybe SQL logging too. Then every ORM query, every request and every loop with a `logger.debug()` inside produces records, pytest captures them all, and none of it is ever read unless a test fails.

## Why it's slow

Three things add up:

- **Your log configuration.** Loggers set to `DEBUG` or `INFO` let every record through. Handlers that write to files or the console format each record, and a `StreamHandler` writing to stderr is captured by pytest on top of that.
- **pytest's log capture.** pytest's logging plugin adds handlers to the root logger during every test phase and formats each record that reaches them, so it can show "Captured log call" when a test fails. It doesn't change log levels unless you set `log_level`, so it captures whatever your configuration lets through.
- **Eager arguments.** `logger.debug(f"payload {payload!r}")` builds the string before the level check, even when the record is discarded. `logger.debug("payload %r", payload)` only formats when a handler actually needs the message.

Live logging makes it worse: with `log_cli = true` and `log_cli_level = DEBUG`, every record is also printed to the terminal.

## The fix: quieter logging in test settings

### Django

Give the test settings their own `LOGGING`, with the root logger at `WARNING`:

```python
# myproject/settings/test.py
from .base import *  # noqa: F403

LOGGING = {
    "version": 1,
    "disable_existing_loggers": False,
    "root": {"handlers": [], "level": "WARNING"},
}
```

Your application's loggers (`logging.getLogger(__name__)` with no level of their own) inherit `WARNING` from the root. Warnings and errors still reach pytest's capture, so failures still show them. If base settings set `django.db.backends` to `DEBUG` to log SQL, this drops that too.

### Plain Python and other frameworks

Set the levels where your logging is configured (a `dictConfig`, a `setup_logging()` call in `conftest.py`), the same way as for Django. pytest's `log_level` option helps less than its name suggests:

```toml
# pyproject.toml
[tool.pytest.ini_options]
log_level = "WARNING"
```

It sets the level of pytest's capture handlers, so they skip formatting `INFO` and `DEBUG` records, but it never raises a logger's level: a logger you set to `DEBUG` still creates every record and your own handlers still format them. If a library is noisy, `--log-disable=<logger name>` turns that logger off. For a hard floor across everything, `logging.disable()` drops records at and below a level before any record is created:

```python
# conftest.py
import logging


def pytest_configure(config):
    logging.disable(logging.INFO)
```

### Remove handlers you don't need

File handlers, JSON formatters, and handlers that ship logs to an external service (Sentry, a log aggregator) shouldn't run in tests at all. Configure them in production settings only, or leave them out of the test `LOGGING`.

### Keep caplog to the tests that assert on logs

`caplog.set_level(logging.DEBUG)` lowers the level for the duration of that test, so every debug record in the code under test is created and captured. Use it in the tests that check log output and set it on the logger you assert on:

```python
import logging

from myapp.payments import charge


def test_logs_declined_charge(caplog):
    caplog.set_level(logging.INFO, logger="myapp.payments")
    charge(amount=100, card="declined")
    assert "declined" in caplog.text
```

## Keep the tests correct

- Tests that assert on log output need their logger enabled at that level: use `caplog.set_level()` or `caplog.at_level()` in those tests. Since pytest 7.4 these also temporarily lift a level disabled with `logging.disable()`.
- Don't turn off `WARNING` and `ERROR`: they often explain why a test failed, and some suites fail on unexpected error logs on purpose.
- pytest's logging plugin can be turned off entirely with `-p no:logging`, but that also removes `caplog` and the captured logs in failure reports. Raising levels is usually enough.

## How flakytest finds it

flakytest puts samples inside the `logging` module in the *logging* category: creating records, formatting them and running handlers, including pytest's capture handlers. When logging takes at least a second and 3% of test time, it suggests **Logging is expensive in tests**, with the tests that log the most and the lines of your code that make the log calls. Run `flakytest compare` after changing the level to see the difference per test.

## Further reading

- [pytest: how to manage logging](https://docs.pytest.org/en/stable/how-to/logging.html)
- [Django: configuring logging](https://docs.djangoproject.com/en/stable/topics/logging/#configuring-logging)
- [Python: `logging.disable()`](https://docs.python.org/3/library/logging.html#logging.disable)
- [Python logging HOWTO: optimization](https://docs.python.org/3/howto/logging.html#optimization)