diff --git a/.changelog/4626.added b/.changelog/4626.added new file mode 100644 index 0000000000..27f51f9169 --- /dev/null +++ b/.changelog/4626.added @@ -0,0 +1 @@ +`opentelemetry-instrumentation-logging`: add optional `inject_trace_context` argument for injecting trace context attributes 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 528ed39f3c..93087e9867 100644 --- a/instrumentation/opentelemetry-instrumentation-logging/src/opentelemetry/instrumentation/logging/__init__.py +++ b/instrumentation/opentelemetry-instrumentation-logging/src/opentelemetry/instrumentation/logging/__init__.py @@ -8,9 +8,9 @@ system with an handler to convert log messages into OpenTelemetry logs. You can disable this setting `OTEL_PYTHON_LOG_AUTO_INSTRUMENTATION` to `false`. -The OpenTelemetry `logging` integration can inject tracing context into -log statements, though it is opt-in and must be enabled explicitly by setting the -environment variable `OTEL_PYTHON_LOG_CORRELATION` to `true`. +Trace context injection is opt-in. Pass ``inject_trace_context=True`` to add +``otelSpanID``, ``otelTraceID``, ``otelTraceSampled``, and ``otelServiceName`` +to every log record without changing the logging format: .. code-block:: python @@ -18,23 +18,13 @@ from opentelemetry.instrumentation.logging import LoggingInstrumentor - LoggingInstrumentor().instrument() + LoggingInstrumentor().instrument(inject_trace_context=True) logging.warning('OTel test') -When running the above example you will see the following output: - -:: - - 2025-03-05 09:40:04,398 WARNING [root] [example.py:7] [trace_id=0 span_id=0 resource.service.name= trace_sampled=False] - OTel test - -The environment variable `OTEL_PYTHON_LOG_CORRELATION` must be set to `true` -in order to enable trace context injection into logs by calling -`logging.basicConfig()` and setting a logging format that makes use of the -injected tracing variables. - -Alternatively, `set_logging_format` argument can be set to `True` when -initializing the `LoggingInstrumentor` class to achieve the same effect: +Alternatively, set ``set_logging_format=True`` (or the environment variable +``OTEL_PYTHON_LOG_CORRELATION=true``) to inject those same attributes and +call ``logging.basicConfig()`` with a format string that includes them: .. code-block:: python @@ -46,6 +36,12 @@ logging.warning('OTel test') +When running the above example you will see the following output: + +:: + + 2025-03-05 09:40:04,398 WARNING [root] [example.py:7] [trace_id=0 span_id=0 resource.service.name= trace_sampled=False] - OTel test + """ import logging # pylint: disable=import-self @@ -120,7 +116,10 @@ def log_hook(span: Span, record: LogRecord): Args: tracer_provider: Tracer provider instance that can be used to fetch a tracer. - set_logging_format: When set to True, it calls logging.basicConfig() and sets a logging format. + set_logging_format: When set to True, injects trace context attributes into log records + and calls logging.basicConfig() with a format string that includes those attributes. + inject_trace_context: When set to True, injects trace context attributes + into every log record without modifying the logging format. logging_format: Accepts a string and sets it as the logging format when set_logging_format is set to True. log_level: Accepts one of the following values and sets the logging level to it. @@ -156,29 +155,33 @@ def _instrument(self, **kwargs): ) if set_logging_format: - log_format = kwargs.get( - "logging_format", environ.get(OTEL_PYTHON_LOG_FORMAT, None) + log_format = ( + kwargs.get( + "logging_format", environ.get(OTEL_PYTHON_LOG_FORMAT, None) + ) + or DEFAULT_LOGGING_FORMAT ) - log_format = log_format or DEFAULT_LOGGING_FORMAT - - log_level = kwargs.get( - "log_level", LEVELS.get(environ.get(OTEL_PYTHON_LOG_LEVEL)) + log_level = ( + kwargs.get( + "log_level", LEVELS.get(environ.get(OTEL_PYTHON_LOG_LEVEL)) + ) + or logging.INFO ) - log_level = log_level or logging.INFO - logging.basicConfig(format=log_format, level=log_level) + inject_context = set_logging_format or kwargs.get( + "inject_trace_context", False + ) + def record_factory(*args, **kwargs): record = old_factory(*args, **kwargs) - # this factory is a no-op if log correlation or log hook are not set - if not set_logging_format and not callable( + if not inject_context 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: + if inject_context: record.otelSpanID = "0" record.otelTraceID = "0" record.otelTraceSampled = False @@ -199,7 +202,7 @@ def record_factory(*args, **kwargs): if span != INVALID_SPAN: ctx = span.get_span_context() if ctx != INVALID_SPAN_CONTEXT: - if set_logging_format: + if inject_context: record.otelSpanID = format(ctx.span_id, "016x") record.otelTraceID = format(ctx.trace_id, "032x") record.otelTraceSampled = ctx.trace_flags.sampled diff --git a/instrumentation/opentelemetry-instrumentation-logging/src/opentelemetry/instrumentation/logging/constants.py b/instrumentation/opentelemetry-instrumentation-logging/src/opentelemetry/instrumentation/logging/constants.py index 6070601649..f787184cad 100644 --- a/instrumentation/opentelemetry-instrumentation-logging/src/opentelemetry/instrumentation/logging/constants.py +++ b/instrumentation/opentelemetry-instrumentation-logging/src/opentelemetry/instrumentation/logging/constants.py @@ -39,9 +39,13 @@ {default_logging_format} -The integration is opt-in and must be enabled explicitly by setting the environment variable ``OTEL_PYTHON_LOG_CORRELATION`` to ``true``. -Setting ``OTEL_PYTHON_LOG_CORRELATION`` to ``true`` calls ``logging.basicConfig()`` to set a logging format that actually makes -use of the injected variables. +Trace context injection is opt-in and can be enabled in two ways: + +- Pass ``inject_trace_context=True`` to inject trace context attributes into every log record without modifying + the logging format. Use this when you manage the logging format yourself but still want + ``otelSpanID``, ``otelTraceID``, ``otelTraceSampled``, and ``otelServiceName`` available on each record. +- Set ``OTEL_PYTHON_LOG_CORRELATION`` to ``true`` (or pass ``set_logging_format=True``) to inject the same + trace context attributes and call ``logging.basicConfig()`` with a format string that includes them. Environment variables --------------------- @@ -151,15 +155,23 @@ from opentelemetry.instrumentation.logging import LoggingInstrumentor + # inject trace context attributes only (manage your own format) + LoggingInstrumentor().instrument(inject_trace_context=True) + +.. code-block:: python + + from opentelemetry.instrumentation.logging import LoggingInstrumentor + + # inject trace context attributes and set the logging format LoggingInstrumentor().instrument(set_logging_format=True) Note ----- -If you do not set ``OTEL_PYTHON_LOG_CORRELATION`` to ``true`` but instead set the logging format manually or through your framework, you must ensure that this -integration is enabled before you set the logging format. This is important because unless the integration is enabled, the tracing context variables -are not injected into the log record objects. This means any attempted log statements made after setting the logging format and before enabling this integration -will result in KeyError exceptions. Such exceptions are automatically swallowed by the logging module and do not result in crashes but you may still lose out -on important log messages. +If you set a logging format with trace context placeholders (e.g. ``%(otelSpanID)s``) but do not enable +trace context injection via ``inject_trace_context=True`` or ``set_logging_format=True``, the placeholders +will not be populated. Any log statements emitted before injection is enabled will result in ``KeyError`` +exceptions, which the logging module silently swallows. Enable this integration as early as possible to +avoid these issues. """.format(default_logging_format=DEFAULT_LOGGING_FORMAT) diff --git a/instrumentation/opentelemetry-instrumentation-logging/tests/test_logging.py b/instrumentation/opentelemetry-instrumentation-logging/tests/test_logging.py index 6ad3bbe626..7ad851d3fa 100644 --- a/instrumentation/opentelemetry-instrumentation-logging/tests/test_logging.py +++ b/instrumentation/opentelemetry-instrumentation-logging/tests/test_logging.py @@ -89,9 +89,15 @@ def assert_trace_context_injected(self, span_id, trace_id, trace_sampled): self.assertEqual(record.otelServiceName, "unknown_service") @mock.patch.dict("os.environ", {"OTEL_PYTHON_LOG_CORRELATION": "true"}) - def test_trace_context_injection_with_log_correlation_from_env_var(self): + @mock.patch("logging.basicConfig") + def test_trace_context_injection_with_log_correlation_from_env_var( + self, basic_config_mock + ): LoggingInstrumentor().uninstrument() LoggingInstrumentor().instrument() + basic_config_mock.assert_called_once_with( + format=DEFAULT_LOGGING_FORMAT, level=logging.INFO + ) with self.tracer.start_as_current_span("s1") as span: span_ctx = span.get_span_context() span_id = format(span_ctx.span_id, "016x") @@ -101,9 +107,15 @@ def test_trace_context_injection_with_log_correlation_from_env_var(self): span_id, trace_id, trace_sampled ) - def test_trace_context_injection_with_log_correlation_instrument_arg(self): + @mock.patch("logging.basicConfig") + def test_trace_context_injection_with_log_correlation_instrument_arg( + self, basic_config_mock + ): LoggingInstrumentor().uninstrument() LoggingInstrumentor().instrument(set_logging_format=True) + basic_config_mock.assert_called_once_with( + format=DEFAULT_LOGGING_FORMAT, level=logging.INFO + ) with self.tracer.start_as_current_span("s1") as span: span_ctx = span.get_span_context() span_id = format(span_ctx.span_id, "016x") @@ -125,9 +137,34 @@ def test_no_trace_context_injection_by_default(self): self.assertFalse(hasattr(record, "otelTraceID")) self.assertFalse(hasattr(record, "otelTraceSampled")) - def test_trace_context_injection_without_span(self): + @mock.patch("logging.basicConfig") + def test_inject_trace_context_arg(self, basic_config_mock): + LoggingInstrumentor().uninstrument() + LoggingInstrumentor().instrument(inject_trace_context=True) + basic_config_mock.assert_not_called() + 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 + ) + + @mock.patch("logging.basicConfig") + def test_inject_trace_context_arg_without_span(self, basic_config_mock): + LoggingInstrumentor().uninstrument() + LoggingInstrumentor().instrument(inject_trace_context=True) + basic_config_mock.assert_not_called() + self.assert_trace_context_injected("0", "0", False) + + @mock.patch("logging.basicConfig") + def test_trace_context_injection_without_span(self, basic_config_mock): LoggingInstrumentor().uninstrument() LoggingInstrumentor().instrument(set_logging_format=True) + basic_config_mock.assert_called_once_with( + format=DEFAULT_LOGGING_FORMAT, level=logging.INFO + ) self.assert_trace_context_injected("0", "0", False) @mock.patch("logging.basicConfig") @@ -196,12 +233,16 @@ def test_log_hook(self): record.custom_user_attribute_from_log_hook, "some-value" ) - def test_log_hook_with_set_logging_format(self): + @mock.patch("logging.basicConfig") + def test_log_hook_with_set_logging_format(self, basic_config_mock): LoggingInstrumentor().uninstrument() LoggingInstrumentor().instrument( set_logging_format=True, log_hook=log_hook, ) + basic_config_mock.assert_called_once_with( + format=DEFAULT_LOGGING_FORMAT, level=logging.INFO + ) with self.tracer.start_as_current_span("s1") as span: span_ctx = span.get_span_context() span_id = format(span_ctx.span_id, "016x") @@ -241,11 +282,15 @@ def test_uninstrumented(self): ] self.assertEqual(logging_handler_instances, []) - def test_no_op_tracer_provider(self): + @mock.patch("logging.basicConfig") + def test_no_op_tracer_provider(self, basic_config_mock): LoggingInstrumentor().uninstrument() LoggingInstrumentor().instrument( tracer_provider=NoOpTracerProvider(), set_logging_format=True ) + basic_config_mock.assert_called_once_with( + format=DEFAULT_LOGGING_FORMAT, level=logging.INFO + ) with self.caplog.at_level(level=logging.INFO): logger = logging.getLogger("test logger")