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.

Answer 1

1. 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.

2. 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 =================================