Bug 779036 (SOA-1447) - jBPM exception logging can block execution of all processes
Summary: jBPM exception logging can block execution of all processes
Keywords:
Status: CLOSED NEXTRELEASE
Alias: SOA-1447
Product: JBoss Enterprise SOA Platform 4
Classification: JBoss
Component: JBPM - within SOA
Version: unspecified
Hardware: Unspecified
OS: Unspecified
urgent
urgent
Target Milestone: ---
: 4.3 CP04 ER1
Assignee: Alejandro Guizar
QA Contact:
URL: http://jira.jboss.org/jira/browse/SOA...
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2009-08-17 10:50 UTC by Jiri Pechanec
Modified: 2010-03-23 15:44 UTC (History)
1 user (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
CP02-CR2/embedded/PostgreSQL/Fedora10
Last Closed: 2010-03-23 15:44:54 UTC
Type: Bug


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Issue Tracker SOA-1447 0 None None None Never

Description Jiri Pechanec 2009-08-17 10:50:31 UTC
Date of First Response: 2009-08-18 00:26:56
project_key: SOA

If an exception is thrown during jBPM process execution then jBPM tries to log exception into database. Unfortunately if it fails (e.g. exception is longer than the column width) and it happens in JobExecutor then
1) The transaction is rolled back
2) JobExecutor goes to sleep for progressively growing time
3) After the wake-up it tries to re-execute the failing process but the execption is thrown again
4) Because all jobs in job executor are processed in the same transaction the processing of all jBPM processes is blocked

How to reproduce
1) Take bpm_orchestration1 quickstart and modify the process definition to generate an exception
      <action name="action2" class="org.jboss.soa.esb.services.jbpm.actionhandlers.EsbActionHandler">
         <esbCategoryName>BPM_Orchestration_Service1</esbCategoryName>
         <esbServiceName>Service1</esbServiceName>
         <bpmToEsbVars>
                <mapping bpm="THISISERROR" esb="BODY_CONTENT" />
         </bpmToEsbVars>
         <esbToBpmVars>
                <mapping esb="BODY_CONTENT" bpm="theBody" />
         </esbToBpmVars>
      </action>
2) Deploy ESB archive, process and start the process
3) Deploy ESB archive, process and start the process of bpm_orchestration2

None of the processes is executed
 bpm_orchestration1 repeatedly generates an exception
 bpm_orchestration2 is not executed at all

2009-08-17 12:32:25,024 ERROR [org.hibernate.event.def.AbstractFlushingEventListener] Could not synchronize database state with session
org.hibernate.exception.DataException: could not update: [org.jbpm.job.ExecuteActionJob#35]
	at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:77)
	at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:43)
	at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2429)
	at org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:2311)
	at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2611)
	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:1406)
	at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:134)
	at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:87)
	at org.jboss.tm.usertx.client.ServerVMClientUserTransaction.commit(ServerVMClientUserTransaction.java:146)
	at org.jbpm.persistence.jta.JtaDbPersistenceService.commit(JtaDbPersistenceService.java:98)
	at org.jbpm.persistence.db.DbPersistenceService.endTransaction(DbPersistenceService.java:135)
	at org.jbpm.persistence.db.DbPersistenceService.close(DbPersistenceService.java:201)
	at org.jbpm.svc.Services.close(Services.java:247)
	at org.jbpm.JbpmContext.close(JbpmContext.java:131)
	at org.jbpm.job.executor.JobExecutorThread.executeJob(JobExecutorThread.java:202)
	at org.jbpm.job.executor.JobExecutorThread.run(JobExecutorThread.java:63)
Caused by: org.postgresql.util.PSQLException: ERROR: value too long for type character varying(4000)
	at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:1531)
	at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1313)
	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:188)
	at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:452)
	at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:354)
	at org.postgresql.jdbc2.AbstractJdbc2Statement.executeUpdate(AbstractJdbc2Statement.java:308)
	at org.jboss.resource.adapter.jdbc.WrappedPreparedStatement.executeUpdate(WrappedPreparedStatement.java:278)
	at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2411)
	... 26 more
2009-08-17 12:32:25,024 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator_2] TwoPhaseCoordinator.beforeCompletion - failed for com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple@28b636
org.hibernate.exception.DataException: could not update: [org.jbpm.job.ExecuteActionJob#35]
	at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:77)
	at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:43)
	at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2429)
	at org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:2311)
	at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2611)
	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:1406)
	at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:134)
	at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:87)
	at org.jboss.tm.usertx.client.ServerVMClientUserTransaction.commit(ServerVMClientUserTransaction.java:146)
	at org.jbpm.persistence.jta.JtaDbPersistenceService.commit(JtaDbPersistenceService.java:98)
	at org.jbpm.persistence.db.DbPersistenceService.endTransaction(DbPersistenceService.java:135)
	at org.jbpm.persistence.db.DbPersistenceService.close(DbPersistenceService.java:201)
	at org.jbpm.svc.Services.close(Services.java:247)
	at org.jbpm.JbpmContext.close(JbpmContext.java:131)
	at org.jbpm.job.executor.JobExecutorThread.executeJob(JobExecutorThread.java:202)
	at org.jbpm.job.executor.JobExecutorThread.run(JobExecutorThread.java:63)
Caused by: org.postgresql.util.PSQLException: ERROR: value too long for type character varying(4000)
	at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:1531)
	at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1313)
	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:188)
	at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:452)
	at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:354)
	at org.postgresql.jdbc2.AbstractJdbc2Statement.executeUpdate(AbstractJdbc2Statement.java:308)
	at org.jboss.resource.adapter.jdbc.WrappedPreparedStatement.executeUpdate(WrappedPreparedStatement.java:278)
	at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2411)
	... 26 more

Comment 1 Jiri Pechanec 2009-08-17 11:03:40 UTC
Link: Added: This issue depends JBPM-2488


Comment 2 Ryan Zhang 2009-08-18 04:26:56 UTC
If the exception is SqlException, could we just rollback the current job instead of retry it.  Can't understand why all jobs in Job Executor will be processed in one transaction.

Comment 3 Kevin Conner 2009-08-30 21:24:47 UTC
I don't believe they are all executed within the same transaction.

A context is created for each execution, the closing of which is causing the transaction to be rolled back.  As a consequence the job executor will pause for a period and then reacquire jobs, the first of which will probably be the failing one from the last iteration.

Is this supposed to be assigned to me?

Comment 4 Alejandro Guizar 2009-11-10 16:19:56 UTC
Resolved upstream as of version 3.2.7

Comment 5 David Le Sage 2010-02-25 04:43:27 UTC
Please review the following draft text added to the Resolved Issues section of the Release Notes:


https://jira.jboss.org/jira/browse/JBPM-2488

    If an exception is thrown during jBPM process execution, it would be logged in a database.
    Unfortunately, this would sometimes fail if the exception message was longer than the database's
    column width. The context created for each execution would close, the transaction was the                                                                                                     
    rolled back, the JobExecutor would sleep for a period and then it would attempt to execute the
    process once more and fail again, blocking all other jobs from being processed.

    To eliminate this problem, there is now a cap length for stack traces. This applies to all databases
    apart from Sybase. As a result, the transactions are no longer rolled back and other processes are
    no longer blocked by the failing process.


Comment 6 Jiri Pechanec 2010-03-23 15:44:54 UTC
Verified in ER1


Note You need to log in before you can comment on or make changes to this bug.