pytest capture logging error still happening

Good morning,

I am seeing the same issue as described in https://github.com/pytest-dev/pytest/issues/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

Start by reproducing the logging error with pytest 4.6.3, pytest-xdist, four workers, and the shown configuration, then inspect _pytest/capture.py around line 441. Compare the behavior with --capture=no and determine whether a worker closes the captured stream prematurely. Done means a minimal reproducer and a verified fix that prevents the logging error while preserving captured output.