From 313e66b17ed7fef0eca17d3ca90a1a8ec5bcf6ba Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?V=C3=ADtor=20De=20Ara=C3=BAjo?= Date: Fri, 4 Apr 2025 10:09:55 +0000 Subject: [PATCH] fix(ci_visibility): set up Test Optimization logging before pytest log capture (#13030) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit We have a recurring problem where emitting logs at the end of a pytest test session results in errors like: ``` Traceback (most recent call last): File "/usr/local/lib/python3.10/logging/__init__.py", line 1103, in emit stream.write(msg + self.terminator) ValueError: I/O operation on closed file. ``` This happens because our plugin calls `take_over_logger_stream_handler()`, which calls `logging.StreamHandler()`, which defaults to using `sys.stderr` as its output stream, but by the time we call it, pytest's [`pytest_load_initial_conftests` hook from `capture.py`](https://github.com/pytest-dev/pytest/blob/8.3.x/src/_pytest/capture.py#L155) has already executed and replaced `sys.stderr` with a `FileIO` buffer that is closed by the end of the test session, so we grab a reference to this internal `FileIO` buffer instead of the actual `sys.stderr`. This PR makes our own `pytest_load_initial_conftests` hook run earlier than pytest's `capture.py` one. Additionally, this fixes `take_over_logger_stream_handler()` to copy the handler list before calling `removeHandler()`, as this mutates the list we are iterating through. One user-visible side effect of this is that now we always print these logs at the beginning of the test session, regardless of whether `pytest -s` is used: ``` [Datadog CI Visibility] INFO ddtrace.internal.ci_visibility.recorder:recorder.py:294 Service: vitor-test (env: some-env) [Datadog CI Visibility] INFO ddtrace.internal.ci_visibility.recorder:recorder.py:295 Requests mode: agentless [Datadog CI Visibility] INFO ddtrace.internal.ci_visibility.recorder:recorder.py:296 Git metadata upload enabled: True [Datadog CI Visibility] INFO ddtrace.internal.ci_visibility.recorder:recorder.py:297 API-provided settings: coverage collection: False [Datadog CI Visibility] INFO ddtrace.internal.ci_visibility.recorder:recorder.py:298 API-provided settings: Intelligent Test Runner: False, test skipping: False [Datadog CI Visibility] INFO ddtrace.internal.ci_visibility.recorder:recorder.py:303 API-provided settings: Early Flake Detection enabled: True [Datadog CI Visibility] INFO ddtrace.internal.ci_visibility.recorder:recorder.py:307 API-provided settings: Auto Test Retries enabled: True [Datadog CI Visibility] INFO ddtrace.internal.ci_visibility.recorder:recorder.py:308 Detected configurations: {'os.architecture': 'x86_64', 'os.platform': 'Linux', 'os.version': '6.5.0-1027-oem', 'runtime.name': 'CPython', 'runtime.version': '3.10.14'} [Datadog CI Visibility] WARNING ddtrace.internal.ci_visibility.recorder:recorder.py:313 CODEOWNERS file is not available [Datadog CI Visibility] INFO ddtrace.internal.ci_visibility.recorder:recorder.py:628 Unique tests fetched for Early Flake Detection: 34 [Datadog CI Visibility] INFO ddtrace.internal.ci_visibility.recorder:recorder.py:576 Final settings: coverage collection: False, test skipping: False, Early Flake Detection: True, Auto Test Retries: True, Flaky Test Management: True ``` Whether this is a bug or a feature is up to discussion. Previously we only printed this if `pytest` was called with `-s`, more by accident than by design. The way I managed to reproduce it was by raising an exception right after tracer shutdown in `CIVisibility._stop_service()`: ``` def _stop_service(self) -> None: ... try: self.tracer.shutdown() raise Exception("ꙮ") # <--- added here except Exception: log.warning("Failed to shutdown tracer", exc_info=True) ``` ## Checklist - [x] PR author has checked that all the criteria below are met - The PR description includes an overview of the change - The PR description articulates the motivation for the change - The change includes tests OR the PR description describes a testing strategy - The PR description notes risks associated with the change, if any - Newly-added code is easy to change - The change follows the [library release note guidelines](https://ddtrace.readthedocs.io/en/stable/releasenotes.html) - The change includes or references documentation updates if necessary - Backport labels are set (if [applicable](https://ddtrace.readthedocs.io/en/latest/contributing.html#backporting)) ## Reviewer Checklist - [x] Reviewer has checked that all the criteria below are met - Title is accurate - All changes are related to the pull request's stated goal - Avoids breaking [API](https://ddtrace.readthedocs.io/en/stable/versioning.html#interfaces) changes - Testing strategy adequately addresses listed risks - Newly-added code is easy to change - Release note makes sense to a user of the library - If necessary, author has acknowledged and discussed the performance implications of this PR as reported in the benchmarks PR comment - Backport labels are set in a manner that is consistent with the [release branch maintenance policy](https://ddtrace.readthedocs.io/en/latest/contributing.html#backporting) (cherry picked from commit 2db08ec02cb7ea3245d0f12d7f763df30c67e536) --- ddtrace/contrib/internal/pytest/_plugin_v2.py | 11 +++++++++++ ddtrace/internal/ci_visibility/utils.py | 2 +- ...fix-io-operation-closed-file-1e1089eabd5296ce.yaml | 5 +++++ 3 files changed, 17 insertions(+), 1 deletion(-) create mode 100644 releasenotes/notes/ci_visibility-fix-io-operation-closed-file-1e1089eabd5296ce.yaml diff --git a/ddtrace/contrib/internal/pytest/_plugin_v2.py b/ddtrace/contrib/internal/pytest/_plugin_v2.py index 5be675c30df..e7cb4a50e84 100644 --- a/ddtrace/contrib/internal/pytest/_plugin_v2.py +++ b/ddtrace/contrib/internal/pytest/_plugin_v2.py @@ -181,7 +181,18 @@ def _disable_ci_visibility(): log.debug("encountered error during disable_ci_visibility", exc_info=True) +@pytest.hookimpl(tryfirst=True, hookwrapper=True) def pytest_load_initial_conftests(early_config, parser, args): + """Perform early initialization of the Test Optimization plugin. + + This has to happen early enough that `sys.stderr` has not been redirected by pytest, so that logging is configured + properly. Setting the hook with `tryfirst=True` and `hookwrapper=True` achieves that. + """ + _pytest_load_initial_conftests_pre_yield(early_config, parser, args) + yield + + +def _pytest_load_initial_conftests_pre_yield(early_config, parser, args): """Performs the bare-minimum to determine whether or ModuleCodeCollector should be enabled ModuleCodeCollector has a tangible impact on the time it takes to load modules, so it should only be installed if diff --git a/ddtrace/internal/ci_visibility/utils.py b/ddtrace/internal/ci_visibility/utils.py index 770c574e98d..43cf91219e4 100644 --- a/ddtrace/internal/ci_visibility/utils.py +++ b/ddtrace/internal/ci_visibility/utils.py @@ -117,7 +117,7 @@ def take_over_logger_stream_handler(remove_ddtrace_stream_handlers=True): if remove_ddtrace_stream_handlers: log.debug("CIVisibility removing DDTrace logger handler") ddtrace_logger = logging.getLogger("ddtrace") - for handler in ddtrace_logger.handlers: + for handler in list(ddtrace_logger.handlers): ddtrace_logger.removeHandler(handler) else: log.warning("Keeping DDTrace logger handler, double logging is likely") diff --git a/releasenotes/notes/ci_visibility-fix-io-operation-closed-file-1e1089eabd5296ce.yaml b/releasenotes/notes/ci_visibility-fix-io-operation-closed-file-1e1089eabd5296ce.yaml new file mode 100644 index 00000000000..9ad2f58f3f1 --- /dev/null +++ b/releasenotes/notes/ci_visibility-fix-io-operation-closed-file-1e1089eabd5296ce.yaml @@ -0,0 +1,5 @@ +--- +fixes: + - | + CI Visibility: This fix resolves an issue where an ``I/O operation on closed file`` error was raised while printing + ``ddtrace`` logs during a pytest session, due to a conflict with pytest's log capture.