diff --git a/CHANGELOG.md b/CHANGELOG.md index 090e996805..1b69f7857e 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -19,6 +19,8 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ([#4397](https://github.com/open-telemetry/opentelemetry-python-contrib/issues/4397)) - Switch to SPDX license headers and add CI enforcement ([#4533](https://github.com/open-telemetry/opentelemetry-python-contrib/pull/4533)) +- `opentelemetry-instrumentation`: Write auto-instrumentation debug startup messages to stderr when `OTEL_LOG_LEVEL` is set to `debug` or `trace`. + ([#4542](https://github.com/open-telemetry/opentelemetry-python-contrib/pull/4542)) - Bump `pylint` to `4.0.5` ([#4244](https://github.com/open-telemetry/opentelemetry-python-contrib/pull/4244)) - `opentelemetry-instrumentation-sqlite3`: Add uninstrument, error status, suppress, and no-op tests diff --git a/opentelemetry-instrumentation/src/opentelemetry/instrumentation/auto_instrumentation/_load.py b/opentelemetry-instrumentation/src/opentelemetry/instrumentation/auto_instrumentation/_load.py index a57295669a..8da1bedfd9 100644 --- a/opentelemetry-instrumentation/src/opentelemetry/instrumentation/auto_instrumentation/_load.py +++ b/opentelemetry-instrumentation/src/opentelemetry/instrumentation/auto_instrumentation/_load.py @@ -2,8 +2,16 @@ # SPDX-License-Identifier: Apache-2.0 from functools import cached_property -from logging import getLogger +from logging import ( + DEBUG, + NOTSET, + Logger, + LoggerAdapter, + NullHandler, + getLogger, +) from os import environ +from sys import stderr from opentelemetry.instrumentation.dependencies import ( DependencyConflictError, @@ -22,9 +30,73 @@ entry_points, ) -_logger = getLogger(__name__) - SKIPPED_INSTRUMENTATIONS_WILDCARD = "*" +OTEL_LOG_LEVEL = "OTEL_LOG_LEVEL" +_DEBUG_LOG_LEVELS = frozenset(("trace", "debug")) + + +def _otel_log_level_allows_debug() -> bool: + log_level = environ.get(OTEL_LOG_LEVEL, "").strip().lower() + return log_level in _DEBUG_LOG_LEVELS + + +def _format_log_arg(arg: object) -> object: + if isinstance(arg, str): + return repr(arg) + + return arg + + +class _OtelLogLevelLoggerAdapter(LoggerAdapter): + """Write startup debug messages to stderr when logging would drop them. + + Auto-instrumentation usually runs from sitecustomize before the + application configures logging, so normal logger.debug calls are often + not visible even when OTEL_LOG_LEVEL=debug. This adapter keeps normal + logging behavior, but also writes the same startup messages to stderr when + OTEL_LOG_LEVEL asks for debug output and Python logging would not emit them. + """ + + def debug(self, msg: str, *args: object, **kwargs: object) -> None: + super().debug(msg, *args, **kwargs) + + if not _otel_log_level_allows_debug() or self._logger_would_emit( + DEBUG + ): + return + + message = msg + if args: + message = message % tuple(_format_log_arg(arg) for arg in args) + + stderr.write(f"DEBUG:{self.logger.name}:{message}\n") + stderr.flush() + + def _logger_would_emit(self, level: int) -> bool: + # If the logger itself would reject this level, don't bother walking handlers. + if not self.logger.isEnabledFor(level): + return False + + logger: Logger | None = self.logger + while logger: + for handler in logger.handlers: + if isinstance(handler, NullHandler): + continue + + if handler.level == NOTSET or level >= handler.level: + return True + + # If we get here, this logger's handlers would not emit the record. + # If propagation is disabled, parent handlers will not see it either. + if not logger.propagate: + break + + logger = logger.parent + + return False + + +_logger = _OtelLogLevelLoggerAdapter(getLogger(__name__), {}) class _EntryPointDistFinder: diff --git a/opentelemetry-instrumentation/tests/auto_instrumentation/test_load.py b/opentelemetry-instrumentation/tests/auto_instrumentation/test_load.py index 3dcd487087..eca8ef591f 100644 --- a/opentelemetry-instrumentation/tests/auto_instrumentation/test_load.py +++ b/opentelemetry-instrumentation/tests/auto_instrumentation/test_load.py @@ -2,6 +2,8 @@ # SPDX-License-Identifier: Apache-2.0 # type: ignore +from io import StringIO +from logging import DEBUG, INFO, NullHandler, StreamHandler, getLogger from unittest import TestCase from unittest.mock import Mock, call, patch @@ -198,6 +200,161 @@ def _instrumentation_failed_to_load_call(entry_point, dependency_conflict): "Skipping instrumentation %s: %s", entry_point, dependency_conflict ) + def test_writes_otel_log_level_output_for_debug_levels(self): + for log_level in ("debug", "trace"): + with ( + self.subTest(log_level=log_level), + patch.dict( + "os.environ", {"OTEL_LOG_LEVEL": log_level}, clear=True + ), + patch( + "opentelemetry.instrumentation.auto_instrumentation._load.stderr" + ) as stderr_mock, + ): + logger_mock = Mock() + logger_mock.isEnabledFor.return_value = True + logger_mock.handlers = [] + logger_mock.parent = None + logger_mock.propagate = True + logger_mock.name = ( + "opentelemetry.instrumentation.auto_instrumentation._load" + ) + logger = _load._OtelLogLevelLoggerAdapter(logger_mock, {}) + + logger.debug("Instrumented %s", "requests") + + logger_mock.log.assert_called_once_with( + DEBUG, "Instrumented %s", "requests", extra={} + ) + stderr_mock.write.assert_called_once_with( + "DEBUG:" + "opentelemetry.instrumentation.auto_instrumentation._load:" + "Instrumented 'requests'\n" + ) + stderr_mock.flush.assert_called_once() + + def test_does_not_write_otel_log_level_output(self): + cases = ( + ("debug", DEBUG), + ("info", False), + ("debug2", False), + ("debugger", False), + ) + + for log_level, handler_level in cases: + with ( + self.subTest(log_level=log_level), + patch.dict( + "os.environ", {"OTEL_LOG_LEVEL": log_level}, clear=True + ), + patch( + "opentelemetry.instrumentation.auto_instrumentation._load.stderr" + ) as stderr_mock, + ): + logger_mock = Mock() + logger_mock.isEnabledFor.return_value = True + logger_mock.handlers = ( + [Mock(level=handler_level)] if handler_level else [] + ) + logger_mock.parent = None + logger_mock.propagate = True + logger = _load._OtelLogLevelLoggerAdapter(logger_mock, {}) + + logger.debug("Instrumented %s", "requests") + + logger_mock.log.assert_called_once_with( + DEBUG, "Instrumented %s", "requests", extra={} + ) + stderr_mock.write.assert_not_called() + stderr_mock.flush.assert_not_called() + + @patch.dict("os.environ", {"OTEL_LOG_LEVEL": "debug"}, clear=True) + def test_otel_log_level_output_uses_logger_hierarchy_handlers( + self, + ): # pylint: disable=no-self-use + parent_logger = getLogger("opentelemetry.test.auto_instrumentation") + logger = getLogger("opentelemetry.test.auto_instrumentation.loader") + + original_parent_handlers = parent_logger.handlers[:] + original_parent_level = parent_logger.level + original_parent_propagate = parent_logger.propagate + original_logger_handlers = logger.handlers[:] + original_logger_level = logger.level + original_logger_propagate = logger.propagate + + try: + parent_logger.handlers = [] + parent_logger.setLevel(DEBUG) + parent_logger.propagate = False + logger.handlers = [] + logger.setLevel(DEBUG) + logger.propagate = True + + otel_log_level_logger = _load._OtelLogLevelLoggerAdapter( + logger, {} + ) + + with patch( + "opentelemetry.instrumentation.auto_instrumentation._load.stderr" + ) as stderr_mock: + otel_log_level_logger.debug("Instrumented %s", "requests") + + stderr_mock.write.assert_called_once_with( + "DEBUG:" + "opentelemetry.test.auto_instrumentation.loader:" + "Instrumented 'requests'\n" + ) + stderr_mock.flush.assert_called_once() + + null_handler = NullHandler() + null_handler.setLevel(DEBUG) + parent_logger.addHandler(null_handler) + + with patch( + "opentelemetry.instrumentation.auto_instrumentation._load.stderr" + ) as stderr_mock: + otel_log_level_logger.debug("Instrumented %s", "requests") + + stderr_mock.write.assert_called_once_with( + "DEBUG:" + "opentelemetry.test.auto_instrumentation.loader:" + "Instrumented 'requests'\n" + ) + stderr_mock.flush.assert_called_once() + + stream_handler = StreamHandler(StringIO()) + stream_handler.setLevel(INFO) + parent_logger.addHandler(stream_handler) + + with patch( + "opentelemetry.instrumentation.auto_instrumentation._load.stderr" + ) as stderr_mock: + otel_log_level_logger.debug("Instrumented %s", "requests") + + stderr_mock.write.assert_called_once_with( + "DEBUG:" + "opentelemetry.test.auto_instrumentation.loader:" + "Instrumented 'requests'\n" + ) + stderr_mock.flush.assert_called_once() + + stream_handler.setLevel(DEBUG) + + with patch( + "opentelemetry.instrumentation.auto_instrumentation._load.stderr" + ) as stderr_mock: + otel_log_level_logger.debug("Instrumented %s", "requests") + + stderr_mock.write.assert_not_called() + stderr_mock.flush.assert_not_called() + finally: + parent_logger.handlers = original_parent_handlers + parent_logger.setLevel(original_parent_level) + parent_logger.propagate = original_parent_propagate + logger.handlers = original_logger_handlers + logger.setLevel(original_logger_level) + logger.propagate = original_logger_propagate + @patch.dict( "os.environ", {OTEL_PYTHON_DISABLED_INSTRUMENTATIONS: " instr1 , instr3 "},