Need help with Hibernate? Read this first:
http://www.hibernate.org/ForumMailingli ... AskForHelp

Ok, I read it! No luck. Spent the last 3 days trying to solve this.
Here's a brief description:

Started working with Hibernate recently. Implemented a GenericDAO based on this:

http://geekswithblogs.net/billy/archive ... 69607.aspx

Right now I have four tables:

Parents and Child
Customers and Users

Child has a Foreign Key to Parents
Users has a Foreign Key to Customers

Mappings are shown below.

Everything looks just about the same but running similar NUnit tests for Parents/Child and for Customers/Users shows different results.

I have double checked everything (several times actually).

Why different results? It's a mistery to me!
Logs say a column does not exist. I checked and double checked. It's there allright.

If full code is needed please let me know.

Any help is welcome. Thanks for reading!

Hibernate version: NHibernate 1.0.3

Mapping documents:

Child
------
<?xml version="1.0" encoding="utf-8" ?>
<hibernate-mapping xmlns="urn:nhibernate-mapping-2.0">
<class name="Server.DataAccess.Model.Child, Server.DataAccess" table="Children">
<id name="Id" column="id">
<generator class="native" />
</id>
<property name="Fullname" column="fullname" />
<many-to-one name="Parent" class="Server.DataAccess.Model.Parent, Server.DataAccess" column="parent" />
</class>
</hibernate-mapping>

Parent
--------
<?xml version="1.0" encoding="utf-8" ?>
<hibernate-mapping xmlns="urn:nhibernate-mapping-2.0">
<class name="Server.DataAccess.Model.Parent, Server.DataAccess" table="Parents">
<id name="Id" column="id">
<generator class="native" />
</id>
<property name="Fullname" column="fullname" />
<set name="Children" inverse="true">
<key column="parent" />
<one-to-many class="Server.DataAccess.Model.Child, Server.DataAccess" />
</set>
</class>
</hibernate-mapping>

-------------------------------------------------------------------------------------
User
-----
<?xml version="1.0" encoding="utf-8" ?>
<hibernate-mapping xmlns="urn:nhibernate-mapping-2.0">
<class name="Server.DataAccess.Model.User, Server.DataAccess" table="Users">
<id name="Id" column="id">
<generator class="native" />
</id>
<property name="Fullname" column="fullname" />
<many-to-one name="Customer" class="Server.DataAccess.Model.Customer, Server.DataAccess" column="customer" />
</class>
</hibernate-mapping>

Customer
-----------
<?xml version="1.0" encoding="utf-8" ?>
<hibernate-mapping xmlns="urn:nhibernate-mapping-2.0">
<class name="Server.DataAccess.Model.Customer, Server.DataAccess" table="Customers">
<id name="Id" column="id">
<generator class="native" />
</id>
<property name="Fullname" column="fullname" />
<set name="Users" inverse="true">
<key column="customer" />
<one-to-many class="Server.DataAccess.Model.User, Server.DataAccess" />
</set>
</class>
</hibernate-mapping>


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

Code shown here is executed in NUnit:

For Parents
-------------
[Test]
public void FindAll()
{
log.Info("--- FindAll");

ParentsDAO pDAO = new ParentsDAO();
List<Parent> parents = pDAO.FindAll();
pDAO.GetSession().Close();

for (int index = 0; index < parents.Count; index++)
{
log.Info("--- Parent");
Parent parent = parents[index];
log.Info("[Parent] Id: " + parent.Id);
log.Info("[Parent] Fullname: " + parent.Fullname);
ISet children = parent.Children;
foreach (Child child in children)
{
log.Info("[Parent] [Child] Id: " + child.Id);
log.Info("[Parent] [Child] Fullname: " + child.Fullname);
}
}
}


-------------------------------------------------------------------------------------

For Customers
-----------------

[Test]
public void FindAll()
{
log.Info("--- FindAll");

CustomersDAO cDAO = new CustomersDAO();
List<Customer> customers = cDAO.FindAll();
cDAO.GetSession().Close();

for (int index = 0; index < customers.Count; index++)
{
log.Info("--- Customer");
Customer customer = customers[index];
log.Info("[Customer] Id: " + customer.Id);
log.Info("[Customer] Fullname: " + customer.Fullname);
ISet users = customer.Users;
foreach (User user in users)
{
log.Info("[Customer] [User] Id: " + user.Id);
log.Info("[Customer] [User] Fullname: " + user.Fullname);
}
}
}

Full stack trace of any exception that occurs:

Test code for ParentsDAO works fine.
Test code for CustomersDAO fails:

at NHibernate.Collection.AbstractCollectionPersister.Initialize(Object key, ISessionImplementor session)
at NHibernate.Impl.SessionImpl.InitializeCollection(PersistentCollection collection, Boolean writing)
at NHibernate.Collection.PersistentCollection.ForceInitialization()
at NHibernate.Impl.SessionImpl.InitializeNonLazyCollections()
at NHibernate.Loader.Loader.DoQueryAndInitializeNonLazyCollections(ISessionImplementor session, QueryParameters queryParameters, Object optionalObject, Object optionalId, Object[] optionalCollectionKeys, Boolean returnProxies)
at NHibernate.Loader.Loader.List(ISessionImplementor session, QueryParameters queryParameters, ISet querySpaces, IType[] resultTypes)
at NHibernate.Loader.CriteriaLoader.List(ISessionImplementor session)
at NHibernate.Impl.SessionImpl.Find(CriteriaImpl criteria)
at NHibernate.Impl.CriteriaImpl.List()
at Framework.DataAccess.GenericDAO`2.FindByCriteria(ICriterion[] criterion) in D:\My Projects\Gateway\trunk\src\Framework\Framework.DataAccess\GenericDAO.cs:line 40
at Framework.DataAccess.GenericDAO`2.FindAll() in D:\My Projects\Gateway\trunk\src\Framework\Framework.DataAccess\GenericDAO.cs:line 66
at Server.UnitTest.DataAccess.CustomersDAOTest.FindAll() in D:\My Projects\Gateway\trunk\src\Server\Server.UnitTest\DataAccess\CustomersDAOTest.cs:line 33
--ADOException
at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection)
at System.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection)
at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj)
at System.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj)
at System.Data.SqlClient.SqlDataReader.ConsumeMetaData()
at System.Data.SqlClient.SqlDataReader.get_MetaData()
at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString)
at System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async)
at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, DbAsyncResult result)
at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method)
at System.Data.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior, String method)
at System.Data.SqlClient.SqlCommand.ExecuteDbDataReader(CommandBehavior behavior)
at System.Data.Common.DbCommand.System.Data.IDbCommand.ExecuteReader()
at NHibernate.Impl.BatcherImpl.ExecuteReader(IDbCommand cmd)
at NHibernate.Loader.Loader.GetResultSet(IDbCommand st, RowSelection selection, ISessionImplementor session)
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.OneToManyLoader.Initialize(Object id, ISessionImplementor session)
at NHibernate.Collection.AbstractCollectionPersister.Initialize(Object key, ISessionImplementor session)

Name and version of the database you are using:

SQL Server 2005

The generated SQL (show_sql=true):

2006-11-09 10:22:16,562 [TestRunnerThread] DEBUG SELECT this.id as id0_, this.fullname as fullname0_ FROM Customers this WHERE 1=1
2006-11-09 10:22:17,015 [TestRunnerThread] DEBUG SELECT users0_.customer as customer__, users0_.id as id__, users0_.id as id0_, users0_.fullname as fullname0_, users0_.customer as customer0_ FROM Users users0_ WHERE users0_.customer=@p0
2006-11-09 10:22:17,015 [TestRunnerThread] DEBUG @p0 = '8'
2006-11-09 10:22:17,187 [TestRunnerThread] DEBUG SELECT this.id as id0_, this.fullname as fullname0_ FROM Parents this WHERE 1=1
2006-11-09 10:22:17,218 [TestRunnerThread] DEBUG SELECT children0_.parent as parent__, children0_.id as id__, children0_.id as id0_, children0_.parent as parent0_, children0_.fullname as fullname0_ FROM Children children0_ WHERE children0_.parent=@p0
2006-11-09 10:22:17,218 [TestRunnerThread] DEBUG @p0 = '2'
2006-11-09 10:22:17,265 [TestRunnerThread] DEBUG SELECT children0_.parent as parent__, children0_.id as id__, children0_.id as id0_, children0_.parent as parent0_, children0_.fullname as fullname0_ FROM Children children0_ WHERE children0_.parent=@p0
2006-11-09 10:22:17,265 [TestRunnerThread] DEBUG @p0 = '1'

Debug level Hibernate log excerpt:

2006-11-09 10:22:15,000 [TestRunnerThread] INFO NHibernate 1.0.2
2006-11-09 10:22:15,000 [TestRunnerThread] INFO Using reflection optimizer
2006-11-09 10:22:15,000 [TestRunnerThread] INFO Searching for mapped documents in assembly: Server.DataAccess
2006-11-09 10:22:15,015 [TestRunnerThread] INFO Found mapping documents in assembly: Server.DataAccess.Model.Child.hbm.xml
2006-11-09 10:22:15,437 [TestRunnerThread] INFO Using dialect: NHibernate.Dialect.MsSql2000Dialect
2006-11-09 10:22:15,515 [TestRunnerThread] INFO Mapping class: Server.DataAccess.Model.Child -> Children
2006-11-09 10:22:15,546 [TestRunnerThread] DEBUG Mapped property: Id -> id, type: Int32
2006-11-09 10:22:15,562 [TestRunnerThread] DEBUG Mapped property: Fullname -> fullname, type: String
2006-11-09 10:22:15,562 [TestRunnerThread] DEBUG Mapped property: Parent -> parent, type: Parent
2006-11-09 10:22:15,562 [TestRunnerThread] INFO Found mapping documents in assembly: Server.DataAccess.Model.Customer.hbm.xml
2006-11-09 10:22:15,562 [TestRunnerThread] INFO Using dialect: NHibernate.Dialect.MsSql2000Dialect
2006-11-09 10:22:15,562 [TestRunnerThread] INFO Mapping class: Server.DataAccess.Model.Customer -> Customers
2006-11-09 10:22:15,562 [TestRunnerThread] DEBUG Mapped property: Id -> id, type: Int32
2006-11-09 10:22:15,562 [TestRunnerThread] DEBUG Mapped property: Fullname -> fullname, type: String
2006-11-09 10:22:15,578 [TestRunnerThread] DEBUG Mapped property: Users, type: ISet
2006-11-09 10:22:15,578 [TestRunnerThread] INFO Found mapping documents in assembly: Server.DataAccess.Model.Parent.hbm.xml
2006-11-09 10:22:15,578 [TestRunnerThread] INFO Using dialect: NHibernate.Dialect.MsSql2000Dialect
2006-11-09 10:22:15,578 [TestRunnerThread] INFO Mapping class: Server.DataAccess.Model.Parent -> Parents
2006-11-09 10:22:15,578 [TestRunnerThread] DEBUG Mapped property: Id -> id, type: Int32
2006-11-09 10:22:15,578 [TestRunnerThread] DEBUG Mapped property: Fullname -> fullname, type: String
2006-11-09 10:22:15,593 [TestRunnerThread] DEBUG Mapped property: Children, type: ISet
2006-11-09 10:22:15,593 [TestRunnerThread] INFO Found mapping documents in assembly: Server.DataAccess.Model.User.hbm.xml
2006-11-09 10:22:15,593 [TestRunnerThread] INFO Using dialect: NHibernate.Dialect.MsSql2000Dialect
2006-11-09 10:22:15,593 [TestRunnerThread] INFO Mapping class: Server.DataAccess.Model.User -> Users
2006-11-09 10:22:15,593 [TestRunnerThread] DEBUG Mapped property: Id -> id, type: Int32
2006-11-09 10:22:15,593 [TestRunnerThread] DEBUG Mapped property: Fullname -> fullname, type: String
2006-11-09 10:22:15,593 [TestRunnerThread] DEBUG Mapped property: Customer -> customer, type: Customer
2006-11-09 10:22:15,593 [TestRunnerThread] INFO processing one-to-many association mappings
2006-11-09 10:22:15,593 [TestRunnerThread] DEBUG Second pass for collection: Server.DataAccess.Model.Customer.Users
2006-11-09 10:22:15,609 [TestRunnerThread] INFO mapping collection: Server.DataAccess.Model.Customer.Users -> Users
2006-11-09 10:22:15,609 [TestRunnerThread] DEBUG Mapped collection key: customer, one-to-many: User
2006-11-09 10:22:15,609 [TestRunnerThread] DEBUG Second pass for collection: Server.DataAccess.Model.Parent.Children
2006-11-09 10:22:15,609 [TestRunnerThread] INFO mapping collection: Server.DataAccess.Model.Parent.Children -> Children
2006-11-09 10:22:15,609 [TestRunnerThread] DEBUG Mapped collection key: parent, one-to-many: Child
2006-11-09 10:22:15,609 [TestRunnerThread] INFO processing one-to-one association property references
2006-11-09 10:22:15,609 [TestRunnerThread] INFO processing foreign key constraints
2006-11-09 10:22:15,609 [TestRunnerThread] DEBUG resolving reference to class: Parent
2006-11-09 10:22:15,609 [TestRunnerThread] DEBUG resolving reference to class: Customer
2006-11-09 10:22:15,625 [TestRunnerThread] INFO Using dialect: NHibernate.Dialect.MsSql2000Dialect
2006-11-09 10:22:15,625 [TestRunnerThread] INFO use outer join fetching: True
2006-11-09 10:22:15,625 [TestRunnerThread] INFO Intitializing connection provider: NHibernate.Connection.DriverConnectionProvider
2006-11-09 10:22:15,625 [TestRunnerThread] INFO Configuring ConnectionProvider
2006-11-09 10:22:15,625 [TestRunnerThread] INFO Optimize cache for minimal puts: False
2006-11-09 10:22:15,625 [TestRunnerThread] INFO echoing all SQL to stdout
2006-11-09 10:22:15,625 [TestRunnerThread] INFO Query language substitutions: {}
2006-11-09 10:22:15,625 [TestRunnerThread] INFO cache provider: NHibernate.Cache.HashtableCacheProvider
2006-11-09 10:22:15,640 [TestRunnerThread] INFO instantiating and configuring caches
2006-11-09 10:22:15,640 [TestRunnerThread] INFO building session factory
2006-11-09 10:22:15,640 [TestRunnerThread] DEBUG instantiating session factory with properties: {hibernate.connection.driver_class=NHibernate.Driver.SqlClientDriver, hibernate.dialect=NHibernate.Dialect.MsSql2000Dialect, hibernate.connection.provider=NHibernate.Connection.DriverConnectionProvider, hibernate.use_reflection_optimizer=True, hibernate.show_sql=true, hibernate.connection.connection_string=Server=localhost;initial catalog=Gateway_Head;Integrated Security=SSPI}
2006-11-09 10:22:15,687 [TestRunnerThread] DEBUG Init compiler for class Server.DataAccess.Model.Parent
2006-11-09 10:22:15,687 [TestRunnerThread] DEBUG Adding referenced assembly C:\Documents and Settings\JCLopes\Local Settings\Temp\nunit20\ShadowCopyCache\632986645337343750\Tests\assembly\dl3\2851327c\144abc6a_c3fdc601\NHibernate.DLL
2006-11-09 10:22:15,687 [TestRunnerThread] DEBUG Adding referenced assembly C:\Documents and Settings\JCLopes\Local Settings\Temp\nunit20\ShadowCopyCache\632986645337343750\Tests\assembly\dl3\783b769a\3e2486d7_9603c701\Server.DataAccess.DLL
2006-11-09 10:22:15,687 [TestRunnerThread] DEBUG Adding referenced assembly C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\mscorlib.dll
2006-11-09 10:22:15,687 [TestRunnerThread] DEBUG Adding referenced assembly C:\Documents and Settings\JCLopes\Local Settings\Temp\nunit20\ShadowCopyCache\632986645337343750\Tests\assembly\dl3\c404e65b\ca609e0d_bd02c701\Framework.DataAccess.DLL
2006-11-09 10:22:15,687 [TestRunnerThread] DEBUG Adding referenced assembly C:\Documents and Settings\JCLopes\Local Settings\Temp\nunit20\ShadowCopyCache\632986645337343750\Tests\assembly\dl3\0e59fb0d\f8fbad6a_c3fdc601\Iesi.Collections.DLL
2006-11-09 10:22:15,906 [TestRunnerThread] DEBUG Compiled ok:
using System;
using NHibernate.Property;
namespace NHibernate.Persister {
public class GetSetHelper_Server_DataAccess_Model_Parent : IGetSetHelper {
ISetter[] setters;
IGetter[] getters;
public GetSetHelper_Server_DataAccess_Model_Parent(ISetter[] setters, IGetter[] getters) {
this.setters = setters;
this.getters = getters;
}
public void SetPropertyValues(object obj, object[] values) {
Server.DataAccess.Model.Parent t = (Server.DataAccess.Model.Parent)obj;
try
{
t.Children = (Iesi.Collections.ISet)values[0];
t.Fullname = (System.String)values[1];
}
catch( InvalidCastException ice )
{
throw new MappingException(
"Invalid mapping information specified for type " + obj.GetType() + ", check your mapping file for property type mismatches",
ice);
}
}
public object[] GetPropertyValues(object obj) {
Server.DataAccess.Model.Parent t = (Server.DataAccess.Model.Parent)obj;
object[] ret = new object[2];
ret[0] = t.Children;
ret[1] = t.Fullname;
return ret;
}
}
}

2006-11-09 10:22:15,921 [TestRunnerThread] DEBUG Init compiler for class Server.DataAccess.Model.User
2006-11-09 10:22:15,921 [TestRunnerThread] DEBUG Adding referenced assembly C:\Documents and Settings\JCLopes\Local Settings\Temp\nunit20\ShadowCopyCache\632986645337343750\Tests\assembly\dl3\2851327c\144abc6a_c3fdc601\NHibernate.DLL
2006-11-09 10:22:15,921 [TestRunnerThread] DEBUG Adding referenced assembly C:\Documents and Settings\JCLopes\Local Settings\Temp\nunit20\ShadowCopyCache\632986645337343750\Tests\assembly\dl3\783b769a\3e2486d7_9603c701\Server.DataAccess.DLL
2006-11-09 10:22:15,921 [TestRunnerThread] DEBUG Adding referenced assembly C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\mscorlib.dll
2006-11-09 10:22:15,921 [TestRunnerThread] DEBUG Adding referenced assembly C:\Documents and Settings\JCLopes\Local Settings\Temp\nunit20\ShadowCopyCache\632986645337343750\Tests\assembly\dl3\c404e65b\ca609e0d_bd02c701\Framework.DataAccess.DLL
2006-11-09 10:22:15,937 [TestRunnerThread] DEBUG Adding referenced assembly C:\Documents and Settings\JCLopes\Local Settings\Temp\nunit20\ShadowCopyCache\632986645337343750\Tests\assembly\dl3\0e59fb0d\f8fbad6a_c3fdc601\Iesi.Collections.DLL
2006-11-09 10:22:16,093 [TestRunnerThread] DEBUG Compiled ok:
using System;
using NHibernate.Property;
namespace NHibernate.Persister {
public class GetSetHelper_Server_DataAccess_Model_User : IGetSetHelper {
ISetter[] setters;
IGetter[] getters;
public GetSetHelper_Server_DataAccess_Model_User(ISetter[] setters, IGetter[] getters) {
this.setters = setters;
this.getters = getters;
}
public void SetPropertyValues(object obj, object[] values) {
Server.DataAccess.Model.User t = (Server.DataAccess.Model.User)obj;
try
{
t.Fullname = (System.String)values[0];
t.Customer = (Server.DataAccess.Model.Customer)values[1];
}
catch( InvalidCastException ice )
{
throw new MappingException(
"Invalid mapping information specified for type " + obj.GetType() + ", check your mapping file for property type mismatches",
ice);
}
}
public object[] GetPropertyValues(object obj) {
Server.DataAccess.Model.User t = (Server.DataAccess.Model.User)obj;
object[] ret = new object[2];
ret[0] = t.Fullname;
ret[1] = t.Customer;
return ret;
}
}
}

2006-11-09 10:22:16,093 [TestRunnerThread] DEBUG Init compiler for class Server.DataAccess.Model.Child
2006-11-09 10:22:16,093 [TestRunnerThread] DEBUG Adding referenced assembly C:\Documents and Settings\JCLopes\Local Settings\Temp\nunit20\ShadowCopyCache\632986645337343750\Tests\assembly\dl3\2851327c\144abc6a_c3fdc601\NHibernate.DLL
2006-11-09 10:22:16,093 [TestRunnerThread] DEBUG Adding referenced assembly C:\Documents and Settings\JCLopes\Local Settings\Temp\nunit20\ShadowCopyCache\632986645337343750\Tests\assembly\dl3\783b769a\3e2486d7_9603c701\Server.DataAccess.DLL
2006-11-09 10:22:16,093 [TestRunnerThread] DEBUG Adding referenced assembly C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\mscorlib.dll
2006-11-09 10:22:16,093 [TestRunnerThread] DEBUG Adding referenced assembly C:\Documents and Settings\JCLopes\Local Settings\Temp\nunit20\ShadowCopyCache\632986645337343750\Tests\assembly\dl3\c404e65b\ca609e0d_bd02c701\Framework.DataAccess.DLL
2006-11-09 10:22:16,093 [TestRunnerThread] DEBUG Adding referenced assembly C:\Documents and Settings\JCLopes\Local Settings\Temp\nunit20\ShadowCopyCache\632986645337343750\Tests\assembly\dl3\0e59fb0d\f8fbad6a_c3fdc601\Iesi.Collections.DLL
2006-11-09 10:22:16,250 [TestRunnerThread] DEBUG Compiled ok:
using System;
using NHibernate.Property;
namespace NHibernate.Persister {
public class GetSetHelper_Server_DataAccess_Model_Child : IGetSetHelper {
ISetter[] setters;
IGetter[] getters;
public GetSetHelper_Server_DataAccess_Model_Child(ISetter[] setters, IGetter[] getters) {
this.setters = setters;
this.getters = getters;
}
public void SetPropertyValues(object obj, object[] values) {
Server.DataAccess.Model.Child t = (Server.DataAccess.Model.Child)obj;
try
{
t.Parent = (Server.DataAccess.Model.Parent)values[0];
t.Fullname = (System.String)values[1];
}
catch( InvalidCastException ice )
{
throw new MappingException(
"Invalid mapping information specified for type " + obj.GetType() + ", check your mapping file for property type mismatches",
ice);
}
}
public object[] GetPropertyValues(object obj) {
Server.DataAccess.Model.Child t = (Server.DataAccess.Model.Child)obj;
object[] ret = new object[2];
ret[0] = t.Parent;
ret[1] = t.Fullname;
return ret;
}
}
}

2006-11-09 10:22:16,250 [TestRunnerThread] DEBUG Init compiler for class Server.DataAccess.Model.Customer
2006-11-09 10:22:16,250 [TestRunnerThread] DEBUG Adding referenced assembly C:\Documents and Settings\JCLopes\Local Settings\Temp\nunit20\ShadowCopyCache\632986645337343750\Tests\assembly\dl3\2851327c\144abc6a_c3fdc601\NHibernate.DLL
2006-11-09 10:22:16,250 [TestRunnerThread] DEBUG Adding referenced assembly C:\Documents and Settings\JCLopes\Local Settings\Temp\nunit20\ShadowCopyCache\632986645337343750\Tests\assembly\dl3\783b769a\3e2486d7_9603c701\Server.DataAccess.DLL
2006-11-09 10:22:16,250 [TestRunnerThread] DEBUG Adding referenced assembly C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\mscorlib.dll
2006-11-09 10:22:16,250 [TestRunnerThread] DEBUG Adding referenced assembly C:\Documents and Settings\JCLopes\Local Settings\Temp\nunit20\ShadowCopyCache\632986645337343750\Tests\assembly\dl3\c404e65b\ca609e0d_bd02c701\Framework.DataAccess.DLL
2006-11-09 10:22:16,265 [TestRunnerThread] DEBUG Adding referenced assembly C:\Documents and Settings\JCLopes\Local Settings\Temp\nunit20\ShadowCopyCache\632986645337343750\Tests\assembly\dl3\0e59fb0d\f8fbad6a_c3fdc601\Iesi.Collections.DLL
2006-11-09 10:22:16,406 [TestRunnerThread] DEBUG Compiled ok:
using System;
using NHibernate.Property;
namespace NHibernate.Persister {
public class GetSetHelper_Server_DataAccess_Model_Customer : IGetSetHelper {
ISetter[] setters;
IGetter[] getters;
public GetSetHelper_Server_DataAccess_Model_Customer(ISetter[] setters, IGetter[] getters) {
this.setters = setters;
this.getters = getters;
}
public void SetPropertyValues(object obj, object[] values) {
Server.DataAccess.Model.Customer t = (Server.DataAccess.Model.Customer)obj;
try
{
t.Fullname = (System.String)values[0];
t.Users = (Iesi.Collections.ISet)values[1];
}
catch( InvalidCastException ice )
{
throw new MappingException(
"Invalid mapping information specified for type " + obj.GetType() + ", check your mapping file for property type mismatches",
ice);
}
}
public object[] GetPropertyValues(object obj) {
Server.DataAccess.Model.Customer t = (Server.DataAccess.Model.Customer)obj;
object[] ret = new object[2];
ret[0] = t.Fullname;
ret[1] = t.Users;
return ret;
}
}
}

2006-11-09 10:22:16,500 [TestRunnerThread] DEBUG initializing class SessionFactoryObjectFactory
2006-11-09 10:22:16,500 [TestRunnerThread] DEBUG registered: f2de4b91f2f144079fa5dfc4be02cc0a(unnamed)
2006-11-09 10:22:16,500 [TestRunnerThread] INFO no name configured
2006-11-09 10:22:16,500 [TestRunnerThread] DEBUG Instantiated session factory
2006-11-09 10:22:16,515 [TestRunnerThread] DEBUG opened session
2006-11-09 10:22:16,515 [TestRunnerThread] DEBUG flushing session
2006-11-09 10:22:16,531 [TestRunnerThread] DEBUG Flushing entities and processing referenced collections
2006-11-09 10:22:16,531 [TestRunnerThread] DEBUG Processing unreferenced collections
2006-11-09 10:22:16,531 [TestRunnerThread] DEBUG scheduling collection removes/(re)creates/updates
2006-11-09 10:22:16,531 [TestRunnerThread] DEBUG Flushed: 0 insertions, 0 updates, 0 deletions to 0 objects
2006-11-09 10:22:16,531 [TestRunnerThread] DEBUG Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
2006-11-09 10:22:16,531 [TestRunnerThread] DEBUG dont need to execute flush
2006-11-09 10:22:16,562 [TestRunnerThread] DEBUG Opened new IDbCommand, open IDbCommands :1
2006-11-09 10:22:16,562 [TestRunnerThread] DEBUG Building an IDbCommand object for the SqlString: SELECT this.id as id0_, this.fullname as fullname0_ FROM Customers this WHERE 1=1
2006-11-09 10:22:16,562 [TestRunnerThread] INFO SELECT this.id as id0_, this.fullname as fullname0_ FROM Customers this WHERE 1=1
2006-11-09 10:22:16,562 [TestRunnerThread] DEBUG SELECT this.id as id0_, this.fullname as fullname0_ FROM Customers this WHERE 1=1
2006-11-09 10:22:16,578 [TestRunnerThread] DEBUG Obtaining IDbConnection from Driver
2006-11-09 10:22:16,937 [TestRunnerThread] DEBUG Opened Reader, open Readers :1
2006-11-09 10:22:16,937 [TestRunnerThread] DEBUG processing result set
2006-11-09 10:22:16,953 [TestRunnerThread] DEBUG returning '1' as column: id0_
2006-11-09 10:22:16,953 [TestRunnerThread] DEBUG result row: 1
2006-11-09 10:22:16,968 [TestRunnerThread] DEBUG Initializing object from DataReader: 1
2006-11-09 10:22:16,968 [TestRunnerThread] DEBUG Hydrating entity: Server.DataAccess.Model.Customer#1
2006-11-09 10:22:16,968 [TestRunnerThread] DEBUG returning 'Clínica Médica e Dentária da Praça de Espanha Lda' as column: fullname0_
2006-11-09 10:22:16,984 [TestRunnerThread] DEBUG returning '2' as column: id0_
2006-11-09 10:22:16,984 [TestRunnerThread] DEBUG result row: 2
2006-11-09 10:22:16,984 [TestRunnerThread] DEBUG Initializing object from DataReader: 2
2006-11-09 10:22:16,984 [TestRunnerThread] DEBUG Hydrating entity: Server.DataAccess.Model.Customer#2
2006-11-09 10:22:16,984 [TestRunnerThread] DEBUG returning 'Quadrantes-Clínica Médica e Diagnóstico' as column: fullname0_
2006-11-09 10:22:16,984 [TestRunnerThread] DEBUG returning '3' as column: id0_
2006-11-09 10:22:16,984 [TestRunnerThread] DEBUG result row: 3
2006-11-09 10:22:16,984 [TestRunnerThread] DEBUG Initializing object from DataReader: 3
2006-11-09 10:22:16,984 [TestRunnerThread] DEBUG Hydrating entity: Server.DataAccess.Model.Customer#3
2006-11-09 10:22:16,984 [TestRunnerThread] DEBUG returning 'Aqualab-Laboratório Clínico e de Saúde Pública Lda' as column: fullname0_
2006-11-09 10:22:16,984 [TestRunnerThread] DEBUG returning '4' as column: id0_
2006-11-09 10:22:16,984 [TestRunnerThread] DEBUG result row: 4
2006-11-09 10:22:16,984 [TestRunnerThread] DEBUG Initializing object from DataReader: 4
2006-11-09 10:22:16,984 [TestRunnerThread] DEBUG Hydrating entity: Server.DataAccess.Model.Customer#4
2006-11-09 10:22:16,984 [TestRunnerThread] DEBUG returning 'Clinatal-Clínica Medicina Familiar e Saúde da Mulher Lda' as column: fullname0_
2006-11-09 10:22:16,984 [TestRunnerThread] DEBUG returning '5' as column: id0_
2006-11-09 10:22:16,984 [TestRunnerThread] DEBUG result row: 5
2006-11-09 10:22:16,984 [TestRunnerThread] DEBUG Initializing object from DataReader: 5
2006-11-09 10:22:16,984 [TestRunnerThread] DEBUG Hydrating entity: Server.DataAccess.Model.Customer#5
2006-11-09 10:22:16,984 [TestRunnerThread] DEBUG returning 'Clínica de Ressonância Magnética do Algarve Lda' as column: fullname0_
2006-11-09 10:22:16,984 [TestRunnerThread] DEBUG returning '6' as column: id0_
2006-11-09 10:22:16,984 [TestRunnerThread] DEBUG result row: 6
2006-11-09 10:22:16,984 [TestRunnerThread] DEBUG Initializing object from DataReader: 6
2006-11-09 10:22:16,984 [TestRunnerThread] DEBUG Hydrating entity: Server.DataAccess.Model.Customer#6
2006-11-09 10:22:16,984 [TestRunnerThread] DEBUG returning 'Moiticare-Clínica Médica Lda' as column: fullname0_
2006-11-09 10:22:16,984 [TestRunnerThread] DEBUG returning '7' as column: id0_
2006-11-09 10:22:16,984 [TestRunnerThread] DEBUG result row: 7
2006-11-09 10:22:16,984 [TestRunnerThread] DEBUG Initializing object from DataReader: 7
2006-11-09 10:22:16,984 [TestRunnerThread] DEBUG Hydrating entity: Server.DataAccess.Model.Customer#7
2006-11-09 10:22:16,984 [TestRunnerThread] DEBUG returning 'Clínica Internacional de Saúde de Cascais-(CIS Cascais)' as column: fullname0_
2006-11-09 10:22:16,984 [TestRunnerThread] DEBUG returning '8' as column: id0_
2006-11-09 10:22:16,984 [TestRunnerThread] DEBUG result row: 8
2006-11-09 10:22:16,984 [TestRunnerThread] DEBUG Initializing object from DataReader: 8
2006-11-09 10:22:16,984 [TestRunnerThread] DEBUG Hydrating entity: Server.DataAccess.Model.Customer#8
2006-11-09 10:22:16,984 [TestRunnerThread] DEBUG returning 'Medicoral-Cliníca Médica e Dentária Lda' as column: fullname0_
2006-11-09 10:22:16,984 [TestRunnerThread] DEBUG done processing result set (8 rows)
2006-11-09 10:22:16,984 [TestRunnerThread] DEBUG running NHybridDataReader.Dispose()
2006-11-09 10:22:16,984 [TestRunnerThread] DEBUG Closed Reader, open Readers :0
2006-11-09 10:22:16,984 [TestRunnerThread] DEBUG Closed IDbCommand, open IDbCommands :0
2006-11-09 10:22:16,984 [TestRunnerThread] DEBUG total objects hydrated: 8
2006-11-09 10:22:16,984 [TestRunnerThread] DEBUG resolving associations for: [Server.DataAccess.Model.Customer#1]
2006-11-09 10:22:16,984 [TestRunnerThread] DEBUG creating collection wrapper:[Server.DataAccess.Model.Customer.Users#1]
2006-11-09 10:22:17,000 [TestRunnerThread] DEBUG done materializing entity [Server.DataAccess.Model.Customer#1]
2006-11-09 10:22:17,000 [TestRunnerThread] DEBUG resolving associations for: [Server.DataAccess.Model.Customer#2]
2006-11-09 10:22:17,000 [TestRunnerThread] DEBUG creating collection wrapper:[Server.DataAccess.Model.Customer.Users#2]
2006-11-09 10:22:17,000 [TestRunnerThread] DEBUG done materializing entity [Server.DataAccess.Model.Customer#2]
2006-11-09 10:22:17,000 [TestRunnerThread] DEBUG resolving associations for: [Server.DataAccess.Model.Customer#3]
2006-11-09 10:22:17,000 [TestRunnerThread] DEBUG creating collection wrapper:[Server.DataAccess.Model.Customer.Users#3]
2006-11-09 10:22:17,000 [TestRunnerThread] DEBUG done materializing entity [Server.DataAccess.Model.Customer#3]
2006-11-09 10:22:17,000 [TestRunnerThread] DEBUG resolving associations for: [Server.DataAccess.Model.Customer#4]
2006-11-09 10:22:17,000 [TestRunnerThread] DEBUG creating collection wrapper:[Server.DataAccess.Model.Customer.Users#4]
2006-11-09 10:22:17,000 [TestRunnerThread] DEBUG done materializing entity [Server.DataAccess.Model.Customer#4]
2006-11-09 10:22:17,000 [TestRunnerThread] DEBUG resolving associations for: [Server.DataAccess.Model.Customer#5]
2006-11-09 10:22:17,000 [TestRunnerThread] DEBUG creating collection wrapper:[Server.DataAccess.Model.Customer.Users#5]
2006-11-09 10:22:17,000 [TestRunnerThread] DEBUG done materializing entity [Server.DataAccess.Model.Customer#5]
2006-11-09 10:22:17,000 [TestRunnerThread] DEBUG resolving associations for: [Server.DataAccess.Model.Customer#6]
2006-11-09 10:22:17,000 [TestRunnerThread] DEBUG creating collection wrapper:[Server.DataAccess.Model.Customer.Users#6]
2006-11-09 10:22:17,000 [TestRunnerThread] DEBUG done materializing entity [Server.DataAccess.Model.Customer#6]
2006-11-09 10:22:17,000 [TestRunnerThread] DEBUG resolving associations for: [Server.DataAccess.Model.Customer#7]
2006-11-09 10:22:17,000 [TestRunnerThread] DEBUG creating collection wrapper:[Server.DataAccess.Model.Customer.Users#7]
2006-11-09 10:22:17,000 [TestRunnerThread] DEBUG done materializing entity [Server.DataAccess.Model.Customer#7]
2006-11-09 10:22:17,000 [TestRunnerThread] DEBUG resolving associations for: [Server.DataAccess.Model.Customer#8]
2006-11-09 10:22:17,000 [TestRunnerThread] DEBUG creating collection wrapper:[Server.DataAccess.Model.Customer.Users#8]
2006-11-09 10:22:17,000 [TestRunnerThread] DEBUG done materializing entity [Server.DataAccess.Model.Customer#8]
2006-11-09 10:22:17,000 [TestRunnerThread] DEBUG initializing non-lazy collections
2006-11-09 10:22:17,000 [TestRunnerThread] DEBUG initializing collection [Server.DataAccess.Model.Customer.Users#8]
2006-11-09 10:22:17,000 [TestRunnerThread] DEBUG checking second-level cache
2006-11-09 10:22:17,000 [TestRunnerThread] DEBUG collection not cached
2006-11-09 10:22:17,000 [TestRunnerThread] DEBUG Opened new IDbCommand, open IDbCommands :1
2006-11-09 10:22:17,000 [TestRunnerThread] DEBUG Building an IDbCommand object for the SqlString: SELECT users0_.customer as customer__, users0_.id as id__, users0_.id as id0_, users0_.fullname as fullname0_, users0_.customer as customer0_ FROM Users users0_ WHERE users0_.customer=:customer
2006-11-09 10:22:17,000 [TestRunnerThread] DEBUG binding '8' to parameter: 0
2006-11-09 10:22:17,015 [TestRunnerThread] INFO SELECT users0_.customer as customer__, users0_.id as id__, users0_.id as id0_, users0_.fullname as fullname0_, users0_.customer as customer0_ FROM Users users0_ WHERE users0_.customer=@p0
2006-11-09 10:22:17,015 [TestRunnerThread] DEBUG SELECT users0_.customer as customer__, users0_.id as id__, users0_.id as id0_, users0_.fullname as fullname0_, users0_.customer as customer0_ FROM Users users0_ WHERE users0_.customer=@p0
2006-11-09 10:22:17,015 [TestRunnerThread] DEBUG @p0 = '8'
2006-11-09 10:22:17,062 [TestRunnerThread] DEBUG SQL Exception
System.Data.SqlClient.SqlException: Invalid column name 'customer'.
Invalid column name 'customer'.
Invalid column name 'customer'.
at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection)
at System.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection)
at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj)
at System.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj)
at System.Data.SqlClient.SqlDataReader.ConsumeMetaData()
at System.Data.SqlClient.SqlDataReader.get_MetaData()
at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString)
at System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async)
at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, DbAsyncResult result)
at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method)
at System.Data.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior, String method)
at System.Data.SqlClient.SqlCommand.ExecuteDbDataReader(CommandBehavior behavior)
at System.Data.Common.DbCommand.System.Data.IDbCommand.ExecuteReader()
at NHibernate.Impl.BatcherImpl.ExecuteReader(IDbCommand cmd)
at NHibernate.Loader.Loader.GetResultSet(IDbCommand st, RowSelection selection, ISessionImplementor session)
2006-11-09 10:22:17,062 [TestRunnerThread] WARN System.Data.SqlClient.SqlException: Invalid column name 'customer'.
Invalid column name 'customer'.
Invalid column name 'customer'.
at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection)
at System.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection)
at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj)
at System.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj)
at System.Data.SqlClient.SqlDataReader.ConsumeMetaData()
at System.Data.SqlClient.SqlDataReader.get_MetaData()
at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString)
at System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async)
at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, DbAsyncResult result)
at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method)
at System.Data.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior, String method)
at System.Data.SqlClient.SqlCommand.ExecuteDbDataReader(CommandBehavior behavior)
at System.Data.Common.DbCommand.System.Data.IDbCommand.ExecuteReader()
at NHibernate.Impl.BatcherImpl.ExecuteReader(IDbCommand cmd)
at NHibernate.Loader.Loader.GetResultSet(IDbCommand st, RowSelection selection, ISessionImplementor session)
2006-11-09 10:22:17,078 [TestRunnerThread] ERROR Invalid column name 'customer'.
Invalid column name 'customer'.
Invalid column name 'customer'.
2006-11-09 10:22:17,078 [TestRunnerThread] DEBUG Closed IDbCommand, open IDbCommands :0
2006-11-09 10:22:17,078 [TestRunnerThread] DEBUG could not initialize collection: [Server.DataAccess.Model.Customer.Users#8]
System.Data.SqlClient.SqlException: Invalid column name 'customer'.
Invalid column name 'customer'.
Invalid column name 'customer'.
at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection)
at System.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection)
at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj)
at System.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj)
at System.Data.SqlClient.SqlDataReader.ConsumeMetaData()
at System.Data.SqlClient.SqlDataReader.get_MetaData()
at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString)
at System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async)
at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, DbAsyncResult result)
at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method)
at System.Data.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior, String method)
at System.Data.SqlClient.SqlCommand.ExecuteDbDataReader(CommandBehavior behavior)
at System.Data.Common.DbCommand.System.Data.IDbCommand.ExecuteReader()
at NHibernate.Impl.BatcherImpl.ExecuteReader(IDbCommand cmd)
at NHibernate.Loader.Loader.GetResultSet(IDbCommand st, RowSelection selection, ISessionImplementor session)
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.OneToManyLoader.Initialize(Object id, ISessionImplementor session)
at NHibernate.Collection.AbstractCollectionPersister.Initialize(Object key, ISessionImplementor session)
2006-11-09 10:22:17,078 [TestRunnerThread] WARN System.Data.SqlClient.SqlException: Invalid column name 'customer'.
Invalid column name 'customer'.
Invalid column name 'customer'.
at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection)
at System.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection)
at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj)
at System.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj)
at System.Data.SqlClient.SqlDataReader.ConsumeMetaData()
at System.Data.SqlClient.SqlDataReader.get_MetaData()
at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString)
at System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async)
at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, DbAsyncResult result)
at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method)
at System.Data.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior, String method)
at System.Data.SqlClient.SqlCommand.ExecuteDbDataReader(CommandBehavior behavior)
at System.Data.Common.DbCommand.System.Data.IDbCommand.ExecuteReader()
at NHibernate.Impl.BatcherImpl.ExecuteReader(IDbCommand cmd)
at NHibernate.Loader.Loader.GetResultSet(IDbCommand st, RowSelection selection, ISessionImplementor session)
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.OneToManyLoader.Initialize(Object id, ISessionImplementor session)
at NHibernate.Collection.AbstractCollectionPersister.Initialize(Object key, ISessionImplementor session)
2006-11-09 10:22:17,078 [TestRunnerThread] ERROR Invalid column name 'customer'.
Invalid column name 'customer'.
Invalid column name 'customer'.
2006-11-09 10:22:17,171 [TestRunnerThread] DEBUG opened session
2006-11-09 10:22:17,171 [TestRunnerThread] DEBUG flushing session
2006-11-09 10:22:17,187 [TestRunnerThread] DEBUG Flushing entities and processing referenced collections
2006-11-09 10:22:17,187 [TestRunnerThread] DEBUG Processing unreferenced collections
2006-11-09 10:22:17,187 [TestRunnerThread] DEBUG scheduling collection removes/(re)creates/updates
2006-11-09 10:22:17,187 [TestRunnerThread] DEBUG Flushed: 0 insertions, 0 updates, 0 deletions to 0 objects
2006-11-09 10:22:17,187 [TestRunnerThread] DEBUG Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
2006-11-09 10:22:17,187 [TestRunnerThread] DEBUG dont need to execute flush
2006-11-09 10:22:17,187 [TestRunnerThread] DEBUG Opened new IDbCommand, open IDbCommands :1
2006-11-09 10:22:17,187 [TestRunnerThread] DEBUG Building an IDbCommand object for the SqlString: SELECT this.id as id0_, this.fullname as fullname0_ FROM Parents this WHERE 1=1
2006-11-09 10:22:17,187 [TestRunnerThread] INFO SELECT this.id as id0_, this.fullname as fullname0_ FROM Parents this WHERE 1=1
2006-11-09 10:22:17,187 [TestRunnerThread] DEBUG SELECT this.id as id0_, this.fullname as fullname0_ FROM Parents this WHERE 1=1
2006-11-09 10:22:17,187 [TestRunnerThread] DEBUG Obtaining IDbConnection from Driver
2006-11-09 10:22:17,218 [TestRunnerThread] DEBUG Opened Reader, open Readers :1
2006-11-09 10:22:17,218 [TestRunnerThread] DEBUG processing result set
2006-11-09 10:22:17,218 [TestRunnerThread] DEBUG returning '1' as column: id0_
2006-11-09 10:22:17,218 [TestRunnerThread] DEBUG result row: 1
2006-11-09 10:22:17,218 [TestRunnerThread] DEBUG Initializing object from DataReader: 1
2006-11-09 10:22:17,218 [TestRunnerThread] DEBUG Hydrating entity: Server.DataAccess.Model.Parent#1
2006-11-09 10:22:17,218 [TestRunnerThread] DEBUG returning 'Américo Pinto da Cunha Lopes' as column: fullname0_
2006-11-09 10:22:17,218 [TestRunnerThread] DEBUG returning '2' as column: id0_
2006-11-09 10:22:17,218 [TestRunnerThread] DEBUG result row: 2
2006-11-09 10:22:17,218 [TestRunnerThread] DEBUG Initializing object from DataReader: 2
2006-11-09 10:22:17,218 [TestRunnerThread] DEBUG Hydrating entity: Server.DataAccess.Model.Parent#2
2006-11-09 10:22:17,218 [TestRunnerThread] DEBUG returning 'Manuel Gomes Cavaco' as column: fullname0_
2006-11-09 10:22:17,218 [TestRunnerThread] DEBUG done processing result set (2 rows)
2006-11-09 10:22:17,218 [TestRunnerThread] DEBUG running NHybridDataReader.Dispose()
2006-11-09 10:22:17,218 [TestRunnerThread] DEBUG Closed Reader, open Readers :0
2006-11-09 10:22:17,218 [TestRunnerThread] DEBUG Closed IDbCommand, open IDbCommands :0
2006-11-09 10:22:17,218 [TestRunnerThread] DEBUG total objects hydrated: 2
2006-11-09 10:22:17,218 [TestRunnerThread] DEBUG resolving associations for: [Server.DataAccess.Model.Parent#1]
2006-11-09 10:22:17,218 [TestRunnerThread] DEBUG creating collection wrapper:[Server.DataAccess.Model.Parent.Children#1]
2006-11-09 10:22:17,218 [TestRunnerThread] DEBUG done materializing entity [Server.DataAccess.Model.Parent#1]
2006-11-09 10:22:17,218 [TestRunnerThread] DEBUG resolving associations for: [Server.DataAccess.Model.Parent#2]
2006-11-09 10:22:17,218 [TestRunnerThread] DEBUG creating collection wrapper:[Server.DataAccess.Model.Parent.Children#2]
2006-11-09 10:22:17,218 [TestRunnerThread] DEBUG done materializing entity [Server.DataAccess.Model.Parent#2]
2006-11-09 10:22:17,218 [TestRunnerThread] DEBUG initializing non-lazy collections
2006-11-09 10:22:17,218 [TestRunnerThread] DEBUG initializing collection [Server.DataAccess.Model.Parent.Children#2]
2006-11-09 10:22:17,218 [TestRunnerThread] DEBUG checking second-level cache
2006-11-09 10:22:17,218 [TestRunnerThread] DEBUG collection not cached
2006-11-09 10:22:17,218 [TestRunnerThread] DEBUG Opened new IDbCommand, open IDbCommands :1
2006-11-09 10:22:17,218 [TestRunnerThread] DEBUG Building an IDbCommand object for the SqlString: SELECT children0_.parent as parent__, children0_.id as id__, children0_.id as id0_, children0_.parent as parent0_, children0_.fullname as fullname0_ FROM Children children0_ WHERE children0_.parent=:parent
2006-11-09 10:22:17,218 [TestRunnerThread] DEBUG binding '2' to parameter: 0
2006-11-09 10:22:17,218 [TestRunnerThread] INFO SELECT children0_.parent as parent__, children0_.id as id__, children0_.id as id0_, children0_.parent as parent0_, children0_.fullname as fullname0_ FROM Children children0_ WHERE children0_.parent=@p0
2006-11-09 10:22:17,218 [TestRunnerThread] DEBUG SELECT children0_.parent as parent__, children0_.id as id__, children0_.id as id0_, children0_.parent as parent0_, children0_.fullname as fullname0_ FROM Children children0_ WHERE children0_.parent=@p0
2006-11-09 10:22:17,218 [TestRunnerThread] DEBUG @p0 = '2'
2006-11-09 10:22:17,234 [TestRunnerThread] DEBUG Opened Reader, open Readers :1
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG result set contains (possibly empty) collection: [Server.DataAccess.Model.Parent.Children#2]
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG uninitialized collection: initializing
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG processing result set
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG returning '3' as column: id0_
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG result row: 3
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG Initializing object from DataReader: 3
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG Hydrating entity: Server.DataAccess.Model.Child#3
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG returning '2' as column: parent0_
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG returning 'Cristina Soares Ribeiro Gomes Cavaco' as column: fullname0_
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG returning '2' as column: parent__
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG found row of collection: [Server.DataAccess.Model.Parent.Children#2]
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG reading row
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG returning '3' as column: id__
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG loading [Child#3]
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG attempting to resolve [Child#3]
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG resolved object in session cache [Server.DataAccess.Model.Child#3]
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG returning '4' as column: id0_
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG result row: 4
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG Initializing object from DataReader: 4
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG Hydrating entity: Server.DataAccess.Model.Child#4
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG returning '2' as column: parent0_
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG returning 'Luís Soares Ribeiro Gomes Cavaco' as column: fullname0_
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG returning '2' as column: parent__
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG found row of collection: [Server.DataAccess.Model.Parent.Children#2]
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG reading row
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG returning '4' as column: id__
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG loading [Child#4]
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG attempting to resolve [Child#4]
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG resolved object in session cache [Server.DataAccess.Model.Child#4]
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG returning '5' as column: id0_
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG result row: 5
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG Initializing object from DataReader: 5
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG Hydrating entity: Server.DataAccess.Model.Child#5
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG returning '2' as column: parent0_
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG returning 'Eduardo Soares Ribeiro Gomes Cavaco' as column: fullname0_
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG returning '2' as column: parent__
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG found row of collection: [Server.DataAccess.Model.Parent.Children#2]
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG reading row
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG returning '5' as column: id__
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG loading [Child#5]
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG attempting to resolve [Child#5]
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG resolved object in session cache [Server.DataAccess.Model.Child#5]
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG done processing result set (3 rows)
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG running NHybridDataReader.Dispose()
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG Closed Reader, open Readers :0
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG Closed IDbCommand, open IDbCommands :0
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG total objects hydrated: 3
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG resolving associations for: [Server.DataAccess.Model.Child#3]
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG loading [Parent#2]
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG attempting to resolve [Parent#2]
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG resolved object in session cache [Server.DataAccess.Model.Parent#2]
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG done materializing entity [Server.DataAccess.Model.Child#3]
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG resolving associations for: [Server.DataAccess.Model.Child#4]
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG loading [Parent#2]
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG attempting to resolve [Parent#2]
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG resolved object in session cache [Server.DataAccess.Model.Parent#2]
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG done materializing entity [Server.DataAccess.Model.Child#4]
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG resolving associations for: [Server.DataAccess.Model.Child#5]
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG loading [Parent#2]
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG attempting to resolve [Parent#2]
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG resolved object in session cache [Server.DataAccess.Model.Parent#2]
2006-11-09 10:22:17,250 [TestRunnerThread] DEBUG done materializing entity [Server.DataAccess.Model.Child#5]
2006-11-09 10:22:17,265 [TestRunnerThread] DEBUG 1 collections were found in result set
2006-11-09 10:22:17,265 [TestRunnerThread] DEBUG collection fully initialized: [Server.DataAccess.Model.Parent.Children#2]
2006-11-09 10:22:17,265 [TestRunnerThread] DEBUG 1 collections initialized
2006-11-09 10:22:17,265 [TestRunnerThread] DEBUG collection initialized
2006-11-09 10:22:17,265 [TestRunnerThread] DEBUG initializing collection [Server.DataAccess.Model.Parent.Children#1]
2006-11-09 10:22:17,265 [TestRunnerThread] DEBUG checking second-level cache
2006-11-09 10:22:17,265 [TestRunnerThread] DEBUG collection not cached
2006-11-09 10:22:17,265 [TestRunnerThread] DEBUG Opened new IDbCommand, open IDbCommands :1
2006-11-09 10:22:17,265 [TestRunnerThread] DEBUG Building an IDbCommand object for the SqlString: SELECT children0_.parent as parent__, children0_.id as id__, children0_.id as id0_, children0_.parent as parent0_, children0_.fullname as fullname0_ FROM Children children0_ WHERE children0_.parent=:parent
2006-11-09 10:22:17,265 [TestRunnerThread] DEBUG binding '1' to parameter: 0
2006-11-09 10:22:17,265 [TestRunnerThread] INFO SELECT children0_.parent as parent__, children0_.id as id__, children0_.id as id0_, children0_.parent as parent0_, children0_.fullname as fullname0_ FROM Children children0_ WHERE children0_.parent=@p0
2006-11-09 10:22:17,265 [TestRunnerThread] DEBUG SELECT children0_.parent as parent__, children0_.id as id__, children0_.id as id0_, children0_.parent as parent0_, children0_.fullname as fullname0_ FROM Children children0_ WHERE children0_.parent=@p0
2006-11-09 10:22:17,265 [TestRunnerThread] DEBUG @p0 = '1'
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG Opened Reader, open Readers :1
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG result set contains (possibly empty) collection: [Server.DataAccess.Model.Parent.Children#1]
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG uninitialized collection: initializing
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG processing result set
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG returning '1' as column: id0_
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG result row: 1
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG Initializing object from DataReader: 1
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG Hydrating entity: Server.DataAccess.Model.Child#1
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG returning '1' as column: parent0_
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG returning 'João Miguel Correia da Cunha Lopes' as column: fullname0_
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG returning '1' as column: parent__
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG found row of collection: [Server.DataAccess.Model.Parent.Children#1]
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG reading row
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG returning '1' as column: id__
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG loading [Child#1]
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG attempting to resolve [Child#1]
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG resolved object in session cache [Server.DataAccess.Model.Child#1]
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG returning '2' as column: id0_
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG result row: 2
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG Initializing object from DataReader: 2
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG Hydrating entity: Server.DataAccess.Model.Child#2
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG returning '1' as column: parent0_
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG returning 'Ana Margarida Correia da Cunha Lopes' as column: fullname0_
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG returning '1' as column: parent__
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG found row of collection: [Server.DataAccess.Model.Parent.Children#1]
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG reading row
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG returning '2' as column: id__
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG loading [Child#2]
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG attempting to resolve [Child#2]
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG resolved object in session cache [Server.DataAccess.Model.Child#2]
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG done processing result set (2 rows)
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG running NHybridDataReader.Dispose()
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG Closed Reader, open Readers :0
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG Closed IDbCommand, open IDbCommands :0
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG total objects hydrated: 2
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG resolving associations for: [Server.DataAccess.Model.Child#1]
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG loading [Parent#1]
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG attempting to resolve [Parent#1]
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG resolved object in session cache [Server.DataAccess.Model.Parent#1]
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG done materializing entity [Server.DataAccess.Model.Child#1]
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG resolving associations for: [Server.DataAccess.Model.Child#2]
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG loading [Parent#1]
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG attempting to resolve [Parent#1]
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG resolved object in session cache [Server.DataAccess.Model.Parent#1]
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG done materializing entity [Server.DataAccess.Model.Child#2]
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG 1 collections were found in result set
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG collection fully initialized: [Server.DataAccess.Model.Parent.Children#1]
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG 1 collections initialized
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG collection initialized
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG closing session
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG disconnecting session
2006-11-09 10:22:17,312 [TestRunnerThread] DEBUG Closing connection
2006-11-09 10:22:17,328 [TestRunnerThread] DEBUG transaction completion