Timestamp issues

[dan1]

Hi,

I have the following setup:

Activiti 5.21
Tomcat 8
Java 8
Postgresql 9.4.1208

I'm having issues with the timestamps stored in ACT_RU_TASK and ACT_HI_ACTINST by Activiti Engine. The timestamp provided by the engine is roughly a day behind the system time. Both Java and Postgres have the correct time. Activiti logs also have the correct time. However, timestamps generated by getClock().getCurrentTime() are wrong. And its stuck. After starting up tomcat and deploying the app, getCurrentTime() always returns the same value. So all my user tasks start and end at the same time. And of course, timers have issues.

I created a simple progress called Timestamps with a groovy script followed by a user task. Here is the script:

println "Entering Groovy Timestamp Script…"

def javaDate = new java.util.Date();
println "    Java date:     " + javaDate.toString()

def activitiDate = execution.getEngineServices().getProcessEngineConfiguration().getClock().getCurrentTime();
println "    Activiti date: " + activitiDate.toString()
‍‍‍‍‍‍‍‍‍

If I start that process twice in a row, here is the output:

Entering Groovy Timestamp Script…
    Java date:     Tue Jul 19 06:47:23 EDT 2016
    Activiti date: Mon Jul 18 06:46:31 EDT 2016
Entering Groovy Timestamp Script…
    Java date:     Tue Jul 19 06:47:36 EDT 2016
    Activiti date: Mon Jul 18 06:46:31 EDT 2016
‍‍‍‍‍‍‍‍

Notice that the Java Date is correct and advances by several seconds. While the Activiti date is roughly a day behind and is stuck. When I complete the 2 user tasks (one per run) sometime later, the end timestamps are the same value too. Effectively, the engine is always generating the same incorrect value for date. In other words, ACT_HI_ACTINST START_TIME_ and END_TIME_ values are equal to each other and the same across all runs.

I wrote another little process called Reset Clock. Its a groovy script that calls getClock().reset().

println "Resting engine clock to match current date."
def javaDate = new java.util.Date();
println "    Current date:     " + javaDate.toString()

def clock = execution.getEngineServices().getProcessEngineConfiguration().getClock()
clock.reset();
def resetDate =  clock.getCurrentTime();
println "    Reset date:        " + resetDate.toString()
‍‍‍‍‍‍‍‍‍‍

Here is output which works as you'd expect:

Resting engine clock to match current date.
    Current date:     Tue Jul 19 06:47:52 EDT 2016
    Reset date:        Tue Jul 19 06:47:52 EDT 2016
‍‍‍‍‍

Now if I go back to the original Timestamps process, things start to work as expected:

Entering Groovy Timestamp Script…
    Java date:     Tue Jul 19 06:48:28 EDT 2016
    Activiti date: Tue Jul 19 06:48:28 EDT 2016
Entering Groovy Timestamp Script…
    Java date:     Tue Jul 19 06:48:36 EDT 2016
    Activiti date: Tue Jul 19 06:48:36 EDT 2016
‍‍‍‍‍‍‍‍

And when I complete the associated user tasks, they have correct timestamps at the end (i.e. ACT_HI_ACTINST is correct).

Looking through the code and many similar issues on the forum, I'm at a loss for what is going on. Seems that others have had similar issues:

https://forums.activiti.org/content/wrong-date-activiti-explorer-handle-vacation-request
https://forums.activiti.org/content/newbie-activiti-clock-configuration
https://forums.activiti.org/content/boundary-event-subprocess-not-firing
etc.

My current work around is to uncomment out all the xml in activiti-custom-context.xml. Then add a bean for engineClock which is DefaultClockImpl. Set that in the clock property of the processEngineConfiguration. And finally, schedule a one time task to invoke the reset method on the engineClock. See attached file.

My solution is a hack. Any clues how to solve this a better way?

Thanks,
Dan

[martin_grofcik]

Hi,

the best would be jUnit test.
It seems that you are setting a clock to -1D value somewhere in the code. That why clock implementation returns always the same value.

Regards
Martin

[dan1]

Hi Martin,

I'm using Activiti Engine and Explorer out of the box other than db, log4j, and engine property settings. I haven't modified any code. I decided to try one more thing. I went back to the original activiti-custom-context.xml WITHOUT my workaround to reproduce the issue. When the issue happens, I see this when tomcat starts up:

<code>
05:18:36,309 [Thread-5] INFO  org.activiti.engine.impl.asyncexecutor.AcquireTimerJobsRunnable  - starting to acquire async jobs due
05:18:36,349 [localhost-startStop-1] INFO  org.activiti.explorer.conf.DemoDataConfiguration  - Initializing demo groups
05:18:36,418 [localhost-startStop-1] INFO  org.activiti.explorer.conf.DemoDataConfiguration  - Initializing demo users
05:18:36,512 [localhost-startStop-1] INFO  org.activiti.explorer.conf.DemoDataConfiguration  - Initializing demo report data
05:18:36,514 [Thread-7] INFO  org.activiti.engine.impl.asyncexecutor.AbstractAsyncJobExecutor  - Shutting down the default async job executor [org.activiti.engine.impl.asyncexecutor.DefaultAsyncJobExecutor].
05:18:36,515 [Thread-5] INFO  org.activiti.engine.impl.asyncexecutor.AcquireTimerJobsRunnable  - stopped async job due acquisition
05:18:36,515 [Thread-6] INFO  org.activiti.engine.impl.asyncexecutor.AcquireAsyncJobsDueRunnable  - stopped async job due acquisition
Exception in thread "Thread-7" org.activiti.engine.ActivitiObjectNotFoundException: no processes deployed with key 'reviewSaledLead'
at org.activiti.engine.impl.persistence.deploy.DeploymentManager.findDeployedLatestProcessDefinitionByKey(DeploymentManager.java:145)
at org.activiti.engine.impl.cmd.StartProcessInstanceCmd.execute(StartProcessInstanceCmd.java:79)
at org.activiti.engine.impl.cmd.StartProcessInstanceCmd.execute(StartProcessInstanceCmd.java:37)
at org.activiti.engine.impl.interceptor.CommandInvoker.execute(CommandInvoker.java:24)
at org.activiti.engine.impl.interceptor.CommandContextInterceptor.execute(CommandContextInterceptor.java:57)
at org.activiti.spring.SpringTransactionInterceptor$1.doInTransaction(SpringTransactionInterceptor.java:47)
at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:133)
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.startProcessInstanceByKey(RuntimeServiceImpl.java:82)
at org.activiti.explorer.conf.DemoDataConfiguration$1.run(DemoDataConfiguration.java:247)
at java.lang.Thread.run(Thread.java:745)
</code>

If I set create.demo.reports=false in the db.properties, tomcat starts up and deploys explorer without that exception and the system behaves as expected.

Here is my working db.properties (and I don't need the afore mentioned workaround where I reset the clock in activiti-custom-context.xml):

<code>
# demo data properties
create.demo.users=true
create.demo.definitions=false
create.demo.models=false
create.demo.reports=true

# engine properties
engine.schema.update=true
engine.activate.jobexecutor=true
engine.asyncexecutor.enabled=true
engine.asyncexecutor.activate=true
engine.history.level=full
</code>

Ultimately, it seems there is a hole where that exception occurs that causes the clock to get jacked up.

For now, I'm am fine since I no longer need my hacked up workaround. And I don't depend on the out of box reports since they need to be modified for Java 8 anyway.

Thanks,
Dan