From c30fa400694deb0a12221a494fbdabf58cdeba48 Mon Sep 17 00:00:00 2001 From: dh Date: Sat, 30 Mar 2024 11:02:32 +0100 Subject: [PATCH 1/2] 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 --- CHANGELOG.md | 2 + .../instrumentation/logging/__init__.py | 27 +++++- .../tests/test_logging.py | 97 ++++++++++++++++--- 3 files changed, 114 insertions(+), 12 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index e17542b104..735ec7ad96 100644 --- a/CHANGELOG.md +++ b/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 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..d12097ee95 100644 --- a/instrumentation/opentelemetry-instrumentation-logging/src/opentelemetry/instrumentation/logging/__init__.py +++ b/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,6 +97,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 +106,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 +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) diff --git a/instrumentation/opentelemetry-instrumentation-logging/tests/test_logging.py b/instrumentation/opentelemetry-instrumentation-logging/tests/test_logging.py index a5a0d5adff..e196dca25b 100644 --- a/instrumentation/opentelemetry-instrumentation-logging/tests/test_logging.py +++ b/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,11 +107,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 +119,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 +141,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 +156,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 +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 + ) From 51ccb36a3677eab49c36ca8dfacac1f248deba4f Mon Sep 17 00:00:00 2001 From: dh Date: Tue, 21 May 2024 23:57:50 +0200 Subject: [PATCH 2/2] changelog adjusted as proposed in review --- CHANGELOG.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 735ec7ad96..72e4e62ceb 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -57,7 +57,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 is especially useful in case of automatic instrumentation) +- `opentelemetry-instrumentation-logging` Ensure that logging is properly configured independently of the order of 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))