When I use ActivityInstanceQuery to query, i expect the target recored is A, but the actual result record is B, are there somebody know why?
one conditon is “end_time_ is null”, but the result record’s “end_time_” run by application in database is not null.
Here is the query condition with both code and sql, and the query results whit that:
Hey @qqxadyy,
Where are you executing this query? Are you doing it form within a Service Task?
Can you create an example test case showcasing this problem?
Cheers,
Filip
@filiphr
It sometime happend when I invoke a service method, so I execute the sql query directly in a SQL tool, and the result I had post on the top.
Recently I enable the debug log and I found that when the problem happen, the debug log is something different from the correct times, here is the debug log.
The correct log:
2021-08-24 10:50:16.432 DEBUG [PID=14344] --- [http-nio-20080-exec-5] (AbstractHandlerMapping.java:424) --- Mapped to public java.lang.String cn.com.trs.journal.controller.TestController.test(java.lang.String)
2021-08-24 10:50:16.432 DEBUG [PID=14344] --- [http-nio-20080-exec-5] (LoginInterceptor.java:91) --- get request source jwt:eyJhbGciOiJIUzUxMiJ9.eyJqdGkiOiIxNzIuMzEuMC41LTY1NzZBNjY1OEUwNjQyMjE4REJCMUY2MDc2MzU2RDBCIiwicm9sZSI6WzBdLCJyZ2EiOnRydWUsImdyb3VwIjoxLCJyZ3JvdXAiOjEsInR5cGUiOiJub3JtYWwiLCJpYXQiOjE2Mjc2MjA0NzYsInN1YiI6IjAiLCJleHAiOjE2Mjc2Mjc2NzZ9.2zfvFRqi8cu-in3WfcVQ2hlrjvvTu1ne5ShW_TvLwuCT-Bgik6AetSNWsljpJJRcB4ZvN5FGoG975mypa4LKyA
2021-08-24 10:50:16.433 DEBUG [PID=14344] --- [http-nio-20080-exec-5] (:) --- --- starting GetExecutionVariableCmd --------------------------------------------------------
2021-08-24 10:50:16.433 DEBUG [PID=14344] --- [http-nio-20080-exec-5] (:) --- Running command with propagation REQUIRED
2021-08-24 10:50:16.435 DEBUG [PID=14344] --- [http-nio-20080-exec-5] (:) --- Operation class org.flowable.engine.impl.interceptor.CommandInvoker$1 added to agenda
2021-08-24 10:50:16.435 DEBUG [PID=14344] --- [http-nio-20080-exec-5] (:) --- Executing operation class org.flowable.engine.impl.interceptor.CommandInvoker$1
2021-08-24 10:50:16.435 DEBUG [PID=14344] --- [http-nio-20080-exec-5] (:) --- ==> Preparing: select * from ACT_RU_EXECUTION where ID_ = ?
2021-08-24 10:50:16.435 DEBUG [PID=14344] --- [http-nio-20080-exec-5] (:) --- ==> Parameters: 4e57c7de-01a5-11ec-9e39-005056c00001(String)
2021-08-24 10:50:16.437 DEBUG [PID=14344] --- [http-nio-20080-exec-5] (:) --- <== Total: 1
2021-08-24 10:50:16.437 DEBUG [PID=14344] --- [http-nio-20080-exec-5] (:) --- ==> Preparing: select * from ACT_RU_VARIABLE WHERE EXECUTION_ID_ = ? AND TASK_ID_ is null AND NAME_ = ?
2021-08-24 10:50:16.437 DEBUG [PID=14344] --- [http-nio-20080-exec-5] (:) --- ==> Parameters: 4e57c7de-01a5-11ec-9e39-005056c00001(String), current_manuscript_status(String)
2021-08-24 10:50:16.440 DEBUG [PID=14344] --- [http-nio-20080-exec-5] (:) --- <== Total: 1
2021-08-24 10:50:16.440 DEBUG [PID=14344] --- [http-nio-20080-exec-5] (:) --- Flushing dbSqlSession
2021-08-24 10:50:16.440 DEBUG [PID=14344] --- [http-nio-20080-exec-5] (:) --- flush summary: 0 insert, 0 update, 0 delete.
2021-08-24 10:50:16.440 DEBUG [PID=14344] --- [http-nio-20080-exec-5] (:) --- now executing flush...
2021-08-24 10:50:16.441 DEBUG [PID=14344] --- [http-nio-20080-exec-5] (:) --- --- GetExecutionVariableCmd finished --------------------------------------------------------
And the wrong log
2021-08-24 10:55:17.014 DEBUG [PID=14344] --- [http-nio-20080-exec-9] (AbstractHandlerMapping.java:424) --- Mapped to public java.lang.String cn.com.trs.journal.controller.TestController.test(java.lang.String)
2021-08-24 10:55:17.014 DEBUG [PID=14344] --- [http-nio-20080-exec-9] (LoginInterceptor.java:91) --- get request source jwt:eyJhbGciOiJIUzUxMiJ9.eyJqdGkiOiIxNzIuMzEuMC41LTY1NzZBNjY1OEUwNjQyMjE4REJCMUY2MDc2MzU2RDBCIiwicm9sZSI6WzBdLCJyZ2EiOnRydWUsImdyb3VwIjoxLCJyZ3JvdXAiOjEsInR5cGUiOiJub3JtYWwiLCJpYXQiOjE2Mjc2MjA0NzYsInN1YiI6IjAiLCJleHAiOjE2Mjc2Mjc2NzZ9.2zfvFRqi8cu-in3WfcVQ2hlrjvvTu1ne5ShW_TvLwuCT-Bgik6AetSNWsljpJJRcB4ZvN5FGoG975mypa4LKyA
2021-08-24 10:55:17.016 DEBUG [PID=14344] --- [http-nio-20080-exec-9] (:) --- --- starting GetExecutionVariableCmd --------------------------------------------------------
2021-08-24 10:55:17.016 DEBUG [PID=14344] --- [http-nio-20080-exec-9] (:) --- Running command with propagation REQUIRED
2021-08-24 10:55:17.017 DEBUG [PID=14344] --- [http-nio-20080-exec-9] (:) --- Valid context found. Reusing it for the current command 'org.flowable.engine.impl.cmd.GetExecutionVariableCmd'
2021-08-24 10:55:17.017 DEBUG [PID=14344] --- [http-nio-20080-exec-9] (:) --- Operation class org.flowable.engine.impl.interceptor.CommandInvoker$1 added to agenda
2021-08-24 10:55:17.017 DEBUG [PID=14344] --- [http-nio-20080-exec-9] (:) --- Executing operation class org.flowable.engine.impl.interceptor.CommandInvoker$1
2021-08-24 10:55:17.019 DEBUG [PID=14344] --- [http-nio-20080-exec-9] (:) --- --- GetExecutionVariableCmd finished --------------------------------------------------------
Hey @filiphr
It sometimes happend when I invoke a service method, so I execute the SQL in the SQL tool directly, and I had post the results on the top.
When it happend , I reinvoke the method but it became correct, and it will happend after I invoke the mehtod few times.
Recently I enable the debug log and I found that when the problem happen, the debug log is something different from the correct log. Here is the logs:
The correct logs:
2021-08-24 10:50:16.432 DEBUG [PID=14344] --- [http-nio-20080-exec-5] (AbstractHandlerMapping.java:424) --- Mapped to public java.lang.String cn.com.trs.journal.controller.TestController.test(java.lang.String)
2021-08-24 10:50:16.432 DEBUG [PID=14344] --- [http-nio-20080-exec-5] (LoginInterceptor.java:91) --- get request source jwt:eyJhbGciOiJIUzUxMiJ9.eyJqdGkiOiIxNzIuMzEuMC41LTY1NzZBNjY1OEUwNjQyMjE4REJCMUY2MDc2MzU2RDBCIiwicm9sZSI6WzBdLCJyZ2EiOnRydWUsImdyb3VwIjoxLCJyZ3JvdXAiOjEsInR5cGUiOiJub3JtYWwiLCJpYXQiOjE2Mjc2MjA0NzYsInN1YiI6IjAiLCJleHAiOjE2Mjc2Mjc2NzZ9.2zfvFRqi8cu-in3WfcVQ2hlrjvvTu1ne5ShW_TvLwuCT-Bgik6AetSNWsljpJJRcB4ZvN5FGoG975mypa4LKyA
2021-08-24 10:50:16.433 DEBUG [PID=14344] --- [http-nio-20080-exec-5] (:) --- --- starting GetExecutionVariableCmd --------------------------------------------------------
2021-08-24 10:50:16.433 DEBUG [PID=14344] --- [http-nio-20080-exec-5] (:) --- Running command with propagation REQUIRED
2021-08-24 10:50:16.435 DEBUG [PID=14344] --- [http-nio-20080-exec-5] (:) --- Operation class org.flowable.engine.impl.interceptor.CommandInvoker$1 added to agenda
2021-08-24 10:50:16.435 DEBUG [PID=14344] --- [http-nio-20080-exec-5] (:) --- Executing operation class org.flowable.engine.impl.interceptor.CommandInvoker$1
2021-08-24 10:50:16.435 DEBUG [PID=14344] --- [http-nio-20080-exec-5] (:) --- ==> Preparing: select * from ACT_RU_EXECUTION where ID_ = ?
2021-08-24 10:50:16.435 DEBUG [PID=14344] --- [http-nio-20080-exec-5] (:) --- ==> Parameters: 4e57c7de-01a5-11ec-9e39-005056c00001(String)
2021-08-24 10:50:16.437 DEBUG [PID=14344] --- [http-nio-20080-exec-5] (:) --- <== Total: 1
2021-08-24 10:50:16.437 DEBUG [PID=14344] --- [http-nio-20080-exec-5] (:) --- ==> Preparing: select * from ACT_RU_VARIABLE WHERE EXECUTION_ID_ = ? AND TASK_ID_ is null AND NAME_ = ?
2021-08-24 10:50:16.437 DEBUG [PID=14344] --- [http-nio-20080-exec-5] (:) --- ==> Parameters: 4e57c7de-01a5-11ec-9e39-005056c00001(String), current_manuscript_status(String)
2021-08-24 10:50:16.440 DEBUG [PID=14344] --- [http-nio-20080-exec-5] (:) --- <== Total: 1
2021-08-24 10:50:16.440 DEBUG [PID=14344] --- [http-nio-20080-exec-5] (:) --- Flushing dbSqlSession
2021-08-24 10:50:16.440 DEBUG [PID=14344] --- [http-nio-20080-exec-5] (:) --- flush summary: 0 insert, 0 update, 0 delete.
2021-08-24 10:50:16.440 DEBUG [PID=14344] --- [http-nio-20080-exec-5] (:) --- now executing flush...
2021-08-24 10:50:16.441 DEBUG [PID=14344] --- [http-nio-20080-exec-5] (:) --- --- GetExecutionVariableCmd finished --------------------------------------------------------
And the wrong logs:
2021-08-24 10:55:17.014 DEBUG [PID=14344] --- [http-nio-20080-exec-9] (AbstractHandlerMapping.java:424) --- Mapped to public java.lang.String cn.com.trs.journal.controller.TestController.test(java.lang.String)
2021-08-24 10:55:17.014 DEBUG [PID=14344] --- [http-nio-20080-exec-9] (LoginInterceptor.java:91) --- get request source jwt:eyJhbGciOiJIUzUxMiJ9.eyJqdGkiOiIxNzIuMzEuMC41LTY1NzZBNjY1OEUwNjQyMjE4REJCMUY2MDc2MzU2RDBCIiwicm9sZSI6WzBdLCJyZ2EiOnRydWUsImdyb3VwIjoxLCJyZ3JvdXAiOjEsInR5cGUiOiJub3JtYWwiLCJpYXQiOjE2Mjc2MjA0NzYsInN1YiI6IjAiLCJleHAiOjE2Mjc2Mjc2NzZ9.2zfvFRqi8cu-in3WfcVQ2hlrjvvTu1ne5ShW_TvLwuCT-Bgik6AetSNWsljpJJRcB4ZvN5FGoG975mypa4LKyA
2021-08-24 10:55:17.016 DEBUG [PID=14344] --- [http-nio-20080-exec-9] (:) --- --- starting GetExecutionVariableCmd --------------------------------------------------------
2021-08-24 10:55:17.016 DEBUG [PID=14344] --- [http-nio-20080-exec-9] (:) --- Running command with propagation REQUIRED
2021-08-24 10:55:17.017 DEBUG [PID=14344] --- [http-nio-20080-exec-9] (:) --- Valid context found. Reusing it for the current command 'org.flowable.engine.impl.cmd.GetExecutionVariableCmd'
2021-08-24 10:55:17.017 DEBUG [PID=14344] --- [http-nio-20080-exec-9] (:) --- Operation class org.flowable.engine.impl.interceptor.CommandInvoker$1 added to agenda
2021-08-24 10:55:17.017 DEBUG [PID=14344] --- [http-nio-20080-exec-9] (:) --- Executing operation class org.flowable.engine.impl.interceptor.CommandInvoker$1
2021-08-24 10:55:17.019 DEBUG [PID=14344] --- [http-nio-20080-exec-9] (:) --- --- GetExecutionVariableCmd finished --------------------------------------------------------
It seems that the reused context cause this problem, but I don’t known why the reused context got the wrong data. Is it necessary? And why use it is this way?
The logs you are showing are super weird. If you are invoking the API from your own service then it should not make any difference.
The only explanation could be if you are invoking from it another Command or from within a Service Task.
This to me sounds like a concurrency problem. If something happens after a second invocation it means that another thread updated the data. Can you check that?
Cheers,
Filip
I just wrote a test method to invoke this
runtimeService.getVariable(executionId, variableName)
And I run it manually once by once, I think the concurrency is not the problem.
If something happens after a second invocation it means that another thread updated the data
To this, actually I had invoked other method to update the data, but it would not change when the problem happend during I query the variable.
Otherwise , I config that “flowable.async-executor-activate=true” , and the app will run some flowable’s query operation, will it cause the concurrency problem?