Introduce a fhirpath debug tracer

src/Hl7.Fhir.Base/FhirPath/DiagnosticsDebugTracer.cs

@@ -0,0 +1,157 @@
+/*
+ * Copyright (c) 2015, Firely (info@fire.ly) and contributors
+ * See the file CONTRIBUTORS for details.
+ *
+ * This file is licensed under the BSD 3-Clause license
+ * available at https://raw.githubusercontent.com/FirelyTeam/firely-net-sdk/master/LICENSE
+ */
+
+#nullable enable
+
+using Hl7.Fhir.ElementModel;
+using Hl7.FhirPath.Expressions;
+using System;
+using System.Collections.Generic;
+using System.Diagnostics;
+using System.Linq;
+
+namespace Hl7.FhirPath
+{
+
+    public class DiagnosticsDebugTracer : IDebugTracer
+    {
+        public void TraceCall(
+            Expression expr,
+            int contextId,
+            IEnumerable<ITypedElement>? focus,
+            IEnumerable<ITypedElement>? thisValue,
+            ITypedElement? index,
+            IEnumerable<ITypedElement> totalValue,
+            IEnumerable<ITypedElement> result,
+            IEnumerable<KeyValuePair<string, IEnumerable<ITypedElement>>> variables)
+        {
+            DiagnosticsDebugTracer.DebugTraceCall(expr, contextId, focus, thisValue, index, totalValue, result, variables);
+        }
+
+        public static void DebugTraceCall(
+            Expression expr,
+            int contextId,
+            IEnumerable<ITypedElement>? focus,
+            IEnumerable<ITypedElement>? thisValue,
+            ITypedElement? index,
+            IEnumerable<ITypedElement> totalValue,
+            IEnumerable<ITypedElement> result,
+            IEnumerable<KeyValuePair<string, IEnumerable<ITypedElement>>> variables)
+        {
+            string exprName;
+
+            switch (expr)
+            {
+                case IdentifierExpression _:
+                    return;
+
+                case ConstantExpression ce:
+                    Trace.WriteLine($"{expr.Location.LineNumber},{expr.Location.LinePosition},constant (ctx.id: {contextId})");
+                    exprName = "constant";
+                    break;
+
+                case ChildExpression child:
+                    Trace.WriteLine($"{expr.Location.LineNumber},{expr.Location.LinePosition},{child.ChildName} (ctx.id: {contextId})");
+                    exprName = child.ChildName;
+                    break;
+
+                case IndexerExpression _:
+                    Trace.WriteLine($"{expr.Location.LineNumber},{expr.Location.LinePosition},[] (ctx.id: {contextId})");
+                    exprName = "[]";
+                    break;
+
+                case UnaryExpression ue:
+                    Trace.WriteLine($"{expr.Location.LineNumber},{expr.Location.LinePosition},{ue.Op} (ctx.id: {contextId})");
+                    exprName = ue.Op;
+                    break;
+
+                case BinaryExpression be:
+                    Trace.WriteLine($"{expr.Location.LineNumber},{expr.Location.LinePosition},{be.Op} (ctx.id: {contextId})");
+                    exprName = be.Op;
+                    break;
+
+                case FunctionCallExpression fe:
+                    Trace.WriteLine($"{expr.Location.LineNumber},{expr.Location.LinePosition},{fe.FunctionName} (ctx.id: {contextId})");
+                    exprName = fe.FunctionName;
+                    break;
+
+                case NewNodeListInitExpression _:
+                    Trace.WriteLine($"{expr.Location.LineNumber},{expr.Location.LinePosition},{{}} (empty) (ctx.id: {contextId})");
+                    exprName = "{}";
+                    break;
+
+                case AxisExpression ae:
+                    if (ae.AxisName == "that")
+                        return;
+                    Trace.WriteLine($"{expr.Location.LineNumber},{expr.Location.LinePosition},${ae.AxisName} (ctx.id: {contextId})");
+                    exprName = "$" + ae.AxisName;
+                    break;
+
+                case VariableRefExpression ve:
+                    Trace.WriteLine($"{expr.Location.LineNumber},{expr.Location.LinePosition},%{ve.Name} (ctx.id: {contextId})");
+                    exprName = "%" + ve.Name;
+                    break;
+
+                default:
+                    exprName = expr.GetType().Name;
+#if DEBUG
+                    Debugger.Break();
+#endif
+                    throw new Exception($"Unknown expression type: {expr.GetType().Name} (ctx.id: {contextId})");
+                    // Trace.WriteLine($"Evaluated: {expr} results: {result.Count()}");
+            }
+
+            if (result != null)
+            {
+                foreach (var item in result)
+                {
+                    DebugTraceValue($"{exprName} »", item);
+                }
+            }
+
+            if (focus != null)
+            {
+                foreach (var item in focus)
+                {
+                    DebugTraceValue($"$focus", item);
+                }
+            }
+
+            if (index != null)
+            {
+                DebugTraceValue("$index", index);
+            }
+
+            if (thisValue != null)
+            {
+                foreach (var item in thisValue)
+                {
+                    DebugTraceValue("$this", item);
+                }
+            }
+
+            if (totalValue != null)
+            {
+                foreach (var item in totalValue)
+                {
+                    DebugTraceValue($"{exprName} »", item);
+                }
+            }
+        }
+
+        private static void DebugTraceValue(string exprName, ITypedElement? item)
+        {
+            if (item == null)
+                return; // possible with a null focus to kick things off
+            if (item.Location == "@primitivevalue@" || item.Location == "@QuantityAsPrimitiveValue@")
+                Trace.WriteLine($"  {exprName}:\t{item.Value}\t({item.InstanceType})");
+            else
+                Trace.WriteLine($"  {exprName}:\t{item.Value}\t({item.InstanceType})\t{item.Location}");
+        }
+    }
+}

src/Hl7.Fhir.Base/FhirPath/EvaluationContext.cs

@@ -11,7 +11,9 @@ public class EvaluationContext
     [Obsolete("This method does not initialize any members and will be removed in a future version. Use the empty constructor instead.")]
     public static EvaluationContext CreateDefault() => new();
 
-
+    private int ClosuresCreated { get; set; } = 0;
+    internal int IncrementClosuresCreatedCount() => ClosuresCreated++;
+
     public EvaluationContext()
     {
         // no defaults yet
@@ -35,13 +37,13 @@ public EvaluationContext(ITypedElement? resource, ITypedElement? rootResource)
         Resource = resource;
         RootResource = rootResource ?? resource;
     }
-        
+
     [Obsolete("%resource and %rootResource are inferred from scoped nodes by the evaluator. If you do not have access to a scoped node, or if you wish to explicitly override this behaviour, use the EvaluationContext.WithResourceOverrides() method. Environment can be set explicitly after construction of the base context")]
     public EvaluationContext(ITypedElement? resource, ITypedElement? rootResource, IDictionary<string, IEnumerable<ITypedElement>> environment) : this(resource, rootResource)
     {
         Environment = environment;
     }
-    
+
     /// <summary>
     /// The data represented by <c>%rootResource</c>.
     /// </summary>
@@ -61,6 +63,11 @@ public EvaluationContext(ITypedElement? resource, ITypedElement? rootResource, I
     /// A delegate that handles the output for the <c>trace()</c> function.
     /// </summary>
     public Action<string?, IEnumerable<ITypedElement>>? Tracer { get; set; }
+
+    /// <summary>
+    /// Gets or sets the tracer used for capturing debug information during evaluation
+    /// </summary>
+    public IDebugTracer? DebugTracer { get; set; }
 }
 
 public static class EvaluationContextExtensions

src/Hl7.Fhir.Base/FhirPath/Expressions/Closure.cs

@@ -1,7 +1,7 @@
-/* 
+/*
  * Copyright (c) 2015, Firely (info@fire.ly) and contributors
  * See the file CONTRIBUTORS for details.
- * 
+ *
  * This file is licensed under the BSD 3-Clause license
  * available at https://raw.githubusercontent.com/FirelyTeam/firely-net-sdk/master/LICENSE
  */
@@ -17,44 +17,86 @@ namespace Hl7.FhirPath.Expressions
 {
     internal class Closure
     {
-        public Closure()
+        internal int Id { get; private set; }
+
+        public Closure(EvaluationContext ctx)
+        {
+            EvaluationContext = ctx;
+            Id = ctx.IncrementClosuresCreatedCount();
+            _debugTracerActive = ctx.DebugTracer != null;
+        }
+
+        public Closure(Closure parent, EvaluationContext ctx)
+        {
+            Parent = parent;
+            EvaluationContext = ctx;
+            Id = ctx.IncrementClosuresCreatedCount();
+            _debugTracerActive = ctx.DebugTracer != null;
+        }
+
+        /// <summary>
+        /// When the debug/trace is enabled this property is used to record the focus of the closure.
+        /// <br/>VALUE IS NOT USED OUTSIDE DEBUG - without debug/tracer, the value is not consistent.
+        /// </summary>
+        /// <remarks>
+        /// It is set in the delegate produced for each node by the evaluator visitor.
+        /// The debug tracer will reset the focus in the closure after calling the delegate it's wrapping.
+        /// ensuring that argument evaluation doesn't impact the focus logged in the debug trace in other
+        /// calls.
+        /// </remarks>
+        public IEnumerable<ITypedElement> focus
         {
+            get
+            {
+                if (!_debugTracerActive)
+                    return ElementNode.EmptyList;
+                return _focus;
+            }
+            set
+            {
+                if (!_debugTracerActive)
+                    return;
+                _focus = value;
+            }
         }
 
+        private IEnumerable<ITypedElement> _focus;
+        private bool _debugTracerActive = false;
+
         public EvaluationContext EvaluationContext { get; private set; }
 
         public static Closure Root(ITypedElement root, EvaluationContext ctx = null)
         {
             var newContext = ctx ?? new EvaluationContext();
-            
+
             var node = root as ScopedNode;
-            
+
             newContext.Resource ??= node != null // if the value has been manually set, we do nothing. Otherwise, if the root is a scoped node:
                 ? getResourceFromNode(node) // we infer the resource from the scoped node
                 : (root?.Definition?.IsResource is true // if we do not have a scoped node, we see if this is even a resource to begin with
                     ? root // if it is, we use the root as the resource
                     : null // if not, this breaks the spec in every way (but we will still continue, hopefully we do not need %resource or %rootResource)
-                ); 
-            
+                );
+
             // Same thing, but we copy the resource into the root resource if we cannot infer it from the node.
-            newContext.RootResource ??= node != null 
-                ? getRootResourceFromNode(node) 
-                : newContext.Resource; 
-            
-            var newClosure = new Closure() { EvaluationContext = ctx ?? new EvaluationContext() };
+            newContext.RootResource ??= node != null
+                ? getRootResourceFromNode(node)
+                : newContext.Resource;
+
+            var newClosure = new Closure(ctx ?? new EvaluationContext());
 
             var input = new[] { root };
 
             foreach (var assignment in newClosure.EvaluationContext.Environment)
             {
                 newClosure.SetValue(assignment.Key, assignment.Value);
             }
-            
+
             newClosure.SetThis(input);
             newClosure.SetThat(input);
             newClosure.SetIndex(ElementNode.CreateList(0));
             newClosure.SetOriginalContext(input);
-            
+
             if (newContext.Resource != null) newClosure.SetResource(new[] { newContext.Resource });
             if (newContext.RootResource != null) newClosure.SetRootResource(new[] { newContext.RootResource });
 
@@ -63,6 +105,11 @@ public static Closure Root(ITypedElement root, EvaluationContext ctx = null)
 
         private Dictionary<string, IEnumerable<ITypedElement>> _namedValues = new Dictionary<string, IEnumerable<ITypedElement>>();
 
+        internal IEnumerable<KeyValuePair<string, IEnumerable<ITypedElement>>> Variables()
+        {
+            return _namedValues;
+        }
+
         public virtual void SetValue(string name, IEnumerable<ITypedElement> value)
         {
             _namedValues.Remove(name);
@@ -74,11 +121,7 @@ public virtual void SetValue(string name, IEnumerable<ITypedElement> value)
 
         public virtual Closure Nest()
         {
-            return new Closure()
-            {
-                Parent = this,
-                EvaluationContext = this.EvaluationContext
-            };
+            return new Closure(this, EvaluationContext);
         }
 
 
@@ -100,7 +143,7 @@ public virtual IEnumerable<ITypedElement> ResolveValue(string name)
         }
 
         private static ScopedNode getResourceFromNode(ScopedNode node) => node.AtResource ? node : node.ParentResource;
-        
+
         private static ScopedNode getRootResourceFromNode(ScopedNode node)
         {
             var resource = getResourceFromNode(node);

src/Hl7.Fhir.Base/FhirPath/Expressions/DynaDispatcher.cs

@@ -1,7 +1,7 @@
-/* 
+/*
  * Copyright (c) 2015, Firely (info@fire.ly) and contributors
  * See the file CONTRIBUTORS for details.
- * 
+ *
  * This file is licensed under the BSD 3-Clause license
  * available at https://raw.githubusercontent.com/FirelyTeam/firely-net-sdk/master/LICENSE
  */
@@ -11,6 +11,7 @@
 using System.Collections.Generic;
 using System.Linq;
 using System.Reflection;
+using FocusCollection = System.Collections.Generic.IEnumerable<Hl7.Fhir.ElementModel.ITypedElement>;
 
 namespace Hl7.FhirPath.Expressions
 {
@@ -25,11 +26,12 @@ public DynaDispatcher(string name, SymbolTable scope)
         private readonly string _name;
         private readonly SymbolTable _scope;
 
-        public IEnumerable<ITypedElement> Dispatcher(Closure context, IEnumerable<Invokee> args)
+        public FocusCollection Dispatcher(Closure context, IEnumerable<Invokee> args)
         {
-            var actualArgs = new List<IEnumerable<ITypedElement>>();
+            var actualArgs = new List<FocusCollection>();
 
             var focus = args.First()(context, InvokeeFactory.EmptyArgs);
+            context.focus = focus;
             if (!focus.Any()) return ElementNode.EmptyList;
 
             actualArgs.Add(focus);
@@ -46,9 +48,13 @@ public IEnumerable<ITypedElement> Dispatcher(Closure context, IEnumerable<Invoke
                 {
                     // The Get() here should never fail, since we already know there's a (dynamic) matching candidate
                     // Need to clean up this duplicate logic later
-
                     var argFuncs = actualArgs.Select(InvokeeFactory.Return);
-                    return entry(context, argFuncs);
+                    var result = entry(context, argFuncs);
+
+                    // Dynamically dispatched function arguments aren't wrapped
+                    // for the debug/trace, so need to manually put the focus back
+                    context.focus = focus;
+                    return result;
                 }
                 catch (TargetInvocationException tie)
                 {