fix(debugging): report error info on every probe error [backport 1.20] (#7187)

Backport a59919e from #7095 to 1.20.

We make sure that we always have error information whenever an error
occurs while handing or instrumenting a probe. Previously, we only added
the information if a Python exception was available.

## 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] Risk is outlined (performance impact, potential for breakage,
maintainability, etc).
- [x] Change is maintainable (easy to change, telemetry, documentation).
- [x] [Library release note
guidelines](https://ddtrace.readthedocs.io/en/stable/releasenotes.html)
are followed. If no release note is required, add label
`changelog/no-changelog`.
- [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))

## Reviewer Checklist

- [x] Title is accurate.
- [x] No unnecessary changes are introduced.
- [x] Description motivates each change.
- [x] Avoids breaking
[API](https://ddtrace.readthedocs.io/en/stable/versioning.html#interfaces)
changes unless absolutely necessary.
- [x] Testing strategy adequately addresses listed risk(s).
- [x] Change is maintainable (easy to change, telemetry, documentation).
- [x] Release note makes sense to a user of the library.
- [x] Reviewer has explicitly 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)
- [x] If this PR touches code that signs or publishes builds or
packages, or handles credentials of any kind, I've requested a review
from `@DataDog/security-design-and-guidance`.
- [x] This PR doesn't touch any of that.

Co-authored-by: Gabriele N. Tornetta <[email protected]>

Author: github-actions[bot]

ddtrace/debugging/_debugger.py

@@ -458,7 +458,7 @@ def _probe_injection_hook(self, module):
                     origin(module),
                 )
                 log.error(message)
-                self._probe_registry.set_error(probe, message)
+                self._probe_registry.set_error(probe, "NoFunctionsAtLine", message)
                 continue
             for function in (cast(FullyNamedWrappedFunction, _) for _ in functions):
                 probes_for_function[function].append(cast(LineProbe, probe))
@@ -470,7 +470,7 @@ def _probe_injection_hook(self, module):
 
             for probe in probes:
                 if probe.probe_id in failed:
-                    self._probe_registry.set_error(probe, "Failed to inject")
+                    self._probe_registry.set_error(probe, "InjectionFailure", "Failed to inject")
                 else:
                     self._probe_registry.set_installed(probe)
 
@@ -497,7 +497,7 @@ def _inject_probes(self, probes):
                 log.error(
                     "Cannot inject probe %s: source file %s cannot be resolved", probe.probe_id, probe.source_file
                 )
-                self._probe_registry.set_error(probe, "Source file location cannot be resolved")
+                self._probe_registry.set_error(probe, "NoSourceFile", "Source file location cannot be resolved")
                 continue
 
         for source in {probe.source_file for probe in probes if probe.source_file is not None}:
@@ -508,7 +508,10 @@ def _inject_probes(self, probes):
                 for probe in probes:
                     if probe.source_file != source:
                         continue
-                    self._probe_registry.set_exc_info(probe, exc_info)
+                    exc_type, exc, _ = exc_info
+                    self._probe_registry.set_error(
+                        probe, exc_type.__name__ if exc_type is not None else type(exc).__name__, str(exc)
+                    )
                 log.error("Cannot register probe injection hook on source '%s'", source, exc_info=True)
 
     def _eject_probes(self, probes_to_eject):
@@ -578,7 +581,7 @@ def _probe_wrapping_hook(self, module):
                     probe.func_qname,
                     probe.module,
                 )
-                self._probe_registry.set_error(probe, message)
+                self._probe_registry.set_error(probe, "NoFunctionInModule", message)
                 log.error(message)
                 continue
 
@@ -614,7 +617,10 @@ def _wrap_functions(self, probes):
                 assert probe.module is not None  # nosec
                 self.__watchdog__.register_module_hook(probe.module, self._probe_wrapping_hook)
             except Exception:
-                self._probe_registry.set_exc_info(probe, sys.exc_info())
+                exc_type, exc, _ = sys.exc_info()
+                self._probe_registry.set_error(
+                    probe, exc_type.__name__ if exc_type is not None else type(exc).__name__, str(exc)
+                )
                 log.error("Cannot register probe wrapping hook on module '%s'", probe.module, exc_info=True)
 
     def _unwrap_functions(self, probes):

ddtrace/debugging/_probe/registry.py

@@ -8,34 +8,29 @@
 from ddtrace.debugging._probe.model import ProbeLocationMixin
 from ddtrace.debugging._probe.status import ProbeStatusLogger
 from ddtrace.internal import forksafe
-from ddtrace.internal.compat import ExcInfoType
 from ddtrace.internal.logger import get_logger
 
 
 logger = get_logger(__name__)
 
 
 class ProbeRegistryEntry(object):
-
-    __slots__ = ("probe", "installed", "exc_info", "message")
+    __slots__ = ("probe", "installed", "error_type", "message")
 
     def __init__(self, probe):
         # type: (Probe) -> None
         self.probe = probe
         self.installed = False
-        self.exc_info = None  # type: Optional[ExcInfoType]
+        self.error_type = None  # type: Optional[str]
         self.message = None  # type: Optional[str]
 
     def set_installed(self):
         # type: () -> None
         self.installed = True
 
-    def set_exc_info(self, exc_info):
-        # type: (ExcInfoType) -> None
-        self.exc_info = exc_info
-
-    def set_message(self, message):
-        # type: (str) -> None
+    def set_error(self, error_type, message):
+        # type: (str, str) -> None
+        self.error_type = error_type
         self.message = message
 
     def update(self, probe):
@@ -83,7 +78,11 @@ def register(self, *probes):
 
                 location = _get_probe_location(probe)
                 if location is None:
-                    self.set_error(probe, "Unable to resolve location information for probe {}".format(probe.probe_id))
+                    self.set_error(
+                        probe,
+                        "UnresolvedLocation",
+                        "Unable to resolve location information for probe {}".format(probe.probe_id),
+                    )
                     continue
 
                 self._pending[location].append(probe)
@@ -111,28 +110,20 @@ def set_installed(self, probe):
 
             self.logger.installed(probe)
 
-    def set_exc_info(self, probe, exc_info):
-        # type: (Probe, ExcInfoType) -> None
-        """Set the installed flag for a probe."""
-        with self._lock:
-            self[probe.probe_id].set_exc_info(exc_info)
-            self.logger.error(probe, exc_info=exc_info)
-
-    def set_error(self, probe, message):
-        # type: (Probe, str) -> None
+    def set_error(self, probe, error_type, message):
+        # type: (Probe, str, str) -> None
         """Set the error message for a probe."""
         with self._lock:
-            self[probe.probe_id].set_message(message)
-            self.logger.error(probe, message)
+            self[probe.probe_id].set_error(error_type, message)
+            self.logger.error(probe, (error_type, message))
 
     def _log_probe_status_unlocked(self, entry):
         # type: (ProbeRegistryEntry) -> None
         if entry.installed:
             self.logger.installed(entry.probe)
-        elif entry.exc_info:
-            self.logger.error(entry.probe, exc_info=entry.exc_info)
-        elif entry.message:
-            self.logger.error(entry.probe, message=entry.message)
+        elif entry.error_type:
+            assert entry.message is not None, entry  # nosec
+            self.logger.error(entry.probe, error=(entry.error_type, entry.message))
         else:
             self.logger.received(entry.probe)
 

ddtrace/debugging/_probe/remoteconfig.py

@@ -288,8 +288,7 @@ def get_probes(config, status_logger):
     except Exception as e:
         status_logger.error(
             probe=Probe(probe_id=config["id"], version=config["version"], tags={}),
-            message=str(e),
-            exc_info=sys.exc_info(),
+            error=(type(e).__name__, str(e)),
         )
         return []
 

ddtrace/debugging/_probe/status.py

@@ -10,25 +10,26 @@
 from ddtrace.debugging._encoding import add_tags
 from ddtrace.debugging._metrics import metrics
 from ddtrace.debugging._probe.model import Probe
-from ddtrace.debugging._signal import utils
 from ddtrace.internal import runtime
-from ddtrace.internal.compat import ExcInfoType
 from ddtrace.internal.logger import get_logger
 
 
 log = get_logger(__name__)
 meter = metrics.get_meter("probe.status")
 
 
+ErrorInfo = Tuple[str, str]
+
+
 class ProbeStatusLogger(object):
     def __init__(self, service, encoder):
         # type: (str, BufferedEncoder) -> None
         self._service = service
         self._encoder = encoder
         self._retry_queue = deque()  # type: deque[Tuple[str, float]]
 
-    def _payload(self, probe, status, message, timestamp, exc_info=None):
-        # type: (Probe, str, str, float, Optional[ExcInfoType]) -> str
+    def _payload(self, probe, status, message, timestamp, error=None):
+        # type: (Probe, str, str, float, Optional[ErrorInfo]) -> str
         payload = {
             "service": self._service,
             "timestamp": int(timestamp * 1e3),  # milliseconds
@@ -46,19 +47,17 @@ def _payload(self, probe, status, message, timestamp, exc_info=None):
 
         add_tags(payload)
 
-        if exc_info is not None:
-            exc_type, exc, tb = exc_info
-            assert exc_type is not None and tb is not None, exc_info  # nosec
+        if error is not None:
+            error_type, message = error
             payload["debugger"]["diagnostics"]["exception"] = {  # type: ignore[index]
-                "type": exc_type.__name__,
-                "message": str(exc),
-                "stacktrace": utils.capture_stack(tb.tb_frame),
+                "type": error_type,
+                "message": message,
             }
 
         return json.dumps(payload)
 
-    def _write(self, probe, status, message, exc_info=None):
-        # type: (Probe, str, str, Optional[ExcInfoType]) -> None
+    def _write(self, probe, status, message, error=None):
+        # type: (Probe, str, str, Optional[ErrorInfo]) -> None
         if self._retry_queue:
             meter.distribution("backlog.size", len(self._retry_queue))
 
@@ -80,7 +79,7 @@ def _write(self, probe, status, message, exc_info=None):
                     meter.increment("backlog.buffer_full")
                     return
 
-            payload = self._payload(probe, status, message, now, exc_info)
+            payload = self._payload(probe, status, message, now, error)
 
             try:
                 self._encoder.put(payload)
@@ -108,13 +107,6 @@ def installed(self, probe, message=None):
             message or "Probe %s instrumented correctly" % probe.probe_id,
         )
 
-    def error(self, probe, message=None, exc_info=None):
-        # type: (Probe, Optional[str], Optional[ExcInfoType]) -> None
-        if message is None and exc_info is None:
-            raise ValueError("Either message or exc_info must be provided")
-
-        if exc_info is not None and message is None:
-            _, exc, _ = exc_info
-            message = "Probe %s instrumentation failed: %r" % (probe.probe_id, exc)
-
-        self._write(probe, "ERROR", message, exc_info)  # type: ignore[arg-type]
+    def error(self, probe, error=None):
+        # type: (Probe, Optional[ErrorInfo]) -> None
+        self._write(probe, "ERROR", "Failed to instrument probe %s" % probe.probe_id, error)

releasenotes/notes/fix-debugger-probe-error-details-c2650877a6dae670.yaml

@@ -0,0 +1,5 @@
+---
+fixes:
+  - |
+   dynamic instrumentation: fix an issue that caused the probe instrumentation
+   error details from being reported for visualization in the UI.

tests/debugging/probe/test_registry.py

@@ -62,14 +62,18 @@ def test_registry_location_error():
     assert status_logger.queue == [
         {
             "service": "test",
-            "message": "Unable to resolve location information for probe 42",
+            "message": "Failed to instrument probe 42",
             "ddsource": "dd_debugger",
             "debugger": {
                 "diagnostics": {
                     "probeId": 42,
                     "probeVersion": 0,
                     "runtimeId": runtime.get_runtime_id(),
                     "status": "ERROR",
+                    "exception": {
+                        "type": "UnresolvedLocation",
+                        "message": "Unable to resolve location information for probe 42",
+                    },
                 }
             },
         }

tests/debugging/probe/test_remoteconfig.py

@@ -604,7 +604,7 @@ def cb(e, ps):
         remoteconfig_poller._poll_data()
 
         status_logger.error.assert_called_once()
-        assert status_logger.error.call_args[1]["message"] == "test exception"
+        assert status_logger.error.call_args[1]["error"] == ("Exception", "test exception")
         assert status_logger.error.call_args[1]["probe"].probe_id == "error"
     finally:
         di_config.diagnostics_interval = old_interval

tests/debugging/probe/test_status.py

@@ -69,19 +69,18 @@ def test_probe_status_error():
         line=36,
         condition=None,
     )
-    message = "Probe %s installed" % probe.probe_id
 
     try:
         raise RuntimeError("Test error")
     except Exception:
-        status_logger.error(probe, message, exc_info=sys.exc_info())
+        exc_type, exc, _ = sys.exc_info()
+        status_logger.error(probe, (exc_type.__name__, str(exc)))
 
     (entry,) = status_logger.queue
-    assert entry["message"] == message
+    assert entry["message"] == "Failed to instrument probe probe-instance-method"
     assert entry["debugger"]["diagnostics"]["probeId"] == probe.probe_id
     assert entry["debugger"]["diagnostics"]["status"] == "ERROR"
 
     exc = entry["debugger"]["diagnostics"]["exception"]
     assert exc["type"] == "RuntimeError"
     assert exc["message"] == "Test error"
-    assert exc["stacktrace"][0]["function"] == "test_probe_status_error"