Skip to content

Commit 4e5b680

Browse files
pmcollinspmcollins
committed
fix(auto-instrumentation): print debug startup diagnostics
1 parent cbd7f65 commit 4e5b680

3 files changed

Lines changed: 141 additions & 8 deletions

File tree

‎CHANGELOG.md‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -13,6 +13,8 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
1313

1414
### Added
1515

16+
- `opentelemetry-instrumentation`: Write auto-instrumentation debug startup messages to stderr when `OTEL_LOG_LEVEL` is set to `debug` or `trace`.
17+
(#4542)[https://github.com/open-telemetry/opentelemetry-python-contrib/pull/4542]
1618
- Bump `pylint` to `4.0.5`
1719
([#4244](https://github.com/open-telemetry/opentelemetry-python-contrib/pull/4244))
1820
- `opentelemetry-instrumentation-sqlite3`: Add uninstrument, error status, suppress, and no-op tests

‎opentelemetry-instrumentation/src/opentelemetry/instrumentation/auto_instrumentation/_load.py‎

Lines changed: 40 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -13,8 +13,9 @@
1313
# limitations under the License.
1414

1515
from functools import cached_property
16-
from logging import getLogger
16+
from logging import DEBUG, getLogger
1717
from os import environ
18+
from sys import stderr
1819

1920
from opentelemetry.instrumentation.dependencies import (
2021
DependencyConflictError,
@@ -36,6 +37,37 @@
3637
_logger = getLogger(__name__)
3738

3839
SKIPPED_INSTRUMENTATIONS_WILDCARD = "*"
40+
OTEL_LOG_LEVEL = "OTEL_LOG_LEVEL"
41+
_DEBUG_LOG_LEVELS = frozenset(("trace", "debug"))
42+
43+
44+
def _diagnostic_debug_enabled() -> bool:
45+
log_level = environ.get(OTEL_LOG_LEVEL, "").strip().lower()
46+
return log_level in _DEBUG_LOG_LEVELS
47+
48+
49+
def _logger_handles_debug() -> bool:
50+
return _logger.isEnabledFor(DEBUG) and _logger.hasHandlers()
51+
52+
53+
def _format_diagnostic_arg(arg: object) -> object:
54+
if isinstance(arg, str):
55+
return repr(arg)
56+
57+
return arg
58+
59+
60+
def _debug(message: str, *args: object) -> None:
61+
_logger.debug(message, *args)
62+
63+
if not _diagnostic_debug_enabled() or _logger_handles_debug():
64+
return
65+
66+
if args:
67+
message = message % tuple(_format_diagnostic_arg(arg) for arg in args)
68+
69+
stderr.write(f"DEBUG:{__name__}:{message}\n")
70+
stderr.flush()
3971

4072

4173
class _EntryPointDistFinder:
@@ -67,12 +99,12 @@ def _load_distro() -> BaseDistro:
6799
if distro_name is None or distro_name == entry_point.name:
68100
distro = entry_point.load()()
69101
if not isinstance(distro, BaseDistro):
70-
_logger.debug(
102+
_debug(
71103
"%s is not an OpenTelemetry Distro. Skipping",
72104
entry_point.name,
73105
)
74106
continue
75-
_logger.debug(
107+
_debug(
76108
"Distribution %s will be configured", entry_point.name
77109
)
78110
return distro
@@ -100,7 +132,7 @@ def _load_instrumentors(distro):
100132
break
101133

102134
if entry_point.name in package_to_exclude:
103-
_logger.debug(
135+
_debug(
104136
"Instrumentation skipped for library %s", entry_point.name
105137
)
106138
continue
@@ -109,7 +141,7 @@ def _load_instrumentors(distro):
109141
entry_point_dist = entry_point_finder.dist_for(entry_point)
110142
conflict = get_dist_dependency_conflicts(entry_point_dist)
111143
if conflict:
112-
_logger.debug(
144+
_debug(
113145
"Skipping instrumentation %s: %s",
114146
entry_point.name,
115147
conflict,
@@ -118,13 +150,13 @@ def _load_instrumentors(distro):
118150

119151
# tell instrumentation to not run dep checks again as we already did it above
120152
distro.load_instrumentor(entry_point, skip_dep_check=True)
121-
_logger.debug("Instrumented %s", entry_point.name)
153+
_debug("Instrumented %s", entry_point.name)
122154
except DependencyConflictError as exc:
123155
# Dependency conflicts are generally caught from get_dist_dependency_conflicts
124156
# returning a DependencyConflict. Keeping this error handling in case custom
125157
# distro and instrumentor behavior raises a DependencyConflictError later.
126158
# See https://github.com/open-telemetry/opentelemetry-python-contrib/pull/3610
127-
_logger.debug(
159+
_debug(
128160
"Skipping instrumentation %s: %s",
129161
entry_point.name,
130162
exc.conflict,
@@ -134,7 +166,7 @@ def _load_instrumentors(distro):
134166
# ModuleNotFoundError is raised when the library is not installed
135167
# and the instrumentation is not required to be loaded.
136168
# See https://github.com/open-telemetry/opentelemetry-python-contrib/issues/3421
137-
_logger.debug(
169+
_debug(
138170
"Skipping instrumentation %s: %s", entry_point.name, exc.msg
139171
)
140172
continue

‎opentelemetry-instrumentation/tests/auto_instrumentation/test_load.py‎

Lines changed: 99 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -209,6 +209,105 @@ def _instrumentation_failed_to_load_call(entry_point, dependency_conflict):
209209
"Skipping instrumentation %s: %s", entry_point, dependency_conflict
210210
)
211211

212+
@patch.dict("os.environ", {"OTEL_LOG_LEVEL": "debug"}, clear=True)
213+
@patch("opentelemetry.instrumentation.auto_instrumentation._load._logger")
214+
@patch("opentelemetry.instrumentation.auto_instrumentation._load.stderr")
215+
def test_writes_diagnostic_debug_output(
216+
self, stderr_mock, logger_mock
217+
):
218+
logger_mock.isEnabledFor.return_value = True
219+
logger_mock.hasHandlers.return_value = False
220+
221+
_load._debug("Instrumented %s", "requests")
222+
223+
logger_mock.debug.assert_called_once_with(
224+
"Instrumented %s", "requests"
225+
)
226+
stderr_mock.write.assert_called_once_with(
227+
"DEBUG:"
228+
"opentelemetry.instrumentation.auto_instrumentation._load:"
229+
"Instrumented 'requests'\n"
230+
)
231+
stderr_mock.flush.assert_called_once()
232+
233+
@patch.dict("os.environ", {"OTEL_LOG_LEVEL": "trace"}, clear=True)
234+
@patch("opentelemetry.instrumentation.auto_instrumentation._load._logger")
235+
@patch("opentelemetry.instrumentation.auto_instrumentation._load.stderr")
236+
def test_writes_diagnostic_trace_output(self, stderr_mock, logger_mock):
237+
logger_mock.isEnabledFor.return_value = True
238+
logger_mock.hasHandlers.return_value = False
239+
240+
_load._debug("Instrumented %s", "requests")
241+
242+
logger_mock.debug.assert_called_once_with(
243+
"Instrumented %s", "requests"
244+
)
245+
stderr_mock.write.assert_called_once_with(
246+
"DEBUG:"
247+
"opentelemetry.instrumentation.auto_instrumentation._load:"
248+
"Instrumented 'requests'\n"
249+
)
250+
stderr_mock.flush.assert_called_once()
251+
252+
@patch.dict("os.environ", {"OTEL_LOG_LEVEL": "debug"}, clear=True)
253+
@patch("opentelemetry.instrumentation.auto_instrumentation._load._logger")
254+
@patch("opentelemetry.instrumentation.auto_instrumentation._load.stderr")
255+
def test_does_not_write_diagnostic_when_logger_handles_debug(
256+
self, stderr_mock, logger_mock
257+
):
258+
logger_mock.isEnabledFor.return_value = True
259+
logger_mock.hasHandlers.return_value = True
260+
261+
_load._debug("Instrumented %s", "requests")
262+
263+
logger_mock.debug.assert_called_once_with(
264+
"Instrumented %s", "requests"
265+
)
266+
stderr_mock.write.assert_not_called()
267+
stderr_mock.flush.assert_not_called()
268+
269+
@patch.dict("os.environ", {"OTEL_LOG_LEVEL": "info"}, clear=True)
270+
@patch("opentelemetry.instrumentation.auto_instrumentation._load._logger")
271+
@patch("opentelemetry.instrumentation.auto_instrumentation._load.stderr")
272+
def test_does_not_write_diagnostic_non_debug_output(
273+
self, stderr_mock, logger_mock
274+
):
275+
_load._debug("Instrumented %s", "requests")
276+
277+
logger_mock.debug.assert_called_once_with(
278+
"Instrumented %s", "requests"
279+
)
280+
stderr_mock.write.assert_not_called()
281+
stderr_mock.flush.assert_not_called()
282+
283+
@patch.dict("os.environ", {"OTEL_LOG_LEVEL": "debug2"}, clear=True)
284+
@patch("opentelemetry.instrumentation.auto_instrumentation._load._logger")
285+
@patch("opentelemetry.instrumentation.auto_instrumentation._load.stderr")
286+
def test_does_not_write_numbered_debug_output(
287+
self, stderr_mock, logger_mock
288+
):
289+
_load._debug("Instrumented %s", "requests")
290+
291+
logger_mock.debug.assert_called_once_with(
292+
"Instrumented %s", "requests"
293+
)
294+
stderr_mock.write.assert_not_called()
295+
stderr_mock.flush.assert_not_called()
296+
297+
@patch.dict("os.environ", {"OTEL_LOG_LEVEL": "debugger"}, clear=True)
298+
@patch("opentelemetry.instrumentation.auto_instrumentation._load._logger")
299+
@patch("opentelemetry.instrumentation.auto_instrumentation._load.stderr")
300+
def test_does_not_prefix_match_diagnostic_debug_output(
301+
self, stderr_mock, logger_mock
302+
):
303+
_load._debug("Instrumented %s", "requests")
304+
305+
logger_mock.debug.assert_called_once_with(
306+
"Instrumented %s", "requests"
307+
)
308+
stderr_mock.write.assert_not_called()
309+
stderr_mock.flush.assert_not_called()
310+
212311
@patch.dict(
213312
"os.environ",
214313
{OTEL_PYTHON_DISABLED_INSTRUMENTATIONS: " instr1 , instr3 "},

0 commit comments

Comments
 (0)