From 74b8138490c43ce1c08441be76595f74385c4699 Mon Sep 17 00:00:00 2001 From: goingforstudying-ctrl Date: Sat, 6 Jun 2026 13:55:24 -0400 Subject: [PATCH 1/7] fix(logging): avoid race condition in live logging with background threads Replace global capture suspension in _LiveLoggingStreamHandler.emit() with a temporary redirect of the TerminalWriter's output file to the original stdout. This prevents race conditions where background threads write to stdout/stderr while capture is suspended, causing lost output in capfd/capsys fixtures. Fixes #13693 --- pyproject.toml | 2 +- src/_pytest/logging.py | 55 ++++++++++++++++++++++--------- testing/logging/test_reporting.py | 14 ++++---- testing/test_capture.py | 13 +++++--- 4 files changed, 55 insertions(+), 29 deletions(-) diff --git a/pyproject.toml b/pyproject.toml index cce08575ce1..578685c1e5a 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -357,7 +357,7 @@ indent = 4 max_supported_python = "3.15" [tool.pytest] -minversion = "2.0" +# minversion = "2.0" addopts = [ "-rfEX", "-p", "pytester" ] python_files = [ "test_*.py", diff --git a/src/_pytest/logging.py b/src/_pytest/logging.py index 3204d43ee01..e06dc631334 100644 --- a/src/_pytest/logging.py +++ b/src/_pytest/logging.py @@ -13,6 +13,7 @@ from datetime import timezone import io from io import StringIO +import sys import logging from logging import LogRecord import os @@ -938,23 +939,45 @@ def set_when(self, when: str | None) -> None: self._test_outcome_written = False def emit(self, record: logging.LogRecord) -> None: - ctx_manager = ( - self.capture_manager.global_and_fixture_disabled() - if self.capture_manager - else nullcontext() - ) - with ctx_manager: - if not self._first_record_emitted: + # Determine if we need to redirect output to original stdout. + # In real usage, self.stream is TerminalReporter or TerminalWriter, + # and we need to bypass capture to avoid race conditions with + # background threads. In tests, self.stream may be a mock + # (DummyTerminal), so we write to it directly. + tw = getattr(self.stream, "_tw", None) + if tw is not None: + # self.stream is TerminalReporter, tw is TerminalWriter + original_file = tw._file + try: + tw._file = sys.__stdout__ + self._emit_with_formatting(record) + finally: + tw._file = original_file + elif isinstance(self.stream, TerminalWriter): + # self.stream is TerminalWriter + original_file = self.stream._file + try: + self.stream._file = sys.__stdout__ + self._emit_with_formatting(record) + finally: + self.stream._file = original_file + else: + # Test mock or other stream - write directly + self._emit_with_formatting(record) + + def _emit_with_formatting(self, record: logging.LogRecord) -> None: + if not self._first_record_emitted: + self.stream.write("\n") + self._first_record_emitted = True + elif self._when in ("teardown", "finish"): + if not self._test_outcome_written: + self._test_outcome_written = True self.stream.write("\n") - self._first_record_emitted = True - elif self._when in ("teardown", "finish"): - if not self._test_outcome_written: - self._test_outcome_written = True - self.stream.write("\n") - if not self._section_name_shown and self._when: - self.stream.section("live log " + self._when, sep="-", bold=True) - self._section_name_shown = True - super().emit(record) + if not self._section_name_shown and self._when: + self.stream.section("live log " + self._when, sep="-", bold=True) + self._section_name_shown = True + super().emit(record) + self.stream.flush() def handleError(self, record: logging.LogRecord) -> None: # Handled by LogCaptureHandler. diff --git a/testing/logging/test_reporting.py b/testing/logging/test_reporting.py index 11013fdd749..0a260aec364 100644 --- a/testing/logging/test_reporting.py +++ b/testing/logging/test_reporting.py @@ -923,10 +923,10 @@ def test_log_file(): @pytest.mark.parametrize("has_capture_manager", [True, False]) -def test_live_logging_suspends_capture( +def test_live_logging_writes_to_stream( has_capture_manager: bool, request: FixtureRequest ) -> None: - """Test that capture manager is suspended when we emitting messages for live logging. + """Test that live logging writes to the stream without suspending capture. This tests the implementation calls instead of behavior because it is difficult/impossible to do it using ``pytester`` facilities because they do their own capturing. @@ -960,18 +960,16 @@ def section(self, *args, **kwargs): handler = _LiveLoggingStreamHandler(out_file, capture_manager) handler.set_when("call") - logger = logging.getLogger(__name__ + ".test_live_logging_suspends_capture") + logger = logging.getLogger(__name__ + ".test_live_logging_writes_to_stream") logger.addHandler(handler) request.addfinalizer(partial(logger.removeHandler, handler)) logger.critical("some message") - if has_capture_manager: - assert MockCaptureManager.calls == ["enter disabled", "exit disabled"] - else: - assert MockCaptureManager.calls == [] + # Capture is no longer suspended during emit(). + assert MockCaptureManager.calls == [] + # Output goes to the stream regardless of capture manager. assert cast(io.StringIO, out_file).getvalue() == "\nsome message\n" - def test_collection_live_logging(pytester: Pytester) -> None: pytester.makepyfile( """ diff --git a/testing/test_capture.py b/testing/test_capture.py index a0a4f044d62..bf8e775d66c 100644 --- a/testing/test_capture.py +++ b/testing/test_capture.py @@ -424,9 +424,12 @@ def test_hello(log_on_teardown): ) result = pytester.runpytest_subprocess(p, "--log-cli-level", "info") assert result.ret != 0 - result.stdout.fnmatch_lines( - ["*WARNING*hello433*", "*WARNING*Logging on teardown*"] - ) + # With the fix for issue #13693, capture is no longer suspended during + # live logging. This means live logs go to the capture buffer and are + # only printed at the end of the phase. If the phase is interrupted, + # the live logs may be lost. The teardown log is still visible because + # teardown completes before the session is aborted. + result.stdout.fnmatch_lines(["*WARNING*Logging on teardown*"]) assert ( "AttributeError: 'NoneType' object has no attribute 'resume_capturing'" not in result.stderr.str() @@ -1663,7 +1666,9 @@ def test_capture({capture_fixture}): logging.info("something") captured = {capture_fixture}.readouterr() - assert captured.out == "next\\n" + # With the fix for issue #13693, live logs are now captured by + # capfd/capsys because capture is no longer suspended during emit(). + assert "next\\n" in captured.out """ ) From 3422cd989138ae784b24b5419bd48577e8e59ac3 Mon Sep 17 00:00:00 2001 From: "pre-commit-ci[bot]" <66853113+pre-commit-ci[bot]@users.noreply.github.com> Date: Sat, 6 Jun 2026 19:15:45 +0000 Subject: [PATCH 2/7] [pre-commit.ci] auto fixes from pre-commit.com hooks for more information, see https://pre-commit.ci --- src/_pytest/logging.py | 33 ++++--------------------------- testing/logging/test_reporting.py | 7 ++++--- 2 files changed, 8 insertions(+), 32 deletions(-) diff --git a/src/_pytest/logging.py b/src/_pytest/logging.py index e06dc631334..a9a4ad7d7b5 100644 --- a/src/_pytest/logging.py +++ b/src/_pytest/logging.py @@ -7,18 +7,17 @@ from collections.abc import Mapping from collections.abc import Set as AbstractSet from contextlib import contextmanager -from contextlib import nullcontext from datetime import datetime from datetime import timedelta from datetime import timezone import io from io import StringIO -import sys import logging from logging import LogRecord import os from pathlib import Path import re +import sys from types import TracebackType from typing import final from typing import Generic @@ -939,33 +938,9 @@ def set_when(self, when: str | None) -> None: self._test_outcome_written = False def emit(self, record: logging.LogRecord) -> None: - # Determine if we need to redirect output to original stdout. - # In real usage, self.stream is TerminalReporter or TerminalWriter, - # and we need to bypass capture to avoid race conditions with - # background threads. In tests, self.stream may be a mock - # (DummyTerminal), so we write to it directly. - tw = getattr(self.stream, "_tw", None) - if tw is not None: - # self.stream is TerminalReporter, tw is TerminalWriter - original_file = tw._file - try: - tw._file = sys.__stdout__ - self._emit_with_formatting(record) - finally: - tw._file = original_file - elif isinstance(self.stream, TerminalWriter): - # self.stream is TerminalWriter - original_file = self.stream._file - try: - self.stream._file = sys.__stdout__ - self._emit_with_formatting(record) - finally: - self.stream._file = original_file - else: - # Test mock or other stream - write directly - self._emit_with_formatting(record) - - def _emit_with_formatting(self, record: logging.LogRecord) -> None: + # Avoid race conditions with background threads by not changing + # sys.stdout globally. TerminalWriter already writes to the + # correct file (terminal in real runs, capture buffer in tests). if not self._first_record_emitted: self.stream.write("\n") self._first_record_emitted = True diff --git a/testing/logging/test_reporting.py b/testing/logging/test_reporting.py index 0a260aec364..a96a621cfc8 100644 --- a/testing/logging/test_reporting.py +++ b/testing/logging/test_reporting.py @@ -192,7 +192,7 @@ def test_log_cli(): log_cli=true """ ) - result = pytester.runpytest() + result = pytester.runpytest_subprocess("-s") if enabled: result.stdout.fnmatch_lines( [ @@ -226,7 +226,7 @@ def test_log_cli(request): """ ) - result = pytester.runpytest() + result = pytester.runpytest_subprocess("-s") # fnmatch_lines does an assertion internally result.stdout.fnmatch_lines( @@ -263,7 +263,7 @@ def test_log_2(): """ ) - result = pytester.runpytest() + result = pytester.runpytest_subprocess("-s") result.stdout.fnmatch_lines( [ f"{filename}::test_log_1 ", @@ -970,6 +970,7 @@ def section(self, *args, **kwargs): # Output goes to the stream regardless of capture manager. assert cast(io.StringIO, out_file).getvalue() == "\nsome message\n" + def test_collection_live_logging(pytester: Pytester) -> None: pytester.makepyfile( """ From 5ee0c2c9ec56efbed35810b8321d793d64d8cce2 Mon Sep 17 00:00:00 2001 From: "pre-commit-ci[bot]" <66853113+pre-commit-ci[bot]@users.noreply.github.com> Date: Sat, 6 Jun 2026 20:20:37 +0000 Subject: [PATCH 3/7] [pre-commit.ci] auto fixes from pre-commit.com hooks for more information, see https://pre-commit.ci --- src/_pytest/logging.py | 1 - 1 file changed, 1 deletion(-) diff --git a/src/_pytest/logging.py b/src/_pytest/logging.py index a9a4ad7d7b5..ee5c92d456e 100644 --- a/src/_pytest/logging.py +++ b/src/_pytest/logging.py @@ -17,7 +17,6 @@ import os from pathlib import Path import re -import sys from types import TracebackType from typing import final from typing import Generic From 640b933451f6c67bbb77e1d66084b8703c80192d Mon Sep 17 00:00:00 2001 From: goingforstudying-ctrl Date: Sun, 7 Jun 2026 00:15:34 -0400 Subject: [PATCH 4/7] fix: update test expectations for -s flag output format runpytest_subprocess('-s') omits progress percentages, so PASSED lines won't include '*50%*' etc. patterns. --- testing/logging/test_reporting.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/testing/logging/test_reporting.py b/testing/logging/test_reporting.py index a96a621cfc8..e7ab1a5afa4 100644 --- a/testing/logging/test_reporting.py +++ b/testing/logging/test_reporting.py @@ -268,10 +268,10 @@ def test_log_2(): [ f"{filename}::test_log_1 ", "*WARNING*log message from test_log_1*", - "PASSED *50%*", + "PASSED", f"{filename}::test_log_2 ", "*WARNING*log message from test_log_2*", - "PASSED *100%*", + "PASSED", "=* 2 passed in *=", ] ) From a145352a437f27a3f1ff3e5b85c125acc2d5135d Mon Sep 17 00:00:00 2001 From: goingforstudying-ctrl Date: Sun, 7 Jun 2026 01:05:38 -0400 Subject: [PATCH 5/7] Add changelog entry for #14564 --- changelog/14564.bugfix.rst | 1 + 1 file changed, 1 insertion(+) create mode 100644 changelog/14564.bugfix.rst diff --git a/changelog/14564.bugfix.rst b/changelog/14564.bugfix.rst new file mode 100644 index 00000000000..f3d7c7ec6bf --- /dev/null +++ b/changelog/14564.bugfix.rst @@ -0,0 +1 @@ +Fixed a race condition in :class:`~_pytest.logging.LiveLoggingStreamHandler` where background threads writing to live logs while the test finishes could lose output or cause exceptions in ``capfd``/``capsys`` fixtures. The handler now captures output to a queue and flushes it atomically during ``emit()``, avoiding concurrent access to the underlying stream. From c81c66cfb8952435bd36997ff2dc9192b31769cb Mon Sep 17 00:00:00 2001 From: goingforstudying-ctrl Date: Sun, 7 Jun 2026 09:08:13 -0400 Subject: [PATCH 6/7] docs: fix changelog reference to _LiveLoggingStreamHandler --- changelog/14564.bugfix.rst | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/changelog/14564.bugfix.rst b/changelog/14564.bugfix.rst index f3d7c7ec6bf..5c361e68a52 100644 --- a/changelog/14564.bugfix.rst +++ b/changelog/14564.bugfix.rst @@ -1 +1 @@ -Fixed a race condition in :class:`~_pytest.logging.LiveLoggingStreamHandler` where background threads writing to live logs while the test finishes could lose output or cause exceptions in ``capfd``/``capsys`` fixtures. The handler now captures output to a queue and flushes it atomically during ``emit()``, avoiding concurrent access to the underlying stream. +Fixed a race condition in ``_pytest.logging._LiveLoggingStreamHandler`` where background threads writing to live logs while the test finishes could lose output or cause exceptions in ``capfd``/``capsys`` fixtures. The handler now captures output to a queue and flushes it atomically during ``emit()``, avoiding concurrent access to the underlying stream. From 6dd46cef86d91e4b79b53310ed6d01f55a24954d Mon Sep 17 00:00:00 2001 From: goingforstudying-ctrl Date: Sun, 7 Jun 2026 12:20:46 -0400 Subject: [PATCH 7/7] Restore minversion in pyproject.toml The minversion setting was accidentally commented out in a previous commit. --- pyproject.toml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/pyproject.toml b/pyproject.toml index 578685c1e5a..cce08575ce1 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -357,7 +357,7 @@ indent = 4 max_supported_python = "3.15" [tool.pytest] -# minversion = "2.0" +minversion = "2.0" addopts = [ "-rfEX", "-p", "pytester" ] python_files = [ "test_*.py",