Linq/LinqLogging.cs: Avoid initializing proxies present in logged linq expressions (NH-3429).

Author: oskarb

src/NHibernate.Test/Linq/LoggingTests.cs

@@ -1,5 +1,6 @@
 using System.Linq;
 using NHibernate.Cfg;
+using NHibernate.DomainModel.Northwind.Entities;
 using NUnit.Framework;
 
 namespace NHibernate.Test.Linq
@@ -26,5 +27,35 @@ public void PageBetweenProjections()
 			}
 		}
 
+
+		[Test]
+		public void CanLogLinqExpressionWithoutInitializingContainedProxy()
+		{
+			var productId = db.Products.Select(p => p.ProductId).First();
+
+			using (var logspy = new LogSpy("NHibernate.Linq"))
+			{
+				var productProxy = session.Load<Product>(productId);
+				Assert.That(NHibernateUtil.IsInitialized(productProxy), Is.False);
+
+				var result = from product in db.Products
+				             where product == productProxy
+				             select product;
+
+				Assert.That(result.Count(), Is.EqualTo(1));
+
+				// Verify that the expected logging did happen.
+				var actualLog = logspy.GetWholeLog();
+
+				const string expectedLog =
+					"Expression (partially evaluated): value(NHibernate.Linq.NhQueryable`1[NHibernate.DomainModel.Northwind.Entities.Product])" +
+					".Where(product => (product = Product#1)).Count()";
+				Assert.That(actualLog, Is.StringContaining(expectedLog));
+
+				// And verify that the proxy in the expression wasn't initialized.
+				Assert.That(NHibernateUtil.IsInitialized(productProxy), Is.False,
+				            "ERROR: We expected the proxy to NOT be initialized.");
+			}
+		}
 	}
 }

src/NHibernate/Linq/LinqLogging.cs

@@ -1,4 +1,7 @@
 using System.Linq.Expressions;
+using NHibernate.Linq.Visitors;
+using NHibernate.Proxy;
+using NHibernate.Util;
 
 namespace NHibernate.Linq
 {
@@ -12,7 +15,37 @@ internal static class LinqLogging
 		internal static void LogExpression(string msg, Expression expression)
 		{
 			if (Log.IsDebugEnabled)
-				Log.DebugFormat("{0}: {1}", msg, expression.ToString());
+			{
+				// If the expression contains NHibernate proxies, those will be initialized
+				// when we call ToString() on the exception. The string representation is
+				// generated by a class internal to System.Linq.Expression, so we cannot
+				// actually override that logic. Circumvent it by replacing such ConstantExpressions
+				// with ParameterExpression, having their name set to the string we wish to display.
+				var visitor = new ProxyReplacingExpressionTreeVisitor();
+				var preparedExpression = visitor.VisitExpression(expression);
+
+				Log.DebugFormat("{0}: {1}", msg, preparedExpression.ToString());
+			}
+		}
+
+
+		/// <summary>
+		/// Replace all occurances of ConstantExpression where the value is an NHibernate
+		/// proxy with a ParameterExpression. The name of the parameter will be a string
+		/// representing the proxied entity, without initializing it.
+		/// </summary>
+		private class ProxyReplacingExpressionTreeVisitor : NhExpressionTreeVisitor
+		{
+			// See also e.g. Remotion.Linq.Clauses.ExpressionTreeVisitors.FormattingExpressionTreeVisitor
+			// for another example of this technique.
+
+			protected override Expression VisitConstantExpression(ConstantExpression expression)
+			{
+				if (expression.Value.IsProxy())
+					return Expression.Parameter(expression.Type, ObjectUtils.IdentityToString(expression.Value));
+
+				return base.VisitConstantExpression(expression);
+			}
 		}
 	}
 }