EJB-JBPM: transaction clash (rollbacks)

[johan.parent]

Hi all,

I'm in desperate need for some pointers. I try to introduce jbpm (3.1.4) into an existing EJB2.X app. The jbpm code is wrapped in the thoroughly tested session bean, works. When the 2 are put together things collide. Monitoring of the db queries indicates that the business logic and jbpm are doing there work. BUT all the work is finally undone by a rollback on the db connection.

Unfortunately I can't cut&paste the logged data here. But in a nutshell: the app does a few selects then call the jbpm code to start a process. Nothing more. Any, really ANY, pointer would be welcome.

Best regards,

Johan

The setting:
- weblogic 8.1
- sybase
- jbpm 3.1.4
- both apps use the same datasource
- DbPersistenceServiceFactory:

<field name="isTransactionEnabled"><false /></field>

- hibernate settings:

 <property name="dialect">org.hibernate.dialect.SybaseDialect</property>
 <property name="hibernate.cache.provider_class">org.hibernate.cache.HashtableCacheProvider</property>
 <property name="hibernate.connection.datasource">tx_sybase</property>
 <property name="hibernate.transaction.factory_class">org.hibernate.transaction.CMTTransactionFactory</property>
 <property name="hibernate.transaction.manager_lookup_class">org.hibernate.transaction.WeblogicTransactionManagerLookup</property>

[kukeltje]

Jsut out of curiosity... why can't you cut and paste the logging here?

The other info (to me) is not enough, I'm no persistency expert... sorry

[estaub]

What's the question? Is it
"Where is the rollback?"

If so, all I can offer is the usual advice - log everything.
If that doesn't lead anywhere, you could start inserting getRollbackOnly() calls to narrow it down.

If you're wondering how to keep an application rollback from rolling back JBPM's persistence - me too! My current theory is to wrap all application work under a command-pattern SLSB that's set to REQUIRES_NEW. If you come up with anything better, please write it up!

-Ed Staub

[kukeltje]

"estaub" wrote:

If you're wondering how to keep an application rollback from rolling back JBPM's persistence - me too! My current theory is to wrap all application work under a command-pattern SLSB that's set to REQUIRES_NEW. If you come up with anything better, please write it up!

Does not sound to strange... Most people want it in one transaction. Let's ask one of the core developers... I'll notify them.

[johan.parent]

Thanks for the reaction guys!

The queries contain some sensitive/personal data and I just don't want my head chopped off by my boss :-P

Well I can post an edited (and somewhat shorter version of the output). It contains JBPM log info but also the queries, I don't think it is confusing. The "select" at the very beginning is the last query produced by the app. After that it's jbpm code. I removed the inserts for the variable instances but all is fine there. I did not leave any commit notifications out.

The way I interpret the output: after the final save() of the process instance the connection is rolled back. I got no clue why this happens, I don't understand nearly enough about dbs to be sure about this "conclusion". What I'm sure about it that there is not trace left in the db afterwards.

Regards,

Johan

 1,874ms executing PreparedStatement: SELECT WL0.Oid, WL0.CreDate, WL0.CreUserId, WL0.Domain, WL0.Identifier, WL0.isActive, WL0.ModDate, WL0.ModUserId, WL0.ServiceId, WL0.SettingId, WL0.SettingValue, WL0.Description, WL0.Version FROM user_db..ServiceSettings WL0 WHERE ( WL0.ServiceId = 'FER' )
creating jbpm context with service factories '[message, scheduler, logging, persistence, authentication]'
creating JbpmContext
creating persistence service
 2,037ms executing PreparedStatement: select processdef0_.ID_ as ID1_2_, processdef0_.NAME_ as NAME2_2_, processdef0_.VERSION_ as VERSION3_2_, processdef0_.ISTERMINATIONIMPLICIT_ as ISTERMIN4_2_, processdef0_.STARTSTATE_ as STARTSTATE5_2_ from JBPM_PROCESSDEFINITION processdef0_ where processdef0_.NAME_='createReadReport' order by processdef0_.VERSION_ desc
closing JbpmContext
closing service 'persistence': org.jbpm.persistence.db.DbPersistenceService@8d7e43
creating jbpm context with service factories '[message, scheduler, logging, persistence, authentication]'
creating JbpmContext
creating persistence service
 0,936ms executing PreparedStatement: select processdef0_.ID_ as ID1_2_, processdef0_.NAME_ as NAME2_2_, processdef0_.VERSION_ as VERSION3_2_, processdef0_.ISTERMINATIONIMPLICIT_ as ISTERMIN4_2_, processdef0_.STARTSTATE_ as STARTSTATE5_2_ from JBPM_PROCESSDEFINITION processdef0_ where processdef0_.NAME_='createReadReport' order by processdef0_.VERSION_ desc
 2,591ms executing PreparedStatement: insert into JBPM_TOKEN (VERSION_, NAME_, START_, END_, NODEENTER_, NEXTLOGINDEX_, ISABLETOREACTIVATEPARENT_, ISTERMINATIONIMPLICIT_, ISSUSPENDED_, NODE_, PROCESSINSTANCE_, PARENT_, SUBPROCESSINSTANCE_) values (0, null, '2007-07-13 13:51:48.533', null, null, 0, true, false, false, 95, null, null, null)
select @@identity
 1,169ms executing PreparedStatement: insert into JBPM_PROCESSINSTANCE (VERSION_, START_, END_, ISSUSPENDED_, PROCESSDEFINITION_, ROOTTOKEN_, SUPERPROCESSTOKEN_) values (0, '2007-07-13 13:51:48.533', null, false, 22, 328, null)
select @@identity
 1,146ms executing PreparedStatement: select definition0_.PROCESSDEFINITION_ as PROCESSD4_1_, definition0_.ID_ as ID1_1_, definition0_.NAME_ as NAME3_1_, definition0_.ID_ as ID1_15_0_, definition0_.NAME_ as NAME3_15_0_, definition0_.PROCESSDEFINITION_ as PROCESSD4_15_0_, definition0_.STARTTASK_ as STARTTASK5_15_0_, definition0_.CLASS_ as CLASS2_15_0_ from JBPM_MODULEDEFINITION definition0_ where definition0_.PROCESSDEFINITION_=22
event 'process-start' on 'ProcessDefinition(createReadReport)' for 'Token(/)'
 1,405ms executing PreparedStatement: select events0_.PROCESSDEFINITION_ as PROCESSD5_1_, events0_.ID_ as ID1_1_, events0_.EVENTTYPE_ as EVENTTYPE2_1_, events0_.ID_ as ID1_5_0_, events0_.EVENTTYPE_ as EVENTTYPE2_5_0_, events0_.TYPE_ as TYPE3_5_0_, events0_.GRAPHELEMENT_ as GRAPHELE4_5_0_ from JBPM_EVENT events0_ where events0_.PROCESSDEFINITION_=22
executing default save operations
saving process instance
flushing logs to logging service.
 2,191ms executing PreparedStatement: insert into JBPM_LOG (INDEX_, DATE_, TOKEN_, PARENT_, CLASS_) values (0, '2007-07-13 13:51:48.593', 328, null, 'I')
select @@identity
cascading save of 'org.jbpm.graph.exe.ProcessInstance@15c9b76'
executing default save operations
saving process instance
flushing logs to logging service.
cascading save of 'org.jbpm.graph.exe.ProcessInstance@15c9b76'
closing JbpmContext
closing service 'persistence': org.jbpm.persistence.db.DbPersistenceService@db7371
closing service 'logging': org.jbpm.logging.db.DbLoggingService@1782201
creating jbpm context with service factories '[message, scheduler, logging, persistence, authentication]'
creating JbpmContext
creating persistence service
create variable ...
... EDITED TO REMOVE CUSTOMER
2,270ms executing PreparedStatement: insert into JBPM_VARIABLEINSTANCE (NAME_, CONVERTER_, TOKEN_, TOKENVARIABLEMAP_, PROCESSINSTANCE_, STRINGVALUE_, CLASS_) values ('MEDICAL_SERVICE', null, 328, null, 328, 'FER', 'S')
select @@identity
 1,822ms executing PreparedStatement: insert into JBPM_LOG (INDEX_, DATE_, TOKEN_, PARENT_, VARIABLEINSTANCE_, CLASS_) values (1, '2007-07-13 13:51:48.804', 328, null, 5764, 'R')
select @@identity
 1,773ms executing PreparedStatement: insert into JBPM_LOG (INDEX_, DATE_, TOKEN_, PARENT_, VARIABLEINSTANCE_, OLDSTRINGVALUE_, NEWSTRINGVALUE_, CLASS_) values (2, '2007-07-13 13:51:48.804', 328, null, 5764, null, 'FER', 'U')
select @@identity
... EDITED HERE TOO
selected transition name 'createNewProcess'
 0,889ms executing PreparedStatement: select leavingtra0_.FROM_ as FROM4_1_, leavingtra0_.ID_ as ID1_1_, leavingtra0_.FROMINDEX_ as FROMINDEX6_1_, leavingtra0_.ID_ as ID1_4_0_, leavingtra0_.NAME_ as NAME2_4_0_, leavingtra0_.PROCESSDEFINITION_ as PROCESSD3_4_0_, leavingtra0_.FROM_ as FROM4_4_0_, leavingtra0_.TO_ as TO5_4_0_ from JBPM_TRANSITION leavingtra0_ where leavingtra0_.FROM_=96
event 'node-leave' on 'Decision(Check creation needed)' for 'Token(/)'
event 'transition' on 'Transition(createNewProcess)' for 'Token(/)'
 0,865ms executing PreparedStatement: select events0_.TRANSITION_ as TRANSITION7_1_, events0_.ID_ as ID1_1_, events0_.EVENTTYPE_ as EVENTTYPE2_1_, events0_.ID_ as ID1_5_0_, events0_.EVENTTYPE_ as EVENTTYPE2_5_0_, events0_.TYPE_ as TYPE3_5_0_, events0_.GRAPHELEMENT_ as GRAPHELE4_5_0_ from JBPM_EVENT events0_ where events0_.TRANSITION_=86
 0,952ms executing PreparedStatement: select node0_.ID_ as ID1_3_0_, node0_.NAME_ as NAME3_3_0_, node0_.PROCESSDEFINITION_ as PROCESSD4_3_0_, node0_.ISASYNC_ as ISASYNC5_3_0_, node0_.ACTION_ as ACTION6_3_0_, node0_.SUPERSTATE_ as SUPERSTATE7_3_0_, node0_.SUBPROCESSDEFINITION_ as SUBPROCE8_3_0_, node0_.DECISIONEXPRESSION_ as DECISION9_3_0_, node0_.DECISIONDELEGATION as DECISIO10_3_0_, node0_.SIGNAL_ as SIGNAL11_3_0_, node0_.CREATETASKS_ as CREATET12_3_0_, node0_.ENDTASKS_ as ENDTASKS13_3_0_, node
0_.CLASS_ as CLASS2_3_0_ from JBPM_NODE node0_ where node0_.ID_=97
event 'node-enter' on 'Node(Create Report)' for 'Token(/)'
 1,033ms executing PreparedStatement: select events0_.NODE_ as NODE6_1_, events0_.ID_ as ID1_1_, events0_.EVENTTYPE_ as EVENTTYPE2_1_, events0_.ID_ as ID1_5_0_, events0_.EVENTTYPE_ as EVENTTYPE2_5_0_, events0_.TYPE_ as TYPE3_5_0_, events0_.GRAPHELEMENT_ as GRAPHELE4_5_0_ from JBPM_EVENT events0_ where events0_.NODE_=97
 2,085ms executing PreparedStatement: select action0_.ID_ as ID1_6_0_, action0_.NAME_ as NAME3_6_0_, action0_.ISPROPAGATIONALLOWED_ as ISPROPAG4_6_0_, action0_.ACTIONEXPRESSION_ as ACTIONEX5_6_0_, action0_.ISASYNC_ as ISASYNC6_6_0_, action0_.REFERENCEDACTION_ as REFERENC7_6_0_, action0_.ACTIONDELEGATION_ as ACTIONDE8_6_0_, action0_.EVENT_ as EVENT9_6_0_, action0_.PROCESSDEFINITION_ as PROCESS10_6_0_, action0_.TIMERNAME_ as TIMERNAME11_6_0_, action0_.DUEDATE_ as DUEDATE12_6_0_, action0_.REPEAT_ as REPEAT13_6_0_, action0_.TRANSITIONNAME_ as TRANSIT14_6_0_, action0_.TIMERACTION_ as TIMERAC15_6_0_, action0_.EXPRESSION_ as EXPRESSION16_6_0_, action0_.class as class6_0_ from JBPM_ACTION action0_ where action0_.ID_=66
 0,791ms executing PreparedStatement: select delegation0_.ID_ as ID1_8_0_, delegation0_.CLASSNAME_ as CLASSNAME2_8_0_, delegation0_.CONFIGURATION_ as CONFIGUR3_8_0_, delegation0_.CONFIGTYPE_ as CONFIGTYPE4_8_0_, delegation0_.PROCESSDEFINITION_ as PROCESSD5_8_0_ from JBPM_DELEGATION delegation0_ where delegation0_.ID_=66
 1,464ms executing PreparedStatement: insert into JBPM_MODULEINSTANCE (PROCESSINSTANCE_, TASKMGMTDEFINITION_, CLASS_) values (328, 44, 'T')
select @@identity
 0,739ms executing PreparedStatement: insert into JBPM_MODULEINSTANCE (PROCESSINSTANCE_, CLASS_) values (328, 'C')
select @@identity
 0,848ms executing PreparedStatement: insert into JBPM_TOKENVARIABLEMAP (TOKEN_, CONTEXTINSTANCE_) values (328, 656)
select @@identity
 1,614ms executing PreparedStatement: select processdef0_.ID_ as ID1_2_, processdef0_.NAME_ as NAME2_2_, processdef0_.VERSION_ as VERSION3_2_, processdef0_.ISTERMINATIONIMPLICIT_ as ISTERMIN4_2_, processdef0_.STARTSTATE_ as STARTSTATE5_2_ from JBPM_PROCESSDEFINITION processdef0_ where processdef0_.NAME_='stresstest_ReadReport' order by processdef0_.VERSION_ desc
 1,312ms executing PreparedStatement: select exceptionh0_.NODE_ as NODE7_1_, exceptionh0_.ID_ as ID1_1_, exceptionh0_.GRAPHELEMENTINDEX_ as GRAPHELE6_1_, exceptionh0_.ID_ as ID1_7_0_, exceptionh0_.EXCEPTIONCLASSNAME_ as EXCEPTIO2_7_0_, exceptionh0_.TYPE_ as TYPE3_7_0_, exceptionh0_.GRAPHELEMENT_ as GRAPHELE4_7_0_ from JBPM_EXCEPTIONHANDLER exceptionh0_ where exceptionh0_.NODE_=97
 0,783ms executing PreparedStatement: select exceptionh0_.PROCESSDEFINITION_ as PROCESSD5_1_, exceptionh0_.ID_ as ID1_1_, exceptionh0_.GRAPHELEMENTINDEX_ as GRAPHELE6_1_, exceptionh0_.ID_ as ID1_7_0_, exceptionh0_.EXCEPTIONCLASSNAME_ as EXCEPTIO2_7_0_, exceptionh0_.TYPE_ as TYPE3_7_0_, exceptionh0_.GRAPHELEMENT_ as GRAPHELE4_7_0_ from JBPM_EXCEPTIONHANDLER exceptionh0_ where exceptionh0_.PROCESSDEFINITION_=22
closing JbpmContext
closing service 'persistence': org.jbpm.persistence.db.DbPersistenceService@1d3bb7b
Rolling back connection: com.sybase.jdbc2.jdbc.SybConnection@118d722
 4,033ms executing PreparedStatement: SELECT RequisitionNo,PerformingServiceId,SequenceNo,FollowUpState,ScheduledTime,Mnemonic,ItemGroupId,PerformingResourceId,AccessNo,RequisitionTime,OriginId,PresriberId,PrescriberName,EventServer,EventTable,EventPK,PatientId,MedServiceId,EventDefName,RelEventDefLevelId,Status,PatientLastName,PatientFirstName,HospitalisationNo,EventRefPK,VerwServiceId FROM ref_db..OrderComEventReferenceView WHERE AccessNo = '07B03406' and PerformingServiceId = 'LABA' ORDER B
Y RequisitionTime DESC
Committing connection: com.sybase.jdbc2.jdbc.SybConnection@118d722

[estaub]

I don't know anything about the Sybase driver.

But I think it's very possible that setRollbackOnly() was set much earlier, and the log message is only reflecting it much later at commit time.

The "4,033ms executing PreparedStatement: SELECT..." log at the end looks strange in the context of closing the JbpmContext. Is there more than one thread running? If so, you should modify the log format to show the thread.

-Ed Staub

[johan.parent]

There is only one thread, that's just the next loop in the test. The setRollBackOnly() idea is worth checking out, I'll do that. Thanks

Johan

[johan.parent]

Ok, I found it. A stupid mistake for a change. I should have seen the

select exceptionh0_.PROCESSDEFINITION_ as PROCESSD5_1_, except
ionh0_.ID_ as ID1_1_, exceptionh0_.GRAPHELEMENTINDEX_ as GRAPHELE6_1_, exceptionh0_.ID_ as ID1_7_0_,
 exceptionh0_.EXCEPTIONCLASSNAME_ as EXCEPTIO2_7_0_, exceptionh0_.TYPE_ as TYPE3_7_0_, exceptionh0_.
GRAPHELEMENT_ as GRAPHELE4_7_0_ from JBPM_EXCEPTIONHANDLER

I missed an exception in one of the handlers. Bit a pitty it is so easily overlooked if you don't define an exception handler in your process.

Anyway, again thanks for the input guys!

Johan

[estaub]

Bit a pitty it is so easily overlooked if you don't define an exception handler in your process.

The log message certainly doesn't jump out and bite you!

Do you perhaps want to JIRA it?

-Ed Staub

[kukeltje]

Does it stand out if the queries are not displayed fully?

[johan.parent]

Sorry for the late reply.

The log message certainly doesn't jump out and bite you!

Does it stand out if the queries are not displayed fully?

The output I pasted in this thread is that with DEBUG set for log4j.logger.org.jbpm . So it is definitely insufficiently reported.

Do you perhaps want to JIRA it?

I will do that. I think some logging when no exception handlers were specified should not be too hard.

Regards,

Johan