pytest-dev / pytest-dev/pytest

Capfd doesn't capture logging StreamHandler

Open
#13,720 1 comment 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

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

Description

This is essentially the capfd version of https://github.com/pytest-dev/pytest/issues/10486's capsys. I globally initialize and configure logging to write to a StreamHandler(sys.stdout). Then, I write to that logger within a pytest test that uses capfd as a fixture. That message isn't caught by capfd, and either gets caught by the global fd-redirection, or prints to console if run with -s.

I find it extra odd since it seems like redirecting stdout at a file-descriptor level should make it impossible for anything to output, right?

For full context, I ran into this trying to make a context-manager that can suppress all stdout output (SO question), including direct writes to fd's. Pytest's capfd seems like something close to this, but still has edge cases like this.

import sys
import os
import logging
import pytest

logging.basicConfig()
_log = logging.getLogger()
_log.setLevel(logging.DEBUG)
_log.handlers = [logging.StreamHandler(sys.stdout)]

def test_read_stdout(capfd):
    sys.stdout.write("hello from stdout!\n")
    captured = capfd.readouterr()
    assert captured.out == 'hello from stdout!\n' #  passes

def test_read_log(capfd):
    _log.debug("hello from logger!")
    captured = capfd.readouterr()
    assert captured.out == 'hello from logger!\n' #  fails

This gives the output:

$ python -m pytest -s .\test_logger_capfd.py
===================================== test session starts =====================================
platform win32 -- Python 3.11.9, pytest-8.4.2, pluggy-1.6.0
rootdir: ~
configfile: pyproject.toml
collected 2 items                                                                               

test_logger_capfd.py .hello from logger!

F

========================================== FAILURES =====================================
________________________________________ test_read_log ________________________________________ 

capfd = <_pytest.capture.CaptureFixture object at 0x00000167734F64D0>

    def test_read_log(capfd: pytest.CaptureFixture):
        _log.debug("hello from logger!\n")
        captured = capfd.readouterr()
>       assert captured.out == 'hello from logger!\n'
E       AssertionError: assert '' == 'hello from logger!\n'
E
E         - hello from logger!

test_logger_capfd.py:19: AssertionError
-------------------------------------- Captured log call -------------------------------------- 
DEBUG    root:test_logger_capfd.py:17 hello from logger!
=================================== short test summary info =================================== 
FAILED test_logger_capfd.py::test_read_log - AssertionError: assert '' == 'hello from logger!\n'================================= 1 failed, 1 passed in 0.14s ================================= 

Note how hello from logger! gets printed to stdout in the middle of the tests. (If I ran without -s, it would get captured by the global output capture, so this is a bit of an artificial issue)

Here's an example using _pytest.capture.FDCapture(1) directly:

import sys
import logging
import _pytest.capture

# Required, otherwise we get a logging error.
_pytest.capture._windowsconsoleio_workaround(sys.stdout)

logging.basicConfig()
_log = logging.getLogger()
_log.setLevel(logging.DEBUG)
_log.handlers = [logging.StreamHandler(sys.stdout)]

cap = _pytest.capture.FDCapture(1)
cap.start()
_log.debug("hello from logger!")
captured = cap.snap()
cap.done()
print("=== Capture: ===")
print(captured)
print("================")

Which outputs

hello from logger!
=== Capture: ===

================

Removing the _windowsconsoleio_workaround() gives:

--- Logging error ---
Traceback (most recent call last):
  File "C:\Python311\Lib\logging\__init__.py", line 1113, in emit
    stream.write(msg + self.terminator)
OSError: [WinError 6] The handle is invalid
Call stack:
  File "test_logger_capfd.py", line 14, in <module>
    _log.debug("hello from logger!")
Message: 'hello from logger!'
Arguments: ()
hello from logger!
=== Capture: ===

================
System details:
Win10 Version 10.0.19045.6093
Python 3.11.9 (tags/v3.11.9:de54cf5, Apr  2 2024, 10:12:12) [MSC v.1938 64 bit (AMD64)] on win32
Fresh venv (`python -m venv`) on Powershell. 
$ pip freeze  
colorama==0.4.6
iniconfig==2.1.0
packaging==25.0
pluggy==1.6.0
Pygments==2.19.2
pytest==8.4.2

Related:

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 reading _pytest.capture.FDCapture and the capfd fixture path, then reproduce the example on Windows with a logging.StreamHandler(sys.stdout). Compare the behavior with issue 10486 and the existing capture tests. Done means a regression test covers this handler case and capfd captures the logger output without printing it outside the capture.

Written by the indexing model from the issue text.

Assessment

Tech stack
python
Domain
operating-systems, testing-qa
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.