How should I log in my pytest plugin?

Question

I'm building a pytest plugin and I currently log by adding something similar to the following two lines at the top of the plugin file:

logging.basicConfig()
log = logging.getLogger(PLUGIN_NAME)

However, this does not seem to take into account pytest configuration (through either command line options or ini file) such as the log file path, logger format, etc.

I can manually copy those into my basicConfig call, but I assume there's a better facility used across pytest and third party plugins for logging, is there not?

I found quite a bit of logging references in pytest's documentation and code, but all of it was discussing capturing test logs. I'm interesting in logging the pytest plugin itself.

This is a great question! Have you looked at the code for some of the more popular plugins? — Stephen Rauch, Aug 08 '18 at 01:28
Thanks! I searched the pytest-django and pytest-xdist a bit, but couldn't find anything concrete. To be honest I did not spend a lot of time searching, I kind-of assume I'm missing a resource here. — NirIzr, Aug 08 '18 at 01:31
I did notice `py.log` (`py` is a package by pytest's team) but this just seem to be a different logging scheme, I could not see how this "plugs into" the pytest logging configuration. It does also seem to be a little deprecated/abandoned. — NirIzr, Aug 08 '18 at 01:34
I have contributed to several medium sized open source projects, and I doubt you are missing a resource. This is almost certainly going to be a monkey see, monkey do thing. Which is what excited me about the question. I would think someone is going to need to go look and see what is generally being done, and then document it for the rest of us... But maybe I am wrong and someone will happen by with a nugget of knowledge. Good Luck, and be sure to let us know what you come up with. — Stephen Rauch, Aug 08 '18 at 01:38
Thanks. I frequently find myself answer my own questions (this probably says something bad about me). Will definitely do so if no one else will beat me to it. — NirIzr, Aug 08 '18 at 01:49

hoefling · Accepted Answer · 2018-08-08T11:46:57.687

As you've already found out, py is deprecated and will be removed from pytest dependencies as soon as all usages of py are refactored; don't use py.log as well as any other modules from py if possible.
pytest does not have any configuration or common functionality for logging outside of tests. LoggingPlugin in _pytest.logging is for printing logs "live" (as soon as they are emitted in tests; see my other answer for examples). The rest of _pytest.logging stuff is for capturing log records in tests.

So, just configure logging in plugins same way as in any other program: create a logger named as your plugin, attach the handlers and you're good to go. An example plugin:

import logging
import pytest


class SpamPlugin:

    name = 'spam-plugin'

    def __init__(self, config):
        # turn debug prints on only if "-vv" or more passed
        level = logging.DEBUG if config.option.verbose > 1 else logging.INFO
        logging.basicConfig(level=level)
        self.logger = logging.getLogger(self.name)

    def pytest_sessionstart(self, session):
        self.logger.debug('session started')

    def pytest_sessionfinish(self, session, exitstatus):
        self.logger.debug('session finished')


@pytest.mark.trylast
def pytest_configure(config):
    config.pluginmanager.register(SpamPlugin(config), SpamPlugin.name)

Test output:

$ pytest -vv
DEBUG:spam-plugin:session started
=================================== test session starts ====================================
platform darwin -- Python 3.6.4, pytest-3.7.1, py-1.5.3, pluggy-0.7.1 -- /Users/hoefling/.virtualenvs/stackoverflow/bin/python3.6
cachedir: .pytest_cache
rootdir: /Users/hoefling/projects/private/stackoverflow/so-51737378, inifile: pytest.ini
collected 2 items

test_spam.py::test_foo PASSED                                                         [ 50%]
test_spam.py::test_bar PASSED                                                         [100%]
DEBUG:spam-plugin:session finished


================================= 2 passed in 0.01 seconds =================================

You can of course reuse the format defined for live logs if you want to, although it requires slightly more work because you have to configure the root logger yourself:

import logging
import pytest
from _pytest.config import create_terminal_writer
from _pytest.logging import ColoredLevelFormatter, get_actual_log_level, get_option_ini


class SpamPlugin:

    name = 'spam-plugin'

    def __init__(self, config):
        level = get_actual_log_level(config, 'log_cli_level')
        fmt = get_option_ini(config, 'log_cli_format')
        datefmt = get_option_ini(config, 'log_cli_date_format')
        formatter = ColoredLevelFormatter(create_terminal_writer(config), fmt, datefmt=datefmt)
        handler = logging.StreamHandler()
        handler.setLevel(level)
        handler.setFormatter(formatter)
        logging.getLogger().setLevel(level)
        logging.getLogger().addHandler(handler)
        self.logger = logging.getLogger(self.name)

    def pytest_sessionstart(self, session):
        self.logger.debug('session started')

    def pytest_sessionfinish(self, session, exitstatus):
        print()
        self.logger.debug('session finished')


@pytest.mark.trylast
def pytest_configure(config):
    config.pluginmanager.register(SpamPlugin(config), SpamPlugin.name)

Test output. Although not visible here, the log level will be colored the same way as in live logs because of ColoredLevelFormatter:

$ pytest --log-cli-level=DEBUG --log-cli-format='%(asctime)s [%(levelname)8s] %(message)s (%(filename)s:%(lineno)s)' --log-cli-date-format='%Y-%m-%d %H:%M:%S'
2018-08-08 13:26:56 [   DEBUG] session started (plugin.py:25)
================================== test session starts ====================================
platform darwin -- Python 3.6.4, pytest-3.7.1, py-1.5.3, pluggy-0.7.1
rootdir: /Users/hoefling/projects/private/stackoverflow/so-51737378, inifile: pytest.ini
collected 2 items

test_spam.py ..                                                                      [100%]
2018-08-08 13:26:56 [   DEBUG] session finished (plugin.py:29)


================================ 2 passed in 0.01 seconds =================================

Thanks for the detailed answer! What does the `--verbose` flag do, for example? — NirIzr, Aug 08 '18 at 17:17
It just prints you more information. Check out two outputs of same test run in the answer - the verbose one prints you a list of tests, each one having status `PASSED` or `FAILED`, while the regular output contains test modules with dots, one for each test. It doesn't show you the actual names of tests. — hoefling, Aug 08 '18 at 17:25
The example with verbosity was just to demonstrate how you can bind the log level to command line argument; I didn't want to introduce a new argument just for that. — hoefling, Aug 08 '18 at 17:26
Ah I didn't notice the `config.verbose` code references before. Thanks again! — NirIzr, Aug 08 '18 at 17:30
Not sure what version of pytest it changed, but `get_actual_log_level` is now `get_log_level_for_setting` — miigotu, Apr 03 '22 at 13:26

How should I log in my pytest plugin?

1 Answers1