pytest-dev / pytest-dev/pytest

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

Open
#5,282 5 comments 3 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

plugin: capture type: bug
Dominant language
Python
Stars
14.5k
Forks
3.4k
Avg merge
2d 9h
Merged PRs (30d)
35

Description

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

Contributor guide

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start by reproducing the atexit logging example and inspecting the capture lifecycle in _pytest/capture.py, especially how its output stream is closed. Trace how pytest handles atexit callbacks and determine a lifecycle-safe fix; done means the example and functional tests finish without logging errors from closed capture streams.

Written by the indexing model from the issue text.

Assessment

Tech stack
python
Domain
testing
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Mostly clear
Newbie friendliness
45/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.