Hi,
I seem to have hit a Hibernate issue (HB-682) that was closed earlier (
http://forum.hibernate.org/viewtopic.php?p=2188306).
Can someone please have a look and see if something is wrong?
My config is:
Hibernate 2.1.5
Oracle 9.2.0.1.0
I use timestamp to version an entity (User). This is not a choice I made, only because I'm working with legacy data.
An unnecessary UPDATE statement is issued when I try to create an entiy that contains a bag (one-to-many). This tries to update the timestamp field and throws a StaleObjectStateException, even though this is while saving a new instance. Same behaviour even if the collection is inverse.
When I remove the one-to-many association, everything works as expected, and the unnecessary UPDATE is not issued.
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 package="com.i2.srm.integration.gen.explore.impl">
<class name="RootTypeImpl" dynamic-insert="true" dynamic-update="true" lazy="true" table="ROOT">
<id name="OID">
<column name="OBJ_ID" sql-type="NUMBER(15)"/>
<generator class="assigned"/>
</id>
<!-- versioning attribute -->
<timestamp column="TIME_STAMP" name="lastModifiedDate"/>
<property name="createDate" column="CREATE_DATE"/>
</class>
<joined-subclass name="UserTypeImpl" dynamic-update="true" extends="com.i2.srm.integration.gen.explore.impl.RootTypeImpl"
lazy="true" table="USERS">
<key column="OBJ_ID"/>
<property name="userName" column="USR_NAME" length="30"/>
<property name="userPassword" column="USR_PASSWD" length="80"/>
<property name="isSuperUser" column="USR_IS_SUPERUSER"/>
<property name="mailAddress" column="USR_MAILADDR" length="128"/>
<property name="telephoneNumber" column="USR_TELEPHONE" length="20"/>
<property name="userAccount" column="USR_ACCOUNT" length="20"/>
<property name="lastName" column="USR_LAST_NAME" length="60"/>
<property name="firstName" column="USR_FIRST_NAME" length="60"/>
<property name="middleName" column="USR_MIDDLE_NAME" length="60"/>
<property name="printableName" column="USR_PRINTABLE_NAME" length="128"/>
<property name="employeeID" column="USR_EMPLOYEE_ID" length="20"/>
<property name="fax" column="USR_FAX" length="20"/>
<property name="title" column="USR_TITLE" length="60"/>
<property name="addressLine1" column="USR_ADDRESS_LINE_1" length="50"/>
<property name="addressLine2" column="USR_ADDRESS_LINE_2" length="50"/>
<property name="addressLine3" column="USR_ADDRESS_LINE_3" length="50"/>
<property name="city" column="USR_CITY" length="30"/>
<property name="state" column="USR_STATE" length="30"/>
<property name="country" column="USR_COUNTRY" length="30"/>
<property name="zip" column="USR_ZIP" length="12"/>
<bag name="uomList" lazy="true">
<key column="USER"/>
<one-to-many class="UOMTypeImpl"/>
</bag>
</joined-subclass>
<joined-subclass name="UOMTypeImpl" extends="com.i2.srm.integration.gen.explore.impl.RootTypeImpl" lazy="true" table="UOM_TABLE">
<key column="OBJ_ID"/>
<property name="uomName" column="UOM_NAME" length="30"/>
<property name="uomDisplaySymbol" column="UOM_DISPL_SYMBOL" length="20"/>
<property name="uomDescription" column="UOM_DESCR" length="70"/>
<property name="uomType" column="UOM_TYPE" length="25"/>
</joined-subclass>
</hibernate-mapping>
Java code segment:
Code:
public void execute() throws Exception
{
// perform persistence operations
Session session = HibernateUtil.currentSession();
Transaction tx = session.beginTransaction();
try
{
// call the concrete implementation..
apply(session);
// commit transaction
tx.commit();
System.out.println("done!");
}
catch (Throwable e)
{
if(tx != null)
tx.rollback();
throw e;
}
finally
{
HibernateUtil.closeSession();
}
}
void apply(Session session)
{
ObjectFactory objFactory = new ObjectFactory();
UserType user = null;
try
{
// create User instance..
user = objFactory.createUserType();
}
catch (javax.xml.bind.JAXBException e)
{
System.out.println("\tCannot create a new User:\n");
e.printStackTrace();
System.exit(1);
}
// read in all relevant information and fill the new object
System.out.println("\tEnter data for new User:");
String in = readLineWithMessage("\tEnter a unique ID:");
user.setOID(Long.parseLong(in));
in = readLineWithMessage("\tEnter user name:");
user.setUserName(in);
in = readLineWithMessage("\tEnter city:");
user.setCity(in);
user.setCreateDate(new Date());
// save
session.save(user);
}
Hibernate Log segment:
Code:
11:02:20,844 DEBUG SessionImpl:555 - opened session
11:02:20,844 DEBUG JDBCTransaction:37 - begin
11:02:20,844 DEBUG DriverManagerConnectionProvider:84 - total checked-out connections: 0
11:02:20,844 DEBUG DriverManagerConnectionProvider:90 - using pooled JDBC connection, pool size: 0
11:02:20,876 DEBUG JDBCTransaction:41 - current autocommit status:false
11:02:30,891 DEBUG SessionImpl:778 - generated identifier: 456
11:02:30,891 DEBUG SessionImpl:825 - saving [com.i2.srm.integration.gen.explore.impl.UserTypeImpl#456]
11:02:30,907 DEBUG Versioning:35 - Seeding: 2004-08-06 11:02:30.907
11:02:30,922 DEBUG WrapVisitor:81 - Wrapped collection in role: com.i2.srm.integration.gen.explore.impl.UserTypeImpl.uomList
11:02:30,922 DEBUG JDBCTransaction:59 - commit
11:02:30,922 DEBUG SessionImpl:2246 - flushing session
11:02:30,938 DEBUG SessionImpl:2439 - Flushing entities and processing referenced collections
11:02:30,938 DEBUG WrapVisitor:81 - Wrapped collection in role: com.i2.srm.integration.gen.explore.impl.UserTypeImpl.uomList
11:02:30,938 DEBUG AbstractEntityPersister:275 - com.i2.srm.integration.gen.explore.impl.UserTypeImpl.uomList is dirty
11:02:30,938 DEBUG SessionImpl:2533 - Updating entity: [com.i2.srm.integration.gen.explore.impl.UserTypeImpl#456]
11:02:30,938 DEBUG Versioning:26 - Incrementing: 2004-08-06 11:02:30.907 to 2004-08-06 11:02:30.938
11:02:30,938 DEBUG SessionImpl:2884 - Collection found: [com.i2.srm.integration.gen.explore.impl.UserTypeImpl.uomList#456], was: [<unreferenced>]
11:02:30,938 DEBUG SessionImpl:2780 - Processing unreferenced collections
11:02:30,938 DEBUG SessionImpl:2794 - Scheduling collection removes/(re)creates/updates
11:02:30,954 DEBUG SessionImpl:2270 - Flushed: 1 insertions, 1 updates, 0 deletions to 1 objects
11:02:30,954 DEBUG SessionImpl:2275 - Flushed: 1 (re)creations, 0 updates, 0 removals to 2 collections
11:02:30,954 DEBUG Printer:75 - listing entities:
11:02:30,985 DEBUG Printer:82 - com.i2.srm.integration.gen.explore.impl.UserTypeImpl{userName=John, title=null, mailAddress=null, userPassword=null, printableName=null, employeeID=null, addressLine2=null, fax=null, firstName=null, lastName=null, addressLine3=null, country=null, lastModifiedDate=2004-08-06 11:02:30, uomList=[], isSuperUser=false, state=null, createDate=2004-08-06 11:02:30, zip=null, OID=456, middleName=null, telephoneNumber=null, userAccount=null, city=San Francisco, addressLine1=null}
11:02:30,985 DEBUG SessionImpl:2359 - executing flush
11:02:30,985 DEBUG NormalizedEntityPersister:443 - Inserting entity: [com.i2.srm.integration.gen.explore.impl.UserTypeImpl#456]
11:02:30,985 DEBUG NormalizedEntityPersister:444 - Version: 2004-08-06 11:02:30.907
11:02:30,985 DEBUG BatcherImpl:200 - about to open: 0 open PreparedStatements, 0 open ResultSets
11:02:30,985 DEBUG SQL:226 - insert into ROOT (TIME_STAMP, CREATE_DATE, OBJ_ID) values (?, ?, ?)
11:02:30,985 DEBUG BatcherImpl:249 - preparing statement
11:02:31,172 DEBUG BatcherImpl:200 - about to open: 1 open PreparedStatements, 0 open ResultSets
11:02:31,172 DEBUG SQL:226 - insert into USERS (USR_NAME, USR_PASSWD, USR_IS_SUPERUSER, USR_MAILADDR, USR_TELEPHONE, USR_ACCOUNT, USR_LAST_NAME, USR_FIRST_NAME, USR_MIDDLE_NAME, USR_PRINTABLE_NAME, USR_EMPLOYEE_ID, USR_FAX, USR_TITLE, USR_ADDRESS_LINE_1, USR_ADDRESS_LINE_2, USR_ADDRESS_LINE_3, USR_CITY, USR_STATE, USR_COUNTRY, USR_ZIP, OBJ_ID) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
11:02:31,172 DEBUG BatcherImpl:249 - preparing statement
11:02:31,172 DEBUG NormalizedEntityPersister:355 - Dehydrating entity: [com.i2.srm.integration.gen.explore.impl.UserTypeImpl#456]
11:02:31,235 DEBUG BatcherImpl:207 - done closing: 1 open PreparedStatements, 0 open ResultSets
11:02:31,235 DEBUG BatcherImpl:269 - closing statement
11:02:31,235 DEBUG BatcherImpl:207 - done closing: 0 open PreparedStatements, 0 open ResultSets
11:02:31,235 DEBUG BatcherImpl:269 - closing statement
11:02:31,235 DEBUG NormalizedEntityPersister:676 - Updating entity: [com.i2.srm.integration.gen.explore.impl.UserTypeImpl#456]
11:02:31,235 DEBUG NormalizedEntityPersister:677 - Existing version: 2004-08-06 11:02:30.907 -> New version: 2004-08-06 11:02:30.938
11:02:31,235 DEBUG BatcherImpl:200 - about to open: 0 open PreparedStatements, 0 open ResultSets
11:02:31,235 DEBUG SQL:226 - update ROOT set TIME_STAMP=? where OBJ_ID=? and TIME_STAMP=?
11:02:31,235 DEBUG BatcherImpl:249 - preparing statement
11:02:31,235 DEBUG NormalizedEntityPersister:355 - Dehydrating entity: [com.i2.srm.integration.gen.explore.impl.UserTypeImpl#456]
11:02:31,250 WARN StaleObjectStateException:27 - An operation failed due to stale data
net.sf.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect) for com.i2.srm.integration.gen.explore.impl.UserTypeImpl instance with identifier: 456
at net.sf.hibernate.persister.AbstractEntityPersister.check(AbstractEntityPersister.java:506)
at net.sf.hibernate.persister.NormalizedEntityPersister.update(NormalizedEntityPersister.java:695)
at net.sf.hibernate.persister.NormalizedEntityPersister.update(NormalizedEntityPersister.java:670)
at net.sf.hibernate.impl.ScheduledUpdate.execute(ScheduledUpdate.java:52)
at net.sf.hibernate.impl.SessionImpl.executeAll(SessionImpl.java:2418)
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 testapp.AbstractUseCase.execute(AbstractUseCase.java:48)
at testapp.Application.run(Application.java:82)
at testapp.Application.main(Application.java:47)
11:02:31,266 DEBUG BatcherImpl:207 - done closing: 0 open PreparedStatements, 0 open ResultSets
11:02:31,266 DEBUG BatcherImpl:269 - closing statement
11:02:31,266 ERROR SessionImpl:2379 - Could not synchronize database state with session
net.sf.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect) for com.i2.srm.integration.gen.explore.impl.UserTypeImpl instance with identifier: 456
at net.sf.hibernate.persister.AbstractEntityPersister.check(AbstractEntityPersister.java:506)
at net.sf.hibernate.persister.NormalizedEntityPersister.update(NormalizedEntityPersister.java:695)
at net.sf.hibernate.persister.NormalizedEntityPersister.update(NormalizedEntityPersister.java:670)
at net.sf.hibernate.impl.ScheduledUpdate.execute(ScheduledUpdate.java:52)
at net.sf.hibernate.impl.SessionImpl.executeAll(SessionImpl.java:2418)
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 testapp.AbstractUseCase.execute(AbstractUseCase.java:48)
at testapp.Application.run(Application.java:82)
at testapp.Application.main(Application.java:47)
11:02:31,266 DEBUG JDBCTransaction:82 - rollback
11:02:31,266 DEBUG SessionImpl:585 - transaction completion
11:02:31,266 DEBUG UpdateTimestampsCache:51 - Invalidating space [USERS]
11:02:31,266 DEBUG UpdateTimestampsCache:51 - Invalidating space [ROOT]
11:02:31,266 DEBUG UpdateTimestampsCache:51 - Invalidating space [USERS]
11:02:31,266 DEBUG UpdateTimestampsCache:51 - Invalidating space [ROOT]
11:02:31,282 DEBUG SessionImpl:573 - closing session
11:02:31,282 DEBUG SessionImpl:3336 - disconnecting session
11:02:31,282 DEBUG DriverManagerConnectionProvider:120 - returning connection to pool, pool size: 1
11:02:31,282 DEBUG SessionImpl:585 - transaction completion
11:02:35,032 DEBUG SessionImpl:555 - opened session
11:02:35,032 DEBUG JDBCTransaction:37 - begin
11:02:35,032 DEBUG DriverManagerConnectionProvider:84 - total checked-out connections: 0
11:02:35,032 DEBUG DriverManagerConnectionProvider:90 - using pooled JDBC connection, pool size: 0
11:02:35,032 DEBUG JDBCTransaction:41 - current autocommit status:false
Thank you.