AnsweredAssumed Answered

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

Question asked by michalwrobel on Mar 3, 2014
Latest reply on Mar 24, 2014 by jbarrez
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)

Outcomes