Testing logging seems broken in pytest 8

[hugobuddel]

pytest 8 seems to break some of our tests, and perhaps our code as well. The order of the tests suddenly matter, and it is related to logging:

pip install pytest==8.2.1

This works fine:

python -m pytest -x --pdb \
    scopesim/tests/tests_effects/test_Quantization.py::TestApplyTo::test_logs_warning_for_float_dtype \
    scopesim/tests/test_logging.py::test_log_to_file 

This fails:

python -m pytest -x --pdb \
    scopesim/tests/test_logging.py::test_log_to_file \
    scopesim/tests/tests_effects/test_Quantization.py::TestApplyTo::test_logs_warning_for_float_dtype

with

==== test session starts =====
platform linux -- Python 3.11.5, pytest-8.2.1, pluggy-1.5.0
rootdir: .../ScopeSim
configfile: pyproject.toml
plugins: cov-5.0.0, anyio-4.3.0
collected 2 items                                                                                                                          

scopesim/tests/test_logging.py .                                                                                                     [ 50%]
scopesim/tests/tests_effects/test_Quantization.py F
>>>> captured stdout >>>>
astar.scopesim.effects.electronic - WARNING: Cannot access cmds for Quantization effect.
astar.scopesim.effects.electronic - WARNING: Setting quantized data to dtype <class 'float'>, which is not an integer subtype.
>>>> traceback >>>>

self = <scopesim.tests.tests_effects.test_Quantization.TestApplyTo object at 0x7f014d714a10>
det = <scopesim.detector.detector.Detector object at 0x7f014d70f2d0>, caplog = <_pytest.logging.LogCaptureFixture object at 0x7f014d70a5d0>

    def test_logs_warning_for_float_dtype(self, det, caplog):
        assert det.data.sum() > det.data.size * 1.2
        quant = Quantization(dtype=float)
        det = quant.apply_to(det)
        assert det.data.sum() == det.data.size
        # Test sub-dtype because exact dtype for "float" may depend on OS
        assert np.issubdtype(det.data.dtype, np.floating)
>       assert "Setting quantized data to dtype" in caplog.text
E       AssertionError: assert 'Setting quantized data to dtype' in ''
E        +  where '' = <_pytest.logging.LogCaptureFixture object at 0x7f014d70a5d0>.text

scopesim/tests/tests_effects/test_Quantization.py:56: AssertionError
>>>> entering PDB >>>>

>>>> PDB post_mortem (IO-capturing turned off) >>>
> .../ScopeSim/scopesim/tests/tests_effects/test_Quantization.py(56)test_logs_warning_for_float_dtype()
-> assert "Setting quantized data to dtype" in caplog.text

[hugobuddel]

It is already broken in pytest 7 if both tests are in the same file. Kinda ~MVP:

import logging
import pytest
import numpy as np
import scopesim
from scopesim.detector import Detector
from scopesim.effects.electronic import Quantization
from scopesim.tests.mocks.py_objects.header_objects import _implane_header

base_logger = logging.getLogger("astar")
print("HB7", base_logger.handlers)
scopesim.log_to_file(enable=True)
print("HB8", base_logger.handlers)
scopesim.log_to_file(enable=False)
print("HB9", base_logger.handlers)


def test_log_to_file():
    base_logger = logging.getLogger("astar")
    print("HB1", base_logger.handlers)
    scopesim.log_to_file(enable=True)
    print("HB2", base_logger.handlers)
    assert any(handler.name == "file" for handler in base_logger.handlers)
    scopesim.log_to_file(enable=False)
    print("HB3", base_logger.handlers)
    assert not any(handler.name == "file" for handler in base_logger.handlers)


def test_logs_warning_for_float_dtype(caplog):
    base_logger = logging.getLogger("astar")
    print("HB6", base_logger.handlers)

    det = Detector(_implane_header())
    width = det._hdu.data.shape[1]
    det._hdu.data[:] = 1.2
    det._hdu.data[:, width // 2] = 1.99

    assert det.data.sum() > det.data.size * 1.2
    quant = Quantization(dtype=float)
    det = quant.apply_to(det)
    assert det.data.sum() == det.data.size
    # Test sub-dtype because exact dtype for "float" may depend on OS
    assert np.issubdtype(det.data.dtype, np.floating)
    assert "Setting quantized data to dtype" in caplog.text

This will print

HB7 [<StreamHandler <stdout> (INFO)>]
HB8 [<StreamHandler <stdout> (INFO)>, <RotatingFileHandler /mnt/bulk/hugo/repos/scopesim/ScopeSim/.scopesim.log (DEBUG)>]
HB9 [<StreamHandler <stdout> (INFO)>]

HB1 []
HB2 [<StreamHandler <stdout> (INFO)>, <RotatingFileHandler /mnt/bulk/hugo/repos/scopesim/ScopeSim/.scopesim.log (DEBUG)>]
HB3 [<StreamHandler <stdout> (INFO)>]              

HB6 [<StreamHandler <stdout> (INFO)>]

and then raises an AssertionError for the last line.

Commenting out test_log_to_file() prints:

HB7 [<StreamHandler <stdout> (INFO)>]
HB8 [<StreamHandler <stdout> (INFO)>, <RotatingFileHandler /mnt/bulk/hugo/repos/scopesim/ScopeSim/.scopesim.log (DEBUG)>]
HB9 [<StreamHandler <stdout> (INFO)>]

HB6 []

and then succeeds.

So for some reason, the tests are ran without any logging handlers set. And test_logs_warning_for_float_dtype actually requires that no logging handlers are set. However, test_log_to_file sets the handlers, so test_logs_warning_for_float_dtype fails.

The difference between pytest 7 and 8 is that the handlers get reset between files in pytest 7, but not in pytest 8.

I don't really have a proper mental model of what is happening. I would have expected that the tests would have the same logging setup as you'd get upon initialization, but this is apparently not the case.

[hugobuddel]

Ah! configure_logging() in conftest.py is supposed to fix this problem:

@pytest.fixture(scope="package", autouse=True)
def configure_logging():
    base_logger = logging.getLogger("astar")
    handlers = base_logger.handlers
    # Disable handlers
    base_logger.handlers = []
    # Make sure logging can reach pytest's caplog
    base_logger.propagate = True
    yield
    # Restore
    base_logger.handlers = handlers
    base_logger.propagate = False

So configure_logging() disables the handlers, but it is only ran once since its scope is package. Then test_log_to_file() calls log_to_file(), which calls update_logging(), which resets the handles for any test afterwards. But in pytest 7, configure_logging() was ran for every file, or maybe for every sub-package.

Changing the scope of configure_logging() to function seems to fix the problem.