fix(ci_visibility): set up Test Optimization logging before pytest log capture [backport 3.3] #13065
Conversation
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
![github-actions[bot]](https://avatars.githubusercontent.com/in/15368?s=60&v=4){kind=small}
…g 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) (cherry picked from commit 2db08ec)
emmettbutler
approved these changes
Apr 4, 2025
|
|
Bootstrap import analysisComparison of import times between this PR and main. SummaryThe average import time in this PR is: 245 ± 5 ms. The average import time in main is: 236 ± 5 ms. The import time difference between this PR and main is: 9.9 ± 0.2 ms. Import time breakdownThe following import paths have appeared:
|
BenchmarksBenchmark execution time: 2025-04-09 16:13:28 Comparing candidate commit b62819d in PR branch Found 0 performance improvements and 7 performance regressions! Performance is the same for 481 metrics, 2 unstable metrics. scenario:iast_aspects-ospathbasename_aspect
scenario:iast_aspects-ospathdirname_aspect
scenario:iast_aspects-ospathjoin_aspect
scenario:iast_aspects-ospathnormcase_aspect
scenario:iast_aspects-ospathsplit_aspect
scenario:iast_aspects-ospathsplitdrive_aspect
scenario:iast_aspects-ospathsplitext_aspect
|
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
Backport 2db08ec from #13030 to 3.3.
We have a recurring problem where emitting logs at the end of a pytest test session results in errors like:
This happens because our plugin calls
take_over_logger_stream_handler(), which callslogging.StreamHandler(), which defaults to usingsys.stderras its output stream, but by the time we call it, pytest'spytest_load_initial_conftestshook fromcapture.pyhas already executed and replacedsys.stderrwith aFileIObuffer that is closed by the end of the test session, so we grab a reference to this internalFileIObuffer instead of the actualsys.stderr. This PR makes our ownpytest_load_initial_conftestshook run earlier than pytest'scapture.pyone.Additionally, this fixes
take_over_logger_stream_handler()to copy the handler list before callingremoveHandler(), 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 -sis used:Whether this is a bug or a feature is up to discussion. Previously we only printed this if
pytestwas 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():Checklist
Reviewer Checklist