From 5ebe8c867ed5e7435d5499d3de86ad86ff369394 Mon Sep 17 00:00:00 2001 From: dh Date: Sat, 30 Mar 2024 11:02:32 +0100 Subject: [PATCH] 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 --- .../instrumentation/logging/__init__.py | 26 ++++- .../tests/test_logging.py | 94 ++++++++++++++++--- 2 files changed, 107 insertions(+), 13 deletions(-) diff --git a/instrumentation/opentelemetry-instrumentation-logging/src/opentelemetry/instrumentation/logging/__init__.py b/instrumentation/opentelemetry-instrumentation-logging/src/opentelemetry/instrumentation/logging/__init__.py index ce332d0113..de66780b65 100644 --- a/instrumentation/opentelemetry-instrumentation-logging/src/opentelemetry/instrumentation/logging/__init__.py +++ b/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,6 +96,8 @@ 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 @@ -84,6 +105,8 @@ def instrumentation_dependencies(self) -> Collection[str]: 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) diff --git a/instrumentation/opentelemetry-instrumentation-logging/tests/test_logging.py b/instrumentation/opentelemetry-instrumentation-logging/tests/test_logging.py index a5a0d5adff..affa04dbb7 100644 --- a/instrumentation/opentelemetry-instrumentation-logging/tests/test_logging.py +++ b/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,11 +106,11 @@ 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( @@ -118,16 +118,16 @@ def test_basic_config_called(self, basic_config_mock): ) 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,14 +140,14 @@ 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( @@ -155,7 +155,7 @@ def test_custom_format_and_level_api( 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 + ) \ No newline at end of file