fix(opentelemetry): record errors in span events [backport 2.9] (#9448)

Backport 7577ee8 from #9379 to 2.9.

#9380 introduced support for
generating and serializing span events for the Opentelemetry API. This
PR uses span events to implement the records exception api:
https://opentelemetry.io/docs/specs/otel/trace/exceptions/#recording-an-exception.

With this enhancement span events will be fully supported.

## Checklist

- [x] Change(s) are motivated and described in the PR description
- [x] Testing strategy is described if automated tests are not included
in the PR
- [x] Risks are described (performance impact, potential for breakage,
maintainability)
- [x] Change is maintainable (easy to change, telemetry, documentation)
- [x] [Library release note
guidelines](https://ddtrace.readthedocs.io/en/stable/releasenotes.html)
are followed or label `changelog/no-changelog` is set
- [x] Documentation is included (in-code, generated user docs, [public
corp docs](https://github.com/DataDog/documentation/))
- [x] Backport labels are set (if
[applicable](https://ddtrace.readthedocs.io/en/latest/contributing.html#backporting))
- [x] If this PR changes the public interface, I've notified
`@DataDog/apm-tees`.

## Reviewer Checklist

- [x] Title is accurate
- [x] All changes are related to the pull request's stated goal
- [x] Description motivates each change
- [x] Avoids breaking
[API](https://ddtrace.readthedocs.io/en/stable/versioning.html#interfaces)
changes
- [x] Testing strategy adequately addresses listed risks
- [x] Change is maintainable (easy to change, telemetry, documentation)
- [x] Release note makes sense to a user of the library
- [x] Author has acknowledged and discussed the performance implications
of this PR as reported in the benchmarks PR comment
- [x] Backport labels are set in a manner that is consistent with the
[release branch maintenance
policy](https://ddtrace.readthedocs.io/en/latest/contributing.html#backporting)

Co-authored-by: Munir Abdinur <[email protected]>

Author: github-actions[bot]

ddtrace/_trace/span.py

@@ -549,16 +549,10 @@ def set_exc_info(self, exc_type, exc_val, exc_tb):
             return
 
         self.error = 1
-        self._set_exc_tags(exc_type, exc_val, exc_tb)
-
-    def _set_exc_tags(self, exc_type, exc_val, exc_tb):
-        limit = config._span_traceback_max_size
-        if limit is None:
-            limit = 30
 
         # get the traceback
         buff = StringIO()
-        traceback.print_exception(exc_type, exc_val, exc_tb, file=buff, limit=limit)
+        traceback.print_exception(exc_type, exc_val, exc_tb, file=buff, limit=config._span_traceback_max_size)
         tb = buff.getvalue()
 
         # readable version of type (e.g. exceptions.ZeroDivisionError)

ddtrace/opentelemetry/_span.py

@@ -1,3 +1,4 @@
+import traceback
 from typing import TYPE_CHECKING
 
 from opentelemetry.trace import Span as OtelSpan
@@ -8,7 +9,10 @@
 from opentelemetry.trace.span import TraceFlags
 from opentelemetry.trace.span import TraceState
 
+from ddtrace import config
 from ddtrace.constants import ERROR_MSG
+from ddtrace.constants import ERROR_STACK
+from ddtrace.constants import ERROR_TYPE
 from ddtrace.constants import SPAN_KIND
 from ddtrace.internal.compat import time_ns
 from ddtrace.internal.logger import get_logger
@@ -216,14 +220,34 @@ def set_status(self, status, description=None):
     def record_exception(self, exception, attributes=None, timestamp=None, escaped=False):
         # type: (BaseException, Optional[Attributes], Optional[int], bool) -> None
         """
-        Records the type, message, and traceback of an exception as Span attributes.
-        Note - Span Events are not currently used to record exception info.
+        Records an exception as an event
         """
         if not self.is_recording():
             return
-        self._ddspan._set_exc_tags(type(exception), exception, exception.__traceback__)
+        # Set exception attributes in a manner that is consistent with the opentelemetry sdk
+        # https://github.com/open-telemetry/opentelemetry-python/blob/v1.24.0/opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py#L998
+        # We will not set the exception.stacktrace attribute, this will reduce the size of the span event
+        attrs = {
+            "exception.type": "%s.%s" % (exception.__class__.__module__, exception.__class__.__name__),
+            "exception.message": str(exception),
+            "exception.escaped": str(escaped),
+        }
         if attributes:
-            self.set_attributes(attributes)
+            # User provided attributes must take precedence over atrrs
+            attrs.update(attributes)
+
+        # Set the error type, error message and error stacktrace tags on the span
+        self._ddspan._meta[ERROR_MSG] = attrs["exception.message"]
+        self._ddspan._meta[ERROR_TYPE] = attrs["exception.type"]
+        if "exception.stacktrace" in attrs:
+            self._ddspan._meta[ERROR_STACK] = attrs["exception.stacktrace"]
+        else:
+            self._ddspan._meta[ERROR_STACK] = "".join(
+                traceback.format_exception(
+                    type(exception), exception, exception.__traceback__, limit=config._span_traceback_max_size
+                )
+            )
+        self.add_event(name="exception", attributes=attrs, timestamp=timestamp)
 
     def __enter__(self):
         # type: () -> Span
@@ -236,9 +260,10 @@ def __exit__(self, exc_type, exc_val, exc_tb):
         """Ends Span context manager"""
         if exc_val:
             if self._record_exception:
-                self.record_exception(exc_val)
+                # Generates a span event for the exception
+                self.record_exception(exc_val, escaped=True)
             if self._set_status_on_exception:
-                # do not overwrite the status message set by record exception
+                # Set the status of to Error, this will NOT set the `error.message` tag on the span
                 self.set_status(StatusCode.ERROR)
         self.end()
 

releasenotes/notes/support-error-events-64fdce253ab0bfaf.yaml

@@ -0,0 +1,4 @@
+---
+fixes:
+  - |
+    opentelemetry: Records exceptions on spans in a manner that is consistent with the `otel specification <https://opentelemetry.io/docs/specs/otel/trace/exceptions/#recording-an-exception>`_ 

tests/opentelemetry/test_trace.py

@@ -1,3 +1,4 @@
+import mock
 import opentelemetry
 import opentelemetry.version
 import pytest
@@ -17,24 +18,31 @@ def test_otel_compatible_tracer_is_returned_by_tracer_provider():
     assert isinstance(otel_compatible_tracer, opentelemetry.trace.Tracer)
 
 
-@pytest.mark.snapshot(wait_for_num_traces=1)
-def test_otel_start_span_with_default_args(oteltracer):
-    otel_span = oteltracer.start_span("test-start-span")
+@pytest.mark.snapshot(wait_for_num_traces=1, ignores=["meta.error.stack"])
+def test_otel_start_span_record_exception(oteltracer):
+    # Avoid mocking time_ns when Span is created. This is a workaround to resolve a rate limit bug.
+    raised_span = oteltracer.start_span("test-raised-exception")
     with pytest.raises(Exception, match="Sorry Otel Span, I failed you"):
-        with opentelemetry.trace.use_span(
-            otel_span,
-            end_on_exit=False,
-            record_exception=False,
-            set_status_on_exception=False,
-        ):
-            otel_span.update_name("rename-start-span")
-            raise Exception("Sorry Otel Span, I failed you")
-
-    # set_status_on_exception is False
-    assert otel_span._ddspan.error == 0
-    # Since end_on_exit=False start_as_current_span should not call Span.end()
-    assert otel_span.is_recording()
-    otel_span.end()
+        # Ensures that the exception is recorded with the consistent timestamp for snapshot testing
+        with mock.patch("ddtrace._trace.span.time_ns", return_value=1716560261227739000):
+            with raised_span:
+                raised_span.record_exception(ValueError("Invalid Operation 1"))
+                raise Exception("Sorry Otel Span, I failed you")
+
+    with oteltracer.start_span("test-recorded-exception") as not_raised_span:
+        not_raised_span.record_exception(
+            IndexError("Invalid Operation 2"), {"exception.stuff": "thing 2"}, 1716560281337739
+        )
+        not_raised_span.record_exception(
+            Exception("Real Exception"),
+            {
+                "exception.type": "RandoException",
+                "exception.message": "MoonEar Fire!!!",
+                "exception.stacktrace": "Fake traceback",
+                "exception.details": "This is FAKE, I overwrote the real exception details",
+            },
+            1716560271237812,
+        )
 
 
 @pytest.mark.snapshot(wait_for_num_traces=1)
@@ -47,22 +55,17 @@ def test_otel_start_span_without_default_args(oteltracer):
         attributes={"start_span_tag": "start_span_val"},
         links=None,
         start_time=0,
-        record_exception=True,
-        set_status_on_exception=True,
+        record_exception=False,
+        set_status_on_exception=False,
     )
-    otel_span.update_name("rename-start-span")
     with pytest.raises(Exception, match="Sorry Otel Span, I failed you"):
-        with opentelemetry.trace.use_span(
-            otel_span,
-            end_on_exit=False,
-            record_exception=False,
-            set_status_on_exception=False,
-        ):
+        with otel_span:
+            otel_span.update_name("rename-start-span")
             raise Exception("Sorry Otel Span, I failed you")
 
     # set_status_on_exception is False
     assert otel_span._ddspan.error == 0
-    assert otel_span.is_recording()
+    assert otel_span.is_recording() is False
     assert root.is_recording()
     otel_span.end()
     root.end()

tests/snapshots/tests.opentelemetry.test_trace.test_otel_start_span_record_exception.json

@@ -0,0 +1,58 @@
+[[
+  {
+    "name": "internal",
+    "service": "",
+    "resource": "test-raised-exception",
+    "trace_id": 0,
+    "span_id": 1,
+    "parent_id": 0,
+    "type": "",
+    "error": 1,
+    "meta": {
+      "_dd.p.dm": "-0",
+      "_dd.p.tid": "6658897400000000",
+      "error.message": "Sorry Otel Span, I failed you",
+      "error.stack": "Traceback (most recent call last):\n  File \"/Users/munirabdinur/go/src/github.com/DataDog/dd-trace-py/tests/opentelemetry/test_trace.py\", line 27, in test_otel_start_span_record_exception\n    raise Exception(\"Sorry Otel Span, I failed you\")\nException: Sorry Otel Span, I failed you\n",
+      "error.type": "builtins.Exception",
+      "events": "[{\"name\": \"exception\", \"time_unix_nano\": 1716560261227739000, \"attributes\": {\"exception.type\": \"builtins.ValueError\", \"exception.message\": \"Invalid Operation 1\", \"exception.escaped\": \"False\"}}, {\"name\": \"exception\", \"time_unix_nano\": 1716560261227739000, \"attributes\": {\"exception.type\": \"builtins.Exception\", \"exception.message\": \"Sorry Otel Span, I failed you\", \"exception.escaped\": \"True\"}}]",
+      "language": "python",
+      "runtime-id": "d0950ce7bda6498183acde9036abb131"
+    },
+    "metrics": {
+      "_dd.top_level": 1,
+      "_dd.tracer_kr": 1.0,
+      "_sampling_priority_v1": 1,
+      "process_id": 71659
+    },
+    "duration": 518127750028000,
+    "start": 1716560261227739000
+  }],
+[
+  {
+    "name": "internal",
+    "service": "",
+    "resource": "test-recorded-exception",
+    "trace_id": 1,
+    "span_id": 1,
+    "parent_id": 0,
+    "type": "",
+    "error": 0,
+    "meta": {
+      "_dd.p.dm": "-0",
+      "_dd.p.tid": "6658897400000000",
+      "error.message": "MoonEar Fire!!!",
+      "error.stack": "Fake traceback",
+      "error.type": "RandoException",
+      "events": "[{\"name\": \"exception\", \"time_unix_nano\": 1716560281337739000, \"attributes\": {\"exception.type\": \"builtins.IndexError\", \"exception.message\": \"Invalid Operation 2\", \"exception.escaped\": \"False\", \"exception.stuff\": \"thing 2\"}}, {\"name\": \"exception\", \"time_unix_nano\": 1716560271237812000, \"attributes\": {\"exception.type\": \"RandoException\", \"exception.message\": \"MoonEar Fire!!!\", \"exception.escaped\": \"False\", \"exception.stacktrace\": \"Fake traceback\", \"exception.details\": \"This is FAKE, I overwrote the real exception details\"}}]",
+      "language": "python",
+      "runtime-id": "d0950ce7bda6498183acde9036abb131"
+    },
+    "metrics": {
+      "_dd.top_level": 1,
+      "_dd.tracer_kr": 1.0,
+      "_sampling_priority_v1": 1,
+      "process_id": 71659
+    },
+    "duration": 518127750240000,
+    "start": 1716560281337739000
+  }]]