pytest capture logging error still happening

[spearsem]

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

[Zac-HD]

A reproducing case, which doesn't need xdist:

import atexit
import logging

LOGGER = logging.getLogger(__name__)

def test_1():
    pass    

atexit.register(lambda: LOGGER.error("test in atexit"))
logging.basicConfig()

[bannsec]

I'm having the same issue. Mine are debug logs during atexit.

[sshishov]

Same happening here in Python 3.7 and latest pytest

[spearsem]

@Zac-HD Thanks for migrating that example from the other issue. In my case with my original bug, there was simply no way to reproduce an example, since it contained so many moving parts related to pytest and pytest-xdist and a large test suite in the project. In general it is quite complex to try to reduce pytest errors to small & reproducible errors, though I agree that's the ideal thing to strive for. Unfortunately most of the time the best effort someone can really do is to paste in the error message and give general context around the use case where the error appears, and hope pytest devs who know much more about the internals can take it from there to scope it down to the reproducible essence of the bug. Just wanted to say it is very appreciated!

[nicoddemus]

Hi everyone,

What I believe is happening is:

1. pytest changes sys.stdout and sys.stderr to a buffer while importing test modules.
2. If there's user code setting up logging and/or creating a logging.StreamHandler at the import level, it will attach itself to pytest's buffer.
3. When pytest is about to finish the test session, it will restore sys.stdout and sys.stderr to the original values, and close the "capture" buffer.
4. Here the problem happens: if any message is emitted at this point, the StreamHandler will try to attach itself to the buffer, hence the error.

Unfortunately I don't see how pytest can work around this, because we can't know who kept a reference to the capture buffer and somehow tell the owner of the reference that we are now "dead".

@spearsem, are you calling basicConfig at import time in your application, or setting up logging yourself at import time?

If I'm getting this right, my suggestion is to avoid setting up your logging configuration at import time, moving it to a function which is called only when running your actual production code.

[spearsem]

@nicoddemus the application we are testing unfortunately requires setting up logging at import time. It is part of a Flask application that has an in-house framework for configuring logging so that it is standardized across all microservices (for compliance). I think this is actually a very commonly needed use case for automating logging in microservices. Some of our pytest code is using Flask testing clients to test these services, and the construction of the services will always produce this problem (unless we change the whole framework).

I can also say this was not always happening with pytest, it appeared in some old bug reports but then went away for a while and came back with recent versions. How did pytest handle this differently inbetween (or am I mistaken about this and it was always present)? Particularly in item 3. from your comment, what prevents pytest from being able to wait definitively for the testing code to complete and be torn down entirely before switching stdout and stderr back?

You mention,

Unfortunately I don't see how pytest can work around this, because we can't know who kept a reference to the capture buffer and somehow tell the owner of the reference that we are now "dead".

but I don't understand. Shouldn't pytest exactly be able to keep track of this, or at least wait until all test operations are completed so that any pytest unit of execution possibly containing an object that requested access to the buffers has fully completed before pytest makes the "undo" switch back?

[blueyed]

Maybe related to #4943 and/or #4988.

Shouldn't pytest exactly be able to keep track of this, or at least wait until all test operations are completed so that any pytest unit of execution possibly containing an object that requested access to the buffers has fully completed before pytest makes the "undo" switch back?

Yes, that would be good. But likely we would need to wrap around atexit then - are you using that also?

[blueyed]

I guess what should be done here is duplicate/redirect the handlers, instead of closing them.