Uploaded image for project: 'jBPM'
  1. jBPM
  2. JBPM-8747

Insert into ExecutionErrorInfo table fails when the message is longer than 255 characters, but the RESTServiceException (and its long message) was created by RESTWorkItemHandler.

    XMLWordPrintable

Details

    • Bug
    • Resolution: Duplicate
    • Major
    • None
    • 7.24.0.Final
    • KieServer
    • None
    • NEW
    • NEW
    • Hide

      This error will happen in many different use cases. Here is just one example:
      When RESTWorkItemHandler is configured to HandleResponseErrors and it tries to access a Rest Service with a wrong URL, it creates RESTServiceException with a message that is too long for the ERROR_MSG VARCHAR(255) column inside ExecutionErrorInfo table.
      Here an example logs for reference:
      2019-08-28 11:00:55.357 WARN 3016 — [0.0-8090-exec-1] o.drools.persistence.PersistableRunner : Could not commit session
      org.jbpm.workflow.instance.WorkflowRuntimeException: [StatusChangeBP:33,555 - Acme Status Change:2] – org.jbpm.bpmn2.handler.WorkItemHandlerRuntimeException: org.jbpm.process.workitem.rest.RESTServiceException: Unsuccessful response from REST server (status 404, endpoint http://localhost:8085/rest/workitems/statuschange, response {"timestamp":"2019-08-27T23:00:55.149+0000","status":404,"error":"Not Found","message":"No message available","path":"/rest/workitems/statuschange"}
      at org.jbpm.workflow.instance.node.WorkItemNodeInstance.processWorkItemHandler(WorkItemNodeInstance.java:174) ~[jbpm-flow-7.24.0-SNAPSHOT.jar:7.24.0-SNAPSHOT]
      ...
      Caused by: org.jbpm.bpmn2.handler.WorkItemHandlerRuntimeException: org.jbpm.bpmn2.handler.WorkItemHandlerRuntimeException: org.jbpm.process.workitem.rest.RESTServiceException: Unsuccessful response from REST server (status 404, endpoint http://localhost:8085/rest/workitems/statuschange, response {"timestamp":"2019-08-27T23:00:55.149+0000","status":404,"error":"Not Found","message":"No message available","path":"/rest/workitems/statuschange"}
      at org.jbpm.process.workitem.core.AbstractLogOrThrowWorkItemHandler.handleException(AbstractLogOrThrowWorkItemHandler.java:69)
      ...
      Caused by: org.jbpm.bpmn2.handler.WorkItemHandlerRuntimeException: org.jbpm.process.workitem.rest.RESTServiceException: Unsuccessful response from REST server (status 404, endpoint http://localhost:8085/rest/workitems/statuschange, response {"timestamp":"2019-08-27T23:00:55.149+0000","status":404,"error":"Not Found","message":"No message available","path":"/rest/workitems/statuschange"}
      at org.jbpm.process.workitem.core.AbstractLogOrThrowWorkItemHandler.handleException(AbstractLogOrThrowWorkItemHandler.java:69) ~[jbpm-workitems-core-7.24.0-SNAPSHOT.jar:7.24.0-SNAPSHOT]
      at org.jbpm.process.workitem.core.AbstractLogOrThrowWorkItemHandler.handleException(AbstractLogOrThrowWorkItemHandler.java:45) ~[jbpm-workitems-core-7.24.0-SNAPSHOT.jar:7.24.0-SNAPSHOT]
      at org.jbpm.process.workitem.rest.RESTWorkItemHandler.executeWorkItem(RESTWorkItemHandler.java:825) ~[jbpm-workitems-rest-7.24.0-SNAPSHOT.jar:7.24.0-SNAPSHOT]
      ... 143 common frames omitted
      Caused by: org.jbpm.process.workitem.rest.RESTServiceException: Unsuccessful response from REST server (status 404, endpoint http://localhost:8085/rest/workitems/statuschange, response {"timestamp":"2019-08-27T23:00:55.149+0000","status":404,"error":"Not Found","message":"No message available","path":"/rest/workitems/statuschange"}
      ... 144 common frames omitted

      2019-08-28 11:00:55.558 WARN 3016 — [0.0-8090-exec-1] o.h.engine.jdbc.spi.SqlExceptionHelper : SQL Error: 22001, SQLState: 22001
      2019-08-28 11:00:55.558 ERROR 3016 — [0.0-8090-exec-1] o.h.engine.jdbc.spi.SqlExceptionHelper : Value too long for column "ERROR_MSG VARCHAR(255)": "'[StatusChangeBP:33,555 - Acme Status Change:2] – org.jbpm.bpmn2.handler.WorkItemHandlerRuntimeException: org.jbpm.process.work... (428)"; SQL statement:
      insert into ExecutionErrorInfo (ERROR_ACK, ERROR_ACK_AT, ERROR_ACK_BY, ACTIVITY_ID, ACTIVITY_NAME, DEPLOYMENT_ID, ERROR_INFO, ERROR_DATE, ERROR_ID, ERROR_MSG, INIT_ACTIVITY_ID, JOB_ID, PROCESS_ID, PROCESS_INST_ID, ERROR_TYPE, id) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) [22001-197]
      2019-08-28 11:00:55.572 ERROR 3016 — [0.0-8090-exec-1] o.h.i.ExceptionMapperStandardImpl : HHH000346: Error during managed flush [org.hibernate.exception.DataException: could not execute statement]
      2019-08-28 11:00:55.584 WARN 3016 — [0.0-8090-exec-1] com.arjuna.ats.arjuna : ARJUNA012125: TwoPhaseCoordinator.beforeCompletion - failed for SynchronizationImple< 0:ffffac103219:e7bd:5d64d266:29c, org.hibernate.resource.transaction.backend.jta.internal.synchronization.RegisteredSynchronization@7c94c2f2 >
      javax.persistence.PersistenceException: org.hibernate.exception.DataException: could not execute statement
      at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:154) ~[hibernate-core-5.3.7.Final.jar:5.3.7.Final]
      ...
      Caused by: org.hibernate.exception.DataException: could not execute statement
      at org.hibernate.exception.internal.SQLStateConversionDelegate.convert(SQLStateConversionDelegate.java:118) ~[hibernate-core-5.3.7.Final.jar:5.3.7.Final]
      ...
      Caused by: org.h2.jdbc.JdbcSQLException: Value too long for column "ERROR_MSG VARCHAR(255)": "'[StatusChangeBP:33,555 - Acme Status Change:2] – org.jbpm.bpmn2.handler.WorkItemHandlerRuntimeException: org.jbpm.process.work... (428)"; SQL statement:
      insert into ExecutionErrorInfo (ERROR_ACK, ERROR_ACK_AT, ERROR_ACK_BY, ACTIVITY_ID, ACTIVITY_NAME, DEPLOYMENT_ID, ERROR_INFO, ERROR_DATE, ERROR_ID, ERROR_MSG, INIT_ACTIVITY_ID, JOB_ID, PROCESS_ID, PROCESS_INST_ID, ERROR_TYPE, id) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) [22001-197]
      at org.h2.message.DbException.getJdbcSQLException(DbException.java:357) ~[h2-1.4.197.jar:1.4.197]
      at org.h2.message.DbException.get(DbException.java:179) ~[h2-1.4.197.jar:1.4.197]
      at org.h2.table.Column.validateConvertUpdateSequence(Column.java:398) ~[h2-1.4.197.jar:1.4.197]
      at org.h2.table.Table.validateConvertUpdateSequence(Table.java:798) ~[h2-1.4.197.jar:1.4.197]
      at org.h2.command.dml.Insert.insertRows(Insert.java:177) ~[h2-1.4.197.jar:1.4.197]
      at org.h2.command.dml.Insert.update(Insert.java:134) ~[h2-1.4.197.jar:1.4.197]
      at org.h2.command.CommandContainer.update(CommandContainer.java:102) ~[h2-1.4.197.jar:1.4.197]
      at org.h2.command.Command.executeUpdate(Command.java:261) ~[h2-1.4.197.jar:1.4.197]
      at org.h2.jdbc.JdbcPreparedStatement.executeUpdateInternal(JdbcPreparedStatement.java:199) ~[h2-1.4.197.jar:1.4.197]
      at org.h2.jdbc.JdbcPreparedStatement.executeUpdate(JdbcPreparedStatement.java:153) ~[h2-1.4.197.jar:1.4.197]
      at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:175) ~[hibernate-core-5.3.7.Final.jar:5.3.7.Final]
      ... 133 common frames omitted

      2019-08-28 11:00:55.601 WARN 3016 — [0.0-8090-exec-1] o.k.s.p.KieSpringTransactionManager : Unable to commit transaction
      org.springframework.transaction.UnexpectedRollbackException: JTA transaction unexpectedly rolled back (maybe due to a timeout); nested exception is javax.transaction.RollbackException: ARJUNA016053: Could not commit transaction.
      at org.springframework.transaction.jta.JtaTransactionManager.doCommit(JtaTransactionManager.java:1037) ~[spring-tx-5.1.3.RELEASE.jar:5.1.3.RELEASE]
      at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:746) ~[spring-tx-5.1.3.RELEASE.jar:5.1.3.RELEASE]
      ...

      Show
      This error will happen in many different use cases. Here is just one example: When RESTWorkItemHandler is configured to HandleResponseErrors and it tries to access a Rest Service with a wrong URL, it creates RESTServiceException with a message that is too long for the ERROR_MSG VARCHAR(255) column inside ExecutionErrorInfo table. Here an example logs for reference: 2019-08-28 11:00:55.357 WARN 3016 — [0.0-8090-exec-1] o.drools.persistence.PersistableRunner : Could not commit session org.jbpm.workflow.instance.WorkflowRuntimeException: [StatusChangeBP:33,555 - Acme Status Change:2] – org.jbpm.bpmn2.handler.WorkItemHandlerRuntimeException: org.jbpm.process.workitem.rest.RESTServiceException: Unsuccessful response from REST server (status 404, endpoint http://localhost:8085/rest/workitems/statuschange , response {"timestamp":"2019-08-27T23:00:55.149+0000","status":404,"error":"Not Found","message":"No message available","path":"/rest/workitems/statuschange"} at org.jbpm.workflow.instance.node.WorkItemNodeInstance.processWorkItemHandler(WorkItemNodeInstance.java:174) ~ [jbpm-flow-7.24.0-SNAPSHOT.jar:7.24.0-SNAPSHOT] ... Caused by: org.jbpm.bpmn2.handler.WorkItemHandlerRuntimeException: org.jbpm.bpmn2.handler.WorkItemHandlerRuntimeException: org.jbpm.process.workitem.rest.RESTServiceException: Unsuccessful response from REST server (status 404, endpoint http://localhost:8085/rest/workitems/statuschange , response {"timestamp":"2019-08-27T23:00:55.149+0000","status":404,"error":"Not Found","message":"No message available","path":"/rest/workitems/statuschange"} at org.jbpm.process.workitem.core.AbstractLogOrThrowWorkItemHandler.handleException(AbstractLogOrThrowWorkItemHandler.java:69) ... Caused by: org.jbpm.bpmn2.handler.WorkItemHandlerRuntimeException: org.jbpm.process.workitem.rest.RESTServiceException: Unsuccessful response from REST server (status 404, endpoint http://localhost:8085/rest/workitems/statuschange , response {"timestamp":"2019-08-27T23:00:55.149+0000","status":404,"error":"Not Found","message":"No message available","path":"/rest/workitems/statuschange"} at org.jbpm.process.workitem.core.AbstractLogOrThrowWorkItemHandler.handleException(AbstractLogOrThrowWorkItemHandler.java:69) ~ [jbpm-workitems-core-7.24.0-SNAPSHOT.jar:7.24.0-SNAPSHOT] at org.jbpm.process.workitem.core.AbstractLogOrThrowWorkItemHandler.handleException(AbstractLogOrThrowWorkItemHandler.java:45) ~ [jbpm-workitems-core-7.24.0-SNAPSHOT.jar:7.24.0-SNAPSHOT] at org.jbpm.process.workitem.rest.RESTWorkItemHandler.executeWorkItem(RESTWorkItemHandler.java:825) ~ [jbpm-workitems-rest-7.24.0-SNAPSHOT.jar:7.24.0-SNAPSHOT] ... 143 common frames omitted Caused by: org.jbpm.process.workitem.rest.RESTServiceException: Unsuccessful response from REST server (status 404, endpoint http://localhost:8085/rest/workitems/statuschange , response {"timestamp":"2019-08-27T23:00:55.149+0000","status":404,"error":"Not Found","message":"No message available","path":"/rest/workitems/statuschange"} ... 144 common frames omitted 2019-08-28 11:00:55.558 WARN 3016 — [0.0-8090-exec-1] o.h.engine.jdbc.spi.SqlExceptionHelper : SQL Error: 22001, SQLState: 22001 2019-08-28 11:00:55.558 ERROR 3016 — [0.0-8090-exec-1] o.h.engine.jdbc.spi.SqlExceptionHelper : Value too long for column "ERROR_MSG VARCHAR(255)": "' [StatusChangeBP:33,555 - Acme Status Change:2] – org.jbpm.bpmn2.handler.WorkItemHandlerRuntimeException: org.jbpm.process.work... (428)"; SQL statement: insert into ExecutionErrorInfo (ERROR_ACK, ERROR_ACK_AT, ERROR_ACK_BY, ACTIVITY_ID, ACTIVITY_NAME, DEPLOYMENT_ID, ERROR_INFO, ERROR_DATE, ERROR_ID, ERROR_MSG, INIT_ACTIVITY_ID, JOB_ID, PROCESS_ID, PROCESS_INST_ID, ERROR_TYPE, id) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) [22001-197] 2019-08-28 11:00:55.572 ERROR 3016 — [0.0-8090-exec-1] o.h.i.ExceptionMapperStandardImpl : HHH000346: Error during managed flush [org.hibernate.exception.DataException: could not execute statement] 2019-08-28 11:00:55.584 WARN 3016 — [0.0-8090-exec-1] com.arjuna.ats.arjuna : ARJUNA012125: TwoPhaseCoordinator.beforeCompletion - failed for SynchronizationImple< 0:ffffac103219:e7bd:5d64d266:29c, org.hibernate.resource.transaction.backend.jta.internal.synchronization.RegisteredSynchronization@7c94c2f2 > javax.persistence.PersistenceException: org.hibernate.exception.DataException: could not execute statement at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:154) ~ [hibernate-core-5.3.7.Final.jar:5.3.7.Final] ... Caused by: org.hibernate.exception.DataException: could not execute statement at org.hibernate.exception.internal.SQLStateConversionDelegate.convert(SQLStateConversionDelegate.java:118) ~ [hibernate-core-5.3.7.Final.jar:5.3.7.Final] ... Caused by: org.h2.jdbc.JdbcSQLException: Value too long for column "ERROR_MSG VARCHAR(255)": "' [StatusChangeBP:33,555 - Acme Status Change:2] – org.jbpm.bpmn2.handler.WorkItemHandlerRuntimeException: org.jbpm.process.work... (428)"; SQL statement: insert into ExecutionErrorInfo (ERROR_ACK, ERROR_ACK_AT, ERROR_ACK_BY, ACTIVITY_ID, ACTIVITY_NAME, DEPLOYMENT_ID, ERROR_INFO, ERROR_DATE, ERROR_ID, ERROR_MSG, INIT_ACTIVITY_ID, JOB_ID, PROCESS_ID, PROCESS_INST_ID, ERROR_TYPE, id) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) [22001-197] at org.h2.message.DbException.getJdbcSQLException(DbException.java:357) ~ [h2-1.4.197.jar:1.4.197] at org.h2.message.DbException.get(DbException.java:179) ~ [h2-1.4.197.jar:1.4.197] at org.h2.table.Column.validateConvertUpdateSequence(Column.java:398) ~ [h2-1.4.197.jar:1.4.197] at org.h2.table.Table.validateConvertUpdateSequence(Table.java:798) ~ [h2-1.4.197.jar:1.4.197] at org.h2.command.dml.Insert.insertRows(Insert.java:177) ~ [h2-1.4.197.jar:1.4.197] at org.h2.command.dml.Insert.update(Insert.java:134) ~ [h2-1.4.197.jar:1.4.197] at org.h2.command.CommandContainer.update(CommandContainer.java:102) ~ [h2-1.4.197.jar:1.4.197] at org.h2.command.Command.executeUpdate(Command.java:261) ~ [h2-1.4.197.jar:1.4.197] at org.h2.jdbc.JdbcPreparedStatement.executeUpdateInternal(JdbcPreparedStatement.java:199) ~ [h2-1.4.197.jar:1.4.197] at org.h2.jdbc.JdbcPreparedStatement.executeUpdate(JdbcPreparedStatement.java:153) ~ [h2-1.4.197.jar:1.4.197] at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:175) ~ [hibernate-core-5.3.7.Final.jar:5.3.7.Final] ... 133 common frames omitted 2019-08-28 11:00:55.601 WARN 3016 — [0.0-8090-exec-1] o.k.s.p.KieSpringTransactionManager : Unable to commit transaction org.springframework.transaction.UnexpectedRollbackException: JTA transaction unexpectedly rolled back (maybe due to a timeout); nested exception is javax.transaction.RollbackException: ARJUNA016053: Could not commit transaction. at org.springframework.transaction.jta.JtaTransactionManager.doCommit(JtaTransactionManager.java:1037) ~ [spring-tx-5.1.3.RELEASE.jar:5.1.3.RELEASE] at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:746) ~ [spring-tx-5.1.3.RELEASE.jar:5.1.3.RELEASE] ...

    Description

      The message on the RESTServiceException thrown by RESTWorkItemHandler is useful but doesn't fit into ExecutionErrorInfo table. The error breaks the transaction.
      Here the end user doesn't have control on the lenght of the error message.
      Can you truncate long messages before trying to persist them?

      Attachments

        Activity

          People

            swiderski.maciej Maciej Swiderski (Inactive)
            jimwest362 Jim West (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: