When using loguru and pytest-loguru plugin, all logs (all level log)will output in terminal even though I add option `--log-level=INFO` or `--log-cli-level=INFO`

When using default logging lib, running pytest -s -v test_e2e.py will not output logs and if running pytest -s -v test_e2e.py --log-cli-level=INFO --capture=no will output INFO level logs.

But when using loguru and pytest-loguru plugin , runing two commands above will output all logs

Here is my setting

from loguru import logger
import sys

from config.log_config import log_config

class TestLog:
    def __init__(self, log_debug, log_info, log_err, log_worker):
        self.log_debug = log_debug
        self.log_info = log_info
        self.log_err = log_err
        self.log_worker = log_worker
        self.log = logger

        config = {
            self.log_debug: "DEBUG",
            self.log_info: "INFO",
            self.log_err: "ERROR",
            self.log_worker: "DEBUG"
        }
        try:
            encoding = "utf-8"
            enqueue = True
            for file, level in config.items():
                self.log.add(
                    sink=file, level=level, encoding=encoding,
                    enqueue=enqueue, rotation="500MB", retention="1 week",
                    # colorize=True
                )

            self.log.add(sys.stdout, level="DEBUG", colorize=False)

        except Exception as e:
            print("Can not use %s or %s or %s to log. error : %s" % (log_debug, log_info, log_err, str(e)))

"""All modules share this unified log"""
log_debug = log_config.log_debug
log_info = log_config.log_info
log_err = log_config.log_err
log_worker = log_config.log_worker
test_log = TestLog(log_debug, log_info, log_err, log_worker).log

@zhuwenxing You probably need to call .remove() at the very beginning of your test. The logs you're seeing are likely the ones sent to stderr by the default handler.

if I add .remove() at beginning like this

from loguru import logger
import sys

from config.log_config import log_config

class TestLog:
    def __init__(self, log_debug, log_info, log_err, log_worker):
        self.log_debug = log_debug
        self.log_info = log_info
        self.log_err = log_err
        self.log_worker = log_worker
        self.log = logger

        config = {
            self.log_debug: "DEBUG",
            self.log_info: "INFO",
            self.log_err: "ERROR",
            self.log_worker: "DEBUG"
        }
        try:
            encoding = "utf-8"
            enqueue = True
            self.log.remove()
            for file, level in config.items():
                self.log.add(
                    sink=file, level=level, encoding=encoding,
                    enqueue=enqueue, rotation="500MB", retention="1 week",
                    colorize=True
                )
            self.log.add(sys.stdout, level="DEBUG", colorize=False)

        except Exception as e:
            print("Can not use %s or %s or %s to log. error : %s" % (log_debug, log_info, log_err, str(e)))

"""All modules share this unified log"""
log_debug = log_config.log_debug
log_info = log_config.log_info
log_err = log_config.log_err
log_worker = log_config.log_worker
test_log = TestLog(log_debug, log_info, log_err, log_worker).log

But then it will never output any logs when using pytest test_e2e.py --log-cli-level=INFO --capture=no.

Maybe using a scoped fixture:


@pytest.fixture(scope="session")
def cleanup_logger():
   logger.remove()

conftest.py

from loguru import logger
import pytest
from _pytest.logging import LogCaptureFixture

@pytest.fixture(autouse=True)
def caplog(caplog: LogCaptureFixture):
    """
    Make pytest work with loguru. See:
    https://loguru.readthedocs.io/en/stable/resources/migration.html#making-things-work-with-pytest-and-caplog
    """
    handler_id = logger.add(caplog.handler, format="{message}")
    yield caplog
    logger.remove(handler_id)

@pytest.fixture
def my_value():
    """
    Some random value
    """
    return 5

log_util.py

from loguru import logger

class TestLog:
    def __init__(self, log_debug, log_info, log_err):
        self.log_debug = log_debug
        self.log_info = log_info
        self.log_err = log_err
        self.log = logger

        config = {
            self.log_debug: "DEBUG",
            self.log_info: "INFO",
            self.log_err: "ERROR",
        }
        try:
            encoding = "utf-8"
            enqueue = True
            for file, level in config.items():
                self.log.add(
                    sink=file, level=level, encoding=encoding,
                    enqueue=enqueue, rotation="500MB", retention="1 week",
                    # colorize=True
                )

            # self.log.add(sys.stdout, level="DEBUG", colorize=False)

        except Exception as e:
            print("Can not use %s or %s or %s to log. error : %s" % (log_debug, log_info, log_err, str(e)))

"""All modules share this unified log"""
log_debug = "./log/debug.log"
log_info = "./log/info.log"
log_err = "./log/error.log"
test_log = TestLog(log_debug, log_info, log_err).log

test_loguru_demo.py

from log_util import test_log as log

def test_log(my_value):
    log.debug("debug message")
    log.info("info message")
    log.error("error message")
    assert my_value <= 4, "Test value."

requirements.txt

loguru=0.5.3
pytest=7.2.0

output

❯ pytest -s -v test_loguru_demo.py --log-cli-level=INFO             
Test session starts (platform: darwin, Python 3.8.8, pytest 7.2.0, pytest-sugar 0.9.5)
cachedir: .pytest_cache
benchmark: 3.4.1 (defaults: timer=time.perf_counter disable_gc=False min_rounds=5 min_time=0.000005 max_time=1.0 calibration_precision=10 warmup=False warmup_iterations=100000)
Test order randomisation NOT enabled. Enable with --random-order or --random-order-bucket=<bucket_type>
tags: all
metadata: {'Python': '3.8.8', 'Platform': 'macOS-10.16-x86_64-i386-64bit', 'Packages': {'pytest': '7.2.0', 'py': '1.10.0', 'pluggy': '0.13.1'}, 'Plugins': {'anyio': '3.6.1', 'benchmark': '3.4.1', 'xdist': '2.5.0', 'repeat': '0.8.0', 'random-order': '1.0.4', 'rerunfailures': '9.1.1', 'assume': '2.4.3', 'sugar': '0.9.5', 'parallel': '0.1.1', 'tags': '1.7.2', 'timeout': '1.3.3', 'print': '0.2.1', 'html': '3.1.1', 'allure-pytest': '2.7.0', 'metadata': '1.11.0', 'level': '0.1.1', 'dependency': '0.5.1', 'reportportal': '5.0.10', 'forked': '1.3.0', 'cov': '2.8.1'}}
rootdir: /Users/wxzhu/workspace/logging_loguru/loguru_demo, configfile: pytest.ini
plugins: anyio-3.6.1, benchmark-3.4.1, xdist-2.5.0, repeat-0.8.0, random-order-1.0.4, rerunfailures-9.1.1, assume-2.4.3, sugar-0.9.5, parallel-0.1.1, tags-1.7.2, timeout-1.3.3, print-0.2.1, html-3.1.1, allure-pytest-2.7.0, metadata-1.11.0, level-0.1.1, dependency-0.5.1, reportportal-5.0.10, forked-1.3.0, cov-2.8.1
selected 1 items
2022-11-18 19:08:03.142 | DEBUG    | test_loguru_demo:test_log:5 - debug message
2022-11-18 19:08:03.143 | INFO     | test_loguru_demo:test_log:6 - info message
2022-11-18 19:08:03.143 | ERROR    | test_loguru_demo:test_log:7 - error message

―――――――――――――――――――――――――――――――――――――――――― test_log ―――――――――――――――――――――――――――――――――――――――――――

my_value = 5

    def test_log(my_value):
        log.debug("debug message")
        log.info("info message")
        log.error("error message")
>       assert my_value <= 4, "Test value."
E       AssertionError: Test value.
E       assert 5 <= 4

test_loguru_demo.py:8: AssertionError

 test_loguru_demo.py::test_log ⨯                                                100% ██████████
=================================== short test summary info ===================================
FAILED test_loguru_demo.py::test_log - AssertionError: Test value.

Results (0.22s):
       1 failed
         - test_loguru_demo.py:4 test_log

expect there is no debug log

Hey @zhuwenxing, I think I figured out a solution.

Basically, Pytest configures multiple handlers, in particular:

The "capture handler" to work with the caplog fixture
The "report handler" which display logged message not captured
The "cli handler" to work with the log_cli option
The "file handler" to work with the log_file option

More details here: How to manage logging - pytest documentation.

According to your use case, you're not interested with the "capture handler". You should remove the autouse=True from it. You instead need to propagate logs from Loguru to both the "report handler" and "cli handler".

We could directly send logs to them as follow:

@pytest.fixture(autouse=True, scope="session")
def cleanup_loguru():
    # Remove all handlers to make sure we don't interfere with tests.
    logger.remove()

@pytest.fixture(autouse=True, scope="session")
def report_logging(pytestconfig, cleanup_loguru):
    logging_plugin = pytestconfig.pluginmanager.getplugin("logging-plugin")
    level = logging_plugin.log_cli_level
    handler_id = logger.add(
        logging_plugin.report_handler,
        level="WARNING" if level is None else level,
        format="{message}",
    )
    yield
    logger.remove(handler_id)

@pytest.fixture(autouse=True, scope="session")
def live_logging(pytestconfig, cleanup_loguru):
    logging_plugin = pytestconfig.pluginmanager.getplugin("logging-plugin")
    level = logging_plugin.log_cli_level
    handler_id = logger.add(
        logging_plugin.log_cli_handler,
        level="WARNING" if level is None else level,
        format="{message}",
    )
    yield
    logger.remove(handler_id)

@pytest.fixture(autouse=True, scope="session")
def file_logging(pytestconfig, cleanup_loguru):
    logging_plugin = pytestconfig.pluginmanager.getplugin("logging-plugin")
    level = logging_plugin.log_file_level
    handler_id = logger.add(
        logging_plugin.log_file_handler,
        level="WARNING" if level is None else level,
        format="{message}",
    )
    yield
    logger.remove(handler_id)

However, this is a bit verbose. Instead, we can make use of the PropagateHandler documented by Loguru:

class PropagateHandler(logging.Handler):
    def emit(self, record):
        logger = logging.getLogger(record.name)
        if logger.isEnabledFor(record.levelno):
            logger.handle(record)

@pytest.fixture(autouse=True, scope="session")
def cleanup_loguru():
    # Remove all handlers to make sure we don't interfere with tests.
    logger.remove()

@pytest.fixture(autouse=True, scope="session")
def propagate_loguru(cleanup_loguru):
    handler_id = logger.add(PropagateHandler(), format="{message}")
    yield
    logger.remove(handler_id)

Note that in both cases I'm relying on a cleanup_loguru fixture which will remove the logs emitted to stderr.

Adding this to conftest.py seems to work well with Pytest, just as when using standard logging. Can you confirm that? If so, I'll update the documentation.

Not precisely as I expected, the output is

INFO     test_loguru_demo:test_loguru_demo.py:6 info message
ERROR    test_loguru_demo:test_loguru_demo.py:7 error message

My expectation is

2022-11-18 19:08:03.143 | INFO     | test_loguru_demo:test_log:6 - info message
2022-11-18 19:08:03.143 | ERROR    | test_loguru_demo:test_log:7 - error message

The format has been changed.

I tried the following conftest.py to change format

from loguru import logger
import logging
import pytest
from _pytest.logging import LogCaptureFixture

_format = "<green>{time:YYYY-MM-DD HH:mm:ss.SSS}</green> | <level>{level: <8}</level> | <cyan>{name}</cyan>:<cyan>{function}</cyan>:<cyan>{line}</cyan> - <level>{message}</level>"
# @pytest.fixture()
# def caplog(caplog: LogCaptureFixture):
#     """
#     Make pytest work with loguru. See:
#     https://loguru.readthedocs.io/en/stable/resources/migration.html#making-things-work-with-pytest-and-caplog
#     """
#     handler_id = logger.add(caplog.handler, format="{message}")
#     yield caplog
#     logger.remove(handler_id)

class PropagateHandler(logging.Handler):
    def emit(self, record):
        logger = logging.getLogger(record.name)
        if logger.isEnabledFor(record.levelno):
            logger.handle(record)

@pytest.fixture(autouse=True, scope="session")
def cleanup_loguru():
    # Remove all handlers to make sure we don't interfere with tests.
    logger.remove()

@pytest.fixture(autouse=True, scope="session")
def propagate_loguru(cleanup_loguru):
    handler_id = logger.add(PropagateHandler(), format=_format)
    yield
    logger.remove(handler_id)

@pytest.fixture
def my_value():
    """
    Some random value
    """
    return 5

But the out is

INFO     test_loguru_demo:test_loguru_demo.py:6 2022-11-21 10:17:36.086 | INFO     | test_loguru_demo:test_log:6 - info message
ERROR    test_loguru_demo:test_loguru_demo.py:7 2022-11-21 10:17:36.086 | ERROR    | test_loguru_demo:test_log:7 - error message

This output is also weird

Well, there is a kind of competition between loguru and the standard logging to format the messages. We can chose one, but not both.

Either we use format="{message}" and the message will be formatted with whatever Pytest configured the standard handlers (LogCaptureHandler, _LiveLoggingStreamHandler, _FileHandler all have their own Formatter), either we decide to use the Loguru formatter and remove format="{message}" but then we have to override the Pytest format by specifying --log-format="%(message)s" in the command line. It should produce the output you're expecting.

Delgan / loguru

When using loguru and pytest-loguru plugin, all logs (all level log)will output in terminal even though I add option `--log-level=INFO` or `--log-cli-level=INFO` #751