`ValueError: I/O operation on closed file` when logging atexit #5577

bluenote10 · 2019-07-08T17:51:16Z

When writing unit tests involving ROS, py.test often crashes at the end of the test execution with:

================================================ 1 passed in 0.03 seconds ================================================
Traceback (most recent call last):
  File "/usr/lib/python2.7/logging/__init__.py", line 882, in emit
    stream.write(fs % msg)
  File "/home/user/.virtualenvs/venv/local/lib/python2.7/site-packages/_pytest/capture.py", line 441, in write
    self.buffer.write(obj)
ValueError: I/O operation on closed file
Logged from file core.py, line 454

After some debugging I can reproduce the problem in a minimal example:

# the test file
import my_package.offending_module

def test_dummy():
    assert True

# the offending module
import atexit
import logging

_logger = logging.getLogger(__name__)

def atexit_callback():
    _logger.error("test")

atexit.register(atexit_callback)

logging.basicConfig()

The problem seems to be that importing this module auto-registers an atexit callback which involves a logging call.

In the case of ROS the offending module is rospy/core.py. Since this file is tied to the entire ROS distribution there is no easy way to fix the problem on the ROS side.

Python: 2.7

pip freeze

absl-py==0.7.1
actionlib==1.11.13
aenum==2.1.2
angles==1.9.11
ansible==2.8.1
anytree==2.6.0
argh==0.26.2
asammdf==5.10.0
asn1crypto==0.24.0
astor==0.8.0
astroid==1.6.6
atomicwrites==1.3.0
attrs==19.1.0
backports-abc==0.5
backports.functools-lru-cache==1.5
backports.shutil-get-terminal-size==1.0.0
backports.weakref==1.0.post1
bcrypt==3.1.6
bidict==0.18.0
bitstruct==7.1.0
bleach==1.5.0
bokeh==0.12.13
bondpy==1.8.3
boolean.py==3.4
bottle==0.12.17
camera-calibration==1.12.23
camera-calibration-parsers==1.11.13
canmatrix==0.8
catkin==0.7.14
catkin-pkg==0.4.12
cchardet==2.1.4
certifi==2019.6.16
cffi==1.12.3
chardet==3.0.4
Click==7.0
cloudpickle==1.2.1
cmake==3.14.4
colorama==0.4.1
coloredlogs==10.0
conan==1.16.1
configparser==3.7.4
contextlib2==0.5.5
coverage==4.5.3
cryptography==2.7
cv-bridge==1.12.8
cycler==0.10.0
dask==1.2.2
decorator==4.4.0
defusedxml==0.6.0
deprecation==2.0.6
dfgui==0.1
diagnostic-analysis==1.9.3
diagnostic-common-diagnostics==1.9.3
diagnostic-updater==1.9.3
dill==0.3.0
distributed==1.28.1
distro==1.1.0
Django==1.11
django-emoji==2.2.2
django-filter==2.0.0
django-mathfilters==0.4.0
django-safedelete==0.5.1
docopt==0.6.2
docutils==0.14
dynamic-reconfigure==1.5.50
empy==3.3.4
entrypoints==0.3
enum34==1.1.6
fasteners==0.15
filelock==3.0.12
first==2.0.1
flake8==3.7.7
Flask==1.0.2
Flask-Cors==3.0.7
ftfy==4.4.3
funcsigs==1.0.2
functools32==3.2.3.post2
future==0.16.0
futures==3.2.0
gast==0.2.2
gazebo-plugins==2.5.18
gazebo-ros==2.5.18
gcovr==4.1
gencpp==0.6.0
geneus==2.2.6
genlisp==0.4.16
genmsg==0.5.11
gennodejs==2.0.1
genpy==0.6.7
gitdb2==2.0.5
GitPython==2.1.11
graphviz==0.11
grpcio==1.22.0
h5py==2.9.0
HeapDict==1.0.0
html5lib==0.9999999
humanfriendly==4.18
idna==2.8
image-geometry==1.12.8
importlib-metadata==0.18
interactive-markers==1.11.4
ipaddress==1.0.22
ipython==5.8.0
ipython-genutils==0.2.0
isort==4.3.21
itsdangerous==1.1.0
jenkinsapi==0.3.9
Jinja2==2.10.1
jsk-recognition-utils==1.2.9
jsk-rviz-plugins==2.1.5
jsk-topic-tools==2.2.10
jsonschema==3.0.1
jupyter-core==4.4.0
Keras==2.2.0
Keras-Applications==1.0.2
Keras-Preprocessing==1.0.1
kiwisolver==1.1.0
laser-geometry==1.6.4
lazy-object-proxy==1.4.1
llvmlite==0.29.0
locket==0.2.0
lockfile==0.12.2
luigi==2.8.3
lxml==4.3.4
maploc-gcovr==4.1
Markdown==3.1.1
MarkupSafe==1.1.1
matplotlib==2.2.4
mccabe==0.6.1
message-filters==1.12.14
mock==3.0.5
monotonic==1.5
more-itertools==5.0.0
mplleaflet==0.0.5
msgpack==0.6.1
multiprocess==0.70.8
natsort==6.0.0
nbformat==4.4.0
netifaces==0.10.9
node-semver==0.6.1
numba==0.44.1
numexpr==2.6.9
numpy==1.16.4
numpy-quaternion==2019.6.26.15.8.24
packaging==19.0
pandas==0.24.2
paramiko==2.4.2
parse==1.11.1
partd==1.0.0
patch==1.16
pathlib==1.0.1
pathlib2==2.3.4
pathos==0.2.4
pathtools==0.1.2
pbr==5.1.3
pexpect==4.7.0
pickleshare==0.7.5
Pillow==5.4.1
pip-tools==3.8.0
pkg-resources==0.0.0
plotly==3.7.1
pluggy==0.12.0
pluginbase==0.7
pluginlib==1.11.3
pox==0.2.6
ppft==1.6.6.1
progressbar==2.5
prompt-toolkit==1.0.16
protobuf==3.8.0
psutil==5.6.3
ptyprocess==0.6.0
py==1.8.0
pyarrow==0.13.0
pyasn1==0.4.5
pybind11==2.2.4
pycodestyle==2.5.0
pycparser==2.19
pyflakes==2.1.1
Pygments==2.4.2
PyJWT==1.7.1
pylint==1.9.4
pymap3d==1.6.3
PyMySQL==0.9.3
PyNaCl==1.3.0
pyparsing==2.4.0
pypcd==0.1.1
pyproj==2.2.1
pyrosbag==0.1.3
pyrsistent==0.14.11
pyserial==3.4
pysolr==3.8.1
pytest==4.6.4
pytest-cov==2.7.1
pytest-mock==1.10.4
pytest-watch==4.2.0
python-daemon==2.1.2
python-dateutil==2.8.0
python-intervals==1.8.0
python-lzf==0.2.4
python-qt-binding==0.3.4
pytz==2019.1
PyYAML==3.13
qt-dotgraph==0.3.11
qt-gui==0.3.11
qt-gui-cpp==0.3.11
qt-gui-py-common==0.3.11
requests==2.22.0
resource-retriever==1.12.4
retrying==1.3.3
rosapi==0.11.1
rosbag==1.12.14
rosboost-cfg==1.14.4
rosbridge-library==0.11.1
rosclean==1.14.4
roscreate==1.14.4
rosdep==0.15.2
rosdistro==0.7.4
rosgraph==1.12.14
roslaunch==1.12.14
roslib==1.14.4
roslint==0.11.0
roslz4==1.12.14
rosmake==1.14.4
rosmaster==1.12.14
rosmsg==1.12.14
rosnode==1.12.14
rosparam==1.12.14
rospkg==1.1.9
rospy==1.12.14
rosservice==1.12.14
rostest==1.12.14
rostopic==1.12.14
rosunit==1.14.4
roswtf==1.12.14
rqt-action==0.4.9
rqt-bag==0.4.12
rqt-bag-plugins==0.4.12
rqt-console==0.4.8
rqt-dep==0.4.9
rqt-graph==0.4.9
rqt-gui==0.5.0
rqt-gui-py==0.5.0
rqt-image-view==0.4.13
rqt-launch==0.4.8
rqt-logger-level==0.4.8
rqt-moveit==0.5.7
rqt-msg==0.4.8
rqt-nav-view==0.5.7
rqt-plot==0.4.8
rqt-pose-view==0.5.8
rqt-publisher==0.4.8
rqt-py-common==0.5.0
rqt-py-console==0.4.8
rqt-reconfigure==0.4.10
rqt-robot-dashboard==0.5.7
rqt-robot-monitor==0.5.8
rqt-robot-steering==0.5.9
rqt-runtime-monitor==0.5.7
rqt-rviz==0.5.10
rqt-service-caller==0.4.8
rqt-shell==0.4.9
rqt-srv==0.4.8
rqt-tf-tree==0.6.0
rqt-top==0.4.8
rqt-topic==0.4.10
rqt-web==0.4.8
rviz==1.12.17
scandir==1.10.0
scikit-learn==0.20.3
scipy==1.2.2
seaborn==0.9.0
sensor-msgs==1.12.7
simplegeneric==0.8.1
singledispatch==3.4.0.3
six==1.12.0
sklearn==0.0
smach==2.0.1
smach-ros==2.0.1
smclib==1.8.3
smmap2==2.0.5
sortedcontainers==2.1.0
sound-play==0.3.3
sqlitedict==1.6.0
subprocess32==3.5.4
swri-transform-util==2.8.0
tables==3.5.2
tblib==1.4.0
tensorboard==1.8.0
tensorflow==1.8.0
termcolor==1.1.0
tf==1.11.9
tf-conversions==1.11.9
tf2-geometry-msgs==0.5.20
tf2-kdl==0.5.20
tf2-py==0.5.20
tf2-ros==0.5.20
Theano==0.9.0
toolz==0.9.0
topic-tools==1.12.14
tornado==5.1.1
tqdm==4.32.2
traitlets==4.3.2
typing==3.7.4
urdfdom-py==0.3.3
urllib3==1.25.3
virtualenv==16.2.0
watchdog==0.9.0
wcwidth==0.1.7
Werkzeug==0.15.4
wiimote==1.12.0
wrapt==1.11.2
xacro==1.11.3
zict==1.0.0
zipp==0.5.1

The text was updated successfully, but these errors were encountered:

twmr · 2019-07-08T20:44:54Z

Thx for the report!
I can reproduce your issue in a python 3.7 env as well with this example

import atexit
import logging

LOGGER = logging.getLogger(__name__)

def test_1():
    pass

def atexit_callback():
    LOGGER.error("test in atexit")

atexit.register(atexit_callback)
logging.basicConfig()

twmr · 2019-07-08T20:48:13Z

This is related to #5502.

Zac-HD · 2019-07-21T10:09:00Z

Closing this as a duplicate of #5502

That said, thanks for providing a reproducible example! That really, really helps to narrow down the problem and there wasn't one on the older issue 😄

Symptom of pytest-dev/pytest#5577

pytest's capsys just closes the stdout when done with tests. there are issues tracking this problem, see pytest-dev/pytest#5577 . but we adds a handler which redirect the logging messages to stdout. so, once pytest finishes testing, exceptions are raised when writing logging messages, like ``` 22:37:20 File "/usr/local/lib/python3.10/logging/__init__.py", line 1101, in emit 22:37:20 stream.write(msg + self.terminator) 22:37:20 ValueError: I/O operation on closed file. ``` so, in this change, `logging.raiseExceptions` is disabled when pytest's session finishes. Fixes scylladb#6000 Signed-off-by: Kefu Chai <kefu.chai@scylladb.com>

pytest's capsys just closes the stdout when done with tests. there are issues tracking this problem, see pytest-dev/pytest#5577 . but we adds a handler which redirect the logging messages to stdout. so, once pytest finishes testing, exceptions are raised when writing logging messages, like ``` 22:37:20 File "/usr/local/lib/python3.10/logging/__init__.py", line 1101, in emit 22:37:20 stream.write(msg + self.terminator) 22:37:20 ValueError: I/O operation on closed file. ``` so, in this change, `logging.raiseExceptions` is disabled when pytest's session finishes. Fixes #6000 Signed-off-by: Kefu Chai <kefu.chai@scylladb.com>

nicoddemus added plugin: logging related to the logging builtin plugin type: bug problem that needs to be addressed labels Jul 8, 2019

Zac-HD closed this as completed Jul 21, 2019

bluenote10 mentioned this issue Oct 24, 2019

pytest capture logging error still happening #5502

Open

neggert mentioned this issue Dec 4, 2019

Fix CometML tests Lightning-AI/pytorch-lightning#585

Merged

tebeka mentioned this issue Jan 9, 2020

Clean logging error from tests mlrun/mlrun#101

Closed

karthikvadla mentioned this issue Mar 17, 2020

Improve error message when tests use closed stdout/stderr (capture) #5743

Open

abhijeetkaurav1st mentioned this issue Jun 12, 2020

ValueError: I/O operation on closed file while running tests nutanix/calm-dsl#78

Closed

ethho pushed a commit to TACC-Cloud/python-reactors that referenced this issue Sep 7, 2021

Debug pytest logging error

f44281a

Symptom of pytest-dev/pytest#5577

tomwhite mentioned this issue Aug 23, 2022

Fix I/O logging error during test suite cubed-dev/cubed#105

Merged

tchaikov mentioned this issue Apr 10, 2023

logger is not able to write to log file after tests complete scylladb/scylla-cluster-tests#6000

Closed

tchaikov mentioned this issue Apr 10, 2023

fix(unit_test): prevent logging from raising exceptions after tests scylladb/scylla-cluster-tests#6001

Merged

7 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

`ValueError: I/O operation on closed file` when logging atexit #5577

`ValueError: I/O operation on closed file` when logging atexit #5577

bluenote10 commented Jul 8, 2019

twmr commented Jul 8, 2019

twmr commented Jul 8, 2019

Zac-HD commented Jul 21, 2019 •

edited

Loading

ValueError: I/O operation on closed file when logging atexit #5577

ValueError: I/O operation on closed file when logging atexit #5577

Comments

bluenote10 commented Jul 8, 2019

twmr commented Jul 8, 2019

twmr commented Jul 8, 2019

Zac-HD commented Jul 21, 2019 • edited Loading

`ValueError: I/O operation on closed file` when logging atexit #5577

`ValueError: I/O operation on closed file` when logging atexit #5577

Zac-HD commented Jul 21, 2019 •

edited

Loading