Bug 1002554 - Timer process with 0s delay fails in many interesting ways
Summary: Timer process with 0s delay fails in many interesting ways
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: JBoss BPMS Platform 6
Classification: Retired
Component: jBPM Core
Version: 6.0.0
Hardware: Unspecified
OS: Unspecified
high
high
Target Milestone: ER5
: 6.0.0
Assignee: Maciej Swiderski
QA Contact: Zuzana Krejčová
URL:
Whiteboard:
Depends On:
Blocks: 1002724 1212366
TreeView+ depends on / blocked
 
Reported: 2013-08-29 12:49 UTC by Zuzana Krejčová
Modified: 2016-08-01 01:07 UTC (History)
4 users (show)

Fixed In Version:
Clone Of:
Environment:
Last Closed: 2014-08-06 20:10:37 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)
server log excerpt (23.53 KB, text/x-log)
2013-08-29 12:49 UTC, Zuzana Krejčová
no flags Details
stacktraces in ER4 (55.78 KB, text/x-log)
2013-10-16 07:41 UTC, Zuzana Krejčová
no flags Details
process used (8.55 KB, application/xml)
2013-10-17 11:23 UTC, Zuzana Krejčová
no flags Details

Description Zuzana Krejčová 2013-08-29 12:49:18 UTC
Created attachment 791783 [details]
server log excerpt

Description of problem:
I have a simple process: Start -> Timer -> Script Task -> End. When the Timer duration is set to 0s, the behaviour gets... strange.

Sometimes, I get an exception stacktrace (see attachment). In this case, the instance finishes. Processinstanceinfo table does not contain this instance, processinstancelog has a record of this instance as completed. Nodeinstancelog table contains only records of the instance after leaving the timer node. Start node information and information about entering the timer node are missing.

Sometimes, I get no stack trace, but the instance never finishes. Processinstanceinfo table has a record of this instance, processinstancelog has a record of this instance as active. Nodeinstancelog table contains only records of the instance up to and including entering the timer node. This instance never finishes.

Sometimes, I get no stack trace, the instance finishes. Processinstanceinfo table might or might not contain this instance, processinstancelog has two records of this instance - one as active, one as completed. Nodeinstancelog table contains records for the whole instance, all the nodes, entering and leaving.

I'd like to add that 0s is not an invalid input, just perhaps one not used often.


Version-Release number of selected component (if applicable):
BPMS 6.0 ER2

Comment 1 Maciej Swiderski 2013-09-05 15:08:00 UTC
fixed by making sure that timer is scheduled only when transaction is successfully committed.

Commit on 6.0.x: https://github.com/droolsjbpm/jbpm/commit/079feb43af255453e1d63f0deaab16a2dd00129c

Comment 5 Zuzana Krejčová 2013-10-16 07:40:48 UTC
I haven't seen the original failures so far with ER4, so this is definitely going in the right direction, but I got this:

ERROR [org.jbpm.process.instance.timer.TimerManager] Error when executing timer job: javax.persistence.TransactionRequiredException: No active JTA transaction on joinTransaction call
...
(the instance was aborted during the timer node execution)

and this:

WARN  [com.arjuna.ats.jta] ARJUNA016029: SynchronizationImple.afterCompletion - failed for org.hibernate.engine.transaction.synchronization.internal.RegisteredSynchronization@aac4909 with exception: java.lang.NullPointerException
...
(the instance stayed active, in the timer node)

and this:

WARN  [com.arjuna.ats.arjuna] ARJUNA012127: TwoPhaseCoordinator.afterCompletion - returned failure for SynchronizationImple< 0:ffff0a22039f:cb13c7:525e3b90:562, org.hibernate.engine.transaction.synchronization.internal.RegisteredSynchronization@aac4909 >
...
(the instance stayed active, in the timer node, and all instances after it as well)

and this a few times:

INFO  [org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl] HHH000106: Forcing container resource cleanup on transaction completion
WARN  [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] SQL Error: 0, SQLState: null
ERROR [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] The result set is closed.
INFO  [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] IJ000311: Throwable from unregister connection: java.lang.IllegalStateException: Trying to return an unknown connection2! org.jboss.jca.adapters.jdbc.jdk6.WrappedConnectionJDK6@2e5064f8
...
(the instance stayed active, in the timer node)

Most of the instances run fine though.

Comment 6 Zuzana Krejčová 2013-10-16 07:41:52 UTC
Created attachment 812793 [details]
stacktraces in ER4

Comment 7 Zuzana Krejčová 2013-10-17 11:23:50 UTC
Created attachment 813271 [details]
process used

Comment 9 Zuzana Krejčová 2013-12-16 16:52:21 UTC
Verified with ER5.

As a sidenote - in 4 out of 30 such instances I got a variation on
"Could not commit session: javax.persistence.TransactionRequiredException: No active JTA transaction on joinTransaction call" (one with "ERROR [org.jbpm.process.instance.timer.TimerManager]")
in the server log. These instances though finished just fine and look the same as the rest in the gui, nothing seems wrong in the database either.

So this seems like a pretty harmless issue with unfortunate logging rather than the original bug. I'll put this into a separate, lower severity BZ.


Thanks!


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