Hi, guys...
I'm getting a weird UnresolvableObjectException stating that a record in the database doesn't exist when it does. The data mapping is somewhat complex and it is possible that I missed something, but the behavior is quite strange and seemingly erratic so it could be an obscure bug... Even if it isn't you may consider improving the infrastucture to make it easier to diagnose this kind of problem.
I have posted the test project (VS 2005) along with a backup of the used database for download on
http://rapidshare.com/files/20953511/NHibernateTest.zip.html.
This is the story:
The data structure is somewhat complicated. I have an Item table, and each Item can have many ItemRevisions and one ItemPrice. Each Item also has an optional reference to the currently active revision, called ActualRevisionID.
I have two Items in the database, with ids 1 and 2. Item 2 has an ItemRevision whose ID is 1, and this is its ActualRevision (note the "mix-up" of IDs: Item 2's revision has the ID of 1). There are two ItemPrice records, but they could be deleted and nothing would change. The problem is that when I execute the HQL query "from Item", I get an UnresolvableObjectException with the message that the ItemRevision with ID 1 doesn't exist - but it does.
There are some very peculiar details:
- The order of records is important. The exception is triggered when using ascending sort by ID (the default), but not when using descending. In other words, it works if I read the Item with the revision first.
- If I load each of the items separately ("from Item itm where itm.ID=2"), the data is read correctly. Only reading both records triggers the exception.
- If I change the IDs of the records so the ItemRevision and Item IDs don't overlap, the exception disappears (this is the reason why there's no autoincrement in the test database, so you can tweak the data).
- If I remove any of the three references (Revisions, ActualRevision, ItemPrices) from the Item.hbm.xml mapping, the exception disappears.
Hibernate version:
1.2.0, both CR1 and beta3
Mapping documents:
Code:
Item.hbm.xml:
<?xml version="1.0" encoding="utf-8" ?>
<hibernate-mapping xmlns="urn:nhibernate-mapping-2.2"
namespace="NHibernateTest" assembly="NHibernateTest">
<class name="Item" table="Item" lazy="false">
<id name="ID">
<column name="ID" sql-type="Int32" not-null="true"/>
<generator class="identity"/>
</id>
<property name="ActualItemRevisionID" insert="false" update="false"/>
<bag name="Revisions" lazy="true" cascade="all-delete-orphan" inverse="true" fetch="join">
<key column="ItemID"/>
<one-to-many class="NHibernateTest.ItemRevision,NHibernateTest"/>
</bag>
<many-to-one name="ActualRevision" column="ActualItemRevisionID" lazy="false" fetch="join"/>
<one-to-one name="ItemPrice" property-ref="Item" cascade="all" lazy="false" fetch="join"/>
</class>
</hibernate-mapping>
ItemRevision.hbm.xml:
<?xml version="1.0" encoding="utf-8" ?>
<hibernate-mapping xmlns="urn:nhibernate-mapping-2.2"
namespace="NHibernateTest" assembly="NHibernateTest">
<class name="ItemPrice" table="ItemPrice" lazy="false">
<id name="ID">
<column name="ID" sql-type="Int32" not-null="true"/>
<generator class="identity"/>
</id>
<property name="ItemID" insert="false" update="false"/>
<many-to-one name="Item" column="ItemID" cascade="all" lazy="false"/>
</class>
</hibernate-mapping>
ItemPrice.hbm.xml:
<?xml version="1.0" encoding="utf-8" ?>
<hibernate-mapping xmlns="urn:nhibernate-mapping-2.2"
namespace="NHibernateTest" assembly="NHibernateTest">
<class name="ItemPrice" table="ItemPrice" lazy="false">
<id name="ID">
<column name="ID" sql-type="Int32" not-null="true"/>
<generator class="identity"/>
</id>
<property name="ItemID" insert="false" update="false"/>
<many-to-one name="Item" column="ItemID" cascade="all" lazy="false"/>
</class>
</hibernate-mapping>
session.CreateQuery("from Item").List();
Full stack trace of any exception that occurs:Code:
NHibernate.dll!NHibernate.UnresolvableObjectException.ThrowIfNull(object o = null, object id = 1, System.Type clazz = {Name = "ItemRevision" FullName = "NHibernateTest.ItemRevision"}) Line 61 C#
NHibernate.dll!NHibernate.Impl.SessionImpl.InternalLoad(System.Type clazz = {Name = "ItemRevision" FullName = "NHibernateTest.ItemRevision"}, object id = 1, bool eager = true, bool isNullable = false) Line 2479 + 0xb bytes C#
NHibernate.dll!NHibernate.Type.EntityType.ResolveIdentifier(object id = 1, NHibernate.Engine.ISessionImplementor session = {NHibernate.Impl.SessionImpl}) Line 259 + 0x38 bytes C#
NHibernate.dll!NHibernate.Type.EntityType.ResolveIdentifier(object id = 1, NHibernate.Engine.ISessionImplementor session = {NHibernate.Impl.SessionImpl}, object owner = {NHibernateTest.Item}) Line 279 + 0xc bytes C#
NHibernate.dll!NHibernate.Impl.SessionImpl.InitializeEntity(object obj = {NHibernateTest.Item}) Line 2925 + 0x4e bytes C#
NHibernate.dll!NHibernate.Loader.Loader.InitializeEntitiesAndCollections(System.Collections.IList hydratedObjects = Count = 2, object resultSetId = {NHibernate.Driver.NHybridDataReader}, NHibernate.Engine.ISessionImplementor session = {NHibernate.Impl.SessionImpl}) Line 609 + 0x20 bytes C#
NHibernate.dll!NHibernate.Loader.Loader.DoQuery(NHibernate.Engine.ISessionImplementor session = {NHibernate.Impl.SessionImpl}, NHibernate.Engine.QueryParameters queryParameters = {NHibernate.Engine.QueryParameters}, bool returnProxies = true) Line 477 + 0x11 bytes C#
NHibernate.dll!NHibernate.Loader.Loader.DoQueryAndInitializeNonLazyCollections(NHibernate.Engine.ISessionImplementor session = {NHibernate.Impl.SessionImpl}, NHibernate.Engine.QueryParameters queryParameters = {NHibernate.Engine.QueryParameters}, bool returnProxies = true) Line 183 + 0x13 bytes C#
NHibernate.dll!NHibernate.Loader.Loader.DoList(NHibernate.Engine.ISessionImplementor session = {NHibernate.Impl.SessionImpl}, NHibernate.Engine.QueryParameters queryParameters = {NHibernate.Engine.QueryParameters}) Line 1777 + 0x10 bytes C#
NHibernate.dll!NHibernate.Loader.Loader.ListIgnoreQueryCache(NHibernate.Engine.ISessionImplementor session = {NHibernate.Impl.SessionImpl}, NHibernate.Engine.QueryParameters queryParameters = {NHibernate.Engine.QueryParameters}) Line 1731 + 0xf bytes C#
NHibernate.dll!NHibernate.Loader.Loader.List(NHibernate.Engine.ISessionImplementor session = {NHibernate.Impl.SessionImpl}, NHibernate.Engine.QueryParameters queryParameters = {NHibernate.Engine.QueryParameters}, Iesi.Collections.ISet querySpaces = {Iesi.Collections.HashedSet}, NHibernate.Type.IType[] resultTypes = {Dimensions:[1]}) Line 1725 + 0xc bytes C#
NHibernate.dll!NHibernate.Hql.Classic.QueryTranslator.List(NHibernate.Engine.ISessionImplementor session = {NHibernate.Impl.SessionImpl}, NHibernate.Engine.QueryParameters queryParameters = {NHibernate.Engine.QueryParameters}) Line 1005 + 0x26 bytes C#
NHibernate.dll!NHibernate.Impl.SessionImpl.Find(string query = "from Item as itm", NHibernate.Engine.QueryParameters parameters = {NHibernate.Engine.QueryParameters}, System.Collections.IList results = Count = 0) Line 1759 + 0x25 bytes C#
NHibernate.dll!NHibernate.Impl.SessionImpl.Find(string query = "from Item as itm", NHibernate.Engine.QueryParameters parameters = {NHibernate.Engine.QueryParameters}) Line 1724 + 0x10 bytes C#
NHibernate.dll!NHibernate.Impl.QueryImpl.List() Line 57 + 0x32 bytes C#
NHibernateTest.exe!NHibernateTest.Form1.Test2() Line 43 + 0x2a bytes C#
NHibernateTest.exe!NHibernateTest.Form1.button1_Click(object sender = {Text = "Go"}, System.EventArgs e = {X = 45 Y = 8 Button = Left}) Line 22 + 0x7 bytes C#
System.Windows.Forms.dll!System.Windows.Forms.Control.OnClick(System.EventArgs e) + 0x57 bytes
System.Windows.Forms.dll!System.Windows.Forms.Button.OnClick(System.EventArgs e) + 0x49 bytes
System.Windows.Forms.dll!System.Windows.Forms.Button.OnMouseUp(System.Windows.Forms.MouseEventArgs mevent = {X = 45 Y = 8 Button = Left}) + 0xc3 bytes
System.Windows.Forms.dll!System.Windows.Forms.Control.WmMouseUp(ref System.Windows.Forms.Message m, System.Windows.Forms.MouseButtons button, int clicks) + 0xf2 bytes
System.Windows.Forms.dll!System.Windows.Forms.Control.WndProc(ref System.Windows.Forms.Message m) + 0x544 bytes
System.Windows.Forms.dll!System.Windows.Forms.ButtonBase.WndProc(ref System.Windows.Forms.Message m) + 0xce bytes
System.Windows.Forms.dll!System.Windows.Forms.Button.WndProc(ref System.Windows.Forms.Message m) + 0x2b bytes
System.Windows.Forms.dll!System.Windows.Forms.Control.ControlNativeWindow.OnMessage(ref System.Windows.Forms.Message m) + 0xd bytes
System.Windows.Forms.dll!System.Windows.Forms.Control.ControlNativeWindow.WndProc(ref System.Windows.Forms.Message m) + 0xd6 bytes
System.Windows.Forms.dll!System.Windows.Forms.NativeWindow.DebuggableCallback(System.IntPtr hWnd, int msg = 514, System.IntPtr wparam, System.IntPtr lparam) + 0x75 bytes
[Native to Managed Transition]
[Managed to Native Transition]
System.Windows.Forms.dll!System.Windows.Forms.Application.ComponentManager.System.Windows.Forms.UnsafeNativeMethods.IMsoComponentManager.FPushMessageLoop(int dwComponentID, int reason = -1, int pvLoopData = 0) + 0x2ea bytes
System.Windows.Forms.dll!System.Windows.Forms.Application.ThreadContext.RunMessageLoopInner(int reason = -1, System.Windows.Forms.ApplicationContext context = {System.Windows.Forms.ApplicationContext}) + 0x17d bytes
System.Windows.Forms.dll!System.Windows.Forms.Application.ThreadContext.RunMessageLoop(int reason, System.Windows.Forms.ApplicationContext context) + 0x53 bytes
System.Windows.Forms.dll!System.Windows.Forms.Application.Run(System.Windows.Forms.Form mainForm) + 0x2e bytes
NHibernateTest.exe!NHibernateTest.Program.Main() Line 17 + 0x1a bytes C#
[Native to Managed Transition]
[Managed to Native Transition]
mscorlib.dll!System.AppDomain.ExecuteAssembly(string assemblyFile, System.Security.Policy.Evidence assemblySecurity, string[] args) + 0x32 bytes
Microsoft.VisualStudio.HostingProcess.Utilities.dll!Microsoft.VisualStudio.HostingProcess.HostProc.RunUsersAssembly() + 0x2b bytes
mscorlib.dll!System.Threading.ThreadHelper.ThreadStart_Context(object state) + 0x3b bytes
mscorlib.dll!System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state) + 0x81 bytes
mscorlib.dll!System.Threading.ThreadHelper.ThreadStart() + 0x40 bytes
Name and version of the database you are using:Microsoft SQL Server Express 2005 SP2
The generated SQL (show_sql=true):Code:
select item0_.ID as ID4_, item0_.ActualItemRevisionID as ActualIt2_4_ from Item item0_
SELECT itemprice0_.ID as ID5_3_, itemprice0_.ItemID as ItemID5_3_, item1_.ID as ID4_0_, item1_.ActualItemRevisionID as ActualIt2_4_0_, revisions2_.ItemID as ItemID__5_, revisions2_.ID as ID5_, revisions2_.ID as ID3_1_, revisions2_.ItemID as ItemID3_1_, itemrevisi3_.ID as ID3_2_, itemrevisi3_.ItemID as ItemID3_2_ FROM ItemPrice itemprice0_ left outer join Item item1_ on itemprice0_.ItemID=item1_.ID left outer join ItemRevision revisions2_ on item1_.ID=revisions2_.ItemID left outer join ItemRevision itemrevisi3_ on item1_.ActualItemRevisionID=itemrevisi3_.ID WHERE itemprice0_.ItemID=@p0; @p0 = '1'
Debug level Hibernate log excerpt:Code:
2007-03-14 10:30:27,327 DEBUG 11 NHibernate.Impl.SessionImpl - find: from Item as itm
2007-03-14 10:30:27,397 DEBUG 11 NHibernate.Engine.QueryParameters - named parameters: {}
2007-03-14 10:30:27,417 DEBUG 11 NHibernate.Hql.Classic.QueryTranslator - compiling query
2007-03-14 10:30:27,487 DEBUG 11 NHibernate.Impl.SessionImpl - flushing session
2007-03-14 10:30:27,497 DEBUG 11 NHibernate.Impl.SessionImpl - Flushing entities and processing referenced collections
2007-03-14 10:30:27,497 DEBUG 11 NHibernate.Impl.SessionImpl - Processing unreferenced collections
2007-03-14 10:30:27,497 DEBUG 11 NHibernate.Impl.SessionImpl - scheduling collection removes/(re)creates/updates
2007-03-14 10:30:27,497 DEBUG 11 NHibernate.Impl.SessionImpl - Flushed: 0 insertions, 0 updates, 0 deletions to 0 objects
2007-03-14 10:30:27,497 DEBUG 11 NHibernate.Impl.SessionImpl - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
2007-03-14 10:30:27,507 DEBUG 11 NHibernate.Impl.SessionImpl - dont need to execute flush
2007-03-14 10:30:27,517 DEBUG 11 NHibernate.Hql.Classic.QueryTranslator - HQL: from NHibernateTest.Item as itm
2007-03-14 10:30:27,687 DEBUG 11 NHibernate.Hql.Classic.QueryTranslator - SQL: select item0_.ID as ID1_, item0_.ActualItemRevisionID as ActualIt2_1_ from Item item0_
2007-03-14 10:30:27,697 DEBUG 11 NHibernate.Impl.BatcherImpl - Opened new IDbCommand, open IDbCommands: 1
2007-03-14 10:30:27,697 DEBUG 11 NHibernate.Impl.BatcherImpl - Building an IDbCommand object for the SqlString: select item0_.ID as ID1_, item0_.ActualItemRevisionID as ActualIt2_1_ from Item item0_
2007-03-14 10:30:27,697 INFO 11 NHibernate.Loader.Loader - select item0_.ID as ID1_, item0_.ActualItemRevisionID as ActualIt2_1_ from Item item0_
2007-03-14 10:30:27,697 INFO 11 NHibernate.Loader.Loader - select item0_.ID as ID1_, item0_.ActualItemRevisionID as ActualIt2_1_ from Item item0_
2007-03-14 10:30:27,707 DEBUG 11 NHibernate.SQL - select item0_.ID as ID1_, item0_.ActualItemRevisionID as ActualIt2_1_ from Item item0_
2007-03-14 10:30:27,908 DEBUG 11 NHibernate.Connection.DriverConnectionProvider - Obtaining IDbConnection from Driver
2007-03-14 10:30:28,028 DEBUG 11 NHibernate.Impl.BatcherImpl - Opened IDataReader, open IDataReaders: 1
2007-03-14 10:30:28,058 DEBUG 11 NHibernate.Driver.NHybridDataReader - running NHybridDataReader.Dispose()
2007-03-14 10:30:28,068 DEBUG 11 NHibernate.Impl.BatcherImpl - Closed IDataReader, open IDataReaders :0
2007-03-14 10:30:28,098 DEBUG 11 NHibernate.Impl.BatcherImpl - Closed IDbCommand, open IDbCommands: 0
2007-03-14 10:30:28,108 DEBUG 11 NHibernate.Impl.ConnectionManager - aggressively releasing database connection
2007-03-14 10:30:28,108 DEBUG 11 NHibernate.Connection.ConnectionProvider - Closing connection
2007-03-14 10:30:28,118 DEBUG 11 NHibernate.Impl.SessionImpl - resolving associations for: [NHibernateTest.Item#1]
2007-03-14 10:30:28,118 DEBUG 11 NHibernate.Impl.SessionImpl - creating collection wrapper:[NHibernateTest.Item.Revisions#1]
2007-03-14 10:30:28,138 DEBUG 11 NHibernate.Impl.BatcherImpl - Opened new IDbCommand, open IDbCommands: 1
2007-03-14 10:30:28,138 DEBUG 11 NHibernate.Impl.BatcherImpl - Building an IDbCommand object for the SqlString: SELECT itemprice0_.ID as ID2_3_, itemprice0_.ItemID as ItemID2_3_, item1_.ID as ID1_0_, item1_.ActualItemRevisionID as ActualIt2_1_0_, revisions2_.ItemID as ItemID__5_, revisions2_.ID as ID5_, revisions2_.ID as ID0_1_, revisions2_.ItemID as ItemID0_1_, itemrevisi3_.ID as ID0_2_, itemrevisi3_.ItemID as ItemID0_2_ FROM ItemPrice itemprice0_ left outer join Item item1_ on itemprice0_.ItemID=item1_.ID left outer join ItemRevision revisions2_ on item1_.ID=revisions2_.ItemID left outer join ItemRevision itemrevisi3_ on item1_.ActualItemRevisionID=itemrevisi3_.ID WHERE itemprice0_.ItemID=?
2007-03-14 10:30:28,338 INFO 11 NHibernate.Loader.Loader - SELECT itemprice0_.ID as ID2_3_, itemprice0_.ItemID as ItemID2_3_, item1_.ID as ID1_0_, item1_.ActualItemRevisionID as ActualIt2_1_0_, revisions2_.ItemID as ItemID__5_, revisions2_.ID as ID5_, revisions2_.ID as ID0_1_, revisions2_.ItemID as ItemID0_1_, itemrevisi3_.ID as ID0_2_, itemrevisi3_.ItemID as ItemID0_2_ FROM ItemPrice itemprice0_ left outer join Item item1_ on itemprice0_.ItemID=item1_.ID left outer join ItemRevision revisions2_ on item1_.ID=revisions2_.ItemID left outer join ItemRevision itemrevisi3_ on item1_.ActualItemRevisionID=itemrevisi3_.ID WHERE itemprice0_.ItemID=@p0
2007-03-14 10:30:28,338 INFO 11 NHibernate.Loader.Loader - SELECT itemprice0_.ID as ID2_3_, itemprice0_.ItemID as ItemID2_3_, item1_.ID as ID1_0_, item1_.ActualItemRevisionID as ActualIt2_1_0_, revisions2_.ItemID as ItemID__5_, revisions2_.ID as ID5_, revisions2_.ID as ID0_1_, revisions2_.ItemID as ItemID0_1_, itemrevisi3_.ID as ID0_2_, itemrevisi3_.ItemID as ItemID0_2_ FROM ItemPrice itemprice0_ left outer join Item item1_ on itemprice0_.ItemID=item1_.ID left outer join ItemRevision revisions2_ on item1_.ID=revisions2_.ItemID left outer join ItemRevision itemrevisi3_ on item1_.ActualItemRevisionID=itemrevisi3_.ID WHERE itemprice0_.ItemID=@p0
2007-03-14 10:30:28,338 DEBUG 11 NHibernate.SQL - SELECT itemprice0_.ID as ID2_3_, itemprice0_.ItemID as ItemID2_3_, item1_.ID as ID1_0_, item1_.ActualItemRevisionID as ActualIt2_1_0_, revisions2_.ItemID as ItemID__5_, revisions2_.ID as ID5_, revisions2_.ID as ID0_1_, revisions2_.ItemID as ItemID0_1_, itemrevisi3_.ID as ID0_2_, itemrevisi3_.ItemID as ItemID0_2_ FROM ItemPrice itemprice0_ left outer join Item item1_ on itemprice0_.ItemID=item1_.ID left outer join ItemRevision revisions2_ on item1_.ID=revisions2_.ItemID left outer join ItemRevision itemrevisi3_ on item1_.ActualItemRevisionID=itemrevisi3_.ID WHERE itemprice0_.ItemID=@p0; @p0 = '1'
2007-03-14 10:30:28,739 DEBUG 11 NHibernate.Connection.DriverConnectionProvider - Obtaining IDbConnection from Driver
2007-03-14 10:30:28,739 DEBUG 11 NHibernate.Impl.BatcherImpl - Opened IDataReader, open IDataReaders: 1
2007-03-14 10:30:28,749 DEBUG 11 NHibernate.Impl.SessionImpl - uninitialized collection: initializing
2007-03-14 10:30:28,759 DEBUG 11 NHibernate.Driver.NHybridDataReader - running NHybridDataReader.Dispose()
2007-03-14 10:30:28,759 DEBUG 11 NHibernate.Impl.BatcherImpl - Closed IDataReader, open IDataReaders :0
2007-03-14 10:30:28,759 DEBUG 11 NHibernate.Impl.BatcherImpl - Closed IDbCommand, open IDbCommands: 0
2007-03-14 10:30:28,759 DEBUG 11 NHibernate.Impl.ConnectionManager - aggressively releasing database connection
2007-03-14 10:30:28,939 DEBUG 11 NHibernate.Connection.ConnectionProvider - Closing connection
2007-03-14 10:30:28,939 DEBUG 11 NHibernate.Impl.SessionImpl - resolving associations for: [NHibernateTest.ItemPrice#2]
2007-03-14 10:30:28,939 DEBUG 11 NHibernate.Impl.SessionImpl - loading [Item#1]
2007-03-14 10:30:28,949 DEBUG 11 NHibernate.Impl.SessionImpl - attempting to resolve [Item#1]
2007-03-14 10:30:28,949 DEBUG 11 NHibernate.Impl.SessionImpl - resolved object in session cache [NHibernateTest.Item#1]
2007-03-14 10:30:28,959 DEBUG 11 NHibernate.Impl.SessionImpl - done materializing entity [NHibernateTest.ItemPrice#2]
2007-03-14 10:30:28,959 DEBUG 11 NHibernate.Impl.SessionImpl - 1 collections were found in result set
2007-03-14 10:30:28,969 DEBUG 11 NHibernate.Impl.SessionImpl - collection fully initialized: [NHibernateTest.Item.Revisions#1]
2007-03-14 10:30:29,170 DEBUG 11 NHibernate.Impl.SessionImpl - 1 collections initialized
2007-03-14 10:30:29,170 DEBUG 11 NHibernate.Impl.SessionImpl - done materializing entity [NHibernateTest.Item#1]
2007-03-14 10:30:29,180 DEBUG 11 NHibernate.Impl.SessionImpl - resolving associations for: [NHibernateTest.Item#2]
2007-03-14 10:30:29,180 DEBUG 11 NHibernate.Impl.SessionImpl - creating collection wrapper:[NHibernateTest.Item.Revisions#2]
2007-03-14 10:30:29,180 DEBUG 11 NHibernate.Impl.SessionImpl - loading [ItemRevision#1]
2007-03-14 10:30:29,180 DEBUG 11 NHibernate.Impl.SessionImpl - attempting to resolve [ItemRevision#1]
2007-03-14 10:30:29,180 DEBUG 11 NHibernate.Impl.SessionImpl - entity does not exist
2007-03-14 10:30:29,220 DEBUG 11 NHibernate.Impl.ConnectionManager - after autocommit
2007-03-14 10:30:29,410 DEBUG 11 NHibernate.Impl.ConnectionManager - aggressively releasing database connection
2007-03-14 10:30:29,410 DEBUG 11 NHibernate.Impl.SessionImpl - transaction completion
Login
FAQ
Search