Lazy collection initialization fails when using cache

Ville Peurala · **Posted:** Mon Oct 11, 2004 6:55 am

Hello,

I wonder why lazy one-to-many collection initialization fails when the "parent" object comes from cache.

If I have a one-to-many relation (the collection type is bag) where both the "parent" object and the "child" object are cached,
and I explicitly initialize the "children" collection of the parent before closing the session (using Hibernate.initialize()),
it works perfectly when the parent is loaded from database - I can access the collection after the Session is closed, since it is initialized.

BUT when the parent is obtained via a cache hit, it seems like the Hibernate.initialize() call does not do what it should:
I get a LazyInitializationException when trying to access the collection after the Session is closed.

I am using Hibernate 2.1.6 with EHCache. This is not an EHCache specific issue.
I tried it also with OSCache and the behaviour was exactly the same as with EHCache. If I disable caching, this works.

- Ville Peurala

Hibernate version:
2.1.6

Mapping documents:

Code:

<?xml version="1.0"?>

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

<hibernate-mapping>
    <class
        name="testcase.withcache.ParentHibernateImpl"
        dynamic-update="false"
        dynamic-insert="false"
        optimistic-lock="version"
        proxy="testcase.withcache.ParentHibernateImpl"
        table="Parent">
      <cache usage="nonstrict-read-write" /> 
      <!-- Primary key -->

      <id name="parentId" 
          access="field"
         column="Parent_id"
         type="java.lang.Integer"
         unsaved-value="null">
         <generator class="native" />
      </id>
      

      <!-- Discriminator -->
      
      <!-- Version -->
      <version    column="Version"
                 name="version"
                 type="java.lang.Integer"
                 access="field"
                 unsaved-value="undefined" />


      <!-- Many-to-one mappings -->
      <!-- Properties -->
      
      <property    name="name"
               access="field"
               type="java.lang.String"
               column="Name"
               length="64"
               not-null="true" />
               
       <!-- Components -->
       
      <!-- One-to-many relations -->
      
      <bag 
            name="children"
            access="field"
            lazy="true"
            inverse="true"
            cascade="all">
            <cache usage="nonstrict-read-write" />
         <key>
            <column name="Parent_id"
                  not-null="true" 
                  sql-type="int" />
         </key>
         <one-to-many class="testcase.withcache.ChildHibernateImpl" />
      </bag>

      <!-- Many-to-many relations -->

      <!-- Subclasses -->

   </class>
</hibernate-mapping>

Code:

<?xml version="1.0"?>

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

<hibernate-mapping>
    <class
        name="testcase.withcache.ChildHibernateImpl"
        dynamic-update="false"
        dynamic-insert="false"
        optimistic-lock="version"
        proxy="testcase.withcache.ChildHibernateImpl"
        table="Child">
      <cache usage="nonstrict-read-write" /> 
      <!-- Primary key -->

      <id name="childId" 
          access="field"
         column="Child_id"
         type="java.lang.Integer"
         unsaved-value="null">
         <generator class="native" />
      </id>
      

      <!-- Discriminator -->
      
      <!-- Version -->
      <version    column="Version"
                 name="version"
                 type="java.lang.Integer"
                 access="field"
                 unsaved-value="undefined" />


      <!-- Many-to-one mappings -->
      <many-to-one   name="parent"
                  access="field"
                  class="testcase.withcache.ParentHibernateImpl"
                  cascade="none"
                  outer-join="auto"
                  not-null="false">
         <column name="Parent_id"
               not-null="true" 
               sql-type="int" />
      </many-to-one>
      <!-- Properties -->
      
      <property    name="name"
               access="field"
               type="java.lang.String"
               column="Name"
               length="64"
               not-null="true" />
               
       <!-- Components -->
       
      <!-- One-to-many relations -->
      

      <!-- Many-to-many relations -->

      <!-- Subclasses -->

   </class>
</hibernate-mapping>

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

Code:

        Session firstSession = factory.openSession();
        String parentQueryString = "FROM ParentHibernateImpl AS parent WHERE parent.parentId = 1";
        Query parentQuery1 = firstSession.createQuery(parentQueryString);
        Parent parent1 = (Parent) parentQuery1.uniqueResult();
        Hibernate.initialize(parent1.getChildren());
        firstSession.close();

        // This works correctly, because parent1 comes from the database
        System.out.println("parent.getChildren() after closing the session: "
                + parent1.getChildren());

        Session secondSession = factory.openSession();
        Query parentQuery2 = secondSession.createQuery(parentQueryString);
        Parent parent2 = (Parent) parentQuery2.uniqueResult();
        Hibernate.initialize(parent2.getChildren());
        secondSession.close();

        // This throws a LazyInitializationException, because parent2 comes from a cache hit
        System.out.println("parent.getChildren() after closing the session: "
                + parent2.getChildren());

        conn.close();

Full stack trace of any exception that occurs:

Code:

net.sf.hibernate.HibernateException: Could not initialize proxy - the owning Session was closed
   at net.sf.hibernate.proxy.LazyInitializer.initialize(LazyInitializer.java:47)
   at net.sf.hibernate.proxy.LazyInitializer.initializeWrapExceptions(LazyInitializer.java:60)
   at net.sf.hibernate.proxy.LazyInitializer.getImplementation(LazyInitializer.java:164)
   at net.sf.hibernate.proxy.CGLIBLazyInitializer.intercept(CGLIBLazyInitializer.java:108)
   at testcase.withcache.ChildHibernateImpl$$EnhancerByCGLIB$$db7e9294.toString(<generated>)
   at java.lang.String.valueOf(Unknown Source)
   at java.util.AbstractCollection.toString(Unknown Source)
   at net.sf.hibernate.collection.Bag.toString(Bag.java:483)
   at java.lang.String.valueOf(Unknown Source)
   at java.lang.StringBuffer.append(Unknown Source)
   at testcase.withcache.Main.main(Main.java:63)
net.sf.hibernate.LazyInitializationException: Exception initializing proxy: [testcase.withcache.ChildHibernateImpl#1]
   at net.sf.hibernate.proxy.LazyInitializer.initializeWrapExceptions(LazyInitializer.java:64)
   at net.sf.hibernate.proxy.LazyInitializer.getImplementation(LazyInitializer.java:164)
   at net.sf.hibernate.proxy.CGLIBLazyInitializer.intercept(CGLIBLazyInitializer.java:108)
   at testcase.withcache.ChildHibernateImpl$$EnhancerByCGLIB$$db7e9294.toString(<generated>)
   at java.lang.String.valueOf(Unknown Source)
   at java.util.AbstractCollection.toString(Unknown Source)
   at net.sf.hibernate.collection.Bag.toString(Bag.java:483)
   at java.lang.String.valueOf(Unknown Source)
   at java.lang.StringBuffer.append(Unknown Source)
   at testcase.withcache.Main.main(Main.java:63)
Caused by: net.sf.hibernate.HibernateException: Could not initialize proxy - the owning Session was closed
   at net.sf.hibernate.proxy.LazyInitializer.initialize(LazyInitializer.java:47)
   at net.sf.hibernate.proxy.LazyInitializer.initializeWrapExceptions(LazyInitializer.java:60)
   ... 9 more

Name and version of the database you are using:
HSQLDB 1.7.2. Also tried with Microsoft SQL Server 2000, the behaviour is exactly the same.

The generated SQL (show_sql=true):

Code:

2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.hql.QueryTranslator - SQL: select parenthibe0_.Parent_id as Parent_id, parenthibe0_.Version as Version, parenthibe0_.Name as Name from Parent parenthibe0_ where (parenthibe0_.Parent_id=1 )

Debug level Hibernate log excerpt:

Code:

2004-10-11 13:30:05,364 INFO net.sf.hibernate.cfg.Environment - Hibernate 2.1.6
2004-10-11 13:30:05,380 INFO net.sf.hibernate.cfg.Environment - hibernate.properties not found
2004-10-11 13:30:05,380 INFO net.sf.hibernate.cfg.Environment - using CGLIB reflection optimizer
2004-10-11 13:30:05,380 INFO net.sf.hibernate.cfg.Configuration - configuring from resource: /hibernate.cfg.xml
2004-10-11 13:30:05,380 INFO net.sf.hibernate.cfg.Configuration - Configuration resource: /hibernate.cfg.xml
2004-10-11 13:30:05,443 DEBUG net.sf.hibernate.util.DTDEntityResolver - trying to locate http://hibernate.sourceforge.net/hibernate-configuration-2.0.dtd in classpath under net/sf/hibernate/
2004-10-11 13:30:05,458 DEBUG net.sf.hibernate.util.DTDEntityResolver - found http://hibernate.sourceforge.net/hibernate-configuration-2.0.dtd in classpath
2004-10-11 13:30:05,505 DEBUG net.sf.hibernate.cfg.Configuration - connection.driver_class=org.hsqldb.jdbcDriver
2004-10-11 13:30:05,505 DEBUG net.sf.hibernate.cfg.Configuration - connection.url=jdbc:hsqldb:mem:test
2004-10-11 13:30:05,505 DEBUG net.sf.hibernate.cfg.Configuration - connection.username=sa
2004-10-11 13:30:05,505 DEBUG net.sf.hibernate.cfg.Configuration - connection.password=
2004-10-11 13:30:05,505 DEBUG net.sf.hibernate.cfg.Configuration - dialect=net.sf.hibernate.dialect.HSQLDialect
2004-10-11 13:30:05,505 DEBUG net.sf.hibernate.cfg.Configuration - show_sql=false
2004-10-11 13:30:05,505 DEBUG net.sf.hibernate.cfg.Configuration - cache.provider_class=net.sf.ehcache.hibernate.Provider
2004-10-11 13:30:05,505 DEBUG net.sf.hibernate.cfg.Configuration - max_fetch_depth=3
2004-10-11 13:30:05,505 DEBUG net.sf.hibernate.cfg.Configuration - cache.use_query_cache=false
2004-10-11 13:30:05,505 DEBUG net.sf.hibernate.cfg.Configuration - null<-org.dom4j.tree.DefaultAttribute@1cdeff [Attribute: name resource value "testcase/withcache/Parent.hbm.xml"]
2004-10-11 13:30:05,505 INFO net.sf.hibernate.cfg.Configuration - Mapping resource: testcase/withcache/Parent.hbm.xml
2004-10-11 13:30:05,521 DEBUG net.sf.hibernate.util.DTDEntityResolver - trying to locate http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath under net/sf/hibernate/
2004-10-11 13:30:05,521 DEBUG net.sf.hibernate.util.DTDEntityResolver - found http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath
2004-10-11 13:30:05,661 INFO net.sf.hibernate.cfg.Binder - Mapping class: testcase.withcache.ParentHibernateImpl -> Parent
2004-10-11 13:30:05,661 DEBUG net.sf.hibernate.cache.CacheFactory - cache for: testcase.withcache.ParentHibernateImpl usage strategy: nonstrict-read-write
2004-10-11 13:30:05,739 DEBUG net.sf.hibernate.cfg.Binder - Mapped property: parentId -> Parent_id, type: integer
2004-10-11 13:30:05,739 DEBUG net.sf.hibernate.cfg.Binder - Mapped property: version -> Version, type: integer
2004-10-11 13:30:05,755 DEBUG net.sf.hibernate.cfg.Binder - Mapped property: name -> Name, type: string
2004-10-11 13:30:05,770 DEBUG net.sf.hibernate.cfg.Binder - Mapped property: children, type: java.util.Collection
2004-10-11 13:30:05,770 DEBUG net.sf.hibernate.cfg.Configuration - null<-org.dom4j.tree.DefaultAttribute@1d15445 [Attribute: name resource value "testcase/withcache/Child.hbm.xml"]
2004-10-11 13:30:05,770 INFO net.sf.hibernate.cfg.Configuration - Mapping resource: testcase/withcache/Child.hbm.xml
2004-10-11 13:30:05,786 DEBUG net.sf.hibernate.util.DTDEntityResolver - trying to locate http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath under net/sf/hibernate/
2004-10-11 13:30:05,786 DEBUG net.sf.hibernate.util.DTDEntityResolver - found http://hibernate.sourceforge.net/hibernate-mapping-2.0.dtd in classpath
2004-10-11 13:30:05,817 INFO net.sf.hibernate.cfg.Binder - Mapping class: testcase.withcache.ChildHibernateImpl -> Child
2004-10-11 13:30:05,817 DEBUG net.sf.hibernate.cache.CacheFactory - cache for: testcase.withcache.ChildHibernateImpl usage strategy: nonstrict-read-write
2004-10-11 13:30:05,817 DEBUG net.sf.hibernate.cfg.Binder - Mapped property: childId -> Child_id, type: integer
2004-10-11 13:30:05,817 DEBUG net.sf.hibernate.cfg.Binder - Mapped property: version -> Version, type: integer
2004-10-11 13:30:05,833 DEBUG net.sf.hibernate.cfg.Binder - Mapped property: parent -> Parent_id, type: testcase.withcache.ParentHibernateImpl
2004-10-11 13:30:05,833 DEBUG net.sf.hibernate.cfg.Binder - Mapped property: name -> Name, type: string
2004-10-11 13:30:05,833 INFO net.sf.hibernate.cfg.Configuration - Configured SessionFactory: null
2004-10-11 13:30:05,833 DEBUG net.sf.hibernate.cfg.Configuration - properties: {hibernate.connection.password=, java.runtime.name=Java(TM) 2 Runtime Environment, Standard Edition, hibernate.cache.provider_class=net.sf.ehcache.hibernate.Provider, sun.boot.library.path=C:\Program Files\Java\j2re1.4.2_05\bin, java.vm.version=1.4.2_05-b04, hibernate.connection.username=sa, java.vm.vendor=Sun Microsystems Inc., java.vendor.url=http://java.sun.com/, hibernate.cache.use_query_cache=false, path.separator=;, java.vm.name=Java HotSpot(TM) Client VM, file.encoding.pkg=sun.io, user.country=FI, sun.os.patch.level=Service Pack 1, java.vm.specification.name=Java Virtual Machine Specification, user.dir=C:\Eclipse3\eclipse\workspace\HibernateTestCase, java.runtime.version=1.4.2_05-b04, java.awt.graphicsenv=sun.awt.Win32GraphicsEnvironment, java.endorsed.dirs=C:\Program Files\Java\j2re1.4.2_05\lib\endorsed, os.arch=x86, java.io.tmpdir=C:\WINDOWS\TEMP\, line.separator=
, java.vm.specification.vendor=Sun Microsystems Inc., cache.provider_class=net.sf.ehcache.hibernate.Provider, user.variant=, os.name=Windows XP, sun.java2d.fontpath=, java.library.path=C:\Program Files\Java\j2re1.4.2_05\bin;.;C:\WINDOWS\System32;C:\WINDOWS;C:\Program Files\NCR\Teradata Warehouse Builder\bin;C:\Program Files\NCR\Teradata Client\\Bin;C:\Program Files\NCR\Teradata Client\Bin\;C:\WINDOWS\system32;C:\WINDOWS;C:\WINDOWS\System32\Wbem;C:\Program Files\Microsoft SQL Server\80\Tools\BINN;C:\Program Files\ATI Technologies\ATI Control Panel;C:\cvsnt;C:\j2sdk1.4.2_05\bin;C:\apache-ant-1.6.2\bin;C:\Program Files\7-Zip;C:\Program Files\Subversion\bin;C:\Maven1.0\bin;C:\cygwin\bin;C:\antlr-2.7.4;C:\Program Files\Common Files\GTK\2.0\lib;c:\ruby\bin, java.specification.name=Java Platform API Specification, java.class.version=48.0, java.util.prefs.PreferencesFactory=java.util.prefs.WindowsPreferencesFactory, os.version=5.1, connection.password=, user.home=C:\Documents and Settings\Ville, user.timezone=Europe/Helsinki, connection.username=sa, java.awt.printerjob=sun.awt.windows.WPrinterJob, file.encoding=Cp1252, java.specification.version=1.4, hibernate.connection.driver_class=org.hsqldb.jdbcDriver, show_sql=false, user.name=Ville, java.class.path=C:\Eclipse3\eclipse\workspace\HibernateTestCase\bin;C:\Eclipse3\eclipse\workspace\HibernateTestCase\lib\cglib-full-2.0.2.jar;C:\Eclipse3\eclipse\workspace\HibernateTestCase\lib\commons-collections-2.1.1.jar;C:\Eclipse3\eclipse\workspace\HibernateTestCase\lib\commons-lang-2.0.jar;C:\Eclipse3\eclipse\workspace\HibernateTestCase\lib\commons-logging-1.0.4.jar;C:\Eclipse3\eclipse\workspace\HibernateTestCase\lib\dom4j-1.4.jar;C:\Eclipse3\eclipse\workspace\HibernateTestCase\lib\epl_0.1.jar;C:\Eclipse3\eclipse\workspace\HibernateTestCase\lib\hibernate2.jar;C:\Eclipse3\eclipse\workspace\HibernateTestCase\lib\hsqldb.jar;C:\Eclipse3\eclipse\workspace\HibernateTestCase\lib\log4j-1.2.8.jar;C:\Eclipse3\eclipse\workspace\HibernateTestCase\lib\odmg-3.0.jar;C:\Eclipse3\eclipse\workspace\HibernateTestCase\lib\ehcache-1.0.jar;C:\Eclipse3\eclipse\workspace\HibernateTestCase\lib\jta.jar, hibernate.show_sql=false, java.vm.specification.version=1.0, java.home=C:\Program Files\Java\j2re1.4.2_05, sun.arch.data.model=32, hibernate.dialect=net.sf.hibernate.dialect.HSQLDialect, hibernate.connection.url=jdbc:hsqldb:mem:test, user.language=fi, java.specification.vendor=Sun Microsystems Inc., awt.toolkit=sun.awt.windows.WToolkit, hibernate.cglib.use_reflection_optimizer=true, java.vm.info=mixed mode, java.version=1.4.2_05, java.ext.dirs=C:\Program Files\Java\j2re1.4.2_05\lib\ext, cache.use_query_cache=false, sun.boot.class.path=C:\Program Files\Java\j2re1.4.2_05\lib\rt.jar;C:\Program Files\Java\j2re1.4.2_05\lib\i18n.jar;C:\Program Files\Java\j2re1.4.2_05\lib\sunrsasign.jar;C:\Program Files\Java\j2re1.4.2_05\lib\jsse.jar;C:\Program Files\Java\j2re1.4.2_05\lib\jce.jar;C:\Program Files\Java\j2re1.4.2_05\lib\charsets.jar;C:\Program Files\Java\j2re1.4.2_05\classes, java.vendor=Sun Microsystems Inc., connection.driver_class=org.hsqldb.jdbcDriver, file.separator=\, max_fetch_depth=3, java.vendor.url.bug=http://java.sun.com/cgi-bin/bugreport.cgi, sun.io.unicode.encoding=UnicodeLittle, sun.cpu.endian=little, hibernate.max_fetch_depth=3, connection.url=jdbc:hsqldb:mem:test, dialect=net.sf.hibernate.dialect.HSQLDialect, sun.cpu.isalist=pentium i486 i386}
2004-10-11 13:30:05,833 INFO net.sf.hibernate.cfg.Configuration - processing one-to-many association mappings
2004-10-11 13:30:05,833 DEBUG net.sf.hibernate.cfg.Binder - Second pass for collection: testcase.withcache.ParentHibernateImpl.children
2004-10-11 13:30:05,833 INFO net.sf.hibernate.cfg.Binder - Mapping collection: testcase.withcache.ParentHibernateImpl.children -> Child
2004-10-11 13:30:05,833 DEBUG net.sf.hibernate.cache.CacheFactory - cache for: testcase.withcache.ParentHibernateImpl.children usage strategy: nonstrict-read-write
2004-10-11 13:30:05,833 DEBUG net.sf.hibernate.cfg.Binder - Mapped collection key: Parent_id, one-to-many: testcase.withcache.ChildHibernateImpl
2004-10-11 13:30:05,833 INFO net.sf.hibernate.cfg.Configuration - processing one-to-one association property references
2004-10-11 13:30:05,833 INFO net.sf.hibernate.cfg.Configuration - processing foreign key constraints
2004-10-11 13:30:05,833 DEBUG net.sf.hibernate.cfg.Configuration - resolving reference to class: testcase.withcache.ParentHibernateImpl
2004-10-11 13:30:05,864 INFO net.sf.hibernate.dialect.Dialect - Using dialect: net.sf.hibernate.dialect.HSQLDialect
2004-10-11 13:30:05,864 INFO net.sf.hibernate.cfg.SettingsFactory - Maximim outer join fetch depth: 3
2004-10-11 13:30:05,864 INFO net.sf.hibernate.cfg.SettingsFactory - Use outer join fetching: true
2004-10-11 13:30:05,864 INFO net.sf.hibernate.connection.DriverManagerConnectionProvider - Using Hibernate built-in connection pool (not for production use!)
2004-10-11 13:30:05,864 INFO net.sf.hibernate.connection.DriverManagerConnectionProvider - Hibernate connection pool size: 20
2004-10-11 13:30:05,880 INFO net.sf.hibernate.connection.DriverManagerConnectionProvider - using driver: org.hsqldb.jdbcDriver at URL: jdbc:hsqldb:mem:test
2004-10-11 13:30:05,880 INFO net.sf.hibernate.connection.DriverManagerConnectionProvider - connection properties: {user=sa, password=}
2004-10-11 13:30:05,880 INFO net.sf.hibernate.transaction.TransactionManagerLookupFactory - No TransactionManagerLookup configured (in JTA environment, use of process level read-write cache is not recommended)
2004-10-11 13:30:05,880 DEBUG net.sf.hibernate.connection.DriverManagerConnectionProvider - total checked-out connections: 0
2004-10-11 13:30:05,880 DEBUG net.sf.hibernate.connection.DriverManagerConnectionProvider - opening new JDBC connection
2004-10-11 13:30:06,192 DEBUG net.sf.hibernate.connection.DriverManagerConnectionProvider - created connection to: jdbc:hsqldb:mem:test, Isolation Level: 1
2004-10-11 13:30:06,208 DEBUG net.sf.hibernate.connection.DriverManagerConnectionProvider - returning connection to pool, pool size: 1
2004-10-11 13:30:06,208 INFO net.sf.hibernate.cfg.SettingsFactory - Use scrollable result sets: true
2004-10-11 13:30:06,208 INFO net.sf.hibernate.cfg.SettingsFactory - Use JDBC3 getGeneratedKeys(): false
2004-10-11 13:30:06,208 INFO net.sf.hibernate.cfg.SettingsFactory - Optimize cache for minimal puts: false
2004-10-11 13:30:06,208 INFO net.sf.hibernate.cfg.SettingsFactory - Query language substitutions: {}
2004-10-11 13:30:06,208 INFO net.sf.hibernate.cfg.SettingsFactory - cache provider: net.sf.ehcache.hibernate.Provider
2004-10-11 13:30:06,208 INFO net.sf.hibernate.cfg.Configuration - instantiating and configuring caches
2004-10-11 13:30:06,208 DEBUG net.sf.hibernate.cfg.Configuration - instantiating cache testcase.withcache.ParentHibernateImpl.children
2004-10-11 13:30:06,208 DEBUG net.sf.ehcache.CacheManager - Creating new CacheManager with default config
2004-10-11 13:30:06,223 DEBUG net.sf.ehcache.CacheManager - Configuring ehcache from classpath.
2004-10-11 13:30:06,223 DEBUG net.sf.ehcache.config.Configurator - Configuring ehcache from ehcache.xml found in the classpath: file:/C:/Eclipse3/eclipse/workspace/HibernateTestCase/bin/ehcache.xml
2004-10-11 13:30:06,223 DEBUG net.sf.ehcache.config.Configuration$DiskStore - Disk Store Path: C:\WINDOWS\TEMP\
2004-10-11 13:30:06,239 DEBUG net.sf.ehcache.store.MemoryStore - testcase.withcache.ParentHibernateImpl.children Cache: Using SpoolingLinkedHashMap implementation
2004-10-11 13:30:06,239 DEBUG net.sf.ehcache.store.MemoryStore - initialized MemoryStore for testcase.withcache.ParentHibernateImpl.children
2004-10-11 13:30:06,239 DEBUG net.sf.ehcache.Cache - Initialised cache: testcase.withcache.ParentHibernateImpl.children
2004-10-11 13:30:06,239 DEBUG net.sf.ehcache.store.MemoryStore - testcase.withcache.ChildHibernateImpl.parent Cache: Using SpoolingLinkedHashMap implementation
2004-10-11 13:30:06,239 DEBUG net.sf.ehcache.store.MemoryStore - initialized MemoryStore for testcase.withcache.ChildHibernateImpl.parent
2004-10-11 13:30:06,239 DEBUG net.sf.ehcache.Cache - Initialised cache: testcase.withcache.ChildHibernateImpl.parent
2004-10-11 13:30:06,239 DEBUG net.sf.ehcache.store.MemoryStore - testcase.withcache.ParentHibernateImpl Cache: Using SpoolingLinkedHashMap implementation
2004-10-11 13:30:06,239 DEBUG net.sf.ehcache.store.MemoryStore - initialized MemoryStore for testcase.withcache.ParentHibernateImpl
2004-10-11 13:30:06,239 DEBUG net.sf.ehcache.Cache - Initialised cache: testcase.withcache.ParentHibernateImpl
2004-10-11 13:30:06,239 DEBUG net.sf.ehcache.store.MemoryStore - testcase.withcache.ChildHibernateImpl Cache: Using SpoolingLinkedHashMap implementation
2004-10-11 13:30:06,239 DEBUG net.sf.ehcache.store.MemoryStore - initialized MemoryStore for testcase.withcache.ChildHibernateImpl
2004-10-11 13:30:06,239 DEBUG net.sf.ehcache.Cache - Initialised cache: testcase.withcache.ChildHibernateImpl
2004-10-11 13:30:06,239 DEBUG net.sf.hibernate.cfg.Configuration - instantiating cache testcase.withcache.ParentHibernateImpl
2004-10-11 13:30:06,239 DEBUG net.sf.ehcache.CacheManager - Attempting to create an existing instance. Existing instance returned.
2004-10-11 13:30:06,239 DEBUG net.sf.hibernate.cfg.Configuration - instantiating cache testcase.withcache.ChildHibernateImpl
2004-10-11 13:30:06,239 DEBUG net.sf.ehcache.CacheManager - Attempting to create an existing instance. Existing instance returned.
2004-10-11 13:30:06,411 INFO net.sf.hibernate.impl.SessionFactoryImpl - building session factory
2004-10-11 13:30:06,411 DEBUG net.sf.hibernate.impl.SessionFactoryImpl - instantiating session factory with properties: {hibernate.connection.password=, java.runtime.name=Java(TM) 2 Runtime Environment, Standard Edition, hibernate.cache.provider_class=net.sf.ehcache.hibernate.Provider, sun.boot.library.path=C:\Program Files\Java\j2re1.4.2_05\bin, java.vm.version=1.4.2_05-b04, hibernate.connection.username=sa, java.vm.vendor=Sun Microsystems Inc., java.vendor.url=http://java.sun.com/, hibernate.cache.use_query_cache=false, path.separator=;, java.vm.name=Java HotSpot(TM) Client VM, file.encoding.pkg=sun.io, user.country=FI, sun.os.patch.level=Service Pack 1, java.vm.specification.name=Java Virtual Machine Specification, user.dir=C:\Eclipse3\eclipse\workspace\HibernateTestCase, java.runtime.version=1.4.2_05-b04, java.awt.graphicsenv=sun.awt.Win32GraphicsEnvironment, java.endorsed.dirs=C:\Program Files\Java\j2re1.4.2_05\lib\endorsed, os.arch=x86, java.io.tmpdir=C:\WINDOWS\TEMP\, line.separator=
, java.vm.specification.vendor=Sun Microsystems Inc., cache.provider_class=net.sf.ehcache.hibernate.Provider, user.variant=, os.name=Windows XP, sun.java2d.fontpath=, java.library.path=C:\Program Files\Java\j2re1.4.2_05\bin;.;C:\WINDOWS\System32;C:\WINDOWS;C:\Program Files\NCR\Teradata Warehouse Builder\bin;C:\Program Files\NCR\Teradata Client\\Bin;C:\Program Files\NCR\Teradata Client\Bin\;C:\WINDOWS\system32;C:\WINDOWS;C:\WINDOWS\System32\Wbem;C:\Program Files\Microsoft SQL Server\80\Tools\BINN;C:\Program Files\ATI Technologies\ATI Control Panel;C:\cvsnt;C:\j2sdk1.4.2_05\bin;C:\apache-ant-1.6.2\bin;C:\Program Files\7-Zip;C:\Program Files\Subversion\bin;C:\Maven1.0\bin;C:\cygwin\bin;C:\antlr-2.7.4;C:\Program Files\Common Files\GTK\2.0\lib;c:\ruby\bin, java.specification.name=Java Platform API Specification, java.class.version=48.0, java.util.prefs.PreferencesFactory=java.util.prefs.WindowsPreferencesFactory, os.version=5.1, connection.password=, user.home=C:\Documents and Settings\Ville, user.timezone=Europe/Helsinki, connection.username=sa, java.awt.printerjob=sun.awt.windows.WPrinterJob, file.encoding=Cp1252, java.specification.version=1.4, hibernate.connection.driver_class=org.hsqldb.jdbcDriver, show_sql=false, user.name=Ville, java.class.path=C:\Eclipse3\eclipse\workspace\HibernateTestCase\bin;C:\Eclipse3\eclipse\workspace\HibernateTestCase\lib\cglib-full-2.0.2.jar;C:\Eclipse3\eclipse\workspace\HibernateTestCase\lib\commons-collections-2.1.1.jar;C:\Eclipse3\eclipse\workspace\HibernateTestCase\lib\commons-lang-2.0.jar;C:\Eclipse3\eclipse\workspace\HibernateTestCase\lib\commons-logging-1.0.4.jar;C:\Eclipse3\eclipse\workspace\HibernateTestCase\lib\dom4j-1.4.jar;C:\Eclipse3\eclipse\workspace\HibernateTestCase\lib\epl_0.1.jar;C:\Eclipse3\eclipse\workspace\HibernateTestCase\lib\hibernate2.jar;C:\Eclipse3\eclipse\workspace\HibernateTestCase\lib\hsqldb.jar;C:\Eclipse3\eclipse\workspace\HibernateTestCase\lib\log4j-1.2.8.jar;C:\Eclipse3\eclipse\workspace\HibernateTestCase\lib\odmg-3.0.jar;C:\Eclipse3\eclipse\workspace\HibernateTestCase\lib\ehcache-1.0.jar;C:\Eclipse3\eclipse\workspace\HibernateTestCase\lib\jta.jar, hibernate.show_sql=false, java.vm.specification.version=1.0, java.home=C:\Program Files\Java\j2re1.4.2_05, sun.arch.data.model=32, hibernate.dialect=net.sf.hibernate.dialect.HSQLDialect, hibernate.connection.url=jdbc:hsqldb:mem:test, user.language=fi, java.specification.vendor=Sun Microsystems Inc., awt.toolkit=sun.awt.windows.WToolkit, hibernate.cglib.use_reflection_optimizer=true, java.vm.info=mixed mode, java.version=1.4.2_05, java.ext.dirs=C:\Program Files\Java\j2re1.4.2_05\lib\ext, cache.use_query_cache=false, sun.boot.class.path=C:\Program Files\Java\j2re1.4.2_05\lib\rt.jar;C:\Program Files\Java\j2re1.4.2_05\lib\i18n.jar;C:\Program Files\Java\j2re1.4.2_05\lib\sunrsasign.jar;C:\Program Files\Java\j2re1.4.2_05\lib\jsse.jar;C:\Program Files\Java\j2re1.4.2_05\lib\jce.jar;C:\Program Files\Java\j2re1.4.2_05\lib\charsets.jar;C:\Program Files\Java\j2re1.4.2_05\classes, java.vendor=Sun Microsystems Inc., connection.driver_class=org.hsqldb.jdbcDriver, file.separator=\, max_fetch_depth=3, java.vendor.url.bug=http://java.sun.com/cgi-bin/bugreport.cgi, sun.io.unicode.encoding=UnicodeLittle, sun.cpu.endian=little, hibernate.max_fetch_depth=3, connection.url=jdbc:hsqldb:mem:test, dialect=net.sf.hibernate.dialect.HSQLDialect, sun.cpu.isalist=pentium i486 i386}
2004-10-11 13:30:06,988 DEBUG net.sf.hibernate.impl.SessionFactoryObjectFactory - initializing class SessionFactoryObjectFactory
2004-10-11 13:30:06,988 DEBUG net.sf.hibernate.impl.SessionFactoryObjectFactory - registered: 8a8080c8ff8789a800ff8789ab8c0000 (unnamed)
2004-10-11 13:30:06,988 INFO net.sf.hibernate.impl.SessionFactoryObjectFactory - Not binding factory to JNDI, no JNDI name configured
2004-10-11 13:30:06,988 DEBUG net.sf.hibernate.impl.SessionFactoryImpl - instantiated session factory
2004-10-11 13:30:07,051 DEBUG net.sf.hibernate.impl.SessionImpl - opened session
2004-10-11 13:30:07,051 DEBUG net.sf.hibernate.connection.DriverManagerConnectionProvider - total checked-out connections: 0
2004-10-11 13:30:07,051 DEBUG net.sf.hibernate.connection.DriverManagerConnectionProvider - using pooled JDBC connection, pool size: 0
2004-10-11 13:30:07,082 DEBUG net.sf.hibernate.impl.SessionImpl - closing session
2004-10-11 13:30:07,082 DEBUG net.sf.hibernate.impl.SessionImpl - disconnecting session
2004-10-11 13:30:07,082 DEBUG net.sf.hibernate.connection.DriverManagerConnectionProvider - returning connection to pool, pool size: 1
2004-10-11 13:30:07,082 DEBUG net.sf.hibernate.impl.SessionImpl - transaction completion
2004-10-11 13:30:07,082 DEBUG net.sf.hibernate.impl.SessionImpl - opened session
2004-10-11 13:30:07,097 DEBUG net.sf.hibernate.impl.SessionImpl - find: FROM ParentHibernateImpl AS parent WHERE parent.parentId = 1
2004-10-11 13:30:07,097 DEBUG net.sf.hibernate.engine.QueryParameters - named parameters: {}
2004-10-11 13:30:07,113 DEBUG net.sf.hibernate.hql.QueryTranslator - compiling query
2004-10-11 13:30:07,129 DEBUG net.sf.hibernate.impl.SessionImpl - flushing session
2004-10-11 13:30:07,129 DEBUG net.sf.hibernate.impl.SessionImpl - Flushing entities and processing referenced collections
2004-10-11 13:30:07,129 DEBUG net.sf.hibernate.impl.SessionImpl - Processing unreferenced collections
2004-10-11 13:30:07,129 DEBUG net.sf.hibernate.impl.SessionImpl - Scheduling collection removes/(re)creates/updates
2004-10-11 13:30:07,129 DEBUG net.sf.hibernate.impl.SessionImpl - Flushed: 0 insertions, 0 updates, 0 deletions to 0 objects
2004-10-11 13:30:07,129 DEBUG net.sf.hibernate.impl.SessionImpl - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
2004-10-11 13:30:07,144 DEBUG net.sf.hibernate.impl.SessionImpl - Dont need to execute flush
2004-10-11 13:30:07,144 DEBUG net.sf.hibernate.hql.QueryTranslator - HQL: FROM testcase.withcache.ParentHibernateImpl AS parent WHERE parent.parentId = 1
2004-10-11 13:30:07,144 DEBUG net.sf.hibernate.hql.QueryTranslator - SQL: select parenthibe0_.Parent_id as Parent_id, parenthibe0_.Version as Version, parenthibe0_.Name as Name from Parent parenthibe0_ where (parenthibe0_.Parent_id=1 )
2004-10-11 13:30:07,144 DEBUG net.sf.hibernate.impl.BatcherImpl - about to open: 0 open PreparedStatements, 0 open ResultSets
2004-10-11 13:30:07,144 DEBUG net.sf.hibernate.connection.DriverManagerConnectionProvider - total checked-out connections: 0
2004-10-11 13:30:07,144 DEBUG net.sf.hibernate.connection.DriverManagerConnectionProvider - using pooled JDBC connection, pool size: 0
2004-10-11 13:30:07,144 DEBUG net.sf.hibernate.SQL - select parenthibe0_.Parent_id as Parent_id, parenthibe0_.Version as Version, parenthibe0_.Name as Name from Parent parenthibe0_ where (parenthibe0_.Parent_id=1 )
2004-10-11 13:30:07,144 DEBUG net.sf.hibernate.impl.BatcherImpl - preparing statement
2004-10-11 13:30:07,222 DEBUG net.sf.hibernate.loader.Loader - processing result set
2004-10-11 13:30:07,222 DEBUG net.sf.hibernate.type.IntegerType - returning '1' as column: Parent_id
2004-10-11 13:30:07,222 DEBUG net.sf.hibernate.loader.Loader - result row: 1
2004-10-11 13:30:07,222 DEBUG net.sf.hibernate.loader.Loader - Initializing object from ResultSet: 1
2004-10-11 13:30:07,222 DEBUG net.sf.hibernate.loader.Loader - Hydrating entity: testcase.withcache.ParentHibernateImpl#1
2004-10-11 13:30:07,222 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: Version
2004-10-11 13:30:07,222 DEBUG net.sf.hibernate.type.StringType - returning 'Ukko' as column: Name
2004-10-11 13:30:07,238 DEBUG net.sf.hibernate.impl.SessionImpl - Version: 0
2004-10-11 13:30:07,238 DEBUG net.sf.hibernate.loader.Loader - done processing result set (1 rows)
2004-10-11 13:30:07,238 DEBUG net.sf.hibernate.impl.BatcherImpl - done closing: 0 open PreparedStatements, 0 open ResultSets
2004-10-11 13:30:07,238 DEBUG net.sf.hibernate.impl.BatcherImpl - closing statement
2004-10-11 13:30:07,238 DEBUG net.sf.hibernate.loader.Loader - total objects hydrated: 1
2004-10-11 13:30:07,238 DEBUG net.sf.hibernate.impl.SessionImpl - resolving associations for [testcase.withcache.ParentHibernateImpl#1]
2004-10-11 13:30:07,238 DEBUG net.sf.hibernate.impl.SessionImpl - creating collection wrapper:[testcase.withcache.ParentHibernateImpl.children#1]
2004-10-11 13:30:07,238 DEBUG net.sf.hibernate.impl.SessionImpl - adding entity to second-level cache [testcase.withcache.ParentHibernateImpl#1]
2004-10-11 13:30:07,238 DEBUG net.sf.hibernate.cache.NonstrictReadWriteCache - Caching: 1
2004-10-11 13:30:07,254 DEBUG net.sf.ehcache.Cache - 1 now: 1097490607254
2004-10-11 13:30:07,254 DEBUG net.sf.ehcache.Cache - 1 Creation Time: 1097490607254 Next To Last Access Time: 0
2004-10-11 13:30:07,254 DEBUG net.sf.ehcache.Cache - 1 mostRecentTime: 1097490607254
2004-10-11 13:30:07,254 DEBUG net.sf.ehcache.Cache - 1 Age to Idle: 600000 Age Idled: 0
2004-10-11 13:30:07,254 DEBUG net.sf.ehcache.Cache - testcase.withcache.ParentHibernateImpl: Is element with key 1 expired?: false
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.impl.SessionImpl - done materializing entity [testcase.withcache.ParentHibernateImpl#1]
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.impl.SessionImpl - initializing non-lazy collections
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.impl.SessionImpl - initializing collection [testcase.withcache.ParentHibernateImpl.children#1]
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.impl.SessionImpl - checking second-level cache
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.cache.NonstrictReadWriteCache - Cache lookup: 1
2004-10-11 13:30:07,254 DEBUG net.sf.ehcache.hibernate.Plugin - key: 1
2004-10-11 13:30:07,254 DEBUG net.sf.ehcache.store.MemoryStore - testcase.withcache.ParentHibernateImpl.childrenCache: MemoryStore miss for 1
2004-10-11 13:30:07,254 DEBUG net.sf.ehcache.Cache - testcase.withcache.ParentHibernateImpl.children cache - Miss
2004-10-11 13:30:07,254 DEBUG net.sf.ehcache.hibernate.Plugin - Element for 1 is null
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.cache.NonstrictReadWriteCache - Cache miss
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.impl.SessionImpl - collection not cached
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.impl.BatcherImpl - about to open: 0 open PreparedStatements, 0 open ResultSets
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.SQL - select children0_.Parent_id as Parent_id__, children0_.Child_id as Child_id__, children0_.Child_id as Child_id0_, children0_.Version as Version0_, children0_.Parent_id as Parent_id0_, children0_.Name as Name0_ from Child children0_ where children0_.Parent_id=?
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.impl.BatcherImpl - preparing statement
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.type.IntegerType - binding '1' to parameter: 1
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.loader.Loader - result set contains (possibly empty) collection: [testcase.withcache.ParentHibernateImpl.children#1]
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.impl.SessionImpl - uninitialized collection: initializing
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.loader.Loader - processing result set
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.type.IntegerType - returning '1' as column: Child_id0_
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.loader.Loader - result row: 1
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.loader.Loader - Initializing object from ResultSet: 1
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.loader.Loader - Hydrating entity: testcase.withcache.ChildHibernateImpl#1
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: Version0_
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.type.IntegerType - returning '1' as column: Parent_id0_
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.type.StringType - returning 'Pekka' as column: Name0_
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.impl.SessionImpl - Version: 0
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.type.IntegerType - returning '1' as column: Parent_id__
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.loader.Loader - found row of collection: [testcase.withcache.ParentHibernateImpl.children#1]
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.impl.SessionImpl - reading row
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.type.IntegerType - returning '1' as column: Child_id__
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.impl.SessionImpl - loading [testcase.withcache.ChildHibernateImpl#1]
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.impl.SessionImpl - attempting to resolve [testcase.withcache.ChildHibernateImpl#1]
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.impl.SessionImpl - resolved object in session cache [testcase.withcache.ChildHibernateImpl#1]
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.type.IntegerType - returning '2' as column: Child_id0_
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.loader.Loader - result row: 2
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.loader.Loader - Initializing object from ResultSet: 2
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.loader.Loader - Hydrating entity: testcase.withcache.ChildHibernateImpl#2
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: Version0_
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.type.IntegerType - returning '1' as column: Parent_id0_
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.type.StringType - returning 'Mikko' as column: Name0_
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.impl.SessionImpl - Version: 0
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.type.IntegerType - returning '1' as column: Parent_id__
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.loader.Loader - found row of collection: [testcase.withcache.ParentHibernateImpl.children#1]
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.impl.SessionImpl - reading row
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.type.IntegerType - returning '2' as column: Child_id__
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.impl.SessionImpl - loading [testcase.withcache.ChildHibernateImpl#2]
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.impl.SessionImpl - attempting to resolve [testcase.withcache.ChildHibernateImpl#2]
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.impl.SessionImpl - resolved object in session cache [testcase.withcache.ChildHibernateImpl#2]
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.type.IntegerType - returning '3' as column: Child_id0_
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.loader.Loader - result row: 3
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.loader.Loader - Initializing object from ResultSet: 3
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.loader.Loader - Hydrating entity: testcase.withcache.ChildHibernateImpl#3
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: Version0_
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.type.IntegerType - returning '1' as column: Parent_id0_
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.type.StringType - returning 'Veijo' as column: Name0_
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.impl.SessionImpl - Version: 0
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.type.IntegerType - returning '1' as column: Parent_id__
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.loader.Loader - found row of collection: [testcase.withcache.ParentHibernateImpl.children#1]
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.impl.SessionImpl - reading row
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.type.IntegerType - returning '3' as column: Child_id__
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.impl.SessionImpl - loading [testcase.withcache.ChildHibernateImpl#3]
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.impl.SessionImpl - attempting to resolve [testcase.withcache.ChildHibernateImpl#3]
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.impl.SessionImpl - resolved object in session cache [testcase.withcache.ChildHibernateImpl#3]
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.loader.Loader - done processing result set (3 rows)
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.impl.BatcherImpl - done closing: 0 open PreparedStatements, 0 open ResultSets
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.impl.BatcherImpl - closing statement
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.loader.Loader - total objects hydrated: 3
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.impl.SessionImpl - resolving associations for [testcase.withcache.ChildHibernateImpl#1]
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.impl.SessionImpl - loading [testcase.withcache.ParentHibernateImpl#1]
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.impl.SessionImpl - attempting to resolve [testcase.withcache.ParentHibernateImpl#1]
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.impl.SessionImpl - resolved object in session cache [testcase.withcache.ParentHibernateImpl#1]
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.impl.SessionImpl - adding entity to second-level cache [testcase.withcache.ChildHibernateImpl#1]
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.cache.NonstrictReadWriteCache - Caching: 1
2004-10-11 13:30:07,254 DEBUG net.sf.ehcache.Cache - 1 now: 1097490607254
2004-10-11 13:30:07,254 DEBUG net.sf.ehcache.Cache - 1 Creation Time: 1097490607254 Next To Last Access Time: 0
2004-10-11 13:30:07,254 DEBUG net.sf.ehcache.Cache - 1 mostRecentTime: 1097490607254
2004-10-11 13:30:07,254 DEBUG net.sf.ehcache.Cache - 1 Age to Idle: 600000 Age Idled: 0
2004-10-11 13:30:07,254 DEBUG net.sf.ehcache.Cache - testcase.withcache.ChildHibernateImpl: Is element with key 1 expired?: false
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.impl.SessionImpl - done materializing entity [testcase.withcache.ChildHibernateImpl#1]
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.impl.SessionImpl - resolving associations for [testcase.withcache.ChildHibernateImpl#2]
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.impl.SessionImpl - loading [testcase.withcache.ParentHibernateImpl#1]
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.impl.SessionImpl - attempting to resolve [testcase.withcache.ParentHibernateImpl#1]
2004-10-11 13:30:07,254 DEBUG net.sf.hibernate.impl.SessionImpl - resolved object in session cache [testcase.withcache.ParentHibernateImpl#1]
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.impl.SessionImpl - adding entity to second-level cache [testcase.withcache.ChildHibernateImpl#2]
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.cache.NonstrictReadWriteCache - Caching: 2
2004-10-11 13:30:07,269 DEBUG net.sf.ehcache.Cache - 1 now: 1097490607269
2004-10-11 13:30:07,269 DEBUG net.sf.ehcache.Cache - 1 Creation Time: 1097490607254 Next To Last Access Time: 0
2004-10-11 13:30:07,269 DEBUG net.sf.ehcache.Cache - 1 mostRecentTime: 1097490607254
2004-10-11 13:30:07,269 DEBUG net.sf.ehcache.Cache - 1 Age to Idle: 600000 Age Idled: 15
2004-10-11 13:30:07,269 DEBUG net.sf.ehcache.Cache - testcase.withcache.ChildHibernateImpl: Is element with key 1 expired?: false
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.impl.SessionImpl - done materializing entity [testcase.withcache.ChildHibernateImpl#2]
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.impl.SessionImpl - resolving associations for [testcase.withcache.ChildHibernateImpl#3]
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.impl.SessionImpl - loading [testcase.withcache.ParentHibernateImpl#1]
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.impl.SessionImpl - attempting to resolve [testcase.withcache.ParentHibernateImpl#1]
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.impl.SessionImpl - resolved object in session cache [testcase.withcache.ParentHibernateImpl#1]
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.impl.SessionImpl - adding entity to second-level cache [testcase.withcache.ChildHibernateImpl#3]
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.cache.NonstrictReadWriteCache - Caching: 3
2004-10-11 13:30:07,269 DEBUG net.sf.ehcache.Cache - 1 now: 1097490607269
2004-10-11 13:30:07,269 DEBUG net.sf.ehcache.Cache - 1 Creation Time: 1097490607254 Next To Last Access Time: 0
2004-10-11 13:30:07,269 DEBUG net.sf.ehcache.Cache - 1 mostRecentTime: 1097490607254
2004-10-11 13:30:07,269 DEBUG net.sf.ehcache.Cache - 1 Age to Idle: 600000 Age Idled: 15
2004-10-11 13:30:07,269 DEBUG net.sf.ehcache.Cache - testcase.withcache.ChildHibernateImpl: Is element with key 1 expired?: false
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.impl.SessionImpl - done materializing entity [testcase.withcache.ChildHibernateImpl#3]
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.impl.SessionImpl - 1 collections were found in result set
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.impl.SessionImpl - Caching collection: [testcase.withcache.ParentHibernateImpl.children#1]
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.cache.NonstrictReadWriteCache - Caching: 1
2004-10-11 13:30:07,269 DEBUG net.sf.ehcache.Cache - 1 now: 1097490607269
2004-10-11 13:30:07,269 DEBUG net.sf.ehcache.Cache - 1 Creation Time: 1097490607269 Next To Last Access Time: 0
2004-10-11 13:30:07,269 DEBUG net.sf.ehcache.Cache - 1 mostRecentTime: 1097490607269
2004-10-11 13:30:07,269 DEBUG net.sf.ehcache.Cache - 1 Age to Idle: 600000 Age Idled: 0
2004-10-11 13:30:07,269 DEBUG net.sf.ehcache.Cache - testcase.withcache.ParentHibernateImpl.children: Is element with key 1 expired?: false
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.impl.SessionImpl - collection fully initialized: [testcase.withcache.ParentHibernateImpl.children#1]
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.impl.SessionImpl - 1 collections initialized
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.impl.SessionImpl - initializing non-lazy collections
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.impl.SessionImpl - collection initialized
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.impl.SessionImpl - closing session
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.impl.SessionImpl - disconnecting session
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.connection.DriverManagerConnectionProvider - returning connection to pool, pool size: 1
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.impl.SessionImpl - transaction completion
parent.getChildren() after closing the session: [testcase.withcache.ChildHibernateImpl@29689095
[
   childId=1
   name=Pekka
], testcase.withcache.ChildHibernateImpl@32915800
[
   childId=2
   name=Mikko
], testcase.withcache.ChildHibernateImpl@3941240
[
   childId=3
   name=Veijo
]]
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.impl.SessionImpl - opened session
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.impl.SessionImpl - find: FROM ParentHibernateImpl AS parent WHERE parent.parentId = 1
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.engine.QueryParameters - named parameters: {}
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.impl.SessionImpl - flushing session
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.impl.SessionImpl - Flushing entities and processing referenced collections
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.impl.SessionImpl - Processing unreferenced collections
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.impl.SessionImpl - Scheduling collection removes/(re)creates/updates
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.impl.SessionImpl - Flushed: 0 insertions, 0 updates, 0 deletions to 0 objects
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.impl.SessionImpl - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.impl.SessionImpl - Dont need to execute flush
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.hql.QueryTranslator - HQL: FROM testcase.withcache.ParentHibernateImpl AS parent WHERE parent.parentId = 1
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.hql.QueryTranslator - SQL: select parenthibe0_.Parent_id as Parent_id, parenthibe0_.Version as Version, parenthibe0_.Name as Name from Parent parenthibe0_ where (parenthibe0_.Parent_id=1 )
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.impl.BatcherImpl - about to open: 0 open PreparedStatements, 0 open ResultSets
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.connection.DriverManagerConnectionProvider - total checked-out connections: 0
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.connection.DriverManagerConnectionProvider - using pooled JDBC connection, pool size: 0
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.SQL - select parenthibe0_.Parent_id as Parent_id, parenthibe0_.Version as Version, parenthibe0_.Name as Name from Parent parenthibe0_ where (parenthibe0_.Parent_id=1 )
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.impl.BatcherImpl - preparing statement
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.loader.Loader - processing result set
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.type.IntegerType - returning '1' as column: Parent_id
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.loader.Loader - result row: 1
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.loader.Loader - Initializing object from ResultSet: 1
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.loader.Loader - Hydrating entity: testcase.withcache.ParentHibernateImpl#1
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.type.IntegerType - returning '0' as column: Version
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.type.StringType - returning 'Ukko' as column: Name
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.impl.SessionImpl - Version: 0
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.loader.Loader - done processing result set (1 rows)
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.impl.BatcherImpl - done closing: 0 open PreparedStatements, 0 open ResultSets
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.impl.BatcherImpl - closing statement
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.loader.Loader - total objects hydrated: 1
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.impl.SessionImpl - resolving associations for [testcase.withcache.ParentHibernateImpl#1]
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.impl.SessionImpl - creating collection wrapper:[testcase.withcache.ParentHibernateImpl.children#1]
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.impl.SessionImpl - adding entity to second-level cache [testcase.withcache.ParentHibernateImpl#1]
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.cache.NonstrictReadWriteCache - Caching: 1
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.impl.SessionImpl - done materializing entity [testcase.withcache.ParentHibernateImpl#1]
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.impl.SessionImpl - initializing non-lazy collections
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.impl.SessionImpl - initializing collection [testcase.withcache.ParentHibernateImpl.children#1]
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.impl.SessionImpl - checking second-level cache
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.cache.NonstrictReadWriteCache - Cache lookup: 1
2004-10-11 13:30:07,269 DEBUG net.sf.ehcache.hibernate.Plugin - key: 1
2004-10-11 13:30:07,269 DEBUG net.sf.ehcache.store.MemoryStore - testcase.withcache.ParentHibernateImpl.childrenCache: MemoryStore hit for 1
2004-10-11 13:30:07,269 DEBUG net.sf.ehcache.Cache - 1 now: 1097490607269
2004-10-11 13:30:07,269 DEBUG net.sf.ehcache.Cache - 1 Creation Time: 1097490607269 Next To Last Access Time: 0
2004-10-11 13:30:07,269 DEBUG net.sf.ehcache.Cache - 1 mostRecentTime: 1097490607269
2004-10-11 13:30:07,269 DEBUG net.sf.ehcache.Cache - 1 Age to Idle: 600000 Age Idled: 0
2004-10-11 13:30:07,269 DEBUG net.sf.ehcache.Cache - testcase.withcache.ParentHibernateImpl.children: Is element with key 1 expired?: false
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.cache.NonstrictReadWriteCache - Cache hit
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.impl.SessionImpl - loading [testcase.withcache.ChildHibernateImpl#1]
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.impl.SessionImpl - loading [testcase.withcache.ChildHibernateImpl#2]
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.impl.SessionImpl - loading [testcase.withcache.ChildHibernateImpl#3]
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.impl.SessionImpl - collection initialized from cache
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.impl.SessionImpl - closing session
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.impl.SessionImpl - disconnecting session
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.connection.DriverManagerConnectionProvider - returning connection to pool, pool size: 1
2004-10-11 13:30:07,269 DEBUG net.sf.hibernate.impl.SessionImpl - transaction completion
2004-10-11 13:30:07,269 ERROR net.sf.hibernate.proxy.LazyInitializer - Exception initializing proxy
net.sf.hibernate.HibernateException: Could not initialize proxy - the owning Session was closed
   at net.sf.hibernate.proxy.LazyInitializer.initialize(LazyInitializer.java:47)
   at net.sf.hibernate.proxy.LazyInitializer.initializeWrapExceptions(LazyInitializer.java:60)
   at net.sf.hibernate.proxy.LazyInitializer.getImplementation(LazyInitializer.java:164)
   at net.sf.hibernate.proxy.CGLIBLazyInitializer.intercept(CGLIBLazyInitializer.java:108)
   at testcase.withcache.ChildHibernateImpl$$EnhancerByCGLIB$$db7e9294.toString(<generated>)
   at java.lang.String.valueOf(Unknown Source)
   at java.util.AbstractCollection.toString(Unknown Source)
   at net.sf.hibernate.collection.Bag.toString(Bag.java:483)
   at java.lang.String.valueOf(Unknown Source)
   at java.lang.StringBuffer.append(Unknown Source)
   at testcase.withcache.Main.main(Main.java:63)
net.sf.hibernate.LazyInitializationException: Exception initializing proxy: [testcase.withcache.ChildHibernateImpl#1]
   at net.sf.hibernate.proxy.LazyInitializer.initializeWrapExceptions(LazyInitializer.java:64)
   at net.sf.hibernate.proxy.LazyInitializer.getImplementation(LazyInitializer.java:164)
   at net.sf.hibernate.proxy.CGLIBLazyInitializer.intercept(CGLIBLazyInitializer.java:108)
   at testcase.withcache.ChildHibernateImpl$$EnhancerByCGLIB$$db7e9294.toString(<generated>)
   at java.lang.String.valueOf(Unknown Source)
   at java.util.AbstractCollection.toString(Unknown Source)
   at net.sf.hibernate.collection.Bag.toString(Bag.java:483)
   at java.lang.String.valueOf(Unknown Source)
   at java.lang.StringBuffer.append(Unknown Source)
   at testcase.withcache.Main.main(Main.java:63)
Caused by: net.sf.hibernate.HibernateException: Could not initialize proxy - the owning Session was closed
   at net.sf.hibernate.proxy.LazyInitializer.initialize(LazyInitializer.java:47)
   at net.sf.hibernate.proxy.LazyInitializer.initializeWrapExceptions(LazyInitializer.java:60)
   ... 9 more
Exception in thread "main" 

[/code]

Ville Peurala · **Posted:** Tue Oct 12, 2004 4:38 am

I examined this more, and noticed that the setting which causes the error is the caching of the bag:

Code:

     <bag name="children"
             access="field"
             lazy="true"
             inverse="true"
             cascade="all">
            <cache usage="nonstrict-read-write" />
            <key>
                <column name="Parent_id" not-null="true" sql-type="int" />
            </key>
            <one-to-many class="testcase.withcache.ChildHibernateImpl" />
     </bag> 

If I remove <cache usage="nonstrict-read-write" />, it works correctly.

So the caching of the classes themselves does not affect this,
but only the caching of their relation.

Does this sound familiar to anyone?

- Ville Peurala

Ville Peurala · **Posted:** Tue Oct 12, 2004 12:32 pm

I examined Hibernate's source code a little more and inserted some log statements. In class net.sf.hibernate.collection.Bag, which is used since the collection type of the relation is a bag, there is a method called:

Code:

public void initializeFromCache(CollectionPersister persister,
            Serializable disassembled, Object owner) throws HibernateException

This method gets called when Hibernate.initialize() is called on the collection of children.

Now, in this method there is this line:

Code:

bag.add( persister.getElementType().assemble( array[i], getSession(), owner ) );

It seems like method assemble() returns a proxy instead of an initialized object. This proxy goes to the client and causes the LazyInitializationException after the session where the parent object was loaded is closed.

When I changed the above line to the following form (which is otherwise identical to the original except for the log statement between assemble() and add()):

Code:

Object assembled = persister.getElementType().assemble(array[i], getSession(), owner);
log.debug("assembled: '" + assembled + "'");
bag.add(assembled);

my test case worked. And I assume that is because, when the object is logged, its toString() method gets called, initializing the proxy - and now it goes to the client as an initialized object which does not care anymore whether the session is open or not.

So is this a bug, or is there something stupid in my configuration?

- Ville Peurala

Ville Peurala · **Posted:** Tue Oct 12, 2004 12:39 pm

Sorry, my previous post had too long lines, making it hard to read. I post it again with better layout. Here:

I examined Hibernate's source code a little more and inserted some log statements.
In class net.sf.hibernate.collection.Bag, which is used since the collection type of the relation is a bag, there is a method called:

Code:

public void initializeFromCache(CollectionPersister persister,
            Serializable disassembled, Object owner) throws HibernateException

This method gets called when Hibernate.initialize() is called on the collection of children.

Now, in this method there is this line:

Code:

bag.add( persister.getElementType().assemble( array[i], getSession(), owner ) );

It seems like method assemble() returns a proxy instead of an initialized object.
This proxy goes to the client and causes the LazyInitializationException after the session where the parent object was loaded is closed.

When I changed the above line to the following form (which is otherwise identical to the original except for the
log statement between assemble() and add()):

Code:

Object assembled = persister.getElementType().assemble(array[i], getSession(), owner);
log.debug("assembled: '" + assembled + "'");
bag.add(assembled);

my test case worked. And I assume that is because, when the object is logged, its toString() method gets called,
initializing the proxy - and now it goes to the client as an initialized object which does not care anymore whether the session is open or not.

So is this a bug, or is there something stupid in my configuration?

- Ville Peurala

Ville Peurala · **Posted:** Wed Oct 13, 2004 3:43 am

Is it really so that no one knows anything about this?
Should I submit this to JIRA?

- Ville Peurala

christian · **Posted:** Wed Oct 13, 2004 4:17 am

Please don't...

Ville Peurala · **Posted:** Wed Oct 13, 2004 4:35 am

christian wrote:

Please don't...

Well, I am really sorry if this was a stupid RTFM type question.

But can you please tell me what is wrong with this?
I have searched the forums, read all the documentation and even a lot of the source code.

I find it quite strange that using a cache breaks my application, when I explicitly initialize the collection with Hibernate.initialize() before closing the session and sending the object to the client.
Isn't there any way to make caching work with a client/server type application with a Swing client?

- Ville Peurala

christian · **Posted:** Wed Oct 13, 2004 4:37 am

It's just that no-one had time to look at your usage question.

Ville Peurala · **Posted:** Wed Oct 13, 2004 9:28 am

OK, but I am not at all sure if it's only a usage question.
This might also be a bug, or at least an undocumented feature, in Hibernate.

From the logs I see that the objects which come out of the cache are proxies.
I wonder how they got there in the first place?
Why are proxies cached?
As far as I have understood, proxies are useful only in the same session where they are created.
So it seems strange that proxies are put in the second level cache at all.

So that's why I asked if I should submit this to JIRA.
It would be really nice if someone had time to look at this.

Right now, there are two ways to solve this:

1) Turn off caching for the collection.
2) Initialize the collection itself, and in addition to that, also initialize every item in it separately, like this:

Code:

Collection children = parent.getChildren();
Hibernate.initialize(children);
for (Iterator it = children.iterator(); it.hasNext();) {
   Child currentChild = (Child) it.next();
   Hibernate.initialize(currentChild);
}

I think that the second way is quite inconvenient.
I also would find it very odd if cached collections were meant to be initialized that way,
when a single Hibernate.initialize() call on the collection itself is
enough for non-cached lazy collections.

Ville Peurala · **Posted:** Thu Oct 14, 2004 2:30 am

Now I have put together the most minimal JUnit testcase I can think of
to demonstrate this thing I have been talking about.

By executing this, you can see that the child objects
in the collection are cglib-enhanced objects (lazy loading proxies),
even though Hibernate.initialize() has been called for the collection.
And this only happens if the collection is cached.
Without a cache it works perfectly.

To execute this test you need only hsqldb in addition to Hibernate's own dependencies.
You can also use any other database, the result is the same.

Here comes the code of the testcase:

ParentChildCacheTest.java:

Code:

import java.sql.Connection;

import junit.framework.TestCase;
import net.sf.cglib.proxy.Enhancer;
import net.sf.hibernate.Hibernate;
import net.sf.hibernate.HibernateException;
import net.sf.hibernate.Session;
import net.sf.hibernate.SessionFactory;
import net.sf.hibernate.cfg.Configuration;

/**
 * This test case shows that when using a cache, lazy loading proxies are
 * returned to the caller even after Hibernate.initialize() is explicitly
 * called. If caching is turned off for collection "children" on Parent, this
 * test passes. If caching is turned on for that collection, this test fails.
 * @author Ville Peurala
 */
public class ParentChildCacheTest extends TestCase {

    /**
     * HSQLDB is used with AUTOCOMMIT ON, so there's no need to explicitly open
     * and commit transactions. I have also tried this with manual transactions,
     * and they don't affect the behaviour of this test case in any way.
     * @throws Exception
     */
    public void testInitializedObjectsShouldNotBeProxies() throws Exception {
        Configuration cfg = new Configuration().configure();
        SessionFactory factory = cfg.buildSessionFactory();
        // Create the tables in one session
        Session ddlSession = factory.openSession();
        Connection conn = ddlSession.connection();
        conn
                .createStatement()
                .execute(
                        "CREATE TABLE Parent (Parent_id INT NOT NULL IDENTITY, Name VARCHAR(64) NOT NULL, PRIMARY KEY(Parent_id))");
        conn
                .createStatement()
                .execute(
                        "CREATE TABLE Child (Child_id INT NOT NULL IDENTITY, Name VARCHAR(64) NOT NULL, Parent_id INT NOT NULL, PRIMARY KEY(Child_id), CONSTRAINT FK_Child_Parent_0 FOREIGN KEY (Parent_id) REFERENCES Parent(Parent_id))");
        conn.createStatement().execute(
                "INSERT INTO Parent (Parent_id, Name) VALUES (1, 'Ukko')");
        conn
                .createStatement()
                .execute(
                        "INSERT INTO Child (Child_id, Name, Parent_id) VALUES (1, 'Pekka', 1)");
        ddlSession.close();

        Child childWhichComesFromDatabase = this
                .getFirstChildOfParentWithId1WhenChildrenAreInitializedAndSessionIsClosed(factory);
        // This assertion passes.
        assertFalse(
                "Objects from an explicitly initialized collection should not be enhanced by CGLIB (if they are, they are lazy loading proxies)",
                Enhancer.isEnhanced(childWhichComesFromDatabase.getClass()));

        Child childWhichComesFromCacheHit = this
                .getFirstChildOfParentWithId1WhenChildrenAreInitializedAndSessionIsClosed(factory);
        // This assertion fails.
        assertFalse(
                "Objects from an explicitly initialized collection should not be enhanced by CGLIB (if they are, they are lazy loading proxies)",
                Enhancer.isEnhanced(childWhichComesFromCacheHit.getClass()));

        conn.close();
    }

    private Child getFirstChildOfParentWithId1WhenChildrenAreInitializedAndSessionIsClosed(
            SessionFactory sessionFactory) throws HibernateException {
        Session session = sessionFactory.openSession();
        Parent parent = (Parent) session.createQuery(
                "FROM Parent AS parent WHERE parent.parentId = 1")
                .uniqueResult();
        Hibernate.initialize(parent.getChildren());
        session.close();
        return (Child) parent.getChildren().get(0);
    }

}

Parent.java:

Code:

import java.io.Serializable;

/**
 * @author Ville Peurala
 */
public class Parent implements Serializable {
    private static final long serialVersionUID = 1977L;

    // fields

    private java.lang.Integer parentId;
    private java.lang.String name;
    private java.util.List children = new java.util.ArrayList();

    // getters and setters

    public java.lang.Integer getParentId() {
        return this.parentId;
    }
    protected void setParentId(java.lang.Integer newValue) {
        this.parentId = newValue;
    }
    public java.lang.String getName() {
        return this.name;
    }
    public void setName(java.lang.String newValue) {
        this.name = newValue;
    }
    public java.util.List getChildren() {
        return this.children;
    }
}

Child.java:

Code:

import java.io.Serializable;

/**
 * @author Ville Peurala
 */
public class Child implements Serializable {
    private static final long serialVersionUID = 1977L;

    // fields

    private java.lang.Integer childId;
    private java.lang.String name;
    private Parent parent;

    // property getters and setters

    public java.lang.Integer getChildId() {
        return this.childId;
    }
    protected void setChildId(java.lang.Integer newValue) {
        this.childId = newValue;
    }
    public java.lang.String getName() {
        return this.name;
    }
    public void setName(java.lang.String newValue) {
        this.name = newValue;
    }
    public Parent getParent() {
        return this.parent;
    }
    public void setParent(Parent newValue) {
        this.parent = newValue;
    }
}

Parent.hbm.xml:

Code:

<?xml version="1.0"?>

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

<hibernate-mapping>
   <class name="Parent" dynamic-update="false" dynamic-insert="false" 
      optimistic-lock="version" proxy="Parent" table="Parent">
      <cache usage="nonstrict-read-write" />
      <id name="parentId" access="field" column="Parent_id" 
         type="java.lang.Integer" unsaved-value="null">
         <generator class="native" />
      </id>
      <property name="name" access="field" type="java.lang.String" 
         column="Name" length="64" not-null="true" />
      <bag name="children" access="field" lazy="true" inverse="true" 
         cascade="all">
         <!-- Comment the following line out and the test (ParentChildCacheTest) passes. -->
         <cache usage="nonstrict-read-write" />
         <key>
            <column name="Parent_id" not-null="true" sql-type="int" />
         </key>
         <one-to-many class="Child" />
      </bag>
   </class>
</hibernate-mapping>

Child.hbm.xml

Code:

<?xml version="1.0"?>

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

<hibernate-mapping>
   <class name="Child" dynamic-update="false" dynamic-insert="false" 
      optimistic-lock="version" proxy="Child" table="Child">
      <cache usage="nonstrict-read-write" />
      <id name="childId" access="field" column="Child_id" 
         type="java.lang.Integer" unsaved-value="null">
         <generator class="native" />
      </id>
      <many-to-one name="parent" access="field" class="Parent" cascade="none" 
         outer-join="auto" not-null="false">
         <column name="Parent_id" not-null="true" sql-type="int" />
      </many-to-one>
      <property name="name" access="field" type="java.lang.String" 
         column="Name" length="64" not-null="true" />
   </class>
</hibernate-mapping>

hibernate.cfg.xml:

Code:

<?xml version="1.0" encoding="ISO-8859-1"?>
<!DOCTYPE hibernate-configuration PUBLIC
   "-//Hibernate/Hibernate Configuration DTD 2.0//EN"
   "http://hibernate.sourceforge.net/hibernate-configuration-2.0.dtd">
<hibernate-configuration>

   <session-factory>
      <!-- properties -->
      <property name="connection.driver_class"> 
         org.hsqldb.jdbcDriver</property>
      <property name="connection.url">jdbc:hsqldb:mem:test</property>
      <property name="connection.username">sa</property>
      <property name="connection.password"></property>
      <property name="dialect">net.sf.hibernate.dialect.HSQLDialect</property>
      <property name="show_sql">false</property>
      <property name="cache.provider_class"> 
         net.sf.ehcache.hibernate.Provider</property>
      <property name="max_fetch_depth">3</property>
      <property name="cache.use_query_cache">false</property>
      <!-- mapping files -->
      <mapping resource="Parent.hbm.xml"/>
      <mapping resource="Child.hbm.xml"/>
   </session-factory>

</hibernate-configuration>

ehcache.xml:

Code:

<ehcache>
   <!-- disk store -->
   <diskStore path="java.io.tmpdir" />
   <!-- default cache -->
   <defaultCache eternal="false" maxElementsInMemory="50000" 
      timeToIdleSeconds="600" timeToLiveSeconds="600" overflowToDisk="false" 
      />
   <!-- persistent object caches -->
   <cache name="Parent" maxElementsInMemory="50000" eternal="false" 
      timeToIdleSeconds="600" timeToLiveSeconds="600" overflowToDisk="false" 
      />
   <cache name="Child" maxElementsInMemory="50000" eternal="false" 
      timeToIdleSeconds="600" timeToLiveSeconds="600" overflowToDisk="false" 
      />
   <!-- persistent relation caches -->
   <cache name="Parent.children" maxElementsInMemory="50000" eternal="false" 
      timeToIdleSeconds="600" timeToLiveSeconds="600" overflowToDisk="false" 
      />
</ehcache>

Ville Peurala · **Posted:** Mon Oct 18, 2004 2:29 am

Since nobody has commented on this for almost a week, I will submit this to JIRA.
I am pretty sure that it is a bug. And if it isn't, at least this behaviour should be documented somewhere.
- Ville Peurala

Ville Peurala · **Posted:** Mon Oct 18, 2004 3:05 am

This is in JIRA now, with key HB-1267:
http://opensource.atlassian.com/project ... se/HB-1267

max · **Posted:** Mon Oct 18, 2004 4:53 am

Not a bug. Expected behavior.

Updated javadoc to explicitly mention that elements inside a collection is not guaranteed to be initialized.