Possible bug in Activiti Engine : cancelling sub-process containing intermediate timer catching events should be cancelled by si

[michalwrobel]

I have developed a following process :

https://dl.dropboxusercontent.com/u/1846654/subprocess.jpg

As you can see the sub-process contains two intermediate catching time events.
When the boundary signal occurs, the process goes through appropriate flow as expected.. but in the next moment black magic happens.

Acknowledgement : Of course I set the cancelActivity="true".

I can see the sub-process is coming alive from dead again (subprocess still does log tasks) then goes the ActivitiOptimisticLockingException stacktrace, and after that sub-process continues to execute just as if nothing happened.

What I suspect is that signal is delivered during suspension of the subProcess when it waits for the timer event to fire, and subprocess isn't aware that the signal was processed and the subProcess should be therefore terminated at once.

The expected behavior would be to terminate the subProcess even when it's suspended by a timer, isn't it.. ?

The log and stacktrace goes as follows:

[LOG] LED OFF (inside subprocess) timestamp:Mon Mar 03 14:54:42 CET 2014
[LOG] LED ON (inside subprocess) timestamp:Mon Mar 03 14:54:43 CET 2014
[SIGNAL] normal-temperature (can cancel subprocess) payload:25
[LOG] ****Leaving subprocess******* (main process) timestamp:Mon Mar 03 14:54:44 CET 2014
[LOG]Temperature below 25  (main process)
[LOG] LED OFF (inside subprocess) timestamp:Mon Mar 03 14:54:44 CET 2014
Output from Server:

2014-03-03 14:54:44.894:WARN:eaw.DeviceCatalogWebSocket:WebSocketClient@192486017-26: Unhandled Error (closing connection)
org.eclipse.jetty.websocket.api.WebSocketException: Cannot call method public void mwrobel.activiti.websocket.DeviceCatalogWebSocket#onMessage(java.lang.String) with args: [java.lang.String]
   at org.eclipse.jetty.websocket.common.events.annotated.CallableMethod.call(CallableMethod.java:99)
   at org.eclipse.jetty.websocket.common.events.annotated.OptionalSessionCallableMethod.call(OptionalSessionCallableMethod.java:72)
   at org.eclipse.jetty.websocket.common.events.JettyAnnotatedEventDriver.onTextMessage(JettyAnnotatedEventDriver.java:209)
   at org.eclipse.jetty.websocket.common.message.SimpleTextMessage.messageComplete(SimpleTextMessage.java:69)
   at org.eclipse.jetty.websocket.common.events.AbstractEventDriver.appendMessage(AbstractEventDriver.java:64)
   at org.eclipse.jetty.websocket.common.events.JettyAnnotatedEventDriver.onTextFrame(JettyAnnotatedEventDriver.java:201)
   at org.eclipse.jetty.websocket.common.events.AbstractEventDriver.incomingFrame(AbstractEventDriver.java:169)
   at org.eclipse.jetty.websocket.common.WebSocketSession.incomingFrame(WebSocketSession.java:302)
   at org.eclipse.jetty.websocket.common.extensions.ExtensionStack.incomingFrame(ExtensionStack.java:204)
   at org.eclipse.jetty.websocket.common.Parser.notifyFrame(Parser.java:223)
   at org.eclipse.jetty.websocket.common.Parser.parse(Parser.java:260)
   at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.read(AbstractWebSocketConnection.java:500)
   at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.onFillable(AbstractWebSocketConnection.java:409)
   at org.eclipse.jetty.io.AbstractConnection$1.run(AbstractConnection.java:505)
   at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:607)
   at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:536)
   at java.lang.Thread.run(Thread.java:744)
Caused by: 
java.lang.reflect.InvocationTargetException
   at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
   at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
   at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
   at java.lang.reflect.Method.invoke(Method.java:483)
   at org.eclipse.jetty.websocket.common.events.annotated.CallableMethod.call(CallableMethod.java:71)
   at org.eclipse.jetty.websocket.common.events.annotated.OptionalSessionCallableMethod.call(OptionalSessionCallableMethod.java:72)
   at org.eclipse.jetty.websocket.common.events.JettyAnnotatedEventDriver.onTextMessage(JettyAnnotatedEventDriver.java:209)
   at org.eclipse.jetty.websocket.common.message.SimpleTextMessage.messageComplete(SimpleTextMessage.java:69)
   at org.eclipse.jetty.websocket.common.events.AbstractEventDriver.appendMessage(AbstractEventDriver.java:64)
   at org.eclipse.jetty.websocket.common.events.JettyAnnotatedEventDriver.onTextFrame(JettyAnnotatedEventDriver.java:201)
   at org.eclipse.jetty.websocket.common.events.AbstractEventDriver.incomingFrame(AbstractEventDriver.java:169)
   at org.eclipse.jetty.websocket.common.WebSocketSession.incomingFrame(WebSocketSession.java:302)
   at org.eclipse.jetty.websocket.common.extensions.ExtensionStack.incomingFrame(ExtensionStack.java:204)
   at org.eclipse.jetty.websocket.common.Parser.notifyFrame(Parser.java:223)
   at org.eclipse.jetty.websocket.common.Parser.parse(Parser.java:260)
   at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.read(AbstractWebSocketConnection.java:500)
   at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.onFillable(AbstractWebSocketConnection.java:409)
   at org.eclipse.jetty.io.AbstractConnection$1.run(AbstractConnection.java:505)
   at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:607)
   at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:536)
   at java.lang.Thread.run(Thread.java:744)
Caused by: 
org.activiti.engine.ActivitiOptimisticLockingException: JobEntity [id=292] was updated by another transaction concurrently
   at org.activiti.engine.impl.db.DbSqlSession$CheckedDeleteOperation.execute(DbSqlSession.java:227)
   at org.activiti.engine.impl.db.DbSqlSession.flushDeletes(DbSqlSession.java:577)
   at org.activiti.engine.impl.db.DbSqlSession.flush(DbSqlSession.java:445)
   at org.activiti.engine.impl.interceptor.CommandContext.flushSessions(CommandContext.java:170)
   at org.activiti.engine.impl.interceptor.CommandContext.close(CommandContext.java:117)
   at org.activiti.engine.impl.interceptor.CommandContextInterceptor.execute(CommandContextInterceptor.java:66)
   at org.activiti.spring.SpringTransactionInterceptor$1.doInTransaction(SpringTransactionInterceptor.java:47)
   at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:130)
   at org.activiti.spring.SpringTransactionInterceptor.execute(SpringTransactionInterceptor.java:45)
   at org.activiti.engine.impl.interceptor.LogInterceptor.execute(LogInterceptor.java:31)
   at org.activiti.engine.impl.cfg.CommandExecutorImpl.execute(CommandExecutorImpl.java:40)
   at org.activiti.engine.impl.cfg.CommandExecutorImpl.execute(CommandExecutorImpl.java:35)
   at org.activiti.engine.impl.RuntimeServiceImpl.signalEventReceived(RuntimeServiceImpl.java:248)
   at mwrobel.activiti.websocket.DeviceCatalogWebSocket.onMessage(DeviceCatalogWebSocket.java:49)
   at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
   at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
   at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
   at java.lang.reflect.Method.invoke(Method.java:483)
   at org.eclipse.jetty.websocket.common.events.annotated.CallableMethod.call(CallableMethod.java:71)
   at org.eclipse.jetty.websocket.common.events.annotated.OptionalSessionCallableMethod.call(OptionalSessionCallableMethod.java:72)
   at org.eclipse.jetty.websocket.common.events.JettyAnnotatedEventDriver.onTextMessage(JettyAnnotatedEventDriver.java:209)
   at org.eclipse.jetty.websocket.common.message.SimpleTextMessage.messageComplete(SimpleTextMessage.java:69)
   at org.eclipse.jetty.websocket.common.events.AbstractEventDriver.appendMessage(AbstractEventDriver.java:64)
   at org.eclipse.jetty.websocket.common.events.JettyAnnotatedEventDriver.onTextFrame(JettyAnnotatedEventDriver.java:201)
   at org.eclipse.jetty.websocket.common.events.AbstractEventDriver.incomingFrame(AbstractEventDriver.java:169)
   at org.eclipse.jetty.websocket.common.WebSocketSession.incomingFrame(WebSocketSession.java:302)
   at org.eclipse.jetty.websocket.common.extensions.ExtensionStack.incomingFrame(ExtensionStack.java:204)
   at org.eclipse.jetty.websocket.common.Parser.notifyFrame(Parser.java:223)
   at org.eclipse.jetty.websocket.common.Parser.parse(Parser.java:260)
   at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.read(AbstractWebSocketConnection.java:500)
   at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.onFillable(AbstractWebSocketConnection.java:409)
   at org.eclipse.jetty.io.AbstractConnection$1.run(AbstractConnection.java:505)
   at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:607)
   at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:536)
   at java.lang.Thread.run(Thread.java:744)
2014-03-03 14:54:44.905:INFO:oejwc.WebSocketClient:WebSocketClient@192486017-26: Session Closed: WebSocketSession[websocket=JettyAnnotatedEventDriver[mwrobel.activiti.websocket.DeviceCatalogWebSocket@7ac6a442],behavior=CLIENT,connection=WebSocketClientConnection@543423c0{FILLING}{g=Generator[CLIENT,validating],p=Parser@433a9f74[ExtensionStack,s=START,c=0,len=277,f=TEXT[len=0,fin=true,rsv=…,masked=false],p=WebSocketPolicy@9c54c9d[behavior=CLIENT,maxTextMessageSize=65536,maxTextMessageBufferSize=32768,maxBinaryMessageSize=65536,maxBinaryMessageBufferSize=32768,asyncWriteTimeout=60000,idleTimeout=300000,inputBufferSize=4096]]},remote=org.eclipse.jetty.websocket.common.WebSocketRemoteEndpoint@46ee0d53,incoming=JettyAnnotatedEventDriver[mwrobel.activiti.websocket.DeviceCatalogWebSocket@7ac6a442],outgoing=ExtensionStack[extensions=[],incoming=org.eclipse.jetty.websocket.common.WebSocketSession,outgoing=org.eclipse.jetty.websocket.client.io.WebSocketClientConnection]]


[LOG] LED ON (inside subprocess) timestamp:Mon Mar 03 14:54:45 CET 2014
[LOG] LED OFF (inside subprocess) timestamp:Mon Mar 03 14:54:46 CET 2014
[LOG] LED ON (inside subprocess) timestamp:Mon Mar 03 14:54:47 CET 2014
[LOG] LED OFF (inside subprocess) timestamp:Mon Mar 03 14:54:48 CET 2014
[LOG] LED ON (inside subprocess) timestamp:Mon Mar 03 14:54:49 CET 2014
[LOG] LED OFF (inside subprocess) timestamp:Mon Mar 03 14:54:50 CET 2014
[LOG] LED ON (inside subprocess) timestamp:Mon Mar 03 14:54:51 CET 2014
[LOG] LED OFF (inside subprocess) timestamp:Mon Mar 03 14:54:52 CET 2014
[LOG] LED ON (inside subprocess) timestamp:Mon Mar 03 14:54:53 CET 2014
[LOG] LED OFF (inside subprocess) timestamp:Mon Mar 03 14:54:54 CET 2014
[LOG] LED ON (inside subprocess) timestamp:Mon Mar 03 14:54:55 CET 2014
[LOG] LED OFF (inside subprocess) timestamp:Mon Mar 03 14:54:56 CET 2014
[LOG] LED ON (inside subprocess) timestamp:Mon Mar 03 14:54:57 CET 2014
[LOG] LED OFF (inside subprocess) timestamp:Mon Mar 03 14:54:58 CET 2014
[LOG] LED ON (inside subprocess) timestamp:Mon Mar 03 14:54:59 CET 2014
‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

(AND IT GOES LIKE THIS TO INFINITY)

[jbarrez]

> The expected behavior would be to terminate the subProcess even when it's suspended by a timer, isn't it.. ?

Correct.

Can you upload the process xml (preferably in a simplified form so we can test it easily)?

[michalwrobel]

(I added .txt extension for the uploaded files because of security policy)
Ok, so I simplified it, now the process uses just script tasks which log something to the console, but in this form the bug tends to be more elusive, not so easy to reproduce. Especially with default timer settings which should be over 5 seconds.  Previously the service tasks had more sophisticated logic, they called some REST webservices, and the bug occured almost every time. 

You enter the loop by sending 'critical-temperature' signal, and the subprocess should exit with 'normal-temperature' signal.
To easier reproduce the bug I lowered timer settings in this case to 1 second.

NOTICE : To achieve such timer interval it was required to tweak the job executor class (there was a bug filed about this somewhere in JIRA, by default the sleep time is set for 5 seconds there). The tweaked job executor is also attached to the post.

Plus the configuration in activiti-context.xml to enable custom job executor:

<code>

<bean id="processEngineConfiguration" class="org.activiti.spring.SpringProcessEngineConfiguration">
        <property name="dataSource" ref="dataSource" />
        <property name="transactionManager" ref="transactionManager" />
        <property name="databaseSchemaUpdate" value="true" />
        <property name="mailServerHost" value="localhost" />
        <property name="mailServerPort" value="5025" />
        <property name="jobExecutorActivate" value="true" />
        <property name="jobExecutor" ref="jobExecutor" />
    </bean>
       
    <bean id="jobExecutor" class="xxxx.activiti.extensions.JobExecutor" />
</code>
After lowering the timer settings you should easily (but not always) get response like this from signal service after sending 'normal-temperature':
<code>
{
errorMessage: "JobEntity [id=348] was updated by another transaction concurrently"
statusCode: 409
}
</code>

[jbarrez]

I tried these processes, but it's very hard to reproduce. It is surely around timing and things going on in parallel. However, what happens (i assume) is that the timer wins vs the signal … and only one can win.

[michalwrobel]

But you managed to reproduce it a few times?
Are you going to investigate it further? I think it's a quite serious bug..

[jbarrez]

> But you managed to reproduce it a few times?

No, I didn't. I ran it 10 times but no issue.

> Are you going to investigate it further? I think it's a quite serious bug..


Everybody's bug is serious 😉 To look into it i would need a 100% reproducable test im afraid