Skip to content

Use spec-compatible logging trace context fields #4914

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
saisharan0103 wants to merge 1 commit into
base: main
Choose a base branch
from
+77 −57
Open

Use spec-compatible logging trace context fields #4914

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
16 changes: 8 additions & 8 deletions ...entelemetry-instrumentation-logging/src/opentelemetry/instrumentation/logging/__init__.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -9,7 +9,7 @@
You can disable this setting `OTEL_PYTHON_LOG_AUTO_INSTRUMENTATION` to `false`.

Trace context injection is opt-in. Pass ``inject_trace_context=True`` to add
``otelSpanID``, ``otelTraceID``, ``otelTraceSampled``, and ``otelServiceName``
``span_id``, ``trace_id``, ``trace_flags``, and ``otelServiceName``
to every log record without changing the logging format:

.. code-block:: python
Expand Down Expand Up @@ -40,7 +40,7 @@

::

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
2025-03-05 09:40:04,398 WARNING [root] [example.py:7] [trace_id=0 span_id=0 resource.service.name= trace_flags=00] - OTel test

"""

Expand Down Expand Up @@ -182,9 +182,9 @@ def record_factory(*args, **kwargs):
return record

if inject_context:
record.otelSpanID = "0"
record.otelTraceID = "0"
record.otelTraceSampled = False
record.span_id = "0"
record.trace_id = "0"
record.trace_flags = "00"

nonlocal service_name
if service_name is None:
Expand All @@ -203,9 +203,9 @@ def record_factory(*args, **kwargs):
ctx = span.get_span_context()
if ctx != INVALID_SPAN_CONTEXT:
if inject_context:
record.otelSpanID = format(ctx.span_id, "016x")
record.otelTraceID = format(ctx.trace_id, "032x")
record.otelTraceSampled = ctx.trace_flags.sampled
record.span_id = format(ctx.span_id, "016x")
record.trace_id = format(ctx.trace_id, "032x")
record.trace_flags = format(ctx.trace_flags, "02x")

if callable(LoggingInstrumentor._log_hook):
try:
Expand Down
16 changes: 8 additions & 8 deletions ...ntelemetry-instrumentation-logging/src/opentelemetry/instrumentation/logging/constants.py
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,7 +1,7 @@
# Copyright The OpenTelemetry Authors
# SPDX-License-Identifier: Apache-2.0

DEFAULT_LOGGING_FORMAT = "%(asctime)s %(levelname)s [%(name)s] [%(filename)s:%(lineno)d] [trace_id=%(otelTraceID)s span_id=%(otelSpanID)s resource.service.name=%(otelServiceName)s trace_sampled=%(otelTraceSampled)s] - %(message)s"
DEFAULT_LOGGING_FORMAT = "%(asctime)s %(levelname)s [%(name)s] [%(filename)s:%(lineno)d] [trace_id=%(trace_id)s span_id=%(span_id)s resource.service.name=%(otelServiceName)s trace_flags=%(trace_flags)s] - %(message)s"


_MODULE_DOC = """
Expand All @@ -24,14 +24,14 @@

The integration registers a custom log record factory with the the standard library logging module that automatically inject
tracing context into log record objects. Optionally, the integration can also call ``logging.basicConfig()`` to set a logging
format with placeholders for span ID, trace ID and service name.
format with placeholders for span ID, trace ID, trace flags and service name.

The following keys are injected into log record objects by the factory:

- ``otelSpanID``
- ``otelTraceID``
- ``span_id``
- ``trace_id``
- ``otelServiceName``
- ``otelTraceSampled``
- ``trace_flags``

The integration uses the following logging format by default:

Expand All @@ -43,7 +43,7 @@

- 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.
``span_id``, ``trace_id``, ``trace_flags``, 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.

Expand Down Expand Up @@ -144,7 +144,7 @@

.. code-block::

%(otelSpanID)s %(otelTraceID)s %(otelServiceName)s %(otelTraceSampled)s
%(span_id)s %(trace_id)s %(otelServiceName)s %(trace_flags)s



Expand All @@ -169,7 +169,7 @@
Note
-----

If you set a logging format with trace context placeholders (e.g. ``%(otelSpanID)s``) but do not enable
If you set a logging format with trace context placeholders (e.g. ``%(span_id)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
Expand Down
102 changes: 61 additions & 41 deletions instrumentation/opentelemetry-instrumentation-logging/tests/test_logging.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -53,10 +53,10 @@ def test_trace_context_injection(self):
logger.info("hello")
self.assertEqual(len(self.caplog.records), 1)
record = self.caplog.records[0]
self.assertEqual(record.otelSpanID, "0")
self.assertEqual(record.otelTraceID, "0")
self.assertEqual(record.span_id, "0")
self.assertEqual(record.trace_id, "0")
self.assertEqual(record.otelServiceName, "")
self.assertEqual(record.otelTraceSampled, False)
self.assertEqual(record.trace_flags, "00")


def log_hook(span, record):
Expand All @@ -77,15 +77,15 @@ def tearDown(self):
super().tearDown()
LoggingInstrumentor().uninstrument()

def assert_trace_context_injected(self, span_id, trace_id, trace_sampled):
def assert_trace_context_injected(self, span_id, trace_id, trace_flags):
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.assertEqual(record.otelSpanID, span_id)
self.assertEqual(record.otelTraceID, trace_id)
self.assertEqual(record.otelTraceSampled, trace_sampled)
self.assertEqual(record.span_id, span_id)
self.assertEqual(record.trace_id, trace_id)
self.assertEqual(record.trace_flags, trace_flags)
self.assertEqual(record.otelServiceName, "unknown_service")

@mock.patch.dict("os.environ", {"OTEL_PYTHON_LOG_CORRELATION": "true"})
Expand All @@ -102,10 +102,8 @@ def test_trace_context_injection_with_log_correlation_from_env_var(
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
)
trace_flags = format(span_ctx.trace_flags, "02x")
self.assert_trace_context_injected(span_id, trace_id, trace_flags)

@mock.patch("logging.basicConfig")
def test_trace_context_injection_with_log_correlation_instrument_arg(
Expand All @@ -120,10 +118,8 @@ def test_trace_context_injection_with_log_correlation_instrument_arg(
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
)
trace_flags = format(span_ctx.trace_flags, "02x")
self.assert_trace_context_injected(span_id, trace_id, trace_flags)

def test_no_trace_context_injection_by_default(self):
with self.tracer.start_as_current_span("s1"):
Expand All @@ -133,9 +129,9 @@ def test_no_trace_context_injection_by_default(self):
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.assertFalse(hasattr(record, "span_id"))
self.assertFalse(hasattr(record, "trace_id"))
self.assertFalse(hasattr(record, "trace_flags"))

@mock.patch("logging.basicConfig")
def test_inject_trace_context_arg(self, basic_config_mock):
Expand All @@ -146,17 +142,41 @@ def test_inject_trace_context_arg(self, basic_config_mock):
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
)
trace_flags = format(span_ctx.trace_flags, "02x")
self.assert_trace_context_injected(span_id, trace_id, trace_flags)

def test_log_record_dict_uses_spec_trace_context_names(self):
LoggingInstrumentor().uninstrument()
LoggingInstrumentor().instrument(inject_trace_context=True)
with self.tracer.start_as_current_span("s1") as span:
span_ctx = span.get_span_context()
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].__dict__
self.assertEqual(
record["span_id"], format(span_ctx.span_id, "016x")
)
self.assertEqual(
record["trace_id"], format(span_ctx.trace_id, "032x")
)
self.assertEqual(
record["trace_flags"], format(span_ctx.trace_flags, "02x")
)
self.assertIs(type(record["span_id"]), str)
self.assertIs(type(record["trace_id"]), str)
self.assertIs(type(record["trace_flags"]), str)
self.assertNotIn("otelSpanID", record)
self.assertNotIn("otelTraceID", record)
self.assertNotIn("otelTraceSampled", record)

@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)
self.assert_trace_context_injected("0", "0", "00")

@mock.patch("logging.basicConfig")
def test_trace_context_injection_without_span(self, basic_config_mock):
Expand All @@ -165,7 +185,7 @@ def test_trace_context_injection_without_span(self, basic_config_mock):
basic_config_mock.assert_called_once_with(
format=DEFAULT_LOGGING_FORMAT, level=logging.INFO
)
self.assert_trace_context_injected("0", "0", False)
self.assert_trace_context_injected("0", "0", "00")

@mock.patch("logging.basicConfig")
def test_basic_config_called(self, basic_config_mock):
Expand Down Expand Up @@ -193,25 +213,25 @@ def test_custom_format_and_level_env(self, basic_config_mock):
"os.environ",
{
"OTEL_PYTHON_LOG_CORRELATION": "true",
"OTEL_PYTHON_LOG_FORMAT": "%(message)s %(otelSpanID)s",
"OTEL_PYTHON_LOG_FORMAT": "%(message)s %(span_id)s",
"OTEL_PYTHON_LOG_LEVEL": "error",
},
):
LoggingInstrumentor().instrument()
basic_config_mock.assert_called_with(
format="%(message)s %(otelSpanID)s", level=logging.ERROR
format="%(message)s %(span_id)s", level=logging.ERROR
)

@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",
logging_format="%(message)s span_id=%(span_id)s",
log_level=logging.WARNING,
)
basic_config_mock.assert_called_with(
format="%(message)s span_id=%(otelSpanID)s", level=logging.WARNING
format="%(message)s span_id=%(span_id)s", level=logging.WARNING
)

def test_log_hook(self):
Expand All @@ -226,9 +246,9 @@ def test_log_hook(self):
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.assertFalse(hasattr(record, "span_id"))
self.assertFalse(hasattr(record, "trace_id"))
self.assertFalse(hasattr(record, "trace_flags"))
self.assertEqual(
record.custom_user_attribute_from_log_hook, "some-value"
)
Expand All @@ -247,16 +267,16 @@ def test_log_hook_with_set_logging_format(self, basic_config_mock):
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
trace_flags = format(span_ctx.trace_flags, "02x")
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.assertEqual(record.otelSpanID, span_id)
self.assertEqual(record.otelTraceID, trace_id)
self.assertEqual(record.span_id, span_id)
self.assertEqual(record.trace_id, trace_id)
self.assertEqual(record.otelServiceName, "unknown_service")
self.assertEqual(record.otelTraceSampled, trace_sampled)
self.assertEqual(record.trace_flags, trace_flags)
self.assertEqual(
record.custom_user_attribute_from_log_hook, "some-value"
)
Expand All @@ -270,9 +290,9 @@ def test_uninstrumented(self):
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.assertFalse(hasattr(record, "span_id"))
self.assertFalse(hasattr(record, "trace_id"))
self.assertFalse(hasattr(record, "trace_flags"))

root_logger = logging.getLogger()
logging_handler_instances = [
Expand All @@ -298,10 +318,10 @@ def test_no_op_tracer_provider(self, basic_config_mock):

self.assertEqual(len(self.caplog.records), 1)
record = self.caplog.records[0]
self.assertEqual(record.otelSpanID, "0")
self.assertEqual(record.otelTraceID, "0")
self.assertEqual(record.span_id, "0")
self.assertEqual(record.trace_id, "0")
self.assertEqual(record.otelServiceName, "")
self.assertEqual(record.otelTraceSampled, False)
self.assertEqual(record.trace_flags, "00")

@mock.patch.dict(
"os.environ",
Expand Down
Loading