Skip to content

Commit 2db08ec

Browse files
fix(ci_visibility): set up Test Optimization logging before pytest log capture (#13030)
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)
1 parent 86dc030 commit 2db08ec

File tree

3 files changed

+17
-1
lines changed

3 files changed

+17
-1
lines changed

ddtrace/contrib/internal/pytest/_plugin_v2.py

+11
Original file line numberDiff line numberDiff line change
@@ -190,7 +190,18 @@ def _disable_ci_visibility():
190190
log.debug("encountered error during disable_ci_visibility", exc_info=True)
191191

192192

193+
@pytest.hookimpl(tryfirst=True, hookwrapper=True)
193194
def pytest_load_initial_conftests(early_config, parser, args):
195+
"""Perform early initialization of the Test Optimization plugin.
196+
197+
This has to happen early enough that `sys.stderr` has not been redirected by pytest, so that logging is configured
198+
properly. Setting the hook with `tryfirst=True` and `hookwrapper=True` achieves that.
199+
"""
200+
_pytest_load_initial_conftests_pre_yield(early_config, parser, args)
201+
yield
202+
203+
204+
def _pytest_load_initial_conftests_pre_yield(early_config, parser, args):
194205
"""Performs the bare-minimum to determine whether or ModuleCodeCollector should be enabled
195206
196207
ModuleCodeCollector has a tangible impact on the time it takes to load modules, so it should only be installed if

ddtrace/internal/ci_visibility/utils.py

+1-1
Original file line numberDiff line numberDiff line change
@@ -117,7 +117,7 @@ def take_over_logger_stream_handler(remove_ddtrace_stream_handlers=True):
117117
if remove_ddtrace_stream_handlers:
118118
log.debug("CIVisibility removing DDTrace logger handler")
119119
ddtrace_logger = logging.getLogger("ddtrace")
120-
for handler in ddtrace_logger.handlers:
120+
for handler in list(ddtrace_logger.handlers):
121121
ddtrace_logger.removeHandler(handler)
122122
else:
123123
log.warning("Keeping DDTrace logger handler, double logging is likely")
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,5 @@
1+
---
2+
fixes:
3+
- |
4+
CI Visibility: This fix resolves an issue where an ``I/O operation on closed file`` error was raised while printing
5+
``ddtrace`` logs during a pytest session, due to a conflict with pytest's log capture.

0 commit comments

Comments
 (0)