fix(debugging): report probe build error via status messages [backport 1.17] (#6452)

Backport 7356ed5 from #6402 to 1.17.

Report probe build errors via status messages to ensure that they are
shown in the UI and the probes are marked with the `ERROR` status,
instead of `WAITING`.

## 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)

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

Author: github-actions[bot]

ddtrace/debugging/_debugger.py

@@ -245,7 +245,9 @@ def __init__(self, tracer=None):
             },
             on_full=self._on_encoder_buffer_full,
         )
-        self._probe_registry = ProbeRegistry(self.__logger__(service_name, self._encoder))
+        status_logger = self.__logger__(service_name, self._encoder)
+
+        self._probe_registry = ProbeRegistry(status_logger=status_logger)
         self._uploader = self.__uploader__(self._encoder)
         self._collector = self.__collector__(self._encoder)
         self._services = [self._uploader]
@@ -277,7 +279,7 @@ def __init__(self, tracer=None):
 
             # Register the debugger with the RCM client.
             if not remoteconfig_poller.update_product_callback("LIVE_DEBUGGING", self._on_configuration):
-                di_callback = self.__rc_adapter__(None, self._on_configuration)
+                di_callback = self.__rc_adapter__(None, self._on_configuration, status_logger=status_logger)
                 remoteconfig_poller.register("LIVE_DEBUGGING", di_callback)
 
         log.debug("%s initialized (service name: %s)", self.__class__.__name__, service_name)

ddtrace/debugging/_probe/remoteconfig.py

@@ -1,4 +1,5 @@
 import os
+import sys
 import time
 from typing import Any
 from typing import Callable
@@ -7,6 +8,8 @@
 from typing import Optional
 from typing import Type
 
+import six
+
 from ddtrace import config as tracer_config
 from ddtrace.debugging._config import di_config
 from ddtrace.debugging._expressions import dd_compile
@@ -31,6 +34,7 @@
 from ddtrace.debugging._probe.model import SpanDecorationTag
 from ddtrace.debugging._probe.model import SpanFunctionProbe
 from ddtrace.debugging._probe.model import StringTemplate
+from ddtrace.debugging._probe.status import ProbeStatusLogger
 from ddtrace.internal.logger import get_logger
 from ddtrace.internal.remoteconfig._connectors import PublisherSubscriberConnector
 from ddtrace.internal.remoteconfig._publishers import RemoteConfigPublisher
@@ -240,6 +244,10 @@ def update_args(cls, args, attribs):
         )
 
 
+class InvalidProbeConfiguration(ValueError):
+    pass
+
+
 def build_probe(attribs):
     # type: (Dict[str, Any]) -> Probe
     """
@@ -249,7 +257,7 @@ def build_probe(attribs):
         _type = attribs["type"]
         _id = attribs["id"]
     except KeyError as e:
-        raise ValueError("Invalid probe attributes: %s" % e)
+        raise InvalidProbeConfiguration("Invalid probe attributes: %s" % e)
 
     args = dict(
         probe_id=_id,
@@ -266,13 +274,23 @@ def build_probe(attribs):
     if _type == ProbeType.SPAN_DECORATION_PROBE:
         return SpanDecorationProbeFactory.build(args, attribs)
 
-    raise ValueError("Unsupported probe type: %s" % _type)
+    raise InvalidProbeConfiguration("Unsupported probe type: %s" % _type)
 
 
 @_filter_by_env_and_version
-def get_probes(config_id, config):
-    # type: (str, dict) -> Iterable[Probe]
-    return [build_probe(config)]
+def get_probes(config, status_logger):
+    # type: (dict, ProbeStatusLogger) -> Iterable[Probe]
+    try:
+        return [build_probe(config)]
+    except InvalidProbeConfiguration:
+        six.reraise(*sys.exc_info())
+    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(),
+        )
+        return []
 
 
 class ProbePollerEvent(object):
@@ -292,10 +310,11 @@ class DebuggerRemoteConfigSubscriber(RemoteConfigSubscriber):
     events that can be handled easily by the debugger.
     """
 
-    def __init__(self, data_connector, callback, name):
+    def __init__(self, data_connector, callback, name, status_logger):
         super(DebuggerRemoteConfigSubscriber, self).__init__(data_connector, callback, name)
         self._configs = {}  # type: Dict[str, Dict[str, Probe]]
         self._status_timestamp = time.time()
+        self._status_logger = status_logger
         self._next_status_update_timestamp()
 
     def _exec_callback(self, data, test_tracer=None):
@@ -342,7 +361,9 @@ def _update_probes_for_config(self, config_id, config):
         # type: (str, Any) -> None
         prev_probes = self._configs.get(config_id, {})  # type: Dict[str, Probe]
         next_probes = (
-            {probe.probe_id: probe for probe in get_probes(config_id, config)} if config not in (None, False) else {}
+            {probe.probe_id: probe for probe in get_probes(config, self._status_logger)}
+            if config not in (None, False)
+            else {}
         )  # type: Dict[str, Probe]
         log.debug("[%s][P: %s] Dynamic Instrumentation, dispatch probe events", os.getpid(), os.getppid())
         self._dispatch_probe_events(prev_probes, next_probes)
@@ -358,6 +379,6 @@ class ProbeRCAdapter(PubSub):
     __subscriber_class__ = DebuggerRemoteConfigSubscriber
     __shared_data__ = PublisherSubscriberConnector()
 
-    def __init__(self, _preprocess_results, callback):
+    def __init__(self, _preprocess_results, callback, status_logger):
         self._publisher = self.__publisher_class__(self.__shared_data__, _preprocess_results)
-        self._subscriber = self.__subscriber_class__(self.__shared_data__, callback, "DEBUGGER")
+        self._subscriber = self.__subscriber_class__(self.__shared_data__, callback, "DEBUGGER", status_logger)

releasenotes/notes/fix-debugger-status-log-probe-build-errors-54bf9ea91aaff5db.yaml

@@ -0,0 +1,6 @@
+---
+fixes:
+  - |
+    dynamic instrumentation: ensure that probes that fail to be instrumented
+    because of invalid conditions/expressions are reported with status ``ERROR``
+    in the UI.

tests/debugging/probe/test_remoteconfig.py

@@ -2,6 +2,7 @@
 from time import sleep
 from uuid import uuid4
 
+import mock
 import pytest
 
 from ddtrace.debugging._config import di_config
@@ -10,6 +11,7 @@
 from ddtrace.debugging._probe.model import LogProbeMixin
 from ddtrace.debugging._probe.model import Probe
 from ddtrace.debugging._probe.model import ProbeType
+from ddtrace.debugging._probe.remoteconfig import InvalidProbeConfiguration
 from ddtrace.debugging._probe.remoteconfig import ProbePollerEvent
 from ddtrace.debugging._probe.remoteconfig import ProbeRCAdapter
 from ddtrace.debugging._probe.remoteconfig import _filter_by_env_and_version
@@ -25,7 +27,7 @@ def __init__(self, *args, **kwargs):
         self.probes = {}
 
     @_filter_by_env_and_version
-    def get_probes(self, _id, _conf):
+    def get_probes(self, _conf, status_logger):
         return list(self.probes.values())
 
     def add_probes(self, probes):
@@ -58,6 +60,23 @@ def mock_config():
         rc.get_probes = original_get_probes
 
 
+@pytest.fixture
+def mock_config_exc():
+    import ddtrace.debugging._probe.remoteconfig as rc
+
+    original_build_probe = rc.build_probe
+
+    def build_probe(config):
+        raise Exception("test exception")
+
+    try:
+        rc.build_probe = build_probe
+
+        yield mock_config
+    finally:
+        rc.build_probe = original_build_probe
+
+
 @pytest.mark.parametrize(
     "env,version,expected",
     [
@@ -106,7 +125,7 @@ def callback(e, ps, *args, **kwargs):
             ]
         )
 
-        adapter = ProbeRCAdapter(None, callback)
+        adapter = ProbeRCAdapter(None, callback, status_logger=None)
         remoteconfig_poller.register("TEST", adapter, skip_enabled=True)
         adapter.append_and_publish({"test": random.randint(0, 11111111)}, "", config_metadata())
         remoteconfig_poller._poll_data()
@@ -127,7 +146,7 @@ def validate_events(expected):
     old_interval = di_config.diagnostics_interval
     di_config.diagnostics_interval = 0.5
     try:
-        adapter = ProbeRCAdapter(None, cb)
+        adapter = ProbeRCAdapter(None, cb, status_logger=None)
         # Wait to allow the next call to the adapter to generate a status event
         remoteconfig_poller.register("TEST", adapter, skip_enabled=True)
         adapter.append_and_publish(
@@ -181,7 +200,7 @@ def validate_events(expected):
     old_interval = di_config.diagnostics_interval
     di_config.diagnostics_interval = 0.5
     try:
-        adapter = ProbeRCAdapter(None, cb)
+        adapter = ProbeRCAdapter(None, cb, status_logger=None)
         # Wait to allow the next call to the adapter to generate a status event
         remoteconfig_poller.register("TEST", adapter, skip_enabled=True)
         adapter.append(
@@ -287,7 +306,7 @@ def callback(e, ps, *args, **kwargs):
     old_interval = di_config.diagnostics_interval
     di_config.diagnostics_interval = 0.5
     try:
-        adapter = ProbeRCAdapter(None, callback)
+        adapter = ProbeRCAdapter(None, callback, status_logger=None)
         remoteconfig_poller.register("TEST2", adapter, skip_enabled=True)
         adapter.append_and_publish({"test": 2}, "", metadata)
         remoteconfig_poller._poll_data()
@@ -341,7 +360,7 @@ def validate_events(expected):
     old_interval = di_config.diagnostics_interval
     di_config.diagnostics_interval = 0.5
     try:
-        adapter = ProbeRCAdapter(None, cb)
+        adapter = ProbeRCAdapter(None, cb, status_logger=mock.Mock())
         # Wait to allow the next call to the adapter to generate a status event
         remoteconfig_poller.register("TEST", adapter, skip_enabled=True)
         adapter.append_and_publish(
@@ -412,7 +431,7 @@ def validate_events(expected):
         # testing two things:
         #  1. after sleep 0.5 probe status should report 2 probes
         #  2. bad config raises ValueError
-        with pytest.raises(ValueError):
+        with pytest.raises(InvalidProbeConfiguration):
             adapter.append_and_publish({}, "", config_metadata("not-supported"))
             remoteconfig_poller._poll_data()
 
@@ -537,7 +556,7 @@ def cb(e, ps):
     old_interval = di_config.diagnostics_interval
     di_config.diagnostics_interval = 0.5
     try:
-        adapter = ProbeRCAdapter(None, cb)
+        adapter = ProbeRCAdapter(None, cb, None)
         # Wait to allow the next call to the adapter to generate a status event
         remoteconfig_poller.register("TEST", adapter, skip_enabled=True)
         sleep(0.5)
@@ -570,3 +589,28 @@ def cb(e, ps):
         ]
     finally:
         di_config.diagnostics_interval = old_interval
+
+
+def test_expression_compilation_error(remote_config_worker, mock_config_exc):
+    events = []
+
+    def cb(e, ps):
+        events.append((e, frozenset([p.probe_id if isinstance(p, Probe) else p for p in ps])))
+
+    metadata = config_metadata()
+    old_interval = di_config.diagnostics_interval
+    di_config.diagnostics_interval = 0.5
+    try:
+        status_logger = mock.Mock()
+        adapter = ProbeRCAdapter(None, cb, status_logger=status_logger)
+        # Wait to allow the next call to the adapter to generate a status event
+        remoteconfig_poller.register("TEST", adapter, skip_enabled=True)
+        sleep(0.5)
+        adapter.append_and_publish({"id": "error", "version": 0}, "", metadata)
+        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]["probe"].probe_id == "error"
+    finally:
+        di_config.diagnostics_interval = old_interval