Skip to content

ValueError: I/O operation on closed file #14

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
pytestbot opened this issue Dec 17, 2010 · 30 comments
Closed

ValueError: I/O operation on closed file #14

pytestbot opened this issue Dec 17, 2010 · 30 comments
Labels
type: bug problem that needs to be addressed

Comments

@pytestbot
Copy link
Contributor

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.


@pytestbot
Copy link
Contributor Author

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
Copy link
Contributor Author

Original comment by Adam Wagner (BitBucket: awagner83, GitHub: awagner83):


This fixes it for me.

@pytestbot
Copy link
Contributor Author

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
Copy link
Contributor Author

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
Copy link
Contributor Author

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
Copy link
Contributor Author

Original comment by Ronny Pfannschmidt (BitBucket: RonnyPfannschmidt, GitHub: RonnyPfannschmidt):


still in trunk

@pytestbot
Copy link
Contributor Author

Original comment by Ronny Pfannschmidt (BitBucket: RonnyPfannschmidt, GitHub: RonnyPfannschmidt):


this would probably best be fixed by integrating logcapture into pytest

@pytestbot
Copy link
Contributor Author

Original comment by Ronny Pfannschmidt (BitBucket: RonnyPfannschmidt, GitHub: RonnyPfannschmidt):


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

@pytestbot
Copy link
Contributor Author

Original comment by holger krekel (BitBucket: hpk42, GitHub: hpk42):


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

@pytestbot
Copy link
Contributor Author

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.

@pytestbot pytestbot added the type: bug problem that needs to be addressed label Jun 15, 2015
@jfitzpatrick99
Copy link

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
Copy link
Member

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

@jfitzpatrick99
Copy link

@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
Copy link
Member

@jfitzpatrick99 thanks! 😄

@shapiy
Copy link

shapiy commented Oct 16, 2015

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
Copy link
Member

@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
Copy link

shapiy commented Oct 16, 2015

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
Copy link

shapiy commented Oct 30, 2015

@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

@The-Compiler The-Compiler reopened this Oct 30, 2015
@RonnyPfannschmidt
Copy link
Member

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
Copy link
Contributor

@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
Copy link
Member

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
Copy link
Contributor

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
Copy link
Member

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
Copy link
Contributor

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
Copy link
Member

OK, thanks!

@bilderbuchi
Copy link
Contributor

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

@ghost
Copy link

ghost commented Jun 4, 2019

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

@gaborbernat
Copy link
Contributor

gaborbernat commented Aug 15, 2019

@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
Copy link
Member

@gaborbernat thanks for the detailed description! I've created #5743 to track this.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
type: bug problem that needs to be addressed
Projects
None yet
Development

No branches or pull requests

8 participants