Cause: java.sql.SQLException: HOUR_OF_DAY

Flowable Engine
1

Hi experts,

After upgrade of flowable to 6.8.0, we are getting error when we execute the models. Could you please help .

Error logs:

- Exception Trace:
org.apache.ibatis.exceptions.PersistenceException:
### Error querying database. Cause: org.apache.ibatis.executor.result.ResultMapException: Error attempting to get column ‘START_TIME_’ from result set. Cause: java.sql.SQLException: HOUR_OF_DAY
### The error may exist in org/flowable/db/mapping/entity/Execution.xml
### The error may involve org.flowable.engine.impl.persistence.entity.ExecutionEntityImpl.selectExecution
### The error occurred while handling results
### SQL: select * from ACT_RU_EXECUTION where ID_ = ?

Cause: org.apache.ibatis.executor.result.ResultMapException: Error attempting to get column ‘START_TIME_’ from result set. Cause: java.sql.SQLException: HOUR_OF_DAY

    at org.apache.ibatis.exceptions.ExceptionFactory.wrapException(ExceptionFactory.java:30) ~[mybatis-3.5.10.jar:3.5.10]
    at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:153) ~[mybatis-3.5.10.jar:3.5.10]
    at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:145) ~[mybatis-3.5.10.jar:3.5.10]
    at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:140) ~[mybatis-3.5.10.jar:3.5.10]
    at org.apache.ibatis.session.defaults.DefaultSqlSession.selectOne(DefaultSqlSession.java:76) ~[mybatis-3.5.10.jar:3.5.10]
    at org.flowable.common.engine.impl.db.DbSqlSession.selectById(DbSqlSession.java:311) ~[flowable-engine-common-6.8.0.jar:6.8.0]
    at org.flowable.common.engine.impl.db.AbstractDataManager.findById(AbstractDataManager.java:76) ~[flowable-engine-common-6.8.0.jar:6.8.0]
    at org.flowable.engine.impl.persistence.entity.data.impl.MybatisExecutionDataManager.findById(MybatisExecutionDataManager.java:96) ~[flowable-engine-6.8.0.jar:6.8.0]
    at org.flowable.engine.impl.persistence.entity.data.impl.MybatisExecutionDataManager.findById(MybatisExecutionDataManager.java:50) ~[flowable-engine-6.8.0.jar:6.8.0]
    at org.flowable.common.engine.impl.persistence.entity.AbstractEntityManager.findById(AbstractEntityManager.java:42) ~[flowable-engine-common-6.8.0.jar:6.8.0]
    at org.flowable.engine.impl.persistence.entity.ExecutionEntityImpl.ensureSuperExecutionInitialized(ExecutionEntityImpl.java:565) ~[flowable-engine-6.8.0.jar:6.8.0]
    at org.flowable.engine.impl.persistence.entity.ExecutionEntityImpl.getSuperExecution(ExecutionEntityImpl.java:545) ~[flowable-engine-6.8.0.jar:6.8.0]
    at org.flowable.engine.impl.persistence.entity.ExecutionEntityImpl.getSuperExecution(ExecutionEntityImpl.java:65) ~[flowable-engine-6.8.0.jar:6.8.0]
    at org.flowable.engine.impl.agenda.EndExecutionOperation.handleProcessInstanceExecution(EndExecutionOperation.java:92) ~[flowable-engine-6.8.0.jar:6.8.0]
    at org.flowable.engine.impl.agenda.EndExecutionOperation.handleRegularExecution(EndExecutionOperation.java:300) ~[flowable-engine-6.8.0.jar:6.8.0]
    at org.flowable.engine.impl.agenda.EndExecutionOperation.run(EndExecutionOperation.java:82) ~[flowable-engine-6.8.0.jar:6.8.0]
    at org.flowable.common.engine.impl.AbstractEngineConfiguration.lambda$new$0(AbstractEngineConfiguration.java:195) ~[flowable-engine-common-6.8.0.jar:6.8.0]
    at org.flowable.engine.impl.interceptor.CommandInvoker.executeOperation(CommandInvoker.java:130) ~[flowable-engine-6.8.0.jar:6.8.0]
    at org.flowable.engine.impl.interceptor.CommandInvoker.executeOperations(CommandInvoker.java:114) ~[flowable-engine-6.8.0.jar:6.8.0]
    at org.flowable.engine.impl.interceptor.CommandInvoker.execute(CommandInvoker.java:72) ~[flowable-engine-6.8.0.jar:6.8.0]
    at org.flowable.engine.impl.interceptor.BpmnOverrideContextInterceptor.execute(BpmnOverrideContextInterceptor.java:26) ~[flowable-engine-6.8.0.jar:6.8.0]
    at org.flowable.common.engine.impl.interceptor.TransactionContextInterceptor.execute(TransactionContextInterceptor.java:53) ~[flowable-engine-common-6.8.0.jar:6.8.0]
    at org.flowable.common.engine.impl.interceptor.CommandContextInterceptor.execute(CommandContextInterceptor.java:105) ~[flowable-engine-common-6.8.0.jar:6.8.0]
    at org.flowable.common.spring.SpringTransactionInterceptor.lambda$execute$0(SpringTransactionInterceptor.java:57) ~[flowable-spring-common-6.8.0.jar:6.8.0]
    at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:140) ~[spring-tx-5.3.24.jar:5.3.24]
    at org.flowable.common.spring.SpringTransactionInterceptor.execute(SpringTransactionInterceptor.java:57) ~[flowable-spring-common-6.8.0.jar:6.8.0]
    at org.flowable.common.engine.impl.interceptor.LogInterceptor.execute(LogInterceptor.java:30) ~[flowable-engine-common-6.8.0.jar:6.8.0]
    at org.flowable.common.engine.impl.cfg.CommandExecutorImpl.execute(CommandExecutorImpl.java:56) ~[flowable-engine-common-6.8.0.jar:6.8.0]
    at org.flowable.common.engine.impl.cfg.CommandExecutorImpl.execute(CommandExecutorImpl.java:51) ~[flowable-engine-common-6.8.0.jar:6.8.0]
    at org.flowable.job.service.impl.asyncexecutor.ExecuteAsyncRunnable.executeJob(ExecuteAsyncRunnable.java:127) ~[flowable-job-service-6.8.0.jar:6.8.0]
    at org.flowable.job.service.impl.asyncexecutor.ExecuteAsyncRunnable.run(ExecuteAsyncRunnable.java:115) ~[flowable-job-service-6.8.0.jar:6.8.0]
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144) ~[na:na]
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642) ~[na:na]
    at java.base/java.lang.Thread.run(Thread.java:1589) ~[na:na]

Caused by: org.apache.ibatis.executor.result.ResultMapException: Error attempting to get column ‘START_TIME_’ from result set. Cause: java.sql.SQLException: HOUR_OF_DAY
at org.apache.ibatis.type.BaseTypeHandler.getResult(BaseTypeHandler.java:87) ~[mybatis-3.5.10.jar:3.5.10]
at org.apache.ibatis.executor.resultset.DefaultResultSetHandler.getPropertyMappingValue(DefaultResultSetHandler.java:518) ~[mybatis-3.5.10.jar:3.5.10]
at org.apache.ibatis.executor.resultset.DefaultResultSetHandler.applyPropertyMappings(DefaultResultSetHandler.java:487) ~[mybatis-3.5.10.jar:3.5.10]
at org.apache.ibatis.executor.resultset.DefaultResultSetHandler.getRowValue(DefaultResultSetHandler.java:411) ~[mybatis-3.5.10.jar:3.5.10]
at org.apache.ibatis.executor.resultset.DefaultResultSetHandler.handleRowValuesForSimpleResultMap(DefaultResultSetHandler.java:361) ~[mybatis-3.5.10.jar:3.5.10]
at org.apache.ibatis.executor.resultset.DefaultResultSetHandler.handleRowValues(DefaultResultSetHandler.java:335) ~[mybatis-3.5.10.jar:3.5.10]
at org.apache.ibatis.executor.resultset.DefaultResultSetHandler.handleResultSet(DefaultResultSetHandler.java:308) ~[mybatis-3.5.10.jar:3.5.10]
at org.apache.ibatis.executor.resultset.DefaultResultSetHandler.handleResultSets(DefaultResultSetHandler.java:201) ~[mybatis-3.5.10.jar:3.5.10]
at org.apache.ibatis.executor.statement.PreparedStatementHandler.query(PreparedStatementHandler.java:65) ~[mybatis-3.5.10.jar:3.5.10]
at org.apache.ibatis.executor.statement.RoutingStatementHandler.query(RoutingStatementHandler.java:79) ~[mybatis-3.5.10.jar:3.5.10]
at org.apache.ibatis.executor.SimpleExecutor.doQuery(SimpleExecutor.java:63) ~[mybatis-3.5.10.jar:3.5.10]
at org.apache.ibatis.executor.BaseExecutor.queryFromDatabase(BaseExecutor.java:325) ~[mybatis-3.5.10.jar:3.5.10]
at org.apache.ibatis.executor.BaseExecutor.query(BaseExecutor.java:156) ~[mybatis-3.5.10.jar:3.5.10]
at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:109) ~[mybatis-3.5.10.jar:3.5.10]
at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:89) ~[mybatis-3.5.10.jar:3.5.10]
at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:151) ~[mybatis-3.5.10.jar:3.5.10]
… 32 common frames omitted
Caused by: java.sql.SQLException: HOUR_OF_DAY
at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:129) ~[mysql-connector-j-8.0.32.jar:8.0.32]
at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:97) ~[mysql-connector-j-8.0.32.jar:8.0.32]
at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:89) ~[mysql-connector-j-8.0.32.jar:8.0.32]
at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:63) ~[mysql-connector-j-8.0.32.jar:8.0.32]
at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:73) ~[mysql-connector-j-8.0.32.jar:8.0.32]
at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:85) ~[mysql-connector-j-8.0.32.jar:8.0.32]
at com.mysql.cj.jdbc.result.ResultSetImpl.getTimestamp(ResultSetImpl.java:947) ~[mysql-connector-j-8.0.32.jar:8.0.32]
at com.mysql.cj.jdbc.result.ResultSetImpl.getTimestamp(ResultSetImpl.java:985) ~[mysql-connector-j-8.0.32.jar:8.0.32]
at com.zaxxer.hikari.pool.HikariProxyResultSet.getTimestamp(HikariProxyResultSet.java) ~[HikariCP-4.0.3.jar:na]
at org.apache.ibatis.type.DateTypeHandler.getNullableResult(DateTypeHandler.java:39) ~[mybatis-3.5.10.jar:3.5.10]
at org.apache.ibatis.type.DateTypeHandler.getNullableResult(DateTypeHandler.java:28) ~[mybatis-3.5.10.jar:3.5.10]
at org.apache.ibatis.type.BaseTypeHandler.getResult(BaseTypeHandler.java:85) ~[mybatis-3.5.10.jar:3.5.10]
… 47 common frames omitted
Caused by: com.mysql.cj.exceptions.WrongArgumentException: HOUR_OF_DAY
at java.base/jdk.internal.reflect.DirectConstructorHandleAccessor.newInstance(DirectConstructorHandleAccessor.java:67) ~[na:na]
at java.base/java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:500) ~[na:na]
at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:484) ~[na:na]
at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:61) ~[mysql-connector-j-8.0.32.jar:8.0.32]
at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:105) ~[mysql-connector-j-8.0.32.jar:8.0.32]
at com.mysql.cj.result.SqlTimestampValueFactory.localCreateFromDatetime(SqlTimestampValueFactory.java:195) ~[mysql-connector-j-8.0.32.jar:8.0.32]
at com.mysql.cj.result.SqlTimestampValueFactory.localCreateFromDatetime(SqlTimestampValueFactory.java:51) ~[mysql-connector-j-8.0.32.jar:8.0.32]
at com.mysql.cj.result.AbstractDateTimeValueFactory.createFromDatetime(AbstractDateTimeValueFactory.java:104) ~[mysql-connector-j-8.0.32.jar:8.0.32]
at com.mysql.cj.protocol.a.MysqlTextValueDecoder.decodeDatetime(MysqlTextValueDecoder.java:90) ~[mysql-connector-j-8.0.32.jar:8.0.32]
at com.mysql.cj.protocol.result.AbstractResultsetRow.decodeAndCreateReturnValue(AbstractResultsetRow.java:86) ~[mysql-connector-j-8.0.32.jar:8.0.32]
at com.mysql.cj.protocol.result.AbstractResultsetRow.getValueFromBytes(AbstractResultsetRow.java:243) ~[mysql-connector-j-8.0.32.jar:8.0.32]
at com.mysql.cj.protocol.a.result.ByteArrayRow.getValue(ByteArrayRow.java:91) ~[mysql-connector-j-8.0.32.jar:8.0.32]
… 53 common frames omitted
Caused by: java.lang.IllegalArgumentException: HOUR_OF_DAY
at java.base/java.util.GregorianCalendar.computeTime(GregorianCalendar.java:2609) ~[na:na]
at java.base/java.util.Calendar.updateTime(Calendar.java:3405) ~[na:na]
at java.base/java.util.Calendar.getTimeInMillis(Calendar.java:1806) ~[na:na]
at com.mysql.cj.result.SqlTimestampValueFactory.localCreateFromDatetime(SqlTimestampValueFactory.java:191) ~[mysql-connector-j-8.0.32.jar:8.0.32]
… 59 common frames omitted

2023-02-14 05:16:49.593 ERROR 16058 — [k-Executor-1110] ltAsyncRunnableExecutionExceptionHandler : Job 5f2f87ab-ac1e-11ed-9eca-42010aeec524 failed

  • Exact sql statement (from mysql.log):
    2023-02-15T09:09:32.710684Z 6040 Query select * from ACT_RU_EXECUTION where ID_ = ‘5b2374bd-ac1e-11ed-9eca-42010aeec524’
    2023-02-15T09:09:32.720860Z 6040 Query rollback
  • Corresponding Wrong Entry:

We tried to check the time

  • Timezone Settings Database:
    mysql> SELECT @@global.time_zone, @@session.time_zone;
    ±-------------------±--------------------+
    | @@global.time_zone | @@session.time_zone |
    ±-------------------±--------------------+
    | SYSTEM | SYSTEM |
    ±-------------------±--------------------+
    1 row in set (0.00 sec)
    - Operating system timezone:
    >timedatectl
    Local time: Tue 2023-02-14 14:01:20 CET
    Universal time: Tue 2023-02-14 13:01:20 UTC
    RTC time: Tue 2023-02-14 13:01:20
    Time zone: Europe/Berlin (CET, +0100)
    Network time on: no
    NTP synchronized: yes
    RTC in local TZ: no

  • Exact sql statement (from mysql.log):
    2023-02-15T09:09:32.710684Z 6040 Query select * from ACT_RU_EXECUTION where ID_ = ‘5b2374bd-ac1e-11ed-9eca-42010aeec524’
    2023-02-15T09:09:32.720860Z 6040 Query rollback

  • Corresponding Wrong Entry:
    mysql> select START_TIME_ from ACT_RU_EXECUTION where ID_ = ‘5b2374bd-ac1e-11ed-9eca-42010aeec524’;
    ±------------------------+
    | START_TIME_ |
    ±------------------------+
    | 5965-09-06 25:42:30.797 |
    ±------------------------+
    1 row in set (0.00 sec)

  • I looked if there are more such entries:
    mysql> select ID_, PROC_INST_ID_, START_TIME_ from ACT_RU_EXECUTION where START_TIME_ NOT LIKE ‘202%’;
    5 rows in set (0.00 sec):
    ±-------------------------------------±-----------------------------------------------------------------±------------------------+
    | ID_ | PROC_INST_ID_ | START_TIME_ |
    ±-------------------------------------±-----------------------------------------------------------------±------------------------+
    | 2093fc1e-ac7a-11ed-96b2-42010aeec524 | 2093adfa-ac7a-11ed-96b2-42010aeec5242093adfa-ac7a-11ed-96b2-4201 | 0082-02-00 00:00:01.024 |
    | 5b2374bd-ac1e-11ed-9eca-42010aeec524 | 1e53d4f0-ac1e-11ed-9eca-42010aeec5241e53d4f0-ac1e-11ed-9eca-4201 | 5965-09-06 25:42:30.797 |
    | c91cf66b-ac21-11ed-9eca-42010aeec524 | c91c0bdb-ac21-11ed-9eca-42010aeec524c91c0bdb-ac21-11ed-9eca-4201 | 3544-07-25 17:63:17.362 |
    | cf228225-ac5b-11ed-9eca-42010aeec524 | 9ea0e89a-ac5b-11ed-9eca-42010aeec5249ea0e89a-ac5b-11ed-9eca-4201 | 0082-05-31 31:63:63.777 |
    | de54f276-ac55-11ed-893b-42010aeec524 | de54a43d-ac55-11ed-893b-42010aeec524de54a43d-ac55-11ed-893b-4201 | 0082-05-28 31:31:63.776 |
    ±-------------------------------------±-----------------------------------------------------------------±------------------------+

  • I recognized that PROC_INST_ID values contains a value which is concatenation of process Instance Id with itself. Example:
    Process Instance Id : 2093adfa-ac7a-11ed-96b2-42010aeec524 → PROC_INST_ID_ = 2093adfa-ac7a-11ed-96b2-42010aeec5242093adfa-ac7a-11ed-96b2-4201

2

#Update

We could see the column ‘START_TIME_’ avaiilable in the table.

mysql> desc ACT_RU_EXECUTION;
±---------------------------±-------------±-----±----±--------±------+
| Field | Type | Null | Key | Default | Extra |
±---------------------------±-------------±-----±----±--------±------+
| ID_ | varchar(64) | NO | PRI | NULL | |
| REV_ | int | YES | | NULL | |
| PROC_INST_ID_ | varchar(64) | YES | MUL | NULL | |
| BUSINESS_KEY_ | varchar(255) | YES | MUL | NULL | |
| PARENT_ID_ | varchar(64) | YES | MUL | NULL | |
| PROC_DEF_ID_ | varchar(64) | YES | MUL | NULL | |
| SUPER_EXEC_ | varchar(64) | YES | MUL | NULL | |
| ROOT_PROC_INST_ID_ | varchar(64) | YES | MUL | NULL | |
| ACT_ID_ | varchar(255) | YES | | NULL | |
| IS_ACTIVE_ | tinyint | YES | | NULL | |
| IS_CONCURRENT_ | tinyint | YES | | NULL | |
| IS_SCOPE_ | tinyint | YES | | NULL | |
| IS_EVENT_SCOPE_ | tinyint | YES | | NULL | |
| IS_MI_ROOT_ | tinyint | YES | | NULL | |
| SUSPENSION_STATE_ | int | YES | | NULL | |
| CACHED_ENT_STATE_ | int | YES | | NULL | |
| TENANT_ID_ | varchar(255) | YES | | | |
| NAME_ | varchar(255) | YES | | NULL | |
| START_ACT_ID_ | varchar(255) | YES | | NULL | |
| START_TIME_ | datetime(3) | YES | | NULL | |
| START_USER_ID_ | varchar(255) | YES | | NULL | |
| LOCK_TIME_ | timestamp(3) | YES | | NULL | |
| IS_COUNT_ENABLED_ | tinyint | YES | | NULL | |
| EVT_SUBSCR_COUNT_ | int | YES | | NULL | |
| TASK_COUNT_ | int | YES | | NULL | |
| JOB_COUNT_ | int | YES | | NULL | |
| TIMER_JOB_COUNT_ | int | YES | | NULL | |
| SUSP_JOB_COUNT_ | int | YES | | NULL | |
| DEADLETTER_JOB_COUNT_ | int | YES | | NULL | |
| VAR_COUNT_ | int | YES | | NULL | |
| ID_LINK_COUNT_ | int | YES | | NULL | |
| CALLBACK_ID_ | varchar(255) | YES | | NULL | |
| CALLBACK_TYPE_ | varchar(255) | YES | | NULL | |
| REFERENCE_ID_ | varchar(255) | YES | MUL | NULL | |
| REFERENCE_TYPE_ | varchar(255) | YES | | NULL | |
| PROPAGATED_STAGE_INST_ID_ | varchar(255) | YES | | NULL | |
| LOCK_OWNER_ | varchar(255) | YES | | NULL | |
| EXTERNAL_WORKER_JOB_COUNT_ | int | YES | | NULL | |
| BUSINESS_STATUS_ | varchar(255) | YES | | NULL | |
±---------------------------±-------------±-----±----±--------±------+
39 rows in set (0.00 sec)

3

Hey @kongearun,

Seems like the reason for the problem is the value that is in START_TIME_ “5965-09-06 25:42:30.797”. Do you have an idea how that value could have been created? It doesn’t look like a valid entry.

Is it possible that someone has manually done some changes in the DB by accident?

Cheers,
Filip