fix(opentelemetry-instrumentation-logging): Ensure that logging is properly configured independently of the order of instrumentation (this helps especially in case of autoinstrumentation)

- add method to perform proper logging initialisation
- add unittests

Author: dhofstetter

CHANGELOG.md

@@ -33,6 +33,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 
 ### Fixed
 
+- `opentelemetry-instrumentation-logging` Ensure that logging is properly configured independently of the order of instrumentation (this helps especially in case of autoinstrumentation)
 - `opentelemetry-instrumentation-grpc` AioClientInterceptor should propagate with a Metadata object
   ([#2363](https://github.com/open-telemetry/opentelemetry-python-contrib/pull/2363))
 - `opentelemetry-instrumentation-boto3sqs` Instrument Session and resource

instrumentation/opentelemetry-instrumentation-logging/src/opentelemetry/instrumentation/logging/__init__.py

@@ -15,6 +15,7 @@
 # pylint: disable=empty-docstring,no-value-for-parameter,no-member,no-name-in-module
 
 import logging  # pylint: disable=import-self
+from collections import defaultdict
 from os import environ
 from typing import Collection
 
@@ -46,6 +47,24 @@
 }
 
 
+def apply_log_settings(format: str, level: int) -> None:
+    """
+    Apply the logging format to the root logger.
+
+    Ensures that the logging format is applied either by calling logging.basicConfig
+    or by setting the logging format on the root logger.
+    This is required in case of auto-instrumentation, where the root logger is configured
+    before we can inject the logging format here.
+    """
+    root_logger = logging.getLogger()
+    if root_logger.hasHandlers():
+        root_logger.setLevel(level)
+        for handler in root_logger.handlers:
+            handler.setFormatter(logging.Formatter(format))
+    else:
+        logging.basicConfig(format=format, level=level)
+
+
 class LoggingInstrumentor(BaseInstrumentor):  # pylint: disable=empty-docstring
     __doc__ = f"""An instrumentor for stdlib logging module.
 
@@ -77,13 +96,17 @@ def log_hook(span: Span, record: LogRecord):
 
     _old_factory = None
     _log_hook = None
+    _old_level = None
+    _old_format = None
 
     def instrumentation_dependencies(self) -> Collection[str]:
         return _instruments
 
     def _instrument(self, **kwargs):
         provider = kwargs.get("tracer_provider", None) or get_tracer_provider()
         old_factory = logging.getLogRecordFactory()
+        self.old_level = logging.getLogger().level
+        self.old_format = logging.getLogger().handlers[0].formatter._fmt
         LoggingInstrumentor._old_factory = old_factory
         LoggingInstrumentor._log_hook = kwargs.get("log_hook", None)
 
@@ -144,9 +167,10 @@ def record_factory(*args, **kwargs):
             )
             log_level = log_level or logging.INFO
 
-            logging.basicConfig(format=log_format, level=log_level)
+            apply_log_settings(format=log_format, level=log_level)
 
     def _uninstrument(self, **kwargs):
         if LoggingInstrumentor._old_factory:
             logging.setLogRecordFactory(LoggingInstrumentor._old_factory)
             LoggingInstrumentor._old_factory = None
+        apply_log_settings(self._old_format, self._old_level or logging.NOTSET)

instrumentation/opentelemetry-instrumentation-logging/tests/test_logging.py

@@ -20,7 +20,7 @@
 
 from opentelemetry.instrumentation.logging import (  # pylint: disable=no-name-in-module
     DEFAULT_LOGGING_FORMAT,
-    LoggingInstrumentor,
+    LoggingInstrumentor, apply_log_settings,
 )
 from opentelemetry.test.test_base import TestBase
 from opentelemetry.trace import ProxyTracer, get_tracer
@@ -106,28 +106,28 @@ def test_trace_context_injection(self):
     def test_trace_context_injection_without_span(self):
         self.assert_trace_context_injected("0", "0", False)
 
-    @mock.patch("logging.basicConfig")
-    def test_basic_config_called(self, basic_config_mock):
+    @mock.patch("opentelemetry.instrumentation.logging.apply_log_settings")
+    def test_basic_config_called(self, apply_log_settings_mock):
         LoggingInstrumentor().uninstrument()
         LoggingInstrumentor().instrument()
-        self.assertFalse(basic_config_mock.called)
+        self.assertTrue(apply_log_settings_mock.called)
         LoggingInstrumentor().uninstrument()
 
         env_patch = mock.patch.dict(
             "os.environ", {"OTEL_PYTHON_LOG_CORRELATION": "true"}
         )
         env_patch.start()
         LoggingInstrumentor().instrument()
-        basic_config_mock.assert_called_with(
+        apply_log_settings_mock.assert_called_with(
             format=DEFAULT_LOGGING_FORMAT, level=logging.INFO
         )
         env_patch.stop()
 
-    @mock.patch("logging.basicConfig")
-    def test_custom_format_and_level_env(self, basic_config_mock):
+    @mock.patch("opentelemetry.instrumentation.logging.apply_log_settings")
+    def test_custom_format_and_level_env(self, apply_log_settings_mock):
         LoggingInstrumentor().uninstrument()
         LoggingInstrumentor().instrument()
-        self.assertFalse(basic_config_mock.called)
+        self.assertTrue(apply_log_settings_mock.called)
         LoggingInstrumentor().uninstrument()
 
         env_patch = mock.patch.dict(
@@ -140,22 +140,22 @@ def test_custom_format_and_level_env(self, basic_config_mock):
         )
         env_patch.start()
         LoggingInstrumentor().instrument()
-        basic_config_mock.assert_called_with(
+        apply_log_settings_mock.assert_called_with(
             format="%(message)s %(otelSpanID)s", level=logging.ERROR
         )
         env_patch.stop()
 
-    @mock.patch("logging.basicConfig")
+    @mock.patch("opentelemetry.instrumentation.logging.apply_log_settings")
     def test_custom_format_and_level_api(
-        self, basic_config_mock
+        self, apply_log_settings_mock
     ):  # pylint: disable=no-self-use
         LoggingInstrumentor().uninstrument()
         LoggingInstrumentor().instrument(
             set_logging_format=True,
             logging_format="%(message)s span_id=%(otelSpanID)s",
             log_level=logging.WARNING,
         )
-        basic_config_mock.assert_called_with(
+        apply_log_settings_mock.assert_called_with(
             format="%(message)s span_id=%(otelSpanID)s", level=logging.WARNING
         )
 
@@ -207,3 +207,73 @@ def test_uninstrumented(self):
                 self.assertFalse(hasattr(record, "otelTraceID"))
                 self.assertFalse(hasattr(record, "otelServiceName"))
                 self.assertFalse(hasattr(record, "otelTraceSampled"))
+
+
+class TestLogSetup(TestBase):
+    """
+    Tests the apply_log_settings function
+    """
+    def setUp(self):
+        super().setUp()
+
+    def tearDown(self):
+        super().tearDown()
+
+    @mock.patch("logging.Formatter")
+    @mock.patch("logging.getLogger")
+    @mock.patch("logging.basicConfig")
+    def test_apply_log_settings_initialized(self, basic_config_mock, get_logger_mock, formatter_mock):
+        """
+        Tests that apply_log_settings tries to apply format and loglevel to the
+        configured logging module if the logging module has already been initialized
+        """
+        # Prepare
+        log_level = logging.DEBUG
+        log_format = "custom %(message)s"
+        formatter = "formatter"
+
+        formatter_mock.return_value = formatter
+
+        handler_mock = mock.MagicMock()
+
+        root_logger_mock = mock.MagicMock()
+        root_logger_mock.hasHandlers.return_value = True
+        root_logger_mock.handlers = [handler_mock]
+
+        get_logger_mock.return_value = root_logger_mock
+
+        # Act
+        apply_log_settings(log_format, log_level)
+
+        # Assert
+        get_logger_mock.assert_called_once_with()
+        root_logger_mock.hasHandlers.assert_called_once()
+        root_logger_mock.setLevel.assert_called_once_with(log_level)
+        handler_mock.setFormatter.assert_called_once_with(formatter)
+        formatter_mock.assert_called_once_with(log_format)
+
+        self.assertFalse(basic_config_mock.called)
+
+    @mock.patch("logging.getLogger")
+    @mock.patch("logging.basicConfig")
+    def test_apply_log_settings_uninitialized(self, basic_config_mock, get_logger_mock):
+        """
+        Tests that apply_log_settings calls logging.basicConfig with the
+        provided format and level when the logging module has not been
+        initialized
+        """
+        log_level = logging.DEBUG
+        log_format = "custom %(message)s"
+
+        root_logger_mock = mock.MagicMock()
+        root_logger_mock.hasHandlers.return_value = False
+
+        get_logger_mock.return_value = root_logger_mock
+
+        apply_log_settings(log_format, log_level)
+
+        root_logger_mock.hasHandlers.assert_called_once()
+        get_logger_mock.assert_called_once_with()
+        basic_config_mock.assert_called_once_with(
+            format=log_format, level=log_level
+        )