Introduce a fhirpath debug tracer

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

@@ -0,0 +1,144 @@
+/*
+ * 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,
+            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");
+                    exprName = "constant";
+                    break;
+
+                case ChildExpression child:
+                    Trace.WriteLine($"{expr.Location.LineNumber},{expr.Location.LinePosition},{child.ChildName}");
+                    exprName = child.ChildName;
+                    break;
+
+                case IndexerExpression _:
+                    Trace.WriteLine($"{expr.Location.LineNumber},{expr.Location.LinePosition},[]");
+                    exprName = "[]";
+                    break;
+
+                case UnaryExpression ue:
+                    Trace.WriteLine($"{expr.Location.LineNumber},{expr.Location.LinePosition},{ue.Op}");
+                    exprName = ue.Op;
+                    break;
+
+                case BinaryExpression be:
+                    Trace.WriteLine($"{expr.Location.LineNumber},{expr.Location.LinePosition},{be.Op}");
+                    exprName = be.Op;
+                    break;
+
+                case FunctionCallExpression fe:
+                    Trace.WriteLine($"{expr.Location.LineNumber},{expr.Location.LinePosition},{fe.FunctionName}");
+                    exprName = fe.FunctionName;
+                    break;
+
+                case NewNodeListInitExpression _:
+                    Trace.WriteLine($"{expr.Location.LineNumber},{expr.Location.LinePosition},{{}} (empty)");
+                    exprName = "{}";
+                    break;
+
+                case AxisExpression ae:
+                    if (ae.AxisName == "that")
+                        return;
+                    Trace.WriteLine($"Evaluated: {ae.AxisName} results: {result.Count()}");
+                    exprName = "$" + ae.AxisName;
+                    break;
+
+                case VariableRefExpression ve:
+                    Trace.WriteLine($"{expr.Location.LineNumber},{expr.Location.LinePosition},%{ve.Name}");
+                    exprName = "%" + ve.Name;
+                    break;
+
+                default:
+                    exprName = expr.GetType().Name;
+#if DEBUG
+                    Debugger.Break();
+#endif
+                    throw new Exception($"Unknown expression type: {expr.GetType().Name}");
+                    // Trace.WriteLine($"Evaluated: {expr} results: {result.Count()}");
+            }
+
+            if (focus != null)
+            {
+                foreach (var item in focus)
+                {
+                    DebugTraceValue($"$focus", item);
+                }
+            }
+
+            if (thisValue != null)
+            {
+                foreach (var item in thisValue)
+                {
+                    DebugTraceValue("$this", item);
+                }
+            }
+
+            if (index != null)
+            {
+                DebugTraceValue("$index", index);
+            }
+
+            if (totalValue != null)
+            {
+                foreach (var item in totalValue)
+                {
+                    DebugTraceValue($"{exprName} »", item);
+                }
+            }
+
+            if (result != null)
+            {
+                foreach (var item in result)
+                {
+                    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/Expressions/Closure.cs

@@ -63,6 +63,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);

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,17 +26,17 @@ 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, out FocusCollection focus)
         {
-            var actualArgs = new List<IEnumerable<ITypedElement>>();
+            var actualArgs = new List<FocusCollection>();
 
-            var focus = args.First()(context, InvokeeFactory.EmptyArgs);
+            focus = args.First()(context, InvokeeFactory.EmptyArgs, out _);
             if (!focus.Any()) return ElementNode.EmptyList;
 
             actualArgs.Add(focus);
             var newCtx = context.Nest(focus);
 
-            actualArgs.AddRange(args.Skip(1).Select(a => a(newCtx, InvokeeFactory.EmptyArgs)));
+            actualArgs.AddRange(args.Skip(1).Select(a => a(newCtx, InvokeeFactory.EmptyArgs, out _)));
             if (actualArgs.Any(aa => !aa.Any())) return ElementNode.EmptyList;
 
             var entry = _scope.DynamicGet(_name, actualArgs);
@@ -46,9 +47,8 @@ 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);
+                    return entry(context, argFuncs, out _);
                 }
                 catch (TargetInvocationException tie)
                 {

src/Hl7.Fhir.Base/FhirPath/Expressions/EvaluatorVisitor.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,29 +11,45 @@
 using System.Collections.Generic;
 using System.Linq;
 using FP = Hl7.FhirPath.Expressions;
+using FocusCollection = System.Collections.Generic.IEnumerable<Hl7.Fhir.ElementModel.ITypedElement>;
 
 namespace Hl7.FhirPath.Expressions
 {
     internal class EvaluatorVisitor : FP.ExpressionVisitor<Invokee>
     {
+        private Invokee WrapForDebugTracer(Invokee invokee, Expression expression)
+        {
+            if (_debugTrace != null)
+            {
+                return (Closure context, IEnumerable<Invokee> arguments, out FocusCollection focus) => {
+                    var result = invokee(context, arguments, out focus);
+                    _debugTrace?.TraceCall(expression, focus, context.GetThis(), context.GetIndex()?.FirstOrDefault(), context.GetTotal(), result, context.Variables());
+                    return result;
+                };
+            }
+            return invokee;
+        }
+
         public SymbolTable Symbols { get; }
+        private IDebugTracer _debugTrace;
 
-        public EvaluatorVisitor(SymbolTable symbols)
+        public EvaluatorVisitor(SymbolTable symbols, IDebugTracer debugTrace = null)
         {
             Symbols = symbols;
+            _debugTrace = debugTrace;
         }
 
 
         public override Invokee VisitConstant(FP.ConstantExpression expression)
         {
-            return InvokeeFactory.Return(ElementNode.ForPrimitive(expression.Value));
+            return WrapForDebugTracer(InvokeeFactory.Return(ElementNode.ForPrimitive(expression.Value)), expression);
         }
 
         public override Invokee VisitFunctionCall(FP.FunctionCallExpression expression)
         {
-            var focus = expression.Focus.ToEvaluator(Symbols);
+            var focus = expression.Focus.ToEvaluator(Symbols, _debugTrace);
             var arguments = new List<Invokee>() { focus };
-            arguments.AddRange(expression.Arguments.Select(arg => arg.ToEvaluator(Symbols)));
+            arguments.AddRange(expression.Arguments.Select(arg => arg.ToEvaluator(Symbols, _debugTrace)));
 
             // We have no real type information, so just pass object as the type
             var types = new List<Type>() { typeof(object) }; //   for the focus;
@@ -42,52 +58,62 @@ public override Invokee VisitFunctionCall(FP.FunctionCallExpression expression)
             // Now locate the function based on the types and name
             Invokee boundFunction = resolve(Symbols, expression.FunctionName, types);
 
-            return InvokeeFactory.Invoke(expression.FunctionName, arguments, boundFunction);
+            return WrapForDebugTracer(InvokeeFactory.Invoke(expression.FunctionName, arguments, boundFunction), expression);
         }
 
         public override Invokee VisitNewNodeListInit(FP.NewNodeListInitExpression expression)
         {
-            return InvokeeFactory.Return(ElementNode.EmptyList);
+            return WrapForDebugTracer(InvokeeFactory.Return(ElementNode.EmptyList), expression);
         }
 
         public override Invokee VisitVariableRef(FP.VariableRefExpression expression)
         {
             // HACK, for now, $this is special, and we handle in run-time, not compile time...
             if (expression.Name == "builtin.this")
-                return InvokeeFactory.GetThis;
+                return WrapForDebugTracer(InvokeeFactory.GetThis, expression);
 
             // HACK, for now, $this is special, and we handle in run-time, not compile time...
             if (expression.Name == "builtin.that")
                 return InvokeeFactory.GetThat;
 
             // HACK, for now, $total is special, and we handle in run-time, not compile time...
             if (expression.Name == "builtin.total")
-                return InvokeeFactory.GetTotal;
+                return WrapForDebugTracer(InvokeeFactory.GetTotal, expression);
 
             // HACK, for now, $index is special, and we handle in run-time, not compile time...
             if (expression.Name == "builtin.index")
-                return InvokeeFactory.GetIndex;
+                return WrapForDebugTracer(InvokeeFactory.GetIndex, expression);
 
             // HACK, for now, %context is special, and we handle in run-time, not compile time...
             if (expression.Name == "context")
-                return InvokeeFactory.GetContext;
+                return WrapForDebugTracer(InvokeeFactory.GetContext, expression);
 
             // HACK, for now, %resource is special, and we handle in run-time, not compile time...
             if (expression.Name == "resource")
-                return InvokeeFactory.GetResource;
+                return WrapForDebugTracer(InvokeeFactory.GetResource, expression);
 
             // HACK, for now, %rootResource is special, and we handle in run-time, not compile time...
             if (expression.Name == "rootResource")
-                return InvokeeFactory.GetRootResource;
+                return WrapForDebugTracer(InvokeeFactory.GetRootResource, expression);
+
+            return WrapForDebugTracer(chainResolves, expression);
 
-            return chainResolves;
-
-            IEnumerable<ITypedElement> chainResolves(Closure context, IEnumerable<Invokee> invokees)
+            FocusCollection chainResolves(Closure context, IEnumerable<Invokee> invokees, out FocusCollection focus)
             {
-                return context.ResolveValue(expression.Name) ?? resolve(Symbols, expression.Name, Enumerable.Empty<Type>())(context, []);
+                var value = context.ResolveValue(expression.Name);
+                if (value != null)
+                {
+                    // this was in the context, so the scope was $this (the context)
+                    focus = context.GetThis();
+                    return value;
+                }
+                else
+                {
+                    return resolve(Symbols, expression.Name, Enumerable.Empty<Type>())(context, [], out focus);
+                }
             }
         }
-        
+
         private static Invokee resolve(SymbolTable scope, string name, IEnumerable<Type> argumentTypes)
         {
             // For now, we don't have the types or the parameters statically, so we just match on name
@@ -113,7 +139,7 @@ private static Invokee resolve(SymbolTable scope, string name, IEnumerable<Type>
             }
             else
             {
-                // No function could be found, but there IS a function with the given name, 
+                // No function could be found, but there IS a function with the given name,
                 // report an error about the fact that the function is known, but could not be bound
                 throw Error.Argument("Unknown symbol '{0}'".FormatWith(name));
             }
@@ -123,11 +149,10 @@ private static Invokee resolve(SymbolTable scope, string name, IEnumerable<Type>
 
     internal static class EvaluatorExpressionExtensions
     {
-        public static Invokee ToEvaluator(this FP.Expression expr, SymbolTable scope)
+        public static Invokee ToEvaluator(this FP.Expression expr, SymbolTable scope, IDebugTracer debugTrace = null)
         {
-            var compiler = new EvaluatorVisitor(scope);
+            var compiler = new EvaluatorVisitor(scope, debugTrace);
             return expr.Accept(compiler);
         }
     }
-
 }

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

@@ -356,12 +356,12 @@ public string DebuggerDisplay
     public class ChildExpression : FunctionCallExpression, Sprache.IPositionAware<ChildExpression>
     {
         public ChildExpression(Expression focus, string name) : base(focus, OP_PREFIX + "children", TypeSpecifier.Any,
-                new ConstantExpression(name, TypeSpecifier.String))
+                new IdentifierExpression(name, TypeSpecifier.String))
         {
         }
 
         public ChildExpression(Expression focus, string name, ISourcePositionInfo location) : base(focus, OP_PREFIX + "children", TypeSpecifier.Any,
-                new ConstantExpression(name, TypeSpecifier.String), location)
+                new IdentifierExpression(name, TypeSpecifier.String), location)
         {
         }