Multiple JBPM4_VARIABLE records pointing to same LOB_ and different EXECUTIONID_

[imjorge]

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

[rebody]

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.

[imjorge]

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

[imjorge]

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

[rebody]

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.

[imjorge]

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_
lastProcessTaskOutcome	1940241	1970117
executionWarnings	1970116	1970117
xmlObject	1940241	1970123
processIdentifier	1970116	1970123
xmlObject	1970139	1970218
executionErrors	1970212	1970218
executionErrors	2260197	2260229
executionErrors	2260223	2260229
executionWarnings	2260197	2260232
xmlObject	2260223	2260232

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>

[imjorge]

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.