I have a simple 3-record structure forming a classic n-m relation with an explicit intersection record:
Code:
{group} {person}
\ /
{GroupMember}
The GroupMember record contains generated fields.
When I add a member to this collection using the following code:
Code:
Group g = DaoGroup.getGroup(getSession(), gid);
UserGroupMember m = findMemberByPersonID(g, id);
if(m == null) { // Not already in the collection?
Person p = DaoPerson.getPerson(getSession(), id);
m = new UserGroupMember();
m.setMember(p);
m.setGroup(g);
getSession().persist(m);
g.getMemberList().add(m);
}
m.setOrder(Integer.valueOf(ord.intValue()));
getSession().commit();
When I use his code I get odd behaviour: I see Hibernate "inserting" the new groupmember record correctly. After that it does a select to retrieve the generated values which is also correct. But then it does an UPDATE on the record it has just inserted and reread, and the update contains null values for the generated fields (that it has just read using the select)!? causing a "not null" constraint to fire in the database.
Replacing the "persist" with "save" does not fix the problem (as expected).
If I move the "persist" or "save"
after the m.setOrder() call the code does work! And I did not expect that! Can anyone explain why I have to save only after all changes to a record are done?
For further info: the log of Hibernate persisting the structure follows:
Code:
DEBUG - loading entity: [nl.itris.viewpoint.db.crm.Relation#1150057523]
DEBUG - creating new proxy for entity
DEBUG - transient instance of: nl.itris.viewpoint.db.crm.UserGroupMember
DEBUG - saving transient instance
DEBUG - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
DEBUG - SELECT red_environment.get_sequence(?) FROM DUAL
DEBUG - preparing statement
DEBUG - ViewPoint identifier generated: 1150003795
DEBUG - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
DEBUG - closing statement
DEBUG - generated identifier: 1150003795, using strategy: nl.itris.viewpoint.db.hibernate.ViewpointIdentifierGenerator
DEBUG - saving [nl.itris.viewpoint.db.crm.UserGroupMember#1150003795]
DEBUG - commit
DEBUG - automatically flushing session
DEBUG - flushing session
DEBUG - processing flush-time cascades
DEBUG - dirty checking collections
DEBUG - Collection dirty: [nl.itris.viewpoint.db.crm.UserGroup.memberList#1150000108]
DEBUG - Flushing entities and processing referenced collections
DEBUG - Collection found: [nl.itris.viewpoint.db.crm.UserGroup.memberList#1150000108], was: [nl.itris.viewpoint.db.crm.UserGroup.memberList#1150000108] (initialized)
DEBUG - nl.itris.viewpoint.db.crm.UserGroupMember.order is dirty
DEBUG - Updating entity: [nl.itris.viewpoint.db.crm.UserGroupMember#1150003795]
DEBUG - nl.itris.viewpoint.db.crm.UserGroupMember.order is dirty
DEBUG - Processing unreferenced collections
DEBUG - Scheduling collection removes/(re)creates/updates
DEBUG - Flushed: 1 insertions, 1 updates, 0 deletions to 7 objects
DEBUG - Flushed: 0 (re)creations, 1 updates, 0 removals to 1 collections
DEBUG - listing entities:
DEBUG - nl.itris.viewpoint.db.crm.UserGroupMember{group=nl.itris.viewpoint.db.crm.UserGroup#1150000108, tcn=null, typeString=null, logTime=null, fgColor=null, order=5, logModule=null, member=nl.itris.viewpoint.db.crm.Relation#1150057523, id=1150003795, organisationId=null, bgColor=null, wtfIsThis=null, roleString=null, logDate=null, logUser=null}
DEBUG - nl.itris.viewpoint.db.crm.UserGroupMember{group=nl.itris.viewpoint.db.crm.UserGroup#1150000108, tcn=259727092, typeString=AGAVIEWER, logTime=17:21:14, fgColor=null, order=2, logModule=null, member=nl.itris.viewpoint.db.crm.Relation#1150058608, id=1150003729, organisationId=1500, bgColor=null, wtfIsThis=null, roleString=null, logDate=2007-04-20 00:00:00, logUser=VPC}
DEBUG - nl.itris.viewpoint.db.crm.UserGroup{groupEmail=null, memberList=[nl.itris.viewpoint.db.crm.UserGroupMember#1150003793, nl.itris.viewpoint.db.crm.UserGroupMember#1150003794, nl.itris.viewpoint.db.crm.UserGroupMember#1150003727, nl.itris.viewpoint.db.crm.UserGroupMember#1150003728, nl.itris.viewpoint.db.crm.UserGroupMember#1150003729, nl.itris.viewpoint.db.crm.UserGroupMember#1150003795], type=PLN, tcn=259977664, logTime=18:03:00, logModule=null, id=1150000108, organisationId=1500, groupLeader=null, description=Test groep voor indelen planbord (test 1), memberMutable=false, logDate=2007-04-20 00:00:00, name=Timmermannen, logUser=VPC}
DEBUG - nl.itris.viewpoint.db.crm.UserGroupMember{group=nl.itris.viewpoint.db.crm.UserGroup#1150000108, tcn=259727091, typeString=AGAVIEWER, logTime=17:21:14, fgColor=null, order=0, logModule=null, member=nl.itris.viewpoint.db.crm.Relation#1150007675, id=1150003728, organisationId=1500, bgColor=null, wtfIsThis=null, roleString=null, logDate=2007-04-20 00:00:00, logUser=VPC}
DEBUG - nl.itris.viewpoint.db.crm.UserGroupMember{group=nl.itris.viewpoint.db.crm.UserGroup#1150000108, tcn=259727088, typeString=AGAVIEWER, logTime=17:21:14, fgColor=null, order=1, logModule=null, member=nl.itris.viewpoint.db.crm.Relation#1150056729, id=1150003727, organisationId=1500, bgColor=null, wtfIsThis=null, roleString=null, logDate=2007-04-20 00:00:00, logUser=VPC}
DEBUG - nl.itris.viewpoint.db.crm.UserGroupMember{group=nl.itris.viewpoint.db.crm.UserGroup#1150000108, tcn=283788200, typeString=null, logTime=12:11:40, fgColor=null, order=4, logModule=null, member=nl.itris.viewpoint.db.crm.Relation#1150054019, id=1150003794, organisationId=1500, bgColor=null, wtfIsThis=null, roleString=null, logDate=2007-04-23 00:00:00, logUser=VPC}
DEBUG - nl.itris.viewpoint.db.crm.UserGroupMember{group=nl.itris.viewpoint.db.crm.UserGroup#1150000108, tcn=283751099, typeString=null, logTime=12:05:29, fgColor=null, order=3, logModule=null, member=nl.itris.viewpoint.db.crm.Relation#1150053992, id=1150003793, organisationId=1500, bgColor=null, wtfIsThis=null, roleString=null, logDate=2007-04-23 00:00:00, logUser=VPC}
DEBUG - executing flush
DEBUG - registering flush begin
DEBUG - Inserting entity: [nl.itris.viewpoint.db.crm.UserGroupMember#1150003795]
DEBUG - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
DEBUG - insert into CRM_GROUPS_PERSONS (CGN_BGCOLOR, CGN_FGCOLOR, CGP_ID, CST_ID, CGN_ORDER, CGP_ROLE, CGN_TYPE, CST_ID_AANMELDER, CGN_ID) values (?, ?, ?, ?, ?, ?, ?, ?, ?)
DEBUG - preparing statement
DEBUG - Dehydrating entity: [nl.itris.viewpoint.db.crm.UserGroupMember#1150003795]
DEBUG - binding null to parameter: 1
DEBUG - binding null to parameter: 2
DEBUG - binding '1150000108' to parameter: 3
DEBUG - binding '1150057523' to parameter: 4
DEBUG - binding null to parameter: 5
DEBUG - binding null to parameter: 6
DEBUG - binding null to parameter: 7
DEBUG - binding null to parameter: 8
DEBUG - binding '1150003795' to parameter: 9
DEBUG - Executing batch size: 1
DEBUG - success of batch update unknown: 0
DEBUG - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
DEBUG - closing statement
DEBUG - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
DEBUG - select usergroupm_.LOG_DATE as LOG2_75_, usergroupm_.LOG_MODULE as LOG3_75_, usergroupm_.LOG_TIME as LOG4_75_, usergroupm_.LOG_USER as LOG5_75_, usergroupm_.TCN as TCN75_, usergroupm_.ROS_ID as ROS7_75_ from CRM_GROUPS_PERSONS usergroupm_ where usergroupm_.CGN_ID=?
DEBUG - preparing statement
DEBUG - binding '1150003795' to parameter: 1
DEBUG - about to open ResultSet (open ResultSets: 0, globally: 0)
DEBUG - returning '2007-04-23 00:00:00' as column: LOG2_75_
DEBUG - returning null as column: LOG3_75_
DEBUG - returning '12:13:05' as column: LOG4_75_
DEBUG - returning 'VPC' as column: LOG5_75_
DEBUG - returning '283796737' as column: TCN75_
DEBUG - returning '1500' as column: ROS7_75_
DEBUG - about to close ResultSet (open ResultSets: 1, globally: 1)
DEBUG - Updating entity: [nl.itris.viewpoint.db.crm.UserGroupMember#1150003795]
DEBUG - about to open PreparedStatement (open PreparedStatements: 1, globally: 1)
DEBUG - update CRM_GROUPS_PERSONS set TCN=?, ROS_ID=?, CGN_BGCOLOR=?, CGN_FGCOLOR=?, CGP_ID=?, CST_ID=?, CGN_ORDER=?, CGP_ROLE=?, CGN_TYPE=?, CST_ID_AANMELDER=? where CGN_ID=?
DEBUG - preparing statement
DEBUG - Dehydrating entity: [nl.itris.viewpoint.db.crm.UserGroupMember#1150003795]
DEBUG - binding null to parameter: 1
DEBUG - binding null to parameter: 2
DEBUG - binding null to parameter: 3
DEBUG - binding null to parameter: 4
DEBUG - binding '1150000108' to parameter: 5
DEBUG - binding '1150057523' to parameter: 6
DEBUG - binding '5' to parameter: 7
DEBUG - binding null to parameter: 8
DEBUG - binding null to parameter: 9
DEBUG - binding null to parameter: 10
DEBUG - binding '1150003795' to parameter: 11
DEBUG - Executing batch size: 1
DEBUG - about to close PreparedStatement (open PreparedStatements: 2, globally: 2)
DEBUG - closing statement
DEBUG - Could not execute JDBC batch update [update CRM_GROUPS_PERSONS set TCN=?, ROS_ID=?, CGN_BGCOLOR=?, CGN_FGCOLOR=?, CGP_ID=?, CST_ID=?, CGN_ORDER=?, CGP_ROLE=?, CGN_TYPE=?, CST_ID_AANMELDER=? where CGN_ID=?]
to.etc.dbpool.BetterSQLException: java.sql.BatchUpdateException: ORA-01407: cannot update ("VIEWPOINT"."CRM_GROUPS_PERSONS"."ROS_ID") to NULL
SQL: update CRM_GROUPS_PERSONS set TCN=?, ROS_ID=?, CGN_BGCOLOR=?, CGN_FGCOLOR=?, CGP_ID=?, CST_ID=?, CGN_ORDER=?, CGP_ROLE=?, CGN_TYPE=?, CST_ID_AANMELDER=? where CGN_ID=?
Parameters:
#1:[null]
#2:[null]
#3:[null]
#4:[null]
#5:java.lang.Long:1150000108
#6:java.lang.Long:1150057523
#7:java.lang.Integer:5
#8:[null]
#9:[null]
#10:[null]
#11:java.lang.Long:1150003795
What is noticeable in this log is that Hibernate seems to think that the single instance added requires both an insert and an update; the insert is probably due to the save() used in the code; the update seems to be caused by the call to setOrder()
after the save. That does not seem right; I would have expected that Hibernate has found that the whole record is new so changes to it after the save should not add an update??
Hibernate version: 3.2.3 and 3.2.0 also
Mapping documents: (Annotations 3.3.0)