From 65d6eed8e68e1c773b8edb13956dd3d82ec4ca26 Mon Sep 17 00:00:00 2001 From: Noah Stapp Date: Mon, 14 Apr 2025 11:01:35 -0400 Subject: [PATCH 1/5] PYTHON-5292 - Debug logs should only print on failed tests --- .evergreen/scripts/run_tests.py | 4 --- .evergreen/scripts/setup_tests.py | 6 ++--- pymongo/logger.py | 41 +++++++++++++++++++++++++++++++ test/asynchronous/conftest.py | 15 +++++++++++ test/asynchronous/test_client.py | 3 ++- test/conftest.py | 15 +++++++++++ test/test_client.py | 3 ++- 7 files changed, 77 insertions(+), 10 deletions(-) diff --git a/.evergreen/scripts/run_tests.py b/.evergreen/scripts/run_tests.py index 9f700d70e0..3cfefd66b8 100644 --- a/.evergreen/scripts/run_tests.py +++ b/.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: diff --git a/.evergreen/scripts/setup_tests.py b/.evergreen/scripts/setup_tests.py index 2fa1fc47fc..a6b569d165 100644 --- a/.evergreen/scripts/setup_tests.py +++ b/.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}" diff --git a/pymongo/logger.py b/pymongo/logger.py index 1b3fe43b86..ce68fbe60a 100644 --- a/pymongo/logger.py +++ b/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: diff --git a/test/asynchronous/conftest.py b/test/asynchronous/conftest.py index a27a9f213d..1799ef1431 100644 --- a/test/asynchronous/conftest.py +++ b/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 diff --git a/test/asynchronous/test_client.py b/test/asynchronous/test_client.py index c9cfca81fc..143cccc3c8 100644 --- a/test/asynchronous/test_client.py +++ b/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): diff --git a/test/conftest.py b/test/conftest.py index 91fad28d0a..057d2767a9 100644 --- a/test/conftest.py +++ b/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 diff --git a/test/test_client.py b/test/test_client.py index 038ba2241b..8ef95699ca 100644 --- a/test/test_client.py +++ b/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): From 2e89d3828a1838ae78a3fdb9eb70788e912383f9 Mon Sep 17 00:00:00 2001 From: Noah Stapp Date: Mon, 14 Apr 2025 14:27:31 -0400 Subject: [PATCH 2/5] Fix env passthrough for DEBUG_LOG --- .evergreen/scripts/setup_tests.py | 2 +- test/asynchronous/conftest.py | 2 +- test/conftest.py | 2 +- 3 files changed, 3 insertions(+), 3 deletions(-) diff --git a/.evergreen/scripts/setup_tests.py b/.evergreen/scripts/setup_tests.py index 780079a3a9..a39020e160 100644 --- a/.evergreen/scripts/setup_tests.py +++ b/.evergreen/scripts/setup_tests.py @@ -30,7 +30,7 @@ "GREEN_FRAMEWORK", "NO_EXT", "MONGODB_API_VERSION", - "PYMONGO_DEBUG_LOG_PATH", + "DEBUG_LOG", "PYTHON_BINARY", "PYTHON_VERSION", "REQUIRE_FIPS", diff --git a/test/asynchronous/conftest.py b/test/asynchronous/conftest.py index 1799ef1431..281707fdcc 100644 --- a/test/asynchronous/conftest.py +++ b/test/asynchronous/conftest.py @@ -18,7 +18,7 @@ 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: + if rep.failed: _DEBUG_LOG_HANDLER.flush() else: _DEBUG_LOG_HANDLER.clear() diff --git a/test/conftest.py b/test/conftest.py index 057d2767a9..a149e100cf 100644 --- a/test/conftest.py +++ b/test/conftest.py @@ -16,7 +16,7 @@ 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: + if rep.failed: _DEBUG_LOG_HANDLER.flush() else: _DEBUG_LOG_HANDLER.clear() From 9f2891d5530c342539ee88b94dd87bbfbb8f6cf9 Mon Sep 17 00:00:00 2001 From: Noah Stapp Date: Mon, 14 Apr 2025 15:20:55 -0400 Subject: [PATCH 3/5] Lock LoggingHandler.clear --- .evergreen/scripts/run_tests.py | 1 + pymongo/logger.py | 5 +++-- 2 files changed, 4 insertions(+), 2 deletions(-) diff --git a/.evergreen/scripts/run_tests.py b/.evergreen/scripts/run_tests.py index 3cfefd66b8..5b85d74c86 100644 --- a/.evergreen/scripts/run_tests.py +++ b/.evergreen/scripts/run_tests.py @@ -173,6 +173,7 @@ def run() -> None: return # Run local tests. + print(f"Running tests with args: {TEST_ARGS + sys.argv[1:]}") ret = pytest.main(TEST_ARGS + sys.argv[1:]) if ret != 0: sys.exit(ret) diff --git a/pymongo/logger.py b/pymongo/logger.py index ce68fbe60a..b760a757c2 100644 --- a/pymongo/logger.py +++ b/pymongo/logger.py @@ -114,8 +114,9 @@ def flush(self): self.capacity = self.original_capacity def clear(self): - self.buffer.clear() - self.capacity = self.original_capacity + with self.lock: + self.buffer.clear() + self.capacity = self.original_capacity if os.environ.get("DEBUG_LOG"): From 25a4a1dfbe7be6688c82c8df94904214b670d26a Mon Sep 17 00:00:00 2001 From: Noah Stapp Date: Thu, 17 Apr 2025 15:16:53 -0400 Subject: [PATCH 4/5] PYTHON-5292 - Debug logs should only output on test failure --- .evergreen/scripts/run_tests.py | 1 - .evergreen/scripts/setup_tests.py | 2 +- CONTRIBUTING.md | 8 ++++---- pymongo/logger.py | 34 ------------------------------- pyproject.toml | 1 + test/asynchronous/conftest.py | 15 -------------- test/conftest.py | 15 -------------- 7 files changed, 6 insertions(+), 70 deletions(-) diff --git a/.evergreen/scripts/run_tests.py b/.evergreen/scripts/run_tests.py index 5b85d74c86..3cfefd66b8 100644 --- a/.evergreen/scripts/run_tests.py +++ b/.evergreen/scripts/run_tests.py @@ -173,7 +173,6 @@ def run() -> None: return # Run local tests. - print(f"Running tests with args: {TEST_ARGS + sys.argv[1:]}") ret = pytest.main(TEST_ARGS + sys.argv[1:]) if ret != 0: sys.exit(ret) diff --git a/.evergreen/scripts/setup_tests.py b/.evergreen/scripts/setup_tests.py index a39020e160..058e86a805 100644 --- a/.evergreen/scripts/setup_tests.py +++ b/.evergreen/scripts/setup_tests.py @@ -465,7 +465,7 @@ def handle_test_env() -> None: UV_ARGS.append(f"--group {framework}") else: - TEST_ARGS = f"-v --capture=no --show-capture=no --durations=5 {TEST_ARGS}" + TEST_ARGS = f"-v --durations=5 {TEST_ARGS}" TEST_SUITE = TEST_SUITE_MAP.get(test_name) if TEST_SUITE: TEST_ARGS = f"-m {TEST_SUITE} {TEST_ARGS}" diff --git a/CONTRIBUTING.md b/CONTRIBUTING.md index 60583022b7..2f55fe9a99 100644 --- a/CONTRIBUTING.md +++ b/CONTRIBUTING.md @@ -351,11 +351,11 @@ If you are running one of the `no-responder` tests, omit the `run-server` step. ## Enable Debug Logs -- Use `-o log_cli_level="DEBUG" -o log_cli=1` with `just test` or `pytest`. -- Add `log_cli_level = "DEBUG` and `log_cli = 1` to the `tool.pytest.ini_options` section in `pyproject.toml` for Evergreen patches or to enable debug logs by default on your machine. -- You can also set `DEBUG_LOG=1` and run either `just setup-tests` or `just-test`. +- Use `-o log_cli_level="DEBUG" -o log_cli=1` with `just test` or `pytest` to output all debug logs to the terminal. **Warning**: This will output a huge amount of logs. +- Add `log_cli_level = "DEBUG` to the `tool.pytest.ini_options` section in `pyproject.toml` to enable debug logs in this manner by default on your machine. +- Set `DEBUG_LOG=1` and run `just setup-tests`, `just-test`, or `pytest` to enable debug logs only for failed tests. - Finally, you can use `just setup-tests --debug-log`. -- For evergreen patch builds, you can use `evergreen patch --param DEBUG_LOG=1` to enable debug logs for the patch. +- For evergreen patch builds, you can use `evergreen patch --param DEBUG_LOG=1` to enable debug logs for failed tests in the patch. ## Adding a new test suite diff --git a/pymongo/logger.py b/pymongo/logger.py index b760a757c2..c8c5348d71 100644 --- a/pymongo/logger.py +++ b/pymongo/logger.py @@ -95,48 +95,14 @@ 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): - with self.lock: - 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: # This is called from a daemon thread so check for None to account for interpreter shutdown. diff --git a/pyproject.toml b/pyproject.toml index 4da75b4c13..6597ddd4e1 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -98,6 +98,7 @@ minversion = "7" addopts = ["-ra", "--strict-config", "--strict-markers", "--junitxml=xunit-results/TEST-results.xml", "-m default or default_async"] testpaths = ["test"] log_cli_level = "INFO" +log_cli = true faulthandler_timeout = 1500 asyncio_default_fixture_loop_scope = "session" xfail_strict = true diff --git a/test/asynchronous/conftest.py b/test/asynchronous/conftest.py index 281707fdcc..a27a9f213d 100644 --- a/test/asynchronous/conftest.py +++ b/test/asynchronous/conftest.py @@ -8,24 +8,9 @@ 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.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 diff --git a/test/conftest.py b/test/conftest.py index a149e100cf..91fad28d0a 100644 --- a/test/conftest.py +++ b/test/conftest.py @@ -6,24 +6,9 @@ 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.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 From 1538fdd149884612a7d56730fc5f10124fd4988e Mon Sep 17 00:00:00 2001 From: Noah Stapp Date: Fri, 18 Apr 2025 11:31:02 -0400 Subject: [PATCH 5/5] Simplify --- .evergreen/scripts/run_tests.py | 4 ++++ CONTRIBUTING.md | 2 +- pymongo/logger.py | 8 -------- pyproject.toml | 1 - 4 files changed, 5 insertions(+), 10 deletions(-) diff --git a/.evergreen/scripts/run_tests.py b/.evergreen/scripts/run_tests.py index 3cfefd66b8..8fa3623d66 100644 --- a/.evergreen/scripts/run_tests.py +++ b/.evergreen/scripts/run_tests.py @@ -1,6 +1,7 @@ from __future__ import annotations import json +import logging import os import platform import shutil @@ -172,6 +173,9 @@ def run() -> None: handle_aws_lambda() return + if os.environ.get("DEBUG_LOG"): + TEST_ARGS.extend(f"-o log_cli_level={logging.DEBUG}".split()) + # Run local tests. ret = pytest.main(TEST_ARGS + sys.argv[1:]) if ret != 0: diff --git a/CONTRIBUTING.md b/CONTRIBUTING.md index 2f55fe9a99..12e6f0cd0e 100644 --- a/CONTRIBUTING.md +++ b/CONTRIBUTING.md @@ -352,7 +352,7 @@ If you are running one of the `no-responder` tests, omit the `run-server` step. ## Enable Debug Logs - Use `-o log_cli_level="DEBUG" -o log_cli=1` with `just test` or `pytest` to output all debug logs to the terminal. **Warning**: This will output a huge amount of logs. -- Add `log_cli_level = "DEBUG` to the `tool.pytest.ini_options` section in `pyproject.toml` to enable debug logs in this manner by default on your machine. +- Add `log_cli=1` and `log_cli_level="DEBUG"` to the `tool.pytest.ini_options` section in `pyproject.toml` to enable debug logs in this manner by default on your machine. - Set `DEBUG_LOG=1` and run `just setup-tests`, `just-test`, or `pytest` to enable debug logs only for failed tests. - Finally, you can use `just setup-tests --debug-log`. - For evergreen patch builds, you can use `evergreen patch --param DEBUG_LOG=1` to enable debug logs for failed tests in the patch. diff --git a/pymongo/logger.py b/pymongo/logger.py index c8c5348d71..1b3fe43b86 100644 --- a/pymongo/logger.py +++ b/pymongo/logger.py @@ -15,7 +15,6 @@ import enum import logging -import logging.handlers import os import warnings from typing import Any @@ -96,13 +95,6 @@ class _SDAMStatusMessage(str, enum.Enum): ConnectionCheckOutFailedReason.TIMEOUT: "Connection exceeded the specified timeout", } -if os.environ.get("DEBUG_LOG"): - _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) - def _log_client_error() -> None: # This is called from a daemon thread so check for None to account for interpreter shutdown. diff --git a/pyproject.toml b/pyproject.toml index 6597ddd4e1..4da75b4c13 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -98,7 +98,6 @@ minversion = "7" addopts = ["-ra", "--strict-config", "--strict-markers", "--junitxml=xunit-results/TEST-results.xml", "-m default or default_async"] testpaths = ["test"] log_cli_level = "INFO" -log_cli = true faulthandler_timeout = 1500 asyncio_default_fixture_loop_scope = "session" xfail_strict = true