-
Notifications
You must be signed in to change notification settings - Fork 979
Add OTEL_SEMCONV_EXCEPTION_SIGNAL_OPT_IN support to record_exception #5323
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.
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
base: main
Are you sure you want to change the base?
Changes from all commits
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
| 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. `Span.record_exception` also takes optional `event_name` and `severity_number` arguments, in `opentelemetry-api` and `opentelemetry-sdk`, applying to the log representation |
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -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 ( | ||
|
|
@@ -86,6 +88,23 @@ | |
|
|
||
| _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 | ||
|
|
@@ -1029,12 +1048,37 @@ def record_exception( | |
| attributes: types.Attributes = None, | ||
| timestamp: int | None = None, | ||
| escaped: bool = False, | ||
| *, | ||
| event_name: str | None = None, | ||
| severity_number: SeverityNumber | None = None, | ||
| ) -> 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 | ||
| ``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__ | ||
| exception_type = f"{module}.{qualname}" if module and module != "builtins" else qualname | ||
| event_name = event_name if event_name is not None else "exception" | ||
| severity_number = severity_number if severity_number is not None else SeverityNumber.ERROR | ||
| signal = _exception_signal_opt_in() | ||
| if signal in (_EXCEPTION_SIGNAL_LOGS, _EXCEPTION_SIGNAL_LOGS_DUP): | ||
| self._record_exception_log( | ||
| exception_type=exception_type, | ||
|
DylanRussell marked this conversation as resolved.
|
||
| exception_message=str(exception), | ||
| stacktrace=stacktrace, | ||
| attributes=attributes, | ||
| timestamp=timestamp, | ||
| event_name=event_name, | ||
| severity_number=severity_number, | ||
| ) | ||
| if signal == _EXCEPTION_SIGNAL_LOGS: | ||
| return | ||
|
|
||
| _attributes: MutableMapping[str, types.AnyValue] = { | ||
| EXCEPTION_TYPE: exception_type, | ||
| EXCEPTION_MESSAGE: str(exception), | ||
|
|
@@ -1045,6 +1089,53 @@ def record_exception( | |
| _attributes.update(attributes) | ||
| self.add_event(name="exception", attributes=_attributes, timestamp=timestamp) | ||
|
|
||
| def _record_exception_log( | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. I believe the old
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. I added a guard. However, unlike Only drawback here is a possible race condition, where log export can happen after the span has ended. This should be okay, because AFAIU the guard should protect against egregious developer mistakes, where a log truly has no business being attached to a long ended span, in which case this race condition would be tolerable. Also unlike adding span events, logs export still functions even after the span ends (and is exported) so I think this minor lack of parity is okay. |
||
| self, | ||
| *, | ||
| exception_type: str, | ||
| exception_message: str, | ||
| stacktrace: str, | ||
| attributes: types.Attributes, | ||
| timestamp: int | None, | ||
| event_name: str, | ||
| severity_number: SeverityNumber, | ||
| ) -> None: | ||
| """Emits the exception as a log correlated with this span.""" | ||
| # Checked without `self._lock` on purpose; the lock would be held | ||
| # across `emit()`, blocking `end()` for the duration of a synchronous | ||
| # export, and a concurrently ending span is not worth that. | ||
| if self._end_time is not None: | ||
| logger.warning("Tried calling record_exception on an ended span.") | ||
| return | ||
|
|
||
| log_attributes: dict[str, types.AnyValue] = { | ||
| EXCEPTION_TYPE: exception_type, | ||
| EXCEPTION_MESSAGE: exception_message, | ||
| EXCEPTION_STACKTRACE: stacktrace, | ||
| } | ||
| if attributes: | ||
| log_attributes.update(attributes) | ||
|
|
||
| scope = self.instrumentation_scope | ||
| exception_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, | ||
|
RKest marked this conversation as resolved.
|
||
| attributes=scope.attributes if scope else None, | ||
| ) | ||
| # The `exception.escaped` attribute is intentionally omitted as it is | ||
| # deprecated for the logs representation. | ||
| exception_logger.emit( | ||
| LogRecord( | ||
| timestamp=timestamp, | ||
| context=trace_api.set_span_in_context(self), | ||
| event_name=event_name, | ||
| severity_number=severity_number, | ||
| severity_text=severity_number.name, | ||
| attributes=log_attributes, | ||
| ) | ||
| ) | ||
|
|
||
|
|
||
| class _Span(Span): | ||
| """Protected implementation of `opentelemetry.trace.Span`. | ||
|
|
||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,143 @@ | ||
| # 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", attributes={"scope.key": "v"}) | ||
| 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, kwargs = self.mock_get_logger.call_args | ||
| self.assertEqual(args[0], "test-scope") | ||
| self.assertEqual(dict(kwargs["attributes"]), {"scope.key": "v"}) | ||
|
|
||
| def test_ended_span_does_not_emit_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: | ||
| pass | ||
| span.record_exception(ValueError("boom")) | ||
| self.assertEqual(self.logger.records, []) | ||
|
|
||
| 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_event_name_and_severity_can_be_overridden(self): | ||
| with mock.patch.dict(os.environ, {OTEL_SEMCONV_EXCEPTION_SIGNAL_OPT_IN: "logs/dup"}): | ||
| with self.tracer.start_as_current_span("op") as span: | ||
| span.record_exception( | ||
| ValueError("boom"), | ||
| event_name="http.client.request.exception", | ||
| severity_number=SeverityNumber.WARN, | ||
| ) | ||
| record = self.logger.records[0] | ||
| self.assertEqual(record.event_name, "http.client.request.exception") | ||
| self.assertEqual(record.severity_number, SeverityNumber.WARN) | ||
| self.assertEqual(record.severity_text, "WARN") | ||
| # The span event representation always uses the "exception" name. | ||
| self.assertEqual(len(self._exception_events()), 1) | ||
|
|
||
| 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") |
Uh oh!
There was an error while loading. Please reload this page.