opentelemetry-instrumentation-logging: don't add out of spec attributes by default (open-telemetry#4112)

* opentelemetry-instrumentation-logging: don't add out of spec attributes by default

Add span context attributes to logging module LogRecord only if the instrumentation
has been configured to do so via set_logging_format argument or OTEL_PYTHON_LOG_CORRELATION
environment variable.

* Add changelog

* Update doc and cleanup tests

* Reduce diff

* Add missing test

Author: sightseeker

CHANGELOG.md

@@ -91,6 +91,8 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 
 ### Breaking changes
 
+- `opentelemetry-instrumentation-logging`: Inject span context attributes into logging LogRecord only if configured to do so
+  ([#4112](https://github.com/open-telemetry/opentelemetry-python-contrib/pull/4112))
 - `opentelemetry-instrumentation-django`: Drop support for Django < 2.0
   ([#3848](https://github.com/open-telemetry/opentelemetry-python-contrib/pull/4083))
 

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

@@ -90,15 +90,17 @@
 class LoggingInstrumentor(BaseInstrumentor):  # pylint: disable=empty-docstring
     __doc__ = f"""An instrumentor for stdlib logging module.
 
-    This instrumentor injects tracing context into logging records and optionally sets the global logging format to the following:
+    This instrumentor optionally injects tracing context into logging records and sets the global logging format to the following:
 
     .. code-block::
 
         {DEFAULT_LOGGING_FORMAT}
 
         def log_hook(span: Span, record: LogRecord):
-                if span and span.is_recording():
-                    record.custom_user_attribute_from_log_hook = "some-value"
+            if span and span.is_recording():
+                record.custom_user_attribute_from_log_hook = "some-value"
+                span_ctx = span.get_span_context()
+                record.from_sampled_span = span_ctx.trace_flags.sampled
 
     Args:
         tracer_provider: Tracer provider instance that can be used to fetch a tracer.
@@ -130,32 +132,61 @@ def _instrument(self, **kwargs):
 
         service_name = None
 
-        def record_factory(*args, **kwargs):
-            record = old_factory(*args, **kwargs)
+        set_logging_format = kwargs.get(
+            "set_logging_format",
+            environ.get(OTEL_PYTHON_LOG_CORRELATION, "false").lower()
+            == "true",
+        )
 
-            record.otelSpanID = "0"
-            record.otelTraceID = "0"
-            record.otelTraceSampled = False
+        if set_logging_format:
+            log_format = kwargs.get(
+                "logging_format", environ.get(OTEL_PYTHON_LOG_FORMAT, None)
+            )
+            log_format = log_format or DEFAULT_LOGGING_FORMAT
+
+            log_level = kwargs.get(
+                "log_level", LEVELS.get(environ.get(OTEL_PYTHON_LOG_LEVEL))
+            )
+            log_level = log_level or logging.INFO
+
+            logging.basicConfig(format=log_format, level=log_level)
 
-            nonlocal service_name
-            if service_name is None:
-                resource = getattr(provider, "resource", None)
-                if resource:
-                    service_name = (
-                        resource.attributes.get("service.name") or ""
-                    )
-                else:
-                    service_name = ""
+        def record_factory(*args, **kwargs):
+            record = old_factory(*args, **kwargs)
 
-            record.otelServiceName = service_name
+            # this factory is a no-op if log correlation or log hook are not set
+            if not set_logging_format and not callable(
+                LoggingInstrumentor._log_hook
+            ):
+                return record
+
+            # out of spec attributes are added to the log record only if log correlation is set
+            if set_logging_format:
+                record.otelSpanID = "0"
+                record.otelTraceID = "0"
+                record.otelTraceSampled = False
+
+                nonlocal service_name
+                if service_name is None:
+                    resource = getattr(provider, "resource", None)
+                    if resource:
+                        service_name = (
+                            resource.attributes.get("service.name") or ""
+                        )
+                    else:
+                        service_name = ""
+
+                record.otelServiceName = service_name
 
             span = get_current_span()
             if span != INVALID_SPAN:
                 ctx = span.get_span_context()
                 if ctx != INVALID_SPAN_CONTEXT:
-                    record.otelSpanID = format(ctx.span_id, "016x")
-                    record.otelTraceID = format(ctx.trace_id, "032x")
-                    record.otelTraceSampled = ctx.trace_flags.sampled
+                    if set_logging_format:
+                        record.otelSpanID = format(ctx.span_id, "016x")
+                        record.otelTraceID = format(ctx.trace_id, "032x")
+                        record.otelTraceSampled = ctx.trace_flags.sampled
+
                     if callable(LoggingInstrumentor._log_hook):
                         try:
                             LoggingInstrumentor._log_hook(  # pylint: disable=E1102
@@ -168,25 +199,6 @@ def record_factory(*args, **kwargs):
 
         logging.setLogRecordFactory(record_factory)
 
-        set_logging_format = kwargs.get(
-            "set_logging_format",
-            environ.get(OTEL_PYTHON_LOG_CORRELATION, "false").lower()
-            == "true",
-        )
-
-        if set_logging_format:
-            log_format = kwargs.get(
-                "logging_format", environ.get(OTEL_PYTHON_LOG_FORMAT, None)
-            )
-            log_format = log_format or DEFAULT_LOGGING_FORMAT
-
-            log_level = kwargs.get(
-                "log_level", LEVELS.get(environ.get(OTEL_PYTHON_LOG_LEVEL))
-            )
-            log_level = log_level or logging.INFO
-
-            logging.basicConfig(format=log_format, level=log_level)
-
     def _uninstrument(self, **kwargs):
         if LoggingInstrumentor._old_factory:
             logging.setLogRecordFactory(LoggingInstrumentor._old_factory)

instrumentation/opentelemetry-instrumentation-logging/tests/test_logging.py

@@ -47,7 +47,9 @@ def inject_fixtures(self, caplog):
 
     def setUp(self):
         super().setUp()
-        LoggingInstrumentor().instrument(tracer_provider=FakeTracerProvider())
+        LoggingInstrumentor().instrument(
+            tracer_provider=FakeTracerProvider(), set_logging_format=True
+        )
 
     def tearDown(self):
         super().tearDown()
@@ -94,16 +96,46 @@ def assert_trace_context_injected(self, span_id, trace_id, trace_sampled):
             self.assertEqual(record.otelTraceSampled, trace_sampled)
             self.assertEqual(record.otelServiceName, "unknown_service")
 
-    def test_trace_context_injection(self):
+    @mock.patch.dict("os.environ", {"OTEL_PYTHON_LOG_CORRELATION": "true"})
+    def test_trace_context_injection_with_log_correlation_from_env_var(self):
+        LoggingInstrumentor().uninstrument()
+        LoggingInstrumentor().instrument()
         with self.tracer.start_as_current_span("s1") as span:
-            span_id = format(span.get_span_context().span_id, "016x")
-            trace_id = format(span.get_span_context().trace_id, "032x")
-            trace_sampled = span.get_span_context().trace_flags.sampled
+            span_ctx = span.get_span_context()
+            span_id = format(span_ctx.span_id, "016x")
+            trace_id = format(span_ctx.trace_id, "032x")
+            trace_sampled = span_ctx.trace_flags.sampled
             self.assert_trace_context_injected(
                 span_id, trace_id, trace_sampled
             )
 
+    def test_trace_context_injection_with_log_correlation_instrument_arg(self):
+        LoggingInstrumentor().uninstrument()
+        LoggingInstrumentor().instrument(set_logging_format=True)
+        with self.tracer.start_as_current_span("s1") as span:
+            span_ctx = span.get_span_context()
+            span_id = format(span_ctx.span_id, "016x")
+            trace_id = format(span_ctx.trace_id, "032x")
+            trace_sampled = span_ctx.trace_flags.sampled
+            self.assert_trace_context_injected(
+                span_id, trace_id, trace_sampled
+            )
+
+    def test_no_trace_context_injection_by_default(self):
+        with self.tracer.start_as_current_span("s1"):
+            with self.caplog.at_level(level=logging.INFO):
+                logger = logging.getLogger("test logger")
+                logger.info("hello")
+                self.assertEqual(len(self.caplog.records), 1)
+                record = self.caplog.records[0]
+                self.assertFalse(hasattr(record, "otelServiceName"))
+                self.assertFalse(hasattr(record, "otelSpanID"))
+                self.assertFalse(hasattr(record, "otelTraceID"))
+                self.assertFalse(hasattr(record, "otelTraceSampled"))
+
     def test_trace_context_injection_without_span(self):
+        LoggingInstrumentor().uninstrument()
+        LoggingInstrumentor().instrument(set_logging_format=True)
         self.assert_trace_context_injected("0", "0", False)
 
     @mock.patch("logging.basicConfig")
@@ -113,15 +145,13 @@ def test_basic_config_called(self, basic_config_mock):
         self.assertFalse(basic_config_mock.called)
         LoggingInstrumentor().uninstrument()
 
-        env_patch = mock.patch.dict(
+        with mock.patch.dict(
             "os.environ", {"OTEL_PYTHON_LOG_CORRELATION": "true"}
-        )
-        env_patch.start()
-        LoggingInstrumentor().instrument()
-        basic_config_mock.assert_called_with(
-            format=DEFAULT_LOGGING_FORMAT, level=logging.INFO
-        )
-        env_patch.stop()
+        ):
+            LoggingInstrumentor().instrument()
+            basic_config_mock.assert_called_with(
+                format=DEFAULT_LOGGING_FORMAT, level=logging.INFO
+            )
 
     @mock.patch("logging.basicConfig")
     def test_custom_format_and_level_env(self, basic_config_mock):
@@ -130,20 +160,18 @@ def test_custom_format_and_level_env(self, basic_config_mock):
         self.assertFalse(basic_config_mock.called)
         LoggingInstrumentor().uninstrument()
 
-        env_patch = mock.patch.dict(
+        with mock.patch.dict(
             "os.environ",
             {
                 "OTEL_PYTHON_LOG_CORRELATION": "true",
                 "OTEL_PYTHON_LOG_FORMAT": "%(message)s %(otelSpanID)s",
                 "OTEL_PYTHON_LOG_LEVEL": "error",
             },
-        )
-        env_patch.start()
-        LoggingInstrumentor().instrument()
-        basic_config_mock.assert_called_with(
-            format="%(message)s %(otelSpanID)s", level=logging.ERROR
-        )
-        env_patch.stop()
+        ):
+            LoggingInstrumentor().instrument()
+            basic_config_mock.assert_called_with(
+                format="%(message)s %(otelSpanID)s", level=logging.ERROR
+            )
 
     @mock.patch("logging.basicConfig")
     def test_custom_format_and_level_api(self, basic_config_mock):  # pylint: disable=no-self-use
@@ -158,15 +186,35 @@ def test_custom_format_and_level_api(self, basic_config_mock):  # pylint: disabl
         )
 
     def test_log_hook(self):
+        LoggingInstrumentor().uninstrument()
+        LoggingInstrumentor().instrument(
+            log_hook=log_hook,
+        )
+        with self.tracer.start_as_current_span("s1"):
+            with self.caplog.at_level(level=logging.INFO):
+                logger = logging.getLogger("test logger")
+                logger.info("hello")
+                self.assertEqual(len(self.caplog.records), 1)
+                record = self.caplog.records[0]
+                self.assertFalse(hasattr(record, "otelServiceName"))
+                self.assertFalse(hasattr(record, "otelSpanID"))
+                self.assertFalse(hasattr(record, "otelTraceID"))
+                self.assertFalse(hasattr(record, "otelTraceSampled"))
+                self.assertEqual(
+                    record.custom_user_attribute_from_log_hook, "some-value"
+                )
+
+    def test_log_hook_with_set_logging_format(self):
         LoggingInstrumentor().uninstrument()
         LoggingInstrumentor().instrument(
             set_logging_format=True,
             log_hook=log_hook,
         )
         with self.tracer.start_as_current_span("s1") as span:
-            span_id = format(span.get_span_context().span_id, "016x")
-            trace_id = format(span.get_span_context().trace_id, "032x")
-            trace_sampled = span.get_span_context().trace_flags.sampled
+            span_ctx = span.get_span_context()
+            span_id = format(span_ctx.span_id, "016x")
+            trace_id = format(span_ctx.trace_id, "032x")
+            trace_sampled = span_ctx.trace_flags.sampled
             with self.caplog.at_level(level=logging.INFO):
                 logger = logging.getLogger("test logger")
                 logger.info("hello")
@@ -181,34 +229,23 @@ def test_log_hook(self):
                 )
 
     def test_uninstrumented(self):
-        with self.tracer.start_as_current_span("s1") as span:
-            span_id = format(span.get_span_context().span_id, "016x")
-            trace_id = format(span.get_span_context().trace_id, "032x")
-            trace_sampled = span.get_span_context().trace_flags.sampled
-            self.assert_trace_context_injected(
-                span_id, trace_id, trace_sampled
-            )
-
         LoggingInstrumentor().uninstrument()
-
-        self.caplog.clear()
-        with self.tracer.start_as_current_span("s1") as span:
-            span_id = format(span.get_span_context().span_id, "016x")
-            trace_id = format(span.get_span_context().trace_id, "032x")
-            trace_sampled = span.get_span_context().trace_flags.sampled
+        with self.tracer.start_as_current_span("s1"):
             with self.caplog.at_level(level=logging.INFO):
                 logger = logging.getLogger("test logger")
                 logger.info("hello")
                 self.assertEqual(len(self.caplog.records), 1)
                 record = self.caplog.records[0]
+                self.assertFalse(hasattr(record, "otelServiceName"))
                 self.assertFalse(hasattr(record, "otelSpanID"))
                 self.assertFalse(hasattr(record, "otelTraceID"))
-                self.assertFalse(hasattr(record, "otelServiceName"))
                 self.assertFalse(hasattr(record, "otelTraceSampled"))
 
     def test_no_op_tracer_provider(self):
         LoggingInstrumentor().uninstrument()
-        LoggingInstrumentor().instrument(tracer_provider=NoOpTracerProvider())
+        LoggingInstrumentor().instrument(
+            tracer_provider=NoOpTracerProvider(), set_logging_format=True
+        )
 
         with self.caplog.at_level(level=logging.INFO):
             logger = logging.getLogger("test logger")