Skip to content

Commit c09b595

Browse files
hazzikhazzik
committed
NH-2779 - Corrected logging for collections using property-refs
1 parent 71994bd commit c09b595

22 files changed

+277
-75
lines changed

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

Lines changed: 61 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,61 @@
1+
using System;
2+
using log4net;
3+
using log4net.Appender;
4+
using log4net.Core;
5+
using log4net.Layout;
6+
using log4net.Repository.Hierarchy;
7+
using NUnit.Framework;
8+
9+
namespace NHibernate.Test.NHSpecificTest.NH2779
10+
{
11+
[TestFixture]
12+
public class Fixture : BugTestCase
13+
{
14+
[Test]
15+
public void Test()
16+
{
17+
using (ISession session = OpenSession())
18+
using (ITransaction tx = session.BeginTransaction())
19+
{
20+
Order order = new Order() { OrderId = "Order-1", InternalOrderId = 1 };
21+
session.Save(order);
22+
tx.Commit();
23+
}
24+
25+
using (ISession session = OpenSession())
26+
using (ITransaction tx = session.BeginTransaction())
27+
using (LogSpy logSpy = new LogSpy()) // <-- Logging must be set DEBUG to reproduce bug
28+
{
29+
Order order = session.Get<Order>("Order-1");
30+
Assert.IsNotNull(order);
31+
32+
// Cleanup
33+
session.Delete(order);
34+
tx.Commit();
35+
}
36+
}
37+
38+
public class LogSpy : IDisposable
39+
{
40+
private readonly DebugAppender appender;
41+
private readonly Logger loggerImpl;
42+
43+
public LogSpy()
44+
{
45+
appender = new DebugAppender
46+
{
47+
Layout = new PatternLayout("%message"),
48+
Threshold = Level.All
49+
};
50+
loggerImpl = (Logger)LogManager.GetLogger("NHibernate").Logger;
51+
loggerImpl.AddAppender(appender);
52+
loggerImpl.Level = Level.All;
53+
}
54+
55+
public void Dispose()
56+
{
57+
loggerImpl.RemoveAppender(appender);
58+
}
59+
}
60+
}
61+
}

‎src/NHibernate.Test/NHSpecificTest/NH2779/LineItem.cs

Lines changed: 10 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,10 @@
1+

2+
namespace NHibernate.Test.NHSpecificTest.NH2779
3+
{
4+
public class LineItem
5+
{
6+
public virtual int LineItemId { get; set; }
7+
public virtual int InternalOrderId { get; set; }
8+
public virtual int SortOrder { get; set; }
9+
}
10+
}

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

Lines changed: 26 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,26 @@
1+
<?xml version="1.0" encoding="utf-8" ?>
2+
<hibernate-mapping xmlns="urn:nhibernate-mapping-2.2"
3+
namespace="NHibernate.Test.NHSpecificTest.NH2779"
4+
assembly="NHibernate.Test">
5+
6+
<class name="Order" table="ORDERS" lazy="false">
7+
<id name="OrderId" column="ORDER_ID" type="String">
8+
<generator class="assigned" />
9+
</id>
10+
<property name="InternalOrderId" column="INTERNAL_ORDER_ID" type="Int32" />
11+
12+
<list name="lineItems" lazy="false" cascade="all" fetch="join" access="field" generic="true">
13+
<key column="INTERNAL_ORDER_ID" property-ref="InternalOrderId" />
14+
<list-index column="SortOrder" base="1" />
15+
<one-to-many class="LineItem" />
16+
</list>
17+
</class>
18+
19+
<class name="LineItem" table="LINEITEMS" lazy="false">
20+
<id name="LineItemId" column="LINEITEM_ID" type="Int32">
21+
<generator class="assigned" />
22+
</id>
23+
<property name="InternalOrderId" column="INTERNAL_ORDER_ID" type="Int32" />
24+
<property name="SortOrder" column="SORT_ORDER" type="Int32" />
25+
</class>
26+
</hibernate-mapping>

‎src/NHibernate.Test/NHSpecificTest/NH2779/Order.cs

Lines changed: 13 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,13 @@
1+
using System.Collections.Generic;
2+
3+
namespace NHibernate.Test.NHSpecificTest.NH2779
4+
{
5+
public class Order
6+
{
7+
private IList<LineItem> lineItems = new List<LineItem>();
8+
9+
public virtual string OrderId { get; set; }
10+
public virtual int InternalOrderId { get; set; }
11+
public virtual IList<LineItem> LineItems { get { return lineItems; } }
12+
}
13+
}

‎src/NHibernate.Test/NHibernate.Test.csproj

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -699,6 +699,9 @@
699699
<Compile Include="NHSpecificTest\NH1082\SynchronizationThatThrowsExceptionAtBeforeTransactionCompletion.cs" />
700700
<Compile Include="NHSpecificTest\NH2756\Fixture.cs" />
701701
<Compile Include="NHSpecificTest\NH2756\Model.cs" />
702+
<Compile Include="NHSpecificTest\NH2779\Fixture.cs" />
703+
<Compile Include="NHSpecificTest\NH2779\LineItem.cs" />
704+
<Compile Include="NHSpecificTest\NH2779\Order.cs" />
702705
<Compile Include="NHSpecificTest\NH2865\Entity.cs" />
703706
<Compile Include="NHSpecificTest\NH2865\Fixture.cs" />
704707
<Compile Include="NHSpecificTest\NH3377\Entity.cs" />
@@ -3090,6 +3093,7 @@
30903093
<EmbeddedResource Include="UnionsubclassPolymorphicFormula\Party.hbm.xml" />
30913094
<EmbeddedResource Include="NHSpecificTest\NH3050\Mappings.hbm.xml" />
30923095
<EmbeddedResource Include="NHSpecificTest\NH2469\Mappings.hbm.xml" />
3096+
<EmbeddedResource Include="NHSpecificTest\NH2779\Mappings.hbm.xml" />
30933097
<EmbeddedResource Include="NHSpecificTest\NH2033\Mappings.hbm.xml" />
30943098
<EmbeddedResource Include="NHSpecificTest\NH3202\Mappings.hbm.xml" />
30953099
<EmbeddedResource Include="NHSpecificTest\NH3221\Mappings.hbm.xml" />

‎src/NHibernate/Action/CollectionUpdateAction.cs

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -16,7 +16,7 @@ public sealed class CollectionUpdateAction : CollectionAction
1616
private readonly bool emptySnapshot;
1717

1818
public CollectionUpdateAction(IPersistentCollection collection, ICollectionPersister persister, object key,
19-
bool emptySnapshot, ISessionImplementor session)
19+
bool emptySnapshot, ISessionImplementor session)
2020
: base(persister, collection, key, session)
2121
{
2222
this.emptySnapshot = emptySnapshot;
@@ -59,7 +59,7 @@ public override void Execute()
5959
if (affectedByFilters)
6060
{
6161
throw new HibernateException("cannot recreate collection while filter is enabled: "
62-
+ MessageHelper.InfoString(persister, id, persister.Factory));
62+
+ MessageHelper.CollectionInfoString(persister, collection, id, session));
6363
}
6464
if (!emptySnapshot)
6565
{

‎src/NHibernate/Collection/AbstractPersistentCollection.cs

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -557,7 +557,7 @@ public virtual bool SetCurrentSession(ISessionImplementor session)
557557
else
558558
{
559559
throw new HibernateException("Illegal attempt to associate a collection with two open sessions: "
560-
+ MessageHelper.InfoString(ce.LoadedPersister, ce.LoadedKey, session.Factory));
560+
+ MessageHelper.CollectionInfoString(ce.LoadedPersister, this, ce.LoadedKey, session));
561561
}
562562
}
563563
else

‎src/NHibernate/Engine/CollectionEntry.cs

Lines changed: 5 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -127,7 +127,7 @@ public CollectionEntry(ICollectionPersister persister, IPersistentCollection col
127127

128128
/// <summary> For collections just loaded from the database</summary>
129129
public CollectionEntry(IPersistentCollection collection, ICollectionPersister loadedPersister, object loadedKey,
130-
bool ignore)
130+
bool ignore)
131131
{
132132
this.ignore = ignore;
133133
this.loadedKey = loadedKey;
@@ -256,9 +256,9 @@ private void Dirty(IPersistentCollection collection)
256256
// if the collection is initialized and it was previously persistent
257257
// initialize the dirty flag
258258
bool forceDirty = collection.WasInitialized && !collection.IsDirty && LoadedPersister != null
259-
&& LoadedPersister.IsMutable
260-
&& (collection.IsDirectlyAccessible || LoadedPersister.ElementType.IsMutable)
261-
&& !collection.EqualsSnapshot(LoadedPersister);
259+
&& LoadedPersister.IsMutable
260+
&& (collection.IsDirectlyAccessible || LoadedPersister.ElementType.IsMutable)
261+
&& !collection.EqualsSnapshot(LoadedPersister);
262262

263263
if (forceDirty)
264264
{
@@ -281,7 +281,7 @@ public void PreFlush(IPersistentCollection collection)
281281

282282
if (log.IsDebugEnabled && collection.IsDirty && loadedPersister != null)
283283
{
284-
log.Debug("Collection dirty: " + MessageHelper.InfoString(loadedPersister, loadedKey));
284+
log.Debug("Collection dirty: " + MessageHelper.CollectionInfoString(loadedPersister, loadedKey));
285285
}
286286

287287
// reset all of these values so any previous flush status

‎src/NHibernate/Engine/CollectionKey.cs

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -68,7 +68,7 @@ public object Key
6868

6969
public override string ToString()
7070
{
71-
return "CollectionKey" + MessageHelper.InfoString(factory.GetCollectionPersister(role), key, factory);
71+
return "CollectionKey" + MessageHelper.CollectionInfoString(factory.GetCollectionPersister(role), key, factory);
7272
}
7373
}
7474
}

‎src/NHibernate/Engine/Collections.cs

Lines changed: 5 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -34,7 +34,7 @@ private static void ProcessDereferencedCollection(IPersistentCollection coll, IS
3434
ICollectionPersister loadedPersister = entry.LoadedPersister;
3535

3636
if (log.IsDebugEnabled && loadedPersister != null)
37-
log.Debug("Collection dereferenced: " + MessageHelper.InfoString(loadedPersister, entry.LoadedKey, session.Factory));
37+
log.Debug("Collection dereferenced: " + MessageHelper.CollectionInfoString(loadedPersister, coll, entry.LoadedKey, session));
3838

3939
// do a check
4040
bool hasOrphanDelete = loadedPersister != null && loadedPersister.HasOrphanDelete;
@@ -84,7 +84,7 @@ private static void ProcessNeverReferencedCollection(IPersistentCollection coll,
8484
{
8585
CollectionEntry entry = session.PersistenceContext.GetCollectionEntry(coll);
8686

87-
log.Debug("Found collection with unloaded owner: " + MessageHelper.InfoString(entry.LoadedPersister, entry.LoadedKey, session.Factory));
87+
log.Debug("Found collection with unloaded owner: " + MessageHelper.CollectionInfoString(entry.LoadedPersister, coll, entry.LoadedKey, session));
8888

8989
entry.CurrentPersister = entry.LoadedPersister;
9090
entry.CurrentKey = entry.LoadedKey;
@@ -127,9 +127,9 @@ public static void ProcessReachableCollection(IPersistentCollection collection,
127127
if (log.IsDebugEnabled)
128128
{
129129
log.Debug("Collection found: " +
130-
MessageHelper.InfoString(persister, ce.CurrentKey, factory) + ", was: " +
131-
MessageHelper.InfoString(ce.LoadedPersister, ce.LoadedKey, factory) +
132-
(collection.WasInitialized ? " (initialized)" : " (uninitialized)"));
130+
MessageHelper.CollectionInfoString(persister, collection, ce.CurrentKey, session) + ", was: " +
131+
MessageHelper.CollectionInfoString(ce.LoadedPersister, collection, ce.LoadedKey, session) +
132+
(collection.WasInitialized ? " (initialized)" : " (uninitialized)"));
133133
}
134134

135135
PrepareCollectionForUpdate(collection, ce, session.EntityMode, factory);

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

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -174,7 +174,7 @@ public void EndLoadingCollections(ICollectionPersister persister)
174174
if (lce.Collection.Owner == null)
175175
{
176176
session.PersistenceContext.AddUnownedCollection(new CollectionKey(persister, lce.Key, session.EntityMode),
177-
lce.Collection);
177+
lce.Collection);
178178
}
179179
if (log.IsDebugEnabled)
180180
{
@@ -272,7 +272,7 @@ private void EndLoadingCollection(LoadingCollectionEntry lce, ICollectionPersist
272272

273273
if (log.IsDebugEnabled)
274274
{
275-
log.Debug("collection fully initialized: " + MessageHelper.InfoString(persister, lce.Key, session.Factory));
275+
log.Debug("collection fully initialized: " + MessageHelper.CollectionInfoString(persister, lce.Collection, lce.Key, session));
276276
}
277277

278278
if (statsEnabled)
@@ -292,7 +292,7 @@ private void AddCollectionToCache(LoadingCollectionEntry lce, ICollectionPersist
292292

293293
if (log.IsDebugEnabled)
294294
{
295-
log.Debug("Caching collection: " + MessageHelper.InfoString(persister, lce.Key, factory));
295+
log.Debug("Caching collection: " + MessageHelper.CollectionInfoString(persister, lce.Collection, lce.Key, session));
296296
}
297297

298298
if (!(session.EnabledFilters.Count == 0) && persister.IsAffectedByEnabledFilters(session))
@@ -324,7 +324,7 @@ private void AddCollectionToCache(LoadingCollectionEntry lce, ICollectionPersist
324324
CollectionCacheEntry entry = new CollectionCacheEntry(lce.Collection, persister);
325325
CacheKey cacheKey = session.GenerateCacheKey(lce.Key, persister.KeyType, persister.Role);
326326
bool put = persister.Cache.Put(cacheKey, persister.CacheEntryStructure.Structure(entry),
327-
session.Timestamp, version, versionComparator,
327+
session.Timestamp, version, versionComparator,
328328
factory.Settings.IsMinimalPutsEnabled && session.CacheMode != CacheMode.Refresh);
329329

330330
if (put && factory.Statistics.IsStatisticsEnabled)

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

Lines changed: 1 addition & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -158,17 +158,12 @@ public IPersistentCollection LocateLoadingCollection(ICollectionPersister persis
158158
{
159159
if (log.IsDebugEnabled)
160160
{
161-
log.Debug("returning loading collection:" + MessageHelper.InfoString(persister, ownerKey, Session.Factory));
161+
log.Debug("returning loading collection:" + MessageHelper.CollectionInfoString(persister, ownerKey, Session.Factory));
162162
}
163163
return lce.Collection;
164164
}
165165
else
166166
{
167-
// todo : should really move this log statement to CollectionType, where this is used from...
168-
if (log.IsDebugEnabled)
169-
{
170-
log.Debug("creating collection wrapper:" + MessageHelper.InfoString(persister, ownerKey, Session.Factory));
171-
}
172167
return null;
173168
}
174169
}

‎src/NHibernate/Event/Default/DefaultInitializeCollectionEventListener.cs

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -35,7 +35,7 @@ public virtual void OnInitializeCollection(InitializeCollectionEvent @event)
3535
{
3636
if (log.IsDebugEnabled)
3737
{
38-
log.Debug("initializing collection " + MessageHelper.InfoString(ce.LoadedPersister, ce.LoadedKey, source.Factory));
38+
log.Debug("initializing collection " + MessageHelper.CollectionInfoString(ce.LoadedPersister, collection, ce.LoadedKey, source));
3939
}
4040

4141
log.Debug("checking second-level cache");

‎src/NHibernate/Event/Default/EvictVisitor.cs

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -52,7 +52,7 @@ private void EvictCollection(IPersistentCollection collection)
5252
CollectionEntry ce = (CollectionEntry)Session.PersistenceContext.CollectionEntries[collection];
5353
Session.PersistenceContext.CollectionEntries.Remove(collection);
5454
if (log.IsDebugEnabled)
55-
log.Debug("evicting collection: " + MessageHelper.InfoString(ce.LoadedPersister, ce.LoadedKey, Session.Factory));
55+
log.Debug("evicting collection: " + MessageHelper.CollectionInfoString(ce.LoadedPersister, collection, ce.LoadedKey, Session));
5656
if (ce.LoadedPersister != null && ce.LoadedKey != null)
5757
{
5858
//TODO: is this 100% correct?

‎src/NHibernate/Event/Default/ReattachVisitor.cs

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,6 @@
11

22
using NHibernate.Action;
3+
using NHibernate.Engine;
34
using NHibernate.Impl;
45
using NHibernate.Persister.Collection;
56
using NHibernate.Type;
@@ -57,8 +58,7 @@ internal void RemoveCollection(ICollectionPersister role, object collectionKey,
5758
{
5859
if (log.IsDebugEnabled)
5960
{
60-
log.Debug("collection dereferenced while transient " +
61-
MessageHelper.InfoString(role, ownerIdentifier, source.Factory));
61+
log.Debug("collection dereferenced while transient " + MessageHelper.CollectionInfoString(role, ownerIdentifier, source.Factory));
6262
}
6363
source.ActionQueue.AddAction(new CollectionRemoveAction(owner, role, collectionKey, false, source));
6464
}

0 commit comments

Comments
 (0)