3 Replies Latest reply on Aug 20, 2010 8:52 AM by aguizar

    StaleObjectStateException

    grisha78

      Hi There,

       

      my logs contain a lot of StaleObjectStateException thrown by the JobExecutor (see below for details). It appears that the jobs are executed at the end, but i can't explain that exceptions

       

      i've found this issue : https://jira.jboss.org/browse/JBPM-1953, but i'm running with a single threaded JobExecutor, and only one node is running in my jboss cluster

       

      versions used :

      jbpm 3.2.6SP1

      jboss 4.2.3GA

       

      Thank you for your help

       

       

       

      2010-08-04 12:11:36,776 DEBUG [org.hibernate.jdbc.ConnectionManager] JMS SessionPool Worker-1 opening JDBC connection
      2010-08-04 12:11:36,776 DEBUG [org.hibernate.SQL] JMS SessionPool Worker-1
          /* update
              org.jbpm.graph.exe.Token */ update
                  JBPM_TOKEN
              set
                  VERSION_=?,
                  NAME_=?,
                  START_=?,
                  END_=?,
                  NODEENTER_=?,
                  NEXTLOGINDEX_=?,
                  ISABLETOREACTIVATEPARENT_=?,
                  ISTERMINATIONIMPLICIT_=?,
                  ISSUSPENDED_=?,
                  LOCK_=?,
                  NODE_=?,
                  PROCESSINSTANCE_=?,
                  PARENT_=?,
                  SUBPROCESSINSTANCE_=?
              where
                  ID_=?
                  and VERSION_=?
      2010-08-04 12:11:36,778 DEBUG [org.hibernate.jdbc.AbstractBatcher] JMS SessionPool Worker-1 about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
      2010-08-04 12:11:36,778 DEBUG [org.hibernate.jdbc.ConnectionManager] JMS SessionPool Worker-1 skipping aggressive-release due to flush cycle
      2010-08-04 12:11:36,778 ERROR [org.hibernate.event.def.AbstractFlushingEventListener] JMS SessionPool Worker-1 Could not synchronize database state with session
      org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect): [org.jbpm.graph.exe.Token#236]
      at org.hibernate.persister.entity.AbstractEntityPersister.check(AbstractEntityPersister.java:1765)
      at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2407)
      at org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:2307)
      at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2607)
      at org.hibernate.action.EntityUpdateAction.execute(EntityUpdateAction.java:92)
      at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:250)
      at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:234)
      at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:142)
      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.jms.asf.StdServerSession.onMessage(StdServerSession.java:351)
      at org.jboss.mq.SpyMessageConsumer.sessionConsumerProcessMessage(SpyMessageConsumer.java:906)
      at org.jboss.mq.SpyMessageConsumer.addMessage(SpyMessageConsumer.java:170)
      at org.jboss.mq.SpySession.run(SpySession.java:323)
      at org.jboss.jms.asf.StdServerSession.run(StdServerSession.java:194)
      at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(PooledExecutor.java:756)
      at java.lang.Thread.run(Thread.java:595)
      2010-08-04 12:11:36,781 DEBUG [org.hibernate.jdbc.ConnectionManager] JMS SessionPool Worker-1 aggressively releasing JDBC connection
      2010-08-04 12:11:36,781 DEBUG [org.hibernate.jdbc.ConnectionManager] JMS SessionPool Worker-1 releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
      2010-08-04 12:11:36,781 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] JMS SessionPool Worker-1 [com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator_2] TwoPhaseCoordinator.beforeCompletion - failed for com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple@da7e5d
      org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect): [org.jbpm.graph.exe.Token#236]
      at org.hibernate.persister.entity.AbstractEntityPersister.check(AbstractEntityPersister.java:1765)
      at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2407)
      at org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:2307)
      at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2607)
      at org.hibernate.action.EntityUpdateAction.execute(EntityUpdateAction.java:92)
      at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:250)
      at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:234)
      at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:142)
      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.jms.asf.StdServerSession.onMessage(StdServerSession.java:351)
      at org.jboss.mq.SpyMessageConsumer.sessionConsumerProcessMessage(SpyMessageConsumer.java:906)
      at org.jboss.mq.SpyMessageConsumer.addMessage(SpyMessageConsumer.java:170)
      at org.jboss.mq.SpySession.run(SpySession.java:323)
      at org.jboss.jms.asf.StdServerSession.run(StdServerSession.java:194)
      at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(PooledExecutor.java:756)
      at java.lang.Thread.run(Thread.java:595)
      2010-08-04 12:11:36,784 DEBUG [org.jbpm.ejb.impl.JobListenerBean] JMS SessionPool Worker-0 getting job id from jms message...
      2010-08-04 12:11:36,784 DEBUG [org.jbpm.ejb.impl.JobListenerBean] JMS SessionPool Worker-0 retrieved jobId '1765' via jms message
      2010-08-04 12:11:36,784 DEBUG [org.jbpm.configuration.JbpmContextInfo] JMS SessionPool Worker-0 creating jbpm context with service factories '[tx, message, scheduler, logging, persistence, authentication]'
      2010-08-04 12:11:36,784 DEBUG [org.jbpm.JbpmContext] JMS SessionPool Worker-0 creating org.jbpm.JbpmContext@1c55cdc
      2010-08-04 12:11:36,784 DEBUG [org.jbpm.ejb.impl.CommandServiceBean] JMS SessionPool Worker-0 executing org.jbpm.ejb.impl.ExecuteJobCommand@5380d6
      2010-08-04 12:11:36,784 DEBUG [org.jbpm.persistence.db.DbPersistenceService] JMS SessionPool Worker-0 using current hibernate session
      2010-08-04 12:11:36,784 DEBUG [org.hibernate.jdbc.JDBCContext] JMS SessionPool Worker-0 successfully registered Synchronization
      2010-08-04 12:11:36,784 DEBUG [org.hibernate.impl.SessionImpl] JMS SessionPool Worker-0 opened session at timestamp: 5246634790027264
      2010-08-04 12:11:36,784 DEBUG [org.hibernate.impl.SessionImpl] JMS SessionPool Worker-0 initializing proxy: [org.jbpm.job.Job#1765]
      2010-08-04 12:11:36,784 DEBUG [org.hibernate.loader.Loader] JMS SessionPool Worker-0 loading entity: [org.jbpm.job.Job#1765]
      2010-08-04 12:11:36,784 DEBUG [org.hibernate.jdbc.AbstractBatcher] JMS SessionPool Worker-0 about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
      2010-08-04 12:11:36,784 DEBUG [org.hibernate.jdbc.ConnectionManager] JMS SessionPool Worker-0 opening JDBC connection
      2010-08-04 12:11:36,785 DEBUG [org.hibernate.SQL] JMS SessionPool Worker-0
          /* load org.jbpm.job.Job */ select
              job0_.ID_ as ID1_26_0_,
              job0_.VERSION_ as VERSION3_26_0_,
              job0_.DUEDATE_ as DUEDATE4_26_0_,
              job0_.PROCESSINSTANCE_ as PROCESSI5_26_0_,
              job0_.TOKEN_ as TOKEN6_26_0_,
              job0_.TASKINSTANCE_ as TASKINST7_26_0_,
              job0_.ISSUSPENDED_ as ISSUSPEN8_26_0_,
              job0_.ISEXCLUSIVE_ as ISEXCLUS9_26_0_,
              job0_.LOCKOWNER_ as LOCKOWNER10_26_0_,
              job0_.LOCKTIME_ as LOCKTIME11_26_0_,
              job0_.EXCEPTION_ as EXCEPTION12_26_0_,
              job0_.RETRIES_ as RETRIES13_26_0_,
              job0_.NAME_ as NAME14_26_0_,
              job0_.REPEAT_ as REPEAT15_26_0_,
              job0_.TRANSITIONNAME_ as TRANSIT16_26_0_,
              job0_.ACTION_ as ACTION17_26_0_,
              job0_.GRAPHELEMENTTYPE_ as GRAPHEL18_26_0_,
              job0_.GRAPHELEMENT_ as GRAPHEL19_26_0_,
              job0_.NODE_ as NODE20_26_0_,
              job0_.CLASS_ as CLASS2_26_0_
          from
              JBPM_JOB job0_
          where
              job0_.ID_=?
      2010-08-04 12:11:36,786 ERROR [org.jboss.jms.asf.StdServerSession] JMS SessionPool Worker-1 failed to commit/rollback
      javax.transaction.RollbackException: [com.arjuna.ats.internal.jta.transaction.arjunacore.commitwhenaborted] [com.arjuna.ats.internal.jta.transaction.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.jms.asf.StdServerSession.onMessage(StdServerSession.java:351)
      at org.jboss.mq.SpyMessageConsumer.sessionConsumerProcessMessage(SpyMessageConsumer.java:906)
      at org.jboss.mq.SpyMessageConsumer.addMessage(SpyMessageConsumer.java:170)
      at org.jboss.mq.SpySession.run(SpySession.java:323)
      at org.jboss.jms.asf.StdServerSession.run(StdServerSession.java:194)
      at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(PooledExecutor.java:756)
      at java.lang.Thread.run(Thread.java:595)
      Caused by: org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect): [org.jbpm.graph.exe.Token#236]
      at org.hibernate.persister.entity.AbstractEntityPersister.check(AbstractEntityPersister.java:1765)
      at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2407)
      at org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:2307)
      at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2607)
      at org.hibernate.action.EntityUpdateAction.execute(EntityUpdateAction.java:92)
      at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:250)
      at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:234)
      at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:142)
      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
        • 1. Re: StaleObjectStateException
          grisha78

          Looking a little deeper into my problem, I am increasingly convinced that jobs are started before jbpm has committed its transaction, so the job is acquiring stale objects and concurrent version checking is failing at the end.

          When deploying on jboss, the jobs are sent to a JMS Queue and are executed by a JMS worker pool (as we can see in the logs).

          I suppose that writing to a queue is done within the same transaction when using XA datasource, but on my server, XA datasources are not used.

          I think that we could delay the JMS job execution so jbpm can commit its transaction? is a there parameter somewhere in jboss ?

          • 2. Re: StaleObjectStateException
            mohreece

            Hi Gregory,

             

            I don't know of any delays you can configure on JBoss AS to stall the relaying of JMS messages, but you might not want to change something like that at such a level - that may impact other applications running in the same environment, and you never know which those may be over time.

             

            There is a way to delay the execution of Jobs, however, and it's quite simple, albeit a little labourious if you need it often.

             

            You would need to call the setDueDate(Date dueDate) method on all of the Job objects you're scheduling. Just using new Date() as the input value schedules them for right now, adding the amount of time you need for a delay should do the trick. (And for that, DateUtils in Apache's commons lang library may be helping out, or you could use jBPM's own BusinessCalendar too).

             

            HTH!

            • 3. Re: StaleObjectStateException
              aguizar

              Gregory, stale state exceptions are to be expected if your process definition contains concurrent paths. Managing these exceptions has been the subject of multiple issues. In JBPM-1952 the JMS message service was reviewed and the queue configuration was changed as follows.

              JBossMQ (AS 4.x)

              <mbean code="org.jboss.mq.server.jmx.Queue"
                name="jboss.mq.destination:service=Queue,name=JbpmJobQueue">
                <depends optional-attribute-name="DestinationManager">jboss.mq:service=DestinationManager</depends>
                <!-- JBPM-1952 a small redelivery delay goes a long way towards mitigating
                     stale state exceptions and deadlocks under heavy concurrency conditions -->
                <attribute name="RedeliveryDelay">1000</attribute>
              </mbean>
              

              JBoss Messaging (AS 5.x)

              <mbean code="org.jboss.jms.server.destination.QueueService"
                name="jboss.messaging.destination:service=Queue,name=JbpmJobQueue"
                xmbean-dd="xmdesc/Queue-xmbean.xml">
                <depends optional-attribute-name="ServerPeer">jboss.messaging:service=ServerPeer</depends>
                <depends>jboss.messaging:service=PostOffice</depends>
                <!-- JBPM-1952 a small redelivery delay goes a long way towards mitigating
                     stale state exceptions and deadlocks under heavy concurrency conditions -->
                <attribute name="RedeliveryDelay">1000</attribute>
              </mbean>
              

              In JBPM-2790 the job executor and the join node were improved as follows.

              • End concurrent token when it enters the join node. Check all children of the parent token have ended when the join executes.
              • Make a small pause in the job executor thread before retrying a failed  job. Retrying a failed job too soon will likely produce another SOSE or  deadlock.

              For best results, the join node should be made asynchronous in order to reduce the window of opportunity for a locking conflict.