Add debug log in case evaluation result is null and it shouldn't be null

Author: dudikeleti

tracer/src/Datadog.Trace/Debugger/Expressions/ExpressionEvaluationResult.cs

@@ -20,19 +20,19 @@ internal ref struct ExpressionEvaluationResult
 
     internal List<EvaluationError> Errors { get; set; }
 
-    internal bool HasError => Errors is { Count: > 0 };
+    internal readonly bool HasError => Errors is { Count: > 0 };
 
-    internal bool IsNull()
+    internal readonly bool IsNull()
     {
         return Template == null && Condition == null && Metric == null && Decorations?.Length == 0 && Errors == null;
     }
 
     internal struct DecorationResult
     {
-        public string TagName { get; set; }
+        internal string TagName { get; set; }
 
-        public string Value { get; set; }
+        internal string Value { get; set; }
 
-        public EvaluationError[] Errors { get; set; }
+        internal EvaluationError[] Errors { get; set; }
     }
 }

tracer/src/Datadog.Trace/Debugger/Expressions/ProbeInfo.cs

@@ -41,9 +41,9 @@ internal record struct ProbeInfo(
 
         internal string[] Tags { get; } = Tags;
 
-        public TargetSpan? TargetSpan { get; } = TargetSpan;
+        internal TargetSpan? TargetSpan { get; } = TargetSpan;
 
-        public CaptureLimitInfo CaptureLimitInfo { get; } = CaptureLimitInfo;
+        internal CaptureLimitInfo CaptureLimitInfo { get; } = CaptureLimitInfo;
     }
 
     internal readonly record struct CaptureLimitInfo(
@@ -52,12 +52,12 @@ internal readonly record struct CaptureLimitInfo(
         int MaxLength,
         int MaxFieldCount)
     {
-        public int MaxReferenceDepth { get; } = MaxReferenceDepth;
+        internal int MaxReferenceDepth { get; } = MaxReferenceDepth;
 
-        public int MaxCollectionSize { get; } = MaxCollectionSize;
+        internal int MaxCollectionSize { get; } = MaxCollectionSize;
 
-        public int MaxLength { get; } = MaxLength;
+        internal int MaxLength { get; } = MaxLength;
 
-        public int MaxFieldCount { get; } = MaxFieldCount;
+        internal int MaxFieldCount { get; } = MaxFieldCount;
     }
 }

tracer/src/Datadog.Trace/Debugger/Expressions/ProbeProcessor.cs

@@ -2,6 +2,7 @@
 // Unless explicitly stated otherwise all files in this repository are licensed under the Apache 2 License.
 // This product includes software developed at Datadog (https://www.datadoghq.com/). Copyright 2017 Datadog, Inc.
 // </copyright>
+
 #nullable enable
 
 using System;
@@ -349,6 +350,8 @@ private ExpressionEvaluationResult Evaluate(DebuggerSnapshotCreator snapshotCrea
 
             if (evaluationResult.IsNull())
             {
+                LogEvaluationState(snapshotCreator.MethodScopeMembers);
+
                 Log.Error("Evaluation result should not be null. Probe: {ProbeId}", ProbeInfo.ProbeId);
                 evaluationResult.Errors = new List<EvaluationError> { new() { Message = $"Evaluation result is null. Probe ID: {ProbeInfo.ProbeId}" } };
                 return evaluationResult;
@@ -390,15 +393,45 @@ private ExpressionEvaluationResult Evaluate(DebuggerSnapshotCreator snapshotCrea
             return evaluationResult;
         }
 
-        private void SetSpanDecoration(DebuggerSnapshotCreator snapshotCreator, ref bool shouldStopCapture, ExpressionEvaluationResult evaluationResult)
+        private void LogEvaluationState(MethodScopeMembers methodScopeMembers)
         {
-            if (!TryGetScope(out var scope))
+            if (_templates == null
+             && _condition == null
+             && _metric == null
+             && _spanDecorations == null)
+            {
+                return;
+            }
+
+            // this should never happen, but if it does, we want to log it for further investigation
+            Log.Error("Evaluation state error: we thought that evaluation result is null but that not true. probably we are using an incorrect version of ProbeExpressionEvaluator");
+
+            try
             {
                 if (Log.IsEnabled(LogEventLevel.Debug))
                 {
-                    Log.Debug("No active scope available, skipping span decoration. Probe: {ProbeId}", ProbeInfo.ProbeId);
+                    var instance = methodScopeMembers.InvocationTarget;
+                    var members = methodScopeMembers.Members?.Select(m => new { Name = m.Name, Type = m.Type?.FullName ?? m.Type?.Name }).ToList();
+                    string? membersAsString = null;
+                    if (members?.Any() == true)
+                    {
+                        membersAsString = string.Join(";", members);
+                    }
+
+                    Log.Error("Evaluation state error: Target Method: Type = {Type}, Name = {Name}. Method Members: {Members}", instance.Type?.FullName ?? instance.Type?.Name, instance.Name, membersAsString);
                 }
+            }
+            catch
+            {
+                // ignored
+            }
+        }
 
+        private void SetSpanDecoration(DebuggerSnapshotCreator snapshotCreator, ref bool shouldStopCapture, ExpressionEvaluationResult evaluationResult)
+        {
+            if (!TryGetScope(out var scope))
+            {
+                Log.Debug("No active scope available, skipping span decoration. Probe: {ProbeId}", ProbeInfo.ProbeId);
                 return;
             }
 
@@ -411,6 +444,11 @@ private void SetSpanDecoration(DebuggerSnapshotCreator snapshotCreator, ref bool
                 var probeIdTag = $"{DynamicPrefix}{decoration.TagName}.probe_id";
                 ISpan? targetSpan = null;
 
+                if (ProbeInfo.TargetSpan == null)
+                {
+                    Log.Error("We can't set the {Tag} tag. Probe ID: {ProbeId}, because target span is null", decoration.TagName, ProbeInfo.ProbeId);
+                }
+
                 switch (ProbeInfo.TargetSpan)
                 {
                     case TargetSpan.Root:
@@ -420,13 +458,13 @@ private void SetSpanDecoration(DebuggerSnapshotCreator snapshotCreator, ref bool
                         targetSpan = scope.Span;
                         break;
                     default:
-                        Log.Error("Invalid target span. Probe: {ProbeId}", ProbeInfo.ProbeId);
+                        Log.Error("We can't set the {Tag} tag. Probe ID: {ProbeId}, because target span {Span} is invalid", decoration.TagName, ProbeInfo.ProbeId, ProbeInfo.TargetSpan);
                         break;
                 }
 
                 if (targetSpan == null)
                 {
-                    Log.Warning("No root span or active span is available, so we can't set the {Tag} tag. Probe ID: {ProbeId}", decoration.TagName, ProbeInfo.ProbeId);
+                    Log.Warning("We can't set the {Tag} tag. Probe ID: {ProbeId}, because the chosen span {Span} is not available", decoration.TagName, ProbeInfo.ProbeId, ProbeInfo.TargetSpan);
                     continue;
                 }
 
@@ -444,7 +482,7 @@ private void SetSpanDecoration(DebuggerSnapshotCreator snapshotCreator, ref bool
                 attachedTags = true;
                 if (Log.IsEnabled(LogEventLevel.Debug))
                 {
-                    Log.Debug("Successfully attached tag {Tag} to span {Span}. ProbID={ProbeId}", decoration.TagName, targetSpan.SpanId, ProbeInfo.ProbeId);
+                    Log.Debug("Successfully attached tag {Tag} to span {Span}. ProbID: {ProbeId}", decoration.TagName, targetSpan.SpanId, ProbeInfo.ProbeId);
                 }
             }