use a LoggerAdapter

Author: pmcollins

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

@@ -13,7 +13,7 @@
 # limitations under the License.
 
 from functools import cached_property
-from logging import DEBUG, getLogger
+from logging import DEBUG, NOTSET, Logger, LoggerAdapter, getLogger
 from os import environ
 from sys import stderr
 
@@ -34,40 +34,78 @@
     entry_points,
 )
 
-_logger = getLogger(__name__)
-
 SKIPPED_INSTRUMENTATIONS_WILDCARD = "*"
 OTEL_LOG_LEVEL = "OTEL_LOG_LEVEL"
 _DEBUG_LOG_LEVELS = frozenset(("trace", "debug"))
 
 
-def _diagnostic_debug_enabled() -> bool:
+def _otel_log_level_allows_debug() -> bool:
     log_level = environ.get(OTEL_LOG_LEVEL, "").strip().lower()
     return log_level in _DEBUG_LOG_LEVELS
 
 
-def _logger_handles_debug() -> bool:
-    return _logger.isEnabledFor(DEBUG) and _logger.hasHandlers()
-
-
-def _format_diagnostic_arg(arg: object) -> object:
+def _format_log_arg(arg: object) -> object:
     if isinstance(arg, str):
         return repr(arg)
 
     return arg
 
 
-def _debug(message: str, *args: object) -> None:
-    _logger.debug(message, *args)
+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 __init__(self, logger, extra):
+        super().__init__(logger, extra)
+        # This adapter is built when this module is imported. That covers the
+        # sitecustomize path where auto-instrumentation runs before application
+        # logging setup, and the edge case where Python logging is set up and then
+        # auto_instrumentation.initialize() is invoked explicitly. If this adapter
+        # is used after application code can change logging, it should be modified
+        # to not use the cached value in the _logger_emits_debug field.
+        self._logger_emits_debug = self._logger_would_emit(DEBUG)
+
+    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_emits_debug:
+            return
+
+        message = msg
+        if args:
+            message = message % tuple(_format_log_arg(arg) for arg in args)
 
-    if not _diagnostic_debug_enabled() or _logger_handles_debug():
-        return
+        stderr.write(f"DEBUG:{self.logger.name}:{message}\n")
+        stderr.flush()
 
-    if args:
-        message = message % tuple(_format_diagnostic_arg(arg) for arg in args)
+    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
 
-    stderr.write(f"DEBUG:{__name__}:{message}\n")
-    stderr.flush()
+        logger: Logger | None = self.logger
+        while logger:
+            for handler in logger.handlers:
+                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:
@@ -99,12 +137,14 @@ def _load_distro() -> BaseDistro:
             if distro_name is None or distro_name == entry_point.name:
                 distro = entry_point.load()()
                 if not isinstance(distro, BaseDistro):
-                    _debug(
+                    _logger.debug(
                         "%s is not an OpenTelemetry Distro. Skipping",
                         entry_point.name,
                     )
                     continue
-                _debug("Distribution %s will be configured", entry_point.name)
+                _logger.debug(
+                    "Distribution %s will be configured", entry_point.name
+                )
                 return distro
         except Exception as exc:  # pylint: disable=broad-except
             _logger.exception(
@@ -130,14 +170,16 @@ def _load_instrumentors(distro):
             break
 
         if entry_point.name in package_to_exclude:
-            _debug("Instrumentation skipped for library %s", entry_point.name)
+            _logger.debug(
+                "Instrumentation skipped for library %s", entry_point.name
+            )
             continue
 
         try:
             entry_point_dist = entry_point_finder.dist_for(entry_point)
             conflict = get_dist_dependency_conflicts(entry_point_dist)
             if conflict:
-                _debug(
+                _logger.debug(
                     "Skipping instrumentation %s: %s",
                     entry_point.name,
                     conflict,
@@ -146,13 +188,13 @@ def _load_instrumentors(distro):
 
             # tell instrumentation to not run dep checks again as we already did it above
             distro.load_instrumentor(entry_point, skip_dep_check=True)
-            _debug("Instrumented %s", entry_point.name)
+            _logger.debug("Instrumented %s", entry_point.name)
         except DependencyConflictError as exc:
             # Dependency conflicts are generally caught from get_dist_dependency_conflicts
             # returning a DependencyConflict. Keeping this error handling in case custom
             # distro and instrumentor behavior raises a DependencyConflictError later.
             # See https://github.com/open-telemetry/opentelemetry-python-contrib/pull/3610
-            _debug(
+            _logger.debug(
                 "Skipping instrumentation %s: %s",
                 entry_point.name,
                 exc.conflict,
@@ -162,7 +204,7 @@ def _load_instrumentors(distro):
             # ModuleNotFoundError is raised when the library is not installed
             # and the instrumentation is not required to be loaded.
             # See https://github.com/open-telemetry/opentelemetry-python-contrib/issues/3421
-            _debug(
+            _logger.debug(
                 "Skipping instrumentation %s: %s", entry_point.name, exc.msg
             )
             continue

opentelemetry-instrumentation/tests/auto_instrumentation/test_load.py

@@ -13,6 +13,7 @@
 # limitations under the License.
 # type: ignore
 
+from logging import DEBUG, INFO, NullHandler, getLogger
 from unittest import TestCase
 from unittest.mock import Mock, call, patch
 
@@ -209,27 +210,32 @@ def _instrumentation_failed_to_load_call(entry_point, dependency_conflict):
             "Skipping instrumentation %s: %s", entry_point, dependency_conflict
         )
 
-    def test_writes_diagnostic_output_for_debug_levels(self):
+    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._logger"
-                ) as logger_mock,
                 patch(
                     "opentelemetry.instrumentation.auto_instrumentation._load.stderr"
                 ) as stderr_mock,
             ):
+                logger_mock = Mock()
                 logger_mock.isEnabledFor.return_value = True
-                logger_mock.hasHandlers.return_value = False
+                logger_mock.handlers = []
+                logger_mock.parent = None
+                logger_mock.propagate = True
+                logger_mock.name = (
+                    "opentelemetry.instrumentation."
+                    "auto_instrumentation._load"
+                )
+                logger = _load._OtelLogLevelLoggerAdapter(logger_mock, {})
 
-                _load._debug("Instrumented %s", "requests")
+                logger.debug("Instrumented %s", "requests")
 
-                logger_mock.debug.assert_called_once_with(
-                    "Instrumented %s", "requests"
+                logger_mock.log.assert_called_once_with(
+                    DEBUG, "Instrumented %s", "requests", extra={}
                 )
                 stderr_mock.write.assert_called_once_with(
                     "DEBUG:"
@@ -238,37 +244,115 @@ def test_writes_diagnostic_output_for_debug_levels(self):
                 )
                 stderr_mock.flush.assert_called_once()
 
-    def test_does_not_write_diagnostic_output(self):
+    def test_does_not_write_otel_log_level_output(self):
         cases = (
-            ("debug", True),
+            ("debug", DEBUG),
             ("info", False),
             ("debug2", False),
             ("debugger", False),
         )
 
-        for log_level, logger_has_handlers in cases:
+        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._logger"
-                ) as logger_mock,
                 patch(
                     "opentelemetry.instrumentation.auto_instrumentation._load.stderr"
                 ) as stderr_mock,
             ):
+                logger_mock = Mock()
                 logger_mock.isEnabledFor.return_value = True
-                logger_mock.hasHandlers.return_value = logger_has_handlers
+                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):
+        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()
+
+            handler = NullHandler()
+            handler.setLevel(INFO)
+            parent_logger.addHandler(handler)
+            otel_log_level_logger = _load._OtelLogLevelLoggerAdapter(
+                logger, {}
+            )
 
-                _load._debug("Instrumented %s", "requests")
+            with patch(
+                "opentelemetry.instrumentation.auto_instrumentation._load.stderr"
+            ) as stderr_mock:
+                otel_log_level_logger.debug("Instrumented %s", "requests")
 
-                logger_mock.debug.assert_called_once_with(
-                    "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()
+
+            handler.setLevel(DEBUG)
+            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_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",