From 244d65581dcb5ad7017f147f64f413c1b4c6c131 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Fr=C3=A9d=C3=A9ric=20Delaporte?= Date: Thu, 3 May 2018 15:24:37 +0200 Subject: [PATCH] Do not log result sets Loggers may enumerate them, causing them to reach their end before being actually used. Fix #1667 --- .../Async/NHSpecificTest/GH1667/Fixture.cs | 74 ++++++++++++ .../NHSpecificTest/GH1667/Entity.cs | 18 +++ .../NHSpecificTest/GH1667/Fixture.cs | 108 ++++++++++++++++++ .../NHSpecificTest/GH1667/Mappings.hbm.xml | 18 +++ .../Engine/Loading/CollectionLoadContext.cs | 4 +- src/NHibernate/Engine/Loading/LoadContexts.cs | 4 +- src/NHibernate/Loader/Loader.cs | 8 +- 7 files changed, 231 insertions(+), 3 deletions(-) create mode 100644 src/NHibernate.Test/Async/NHSpecificTest/GH1667/Fixture.cs create mode 100644 src/NHibernate.Test/NHSpecificTest/GH1667/Entity.cs create mode 100644 src/NHibernate.Test/NHSpecificTest/GH1667/Fixture.cs create mode 100644 src/NHibernate.Test/NHSpecificTest/GH1667/Mappings.hbm.xml 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)