Skip to content
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 [backport 3.1] #13063

Open
wants to merge 1 commit into
base: 3.1
Choose a base branch
from

Conversation

github-actions[bot]
Copy link
Contributor

@github-actions github-actions bot commented Apr 4, 2025

Backport 2db08ec from #13030 to 3.1.

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 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

  • 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
  • The change includes or references documentation updates if necessary
  • Backport labels are set (if applicable)

Reviewer Checklist

  • 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 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

…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)
@github-actions github-actions bot requested review from a team as code owners April 4, 2025 10:10
@pr-commenter
Copy link

pr-commenter bot commented Apr 4, 2025

Benchmarks

Benchmark execution time: 2025-04-04 10:51:22

Comparing candidate commit 313e66b in PR branch backport-13030-to-3.1 with baseline commit f0fcbaf in branch 3.1.

Found 0 performance improvements and 0 performance regressions! Performance is the same for 386 metrics, 2 unstable metrics.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants