-
Notifications
You must be signed in to change notification settings - Fork 456
fix(ci_visibility): set up Test Optimization logging before pytest log capture #13030
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
fix(ci_visibility): set up Test Optimization logging before pytest log capture #13030
Conversation
|
…raujo/SDTEST-323/io-operation-closed-file
Bootstrap import analysisComparison of import times between this PR and base. SummaryThe average import time from this PR is: 230 ± 4 ms. The average import time from base is: 232 ± 4 ms. The import time difference between this PR and base is: -2.1 ± 0.2 ms. Import time breakdownThe following import paths have shrunk:
|
Finally! Yet another of my crimes is will be avenged. 😍 |
This is a feature. This output was missing since the migration to the the |
BenchmarksBenchmark execution time: 2025-04-04 09:44:51 Comparing candidate commit c53aa66 in PR branch Found 0 performance improvements and 0 performance regressions! Performance is the same for 490 metrics, 2 unstable metrics. |
…raujo/SDTEST-323/io-operation-closed-file
|
|
|
This reverts commit 713155e.
|
|
|
|
|
|
…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)
…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)
…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)
…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)
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.stderr
as its output stream, but by the time we call it, pytest'spytest_load_initial_conftests
hook fromcapture.py
has already executed and replacedsys.stderr
with aFileIO
buffer that is closed by the end of the test session, so we grab a reference to this internalFileIO
buffer instead of the actualsys.stderr
. This PR makes our ownpytest_load_initial_conftests
hook run earlier than pytest'scapture.py
one.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 -s
is used: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()
:Checklist
Reviewer Checklist