Skip to content

Commit 590accb

Browse files
fix(ci_visibility): do not propagate ddtrace logs to the root logger (#14121)
When pytest is run with log capture on (which is the default, unless `-s` or similar is used), it replaces `sys.stdout` and `sys.stderr` with temporary file descriptors that are closed at the end of the test session. If a custom logger is created referencing one of those streams, any logs emitted after the end of the test session will try to write to the closed file descriptor, leading to an ` I/O operation on closed file` error. See #12018 for example cases. Annoyingly, this happens even if ddtrace is not explicitly enabled in pytest with `--ddtrace`, because before we even have the opportunity to parse command line arguments, `ddtrace/__init__.py` will load, which sets up a bunch of things, including loggers. At the beginning of a pytest session, we call a `take_over_logger_stream_handler()` function which sets up the `ddtrace` logger specifically for test runs. This PR: - Changes `take_over_logger_stream_handler()` to not propagate logs from the `ddtrace` handler to the root handler. This means the `ddtrace` handler will not be affected by custom loggers by default. - Makes `take_over_logger_stream_handler()` run even if `--ddtrace` is not enabled. This is not the ideal solution in the sky: ideally we would not enable ddtrace features at all when `--ddtrace` is not activated, however this is a bigger change to the way ddtrace works at the moment, so this PR focuses on avoiding the logging issue. Finally, this change makes the current tests that use `caplog` to check for logs emitted by `ddtrace` to break, because `caplog` depends on the logs being propagated to the root logger to capture them, so this PR adds a wrapping `caplog` fixture in our `conftest.py` that re-enables log propagation for those tests. (The alternative would be changing every `caplog.at_level(lvl)` call in our tests to `caplog.at_level(lvl, "ddtrace")`, but there are _a lot_ of them.) ## 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 ef1048e commit 590accb

File tree

5 files changed

+118
-5
lines changed

5 files changed

+118
-5
lines changed

ddtrace/contrib/internal/pytest/_plugin_v2.py

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -237,11 +237,12 @@ def _pytest_load_initial_conftests_pre_yield(early_config, parser, args):
237237
ModuleCodeCollector has a tangible impact on the time it takes to load modules, so it should only be installed if
238238
coverage collection is requested by the backend.
239239
"""
240+
take_over_logger_stream_handler()
241+
240242
if not _is_enabled_early(early_config, args):
241243
return
242244

243245
try:
244-
take_over_logger_stream_handler()
245246
dd_config.test_visibility.itr_skipping_level = ITR_SKIPPING_LEVEL.SUITE
246247
enable_test_visibility(config=dd_config.pytest)
247248
if InternalTestSession.should_collect_coverage():

ddtrace/internal/ci_visibility/utils.py

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -112,11 +112,10 @@ def take_over_logger_stream_handler(remove_ddtrace_stream_handlers=True):
112112
log.debug("CIVisibility not taking over ddtrace logger because level is set to: %s", level)
113113
return
114114

115-
root_logger = logging.getLogger()
115+
ddtrace_logger = logging.getLogger("ddtrace")
116116

117117
if remove_ddtrace_stream_handlers:
118118
log.debug("CIVisibility removing DDTrace logger handler")
119-
ddtrace_logger = logging.getLogger("ddtrace")
120119
for handler in list(ddtrace_logger.handlers):
121120
ddtrace_logger.removeHandler(handler)
122121
else:
@@ -136,8 +135,9 @@ def take_over_logger_stream_handler(remove_ddtrace_stream_handlers=True):
136135
log.warning("Invalid log level: %s", level)
137136
return
138137

139-
root_logger.addHandler(ci_visibility_handler)
140-
root_logger.setLevel(min(root_logger.level, ci_visibility_handler.level))
138+
ddtrace_logger.addHandler(ci_visibility_handler)
139+
ddtrace_logger.setLevel(min(ddtrace_logger.level, ci_visibility_handler.level))
140+
ddtrace_logger.propagate = False
141141

142142
log.debug("logger setup complete")
143143

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,6 @@
1+
---
2+
fixes:
3+
- |
4+
CI Visibility: This fix resolves an issue where setting custom loggers during a test session could cause the tracer
5+
to emit logs to a logging stream handler that was already closed by ``pytest``, leading to ``I/O operation on closed
6+
file`` errors at the end of the test session.

tests/conftest.py

Lines changed: 18 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -6,6 +6,7 @@
66
import importlib
77
from itertools import product
88
import json
9+
import logging
910
import os
1011
from os.path import split
1112
from os.path import splitext
@@ -678,3 +679,20 @@ def test_agent_session(telemetry_writer, request):
678679
finally:
679680
os.environ["DD_CIVISIBILITY_AGENTLESS_ENABLED"] = p_agentless
680681
telemetry_writer.reset_queues()
682+
683+
684+
@pytest.fixture()
685+
def caplog(caplog):
686+
"""
687+
During tests, ddtrace logs are not propagated to the root logger by default (see PR #14121).
688+
This breaks caplog tests that capture logs from the ddtrace logger, so we need to re-enable propagation for those.
689+
"""
690+
ddtrace_logger = logging.getLogger("ddtrace")
691+
692+
try:
693+
original_propagate = ddtrace_logger.propagate
694+
ddtrace_logger.propagate = True
695+
yield caplog
696+
697+
finally:
698+
ddtrace_logger.propagate = original_propagate

tests/contrib/pytest/test_pytest.py

Lines changed: 88 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -4187,6 +4187,94 @@ def test_dependency_collection_disabled():
41874187
result = self.subprocess_run("--ddtrace", file_name)
41884188
assert result.ret == 0
41894189

4190+
def test_pytest_ddtrace_logger_unaffected_by_log_capture(self):
4191+
py_file = self.testdir.makepyfile(
4192+
"""
4193+
import os
4194+
import sys
4195+
import logging.config
4196+
4197+
def test_log_capture():
4198+
config = {
4199+
"version": 1,
4200+
"disable_existing_loggers": False,
4201+
"formatters": {
4202+
"simple": {
4203+
"format": "%(asctime)s - %(name)s - %(levelname)s - %(message)s",
4204+
"datefmt": "%Y-%m-%d %H:%M:%S"
4205+
}
4206+
},
4207+
"handlers": {
4208+
"stdout": {
4209+
"class": "logging.StreamHandler",
4210+
"level": "DEBUG",
4211+
"formatter": "simple",
4212+
"stream": "ext://sys.stdout"
4213+
}
4214+
},
4215+
"loggers": {
4216+
"root": {
4217+
"level": "DEBUG",
4218+
"handlers": [
4219+
"stdout"
4220+
]
4221+
}
4222+
}
4223+
}
4224+
logging.config.dictConfig(config)
4225+
4226+
"""
4227+
)
4228+
file_name = os.path.basename(py_file.strpath)
4229+
4230+
result = self.subprocess_run("--ddtrace", file_name)
4231+
assert "I/O operation on closed file" not in result.stderr.str()
4232+
assert result.ret == 0
4233+
4234+
def test_pytest_no_ddtrace_logger_unaffected_by_log_capture(self):
4235+
py_file = self.testdir.makepyfile(
4236+
"""
4237+
import os
4238+
import sys
4239+
import logging.config
4240+
4241+
def test_log_capture():
4242+
config = {
4243+
"version": 1,
4244+
"disable_existing_loggers": False,
4245+
"formatters": {
4246+
"simple": {
4247+
"format": "%(asctime)s - %(name)s - %(levelname)s - %(message)s",
4248+
"datefmt": "%Y-%m-%d %H:%M:%S"
4249+
}
4250+
},
4251+
"handlers": {
4252+
"stdout": {
4253+
"class": "logging.StreamHandler",
4254+
"level": "DEBUG",
4255+
"formatter": "simple",
4256+
"stream": "ext://sys.stdout"
4257+
}
4258+
},
4259+
"loggers": {
4260+
"root": {
4261+
"level": "DEBUG",
4262+
"handlers": [
4263+
"stdout"
4264+
]
4265+
}
4266+
}
4267+
}
4268+
logging.config.dictConfig(config)
4269+
4270+
"""
4271+
)
4272+
file_name = os.path.basename(py_file.strpath)
4273+
4274+
result = self.subprocess_run(file_name)
4275+
assert "I/O operation on closed file" not in result.stderr.str()
4276+
assert result.ret == 0
4277+
41904278

41914279
def test_pytest_coverage_data_format_handling_none_value():
41924280
"""Test that coverage data format issues are handled correctly with proper logging for None value."""

0 commit comments

Comments
 (0)