Pytest: ValueError: I/O operation on closed file

[pytestbot]

Originally reported by: Alfredo Deza (BitBucket: alfredodeza, GitHub: alfredodeza)

---

There is a problem with the logging module and py.test

Error in atexit._run_exitfuncs:
Traceback (most recent call last):
  File "/System/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/atexit.py", line 24, in _run_exitfuncs
    func(*targs, **kargs)
  File "/System/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/logging/__init__.py", line 1472, in shutdown
Error in atexit._run_exitfuncs:
Traceback (most recent call last):
  File "/System/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/atexit.py", line 24, in _run_exitfuncs
    func(*targs, **kargs)
  File "/System/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/logging/__init__.py", line 1472, in shutdown
    h.flush()
  File "/System/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/logging/__init__.py", line 740, in flush
    self.stream.flush()
    h.flush()
ValueError: I/O operation on closed file

It seems that if it runs with the '-s' flag it doesn't do this anymore.

---

• Bitbucket: https://bitbucket.org/pytest-dev/pytest/issue/14

[pytestbot]

_Original comment by_ holger krekel (BitBucket: hpk42, GitHub: hpk42):

---

fix issue14 : it was actually issue14 instead of issue8 that was fixed with
the older https://bitbucket.org/hpk42/pytest/changeset/1c3eb86502b3

please try out with the usual "pip install -i http://pypi.testrun.org -U pytest"

[pytestbot]

_Original comment by_ Adam Wagner (BitBucket: awagner83, GitHub: awagner83):

---

This fixes it for me.

[pytestbot]

_Original comment by_ Alfredo Deza (BitBucket: alfredodeza, GitHub: alfredodeza):

---

I can confirm this gets fixed with the update. Sorry for not reporting it sooner...

[pytestbot]

_Original comment by_ eduardo schettino (BitBucket: schettino72, GitHub: schettino72):

---

there is still a problem with this when used with capsys...

{{{

!python

(py26)~/work/xxx$ cat bug14.py
import logging
def test_133(capsys):
logging.error('x')

(py26)~/work/xxx$ py.test bug14.py
================================================ test session starts =================================================
platform linux2 -- Python 2.6.6 -- pytest-2.0.2
collected 1 items

bug14.py .

============================================== 1 passed in 0.01 seconds ==============================================
Error in atexit._run_exitfuncs:
Traceback (most recent call last):
File "/usr/lib/python2.6/atexit.py", line 24, in _run_exitfuncs
func(_targs, *_kargs)
File "/usr/lib/python2.6/logging/__init__.py", line 1516, in shutdown
h.flush()
File "/usr/lib/python2.6/logging/init.py", line 762, in flush
self.stream.flush()
File "/usr/lib/python2.6/io.py", line 1488, in flush
self.buffer.flush()
ValueError: I/O operation on closed file.
Error in sys.exitfunc:
Traceback (most recent call last):
File "/usr/lib/python2.6/atexit.py", line 24, in _run_exitfuncs
func(_targs, *_kargs)
File "/usr/lib/python2.6/logging/__init__.py", line 1516, in shutdown
h.flush()
File "/usr/lib/python2.6/logging/init.py", line 762, in flush
self.stream.flush()
File "/usr/lib/python2.6/io.py", line 1488, in flush
self.buffer.flush()
ValueError: I/O operation on closed file.

}}}

[pytestbot]

_Original comment by_ holger krekel (BitBucket: hpk42, GitHub: hpk42):

---

can you quickly try with "pip install -U -i http://pypi.testrun.org pytest" which should get you 2.0.3.dev3 and fix the issue? (To be honest, i am not yet sure why it is fixed, but i'd rather first check if it works for you as well)

[pytestbot]

_Original comment by_ Ronny Pfannschmidt (BitBucket: RonnyPfannschmidt, GitHub: RonnyPfannschmidt):

---

still in trunk

[pytestbot]

_Original comment by_ Ronny Pfannschmidt (BitBucket: RonnyPfannschmidt, GitHub: RonnyPfannschmidt):

---

this would probably best be fixed by integrating logcapture into pytest

[pytestbot]

_Original comment by_ Ronny Pfannschmidt (BitBucket: RonnyPfannschmidt, GitHub: RonnyPfannschmidt):

---

as a extra note, it seems this is version specific to python2.7

[pytestbot]

_Original comment by_ holger krekel (BitBucket: hpk42, GitHub: hpk42):

---

i can't reproduce this with my py27/py33 and pytest-trunk anymore

[pytestbot]

_Original comment by_ Alfredo Deza (BitBucket: alfredodeza, GitHub: alfredodeza):

---

I am not consistently hitting this with Python 2.6

#!text

 py.test -v
================================================ test session starts =================================================
platform darwin -- Python 2.6.7 -- pytest-2.3.5 -- /Users/alfredo/python/ceph-deploy/.tox/py26/bin/python2.6
collected 28 items

tests/test_cli.py:5: test_help PASSED
tests/test_cli.py:16: test_bad_command PASSED
tests/test_cli.py:28: test_bad_cluster PASSED
tests/test_cli_install.py:13: test_help PASSED
tests/test_cli_install.py:24: test_bad_no_host PASSED
tests/test_cli_install.py:36: test_simple PASSED
tests/test_cli_mon.py:13: test_help PASSED
tests/test_cli_mon.py:24: test_bad_no_conf PASSED
tests/test_cli_mon.py:36: test_bad_no_mon PASSED
tests/test_cli_mon.py:50: test_simple PASSED
tests/test_cli_new.py:13: test_help PASSED
tests/test_cli_new.py:24: test_write_global_conf_section PASSED
tests/test_cli_new.py:49: test_uuid PASSED
tests/test_cli_new.py:67: test_mons PASSED
tests/test_cli_new.py:73: test_defaults PASSED
tests/test_cli_osd.py:13: test_help PASSED
tests/test_cli_osd.py:24: test_bad_no_conf PASSED
tests/test_cli_osd.py:36: test_bad_no_disk PASSED
tests/test_cli_osd.py:49: test_simple PASSED
tests/test_conf.py:5: test_simple PASSED
tests/test_conf.py:14: test_indent_space PASSED
tests/test_conf.py:23: test_indent_tab PASSED
tests/test_conf.py:32: test_words_underscore PASSED
tests/test_conf.py:42: test_words_space PASSED
tests/test_conf.py:52: test_words_many PASSED
tests/test_mon.py:30: TestCatchCommonErrors.test_warn_if_no_intial_members PASSED
tests/test_mon.py:36: TestCatchCommonErrors.test_warn_if_not_mon_in_monmap PASSED
tests/test_mon.py:42: TestCatchCommonErrors.test_warn_if_not_public_addr_and_not_public_netw PASSED

============================================= 28 passed in 2.81 seconds ==============================================
Error in atexit._run_exitfuncs:
Traceback (most recent call last):
  File "/System/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/atexit.py", line 24, in _run_exitfuncs
    func(*targs, **kargs)
  File "/System/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/logging/__init__.py", line 1516, in shutdown
    h.flush()
  File "/System/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/logging/__init__.py", line 762, in flush
    self.stream.flush()
  File "/System/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/io.py", line 1488, in flush
    self.buffer.flush()
ValueError: I/O operation on closed file.
Error in sys.exitfunc:
Traceback (most recent call last):
  File "/System/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/atexit.py", line 24, in _run_exitfuncs
    func(*targs, **kargs)
  File "/System/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/logging/__init__.py", line 1516, in shutdown
    h.flush()
  File "/System/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/logging/__init__.py", line 762, in flush
    self.stream.flush()
  File "/System/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/io.py", line 1488, in flush
    self.buffer.flush()
ValueError: I/O operation on closed file.

This only happens if I use capsys. As soon as I stop using it the error goes away.

[jfitzpatrick99]

I am hitting this with pytest 2.7.2 and python 2.7.2. The issue seems to occur if the logger I use is instantiated at the module level instead of inside a module function.

[nicoddemus]

Hi @jfitzpatrick99, can you provide a small example which reproduces the problem?

[jfitzpatrick99]

@nicoddemus I just tried putting together a small reproducer but at the moment I can only reproduce with my entire application. I will see if I can get something together for tomorrow.

[nicoddemus]

@jfitzpatrick99 thanks! :smile:

[shapiy]

I have encountered this issue when running parametrised tests. The test for the first parameter value always passes, but the next ones fail.

Pytest 2.8.1
Python 2.7.6

[The-Compiler]

@shapiy Could you maybe show an example which reproduces the issue, or if it happens in a public codebase, do you have a link?

[shapiy]

Unfortunately, the code I am working on is not available for public. The problem is very similar to @jfitzpatrick99's : the issue reproduces in the context only.

Actually, I'm not sure if pytest is to blame. It could be any other component in the system.

[shapiy]

@The-Compiler, here's a sample:

@pytest.mark.parametrize('param', [1 ,2])
def test_logging(param, capsys):
    logging.basicConfig(level=logging.DEBUG, stream=sys.stdout)
    logger = logging.getLogger('test')
    logger.info('A')

    out, err = capsys.readouterr()
    print(err)
    assert 'A' in out

Will pass for the first test, but will fail for the second:

---------------------------------------------------------------------------------------- Captured stdout call -----------------------------------------------------------------------------------------
Traceback (most recent call last):
  File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/logging/__init__.py", line 880, in emit
    stream.write(fs % msg)
  File "/Users/shapiy/.virtualenv/dev/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 capsys_test.py, line 20

[RonnyPfannschmidt]

Passing a concrete captured stream that will be closed without removing its handler in teardown is bound to fail

Not even the pending merge of log capturing can fix that particular usage pattern

[bilderbuchi]

@RonnyPfannschmidt I just hit the exact same issue as @shapiy above when testing if logging output of my package is correct. What _is_ the correct usage pattern to do this with pytest?

[nicoddemus]

What is the correct usage pattern to do this with pytest?

Short answer (IMO) is to use pytest-catchlog which provides great integration with the logging package, including a caplog fixture to capture logging output.

Long answer:

The problem is (please correct me @RonnyPfannschmidt):

logging.basicConfig(level=logging.DEBUG, stream=sys.stdout)

sys.stdout at this point is a StringIO object installed by the capsys fixture.

You should "undo" what logging.basicConfig does when the test finishes, possibly in a fixture or a try/finally block.

[bilderbuchi]

Thank you for your pointers! I have found if I leave stream=sys.stdout out of the call in the example, it works correctly: logging.basicConfig(level=logging.DEBUG). Interestingly, in my slightly more complex usecase it still didn't work correctly despite doing that.

In the end, I found that removing the stream handler manually afterwards was enough to make the tests run as expected:

root_logger = logging.getLogger()
root_logger.setLevel(logging.INFO)
hdlr = logging.StreamHandler()
root_logger.addHandler(hdlr)
# run stuff here...
root_logger.removeHandler(hdlr)

[nicoddemus]

Glad you found a solution!

Notice that you can add that to a fixture and even make it autouse so all tests do that logging setup/tear down automatically.

Out of curiosity, did you try to use pytest-catchlog?

[bilderbuchi]

Yeah I know I could do a fixture, but it's just for those two tests, if I use it more I'll definitely refactor it.
No, I didn't try pytest-catchlog at first, I didn't want to incur another dependency if I could avoid it.

[nicoddemus]

OK, thanks!

[bilderbuchi]

By the way, thank you for a great tool, all you pytest devs!
Now I'll shut up and stop spamming. ^.^

[nicoddemus]

Thanks, we appreciate it. 😁

[ghost]

I was getting this error when disabling a custom logger in one test, which's state persisted to the next test. Be cautious :)

[gaborbernat]

@nicoddemus @asottile

This is still an issue with the latest pytest across tests (e.g. when one tests change the logging config and add a stream handler pointing to stdout, a subsequent test that doesn't setup logging and tries to write to logging will fail).

I think the issue boils down to the fact that if you set up a Stream Handler and you enable capsys the actual output stream will be a pytest stream that will be closed and thrown away at the next test in the test suite. So when a subsequent test tries to write to it you get this error. Adding the following fixture fixed this:

LOGGER = logging.getLogger()

@pytest.fixture(autouse=True)
def ensure_logging_framework_not_altered():
    before_handlers = list(LOGGER.handlers)
    yield
    LOGGER.handlers = before_handlers

Should this be automatically done always by pytest? Granted for this to work ideally you would need to do it for all loggers, not just the root one. In this case, for me, this was enough as I was only set up a custom stream logger onto the root logger.

In an ideal world, I would expect though pytest to cleanup loggig configurations at the end tests that requested the caplog fixture.

[nicoddemus]

@gaborbernat thanks for the detailed description! I've created https://github.com/pytest-dev/pytest/issues/5743 to track this.