pytest 4.5 floods the output with logging errors when logging from atexit handlers

[hynek]

This seems to be related to #4942 however I'd prefer this to be fixed rather than masked away. :)

Consider the following example:

import atexit
import io
import logging
import logging.config

import pytest


LOG_PROD = """\
[loggers]
keys = root

[handlers]
keys = console

[formatters]
keys = generic

[logger_root]
level = INFO
handlers = console

[handler_console]
class = StreamHandler
args = (sys.stdout,)
level = NOTSET
formatter = generic

[formatter_generic]
format = %(message)s
"""


logger = logging.getLogger()

logging.config.fileConfig(
    io.StringIO(LOG_PROD), disable_existing_loggers=False
)


@pytest.fixture
def fix():
    logger.error("start")

    @atexit.register
    def boom():
        logger.error("end")

    return True


def test_boom(fix):
    assert fix

It will output the following:

==================================================================== test session starts =====================================================================
platform darwin -- Python 3.7.3, pytest-4.5.0, py-1.8.0, pluggy-0.11.0
rootdir: /Users/hynek/tmp, inifile: setup.cfg
collected 1 item

t.py .                                                                                                                                                 [100%]

================================================================== 1 passed in 0.01 seconds ==================================================================
--- Logging error ---
Traceback (most recent call last):
  File "/Users/hynek/.pyenv/versions/3.7.3/lib/python3.7/logging/__init__.py", line 1037, in emit
    stream.write(msg + self.terminator)
  File "/Users/hynek/.local/venvs/tempenv-4f92186385ef7/lib/python3.7/site-packages/_pytest/capture.py", line 439, in write
    self.buffer.write(obj)
ValueError: I/O operation on closed file
Call stack:
  File "/Users/hynek/tmp/t.py", line 47, in boom
    logger.error("end")
Message: 'end'
Arguments: ()

When running functional tests, this output gets very long.

---

I guess the proper fix would be to monkeypatch atexit and run the hooks when a test ends?

cc @blueyed @The-Compiler

[blueyed]

I'd prefer this to be fixed rather than masked away. :)

👍

It looks like the capture plugin should not close the handler when finished the session maybe, but rather restore it?

It appears to happen via

  File "…/Vcs/pytest/src/_pytest/main.py", line 242, in pytest_cmdline_main
    return wrap_session(config, _main)
  File "…/Vcs/pytest/src/_pytest/main.py", line 237, in wrap_session
    config._ensure_unconfigure()
  File "…/Vcs/pytest/src/_pytest/config/__init__.py", line 677, in _ensure_unconfigure
    fin()
  File "…/Vcs/pytest/src/_pytest/capture.py", line 126, in stop_global_capturing
    self._global_capturing.stop_capturing()
  File "…/Vcs/pytest/src/_pytest/capture.py", line 532, in stop_capturing
    self.in_.done()
  File "…/Vcs/pytest/src/_pytest/capture.py", line 607, in done
    __import__("traceback").print_stack()

The closing happens in https://github.com/blueyed/pytest/blob/034874c07434e3ac58e003a1188dc34875e74443/src/_pytest/capture.py#L840 - when not doing it there it works, but will not output anything. I think it would be good to see the "end" then also with capturing enabled, no?

[hynek]

I think this is bigger than just capture tbh. 🤔 I think pytest should intercept atexit.registers and run them at the end of a test that registered them.

[blueyed]

Sounds like a good idea in general - but might intercept things then that are really meant for atexit.
Therefore it should only do this during test execution probably, and might still run into this with global / previously defined handlers.

As for the example itself: you should/would not use atexit, but normal teardown there.

[stephen-thomas]

Any thoughts on this? @blueyed ?

I just followed three issues with a ton of discussion that got closed for being 'duplicates' and ended up here.

[tillahoffmann]

Not a proper fix, of course, but adding the following to your conftest.py keeps the console free of logging errors.

import logging


def pytest_sessionfinish():
    """
    Register a hook to suppress logging errors after the session finishes.
    """
    logging.raiseExceptions = False