Question: Why does pytest not recognise AssertionError when enqueue=True?

[codeananda]

In conftest.py I have redefined caplog as per loguru's docs. I have enqueue=True because some of my code uses multiprocessing.

@pytest.fixture
def caplog(caplog: LogCaptureFixture):
    """Redefine caplog to work with loguru, taken from their docs
    """
    handler_id = logger.add(
        caplog.handler,
        format="{message}",
        level=0,
        filter=lambda record: record["level"].no >= caplog.handler.level,
        enqueue=True,  # Set to 'True' if your test is spawning child processes.
    )
    yield caplog
    logger.remove(handler_id)

I have a basic test which works when enqueue=False but not when enqueue=True. It works if I copy/paste the contents of assert_no_errors_logged underneath the test. But if I call assert_no_errors_logged, pytest complains. This is not an issue if enqueue=False.

def test_errors_are_caught(caplog):
    logger.debug("debug message")
    logger.info("an info")
    logger.error("an error")
    logger.critical("a very bad thing")
    with pytest.raises(AssertionError):
        assert_no_errors_logged(caplog)

def assert_no_errors_logged(caplog):
    error_messages = [record for record in caplog.records if record.levelno >= logging.ERROR]
    num_errors = len(error_messages)
    assert num_errors == 0

Error

============================== 1 failed in 0.28s ==============================
FAILED                [100%]2024-07-15 14:38:33.327 | DEBUG    | test_compute_statistics:test_errors_are_caught:440 - debug message
2024-07-15 14:38:33.327 | INFO     | test_compute_statistics:test_errors_are_caught:441 - an info
2024-07-15 14:38:33.327 | ERROR    | test_compute_statistics:test_errors_are_caught:442 - an error
2024-07-15 14:38:33.327 | CRITICAL | test_compute_statistics:test_errors_are_caught:443 - a very bad thing

tests\unit\test_compute_statistics.py:438 (test_errors_are_caught)
caplog = <_pytest.logging.LogCaptureFixture object at 0x000001A41CBB4550>

    def test_errors_are_caught(caplog):
        logger.debug("debug message")
        logger.info("an info")
        logger.error("an error")
        logger.critical("a very bad thing")
>       with pytest.raises(AssertionError):
E       Failed: DID NOT RAISE <class 'AssertionError'>

test_compute_statistics.py:444: Failed

Process finished with exit code 1

[Delgan]

Have you tried to call logger.complete() before assert_no_errors_logged()?

When enqueue=True, messages are not immediately logged: they are added to a queue and processed by a background thread. I think your test is failing because when assert_no_errors_logged() is called, not all logs reached the caplog sink yet. Adding a call to logger.complete() ensures there is no pending logs remaining.

[codeananda]

Aha! Yes logger.complete() makes it work. Thanks

[codeananda]

But hmm, does this mean I always have to call logger.complete() before assert_no_errors_logged()?

[Delgan]

But hmm, does this mean I always have to call logger.complete() before assert_no_errors_logged()?

Maybe that works as well if logger.complete() is called at the beginning of assert_no_errors_logged()?

You can also turn off the enqueue option for such simple tests.