Hi,

I have a simple test program to reproduce the problem. The tables reflect real tables in our product, but they have been simplified for the test and should be easy to replicate. All of the required information is below. It is fairly complete and exhaustive (maybe even too much information).

Problem description:

We have data in a 4 level hierarchy or tree. The child nodes are stored in sets. I then run a query to load all of the tree using query and iterate(). This places the data in the cache. When I try to load the data again using query and iterate, it finds all of the nodes in the cache instead of doing the query. The problem is, the nodes no longer contain any member data. All of the fields are now null. I query the data by the leaf nodes.

D
*C1
**B1
***A1
***A2
**B2
***A3
***A4

I do the query on A. C has a hashCode that depends on a name and a sequence number. Now name is null. I have the complete mappings, test code and logging below. This is probably a bug and it would be great if someone can provide some assistance. Thanks.

chuck

P.S. I didn't include class A-D because they just have a reference to their parent and children. Except for C which has a name and sequence and the following hashCode method.

public int hashCode() {
return getSequence() + getName().hashCode();
}



Hibernate version: 2.1.7c

Mapping documents:

<?xml version="1.0" encoding="UTF-8"?>

<!DOCTYPE hibernate-mapping PUBLIC
"-//Hibernate/Hibernate Mapping DTD 2.0//EN"
"http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd">

<hibernate-mapping>
<class name="com.reddline.test.A" table="slot">
<cache usage="read-write" />

<id name="surrogateId" column="surrogate_id" type="java.lang.Long">
<generator class="sequence"/>
</id>

<many-to-one name="parent" class="com.reddline.test.B" column="shelf_id"/>
</class>

</hibernate-mapping>


<?xml version="1.0" encoding="UTF-8"?>

<!DOCTYPE hibernate-mapping PUBLIC
"-//Hibernate/Hibernate Mapping DTD 2.0//EN"
"http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd">

<hibernate-mapping>
<class name="com.reddline.test.B" table="shelf">
<cache usage="read-write" />

<id name="surrogateId" column="surrogate_id" type="java.lang.Long">
<generator class="sequence"/>
</id>

<many-to-one name="parent" class="com.reddline.test.C" column="bay_id"/>

<set name="children" inverse="true" cascade="all-delete-orphan" sort="natural">
<cache usage="read-write"/>
<key column="shelf_id"/>

<one-to-many class="com.reddline.test.A"/>

</set>
</class>

</hibernate-mapping>


<?xml version="1.0" encoding="UTF-8"?>

<!DOCTYPE hibernate-mapping PUBLIC
"-//Hibernate/Hibernate Mapping DTD 2.0//EN"
"http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd">

<hibernate-mapping>
<class name="com.reddline.test.C" table="bay">
<cache usage="read-write" />

<id name="surrogateId" column="surrogate_id" type="java.lang.Long">
<generator class="sequence"/>
</id>

<property name="name" type="java.lang.String" column="name" not-null="true"/>

<property name="sequence" type="int" column="sequence"/>

<many-to-one name="parent" class="com.reddline.test.D" column="section_id"/>

<set name="children" inverse="true" cascade="all-delete-orphan" sort="natural">
<cache usage="read-write" />
<key column="bay_id"/>
<one-to-many class="com.reddline.test.B"/>
</set>

</class>

</hibernate-mapping>



<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE hibernate-mapping PUBLIC
"-//Hibernate/Hibernate Mapping DTD 2.0//EN"
"http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd">

<hibernate-mapping>
<class name="com.reddline.test.D" table="section">
<cache usage="read-write" />

<id name="surrogateId" column="surrogate_id" type="java.lang.Long">
<generator class="sequence"/>
</id>

<set name="children" inverse="true" cascade="all-delete-orphan" sort="natural">
<cache usage="read-write"/>
<key column="section_id"/>
<one-to-many class="com.reddline.test.C"/>
</set>

</class>

</hibernate-mapping>






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

public static void main(String[] args) throws Exception {
Tester test;

//create the test
test = new Tester();
//load the A object graph into the cache
test.loadA();
System.out.println"********************************************);
//get the A graph from the cache
test.loadA();
}

public void loadA() throws HibernateException {
Session session = null;
Transaction transaction = null;
Query query;

try {
//get a session
session = getSession(); //SessionFactory.openSession()
//get the transaction
transaction = session.beginTransaction();
//create the query
query = session.createQuery("from A");
//load the elements
query.iterate();
//commit the transaction
transaction.commit();
} catch (HibernateException hibEx) {
if (transaction != null) {
//rollback the transaction
transaction.rollback();
}
} finally {
if (session != null) {
session.close();
}
}
}


Full stack trace of any exception that occurs:

[18:52:12.657] [DEBUG] [net.sf.hibernate.impl.BatcherImpl] - closing statement
Exception in thread "main" java.lang.NullPointerException
at com.reddline.test.C.hashCode(C.java:81)
at java.util.HashMap.hash(HashMap.java:264)
at java.util.HashMap.put(HashMap.java:382)
at net.sf.hibernate.collection.Set.snapshot(Set.java:40)
at net.sf.hibernate.collection.PersistentCollection.getSnapshot(PersistentCollection.java:325)
at net.sf.hibernate.impl.SessionImpl$CollectionEntry.postInitialize(SessionImpl.java:359)
at net.sf.hibernate.impl.SessionImpl.initializeCollectionFromCache(SessionImpl.java:4013)
at net.sf.hibernate.impl.SessionImpl.initializeCollection(SessionImpl.java:3297)
at net.sf.hibernate.collection.PersistentCollection.forceInitialization(PersistentCollection.java:336)
at net.sf.hibernate.impl.SessionImpl.initializeNonLazyCollections(SessionImpl.java:3156)
at net.sf.hibernate.impl.SessionImpl.assembleCacheEntry(SessionImpl.java:2152)
at net.sf.hibernate.impl.SessionImpl.doLoad(SessionImpl.java:2125)
at net.sf.hibernate.impl.SessionImpl.doLoadByClass(SessionImpl.java:2000)
at net.sf.hibernate.impl.SessionImpl.internalLoad(SessionImpl.java:1962)
at net.sf.hibernate.type.ManyToOneType.resolveIdentifier(ManyToOneType.java:69)
at net.sf.hibernate.type.ManyToOneType.assemble(ManyToOneType.java:108)
at net.sf.hibernate.impl.CacheEntry.assemble(CacheEntry.java:56)
at net.sf.hibernate.impl.CacheEntry.assemble(CacheEntry.java:48)
at net.sf.hibernate.impl.SessionImpl.assembleCacheEntry(SessionImpl.java:2147)
at net.sf.hibernate.impl.SessionImpl.doLoad(SessionImpl.java:2125)
at net.sf.hibernate.impl.SessionImpl.doLoadByClass(SessionImpl.java:2000)
at net.sf.hibernate.impl.SessionImpl.internalLoad(SessionImpl.java:1962)
at net.sf.hibernate.type.ManyToOneType.resolveIdentifier(ManyToOneType.java:69)
at net.sf.hibernate.type.ManyToOneType.assemble(ManyToOneType.java:108)
at net.sf.hibernate.impl.CacheEntry.assemble(CacheEntry.java:56)
at net.sf.hibernate.impl.CacheEntry.assemble(CacheEntry.java:48)
at net.sf.hibernate.impl.SessionImpl.assembleCacheEntry(SessionImpl.java:2147)
at net.sf.hibernate.impl.SessionImpl.doLoad(SessionImpl.java:2125)
at net.sf.hibernate.impl.SessionImpl.doLoadByClass(SessionImpl.java:2000)
at net.sf.hibernate.impl.SessionImpl.internalLoad(SessionImpl.java:1962)
at net.sf.hibernate.type.ManyToOneType.resolveIdentifier(ManyToOneType.java:69)
at net.sf.hibernate.type.ManyToOneType.assemble(ManyToOneType.java:108)
at net.sf.hibernate.impl.CacheEntry.assemble(CacheEntry.java:56)
at net.sf.hibernate.impl.CacheEntry.assemble(CacheEntry.java:48)
at net.sf.hibernate.impl.SessionImpl.assembleCacheEntry(SessionImpl.java:2147)
at net.sf.hibernate.impl.SessionImpl.doLoad(SessionImpl.java:2125)
at net.sf.hibernate.impl.SessionImpl.doLoadByClass(SessionImpl.java:2000)
at net.sf.hibernate.impl.SessionImpl.internalLoad(SessionImpl.java:1962)
at net.sf.hibernate.type.ManyToOneType.resolveIdentifier(ManyToOneType.java:69)
at net.sf.hibernate.type.EntityType.resolveIdentifier(EntityType.java:204)
at net.sf.hibernate.type.EntityType.nullSafeGet(EntityType.java:126)
at net.sf.hibernate.impl.IteratorImpl.postNext(IteratorImpl.java:93)
at net.sf.hibernate.impl.IteratorImpl.<init>(IteratorImpl.java:64)
at net.sf.hibernate.hql.QueryTranslator.iterate(QueryTranslator.java:869)
at net.sf.hibernate.impl.SessionImpl.iterate(SessionImpl.java:1618)
at net.sf.hibernate.impl.QueryImpl.iterate(QueryImpl.java:27)
at com.reddline.test.Tester.loadA(Tester.java:64)
at com.reddline.test.Tester.main(Tester.java:88)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:585)
at com.intellij.rt.execution.application.AppMain.main(AppMain.java:78)
[18:52:12.667] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - running Session.finalize()

Name and version of the database you are using:

MaxDB 7.5.0.18

The generated SQL (show_sql=true):

Hibernate: select a0_.surrogate_id as x0_0_ from slot a0_
Hibernate: select a0_.surrogate_id as surrogat1_3_, a0_.shelf_id as shelf_id3_, b1_.surrogate_id as surrogat1_0_, b1_.bay_id as bay_id0_, c2_.surrogate_id as surrogat1_1_, c2_.name as name1_, c2_.sequence as sequence1_, c2_.section_id as section_id1_, d3_.surrogate_id as surrogat1_2_ from slot a0_, shelf b1_, bay c2_, section d3_ where a0_.surrogate_id=? and a0_.shelf_id=b1_.surrogate_id(+) and b1_.bay_id=c2_.surrogate_id(+) and c2_.section_id=d3_.surrogate_id(+)
Hibernate: select children0_.section_id as section_id__, children0_.surrogate_id as surrogat1___, children0_.surrogate_id as surrogat1_0_, children0_.name as name0_, children0_.sequence as sequence0_, children0_.section_id as section_id0_ from bay children0_ where children0_.section_id=?
Hibernate: select children0_.bay_id as bay_id__, children0_.surrogate_id as surrogat1___, children0_.surrogate_id as surrogat1_0_, children0_.bay_id as bay_id0_ from shelf children0_ where children0_.bay_id=?
Hibernate: select children0_.shelf_id as shelf_id__, children0_.surrogate_id as surrogat1___, children0_.surrogate_id as surrogat1_0_, children0_.shelf_id as shelf_id0_ from slot children0_ where children0_.shelf_id=?
Hibernate: select children0_.shelf_id as shelf_id__, children0_.surrogate_id as surrogat1___, children0_.surrogate_id as surrogat1_0_, children0_.shelf_id as shelf_id0_ from slot children0_ where children0_.shelf_id=?
**********************************************
Hibernate: select a0_.surrogate_id as x0_0_ from slot a0_

Debug level Hibernate log excerpt:

[18:52:11.305] [INFO ] [net.sf.hibernate.dialect.Dialect] - Using dialect: net.sf.hibernate.dialect.SAPDBDialect
[18:52:11.315] [DEBUG] [net.sf.hibernate.exception.SQLExceptionConverterFactory] - Using dialect defined converter
[18:52:11.325] [INFO ] [net.sf.hibernate.connection.C3P0ConnectionProvider] - C3P0 using driver: com.sap.dbtech.jdbc.DriverSapDB at URL: jdbc:sapdb://localhost/reddline
[18:52:11.325] [INFO ] [net.sf.hibernate.connection.C3P0ConnectionProvider] - Connection properties: {user=dba, password=dba}
[18:52:11.385] [INFO ] [net.sf.hibernate.transaction.TransactionFactoryFactory] - Transaction strategy: net.sf.hibernate.transaction.JDBCTransactionFactory
[18:52:11.385] [INFO ] [net.sf.hibernate.transaction.TransactionManagerLookupFactory] - No TransactionManagerLookup configured (in JTA environment, use of process level read-write cache is not recommended)
Initializing c3p0 pool... com.mchange.v2.c3p0.PoolBackedDataSource@65a77f [ connectionPoolDataSource -> com.mchange.v2.c3p0.WrapperConnectionPoolDataSource@1ccce3c [ acquireIncrement -> 1, autoCommitOnClose -> false, connectionTesterClassName -> com.mchange.v2.c3p0.impl.DefaultConnectionTester, factoryClassLocation -> null, forceIgnoreUnresolvedTransactions -> false, idleConnectionTestPeriod -> 3000, initialPoolSize -> 5, maxIdleTime -> 300, maxPoolSize -> 30, maxStatements -> 50, minPoolSize -> 5, nestedDataSource -> com.mchange.v2.c3p0.DriverManagerDataSource@1d7ad1c [ description -> null, driverClass -> null, factoryClassLocation -> null, jdbcUrl -> jdbc:sapdb://localhost/reddline, properties -> {user=dba, password=dba} ] , propertyCycle -> 300, testConnectionOnCheckout -> false ] , factoryClassLocation -> null, numHelperThreads -> 3 ]
[18:52:11.776] [INFO ] [net.sf.hibernate.impl.SessionFactoryImpl] - building session factory
[18:52:11.776] [DEBUG] [net.sf.hibernate.impl.SessionFactoryImpl] - instantiating session factory with properties: {show_sql=true, java.vendor=Sun Microsystems Inc., hibernate.connection.url=jdbc:sapdb://localhost/reddline, sun.management.compiler=HotSpot Client Compiler, c3p0.min_size=5, hibernate.jdbc.use_get_generated_keys=true, os.name=Windows XP, sun.boot.class.path=D:\tools\j2sdk1.5.0_01\jre\lib\rt.jar;D:\tools\j2sdk1.5.0_01\jre\lib\i18n.jar;D:\tools\j2sdk1.5.0_01\jre\lib\sunrsasign.jar;D:\tools\j2sdk1.5.0_01\jre\lib\jsse.jar;D:\tools\j2sdk1.5.0_01\jre\lib\jce.jar;D:\tools\j2sdk1.5.0_01\jre\lib\charsets.jar;D:\tools\j2sdk1.5.0_01\jre\classes, sun.desktop=windows, hibernate.c3p0.max_size=30, java.vm.specification.vendor=Sun Microsystems Inc., c3p0.max_size=30, java.runtime.version=1.5.0_01-b08, hibernate.c3p0.min_size=5, hibernate.cache.provider_class=net.sf.ehcache.hibernate.Provider, user.name=Charles Canning, connection.driver_class=com.sap.dbtech.jdbc.DriverSapDB, hibernate.c3p0.timeout=300, user.language=en, sun.boot.library.path=D:\tools\j2sdk1.5.0_01\jre\bin, dialect=net.sf.hibernate.dialect.SAPDBDialect, max_fetch_depth=15, java.version=1.5.0_01, user.timezone=America/Chicago, jdbc.batch_size=15, sun.arch.data.model=32, java.endorsed.dirs=D:\tools\j2sdk1.5.0_01\jre\lib\endorsed, sun.cpu.isalist=pentium_pro+mmx pentium_pro pentium+mmx pentium i486 i386 i86, sun.jnu.encoding=Cp1252, file.encoding.pkg=sun.io, cache.use_query_cache=true, file.separator=\, java.specification.name=Java Platform API Specification, hibernate.cglib.use_reflection_optimizer=true, java.class.version=49.0, user.country=US, connection.url=jdbc:sapdb://localhost/reddline, java.home=D:\tools\j2sdk1.5.0_01\jre, java.vm.info=mixed mode, sharing, os.version=5.1, transaction.factory_class=net.sf.hibernate.transaction.JDBCTransactionFactory, hibernate.transaction.factory_class=net.sf.hibernate.transaction.JDBCTransactionFactory, c3p0.idle_test_period=3000, path.separator=;, connection.password=dba, java.vm.version=1.5.0_01-b08, hibernate.max_fetch_depth=15, hibernate.connection.password=dba, user.variant=, hibernate.jdbc.batch_size=15, java.awt.printerjob=sun.awt.windows.WPrinterJob, sun.io.unicode.encoding=UnicodeLittle, awt.toolkit=sun.awt.windows.WToolkit, hibernate.connection.username=dba, jdbc.use_streams_for_binary=true, user.home=C:\Documents and Settings\Charles Canning, idea.launcher.library=D:\Apps\IntelliJ4.5\bin\breakgen.dll, java.specification.vendor=Sun Microsystems Inc., java.library.path=D:\tools\j2sdk1.5.0_01\bin;.;C:\WINDOWS\system32;C:\WINDOWS;d:\databases\maxdb\programs\bin;d:\databases\maxdb\programs\pgm;C:\PROGRAM FILES\THINKPAD\UTILITIES;C:\WINDOWS\system32;C:\WINDOWS;C:\WINDOWS\System32\Wbem;C:\Program Files\ATI Technologies\ATI Control Panel;C:\Program Files\PC-Doctor for Windows\services;D:\tools\OpenSSH\bin;C:\Program Files\Executive Software\Diskeeper\;D:\Apps\VShell;D:\Apps\VShell\Bin;d:\databases\maxdb\programs\bin;d:\databases\maxdb\programs\pgm;C:\PROGRAM FILES\THINKPAD\UTILITIES;C:\WINDOWS\system32;C:\WINDOWS;C:\WINDOWS\System32\Wbem;C:\Program Files\ATI Technologies\ATI Control Panel;C:\Program Files\PC-Doctor for Windows\services;D:\tools\OpenSSH\bin;C:\Program Files\Executive Software\Diskeeper\;D:\Apps\VShell;D:\Apps\VShell\Bin;D:\tools\ant1.6.1\bin, java.vendor.url=http://java.sun.com/, hibernate.connection.driver_class=com.sap.dbtech.jdbc.DriverSapDB, connection.username=dba, java.vm.vendor=Sun Microsystems Inc., hibernate.dialect=net.sf.hibernate.dialect.SAPDBDialect, hibernate.jdbc.use_streams_for_binary=true, java.runtime.name=Java(TM) 2 Runtime Environment, Standard Edition, java.class.path=D:\tools\j2sdk1.5.0_01\jre\lib\charsets.jar;D:\tools\j2sdk1.5.0_01\jre\lib\deploy.jar;D:\tools\j2sdk1.5.0_01\jre\lib\javaws.jar;D:\tools\j2sdk1.5.0_01\jre\lib\jce.jar;D:\tools\j2sdk1.5.0_01\jre\lib\jsse.jar;D:\tools\j2sdk1.5.0_01\jre\lib\plugin.jar;D:\tools\j2sdk1.5.0_01\jre\lib\rt.jar;D:\tools\j2sdk1.5.0_01\jre\lib\ext\dnsns.jar;D:\tools\j2sdk1.5.0_01\jre\lib\ext\localedata.jar;D:\tools\j2sdk1.5.0_01\jre\lib\ext\sunjce_provider.jar;D:\tools\j2sdk1.5.0_01\jre\lib\ext\sunpkcs11.jar;D:\Work\Reddline\All\classes;D:\Work\Reddline\All\lib\log4j-1.2.8.jar;D:\Work\Reddline\All\lib\hibernate\ehcache-0.9.jar;D:\Work\Reddline\All\lib\hibernate\odmg-3.0.jar;D:\Work\Reddline\All\lib\hibernate\commons-logging-1.0.4.jar;D:\Work\Reddline\All\lib\hibernate\cglib-full-2.0.2.jar;D:\Work\Reddline\All\lib\hibernate\c3p0-0.8.4.5.jar;D:\Work\Reddline\All\lib\hibernate\xerces-2.4.0.jar;D:\Work\Reddline\All\lib\hibernate\hibernate2.jar;D:\Work\Reddline\All\lib\hibernate\xml-apis.jar;D:\Work\Reddline\All\lib\hibernate\dom4j-1.4.jar;D:\Work\Reddline\All\lib\hibernate\commons-collections-2.1.1.jar;D:\tools\concurrent\lib\concurrent.jar;D:\Work\Reddline\All\lib\commons-lang-2.0.jar;D:\Work\Reddline\All\lib\junit-3.8.1.jar;D:\Work\Reddline\All\lib\drools\jsr94.jar;D:\Work\Reddline\All\lib\drools\drools-jsr94-2.0-beta-17.jar;D:\Work\Reddline\All\lib\drools\drools-smf-2.0-beta-17.jar;D:\Work\Reddline\All\lib\drools\drools-java-2.0-beta-17.jar;D:\Work\Reddline\All\lib\drools\drools-core-2.0-beta-17.jar;D:\Work\Reddline\All\lib\drools\drools-base-2.0-beta-17.jar;D:\Work\Reddline\All\lib\drools\drools-io-2.0-beta-17.jar;D:\Work\Reddline\All\lib\drools\janino.jar;D:\Work\Reddline\All\lib\drools\antlr.jar;D:\servers\jboss-3.2.6\lib\jboss-common.jar;D:\servers\jboss-3.2.6\lib\jboss-system.jar;D:\servers\jboss-3.2.6\lib\jboss-jmx.jar;D:\servers\jboss-3.2.6\lib\getopt.jar;D:\servers\jboss-3.2.6\lib\xml-apis.jar;D:\servers\jboss-3.2.6\lib\webdavlib.jar;D:\servers\jboss-3.2.6\lib\log4j-boot.jar;D:\servers\jboss-3.2.6\lib\xercesImpl.jar;D:\servers\jboss-3.2.6\lib\commons-httpclient.jar;D:\servers\jboss-3.2.6\lib\concurrent.jar;D:\servers\jboss-3.2.6\lib\jaxen.jar;D:\servers\jboss-3.2.6\lib\dom4j.jar;D:\servers\jboss-3.2.6\lib\namespace.jar;D:\servers\jboss-3.2.6\lib\gnu-regexp.jar;D:\servers\jboss-3.2.6\lib\commons-logging.jar;D:\Work\Reddline\All\lib\struts-1.1.jar;D:\Work\Reddline\All\lib\j2ee-1.3.jar;D:\Work\Reddline\All\lib\commons-configuration-1.0.jar;D:\Work\Reddline\All\lib\maxdb7.5\sapdbc.jar;D:\Apps\IntelliJ4.5\lib\idea_rt.jar, idea.launcher.port=7532, c3p0.timeout=300, java.vm.specification.name=Java Virtual Machine Specification, java.vm.specification.version=1.0, hibernate.cache.use_query_cache=true, sun.cpu.endian=little, sun.os.patch.level=Service Pack 2, java.io.tmpdir=C:\DOCUME~1\CHARLE~1\LOCALS~1\Temp\, java.vendor.url.bug=http://java.sun.com/cgi-bin/bugreport.cgi, os.arch=x86, java.awt.graphicsenv=sun.awt.Win32GraphicsEnvironment, java.ext.dirs=D:\tools\j2sdk1.5.0_01\jre\lib\ext, user.dir=D:\Work\Reddline\Reddline OMS, hibernate.c3p0.idle_test_period=3000, line.separator=
, java.vm.name=Java HotSpot(TM) Client VM, cache.provider_class=net.sf.ehcache.hibernate.Provider, file.encoding=windows-1252, jdbc.use_get_generated_keys=true, java.specification.version=1.5, c3p0.max_statements=50, hibernate.show_sql=true, hibernate.c3p0.max_statements=50}
[18:52:12.317] [DEBUG] [net.sf.hibernate.impl.SessionFactoryObjectFactory] - initializing class SessionFactoryObjectFactory
[18:52:12.317] [DEBUG] [net.sf.hibernate.impl.SessionFactoryObjectFactory] - registered: 40288083015f41a101015f41a39d0000 (unnamed)
[18:52:12.317] [INFO ] [net.sf.hibernate.impl.SessionFactoryObjectFactory] - Not binding factory to JNDI, no JNDI name configured
[18:52:12.317] [DEBUG] [net.sf.hibernate.impl.SessionFactoryImpl] - instantiated session factory
[18:52:12.367] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - opened session
[18:52:12.367] [DEBUG] [net.sf.hibernate.transaction.JDBCTransaction] - begin
[18:52:12.367] [DEBUG] [net.sf.hibernate.transaction.JDBCTransaction] - current autocommit status:false
[18:52:12.377] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - iterate: from A
[18:52:12.387] [DEBUG] [net.sf.hibernate.hql.QueryTranslator] - compiling query
[18:52:12.407] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - flushing session
[18:52:12.407] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - Flushing entities and processing referenced collections
[18:52:12.407] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - Processing unreferenced collections
[18:52:12.407] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - Scheduling collection removes/(re)creates/updates
[18:52:12.407] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - Flushed: 0 insertions, 0 updates, 0 deletions to 0 objects
[18:52:12.407] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
[18:52:12.407] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - Dont need to execute flush
[18:52:12.407] [DEBUG] [net.sf.hibernate.hql.QueryTranslator] - HQL: from com.reddline.test.A
[18:52:12.407] [DEBUG] [net.sf.hibernate.hql.QueryTranslator] - SQL: select a0_.surrogate_id as x0_0_ from slot a0_
[18:52:12.407] [DEBUG] [net.sf.hibernate.impl.BatcherImpl] - about to open: 0 open PreparedStatements, 0 open ResultSets
[18:52:12.407] [DEBUG] [net.sf.hibernate.SQL] - select a0_.surrogate_id as x0_0_ from slot a0_
[18:52:12.407] [DEBUG] [net.sf.hibernate.impl.BatcherImpl] - preparing statement
Hibernate: select a0_.surrogate_id as x0_0_ from slot a0_
[18:52:12.487] [DEBUG] [net.sf.hibernate.impl.IteratorImpl] - retrieving next results
[18:52:12.487] [DEBUG] [net.sf.hibernate.type.LongType] - returning '107' as column: x0_0_
[18:52:12.487] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - loading [com.reddline.test.A#107]
[18:52:12.487] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - attempting to resolve [com.reddline.test.A#107]
[18:52:12.487] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - object not resolved in any cache [com.reddline.test.A#107]
[18:52:12.487] [DEBUG] [net.sf.hibernate.persister.EntityPersister] - Materializing entity: [com.reddline.test.A#107]
[18:52:12.487] [DEBUG] [net.sf.hibernate.impl.BatcherImpl] - about to open: 1 open PreparedStatements, 1 open ResultSets
[18:52:12.487] [DEBUG] [net.sf.hibernate.SQL] - select a0_.surrogate_id as surrogat1_3_, a0_.shelf_id as shelf_id3_, b1_.surrogate_id as surrogat1_0_, b1_.bay_id as bay_id0_, c2_.surrogate_id as surrogat1_1_, c2_.name as name1_, c2_.sequence as sequence1_, c2_.section_id as section_id1_, d3_.surrogate_id as surrogat1_2_ from slot a0_, shelf b1_, bay c2_, section d3_ where a0_.surrogate_id=? and a0_.shelf_id=b1_.surrogate_id(+) and b1_.bay_id=c2_.surrogate_id(+) and c2_.section_id=d3_.surrogate_id(+)
Hibernate: select a0_.surrogate_id as surrogat1_3_, a0_.shelf_id as shelf_id3_, b1_.surrogate_id as surrogat1_0_, b1_.bay_id as bay_id0_, c2_.surrogate_id as surrogat1_1_, c2_.name as name1_, c2_.sequence as sequence1_, c2_.section_id as section_id1_, d3_.surrogate_id as surrogat1_2_ from slot a0_, shelf b1_, bay c2_, section d3_ where a0_.surrogate_id=? and a0_.shelf_id=b1_.surrogate_id(+) and b1_.bay_id=c2_.surrogate_id(+) and c2_.section_id=d3_.surrogate_id(+)
[18:52:12.487] [DEBUG] [net.sf.hibernate.impl.BatcherImpl] - preparing statement
[18:52:12.497] [DEBUG] [net.sf.hibernate.type.LongType] - binding '107' to parameter: 1
[18:52:12.497] [DEBUG] [net.sf.hibernate.loader.Loader] - processing result set
[18:52:12.497] [DEBUG] [net.sf.hibernate.type.LongType] - returning '106' as column: surrogat1_0_
[18:52:12.497] [DEBUG] [net.sf.hibernate.type.LongType] - returning '102' as column: surrogat1_1_
[18:52:12.497] [DEBUG] [net.sf.hibernate.type.LongType] - returning '148' as column: surrogat1_2_
[18:52:12.497] [DEBUG] [net.sf.hibernate.loader.Loader] - result row: 106, 102, 148, 107
[18:52:12.497] [DEBUG] [net.sf.hibernate.loader.Loader] - Initializing object from ResultSet: 106
[18:52:12.497] [DEBUG] [net.sf.hibernate.loader.Loader] - Hydrating entity: com.reddline.test.B#106
[18:52:12.497] [DEBUG] [net.sf.hibernate.type.LongType] - returning '102' as column: bay_id0_
[18:52:12.497] [DEBUG] [net.sf.hibernate.loader.Loader] - Initializing object from ResultSet: 102
[18:52:12.497] [DEBUG] [net.sf.hibernate.loader.Loader] - Hydrating entity: com.reddline.test.C#102
[18:52:12.507] [DEBUG] [net.sf.hibernate.type.StringType] - returning 'Bay0' as column: name1_
[18:52:12.507] [DEBUG] [net.sf.hibernate.type.IntegerType] - returning '0' as column: sequence1_
[18:52:12.507] [DEBUG] [net.sf.hibernate.type.LongType] - returning '148' as column: section_id1_
[18:52:12.507] [DEBUG] [net.sf.hibernate.loader.Loader] - Initializing object from ResultSet: 148
[18:52:12.507] [DEBUG] [net.sf.hibernate.loader.Loader] - Hydrating entity: com.reddline.test.D#148
[18:52:12.507] [DEBUG] [net.sf.hibernate.loader.Loader] - Initializing object from ResultSet: 107
[18:52:12.507] [DEBUG] [net.sf.hibernate.loader.Loader] - Hydrating entity: com.reddline.test.A#107
[18:52:12.507] [DEBUG] [net.sf.hibernate.type.LongType] - returning '106' as column: shelf_id3_
[18:52:12.507] [DEBUG] [net.sf.hibernate.loader.Loader] - done processing result set (1 rows)
[18:52:12.507] [DEBUG] [net.sf.hibernate.impl.BatcherImpl] - done closing: 1 open PreparedStatements, 1 open ResultSets
[18:52:12.507] [DEBUG] [net.sf.hibernate.impl.BatcherImpl] - closing statement
[18:52:12.507] [DEBUG] [net.sf.hibernate.loader.Loader] - total objects hydrated: 4
[18:52:12.507] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - resolving associations for [com.reddline.test.B#106]
[18:52:12.507] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - loading [com.reddline.test.C#102]
[18:52:12.507] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - attempting to resolve [com.reddline.test.C#102]
[18:52:12.507] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - resolved object in session cache [com.reddline.test.C#102]
[18:52:12.507] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - creating collection wrapper:[com.reddline.test.B.children#106]
[18:52:12.517] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - adding entity to second-level cache [com.reddline.test.B#106]
[18:52:12.517] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - done materializing entity [com.reddline.test.B#106]
[18:52:12.517] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - resolving associations for [com.reddline.test.C#102]
[18:52:12.517] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - loading [com.reddline.test.D#148]
[18:52:12.517] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - attempting to resolve [com.reddline.test.D#148]
[18:52:12.517] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - resolved object in session cache [com.reddline.test.D#148]
[18:52:12.517] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - creating collection wrapper:[com.reddline.test.C.children#102]
[18:52:12.567] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - adding entity to second-level cache [com.reddline.test.C#102]
[18:52:12.567] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - done materializing entity [com.reddline.test.C#102]
[18:52:12.567] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - resolving associations for [com.reddline.test.D#148]
[18:52:12.567] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - creating collection wrapper:[com.reddline.test.D.children#148]
[18:52:12.567] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - adding entity to second-level cache [com.reddline.test.D#148]
[18:52:12.577] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - done materializing entity [com.reddline.test.D#148]
[18:52:12.577] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - resolving associations for [com.reddline.test.A#107]
[18:52:12.577] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - loading [com.reddline.test.B#106]
[18:52:12.577] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - attempting to resolve [com.reddline.test.B#106]
[18:52:12.577] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - resolved object in session cache [com.reddline.test.B#106]
[18:52:12.577] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - adding entity to second-level cache [com.reddline.test.A#107]
[18:52:12.577] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - done materializing entity [com.reddline.test.A#107]
[18:52:12.577] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - initializing non-lazy collections
[18:52:12.577] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - initializing collection [com.reddline.test.D.children#148]
[18:52:12.577] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - checking second-level cache
[18:52:12.577] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - collection not cached
[18:52:12.577] [DEBUG] [net.sf.hibernate.impl.BatcherImpl] - about to open: 1 open PreparedStatements, 1 open ResultSets
[18:52:12.577] [DEBUG] [net.sf.hibernate.SQL] - select children0_.section_id as section_id__, children0_.surrogate_id as surrogat1___, children0_.surrogate_id as surrogat1_0_, children0_.name as name0_, children0_.sequence as sequence0_, children0_.section_id as section_id0_ from bay children0_ where children0_.section_id=?
Hibernate: select children0_.section_id as section_id__, children0_.surrogate_id as surrogat1___, children0_.surrogate_id as surrogat1_0_, children0_.name as name0_, children0_.sequence as sequence0_, children0_.section_id as section_id0_ from bay children0_ where children0_.section_id=?
[18:52:12.577] [DEBUG] [net.sf.hibernate.impl.BatcherImpl] - preparing statement
[18:52:12.577] [DEBUG] [net.sf.hibernate.type.LongType] - binding '148' to parameter: 1
[18:52:12.577] [DEBUG] [net.sf.hibernate.loader.Loader] - result set contains (possibly empty) collection: [com.reddline.test.D.children#148]
[18:52:12.577] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - uninitialized collection: initializing
[18:52:12.577] [DEBUG] [net.sf.hibernate.loader.Loader] - processing result set
[18:52:12.587] [DEBUG] [net.sf.hibernate.type.LongType] - returning '102' as column: surrogat1_0_
[18:52:12.587] [DEBUG] [net.sf.hibernate.loader.Loader] - result row: 102
[18:52:12.587] [DEBUG] [net.sf.hibernate.type.LongType] - returning '148' as column: section_id__
[18:52:12.587] [DEBUG] [net.sf.hibernate.loader.Loader] - found row of collection: [com.reddline.test.D.children#148]
[18:52:12.587] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - reading row
[18:52:12.587] [DEBUG] [net.sf.hibernate.type.LongType] - returning '102' as column: surrogat1___
[18:52:12.587] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - loading [com.reddline.test.C#102]
[18:52:12.587] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - attempting to resolve [com.reddline.test.C#102]
[18:52:12.587] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - resolved object in session cache [com.reddline.test.C#102]
[18:52:12.587] [DEBUG] [net.sf.hibernate.loader.Loader] - done processing result set (1 rows)
[18:52:12.587] [DEBUG] [net.sf.hibernate.impl.BatcherImpl] - done closing: 1 open PreparedStatements, 1 open ResultSets
[18:52:12.587] [DEBUG] [net.sf.hibernate.impl.BatcherImpl] - closing statement
[18:52:12.587] [DEBUG] [net.sf.hibernate.loader.Loader] - total objects hydrated: 0
[18:52:12.587] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - 1 collections were found in result set
[18:52:12.587] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - Caching collection: [com.reddline.test.D.children#148]
[18:52:12.587] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - collection fully initialized: [com.reddline.test.D.children#148]
[18:52:12.587] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - 1 collections initialized
[18:52:12.587] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - collection initialized
[18:52:12.587] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - initializing collection [com.reddline.test.C.children#102]
[18:52:12.587] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - checking second-level cache
[18:52:12.587] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - collection not cached
[18:52:12.587] [DEBUG] [net.sf.hibernate.impl.BatcherImpl] - about to open: 1 open PreparedStatements, 1 open ResultSets
[18:52:12.587] [DEBUG] [net.sf.hibernate.SQL] - select children0_.bay_id as bay_id__, children0_.surrogate_id as surrogat1___, children0_.surrogate_id as surrogat1_0_, children0_.bay_id as bay_id0_ from shelf children0_ where children0_.bay_id=?
Hibernate: select children0_.bay_id as bay_id__, children0_.surrogate_id as surrogat1___, children0_.surrogate_id as surrogat1_0_, children0_.bay_id as bay_id0_ from shelf children0_ where children0_.bay_id=?
[18:52:12.587] [DEBUG] [net.sf.hibernate.impl.BatcherImpl] - preparing statement
[18:52:12.587] [DEBUG] [net.sf.hibernate.type.LongType] - binding '102' to parameter: 1
[18:52:12.587] [DEBUG] [net.sf.hibernate.loader.Loader] - result set contains (possibly empty) collection: [com.reddline.test.C.children#102]
[18:52:12.587] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - uninitialized collection: initializing
[18:52:12.587] [DEBUG] [net.sf.hibernate.loader.Loader] - processing result set
[18:52:12.597] [DEBUG] [net.sf.hibernate.type.LongType] - returning '106' as column: surrogat1_0_
[18:52:12.597] [DEBUG] [net.sf.hibernate.loader.Loader] - result row: 106
[18:52:12.597] [DEBUG] [net.sf.hibernate.type.LongType] - returning '102' as column: bay_id__
[18:52:12.597] [DEBUG] [net.sf.hibernate.loader.Loader] - found row of collection: [com.reddline.test.C.children#102]
[18:52:12.597] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - reading row
[18:52:12.597] [DEBUG] [net.sf.hibernate.type.LongType] - returning '106' as column: surrogat1___
[18:52:12.597] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - loading [com.reddline.test.B#106]
[18:52:12.597] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - attempting to resolve [com.reddline.test.B#106]
[18:52:12.597] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - resolved object in session cache [com.reddline.test.B#106]
[18:52:12.597] [DEBUG] [net.sf.hibernate.type.LongType] - returning '113' as column: surrogat1_0_
[18:52:12.597] [DEBUG] [net.sf.hibernate.loader.Loader] - result row: 113
[18:52:12.597] [DEBUG] [net.sf.hibernate.loader.Loader] - Initializing object from ResultSet: 113
[18:52:12.597] [DEBUG] [net.sf.hibernate.loader.Loader] - Hydrating entity: com.reddline.test.B#113
[18:52:12.597] [DEBUG] [net.sf.hibernate.type.LongType] - returning '102' as column: bay_id0_
[18:52:12.597] [DEBUG] [net.sf.hibernate.type.LongType] - returning '102' as column: bay_id__
[18:52:12.597] [DEBUG] [net.sf.hibernate.loader.Loader] - found row of collection: [com.reddline.test.C.children#102]
[18:52:12.597] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - reading row
[18:52:12.597] [DEBUG] [net.sf.hibernate.type.LongType] - returning '113' as column: surrogat1___
[18:52:12.597] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - loading [com.reddline.test.B#113]
[18:52:12.597] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - attempting to resolve [com.reddline.test.B#113]
[18:52:12.597] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - resolved object in session cache [com.reddline.test.B#113]
[18:52:12.597] [DEBUG] [net.sf.hibernate.loader.Loader] - done processing result set (2 rows)
[18:52:12.597] [DEBUG] [net.sf.hibernate.impl.BatcherImpl] - done closing: 1 open PreparedStatements, 1 open ResultSets
[18:52:12.597] [DEBUG] [net.sf.hibernate.impl.BatcherImpl] - closing statement
[18:52:12.597] [DEBUG] [net.sf.hibernate.loader.Loader] - total objects hydrated: 1
[18:52:12.597] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - resolving associations for [com.reddline.test.B#113]
[18:52:12.597] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - loading [com.reddline.test.C#102]
[18:52:12.597] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - attempting to resolve [com.reddline.test.C#102]
[18:52:12.597] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - resolved object in session cache [com.reddline.test.C#102]
[18:52:12.597] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - creating collection wrapper:[com.reddline.test.B.children#113]
[18:52:12.597] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - adding entity to second-level cache [com.reddline.test.B#113]
[18:52:12.597] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - done materializing entity [com.reddline.test.B#113]
[18:52:12.597] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - 1 collections were found in result set
[18:52:12.597] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - Caching collection: [com.reddline.test.C.children#102]
[18:52:12.597] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - collection fully initialized: [com.reddline.test.C.children#102]
[18:52:12.597] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - 1 collections initialized
[18:52:12.597] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - collection initialized
[18:52:12.597] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - initializing collection [com.reddline.test.B.children#113]
[18:52:12.597] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - checking second-level cache
[18:52:12.597] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - collection not cached
[18:52:12.597] [DEBUG] [net.sf.hibernate.impl.BatcherImpl] - about to open: 1 open PreparedStatements, 1 open ResultSets
[18:52:12.597] [DEBUG] [net.sf.hibernate.SQL] - select children0_.shelf_id as shelf_id__, children0_.surrogate_id as surrogat1___, children0_.surrogate_id as surrogat1_0_, children0_.shelf_id as shelf_id0_ from slot children0_ where children0_.shelf_id=?
Hibernate: select children0_.shelf_id as shelf_id__, children0_.surrogate_id as surrogat1___, children0_.surrogate_id as surrogat1_0_, children0_.shelf_id as shelf_id0_ from slot children0_ where children0_.shelf_id=?
[18:52:12.597] [DEBUG] [net.sf.hibernate.impl.BatcherImpl] - preparing statement
[18:52:12.597] [DEBUG] [net.sf.hibernate.type.LongType] - binding '113' to parameter: 1
[18:52:12.607] [DEBUG] [net.sf.hibernate.loader.Loader] - result set contains (possibly empty) collection: [com.reddline.test.B.children#113]
[18:52:12.607] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - uninitialized collection: initializing
[18:52:12.607] [DEBUG] [net.sf.hibernate.loader.Loader] - processing result set
[18:52:12.607] [DEBUG] [net.sf.hibernate.type.LongType] - returning '114' as column: surrogat1_0_
[18:52:12.607] [DEBUG] [net.sf.hibernate.loader.Loader] - result row: 114
[18:52:12.607] [DEBUG] [net.sf.hibernate.loader.Loader] - Initializing object from ResultSet: 114
[18:52:12.607] [DEBUG] [net.sf.hibernate.loader.Loader] - Hydrating entity: com.reddline.test.A#114
[18:52:12.607] [DEBUG] [net.sf.hibernate.type.LongType] - returning '113' as column: shelf_id0_
[18:52:12.607] [DEBUG] [net.sf.hibernate.type.LongType] - returning '113' as column: shelf_id__
[18:52:12.607] [DEBUG] [net.sf.hibernate.loader.Loader] - found row of collection: [com.reddline.test.B.children#113]
[18:52:12.607] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - reading row
[18:52:12.607] [DEBUG] [net.sf.hibernate.type.LongType] - returning '114' as column: surrogat1___
[18:52:12.607] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - loading [com.reddline.test.A#114]
[18:52:12.607] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - attempting to resolve [com.reddline.test.A#114]
[18:52:12.607] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - resolved object in session cache [com.reddline.test.A#114]
[18:52:12.607] [DEBUG] [net.sf.hibernate.type.LongType] - returning '117' as column: surrogat1_0_
[18:52:12.607] [DEBUG] [net.sf.hibernate.loader.Loader] - result row: 117
[18:52:12.607] [DEBUG] [net.sf.hibernate.loader.Loader] - Initializing object from ResultSet: 117
[18:52:12.607] [DEBUG] [net.sf.hibernate.loader.Loader] - Hydrating entity: com.reddline.test.A#117
[18:52:12.607] [DEBUG] [net.sf.hibernate.type.LongType] - returning '113' as column: shelf_id0_
[18:52:12.607] [DEBUG] [net.sf.hibernate.type.LongType] - returning '113' as column: shelf_id__
[18:52:12.607] [DEBUG] [net.sf.hibernate.loader.Loader] - found row of collection: [com.reddline.test.B.children#113]
[18:52:12.607] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - reading row
[18:52:12.607] [DEBUG] [net.sf.hibernate.type.LongType] - returning '117' as column: surrogat1___
[18:52:12.607] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - loading [com.reddline.test.A#117]
[18:52:12.607] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - attempting to resolve [com.reddline.test.A#117]
[18:52:12.607] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - resolved object in session cache [com.reddline.test.A#117]
[18:52:12.607] [DEBUG] [net.sf.hibernate.loader.Loader] - done processing result set (2 rows)
[18:52:12.607] [DEBUG] [net.sf.hibernate.impl.BatcherImpl] - done closing: 1 open PreparedStatements, 1 open ResultSets
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.BatcherImpl] - closing statement
[18:52:12.617] [DEBUG] [net.sf.hibernate.loader.Loader] - total objects hydrated: 2
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - resolving associations for [com.reddline.test.A#114]
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - loading [com.reddline.test.B#113]
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - attempting to resolve [com.reddline.test.B#113]
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - resolved object in session cache [com.reddline.test.B#113]
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - adding entity to second-level cache [com.reddline.test.A#114]
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - done materializing entity [com.reddline.test.A#114]
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - resolving associations for [com.reddline.test.A#117]
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - loading [com.reddline.test.B#113]
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - attempting to resolve [com.reddline.test.B#113]
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - resolved object in session cache [com.reddline.test.B#113]
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - adding entity to second-level cache [com.reddline.test.A#117]
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - done materializing entity [com.reddline.test.A#117]
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - 1 collections were found in result set
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - Caching collection: [com.reddline.test.B.children#113]
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - collection fully initialized: [com.reddline.test.B.children#113]
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - 1 collections initialized
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - collection initialized
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - initializing collection [com.reddline.test.B.children#106]
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - checking second-level cache
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - collection not cached
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.BatcherImpl] - about to open: 1 open PreparedStatements, 1 open ResultSets
[18:52:12.617] [DEBUG] [net.sf.hibernate.SQL] - select children0_.shelf_id as shelf_id__, children0_.surrogate_id as surrogat1___, children0_.surrogate_id as surrogat1_0_, children0_.shelf_id as shelf_id0_ from slot children0_ where children0_.shelf_id=?
Hibernate: select children0_.shelf_id as shelf_id__, children0_.surrogate_id as surrogat1___, children0_.surrogate_id as surrogat1_0_, children0_.shelf_id as shelf_id0_ from slot children0_ where children0_.shelf_id=?
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.BatcherImpl] - preparing statement
[18:52:12.617] [DEBUG] [net.sf.hibernate.type.LongType] - binding '106' to parameter: 1
[18:52:12.617] [DEBUG] [net.sf.hibernate.loader.Loader] - result set contains (possibly empty) collection: [com.reddline.test.B.children#106]
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - uninitialized collection: initializing
[18:52:12.617] [DEBUG] [net.sf.hibernate.loader.Loader] - processing result set
[18:52:12.617] [DEBUG] [net.sf.hibernate.type.LongType] - returning '107' as column: surrogat1_0_
[18:52:12.617] [DEBUG] [net.sf.hibernate.loader.Loader] - result row: 107
[18:52:12.617] [DEBUG] [net.sf.hibernate.type.LongType] - returning '106' as column: shelf_id__
[18:52:12.617] [DEBUG] [net.sf.hibernate.loader.Loader] - found row of collection: [com.reddline.test.B.children#106]
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - reading row
[18:52:12.617] [DEBUG] [net.sf.hibernate.type.LongType] - returning '107' as column: surrogat1___
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - loading [com.reddline.test.A#107]
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - attempting to resolve [com.reddline.test.A#107]
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - resolved object in session cache [com.reddline.test.A#107]
[18:52:12.617] [DEBUG] [net.sf.hibernate.type.LongType] - returning '110' as column: surrogat1_0_
[18:52:12.617] [DEBUG] [net.sf.hibernate.loader.Loader] - result row: 110
[18:52:12.617] [DEBUG] [net.sf.hibernate.loader.Loader] - Initializing object from ResultSet: 110
[18:52:12.617] [DEBUG] [net.sf.hibernate.loader.Loader] - Hydrating entity: com.reddline.test.A#110
[18:52:12.617] [DEBUG] [net.sf.hibernate.type.LongType] - returning '106' as column: shelf_id0_
[18:52:12.617] [DEBUG] [net.sf.hibernate.type.LongType] - returning '106' as column: shelf_id__
[18:52:12.617] [DEBUG] [net.sf.hibernate.loader.Loader] - found row of collection: [com.reddline.test.B.children#106]
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - reading row
[18:52:12.617] [DEBUG] [net.sf.hibernate.type.LongType] - returning '110' as column: surrogat1___
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - loading [com.reddline.test.A#110]
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - attempting to resolve [com.reddline.test.A#110]
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - resolved object in session cache [com.reddline.test.A#110]
[18:52:12.617] [DEBUG] [net.sf.hibernate.loader.Loader] - done processing result set (2 rows)
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.BatcherImpl] - done closing: 1 open PreparedStatements, 1 open ResultSets
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.BatcherImpl] - closing statement
[18:52:12.617] [DEBUG] [net.sf.hibernate.loader.Loader] - total objects hydrated: 1
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - resolving associations for [com.reddline.test.A#110]
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - loading [com.reddline.test.B#106]
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - attempting to resolve [com.reddline.test.B#106]
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - resolved object in session cache [com.reddline.test.B#106]
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - adding entity to second-level cache [com.reddline.test.A#110]
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - done materializing entity [com.reddline.test.A#110]
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - 1 collections were found in result set
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - Caching collection: [com.reddline.test.B.children#106]
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - collection fully initialized: [com.reddline.test.B.children#106]
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - 1 collections initialized
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - collection initialized
[18:52:12.617] [DEBUG] [net.sf.hibernate.transaction.JDBCTransaction] - commit
[18:52:12.617] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - flushing session
[18:52:12.627] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - saveOrUpdate() persistent instance
[18:52:12.627] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - saveOrUpdate() persistent instance
[18:52:12.627] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - saveOrUpdate() persistent instance
[18:52:12.627] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - saveOrUpdate() persistent instance
[18:52:12.627] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - saveOrUpdate() persistent instance
[18:52:12.627] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - saveOrUpdate() persistent instance
[18:52:12.627] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - saveOrUpdate() persistent instance
[18:52:12.627] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - Flushing entities and processing referenced collections
[18:52:12.637] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - Collection found: [com.reddline.test.B.children#106], was: [com.reddline.test.B.children#106]
[18:52:12.637] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - Collection found: [com.reddline.test.C.children#102], was: [com.reddline.test.C.children#102]
[18:52:12.637] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - Collection found: [com.reddline.test.D.children#148], was: [com.reddline.test.D.children#148]
[18:52:12.637] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - Collection found: [com.reddline.test.B.children#113], was: [com.reddline.test.B.children#113]
[18:52:12.637] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - Processing unreferenced collections
[18:52:12.637] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - Scheduling collection removes/(re)creates/updates
[18:52:12.637] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - Flushed: 0 insertions, 0 updates, 0 deletions to 8 objects
[18:52:12.637] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - Flushed: 0 (re)creations, 0 updates, 0 removals to 4 collections
[18:52:12.637] [DEBUG] [net.sf.hibernate.impl.Printer] - listing entities:
[18:52:12.637] [DEBUG] [net.sf.hibernate.impl.Printer] - com.reddline.test.A{surrogateId=107, parent=B#106}
[18:52:12.637] [DEBUG] [net.sf.hibernate.impl.Printer] - com.reddline.test.D{surrogateId=148, children=[C#102]}
[18:52:12.637] [DEBUG] [net.sf.hibernate.impl.Printer] - com.reddline.test.A{surrogateId=114, parent=B#113}
[18:52:12.637] [DEBUG] [net.sf.hibernate.impl.Printer] - com.reddline.test.B{surrogateId=106, children=[A#107, A#110], parent=C#102}
[18:52:12.637] [DEBUG] [net.sf.hibernate.impl.Printer] - com.reddline.test.A{surrogateId=117, parent=B#113}
[18:52:12.637] [DEBUG] [net.sf.hibernate.impl.Printer] - com.reddline.test.C{surrogateId=102, sequence=0, name=Bay0, children=[B#106, B#113], parent=D#148}
[18:52:12.637] [DEBUG] [net.sf.hibernate.impl.Printer] - com.reddline.test.A{surrogateId=110, parent=B#106}
[18:52:12.637] [DEBUG] [net.sf.hibernate.impl.Printer] - com.reddline.test.B{surrogateId=113, children=[A#114, A#117], parent=C#102}
[18:52:12.637] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - executing flush
[18:52:12.637] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - post flush
[18:52:12.637] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - transaction completion
[18:52:12.637] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - closing session
[18:52:12.637] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - disconnecting session
[18:52:12.637] [DEBUG] [net.sf.hibernate.impl.BatcherImpl] - done closing: 0 open PreparedStatements, 0 open ResultSets
[18:52:12.637] [DEBUG] [net.sf.hibernate.impl.BatcherImpl] - closing statement
[18:52:12.647] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - transaction completion
[18:52:12.647] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - opened session
[18:52:12.647] [DEBUG] [net.sf.hibernate.transaction.JDBCTransaction] - begin
**********************************************
[18:52:12.647] [DEBUG] [net.sf.hibernate.transaction.JDBCTransaction] - current autocommit status:false
[18:52:12.647] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - iterate: from A
[18:52:12.647] [DEBUG] [net.sf.hibernate.hql.QueryTranslator] - compiling query
[18:52:12.647] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - flushing session
[18:52:12.647] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - Flushing entities and processing referenced collections
[18:52:12.647] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - Processing unreferenced collections
[18:52:12.647] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - Scheduling collection removes/(re)creates/updates
[18:52:12.647] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - Flushed: 0 insertions, 0 updates, 0 deletions to 0 objects
[18:52:12.647] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
[18:52:12.647] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - Dont need to execute flush
[18:52:12.647] [DEBUG] [net.sf.hibernate.hql.QueryTranslator] - HQL: from com.reddline.test.A
[18:52:12.647] [DEBUG] [net.sf.hibernate.hql.QueryTranslator] - SQL: select a0_.surrogate_id as x0_0_ from slot a0_
[18:52:12.647] [DEBUG] [net.sf.hibernate.impl.BatcherImpl] - about to open: 0 open PreparedStatements, 0 open ResultSets
[18:52:12.647] [DEBUG] [net.sf.hibernate.SQL] - select a0_.surrogate_id as x0_0_ from slot a0_
[18:52:12.647] [DEBUG] [net.sf.hibernate.impl.BatcherImpl] - preparing statement
Hibernate: select a0_.surrogate_id as x0_0_ from slot a0_
[18:52:12.647] [DEBUG] [net.sf.hibernate.impl.IteratorImpl] - retrieving next results
[18:52:12.657] [DEBUG] [net.sf.hibernate.type.LongType] - returning '107' as column: x0_0_
[18:52:12.657] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - loading [com.reddline.test.A#107]
[18:52:12.657] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - attempting to resolve [com.reddline.test.A#107]
[18:52:12.657] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - resolved object in second-level cache [com.reddline.test.A#107]
[18:52:12.657] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - loading [com.reddline.test.B#106]
[18:52:12.657] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - attempting to resolve [com.reddline.test.B#106]
[18:52:12.657] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - resolved object in second-level cache [com.reddline.test.B#106]
[18:52:12.657] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - loading [com.reddline.test.C#102]
[18:52:12.657] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - attempting to resolve [com.reddline.test.C#102]
[18:52:12.657] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - resolved object in second-level cache [com.reddline.test.C#102]
[18:52:12.657] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - loading [com.reddline.test.D#148]
[18:52:12.657] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - attempting to resolve [com.reddline.test.D#148]
[18:52:12.657] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - resolved object in second-level cache [com.reddline.test.D#148]
[18:52:12.657] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - creating collection wrapper:[com.reddline.test.D.children#148]
[18:52:12.657] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - Cached Version: null
[18:52:12.657] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - initializing non-lazy collections
[18:52:12.657] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - initializing collection [com.reddline.test.D.children#148]
[18:52:12.657] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - checking second-level cache
[18:52:12.657] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - loading [com.reddline.test.C#102]
[18:52:12.657] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - attempting to resolve [com.reddline.test.C#102]
[18:52:12.657] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - resolved object in session cache [com.reddline.test.C#102]
[18:52:12.657] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - closing session
[18:52:12.657] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - disconnecting session
[18:52:12.657] [DEBUG] [net.sf.hibernate.impl.BatcherImpl] - done closing: 0 open PreparedStatements, 0 open ResultSets
[18:52:12.657] [DEBUG] [net.sf.hibernate.impl.BatcherImpl] - closing statement
Exception in thread "main" java.lang.NullPointerException
at com.reddline.test.C.hashCode(C.java:81)
at java.util.HashMap.hash(HashMap.java:264)
at java.util.HashMap.put(HashMap.java:382)
at net.sf.hibernate.collection.Set.snapshot(Set.java:40)
at net.sf.hibernate.collection.PersistentCollection.getSnapshot(PersistentCollection.java:325)
at net.sf.hibernate.impl.SessionImpl$CollectionEntry.postInitialize(SessionImpl.java:359)
at net.sf.hibernate.impl.SessionImpl.initializeCollectionFromCache(SessionImpl.java:4013)
at net.sf.hibernate.impl.SessionImpl.initializeCollection(SessionImpl.java:3297)
at net.sf.hibernate.collection.PersistentCollection.forceInitialization(PersistentCollection.java:336)
at net.sf.hibernate.impl.SessionImpl.initializeNonLazyCollections(SessionImpl.java:3156)
at net.sf.hibernate.impl.SessionImpl.assembleCacheEntry(SessionImpl.java:2152)
at net.sf.hibernate.impl.SessionImpl.doLoad(SessionImpl.java:2125)
at net.sf.hibernate.impl.SessionImpl.doLoadByClass(SessionImpl.java:2000)
at net.sf.hibernate.impl.SessionImpl.internalLoad(SessionImpl.java:1962)
at net.sf.hibernate.type.ManyToOneType.resolveIdentifier(ManyToOneType.java:69)
at net.sf.hibernate.type.ManyToOneType.assemble(ManyToOneType.java:108)
at net.sf.hibernate.impl.CacheEntry.assemble(CacheEntry.java:56)
at net.sf.hibernate.impl.CacheEntry.assemble(CacheEntry.java:48)
at net.sf.hibernate.impl.SessionImpl.assembleCacheEntry(SessionImpl.java:2147)
at net.sf.hibernate.impl.SessionImpl.doLoad(SessionImpl.java:2125)
at net.sf.hibernate.impl.SessionImpl.doLoadByClass(SessionImpl.java:2000)
at net.sf.hibernate.impl.SessionImpl.internalLoad(SessionImpl.java:1962)
at net.sf.hibernate.type.ManyToOneType.resolveIdentifier(ManyToOneType.java:69)
at net.sf.hibernate.type.ManyToOneType.assemble(ManyToOneType.java:108)
at net.sf.hibernate.impl.CacheEntry.assemble(CacheEntry.java:56)
at net.sf.hibernate.impl.CacheEntry.assemble(CacheEntry.java:48)
at net.sf.hibernate.impl.SessionImpl.assembleCacheEntry(SessionImpl.java:2147)
at net.sf.hibernate.impl.SessionImpl.doLoad(SessionImpl.java:2125)
at net.sf.hibernate.impl.SessionImpl.doLoadByClass(SessionImpl.java:2000)
at net.sf.hibernate.impl.SessionImpl.internalLoad(SessionImpl.java:1962)
at net.sf.hibernate.type.ManyToOneType.resolveIdentifier(ManyToOneType.java:69)
at net.sf.hibernate.type.ManyToOneType.assemble(ManyToOneType.java:108)
at net.sf.hibernate.impl.CacheEntry.assemble(CacheEntry.java:56)
at net.sf.hibernate.impl.CacheEntry.assemble(CacheEntry.java:48)
at net.sf.hibernate.impl.SessionImpl.assembleCacheEntry(SessionImpl.java:2147)
at net.sf.hibernate.impl.SessionImpl.doLoad(SessionImpl.java:2125)
at net.sf.hibernate.impl.SessionImpl.doLoadByClass(SessionImpl.java:2000)
at net.sf.hibernate.impl.SessionImpl.internalLoad(SessionImpl.java:1962)
at net.sf.hibernate.type.ManyToOneType.resolveIdentifier(ManyToOneType.java:69)
at net.sf.hibernate.type.EntityType.resolveIdentifier(EntityType.java:204)
at net.sf.hibernate.type.EntityType.nullSafeGet(EntityType.java:126)
at net.sf.hibernate.impl.IteratorImpl.postNext(IteratorImpl.java:93)
at net.sf.hibernate.impl.IteratorImpl.<init>(IteratorImpl.java:64)
at net.sf.hibernate.hql.QueryTranslator.iterate(QueryTranslator.java:869)
at net.sf.hibernate.impl.SessionImpl.iterate(SessionImpl.java:1618)
at net.sf.hibernate.impl.QueryImpl.iterate(QueryImpl.java:27)
at com.reddline.test.Tester.loadA(Tester.java:64)
at com.reddline.test.Tester.main(Tester.java:88)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:585)
at com.intellij.rt.execution.application.AppMain.main(AppMain.java:78)
[18:52:12.667] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - running Session.finalize()
[18:52:12.667] [DEBUG] [net.sf.hibernate.impl.SessionImpl] - running Session.finalize()
[18:52:12.667] [WARN ] [net.sf.hibernate.impl.SessionImpl] - afterTransactionCompletion() was never called

Process finished with exit code 1

I tried another test where I load the data from the top down and it works fine. Here is the differences:

replace "from A" with "from D"

and here is the new generated SQL

Hibernate: select d0_.surrogate_id as x0_0_ from section d0_
Hibernate: select d0_.surrogate_id as surrogat1_0_ from section d0_ where d0_.surrogate_id=?
Hibernate: select children0_.section_id as section_id__, children0_.surrogate_id as surrogat1___, children0_.surrogate_id as surrogat1_0_, children0_.name as name0_, children0_.sequence as sequence0_, children0_.section_id as section_id0_ from bay children0_ where children0_.section_id=?
Hibernate: select children0_.bay_id as bay_id__, children0_.surrogate_id as surrogat1___, children0_.surrogate_id as surrogat1_0_, children0_.bay_id as bay_id0_ from shelf children0_ where children0_.bay_id=?
Hibernate: select children0_.shelf_id as shelf_id__, children0_.surrogate_id as surrogat1___, children0_.surrogate_id as surrogat1_0_, children0_.shelf_id as shelf_id0_ from slot children0_ where children0_.shelf_id=?
Hibernate: select children0_.shelf_id as shelf_id__, children0_.surrogate_id as surrogat1___, children0_.surrogate_id as surrogat1_0_, children0_.shelf_id as shelf_id0_ from slot children0_ where children0_.shelf_id=?
**********************************************
Hibernate: select d0_.surrogate_id as x0_0_ from section d0_

Oops, sorry about that. The last statement was wrong. It executes fine because it doesn't seem to call hashCode() on C.

if I do

"from D"
"from D" it appears to work.

If i then call "from A", it fails again.

We are currently experiencing a similar issue related to associated collections of objects stored in second-level cache. When the cache is clear, the query retrieves the data from the database. It then retrieves the associated collection via a lazy join. The hibernate logging suggests that all entities are placed successfully in second level cache.

On subsequent calls to the same query, the logs suggest that the objects are available in second level cache and are hydrated. However, the objects are hydrated as nulls and creates errors within the application. When polling the CacheManager directly, the key is indeed in the second level cache, but the attributes are not present. It simply states that the value is {null}.

We are using OSCache 2.1.1 (clustered) for second-level caching mechanism, Hibernate 3.0.5.

Has there been any progress on this problem or other people reporting similar issues?

I have experienced those problems before if you are circular references in your data model. Hibernate does not handle this as it would require a two-phase scan of the data to correctly identify the second reference to the previous class and load its data or pull from the cache. But, lazy loading is *supposed* to fix it. That was how we got around the problem. We used lazy to break the circular references.