[#HHH-1921] "dirty, but no dirty properties" thrown when Interceptor resets properties.

Hibernate Core

"dirty, but no dirty properties" thrown when Interceptor resets properties.

Created: 19/Jul/06 03:04 PM Updated: 10/Nov/06 11:15 PM

Component/s:

core

Affects Version/s:

3.2.0.cr2

Fix Version/s:

3.2.1

Time Tracking:

Not Specified

File Attachments:

dirtybutnotdirty.zip (3 kB)
2.

InterceptorTest.java (2 kB)
3.

ResetInterceptor.java (0.5 kB)

Environment:

« Hide

java version "1.5.0_07"
Hibernate 3.2.cr2

Issue Links:

Duplicate

This issue is duplicated by:

~~EJB-180~~ org.hibernate.AssertionFailure: dirty, but no dirty properties

Relates

This issue relates to:

~~HHH-2027~~ merge listener over-writes Interceptor changes to component state for a transient entity

Description

« Hide

When Interceptor.onfindDirty() resets properties to their DB value, the check in DefaultFlushEntityEventListener.scheduleUpdate:

// if it was dirtied by a collection only
int[] dirtyProperties = event.getDirtyProperties();
if ( event.isDirtyCheckPossible() && dirtyProperties==null ) {
if ( !event.hasDirtyCollection() ) {
throw new AssertionFailure("dirty, but no dirty properties");
}
dirtyProperties = ArrayHelper.EMPTY_INT_ARRAY;
}

fails needlessly.

Attached test has been confirmed against SVN TRUNK:

URL: http://anonhibernate.labs.jboss.com/trunk/Hibernate3
Revision: 10125

All

Comments

Work Log

Change History

FishEye

Sort Order:

[ Permalink | « Hide ]

Josh Moore added a comment - 19/Jul/06 03:05 PM

Same error with the EntityManager (~~EJB-180~~)

[ Permalink | « Hide ]

Josh Moore added a comment - 19/Jul/06 03:14 PM

Forgot to mention, test is copied all but verbatim from org.hibernate.test.interceptor. Standing on the shoulders of giants and what not. Will also attach changes to that package if it's easier.

[ Permalink | « Hide ]

Josh Moore added a comment - 19/Jul/06 03:36 PM

Index: DefaultFlushEntityEventListener.java
===================================================================
--- DefaultFlushEntityEventListener.java (revision 10125)
+++ DefaultFlushEntityEventListener.java (working copy)
@@ -251,7 +251,7 @@

                // if it was dirtied by a collection only
                int[] dirtyProperties = event.getDirtyProperties();
- if ( event.isDirtyCheckPossible() && dirtyProperties==null ) {
+ if ( !substitute && event.isDirtyCheckPossible() && dirtyProperties==null ) {
                        if ( !event.hasDirtyCollection() ) {
                                throw new AssertionFailure("dirty, but no dirty properties");
                        }

is working for me. Attached test passes. My code passes. The list of tests which fail from TRUNK is similar to that listed on ~~HHH-1401~~ (http://opensource.atlassian.com/projects/hibernate/browse/HHH-1401#action_23666), i.e. it doesn't seem to have broken too much.

    [junit] TEST org.hibernate.test.cuk.CompositePropertyRefTest FAILED
    [junit] TEST org.hibernate.test.hql.ASTParserLoadingTest FAILED
    [junit] TEST org.hibernate.test.hql.CriteriaHQLAlignmentTest FAILED
    [junit] TEST org.hibernate.test.hql.HQLTest FAILED
    [junit] TEST org.hibernate.test.legacy.SQLLoaderTest FAILED
    [junit] TEST org.hibernate.test.optlock.OptimisticLockTest FAILED
    [junit] TEST org.hibernate.test.orphan.PropertyRefTest FAILED
    [junit] TEST org.hibernate.test.propertyref.PropertyRefTest FAILED
    [junit] TEST org.hibernate.test.readonly.ReadOnlyTest FAILED
    [junit] TEST org.hibernate.test.sql.GeneralTest FAILED

(SQLLoaderTest was added but that is more likely due to the difference in versions: 10123 --> 10125)

[ Show » ]

Josh Moore added a comment - 19/Jul/06 03:36 PM Index: DefaultFlushEntityEventListener.java =================================================================== --- DefaultFlushEntityEventListener.java (revision 10125) +++ DefaultFlushEntityEventListener.java (working copy) @@ -251,7 +251,7 @@ // if it was dirtied by a collection only int[] dirtyProperties = event.getDirtyProperties(); - if ( event.isDirtyCheckPossible() && dirtyProperties==null ) { + if ( !substitute && event.isDirtyCheckPossible() && dirtyProperties==null ) { if ( !event.hasDirtyCollection() ) { throw new AssertionFailure("dirty, but no dirty properties"); } is working for me. Attached test passes. My code passes. The list of tests which fail from TRUNK is similar to that listed on ~~HHH-1401~~ (http://opensource.atlassian.com/projects/hibernate/browse/HHH-1401#action_23666), i.e. it doesn't seem to have broken too much. [junit] TEST org.hibernate.test.cuk.CompositePropertyRefTest FAILED [junit] TEST org.hibernate.test.hql.ASTParserLoadingTest FAILED [junit] TEST org.hibernate.test.hql.CriteriaHQLAlignmentTest FAILED [junit] TEST org.hibernate.test.hql.HQLTest FAILED [junit] TEST org.hibernate.test.legacy.SQLLoaderTest FAILED [junit] TEST org.hibernate.test.optlock.OptimisticLockTest FAILED [junit] TEST org.hibernate.test.orphan.PropertyRefTest FAILED [junit] TEST org.hibernate.test.propertyref.PropertyRefTest FAILED [junit] TEST org.hibernate.test.readonly.ReadOnlyTest FAILED [junit] TEST org.hibernate.test.sql.GeneralTest FAILED (SQLLoaderTest was added but that is more likely due to the difference in versions: 10123 --> 10125)

[ Permalink | « Hide ]

Josh Moore added a comment - 24/Aug/06 01:10 PM

Updating to r10347 appears to fix this; at least the given test case now passes. Can anyone confirm or explain?

[ Permalink | « Hide ]

John Gilbert added a comment - 31/Oct/06 09:42 AM

I encounter this same issue when using Ejb3 callbacks. For example:

onPrePersist i want to encrypt a value for storage in the db
onPostPersist i want to decrypt the value so i can continue to use it in memory.

Here is a sample trace. Notice that it tries to doPreUpdate during the flush.

2006-10-31 10:13:20,948 DEBUG [net.pay.security.service.CustomerServiceBean] Invoking: net.pay.security.service.CustomerServiceBean.save
Parameters:
net.pay.security.entity.Customer@473fc2[
  id=<null>
  name=fred
  creditCardNumber=5555-5555-5555-5555
]

2006-10-31 10:13:21,042 DEBUG [org.hibernate.impl.SessionImpl] opened session at timestamp: 4760811933609984
2006-10-31 10:13:21,042 DEBUG [org.hibernate.jdbc.JDBCContext] TransactionFactory reported no active transaction; Synchronization not registered
2006-10-31 10:13:21,042 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] Looking for a JTA transaction to join
2006-10-31 10:13:21,042 DEBUG [org.hibernate.jdbc.JDBCContext] successfully registered Synchronization
2006-10-31 10:13:21,042 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] Adding flush() and close() synchronization
2006-10-31 10:13:21,057 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] Looking for a JTA transaction to join
2006-10-31 10:13:21,057 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] Transaction already joined
2006-10-31 10:13:21,057 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] transient instance of: net.pay.security.entity.Customer
2006-10-31 10:13:21,057 DEBUG [org.hibernate.event.def.DefaultMergeEventListener] merging transient instance
2006-10-31 10:13:21,073 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] saving [net.pay.security.entity.Customer#<null>]
2006-10-31 10:13:21,073 DEBUG [net.pay.security.entity.Customer] doPrePersist:
net.pay.security.entity.Customer@ab48a7[
  id=<null>
  name=fred
  creditCardNumber=NTU1NS01NTU1LTU1NTUtNTU1NQ==
]
2006-10-31 10:13:21,073 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] executing insertions
2006-10-31 10:13:21,088 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] executing identity-insert immediately
2006-10-31 10:13:21,088 DEBUG [org.hibernate.persister.entity.AbstractEntityPersister] Inserting entity: net.pay.security.entity.Customer (native id)
2006-10-31 10:13:21,088 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2006-10-31 10:13:21,088 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2006-10-31 10:13:21,088 DEBUG [org.hibernate.SQL] insert into Customer (id, name, creditCardNumber) values (null, ?, ?)
2006-10-31 10:13:21,088 DEBUG [org.hibernate.jdbc.AbstractBatcher] preparing statement
2006-10-31 10:13:21,088 DEBUG [org.hibernate.persister.entity.AbstractEntityPersister] Dehydrating entity: [net.pay.security.entity.Customer#<null>]
2006-10-31 10:13:21,088 DEBUG [org.hibernate.type.StringType] binding 'fred' to parameter: 1
2006-10-31 10:13:21,088 DEBUG [org.hibernate.type.StringType] binding 'NTU1NS01NTU1LTU1NTUtNTU1NQ==' to parameter: 2
2006-10-31 10:13:21,088 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2006-10-31 10:13:21,088 DEBUG [org.hibernate.jdbc.AbstractBatcher] closing statement
2006-10-31 10:13:21,088 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2006-10-31 10:13:21,088 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2006-10-31 10:13:21,088 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2006-10-31 10:13:21,088 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2006-10-31 10:13:21,088 DEBUG [org.hibernate.SQL] call identity()
2006-10-31 10:13:21,088 DEBUG [org.hibernate.jdbc.AbstractBatcher] preparing statement
2006-10-31 10:13:21,088 DEBUG [org.hibernate.id.IdentifierGeneratorFactory] Natively generated identity: 3
2006-10-31 10:13:21,088 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2006-10-31 10:13:21,088 DEBUG [org.hibernate.jdbc.AbstractBatcher] closing statement
2006-10-31 10:13:21,088 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
2006-10-31 10:13:21,088 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2006-10-31 10:13:21,104 DEBUG [net.pay.security.entity.Customer] doPostPersist:
net.pay.security.entity.Customer@ab48a7[
  id=3
  name=fred
  creditCardNumber=5555-5555-5555-5555
]
2006-10-31 10:13:21,229 DEBUG [net.pay.security.service.CustomerServiceBean] Returning: net.pay.security.service.CustomerServiceBean.save
net.pay.security.entity.Customer@ab48a7[
  id=3
  name=fred
  creditCardNumber=5555-5555-5555-5555
]
2006-10-31 10:13:21,229 DEBUG [org.hibernate.transaction.CacheSynchronization] transaction before completion callback
2006-10-31 10:13:21,229 DEBUG [org.hibernate.jdbc.JDBCContext] before transaction completion
2006-10-31 10:13:21,229 DEBUG [org.hibernate.impl.SessionImpl] before transaction completion
2006-10-31 10:13:21,229 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] automatically flushing session
2006-10-31 10:13:21,229 DEBUG [org.hibernate.impl.SessionImpl] automatically flushing session
2006-10-31 10:13:21,229 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] flushing session
2006-10-31 10:13:21,229 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] processing flush-time cascades
2006-10-31 10:13:21,229 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] dirty checking collections
2006-10-31 10:13:21,229 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] Flushing entities and processing referenced collections
2006-10-31 10:13:21,229 DEBUG [org.hibernate.persister.entity.AbstractEntityPersister] net.pay.security.entity.Customer.creditCardNumber is dirty
2006-10-31 10:13:21,229 DEBUG [org.hibernate.event.def.DefaultFlushEntityEventListener] Updating entity: [net.pay.security.entity.Customer#3]
2006-10-31 10:13:21,229 DEBUG [net.pay.security.entity.Customer] doPreUpdate:
net.pay.security.entity.Customer@ab48a7[
  id=3
  name=fred
  creditCardNumber=NTU1NS01NTU1LTU1NTUtNTU1NQ==
]
2006-10-31 10:13:21,245 ERROR [org.hibernate.AssertionFailure] an assertion failure occured (this may indicate a bug in Hibernate, but is more likely due to unsafe use of the session)
org.hibernate.AssertionFailure: dirty, but no dirty properties
at org.hibernate.event.def.DefaultFlushEntityEventListener.scheduleUpdate(DefaultFlushEntityEventListener.java:256)
at org.hibernate.event.def.DefaultFlushEntityEventListener.onFlushEntity(DefaultFlushEntityEventListener.java:121)
at org.hibernate.event.def.AbstractFlushingEventListener.flushEntities(AbstractFlushingEventListener.java:195)
at org.hibernate.event.def.AbstractFlushingEventListener.flushEverythingToExecutions(AbstractFlushingEventListener.java:76)
at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:26)
at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:993)
at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:340)
at org.hibernate.ejb.AbstractEntityManagerImpl$1.beforeCompletion(AbstractEntityManagerImpl.java:475)
at org.jboss.tm.TransactionImpl.doBeforeCompletion(TransactionImpl.java:3074)
at org.jboss.tm.TransactionImpl.beforePrepare(TransactionImpl.java:2632)
at org.jboss.tm.TransactionImpl.commit(TransactionImpl.java:1194)
at org.jboss.tm.TxManager.commit(TxManager.java:588)
at org.jboss.aspects.tx.TxPolicy.endTransaction(TxPolicy.java:175)
at org.jboss.aspects.tx.TxPolicy.invokeInOurTx(TxPolicy.java:87)
at org.jboss.aspects.tx.TxInterceptor$Required.invoke(TxInterceptor.java:197)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.aspects.tx.TxPropagationInterceptor.invoke(TxPropagationInterceptor.java:76)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.ejb3.stateless.StatelessInstanceInterceptor.invoke(StatelessInstanceInterceptor.java:62)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.aspects.remoting.ReplicantsManagerInterceptor.invoke(ReplicantsManagerInterceptor.java:51)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.aspects.security.RoleBasedAuthorizationInterceptor.invoke(RoleBasedAuthorizationInterceptor.java:167)
at org.jboss.ejb3.security.RoleBasedAuthorizationInterceptor.invoke(RoleBasedAuthorizationInterceptor.java:100)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.aspects.security.AuthenticationInterceptor.invoke(AuthenticationInterceptor.java:78)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.ejb3.ENCPropagationInterceptor.invoke(ENCPropagationInterceptor.java:47)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.ejb3.asynchronous.AsynchronousInterceptor.invoke(AsynchronousInterceptor.java:106)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.ejb3.stateless.StatelessContainer.localInvoke(StatelessContainer.java:181)
at org.jboss.ejb3.stateless.StatelessLocalProxy.invoke(StatelessLocalProxy.java:79)
at $Proxy64.save(Unknown Source)
at net.pay.security.service.CustomerServiceTest.testSave(CustomerServiceTest.java:80)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
at java.lang.reflect.Method.invoke(Unknown Source)
at junit.framework.TestCase.runTest(TestCase.java:154)
at junit.framework.TestCase.runBare(TestCase.java:127)
at junit.framework.TestResult$1.protect(TestResult.java:106)
at junit.framework.TestResult.runProtected(TestResult.java:124)
at junit.framework.TestResult.run(TestResult.java:109)
at junit.framework.TestCase.run(TestCase.java:118)
at junit.framework.TestSuite.runTest(TestSuite.java:208)
at junit.framework.TestSuite.run(TestSuite.java:203)
at junit.extensions.TestDecorator.basicRun(TestDecorator.java:22)
at junit.extensions.TestSetup$1.protect(TestSetup.java:19)
at junit.framework.TestResult.runProtected(TestResult.java:124)
at junit.extensions.TestSetup.run(TestSetup.java:23)
at org.eclipse.jdt.internal.junit.runner.junit3.JUnit3TestReference.run(JUnit3TestReference.java:128)
at org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:38)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:460)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:673)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:386)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:196)

[ Show » ]

John Gilbert added a comment - 31/Oct/06 09:42 AM I encounter this same issue when using Ejb3 callbacks. For example: onPrePersist i want to encrypt a value for storage in the db onPostPersist i want to decrypt the value so i can continue to use it in memory. Here is a sample trace. Notice that it tries to doPreUpdate during the flush. 2006-10-31 10:13:20,948 DEBUG [net.pay.security.service.CustomerServiceBean] Invoking: net.pay.security.service.CustomerServiceBean.save Parameters: net.pay.security.entity.Customer@473fc2[ id=<null> name=fred creditCardNumber=5555-5555-5555-5555 ] 2006-10-31 10:13:21,042 DEBUG [org.hibernate.impl.SessionImpl] opened session at timestamp: 4760811933609984 2006-10-31 10:13:21,042 DEBUG [org.hibernate.jdbc.JDBCContext] TransactionFactory reported no active transaction; Synchronization not registered 2006-10-31 10:13:21,042 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] Looking for a JTA transaction to join 2006-10-31 10:13:21,042 DEBUG [org.hibernate.jdbc.JDBCContext] successfully registered Synchronization 2006-10-31 10:13:21,042 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] Adding flush() and close() synchronization 2006-10-31 10:13:21,057 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] Looking for a JTA transaction to join 2006-10-31 10:13:21,057 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] Transaction already joined 2006-10-31 10:13:21,057 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] transient instance of: net.pay.security.entity.Customer 2006-10-31 10:13:21,057 DEBUG [org.hibernate.event.def.DefaultMergeEventListener] merging transient instance 2006-10-31 10:13:21,073 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] saving [net.pay.security.entity.Customer#<null>] 2006-10-31 10:13:21,073 DEBUG [net.pay.security.entity.Customer] doPrePersist: net.pay.security.entity.Customer@ab48a7[ id=<null> name=fred creditCardNumber=NTU1NS01NTU1LTU1NTUtNTU1NQ== ] 2006-10-31 10:13:21,073 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] executing insertions 2006-10-31 10:13:21,088 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] executing identity-insert immediately 2006-10-31 10:13:21,088 DEBUG [org.hibernate.persister.entity.AbstractEntityPersister] Inserting entity: net.pay.security.entity.Customer (native id) 2006-10-31 10:13:21,088 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0) 2006-10-31 10:13:21,088 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection 2006-10-31 10:13:21,088 DEBUG [org.hibernate.SQL] insert into Customer (id, name, creditCardNumber) values (null, ?, ?) 2006-10-31 10:13:21,088 DEBUG [org.hibernate.jdbc.AbstractBatcher] preparing statement 2006-10-31 10:13:21,088 DEBUG [org.hibernate.persister.entity.AbstractEntityPersister] Dehydrating entity: [net.pay.security.entity.Customer#<null>] 2006-10-31 10:13:21,088 DEBUG [org.hibernate.type.StringType] binding 'fred' to parameter: 1 2006-10-31 10:13:21,088 DEBUG [org.hibernate.type.StringType] binding 'NTU1NS01NTU1LTU1NTUtNTU1NQ==' to parameter: 2 2006-10-31 10:13:21,088 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1) 2006-10-31 10:13:21,088 DEBUG [org.hibernate.jdbc.AbstractBatcher] closing statement 2006-10-31 10:13:21,088 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection 2006-10-31 10:13:21,088 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)] 2006-10-31 10:13:21,088 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0) 2006-10-31 10:13:21,088 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection 2006-10-31 10:13:21,088 DEBUG [org.hibernate.SQL] call identity() 2006-10-31 10:13:21,088 DEBUG [org.hibernate.jdbc.AbstractBatcher] preparing statement 2006-10-31 10:13:21,088 DEBUG [org.hibernate.id.IdentifierGeneratorFactory] Natively generated identity: 3 2006-10-31 10:13:21,088 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1) 2006-10-31 10:13:21,088 DEBUG [org.hibernate.jdbc.AbstractBatcher] closing statement 2006-10-31 10:13:21,088 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection 2006-10-31 10:13:21,088 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)] 2006-10-31 10:13:21,104 DEBUG [net.pay.security.entity.Customer] doPostPersist: net.pay.security.entity.Customer@ab48a7[ id=3 name=fred creditCardNumber=5555-5555-5555-5555 ] 2006-10-31 10:13:21,229 DEBUG [net.pay.security.service.CustomerServiceBean] Returning: net.pay.security.service.CustomerServiceBean.save net.pay.security.entity.Customer@ab48a7[ id=3 name=fred creditCardNumber=5555-5555-5555-5555 ] 2006-10-31 10:13:21,229 DEBUG [org.hibernate.transaction.CacheSynchronization] transaction before completion callback 2006-10-31 10:13:21,229 DEBUG [org.hibernate.jdbc.JDBCContext] before transaction completion 2006-10-31 10:13:21,229 DEBUG [org.hibernate.impl.SessionImpl] before transaction completion 2006-10-31 10:13:21,229 DEBUG [org.hibernate.ejb.AbstractEntityManagerImpl] automatically flushing session 2006-10-31 10:13:21,229 DEBUG [org.hibernate.impl.SessionImpl] automatically flushing session 2006-10-31 10:13:21,229 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] flushing session 2006-10-31 10:13:21,229 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] processing flush-time cascades 2006-10-31 10:13:21,229 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] dirty checking collections 2006-10-31 10:13:21,229 DEBUG [org.hibernate.event.def.AbstractFlushingEventListener] Flushing entities and processing referenced collections 2006-10-31 10:13:21,229 DEBUG [org.hibernate.persister.entity.AbstractEntityPersister] net.pay.security.entity.Customer.creditCardNumber is dirty 2006-10-31 10:13:21,229 DEBUG [org.hibernate.event.def.DefaultFlushEntityEventListener] Updating entity: [net.pay.security.entity.Customer#3] 2006-10-31 10:13:21,229 DEBUG [net.pay.security.entity.Customer] doPreUpdate: net.pay.security.entity.Customer@ab48a7[ id=3 name=fred creditCardNumber=NTU1NS01NTU1LTU1NTUtNTU1NQ== ] 2006-10-31 10:13:21,245 ERROR [org.hibernate.AssertionFailure] an assertion failure occured (this may indicate a bug in Hibernate, but is more likely due to unsafe use of the session) org.hibernate.AssertionFailure: dirty, but no dirty properties at org.hibernate.event.def.DefaultFlushEntityEventListener.scheduleUpdate(DefaultFlushEntityEventListener.java:256) at org.hibernate.event.def.DefaultFlushEntityEventListener.onFlushEntity(DefaultFlushEntityEventListener.java:121) at org.hibernate.event.def.AbstractFlushingEventListener.flushEntities(AbstractFlushingEventListener.java:195) at org.hibernate.event.def.AbstractFlushingEventListener.flushEverythingToExecutions(AbstractFlushingEventListener.java:76) at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:26) at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:993) at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:340) at org.hibernate.ejb.AbstractEntityManagerImpl$1.beforeCompletion(AbstractEntityManagerImpl.java:475) at org.jboss.tm.TransactionImpl.doBeforeCompletion(TransactionImpl.java:3074) at org.jboss.tm.TransactionImpl.beforePrepare(TransactionImpl.java:2632) at org.jboss.tm.TransactionImpl.commit(TransactionImpl.java:1194) at org.jboss.tm.TxManager.commit(TxManager.java:588) at org.jboss.aspects.tx.TxPolicy.endTransaction(TxPolicy.java:175) at org.jboss.aspects.tx.TxPolicy.invokeInOurTx(TxPolicy.java:87) at org.jboss.aspects.tx.TxInterceptor$Required.invoke(TxInterceptor.java:197) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101) at org.jboss.aspects.tx.TxPropagationInterceptor.invoke(TxPropagationInterceptor.java:76) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101) at org.jboss.ejb3.stateless.StatelessInstanceInterceptor.invoke(StatelessInstanceInterceptor.java:62) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101) at org.jboss.aspects.remoting.ReplicantsManagerInterceptor.invoke(ReplicantsManagerInterceptor.java:51) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101) at org.jboss.aspects.security.RoleBasedAuthorizationInterceptor.invoke(RoleBasedAuthorizationInterceptor.java:167) at org.jboss.ejb3.security.RoleBasedAuthorizationInterceptor.invoke(RoleBasedAuthorizationInterceptor.java:100) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101) at org.jboss.aspects.security.AuthenticationInterceptor.invoke(AuthenticationInterceptor.java:78) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101) at org.jboss.ejb3.ENCPropagationInterceptor.invoke(ENCPropagationInterceptor.java:47) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101) at org.jboss.ejb3.asynchronous.AsynchronousInterceptor.invoke(AsynchronousInterceptor.java:106) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101) at org.jboss.ejb3.stateless.StatelessContainer.localInvoke(StatelessContainer.java:181) at org.jboss.ejb3.stateless.StatelessLocalProxy.invoke(StatelessLocalProxy.java:79) at $Proxy64.save(Unknown Source) at net.pay.security.service.CustomerServiceTest.testSave(CustomerServiceTest.java:80) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) at java.lang.reflect.Method.invoke(Unknown Source) at junit.framework.TestCase.runTest(TestCase.java:154) at junit.framework.TestCase.runBare(TestCase.java:127) at junit.framework.TestResult$1.protect(TestResult.java:106) at junit.framework.TestResult.runProtected(TestResult.java:124) at junit.framework.TestResult.run(TestResult.java:109) at junit.framework.TestCase.run(TestCase.java:118) at junit.framework.TestSuite.runTest(TestSuite.java:208) at junit.framework.TestSuite.run(TestSuite.java:203) at junit.extensions.TestDecorator.basicRun(TestDecorator.java:22) at junit.extensions.TestSetup$1.protect(TestSetup.java:19) at junit.framework.TestResult.runProtected(TestResult.java:124) at junit.extensions.TestSetup.run(TestSetup.java:23) at org.eclipse.jdt.internal.junit.runner.junit3.JUnit3TestReference.run(JUnit3TestReference.java:128) at org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:38) at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:460) at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:673) at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:386) at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:196)

[ Permalink | « Hide ]

Steve Ebersole added a comment - 10/Nov/06 09:28 PM

Actually the real culprit here is DefaultMergeEventListener.entityIsTransient(). The save calls actually complete as anticipated *in terms of the managed copy state*, but the problem comes then from the after save cascading which writes the null component value from the original entity back into the managed copy, over-writing the work done by the interceptor during sve.

Just so I dont forget when I get a chance to get back to this ;)