How to log a predicate Expression?

Question

Typically my repositories have logging statements for debugging purposes, allowing me to see values of parameters. Recently I went down the path of creating a generic repository that take predicate Expression as argument for great flexibility, however I cannot figure out a decent way of logging the condition to where it would be remotely useful.

Example Method:

public int GetCount<K>(Expression<Func<K, bool>> predicate) where K : class
{
    Logger.LogDebugMessage(String.Format("Parameters [predicate: {0}]", predicate == null ? string.Empty : predicate.Body.ToString()));

    ...
}

You can see I am using the Body.ToString() at this point, but the results are not-so-readble:

Parameters [predicate: (fa.SomeId == value(NameSpace.SomeClass+<>c__DisplayClass2).SomeId)]

Ultimately what I would love to see is something similar to the below:

Parameters [predicate: (fa.SomeId == 1 && fa.Account.Name == "MyName").SomeId)]

In essence the value of this log is being able to know the input values when something blows up. Is there any way around this short of forcing the user of the API to supply the predicate as a string?

Aiello

If you want to improve readability, it will have to be at the cost of accuracy. The predicate is currently responsive to changes in the closure class. There's nothing stopping you from eagerly evaluating the right-hand side of the == expression and replacing it with its value, but that would not correctly represent the actual predicate. – Fogbound

Can you point me to an example? Also if I clone the expression just for logging purposes then perhaps accuracy of the clone is not a factor? – Aiello

@e36M3: Expressions are, in general, immutable so it's not about that. If you want to go through with this, you can create a new expression such that the member-expression on the RHS of the binary-expression is replaced with a constant-expression. Then call ToString() on that. A "generic" predicate beautifier is going to be a lot harder to write, even if you remove the accuracy requirement. – Fogbound

@Ani, sounds like a losing proposition. A generic repository as such is extremely powerful, however not having good logs seems like a big drawback. I will be able to determine the expression by tracing the code, but I would never be able to know the values of the variables via the logs. – Aiello

@e36M3: If you stated the requirements more precisely, we could help more. Will all predicates be of the form x.Something == ExpressionNotInvolvingXYouWantToEvaluateEagerly? If so, it's easy to simplify. – Fogbound

@Ani, in fact they will not. They are your typical predicates that will be forwarded to methods such as context.Something.First(predicate); It could really be anything that applies to the domain model. – Aiello

@e36M3: Then it's going to be really hard. Start off by defining what you want from the simplification more precisely. You want to recursively evaluate all sub-expressions not involving the input-item? – Fogbound

@Ani, I added more information in the original post. But yes, in essence I just want the values evaluated, so int, string, etc. – Aiello

Answer 1

This blog post by Matt Warren contains code that replaces a local variable reference with the variable name. So, instead of predicate: (fa.SomeId == value(NameSpace.SomeClass+<>c__DisplayClass2).SomeId), you will get predicate: (fa.SomeId == someValue).

The blog post:

http://blogs.msdn.com/b/mattwar/archive/2007/08/01/linq-building-an-iqueryable-provider-part-iii.aspx

The source:

public static class Evaluator
{
    /// <summary>
    /// Performs evaluation & replacement of independent sub-trees
    /// </summary>
    /// <param name="expression">The root of the expression tree.</param>
    /// <param name="fnCanBeEvaluated">A function that decides whether a given expression node can be part of the local function.</param>
    /// <returns>A new tree with sub-trees evaluated and replaced.</returns>
    public static Expression PartialEval(Expression expression, Func<Expression, bool> fnCanBeEvaluated)
    {
        return new SubtreeEvaluator(new Nominator(fnCanBeEvaluated).Nominate(expression)).Eval(expression);
    }

    /// <summary>
    /// Performs evaluation & replacement of independent sub-trees
    /// </summary>
    /// <param name="expression">The root of the expression tree.</param>
    /// <returns>A new tree with sub-trees evaluated and replaced.</returns>
    public static Expression PartialEval(Expression expression)
    {
        return PartialEval(expression, Evaluator.CanBeEvaluatedLocally);
    }

    private static bool CanBeEvaluatedLocally(Expression expression)
    {
        return expression.NodeType != ExpressionType.Parameter;
    }

    /// <summary>
    /// Evaluates & replaces sub-trees when first candidate is reached (top-down)
    /// </summary>
    class SubtreeEvaluator : ExpressionVisitor
    {
        HashSet<Expression> candidates;

        internal SubtreeEvaluator(HashSet<Expression> candidates)
        {
            this.candidates = candidates;
        }

        internal Expression Eval(Expression exp)
        {
            return this.Visit(exp);
        }

        protected override Expression Visit(Expression exp)
        {
            if (exp == null)
            {
                return null;
            }
            if (this.candidates.Contains(exp))
            {
                return this.Evaluate(exp);
            }
            return base.Visit(exp);
        }

        private Expression Evaluate(Expression e)
        {
            if (e.NodeType == ExpressionType.Constant)
            {
                return e;
            }
            LambdaExpression lambda = Expression.Lambda(e);
            Delegate fn = lambda.Compile();
            return Expression.Constant(fn.DynamicInvoke(null), e.Type);
        }
    }

    /// <summary>
    /// Performs bottom-up analysis to determine which nodes can possibly
    /// be part of an evaluated sub-tree.
    /// </summary>
    class Nominator : ExpressionVisitor
    {
        Func<Expression, bool> fnCanBeEvaluated;
        HashSet<Expression> candidates;
        bool cannotBeEvaluated;

        internal Nominator(Func<Expression, bool> fnCanBeEvaluated)
        {
            this.fnCanBeEvaluated = fnCanBeEvaluated;
        }

        internal HashSet<Expression> Nominate(Expression expression)
        {
            this.candidates = new HashSet<Expression>();
            this.Visit(expression);
            return this.candidates;
        }

        protected override Expression Visit(Expression expression)
        {
            if (expression != null)
            {
                bool saveCannotBeEvaluated = this.cannotBeEvaluated;
                this.cannotBeEvaluated = false;
                base.Visit(expression);
                if (!this.cannotBeEvaluated)
                {
                    if (this.fnCanBeEvaluated(expression))
                    {
                        this.candidates.Add(expression);
                    }
                    else
                    {
                        this.cannotBeEvaluated = true;
                    }
                }
                this.cannotBeEvaluated |= saveCannotBeEvaluated;
            }
            return expression;
        }
    }
}

Bacteriology

The source for the ExpressionVisitor class is located at the end of this post: blogs.msdn.com/b/mattwar/archive/2007/07/31/… – Bacteriology

it is actually more important (to me) to know the value of the variable rather than the name. For example assuming I have multiple calls to the repository method and one of them causes an exception, the log should be able to tell me that fa.SomeId == 5 in the exception case, allow me to quickly replicate the issue. – Aiello

The Evaluator class I posted does just that and encapsulates the value in a ConstantExpression. I'm sure you can tweak it for whatever other functionality you need. – Bacteriology

I updated my answer to reflect that this is actually the functionality of the class. I got confused. – Bacteriology

The context of the code I'm in now makes the complexity of this just too much to absorb - I'd be keen to see a quick example of how I use this code, given a predicate. – Nonnah

My hints after figuring this out are 1) You must use the custom ExpressionVisitor class (don't use the one in System) 2) You will probably need to work out how to wrap your predicate in an Expression before you can work out how to call the code here ie Evaluator.PartialEval(expression); - see #3989060 – Nonnah

Answer 2

I had this problem once, and solved it by creating an enum for all predicates that could possible be logged, which weren't that many in my case. If it isn't either in your case, just create one enum-entry per predicate and a Dictionary<Predicate<T>, YourEnum>, and log the value of the enum instead of the predicate.

Orman

Unfortunately the values could be endless, like identity columns, etc. – Aiello