1 Reply Latest reply on Jun 16, 2008 8:56 PM by aguizar

    Hiding StaleObjectStaleException problem

      Hello,

      when running with more threads, or when suspending running process I receive StaleObjectStaleException. I tried to get rid of them according to docs (chapter 6.5).

      I set log4j

      log4j.logger.org.hibernate.event.def.AbstractFlushingEventListener=FATAL


      With that log4j setting some stack traces disappeared.
      When suspending running process I still got
      15:06:59,500 ERROR [Services] problem closing service 'persistence'
      org.jbpm.JbpmException: couldn't commit JTA transaction
       at org.jbpm.persistence.jta.JtaDbPersistenceService.endJtaTransaction(JtaDbPersistenceService.java:93)
       at org.jbpm.persistence.jta.JtaDbPersistenceService.close(JtaDbPersistenceService.java:61)
       at org.jbpm.svc.Services.close(Services.java:223)
       at org.jbpm.JbpmContext.close(JbpmContext.java:139)
       at org.jbpm.job.executor.JobExecutorThread.executeJob(JobExecutorThread.java:210)
       at org.jbpm.job.executor.JobExecutorThread.run(JobExecutorThread.java:64)
      Caused by: javax.transaction.RollbackException: [com.arjuna.ats.internal.jta.transaction.arjunacore.commitwhenaborted] [com.arjuna.at
      ansaction.arjunacore.commitwhenaborted] Can't commit because the transaction is in aborted state
       at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1401)
       at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:135)
       at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:87)
       at org.jboss.tm.usertx.client.ServerVMClientUserTransaction.commit(ServerVMClientUserTransaction.java:140)
       at org.jbpm.persistence.jta.JtaDbPersistenceService.endJtaTransaction(JtaDbPersistenceService.java:91)
       ... 5 more
      Caused by: org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was i
      bpm.graph.exe.Token#70784]
       at org.hibernate.persister.entity.AbstractEntityPersister.check(AbstractEntityPersister.java:1769)
       at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2412)
       at org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:2312)
       at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2612)
       at org.hibernate.action.EntityUpdateAction.execute(EntityUpdateAction.java:96)
       at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:279)
       at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:263)
       at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:168)
       at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:298)
       at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:27)
       at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1000)
       at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:338)
       at org.hibernate.transaction.CacheSynchronization.beforeCompletion(CacheSynchronization.java:59)
       at com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple.beforeCompletion(SynchronizationImple.java:114)
       at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.beforeCompletion(TwoPhaseCoordinator.java:247)
       at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:86)
       at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:177)
       at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1389)
       ... 9 more
      15:06:59,504 ERROR [JobExecutorThread] exception in job executor thread. waiting 5000 milliseconds
      org.jbpm.JbpmException: couldn't commit JTA transaction
       at org.jbpm.persistence.jta.JtaDbPersistenceService.endJtaTransaction(JtaDbPersistenceService.java:93)
       at org.jbpm.persistence.jta.JtaDbPersistenceService.close(JtaDbPersistenceService.java:61)
       at org.jbpm.svc.Services.close(Services.java:223)
       at org.jbpm.JbpmContext.close(JbpmContext.java:139)
       at org.jbpm.job.executor.JobExecutorThread.executeJob(JobExecutorThread.java:210)
       at org.jbpm.job.executor.JobExecutorThread.run(JobExecutorThread.java:64)
      Caused by: javax.transaction.RollbackException: [com.arjuna.ats.internal.jta.transaction.arjunacore.commitwhenaborted] [com.arjuna.at
      ansaction.arjunacore.commitwhenaborted] Can't commit because the transaction is in aborted state
       at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1401)
       at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:135)
       at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:87)
       at org.jboss.tm.usertx.client.ServerVMClientUserTransaction.commit(ServerVMClientUserTransaction.java:140)
       at org.jbpm.persistence.jta.JtaDbPersistenceService.endJtaTransaction(JtaDbPersistenceService.java:91)
       ... 5 more
      Caused by: org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was i
      bpm.graph.exe.Token#70784]
       at org.hibernate.persister.entity.AbstractEntityPersister.check(AbstractEntityPersister.java:1769)
       at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2412)
       at org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:2312)
       at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2612)
       at org.hibernate.action.EntityUpdateAction.execute(EntityUpdateAction.java:96)
       at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:279)
       at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:263)
       at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:168)
       at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:298)
       at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:27)
       at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1000)
       at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:338)
       at org.hibernate.transaction.CacheSynchronization.beforeCompletion(CacheSynchronization.java:59)
       at com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple.beforeCompletion(SynchronizationImple.java:114)
       at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.beforeCompletion(TwoPhaseCoordinator.java:247)
       at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:86)
       at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:177)
       at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1389)
       ... 9 more
      


      To get rid of those I had to make some changes to classes org.jbpm.svc.Services and org.jbpm.job.executor.JobExecutorThread.

      I have to replace following code
      } catch (JbpmPersistenceException e) {
       if ("org.hibernate.StaleObjectStateException".equals(e.getCause().getClass().getName()))
       {
       ...
       StaleObjectLogConfigurer.staleObjectExceptionsLog.error("problem closing service '"+serviceName+"': optimistic locking failed", e);
       } else {
       ...
       }
      }
      


      with
      } catch (JbpmException e) {
       if (isCausedBy(e, "org.hibernate.StaleObjectStateException")) {
       ...
       StaleObjectLogConfigurer.staleObjectExceptionsLog.error("problem closing service '"+serviceName+"': optimistic locking failed", e);
       } else {
       ...
       }
      }
      

      where method isCausedBy is defined as follows
      private boolean isCausedBy(Throwable e, String name) {
      
       boolean isCaused = false;
       while (e != null) {
       if (e.getClass().getName().equals(name)) {
       isCaused = true;
       break;
       }
       e = e.getCause();
       }
       return isCaused;
      }
      


      With these changes I receive only
      15:40:13,104 WARN [arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator_2] TwoPhaseCoordinator.beforeCompletion - failed fo
      una.ats.internal.jta.resources.arjunacore.SynchronizationImple@fa447
      org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect): [org.jbp
      xe.Token#73493]
       at org.hibernate.persister.entity.AbstractEntityPersister.check(AbstractEntityPersister.java:1769)
       at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2412)
       at org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:2312)
       at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2612)
       at org.hibernate.action.EntityUpdateAction.execute(EntityUpdateAction.java:96)
       at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:279)
       at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:263)
       at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:168)
       at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:298)
       at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:27)
       at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1000)
       at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:338)
       at org.hibernate.transaction.CacheSynchronization.beforeCompletion(CacheSynchronization.java:59)
       at com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple.beforeCompletion(SynchronizationImple.java:114)
       at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.beforeCompletion(TwoPhaseCoordinator.java:247)
       at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:86)
       at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:177)
       at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1389)
       at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:135)
       at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:87)
       at org.jboss.tm.usertx.client.ServerVMClientUserTransaction.commit(ServerVMClientUserTransaction.java:140)
       at org.jbpm.persistence.jta.JtaDbPersistenceService.endJtaTransaction(JtaDbPersistenceService.java:91)
       at org.jbpm.persistence.jta.JtaDbPersistenceService.close(JtaDbPersistenceService.java:61)
       at org.jbpm.svc.Services.close(Services.java:223)
       at org.jbpm.JbpmContext.close(JbpmContext.java:139)
       at org.jbpm.job.executor.JobExecutorThread.executeJob(JobExecutorThread.java:211)
       at org.jbpm.job.executor.JobExecutorThread.run(JobExecutorThread.java:65)
      


      And this is JBoss Transaction logging which is somehow configurable as well.

      Is it bug in jBPM that not all StaleObjectStateExeception are hidden in Services and JobExecutorThread?

      Regars
      Pavel

        • 1. Re: Hiding StaleObjectStaleException problem
          aguizar

          StaleObjectStateExceptions are directed to the StaleObjectLogConfigurer, but the fact that one such exception could occur as the cause of a RollbackException is something that we did not see coming. You might want to report the issue and your proposed fix in Jira.