From 6c9b916f7f31486b5e13f95342fc5fe31cdb6973 Mon Sep 17 00:00:00 2001 From: Mike Goldsmith Date: Fri, 13 Feb 2026 17:34:17 +0000 Subject: [PATCH 1/5] fix(logging): apply format/level when logging preconfigured basicConfig() no-op when handlers exist (autoinstrumentation, Gunicorn, Flask). Fix: update existing handlers instead of only calling basicConfig. Saves/restores state for clean uninstrumentation. Supersedes #2384, fixes #2346 --- CHANGELOG.md | 2 + .../instrumentation/logging/__init__.py | 42 +++++- .../tests/test_logging.py | 122 ++++++++++++++++++ 3 files changed, 165 insertions(+), 1 deletion(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index edb46a567f..0a6d0b7216 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -58,6 +58,8 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Fixed +- `opentelemetry-instrumentation-logging`: Apply log format/level when logging already configured (autoinstrumentation, Gunicorn, Flask) + ([#2384](https://github.com/open-telemetry/opentelemetry-python-contrib/issues/2384)) - `opentelemetry-instrumentation-cassandra`: Use `_instruments_any` instead of `_instruments` for driver dependencies so that having either `cassandra-driver` or `scylla-driver` installed is sufficient ([#4182](https://github.com/open-telemetry/opentelemetry-python-contrib/pull/4182)) - `opentelemetry-instrumentation-asyncpg`: Hydrate span attributes before creation so samplers can filter on database details 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 53197957cb..1e2aadab32 100644 --- a/instrumentation/opentelemetry-instrumentation-logging/src/opentelemetry/instrumentation/logging/__init__.py +++ b/instrumentation/opentelemetry-instrumentation-logging/src/opentelemetry/instrumentation/logging/__init__.py @@ -87,6 +87,24 @@ } +def _apply_log_settings(log_format, log_level): + """Apply format/level to logging, handling pre-configured scenarios. + + If root logger has handlers, update formatters on all handlers. + If no handlers, call basicConfig. + """ + root_logger = logging.getLogger() + + if root_logger.hasHandlers(): + # Logging already configured - update existing handlers + for handler in root_logger.handlers: + handler.setFormatter(logging.Formatter(log_format)) + root_logger.setLevel(log_level) + else: + # No handlers - use basicConfig (backward compatible) + logging.basicConfig(format=log_format, level=log_level) + + class LoggingInstrumentor(BaseInstrumentor): # pylint: disable=empty-docstring __doc__ = f"""An instrumentor for stdlib logging module. @@ -120,6 +138,8 @@ def log_hook(span: Span, record: LogRecord): _old_factory = None _log_hook = None + _old_handler_formatters = None + _old_level = None def instrumentation_dependencies(self) -> Collection[str]: return _instruments @@ -149,7 +169,17 @@ def _instrument(self, **kwargs): ) log_level = log_level or logging.INFO - logging.basicConfig(format=log_format, level=log_level) + root_logger = logging.getLogger() + + # Save old state if logging already configured + if root_logger.hasHandlers(): + LoggingInstrumentor._old_handler_formatters = [ + (handler, handler.formatter) + for handler in root_logger.handlers + ] + LoggingInstrumentor._old_level = root_logger.level + + _apply_log_settings(log_format, log_level) def record_factory(*args, **kwargs): record = old_factory(*args, **kwargs) @@ -203,3 +233,13 @@ def _uninstrument(self, **kwargs): if LoggingInstrumentor._old_factory: logging.setLogRecordFactory(LoggingInstrumentor._old_factory) LoggingInstrumentor._old_factory = None + + # Restore formatters and level + if LoggingInstrumentor._old_handler_formatters is not None: + for handler, old_formatter in LoggingInstrumentor._old_handler_formatters: + handler.setFormatter(old_formatter) + LoggingInstrumentor._old_handler_formatters = None + + if LoggingInstrumentor._old_level is not None: + logging.getLogger().setLevel(LoggingInstrumentor._old_level) + LoggingInstrumentor._old_level = None diff --git a/instrumentation/opentelemetry-instrumentation-logging/tests/test_logging.py b/instrumentation/opentelemetry-instrumentation-logging/tests/test_logging.py index 37e635f2a4..13885a3b08 100644 --- a/instrumentation/opentelemetry-instrumentation-logging/tests/test_logging.py +++ b/instrumentation/opentelemetry-instrumentation-logging/tests/test_logging.py @@ -257,3 +257,125 @@ def test_no_op_tracer_provider(self): self.assertEqual(record.otelTraceID, "0") self.assertEqual(record.otelServiceName, "") self.assertEqual(record.otelTraceSampled, False) + + +class TestLoggingInstrumentorPreConfigured(TestBase): + """Tests for pre-configured logging scenarios.""" + + @pytest.fixture(autouse=True) + def inject_fixtures(self, caplog): + self.caplog = caplog # pylint: disable=attribute-defined-outside-init + + def setUp(self): + super().setUp() + self.tracer = get_tracer(__name__) + # Clear any existing handlers + root = logging.getLogger() + for handler in root.handlers[:]: + root.removeHandler(handler) + + def tearDown(self): + super().tearDown() + LoggingInstrumentor().uninstrument() + # Clear handlers + root = logging.getLogger() + for handler in root.handlers[:]: + root.removeHandler(handler) + + def test_preconfigured_logging(self): + """Test instrumentation works when logging is already configured.""" + # Configure logging before instrumentation + logging.basicConfig(format="OLD: %(message)s", level=logging.WARNING) + + # Instrument with set_logging_format=True + LoggingInstrumentor().instrument(set_logging_format=True) + + # Verify root logger level updated + self.assertEqual(logging.getLogger().level, logging.INFO) + + # Verify formatter updated to include OTel fields + handler = logging.getLogger().handlers[0] + format_str = handler.formatter._style._fmt + self.assertIn("otelTraceID", format_str) + self.assertIn("otelSpanID", format_str) + + # Verify logs include trace context + with self.tracer.start_as_current_span("test") as span: + with self.caplog.at_level(level=logging.INFO): + logger = logging.getLogger("test logger") + logger.info("test message") + self.assertEqual(len(self.caplog.records), 1) + record = self.caplog.records[0] + span_ctx = span.get_span_context() + self.assertEqual( + record.otelSpanID, format(span_ctx.span_id, "016x") + ) + self.assertEqual( + record.otelTraceID, format(span_ctx.trace_id, "032x") + ) + + # Uninstrument and verify restoration + LoggingInstrumentor().uninstrument() + self.assertEqual(handler.formatter._style._fmt, "OLD: %(message)s") + self.assertEqual(logging.getLogger().level, logging.WARNING) + + def test_multiple_handlers(self): + """Test that all handlers are updated and restored.""" + root = logging.getLogger() + h1 = logging.StreamHandler() + h1.setFormatter(logging.Formatter("H1: %(message)s")) + h2 = logging.StreamHandler() + h2.setFormatter(logging.Formatter("H2: %(message)s")) + root.addHandler(h1) + root.addHandler(h2) + + LoggingInstrumentor().instrument(set_logging_format=True) + + # Both handlers updated + self.assertIn("otelTraceID", h1.formatter._style._fmt) + self.assertIn("otelTraceID", h2.formatter._style._fmt) + + LoggingInstrumentor().uninstrument() + + # Both restored + self.assertEqual(h1.formatter._style._fmt, "H1: %(message)s") + self.assertEqual(h2.formatter._style._fmt, "H2: %(message)s") + + def test_handler_without_formatter(self): + """Test handler with no formatter gets one set.""" + root = logging.getLogger() + handler = logging.StreamHandler() + # Don't set formatter + root.addHandler(handler) + + self.assertIsNone(handler.formatter) + + LoggingInstrumentor().instrument(set_logging_format=True) + + # Formatter now set + self.assertIsNotNone(handler.formatter) + self.assertIn("otelTraceID", handler.formatter._style._fmt) + + LoggingInstrumentor().uninstrument() + + # Restored to None + self.assertIsNone(handler.formatter) + + def test_instrument_uninstrument_cycle(self): + """Test multiple instrument/uninstrument cycles.""" + logging.basicConfig(format="ORIGINAL: %(message)s", level=logging.ERROR) + + LoggingInstrumentor().instrument(set_logging_format=True) + handler = logging.getLogger().handlers[0] + self.assertIn("otelTraceID", handler.formatter._style._fmt) + + LoggingInstrumentor().uninstrument() + self.assertEqual(handler.formatter._style._fmt, "ORIGINAL: %(message)s") + + # Re-instrument + LoggingInstrumentor().instrument(set_logging_format=True) + self.assertIn("otelTraceID", handler.formatter._style._fmt) + + # Re-uninstrument + LoggingInstrumentor().uninstrument() + self.assertEqual(handler.formatter._style._fmt, "ORIGINAL: %(message)s") From f7714a9fa08448cd7c917fcdf237c7a14020e2b1 Mon Sep 17 00:00:00 2001 From: Mike Goldsmith Date: Fri, 13 Feb 2026 17:42:17 +0000 Subject: [PATCH 2/5] update changelog --- CHANGELOG.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 0a6d0b7216..eea5b3f18d 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -59,7 +59,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Fixed - `opentelemetry-instrumentation-logging`: Apply log format/level when logging already configured (autoinstrumentation, Gunicorn, Flask) - ([#2384](https://github.com/open-telemetry/opentelemetry-python-contrib/issues/2384)) + ([#4204](https://github.com/open-telemetry/opentelemetry-python-contrib/pull/4204)) - `opentelemetry-instrumentation-cassandra`: Use `_instruments_any` instead of `_instruments` for driver dependencies so that having either `cassandra-driver` or `scylla-driver` installed is sufficient ([#4182](https://github.com/open-telemetry/opentelemetry-python-contrib/pull/4182)) - `opentelemetry-instrumentation-asyncpg`: Hydrate span attributes before creation so samplers can filter on database details From f1e9454d7eb06697b4aa541d895f5d47d05128eb Mon Sep 17 00:00:00 2001 From: Mike Goldsmith Date: Mon, 16 Feb 2026 15:28:52 +0000 Subject: [PATCH 3/5] fix: test failures and formatting - Clear handlers before basicConfig tests - Run ruff format --- .../instrumentation/logging/__init__.py | 5 +++- .../tests/test_logging.py | 28 +++++++++++++++++-- 2 files changed, 29 insertions(+), 4 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 1e2aadab32..dc985be09a 100644 --- a/instrumentation/opentelemetry-instrumentation-logging/src/opentelemetry/instrumentation/logging/__init__.py +++ b/instrumentation/opentelemetry-instrumentation-logging/src/opentelemetry/instrumentation/logging/__init__.py @@ -236,7 +236,10 @@ def _uninstrument(self, **kwargs): # Restore formatters and level if LoggingInstrumentor._old_handler_formatters is not None: - for handler, old_formatter in LoggingInstrumentor._old_handler_formatters: + for ( + handler, + old_formatter, + ) in LoggingInstrumentor._old_handler_formatters: handler.setFormatter(old_formatter) LoggingInstrumentor._old_handler_formatters = None diff --git a/instrumentation/opentelemetry-instrumentation-logging/tests/test_logging.py b/instrumentation/opentelemetry-instrumentation-logging/tests/test_logging.py index 13885a3b08..d62df832b3 100644 --- a/instrumentation/opentelemetry-instrumentation-logging/tests/test_logging.py +++ b/instrumentation/opentelemetry-instrumentation-logging/tests/test_logging.py @@ -145,6 +145,11 @@ def test_basic_config_called(self, basic_config_mock): self.assertFalse(basic_config_mock.called) LoggingInstrumentor().uninstrument() + # Clear handlers to ensure basicConfig is called + root = logging.getLogger() + for handler in root.handlers[:]: + root.removeHandler(handler) + with mock.patch.dict( "os.environ", {"OTEL_PYTHON_LOG_CORRELATION": "true"} ): @@ -160,6 +165,11 @@ def test_custom_format_and_level_env(self, basic_config_mock): self.assertFalse(basic_config_mock.called) LoggingInstrumentor().uninstrument() + # Clear handlers to ensure basicConfig is called + root = logging.getLogger() + for handler in root.handlers[:]: + root.removeHandler(handler) + with mock.patch.dict( "os.environ", { @@ -176,6 +186,12 @@ def test_custom_format_and_level_env(self, basic_config_mock): @mock.patch("logging.basicConfig") def test_custom_format_and_level_api(self, basic_config_mock): # pylint: disable=no-self-use LoggingInstrumentor().uninstrument() + + # Clear handlers to ensure basicConfig is called + root = logging.getLogger() + for handler in root.handlers[:]: + root.removeHandler(handler) + LoggingInstrumentor().instrument( set_logging_format=True, logging_format="%(message)s span_id=%(otelSpanID)s", @@ -363,14 +379,18 @@ def test_handler_without_formatter(self): def test_instrument_uninstrument_cycle(self): """Test multiple instrument/uninstrument cycles.""" - logging.basicConfig(format="ORIGINAL: %(message)s", level=logging.ERROR) + logging.basicConfig( + format="ORIGINAL: %(message)s", level=logging.ERROR + ) LoggingInstrumentor().instrument(set_logging_format=True) handler = logging.getLogger().handlers[0] self.assertIn("otelTraceID", handler.formatter._style._fmt) LoggingInstrumentor().uninstrument() - self.assertEqual(handler.formatter._style._fmt, "ORIGINAL: %(message)s") + self.assertEqual( + handler.formatter._style._fmt, "ORIGINAL: %(message)s" + ) # Re-instrument LoggingInstrumentor().instrument(set_logging_format=True) @@ -378,4 +398,6 @@ def test_instrument_uninstrument_cycle(self): # Re-uninstrument LoggingInstrumentor().uninstrument() - self.assertEqual(handler.formatter._style._fmt, "ORIGINAL: %(message)s") + self.assertEqual( + handler.formatter._style._fmt, "ORIGINAL: %(message)s" + ) From 6a56f5a36510feec49a2f06764b3dd640ee03a8c Mon Sep 17 00:00:00 2001 From: Mike Goldsmith Date: Mon, 16 Feb 2026 15:50:12 +0000 Subject: [PATCH 4/5] fix: caplog capture issue in test_preconfigured_logging caplog doesn't capture when basicConfig called before fixture setup. Use custom handler to capture records instead. --- .../tests/test_logging.py | 31 +++++++++++++++---- 1 file changed, 25 insertions(+), 6 deletions(-) diff --git a/instrumentation/opentelemetry-instrumentation-logging/tests/test_logging.py b/instrumentation/opentelemetry-instrumentation-logging/tests/test_logging.py index d62df832b3..aa83577394 100644 --- a/instrumentation/opentelemetry-instrumentation-logging/tests/test_logging.py +++ b/instrumentation/opentelemetry-instrumentation-logging/tests/test_logging.py @@ -315,20 +315,39 @@ def test_preconfigured_logging(self): self.assertIn("otelTraceID", format_str) self.assertIn("otelSpanID", format_str) - # Verify logs include trace context + # Verify trace context injection works + # Note: caplog doesn't capture properly when basicConfig is called before it, + # so we verify by checking that the formatter includes the required fields + # and that log records have the otel attributes injected with self.tracer.start_as_current_span("test") as span: - with self.caplog.at_level(level=logging.INFO): - logger = logging.getLogger("test logger") + span_ctx = span.get_span_context() + logger = logging.getLogger("test logger") + + # Create a test handler to capture log records + test_handler = logging.StreamHandler() + test_handler.setLevel(logging.INFO) + test_records = [] + + class RecordCapture(logging.Handler): + def emit(self, record): + test_records.append(record) + + capture_handler = RecordCapture() + capture_handler.setLevel(logging.INFO) + logger.addHandler(capture_handler) + + try: logger.info("test message") - self.assertEqual(len(self.caplog.records), 1) - record = self.caplog.records[0] - span_ctx = span.get_span_context() + self.assertEqual(len(test_records), 1) + record = test_records[0] self.assertEqual( record.otelSpanID, format(span_ctx.span_id, "016x") ) self.assertEqual( record.otelTraceID, format(span_ctx.trace_id, "032x") ) + finally: + logger.removeHandler(capture_handler) # Uninstrument and verify restoration LoggingInstrumentor().uninstrument() From ffb82aca528d6f236e010cfca4f0114c7c432dde Mon Sep 17 00:00:00 2001 From: Mike Goldsmith Date: Wed, 18 Feb 2026 10:46:12 +0000 Subject: [PATCH 5/5] refactor: mock hasHandlers instead of clearing handlers in tests --- .../tests/test_logging.py | 63 +++++++++---------- 1 file changed, 31 insertions(+), 32 deletions(-) diff --git a/instrumentation/opentelemetry-instrumentation-logging/tests/test_logging.py b/instrumentation/opentelemetry-instrumentation-logging/tests/test_logging.py index aa83577394..da694dac1f 100644 --- a/instrumentation/opentelemetry-instrumentation-logging/tests/test_logging.py +++ b/instrumentation/opentelemetry-instrumentation-logging/tests/test_logging.py @@ -145,13 +145,13 @@ def test_basic_config_called(self, basic_config_mock): self.assertFalse(basic_config_mock.called) LoggingInstrumentor().uninstrument() - # Clear handlers to ensure basicConfig is called - root = logging.getLogger() - for handler in root.handlers[:]: - root.removeHandler(handler) - - with mock.patch.dict( - "os.environ", {"OTEL_PYTHON_LOG_CORRELATION": "true"} + with ( + mock.patch.object( + logging.getLogger(), "hasHandlers", return_value=False + ), + mock.patch.dict( + "os.environ", {"OTEL_PYTHON_LOG_CORRELATION": "true"} + ), ): LoggingInstrumentor().instrument() basic_config_mock.assert_called_with( @@ -165,18 +165,18 @@ def test_custom_format_and_level_env(self, basic_config_mock): self.assertFalse(basic_config_mock.called) LoggingInstrumentor().uninstrument() - # Clear handlers to ensure basicConfig is called - root = logging.getLogger() - for handler in root.handlers[:]: - root.removeHandler(handler) - - with mock.patch.dict( - "os.environ", - { - "OTEL_PYTHON_LOG_CORRELATION": "true", - "OTEL_PYTHON_LOG_FORMAT": "%(message)s %(otelSpanID)s", - "OTEL_PYTHON_LOG_LEVEL": "error", - }, + with ( + mock.patch.object( + logging.getLogger(), "hasHandlers", return_value=False + ), + mock.patch.dict( + "os.environ", + { + "OTEL_PYTHON_LOG_CORRELATION": "true", + "OTEL_PYTHON_LOG_FORMAT": "%(message)s %(otelSpanID)s", + "OTEL_PYTHON_LOG_LEVEL": "error", + }, + ), ): LoggingInstrumentor().instrument() basic_config_mock.assert_called_with( @@ -187,19 +187,18 @@ def test_custom_format_and_level_env(self, basic_config_mock): def test_custom_format_and_level_api(self, basic_config_mock): # pylint: disable=no-self-use LoggingInstrumentor().uninstrument() - # Clear handlers to ensure basicConfig is called - root = logging.getLogger() - for handler in root.handlers[:]: - root.removeHandler(handler) - - LoggingInstrumentor().instrument( - set_logging_format=True, - logging_format="%(message)s span_id=%(otelSpanID)s", - log_level=logging.WARNING, - ) - basic_config_mock.assert_called_with( - format="%(message)s span_id=%(otelSpanID)s", level=logging.WARNING - ) + with mock.patch.object( + logging.getLogger(), "hasHandlers", return_value=False + ): + LoggingInstrumentor().instrument( + set_logging_format=True, + logging_format="%(message)s span_id=%(otelSpanID)s", + log_level=logging.WARNING, + ) + basic_config_mock.assert_called_with( + format="%(message)s span_id=%(otelSpanID)s", + level=logging.WARNING, + ) def test_log_hook(self): LoggingInstrumentor().uninstrument()