Skip to content
Open
Show file tree
Hide file tree
Changes from all commits
Commits
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
1 change: 1 addition & 0 deletions .changelog/5318.added
Original file line number Diff line number Diff line change
@@ -0,0 +1 @@
`opentelemetry-sdk`: `Span.record_exception` now honors `OTEL_SEMCONV_EXCEPTION_SIGNAL_OPT_IN` (`logs`/`logs/dup`) to record exceptions as logs instead of (or in addition to) span events
80 changes: 79 additions & 1 deletion opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py
Original file line number Diff line number Diff line change
Expand Up @@ -30,9 +30,11 @@

from typing_extensions import deprecated

from opentelemetry import _logs
from opentelemetry import context as context_api
from opentelemetry import metrics as metrics_api
from opentelemetry import trace as trace_api
from opentelemetry._logs import LogRecord, SeverityNumber
from opentelemetry.attributes import BoundedAttributes
from opentelemetry.sdk import util
from opentelemetry.sdk.environment_variables import (
Expand Down Expand Up @@ -83,6 +85,25 @@

_ENV_VALUE_UNSET = ""

# OTEL_SEMCONV_EXCEPTION_SIGNAL_OPT_IN is an experimental, transitional opt-in
# that may be removed once exceptions-as-logs is stable, so it is kept private
# here rather than exported from opentelemetry.sdk.environment_variables. See
# https://opentelemetry.io/docs/specs/semconv/exceptions/exceptions-logs/.
_OTEL_SEMCONV_EXCEPTION_SIGNAL_OPT_IN = "OTEL_SEMCONV_EXCEPTION_SIGNAL_OPT_IN"
_EXCEPTION_SIGNAL_LOGS = "logs"
_EXCEPTION_SIGNAL_LOGS_DUP = "logs/dup"


def _exception_signal_opt_in() -> str:
"""Returns the OTEL_SEMCONV_EXCEPTION_SIGNAL_OPT_IN value.

Anything other than ``logs``/``logs/dup`` (unset or unrecognized) keeps the
existing span-event behavior.
"""
return environ.get(
_OTEL_SEMCONV_EXCEPTION_SIGNAL_OPT_IN, _ENV_VALUE_UNSET
)


class SpanProcessor:
"""Interface which allows hooks for SDK's `Span` start and end method
Expand Down Expand Up @@ -1065,7 +1086,13 @@ def record_exception(
timestamp: int | None = None,
escaped: bool = False,
) -> None:
"""Records an exception as a span event."""
"""Records an exception as a span event and/or a log.

By default the exception is recorded as a span event. Set
:envvar:`OTEL_SEMCONV_EXCEPTION_SIGNAL_OPT_IN` to ``logs`` to record it
as a log instead, or ``logs/dup`` to record both. See
https://opentelemetry.io/docs/specs/semconv/exceptions/exceptions-logs/.
"""
stacktrace = "".join(traceback.format_exception(exception))
module = type(exception).__module__
qualname = type(exception).__qualname__
Expand All @@ -1074,6 +1101,19 @@ def record_exception(
if module and module != "builtins"
else qualname
)

signal = _exception_signal_opt_in()
if signal in (_EXCEPTION_SIGNAL_LOGS, _EXCEPTION_SIGNAL_LOGS_DUP):
self._record_exception_log(
exception_type=exception_type,
exception_message=str(exception),
stacktrace=stacktrace,
attributes=attributes,
timestamp=timestamp,
)
if signal == _EXCEPTION_SIGNAL_LOGS:
return

_attributes: MutableMapping[str, types.AttributeValue] = {
EXCEPTION_TYPE: exception_type,
EXCEPTION_MESSAGE: str(exception),
Expand All @@ -1086,6 +1126,44 @@ def record_exception(
name="exception", attributes=_attributes, timestamp=timestamp
)

def _record_exception_log(
self,
*,
exception_type: str,
exception_message: str,
stacktrace: str,
attributes: types.Attributes,
timestamp: int | None,
) -> None:
"""Emits the exception as a log correlated with this span."""
log_attributes: dict[str, types.AttributeValue] = {
EXCEPTION_TYPE: exception_type,
EXCEPTION_MESSAGE: exception_message,
EXCEPTION_STACKTRACE: stacktrace,
}
if attributes:
log_attributes.update(attributes)

scope = self.instrumentation_scope
logger = _logs.get_logger(
scope.name if scope else __name__,
scope.version or "" if scope else "",
schema_url=scope.schema_url if scope else None,
)
# Exceptions are recorded at severity ERROR. The `exception.escaped`
# attribute is intentionally omitted as it is deprecated for the logs
# representation.
logger.emit(
LogRecord(
timestamp=timestamp,
context=trace_api.set_span_in_context(self),
event_name="exception",
severity_number=SeverityNumber.ERROR,
severity_text="ERROR",
attributes=log_attributes,
)
)


class _Span(Span):
"""Protected implementation of `opentelemetry.trace.Span`.
Expand Down
138 changes: 138 additions & 0 deletions opentelemetry-sdk/tests/trace/test_record_exception_logs.py
Original file line number Diff line number Diff line change
@@ -0,0 +1,138 @@
# Copyright The OpenTelemetry Authors
# SPDX-License-Identifier: Apache-2.0

"""Tests for OTEL_SEMCONV_EXCEPTION_SIGNAL_OPT_IN handling in record_exception."""

import os
import unittest
from unittest import mock

from opentelemetry._logs import SeverityNumber
from opentelemetry.sdk.trace import (
_OTEL_SEMCONV_EXCEPTION_SIGNAL_OPT_IN as OTEL_SEMCONV_EXCEPTION_SIGNAL_OPT_IN,
)
from opentelemetry.sdk.trace import (
TracerProvider,
)
from opentelemetry.sdk.trace.export import SimpleSpanProcessor
from opentelemetry.sdk.trace.export.in_memory_span_exporter import (
InMemorySpanExporter,
)


class _CapturingLogger:
"""A minimal Logger that records emitted LogRecords."""

def __init__(self):
self.records = []

def emit(self, record):
self.records.append(record)


class TestRecordExceptionSignalOptIn(unittest.TestCase):
def setUp(self):
self.span_exporter = InMemorySpanExporter()
provider = TracerProvider()
provider.add_span_processor(SimpleSpanProcessor(self.span_exporter))
self.tracer = provider.get_tracer("test-scope", "1.0")
self.logger = _CapturingLogger()
patcher = mock.patch(
"opentelemetry.sdk.trace._logs.get_logger",
return_value=self.logger,
)
self.mock_get_logger = patcher.start()
self.addCleanup(patcher.stop)

def _raise_in_span(self):
with self.assertRaises(ValueError):
with self.tracer.start_as_current_span("op"):
raise ValueError("boom")

def _exception_events(self):
finished_span = self.span_exporter.get_finished_spans()[0]
return [e for e in finished_span.events if e.name == "exception"]

def test_unset_records_span_event_only(self):
with mock.patch.dict(os.environ, {}, clear=True):
self._raise_in_span()
self.assertEqual(len(self._exception_events()), 1)
self.assertEqual(self.logger.records, [])

def test_unrecognized_value_records_span_event_only(self):
with mock.patch.dict(
os.environ, {OTEL_SEMCONV_EXCEPTION_SIGNAL_OPT_IN: "bogus"}
):
self._raise_in_span()
self.assertEqual(len(self._exception_events()), 1)
self.assertEqual(self.logger.records, [])

def test_logs_records_log_only(self):
with mock.patch.dict(
os.environ, {OTEL_SEMCONV_EXCEPTION_SIGNAL_OPT_IN: "logs"}
):
self._raise_in_span()
self.assertEqual(self._exception_events(), [])
self.assertEqual(len(self.logger.records), 1)
record = self.logger.records[0]
self.assertEqual(record.event_name, "exception")
self.assertEqual(record.severity_number, SeverityNumber.ERROR)
self.assertEqual(record.attributes["exception.type"], "ValueError")
self.assertEqual(record.attributes["exception.message"], "boom")
self.assertIn(
"ValueError: boom", record.attributes["exception.stacktrace"]
)
# The deprecated exception.escaped attribute is not set on logs.
self.assertNotIn("exception.escaped", record.attributes)

def test_logs_dup_records_both(self):
with mock.patch.dict(
os.environ, {OTEL_SEMCONV_EXCEPTION_SIGNAL_OPT_IN: "logs/dup"}
):
self._raise_in_span()
self.assertEqual(len(self._exception_events()), 1)
self.assertEqual(len(self.logger.records), 1)

def test_log_is_correlated_with_span(self):
with mock.patch.dict(
os.environ, {OTEL_SEMCONV_EXCEPTION_SIGNAL_OPT_IN: "logs"}
):
self._raise_in_span()
finished_span = self.span_exporter.get_finished_spans()[0]
record = self.logger.records[0]
self.assertEqual(record.trace_id, finished_span.context.trace_id)
self.assertEqual(record.span_id, finished_span.context.span_id)

def test_logs_uses_instrumentation_scope_for_logger(self):
with mock.patch.dict(
os.environ, {OTEL_SEMCONV_EXCEPTION_SIGNAL_OPT_IN: "logs"}
):
self._raise_in_span()
# The logger is obtained using the span's instrumentation scope.
args, _ = self.mock_get_logger.call_args
self.assertEqual(args[0], "test-scope")

def test_directly_recorded_exception_is_logged(self):
with mock.patch.dict(
os.environ, {OTEL_SEMCONV_EXCEPTION_SIGNAL_OPT_IN: "logs"}
):
with self.tracer.start_as_current_span("op") as span:
try:
raise ValueError("handled")
except ValueError as err:
span.record_exception(err)
record = self.logger.records[0]
self.assertEqual(record.event_name, "exception")
self.assertEqual(record.severity_number, SeverityNumber.ERROR)
self.assertEqual(record.attributes["exception.type"], "ValueError")

def test_extra_attributes_forwarded_to_log(self):
with mock.patch.dict(
os.environ, {OTEL_SEMCONV_EXCEPTION_SIGNAL_OPT_IN: "logs"}
):
with self.tracer.start_as_current_span("op") as span:
span.record_exception(
ValueError("boom"), attributes={"custom.key": "v"}
)
record = self.logger.records[0]
self.assertEqual(record.attributes["custom.key"], "v")