I am using hibernate 3.0.5 and discovered a problem with merging a detached bean which contains collections. While merging the collection the
CollectionEntry of the PersistenList is marked dirty even if the bean was not modified while detached.
(CollectionType.replaceElements() on line 393 calls result.clear() which, when target is a PersistentList, is setting its collectionEntry to dirty).
When flushing the session after merge() has finished DefaultEntityRefreshListener.isUpdateNecessary() line 292 to 305 is discovering these dirty marked collections and returns true even if
dirtyCheck() did not find modifications.
The result is, that the bean is written to the database each time it is reattached (merged). I discovered this because I used a versioned bean and the version number was incremented each time I merged the
unmodified bean.
I used the following stripped down example to demonstrate the behavour.
The example uses a SimpleNode bean, which contains a simple Text descriptor, references to its parent node and a list of child nodes (and of course the id, version and childIndex property).
For simplicity I cut out the getter/setter for the properties.
Code:
public class SimpleNode
{
private long id = 0;
private int version = 0;
private String descriptor = null;
private SimpleNode parent = null;
private List<SimpleNode> children = new ArrayList<SimpleNode>();
private int childIndex = -1;
public SimpleNode()
{
super();
}
... getters/setters for id,version, desriptor,parent,children and childIndex
public void addChild(SimpleNode child)
{
this.addChild(this.children.size(), child);
}
public void addChild(int index, SimpleNode child)
{
this.children.add(index, child);
child.setParent(this);
}
public SimpleNode removeChild(int index)
{
SimpleNode child = this.children.remove(index);
child.setParent(null);
return child;
}
public boolean removeChild(SimpleNode child)
{
boolean changed = this.children.remove(child);
if (changed) child.setParent(null);
return changed;
}
The following mapping is used:
Code:
<hibernate-mapping>
<class name="SimpleNode" table="TBL_SIMPLE_NODES">
<id name="id" type="long" column="SIMPLE_NODE_ID">
<generator class="native" />
</id>
<version name="version" type="integer"
column="SIMPLE_NODE_VERSION" />
<property name="descriptor" type="string"
column="SIMPLE_NODE_DESCRIPTOR" />
<many-to-one name="parent" class="SimpleNode"
column="SIMPLE_NODE_PARENT_ID"
not-null="false" unique="false" lazy="false"
cascade="save-update,persist,merge,evict,lock,replicate,refresh"/>
<property name="childIndex" type="integer"
column="SIMPLE_NODE_CHILD_INDEX" />
<list name="children" inverse="true"
cascade="all,delete-orphan" lazy="false" >
<key column="SIMPLE_NODE_PARENT_ID" />
<list-index column="SIMPLE_NODE_CHILD_INDEX" />
<one-to-many class="SimpleNode" />
</list>
</class>
</hibernate-mapping>
I am working with Spring and used the following DAO-Class
to handle the SimpleNode beans:
Code:
public class SimpleNodeDao
extends HibernateDaoSupport
{
public SimpleNode saveOrUpdate(SimpleNode node) {
SimpleNode returnNode = node;
if (node.getId() == 0) {
getHibernateTemplate().persist(node);
} else {
returnNode = (SimpleNode)getHibernateTemplate().merge(node);
}
return returnNode;
}
public SimpleNode loadById(long id) {
return (SimpleNode)getHibernateTemplate().load(SimpleNode.class, id);
}
public void flush() {
getHibernateTemplate().flush();
}
For those not knowing Spring the Spring HibernateTemplate does "only" the transaction and session handling (create a new transaction/session or join an existing transaction/session, commit on success, rollback on exception) and forwards the operation (merge()/persist()/load()) to the
HibernateSession.
To test the SimpleNodeDao I created the follwing JUnit-Test
which is derived from the Spring AbstractTransactionalSpringContextTests, which is creating a new
transaction/session for each UnitTest. To detach a bean I simply store it
in a static property at the end of UnitTest1 and reassociate it in the next
UnitTest (which uses a new session).
Code:
public class HierarchyTestCase
extends AbstractTransactionalSpringEnabledTestCase
{
private SimpleNodeDao simpleNodeDao = null;
public HierarchyTestCase()
{
super();
// do not rollback after test
this.setDefaultRollback(false);
}
public HierarchyTestCase(String name)
{
super(name);
// do not rollback after test
this.setDefaultRollback(false);
}
public void setSimpleNodeDao(SimpleNodeDao simpleNodeDao)
{
this.simpleNodeDao = simpleNodeDao;
}
private static SimpleNode staticNode1 = null;
public void testCreateParentChild()
{
SimpleNode parent = new SimpleNode();
parent.setDescriptor("Parent node");
SimpleNode child = new SimpleNode();
child.setDescriptor("Child node");
parent.addChild(child);
SimpleNode savedParent =
this.simpleNodeDao.saveOrUpdate(parent);
assertFalse("Parent id not generated", savedParent.getId() == 0);
SimpleNode savedChild = savedParent.getChildren().get(0);
assertFalse("Child id not generated", savedChild.getId() == 0);
// keep saved Node for next test (detach)
staticNode1 = savedParent;
}
public void testUpdateParentChild_noModification()
{
// use (now detached) bean from previous test
SimpleNode parent = staticNode1;
SimpleNode updatedParent =
this.simpleNodeDao.saveOrUpdate(parent);
SimpleNode updatedChild = updatedParent.getChildren().get(0);
assertTrue("Parent version is modified", updatedParent.getVersion() == 0);
assertTrue("Child version is modified", updatedChild.getVersion() == 0);
this.simpleNodeDao.flush();
assertTrue("Parent version is modified", updatedParent.getVersion() == 0);
assertTrue("Child version is modified", updatedChild.getVersion() == 0);
staticNode1 = updatedParent;
}
The first test simply creates and persists two Nodes with a parent/child relationship.
At the end the parent node (containing the child node) is saved to the static variable staticNode1 and is detached when the session is closed after the end of the first test.
In the next test the (now detached) bean hierarchy is simply merged again (without modification).
Now wether the parent nor the child should be modified (version still set to 0) but it is incremented after flushing() because of the behaviour I described above. The second version checks after flushing will fail.
(Should not the version be already incremented after the merge(), when the bean was really modified?).
Here is the log generated by the test:
[code]
=== Hibernate startup
2005-07-12 11:47:41,667 1151 INFO [main] org.hibernate.cfg.Environment - Hibernate 3.0.5
2005-07-12 11:47:41,667 1151 INFO [main] org.hibernate.cfg.Environment - loaded properties from resource hibernate.properties: {hibernate.cglib.use_reflection_optimizer=false}
2005-07-12 11:47:41,677 1161 INFO [main] org.hibernate.cfg.Environment - using JDK 1.4 java.sql.Timestamp handling
2005-07-12 11:47:41,848 1332 INFO [main] org.hibernate.cfg.Configuration - Mapping file: C:\daten\development\test\classes\SimpleNode.hbm.xml
2005-07-12 11:47:41,968 1452 DEBUG [main] org.hibernate.util.DTDEntityResolver - trying to locate http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd in classpath under org/hibernate/
2005-07-12 11:47:41,968 1452 DEBUG [main] org.hibernate.util.DTDEntityResolver - found http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd in classpath
2005-07-12 11:47:42,328 1812 INFO [main] org.hibernate.cfg.HbmBinder - Mapping class: SimpleNode -> TBL_SIMPLE_NODES
2005-07-12 11:47:42,338 1822 DEBUG [main] org.hibernate.cfg.HbmBinder - Mapped property: id -> SIMPLE_NODE_ID
2005-07-12 11:47:42,338 1822 DEBUG [main] org.hibernate.cfg.HbmBinder - Mapped property: version -> SIMPLE_NODE_VERSION
2005-07-12 11:47:42,488 1972 DEBUG [main] org.hibernate.cfg.HbmBinder - Mapped property: parent -> SIMPLE_NODE_PARENT_ID
2005-07-12 11:47:42,488 1972 DEBUG [main] org.hibernate.cfg.HbmBinder - Mapped property: childIndex -> SIMPLE_NODE_CHILD_INDEX
2005-07-12 11:47:42,498 1982 DEBUG [main] org.hibernate.cfg.HbmBinder - Mapped property: children
2005-07-12 11:47:42,498 1982 DEBUG [main] org.hibernate.cfg.HbmBinder - Mapped property: descriptor -> SIMPLE_NODE_DESCRIPTOR
2005-07-12 11:47:42,498 1982 INFO [main] org.springframework.orm.hibernate3.LocalSessionFactoryBean - Building new Hibernate SessionFactory
2005-07-12 11:47:42,498 1982 DEBUG [main] org.hibernate.cfg.Configuration - Preparing to build session factory with filters : {}
2005-07-12 11:47:42,498 1982 INFO [main] org.hibernate.cfg.Configuration - processing extends queue
2005-07-12 11:47:42,498 1982 INFO [main] org.hibernate.cfg.Configuration - processing collection mappings
2005-07-12 11:47:42,498 1982 DEBUG [main] org.hibernate.cfg.HbmBinder - Second pass for collection: SimpleNode.children
2005-07-12 11:47:42,498 1982 INFO [main] org.hibernate.cfg.HbmBinder - Mapping collection: SimpleNode.children -> TBL_SIMPLE_NODES
2005-07-12 11:47:42,498 1982 DEBUG [main] org.hibernate.cfg.HbmBinder - Mapped collection key: SIMPLE_NODE_PARENT_ID, index: SIMPLE_NODE_CHILD_INDEX, one-to-many: SimpleNode
2005-07-12 11:47:42,498 1982 INFO [main] org.hibernate.cfg.Configuration - processing association property references
2005-07-12 11:47:42,498 1982 INFO [main] org.hibernate.cfg.Configuration - processing foreign key constraints
2005-07-12 11:47:42,498 1982 DEBUG [main] org.hibernate.cfg.Configuration - resolving reference to class: SimpleNode
2005-07-12 11:47:42,508 1992 INFO [main] org.hibernate.connection.ConnectionProviderFactory - Initializing connection provider: org.springframework.orm.hibernate3.LocalDataSourceConnectionProvider
2005-07-12 11:47:43,450 2934 INFO [main] org.hibernate.cfg.SettingsFactory - RDBMS: PostgreSQL, version: 8.0.1
2005-07-12 11:47:43,450 2934 INFO [main] org.hibernate.cfg.SettingsFactory - JDBC driver: PostgreSQL Native Driver, version: PostgreSQL 8.0devel JDBC3 with SSL (build 309)
2005-07-12 11:47:43,490 2974 INFO [main] org.hibernate.dialect.Dialect - Using dialect: org.hibernate.dialect.PostgreSQLDialect
2005-07-12 11:47:43,500 2984 INFO [main] org.hibernate.transaction.TransactionFactoryFactory - Using default transaction strategy (direct JDBC transactions)
2005-07-12 11:47:43,500 2984 INFO [main] org.hibernate.transaction.TransactionManagerLookupFactory - No TransactionManagerLookup configured (in JTA environment, use of read-write or transactional second-level cache is not recommended)
2005-07-12 11:47:43,500 2984 INFO [main] org.hibernate.cfg.SettingsFactory - Automatic flush during beforeCompletion(): disabled
2005-07-12 11:47:43,500 2984 INFO [main] org.hibernate.cfg.SettingsFactory - Automatic session close at end of transaction: disabled
2005-07-12 11:47:43,500 2984 INFO [main] org.hibernate.cfg.SettingsFactory - JDBC batch size: 15
2005-07-12 11:47:43,500 2984 INFO [main] org.hibernate.cfg.SettingsFactory - JDBC batch updates for versioned data: disabled
2005-07-12 11:47:43,510 2994 INFO [main] org.hibernate.cfg.SettingsFactory - Scrollable result sets: enabled
2005-07-12 11:47:43,510 2994 DEBUG [main] org.hibernate.cfg.SettingsFactory - Wrap result sets: disabled
2005-07-12 11:47:43,510 2994 INFO [main] org.hibernate.cfg.SettingsFactory - JDBC3 getGeneratedKeys(): disabled
2005-07-12 11:47:43,510 2994 INFO [main] org.hibernate.cfg.SettingsFactory - Connection release mode: null
2005-07-12 11:47:43,510 2994 INFO [main] org.hibernate.cfg.SettingsFactory - Default batch fetch size: 1
2005-07-12 11:47:43,680 3164 INFO [main] org.hibernate.cfg.SettingsFactory - Generate SQL with comments: disabled
2005-07-12 11:47:43,680 3164 INFO [main] org.hibernate.cfg.SettingsFactory - Order SQL updates by primary key: disabled
2005-07-12 11:47:43,680 3164 INFO [main] org.hibernate.cfg.SettingsFactory - Query translator: org.hibernate.hql.ast.ASTQueryTranslatorFactory
2005-07-12 11:47:43,680 3164 INFO [main] org.hibernate.hql.ast.ASTQueryTranslatorFactory - Using ASTQueryTranslatorFactory
2005-07-12 11:47:43,680 3164 INFO [main] org.hibernate.cfg.SettingsFactory - Query language substitutions: {}
2005-07-12 11:47:43,680 3164 INFO [main] org.hibernate.cfg.SettingsFactory - Second-level cache: enabled
2005-07-12 11:47:43,680 3164 INFO [main] org.hibernate.cfg.SettingsFactory - Query cache: disabled
2005-07-12 11:47:43,680 3164 INFO [main] org.hibernate.cfg.SettingsFactory - Cache provider: org.hibernate.cache.EhCacheProvider
2005-07-12 11:47:43,680 3164 INFO [main] org.hibernate.cfg.SettingsFactory - Optimize cache for minimal puts: disabled
2005-07-12 11:47:43,680 3164 INFO [main] org.hibernate.cfg.SettingsFactory - Structured second-level cache entries: disabled
2005-07-12 11:47:43,680 3164 DEBUG [main] org.hibernate.exception.SQLExceptionConverterFactory - Using dialect defined converter
2005-07-12 11:47:43,690 3174 INFO [main] org.hibernate.cfg.SettingsFactory - Echoing all SQL to stdout
2005-07-12 11:47:43,690 3174 INFO [main] org.hibernate.cfg.SettingsFactory - Statistics: disabled
2005-07-12 11:47:43,690 3174 INFO [main] org.hibernate.cfg.SettingsFactory - Deleted entity synthetic identifier rollback: disabled
2005-07-12 11:47:43,690 3174 INFO [main] org.hibernate.cfg.SettingsFactory - Default entity-mode: pojo
2005-07-12 11:47:43,971 3455 INFO [main] org.hibernate.impl.SessionFactoryImpl - building session factory
2005-07-12 11:47:43,971 3455 DEBUG [main] org.hibernate.impl.SessionFactoryImpl - Session factory constructed with filter configurations : {}
2005-07-12 11:47:43,971 3455 DEBUG [main] org.hibernate.impl.SessionFactoryImpl - instantiating session factory with properties: {java.runtime.name=Java(TM) 2 Runtime Environment, Standard Edition, hibernate.cache.provider_class=org.hibernate.cache.EhCacheProvider, sun.boot.library.path=C:\Programme\Java\jdk1.5.0_04\jre\bin, java.vm.version=1.5.0_04-b05, java.vm.vendor=Sun Microsystems Inc., java.vendor.url=http://java.sun.com/, path.separator=;, java.vm.name=Java HotSpot(TM) Client VM, file.encoding.pkg=sun.io, user.country=CH, sun.os.patch.level=Service Pack 2, java.vm.specification.name=Java Virtual Machine Specification, user.dir=C:\daten\development\test, java.runtime.version=1.5.0_04-b05, java.awt.graphicsenv=sun.awt.Win32GraphicsEnvironment, java.endorsed.dirs=C:\Programme\Java\jdk1.5.0_04\jre\lib\endorsed, os.arch=x86, java.io.tmpdir=C:\DOKUME~1\mrt\LOKALE~1\Temp\, line.separator=
, java.vm.specification.vendor=Sun Microsystems Inc., user.variant=, os.name=Windows XP, sun.jnu.encoding=Cp1252, java.library.path=C:\Programme\Java\jdk1.5.0_04\bin;.;C:\windows\system32;C:\windows;C:\windows\system32;C:\windows;C:\windows\system32\wbem;C:\Programme\Java\jdk1.5.0_04\bin;C:\Programme\apache-ant-1.6.2\bin;C:\Programme\Apache Software Foundation\Maven 1.0.2\bin;c:\daten\mysql\bin;C:\Programme\PostgreSQL\8.0\bin, java.specification.name=Java Platform API Specification, java.class.version=49.0, sun.management.compiler=HotSpot Client Compiler, os.version=5.1, user.home=C:\Dokumente und Einstellungen\mrt, user.timezone=Europe/Berlin, java.awt.printerjob=sun.awt.windows.WPrinterJob, file.encoding=Cp1252, java.specification.version=1.5, user.name=mrt, java.class.path=C:\daten\development\classes;C:\daten\development\lib\dist\activation-1.0.2.jar;C:\daten\development\test\lib\dist\aopalliance-1.0.jar;C:\daten\development\test\lib\dist\cglib-nodep-2.1-dev.jar;C:\daten\development\test\lib\dist\commons-lang-2.0.jar;C:\daten\development\test\lib\dist\commons-logging-1.0.4.jar;C:\daten\development\test\lib\dist\ehcache-1.1.jar;C:\daten\development\test\lib\dist\log4j-1.2.9.jar;C:\daten\development\test\lib\dist\mail-1.3.2.jar;C:\daten\development\test\lib\dist\ojdbc14.jar;C:\daten\development\test\lib\dist\postgresql-8.0.309.jdbc3.jar;C:\daten\development\test\lib\build\junit-3.8.1.jar;C:\daten\development\test\lib\build\servlet-api-2.4.jar;C:\daten\development\test\lib\build\antspringfactory.jar;C:\daten\development\test\lib\build\ognl-2.6.7.jar;C:\daten\development\test\lib\dist\commons-collections-3.1.jar;C:\daten\development\test\lib\dist\commons-dbcp-1.2.1.jar;C:\daten\development\test\lib\dist\commons-pool-1.2.jar;C:\daten\development\test\lib\dist\jta.jar;C:\daten\development\test\lib\dist\odmg-3.0.jar;C:\daten\development\test\lib\dist\commons-codec-1.3.jar;C:\daten\development\test\lib\dist\jotm-2.0.8.jar;C:\daten\development\test\lib\build\axis-ant-1.2.jar;C:\daten\development\test\lib\dist\acegi-security-0.8.2.jar;C:\daten\development\test\lib\dist\axis-1.2.jar;C:\daten\development\test\lib\dist\dom4j-1.6.jar;C:\daten\development\test\lib\dist\jaxrpc-1.1.jar;C:\daten\development\test\lib\dist\saaj-1.2.jar;C:\daten\development\test\lib\dist\wsdl4j-1.5.1.jar;C:\daten\development\test\lib\dist\xerces-2.6.2.jar;C:\daten\development\test\lib\dist\hibernate-3.0.5.jar;C:\daten\development\test\lib\dist\antlr-2.7.5.jar;C:\daten\development\test\lib\dist\spring-framework-1.2.2.jar;C:\daten\development\test\lib\build\spring-mock-1.2.2.jar;/c:/Programme/eclipse/plugins/org.eclipse.jdt.junit_3.1.0/junitsupport.jar;/c:/Programme/eclipse/plugins/org.eclipse.jdt.junit.runtime_3.1.0/junitruntime.jar, hibernate.show_sql=true, java.vm.specification.version=1.0, java.home=C:\Programme\Java\jdk1.5.0_04\jre, sun.arch.data.model=32, hibernate.dialect=org.hibernate.dialect.PostgreSQLDialect, user.language=de, java.specification.vendor=Sun Microsystems Inc., awt.toolkit=sun.awt.windows.WToolkit, hibernate.cglib.use_reflection_optimizer=false, java.vm.info=mixed mode, sharing, java.version=1.5.0_04, java.ext.dirs=C:\Programme\Java\jdk1.5.0_04\jre\lib\ext, sun.boot.class.path=C:\Programme\Java\jdk1.5.0_04\jre\lib\rt.jar;C:\Programme\Java\jdk1.5.0_04\jre\lib\i18n.jar;C:\Programme\Java\jdk1.5.0_04\jre\lib\sunrsasign.jar;C:\Programme\Java\jdk1.5.0_04\jre\lib\jsse.jar;C:\Programme\Java\jdk1.5.0_04\jre\lib\jce.jar;C:\Programme\Java\jdk1.5.0_04\jre\lib\charsets.jar;C:\Programme\Java\jdk1.5.0_04\jre\classes, java.vendor=Sun Microsystems Inc., file.separator=\, hibernate.connection.provider_class=org.springframework.orm.hibernate3.LocalDataSourceConnectionProvider, java.vendor.url.bug=http://java.sun.com/cgi-bin/bugreport.cgi, sun.io.unicode.encoding=UnicodeLittle, sun.cpu.endian=little, sun.desktop=windows, sun.cpu.isalist=}
2005-07-12 11:47:43,991 3475 WARN [main] net.sf.ehcache.config.Configurator - No configuration found. Configuring ehcache from ehcache-failsafe.xml found in the classpath: jar:file:/C:/daten/development/test/lib/dist/ehcache-1.1.jar!/ehcache-failsafe.xml
2005-07-12 11:47:44,561 4045 DEBUG [main] org.hibernate.persister.entity.BasicEntityPersister - Static SQL for entity: SimpleNode
2005-07-12 11:47:44,561 4045 DEBUG [main] org.hibernate.persister.entity.BasicEntityPersister - Version select: select SIMPLE_NODE_VERSION from TBL_SIMPLE_NODES where SIMPLE_NODE_ID =?
2005-07-12 11:47:44,561 4045 DEBUG [main] org.hibernate.persister.entity.BasicEntityPersister - Snapshot select: select simplenode_.SIMPLE_NODE_ID, simplenode_.SIMPLE_NODE_VERSION as SIMPLE2_0_, simplenode_.SIMPLE_NODE_PARENT_ID as SIMPLE3_0_, simplenode_.SIMPLE_NODE_CHILD_INDEX as SIMPLE4_0_, simplenode_.SIMPLE_NODE_DESCRIPTOR as SIMPLE5_0_ from TBL_SIMPLE_NODES simplenode_ where simplenode_.SIMPLE_NODE_ID=?
2005-07-12 11:47:44,561 4045 DEBUG [main] org.hibernate.persister.entity.BasicEntityPersister - Insert 0: insert into TBL_SIMPLE_NODES (SIMPLE_NODE_VERSION, SIMPLE_NODE_PARENT_ID, SIMPLE_NODE_CHILD_INDEX, SIMPLE_NODE_DESCRIPTOR, SIMPLE_NODE_ID) values (?, ?, ?, ?, ?)
2005-07-12 11:47:44,561 4045 DEBUG [main] org.hibernate.persister.entity.BasicEntityPersister - Update 0: update TBL_SIMPLE_NODES set SIMPLE_NODE_VERSION=?, SIMPLE_NODE_PARENT_ID=?, SIMPLE_NODE_CHILD_INDEX=?, SIMPLE_NODE_DESCRIPTOR=? where SIMPLE_NODE_ID=? and SIMPLE_NODE_VERSION=?
2005-07-12 11:47:44,561 4045 DEBUG [main] org.hibernate.persister.entity.BasicEntityPersister - Delete 0: delete from TBL_SIMPLE_NODES where SIMPLE_NODE_ID=? and SIMPLE_NODE_VERSION=?
2005-07-12 11:47:44,571 4055 DEBUG [main] org.hibernate.persister.collection.AbstractCollectionPersister - Static SQL for collection: SimpleNode.children
2005-07-12 11:47:44,571 4055 DEBUG [main] org.hibernate.persister.collection.AbstractCollectionPersister - Row insert: update TBL_SIMPLE_NODES set SIMPLE_NODE_PARENT_ID=?, SIMPLE_NODE_CHILD_INDEX=? where SIMPLE_NODE_ID=?
2005-07-12 11:47:44,571 4055 DEBUG [main] org.hibernate.persister.collection.AbstractCollectionPersister - Row delete: update TBL_SIMPLE_NODES set SIMPLE_NODE_PARENT_ID=null, SIMPLE_NODE_CHILD_INDEX=null where SIMPLE_NODE_PARENT_ID=? and SIMPLE_NODE_ID=?
2005-07-12 11:47:44,571 4055 DEBUG [main] org.hibernate.persister.collection.AbstractCollectionPersister - One-shot delete: update TBL_SIMPLE_NODES set SIMPLE_NODE_PARENT_ID=null, SIMPLE_NODE_CHILD_INDEX=null where SIMPLE_NODE_PARENT_ID=?
2005-07-12 11:47:44,621 4105 DEBUG [main] org.hibernate.loader.entity.EntityLoader - Static select for entity SimpleNode: select simplenode0_.SIMPLE_NODE_ID as SIMPLE1_0_, simplenode0_.SIMPLE_NODE_VERSION as SIMPLE2_0_0_, simplenode0_.SIMPLE_NODE_PARENT_ID as SIMPLE3_0_0_, simplenode0_.SIMPLE_NODE_CHILD_INDEX as SIMPLE4_0_0_, simplenode0_.SIMPLE_NODE_DESCRIPTOR as SIMPLE5_0_0_ from TBL_SIMPLE_NODES simplenode0_ where simplenode0_.SIMPLE_NODE_ID=?
2005-07-12 11:47:44,621 4105 DEBUG [main] org.hibernate.loader.entity.EntityLoader - Static select for entity SimpleNode: select simplenode0_.SIMPLE_NODE_ID as SIMPLE1_0_, simplenode0_.SIMPLE_NODE_VERSION as SIMPLE2_0_0_, simplenode0_.SIMPLE_NODE_PARENT_ID as SIMPLE3_0_0_, simplenode0_.SIMPLE_NODE_CHILD_INDEX as SIMPLE4_0_0_, simplenode0_.SIMPLE_NODE_DESCRIPTOR as SIMPLE5_0_0_ from TBL_SIMPLE_NODES simplenode0_ where simplenode0_.SIMPLE_NODE_ID=?
2005-07-12 11:47:44,632 4116 DEBUG [main] org.hibernate.loader.entity.EntityLoader - Static select for entity SimpleNode: select simplenode0_.SIMPLE_NODE_ID as SIMPLE1_0_, simplenode0_.SIMPLE_NODE_VERSION as SIMPLE2_0_0_, simplenode0_.SIMPLE_NODE_PARENT_ID as SIMPLE3_0_0_, simplenode0_.SIMPLE_NODE_CHILD_INDEX as SIMPLE4_0_0_, simplenode0_.SIMPLE_NODE_DESCRIPTOR as SIMPLE5_0_0_ from TBL_SIMPLE_NODES simplenode0_ where simplenode0_.SIMPLE_NODE_ID=? for update
2005-07-12 11:47:44,632 4116 DEBUG [main] org.hibernate.loader.entity.EntityLoader - Static select for entity SimpleNode: select simplenode0_.SIMPLE_NODE_ID as SIMPLE1_0_, simplenode0_.SIMPLE_NODE_VERSION as SIMPLE2_0_0_, simplenode0_.SIMPLE_NODE_PARENT_ID as SIMPLE3_0_0_, simplenode0_.SIMPLE_NODE_CHILD_INDEX as SIMPLE4_0_0_, simplenode0_.SIMPLE_NODE_DESCRIPTOR as SIMPLE5_0_0_ from TBL_SIMPLE_NODES simplenode0_ where simplenode0_.SIMPLE_NODE_ID=? for update
2005-07-12 11:47:44,642 4126 DEBUG [main] org.hibernate.loader.collection.OneToManyLoader - Static select for one-to-many SimpleNode.children: select children0_.SIMPLE_NODE_PARENT_ID as SIMPLE3_1_, children0_.SIMPLE_NODE_ID as SIMPLE1_1_, children0_.SIMPLE_NODE_CHILD_INDEX as SIMPLE4_1_, children0_.SIMPLE_NODE_ID as SIMPLE1_0_, children0_.SIMPLE_NODE_VERSION as SIMPLE2_0_0_, children0_.SIMPLE_NODE_PARENT_ID as SIMPLE3_0_0_, children0_.SIMPLE_NODE_CHILD_INDEX as SIMPLE4_0_0_, children0_.SIMPLE_NODE_DESCRIPTOR as SIMPLE5_0_0_ from TBL_SIMPLE_NODES children0_ where children0_.SIMPLE_NODE_PARENT_ID=?
2005-07-12 11:47:44,652 4136 DEBUG [main] org.hibernate.impl.SessionFactoryObjectFactory - initializing class SessionFactoryObjectFactory
2005-07-12 11:47:44,652 4136 DEBUG [main] org.hibernate.impl.SessionFactoryObjectFactory - registered: 40288ee9050a715401050a7158820000 (unnamed)
2005-07-12 11:47:44,652 4136 INFO [main] org.hibernate.impl.SessionFactoryObjectFactory - Not binding factory to JNDI, no JNDI name configured
2005-07-12 11:47:44,652 4136 DEBUG [main] org.hibernate.impl.SessionFactoryImpl - instantiated session factory
2005-07-12 11:47:44,652 4136 INFO [main] org.hibernate.impl.SessionFactoryImpl - Checking 0 named queries
2005-07-12 11:47:44,892 4376 INFO [main] org.springframework.beans.factory.support.DefaultListableBeanFactory - Creating shared instance of singleton bean 'transactionManager'
2005-07-12 11:47:44,932 4416 INFO [main] org.springframework.orm.hibernate3.HibernateTransactionManager - Using DataSource [org.apache.commons.dbcp.BasicDataSource@16c79d7] of Hibernate SessionFactory for HibernateTransactionManager
2005-07-12 11:47:44,932 4416 INFO [main] org.springframework.beans.factory.support.DefaultListableBeanFactory - Creating shared instance of singleton bean 'simpleNodeDao'
2005-07-12 11:47:44,982 4466 INFO [main] org.springframework.jdbc.datasource.JdbcTransactionObjectSupport - JDBC 3.0 Savepoint class is available
=== Begin of Unit Test 1 (testCreateParentChild)
2005-07-12 11:47:46,074 5558 DEBUG [main] org.hibernate.impl.SessionImpl - opened session at timestamp: 4592278184239104
2005-07-12 11:47:46,074 5558 DEBUG [main] org.hibernate.jdbc.ConnectionManager - opening JDBC connection
2005-07-12 11:47:46,074 5558 DEBUG [main] org.hibernate.transaction.JDBCTransaction - begin
2005-07-12 11:47:46,074 5558 DEBUG [main] org.hibernate.transaction.JDBCTransaction - current autocommit status: true
2005-07-12 11:47:46,074 5558 DEBUG [main] org.hibernate.transaction.JDBCTransaction - disabling autocommit
2005-07-12 11:47:46,074 5558 INFO [main] HierarchyTestCase - Began transaction: transaction manager [org.springframework.orm.hibernate3.HibernateTransactionManager@17f409c]; defaultCommit true
2005-07-12 11:47:46,074 5558 DEBUG [main] org.hibernate.engine.Cascades - version unsaved-value strategy UNDEFINED
2005-07-12 11:47:46,074 5558 DEBUG [main] org.hibernate.engine.Cascades - id unsaved-value: 0
2005-07-12 11:47:46,074 5558 DEBUG [main] org.hibernate.event.def.AbstractSaveEventListener - transient instance of: SimpleNode
2005-07-12 11:47:46,074 5558 DEBUG [main] org.hibernate.event.def.DefaultPersistEventListener - saving transient instance
2005-07-12 11:47:46,074 5558 DEBUG [main] org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2005-07-12 11:47:46,074 5558 DEBUG [main] org.hibernate.SQL - select nextval ('simple_node_sequence')
Hibernate: select nextval ('simple_node_sequence')
2005-07-12 11:47:46,074 5558 DEBUG [main] org.hibernate.jdbc.AbstractBatcher - preparing statement
2005-07-12 11:47:46,074 5558 DEBUG [main] org.hibernate.id.SequenceGenerator - Sequence identifier generated: 52
2005-07-12 11:47:46,074 5558 DEBUG [main] org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2005-07-12 11:47:46,074 5558 DEBUG [main] org.hibernate.jdbc.AbstractBatcher - closing statement
2005-07-12 11:47:46,074 5558 DEBUG [main] org.hibernate.event.def.AbstractSaveEventListener - generated identifier: 52, using strategy: org.hibernate.id.SequenceGenerator
2005-07-12 11:47:46,074 5558 DEBUG [main] org.hibernate.event.def.AbstractSaveEventListener - saving [SimpleNode#52]
2005-07-12 11:47:46,074 5558 DEBUG [main] org.hibernate.engine.Cascades - processing cascade ACTION_PERSIST for: SimpleNode
2005-07-12 11:47:46,074 5558 DEBUG [main] org.hibernate.engine.Cascades - done processing cascade ACTION_PERSIST for: SimpleNode
2005-07-12 11:47:46,074 5558 DEBUG [main] org.hibernate.engine.Versioning - using initial version: 0
2005-07-12 11:47:46,074 5558 DEBUG [main] org.hibernate.event.def.WrapVisitor - Wrapped collection in role: SimpleNode.children
2005-07-12 11:47:46,074 5558 DEBUG [main] org.hibernate.engine.Cascades - processing cascade ACTION_PERSIST for: SimpleNode
2005-07-12 11:47:46,164 5648 DEBUG [main] org.hibernate.engine.Cascades - cascade ACTION_PERSIST for collection: SimpleNode.children
2005-07-12 11:47:46,164 5648 DEBUG [main] org.hibernate.engine.Cascades - cascading to persist: SimpleNode
2005-07-12 11:47:46,164 5648 DEBUG [main] org.hibernate.engine.Cascades - version unsaved-value strategy UNDEFINED
2005-07-12 11:47:46,164 5648 DEBUG [main] org.hibernate.engine.Cascades - id unsaved-value: 0
2005-07-12 11:47:46,164 5648 DEBUG [main] org.hibernate.event.def.AbstractSaveEventListener - transient instance of: SimpleNode
2005-07-12 11:47:46,164 5648 DEBUG [main] org.hibernate.event.def.DefaultPersistEventListener - saving transient instance
2005-07-12 11:47:46,164 5648 DEBUG [main] org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2005-07-12 11:47:46,164 5648 DEBUG [main] org.hibernate.SQL - select nextval ('simple_node_sequence')
Hibernate: select nextval ('simple_node_sequence')
2005-07-12 11:47:46,164 5648 DEBUG [main] org.hibernate.jdbc.AbstractBatcher - preparing statement
2005-07-12 11:47:46,174 5658 DEBUG [main] org.hibernate.id.SequenceGenerator - Sequence identifier generated: 53
2005-07-12 11:47:46,174 5658 DEBUG [main] org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2005-07-12 11:47:46,174 5658 DEBUG [main] org.hibernate.jdbc.AbstractBatcher - closing statement
2005-07-12 11:47:46,174 5658 DEBUG [main] org.hibernate.event.def.AbstractSaveEventListener - generated identifier: 53, using strategy: org.hibernate.id.SequenceGenerator
2005-07-12 11:47:46,174 5658 DEBUG [main] org.hibernate.event.def.AbstractSaveEventListener - saving [SimpleNode#53]
2005-07-12 11:47:46,174 5658 DEBUG [main] org.hibernate.engine.Cascades - processing cascade ACTION_PERSIST for: SimpleNode
2005-07-12 11:47:46,174 5658 DEBUG [main] org.hibernate.engine.Cascades - cascading to persist: SimpleNode
2005-07-12 11:47:46,174 5658 DEBUG [main] org.hibernate.event.def.AbstractSaveEventListener - persistent instance of: SimpleNode
2005-07-12 11:47:46,174 5658 DEBUG [main] org.hibernate.event.def.DefaultPersistEventListener - ignoring persistent instance
2005-07-12 11:47:46,174 5658 DEBUG [main] org.hibernate.engine.Cascades - done processing cascade ACTION_PERSIST for: SimpleNode
2005-07-12 11:47:46,174 5658 DEBUG [main] org.hibernate.engine.Versioning - using initial version: 0
2005-07-12 11:47:46,174 5658 DEBUG [main] org.hibernate.event.def.WrapVisitor - Wrapped collection in role: SimpleNode.children
2005-07-12 11:47:46,174 5658 DEBUG [main] org.hibernate.engine.Cascades - processing cascade ACTION_PERSIST for: SimpleNode
2005-07-12 11:47:46,174 5658 DEBUG [main] org.hibernate.engine.Cascades - cascade ACTION_PERSIST for collection: SimpleNode.children
2005-07-12 11:47:46,174 5658 DEBUG [main] org.hibernate.engine.Cascades - done cascade ACTION_PERSIST for collection: SimpleNode.children
2005-07-12 11:47:46,174 5658 DEBUG [main] org.hibernate.engine.Cascades - done processing cascade ACTION_PERSIST for: SimpleNode
2005-07-12 11:47:46,174 5658 DEBUG [main] org.hibernate.engine.Cascades - done cascade ACTION_PERSIST for collection: SimpleNode.children
2005-07-12 11:47:46,174 5658 DEBUG [main] org.hibernate.engine.Cascades - done processing cascade ACTION_PERSIST for: SimpleNode
2005-07-12 11:47:46,174 5658 DEBUG [main] org.hibernate.transaction.JDBCTransaction - commit
2005-07-12 11:47:46,174 5658 DEBUG [main] org.hibernate.impl.SessionImpl - automatically flushing session
2005-07-12 11:47:46,174 5658 DEBUG [main] org.hibernate.event.def.AbstractFlushingEventListener - flushing session
2005-07-12 11:47:46,174 5658 DEBUG [main] org.hibernate.event.def.AbstractFlushingEventListener - processing flush-time cascades
2005-07-12 11:47:46,174 5658 DEBUG [main] org.hibernate.engine.Cascades - processing cascade ACTION_SAVE_UPDATE for: SimpleNode
2005-07-12 11:47:46,174 5658 DEBUG [main] org.hibernate.engine.Cascades - cascade ACTION_SAVE_UPDATE for collection: SimpleNode.children
2005-07-12 11:47:46,174 5658 DEBUG [main] org.hibernate.engine.Cascades - cascading to saveOrUpdate: SimpleNode
2005-07-12 11:47:46,174 5658 DEBUG [main] org.hibernate.event.def.AbstractSaveEventListener - persistent instance of: SimpleNode
2005-07-12 11:47:46,174 5658 DEBUG [main] org.hibernate.event.def.DefaultSaveOrUpdateEventListener - ignoring persistent instance
2005-07-12 11:47:46,174 5658 DEBUG [main] org.hibernate.event.def.DefaultSaveOrUpdateEventListener - object already associated with session: [SimpleNode#53]
2005-07-12 11:47:46,174 5658 DEBUG [main] org.hibernate.engine.Cascades - done cascade ACTION_SAVE_UPDATE for collection: SimpleNode.children
2005-07-12 11:47:46,174 5658 DEBUG [main] org.hibernate.engine.Cascades - deleting orphans for collection: SimpleNode.children
2005-07-12 11:47:46,184 5668 DEBUG [main] org.hibernate.engine.Cascades - done deleting orphans for collection: SimpleNode.children
2005-07-12 11:47:46,184 5668 DEBUG [main] org.hibernate.engine.Cascades - done processing cascade ACTION_SAVE_UPDATE for: SimpleNode
2005-07-12 11:47:46,184 5668 DEBUG [main] org.hibernate.engine.Cascades - processing cascade ACTION_SAVE_UPDATE for: SimpleNode
2005-07-12 11:47:46,184 5668 DEBUG [main] org.hibernate.engine.Cascades - cascading to saveOrUpdate: SimpleNode
2005-07-12 11:47:46,184 5668 DEBUG [main] org.hibernate.event.def.AbstractSaveEventListener - persistent instance of: SimpleNode
2005-07-12 11:47:46,184 5668 DEBUG [main] org.hibernate.event.def.DefaultSaveOrUpdateEventListener - ignoring persistent instance
2005-07-12 11:47:46,184 5668 DEBUG [main] org.hibernate.event.def.DefaultSaveOrUpdateEventListener - object already associated with session: [SimpleNode#52]
2005-07-12 11:47:46,184 5668 DEBUG [main] org.hibernate.engine.Cascades - cascade ACTION_SAVE_UPDATE for collection: SimpleNode.children
2005-07-12 11:47:46,184 5668 DEBUG [main] org.hibernate.engine.Cascades - done cascade ACTION_SAVE_UPDATE for collection: SimpleNode.children
2005-07-12 11:47:46,184 5668 DEBUG [main] org.hibernate.engine.Cascades - deleting orphans for collection: SimpleNode.children
2005-07-12 11:47:46,184 5668 DEBUG [main] org.hibernate.engine.Cascades - done deleting orphans for collection: SimpleNode.children
2005-07-12 11:47:46,184 5668 DEBUG [main] org.hibernate.engine.Cascades - done processing cascade ACTION_SAVE_UPDATE for: SimpleNode
2005-07-12 11:47:46,184 5668 DEBUG [main] org.hibernate.event.def.AbstractFlushingEventListener - dirty checking collections
2005-07-12 11:47:46,184 5668 DEBUG [main] org.hibernate.event.def.AbstractFlushingEventListener - Flushing entities and processing referenced collections
2005-07-12 11:47:46,184 5668 DEBUG [main] org.hibernate.engine.Collections - Collection found: [SimpleNode.children#52], was: [<unreferenced>] (initialized)
2005-07-12 11:47:46,184 5668 DEBUG [main] org.hibernate.engine.Collections - Collection found: [SimpleNode.children#53], was: [<unreferenced>] (initialized)
2005-07-12 11:47:46,194 5678 DEBUG [main] org.hibernate.event.def.AbstractFlushingEventListener - Processing unreferenced collections
2005-07-12 11:47:46,194 5678 DEBUG [main] org.hibernate.event.def.AbstractFlushingEventListener - Scheduling collection removes/(re)creates/updates
2005-07-12 11:47:46,194 5678 DEBUG [main] org.hibernate.event.def.AbstractFlushingEventListener - Flushed: 2 insertions, 0 updates, 0 deletions to 2 objects
2005-07-12 11:47:46,194 5678 DEBUG [main] org.hibernate.event.def.AbstractFlushingEventListener - Flushed: 2 (re)creations, 0 updates, 0 removals to 2 collections
2005-07-12 11:47:46,194 5678 DEBUG [main] org.hibernate.pretty.Printer - listing entities:
2005-07-12 11:47:46,194 5678 DEBUG [main] org.hibernate.pretty.Printer - SimpleNode{childIndex=0, descriptor=Parent node, children=[SimpleNode#53], parent=null, id=52, version=0}
2005-07-12 11:47:46,194 5678 DEBUG [main] org.hibernate.pretty.Printer - SimpleNode{childIndex=0, descriptor=Child node, children=[], parent=SimpleNode#52, id=53, version=0}
2005-07-12 11:47:46,194 5678 DEBUG [main] org.hibernate.event.def.AbstractFlushingEventListener - executing flush
2005-07-12 11:47:46,194 5678 DEBUG [main] org.hibernate.persister.entity.BasicEntityPersister - Inserting entity: [SimpleNode#52]
2005-07-12 11:47:46,194 5678 DEBUG [main] org.hibernate.persister.entity.BasicEntityPersister - Version: 0
2005-07-12 11:47:46,194 5678 DEBUG [main] org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2005-07-12 11:47:46,194 5678 DEBUG [main] org.hibernate.SQL - insert into TBL_SIMPLE_NODES (SIMPLE_NODE_VERSION, SIMPLE_NODE_PARENT_ID, SIMPLE_NODE_CHILD_INDEX, SIMPLE_NODE_DESCRIPTOR, SIMPLE_NODE_ID) values (?, ?, ?, ?, ?)
Hibernate: insert into TBL_SIMPLE_NODES (SIMPLE_NODE_VERSION, SIMPLE_NODE_PARENT_ID, SIMPLE_NODE_CHILD_INDEX, SIMPLE_NODE_DESCRIPTOR, SIMPLE_NODE_ID) values (?, ?, ?, ?, ?)
2005-07-12 11:47:46,194 5678 DEBUG [main] org.hibernate.jdbc.AbstractBatcher - preparing statement
2005-07-12 11:47:46,194 5678 DEBUG [main] org.hibernate.persister.entity.BasicEntityPersister - Dehydrating entity: [SimpleNode#52]
2005-07-12 11:47:46,194 5678 DEBUG [main] org.hibernate.type.IntegerType - binding '0' to parameter: 1
2005-07-12 11:47:46,194 5678 DEBUG [main] org.hibernate.type.LongType - binding null to parameter: 2
2005-07-12 11:47:46,194 5678 DEBUG [main] org.hibernate.type.IntegerType - binding '0' to parameter: 3
2005-07-12 11:47:46,194 5678 DEBUG [main] org.hibernate.type.StringType - binding 'Parent node' to parameter: 4
2005-07-12 11:47:46,194 5678 DEBUG [main] org.hibernate.type.LongType - binding '52' to parameter: 5
2005-07-12 11:47:46,194 5678 DEBUG [main] org.hibernate.jdbc.AbstractBatcher - Adding to batch
2005-07-12 11:47:46,194 5678 DEBUG [main] org.hibernate.persister.entity.BasicEntityPersister - Inserting entity: [SimpleNode#53]
2005-07-12 11:47:46,194 5678 DEBUG [main] org.hibernate.persister.entity.BasicEntityPersister - Version: 0
2005-07-12 11:47:46,194 5678 DEBUG [main] org.hibernate.jdbc.AbstractBatcher - reusing prepared statement
2005-07-12 11:47:46,194 5678 DEBUG [main] org.hibernate.SQL - insert into TBL_SIMPLE_NODES (SIMPLE_NODE_VERSION, SIMPLE_NODE_PARENT_ID, SIMPLE_NODE_CHILD_INDEX, SIMPLE_NODE_DESCRIPTOR, SIMPLE_NODE_ID) values (?, ?, ?, ?, ?)
Hibernate: insert into TBL_SIMPLE_NODES (SIMPLE_NODE_VERSION, SIMPLE_NODE_PARENT_ID, SIMPLE_NODE_CHILD_INDEX, SIMPLE_NODE_DESCRIPTOR, SIMPLE_NODE_ID) values (?, ?, ?, ?, ?)
2005-07-12 11:47:46,194 5678 DEBUG [main] org.hibernate.persister.entity.BasicEntityPersister - Dehydrating entity: [SimpleNode#53]
2005-07-12 11:47:46,194 5678 DEBUG [main] org.hibernate.type.IntegerType - binding '0' to parameter: 1
2005-07-12 11:47:46,194 5678 DEBUG [main] org.hibernate.type.LongType - binding '52' to parameter: 2
2005-07-12 11:47:46,194 5678 DEBUG [main] org.hibernate.type.IntegerType - binding '0' to parameter: 3
2005-07-12 11:47:46,204 5688 DEBUG [main] org.hibernate.type.StringType - binding 'Child node' to parameter: 4
2005-07-12 11:47:46,204 5688 DEBUG [main] org.hibernate.type.LongType - binding '53' to parameter: 5
2005-07-12 11:47:46,204 5688 DEBUG [main] org.hibernate.jdbc.AbstractBatcher - Adding to batch
2005-07-12 11:47:46,204 5688 DEBUG [main] org.hibernate.jdbc.AbstractBatcher - Executing batch size: 2
2005-07-12 11:47:46,204 5688 DEBUG [main] org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2005-07-12 11:47:46,204 5688 DEBUG [main] org.hibernate.jdbc.AbstractBatcher - closing statement
2005-07-12 11:47:46,204 5688 DEBUG [main] org.hibernate.event.def.AbstractFlushingEventListener - post flush
2005-07-12 11:47:46,204 5688 DEBUG [main] org.hibernate.jdbc.JDBCContext - before transaction completion
2005-07-12 11:47:46,204 5688 DEBUG [main] org.hibernate.impl.SessionImpl - before transaction completion
2005-07-12 11:47:46,204 5688 DEBUG [main] org.hibernate.transaction.JDBCTransaction - re-enabling autocommit
2005-07-12 11:47:46,204 5688 DEBUG [main] org.hibernate.transaction.JDBCTransaction - committed JDBC Connection
2005-07-12 11:47:46,204 5688 DEBUG [main] org.hibernate.jdbc.JDBCContext - after transaction completion
2005-07-12 11:47:46,204 5688 DEBUG [main] org.hibernate.impl.SessionImpl - after transaction completion
2005-07-12 11:47:46,204 5688 DEBUG [main] org.hibernate.impl.SessionImpl - closing session
2005-07-12 11:47:46,204 5688 DEBUG [main] org.hibernate.jdbc.ConnectionManager - closing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2005-07-12 11:47:46,204 5688 DEBUG [main] org.hibernate.jdbc.JDBCContext - after transaction completion
2005-07-12 11:47:46,204 5688 DEBUG [main] org.hibernate.impl.SessionImpl - after transaction completion
2005-07-12 11:47:46,204 5688 INFO [main] HierarchyTestCase - Committed transaction after test execution
=== Begin of UnitTest 2 (testUpdateParentChild_noModification)
2005-07-12 11:47:46,224 5708 DEBUG [main] org.hibernate.impl.SessionImpl - opened session at timestamp: 4592278184853504
2005-07-12 11:47:46,324 5808 DEBUG [main] org.hibernate.jdbc.ConnectionManager - opening JDBC connection
2005-07-12 11:47:46,324 5808 DEBUG [main] org.hibernate.transaction.JDBCTransaction - begin
2005-07-12 11:47:46,324 5808 DEBUG [main] org.hibernate.transaction.JDBCTransaction - current autocommit status: true
2005-07-12 11:47:46,324 5808 DEBUG [main] org.hibernate.transaction.JDBCTransaction - disabling autocommit
2005-07-12 11:47:46,324 5808 INFO [main] HierarchyTestCase - Began transaction: transaction manager [org.springframework.orm.hibernate3.HibernateTransactionManager@17f409c]; defaultCommit true
2005-07-12 11:47:46,334 5818 DEBUG [main] org.hibernate.engine.Cascades - version unsaved-value strategy UNDEFINED
2005-07-12 11:47:46,334 5818 DEBUG [main] org.hibernate.engine.Cascades - id unsaved-value: 0
2005-07-12 11:47:46,334 5818 DEBUG [main] org.hibernate.event.def.AbstractSaveEventListener - detached instance of: SimpleNode
2005-07-12 11:47:46,344 5828 DEBUG [main] org.hibernate.event.def.DefaultMergeEventListener - merging detached instance
2005-07-12 11:47:46,344 5828 DEBUG [main] org.hibernate.event.def.DefaultLoadEventListener - loading entity: [SimpleNode#52]
2005-07-12 11:47:46,344 5828 DEBUG [main] org.hibernate.event.def.DefaultLoadEventListener - attempting to resolve: [SimpleNode#52]
2005-07-12 11:47:46,344 5828 DEBUG [main] org.hibernate.event.def.DefaultLoadEventListener - object not resolved in any cache: [SimpleNode#52]
2005-07-12 11:47:46,344 5828 DEBUG [main] org.hibernate.persister.entity.BasicEntityPersister - Materializing entity: [SimpleNode#52]
2005-07-12 11:47:46,344 5828 DEBUG [main] org.hibernate.loader.Loader - loading entity: [SimpleNode#52]
2005-07-12 11:47:46,344 5828 DEBUG [main] org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2005-07-12 11:47:46,344 5828 DEBUG [main] org.hibernate.SQL - select simplenode0_.SIMPLE_NODE_ID as SIMPLE1_0_, simplenode0_.SIMPLE_NODE_VERSION as SIMPLE2_0_0_, simplenode0_.SIMPLE_NODE_PARENT_ID as SIMPLE3_0_0_, simplenode0_.SIMPLE_NODE_CHILD_INDEX as SIMPLE4_0_0_, simplenode0_.SIMPLE_NODE_DESCRIPTOR as SIMPLE5_0_0_ from TBL_SIMPLE_NODES simplenode0_ where simplenode0_.SIMPLE_NODE_ID=?
Hibernate: select simplenode0_.SIMPLE_NODE_ID as SIMPLE1_0_, simplenode0_.SIMPLE_NODE_VERSION as SIMPLE2_0_0_, simplenode0_.SIMPLE_NODE_PARENT_ID as SIMPLE3_0_0_, simplenode0_.SIMPLE_NODE_CHILD_INDEX as SIMPLE4_0_0_, simplenode0_.SIMPLE_NODE_DESCRIPTOR as SIMPLE5_0_0_ from TBL_SIMPLE_NODES simplenode0_ where simplenode0_.SIMPLE_NODE_ID=?
2005-07-12 11:47:46,344 5828 DEBUG [main] org.hibernate.jdbc.AbstractBatcher - preparing statement
2005-07-12 11:47:46,344 5828 DEBUG [main] org.hibernate.type.LongType - binding '52' to parameter: 1
2005-07-12 11:47:46,344 5828 DEBUG [main] org.hibernate.jdbc.AbstractBatcher - about to open ResultSet (open ResultSets: 0, globally: 0)
2005-07-12 11:47:46,344 5828 DEBUG [main] org.hibernate.loader.Loader - processing result set
2005-07-12 11:47:46,344 5828 DEBUG [main] org.hibernate.loader.Loader - result set row: 0
2005-07-12 11:47:46,344 5828 DEBUG [main] org.hibernate.loader.Loader - result row: EntityKey[SimpleNode#52]
2005-07-12 11:47:46,344 5828 DEBUG [main] org.hibernate.loader.Loader - Initializing object from ResultSet: [SimpleNode#52]
2005-07-12 11:47:46,344 5828 DEBUG [main] org.hibernate.persister.entity.BasicEntityPersister - Hydrating entity: [SimpleNode#52]
2005-07-12 11:47:46,344 5828 DEBUG [main] org.hibernate.type.IntegerType - returning '0' as column: SIMPLE2_0_0_
2005-07-12 11:47:46,344 5828 DEBUG [main] org.hibernate.type.LongType - returning null as column: SIMPLE3_0_0_
2005-07-12 11:47:46,344 5828 DEBUG [main] org.hibernate.type.IntegerType - returning '0' as column: SIMPLE4_0_0_
2005-07-12 11:47:46,344 5828 DEBUG [main] org.hibernate.type.StringType - returning 'Parent node' as column: SIMPLE5_0_0_
2005-07-12 11:47:46,344 5828 DEBUG [main] org.hibernate.engine.TwoPhaseLoad - Version: 0
2005-07-12 11:47:46,344 5828 DEBUG [main] org.hibernate.loader.Loader - done processing result set (1 rows)
2005-07-12 11:47:46,344 5828 DEBUG [Finalizer] org.hibernate.jdbc.ConnectionManager - running Session.finalize()
2005-07-12 11:47:46,344 5828 DEBUG [main] org.hibernate.jdbc.AbstractBatcher - about to close ResultSet (open ResultSets: 1, globally: 1)
2005-07-12 11:47:46,344 5828 DEBUG [main] org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2005-07-12 11:47:46,344 5828 DEBUG [main] org.hibernate.jdbc.AbstractBatcher - closing statement
2005-07-12 11:47:46,344 5828 DEBUG [main] org.hibernate.loader.Loader - total objects hydrated: 1
2005-07-12 11:47:46,344 5828 DEBUG [main] org.hibernate.engine.TwoPhaseLoad - resolving associations for [SimpleNode#52]
2005-07-12 11:47:46,344 5828 DEBUG [main] org.hibernate.engine.CollectionLoadContext - creating collection wrapper:[SimpleNode.children#52]
2005-07-12 11:47:46,344 5828 DEBUG [main] org.hibernate.engine.TwoPhaseLoad - done materializing entity [SimpleNode#52]
2005-07-12 11:47:46,344 5828 DEBUG [main] org.hibernate.engine.PersistenceContext - initializing non-lazy collections
2005-07-12 11:47:46,344 5828 DEBUG [main] org.hibernate.event.def.DefaultInitializeCollectionEventListener - initializing collection [SimpleNode.children#52]
2005-07-12 11:47:46,354 5838 DEBUG [main] org.hibernate.event.def.DefaultInitializeCollectionEventListener - checking second-level cache
2005-07-12 11:47:46,354 5838 DEBUG [main] org.hibernate.event.def.DefaultInitializeCollectionEventListener - collection not cached
2005-07-12 11:47:46,354 5838 DEBUG [main] org.hibernate.loader.Loader - loading collection: [SimpleNode.children#52]
2005-07-12 11:47:46,354 5838 DEBUG [main] org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2005-07-12 11:47:46,354 5838 DEBUG [main] org.hibernate.SQL - select children0_.SIMPLE_NODE_PARENT_ID as SIMPLE3_1_, children0_.SIMPLE_NODE_ID as SIMPLE1_1_, children0_.SIMPLE_NODE_CHILD_INDEX as SIMPLE4_1_, children0_.SIMPLE_NODE_ID as SIMPLE1_0_, children0_.SIMPLE_NODE_VERSION as SIMPLE2_0_0_, children0_.SIMPLE_NODE_PARENT_ID as SIMPLE3_0_0_, children0_.SIMPLE_NODE_CHILD_INDEX as SIMPLE4_0_0_, children0_.SIMPLE_NODE_DESCRIPTOR as SIMPLE5_0_0_ from TBL_SIMPLE_NODES children0_ where children0_.SIMPLE_NODE_PARENT_ID=?
Hibernate: select children0_.SIMPLE_NODE_PARENT_ID as SIMPLE3_1_, children0_.SIMPLE_NODE_ID as SIMPLE1_1_, children0_.SIMPLE_NODE_CHILD_INDEX as SIMPLE4_1_, children0_.SIMPLE_NODE_ID as SIMPLE1_0_, children0_.SIMPLE_NODE_VERSION as SIMPLE2_0_0_, children0_.SIMPLE_NODE_PARENT_ID as SIMPLE3_0_0_, children0_.SIMPLE_NODE_CHILD_INDEX as SIMPLE4_0_0_, children0_.SIMPLE_NODE_DESCRIPTOR as SIMPLE5_0_0_ from TBL_SIMPLE_NODES children0_ where children0_.SIMPLE_NODE_PARENT_ID=?
2005-07-12 11:47:46,354 5838 DEBUG [main] org.hibernate.jdbc.AbstractBatcher - preparing statement
2005-07-12 11:47:46,354 5838 DEBUG [main] org.hibernate.type.LongType - binding '52' to parameter: 1
2005-07-12 11:47:46,374 5858 DEBUG [main] org.hibernate.jdbc.AbstractBatcher - about to open ResultSet (open ResultSets: 0, globally: 0)
2005-07-12 11:47:46,374 5858 DEBUG [main] org.hibernate.loader.Loader - result set contains (possibly empty) collection: [SimpleNode.children#52]
2005-07-12 11:47:46,374 5858 DEBUG [main] org.hibernate.engine.CollectionLoadContext - uninitialized collection: initializing
2005-07-12 11:47:46,374 5858 DEBUG [main] org.hibernate.loader.Loader - processing result set
2005-07-12 11:47:46,374 5858 DEBUG [main] org.hibernate.loader.Loader - result set row: 0
2005-07-12 11:47:46,374 5858 DEBUG [main] org.hibernate.type.LongType - returning '53' as column: SIMPLE1_0_
2005-07-12 11:47:46,374 5858 DEBUG [main] org.hibernate.loader.Loader - result row: EntityKey[SimpleNode#53]
2005-07-12 11:47:46,374 5858 DEBUG [main] org.hibernate.loader.Loader - Initializing object from ResultSet: [SimpleNode#53]
2005-07-12 11:47:46,474 5958 DEBUG [main] org.hibernate.persister.entity.BasicEntityPersister - Hydrating entity: [SimpleNode#53]
2005-07-12 11:47:46,474 5958 DEBUG [main] org.hibernate.type.IntegerType - returning '0' as column: SIMPLE2_0_0_
2005-07-12 11:47:46,474 5958 DEBUG [main] org.hibernate.type.LongType - returning '52' as column: SIMPLE3_0_0_
2005-07-12 11:47:46,474 5958 DEBUG [main] org.hibernate.type.IntegerType - returning '0' as column: SIMPLE4_0_0_
2005-07-12 11:47:46,484 5968 DEBUG [main] org.hibernate.type.StringType - returning 'Child node' as column: SIMPLE5_0_0_
2005-07-12 11:47:46,484 5968 DEBUG [main] org.hibernate.engine.TwoPhaseLoad - Version: 0
2005-07-12 11:47:46,484 5968 DEBUG [main] org.hibernate.type.LongType - returning '52' as column: SIMPLE3_1_
2005-07-12 11:47:46,484 5968 DEBUG [main] org.hibernate.loader.Loader - found row of collection: [SimpleNode.children#52]
2005-07-12 11:47:46,484 5968 DEBUG [main] org.hibernate.engine.CollectionLoadContext - reading row
2005-07-12 11:47:46,484 5968 DEBUG [main] org.hibernate.type.LongType - returning '53' as column: SIMPLE1_1_
2005-07-12 11:47:46,484 5968 DEBUG [main] org.hibernate.event.def.DefaultLoadEventListener - loading entity: [SimpleNode#53]
2005-07-12 11:47:46,484 5968 DEBUG [main] org.hibernate.event.def.DefaultLoadEventListener - attempting to resolve: [SimpleNode#53]
2005-07-12 11:47:46,484 5968 DEBUG [main] org.hibernate.event.def.DefaultLoadEventListener - resolved object in session cache: [SimpleNode#53]
2005-07-12 11:47:46,484 5968 DEBUG [main] org.hibernate.type.IntegerType - returning '0' as column: SIMPLE4_1_
2005-07-12 11:47:46,484 5968 DEBUG [main] org.hibernate.loader.Loader - done processing result set (1 rows)
2005-07-12 11:47:46,484 5968 DEBUG [main] org.hibernate.jdbc.AbstractBatcher - about to close ResultSet (open ResultSets: 1, globally: 1)
2005-07-12 11:47:46,484 5968 DEBUG [main] org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2005-07-12 11:47:46,484 5968 DEBUG [main] org.hibernate.jdbc.AbstractBatcher - closing statement
2005-07-12 11:47:46,484 5968 DEBUG [main] org.hibernate.loader.Loader - total objects hydrated: 1
2005-07-12 11:47:46,484 5968 DEBUG [main] org.hibernate.engine.TwoPhaseLoad - resolving associations for [SimpleNode#53]
2005-07-12 11:47:46,484 5968 DEBUG [main] org.hibernate.event.def.DefaultLoadEventListener - loading entity: [SimpleNode#52]
2005-07-12 11:47:46,484 5968 DEBUG [main] org.hibernate.event.def.DefaultLoadEventListener - attempting to resolve: [SimpleNode#52]
2005-07-12 11:47:46,484 5968 DEBUG [main] org.hibernate.event.def.DefaultLoadEventListener - resolved object in session cache: [SimpleNode#52]
2005-07-12 11:47:46,484 5968 DEBUG [main] org.hibernate.engine.CollectionLoadContext - creating collection wrapper:[SimpleNode.children#53]
2005-07-12 11:47:46,484 5968 DEBUG [main] org.hibernate.engine.TwoPhaseLoad - done materializing entity [SimpleNode#53]
2005-07-12 11:47:46,484 5968 DEBUG [main] org.hibernate.engine.CollectionLoadContext - 1 collections were found in result set for role: SimpleNode.children
2005-07-12 11:47:46,484 5968 DEBUG [main] org.hibernate.engine.CollectionLoadContext - collection fully initialized: [SimpleNode.children#52]
2005-07-12 11:47:46,484 5968 DEBUG [main] org.hibernate.engine.CollectionLoadContext - 1 collections initialized for role: SimpleNode.children
2005-07-12 11:47:46,484 5968 DEBUG [main] org.hibernate.loader.Loader - done loading collection
2005-07-12 11:47:46,484 5968 DEBUG [main] org.hibernate.event.def.DefaultInitializeCollectionEventListener - collection initialized
2005-07-12 11:47:46,484 5968 DEBUG [main] org.hibernate.event.def.DefaultInitializeCollectionEventListener - initializing collection [SimpleNode.children#53]
2005-07-12 11:47:46,484 5968 DEBUG [main] org.hibernate.event.def.DefaultInitializeCollectionEventListener - checking second-level cache
2005-07-12 11:47:46,484 5968 DEBUG [main] org.hibernate.event.def.DefaultInitializeCollectionEventListener - collection not cached
2005-07-12 11:47:46,484 5968 DEBUG [main] org.hibernate.loader.Loader - loading collection: [SimpleNode.children#53]
2005-07-12 11:47:46,484 5968 DEBUG [main] org.hibernate.jdbc.AbstractBatcher - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2005-07-12 11:47:46,484 5968 DEBUG [main] org.hibernate.SQL - select children0_.SIMPLE_NODE_PARENT_ID as SIMPLE3_1_, children0_.SIMPLE_NODE_ID as SIMPLE1_1_, children0_.SIMPLE_NODE_CHILD_INDEX as SIMPLE4_1_, children0_.SIMPLE_NODE_ID as SIMPLE1_0_, children0_.SIMPLE_NODE_VERSION as SIMPLE2_0_0_, children0_.SIMPLE_NODE_PARENT_ID as SIMPLE3_0_0_, children0_.SIMPLE_NODE_CHILD_INDEX as SIMPLE4_0_0_, children0_.SIMPL
Login
FAQ
Search