I have a situation where I need to have disconnected objects from a session so that they can be edited in another layer and then sent back to Hibernate for persistence. I get this work as expected. However, I also want to record the changes to the object using an audit through a Hibernate Interceptor. If I find the object and then send the object (disconnected from a Session) to another layer and update it the Interceptor only works if I lock the object (unmodified) and then do the updates after the locking. If I just do a session.update without locking first it updates the object in the database however, the Interceptor does not write out the changes to the database. Is there a reason for this?
Here are my test cases with code and logging. The first set of code and logging does not invoke the Interceptor. The second set of code works correctly. However, I think it would be more convienent if I can just update the object and use update instead of locking the object and the modifiying before the update. The question is: Am I doing something wrong in the first case?
See how AuditLogInterceptor gets invoked in the log based on the different sets of code:
With session.update and no session.lock(order, LockMode.NONE);
Code:
public Order updateOrder(final Order order) {
return (Order) getHibernateTemplate().execute(new HibernateCallback() {
public Object doInHibernate(Session session)
throws HibernateException, SQLException {
session.update(order);
return order;
}
});
}
2004-03-17 07:41:06,286 DEBUG hibernate.impl.SessionImpl:1411 -> updating [com.meagle.bo.Order#1]
2004-03-17 07:41:06,286 DEBUG hibernate.engine.Cascades:497 -> processing cascades for: com.meagle.bo.Order
2004-03-17 07:41:06,286 DEBUG hibernate.engine.Cascades:524 -> cascading to collection: com.meagle.bo.Order.orderLineItems
2004-03-17 07:41:06,286 DEBUG hibernate.engine.Cascades:113 -> cascading to saveOrUpdate()
2004-03-17 07:41:06,286 DEBUG hibernate.engine.Cascades:312 -> id unsaved-value: 0
2004-03-17 07:41:06,302 DEBUG hibernate.impl.SessionImpl:1363 -> saveOrUpdate() previously saved instance with id: 1
2004-03-17 07:41:06,302 DEBUG hibernate.impl.SessionImpl:1411 -> updating [com.meagle.bo.OrderLineItem#1]
2004-03-17 07:41:06,302 DEBUG hibernate.engine.Cascades:524 -> cascading to collection: com.meagle.bo.Order.audits
2004-03-17 07:41:06,302 DEBUG hibernate.engine.Cascades:506 -> done processing cascades for: com.meagle.bo.Order
2004-03-17 07:41:06,302 DEBUG transaction.interceptor.TransactionInterceptor:171 -> Invoking commit for transaction on method 'saveNewOrder' in class [com.meagle.service.IOrderService]
2004-03-17 07:41:06,302 DEBUG orm.hibernate.HibernateTransactionManager:400 -> Triggering beforeCommit synchronization
2004-03-17 07:41:06,302 DEBUG orm.hibernate.HibernateTransactionManager:415 -> Triggering beforeCompletion synchronization
2004-03-17 07:41:06,302 INFO orm.hibernate.HibernateTransactionManager:301 -> Initiating transaction commit
2004-03-17 07:41:06,302 DEBUG orm.hibernate.HibernateTransactionManager:335 -> Committing Hibernate transaction on session [net.sf.hibernate.impl.SessionImpl@646bfb]
2004-03-17 07:41:06,302 DEBUG hibernate.transaction.JDBCTransaction:59 -> commit
2004-03-17 07:41:06,302 DEBUG hibernate.impl.SessionImpl:2210 -> flushing session
2004-03-17 07:41:06,317 DEBUG hibernate.engine.Cascades:497 -> processing cascades for: com.meagle.bo.Order
2004-03-17 07:41:06,317 DEBUG hibernate.engine.Cascades:524 -> cascading to collection: com.meagle.bo.Order.orderLineItems
2004-03-17 07:41:06,317 DEBUG hibernate.engine.Cascades:113 -> cascading to saveOrUpdate()
2004-03-17 07:41:06,317 DEBUG hibernate.impl.SessionImpl:1343 -> saveOrUpdate() persistent instance
2004-03-17 07:41:06,317 DEBUG hibernate.engine.Cascades:524 -> cascading to collection: com.meagle.bo.Order.audits
2004-03-17 07:41:06,317 DEBUG hibernate.engine.Cascades:506 -> done processing cascades for: com.meagle.bo.Order
2004-03-17 07:41:06,317 DEBUG hibernate.impl.SessionImpl:2403 -> Flushing entities and processing referenced collections
2004-03-17 07:41:06,317 DEBUG hibernate.impl.SessionImpl:2497 -> Updating entity: [com.meagle.bo.Order#1]
2004-03-17 07:41:17,062 DEBUG hibernate.engine.Versioning:26 -> Incrementing: 2004-03-17 07:40:02.13 to 2004-03-17 07:41:17.062
2004-03-17 07:41:17,062 DEBUG hibernate.impl.SessionImpl:2850 -> Collection found: [com.meagle.bo.Order.orderLineItems#1], was: [com.meagle.bo.Order.orderLineItems#1]
2004-03-17 07:41:17,062 DEBUG hibernate.impl.SessionImpl:2850 -> Collection found: [com.meagle.bo.Order.audits#1], was: [com.meagle.bo.Order.audits#1]
2004-03-17 07:41:17,062 DEBUG hibernate.impl.SessionImpl:2497 -> Updating entity: [com.meagle.bo.OrderLineItem#1]
2004-03-17 07:41:18,657 DEBUG hibernate.impl.SessionImpl:2746 -> Processing unreferenced collections
2004-03-17 07:41:18,657 DEBUG hibernate.impl.SessionImpl:2760 -> Scheduling collection removes/(re)creates/updates
2004-03-17 07:41:18,657 DEBUG hibernate.impl.SessionImpl:2234 -> Flushed: 0 insertions, 2 updates, 0 deletions to 2 objects
2004-03-17 07:41:18,657 DEBUG hibernate.impl.SessionImpl:2239 -> Flushed: 0 (re)creations, 0 updates, 0 removals to 2 collections
2004-03-17 07:41:18,657 DEBUG hibernate.impl.Printer:75 -> listing entities:
2004-03-17 07:41:18,657 DEBUG hibernate.impl.Printer:82 -> com.meagle.bo.OrderLineItem{lineItemPrice=33333.0, order=Order#1, description=BaseBall, id=1}
2004-03-17 07:41:18,657 DEBUG hibernate.impl.Printer:82 -> com.meagle.bo.Order{orderLineItems=[OrderLineItem#1], audits=uninitialized, total=33333.0, userName=Tim3, timestamp=17 March 2004 07:40:02, id=1}
2004-03-17 07:41:18,657 DEBUG hibernate.impl.SessionImpl:2323 -> executing flush
2004-03-17 07:41:18,673 DEBUG hibernate.persister.EntityPersister:647 -> Updating entity: [com.meagle.bo.Order#1]
2004-03-17 07:41:18,673 DEBUG hibernate.persister.EntityPersister:648 -> Existing version: 2004-03-17 07:40:02.13 -> New version: 2004-03-17 07:41:17.062
2004-03-17 07:41:18,673 DEBUG hibernate.impl.BatcherImpl:196 -> about to open: 0 open PreparedStatements, 0 open ResultSets
2004-03-17 07:41:18,673 DEBUG sf.hibernate.SQL:237 -> update TestOrder set ModifiedTS=?, UserName=?, Total=? where Order_ID=? and ModifiedTS=?
Hibernate: update TestOrder set ModifiedTS=?, UserName=?, Total=? where Order_ID=? and ModifiedTS=?
2004-03-17 07:41:18,673 DEBUG hibernate.impl.BatcherImpl:241 -> preparing statement
2004-03-17 07:41:18,673 DEBUG hibernate.persister.EntityPersister:388 -> Dehydrating entity: [com.meagle.bo.Order#1]
2004-03-17 07:41:18,673 DEBUG hibernate.type.TimestampType:46 -> binding '17 March 2004 07:41:17' to parameter: 1
2004-03-17 07:41:18,673 DEBUG hibernate.type.StringType:46 -> binding 'Tim3' to parameter: 2
2004-03-17 07:41:18,688 DEBUG hibernate.type.DoubleType:46 -> binding '33333.0' to parameter: 3
2004-03-17 07:41:18,688 DEBUG hibernate.type.IntegerType:46 -> binding '1' to parameter: 4
2004-03-17 07:41:18,688 DEBUG hibernate.type.TimestampType:46 -> binding '17 March 2004 07:40:02' to parameter: 5
2004-03-17 07:41:18,688 DEBUG hibernate.impl.BatcherImpl:203 -> done closing: 0 open PreparedStatements, 0 open ResultSets
2004-03-17 07:41:18,688 DEBUG hibernate.impl.BatcherImpl:261 -> closing statement
2004-03-17 07:41:18,688 DEBUG hibernate.persister.EntityPersister:647 -> Updating entity: [com.meagle.bo.OrderLineItem#1]
2004-03-17 07:41:18,688 DEBUG hibernate.impl.BatcherImpl:196 -> about to open: 0 open PreparedStatements, 0 open ResultSets
2004-03-17 07:41:18,704 DEBUG sf.hibernate.SQL:237 -> update TestOrderLineItem set Order_ID=?, Description=?, LineItemPrice=? where OrderLineItem_ID=?
Hibernate: update TestOrderLineItem set Order_ID=?, Description=?, LineItemPrice=? where OrderLineItem_ID=?
2004-03-17 07:41:18,704 DEBUG hibernate.impl.BatcherImpl:241 -> preparing statement
2004-03-17 07:41:18,704 DEBUG hibernate.persister.EntityPersister:388 -> Dehydrating entity: [com.meagle.bo.OrderLineItem#1]
2004-03-17 07:41:18,704 DEBUG hibernate.type.IntegerType:46 -> binding '1' to parameter: 1
2004-03-17 07:41:18,704 DEBUG hibernate.type.StringType:46 -> binding 'BaseBall' to parameter: 2
2004-03-17 07:41:18,704 DEBUG hibernate.type.DoubleType:46 -> binding '33333.0' to parameter: 3
2004-03-17 07:41:18,704 DEBUG hibernate.type.IntegerType:46 -> binding '1' to parameter: 4
2004-03-17 07:41:18,720 DEBUG hibernate.impl.BatcherImpl:203 -> done closing: 0 open PreparedStatements, 0 open ResultSets
2004-03-17 07:41:18,720 DEBUG hibernate.impl.BatcherImpl:261 -> closing statement
2004-03-17 07:41:18,720 DEBUG hibernate.impl.SessionImpl:2790 -> post flush
2004-03-17 07:41:18,720 INFO hibernate.interceptor.
AuditLogInterceptor:159 -> element: com.meagle.bo.OrderLineItem@664795
2004-03-17 07:41:29,432 INFO hibernate.interceptor.
AuditLogInterceptor:159 -> element: com.meagle.bo.Order@e3f35f30
2004-03-17 07:41:29,432 DEBUG hibernate.impl.SessionImpl:561 -> transaction completion
2004-03-17 07:41:29,432 DEBUG orm.hibernate.HibernateTransactionManager:433 -> Triggering afterCompletion synchronization
2004-03-17 07:41:29,432 DEBUG transaction.support.TransactionSynchronizationManager:187 -> Clearing transaction synchronization
2004-03-17 07:41:29,447 DEBUG transaction.support.TransactionSynchronizationManager:123 -> Removed value [org.springframework.orm.hibernate.SessionHolder@6d3b53] for key [net.sf.hibernate.impl.SessionFactoryImpl@48083b] from thread [http8080-Processor4]
2004-03-17 07:41:29,447 DEBUG orm.hibernate.HibernateTransactionManager:428 -> Closing Hibernate session [net.sf.hibernate.impl.SessionImpl@646bfb] after transaction
2004-03-17 07:41:29,447 DEBUG orm.hibernate.SessionFactoryUtils:190 -> Closing Hibernate session
2004-03-17 07:41:29,447 DEBUG hibernate.impl.SessionImpl:549 -> closing session
2004-03-17 07:41:29,447 DEBUG hibernate.impl.SessionImpl:3294 -> disconnecting session
2004-03-17 07:41:29,447 DEBUG logicalcobwebs.proxool.spring:283 -> #1 - autoCommit reset back to true
2004-03-17 07:41:29,447 DEBUG hibernate.impl.SessionImpl:561 -> transaction completion
With session.update and no session.lock(order, LockMode.NONE); and an update to the object after the session.lock
Code:
public Order saveOrder(final Order order) {
return (Order) getHibernateTemplate().execute(new HibernateCallback() {
public Object doInHibernate(Session session)
throws HibernateException, SQLException {
session.lock(order, LockMode.NONE);
order.setUserName("Mark");
session.update(order);
return order;
}
});
}
2004-03-17 07:45:18,175 DEBUG hibernate.impl.SessionImpl:1312 -> object already associated with session
2004-03-17 07:45:18,175 DEBUG transaction.interceptor.TransactionInterceptor:171 -> Invoking commit for transaction on method 'saveNewOrder' in class [com.meagle.service.IOrderService]
2004-03-17 07:45:18,175 DEBUG orm.hibernate.HibernateTransactionManager:400 -> Triggering beforeCommit synchronization
2004-03-17 07:45:18,175 DEBUG orm.hibernate.HibernateTransactionManager:415 -> Triggering beforeCompletion synchronization
2004-03-17 07:45:18,175 INFO orm.hibernate.HibernateTransactionManager:301 -> Initiating transaction commit
2004-03-17 07:45:18,175 DEBUG orm.hibernate.HibernateTransactionManager:335 -> Committing Hibernate transaction on session [net.sf.hibernate.impl.SessionImpl@12de02]
2004-03-17 07:45:18,175 DEBUG hibernate.transaction.JDBCTransaction:59 -> commit
2004-03-17 07:45:18,175 DEBUG hibernate.impl.SessionImpl:2210 -> flushing session
2004-03-17 07:45:18,190 DEBUG hibernate.engine.Cascades:497 -> processing cascades for: com.meagle.bo.Order
2004-03-17 07:45:18,190 DEBUG hibernate.engine.Cascades:524 -> cascading to collection: com.meagle.bo.Order.orderLineItems
2004-03-17 07:45:18,190 DEBUG hibernate.engine.Cascades:113 -> cascading to saveOrUpdate()
2004-03-17 07:45:18,190 DEBUG hibernate.impl.SessionImpl:1343 -> saveOrUpdate() persistent instance
2004-03-17 07:45:18,190 DEBUG hibernate.engine.Cascades:524 -> cascading to collection: com.meagle.bo.Order.audits
2004-03-17 07:45:18,190 DEBUG hibernate.engine.Cascades:506 -> done processing cascades for: com.meagle.bo.Order
2004-03-17 07:45:18,190 DEBUG hibernate.impl.SessionImpl:2403 -> Flushing entities and processing referenced collections
2004-03-17 07:45:18,206 DEBUG hibernate.persister.AbstractEntityPersister:275 -> com.meagle.bo.Order.userName is dirty
2004-03-17 07:45:18,206 DEBUG hibernate.impl.SessionImpl:2497 -> Updating entity: [com.meagle.bo.Order#1]
2004-03-17 07:45:20,958 DEBUG transaction.support.TransactionSynchronizationManager:90 -> Retrieved value [org.springframework.orm.hibernate.SessionHolder@2d80ae] for key [net.sf.hibernate.impl.SessionFactoryImpl@b4ccb] bound to thread [http8080-Processor2]
2004-03-17 07:45:20,974 DEBUG hibernate.impl.SessionImpl:531 -> opened session
2004-03-17 07:45:22,616 DEBUG hibernate.impl.SessionImpl:3218 -> initializing collection [com.meagle.bo.Order.audits#1]
2004-03-17 07:45:22,632 DEBUG hibernate.impl.SessionImpl:3219 -> checking second-level cache
2004-03-17 07:45:22,632 DEBUG hibernate.impl.SessionImpl:3225 -> collection not cached
2004-03-17 07:45:22,632 DEBUG hibernate.impl.BatcherImpl:196 -> about to open: 0 open PreparedStatements, 0 open ResultSets
2004-03-17 07:45:22,632 DEBUG sf.hibernate.SQL:237 -> select audits0_.OrderAudit_ID as OrderAud1___, audits0_.Order_ID as Order_ID__, audits0_.OrderAudit_ID as Abstract1_0_, audits0_.Order_ID as Order_ID3_0_, audits0__1_.propertyValues as property2_2_0_, audits0__1_.UserName as UserName2_0_, audits0__1_.PropertyName as Property4_2_0_ from TestOrderAudit audits0_ inner join TestAbstractAudit audits0__1_ on audits0_.OrderAudit_ID=audits0__1_.AbstractAudit_ID where audits0_.Order_ID=?
Hibernate: select audits0_.OrderAudit_ID as OrderAud1___, audits0_.Order_ID as Order_ID__, audits0_.OrderAudit_ID as Abstract1_0_, audits0_.Order_ID as Order_ID3_0_, audits0__1_.propertyValues as property2_2_0_, audits0__1_.UserName as UserName2_0_, audits0__1_.PropertyName as Property4_2_0_ from TestOrderAudit audits0_ inner join TestAbstractAudit audits0__1_ on audits0_.OrderAudit_ID=audits0__1_.AbstractAudit_ID where audits0_.Order_ID=?
2004-03-17 07:45:22,632 DEBUG hibernate.impl.BatcherImpl:241 -> preparing statement
2004-03-17 07:45:22,788 DEBUG hibernate.type.IntegerType:46 -> binding '1' to parameter: 1
2004-03-17 07:45:22,788 DEBUG hibernate.loader.Loader:327 -> result set contains (possibly empty) collection: [com.meagle.bo.Order.audits#1]
2004-03-17 07:45:22,788 DEBUG hibernate.impl.SessionImpl:2984 -> uninitialized collection: initializing
2004-03-17 07:45:22,788 DEBUG hibernate.loader.Loader:197 -> processing result set
2004-03-17 07:45:22,788 DEBUG hibernate.type.IntegerType:68 -> returning '1' as column: Abstract1_0_
2004-03-17 07:45:22,804 DEBUG hibernate.loader.Loader:405 -> result row: 1
2004-03-17 07:45:22,804 DEBUG hibernate.loader.Loader:536 -> Initializing object from ResultSet: 1
2004-03-17 07:45:22,804 DEBUG hibernate.loader.Loader:605 -> Hydrating entity: com.meagle.bo.OrderAudit#1
2004-03-17 07:45:22,804 DEBUG hibernate.type.IntegerType:68 -> returning '1' as column: Order_ID3_0_
2004-03-17 07:45:22,804 DEBUG hibernate.type.StringType:68 -> returning '33333.0' as column: property2_2_0_
2004-03-17 07:45:22,804 DEBUG hibernate.type.StringType:68 -> returning 'created by Test User' as column: UserName2_0_
2004-03-17 07:45:22,804 DEBUG hibernate.type.StringType:68 -> returning 'total' as column: Property4_2_0_
2004-03-17 07:45:22,804 DEBUG hibernate.type.IntegerType:68 -> returning '1' as column: Order_ID__
2004-03-17 07:45:22,804 DEBUG hibernate.loader.Loader:292 -> found row of collection: [com.meagle.bo.Order.audits#1]
2004-03-17 07:45:22,804 DEBUG hibernate.impl.SessionImpl:3007 -> reading row
2004-03-17 07:45:22,804 DEBUG hibernate.type.IntegerType:68 -> returning '1' as column: OrderAud1___
2004-03-17 07:45:22,804 DEBUG hibernate.impl.SessionImpl:1950 -> loading [com.meagle.bo.OrderAudit#1]
2004-03-17 07:45:22,804 DEBUG hibernate.impl.SessionImpl:2047 -> attempting to resolve [com.meagle.bo.OrderAudit#1]
2004-03-17 07:45:22,819 DEBUG hibernate.impl.SessionImpl:2063 -> resolved object in session cache [com.meagle.bo.OrderAudit#1]
2004-03-17 07:45:22,819 DEBUG hibernate.type.IntegerType:68 -> returning '2' as column: Abstract1_0_
2004-03-17 07:45:22,819 DEBUG hibernate.loader.Loader:405 -> result row: 2
2004-03-17 07:45:22,819 DEBUG hibernate.loader.Loader:536 -> Initializing object from ResultSet: 2
2004-03-17 07:45:22,819 DEBUG hibernate.loader.Loader:605 -> Hydrating entity: com.meagle.bo.OrderAudit#2
2004-03-17 07:45:22,819 DEBUG hibernate.type.IntegerType:68 -> returning '1' as column: Order_ID3_0_
2004-03-17 07:45:22,819 DEBUG hibernate.type.StringType:68 -> returning 'Test User' as column: property2_2_0_
2004-03-17 07:45:22,819 DEBUG hibernate.type.StringType:68 -> returning 'created by Test User' as column: UserName2_0_
2004-03-17 07:45:22,819 DEBUG hibernate.type.StringType:68 -> returning 'userName' as column: Property4_2_0_
2004-03-17 07:45:22,819 DEBUG hibernate.type.IntegerType:68 -> returning '1' as column: Order_ID__
2004-03-17 07:45:22,835 DEBUG hibernate.loader.Loader:292 -> found row of collection: [com.meagle.bo.Order.audits#1]
2004-03-17 07:45:22,835 DEBUG hibernate.impl.SessionImpl:3007 -> reading row
2004-03-17 07:45:22,835 DEBUG hibernate.type.IntegerType:68 -> returning '2' as column: OrderAud1___
2004-03-17 07:45:22,835 DEBUG hibernate.impl.SessionImpl:1950 -> loading [com.meagle.bo.OrderAudit#2]
2004-03-17 07:45:22,835 DEBUG hibernate.impl.SessionImpl:2047 -> attempting to resolve [com.meagle.bo.OrderAudit#2]
2004-03-17 07:45:22,835 DEBUG hibernate.impl.SessionImpl:2063 -> resolved object in session cache [com.meagle.bo.OrderAudit#2]
2004-03-17 07:45:22,851 DEBUG hibernate.type.IntegerType:68 -> returning '3' as column: Abstract1_0_
2004-03-17 07:45:22,851 DEBUG hibernate.loader.Loader:405 -> result row: 3
2004-03-17 07:45:22,851 DEBUG hibernate.loader.Loader:536 -> Initializing object from ResultSet: 3
2004-03-17 07:45:22,851 DEBUG hibernate.loader.Loader:605 -> Hydrating entity: com.meagle.bo.OrderAudit#3
2004-03-17 07:45:22,851 DEBUG hibernate.type.IntegerType:68 -> returning '1' as column: Order_ID3_0_
2004-03-17 07:45:22,851 DEBUG hibernate.type.StringType:68 -> returning 'Test User34->Tim' as column: property2_2_0_
2004-03-17 07:45:22,851 DEBUG hibernate.type.StringType:68 -> returning 'updated by Tim' as column: UserName2_0_
2004-03-17 07:45:22,851 DEBUG hibernate.type.StringType:68 -> returning 'userName' as column: Property4_2_0_
2004-03-17 07:45:22,851 DEBUG hibernate.type.IntegerType:68 -> returning '1' as column: Order_ID__
2004-03-17 07:45:22,851 DEBUG hibernate.loader.Loader:292 -> found row of collection: [com.meagle.bo.Order.audits#1]
2004-03-17 07:45:22,851 DEBUG hibernate.impl.SessionImpl:3007 -> reading row
2004-03-17 07:45:22,851 DEBUG hibernate.type.IntegerType:68 -> returning '3' as column: OrderAud1___
2004-03-17 07:45:22,851 DEBUG hibernate.impl.SessionImpl:1950 -> loading [com.meagle.bo.OrderAudit#3]
2004-03-17 07:45:22,866 DEBUG hibernate.impl.SessionImpl:2047 -> attempting to resolve [com.meagle.bo.OrderAudit#3]
2004-03-17 07:45:22,866 DEBUG hibernate.impl.SessionImpl:2063 -> resolved object in session cache [com.meagle.bo.OrderAudit#3]
2004-03-17 07:45:22,866 DEBUG hibernate.loader.Loader:226 -> done processing result set (3 rows)
2004-03-17 07:45:22,866 DEBUG hibernate.impl.BatcherImpl:203 -> done closing: 0 open PreparedStatements, 0 open ResultSets
2004-03-17 07:45:22,866 DEBUG hibernate.impl.BatcherImpl:261 -> closing statement
2004-03-17 07:45:22,866 DEBUG hibernate.loader.Loader:239 -> total objects hydrated: 3
2004-03-17 07:45:22,866 DEBUG hibernate.impl.SessionImpl:2166 -> resolving associations for [com.meagle.bo.OrderAudit#1]
2004-03-17 07:45:22,866 DEBUG hibernate.impl.SessionImpl:1950 -> loading [com.meagle.bo.Order#1]
2004-03-17 07:45:22,866 DEBUG hibernate.impl.SessionImpl:2047 -> attempting to resolve [com.meagle.bo.Order#1]
2004-03-17 07:45:22,866 DEBUG hibernate.impl.SessionImpl:2063 -> resolved object in session cache [com.meagle.bo.Order#1]
2004-03-17 07:45:22,866 DEBUG hibernate.impl.SessionImpl:2190 -> done materializing entity [com.meagle.bo.OrderAudit#1]
2004-03-17 07:45:22,882 DEBUG hibernate.impl.SessionImpl:2166 -> resolving associations for [com.meagle.bo.OrderAudit#2]
2004-03-17 07:45:22,882 DEBUG hibernate.impl.SessionImpl:1950 -> loading [com.meagle.bo.Order#1]
2004-03-17 07:45:22,882 DEBUG hibernate.impl.SessionImpl:2047 -> attempting to resolve [com.meagle.bo.Order#1]
2004-03-17 07:45:22,882 DEBUG hibernate.impl.SessionImpl:2063 -> resolved object in session cache [com.meagle.bo.Order#1]
2004-03-17 07:45:22,882 DEBUG hibernate.impl.SessionImpl:2190 -> done materializing entity [com.meagle.bo.OrderAudit#2]
2004-03-17 07:45:22,882 DEBUG hibernate.impl.SessionImpl:2166 -> resolving associations for [com.meagle.bo.OrderAudit#3]
2004-03-17 07:45:22,882 DEBUG hibernate.impl.SessionImpl:1950 -> loading [com.meagle.bo.Order#1]
2004-03-17 07:45:22,882 DEBUG hibernate.impl.SessionImpl:2047 -> attempting to resolve [com.meagle.bo.Order#1]
2004-03-17 07:45:22,882 DEBUG hibernate.impl.SessionImpl:2063 -> resolved object in session cache [com.meagle.bo.Order#1]
2004-03-17 07:45:22,882 DEBUG hibernate.impl.SessionImpl:2190 -> done materializing entity [com.meagle.bo.OrderAudit#3]
2004-03-17 07:45:22,882 DEBUG hibernate.impl.SessionImpl:3043 -> 1 collections were found in result set
2004-03-17 07:45:22,882 DEBUG hibernate.impl.SessionImpl:3061 -> collection fully initialized: [com.meagle.bo.Order.audits#1]
2004-03-17 07:45:22,882 DEBUG hibernate.impl.SessionImpl:3064 -> 1 collections initialized
2004-03-17 07:45:22,882 DEBUG hibernate.impl.SessionImpl:3082 -> initializing non-lazy collections
2004-03-17 07:45:22,898 DEBUG hibernate.impl.SessionImpl:3227 -> collection initialized
2004-03-17 07:45:22,898 DEBUG hibernate.impl.SessionImpl:807 -> saving [com.meagle.bo.OrderAudit#<null>]
2004-03-17 07:45:22,898 DEBUG hibernate.impl.SessionImpl:2273 ->
executing insertions2004-03-17 07:45:22,898 DEBUG hibernate.engine.Cascades:385 -> version unsaved-value strategy NULL
2004-03-17 07:45:22,898 DEBUG hibernate.persister.NormalizedEntityPersister:486 -> Inserting entity: com.meagle.bo.OrderAudit (native id)
2004-03-17 07:45:22,898 DEBUG hibernate.impl.BatcherImpl:196 -> about to open: 0 open PreparedStatements, 0 open ResultSets
2004-03-17 07:45:22,898 DEBUG sf.hibernate.SQL:237 -> insert into TestAbstractAudit (propertyValues, UserName, PropertyName, AbstractAudit_ID) values (?, ?, ?, default)
Hibernate: insert into TestAbstractAudit (propertyValues, UserName, PropertyName, AbstractAudit_ID) values (?, ?, ?, default)
2004-03-17 07:45:22,898 DEBUG hibernate.impl.BatcherImpl:241 -> preparing statement
2004-03-17 07:45:22,913 DEBUG hibernate.type.StringType:46 -> binding 'Timmmmy->Mark' to parameter: 1
2004-03-17 07:45:22,913 DEBUG hibernate.type.StringType:46 -> binding 'updated by Mark' to parameter: 2
2004-03-17 07:45:22,913 DEBUG hibernate.type.StringType:46 -> binding 'userName' to parameter: 3
2004-03-17 07:45:22,913 DEBUG hibernate.impl.BatcherImpl:203 -> done closing: 0 open PreparedStatements, 0 open ResultSets
2004-03-17 07:45:22,913 DEBUG hibernate.impl.BatcherImpl:261 -> closing statement
2004-03-17 07:45:22,929 DEBUG hibernate.impl.BatcherImpl:196 -> about to open: 0 open PreparedStatements, 0 open ResultSets
2004-03-17 07:45:22,929 DEBUG sf.hibernate.SQL:237 -> values IDENTITY_VAL_LOCAL()
Hibernate: values IDENTITY_VAL_LOCAL()
2004-03-17 07:45:22,929 DEBUG hibernate.impl.BatcherImpl:241 -> preparing statement
2004-03-17 07:45:22,929 DEBUG hibernate.persister.AbstractEntityPersister:1230 -> Natively generated identity: 4
2004-03-17 07:45:22,944 DEBUG hibernate.impl.BatcherImpl:203 -> done closing: 0 open PreparedStatements, 0 open ResultSets
2004-03-17 07:45:22,944 DEBUG hibernate.impl.BatcherImpl:261 -> closing statement
2004-03-17 07:45:22,944 DEBUG hibernate.impl.BatcherImpl:196 -> about to open: 0 open PreparedStatements, 0 open ResultSets
2004-03-17 07:45:22,944 DEBUG sf.hibernate.SQL:237 -> insert into TestOrderAudit (Order_ID, OrderAudit_ID) values (?, ?)
Hibernate: insert into TestOrderAudit (Order_ID, OrderAudit_ID) values (?, ?)
2004-03-17 07:45:22,944 DEBUG hibernate.impl.BatcherImpl:241 -> preparing statement
2004-03-17 07:45:22,944 DEBUG hibernate.engine.Cascades:385 -> version unsaved-value strategy NULL
2004-03-17 07:45:22,944 DEBUG hibernate.type.IntegerType:46 -> binding '1' to parameter: 1
2004-03-17 07:45:22,944 DEBUG hibernate.type.IntegerType:46 -> binding '4' to parameter: 2
2004-03-17 07:45:22,960 DEBUG hibernate.impl.BatcherImpl:203 -> done closing: 0 open PreparedStatements, 0 open ResultSets
2004-03-17 07:45:22,960 DEBUG hibernate.impl.BatcherImpl:261 -> closing statement
2004-03-17 07:45:22,960 DEBUG hibernate.impl.SessionImpl:2210 -> flushing session
2004-03-17 07:45:22,960 DEBUG hibernate.impl.SessionImpl:2403 -> Flushing entities and processing referenced collections
2004-03-17 07:45:22,960 DEBUG hibernate.impl.SessionImpl:2746 -> Processing unreferenced collections
2004-03-17 07:45:22,960 DEBUG hibernate.impl.SessionImpl:2760 -> Scheduling collection removes/(re)creates/updates
2004-03-17 07:45:22,960 DEBUG hibernate.impl.SessionImpl:2234 -> Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
2004-03-17 07:45:22,976 DEBUG hibernate.impl.SessionImpl:2239 -> Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
2004-03-17 07:45:22,976 DEBUG hibernate.impl.Printer:75 -> listing entities:
2004-03-17 07:45:22,976 DEBUG hibernate.impl.Printer:82 -> com.meagle.bo.OrderAudit{propertyValues=Timmmmy->Mark, order=Order#1, propertyName=userName, userName=updated by Mark, id=4}
2004-03-17 07:45:22,976 DEBUG hibernate.impl.SessionImpl:2323 -> executing flush
2004-03-17 07:45:22,976 DEBUG hibernate.impl.SessionImpl:2790 -> post flush
2004-03-17 07:45:22,976 INFO hibernate.interceptor.
AuditLogInterceptor:159 -> element: com.meagle.bo.OrderAudit@3d5f21
2004-03-17 07:45:22,976 DEBUG hibernate.impl.SessionImpl:549 -> closing session
2004-03-17 07:45:22,976 DEBUG hibernate.impl.SessionImpl:3294 -> disconnecting session
2004-03-17 07:45:22,976 DEBUG hibernate.impl.SessionImpl:561 -> transaction completion
2004-03-17 07:45:22,976 DEBUG hibernate.engine.Versioning:26 -> Incrementing: 2004-03-17 07:41:17.062 to 2004-03-17 07:45:22.976
2004-03-17 07:45:22,991 DEBUG hibernate.impl.SessionImpl:2850 -> Collection found: [com.meagle.bo.Order.orderLineItems#1], was: [com.meagle.bo.Order.orderLineItems#1]
2004-03-17 07:45:22,991 DEBUG hibernate.impl.SessionImpl:2850 -> Collection found: [com.meagle.bo.Order.audits#1], was: [com.meagle.bo.Order.audits#1]
2004-03-17 07:45:22,991 DEBUG hibernate.impl.SessionImpl:2746 -> Processing unreferenced collections
2004-03-17 07:45:22,991 DEBUG hibernate.impl.SessionImpl:2760 -> Scheduling collection removes/(re)creates/updates
2004-03-17 07:45:22,991 DEBUG hibernate.impl.SessionImpl:2234 -> Flushed: 0 insertions, 1 updates, 0 deletions to 5 objects
2004-03-17 07:45:22,991 DEBUG hibernate.impl.SessionImpl:2239 -> Flushed: 0 (re)creations, 1 updates, 0 removals to 2 collections
2004-03-17 07:45:23,007 DEBUG hibernate.impl.Printer:75 -> listing entities:
2004-03-17 07:45:23,007 DEBUG hibernate.impl.Printer:82 -> com.meagle.bo.OrderAudit{propertyValues=Test User34->Tim, order=Order#1, propertyName=userName, userName=updated by Tim, id=3}
2004-03-17 07:45:23,007 DEBUG hibernate.impl.Printer:82 -> com.meagle.bo.OrderAudit{propertyValues=Test User, order=Order#1, propertyName=userName, userName=created by Test User, id=2}
2004-03-17 07:45:23,007 DEBUG hibernate.impl.Printer:82 -> com.meagle.bo.OrderAudit{propertyValues=33333.0, order=Order#1, propertyName=total, userName=created by Test User, id=1}
2004-03-17 07:45:23,007 DEBUG hibernate.impl.Printer:82 -> com.meagle.bo.OrderLineItem{lineItemPrice=33333.0, order=Order#1, description=BaseBall, id=1}
2004-03-17 07:45:23,007 DEBUG hibernate.impl.Printer:82 -> com.meagle.bo.Order{orderLineItems=[OrderLineItem#1], audits=[OrderAudit#2, OrderAudit#4, OrderAudit#3, OrderAudit#1], total=33333.0, userName=Mark, timestamp=17 March 2004 07:41:17, id=1}
2004-03-17 07:45:23,007 DEBUG hibernate.impl.SessionImpl:2323 -> executing flush
2004-03-17 07:45:23,007 DEBUG hibernate.persister.EntityPersister:647 -> Updating entity: [com.meagle.bo.Order#1]
2004-03-17 07:45:23,007 DEBUG hibernate.persister.EntityPersister:648 -> Existing version: 2004-03-17 07:41:17.062 -> New version: 2004-03-17 07:45:22.976
2004-03-17 07:45:23,007 DEBUG hibernate.impl.BatcherImpl:196 -> about to open: 0 open PreparedStatements, 0 open ResultSets
2004-03-17 07:45:23,007 DEBUG sf.hibernate.SQL:237 -> update TestOrder set ModifiedTS=?, UserName=?, Total=? where Order_ID=? and ModifiedTS=?
Hibernate: update TestOrder set ModifiedTS=?, UserName=?, Total=? where Order_ID=? and ModifiedTS=?
2004-03-17 07:45:23,007 DEBUG hibernate.impl.BatcherImpl:241 -> preparing statement
2004-03-17 07:45:23,007 DEBUG hibernate.persister.EntityPersister:388 -> Dehydrating entity: [com.meagle.bo.Order#1]
2004-03-17 07:45:23,023 DEBUG hibernate.type.TimestampType:46 -> binding '17 March 2004 07:45:22' to parameter: 1
2004-03-17 07:45:23,023 DEBUG hibernate.type.StringType:46 -> binding 'Mark' to parameter: 2
2004-03-17 07:45:23,023 DEBUG hibernate.type.DoubleType:46 -> binding '33333.0' to parameter: 3
2004-03-17 07:45:23,023 DEBUG hibernate.type.IntegerType:46 -> binding '1' to parameter: 4
2004-03-17 07:45:23,023 DEBUG hibernate.type.TimestampType:46 -> binding '17 March 2004 07:41:17' to parameter: 5
2004-03-17 07:45:23,023 DEBUG hibernate.impl.BatcherImpl:203 -> done closing: 0 open PreparedStatements, 0 open ResultSets
2004-03-17 07:45:23,023 DEBUG hibernate.impl.BatcherImpl:261 -> closing statement
2004-03-17 07:45:23,023 DEBUG hibernate.impl.SessionImpl:2790 -> post flush
2004-03-17 07:45:23,023 INFO hibernate.interceptor.
AuditLogInterceptor:159 -> element: com.meagle.bo.OrderAudit@51630a
2004-03-17 07:45:23,023 INFO hibernate.interceptor.
AuditLogInterceptor:159 -> element: com.meagle.bo.OrderAudit@242c31
2004-03-17 07:45:23,023 INFO hibernate.interceptor.
AuditLogInterceptor:159 -> element: com.meagle.bo.OrderAudit@1bd13
2004-03-17 07:45:23,023 INFO hibernate.interceptor.
AuditLogInterceptor:159 -> element: com.meagle.bo.OrderLineItem@50e2c9
2004-03-17 07:45:24,586 INFO hibernate.interceptor.
AuditLogInterceptor:159 -> element: com.meagle.bo.Order@e3f01362
2004-03-17 07:45:24,602 DEBUG hibernate.impl.SessionImpl:561 -> transaction completion
2004-03-17 07:45:24,602 DEBUG orm.hibernate.HibernateTransactionManager:433 -> Triggering afterCompletion synchronization
2004-03-17 07:45:24,602 DEBUG transaction.support.TransactionSynchronizationManager:187 -> Clearing transaction synchronization
2004-03-17 07:45:24,602 DEBUG transaction.support.TransactionSynchronizationManager:123 -> Removed value [org.springframework.orm.hibernate.SessionHolder@2d80ae] for key [net.sf.hibernate.impl.SessionFactoryImpl@b4ccb] from thread [http8080-Processor2]
2004-03-17 07:45:24,602 DEBUG orm.hibernate.HibernateTransactionManager:428 -> Closing Hibernate session [net.sf.hibernate.impl.SessionImpl@12de02] after transaction
2004-03-17 07:45:24,602 DEBUG orm.hibernate.SessionFactoryUtils:190 -> Closing Hibernate session
2004-03-17 07:45:24,602 DEBUG hibernate.impl.SessionImpl:549 -> closing session
2004-03-17 07:45:24,602 DEBUG hibernate.impl.SessionImpl:3294 -> disconnecting session
2004-03-17 07:45:24,618 DEBUG logicalcobwebs.proxool.spring:283 -> #1 - autoCommit reset back to true
2004-03-17 07:45:24,618 DEBUG hibernate.impl.SessionImpl:561 -> transaction completion
Code:
Code: