I/O operation on closed file after monkeypatching logging.root.handlers

[sashkab]

I've ran into strange issue with pytest-catchlog. I have a fairly large test suite, and one of the tests has to run without any loggers in order to test functionality. I use monkeypatch to patch it:

    monkeypatch.setattr(logging.root, 'handlers', [])

I've setup test repository -- https://github.com/sashkab/catchlog-failure, but here are tests:

from __future__ import absolute_import
import logging

from module import *


def test_one(monkeypatch, capsys):
    monkeypatch.setattr(logging.root, 'handlers', [])
    one()
    assert capsys.readouterr() == ('one', '')


def test_two(caplog, capsys):
    two()

    assert caplog.records[-1].msg == 'two'
    assert capsys.readouterr() == ('', '')

Test test_one passes and works as expected:

~/Work/catchlog-failure/src (master) $ python -mpytest module -k test_one
================================================ test session starts =================================================
platform darwin -- Python 2.7.11, pytest-2.9.1, py-1.4.31, pluggy-0.3.1
rootdir: /Users/b/.tmp/catchlog-failure/src/module, inifile:
plugins: catchlog-1.2.2, cov-2.2.1, pyq-1.1
collected 2 items

module/tests/test_module.py .

========================================= 1 tests deselected by '-ktest_one' =========================================
======================================= 1 passed, 1 deselected in 0.01 seconds =======================================

Then I've got second test -- test_two, which requires logger and it passes by itself perfectly fine.

~/Work/catchlog-failure/src (master) $ python -mpytest module -k test_two
================================================ test session starts =================================================
platform darwin -- Python 2.7.11, pytest-2.9.1, py-1.4.31, pluggy-0.3.1
rootdir: /Users/b/.tmp/catchlog-failure/src/module, inifile:
plugins: catchlog-1.2.2, cov-2.2.1, pyq-1.1
collected 2 items

module/tests/test_module.py .

========================================= 1 tests deselected by '-ktest_two' =========================================
======================================= 1 passed, 1 deselected in 0.01 seconds =======================================

But when I try to run both of tests together, I end up with the following error:

~/Work/catchlog-failure/src (master) $ python -mpytest module
================================================ test session starts =================================================
platform darwin -- Python 2.7.11, pytest-2.9.1, py-1.4.31, pluggy-0.3.1
rootdir: /Users/b/.tmp/catchlog-failure/src/module, inifile:
plugins: catchlog-1.2.2, cov-2.2.1, pyq-1.1
collected 2 items

module/tests/test_module.py .F

====================================================== FAILURES ======================================================
______________________________________________________ test_two ______________________________________________________

caplog = <pytest_catchlog.CompatLogCaptureFixture object at 0x772d790>
capsys = <_pytest.capture.CaptureFixture instance at 0x77298a0>

    def test_two(caplog, capsys):
        two()

        assert caplog.records[-1].msg == 'two'
>       assert capsys.readouterr() == ('', '')
E       assert ('', 'Traceba...py, line 12\n') == ('', '')
E         At index 1 diff: u'Traceback (most recent call last):\n  File "/usr/local/Cellar/python/2.7.11/Frameworks/Python.framework/Versions/2.7/lib/python2.7/logging/__init__.py", line 874, in emit\n    stream.write(fs % msg)\n  File "/Users/b/.virtualenvs/d/lib/python2.7/site-packages/py/_io/capture.py", line 16, in write\n    StringIO.write(self, data)\nValueError: I/O operation on closed file\nLogged from file __init__.py, line 12\n' != ''
E         Use -v to get the full diff

module/tests/test_module.py:17: AssertionError
------------------------------------------------- Captured log call --------------------------------------------------
__init__.py                 12 INFO     two
========================================= 1 failed, 1 passed in 0.01 seconds =========================================

Here is traceback for easier reading:

Traceback (most recent call last):
  File "/usr/local/Cellar/python/2.7.11/Frameworks/Python.framework/Versions/2.7/lib/python2.7/logging/__init__.py", line 874, in emit
    stream.write(fs % msg)
  File "/Users/b/.virtualenvs/d/lib/python2.7/site-packages/py/_io/capture.py", line 16, in write
    StringIO.write(self, data)
    ValueError: I/O operation on closed file
Logged from file __init__.py, line 12

So, it seems like pytest-catchlog doesn't properly handle the case where logging.root.handlers where monkeypatched in the tests.

[abusalimov]

Thank you for such a detailed report!

I can't tell for sure what the actual reason is, but I suspect that the following steps could lead to the error in question:

1. catchlog hook wrapper creates a handler before running the first test case
2. catchlog attaches that newly create handler to the root logger
3. the test case mokey patches the root.handlers list holding our handler
4. catchlog attempts to detach its handler, but it's not on the list, i.e. nothing happens
5. catchlog closes the handler
6. monkeypatch plugin restores the original value of the root.handlers as part of its cleanup routine

At this point we've got the closed handler leaked through the root.handlers list. And it just complains about a closed underlying stream on the very next log call.

We could add a (rather dirty, IMHO) workaround, that would remove the handler from the very list it was originally attached to, but just doesn't feel to be the right solution...
Out of curiosity, what is the exact problem you're solving by monkey patching the root logger?

[sashkab]

I was under impression, that pytest-catchlog would attach only in tests, which use caplog fixture, but it seems it's not the case.

In any case, my workaround was to delete all existing LogCaptureHandler from logging.root.handlers in the second test instead of monkeypatching it.

As a workaround, I've modified test_one:

Removed:

    monkeypatch.setattr(logging.root, 'handlers', [])

And added:

    from pytest_catchlog import LogCaptureHandler

    for h in logging.root.handlers:
        if isinstance(h, LogCaptureHandler):
            logging.root.removeHandler(h)

[abusalimov]

I was under impression, that pytest-catchlog would attach only in tests, which use caplog fixture, but it seems it's not the case.

Yes, it needs a handler for every test case in order to provide proper reporting section in case of a test failure.

[markfink]

sorry to intrude. it appears like I am suffering from that, too. is there a workaround for that?

[sashkab]

@markfink did you try my workaround #41 (comment)

[markfink]

@sashkab thank you for the advice. I understand that this workaround needs to be applied within every test which is not really an option for me. Do you think it works to wrap the "caplog" fixture into like caplog2 to remove the handlers?