Skip to content

Commit a9cab57

Browse files
fredericDelaportefredericDelaporte
committed
Do not log result sets
Loggers may enumerate them, causing them to reach their end before being actually used. Fix nhibernate#1667
1 parent 231b080 commit a9cab57

File tree

7 files changed

+231
-3
lines changed

7 files changed

+231
-3
lines changed

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

Lines changed: 74 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,74 @@
1+
//------------------------------------------------------------------------------
2+
// <auto-generated>
3+
// This code was generated by AsyncGenerator.
4+
//
5+
// Changes to this file may cause incorrect behavior and will be lost if
6+
// the code is regenerated.
7+
// </auto-generated>
8+
//------------------------------------------------------------------------------
9+
10+
11+
using System;
12+
using System.Collections;
13+
using System.Collections.Generic;
14+
using System.Linq;
15+
using System.Reflection;
16+
using NUnit.Framework;
17+
using NHibernate.Linq;
18+
19+
namespace NHibernate.Test.NHSpecificTest.GH1667
20+
{
21+
using System.Threading.Tasks;
22+
[TestFixture]
23+
public class FixtureAsync : BugTestCase
24+
{
25+
private INHibernateLoggerFactory _defaultLogger;
26+
27+
private static readonly FieldInfo _loggerFactoryField =
28+
typeof(NHibernateLogger).GetField("_loggerFactory", BindingFlags.NonPublic | BindingFlags.Static);
29+
30+
protected override void OnSetUp()
31+
{
32+
_defaultLogger = (INHibernateLoggerFactory)_loggerFactoryField.GetValue(null);
33+
NHibernateLogger.SetLoggersFactory(new EnumeratingLoggerFactory());
34+
35+
using (var session = OpenSession())
36+
using (var transaction = session.BeginTransaction())
37+
{
38+
var e1 = new EntityChild { Name = "Bob" };
39+
session.Save(e1);
40+
41+
var e2 = new Entity { Name = "Sally", Children = new HashSet<EntityChild> { e1 } };
42+
session.Save(e2);
43+
44+
transaction.Commit();
45+
}
46+
}
47+
48+
protected override void OnTearDown()
49+
{
50+
if (_defaultLogger != null)
51+
NHibernateLogger.SetLoggersFactory(_defaultLogger);
52+
53+
using (var session = OpenSession())
54+
using (var transaction = session.BeginTransaction())
55+
{
56+
session.CreateQuery("delete from EntityChild").ExecuteUpdate();
57+
session.CreateQuery("delete from Entity").ExecuteUpdate();
58+
59+
transaction.Commit();
60+
}
61+
}
62+
63+
[Test]
64+
public async Task LoggingDoesNotWreckCollectionLoadingAsync()
65+
{
66+
using (var session = OpenSession())
67+
using (session.BeginTransaction())
68+
{
69+
var parent = await (session.Query<Entity>().FirstAsync());
70+
Assert.That(parent.Children, Has.Count.EqualTo(1));
71+
}
72+
}
73+
}
74+
}

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

Lines changed: 18 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,18 @@
1+
using System;
2+
using System.Collections.Generic;
3+
4+
namespace NHibernate.Test.NHSpecificTest.GH1667
5+
{
6+
class Entity
7+
{
8+
public virtual Guid Id { get; set; }
9+
public virtual string Name { get; set; }
10+
public virtual ISet<EntityChild> Children { get; set; }
11+
}
12+
13+
class EntityChild
14+
{
15+
public virtual Guid Id { get; set; }
16+
public virtual string Name { get; set; }
17+
}
18+
}

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

Lines changed: 108 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,108 @@
1+
using System;
2+
using System.Collections;
3+
using System.Collections.Generic;
4+
using System.Linq;
5+
using System.Reflection;
6+
using NUnit.Framework;
7+
8+
namespace NHibernate.Test.NHSpecificTest.GH1667
9+
{
10+
[TestFixture]
11+
public class Fixture : BugTestCase
12+
{
13+
private INHibernateLoggerFactory _defaultLogger;
14+
15+
private static readonly FieldInfo _loggerFactoryField =
16+
typeof(NHibernateLogger).GetField("_loggerFactory", BindingFlags.NonPublic | BindingFlags.Static);
17+
18+
protected override void OnSetUp()
19+
{
20+
_defaultLogger = (INHibernateLoggerFactory)_loggerFactoryField.GetValue(null);
21+
NHibernateLogger.SetLoggersFactory(new EnumeratingLoggerFactory());
22+
23+
using (var session = OpenSession())
24+
using (var transaction = session.BeginTransaction())
25+
{
26+
var e1 = new EntityChild { Name = "Bob" };
27+
session.Save(e1);
28+
29+
var e2 = new Entity { Name = "Sally", Children = new HashSet<EntityChild> { e1 } };
30+
session.Save(e2);
31+
32+
transaction.Commit();
33+
}
34+
}
35+
36+
protected override void OnTearDown()
37+
{
38+
if (_defaultLogger != null)
39+
NHibernateLogger.SetLoggersFactory(_defaultLogger);
40+
41+
using (var session = OpenSession())
42+
using (var transaction = session.BeginTransaction())
43+
{
44+
session.CreateQuery("delete from EntityChild").ExecuteUpdate();
45+
session.CreateQuery("delete from Entity").ExecuteUpdate();
46+
47+
transaction.Commit();
48+
}
49+
}
50+
51+
[Test]
52+
public void LoggingDoesNotWreckCollectionLoading()
53+
{
54+
using (var session = OpenSession())
55+
using (session.BeginTransaction())
56+
{
57+
var parent = session.Query<Entity>().First();
58+
Assert.That(parent.Children, Has.Count.EqualTo(1));
59+
}
60+
}
61+
}
62+
63+
public class EnumeratingLoggerFactory : INHibernateLoggerFactory
64+
{
65+
public INHibernateLogger LoggerFor(string keyName)
66+
{
67+
return new EnumeratingLogger();
68+
}
69+
70+
public INHibernateLogger LoggerFor(System.Type type)
71+
{
72+
return new EnumeratingLogger();
73+
}
74+
}
75+
76+
public class EnumeratingLogger : INHibernateLogger
77+
{
78+
public void Log(NHibernateLogLevel logLevel, NHibernateLogValues state, Exception exception)
79+
{
80+
if (state.Args == null)
81+
return;
82+
83+
foreach (var arg in state.Args)
84+
{
85+
if (!(arg is IEnumerable e))
86+
continue;
87+
88+
var enumerator = e.GetEnumerator();
89+
try
90+
{
91+
while (enumerator.MoveNext())
92+
{
93+
}
94+
}
95+
finally
96+
{
97+
if (enumerator is IDisposable disp)
98+
disp.Dispose();
99+
}
100+
}
101+
}
102+
103+
public bool IsEnabled(NHibernateLogLevel logLevel)
104+
{
105+
return true;
106+
}
107+
}
108+
}

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

Lines changed: 18 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,18 @@
1+
<?xml version="1.0" encoding="utf-8" ?>
2+
<hibernate-mapping xmlns="urn:nhibernate-mapping-2.2" assembly="NHibernate.Test"
3+
namespace="NHibernate.Test.NHSpecificTest.GH1667">
4+
5+
<class name="Entity">
6+
<id name="Id" generator="guid.comb"/>
7+
<property name="Name"/>
8+
<set name="Children">
9+
<key column="Parent" />
10+
<one-to-many class="EntityChild" />
11+
</set>
12+
</class>
13+
<class name="EntityChild">
14+
<id name="Id" generator="guid.comb"/>
15+
<property name="Name"/>
16+
</class>
17+
18+
</hibernate-mapping>

‎src/NHibernate/Engine/Loading/CollectionLoadContext.cs

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -108,7 +108,9 @@ public IPersistentCollection GetLoadingCollection(ICollectionPersister persister
108108
// create one
109109
if (log.IsDebugEnabled())
110110
{
111-
log.Debug("instantiating new collection [key={0}, rs={1}]", key, resultSet);
111+
// Do not log the resultSet as-is, it is an IEnumerable which may get enumerated by loggers.
112+
// (Serilog does that.) See #1667.
113+
log.Debug("instantiating new collection [key={0}, rs={1}]", key, resultSet.GetType());
112114
}
113115
collection = persister.CollectionType.Instantiate(loadContexts.PersistenceContext.Session, persister, key);
114116
}

‎src/NHibernate/Engine/Loading/LoadContexts.cs

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -136,7 +136,9 @@ public CollectionLoadContext GetCollectionLoadContext(DbDataReader resultSet)
136136
{
137137
if (log.IsDebugEnabled())
138138
{
139-
log.Debug("constructing collection load context for result set [{0}]", resultSet);
139+
// Do not log the resultSet as-is, it is an IEnumerable which may get enumerated by loggers.
140+
// (Serilog does that.) See #1667.
141+
log.Debug("constructing collection load context for result set [{0}]", resultSet.GetType());
140142
}
141143
context = new CollectionLoadContext(this, resultSet);
142144
collectionLoadContexts[resultSet] = context;

‎src/NHibernate/Loader/Loader.cs

Lines changed: 7 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1369,7 +1369,13 @@ private DbDataReader WrapResultSet(DbDataReader rs)
13691369
// potential deadlock issues due to nature of code.
13701370
try
13711371
{
1372-
Log.Debug("Wrapping result set [{0}]", rs);
1372+
if (Log.IsDebugEnabled())
1373+
{
1374+
// Do not log the result set as-is, it is an IEnumerable which may get enumerated by loggers.
1375+
// (Serilog does that.) See #1667.
1376+
Log.Debug("Wrapping result set [{0}]", rs.GetType());
1377+
}
1378+
13731379
return new ResultSetWrapper(rs, RetreiveColumnNameToIndexCache(rs));
13741380
}
13751381
catch (Exception e)

0 commit comments

Comments
 (0)