Do not log result sets

src/NHibernate.Test/Async/NHSpecificTest/GH1667/Fixture.cs

@@ -0,0 +1,74 @@
+//------------------------------------------------------------------------------
+// <auto-generated>
+//     This code was generated by AsyncGenerator.
+//
+//     Changes to this file may cause incorrect behavior and will be lost if
+//     the code is regenerated.
+// </auto-generated>
+//------------------------------------------------------------------------------
+
+
+using System;
+using System.Collections;
+using System.Collections.Generic;
+using System.Linq;
+using System.Reflection;
+using NUnit.Framework;
+using NHibernate.Linq;
+
+namespace NHibernate.Test.NHSpecificTest.GH1667
+{
+	using System.Threading.Tasks;
+	[TestFixture]
+	public class FixtureAsync : BugTestCase
+	{
+		private INHibernateLoggerFactory _defaultLogger;
+
+		private static readonly FieldInfo _loggerFactoryField =
+			typeof(NHibernateLogger).GetField("_loggerFactory", BindingFlags.NonPublic | BindingFlags.Static);
+
+		protected override void OnSetUp()
+		{
+			_defaultLogger = (INHibernateLoggerFactory)_loggerFactoryField.GetValue(null);
+			NHibernateLogger.SetLoggersFactory(new EnumeratingLoggerFactory());
+
+			using (var session = OpenSession())
+			using (var transaction = session.BeginTransaction())
+			{
+				var e1 = new EntityChild { Name = "Bob" };
+				session.Save(e1);
+
+				var e2 = new Entity { Name = "Sally", Children = new HashSet<EntityChild> { e1 } };
+				session.Save(e2);
+
+				transaction.Commit();
+			}
+		}
+
+		protected override void OnTearDown()
+		{
+			if (_defaultLogger != null)
+				NHibernateLogger.SetLoggersFactory(_defaultLogger);
+
+			using (var session = OpenSession())
+			using (var transaction = session.BeginTransaction())
+			{
+				session.CreateQuery("delete from EntityChild").ExecuteUpdate();
+				session.CreateQuery("delete from Entity").ExecuteUpdate();
+
+				transaction.Commit();
+			}
+		}
+
+		[Test]
+		public async Task LoggingDoesNotWreckCollectionLoadingAsync()
+		{
+			using (var session = OpenSession())
+			using (session.BeginTransaction())
+			{
+				var parent = await (session.Query<Entity>().FirstAsync());
+				Assert.That(parent.Children, Has.Count.EqualTo(1));
+			}
+		}
+	}
+}

src/NHibernate.Test/NHSpecificTest/GH1667/Entity.cs

@@ -0,0 +1,18 @@
+using System;
+using System.Collections.Generic;
+
+namespace NHibernate.Test.NHSpecificTest.GH1667
+{
+	class Entity
+	{
+		public virtual Guid Id { get; set; }
+		public virtual string Name { get; set; }
+		public virtual ISet<EntityChild> Children { get; set; }
+	}
+
+	class EntityChild
+	{
+		public virtual Guid Id { get; set; }
+		public virtual string Name { get; set; }
+	}
+}

src/NHibernate.Test/NHSpecificTest/GH1667/Fixture.cs

@@ -0,0 +1,108 @@
+using System;
+using System.Collections;
+using System.Collections.Generic;
+using System.Linq;
+using System.Reflection;
+using NUnit.Framework;
+
+namespace NHibernate.Test.NHSpecificTest.GH1667
+{
+	[TestFixture]
+	public class Fixture : BugTestCase
+	{
+		private INHibernateLoggerFactory _defaultLogger;
+
+		private static readonly FieldInfo _loggerFactoryField =
+			typeof(NHibernateLogger).GetField("_loggerFactory", BindingFlags.NonPublic | BindingFlags.Static);
+
+		protected override void OnSetUp()
+		{
+			_defaultLogger = (INHibernateLoggerFactory)_loggerFactoryField.GetValue(null);
+			NHibernateLogger.SetLoggersFactory(new EnumeratingLoggerFactory());
+
+			using (var session = OpenSession())
+			using (var transaction = session.BeginTransaction())
+			{
+				var e1 = new EntityChild { Name = "Bob" };
+				session.Save(e1);
+
+				var e2 = new Entity { Name = "Sally", Children = new HashSet<EntityChild> { e1 } };
+				session.Save(e2);
+
+				transaction.Commit();
+			}
+		}
+
+		protected override void OnTearDown()
+		{
+			if (_defaultLogger != null)
+				NHibernateLogger.SetLoggersFactory(_defaultLogger);
+
+			using (var session = OpenSession())
+			using (var transaction = session.BeginTransaction())
+			{
+				session.CreateQuery("delete from EntityChild").ExecuteUpdate();
+				session.CreateQuery("delete from Entity").ExecuteUpdate();
+
+				transaction.Commit();
+			}
+		}
+
+		[Test]
+		public void LoggingDoesNotWreckCollectionLoading()
+		{
+			using (var session = OpenSession())
+			using (session.BeginTransaction())
+			{
+				var parent = session.Query<Entity>().First();
+				Assert.That(parent.Children, Has.Count.EqualTo(1));
+			}
+		}
+	}
+
+	public class EnumeratingLoggerFactory : INHibernateLoggerFactory
+	{
+		public INHibernateLogger LoggerFor(string keyName)
+		{
+			return new EnumeratingLogger();
+		}
+
+		public INHibernateLogger LoggerFor(System.Type type)
+		{
+			return new EnumeratingLogger();
+		}
+	}
+
+	public class EnumeratingLogger : INHibernateLogger
+	{
+		public void Log(NHibernateLogLevel logLevel, NHibernateLogValues state, Exception exception)
+		{
+			if (state.Args == null)
+				return;
+
+			foreach (var arg in state.Args)
+			{
+				if (!(arg is IEnumerable e))
+					continue;
+
+				var enumerator = e.GetEnumerator();
+				try
+				{
+					while (enumerator.MoveNext())
+					{
+					}
+				}
+				finally
+				{
+					if (enumerator is IDisposable disp)
+						disp.Dispose();
+				}
+			}
+		}
+
+		public bool IsEnabled(NHibernateLogLevel logLevel)
+		{
+			return true;
+		}
+	}
+}

src/NHibernate.Test/NHSpecificTest/GH1667/Mappings.hbm.xml

@@ -0,0 +1,18 @@
+<?xml version="1.0" encoding="utf-8" ?>
+<hibernate-mapping xmlns="urn:nhibernate-mapping-2.2" assembly="NHibernate.Test"
+                   namespace="NHibernate.Test.NHSpecificTest.GH1667">
+
+  <class name="Entity">
+    <id name="Id" generator="guid.comb"/>
+    <property name="Name"/>
+    <set name="Children">
+      <key column="Parent" />
+      <one-to-many class="EntityChild" />
+    </set>
+  </class>
+  <class name="EntityChild">
+    <id name="Id" generator="guid.comb"/>
+    <property name="Name"/>
+  </class>
+
+</hibernate-mapping>

src/NHibernate/Engine/Loading/CollectionLoadContext.cs

@@ -108,7 +108,9 @@ public IPersistentCollection GetLoadingCollection(ICollectionPersister persister
 						// create one
 						if (log.IsDebugEnabled())
 						{
-							log.Debug("instantiating new collection [key={0}, rs={1}]", key, resultSet);
+							// Do not log the resultSet as-is, it is an IEnumerable which may get enumerated by loggers.
+							// (Serilog does that.) See #1667.
+							log.Debug("instantiating new collection [key={0}, rs={1}]", key, resultSet.GetType());
 						}
 						collection = persister.CollectionType.Instantiate(loadContexts.PersistenceContext.Session, persister, key);
 					}

src/NHibernate/Engine/Loading/LoadContexts.cs

@@ -136,7 +136,9 @@ public CollectionLoadContext GetCollectionLoadContext(DbDataReader resultSet)
 			{
 				if (log.IsDebugEnabled())
 				{
-					log.Debug("constructing collection load context for result set [{0}]", resultSet);
+					// Do not log the resultSet as-is, it is an IEnumerable which may get enumerated by loggers.
+					// (Serilog does that.) See #1667.
+					log.Debug("constructing collection load context for result set [{0}]", resultSet.GetType());
 				}
 				context = new CollectionLoadContext(this, resultSet);
 				collectionLoadContexts[resultSet] = context;

src/NHibernate/Loader/Loader.cs

@@ -1369,7 +1369,13 @@ private DbDataReader WrapResultSet(DbDataReader rs)
 			// potential deadlock issues due to nature of code.
 			try
 			{
-				Log.Debug("Wrapping result set [{0}]", rs);
+				if (Log.IsDebugEnabled())
+				{
+					// Do not log the result set as-is, it is an IEnumerable which may get enumerated by loggers.
+					// (Serilog does that.) See #1667.
+					Log.Debug("Wrapping result set [{0}]", rs.GetType());
+				}
+
 				return new ResultSetWrapper(rs, RetreiveColumnNameToIndexCache(rs));
 			}
 			catch (Exception e)