diff --git a/CHANGELOG.md b/CHANGELOG.md index 0e01dbe8bc..ebd8f0dcb0 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -59,6 +59,9 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ([#4139](https://github.com/open-telemetry/opentelemetry-python-contrib/pull/4139)) ### Fixed + +- `opentelemetry-instrumentation-logging`: Apply log format/level when logging already configured (autoinstrumentation, Gunicorn, Flask) + ([#4204](https://github.com/open-telemetry/opentelemetry-python-contrib/pull/4204)) - `opentelemetry-instrumentation-mysql`: Refactor MySQL integration test mocks to use concrete DBAPI connection attributes, reducing noisy attribute type warnings. ([#4116](https://github.com/open-telemetry/opentelemetry-python-contrib/pull/4116)) - `opentelemetry-instrumentation-cassandra`: Use `_instruments_any` instead of `_instruments` for driver dependencies so that having either `cassandra-driver` or `scylla-driver` installed is sufficient 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..dc985be09a 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,16 @@ 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..da694dac1f 100644 --- a/instrumentation/opentelemetry-instrumentation-logging/tests/test_logging.py +++ b/instrumentation/opentelemetry-instrumentation-logging/tests/test_logging.py @@ -145,8 +145,13 @@ def test_basic_config_called(self, basic_config_mock): self.assertFalse(basic_config_mock.called) LoggingInstrumentor().uninstrument() - 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( @@ -160,13 +165,18 @@ def test_custom_format_and_level_env(self, basic_config_mock): self.assertFalse(basic_config_mock.called) LoggingInstrumentor().uninstrument() - 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( @@ -176,14 +186,19 @@ 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() - 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() @@ -257,3 +272,150 @@ 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 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: + 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(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() + 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" + )