6 Replies Latest reply on Jun 24, 2010 12:21 PM by Jorge Ferreira

    Multiple JBPM4_VARIABLE records pointing to same LOB_ and different EXECUTIONID_

    Jorge Ferreira Newbie

      I am using jBPM 4.3. If you need any more version information please ask.

       

      We get an exception when trying to call ExecutionService#endProcessInstance(...).

       

      org.zkoss.zk.ui.UiException: rendering.0010: org.hibernate.exception.ConstraintViolationException: could not delete: [org.jbpm.pvm.internal.lob.Lob#2260042].
      at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
      at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)
      at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
      at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
      at org.zkoss.lang.Classes.newInstance(Classes.java:76)
      at org.zkoss.lang.Exceptions.wrap(Exceptions.java:162)
      at org.zkoss.zk.ui.UiException$Aide.wrap(UiException.java:44)
      at org.zkoss.zk.ui.impl.UiEngineImpl.processEvent(UiEngineImpl.java:1452)
      at org.zkoss.zk.ui.impl.UiEngineImpl.process(UiEngineImpl.java:1229)
      at org.zkoss.zk.ui.impl.UiEngineImpl.execUpdate(UiEngineImpl.java:1009)
      at org.zkoss.zk.au.http.DHtmlUpdateServlet.process(DHtmlUpdateServlet.java:549)
      at org.zkoss.zk.au.http.DHtmlUpdateServlet.doGet(DHtmlUpdateServlet.java:441)
      at org.zkoss.zk.au.http.DHtmlUpdateServlet.doPost(DHtmlUpdateServlet.java:449)
      at javax.servlet.http.HttpServlet.service(HttpServlet.java:710)
      at javax.servlet.http.HttpServlet.service(HttpServlet.java:803)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
      at org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:96)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
      at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:230)
      at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:175)
      at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:182)
      at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:524)
      at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:84)
      at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
      at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
      at org.jboss.web.tomcat.service.jca.CachedConnectionValve.invoke(CachedConnectionValve.java:157)
      at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
      at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:262)
      at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:844)
      at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583)
      at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:446)
      at java.lang.Thread.run(Thread.java:619)
      Caused by: rendering.0010: org.hibernate.exception.ConstraintViolationException: could not delete: [org.jbpm.pvm.internal.lob.Lob#2260042].
      at com.csw.impression.rendering.component.action.OutcomeAction.execute(OutcomeAction.java:177)
      at com.csw.impression.rendering.component.action.event.ExecuteActionEventListener.onEvent(ExecuteActionEventListener.java:49)
      at org.zkoss.zk.ui.impl.EventProcessor.process0(EventProcessor.java:196)
      at org.zkoss.zk.ui.impl.EventProcessor.process(EventProcessor.java:140)
      at org.zkoss.zk.ui.impl.UiEngineImpl.processEvent(UiEngineImpl.java:1445)
      ... 26 more
      Caused by: javax.ejb.EJBException: org.hibernate.exception.ConstraintViolationException: could not delete: [org.jbpm.pvm.internal.lob.Lob#2260042]
      at org.jboss.ejb3.tx.Ejb3TxPolicy.handleExceptionInOurTx(Ejb3TxPolicy.java:63)
      at org.jboss.aspects.tx.TxPolicy.invokeInOurTx(TxPolicy.java:83)
      at org.jboss.aspects.tx.TxInterceptor$Required.invoke(TxInterceptor.java:191)
      at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
      at org.jboss.aspects.tx.TxPropagationInterceptor.invoke(TxPropagationInterceptor.java:95)
      at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
      at org.jboss.ejb3.stateless.StatelessInstanceInterceptor.invoke(StatelessInstanceInterceptor.java:62)
      at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
      at org.jboss.aspects.security.RunAsSecurityInterceptor.invoke(RunAsSecurityInterceptor.java:83)
      at org.jboss.ejb3.security.RunAsSecurityInterceptor.invoke(RunAsSecurityInterceptor.java:54)
      at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
      at org.jboss.aspects.security.RoleBasedAuthorizationInterceptor.invoke(RoleBasedAuthorizationInterceptor.java:166)
      at org.jboss.ejb3.security.RoleBasedAuthorizationInterceptor.invoke(RoleBasedAuthorizationInterceptor.java:115)
      at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
      at org.jboss.aspects.security.AuthenticationInterceptor.invoke(AuthenticationInterceptor.java:77)
      at org.jboss.ejb3.security.Ejb3AuthenticationInterceptor.invoke(Ejb3AuthenticationInterceptor.java:110)
      at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
      at org.jboss.ejb3.ENCPropagationInterceptor.invoke(ENCPropagationInterceptor.java:46)
      at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
      at org.jboss.ejb3.asynchronous.AsynchronousInterceptor.invoke(AsynchronousInterceptor.java:106)
      at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
      at org.jboss.ejb3.stateless.StatelessContainer.localInvoke(StatelessContainer.java:240)
      at org.jboss.ejb3.stateless.StatelessContainer.localInvoke(StatelessContainer.java:210)
      at org.jboss.ejb3.stateless.StatelessLocalProxy.invoke(StatelessLocalProxy.java:84)
      at $Proxy248.completeTask(Unknown Source)
      at com.csw.impression.rendering.component.panel.AbstractPanel.executeOutcome(AbstractPanel.java:686)
      at com.csw.impression.rendering.component.action.OutcomeAction.execute(OutcomeAction.java:129)
      ... 30 more
      Caused by: org.hibernate.exception.ConstraintViolationException: could not delete: [org.jbpm.pvm.internal.lob.Lob#2260042]
      at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:71)
      at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:43)
      at org.hibernate.persister.entity.AbstractEntityPersister.delete(AbstractEntityPersister.java:2541)
      at org.hibernate.persister.entity.AbstractEntityPersister.delete(AbstractEntityPersister.java:2697)
      at org.hibernate.action.EntityDeleteAction.execute(EntityDeleteAction.java:74)
      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:146)
      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.jbpm.pvm.internal.tx.HibernateSessionResource.prepare(HibernateSessionResource.java:56)
      at org.jbpm.pvm.internal.tx.StandardTransaction.commit(StandardTransaction.java:107)
      at org.jbpm.pvm.internal.tx.StandardTransaction.complete(StandardTransaction.java:64)
      at org.jbpm.pvm.internal.tx.StandardTransactionInterceptor.execute(StandardTransactionInterceptor.java:61)
      at org.jbpm.pvm.internal.svc.EnvironmentInterceptor.executeInNewEnvironment(EnvironmentInterceptor.java:53)
      at org.jbpm.pvm.internal.svc.EnvironmentInterceptor.execute(EnvironmentInterceptor.java:40)
      at org.jbpm.pvm.internal.svc.RetryInterceptor.execute(RetryInterceptor.java:55)
      at org.jbpm.pvm.internal.svc.SkipInterceptor.execute(SkipInterceptor.java:43)
      at org.jbpm.pvm.internal.svc.TaskServiceImpl.completeTask(TaskServiceImpl.java:96)
      at com.csw.impression.bpm.ExecutionServiceImpl.completeTaskWork(ExecutionServiceImpl.java:206)
      at com.csw.impression.bpm.ExecutionServiceImpl.completeTask(ExecutionServiceImpl.java:235)
      at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
      at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
      at java.lang.reflect.Method.invoke(Method.java:597)
      at org.jboss.aop.joinpoint.MethodInvocation.invokeTarget(MethodInvocation.java:122)
      at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:111)
      at org.jboss.ejb3.interceptor.InvocationContextImpl.proceed(InvocationContextImpl.java:166)
      at org.jboss.ejb3.interceptor.EJB3InterceptorsInterceptor.invoke(EJB3InterceptorsInterceptor.java:63)
      at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
      at org.jboss.ejb3.entity.TransactionScopedEntityManagerInterceptor.invoke(TransactionScopedEntityManagerInterceptor.java:54)
      at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
      at org.jboss.ejb3.AllowedOperationsInterceptor.invoke(AllowedOperationsInterceptor.java:47)
      at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
      at org.jboss.aspects.tx.TxPolicy.invokeInOurTx(TxPolicy.java:79)
      ... 55 more
      Caused by: java.sql.SQLException: The DELETE statement conflicted with the REFERENCE constraint "FK_VAR_LOB". The conflict occurred in database "impression", table "dbo.JBPM4_VARIABLE", column 'LOB_'.
      at net.sourceforge.jtds.jdbc.SQLDiagnostic.addDiagnostic(SQLDiagnostic.java:368)
      at net.sourceforge.jtds.jdbc.TdsCore.tdsErrorToken(TdsCore.java:2820)
      at net.sourceforge.jtds.jdbc.TdsCore.nextToken(TdsCore.java:2258)
      at net.sourceforge.jtds.jdbc.TdsCore.getMoreResults(TdsCore.java:632)
      at net.sourceforge.jtds.jdbc.JtdsStatement.processResults(JtdsStatement.java:584)
      at net.sourceforge.jtds.jdbc.JtdsStatement.executeSQL(JtdsStatement.java:546)
      at net.sourceforge.jtds.jdbc.JtdsPreparedStatement.executeUpdate(JtdsPreparedStatement.java:506)
      at org.jboss.resource.adapter.jdbc.WrappedPreparedStatement.executeUpdate(WrappedPreparedStatement.java:365)
      at org.hibernate.persister.entity.AbstractEntityPersister.delete(AbstractEntityPersister.java:2523)
      ... 88 more

       

      FK_VAR_LOB is a foreign key constraint for JBPM4_VARIABLE.LOB_ column that points to JBPM4_LOB.DBID_. This error means that a DELETE for a record in JBPM4_LOB conflicts with a record in JBPM4_VARIABLE that points to that same record.

       

      I think this problem is related with this strange situation.

       

      The LOB_ in question is 2260042 (see next line).

       

      org.zkoss.zk.ui.UiException: rendering.0010: org.hibernate.exception.ConstraintViolationException: could not delete: [org.jbpm.pvm.internal.lob.Lob#2260042].

       

      So I did a query on JBPM4_VARIABLE for any records with that LOB_.

       

      select * from jbpm4_variable where lob_ is not null and lob_ = 2260229

       

      And I got two records that:

      • use ser-bytes converter;
      • have two diferent KEY_ names;
      • have two different EXECUTIONID_ values;
      • Point to the same LOB_.

       

      Oddly enough the EXECUTIONID_ values are for different processes.

       

      select dbid_, procdefid_ from jbpm4_execution where dbid_ in (2260197, 2260223)

       

      For setting a variable value we use several API, but all from publicly exposed jBPM interfaces:

      • OpenExecution.setVariable(...);
      • ActivityExecution.setVariable(...);
      • ExecutionService.setVariable(...);

       

      So, to make my questions clear.

       

      Is this behavior normal for JBPM4_VARIABLE, I would have guessed it is not?

       

      And, what could be causing this strange behavior?

       

      Feel free to ask any more input or data that you consider could help further investigating this issue.

       

      -- Jorge

        • 1. Re: Multiple JBPM4_VARIABLE records pointing to same LOB_ and different EXECUTIONID_
          HuiSheng Xu Master

          Hi Jorge,

           

          Could you provide a testcase to reproduce this problem.  It will help us to understand this problem more clearly.  Thank you very much.

          • 2. Re: Multiple JBPM4_VARIABLE records pointing to same LOB_ and different EXECUTIONID_
            Jorge Ferreira Newbie

            At the moment I cannot create a test case that reproduces this problem. I haven't figured out a pattern for this situation. This issue appears from time to time in a large system. My best bet so far would be concurrency and some FK becomes mangled in the middle.

             

            I will continue to work on this issue to understand the root cause of the problem.

             

            From your answer can I assume that different JBPM4_VARIABLE  records SHOULD NOT point to the same LOB_?

             

            -- Jorge

            • 3. Re: Multiple JBPM4_VARIABLE records pointing to same LOB_ and different EXECUTIONID_
              Jorge Ferreira Newbie

              After looking into jBPM source code I get a concrete impression that there should not be two jbpm4_variable (Variable and class hierarchy) that share the same Lob. The Lob constructors take care (because generateDbId is true) of assigning a new id to the record.

               

              My best guess is something with the DatabaseDbIdGenerator but looking into the source code I have found nothing strange. More, the LOB_ that are duplicated as FK in jbpm4_variable table seem unrelated:

               

              1970117,
              1970123,
              1970218,
              2260229,
              2260232

               

              So a guess on edge cases, boundaries of block size, is off by now. I put a little test with two JVM for concurrency but the block generation is done inside a transaction and the behavior seems correct. One JVM fails but it is on a cycle of attempts and it peeks the next available block.

               

              Any ideas from the people that coded jBPM, maybe I am missing something.

               

              Can I instrument my source code in any way that would help debugging this issue? Or even jBPM source code.

               

              -- Jorge

              • 4. Re: Multiple JBPM4_VARIABLE records pointing to same LOB_ and different EXECUTIONID_
                HuiSheng Xu Master

                Hi Jorge,

                 

                I think what you said is correct,  there should be a shared Lob by two different variables.  Whenever we create a new variable, jbpm4 will always assign a unique dbid to it.

                 

                If you could tell us how you saved variable and the type and value of variable,  it will be much helpful for us to investigating.  Thank you very much.

                • 5. Re: Multiple JBPM4_VARIABLE records pointing to same LOB_ and different EXECUTIONID_
                  Jorge Ferreira Newbie

                  The ONLY types of variables that are stored for any given process:

                   

                  • org.w3c.dom.Document
                  • java.util.List<String>
                  • java.lang.Boolean
                  • java.lang.Long
                  • TWO custom classes that implement java.io.Serializable

                   

                  For setting a variable value we use several API, but all from publicly exposed jBPM interfaces:

                  • OpenExecution.setVariable(...);
                  • ActivityExecution.setVariable(...);
                  • ExecutionService.setVariable(...);

                   

                  At the moment JBPM4_VARIABLE has several pairs (2) of records that point to the same LOB_.

                   

                  select lob_
                  from jbpm4_variable
                  group by lob_
                  having count(1) > 1
                  order by lob_

                   

                   

                  select v.key_, v.execution_, v.lob_

                  from jbpm4_variable  v

                  where v.lob_ in (

                  1970117,

                  1970123,

                  1970218,

                  2260229,

                  2260232)

                  order by v.lob_

                   

                  key_execution_lob_
                  lastProcessTaskOutcome19402411970117
                  executionWarnings19701161970117
                  xmlObject19402411970123
                  processIdentifier19701161970123
                  xmlObject19701391970218
                  executionErrors19702121970218
                  executionErrors22601972260229
                  executionErrors22602232260229
                  executionWarnings22601972260232
                  xmlObject22602232260232

                   

                  The types of the variables are:

                  • lastProcessTaskOutcome - custom class that implements java.io.Serializable
                  • executionWarnings - java.util.List<String>
                  • xmlObject - org.w3c.dom.Document
                  • processIdentifier - java.lang.Long
                  • executionErrors - java.util.List<String>
                  • 6. Re: Multiple JBPM4_VARIABLE records pointing to same LOB_ and different EXECUTIONID_
                    Jorge Ferreira Newbie

                    We have found the cause of the problem.

                     

                    Basically jBPM was reusing the same block of identifiers as can be seen by the following two log lines:

                     

                    73099 2010-06-24 16:40:54,018 DEBUG [org.jbpm.pvm.internal.id.DatabaseDbidGenerator] acquired new id block [2610001-2620000]
                    75993 2010-06-24 17:22:05,254 DEBUG [org.jbpm.pvm.internal.id.DatabaseDbidGenerator] acquired new id block [2610001-2620000]

                     

                    That caused all sort of strange behavior. Now why is this happing? First let me talk about our environment setup.

                     

                    We use jBPM as part of an EAR application deployed in jBOSS. Because we did not want to manage different databases we deployed the jBPM tables in our application database. So a single database with both application tables and jBPM tables.

                     

                    The problem happens with very specific conditions, as one could expected, and is due to the nature of nested transactions.

                     

                    DatabaseDbIdGenerator picks a new block of ids inside a transaction. But because this can happen from an EJB call it will be a nested transaction.

                    Nested transactions are implemented differently in databases. However, they have in common that the changes are not made visibile to any unrelated transactions until the outermost transaction has committed. This means that a commit in an inner transaction does not necessary persist updates to the database.

                    The problem only happens if the block generation is done in a nested transaction and the outer transaction - that would commit definitely the results of the nested transaction - rollbacks for some reason.

                     

                    1. start transaction
                      1. start jbpm transaction for block generation
                        1. get current nextid from jbpm4_property - nextid = 1
                        2. update nextid in jbpm4_property - nextid = 100001
                      2. commit jbpm transaction
                      3. [...]
                      4. some error that causes an exception that means rollback
                    2. rollback transaction - nextid = 1

                     

                    Because the ultimate result will be to rollback the transaction the nextid that jBPM THINKS that is on the database is now incorrect. But it still holds that block in memory and uses it to assign ids. The next time a block generation happens the ids will start to be repeated.

                     

                    Perhaps a simple check SHOULD be added in DatabaseDbIdGenerator to ensure that the nextId returned from the database is after the lastId consumed?

                     

                    Our solution: implement a custom id generator that uses an independent transaction and hook it up using jbpm.default.cfg.xml.