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]