diff --git a/src/NHibernate.Test/Async/NHSpecificTest/GH1667/Fixture.cs b/src/NHibernate.Test/Async/NHSpecificTest/GH1667/Fixture.cs
new file mode 100644
index 00000000000..5d867198bf0
--- /dev/null
+++ b/src/NHibernate.Test/Async/NHSpecificTest/GH1667/Fixture.cs
@@ -0,0 +1,74 @@
+//------------------------------------------------------------------------------
+//
+// This code was generated by AsyncGenerator.
+//
+// Changes to this file may cause incorrect behavior and will be lost if
+// the code is regenerated.
+//
+//------------------------------------------------------------------------------
+
+
+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 { 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().FirstAsync());
+ Assert.That(parent.Children, Has.Count.EqualTo(1));
+ }
+ }
+ }
+}
diff --git a/src/NHibernate.Test/NHSpecificTest/GH1667/Entity.cs b/src/NHibernate.Test/NHSpecificTest/GH1667/Entity.cs
new file mode 100644
index 00000000000..2ae9e119fca
--- /dev/null
+++ b/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 Children { get; set; }
+ }
+
+ class EntityChild
+ {
+ public virtual Guid Id { get; set; }
+ public virtual string Name { get; set; }
+ }
+}
diff --git a/src/NHibernate.Test/NHSpecificTest/GH1667/Fixture.cs b/src/NHibernate.Test/NHSpecificTest/GH1667/Fixture.cs
new file mode 100644
index 00000000000..1f353fc752f
--- /dev/null
+++ b/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 { 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().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;
+ }
+ }
+}
diff --git a/src/NHibernate.Test/NHSpecificTest/GH1667/Mappings.hbm.xml b/src/NHibernate.Test/NHSpecificTest/GH1667/Mappings.hbm.xml
new file mode 100644
index 00000000000..a5938741674
--- /dev/null
+++ b/src/NHibernate.Test/NHSpecificTest/GH1667/Mappings.hbm.xml
@@ -0,0 +1,18 @@
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
+
diff --git a/src/NHibernate/Engine/Loading/CollectionLoadContext.cs b/src/NHibernate/Engine/Loading/CollectionLoadContext.cs
index 9dd97e4351e..a0843b17dff 100644
--- a/src/NHibernate/Engine/Loading/CollectionLoadContext.cs
+++ b/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);
}
diff --git a/src/NHibernate/Engine/Loading/LoadContexts.cs b/src/NHibernate/Engine/Loading/LoadContexts.cs
index 5fa1521306f..dd13812980a 100644
--- a/src/NHibernate/Engine/Loading/LoadContexts.cs
+++ b/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;
diff --git a/src/NHibernate/Loader/Loader.cs b/src/NHibernate/Loader/Loader.cs
index 84221432140..13bb38cdfe3 100644
--- a/src/NHibernate/Loader/Loader.cs
+++ b/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)