Pytest 3.3: cannot mock root logger

[CaselIT]

Pytest 3.3.0 uses the root logger in each test so it can no longer be mocked with monkeypatch

import logging
import pytest
from unittest.mock import MagicMock
@pytest.fixture
def setup(monkeypatch):
    mock = MagicMock()
    monkeypatch.setattr('logging.getLogger', lambda: mock) 
    return mock
def test_x(setup, monkeypatch):
    assert id(setup) == id(logging.getLogger())

raires

TypeError: <lambda>() takes 0 positional arguments but 1 was given
<python-path>\lib\contextlib.py:81: TypeError

changing the lambda to lambda _: mock raises

TypeError: '<' not supported between instances of 'int' and 'MagicMock'
<python-path>\lib\contextlib.py:81: TypeError

Moving the monkeypatch call in the function does not help since the second error is always raised.
The error is raised in <python-path>\lib\site-packages\_pytest\logging.py on line 102 or 110

Using the --no-print-logs flag does not change the output

Pytest 3.2.5 does not have this problem

Also if there are subsequent tests after the one that caused the previous error, pytest crashes completely: appending

def test_y():
    assert True

after test_x in the example above results in the following error when running pytest without filters

x_test.py FE                                                             [100%]
INTERNALERROR> Traceback (most recent call last):
INTERNALERROR>   File "<python-path>\lib\site-packages\_pytest\main.py", line 103, in wrap_session
INTERNALERROR>     session.exitstatus = doit(config, session) or 0
INTERNALERROR>   File "<python-path>\lib\site-packages\_pytest\main.py", line 141, in _main
INTERNALERROR>     config.hook.pytest_runtestloop(session=session)
INTERNALERROR>   File "<python-path>\lib\site-packages\pluggy\__init__.py", line 617, in __call__
INTERNALERROR>     return self._hookexec(self, self._nonwrappers + self._wrappers, kwargs)
INTERNALERROR>   File "<python-path>\lib\site-packages\pluggy\__init__.py", line 222, in _hookexec
INTERNALERROR>     return self._inner_hookexec(hook, methods, kwargs)
INTERNALERROR>   File "<python-path>\lib\site-packages\pluggy\__init__.py", line 216, in <lambda>
INTERNALERROR>     firstresult=hook.spec_opts.get('firstresult'),
INTERNALERROR>   File "<python-path>\lib\site-packages\pluggy\callers.py", line 201, in _multicall
INTERNALERROR>     return outcome.get_result()
INTERNALERROR>   File "<python-path>\lib\site-packages\pluggy\callers.py", line 76, in get_result
INTERNALERROR>     raise ex[1].with_traceback(ex[2])
INTERNALERROR>   File "<python-path>\lib\site-packages\pluggy\callers.py", line 180, in _multicall
INTERNALERROR>     res = hook_impl.function(*args)
INTERNALERROR>   File "<python-path>\lib\site-packages\_pytest\main.py", line 164, in pytest_runtestloop
INTERNALERROR>     item.config.hook.pytest_runtest_protocol(item=item, nextitem=nextitem)
INTERNALERROR>   File "<python-path>\lib\site-packages\pluggy\__init__.py", line 617, in __call__
INTERNALERROR>     return self._hookexec(self, self._nonwrappers + self._wrappers, kwargs)
INTERNALERROR>   File "<python-path>\lib\site-packages\pluggy\__init__.py", line 222, in _hookexec
INTERNALERROR>     return self._inner_hookexec(hook, methods, kwargs)
INTERNALERROR>   File "<python-path>\lib\site-packages\pluggy\__init__.py", line 216, in <lambda>
INTERNALERROR>     firstresult=hook.spec_opts.get('firstresult'),
INTERNALERROR>   File "<python-path>\lib\site-packages\pluggy\callers.py", line 201, in _multicall
INTERNALERROR>     return outcome.get_result()
INTERNALERROR>   File "<python-path>\lib\site-packages\pluggy\callers.py", line 76, in get_result
INTERNALERROR>     raise ex[1].with_traceback(ex[2])
INTERNALERROR>   File "<python-path>\lib\site-packages\pluggy\callers.py", line 180, in _multicall
INTERNALERROR>     res = hook_impl.function(*args)
INTERNALERROR>   File "<python-path>\lib\site-packages\_pytest\runner.py", line 63, in pytest_runtest_protocol
INTERNALERROR>     runtestprotocol(item, nextitem=nextitem)
INTERNALERROR>   File "<python-path>\lib\site-packages\_pytest\runner.py", line 71, in runtestprotocol
INTERNALERROR>     rep = call_and_report(item, "setup", log)
INTERNALERROR>   File "<python-path>\lib\site-packages\_pytest\runner.py", line 159, in call_and_report
INTERNALERROR>     report = hook.pytest_runtest_makereport(item=item, call=call)
INTERNALERROR>   File "<python-path>\lib\site-packages\pluggy\__init__.py", line 617, in __call__
INTERNALERROR>     return self._hookexec(self, self._nonwrappers + self._wrappers, kwargs)
INTERNALERROR>   File "<python-path>\lib\site-packages\pluggy\__init__.py", line 222, in _hookexec
INTERNALERROR>     return self._inner_hookexec(hook, methods, kwargs)
INTERNALERROR>   File "<python-path>\lib\site-packages\pluggy\__init__.py", line 216, in <lambda>
INTERNALERROR>     firstresult=hook.spec_opts.get('firstresult'),
INTERNALERROR>   File "<python-path>\lib\site-packages\pluggy\callers.py", line 196, in _multicall
INTERNALERROR>     gen.send(outcome)
INTERNALERROR>   File "<python-path>\lib\site-packages\_pytest\skipping.py", line 264, in pytest_runtest_makereport
INTERNALERROR>     elif item._skipped_by_mark and rep.skipped and type(rep.longrepr) is tuple:
INTERNALERROR> AttributeError: 'Function' object has no attribute '_skipped_by_mark'

Selecting only test_x does not raises the AttributeError
I'm on windows 10 with python 3.6.3, but I've confirmed the same bug on linux under python 3.5 and 3.6

[nicoddemus]

Thanks @CaselIT

I will take a look later when I have more time, but just wanted to mention that you can disable the builtin logging plugin by passing -p no:logging to pytest as a workaround for now.

[CaselIT]

Thanks @nicoddemus for the quick answer.

Indeed -p no:logging works as a workaround. Thanks for the heads up

[CaselIT]

I can no longer reproduce the original bug with pytest > 3.4.0, Thanks for fixing it!

The logging module continues to use the mocked value though. This:

import pytest
from unittest.mock import MagicMock
@pytest.fixture
def setup(monkeypatch):
    mock = MagicMock()
    monkeypatch.setattr('logging.getLogger', lambda: mock)
    return mock
def test_x(setup):
    assert setup.mock_calls == []

fails since the mock has the calls: [call.handlers.__contains__(<LogCaptureHandler (NOTSET)>), call.addHandler(<LogCaptureHandler (NOTSET)>)]

Resetting the mock with reset_mock() at the beginning of the test can be used as workaround

Let me know if you prefer if I open a new issue for this

[nicoddemus]

Thanks @CaselIT for the feedback, I'm closing this one then.

The logging module continues to use the mocked value though

Yeah by the time your fixture executes, _pytest.logging has already called logging.getLogger.

It is not possible to use a fixture to monkeypatch logging.getLogger because we need to have a logger installed already to capture logging from fixtures itself.

[CaselIT]

Thanks for the clarification.
Maybe there should be a mention in the monkeypatch documentation about it? I could add a pr for it to add a brief note at the bottom

[nicoddemus]

It is not really related to monkeypatch, but about trying to monkeypatch logging.getLogger... what note would you like to add?

[CaselIT]

Something like:

Note: Using monkeypatch to patch logging.getLogger inside a fixture can interfere with the logging module. Consider moving the patch call inside the body of the test function

And maybe a reference to this issue

[nicoddemus]

Unfortunately this issue is not isolated to logging, there are probably a multitude of functions that could cause various problems if monkeypatched, and is not feasible to start listing them all (for example, os.open, shutil.copy, sys.stdout.fileno are all examples that would also cause various problems, just from the top of my head). Because of that, I think it is not very helpful to add a note about this specific use case, this is not something people usually do I believe

It is probably sufficient to have this discussion here so others can find.

But really, we do appreciate the willingness to contribute a patch! 👍

[CaselIT]

multitude of functions that could cause various problems if monkeypatched

I was not thinking about them. I agree that this is a bit of an edge case.

Out of curiosity, premising that I'm not familiar with the internasl of pytest, wouldn't it worth considering making the logging module cache the root logger at the startup of pytest so it's not affected by patching and other modifications? And/or replace it with a child of the original root logger?

[nicoddemus]

Out of curiosity, premising that I'm not familiar with the internasl of pytest, wouldn't it worth considering making the logging module cache the root logger at the startup of pytest so it's not affected by patching and other modifications? And/or replace it with a child of the original root logger?

Good question, but we probably don't want to make any logging calls until the plugin is actually "activated" (users can disable the plugin by passing -p no:logging in the command line).

[CaselIT]

Yes, of course, it should take into consideration the flag -p no:logging. Again I'm not familiar at all with the internals of pytest, so it may be totally unfeasible doing what I suggested

[mikenerone]

BTW, you can still patch getLogger() in a fixture - just patch it with a function that only applies the patch for non-root loggers. As an extra precaution, I would also exclude loggers with "pytest" in the name. E.g.

@pytest.fixture(autouse=True)
def _always_patch_loggers(mocker):
    real_get_logger = logging.getLogger

    def get_patched_logger(name=None):
        logger = real_get_logger(name)
        if not isinstance(logger._log, mocker.Mock) and name and 'pytest' not in name:
            mocker.patch.object(logger, '_log')
        return logger

    mocker.patch.object(logging, 'getLogger', side_effect=get_patched_logger)

(Oh, and I'm using pytest-mock here - adapt if you want to use monkeypatch.)