chore: add debug logs to sampling rules (#14549)

Add logs to sampling rules to more easily debug sampling mechanism and
sampling rate, especially in cases where the sampling rules may get
reset / recreated.

## Checklist
- [x] PR author has checked that all the criteria below are met
- The PR description includes an overview of the change
- The PR description articulates the motivation for the change
- The change includes tests OR the PR description describes a testing
strategy
- The PR description notes risks associated with the change, if any
- Newly-added code is easy to change
- The change follows the [library release note
guidelines](https://ddtrace.readthedocs.io/en/stable/releasenotes.html)
- The change includes or references documentation updates if necessary
- Backport labels are set (if
[applicable](https://ddtrace.readthedocs.io/en/latest/contributing.html#backporting))

## Reviewer Checklist
- [ ] Reviewer has checked that all the criteria below are met 
- Title is accurate
- All changes are related to the pull request's stated goal
- Avoids breaking
[API](https://ddtrace.readthedocs.io/en/stable/versioning.html#interfaces)
changes
- Testing strategy adequately addresses listed risks
- Newly-added code is easy to change
- Release note makes sense to a user of the library
- If necessary, author has acknowledged and discussed the performance
implications of this PR as reported in the benchmarks PR comment
- 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: Brett Langdon <brett.langdon@datadoghq.com>

Author: quinna-h

ddtrace/_trace/processor/__init__.py

@@ -19,6 +19,7 @@
 from ddtrace.internal.constants import HIGHER_ORDER_TRACE_ID_BITS
 from ddtrace.internal.constants import LAST_DD_PARENT_ID_KEY
 from ddtrace.internal.constants import MAX_UINT_64BITS
+from ddtrace.internal.constants import SAMPLING_DECISION_TRACE_TAG_KEY
 from ddtrace.internal.constants import SamplingMechanism
 from ddtrace.internal.logger import get_logger
 from ddtrace.internal.rate_limiter import RateLimiter
@@ -280,7 +281,7 @@ class SpanAggregator(SpanProcessor):
     SPAN_FINISH_DEBUG_MESSAGE = (
         "Encoding %d spans. Spans processed: %d. Spans dropped by trace processors: %d. Unfinished "
         "spans remaining in the span aggregator: %d. (trace_id: %d) (top level span: name=%s) "
-        "(partial flush triggered: %s)"
+        "(sampling_priority: %s) (sampling_mechanism: %s) (partial flush triggered: %s)"
     )
 
     SPAN_START_DEBUG_MESSAGE = "Starting span: %s, trace has %d spans in the span aggregator"
@@ -390,6 +391,11 @@ def on_span_finish(self, span: Span) -> None:
                 log.error("error applying processor %r to trace %d", tp, span.trace_id, exc_info=True)
 
         if spans:
+            # Get sampling information from the root span
+            root_span = spans[0]._local_root
+            sampling_priority = root_span.context.sampling_priority
+            sampling_mechanism = root_span.context._meta.get(SAMPLING_DECISION_TRACE_TAG_KEY, "None")
+
             log.debug(
                 self.SPAN_FINISH_DEBUG_MESSAGE,
                 len(spans),
@@ -398,6 +404,8 @@ def on_span_finish(self, span: Span) -> None:
                 num_buffered - num_finished,
                 spans[0].trace_id,
                 spans[0].name,
+                sampling_priority,
+                sampling_mechanism,
                 should_partial_flush,
             )
             self.writer.write(spans)

ddtrace/_trace/product.py

@@ -182,7 +182,12 @@ def _apply_config_change(config_name, config_value, dd_config):
 
     if config_name == "_trace_sampling_rules":
         tracer._sampler.set_sampling_rules(config_value)
-        log.debug("Updated tracer sampling rules via remote_config: %s", config_value)
+        log.debug(
+            "Updated tracer sampler (id: %s, rules: %s) sampling rules via remote_config: %s.",
+            id(tracer._sampler),
+            tracer._sampler.rules,
+            config_value,
+        )
     elif config_name == "tags":
         tracer._tags = (config_value or {}).copy()
         log.debug("Updated tracer tags via remote_config: %s", tracer._tags)

ddtrace/_trace/sampler.py

@@ -82,7 +82,7 @@ class DatadogSampler:
 
     SAMPLE_DEBUG_MESSAGE = (
         "Sampling decision applied to %s: sampled=%s sample_rate=%s sampling_mechanism=%s "
-        "matched_trace_sampling_rule=%s agent_sampled=%s"
+        "matched_trace_sampling_rule=%s agent_sampled=%s rules=%s sampler_id=%s"
     )
 
     def __init__(
@@ -197,7 +197,9 @@ def sample(self, span: Span) -> bool:
             sample_rate,
             sampling_mechanism,
             matched_rule,
-            agent_sampler is not None,
+            str(agent_sampler) if agent_sampler is not None else "None",
+            str(self.rules) if self.rules is not None else "None",
+            id(self),
         )
         return sampled
 

releasenotes/notes/add-debug-logs-sampling-2b163de7c992fe0b.yaml

@@ -0,0 +1,4 @@
+---
+other:
+  - |
+    sampling: Add more debug logs to help debug sampling issues.

tests/integration/test_integration.py

@@ -775,13 +775,15 @@ def test_partial_flush_log():
             mock.call(
                 "Encoding %d spans. Spans processed: %d. Spans dropped by trace processors: %d. Unfinished "
                 "spans remaining in the span aggregator: %d. (trace_id: %d) (top level span: name=%s) "
-                "(partial flush triggered: %s)",
+                "(sampling_priority: %s) (sampling_mechanism: %s) (partial flush triggered: %s)",
                 2,
                 3,
                 0,
                 1,
                 t_id,
                 "2",
+                1,
+                "-0",
                 True,
             ),
         ]

tests/internal/test_settings.py

@@ -647,7 +647,7 @@ def test_remoteconfig_debug_logging():
         }
 
         for _ in range(3):
-            # Attempt to set the same RC Configurations multiple times. This mimicks the behavior
+            # Attempt to set the same RC Configurations multiple times. This mimics the behavior
             # of the agent where all the current RC configurations are returned periodically.
             call_apm_tracing_rc(
                 _base_rc_config(rc_configs),
@@ -656,7 +656,12 @@ def test_remoteconfig_debug_logging():
     # Ensure APM Tracing Remote Config debug logs are generated
     expected_logs = [
         # Tracer configurations are only updated once (calls with duplicate values should be ignored)
-        mock.call("Updated tracer sampling rules via remote_config: %s", '[{"sample_rate": 0.3}]'),
+        mock.call(
+            "Updated tracer sampler (id: %s, rules: %s) sampling rules via remote_config: %s.",
+            mock.ANY,
+            mock.ANY,
+            '[{"sample_rate": 0.3}]',
+        ),
         mock.call("Updated tracer tags via remote_config: %s", {"team": "onboarding"}),
         mock.call("Tracing disabled via remote_config. Config: %s Value: %s", "_tracing_enabled", False),
         mock.call(