Re: Wrong dates. Activiti deployment date.

vipi_voxa · ‎23 Jan 2017

Hello Fellows!

I experience this strange product behavior, quite critical thing i must admit. The processes i am deploying via activiti explorer are getting wrong deployment date. And what is more crucial - instance actions also randomly gets wrong start_time_ and end_time_.

Well, with a deployment i can replicate it quite easily. I just go to activiti admin (logged as kermit_ and deploy my test processes. (Screenshot attached. You can see in a screen shot that OS date and time as well as DB date and time are fine). With instance actions i have not found a straight path to replicate, it is just happening, and it is a complete stopper to use the product, since it is not possible to analyze when the action happened.

Maybe somebody can assist me with a solution. Hope it's kind of configuration or something...

thank you in advance!

activit 5.22.0

db oracle 11g

app server: (wildfly) Jboss eap 7.0.0.GA

os jboss running on - windows 7 pro

cjose · ‎23 Jan 2017

The process is most likely not getting deployed if there is no change to your bpmn xml. There is filtering in place that prevents duplicate deployments (Please see Activiti User Guide). If this is not the case, could you please provide a unit test to easily reproduce this issue?

Regards,

Ciju

gdharley · ‎23 Jan 2017

Just to clarify what Ciju said (which is absolutely correct).
When a new bar, zip or bpmn xml file is deployed, the deployment code checks to see if there were any changes to the bpmn files. Only if the bpmn file is updated or modified is the process redeployed. This can really cause confusion when other assets in the bar/zip may have changed.

vipi_voxa · ‎24 Jan 2017

Guys thank you at looking at this!

well, just to make it absolutely clear, the new deployment is successfully deployed. Before the deployment of the new process there are no similar deployments deployed (you probably can notice it in the deployment list on the first screenshot, left side - list of deployments consist only of demo reports and demo processes).

Table act_re_deployment does not hold any records about the new deployment on the moment of the deployment. I hope it is clear enough now.

After new deployment is done, the record appears in act_re_deployment not only with the wrong date but with the wrong time as well (date is in a past).

Can you please guide me a of how to create a test case for this scenario? I can replicate it every time i deploy any process.

gdharley · ‎24 Jan 2017

A couple of things we need in order to be able to reproduce this.

1. How are you deploying the app (REST, Java, spring auto deploy)?

2. What timezone is your laptop/computer in?

3. What timezone is the server in?
4. What timezone is the database in?

I have trouble seeing the specific dates in the database snapshot (I'm old and my eyes dont work very well) and without understanding the deployment mechanism and time it occurred (from your perspective) it's hard to piece together a scenario.

Thx,

Greg

‌

vipi_voxa · ‎24 Jan 2017

Hi Greg,

Please find the answers below.

1. I am deploying with activiti-explorer-> manage->deployments->upload new

2. UTC+02:00

3. app. server is running on my PC

4. DB OS is: EET,

SELECT EXTRACT(TIMEZONE_HOUR FROM SYSTIMESTAMP)
FROM dual;

-----------------------------------------------------------------------------------------

2

Let me know if you need more info on that.

thank you!

gdharley · ‎25 Jan 2017

Perhaps I am missing something, but I am not able to duplicate the behavior.

Greg

vipi_voxa · ‎25 Jan 2017

Hi Greg,

I would assume that I hit some kind of rear issue. Or i miss configured something (which i am not sure what it could be)

I enabled debug level during deployment of absolutely new process Y. Hope this will give you more hints on what and why is going on.

Take a look at Line number 37. deployment for some reason is setting 2017-01-15 17:24:33.872(Timestamp).

(thanks god debug level is showing that information ). And it would be good to figure out where this is coming from.

(Can you please investigate it more, i will repeat, that i am getting this date in past also in ACT_HI_ACTINST.start_time_ and ACT_HI_ACTINST.end_time_ upon action completion. And this is pretty critical.)

[Server:common-server] 25 janv. 2017 05:06:24,307 [default task-33] DEBUG org.activiti.engine.impl.interceptor.LogInterceptor - 
[Server:common-server] 
[Server:common-server] 25 janv. 2017 05:06:24,307 [default task-33] DEBUG org.activiti.engine.impl.interceptor.LogInterceptor - --- starting DeployCmd --------------------------------------------------------
[Server:common-server] 25 janv. 2017 05:06:24,307 [default task-33] DEBUG org.activiti.spring.SpringTransactionInterceptor - Running command with propagation REQUIRED
[Server:common-server] 25 janv. 2017 05:06:24,308 [default task-33] DEBUG org.activiti.engine.impl.bpmn.deployer.BpmnDeployer - Processing deployment ProcessY.bpmn
[Server:common-server] 25 janv. 2017 05:06:24,308 [default task-33] INFO org.activiti.engine.impl.bpmn.deployer.BpmnDeployer - Processing resource ProcessY.bpmn
[Server:common-server] 25 janv. 2017 05:06:24,342 [default task-33] DEBUG org.activiti.engine.impl.bpmn.parser.handler.ProcessParseHandler - Parsing process pocessY
[Server:common-server] 25 janv. 2017 05:06:24,342 [default task-33] DEBUG org.activiti.engine.impl.bpmn.parser.handler.AbstractBpmnParseHandler - Parsing activity startevent1
[Server:common-server] 25 janv. 2017 05:06:24,342 [default task-33] DEBUG org.activiti.engine.impl.bpmn.parser.handler.AbstractBpmnParseHandler - Parsing activity endevent1
[Server:common-server] 25 janv. 2017 05:06:24,398 [default task-33] DEBUG org.apache.ibatis.transaction.managed.ManagedTransaction - Opening JDBC Connection
[Server:common-server] 25 janv. 2017 05:06:24,398 [default task-33] DEBUG org.activiti.engine.impl.persistence.entity.ProcessDefinitionEntity.selectLatestProcessDefinitionByKey - ==> Preparing: select * from ACT_RE_PROCDEF where KEY_ = ? and (TENANT_ID_ = '' or TENANT_ID_ is null) and VERSION_ = (select max(VERSION_) from ACT_RE_PROCDEF where KEY_ = ? and (TENANT_ID_ = '' or TENANT_ID_ is null)) 
[Server:common-server] 25 janv. 2017 05:06:24,399 [default task-33] DEBUG org.activiti.engine.impl.persistence.entity.ProcessDefinitionEntity.selectLatestProcessDefinitionByKey - ==> Parameters: pocessY(String), pocessY(String)
[Server:common-server] 25 janv. 2017 05:06:24,445 [default task-33] DEBUG org.activiti.engine.impl.persistence.entity.ProcessDefinitionEntity.selectLatestProcessDefinitionByKey - <== Total: 0
[Server:common-server] 25 janv. 2017 05:06:24,446 [default task-33] DEBUG org.activiti.engine.impl.persistence.entity.JobEntity.selectJobByTypeAndProcessDefinitionKeyNoTenantId - ==> Preparing: select J.* from ACT_RU_JOB J inner join ACT_RE_PROCDEF P on J.PROC_DEF_ID_ = P.ID_ where J.HANDLER_TYPE_ = ? and P.KEY_ = ? and (P.TENANT_ID_ = '' or P.TENANT_ID_ is null) 
[Server:common-server] 25 janv. 2017 05:06:24,446 [default task-33] DEBUG org.activiti.engine.impl.persistence.entity.JobEntity.selectJobByTypeAndProcessDefinitionKeyNoTenantId - ==> Parameters: timer-start-event(String), pocessY(String)
[Server:common-server] 25 janv. 2017 05:06:24,491 [default task-33] DEBUG org.activiti.engine.impl.persistence.entity.JobEntity.selectJobByTypeAndProcessDefinitionKeyNoTenantId - <== Total: 0
[Server:common-server] 25 janv. 2017 05:06:24,492 [default task-33] DEBUG org.activiti.engine.impl.interceptor.LogInterceptor - 
[Server:common-server] 
[Server:common-server] 25 janv. 2017 05:06:24,492 [default task-33] DEBUG org.activiti.engine.impl.interceptor.LogInterceptor - --- starting GetProcessDefinitionInfoCmd --------------------------------------------------------
[Server:common-server] 25 janv. 2017 05:06:24,492 [default task-33] DEBUG org.activiti.spring.SpringTransactionInterceptor - Running command with propagation REQUIRED
[Server:common-server] 25 janv. 2017 05:06:24,492 [default task-33] DEBUG org.activiti.engine.impl.interceptor.CommandContextInterceptor - Valid context found. Reusing it for the current command 'org.activiti.engine.impl.cmd.GetProcessDefinitionInfoCmd'
[Server:common-server] 25 janv. 2017 05:06:24,493 [default task-33] DEBUG org.activiti.engine.impl.interceptor.LogInterceptor - --- GetProcessDefinitionInfoCmd finished --------------------------------------------------------
[Server:common-server] 25 janv. 2017 05:06:24,493 [default task-33] DEBUG org.activiti.engine.impl.interceptor.LogInterceptor - 
[Server:common-server] 
[Server:common-server] 25 janv. 2017 05:06:24,493 [default task-33] DEBUG org.activiti.engine.impl.db.DbSqlSession - insert ProcessDefinitionEntity[pocessY:1:380792]
[Server:common-server] 25 janv. 2017 05:06:24,493 [default task-33] DEBUG org.activiti.engine.impl.db.DbSqlSession - insert ResourceEntity[id=380790, name=ProcessY.bpmn]
[Server:common-server] 25 janv. 2017 05:06:24,493 [default task-33] DEBUG org.activiti.engine.impl.db.DbSqlSession - insert ResourceEntity[id=380791, name=ProcessY.pocessY.png]
[Server:common-server] 25 janv. 2017 05:06:24,493 [default task-33] DEBUG org.activiti.engine.impl.db.DbSqlSession - insert DeploymentEntity[id=380789, name=ProcessY.bpmn]
[Server:common-server] 25 janv. 2017 05:06:24,493 [default task-33] DEBUG org.activiti.engine.impl.db.DbSqlSession - flush summary: 4 insert, 0 update, 0 delete.
[Server:common-server] 25 janv. 2017 05:06:24,493 [default task-33] DEBUG org.activiti.engine.impl.db.DbSqlSession - now executing flush...
[Server:common-server] 25 janv. 2017 05:06:24,493 [default task-33] DEBUG org.activiti.engine.impl.db.DbSqlSession - inserting: ProcessDefinitionEntity[pocessY:1:380792]
[Server:common-server] 25 janv. 2017 05:06:24,493 [default task-33] DEBUG org.activiti.engine.impl.persistence.entity.ProcessDefinitionEntity.insertProcessDefinition - ==> Preparing: insert into ACT_RE_PROCDEF(ID_, REV_, CATEGORY_, NAME_, KEY_, VERSION_, DEPLOYMENT_ID_, RESOURCE_NAME_, DGRM_RESOURCE_NAME_, DESCRIPTION_, HAS_START_FORM_KEY_, HAS_GRAPHICAL_NOTATION_ , SUSPENSION_STATE_, TENANT_ID_) values (?, 1, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) 
[Server:common-server] 25 janv. 2017 05:06:24,494 [default task-33] DEBUG org.activiti.engine.impl.persistence.entity.ProcessDefinitionEntity.insertProcessDefinition - ==> Parameters: pocessY:1:380792(String), http://www.activiti.org/testy(String), process y(String), pocessY(String), 1(Integer), 380789(String), ProcessY.bpmn(String), ProcessY.pocessY.png(String), null, false(Boolean), true(Boolean), 1(Integer), (String)
[Server:common-server] 25 janv. 2017 05:06:24,533 [default task-33] DEBUG org.activiti.engine.impl.persistence.entity.ProcessDefinitionEntity.insertProcessDefinition - <== Updates: 1
[Server:common-server] 25 janv. 2017 05:06:24,533 [default task-33] DEBUG org.activiti.engine.impl.db.DbSqlSession - inserting: DeploymentEntity[id=380789, name=ProcessY.bpmn]
[Server:common-server] 25 janv. 2017 05:06:24,533 [default task-33] DEBUG org.activiti.engine.impl.persistence.entity.DeploymentEntity.insertDeployment - ==> Preparing: insert into ACT_RE_DEPLOYMENT(ID_, NAME_, CATEGORY_, TENANT_ID_, DEPLOY_TIME_) values(?, ?, ?, ?, ?) 
[Server:common-server] 25 janv. 2017 05:06:24,533 [default task-33] DEBUG org.activiti.engine.impl.persistence.entity.DeploymentEntity.insertDeployment - ==> Parameters: 380789(String), ProcessY.bpmn(String), null, (String), 2017-01-15 17:24:33.872(Timestamp)
[Server:common-server] 25 janv. 2017 05:06:24,580 [default task-33] DEBUG org.activiti.engine.impl.persistence.entity.DeploymentEntity.insertDeployment - <== Updates: 1
[Server:common-server] 25 janv. 2017 05:06:24,580 [default task-33] DEBUG org.activiti.engine.impl.persistence.entity.ResourceEntity.bulkInsertResource_oracle - ==> Preparing: INSERT ALL INTO ACT_GE_BYTEARRAY(ID_, REV_, NAME_, BYTES_, DEPLOYMENT_ID_, GENERATED_) VALUES (?, 1, ?, ?, ?, ?) INTO ACT_GE_BYTEARRAY(ID_, REV_, NAME_, BYTES_, DEPLOYMENT_ID_, GENERATED_) VALUES (?, 1, ?, ?, ?, ?) SELECT * FROM dual 
[Server:common-server] 25 janv. 2017 05:06:24,581 [default task-33] DEBUG org.activiti.engine.impl.persistence.entity.ResourceEntity.bulkInsertResource_oracle - ==> Parameters: 380790(String), ProcessY.bpmn(String), java.io.ByteArrayInputStream@650c7182(ByteArrayInputStream), 380789(String), false(Boolean), 380791(String), ProcessY.pocessY.png(String), java.io.ByteArrayInputStream@2fdd7c1d(ByteArrayInputStream), 380789(String), true(Boolean)
[Server:common-server] 25 janv. 2017 05:06:24,630 [default task-33] DEBUG org.activiti.engine.impl.persistence.entity.ResourceEntity.bulkInsertResource_oracle - <== Updates: 2
[Server:common-server] 25 janv. 2017 05:06:24,630 [default task-33] DEBUG org.apache.ibatis.transaction.managed.ManagedTransaction - Closing JDBC Connection [Transaction-aware proxy for target Connection [jdbc:oracle:thin:@testdb:1555:devtest, UserName=TEST_USER, Oracle JDBC driver]]
[Server:common-server] 25 janv. 2017 05:06:24,717 [default task-33] DEBUG org.activiti.engine.impl.interceptor.LogInterceptor - --- DeployCmd finished --------------------------------------------------------
[Server:common-server] 25 janv. 2017 05:06:24,717 [default task-33] DEBUG org.activiti.engine.impl.interceptor.LogInterceptor - 
[Server:common-server] 
[Server:common-server] 25 janv. 2017 05:06:24,720 [default task-33] DEBUG org.activiti.engine.impl.interceptor.LogInterceptor - 
[Server:common-server] 
[Server:common-server] 25 janv. 2017 05:06:24,720 [default task-33] DEBUG org.activiti.engine.impl.interceptor.LogInterceptor - --- starting DeploymentQueryImpl --------------------------------------------------------
[Server:common-server] 25 janv. 2017 05:06:24,720 [default task-33] DEBUG org.activiti.spring.SpringTransactionInterceptor - Running command with propagation REQUIRED
[Server:common-server] 25 janv. 2017 05:06:24,720 [default task-33] DEBUG org.apache.ibatis.transaction.managed.ManagedTransaction - Opening JDBC Connection
[Server:common-server] 25 janv. 2017 05:06:24,721 [default task-33] DEBUG org.activiti.engine.impl.persistence.entity.DeploymentEntity.selectDeploymentCountByQueryCriteria - ==> Preparing: select count(distinct RES.ID_) from ACT_RE_DEPLOYMENT RES 
[Server:common-server] 25 janv. 2017 05:06:24,721 [default task-33] DEBUG org.activiti.engine.impl.persistence.entity.DeploymentEntity.selectDeploymentCountByQueryCriteria - ==> Parameters: 
[Server:common-server] 25 janv. 2017 05:06:24,759 [default task-33] DEBUG org.activiti.engine.impl.persistence.entity.DeploymentEntity.selectDeploymentCountByQueryCriteria - <== Total: 1
[Server:common-server] 25 janv. 2017 05:06:24,759 [default task-33] DEBUG org.activiti.engine.impl.db.DbSqlSession - flush summary: 0 insert, 0 update, 0 delete.
[Server:common-server] 25 janv. 2017 05:06:24,759 [default task-33] DEBUG org.activiti.engine.impl.db.DbSqlSession - now executing flush...
[Server:common-server] 25 janv. 2017 05:06:24,760 [default task-33] DEBUG org.apache.ibatis.transaction.managed.ManagedTransaction - Closing JDBC Connection [Transaction-aware proxy for target Connection [jdbc:oracle:thin:@testdb:1555:devtest, UserName=TEST_USER, Oracle JDBC driver]]
[Server:common-server] 25 janv. 2017 05:06:24,873 [default task-33] DEBUG org.activiti.engine.impl.interceptor.LogInterceptor - --- DeploymentQueryImpl finished --------------------------------------------------------
[Server:common-server] 25 janv. 2017 05:06:24,873 [default task-33] DEBUG org.activiti.engine.impl.interceptor.LogInterceptor - 
[Server:common-server] 
[Server:common-server] 25 janv. 2017 05:06:24,873 [default task-33] DEBUG org.activiti.engine.impl.interceptor.LogInterceptor - 
[Server:common-server] 
[Server:common-server] 25 janv. 2017 05:06:24,873 [default task-33] DEBUG org.activiti.engine.impl.interceptor.LogInterceptor - --- starting DeploymentQueryImpl --------------------------------------------------------
[Server:common-server] 25 janv. 2017 05:06:24,873 [default task-33] DEBUG org.activiti.spring.SpringTransactionInterceptor - Running command with propagation REQUIRED
[Server:common-server] 25 janv. 2017 05:06:24,873 [default task-33] DEBUG org.apache.ibatis.transaction.managed.ManagedTransaction - Opening JDBC Connection
[Server:common-server] 25 janv. 2017 05:06:24,874 [default task-33] DEBUG org.activiti.engine.impl.persistence.entity.DeploymentEntity.selectDeploymentsByQueryCriteria - ==> Preparing: select * from ( select a.*, ROWNUM rnum from ( select distinct RES.* from ACT_RE_DEPLOYMENT RES order by RES.NAME_ asc, RES.ID_ asc ) a where ROWNUM < ?) where rnum >= ? 
[Server:common-server] 25 janv. 2017 05:06:24,874 [default task-33] DEBUG org.activiti.engine.impl.persistence.entity.DeploymentEntity.selectDeploymentsByQueryCriteria - ==> Parameters: 31(Integer), 1(Integer)
[Server:common-server] 25 janv. 2017 05:06:24,913 [default task-33] DEBUG org.activiti.engine.impl.persistence.entity.DeploymentEntity.selectDeploymentsByQueryCriteria - <== Total: 4
[Server:common-server] 25 janv. 2017 05:06:24,913 [default task-33] DEBUG org.activiti.engine.impl.db.DbSqlSession - flush summary: 0 insert, 0 update, 0 delete.
[Server:common-server] 25 janv. 2017 05:06:24,913 [default task-33] DEBUG org.activiti.engine.impl.db.DbSqlSession - now executing flush...
[Server:common-server] 25 janv. 2017 05:06:24,913 [default task-33] DEBUG org.apache.ibatis.transaction.managed.ManagedTransaction - Closing JDBC Connection [Transaction-aware proxy for target Connection [jdbc:oracle:thin:@testdb:1555:devtest, UserName=TEST_USER, Oracle JDBC driver]]
[Server:common-server] 25 janv. 2017 05:06:24,995 [default task-33] DEBUG org.activiti.engine.impl.interceptor.LogInterceptor - --- DeploymentQueryImpl finished --------------------------------------------------------
[Server:common-server] 25 janv. 2017 05:06:24,996 [default task-33] DEBUG org.activiti.engine.impl.interceptor.LogInterceptor - 
[Server:common-server] 
[Server:common-server] 25 janv. 2017 05:06:24,996 [default task-33] DEBUG org.activiti.engine.impl.interceptor.LogInterceptor - 
‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

gdharley · ‎25 Jan 2017

The deployment timestamp is taken from the ProcessEngineConfiguration clock:

deployment.setDeploymentTime(commandContext.getProcessEngineConfiguration().getClock().getCurrentTime());

The default clock is initialized in the ProcessEngineConfigurationImpl.initClock() method which sets the default clock.

The default clock implementation is defined in DefaultClockImpl() class, but it does take timezone into account:

public Calendar getCurrentCalendar(TimeZone timeZone) {
return TimeZoneUtil.convertToTimeZone(getCurrentCalendar(), timeZone);
}

It would be interesting to see what the engine thinks is the current timezone.
You get get this from the ProcessEngineConfiguration.getClock().getCurrentTimeZone().
Create a simple process listener and printout what the engine believes the timezone to be may give us a clue.

vipi_voxa · ‎26 Jan 2017

Greg, Your assumption was quite right. Not sure if this is a time zone issue, Because minutes are different then system current time minutes.

so - the groovy script i run in a process:

import java.util.Date
import java.text.DateFormat
import java.text.SimpleDateFormat
System.out.println( 'getting timezone processEngineConfiguration...')
String lTm = processEngineConfiguration.getClock().getCurrentTimeZone().getDisplayName() 
DateFormat lDf = new SimpleDateFormat("MM/dd/yyyy HH:mm:ss")
java.util.Date lDate = processEngineConfiguration.getClock().getCurrentTime()
String lFormatedDate = lDf.format(lDate)
System.out.println( 'timeZone: ' + lTm)
System.out.println( 'lFormatedDate: ' + lFormatedDate)
System.out.println( 'getting timezone processEngineConfiguration done.')‍‍‍‍‍‍‍‍‍‍‍

and the output i get in a console:

[Server:common-server] 26 janv. 2017 06:03:48,320 [default task-4] INFO stdout - getting timezone processEngineConfiguration...
[Server:common-server] 
[Server:common-server] 26 janv. 2017 06:03:48,323 [default task-4] INFO stdout - timeZone: Eastern European Time
[Server:common-server] 
[Server:common-server] 26 janv. 2017 06:03:48,323 [default task-4] INFO stdout - lFormatedDate: 01/15/2017 17:24:43
[Server:common-server] 
[Server:common-server] 26 janv. 2017 06:03:48,324 [default task-4] INFO stdout - getting timezone processEngineConfiguration done.‍‍‍‍‍‍‍‍‍‍‍‍‍‍

and further down in the log i can see all this updates to database process execution is making with that wrong 01/15/2017 date :

[Server:common-server] 26 janv. 2017 06:03:48,366 [default task-4] DEBUG org.activiti.engine.impl.db.DbSqlSession - insert Sun Jan 15 17:24:43 EET 2017 : PROCESSINSTANCE_START
[Server:common-server] 26 janv. 2017 06:03:48,366 [default task-4] DEBUG org.activiti.engine.impl.db.DbSqlSession - insert Sun Jan 15 17:24:43 EET 2017 : ACTIVITY_STARTED
[Server:common-server] 26 janv. 2017 06:03:48,366 [default task-4] DEBUG org.activiti.engine.impl.db.DbSqlSession - insert Sun Jan 15 17:24:43 EET 2017 : ACTIVITY_COMPLETED
[Server:common-server] 26 janv. 2017 06:03:48,366 [default task-4] DEBUG org.activiti.engine.impl.db.DbSqlSession - insert Sun Jan 15 17:24:43 EET 2017 : SEQUENCEFLOW_TAKEN
[Server:common-server] 26 janv. 2017 06:03:48,366 [default task-4] DEBUG org.activiti.engine.impl.db.DbSqlSession - insert Sun Jan 15 17:24:43 EET 2017 : ACTIVITY_STARTED
[Server:common-server] 26 janv. 2017 06:03:48,366 [default task-4] DEBUG org.activiti.engine.impl.db.DbSqlSession - insert Sun Jan 15 17:24:43 EET 2017 : ACTIVITY_COMPLETED‍‍‍‍‍‍

Please guide me where this 01/15/2017 is coming from? what am i doing wrong?

Thank you!

Wrong dates. Activiti deployment date.

Wrong dates. Activiti deployment date.