Greetings, I am converting working demonstrations built with Hibernate2 and Eclipse 3.1.2 using Java 1.4 into equivalent NHibernate applications. I am working with NHibernate v1.0.2.0 in a VS 2003 environment. The Hibernate applications are using Oracle9i dialect, while the NHibernate applications are using MsSql2000Dialect. I am having a problem with a one-to-many relationship. In the theme of Caveat Emptor, I am working with Items (to be auctioned) and Bids on these Items. When my application begins, it queries the database for the Items and places the results in a list. Then the application selects a default Item and queries the database for respective Bids. So, after startup, the user should see a list of Items with one item selected by default and another list of the Bids for that selected Item. The two queries are handled sequentially by two different sessions. The first session handles the transaction which gets the Items, the second session handles the transaction which gets the Bids for the selected Item. To me it appears as though completing the first transaction and closing the first session is not rendering the System.Data.SqlClient.SqlConnection capable of performing another transaction. What has to be done to clear the SqlConnection for it to perform another transaction? I reiterate that this same sequence of events works fine with Hibernate.

Here is the stack trace:
2006-06-17 11:24:17,825 [1200] INFO NHibernate.Cfg.Environment [(null)] <(null)> - NHibernate 1.0.2
2006-06-17 11:24:17,895 [1200] INFO NHibernate.Cfg.Environment [(null)] <(null)> - nhibernate section not found in application configuration file
2006-06-17 11:24:17,895 [1200] INFO NHibernate.Cfg.Environment [(null)] <(null)> - Using reflection optimizer
2006-06-17 11:24:18,336 [1200] DEBUG NHibernate.Cfg.Configuration [(null)] <(null)> - connection.provider=NHibernate.Connection.DriverConnectionProvider
2006-06-17 11:24:18,336 [1200] DEBUG NHibernate.Cfg.Configuration [(null)] <(null)> - connection.driver_class=NHibernate.Driver.SqlClientDriver
2006-06-17 11:24:18,336 [1200] DEBUG NHibernate.Cfg.Configuration [(null)] <(null)> - connection.connection_string=Server=myserver.com;Initial Catalog=MYCATALOG;Uid=MYACCT;Pwd=MYPASSWD
2006-06-17 11:24:18,336 [1200] DEBUG NHibernate.Cfg.Configuration [(null)] <(null)> - show_sql=false
2006-06-17 11:24:18,336 [1200] DEBUG NHibernate.Cfg.Configuration [(null)] <(null)> - dialect=NHibernate.Dialect.MsSql2000Dialect
2006-06-17 11:24:18,336 [1200] DEBUG NHibernate.Cfg.Configuration [(null)] <(null)> - use_outer_join=true
2006-06-17 11:24:18,336 [1200] DEBUG NHibernate.Cfg.Configuration [(null)] <(null)> - query.substitutions=true 1, false 0, yes 'Y', no 'N'
2006-06-17 11:24:18,336 [1200] DEBUG NHibernate.Cfg.Configuration [(null)] <(null)> - HOTM<-HOTM.Bid.hbm.xml in HOTM
2006-06-17 11:24:18,336 [1200] INFO NHibernate.Cfg.Configuration [(null)] <(null)> - Mapping resource: HOTM.Bid.hbm.xml
2006-06-17 11:24:18,446 [1200] INFO NHibernate.Dialect.Dialect [(null)] <(null)> - Using dialect: NHibernate.Dialect.MsSql2000Dialect
2006-06-17 11:24:18,476 [1200] INFO NHibernate.Cfg.Binder [(null)] <(null)> - Mapping class: HOTM.Bid -> HOTM1_BID
2006-06-17 11:24:18,496 [1200] DEBUG NHibernate.Cfg.Binder [(null)] <(null)> - Mapped property: IdBid -> BID_ID, type: Int32
2006-06-17 11:24:18,516 [1200] DEBUG NHibernate.Cfg.Binder [(null)] <(null)> - Mapped property: BidAmount -> AMOUNT, type: Double
2006-06-17 11:24:18,526 [1200] DEBUG NHibernate.Cfg.Binder [(null)] <(null)> - Mapped property: Item -> ITEM_ID, type: Item
2006-06-17 11:24:18,526 [1200] DEBUG NHibernate.Cfg.Configuration [(null)] <(null)> - HOTM<-HOTM.Item.hbm.xml in HOTM
2006-06-17 11:24:18,526 [1200] INFO NHibernate.Cfg.Configuration [(null)] <(null)> - Mapping resource: HOTM.Item.hbm.xml
2006-06-17 11:24:18,526 [1200] INFO NHibernate.Dialect.Dialect [(null)] <(null)> - Using dialect: NHibernate.Dialect.MsSql2000Dialect
2006-06-17 11:24:18,526 [1200] INFO NHibernate.Cfg.Binder [(null)] <(null)> - Mapping class: HOTM.Item -> HOTM1_ITEM
2006-06-17 11:24:18,526 [1200] DEBUG NHibernate.Cfg.Binder [(null)] <(null)> - Mapped property: Id -> ITEM_ID, type: Int32
2006-06-17 11:24:18,536 [1200] DEBUG NHibernate.Cfg.Binder [(null)] <(null)> - Mapped property: Name -> NAME, type: String
2006-06-17 11:24:18,546 [1200] DEBUG NHibernate.Cfg.Binder [(null)] <(null)> - Mapped property: Bids, type: ISet
2006-06-17 11:24:18,546 [1200] INFO NHibernate.Cfg.Configuration [(null)] <(null)> - Configured SessionFactory: HOTM
2006-06-17 11:24:18,546 [1200] DEBUG NHibernate.Cfg.Configuration [(null)] <(null)> - properties: System.Collections.Hashtable
2006-06-17 11:24:18,556 [1200] INFO NHibernate.Cfg.Configuration [(null)] <(null)> - processing one-to-many association mappings
2006-06-17 11:24:18,556 [1200] DEBUG NHibernate.Cfg.Binder [(null)] <(null)> - Second pass for collection: HOTM.Item.Bids
2006-06-17 11:24:18,566 [1200] INFO NHibernate.Cfg.Binder [(null)] <(null)> - mapping collection: HOTM.Item.Bids -> HOTM1_BID
2006-06-17 11:24:18,566 [1200] DEBUG NHibernate.Cfg.Binder [(null)] <(null)> - Mapped collection key: ITEM_ID, one-to-many: Bid
2006-06-17 11:24:18,566 [1200] INFO NHibernate.Cfg.Configuration [(null)] <(null)> - processing one-to-one association property references
2006-06-17 11:24:18,566 [1200] INFO NHibernate.Cfg.Configuration [(null)] <(null)> - processing foreign key constraints
2006-06-17 11:24:18,566 [1200] DEBUG NHibernate.Cfg.Configuration [(null)] <(null)> - resolving reference to class: Item
2006-06-17 11:24:18,576 [1200] INFO NHibernate.Dialect.Dialect [(null)] <(null)> - Using dialect: NHibernate.Dialect.MsSql2000Dialect
2006-06-17 11:24:18,576 [1200] INFO NHibernate.Cfg.SettingsFactory [(null)] <(null)> - use outer join fetching: True
2006-06-17 11:24:18,576 [1200] INFO NHibernate.Connection.ConnectionProviderFactory [(null)] <(null)> - Intitializing connection provider: NHibernate.Connection.DriverConnectionProvider
2006-06-17 11:24:18,586 [1200] INFO NHibernate.Connection.ConnectionProvider [(null)] <(null)> - Configuring ConnectionProvider
2006-06-17 11:24:18,586 [1200] INFO NHibernate.Cfg.SettingsFactory [(null)] <(null)> - Optimize cache for minimal puts: False
2006-06-17 11:24:18,586 [1200] INFO NHibernate.Cfg.SettingsFactory [(null)] <(null)> - Query language substitutions: {yes='Y', true=1, no='N', false=0}
2006-06-17 11:24:18,586 [1200] INFO NHibernate.Cfg.SettingsFactory [(null)] <(null)> - cache provider: NHibernate.Cache.HashtableCacheProvider
2006-06-17 11:24:18,596 [1200] INFO NHibernate.Cfg.Configuration [(null)] <(null)> - instantiating and configuring caches
2006-06-17 11:24:18,596 [1200] INFO NHibernate.Impl.SessionFactoryImpl [(null)] <(null)> - building session factory
2006-06-17 11:24:18,596 [1200] DEBUG NHibernate.Impl.SessionFactoryImpl [(null)] <(null)> - instantiating session factory with properties: {show_sql=false, connection.provider=NHibernate.Connection.DriverConnectionProvider, dialect=NHibernate.Dialect.MsSql2000Dialect, connection.driver_class=NHibernate.Driver.SqlClientDriver, hibernate.session_factory_name=HOTM, hibernate.use_reflection_optimizer=True, hibernate.use_outer_join=true, hibernate.connection.connection_string=Server=MYSERVER.COM;Initial Catalog=MYCATALOG;Uid=MYUID;Pwd=MYPASSWD, hibernate.connection.driver_class=NHibernate.Driver.SqlClientDriver, query.substitutions=true 1, false 0, yes 'Y', no 'N', connection.connection_string=Server=MYSERVER.COM;Initial Catalog=MYCATALOG;Uid=MYUID;Pwd=MYPASSWD, hibernate.connection.provider=NHibernate.Connection.DriverConnectionProvider, hibernate.dialect=NHibernate.Dialect.MsSql2000Dialect, use_outer_join=true, hibernate.show_sql=false, hibernate.query.substitutions=true 1, false 0, yes 'Y', no 'N'}
2006-06-17 11:24:18,666 [1200] DEBUG NHibernate.Persister.GetSetHelperFactory [(null)] <(null)> - Init compiler for class HOTM.Bid
2006-06-17 11:24:18,666 [1200] DEBUG NHibernate.Persister.GetSetHelperFactory [(null)] <(null)> - Adding referenced assembly z:\csc351\hibernate_.net\hibernateonetomany\hotm\bin\debug\nhibernate.dll
2006-06-17 11:24:18,666 [1200] DEBUG NHibernate.Persister.GetSetHelperFactory [(null)] <(null)> - Adding referenced assembly Z:\CSC351\Hibernate_.NET\HibernateOneToMany\HOTM\bin\Debug\HOTM.exe
2006-06-17 11:24:18,666 [1200] DEBUG NHibernate.Persister.GetSetHelperFactory [(null)] <(null)> - Adding referenced assembly e:\windows\microsoft.net\framework\v1.1.4322\mscorlib.dll
2006-06-17 11:24:18,666 [1200] DEBUG NHibernate.Persister.GetSetHelperFactory [(null)] <(null)> - Adding referenced assembly e:\windows\assembly\gac\system.windows.forms\1.0.5000.0__b77a5c561934e089\system.windows.forms.dll
2006-06-17 11:24:18,666 [1200] DEBUG NHibernate.Persister.GetSetHelperFactory [(null)] <(null)> - Adding referenced assembly z:\csc351\hibernate_.net\hibernateonetomany\hotm\bin\debug\log4net.dll
2006-06-17 11:24:18,666 [1200] DEBUG NHibernate.Persister.GetSetHelperFactory [(null)] <(null)> - Adding referenced assembly e:\windows\assembly\gac\system\1.0.5000.0__b77a5c561934e089\system.dll
2006-06-17 11:24:18,666 [1200] DEBUG NHibernate.Persister.GetSetHelperFactory [(null)] <(null)> - Adding referenced assembly z:\csc351\hibernate_.net\hibernateonetomany\hotm\bin\debug\iesi.collections.dll
2006-06-17 11:24:18,666 [1200] DEBUG NHibernate.Persister.GetSetHelperFactory [(null)] <(null)> - Adding referenced assembly e:\windows\assembly\gac\system.drawing\1.0.5000.0__b03f5f7f11d50a3a\system.drawing.dll
2006-06-17 11:24:18,666 [1200] DEBUG NHibernate.Persister.GetSetHelperFactory [(null)] <(null)> - Adding referenced assembly e:\windows\assembly\gac\system.data\1.0.5000.0__b77a5c561934e089\system.data.dll
2006-06-17 11:24:18,957 [1200] DEBUG NHibernate.Persister.GetSetHelperFactory [(null)] <(null)> - Compiled ok:
using System;
using NHibernate.Property;
namespace NHibernate.Persister {
public class GetSetHelper_HOTM_Bid : IGetSetHelper {
ISetter[] setters;
IGetter[] getters;
public GetSetHelper_HOTM_Bid(ISetter[] setters, IGetter[] getters) {
this.setters = setters;
this.getters = getters;
}
public void SetPropertyValues(object obj, object[] values) {
HOTM.Bid t = (HOTM.Bid)obj;
try
{
t.BidAmount = values[0] == null ? new System.Double() : (System.Double)values[0];
t.Item = (HOTM.Item)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) {
HOTM.Bid t = (HOTM.Bid)obj;
object[] ret = new object[2];
ret[0] = t.BidAmount;
ret[1] = t.Item;
return ret;
}
}
}

2006-06-17 11:24:18,977 [1200] DEBUG NHibernate.Persister.GetSetHelperFactory [(null)] <(null)> - Init compiler for class HOTM.Item
2006-06-17 11:24:18,977 [1200] DEBUG NHibernate.Persister.GetSetHelperFactory [(null)] <(null)> - Adding referenced assembly z:\csc351\hibernate_.net\hibernateonetomany\hotm\bin\debug\nhibernate.dll
2006-06-17 11:24:18,977 [1200] DEBUG NHibernate.Persister.GetSetHelperFactory [(null)] <(null)> - Adding referenced assembly Z:\CSC351\Hibernate_.NET\HibernateOneToMany\HOTM\bin\Debug\HOTM.exe
2006-06-17 11:24:18,977 [1200] DEBUG NHibernate.Persister.GetSetHelperFactory [(null)] <(null)> - Adding referenced assembly e:\windows\microsoft.net\framework\v1.1.4322\mscorlib.dll
2006-06-17 11:24:18,977 [1200] DEBUG NHibernate.Persister.GetSetHelperFactory [(null)] <(null)> - Adding referenced assembly e:\windows\assembly\gac\system.windows.forms\1.0.5000.0__b77a5c561934e089\system.windows.forms.dll
2006-06-17 11:24:18,977 [1200] DEBUG NHibernate.Persister.GetSetHelperFactory [(null)] <(null)> - Adding referenced assembly z:\csc351\hibernate_.net\hibernateonetomany\hotm\bin\debug\log4net.dll
2006-06-17 11:24:18,977 [1200] DEBUG NHibernate.Persister.GetSetHelperFactory [(null)] <(null)> - Adding referenced assembly e:\windows\assembly\gac\system\1.0.5000.0__b77a5c561934e089\system.dll
2006-06-17 11:24:18,977 [1200] DEBUG NHibernate.Persister.GetSetHelperFactory [(null)] <(null)> - Adding referenced assembly z:\csc351\hibernate_.net\hibernateonetomany\hotm\bin\debug\iesi.collections.dll
2006-06-17 11:24:18,977 [1200] DEBUG NHibernate.Persister.GetSetHelperFactory [(null)] <(null)> - Adding referenced assembly e:\windows\assembly\gac\system.drawing\1.0.5000.0__b03f5f7f11d50a3a\system.drawing.dll
2006-06-17 11:24:18,977 [1200] DEBUG NHibernate.Persister.GetSetHelperFactory [(null)] <(null)> - Adding referenced assembly e:\windows\assembly\gac\system.data\1.0.5000.0__b77a5c561934e089\system.data.dll
2006-06-17 11:24:19,187 [1200] DEBUG NHibernate.Persister.GetSetHelperFactory [(null)] <(null)> - Compiled ok:
using System;
using NHibernate.Property;
namespace NHibernate.Persister {
public class GetSetHelper_HOTM_Item : IGetSetHelper {
ISetter[] setters;
IGetter[] getters;
public GetSetHelper_HOTM_Item(ISetter[] setters, IGetter[] getters) {
this.setters = setters;
this.getters = getters;
}
public void SetPropertyValues(object obj, object[] values) {
HOTM.Item t = (HOTM.Item)obj;
try
{
t.Name = (System.String)values[0];
t.Bids = (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) {
HOTM.Item t = (HOTM.Item)obj;
object[] ret = new object[2];
ret[0] = t.Name;
ret[1] = t.Bids;
return ret;
}
}
}

2006-06-17 11:24:19,297 [1200] DEBUG NHibernate.Impl.SessionFactoryObjectFactory [(null)] <(null)> - initializing class SessionFactoryObjectFactory
2006-06-17 11:24:19,297 [1200] DEBUG NHibernate.Impl.SessionFactoryObjectFactory [(null)] <(null)> - registered: 15b60f34d9d74a9a80f7ecf6be172f47(HOTM)
2006-06-17 11:24:19,297 [1200] INFO NHibernate.Impl.SessionFactoryObjectFactory [(null)] <(null)> - Factory name:HOTM
2006-06-17 11:24:19,297 [1200] DEBUG NHibernate.Impl.SessionFactoryImpl [(null)] <(null)> - Instantiated session factory
2006-06-17 11:24:19,297 [1200] INFO HNibernate [(null)] <(null)> - right before trying to get Items list
2006-06-17 11:24:19,307 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - opened session*************************************
2006-06-17 11:24:19,317 [1200] DEBUG NHibernate.Transaction.AdoTransaction [(null)] <(null)> - begin
2006-06-17 11:24:19,317 [1200] DEBUG NHibernate.Connection.DriverConnectionProvider [(null)] <(null)> - Obtaining IDbConnection from Driver
2006-06-17 11:24:19,888 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - find: from HOTM.Item as m order by m.Name asc
2006-06-17 11:24:19,908 [1200] DEBUG NHibernate.Hql.QueryTranslator [(null)] <(null)> - compiling query
2006-06-17 11:24:19,968 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - flushing session
2006-06-17 11:24:19,978 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - Flushing entities and processing referenced collections
2006-06-17 11:24:19,978 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - Processing unreferenced collections
2006-06-17 11:24:19,978 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - scheduling collection removes/(re)creates/updates
2006-06-17 11:24:19,978 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - Flushed: 0 insertions, 0 updates, 0 deletions to 0 objects
2006-06-17 11:24:19,978 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
2006-06-17 11:24:19,978 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - dont need to execute flush
2006-06-17 11:24:19,978 [1200] DEBUG NHibernate.Hql.QueryTranslator [(null)] <(null)> - HQL: from HOTM.Item as m order by m.Name asc
2006-06-17 11:24:19,978 [1200] DEBUG NHibernate.Hql.QueryTranslator [(null)] <(null)> - SQL: select item0_.ITEM_ID as ITEM_ID, item0_.NAME as NAME from HOTM1_ITEM item0_ order by item0_.NAME asc
2006-06-17 11:24:19,998 [1200] DEBUG NHibernate.Impl.BatcherImpl [(null)] <(null)> - Opened new IDbCommand, open IDbCommands :1
2006-06-17 11:24:19,998 [1200] DEBUG NHibernate.Impl.BatcherImpl [(null)] <(null)> - Building an IDbCommand object for the SqlString: select item0_.ITEM_ID as ITEM_ID, item0_.NAME as NAME from HOTM1_ITEM item0_ order by item0_.NAME asc
2006-06-17 11:24:19,998 [1200] INFO NHibernate.Loader.Loader [(null)] <(null)> - select item0_.ITEM_ID as ITEM_ID, item0_.NAME as NAME from HOTM1_ITEM item0_ order by item0_.NAME asc
2006-06-17 11:24:19,998 [1200] DEBUG NHibernate.SQL [(null)] <(null)> - select item0_.ITEM_ID as ITEM_ID, item0_.NAME as NAME from HOTM1_ITEM item0_ order by item0_.NAME asc
2006-06-17 11:24:20,078 [1200] DEBUG NHibernate.Impl.BatcherImpl [(null)] <(null)> - Opened Reader, open Readers :1
2006-06-17 11:24:20,078 [1200] DEBUG NHibernate.Loader.Loader [(null)] <(null)> - processing result set
2006-06-17 11:24:20,148 [1200] DEBUG NHibernate.Type.Int32Type [(null)] <(null)> - returning '1' as column: ITEM_ID
2006-06-17 11:24:20,148 [1200] DEBUG NHibernate.Loader.Loader [(null)] <(null)> - result row: 1
2006-06-17 11:24:20,148 [1200] DEBUG NHibernate.Loader.Loader [(null)] <(null)> - Initializing object from DataReader: 1
2006-06-17 11:24:20,158 [1200] DEBUG NHibernate.Loader.Loader [(null)] <(null)> - Hydrating entity: HOTM.Item#1
2006-06-17 11:24:20,158 [1200] DEBUG NHibernate.Type.StringType [(null)] <(null)> - returning 'Geek Cap' as column: NAME
2006-06-17 11:24:20,158 [1200] DEBUG NHibernate.Type.Int32Type [(null)] <(null)> - returning '2' as column: ITEM_ID
2006-06-17 11:24:20,158 [1200] DEBUG NHibernate.Loader.Loader [(null)] <(null)> - result row: 2
2006-06-17 11:24:20,158 [1200] DEBUG NHibernate.Loader.Loader [(null)] <(null)> - Initializing object from DataReader: 2
2006-06-17 11:24:20,158 [1200] DEBUG NHibernate.Loader.Loader [(null)] <(null)> - Hydrating entity: HOTM.Item#2
2006-06-17 11:24:20,158 [1200] DEBUG NHibernate.Type.StringType [(null)] <(null)> - returning 'Geek Shirt' as column: NAME
2006-06-17 11:24:20,158 [1200] DEBUG NHibernate.Type.Int32Type [(null)] <(null)> - returning '3' as column: ITEM_ID
2006-06-17 11:24:20,158 [1200] DEBUG NHibernate.Loader.Loader [(null)] <(null)> - result row: 3
2006-06-17 11:24:20,158 [1200] DEBUG NHibernate.Loader.Loader [(null)] <(null)> - Initializing object from DataReader: 3
2006-06-17 11:24:20,158 [1200] DEBUG NHibernate.Loader.Loader [(null)] <(null)> - Hydrating entity: HOTM.Item#3
2006-06-17 11:24:20,158 [1200] DEBUG NHibernate.Type.StringType [(null)] <(null)> - returning 'Geek Socks' as column: NAME
2006-06-17 11:24:20,158 [1200] DEBUG NHibernate.Type.Int32Type [(null)] <(null)> - returning '4' as column: ITEM_ID
2006-06-17 11:24:20,158 [1200] DEBUG NHibernate.Loader.Loader [(null)] <(null)> - result row: 4
2006-06-17 11:24:20,158 [1200] DEBUG NHibernate.Loader.Loader [(null)] <(null)> - Initializing object from DataReader: 4
2006-06-17 11:24:20,158 [1200] DEBUG NHibernate.Loader.Loader [(null)] <(null)> - Hydrating entity: HOTM.Item#4
2006-06-17 11:24:20,158 [1200] DEBUG NHibernate.Type.StringType [(null)] <(null)> - returning 'sssss' as column: NAME
2006-06-17 11:24:20,158 [1200] DEBUG NHibernate.Loader.Loader [(null)] <(null)> - done processing result set (4 rows)
2006-06-17 11:24:20,158 [1200] DEBUG NHibernate.Driver.NHybridDataReader [(null)] <(null)> - running NHybridDataReader.Dispose()
2006-06-17 11:24:20,169 [1200] DEBUG NHibernate.Impl.BatcherImpl [(null)] <(null)> - Closed Reader, open Readers :0
2006-06-17 11:24:20,169 [1200] DEBUG NHibernate.Impl.BatcherImpl [(null)] <(null)> - Closed IDbCommand, open IDbCommands :0
2006-06-17 11:24:20,169 [1200] DEBUG NHibernate.Loader.Loader [(null)] <(null)> - total objects hydrated: 4
2006-06-17 11:24:20,169 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - resolving associations for: [HOTM.Item#1]
2006-06-17 11:24:20,179 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - creating collection wrapper:[HOTM.Item.Bids#1]
2006-06-17 11:24:20,179 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - done materializing entity [HOTM.Item#1]
2006-06-17 11:24:20,179 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - resolving associations for: [HOTM.Item#2]
2006-06-17 11:24:20,179 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - creating collection wrapper:[HOTM.Item.Bids#2]
2006-06-17 11:24:20,179 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - done materializing entity [HOTM.Item#2]
2006-06-17 11:24:20,179 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - resolving associations for: [HOTM.Item#3]
2006-06-17 11:24:20,179 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - creating collection wrapper:[HOTM.Item.Bids#3]
2006-06-17 11:24:20,179 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - done materializing entity [HOTM.Item#3]
2006-06-17 11:24:20,179 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - resolving associations for: [HOTM.Item#4]
2006-06-17 11:24:20,179 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - creating collection wrapper:[HOTM.Item.Bids#4]
2006-06-17 11:24:20,179 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - done materializing entity [HOTM.Item#4]
2006-06-17 11:24:20,179 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - initializing non-lazy collections
2006-06-17 11:24:20,179 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - initializing collection [HOTM.Item.Bids#4]
2006-06-17 11:24:20,179 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - checking second-level cache
2006-06-17 11:24:20,189 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - collection not cached
2006-06-17 11:24:20,189 [1200] DEBUG NHibernate.Impl.BatcherImpl [(null)] <(null)> - Opened new IDbCommand, open IDbCommands :1
2006-06-17 11:24:20,189 [1200] DEBUG NHibernate.Impl.BatcherImpl [(null)] <(null)> - Building an IDbCommand object for the SqlString: SELECT bids0_.ITEM_ID as ITEM_ID__, bids0_.BID_ID as BID_ID__, bids0_.BID_ID as BID_ID0_, bids0_.AMOUNT as AMOUNT0_, bids0_.ITEM_ID as ITEM_ID0_ FROM HOTM1_BID bids0_ WHERE bids0_.ITEM_ID=:ITEM_ID
2006-06-17 11:24:20,189 [1200] DEBUG NHibernate.Type.Int32Type [(null)] <(null)> - binding '4' to parameter: 0
2006-06-17 11:24:20,199 [1200] INFO NHibernate.Loader.Loader [(null)] <(null)> - SELECT bids0_.ITEM_ID as ITEM_ID__, bids0_.BID_ID as BID_ID__, bids0_.BID_ID as BID_ID0_, bids0_.AMOUNT as AMOUNT0_, bids0_.ITEM_ID as ITEM_ID0_ FROM HOTM1_BID bids0_ WHERE bids0_.ITEM_ID=@p0
2006-06-17 11:24:20,199 [1200] DEBUG NHibernate.SQL [(null)] <(null)> - SELECT bids0_.ITEM_ID as ITEM_ID__, bids0_.BID_ID as BID_ID__, bids0_.BID_ID as BID_ID0_, bids0_.AMOUNT as AMOUNT0_, bids0_.ITEM_ID as ITEM_ID0_ FROM HOTM1_BID bids0_ WHERE bids0_.ITEM_ID=@p0
2006-06-17 11:24:20,199 [1200] DEBUG NHibernate.SQL [(null)] <(null)> - @p0 = '4'
2006-06-17 11:24:20,269 [1200] DEBUG NHibernate.Impl.BatcherImpl [(null)] <(null)> - Opened Reader, open Readers :1
2006-06-17 11:24:20,269 [1200] DEBUG NHibernate.Loader.Loader [(null)] <(null)> - result set contains (possibly empty) collection: [HOTM.Item.Bids#4]
2006-06-17 11:24:20,269 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - uninitialized collection: initializing
2006-06-17 11:24:20,279 [1200] DEBUG NHibernate.Loader.Loader [(null)] <(null)> - processing result set
2006-06-17 11:24:20,279 [1200] DEBUG NHibernate.Loader.Loader [(null)] <(null)> - done processing result set (0 rows)
2006-06-17 11:24:20,279 [1200] DEBUG NHibernate.Driver.NHybridDataReader [(null)] <(null)> - running NHybridDataReader.Dispose()
2006-06-17 11:24:20,279 [1200] DEBUG NHibernate.Impl.BatcherImpl [(null)] <(null)> - Closed Reader, open Readers :0
2006-06-17 11:24:20,279 [1200] DEBUG NHibernate.Impl.BatcherImpl [(null)] <(null)> - Closed IDbCommand, open IDbCommands :0
2006-06-17 11:24:20,279 [1200] DEBUG NHibernate.Loader.Loader [(null)] <(null)> - total objects hydrated: 0
2006-06-17 11:24:20,279 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - 1 collections were found in result set
2006-06-17 11:24:20,279 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - collection fully initialized: [HOTM.Item.Bids#4]
2006-06-17 11:24:20,279 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - 1 collections initialized
2006-06-17 11:24:20,279 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - collection initialized
2006-06-17 11:24:20,279 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - initializing collection [HOTM.Item.Bids#3]
2006-06-17 11:24:20,279 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - checking second-level cache
2006-06-17 11:24:20,279 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - collection not cached
2006-06-17 11:24:20,279 [1200] DEBUG NHibernate.Impl.BatcherImpl [(null)] <(null)> - Opened new IDbCommand, open IDbCommands :1
2006-06-17 11:24:20,279 [1200] DEBUG NHibernate.Impl.BatcherImpl [(null)] <(null)> - Building an IDbCommand object for the SqlString: SELECT bids0_.ITEM_ID as ITEM_ID__, bids0_.BID_ID as BID_ID__, bids0_.BID_ID as BID_ID0_, bids0_.AMOUNT as AMOUNT0_, bids0_.ITEM_ID as ITEM_ID0_ FROM HOTM1_BID bids0_ WHERE bids0_.ITEM_ID=:ITEM_ID
2006-06-17 11:24:20,279 [1200] DEBUG NHibernate.Type.Int32Type [(null)] <(null)> - binding '3' to parameter: 0
2006-06-17 11:24:20,279 [1200] INFO NHibernate.Loader.Loader [(null)] <(null)> - SELECT bids0_.ITEM_ID as ITEM_ID__, bids0_.BID_ID as BID_ID__, bids0_.BID_ID as BID_ID0_, bids0_.AMOUNT as AMOUNT0_, bids0_.ITEM_ID as ITEM_ID0_ FROM HOTM1_BID bids0_ WHERE bids0_.ITEM_ID=@p0
2006-06-17 11:24:20,279 [1200] DEBUG NHibernate.SQL [(null)] <(null)> - SELECT bids0_.ITEM_ID as ITEM_ID__, bids0_.BID_ID as BID_ID__, bids0_.BID_ID as BID_ID0_, bids0_.AMOUNT as AMOUNT0_, bids0_.ITEM_ID as ITEM_ID0_ FROM HOTM1_BID bids0_ WHERE bids0_.ITEM_ID=@p0
2006-06-17 11:24:20,279 [1200] DEBUG NHibernate.SQL [(null)] <(null)> - @p0 = '3'
2006-06-17 11:24:20,339 [1200] DEBUG NHibernate.Impl.BatcherImpl [(null)] <(null)> - Opened Reader, open Readers :1
2006-06-17 11:24:20,339 [1200] DEBUG NHibernate.Loader.Loader [(null)] <(null)> - result set contains (possibly empty) collection: [HOTM.Item.Bids#3]
2006-06-17 11:24:20,339 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - uninitialized collection: initializing
2006-06-17 11:24:20,339 [1200] DEBUG NHibernate.Loader.Loader [(null)] <(null)> - processing result set
2006-06-17 11:24:20,339 [1200] DEBUG NHibernate.Loader.Loader [(null)] <(null)> - done processing result set (0 rows)
2006-06-17 11:24:20,339 [1200] DEBUG NHibernate.Driver.NHybridDataReader [(null)] <(null)> - running NHybridDataReader.Dispose()
2006-06-17 11:24:20,339 [1200] DEBUG NHibernate.Impl.BatcherImpl [(null)] <(null)> - Closed Reader, open Readers :0
2006-06-17 11:24:20,339 [1200] DEBUG NHibernate.Impl.BatcherImpl [(null)] <(null)> - Closed IDbCommand, open IDbCommands :0
2006-06-17 11:24:20,339 [1200] DEBUG NHibernate.Loader.Loader [(null)] <(null)> - total objects hydrated: 0
2006-06-17 11:24:20,339 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - 1 collections were found in result set
2006-06-17 11:24:20,339 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - collection fully initialized: [HOTM.Item.Bids#3]
2006-06-17 11:24:20,339 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - 1 collections initialized
2006-06-17 11:24:20,339 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - collection initialized
2006-06-17 11:24:20,339 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - initializing collection [HOTM.Item.Bids#2]
2006-06-17 11:24:20,339 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - checking second-level cache
2006-06-17 11:24:20,339 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - collection not cached
2006-06-17 11:24:20,339 [1200] DEBUG NHibernate.Impl.BatcherImpl [(null)] <(null)> - Opened new IDbCommand, open IDbCommands :1
2006-06-17 11:24:20,339 [1200] DEBUG NHibernate.Impl.BatcherImpl [(null)] <(null)> - Building an IDbCommand object for the SqlString: SELECT bids0_.ITEM_ID as ITEM_ID__, bids0_.BID_ID as BID_ID__, bids0_.BID_ID as BID_ID0_, bids0_.AMOUNT as AMOUNT0_, bids0_.ITEM_ID as ITEM_ID0_ FROM HOTM1_BID bids0_ WHERE bids0_.ITEM_ID=:ITEM_ID
2006-06-17 11:24:20,339 [1200] DEBUG NHibernate.Type.Int32Type [(null)] <(null)> - binding '2' to parameter: 0
2006-06-17 11:24:20,339 [1200] INFO NHibernate.Loader.Loader [(null)] <(null)> - SELECT bids0_.ITEM_ID as ITEM_ID__, bids0_.BID_ID as BID_ID__, bids0_.BID_ID as BID_ID0_, bids0_.AMOUNT as AMOUNT0_, bids0_.ITEM_ID as ITEM_ID0_ FROM HOTM1_BID bids0_ WHERE bids0_.ITEM_ID=@p0
2006-06-17 11:24:20,339 [1200] DEBUG NHibernate.SQL [(null)] <(null)> - SELECT bids0_.ITEM_ID as ITEM_ID__, bids0_.BID_ID as BID_ID__, bids0_.BID_ID as BID_ID0_, bids0_.AMOUNT as AMOUNT0_, bids0_.ITEM_ID as ITEM_ID0_ FROM HOTM1_BID bids0_ WHERE bids0_.ITEM_ID=@p0
2006-06-17 11:24:20,339 [1200] DEBUG NHibernate.SQL [(null)] <(null)> - @p0 = '2'
2006-06-17 11:24:20,399 [1200] DEBUG NHibernate.Impl.BatcherImpl [(null)] <(null)> - Opened Reader, open Readers :1
2006-06-17 11:24:20,399 [1200] DEBUG NHibernate.Loader.Loader [(null)] <(null)> - result set contains (possibly empty) collection: [HOTM.Item.Bids#2]
2006-06-17 11:24:20,399 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - uninitialized collection: initializing
2006-06-17 11:24:20,399 [1200] DEBUG NHibernate.Loader.Loader [(null)] <(null)> - processing result set
2006-06-17 11:24:20,399 [1200] DEBUG NHibernate.Type.Int32Type [(null)] <(null)> - returning '1' as column: BID_ID0_
2006-06-17 11:24:20,399 [1200] DEBUG NHibernate.Loader.Loader [(null)] <(null)> - result row: 1
2006-06-17 11:24:20,399 [1200] DEBUG NHibernate.Loader.Loader [(null)] <(null)> - Initializing object from DataReader: 1
2006-06-17 11:24:20,399 [1200] DEBUG NHibernate.Loader.Loader [(null)] <(null)> - Hydrating entity: HOTM.Bid#1
2006-06-17 11:24:20,399 [1200] DEBUG NHibernate.Type.DoubleType [(null)] <(null)> - returning '10' as column: AMOUNT0_
2006-06-17 11:24:20,399 [1200] DEBUG NHibernate.Type.Int32Type [(null)] <(null)> - returning '2' as column: ITEM_ID0_
2006-06-17 11:24:20,399 [1200] DEBUG NHibernate.Type.Int32Type [(null)] <(null)> - returning '2' as column: ITEM_ID__
2006-06-17 11:24:20,399 [1200] DEBUG NHibernate.Loader.Loader [(null)] <(null)> - found row of collection: [HOTM.Item.Bids#2]
2006-06-17 11:24:20,399 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - reading row
2006-06-17 11:24:20,399 [1200] DEBUG NHibernate.Type.Int32Type [(null)] <(null)> - returning '1' as column: BID_ID__
2006-06-17 11:24:20,409 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - loading [Bid#1]
2006-06-17 11:24:20,409 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - attempting to resolve [Bid#1]
2006-06-17 11:24:20,409 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - resolved object in session cache [HOTM.Bid#1]
2006-06-17 11:24:20,409 [1200] DEBUG NHibernate.Type.Int32Type [(null)] <(null)> - returning '2' as column: BID_ID0_
2006-06-17 11:24:20,409 [1200] DEBUG NHibernate.Loader.Loader [(null)] <(null)> - result row: 2
2006-06-17 11:24:20,409 [1200] DEBUG NHibernate.Loader.Loader [(null)] <(null)> - Initializing object from DataReader: 2
2006-06-17 11:24:20,409 [1200] DEBUG NHibernate.Loader.Loader [(null)] <(null)> - Hydrating entity: HOTM.Bid#2
2006-06-17 11:24:20,409 [1200] DEBUG NHibernate.Type.DoubleType [(null)] <(null)> - returning '11' as column: AMOUNT0_
2006-06-17 11:24:20,409 [1200] DEBUG NHibernate.Type.Int32Type [(null)] <(null)> - returning '2' as column: ITEM_ID0_
2006-06-17 11:24:20,409 [1200] DEBUG NHibernate.Type.Int32Type [(null)] <(null)> - returning '2' as column: ITEM_ID__
2006-06-17 11:24:20,409 [1200] DEBUG NHibernate.Loader.Loader [(null)] <(null)> - found row of collection: [HOTM.Item.Bids#2]
2006-06-17 11:24:20,409 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - reading row
2006-06-17 11:24:20,409 [1200] DEBUG NHibernate.Type.Int32Type [(null)] <(null)> - returning '2' as column: BID_ID__
2006-06-17 11:24:20,409 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - loading [Bid#2]
2006-06-17 11:24:20,409 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - attempting to resolve [Bid#2]
2006-06-17 11:24:20,409 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - resolved object in session cache [HOTM.Bid#2]
2006-06-17 11:24:20,409 [1200] DEBUG NHibernate.Type.Int32Type [(null)] <(null)> - returning '3' as column: BID_ID0_
2006-06-17 11:24:20,409 [1200] DEBUG NHibernate.Loader.Loader [(null)] <(null)> - result row: 3
2006-06-17 11:24:20,409 [1200] DEBUG NHibernate.Loader.Loader [(null)] <(null)> - Initializing object from DataReader: 3
2006-06-17 11:24:20,409 [1200] DEBUG NHibernate.Loader.Loader [(null)] <(null)> - Hydrating entity: HOTM.Bid#3
2006-06-17 11:24:20,409 [1200] DEBUG NHibernate.Type.DoubleType [(null)] <(null)> - returning '12' as column: AMOUNT0_
2006-06-17 11:24:20,409 [1200] DEBUG NHibernate.Type.Int32Type [(null)] <(null)> - returning '2' as column: ITEM_ID0_
2006-06-17 11:24:20,409 [1200] DEBUG NHibernate.Type.Int32Type [(null)] <(null)> - returning '2' as column: ITEM_ID__
2006-06-17 11:24:20,409 [1200] DEBUG NHibernate.Loader.Loader [(null)] <(null)> - found row of collection: [HOTM.Item.Bids#2]
2006-06-17 11:24:20,409 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - reading row
2006-06-17 11:24:20,409 [1200] DEBUG NHibernate.Type.Int32Type [(null)] <(null)> - returning '3' as column: BID_ID__
2006-06-17 11:24:20,419 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - loading [Bid#3]
2006-06-17 11:24:20,419 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - attempting to resolve [Bid#3]
2006-06-17 11:24:20,419 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - resolved object in session cache [HOTM.Bid#3]
2006-06-17 11:24:20,419 [1200] DEBUG NHibernate.Loader.Loader [(null)] <(null)> - done processing result set (3 rows)
2006-06-17 11:24:20,419 [1200] DEBUG NHibernate.Driver.NHybridDataReader [(null)] <(null)> - running NHybridDataReader.Dispose()
2006-06-17 11:24:20,419 [1200] DEBUG NHibernate.Impl.BatcherImpl [(null)] <(null)> - Closed Reader, open Readers :0
2006-06-17 11:24:20,419 [1200] DEBUG NHibernate.Impl.BatcherImpl [(null)] <(null)> - Closed IDbCommand, open IDbCommands :0
2006-06-17 11:24:20,419 [1200] DEBUG NHibernate.Loader.Loader [(null)] <(null)> - total objects hydrated: 3
2006-06-17 11:24:20,419 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - resolving associations for: [HOTM.Bid#1]
2006-06-17 11:24:20,419 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - loading [Item#2]
2006-06-17 11:24:20,419 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - attempting to resolve [Item#2]
2006-06-17 11:24:20,419 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - resolved object in session cache [HOTM.Item#2]
2006-06-17 11:24:20,429 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - done materializing entity [HOTM.Bid#1]
2006-06-17 11:24:20,429 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - resolving associations for: [HOTM.Bid#2]
2006-06-17 11:24:20,429 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - loading [Item#2]
2006-06-17 11:24:20,429 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - attempting to resolve [Item#2]
2006-06-17 11:24:20,429 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - resolved object in session cache [HOTM.Item#2]
2006-06-17 11:24:20,429 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - done materializing entity [HOTM.Bid#2]
2006-06-17 11:24:20,429 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - resolving associations for: [HOTM.Bid#3]
2006-06-17 11:24:20,429 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - loading [Item#2]
2006-06-17 11:24:20,429 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - attempting to resolve [Item#2]
2006-06-17 11:24:20,429 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - resolved object in session cache [HOTM.Item#2]
2006-06-17 11:24:20,429 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - done materializing entity [HOTM.Bid#3]
2006-06-17 11:24:20,429 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - 1 collections were found in result set
2006-06-17 11:24:20,429 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - collection fully initialized: [HOTM.Item.Bids#2]
2006-06-17 11:24:20,429 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - 1 collections initialized
2006-06-17 11:24:20,429 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - collection initialized
2006-06-17 11:24:20,429 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - initializing collection [HOTM.Item.Bids#1]
2006-06-17 11:24:20,429 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - checking second-level cache
2006-06-17 11:24:20,429 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - collection not cached
2006-06-17 11:24:20,429 [1200] DEBUG NHibernate.Impl.BatcherImpl [(null)] <(null)> - Opened new IDbCommand, open IDbCommands :1
2006-06-17 11:24:20,429 [1200] DEBUG NHibernate.Impl.BatcherImpl [(null)] <(null)> - Building an IDbCommand object for the SqlString: SELECT bids0_.ITEM_ID as ITEM_ID__, bids0_.BID_ID as BID_ID__, bids0_.BID_ID as BID_ID0_, bids0_.AMOUNT as AMOUNT0_, bids0_.ITEM_ID as ITEM_ID0_ FROM HOTM1_BID bids0_ WHERE bids0_.ITEM_ID=:ITEM_ID
2006-06-17 11:24:20,429 [1200] DEBUG NHibernate.Type.Int32Type [(null)] <(null)> - binding '1' to parameter: 0
2006-06-17 11:24:20,429 [1200] INFO NHibernate.Loader.Loader [(null)] <(null)> - SELECT bids0_.ITEM_ID as ITEM_ID__, bids0_.BID_ID as BID_ID__, bids0_.BID_ID as BID_ID0_, bids0_.AMOUNT as AMOUNT0_, bids0_.ITEM_ID as ITEM_ID0_ FROM HOTM1_BID bids0_ WHERE bids0_.ITEM_ID=@p0
2006-06-17 11:24:20,429 [1200] DEBUG NHibernate.SQL [(null)] <(null)> - SELECT bids0_.ITEM_ID as ITEM_ID__, bids0_.BID_ID as BID_ID__, bids0_.BID_ID as BID_ID0_, bids0_.AMOUNT as AMOUNT0_, bids0_.ITEM_ID as ITEM_ID0_ FROM HOTM1_BID bids0_ WHERE bids0_.ITEM_ID=@p0
2006-06-17 11:24:20,429 [1200] DEBUG NHibernate.SQL [(null)] <(null)> - @p0 = '1'
2006-06-17 11:24:20,479 [1200] DEBUG NHibernate.Impl.BatcherImpl [(null)] <(null)> - Opened Reader, open Readers :1
2006-06-17 11:24:20,479 [1200] DEBUG NHibernate.Loader.Loader [(null)] <(null)> - result set contains (possibly empty) collection: [HOTM.Item.Bids#1]
2006-06-17 11:24:20,479 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - uninitialized collection: initializing
2006-06-17 11:24:20,479 [1200] DEBUG NHibernate.Loader.Loader [(null)] <(null)> - processing result set
2006-06-17 11:24:20,479 [1200] DEBUG NHibernate.Loader.Loader [(null)] <(null)> - done processing result set (0 rows)
2006-06-17 11:24:20,479 [1200] DEBUG NHibernate.Driver.NHybridDataReader [(null)] <(null)> - running NHybridDataReader.Dispose()
2006-06-17 11:24:20,479 [1200] DEBUG NHibernate.Impl.BatcherImpl [(null)] <(null)> - Closed Reader, open Readers :0
2006-06-17 11:24:20,479 [1200] DEBUG NHibernate.Impl.BatcherImpl [(null)] <(null)> - Closed IDbCommand, open IDbCommands :0
2006-06-17 11:24:20,479 [1200] DEBUG NHibernate.Loader.Loader [(null)] <(null)> - total objects hydrated: 0
2006-06-17 11:24:20,479 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - 1 collections were found in result set
2006-06-17 11:24:20,479 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - collection fully initialized: [HOTM.Item.Bids#1]
2006-06-17 11:24:20,479 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - 1 collections initialized
2006-06-17 11:24:20,479 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - collection initialized
2006-06-17 11:24:20,489 [1200] DEBUG NHibernate.Transaction.AdoTransaction [(null)] <(null)> - commit
2006-06-17 11:24:20,489 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - flushing session
2006-06-17 11:24:20,489 [1200] DEBUG NHibernate.Engine.Cascades [(null)] <(null)> - processing cascades for: HOTM.Item
2006-06-17 11:24:20,499 [1200] DEBUG NHibernate.Engine.Cascades [(null)] <(null)> - cascading to collection: HOTM.Item.Bids
2006-06-17 11:24:20,499 [1200] DEBUG NHibernate.Engine.Cascades [(null)] <(null)> - done processing cascades for: HOTM.Item
2006-06-17 11:24:20,499 [1200] DEBUG NHibernate.Engine.Cascades [(null)] <(null)> - processing cascades for: HOTM.Item
2006-06-17 11:24:20,499 [1200] DEBUG NHibernate.Engine.Cascades [(null)] <(null)> - cascading to collection: HOTM.Item.Bids
2006-06-17 11:24:20,499 [1200] DEBUG NHibernate.Engine.Cascades [(null)] <(null)> - cascading to SaveOrUpdate()
2006-06-17 11:24:20,499 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - SaveOrUpdate() persistent instance
2006-06-17 11:24:20,499 [1200] DEBUG NHibernate.Engine.Cascades [(null)] <(null)> - cascading to SaveOrUpdate()
2006-06-17 11:24:20,499 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - SaveOrUpdate() persistent instance
2006-06-17 11:24:20,499 [1200] DEBUG NHibernate.Engine.Cascades [(null)] <(null)> - cascading to SaveOrUpdate()
2006-06-17 11:24:20,499 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - SaveOrUpdate() persistent instance
2006-06-17 11:24:20,499 [1200] DEBUG NHibernate.Engine.Cascades [(null)] <(null)> - done processing cascades for: HOTM.Item
2006-06-17 11:24:20,499 [1200] DEBUG NHibernate.Engine.Cascades [(null)] <(null)> - processing cascades for: HOTM.Item
2006-06-17 11:24:20,499 [1200] DEBUG NHibernate.Engine.Cascades [(null)] <(null)> - cascading to collection: HOTM.Item.Bids
2006-06-17 11:24:20,499 [1200] DEBUG NHibernate.Engine.Cascades [(null)] <(null)> - done processing cascades for: HOTM.Item
2006-06-17 11:24:20,499 [1200] DEBUG NHibernate.Engine.Cascades [(null)] <(null)> - processing cascades for: HOTM.Item
2006-06-17 11:24:20,499 [1200] DEBUG NHibernate.Engine.Cascades [(null)] <(null)> - cascading to collection: HOTM.Item.Bids
2006-06-17 11:24:20,499 [1200] DEBUG NHibernate.Engine.Cascades [(null)] <(null)> - done processing cascades for: HOTM.Item
2006-06-17 11:24:20,509 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - Flushing entities and processing referenced collections
2006-06-17 11:24:20,519 [1200] DEBUG NHibernate.Impl.AbstractVisitor [(null)] <(null)> - Processing collection for role HOTM.Item.Bids
2006-06-17 11:24:20,519 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - Collection found: [HOTM.Item.Bids#1], was: [HOTM.Item.Bids#1]
2006-06-17 11:24:20,519 [1200] DEBUG NHibernate.Impl.AbstractVisitor [(null)] <(null)> - Processing collection for role HOTM.Item.Bids
2006-06-17 11:24:20,519 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - Collection found: [HOTM.Item.Bids#2], was: [HOTM.Item.Bids#2]
2006-06-17 11:24:20,519 [1200] DEBUG NHibernate.Impl.AbstractVisitor [(null)] <(null)> - Processing collection for role HOTM.Item.Bids
2006-06-17 11:24:20,519 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - Collection found: [HOTM.Item.Bids#3], was: [HOTM.Item.Bids#3]
2006-06-17 11:24:20,519 [1200] DEBUG NHibernate.Impl.AbstractVisitor [(null)] <(null)> - Processing collection for role HOTM.Item.Bids
2006-06-17 11:24:20,519 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - Collection found: [HOTM.Item.Bids#4], was: [HOTM.Item.Bids#4]
2006-06-17 11:24:20,519 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - Processing unreferenced collections
2006-06-17 11:24:20,519 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - scheduling collection removes/(re)creates/updates
2006-06-17 11:24:20,519 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - Flushed: 0 insertions, 0 updates, 0 deletions to 7 objects
2006-06-17 11:24:20,519 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - Flushed: 0 (re)creations, 0 updates, 0 removals to 4 collections
2006-06-17 11:24:20,519 [1200] DEBUG NHibernate.Impl.Printer [(null)] <(null)> - listing entities:
2006-06-17 11:24:20,519 [1200] DEBUG NHibernate.Impl.Printer [(null)] <(null)> - HOTM.Bid{IdBid=3, BidAmount=12, Item=Item#2}
2006-06-17 11:24:20,519 [1200] DEBUG NHibernate.Impl.Printer [(null)] <(null)> - HOTM.Bid{IdBid=2, BidAmount=11, Item=Item#2}
2006-06-17 11:24:20,519 [1200] DEBUG NHibernate.Impl.Printer [(null)] <(null)> - HOTM.Bid{IdBid=1, BidAmount=10, Item=Item#2}
2006-06-17 11:24:20,529 [1200] DEBUG NHibernate.Impl.Printer [(null)] <(null)> - HOTM.Item{Id=4, Name=sssss, Bids=[]}
2006-06-17 11:24:20,529 [1200] DEBUG NHibernate.Impl.Printer [(null)] <(null)> - HOTM.Item{Id=3, Name=Geek Socks, Bids=[]}
2006-06-17 11:24:20,529 [1200] DEBUG NHibernate.Impl.Printer [(null)] <(null)> - HOTM.Item{Id=2, Name=Geek Shirt, Bids=[Bid#1, Bid#3, Bid#2]}
2006-06-17 11:24:20,529 [1200] DEBUG NHibernate.Impl.Printer [(null)] <(null)> - HOTM.Item{Id=1, Name=Geek Cap, Bids=[]}
2006-06-17 11:24:20,529 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - executing flush
2006-06-17 11:24:20,529 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - post flush
2006-06-17 11:24:20,589 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - transaction completion
2006-06-17 11:24:20,589 [1200] DEBUG NHibernate.Transaction.AdoTransaction [(null)] <(null)> - running AdoTransaction.Dispose()
2006-06-17 11:24:20,589 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - closing session
2006-06-17 11:24:20,589 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - disconnecting session******************************
2006-06-17 11:24:20,589 [1200] DEBUG NHibernate.Connection.ConnectionProvider [(null)] <(null)> - Closing connection
2006-06-17 11:24:20,599 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - transaction completion**************************
2006-06-17 11:24:20,609 [1200] DEBUG NHibernate.Impl.SessionImpl [(null)] <(null)> - opened session**********************************
2006-06-17 11:24:20,609 [1200] DEBUG NHibernate.Transaction.AdoTransaction [(null)] <(null)> - begin
2006-06-17 11:24:20,609 [1200] DEBUG NHibernate.Connection.DriverConnectionProvider [(null)] <(null)> - Obtaining IDbConnection from Driver
2006-06-17 11:24:20,799 [1200] DEBUG NHibernate.Transaction.AdoTransaction [(null)] <(null)> - begin
2006-06-17 11:24:20,799 [1200] ERROR NHibernate.Transaction.AdoTransaction [(null)] <(null)> - Begin transaction failed
System.InvalidOperationException: SqlConnection does not support parallel transactions.
at System.Data.SqlClient.SqlConnection.BeginTransaction(IsolationLevel iso)
at System.Data.SqlClient.SqlConnection.BeginTransaction()
at System.Data.SqlClient.SqlConnection.System.Data.IDbConnection.BeginTransaction()
at NHibernate.Transaction.AdoTransaction.Begin(IsolationLevel isolationLevel)
2006-06-17 11:24:20,809 [1200] INFO HNibernate [(null)] <(null)> - ***********right after trying to get Items list**********
****************************************************************
MAPPING DOCUMENTS
****************************************************************

****************************************************************
CODE – NOTE THAT THE COMMENTED CODE IS THE JAVA EQUIVALENT
****************************************************************
THIS IS THE CODE FOR THE FIRST SESSION

********************************************************************
CODE FOR SEC0ND SESSION
********************************************************************
THE LISTENER ON THE listItem ListBox invokes the getBids method

***********************************************
Thanks,

Dokta T.

Edit: changed formatting of code sections - sergey

You forgot to close the first transaction in the code for the second session.

Yes, you are seeing the third transaction which I hadn’t considered because the log had indicated that the processing hadn’t even gotten that far. I was confused at this point but later realized that the reason why the first session was not working properly was due to the line where I was trying to insert Items into the ListBox. When I changed the line from listItem.Items.Add(tempItem); to listItem.Items.Add(tempItem.Name);,
I was able to proceed to the next session which was getting the bids. I was, however still getting the same error message about the SqlConnection not supporting parallel transactions. This was due, as you rightly pointed out, to the fact that I was trying to run another transaction on the same session without closing the previous one. In an attempt (hopefully not too pathetic) to add some clarity here, I think it worthwhile to note that Hibernate is able to execute the third transaction without any complaining (log4j set at DEBUG), while NHibernate is not. This is no excuse however, for trying to run transactions before committing and closing the previous ones. Thank you for your help and tolerance - Cheers, Doktat

I don't think it's something in Hibernate that allows it to execute two transactions in parallel, it's most likely an Oracle feature that MS SQL Server doesn't have.

We hit this issue as well. I'll post the link my co-worker found as soon as I see him on Monday.

Basically, SQL Server does not allow parallel transactions but the JET drivers do... odd.

There is support in the SqlConnection class for named save points in transactions, however it's not exposed in the IDbConnection class, so I'm guessing that's why it's not exposed in NHibernate.

I'd kill for transactions I could partially roll back...well, maybe not kill...but I'd sacrifice a beer!

Symon.