Thanks for your answer.
I am logging everything now and the exception from NHibernate is (the part which I think matters):
2007-09-04 18:11:39,312 [4864 ] DEBUG ((null) ) ((null)) initializing class SessionFactoryObjectFactory
2007-09-04 18:11:39,312 [4864 ] DEBUG ((null) ) ((null)) registered: e721dd9a84e74d39984c22d47a1d806f(unnamed)
2007-09-04 18:11:39,312 [4864 ] INFO ((null) ) ((null)) no name configured
2007-09-04 18:11:39,312 [4864 ] DEBUG ((null) ) ((null)) Instantiated session factory
2007-09-04 18:11:39,343 [4864 ] DEBUG ((null) ) ((null)) opened session
2007-09-04 18:11:39,390 [4864 ] DEBUG ((null) ) ((null)) The initial capacity was set too low at: 8 for the SelectSqlBuilder that needed a capacity of: 14 for the table users this
2007-09-04 18:11:39,406 [4864 ] DEBUG ((null) ) ((null)) flushing session
2007-09-04 18:11:39,421 [4864 ] DEBUG ((null) ) ((null)) Flushing entities and processing referenced collections
2007-09-04 18:11:39,421 [4864 ] DEBUG ((null) ) ((null)) Processing unreferenced collections
2007-09-04 18:11:39,421 [4864 ] DEBUG ((null) ) ((null)) scheduling collection removes/(re)creates/updates
2007-09-04 18:11:39,421 [4864 ] DEBUG ((null) ) ((null)) Flushed: 0 insertions, 0 updates, 0 deletions to 0 objects
2007-09-04 18:11:39,421 [4864 ] DEBUG ((null) ) ((null)) Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
2007-09-04 18:11:39,437 [4864 ] DEBUG ((null) ) ((null)) dont need to execute flush
2007-09-04 18:11:39,515 [4864 ] DEBUG ((null) ) ((null)) Opened new IDbCommand, open IDbCommands :1
2007-09-04 18:11:39,515 [4864 ] DEBUG ((null) ) ((null)) Building an IDbCommand object for the SqlString: SELECT this.Id as Id0_, this.email as email0_, this.logon as logon0_, this.deleted as deleted0_, this.password as password0_ FROM users this WHERE (this.logon = :this.logon and this.password = :this.password)
2007-09-04 18:11:39,515 [4864 ] DEBUG ((null) ) ((null)) binding 'demo' to parameter: 0
2007-09-04 18:11:39,515 [4864 ] DEBUG ((null) ) ((null)) binding 'demo' to parameter: 1
2007-09-04 18:11:39,515 [4864 ] INFO ((null) ) ((null)) SELECT this.Id as Id0_, this.email as email0_, this.logon as logon0_, this.deleted as deleted0_, this.password as password0_ FROM users this WHERE (this.logon = @p0 and this.password = @p1)
2007-09-04 18:11:39,531 [4864 ] DEBUG ((null) ) ((null)) SELECT this.Id as Id0_, this.email as email0_, this.logon as logon0_, this.deleted as deleted0_, this.password as password0_ FROM users this WHERE (this.logon = @p0 and this.password = @p1)
2007-09-04 18:11:39,531 [4864 ] DEBUG ((null) ) ((null)) @p0 = 'demo'
2007-09-04 18:11:39,531 [4864 ] DEBUG ((null) ) ((null)) @p1 = 'demo'
2007-09-04 18:11:39,531 [4864 ] DEBUG ((null) ) ((null)) Obtaining IDbConnection from Driver
2007-09-04 18:11:39,796 [4864 ] DEBUG ((null) ) ((null)) Opened Reader, open Readers :1
2007-09-04 18:11:39,796 [4864 ] DEBUG ((null) ) ((null)) processing result set
2007-09-04 18:11:39,812 [4864 ] DEBUG ((null) ) ((null)) returning '1' as column: Id0_
2007-09-04 18:11:39,812 [4864 ] DEBUG ((null) ) ((null)) result row: 1
2007-09-04 18:11:39,828 [4864 ] DEBUG ((null) ) ((null)) Initializing object from DataReader: 1
2007-09-04 18:11:39,843 [4864 ] DEBUG ((null) ) ((null)) Hydrating entity: Test.SyncAPI.Contacts.DAO.User#1
2007-09-04 18:11:39,843 [4864 ] DEBUG ((null) ) ((null)) returning '
[email protected]' as column: email0_
2007-09-04 18:11:39,843 [4864 ] DEBUG ((null) ) ((null)) returning 'demo' as column: logon0_
2007-09-04 18:11:39,843 [4864 ] DEBUG ((null) ) ((null)) returning 'False' as column: deleted0_
2007-09-04 18:11:39,843 [4864 ] DEBUG ((null) ) ((null)) returning 'demo' as column: password0_
2007-09-04 18:11:39,843 [4864 ] DEBUG ((null) ) ((null)) done processing result set (1 rows)
2007-09-04 18:11:39,843 [4864 ] DEBUG ((null) ) ((null)) running NHybridDataReader.Dispose()
2007-09-04 18:11:39,859 [4864 ] DEBUG ((null) ) ((null)) Closed Reader, open Readers :0
2007-09-04 18:11:39,859 [4864 ] DEBUG ((null) ) ((null)) Closed IDbCommand, open IDbCommands :0
2007-09-04 18:11:39,859 [4864 ] DEBUG ((null) ) ((null)) total objects hydrated: 1
2007-09-04 18:11:39,859 [4864 ] DEBUG ((null) ) ((null)) resolving associations for: [Test.SyncAPI.Contacts.DAO.User#1]
2007-09-04 18:11:39,875 [4864 ] DEBUG ((null) ) ((null)) creating collection wrapper:[Test.SyncAPI.Contacts.DAO.User.GroupsCollection#1]
2007-09-04 18:11:39,890 [4864 ] DEBUG ((null) ) ((null)) done materializing entity [Test.SyncAPI.Contacts.DAO.User#1]
2007-09-04 18:11:39,890 [4864 ] DEBUG ((null) ) ((null)) initializing non-lazy collections
2007-09-04 18:11:39,890 [4864 ] DEBUG ((null) ) ((null)) initializing collection [Test.SyncAPI.Contacts.DAO.User.GroupsCollection#1]
2007-09-04 18:11:39,890 [4864 ] DEBUG ((null) ) ((null)) checking second-level cache
2007-09-04 18:11:39,890 [4864 ] DEBUG ((null) ) ((null)) collection not cached
2007-09-04 18:11:39,890 [4864 ] DEBUG ((null) ) ((null)) Opened new IDbCommand, open IDbCommands :1
2007-09-04 18:11:39,890 [4864 ] DEBUG ((null) ) ((null)) Building an IDbCommand object for the SqlString: SELECT groupscoll0_.[userId] as [userId__], groupscoll0_.[groupId] as [groupId__], group1_.Id as Id0_, group1_.name as name0_, group1_.groupTypeId as groupTyp3_0_, grouptype2_.Id as Id1_, grouptype2_.name as name1_, grouptype2_.isDefault as isDefault1_ FROM usersGroup groupscoll0_ inner join groups group1_ on groupscoll0_.[groupId]=group1_.Id left outer join groupsType grouptype2_ on group1_.groupTypeId=grouptype2_.Id WHERE groupscoll0_.[userId]=:[userId]
2007-09-04 18:11:39,890 [4864 ] DEBUG ((null) ) ((null)) binding '1' to parameter: 0
2007-09-04 18:11:39,890 [4864 ] INFO ((null) ) ((null)) SELECT groupscoll0_.[userId] as [userId__], groupscoll0_.[groupId] as [groupId__], group1_.Id as Id0_, group1_.name as name0_, group1_.groupTypeId as groupTyp3_0_, grouptype2_.Id as Id1_, grouptype2_.name as name1_, grouptype2_.isDefault as isDefault1_ FROM usersGroup groupscoll0_ inner join groups group1_ on groupscoll0_.[groupId]=group1_.Id left outer join groupsType grouptype2_ on group1_.groupTypeId=grouptype2_.Id WHERE groupscoll0_.[userId]=@p0
2007-09-04 18:11:39,890 [4864 ] DEBUG ((null) ) ((null)) SELECT groupscoll0_.[userId] as [userId__], groupscoll0_.[groupId] as [groupId__], group1_.Id as Id0_, group1_.name as name0_, group1_.groupTypeId as groupTyp3_0_, grouptype2_.Id as Id1_, grouptype2_.name as name1_, grouptype2_.isDefault as isDefault1_ FROM usersGroup groupscoll0_ inner join groups group1_ on groupscoll0_.[groupId]=group1_.Id left outer join groupsType grouptype2_ on group1_.groupTypeId=grouptype2_.Id WHERE groupscoll0_.[userId]=@p0
2007-09-04 18:11:39,890 [4864 ] DEBUG ((null) ) ((null)) @p0 = '1'
2007-09-04 18:11:39,906 [4864 ] DEBUG ((null) ) ((null)) Opened Reader, open Readers :1
2007-09-04 18:11:39,906 [4864 ] DEBUG ((null) ) ((null)) result set contains (possibly empty) collection: [Test.SyncAPI.Contacts.DAO.User.GroupsCollection#1]
2007-09-04 18:11:39,906 [4864 ] DEBUG ((null) ) ((null)) uninitialized collection: initializing
2007-09-04 18:11:39,906 [4864 ] DEBUG ((null) ) ((null)) processing result set
2007-09-04 18:11:39,906 [4864 ] DEBUG ((null) ) ((null)) returning '5' as column: Id0_
2007-09-04 18:11:39,906 [4864 ] DEBUG ((null) ) ((null)) returning '1' as column: Id1_
2007-09-04 18:11:39,906 [4864 ] DEBUG ((null) ) ((null)) result row: 5, 1
2007-09-04 18:11:39,906 [4864 ] DEBUG ((null) ) ((null)) Initializing object from DataReader: 5
2007-09-04 18:11:39,906 [4864 ] DEBUG ((null) ) ((null)) Hydrating entity: Test.SyncAPI.Contacts.DAO.Group#5
2007-09-04 18:11:39,906 [4864 ] DEBUG ((null) ) ((null)) returning 'demo' as column: name0_
2007-09-04 18:11:39,921 [4864 ] DEBUG ((null) ) ((null)) returning '1' as column: groupTyp3_0_
2007-09-04 18:11:39,921 [4864 ] DEBUG ((null) ) ((null)) Initializing object from DataReader: 1
2007-09-04 18:11:39,921 [4864 ] DEBUG ((null) ) ((null)) Hydrating entity: Test.SyncAPI.Contacts.DAO.GroupType#1
2007-09-04 18:11:39,921 [4864 ] DEBUG ((null) ) ((null)) returning 'Private ' as column: name1_
2007-09-04 18:11:39,921 [4864 ] DEBUG ((null) ) ((null)) returning 'True' as column: isDefault1_
2007-09-04 18:11:39,921 [4864 ] DEBUG ((null) ) ((null)) SQL Exception
System.IndexOutOfRangeException: [userId__]
at System.Data.ProviderBase.FieldNameLookup.GetOrdinal(String fieldName)
at System.Data.SqlClient.SqlDataReader.GetOrdinal(String name)
at NHibernate.Driver.NHybridDataReader.GetOrdinal(String name)
at NHibernate.Type.NullableType.NullSafeGet(IDataReader rs, String name)
at NHibernate.Type.NullableType.NullSafeGet(IDataReader rs, String[] names, ISessionImplementor session, Object owner)
at NHibernate.Collection.AbstractCollectionPersister.ReadKey(IDataReader dr, ISessionImplementor session)
at NHibernate.Loader.Loader.ReadCollectionElement(Object optionalOwner, Object optionalKey, IDataReader rs, ISessionImplementor session)
at NHibernate.Loader.Loader.GetRowFromResultSet(IDataReader resultSet, ISessionImplementor session, QueryParameters queryParameters, IList hydratedObjects, Object optionalObject, Object optionalId, Key[] keys, Boolean returnProxies)
at NHibernate.Loader.Loader.DoQuery(ISessionImplementor session, QueryParameters queryParameters, Object optionalObject, Object optionalId, Object[] optionalCollectionKeys, Boolean returnProxies)
2007-09-04 18:11:39,937 [4864 ] WARN ((null) ) ((null)) System.IndexOutOfRangeException: [userId__]
at System.Data.ProviderBase.FieldNameLookup.GetOrdinal(String fieldName)
at System.Data.SqlClient.SqlDataReader.GetOrdinal(String name)
at NHibernate.Driver.NHybridDataReader.GetOrdinal(String name)
at NHibernate.Type.NullableType.NullSafeGet(IDataReader rs, String name)
at NHibernate.Type.NullableType.NullSafeGet(IDataReader rs, String[] names, ISessionImplementor session, Object owner)
at NHibernate.Collection.AbstractCollectionPersister.ReadKey(IDataReader dr, ISessionImplementor session)
at NHibernate.Loader.Loader.ReadCollectionElement(Object optionalOwner, Object optionalKey, IDataReader rs, ISessionImplementor session)
at NHibernate.Loader.Loader.GetRowFromResultSet(IDataReader resultSet, ISessionImplementor session, QueryParameters queryParameters, IList hydratedObjects, Object optionalObject, Object optionalId, Key[] keys, Boolean returnProxies)
at NHibernate.Loader.Loader.DoQuery(ISessionImplementor session, QueryParameters queryParameters, Object optionalObject, Object optionalId, Object[] optionalCollectionKeys, Boolean returnProxies)
2007-09-04 18:11:39,937 [4864 ] ERROR ((null) ) ((null)) [userId__]
2007-09-04 18:11:39,937 [4864 ] DEBUG ((null) ) ((null)) running NHybridDataReader.Dispose()
2007-09-04 18:11:39,937 [4864 ] DEBUG ((null) ) ((null)) Closed Reader, open Readers :0
2007-09-04 18:11:39,937 [4864 ] DEBUG ((null) ) ((null)) Closed IDbCommand, open IDbCommands :0
2007-09-04 18:11:39,937 [4864 ] DEBUG ((null) ) ((null)) could not initialize collection: [Test.SyncAPI.Contacts.DAO.User.GroupsCollection#1]
System.IndexOutOfRangeException: [userId__]
at System.Data.ProviderBase.FieldNameLookup.GetOrdinal(String fieldName)
at System.Data.SqlClient.SqlDataReader.GetOrdinal(String name)
at NHibernate.Driver.NHybridDataReader.GetOrdinal(String name)
at NHibernate.Type.NullableType.NullSafeGet(IDataReader rs, String name)
at NHibernate.Type.NullableType.NullSafeGet(IDataReader rs, String[] names, ISessionImplementor session, Object owner)
at NHibernate.Collection.AbstractCollectionPersister.ReadKey(IDataReader dr, ISessionImplementor session)
at NHibernate.Loader.Loader.ReadCollectionElement(Object optionalOwner, Object optionalKey, IDataReader rs, ISessionImplementor session)
at NHibernate.Loader.Loader.GetRowFromResultSet(IDataReader resultSet, ISessionImplementor session, QueryParameters queryParameters, IList hydratedObjects, Object optionalObject, Object optionalId, Key[] keys, Boolean returnProxies)
at NHibernate.Loader.Loader.DoQuery(ISessionImplementor session, QueryParameters queryParameters, Object optionalObject, Object optionalId, Object[] optionalCollectionKeys, Boolean returnProxies)
at NHibernate.Loader.Loader.DoQueryAndInitializeNonLazyCollections(ISessionImplementor session, QueryParameters queryParameters, Object optionalObject, Object optionalId, Object[] optionalCollectionKeys, Boolean returnProxies)
at NHibernate.Loader.CollectionLoader.Initialize(Object id, ISessionImplementor session)
at NHibernate.Collection.AbstractCollectionPersister.Initialize(Object key, ISessionImplementor session)
2007-09-04 18:11:39,937 [4864 ] WARN ((null) ) ((null)) System.IndexOutOfRangeException: [userId__]
at System.Data.ProviderBase.FieldNameLookup.GetOrdinal(String fieldName)
at System.Data.SqlClient.SqlDataReader.GetOrdinal(String name)
at NHibernate.Driver.NHybridDataReader.GetOrdinal(String name)
at NHibernate.Type.NullableType.NullSafeGet(IDataReader rs, String name)
at NHibernate.Type.NullableType.NullSafeGet(IDataReader rs, String[] names, ISessionImplementor session, Object owner)
at NHibernate.Collection.AbstractCollectionPersister.ReadKey(IDataReader dr, ISessionImplementor session)
at NHibernate.Loader.Loader.ReadCollectionElement(Object optionalOwner, Object optionalKey, IDataReader rs, ISessionImplementor session)
at NHibernate.Loader.Loader.GetRowFromResultSet(IDataReader resultSet, ISessionImplementor session, QueryParameters queryParameters, IList hydratedObjects, Object optionalObject, Object optionalId, Key[] keys, Boolean returnProxies)
at NHibernate.Loader.Loader.DoQuery(ISessionImplementor session, QueryParameters queryParameters, Object optionalObject, Object optionalId, Object[] optionalCollectionKeys, Boolean returnProxies)
at NHibernate.Loader.Loader.DoQueryAndInitializeNonLazyCollections(ISessionImplementor session, QueryParameters queryParameters, Object optionalObject, Object optionalId, Object[] optionalCollectionKeys, Boolean returnProxies)
at NHibernate.Loader.CollectionLoader.Initialize(Object id, ISessionImplementor session)
at NHibernate.Collection.AbstractCollectionPersister.Initialize(Object key, ISessionImplementor session)
2007-09-04 18:11:39,937 [4864 ] ERROR ((null) ) ((null)) [userId__]
exec sp_executesql N'SELECT groupscoll0_.[userId] as [userId__], groupscoll0_.[groupId] as [groupId__], group1_.Id as Id0_, group1_.name as name0_, group1_.groupTypeId as groupTyp3_0_,
grouptype2_.Id as Id1_, grouptype2_.name as name1_, grouptype2_.isDefault as isDefault1_ FROM usersGroup groupscoll0_ inner join groups group1_ on groupscoll0_.[groupId]=group1_.Id left outer
join groupsType grouptype2_ on group1_.groupTypeId=grouptype2_.Id WHERE groupscoll0_.[userId]=@p0',N'@p0 int',@p0=1
I can't believe that's so painful! It should be easy as I am not doing anything complicated.