I/O operation on closed file with current pytest version
Closed this issue · 3 comments
ldruschk commented
With a current pytest version I get the following output (although pytest still exits with exit code 0), I worked around this by pinning pytest==4.4.2 in fc7f212 (the errors occur with pytest>=4.5.0 and pytest>=5
python -m pytest
==================================================================================================================== test session starts =====================================================================================================================
platform linux -- Python 3.8.3, pytest-5.4.3, py-1.8.0, pluggy-0.13.1
rootdir: /home/lucas/Documents/prog/enochecker
collected 10 items
tests/test_enochecker.py .........2020-06-03 17:38:56,513 - CheckerExampleImpl - DEBUG - Assuming checker Name . If that's not the case, please override.
2020-06-03 17:38:56,513 - CheckerExampleImpl - DEBUG - Initialized checker for flag {"method": "putflag", "address": "localhost", "team": "team", "team_id": 1, "round": 1, "flag_round": 1, "flag": "ENOFLAGENOFLAG=", "timeout": 30, "flag_idx": 2, "json_logging": false, "log_endpoint": "", "round_length": 300} with in 0:00:00.000161 seconds
2020-06-03 17:38:56,513 - CheckerExampleImpl - DEBUG - Remote DB team_team was not cached.
2020-06-03 17:38:56,513 - CheckerExampleImpl - DEBUG - MONGO_ENABLED not set. Using stored dict at .data
2020-06-03 17:38:56,513 - CheckerExampleImpl - DEBUG - Locking team_team db
2020-06-03 17:38:56,513 - CheckerExampleImpl - DEBUG - Log db lock for team_team
2020-06-03 17:38:56,513 - CheckerExampleImpl - DEBUG - Released db lock for team_team
2020-06-03 17:38:56,513 - CheckerExampleImpl - INFO - RAN IDX 2
2020-06-03 17:38:56,513 - CheckerExampleImpl - ERROR - Unhandled checker error occurred:
Traceback (most recent call last):
File "/home/lucas/Documents/prog/enochecker/venv_dev/lib/python3.8/site-packages/enochecker/enochecker.py", line 398, in run
ret = getattr(self, snake_caseify(method))()
File "/home/lucas/Documents/prog/enochecker/tests/test_enochecker.py", line 64, in putflag
raise Exception()
Exception
2020-06-03 17:38:56,514 - CheckerExampleImpl - DEBUG - Locking team_team db
2020-06-03 17:38:56,514 - CheckerExampleImpl - DEBUG - Log db lock for team_team
2020-06-03 17:38:56,514 - CheckerExampleImpl - DEBUG - Locking team_team db
2020-06-03 17:38:56,514 - CheckerExampleImpl - DEBUG - Log db lock for team_team
2020-06-03 17:38:56,514 - CheckerExampleImpl - DEBUG - Released db lock for team_team
2020-06-03 17:38:56,514 - CheckerExampleImpl - DEBUG - Locking team_team db
2020-06-03 17:38:56,514 - CheckerExampleImpl - DEBUG - Log db lock for team_team
2020-06-03 17:38:56,514 - CheckerExampleImpl - DEBUG - Released db lock for team_team
2020-06-03 17:38:56,515 - CheckerExampleImpl - DEBUG - Locking team_team db
2020-06-03 17:38:56,515 - CheckerExampleImpl - DEBUG - Log db lock for team_team
2020-06-03 17:38:56,515 - CheckerExampleImpl - DEBUG - Released db lock for team_team
2020-06-03 17:38:56,515 - CheckerExampleImpl - DEBUG - Released db lock for team_team
Checker run resulted in Result.INTERNAL_ERROR
. [100%]
===================================================================================================================== 10 passed in 0.57s =====================================================================================================================
--- Logging error ---
Traceback (most recent call last):
File "/usr/lib64/python3.8/logging/__init__.py", line 1084, in emit
stream.write(msg + self.terminator)
ValueError: I/O operation on closed file.
Call stack:
File "/home/lucas/Documents/prog/enochecker/venv_dev/lib/python3.8/site-packages/enochecker/storeddict.py", line 52, in locked
self.logger.debug("Locking {} db".format(self.name))
Message: 'Locking team_team db'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
File "/usr/lib64/python3.8/logging/__init__.py", line 1084, in emit
stream.write(msg + self.terminator)
ValueError: I/O operation on closed file.
Call stack:
File "/home/lucas/Documents/prog/enochecker/venv_dev/lib/python3.8/site-packages/enochecker/storeddict.py", line 54, in locked
self.logger.debug("Log db lock for {}".format(self.name))
Message: 'Log db lock for team_team'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
File "/usr/lib64/python3.8/logging/__init__.py", line 1084, in emit
stream.write(msg + self.terminator)
ValueError: I/O operation on closed file.
Call stack:
File "/home/lucas/Documents/prog/enochecker/venv_dev/lib/python3.8/site-packages/enochecker/storeddict.py", line 56, in locked
return func(self, *args, **kwargs)
File "/home/lucas/Documents/prog/enochecker/venv_dev/lib/python3.8/site-packages/enochecker/storeddict.py", line 135, in _cleanup
self.logger.debug("StoredDict cleanup task running.")
Message: 'StoredDict cleanup task running.'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
File "/usr/lib64/python3.8/logging/__init__.py", line 1084, in emit
stream.write(msg + self.terminator)
ValueError: I/O operation on closed file.
Call stack:
File "/home/lucas/Documents/prog/enochecker/venv_dev/lib/python3.8/site-packages/enochecker/storeddict.py", line 56, in locked
return func(self, *args, **kwargs)
File "/home/lucas/Documents/prog/enochecker/venv_dev/lib/python3.8/site-packages/enochecker/storeddict.py", line 137, in _cleanup
self.persist()
File "/home/lucas/Documents/prog/enochecker/venv_dev/lib/python3.8/site-packages/enochecker/storeddict.py", line 52, in locked
self.logger.debug("Locking {} db".format(self.name))
Message: 'Locking team_team db'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
File "/usr/lib64/python3.8/logging/__init__.py", line 1084, in emit
stream.write(msg + self.terminator)
ValueError: I/O operation on closed file.
Call stack:
File "/home/lucas/Documents/prog/enochecker/venv_dev/lib/python3.8/site-packages/enochecker/storeddict.py", line 56, in locked
return func(self, *args, **kwargs)
File "/home/lucas/Documents/prog/enochecker/venv_dev/lib/python3.8/site-packages/enochecker/storeddict.py", line 137, in _cleanup
self.persist()
File "/home/lucas/Documents/prog/enochecker/venv_dev/lib/python3.8/site-packages/enochecker/storeddict.py", line 54, in locked
self.logger.debug("Log db lock for {}".format(self.name))
Message: 'Log db lock for team_team'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
File "/usr/lib64/python3.8/logging/__init__.py", line 1084, in emit
stream.write(msg + self.terminator)
ValueError: I/O operation on closed file.
Call stack:
File "/home/lucas/Documents/prog/enochecker/venv_dev/lib/python3.8/site-packages/enochecker/storeddict.py", line 56, in locked
return func(self, *args, **kwargs)
File "/home/lucas/Documents/prog/enochecker/venv_dev/lib/python3.8/site-packages/enochecker/storeddict.py", line 137, in _cleanup
self.persist()
File "/home/lucas/Documents/prog/enochecker/venv_dev/lib/python3.8/site-packages/enochecker/storeddict.py", line 59, in locked
self.logger.debug("Released db lock for {}".format(self.name))
Message: 'Released db lock for team_team'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
File "/usr/lib64/python3.8/logging/__init__.py", line 1084, in emit
stream.write(msg + self.terminator)
ValueError: I/O operation on closed file.
Call stack:
File "/home/lucas/Documents/prog/enochecker/venv_dev/lib/python3.8/site-packages/enochecker/storeddict.py", line 59, in locked
self.logger.debug("Released db lock for {}".format(self.name))
Message: 'Released db lock for team_team'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
File "/usr/lib64/python3.8/logging/__init__.py", line 1084, in emit
stream.write(msg + self.terminator)
File "/home/lucas/Documents/prog/enochecker/venv_dev/lib/python3.8/site-packages/_pytest/capture.py", line 424, in write
return self.buffer.write(s.encode(self.encoding, "replace"))
ValueError: I/O operation on closed file
Call stack:
File "/home/lucas/Documents/prog/enochecker/venv_dev/lib/python3.8/site-packages/enochecker/storeddict.py", line 52, in locked
self.logger.debug("Locking {} db".format(self.name))
Message: 'Locking team_Testteam db'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
File "/usr/lib64/python3.8/logging/__init__.py", line 1084, in emit
stream.write(msg + self.terminator)
File "/home/lucas/Documents/prog/enochecker/venv_dev/lib/python3.8/site-packages/_pytest/capture.py", line 424, in write
return self.buffer.write(s.encode(self.encoding, "replace"))
ValueError: I/O operation on closed file
Call stack:
File "/home/lucas/Documents/prog/enochecker/venv_dev/lib/python3.8/site-packages/enochecker/storeddict.py", line 54, in locked
self.logger.debug("Log db lock for {}".format(self.name))
Message: 'Log db lock for team_Testteam'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
File "/usr/lib64/python3.8/logging/__init__.py", line 1084, in emit
stream.write(msg + self.terminator)
File "/home/lucas/Documents/prog/enochecker/venv_dev/lib/python3.8/site-packages/_pytest/capture.py", line 424, in write
return self.buffer.write(s.encode(self.encoding, "replace"))
ValueError: I/O operation on closed file
Call stack:
File "/home/lucas/Documents/prog/enochecker/venv_dev/lib/python3.8/site-packages/enochecker/storeddict.py", line 56, in locked
return func(self, *args, **kwargs)
File "/home/lucas/Documents/prog/enochecker/venv_dev/lib/python3.8/site-packages/enochecker/storeddict.py", line 135, in _cleanup
self.logger.debug("StoredDict cleanup task running.")
Message: 'StoredDict cleanup task running.'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
File "/usr/lib64/python3.8/logging/__init__.py", line 1084, in emit
stream.write(msg + self.terminator)
File "/home/lucas/Documents/prog/enochecker/venv_dev/lib/python3.8/site-packages/_pytest/capture.py", line 424, in write
return self.buffer.write(s.encode(self.encoding, "replace"))
ValueError: I/O operation on closed file
Call stack:
File "/home/lucas/Documents/prog/enochecker/venv_dev/lib/python3.8/site-packages/enochecker/storeddict.py", line 56, in locked
return func(self, *args, **kwargs)
File "/home/lucas/Documents/prog/enochecker/venv_dev/lib/python3.8/site-packages/enochecker/storeddict.py", line 137, in _cleanup
self.persist()
File "/home/lucas/Documents/prog/enochecker/venv_dev/lib/python3.8/site-packages/enochecker/storeddict.py", line 52, in locked
self.logger.debug("Locking {} db".format(self.name))
Message: 'Locking team_Testteam db'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
File "/usr/lib64/python3.8/logging/__init__.py", line 1084, in emit
stream.write(msg + self.terminator)
File "/home/lucas/Documents/prog/enochecker/venv_dev/lib/python3.8/site-packages/_pytest/capture.py", line 424, in write
return self.buffer.write(s.encode(self.encoding, "replace"))
ValueError: I/O operation on closed file
Call stack:
File "/home/lucas/Documents/prog/enochecker/venv_dev/lib/python3.8/site-packages/enochecker/storeddict.py", line 56, in locked
return func(self, *args, **kwargs)
File "/home/lucas/Documents/prog/enochecker/venv_dev/lib/python3.8/site-packages/enochecker/storeddict.py", line 137, in _cleanup
self.persist()
File "/home/lucas/Documents/prog/enochecker/venv_dev/lib/python3.8/site-packages/enochecker/storeddict.py", line 54, in locked
self.logger.debug("Log db lock for {}".format(self.name))
Message: 'Log db lock for team_Testteam'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
File "/usr/lib64/python3.8/logging/__init__.py", line 1084, in emit
stream.write(msg + self.terminator)
File "/home/lucas/Documents/prog/enochecker/venv_dev/lib/python3.8/site-packages/_pytest/capture.py", line 424, in write
return self.buffer.write(s.encode(self.encoding, "replace"))
ValueError: I/O operation on closed file
Call stack:
File "/home/lucas/Documents/prog/enochecker/venv_dev/lib/python3.8/site-packages/enochecker/storeddict.py", line 56, in locked
return func(self, *args, **kwargs)
File "/home/lucas/Documents/prog/enochecker/venv_dev/lib/python3.8/site-packages/enochecker/storeddict.py", line 137, in _cleanup
self.persist()
File "/home/lucas/Documents/prog/enochecker/venv_dev/lib/python3.8/site-packages/enochecker/storeddict.py", line 59, in locked
self.logger.debug("Released db lock for {}".format(self.name))
Message: 'Released db lock for team_Testteam'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
File "/usr/lib64/python3.8/logging/__init__.py", line 1084, in emit
stream.write(msg + self.terminator)
File "/home/lucas/Documents/prog/enochecker/venv_dev/lib/python3.8/site-packages/_pytest/capture.py", line 424, in write
return self.buffer.write(s.encode(self.encoding, "replace"))
ValueError: I/O operation on closed file
Call stack:
File "/home/lucas/Documents/prog/enochecker/venv_dev/lib/python3.8/site-packages/enochecker/storeddict.py", line 59, in locked
self.logger.debug("Released db lock for {}".format(self.name))
Message: 'Released db lock for team_Testteam'
Arguments: ()
ldruschk commented
Seems to be related to pytest-dev/pytest#5502
domenukk commented
We apparently do not have this issue anymore, pytest is now on version 6 with #99
ldruschk commented
Yes, for future reference, the problem was the usage of atexit here:
https://github.com/enowars/enochecker/pull/99/files#diff-ab2b1111dc2f21ae8bedb59461cef621104f4ee349fad233b3b5d55052a25597L125
Which included a call to a logging function. Pytest "hijacks" stdout/stderr of the program under test and redirects them to buffers and restores this after the test case. However, since atexit is run after pytest has restored the original stdout/stderr, the logger which was initialized while the buffers were attached now tries to write to a closed buffer.