Summary of my question: According to the docs I've read, lazy-loading cannot occur outside the scope of a transaction unless auto-commit is on. I've verified that auto-commit is off in my app, so why is lazy-loading working outside of a transaction?
The details:
I'm trying to implement the Open Session in View pattern, and I've been debugging my progress as I go along to make sure I understand what's going on and am doing thing properly. In one of my tests I was expecting to get a LazyInitializationException but I didn't, and I'm hoping someone can help me understand why.
According to
http://hibernate.org/43.html "some developers are using a variation of this pattern that keeps the Session open until the view has been rendered, but commits the database transaction before rendering of the view. The consequences are the same as not keeping the Session open: lazy loading does not work outside of a database transaction. It doesn't matter if the Session is still open, it has no connection."
Based on that information I was expecting to get a LazyInitializationException when I committed a transaction and then accessed a lazy collection without starting another transaction, but it successfully lazy-loaded the collection without throwing an error. The next part of the URL above states: "further confusion appears when this anti-pattern actually works, but simply because the auto-commit mode is actually in use." I've verified that the connections I'm getting back are not auto-committable, so I don't know why it's not throwing an error and I want to know why to make sure I don't have some settings on that would cause poor performance or other errors down the road.
I'm using Hibernate 3.1.2, Tomcat 5.5.9, Struts 1.2.8, and MySQL 4.1.18 as the database. No J2EE container. Windows XP.
Here's the code that I'm expecting to throw a LazyInitializationException but doesn't (if it matters, I'm doing this inside a Struts Action):
------
Code:
Session session = HibernateUtil.getSessionFactory().getCurrentSession();
session.beginTransaction();
Person person = (Person)session.get(Person.class, new Long(1));
session.flush();
session.getTransaction().commit();
List itemList = person.getItemList();
//this should throw a LazyInitializationError. Why doesn't it?
Iterator iterator = itemList.iterator();
------
With debugging I've verified that itemList is null after person.getItemList() and is lazy-loaded on the itemList.iterator() call. My app is using an extended ThreadLocalSessionContext in order to prevent flushing and session closing. Here's the code for that (minus comments):
------
Code:
package com.testapp.dal.hibernate;
import org.hibernate.ConnectionReleaseMode;
import org.hibernate.FlushMode;
import org.hibernate.SessionFactory;
import org.hibernate.classic.Session;
import org.hibernate.context.ThreadLocalSessionContext;
import org.hibernate.engine.SessionFactoryImplementor;
public class ThreadLocalSessionContextNoAutoClose extends ThreadLocalSessionContext
{
public ThreadLocalSessionContextNoAutoClose(SessionFactoryImplementor factory)
{
super(factory);
}
protected boolean isAutoCloseEnabled()
{
return false;
}
protected boolean isAutoFlushEnabled()
{
return false;
}
protected Session buildOrObtainSession()
{
Session s = super.buildOrObtainSession();
s.setFlushMode(FlushMode.NEVER);
return s;
}
protected CleanupSynch buildCleanupSynch()
{
return new NoCleanupSynch(factory);
}
private static class NoCleanupSynch extends ThreadLocalSessionContext.CleanupSynch
{
public NoCleanupSynch(SessionFactory factory)
{
super(factory);
}
public void beforeCompletion()
{
//do nothing
}
public void afterCompletion(int i)
{
//do nothing
}
}
}
------
My HibernateUtil is the standard recommended one for Hibernate 3.1 found in
http://hibernate.org/42.html.
Here's my hibernate config file:
------
Code:
<?xml version="1.0" encoding="utf-8"?>
<!DOCTYPE hibernate-configuration PUBLIC "-//Hibernate/Hibernate Configuration DTD//EN"
"http://hibernate.sourceforge.net/hibernate-configuration-3.0.dtd">
<hibernate-configuration>
<session-factory>
<property name="dialect">org.hibernate.dialect.MySQLDialect</property>
<property name="connection.datasource">java:comp/env/jdbc/testapp</property>
<property name="hibernate.connection.autocommit">false</property>
<property name="hibernate.current_session_context_class">com.testapp.dal.hibernate.ThreadLocalSessionContextNoAutoClose</property>
<property name="cache.provider_class">org.hibernate.cache.EhCacheProvider</property>
<property name="show_sql">true</property>
<mapping resource="com/testapp/dal/hibernate/Person.hbm.xml"/>
<mapping resource="com/testapp/dal/hibernate/Item.hbm.xml"/>
</session-factory>
</hibernate-configuration>
------
Here's my Person mapping file:
------
Code:
<?xml version="1.0"?>
<!DOCTYPE hibernate-mapping PUBLIC
"-//Hibernate/Hibernate Mapping DTD 3.0//EN"
"http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd">
<hibernate-mapping>
<class name="com.testapp.dal.Person" table="person">
<id name="id" type="java.lang.Long" column="id">
<generator class="increment"/>
</id>
<property name="username" column="username" type="java.lang.String" not-null="true"/>
<property name="password" column="password" type="java.lang.String" not-null="true"/>
<bag name="itemList" cascade="all" inverse="true" lazy="true">
<key column="fk_person"/>
<one-to-many class="com.testapp.dal.Item"/>
</bag>
</class>
</hibernate-mapping>
------
Here's my Item mapping file:
------
Code:
<?xml version="1.0"?>
<!DOCTYPE hibernate-mapping PUBLIC
"-//Hibernate/Hibernate Mapping DTD 3.0//EN"
"http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd">
<hibernate-mapping>
<class name="com.testapp.dal.Item" table="item">
<id name="id" type="java.lang.Long" column="id">
<generator class="increment"/>
</id>
<many-to-one name="person" class="com.testapp.dal.Person" lazy="false">
<column name="fk_person"/>
</many-to-one>
</class>
</hibernate-mapping>
------
Here's the data source setup in my tomcat server.xml file:
------
Code:
<Resource name="jdbc/testapp"
auth="Container"
type="javax.sql.DataSource"
factory="org.apache.tomcat.dbcp.dbcp.BasicDataSourceFactory"
maxActive="100"
maxIdle="30"
maxWait="10000"
username="testapp"
password="testapp"
driverClassName="com.mysql.jdbc.Driver"
url="jdbc:mysql://localhost/testapp"
defaultAutoCommit="false"
removeAbandoned="true"
removeAbandonedTimeout="60"
logAbandoned="true"/>
------
I could include my Person and Item java files, but they're just standard getters and setters for the properties. Nothing special. Anybody have an idea on why I *don't* get a LazyInitializationException when accessing the not-yet-loaded item collection outside of a transaction? I'm happy to provide any more information if I forgot to include it here. In case the logs and generated SQL help, here's everything I get from session.beginTransaction() to itemList.iterator():
------
Code:
DEBUG [2006-02-19 00:39:55,859] [http-8080-Processor25] [org.hibernate.context.ThreadLocalSessionContext] - allowing method [beginTransaction] in non-transacted context
DEBUG [2006-02-19 00:39:55,859] [http-8080-Processor25] [org.hibernate.context.ThreadLocalSessionContext] - allowing proxied method [beginTransaction] to proceed to real session
DEBUG [2006-02-19 00:39:55,859] [http-8080-Processor25] [org.hibernate.transaction.JDBCTransaction] - begin
DEBUG [2006-02-19 00:39:55,859] [http-8080-Processor25] [org.hibernate.jdbc.ConnectionManager] - opening JDBC connection
DEBUG [2006-02-19 00:39:55,859] [http-8080-Processor25] [org.hibernate.transaction.JDBCTransaction] - current autocommit status: false
DEBUG [2006-02-19 00:39:55,859] [http-8080-Processor25] [org.hibernate.jdbc.JDBCContext] - after transaction begin
DEBUG [2006-02-19 00:40:52,140] [http-8080-Processor25] [org.hibernate.context.ThreadLocalSessionContext] - allowing proxied method [get] to proceed to real session
DEBUG [2006-02-19 00:40:52,187] [http-8080-Processor25] [org.hibernate.event.def.DefaultLoadEventListener] - loading entity: [com.testapp.dal.Person#1]
DEBUG [2006-02-19 00:40:52,187] [http-8080-Processor25] [org.hibernate.event.def.DefaultLoadEventListener] - attempting to resolve: [com.testapp.dal.Person#1]
DEBUG [2006-02-19 00:40:52,187] [http-8080-Processor25] [org.hibernate.event.def.DefaultLoadEventListener] - object not resolved in any cache: [com.testapp.dal.Person#1]
DEBUG [2006-02-19 00:40:52,187] [http-8080-Processor25] [org.hibernate.persister.entity.AbstractEntityPersister] - Fetching entity: [com.testapp.dal.Person#1]
DEBUG [2006-02-19 00:40:52,187] [http-8080-Processor25] [org.hibernate.loader.Loader] - loading entity: [com.testapp.dal.Person#1]
DEBUG [2006-02-19 00:40:52,187] [http-8080-Processor25] [org.hibernate.jdbc.AbstractBatcher] - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
DEBUG [2006-02-19 00:40:52,203] [http-8080-Processor25] [org.hibernate.SQL] - select person0_.id as id0_0_, person0_.username as username0_0_, person0_.password as password0_0_ from person person0_ where person0_.id=?
Hibernate: select person0_.id as id0_0_, person0_.username as username0_0_, person0_.password as password0_0_ from person person0_ where person0_.id=?
DEBUG [2006-02-19 00:40:52,203] [http-8080-Processor25] [org.hibernate.jdbc.AbstractBatcher] - preparing statement
DEBUG [2006-02-19 00:40:52,234] [http-8080-Processor25] [org.hibernate.type.LongType] - binding '1' to parameter: 1
DEBUG [2006-02-19 00:40:52,250] [http-8080-Processor25] [org.hibernate.jdbc.AbstractBatcher] - about to open ResultSet (open ResultSets: 0, globally: 0)
DEBUG [2006-02-19 00:40:52,265] [http-8080-Processor25] [org.hibernate.loader.Loader] - processing result set
DEBUG [2006-02-19 00:40:52,265] [http-8080-Processor25] [org.hibernate.loader.Loader] - result set row: 0
DEBUG [2006-02-19 00:40:52,265] [http-8080-Processor25] [org.hibernate.loader.Loader] - result row: EntityKey[com.testapp.dal.Person#1]
DEBUG [2006-02-19 00:40:52,265] [http-8080-Processor25] [org.hibernate.loader.Loader] - Initializing object from ResultSet: [com.testapp.dal.Person#1]
DEBUG [2006-02-19 00:40:52,296] [http-8080-Processor25] [org.hibernate.persister.entity.AbstractEntityPersister] - Hydrating entity: [com.testapp.dal.Person#1]
DEBUG [2006-02-19 00:40:52,296] [http-8080-Processor25] [org.hibernate.type.StringType] - returning 'someuser5' as column: username0_0_
DEBUG [2006-02-19 00:40:52,296] [http-8080-Processor25] [org.hibernate.type.StringType] - returning 'somepassword' as column: password0_0_
DEBUG [2006-02-19 00:40:52,312] [http-8080-Processor25] [org.hibernate.loader.Loader] - done processing result set (1 rows)
DEBUG [2006-02-19 00:40:52,312] [http-8080-Processor25] [org.hibernate.jdbc.AbstractBatcher] - about to close ResultSet (open ResultSets: 1, globally: 1)
DEBUG [2006-02-19 00:40:52,312] [http-8080-Processor25] [org.hibernate.jdbc.AbstractBatcher] - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
DEBUG [2006-02-19 00:40:52,328] [http-8080-Processor25] [org.hibernate.jdbc.AbstractBatcher] - closing statement
DEBUG [2006-02-19 00:40:52,343] [http-8080-Processor25] [org.hibernate.loader.Loader] - total objects hydrated: 1
DEBUG [2006-02-19 00:40:52,343] [http-8080-Processor25] [org.hibernate.engine.TwoPhaseLoad] - resolving associations for [com.testapp.dal.Person#1]
DEBUG [2006-02-19 00:40:52,390] [http-8080-Processor25] [org.hibernate.engine.CollectionLoadContext] - creating collection wrapper:[com.testapp.dal.Person.itemList#1]
DEBUG [2006-02-19 00:40:52,421] [http-8080-Processor25] [org.hibernate.engine.TwoPhaseLoad] - done materializing entity [com.testapp.dal.Person#1]
DEBUG [2006-02-19 00:40:52,421] [http-8080-Processor25] [org.hibernate.engine.StatefulPersistenceContext] - initializing non-lazy collections
DEBUG [2006-02-19 00:40:52,421] [http-8080-Processor25] [org.hibernate.loader.Loader] - done entity load
DEBUG [2006-02-19 00:41:15,625] [http-8080-Processor25] [org.hibernate.context.ThreadLocalSessionContext] - allowing proxied method [flush] to proceed to real session
DEBUG [2006-02-19 00:41:15,640] [http-8080-Processor25] [org.hibernate.event.def.AbstractFlushingEventListener] - flushing session
DEBUG [2006-02-19 00:41:15,640] [http-8080-Processor25] [org.hibernate.event.def.AbstractFlushingEventListener] - processing flush-time cascades
DEBUG [2006-02-19 00:41:15,671] [http-8080-Processor25] [org.hibernate.engine.Cascade] - processing cascade ACTION_SAVE_UPDATE for: com.testapp.dal.Person
DEBUG [2006-02-19 00:41:15,671] [http-8080-Processor25] [org.hibernate.engine.Cascade] - cascade ACTION_SAVE_UPDATE for collection: com.testapp.dal.Person.itemList
DEBUG [2006-02-19 00:41:15,671] [http-8080-Processor25] [org.hibernate.engine.Cascade] - done cascade ACTION_SAVE_UPDATE for collection: com.testapp.dal.Person.itemList
DEBUG [2006-02-19 00:41:15,671] [http-8080-Processor25] [org.hibernate.engine.Cascade] - done processing cascade ACTION_SAVE_UPDATE for: com.testapp.dal.Person
DEBUG [2006-02-19 00:41:15,671] [http-8080-Processor25] [org.hibernate.event.def.AbstractFlushingEventListener] - dirty checking collections
DEBUG [2006-02-19 00:41:15,671] [http-8080-Processor25] [org.hibernate.event.def.AbstractFlushingEventListener] - Flushing entities and processing referenced collections
DEBUG [2006-02-19 00:41:15,750] [http-8080-Processor25] [org.hibernate.engine.Collections] - Collection found: [com.testapp.dal.Person.itemList#1], was: [com.testapp.dal.Person.itemList#1] (uninitialized)
DEBUG [2006-02-19 00:41:15,750] [http-8080-Processor25] [org.hibernate.event.def.AbstractFlushingEventListener] - Processing unreferenced collections
DEBUG [2006-02-19 00:41:15,750] [http-8080-Processor25] [org.hibernate.event.def.AbstractFlushingEventListener] - Scheduling collection removes/(re)creates/updates
DEBUG [2006-02-19 00:41:15,750] [http-8080-Processor25] [org.hibernate.event.def.AbstractFlushingEventListener] - Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
DEBUG [2006-02-19 00:41:15,750] [http-8080-Processor25] [org.hibernate.event.def.AbstractFlushingEventListener] - Flushed: 0 (re)creations, 0 updates, 0 removals to 1 collections
DEBUG [2006-02-19 00:41:15,765] [http-8080-Processor25] [org.hibernate.pretty.Printer] - listing entities:
DEBUG [2006-02-19 00:41:15,765] [http-8080-Processor25] [org.hibernate.pretty.Printer] - com.testapp.dal.Person{password=somepassword, username=someuser5, itemList=<uninitialized>, id=1}
DEBUG [2006-02-19 00:41:15,765] [http-8080-Processor25] [org.hibernate.event.def.AbstractFlushingEventListener] - executing flush
DEBUG [2006-02-19 00:41:15,765] [http-8080-Processor25] [org.hibernate.event.def.AbstractFlushingEventListener] - post flush
DEBUG [2006-02-19 00:41:17,421] [http-8080-Processor25] [org.hibernate.context.ThreadLocalSessionContext] - allowing proxied method [getTransaction] to proceed to real session
DEBUG [2006-02-19 00:41:17,437] [http-8080-Processor25] [org.hibernate.transaction.JDBCTransaction] - commit
DEBUG [2006-02-19 00:41:17,437] [http-8080-Processor25] [org.hibernate.jdbc.JDBCContext] - before transaction completion
DEBUG [2006-02-19 00:41:17,437] [http-8080-Processor25] [org.hibernate.impl.SessionImpl] - before transaction completion
DEBUG [2006-02-19 00:41:17,437] [http-8080-Processor25] [org.hibernate.transaction.JDBCTransaction] - committed JDBC Connection
DEBUG [2006-02-19 00:41:17,437] [http-8080-Processor25] [org.hibernate.jdbc.JDBCContext] - after transaction completion
DEBUG [2006-02-19 00:41:17,437] [http-8080-Processor25] [org.hibernate.jdbc.ConnectionManager] - aggressively releasing JDBC connection
DEBUG [2006-02-19 00:41:17,437] [http-8080-Processor25] [org.hibernate.jdbc.ConnectionManager] - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
DEBUG [2006-02-19 00:41:17,453] [http-8080-Processor25] [org.hibernate.impl.SessionImpl] - after transaction completion
DEBUG [2006-02-19 00:41:27,609] [http-8080-Processor25] [org.hibernate.event.def.DefaultInitializeCollectionEventListener] - initializing collection [com.testapp.dal.Person.itemList#1]
DEBUG [2006-02-19 00:41:27,625] [http-8080-Processor25] [org.hibernate.event.def.DefaultInitializeCollectionEventListener] - checking second-level cache
DEBUG [2006-02-19 00:41:27,625] [http-8080-Processor25] [org.hibernate.event.def.DefaultInitializeCollectionEventListener] - collection not cached
DEBUG [2006-02-19 00:41:27,625] [http-8080-Processor25] [org.hibernate.loader.Loader] - loading collection: [com.testapp.dal.Person.itemList#1]
DEBUG [2006-02-19 00:41:27,625] [http-8080-Processor25] [org.hibernate.jdbc.AbstractBatcher] - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
DEBUG [2006-02-19 00:41:27,625] [http-8080-Processor25] [org.hibernate.jdbc.ConnectionManager] - opening JDBC connection
DEBUG [2006-02-19 00:41:27,625] [http-8080-Processor25] [org.hibernate.SQL] - select itemlist0_.fk_person as fk2_1_, itemlist0_.id as id1_, itemlist0_.id as id1_0_, itemlist0_.fk_person as fk2_1_0_ from item itemlist0_ where itemlist0_.fk_person=?
Hibernate: select itemlist0_.fk_person as fk2_1_, itemlist0_.id as id1_, itemlist0_.id as id1_0_, itemlist0_.fk_person as fk2_1_0_ from item itemlist0_ where itemlist0_.fk_person=?
DEBUG [2006-02-19 00:41:27,625] [http-8080-Processor25] [org.hibernate.jdbc.AbstractBatcher] - preparing statement
DEBUG [2006-02-19 00:41:27,640] [http-8080-Processor25] [org.hibernate.type.LongType] - binding '1' to parameter: 1
DEBUG [2006-02-19 00:41:27,640] [http-8080-Processor25] [org.hibernate.jdbc.AbstractBatcher] - about to open ResultSet (open ResultSets: 0, globally: 0)
DEBUG [2006-02-19 00:41:27,640] [http-8080-Processor25] [org.hibernate.loader.Loader] - result set contains (possibly empty) collection: [com.testapp.dal.Person.itemList#1]
DEBUG [2006-02-19 00:41:27,640] [http-8080-Processor25] [org.hibernate.engine.CollectionLoadContext] - uninitialized collection: initializing
DEBUG [2006-02-19 00:41:27,656] [http-8080-Processor25] [org.hibernate.loader.Loader] - processing result set
DEBUG [2006-02-19 00:41:27,656] [http-8080-Processor25] [org.hibernate.loader.Loader] - result set row: 0
DEBUG [2006-02-19 00:41:27,656] [http-8080-Processor25] [org.hibernate.type.LongType] - returning '1' as column: id1_0_
DEBUG [2006-02-19 00:41:27,656] [http-8080-Processor25] [org.hibernate.loader.Loader] - result row: EntityKey[com.testapp.dal.Item#1]
DEBUG [2006-02-19 00:41:27,656] [http-8080-Processor25] [org.hibernate.loader.Loader] - Initializing object from ResultSet: [com.testapp.dal.Item#1]
DEBUG [2006-02-19 00:41:27,656] [http-8080-Processor25] [org.hibernate.persister.entity.AbstractEntityPersister] - Hydrating entity: [com.testapp.dal.Item#1]
DEBUG [2006-02-19 00:41:27,656] [http-8080-Processor25] [org.hibernate.type.LongType] - returning '1' as column: fk2_1_0_
DEBUG [2006-02-19 00:41:27,656] [http-8080-Processor25] [org.hibernate.type.LongType] - returning '1' as column: fk2_1_
DEBUG [2006-02-19 00:41:27,656] [http-8080-Processor25] [org.hibernate.loader.Loader] - found row of collection: [com.testapp.dal.Person.itemList#1]
DEBUG [2006-02-19 00:41:27,656] [http-8080-Processor25] [org.hibernate.engine.CollectionLoadContext] - reading row
DEBUG [2006-02-19 00:41:27,656] [http-8080-Processor25] [org.hibernate.type.LongType] - returning '1' as column: id1_
DEBUG [2006-02-19 00:41:27,656] [http-8080-Processor25] [org.hibernate.event.def.DefaultLoadEventListener] - loading entity: [com.testapp.dal.Item#1]
DEBUG [2006-02-19 00:41:27,656] [http-8080-Processor25] [org.hibernate.event.def.DefaultLoadEventListener] - attempting to resolve: [com.testapp.dal.Item#1]
DEBUG [2006-02-19 00:41:27,671] [http-8080-Processor25] [org.hibernate.event.def.DefaultLoadEventListener] - resolved object in session cache: [com.testapp.dal.Item#1]
DEBUG [2006-02-19 00:41:27,671] [http-8080-Processor25] [org.hibernate.loader.Loader] - done processing result set (1 rows)
DEBUG [2006-02-19 00:41:27,671] [http-8080-Processor25] [org.hibernate.jdbc.AbstractBatcher] - about to close ResultSet (open ResultSets: 1, globally: 1)
DEBUG [2006-02-19 00:41:27,671] [http-8080-Processor25] [org.hibernate.jdbc.AbstractBatcher] - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
DEBUG [2006-02-19 00:41:27,671] [http-8080-Processor25] [org.hibernate.jdbc.AbstractBatcher] - closing statement
DEBUG [2006-02-19 00:41:27,687] [http-8080-Processor25] [org.hibernate.loader.Loader] - total objects hydrated: 1
DEBUG [2006-02-19 00:41:27,687] [http-8080-Processor25] [org.hibernate.engine.TwoPhaseLoad] - resolving associations for [com.testapp.dal.Item#1]
DEBUG [2006-02-19 00:41:27,703] [http-8080-Processor25] [org.hibernate.event.def.DefaultLoadEventListener] - loading entity: [com.testapp.dal.Person#1]
DEBUG [2006-02-19 00:41:27,703] [http-8080-Processor25] [org.hibernate.event.def.DefaultLoadEventListener] - attempting to resolve: [com.testapp.dal.Person#1]
DEBUG [2006-02-19 00:41:27,703] [http-8080-Processor25] [org.hibernate.event.def.DefaultLoadEventListener] - resolved object in session cache: [com.testapp.dal.Person#1]
DEBUG [2006-02-19 00:41:27,703] [http-8080-Processor25] [org.hibernate.engine.TwoPhaseLoad] - done materializing entity [com.testapp.dal.Item#1]
DEBUG [2006-02-19 00:41:27,703] [http-8080-Processor25] [org.hibernate.engine.CollectionLoadContext] - 1 collections were found in result set for role: com.testapp.dal.Person.itemList
DEBUG [2006-02-19 00:41:27,703] [http-8080-Processor25] [org.hibernate.engine.CollectionLoadContext] - collection fully initialized: [com.testapp.dal.Person.itemList#1]
DEBUG [2006-02-19 00:41:27,703] [http-8080-Processor25] [org.hibernate.engine.CollectionLoadContext] - 1 collections initialized for role: com.testapp.dal.Person.itemList
DEBUG [2006-02-19 00:41:27,703] [http-8080-Processor25] [org.hibernate.engine.StatefulPersistenceContext] - initializing non-lazy collections
DEBUG [2006-02-19 00:41:27,703] [http-8080-Processor25] [org.hibernate.loader.Loader] - done loading collection
DEBUG [2006-02-19 00:41:27,703] [http-8080-Processor25] [org.hibernate.event.def.DefaultInitializeCollectionEventListener] - collection initialized
------
<edited to make the post easier to read>