Uploaded image for project: 'Red Hat Process Automation Manager'
  1. Red Hat Process Automation Manager
  2. RHPAM-3487

Task instance marked as Completed despite OptimisticLockException

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Done
    • Icon: Critical Critical
    • 7.10.1.GA, 7.11.0.GA
    • 7.10.0.GA
    • jBPM Core
    • RHPAM 7.x running on multiple nodes

    • False
    • False
    • Release Notes
    • CR1
    • +
    • Undefined
    • Hide

      see attached reproducer

      Show
      see attached reproducer
    • ---
    • ---
    • 2021 Week 07-09 (from Feb 15)

      When running RHPAM / kie-server on multiple nodes, concurrent taskComplete operations related to the same process instance will cause an OptimisticLockException on one of the nodes. This exception should cause all operations to be rolled back, however the update on the Task table is still getting committed:

      // taskComplete call through REST
      2021-03-01 03:24:06,561 DEBUG [org.kie.server.services.jbpm.UserTaskServiceBase] (default task-11) About to complete task with id '2448237' as user 'xyz' with data {...}
      
      // update statement
      2021-03-01 03:24:06,668 DEBUG [org.hibernate.SQL] (default task-11) update Task set archived=?, allowedToDelegate=?, description=?, formName=?, name=?, taskInitiator_id=?, priority=?, subTaskStrategy=?, subject=?, activationTime=?, actualOwner_id=?, createdBy_id=?, createdOn=?, deploymentId=?, documentAccessType=?, documentContentId=?, documentType=?, expirationTime=?, faultAccessType=?, faultContentId=?, faultName=?, faultType=?, outputAccessType=?, outputContentId=?, outputType=?, parentId=?, previousStatus=?, processId=?, processInstanceId=?, processSessionId=?, skipable=?, status=?, workItemId=?, taskType=?, OPTLOCK=? where id=? and OPTLOCK=?
      
      // parameters status and id
      2021-03-01 03:24:06,679 TRACE [org.hibernate.metamodel.model.convert.internal.NamedEnumValueConverter] (default task-11) Binding [Completed] to parameter: [32]
      2021-03-01 03:24:06,679 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] (default task-11) binding parameter [36] as [BIGINT] - [2448237]
      
      // OptimisticLockException (due to concurrent update of the process instance on another node)
      2021-03-01 03:24:06,684 WARN  [org.jbpm.services.task.persistence.TaskTransactionInterceptor] (default task-11) Could not commit session: javax.persistence.OptimisticLockException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect) : [org.jbpm.persistence.processinstance.ProcessInstanceInfo#639156]
              at org.hibernate.internal.ExceptionConverterImpl.wrapStaleStateException(ExceptionConverterImpl.java:226)
              at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:93)
              at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:181)
              at org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1514)
              at org.hibernate.query.Query.getResultList(Query.java:135)
              at org.jbpm.services.task.persistence.JPATaskPersistenceContext.queryStringWithParameters(JPATaskPersistenceContext.java:665)
              at org.jbpm.services.task.persistence.JPATaskPersistenceContext.queryWithParametersInTransaction(JPATaskPersistenceContext.java:488)
              at org.jbpm.services.task.audit.JPATaskLifeCycleEventListener.getAuditTask(JPATaskLifeCycleEventListener.java:468)
              at org.jbpm.services.task.audit.JPATaskLifeCycleEventListener.afterTaskCompletedEvent(JPATaskLifeCycleEventListener.java:189)
              at org.jbpm.services.task.events.TaskEventSupport.fireAfterTaskCompleted(TaskEventSupport.java:347)
              at org.jbpm.services.task.internals.lifecycle.MVELLifeCycleManager.taskOperation(MVELLifeCycleManager.java:411)
              at org.jbpm.services.task.impl.TaskInstanceServiceImpl.complete(TaskInstanceServiceImpl.java:191)
      
      
      // After the OptimisticLockExcpetion, there is another Task update statement that sets the Task instance to completed:
      
      2021-03-01 03:24:06,765 DEBUG [org.hibernate.SQL] (default task-11) update Task set archived=?, allowedToDelegate=?, description=?, formName=?, name=?, taskInitiator_id=?, priority=?, subTaskStrategy=?, subject=?, activationTime=?, actualOwner_id=?, createdBy_id=?, createdOn=?, deploymentId=?, documentAccessType=?, documentContentId=?, documentType=?, expirationTime=?, faultAccessType=?, faultContentId=?, faultName=?, faultType=?, outputAccessType=?, outputContentId=?, outputType=?, parentId=?, previousStatus=?, processId=?, processInstanceId=?, processSessionId=?, skipable=?, status=?, workItemId=?, taskType=?, OPTLOCK=? where id=? and OPTLOCK=?
      
      2021-03-01 03:24:06,769 TRACE [org.hibernate.metamodel.model.convert.internal.NamedEnumValueConverter] (default task-11) Binding [Completed] to parameter: [32]
      2021-03-01 03:24:06,769 TRACE [org.hibernate.type.descriptor.sql.BasicBinder] (default task-11) binding parameter [36] as [BIGINT] - [2448237]
      

      In the database, we see an inconsistent state of the Task entity as a result:

      Table Task status
      AuditTaskImpl InProgress
      TaskEvent ADDED, STARTED
      Task Completed

      Further debugging shows that the OptimisticLockRetryInterceptor retries the operation once, which in turn calls the TaskTransactionInterceptor.execute method, which then results in the status update of the Task entity through the TaskSynchronizationImpl.afterCompletion method. If I disable the logic in OptimisticLockRetryInterceptor by setting retries=0 for a test, then the outcome is expected (all updates rolled back), and even the client is getting the error message.

       

            elguardian@gmail.com Enrique González Martínez (Inactive)
            rhn-support-mputz Martin Weiler (Inactive)
            Gonzalo Muñoz Fernández Gonzalo Muñoz Fernández
            Gonzalo Muñoz Fernández Gonzalo Muñoz Fernández
            Votes:
            0 Vote for this issue
            Watchers:
            6 Start watching this issue

              Created:
              Updated:
              Resolved: