5 Replies Latest reply: Jul 13, 2012 10:57 AM by Adam Warski RSS

Envers still tries to audit after transaction rolled back

Ging Ming Chan Newbie

Hi,

 

I'm using Envers 3.6.0 in Seam 2.2.2.Final under JBoss 6.  I've encountered the following error that I couldn't solve.  The following is an example of the code that I ran:

 

public class ServiceProvider {

 

 

     @Column(name = "code", unique = true, nullable = false, length = 128)

     public String getCode() {
        return this.code;
    }

 

    @OneToMany(fetch=FetchType.LAZY, cascade={CascadeType.REMOVE, CascadeType.PERSIST}, mappedBy="serviceProvider")

    public Set<ServiceProviderProperty> getServiceProviderProperties() {

        return this.serviceProviderProperties;

    }

     .

     .

     .

}

 

public class ServiceProviderProperty {

 

     @Column(name = "code", unique=true, nullable = false, length = 128)

     public String getCode() {

          return this.code;

     }

}

 

 

Another class:

 

@Transactional

public void persist(ServiceProvider sp) {

     serviceProviderDao.persist(sp);

}

 

The ServiceProvider and ServiceProviderProperty database tables have unique constraint on the code.

 

Scenario 1:

If I insert service provider with duplicate code, exception is thrown, the transaction is rolled back and envers is not invoked.

 

Scenario 2:

If I insert service provider with service provider properties with duplicate code (i.e. inserted via cascading releationship), exception is thrown, the transaction is rolled back BUT envers is still invoked.  Because my Audit Entity contains some required fields that is not populated, it ended up in a infinite loop, e.g.

 

14:58:58,912 ERROR [org.jboss.seam.exception.Exceptions] handled and logged exception: java.lang.IllegalStateException: Could not commit transaction
    at org.jboss.seam.jsf.SeamPhaseListener.commitOrRollback(SeamPhaseListener.java:624) [:2.2.2.Final]
    at org.jboss.seam.jsf.SeamPhaseListener.commitOrRollback(SeamPhaseListener.java:603) [:2.2.2.Final]

Caused by: javax.transaction.RollbackException: ARJUNA-16053 Could not commit transaction.
    at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1170) [:6.0.0.Final]

Caused by: org.hibernate.AssertionFailure: Unable to perform beforeTransactionCompletion callback
    at org.hibernate.engine.ActionQueue$BeforeTransactionCompletionProcessQueue.beforeTransactionCompletion(ActionQueue.java:549) [:3.6.0.Final]
    at org.hibernate.engine.ActionQueue.beforeTransactionCompletion(ActionQueue.java:216) [:3.6.0.Final]

Caused by: org.hibernate.validator.InvalidStateException: validation failed for: com.test.ConfigurationChangeRecord
    at org.hibernate.validator.event.ValidateEventListener.validate(ValidateEventListener.java:148) [:4.0.2.GA]
    at org.hibernate.validator.event.ValidateEventListener.onPreInsert(ValidateEventListener.java:172) [:4.0.2.GA]
    at org.hibernate.action.EntityIdentityInsertAction.preInsert(EntityIdentityInsertAction.java:160) [:3.6.0.Final]
    at org.hibernate.action.EntityIdentityInsertAction.execute(EntityIdentityInsertAction.java:65) [:3.6.0.Final]
    at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:273) [:3.6.0.Final]
    at org.hibernate.event.def.AbstractSaveEventListener.performSaveOrReplicate(AbstractSaveEventListener.java:320) [:3.6.0.Final]
    at org.hibernate.event.def.AbstractSaveEventListener.performSave(AbstractSaveEventListener.java:203) [:3.6.0.Final]
    at org.hibernate.event.def.AbstractSaveEventListener.saveWithGeneratedId(AbstractSaveEventListener.java:129) [:3.6.0.Final]
    at org.hibernate.ejb.event.EJB3SaveEventListener.saveWithGeneratedId(EJB3SaveEventListener.java:62) [:3.6.0.Final]
    at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.saveWithGeneratedOrRequestedId(DefaultSaveOrUpdateEventListener.java:210) [:3.6.0.Final]
    at org.hibernate.event.def.DefaultSaveEventListener.saveWithGeneratedOrRequestedId(DefaultSaveEventListener.java:56) [:3.6.0.Final]
    at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.entityIsTransient(DefaultSaveOrUpdateEventListener.java:195) [:3.6.0.Final]
    at org.hibernate.event.def.DefaultSaveEventListener.performSaveOrUpdate(DefaultSaveEventListener.java:50) [:3.6.0.Final]
    at org.hibernate.event.def.DefaultSaveOrUpdateEventListener.onSaveOrUpdate(DefaultSaveOrUpdateEventListener.java:93) [:3.6.0.Final]
    at org.hibernate.impl.SessionImpl.fireSave(SessionImpl.java:713) [:3.6.0.Final]
    at org.hibernate.impl.SessionImpl.save(SessionImpl.java:701) [:3.6.0.Final]
    at org.hibernate.envers.revisioninfo.DefaultRevisionInfoGenerator.saveRevisionData(DefaultRevisionInfoGenerator.java:71) [:3.6.0.Final]
    at org.hibernate.envers.synchronization.AuditProcess.getCurrentRevisionData(AuditProcess.java:126) [:3.6.0.Final]
    at org.hibernate.envers.synchronization.AuditProcess.executeInSession(AuditProcess.java:104) [:3.6.0.Final]
    at org.hibernate.envers.synchronization.AuditProcess.doBeforeTransactionCompletion(AuditProcess.java:143) [:3.6.0.Final]
    at org.hibernate.engine.ActionQueue$BeforeTransactionCompletionProcessQueue.beforeTransactionCompletion(ActionQueue.java:543) [:3.6.0.Final]
    ... 72 more

 

My question is, why is envers still got invoked in Scenario 2 even if the transaction is rolled back? How can I prevent that from happening?

 

I've tried to set the service provider property collection to null, persist the service provider first and then persist the properties using serviceProviderDao in the same transaction, and the same problem occurred.  So it has nothing to do with the cascading persist.  Any idea?

 

  • 1. Re: Envers still tries to audit after transaction rolled back
    Ging Ming Chan Newbie

    After some more investigation, it seems like Envers tries to log every database call regardless of whether the Transaction is successful. E.g. I tried the following code (simplified version) with the same problem:

     

    @Transactional

    public void test(ServiceProvider sp) {

         serviceProviderDao.persist(sp);

         throw new IllegalArgumentException("Error");

    }

     

    After the code failed, the transaction is rolled back, the service provider is not persisted, however, Envers created a new revision for my entity, which is wrong as the entity does not exist in the actual application.

     

    I've found that the auditProcess that is registered with the session.getActionQueue().registerProcess(auditProcess) call (in AuditProcessManager class) maybe responsible for that since it is not removed and still being called after the transaction is rolled back.

     

    Is that a bug, by design or I'm not using Envers correctly?

  • 2. Re: Envers still tries to audit after transaction rolled back
    Ging Ming Chan Newbie

    Further investigation shows that the audit occurs when the SessionImpl.beforeTransactionCompletion(tx) is called, which causes the AuditProcess.doBeforeTransactionCompletion() being called.

     

    Is there any way that I can access and modify the beforeTransactionProcesses of the ActionQueue?  From the code, it seems like it's impossible.  The SessionImpl.clear() -> ActionQueue.clear() doesn't clear the beforeTransactionProcesses and I can't find any method to access the beforeTransactionProcesses to remove the AuditProcess.

  • 3. Re: Envers still tries to audit after transaction rolled back
    Adam Warski Master

    Looking at the sources, beforeTransactionCompletion is called only befor the transaction is commited. There are several levels of indirection, but the call originates from AbstractTransactionImpl.beforeTransactionCommit() (in Hib4 sources). So what I would do is check if:

     

    1. is the transaction indeed trying to be commited

    2. why is it commited.

     

    Adam

  • 4. Re: Envers still tries to audit after transaction rolled back
    Ging Ming Chan Newbie

    Hi Adam,

     

    Thanks for your response. I think I've found the problem.  It's similar to https://community.jboss.org/thread/199389?tstart=0 but I don't know how to start a new Hibernate session as it is controlled by Seam.  Let me describe my observations:

     

    1. A new request came in that raised the Hibernate postInsert event.

    2. Within that request, an exception is thrown and the transaction is rolled back (we call it tx1), and Hibernate sessionImpl instance (s1) was observed there.

    3. I observed that the beforeTransactionCompletion(tx1) was NOT invoked, only the afterTransactionCompletion was invoked. This is correct behaviour.

    4. Somehow, a new transaction was created by Seam (we call it tx2), and the beforeTransactionCompletion(tx2) was invoked.  In tx2, it is using the same s1 instance and caused the Envers' AuditProcess event to be executed.

    5. afterTransactionCompletion for tx2 was invoked.

    6. Seam error page is shown.

    7. A new Envers revision is observed in the database.

     

    I think the problem lies in the sharing of the Hibernate session for the two transactions.  Although to the user, it's a single request, somehow Seam created two transactions and share the same Hibernate session.

     

    I've to read more into how Seam is using transaction and the lifecycle of the components but if there are Seam experts that can point me to the right direction then it'd be greatly appreciated as all of these are very time consuming.

  • 5. Re: Envers still tries to audit after transaction rolled back
    Adam Warski Master

    Hmm that's interesting. Seam creates two transactions, one for processing the request, second for rendering the view (kind of POST + GET).

    Though of course entities that have been audited in one transaction but haven't been commited shouldn't be added in subsequent transacitons.

     

    Could you maybe create an Envers test case (there's quite a lot of them in the test suite), where there are two transactions in using a single session?

     

    Adam