Here, I have a problem that I minimized into 2 classes and hsqldb for easy re-generation of the issue. I have a List of Bars under Foo. It is declared to be cascade="all-delete-orphan" and inverse="true". I create a new "Foo" and add a "Bar" under it. Then I try to save the "Foo". If a problem occurs during the save, I rollback the transaction and close the session. If nothing goes wrong, Hibernate understands that it should issue an "insert" for the "Bar" and everything works well. If for some reason the operation fails, let it be a database constraint or a ValidationFailure, in the next attempt to save the "Foo", the "Bar" is accepted as inserted and Hibernate issues an "update". Naturally it cannot find a row to update and the update fails and Hibernate generates the Error: Could not synchronize database state with session.
Problem still occurs in both cases of "Foo" as a new one or a "Foo" that is already in the database and loaded for an update.
Problem occurs both in Sybase ASA and hsqldb.
Is it something that I am doing wrong or missing?
Best regards,
Levent Aksu
Hibernate version:
2.1.4 to 2.1.6
Mapping documents:
<hibernate-mapping>
<class name="Foo">
<id name="id" type="long" unsaved-value="0">
<generator class="hilo">
<param name="max_lo">0</param>
<param name="table">key_Foo</param>
</generator></id>
<property name="a" length="50" type="string"/>
<property name="b" type="double"/>
<list name="bars" inverse="true" cascade="all-delete-orphan" lazy="true">
<key column="foo"/>
<index column="sortorder"/>
<one-to-many class="Bar"/>
</list>
</class>
<class name="Bar">
<id name="id" unsaved-value="0" type="long">
<generator class="hilo">
<param name="max_lo">0</param>
<param name="table">key_Bar</param>
</generator></id>
<many-to-one name="foo" class="Foo" not-null="true" />
<property name="sortorder" type="int"/>
<property name="c" length="50" type="string"/>
<property name="d" type="double"/>
</class>
</hibernate-mapping>
Code between sessionFactory.openSession() and session.close():
Foo f=new Foo();
f.setA("aaa");
f.setB(3);
Bar b=new Bar();
b.setC("ccc");
// Bar implements Validatable and throws
// ValidationFailure if D is less than 10
b.setD(5); // Try an invalid value
b.setFoo(f);
f.getBars().add(b);
s1=sf.openSession();
try{
t = s1.beginTransaction();
s1.save(f);
t.commit();
} catch(HibernateException he){ // it's rejected as expected
System.out.println("Exception occured:"+he.getMessage());
if (t!=null)
t.rollback();
} finally {
s1.close();
}
b.setD(15); // let's correct it
s2=sf.openSession();
try{
t = s2.beginTransaction();
s2.save(f);
t.commit();
} catch(HibernateException he){
System.out.println("Exception occured:"+he.getMessage());
if (t!=null)
t.rollback();
} finally {
s2.close();
}
Full stack trace of any exception that occurs:
Included in the log below
Name and version of the database you are using:
Both with hsqldb 1.7.2 and Sybase ASA 9.0.1
Debug level Hibernate log excerpt:
06:27:04,140 INFO ReflectHelper:186 - reflection optimizer disabled for: Bar, NullPointerException: null
06:27:04,328 DEBUG SessionFactoryObjectFactory:39 - initializing class SessionFactoryObjectFactory
06:27:04,343 DEBUG SessionFactoryObjectFactory:76 - registered: 40288182fe562f2600fe562f28880000 (unnamed)
06:27:04,343 INFO SessionFactoryObjectFactory:82 - Not binding factory to JNDI, no JNDI name configured
06:27:04,343 DEBUG SessionFactoryImpl:195 - instantiated session factory
06:27:04,421 DEBUG SessionImpl:555 - opened session
06:27:04,421 DEBUG JDBCTransaction:37 - begin
06:27:04,437 DEBUG DriverManagerConnectionProvider:84 - total checked-out connections: 0
06:27:04,437 DEBUG DriverManagerConnectionProvider:90 - using pooled JDBC connection, pool size: 0
06:27:04,437 DEBUG JDBCTransaction:41 - current autocommit status:false
06:27:04,437 DEBUG DriverManagerConnectionProvider:84 - total checked-out connections: 1
06:27:04,437 DEBUG DriverManagerConnectionProvider:100 - opening new JDBC connection
06:27:04,437 DEBUG DriverManagerConnectionProvider:106 - created connection to: jdbc:hsqldb:file:data/prob, Isolation Level: 1
06:27:04,515 DEBUG DriverManagerConnectionProvider:120 - returning connection to pool, pool size: 1
06:27:04,515 DEBUG TableHiLoGenerator:62 - new hi value: 14
06:27:04,515 DEBUG SessionImpl:778 - generated identifier: 15
06:27:04,515 DEBUG SessionImpl:825 - saving [Foo#15]
06:27:04,515 DEBUG Cascades:497 - processing cascades for: Foo
06:27:04,531 DEBUG Cascades:506 - done processing cascades for: Foo
06:27:04,546 DEBUG WrapVisitor:81 - Wrapped collection in role: Foo.bars
06:27:04,546 DEBUG Cascades:497 - processing cascades for: Foo
06:27:04,562 DEBUG Cascades:524 - cascading to collection: Foo.bars
06:27:04,562 DEBUG Cascades:113 - cascading to saveOrUpdate()
06:27:04,562 DEBUG Cascades:312 - id unsaved-value: 0
06:27:04,562 DEBUG SessionImpl:1387 - saveOrUpdate() unsaved instance
06:27:04,562 DEBUG DriverManagerConnectionProvider:84 - total checked-out connections: 1
06:27:04,562 DEBUG DriverManagerConnectionProvider:90 - using pooled JDBC connection, pool size: 0
06:27:04,562 DEBUG DriverManagerConnectionProvider:120 - returning connection to pool, pool size: 1
06:27:04,562 DEBUG TableHiLoGenerator:62 - new hi value: 11
06:27:04,578 DEBUG SessionImpl:778 - generated identifier: 12
06:27:04,578 DEBUG SessionImpl:825 - saving [Bar#12]
Exception occured:d must be greater than 10
06:27:04,578 DEBUG JDBCTransaction:82 - rollback
06:27:04,578 DEBUG SessionImpl:585 - transaction completion
06:27:04,578 DEBUG SessionImpl:573 - closing session
06:27:04,578 DEBUG SessionImpl:3336 - disconnecting session
06:27:04,578 DEBUG DriverManagerConnectionProvider:120 - returning connection to pool, pool size: 2
06:27:04,578 DEBUG SessionImpl:585 - transaction completion
06:27:04,578 DEBUG SessionImpl:555 - opened session
06:27:04,578 DEBUG JDBCTransaction:37 - begin
06:27:04,593 DEBUG DriverManagerConnectionProvider:84 - total checked-out connections: 0
06:27:04,593 DEBUG DriverManagerConnectionProvider:90 - using pooled JDBC connection, pool size: 1
06:27:04,593 DEBUG JDBCTransaction:41 - current autocommit status:false
06:27:04,593 DEBUG DriverManagerConnectionProvider:84 - total checked-out connections: 1
06:27:04,593 DEBUG DriverManagerConnectionProvider:90 - using pooled JDBC connection, pool size: 0
06:27:04,593 DEBUG DriverManagerConnectionProvider:120 - returning connection to pool, pool size: 1
06:27:04,593 DEBUG TableHiLoGenerator:62 - new hi value: 15
06:27:04,593 DEBUG SessionImpl:778 - generated identifier: 16
06:27:04,593 DEBUG SessionImpl:825 - saving [Foo#16]
06:27:04,609 DEBUG Cascades:497 - processing cascades for: Foo
06:27:04,609 DEBUG Cascades:506 - done processing cascades for: Foo
06:27:04,609 DEBUG Cascades:497 - processing cascades for: Foo
06:27:04,609 DEBUG Cascades:524 - cascading to collection: Foo.bars
06:27:04,609 DEBUG Cascades:113 - cascading to saveOrUpdate()
06:27:04,609 DEBUG Cascades:312 - id unsaved-value: 0
06:27:04,609 DEBUG SessionImpl:1392 - saveOrUpdate() previously saved instance with id:12
06:27:04,609 DEBUG SessionImpl:1440 - updating [Bar#12]
06:27:04,609 DEBUG Cascades:506 - done processing cascades for: Foo
06:27:04,625 DEBUG JDBCTransaction:59 - commit
06:27:04,625 DEBUG SessionImpl:2246 - flushing session
06:27:04,625 DEBUG Cascades:497 - processing cascades for: Foo
06:27:04,625 DEBUG Cascades:524 - cascading to collection: Foo.bars
06:27:04,625 DEBUG Cascades:113 - cascading to saveOrUpdate()
06:27:04,625 DEBUG SessionImpl:1372 - saveOrUpdate() persistent instance
06:27:04,625 DEBUG Cascades:506 - done processing cascades for: Foo
06:27:04,625 DEBUG SessionImpl:2439 - Flushing entities and processing referenced collections
06:27:04,625 DEBUG SessionImpl:2884 - Collection found: [Foo.bars#16], was: [<unreferenced>]
06:27:04,640 DEBUG SessionImpl:2533 - Updating entity: [Bar#12]
06:27:04,640 DEBUG SessionImpl:2780 - Processing unreferenced collections
06:27:04,640 DEBUG SessionImpl:2794 - Scheduling collection removes/(re)creates/updates
06:27:04,640 DEBUG SessionImpl:2270 - Flushed: 1 insertions, 1 updates, 0 deletions to 2 objects
06:27:04,640 DEBUG SessionImpl:2275 - Flushed: 1 (re)creations, 0 updates, 0 removals to 1 collections
06:27:04,640 DEBUG Printer:75 - listing entities:
06:27:04,656 DEBUG Printer:82 - Bar{d=15.0, foo=Foo#16, sortorder=0, c=ccc, id=12}
06:27:04,656 DEBUG Printer:82 - Foo{a=aaa, bars=[Bar#12], b=3.0, id=16}
06:27:04,656 DEBUG SessionImpl:2359 - executing flush
06:27:04,656 DEBUG EntityPersister:453 - Inserting entity: [Foo#16]
06:27:04,656 DEBUG BatcherImpl:200 - about to open: 0 open PreparedStatements, 0 open ResultSets
06:27:04,656 DEBUG SQL:226 - insert into Foo (a, b, id) values (?, ?, ?)
Hibernate: insert into Foo (a, b, id) values (?, ?, ?)
06:27:04,656 DEBUG BatcherImpl:249 - preparing statement
06:27:04,656 DEBUG EntityPersister:388 - Dehydrating entity: [Foo#16]
06:27:04,656 DEBUG StringType:46 - binding 'aaa' to parameter: 1
06:27:04,656 DEBUG DoubleType:46 - binding '3.0' to parameter: 2
06:27:04,656 DEBUG LongType:46 - binding '16' to parameter: 3
06:27:04,671 DEBUG BatcherImpl:28 - Adding to batch
06:27:04,671 DEBUG BatcherImpl:50 - Executing batch size: 1
06:27:04,671 DEBUG BatcherImpl:207 - done closing: 0 open PreparedStatements, 0 open ResultSets
06:27:04,671 DEBUG BatcherImpl:269 - closing statement
06:27:04,671 DEBUG EntityPersister:648 - Updating entity: [Bar#12]
06:27:04,671 DEBUG BatcherImpl:200 - about to open: 0 open PreparedStatements, 0 open ResultSets
06:27:04,671 DEBUG SQL:226 - update Bar set foo=?, sortorder=?, c=?, d=? where id=?
Hibernate: update Bar set foo=?, sortorder=?, c=?, d=? where id=?
06:27:04,671 DEBUG BatcherImpl:249 - preparing statement
06:27:04,671 DEBUG EntityPersister:388 - Dehydrating entity: [Bar#12]
06:27:04,671 DEBUG LongType:46 - binding '16' to parameter: 1
06:27:04,671 DEBUG IntegerType:46 - binding '0' to parameter: 2
06:27:04,687 DEBUG StringType:46 - binding 'ccc' to parameter: 3
06:27:04,687 DEBUG DoubleType:46 - binding '15.0' to parameter: 4
06:27:04,687 DEBUG LongType:46 - binding '12' to parameter: 5
06:27:04,687 DEBUG BatcherImpl:28 - Adding to batch
06:27:04,687 DEBUG BatcherImpl:50 - Executing batch size: 1
06:27:04,687 DEBUG BatcherImpl:207 - done closing: 0 open PreparedStatements, 0 open ResultSets
06:27:04,687 DEBUG BatcherImpl:269 - closing statement
06:27:04,703 ERROR SessionImpl:2379 - Could not synchronize database state with session
net.sf.hibernate.HibernateException: Batch update row count wrong: 0
at net.sf.hibernate.impl.BatchingBatcher.doExecuteBatch(BatchingBatcher.java:65)
at net.sf.hibernate.impl.BatcherImpl.executeBatch(BatcherImpl.java:126)
at net.sf.hibernate.impl.SessionImpl.executeAll(SessionImpl.java:2421)
at net.sf.hibernate.impl.SessionImpl.execute(SessionImpl.java:2372)
at net.sf.hibernate.impl.SessionImpl.flush(SessionImpl.java:2240)
at net.sf.hibernate.transaction.JDBCTransaction.commit(JDBCTransaction.java:61)
at meyn.main(meyn.java:44)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:324)
at org.apache.tools.ant.taskdefs.ExecuteJava.run(ExecuteJava.java:193)
at org.apache.tools.ant.taskdefs.ExecuteJava.execute(ExecuteJava.java:130)
at org.apache.tools.ant.taskdefs.Java.run(Java.java:705)
at org.apache.tools.ant.taskdefs.Java.executeJava(Java.java:177)
at org.apache.tools.ant.taskdefs.Java.execute(Java.java:83)
at org.apache.tools.ant.UnknownElement.execute(UnknownElement.java:275)
at org.apache.tools.ant.Task.perform(Task.java:364)
at org.apache.tools.ant.Target.execute(Target.java:341)
at org.apache.tools.ant.Target.performTasks(Target.java:369)
at org.apache.tools.ant.Project.executeTarget(Project.java:1214)
at org.apache.tools.ant.Project.executeTargets(Project.java:1062)
at org.apache.tools.ant.Main.runBuild(Main.java:673)
at org.apache.tools.ant.Main.startAnt(Main.java:188)
at org.apache.tools.ant.launch.Launcher.run(Launcher.java:196)
at org.apache.tools.ant.launch.Launcher.main(Launcher.java:55)
Exception occured:Batch update row count wrong: 0
06:27:04,718 DEBUG JDBCTransaction:82 - rollback
06:27:04,718 DEBUG SessionImpl:585 - transaction completion
06:27:04,718 DEBUG SessionImpl:573 - closing session
06:27:04,718 DEBUG SessionImpl:3336 - disconnecting session
06:27:04,718 DEBUG DriverManagerConnectionProvider:120 - returning connection to pool, pool size: 2
06:27:04,718 DEBUG SessionImpl:585 - transaction completion
|