The upshot of the following is that the Principal.nhIdentity is set correctly on a cache miss (or no cache use at all) but not on a cache hit. Everything appears to work, but in the following case, after the apparently successful load from the cache, an assertion fails.

I'm not sure what the difference is in the two situations. I tried to diagnose this behavior, but I started getting cross-eyed perusing the source...it was a little beyond me. The following is a little hairy; I'll try to distill to a more encapsulated failure case, but for now I'll post the code with which I'm experiencing the trouble.

The Details:

NHibernate version: 1.0.2

Mapping documents:


Code between sessionFactory.openSession() and session.close():
Just

Name and version of the database you are using:MSSQL 8.0 (2000)

The generated SQL (show_sql=true):Not applicable; this appears to only occur on a cache hit, so there's no SQL to show.

Debug level Hibernate log excerpt:
So that everything is clear, I'll show what happens on a cache miss, and then a hit, with what seem to be the relevant differences in bold.

Cache miss:

171241489 [3428] DEBUG TBI.UserDirectory.UnitTest.PersistentFunctionTest (null) - GetUser() (maybe 2nd level cache)
171241489 [3428] DEBUG TBI.UserDirectory.DirectoryManager (null) - GetUser(test)
171241489 [3428] DEBUG NHibernate.Impl.SessionImpl (null) - opened session
171241489 [3428] DEBUG NHibernate.Impl.SessionImpl (null) - loading [TbiUser#test]
171241489 [3428] DEBUG NHibernate.Impl.SessionImpl (null) - attempting to resolve [TbiUser#test]
171241489 [3428] DEBUG NHibernate.Cache.ReadWriteCache (null) - Cache lookup: test
171241489 [3428] DEBUG NHibernate.Cache.ReadWriteCache (null) - Cache miss: test
171241489 [3428] DEBUG NHibernate.Impl.SessionImpl (null) - object not resolved in any cache [TBI.UserDirectory.TbiUser#test]
171241489 [3428] DEBUG NHibernate.Persister.EntityPersister (null) - Materializing entity: TBI.UserDirectory.TbiUser#test
171241499 [3428] DEBUG NHibernate.Impl.BatcherImpl (null) - Opened new IDbCommand, open IDbCommands :1
171241499 [3428] DEBUG NHibernate.Impl.BatcherImpl (null) - Building an IDbCommand object for the SqlString: SELECT tbiuser0_.UserName as UserName1_, tbiuser0_.IsEnabled as IsEnabled1_, tbiuser0_.FullName as FullName1_, tbiuser0_.TimeZoneIndex as TimeZone6_1_, tbiuser0_.passHash as passHash1_, tbiuser0_.Role as Role1_, tbiuser0_.MemberOf as MemberOf1_, tbiuser0_.passSalt as passSalt1_, tbiuser0_.Email as Email1_, tbiuser0_.IMName as IMName1_, tbiuser0_.Version as Version1_, clientorg1_.ID as ID0_, clientorg1_.RootDataBase as RootData6_0_, clientorg1_.RootDataSource as RootData5_0_, clientorg1_.Version as Version0_, clientorg1_.IsEnabled as IsEnabled0_, clientorg1_.Code as Code0_, clientorg1_.Name as Name0_ FROM Users tbiuser0_ left outer join ClientOrganizations clientorg1_ on tbiuser0_.MemberOf=clientorg1_.ID WHERE tbiuser0_.UserName=:UserName
171241499 [3428] DEBUG NHibernate.Type.StringType (null) - binding 'test' to parameter: 0
171241499 [3428] INFO NHibernate.Loader.Loader (null) - SELECT tbiuser0_.UserName as UserName1_, tbiuser0_.IsEnabled as IsEnabled1_, tbiuser0_.FullName as FullName1_, tbiuser0_.TimeZoneIndex as TimeZone6_1_, tbiuser0_.passHash as passHash1_, tbiuser0_.Role as Role1_, tbiuser0_.MemberOf as MemberOf1_, tbiuser0_.passSalt as passSalt1_, tbiuser0_.Email as Email1_, tbiuser0_.IMName as IMName1_, tbiuser0_.Version as Version1_, clientorg1_.ID as ID0_, clientorg1_.RootDataBase as RootData6_0_, clientorg1_.RootDataSource as RootData5_0_, clientorg1_.Version as Version0_, clientorg1_.IsEnabled as IsEnabled0_, clientorg1_.Code as Code0_, clientorg1_.Name as Name0_ FROM Users tbiuser0_ left outer join ClientOrganizations clientorg1_ on tbiuser0_.MemberOf=clientorg1_.ID WHERE tbiuser0_.UserName=@p0
171241499 [3428] DEBUG NHibernate.SQL (null) - SELECT tbiuser0_.UserName as UserName1_, tbiuser0_.IsEnabled as IsEnabled1_, tbiuser0_.FullName as FullName1_, tbiuser0_.TimeZoneIndex as TimeZone6_1_, tbiuser0_.passHash as passHash1_, tbiuser0_.Role as Role1_, tbiuser0_.MemberOf as MemberOf1_, tbiuser0_.passSalt as passSalt1_, tbiuser0_.Email as Email1_, tbiuser0_.IMName as IMName1_, tbiuser0_.Version as Version1_, clientorg1_.ID as ID0_, clientorg1_.RootDataBase as RootData6_0_, clientorg1_.RootDataSource as RootData5_0_, clientorg1_.Version as Version0_, clientorg1_.IsEnabled as IsEnabled0_, clientorg1_.Code as Code0_, clientorg1_.Name as Name0_ FROM Users tbiuser0_ left outer join ClientOrganizations clientorg1_ on tbiuser0_.MemberOf=clientorg1_.ID WHERE tbiuser0_.UserName=@p0
171241499 [3428] DEBUG NHibernate.SQL (null) - @p0 = 'test'
171241499 [3428] DEBUG NHibernate.Connection.DriverConnectionProvider (null) - Obtaining IDbConnection from Driver
171241499 [3428] DEBUG NHibernate.Impl.BatcherImpl (null) - Opened Reader, open Readers :1
171241509 [3428] DEBUG NHibernate.Loader.Loader (null) - processing result set
171241509 [3428] DEBUG NHibernate.Type.Int32Type (null) - returning null as column: ID0_
171241509 [3428] DEBUG NHibernate.Loader.Loader (null) - result row: , test
171241509 [3428] DEBUG TBI.UserDirectory.PrincipalRoleList (null) - ctor( principal )
171241509 [3428] DEBUG NHibernate.Loader.Loader (null) - Initializing object from DataReader: test
171241509 [3428] DEBUG NHibernate.Loader.Loader (null) - Hydrating entity: TBI.UserDirectory.TbiUser#test
171241509 [3428] DEBUG NHibernate.Type.BooleanType (null) - returning 'True' as column: IsEnabled1_
171241509 [3428] DEBUG NHibernate.Type.StringType (null) - returning 'Bill Testing' as column: FullName1_
171241519 [3428] DEBUG NHibernate.Type.Int16Type (null) - returning '35' as column: TimeZone6_1_
171241519 [3428] DEBUG NHibernate.Type.BinaryType (null) - returning 'b082f58805946a9907ae972f9040f2e6b6bc13e8' as column: passHash1_
171241519 [3428] DEBUG NHibernate.Type.PersistentEnumType (null) - returning '1' as column: Role1_
171241519 [3428] DEBUG NHibernate.Type.Int32Type (null) - returning null as column: MemberOf1_
171241519 [3428] DEBUG NHibernate.Type.BinaryType (null) - returning '1c5defe3f40dbfee743f' as column: passSalt1_
171241519 [3428] DEBUG NHibernate.Type.StringType (null) - returning null as column: Email1_
171241519 [3428] DEBUG NHibernate.Type.StringType (null) - returning null as column: IMName1_
171241519 [3428] DEBUG NHibernate.Type.Int16Type (null) - returning '0' as column: Version1_
171241519 [3428] DEBUG NHibernate.Impl.SessionImpl (null) - Version: 0
171241519 [3428] DEBUG NHibernate.Loader.Loader (null) - done processing result set (1 rows)
171241519 [3428] DEBUG NHibernate.Driver.NHybridDataReader (null) - running NHybridDataReader.Dispose()
171241519 [3428] DEBUG NHibernate.Impl.BatcherImpl (null) - Closed Reader, open Readers :0
171241519 [3428] DEBUG NHibernate.Impl.BatcherImpl (null) - Closed IDbCommand, open IDbCommands :0
171241519 [3428] DEBUG NHibernate.Loader.Loader (null) - total objects hydrated: 1
171241519 [3428] DEBUG NHibernate.Impl.SessionImpl (null) - resolving associations for: [TBI.UserDirectory.TbiUser#test]
171241519 [3428] DEBUG TBI.UserDirectory.TbiPrincipal (null) - ctor()
171241519 [3428] DEBUG TBI.UserDirectory.TbiPrincipal (null) - set_nhIdentity: test
171241519 [3428] DEBUG TBI.UserDirectory.PrincipalRoleList (null) - ctor()
171241519 [3428] DEBUG TBI.UserDirectory.PrincipalRoleList (null) - set_nhUser: test
171241529 [3428] DEBUG NHibernate.Impl.SessionImpl (null) - creating collection wrapper:[TBI.UserDirectory.TbiUser.Principal.AppRoles.Roles#test]
171241529 [3428] DEBUG NHibernate.Impl.SessionImpl (null) - adding entity to second-level cache [TBI.UserDirectory.TbiUser#test]
171241529 [3428] DEBUG NHibernate.Cache.ReadWriteCache (null) - Caching: test
171241529 [3428] DEBUG NHibernate.Cache.ReadWriteCache (null) - Cached: test
171241529 [3428] DEBUG TBI.UserDirectory.PrincipalRoleList (null) - ctor()
171241529 [3428] DEBUG TBI.UserDirectory.PrincipalRoleList (null) - get_nhUser: test
171241529 [3428] DEBUG TBI.UserDirectory.PrincipalRoleList (null) - set_nhUser: test
171241529 [3428] DEBUG TBI.UserDirectory.TbiPrincipal (null) - ctor()
171241529 [3428] DEBUG TBI.UserDirectory.TbiPrincipal (null) - get_nhIdentity: test
171241529 [3428] DEBUG TBI.UserDirectory.TbiPrincipal (null) - set_nhIdentity: test
171241529 [3428] DEBUG NHibernate.Impl.SessionImpl (null) - done materializing entity [TBI.UserDirectory.TbiUser#test]
171241529 [3428] DEBUG NHibernate.Impl.SessionImpl (null) - initializing non-lazy collections
171241529 [3428] DEBUG NHibernate.Impl.SessionImpl (null) - initializing collection [TBI.UserDirectory.TbiUser.Principal.AppRoles.Roles#test]
171241529 [3428] DEBUG NHibernate.Impl.SessionImpl (null) - checking second-level cache
171241529 [3428] DEBUG NHibernate.Impl.SessionImpl (null) - collection not cached
171241539 [3428] DEBUG NHibernate.Impl.BatcherImpl (null) - Opened new IDbCommand, open IDbCommands :1
171241539 [3428] DEBUG NHibernate.Impl.BatcherImpl (null) - Building an IDbCommand object for the SqlString: SELECT roles0_.UserName as UserName__, roles0_.RoleID as RoleID__, roles0_.AppInstanceID as AppInsta3___, applicatio1_.ID as ID0_, applicatio1_.Name as Name0_, applicatio1_.ApplicationID as Applicat5_0_, applicatio1_.FlagValue as FlagValue0_, applicatio1_.PermittedRole as Permitte4_0_, applicatio2_.ID as ID1_, applicatio2_.Name as Name1_, applicatio2_.Description as Descript3_1_, applicatio2_.Code as Code1_ FROM UserRoles roles0_ inner join AppRoles applicatio1_ on roles0_.RoleID=applicatio1_.ID left outer join Applications applicatio2_ on applicatio1_.ApplicationID=applicatio2_.ID WHERE roles0_.UserName=:UserName
171241539 [3428] DEBUG NHibernate.Type.StringType (null) - binding 'test' to parameter: 0
171241539 [3428] INFO NHibernate.Loader.Loader (null) - SELECT roles0_.UserName as UserName__, roles0_.RoleID as RoleID__, roles0_.AppInstanceID as AppInsta3___, applicatio1_.ID as ID0_, applicatio1_.Name as Name0_, applicatio1_.ApplicationID as Applicat5_0_, applicatio1_.FlagValue as FlagValue0_, applicatio1_.PermittedRole as Permitte4_0_, applicatio2_.ID as ID1_, applicatio2_.Name as Name1_, applicatio2_.Description as Descript3_1_, applicatio2_.Code as Code1_ FROM UserRoles roles0_ inner join AppRoles applicatio1_ on roles0_.RoleID=applicatio1_.ID left outer join Applications applicatio2_ on applicatio1_.ApplicationID=applicatio2_.ID WHERE roles0_.UserName=@p0
171241539 [3428] DEBUG NHibernate.SQL (null) - SELECT roles0_.UserName as UserName__, roles0_.RoleID as RoleID__, roles0_.AppInstanceID as AppInsta3___, applicatio1_.ID as ID0_, applicatio1_.Name as Name0_, applicatio1_.ApplicationID as Applicat5_0_, applicatio1_.FlagValue as FlagValue0_, applicatio1_.PermittedRole as Permitte4_0_, applicatio2_.ID as ID1_, applicatio2_.Name as Name1_, applicatio2_.Description as Descript3_1_, applicatio2_.Code as Code1_ FROM UserRoles roles0_ inner join AppRoles applicatio1_ on roles0_.RoleID=applicatio1_.ID left outer join Applications applicatio2_ on applicatio1_.ApplicationID=applicatio2_.ID WHERE roles0_.UserName=@p0
171241539 [3428] DEBUG NHibernate.SQL (null) - @p0 = 'test'
171241539 [3428] DEBUG NHibernate.Impl.BatcherImpl (null) - Opened Reader, open Readers :1
171241539 [3428] DEBUG NHibernate.Loader.Loader (null) - result set contains (possibly empty) collection: [TBI.UserDirectory.TbiUser.Principal.AppRoles.Roles#test]
171241539 [3428] DEBUG NHibernate.Impl.SessionImpl (null) - uninitialized collection: initializing
171241539 [3428] DEBUG NHibernate.Loader.Loader (null) - processing result set
171241539 [3428] DEBUG NHibernate.Loader.Loader (null) - done processing result set (0 rows)
171241539 [3428] DEBUG NHibernate.Driver.NHybridDataReader (null) - running NHybridDataReader.Dispose()
171241539 [3428] DEBUG NHibernate.Impl.BatcherImpl (null) - Closed Reader, open Readers :0
171241539 [3428] DEBUG NHibernate.Impl.BatcherImpl (null) - Closed IDbCommand, open IDbCommands :0
171241539 [3428] DEBUG NHibernate.Loader.Loader (null) - total objects hydrated: 0
171241539 [3428] DEBUG NHibernate.Impl.SessionImpl (null) - 1 collections were found in result set
171241549 [3428] DEBUG NHibernate.Impl.SessionImpl (null) - collection fully initialized: [TBI.UserDirectory.TbiUser.Principal.AppRoles.Roles#test]
171241549 [3428] DEBUG NHibernate.Impl.SessionImpl (null) - 1 collections initialized
171241549 [3428] DEBUG NHibernate.Impl.SessionImpl (null) - collection initialized
171241549 [3428] DEBUG NHibernate.Impl.SessionImpl (null) - closing session
171241549 [3428] DEBUG NHibernate.Impl.SessionImpl (null) - disconnecting session
171241549 [3428] DEBUG NHibernate.Connection.ConnectionProvider (null) - Closing connection
171241549 [3428] DEBUG NHibernate.Impl.SessionImpl (null) - transaction completion

And the cache hit:

171241549 [3428] DEBUG TBI.UserDirectory.UnitTest.PersistentFunctionTest (null) - GetUser() (2nd level cache)
171241549 [3428] DEBUG TBI.UserDirectory.DirectoryManager (null) - GetUser(test)
171241549 [3428] DEBUG NHibernate.Impl.SessionImpl (null) - opened session
171241549 [3428] DEBUG NHibernate.Impl.SessionImpl (null) - loading [TbiUser#test]
171241549 [3428] DEBUG NHibernate.Impl.SessionImpl (null) - attempting to resolve [TbiUser#test]
171241549 [3428] DEBUG NHibernate.Cache.ReadWriteCache (null) - Cache lookup: test
171241549 [3428] DEBUG NHibernate.Cache.ReadWriteCache (null) - Cache hit: test
171241549 [3428] DEBUG NHibernate.Impl.SessionImpl (null) - resolved object in second-level cache [TBI.UserDirectory.TbiUser#test]
171241549 [3428] DEBUG TBI.UserDirectory.PrincipalRoleList (null) - ctor( principal )
171241549 [3428] DEBUG NHibernate.Impl.SessionImpl (null) - creating collection wrapper:[TBI.UserDirectory.TbiUser.Principal.AppRoles.Roles#test]
171241549 [3428] DEBUG TBI.UserDirectory.PrincipalRoleList (null) - ctor()
171241549 [3428] DEBUG TBI.UserDirectory.TbiPrincipal (null) - ctor()
171241549 [3428] DEBUG TBI.UserDirectory.PrincipalRoleList (null) - ctor()
171241559 [3428] DEBUG TBI.UserDirectory.PrincipalRoleList (null) - get_nhUser:
171241559 [3428] DEBUG TBI.UserDirectory.PrincipalRoleList (null) - set_nhUser:
171241559 [3428] DEBUG TBI.UserDirectory.TbiPrincipal (null) - ctor()
171241559 [3428] DEBUG TBI.UserDirectory.TbiPrincipal (null) - get_nhIdentity:
171241559 [3428] DEBUG TBI.UserDirectory.TbiPrincipal (null) - set_nhIdentity:
171241559 [3428] DEBUG NHibernate.Impl.SessionImpl (null) - Cached Version: 0
171241559 [3428] DEBUG NHibernate.Impl.SessionImpl (null) - initializing non-lazy collections
171241559 [3428] DEBUG NHibernate.Impl.SessionImpl (null) - initializing collection [TBI.UserDirectory.TbiUser.Principal.AppRoles.Roles#test]
171241559 [3428] DEBUG NHibernate.Impl.SessionImpl (null) - checking second-level cache
171241559 [3428] DEBUG NHibernate.Impl.SessionImpl (null) - collection not cached
171241559 [3428] DEBUG NHibernate.Impl.BatcherImpl (null) - Opened new IDbCommand, open IDbCommands :1
171241559 [3428] DEBUG NHibernate.Impl.BatcherImpl (null) - Building an IDbCommand object for the SqlString: SELECT roles0_.UserName as UserName__, roles0_.RoleID as RoleID__, roles0_.AppInstanceID as AppInsta3___, applicatio1_.ID as ID0_, applicatio1_.Name as Name0_, applicatio1_.ApplicationID as Applicat5_0_, applicatio1_.FlagValue as FlagValue0_, applicatio1_.PermittedRole as Permitte4_0_, applicatio2_.ID as ID1_, applicatio2_.Name as Name1_, applicatio2_.Description as Descript3_1_, applicatio2_.Code as Code1_ FROM UserRoles roles0_ inner join AppRoles applicatio1_ on roles0_.RoleID=applicatio1_.ID left outer join Applications applicatio2_ on applicatio1_.ApplicationID=applicatio2_.ID WHERE roles0_.UserName=:UserName
171241559 [3428] DEBUG NHibernate.Type.StringType (null) - binding 'test' to parameter: 0
171241559 [3428] INFO NHibernate.Loader.Loader (null) - SELECT roles0_.UserName as UserName__, roles0_.RoleID as RoleID__, roles0_.AppInstanceID as AppInsta3___, applicatio1_.ID as ID0_, applicatio1_.Name as Name0_, applicatio1_.ApplicationID as Applicat5_0_, applicatio1_.FlagValue as FlagValue0_, applicatio1_.PermittedRole as Permitte4_0_, applicatio2_.ID as ID1_, applicatio2_.Name as Name1_, applicatio2_.Description as Descript3_1_, applicatio2_.Code as Code1_ FROM UserRoles roles0_ inner join AppRoles applicatio1_ on roles0_.RoleID=applicatio1_.ID left outer join Applications applicatio2_ on applicatio1_.ApplicationID=applicatio2_.ID WHERE roles0_.UserName=@p0
171241559 [3428] DEBUG NHibernate.SQL (null) - SELECT roles0_.UserName as UserName__, roles0_.RoleID as RoleID__, roles0_.AppInstanceID as AppInsta3___, applicatio1_.ID as ID0_, applicatio1_.Name as Name0_, applicatio1_.ApplicationID as Applicat5_0_, applicatio1_.FlagValue as FlagValue0_, applicatio1_.PermittedRole as Permitte4_0_, applicatio2_.ID as ID1_, applicatio2_.Name as Name1_, applicatio2_.Description as Descript3_1_, applicatio2_.Code as Code1_ FROM UserRoles roles0_ inner join AppRoles applicatio1_ on roles0_.RoleID=applicatio1_.ID left outer join Applications applicatio2_ on applicatio1_.ApplicationID=applicatio2_.ID WHERE roles0_.UserName=@p0
171241559 [3428] DEBUG NHibernate.SQL (null) - @p0 = 'test'
171241559 [3428] DEBUG NHibernate.Connection.DriverConnectionProvider (null) - Obtaining IDbConnection from Driver
171241559 [3428] DEBUG NHibernate.Impl.BatcherImpl (null) - Opened Reader, open Readers :1
171241559 [3428] DEBUG NHibernate.Loader.Loader (null) - result set contains (possibly empty) collection: [TBI.UserDirectory.TbiUser.Principal.AppRoles.Roles#test]
171241559 [3428] DEBUG NHibernate.Impl.SessionImpl (null) - uninitialized collection: initializing
171241559 [3428] DEBUG NHibernate.Loader.Loader (null) - processing result set
171241559 [3428] DEBUG NHibernate.Loader.Loader (null) - done processing result set (0 rows)
171241559 [3428] DEBUG NHibernate.Driver.NHybridDataReader (null) - running NHybridDataReader.Dispose()
171241559 [3428] DEBUG NHibernate.Impl.BatcherImpl (null) - Closed Reader, open Readers :0
171241559 [3428] DEBUG NHibernate.Impl.BatcherImpl (null) - Closed IDbCommand, open IDbCommands :0
171241569 [3428] DEBUG NHibernate.Loader.Loader (null) - total objects hydrated: 0
171241569 [3428] DEBUG NHibernate.Impl.SessionImpl (null) - 1 collections were found in result set
171241569 [3428] DEBUG NHibernate.Impl.SessionImpl (null) - collection fully initialized: [TBI.UserDirectory.TbiUser.Principal.AppRoles.Roles#test]
171241569 [3428] DEBUG NHibernate.Impl.SessionImpl (null) - 1 collections initialized
171241569 [3428] DEBUG NHibernate.Impl.SessionImpl (null) - collection initialized
171241569 [3428] DEBUG NHibernate.Impl.SessionImpl (null) - closing session
171241569 [3428] DEBUG NHibernate.Impl.SessionImpl (null) - disconnecting session
171241569 [3428] DEBUG NHibernate.Connection.ConnectionProvider (null) - Closing connection
171241569 [3428] DEBUG NHibernate.Impl.SessionImpl (null) - transaction completion

Hmm, I thought I fixed this in 1.0.2. Please create a simple test case and report it in JIRA.

Done: NH-548

The test case should be integrable with the NH unit tests fairly easily; if you'd prefer it that way, let me know.

Sergey,

I've been working on understanding and perhaps trying to fix this problem, but I'm having some trouble wrapping my head around the difference between the way an object is hydrated from the DB (SessionImpl.InitializeEntity) and from the 2nd level cache (SessionImpl.AssembleCacheEntry). Do you have any tips/ideas on where I should go to solve the problem? Also, is this the best forum to discuss this, or should I use a JIRA comment or perhaps the dev mailing list?

Thanks,
Marc

I don't have much advice, unfortunately. I usually fix such bugs just by stepping through the NHibernate code using a debugger and trying to determine what went wrong.

That's kind of where I was at. Perhaps I'll have another go at it, then.