Description
Good morning,
I am seeing the same issue as described in #14 but using a much more modern combination of both (anaconda) Python and pytest.
Test session starts (platform: linux, Python 3.6.8, pytest 4.6.3, pytest-sugar 0.9.2)
rootdir: /ml/tests/ml/services, inifile: all-tests.ini
plugins: forked-1.0.2, xdist-1.29.0, sugar-0.9.2, cov-2.7.1, mock-1.10.4
In the relevant .ini file I have this:
[pytest]
testpaths = tests
addopts =
-n 4
--durations=20
--disable-warnings
where -n 4
is to use 4 parallel test runners with pytest-xdist. Edit: I was able to isolate the behavior to when using parallel worker with xdist, so likely it is an issue with an xdist worker prematurely closing a logger stream.
Basically, when I run one particular test file, I see a large number of repeated error messages in the pytest output:
--- Logging error ---
Traceback (most recent call last):
File "/usr/lib/python3.6/logging/__init__.py", line 996, in emit
stream.write(msg)
File "/usr/local/lib/python3.6/dist-packages/_pytest/capture.py", line 441, in write
self.buffer.write(obj)
ValueError: I/O operation on closed file
Call stack:
File "/usr/lib/python3.6/threading.py", line 884, in _bootstrap
self._bootstrap_inner()
File "/usr/lib/python3.6/threading.py", line 916, in _bootstrap_inner
self.run()
File "/usr/lib/python3.6/threading.py", line 864, in run
self._target(*self._args, **self._kwargs)
File "/ml/ml/models/neighbors.py", line 289, in re_index
success = self._re_index()
File "/ml/ml/models/neighbors.py", line 349, in _re_index
logger.info('== Fit new model with {} ids and a dimensionality of {} =='.format(n, dim))
Message: '== Fit new model with 48 ids and a dimensionality of 2 =='
Arguments: ()
The issue appears to be related to pytest prematurely closing the stream associated with a given logger for the underlying code module in question. I can't really post all the code since it is an extended example from my work, but I can confirm there is nothing exotic or unusual happening with this logger. The module being tested just uses the normal convention to define
logger = logging.getLogger(__name__)
and there are no duplicate loggers or conflicts with this logger's name. The logger itself is not defined in any multiprocessing context or anything like that. Just a boring import of a top-level module from our code base.
But during the test execution, something weird is happening with pytest such that the eventual calls into that logger produce these errors.
If I turn off pytest capturing with --capture=no
, then the messages go away, but unfortunately so does a bunch of other necessary output that I want pytest to capture and display.
How can I debug this further? I'm sorry that I cannot provide a minimal working example, but I can definitely confirm that there is nothing weird going on with these tests. It's a very straightforward use of logging
and a very straightforward test file with simple imports and function calls.
- [x ] a detailed description of the bug or suggestion
- [ x] output of
pip list
from the virtual environment you are using - [ x] pytest and operating system versions
- [ x] minimal example if possible