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 - extend CHANGELOG

Author: dhofstetter

CHANGELOG.md

@@ -57,6 +57,8 @@ 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 is especially useful in case of automatic instrumentation)
+ ([#2384](https://github.com/open-telemetry/opentelemetry-python-contrib/pull/2384))
 - `opentelemetry-instrumentation-dbapi` Fix compatibility with Psycopg3 to extract libpq build version
  ([#2500](https://github.com/open-telemetry/opentelemetry-python-contrib/pull/2500))
 - `opentelemetry-instrumentation-grpc` AioClientInterceptor should propagate with a Metadata object

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

@@ -46,6 +46,26 @@
 }
 
 
+def apply_log_settings(
+ format: str, level: int # pylint: disable=redefined-builtin
+) -> 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 +97,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 +168,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

@@ -21,6 +21,7 @@
 from opentelemetry.instrumentation.logging import ( # pylint: disable=no-name-in-module
  DEFAULT_LOGGING_FORMAT,
  LoggingInstrumentor,
+ apply_log_settings,
 )
 from opentelemetry.test.test_base import TestBase
 from opentelemetry.trace import ProxyTracer, get_tracer
@@ -106,28 +107,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 +141,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 +208,77 @@ 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
+ """
+
+ @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, # pylint: disable=no-self-use
+ ):
+ """
+ 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 # pylint: disable=no-self-use
+ ):
+ """
+ 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()
+
+ self.assertTrue(basic_config_mock.called)
+ basic_config_mock.assert_called_once_with(
+ format=log_format, level=log_level
+ )