fix(auto-instrumentation): print debug startup messages

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

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:

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 "},