PYTHON-5292 - Debug logs should only print on failed tests

Author: NoahStapp

.evergreen/scripts/run_tests.py

@@ -1,7 +1,6 @@
 from __future__ import annotations
 
 import json
-import logging
 import os
 import platform
 import shutil
@@ -173,9 +172,6 @@ def run() -> None:
         handle_aws_lambda()
         return
 
-    if os.environ.get("DEBUG_LOG"):
-        TEST_ARGS.extend(f"-o log_cli_level={logging.DEBUG} -o log_cli=1".split())
-
     # Run local tests.
     ret = pytest.main(TEST_ARGS + sys.argv[1:])
     if ret != 0:

.evergreen/scripts/setup_tests.py

@@ -30,7 +30,7 @@
     "GREEN_FRAMEWORK",
     "NO_EXT",
     "MONGODB_API_VERSION",
-    "DEBUG_LOG",
+    "PYMONGO_DEBUG_LOG_PATH",
     "PYTHON_BINARY",
     "PYTHON_VERSION",
     "REQUIRE_FIPS",
@@ -464,9 +464,7 @@ def handle_test_env() -> None:
         UV_ARGS.append(f"--group {framework}")
 
     else:
-        # Use --capture=tee-sys so pytest prints test output inline:
-        # https://docs.pytest.org/en/stable/how-to/capture-stdout-stderr.html
-        TEST_ARGS = f"-v --capture=tee-sys --durations=5 {TEST_ARGS}"
+        TEST_ARGS = f"-v --capture=no --show-capture=no --durations=5 {TEST_ARGS}"
         TEST_SUITE = TEST_SUITE_MAP.get(test_name)
         if TEST_SUITE:
             TEST_ARGS = f"-m {TEST_SUITE} {TEST_ARGS}"

pymongo/logger.py

@@ -15,6 +15,7 @@
 
 import enum
 import logging
+import logging.handlers
 import os
 import warnings
 from typing import Any
@@ -94,6 +95,46 @@ class _SDAMStatusMessage(str, enum.Enum):
     ConnectionClosedReason.IDLE: "Connection was idle too long",
     ConnectionCheckOutFailedReason.TIMEOUT: "Connection exceeded the specified timeout",
 }
+_DEBUG_LOG_HANDLER = None
+
+
+# Custom logging handler to ensure we only flush the buffered logs on a test failure
+class LoggingHandler(logging.handlers.MemoryHandler):
+    def __init__(self, capacity=1000, target=None):
+        super().__init__(capacity, logging.DEBUG, target, flushOnClose=False)
+        self.original_capacity = capacity
+
+    def shouldFlush(self, record):
+        if len(self.buffer) >= self.capacity:
+            self.capacity = len(self.buffer) * 2
+        return False
+
+    def flush(self):
+        super().flush()
+        self.capacity = self.original_capacity
+
+    def clear(self):
+        self.buffer.clear()
+        self.capacity = self.original_capacity
+
+
+if os.environ.get("DEBUG_LOG"):
+    FORMAT = "%(levelname)s %(name)s %(message)s"
+    handler = logging.StreamHandler()
+    handler.setFormatter(logging.Formatter(FORMAT))
+    _DEBUG_LOG_HANDLER = LoggingHandler(target=handler)
+
+    _COMMAND_LOGGER.setLevel(logging.DEBUG)
+    _SERVER_SELECTION_LOGGER.setLevel(logging.DEBUG)
+    _CONNECTION_LOGGER.setLevel(logging.DEBUG)
+    _CLIENT_LOGGER.setLevel(logging.DEBUG)
+    _SDAM_LOGGER.setLevel(logging.DEBUG)
+
+    _COMMAND_LOGGER.addHandler(_DEBUG_LOG_HANDLER)
+    _SERVER_SELECTION_LOGGER.addHandler(_DEBUG_LOG_HANDLER)
+    _CONNECTION_LOGGER.addHandler(_DEBUG_LOG_HANDLER)
+    _CLIENT_LOGGER.addHandler(_DEBUG_LOG_HANDLER)
+    _SDAM_LOGGER.addHandler(_DEBUG_LOG_HANDLER)
 
 
 def _log_client_error() -> None:

test/asynchronous/conftest.py

@@ -8,9 +8,24 @@
 import pytest
 import pytest_asyncio
 
+from pymongo.logger import _DEBUG_LOG_HANDLER
+
 _IS_SYNC = False
 
 
+@pytest.hookimpl(hookwrapper=True)
+def pytest_runtest_makereport(item):
+    if _DEBUG_LOG_HANDLER is not None:
+        outcome = yield
+        rep = outcome.get_result()
+        if rep.when == "call" and rep.failed:
+            _DEBUG_LOG_HANDLER.flush()
+        else:
+            _DEBUG_LOG_HANDLER.clear()
+    else:
+        yield
+
+
 @pytest.fixture(scope="session")
 def event_loop_policy():
     # The default asyncio loop implementation on Windows

test/asynchronous/test_client.py

@@ -34,7 +34,7 @@
 import time
 import uuid
 from typing import Any, Iterable, Type, no_type_check
-from unittest import mock
+from unittest import mock, skipIf
 from unittest.mock import patch
 
 import pytest
@@ -629,6 +629,7 @@ def test_detected_environment_logging(self, mock_get_hosts):
             logs = [record.getMessage() for record in cm.records if record.name == "pymongo.client"]
             self.assertEqual(len(logs), 7)
 
+    @skipIf(os.environ.get("DEBUG_LOG"), "Enabling debug logs breaks this test")
     @patch("pymongo.asynchronous.srv_resolver._SrvResolver.get_hosts")
     async def test_detected_environment_warning(self, mock_get_hosts):
         with self._caplog.at_level(logging.WARN):

test/conftest.py

@@ -6,9 +6,24 @@
 
 import pytest
 
+from pymongo.logger import _DEBUG_LOG_HANDLER
+
 _IS_SYNC = True
 
 
+@pytest.hookimpl(hookwrapper=True)
+def pytest_runtest_makereport(item):
+    if _DEBUG_LOG_HANDLER is not None:
+        outcome = yield
+        rep = outcome.get_result()
+        if rep.when == "call" and rep.failed:
+            _DEBUG_LOG_HANDLER.flush()
+        else:
+            _DEBUG_LOG_HANDLER.clear()
+    else:
+        yield
+
+
 @pytest.fixture(scope="session")
 def event_loop_policy():
     # The default asyncio loop implementation on Windows

test/test_client.py

@@ -34,7 +34,7 @@
 import time
 import uuid
 from typing import Any, Iterable, Type, no_type_check
-from unittest import mock
+from unittest import mock, skipIf
 from unittest.mock import patch
 
 import pytest
@@ -622,6 +622,7 @@ def test_detected_environment_logging(self, mock_get_hosts):
             logs = [record.getMessage() for record in cm.records if record.name == "pymongo.client"]
             self.assertEqual(len(logs), 7)
 
+    @skipIf(os.environ.get("DEBUG_LOG"), "Enabling debug logs breaks this test")
     @patch("pymongo.synchronous.srv_resolver._SrvResolver.get_hosts")
     def test_detected_environment_warning(self, mock_get_hosts):
         with self._caplog.at_level(logging.WARN):