Better Logging of " java.sql.BatchUpdateException: String or binary data would be truncated"

stefan_geiss · February 6, 2019, 11:02am

Hello community,

My company is working with giant pieces of data in camunda.

Most of the time this works just fine, but sometimes it happens, that a java.sql.BatchUpdateException occurrs with the message “String or binary data would be truncated”.

I know what this exception means and what I have to do in my code to fix this, but the only problem is the question “where?”.
The org.camunda.bpm.engine.impl.db.EnginePersistenceLogger flushes the summary of the database operations which contain not much useful information. (Maybe I’m reading them wrong?)

So what I would like to see is a brief information about the variable I tried to save into the ExecutionEntity that failed to be written into the database.

The flush below contains the following line:
INSERT VariableInstanceEntity[77bf459b-29f9-11e9-81eb-0a0027000004]
(I can’t find the ID in the square brackets anywhere)

Here’s an example of such a flush of database operations:

2019-02-06T11:25:04,420 ERROR [pool-4-thread-3] org.camunda.bpm.engine.context: ENGINE-16004 Exception while closing command context: ENGINE-03083 Exception while executing Batch Database Operations with message ’
Error flushing statements. Cause: org.apache.ibatis.executor.BatchExecutorException: org.camunda.bpm.engine.impl.persistence.entity.VariableInstanceEntity.insertVariableInstance (batch index #2) failed. 1 prior sub executor(s) completed successfully, but will be rolled back. Cause: java.sql.BatchUpdateException: Zeichenfolgen- oder Binärdaten würden abgeschnitten.
Cause: org.apache.ibatis.executor.BatchExecutorException: org.camunda.bpm.engine.impl.persistence.entity.VariableInstanceEntity.insertVariableInstance (batch index #2) failed. 1 prior sub executor(s) completed successfully, but will be rolled back. Cause: java.sql.BatchUpdateException: Zeichenfolgen- oder Binärdaten würden abgeschnitten.
java.sql.BatchUpdateException: Zeichenfolgen- oder Binärdaten würden abgeschnitten.
'. Flush summary:
[
INSERT ByteArrayEntity[77bf459a-29f9-11e9-81eb-0a0027000004]
INSERT VariableInstanceEntity[77bf459b-29f9-11e9-81eb-0a0027000004]
INSERT MessageEntity[77bf6cac-29f9-11e9-81eb-0a0027000004]
DELETE MessageEntity[77bd22b8-29f9-11e9-81eb-0a0027000004]
UPDATE ExecutionEntity[77b337a1-29f9-11e9-81eb-0a0027000004]
]

So my questions at the end:

Is there any way to improve the logging in this part?
Did I read the log wrong? (Is there useful information?)

Ingo_Richtsmeier · February 6, 2019, 11:44am

Hi @stefan_geiss,

try out this log levels:

  <logger name="org.camunda.bpm.engine.cmd" level="debug" />
  <logger name="org.camunda.bpm.engine.impl.persistence.entity" level="debug" />
  <logger name="org.camunda.bpm.engine.impl.history.event" level="debug" />
  <logger name="org.camunda.bpm.engine.impl.batch.history" level="debug" />
  <logger name="org.camunda.bpm.engine.impl.batch" level="debug" />

Hope this helps, Ingo

stefan_geiss · February 7, 2019, 1:12pm

Many thanks to you, @Ingo_Richtsmeier!

The logger for “org.camunda.bpm.engine.impl.persistence.entity” did the trick.

Using it shows the SQL queries that the engine tries to set of. Just take the nearest “insert into ACT_RU_VARIABLE” at the actual exception and you’re golden.

Example Log

2019-02-07T13:47:31,571 DEBUG [pool-4-thread-1] org.camunda.bpm.engine.impl.persistence.entity.VariableInstanceEntity.insertVariableInstance: ==> Preparing: insert into ACT_RU_VARIABLE ( ID_, TYPE_, NAME_, PROC_INST_ID_, EXECUTION_ID_, CASE_INST_ID_, CASE_EXECUTION_ID_, TASK_ID_, BYTEARRAY_ID_, DOUBLE_, LONG_, TEXT_, TEXT2_, VAR_SCOPE_, SEQUENCE_COUNTER_, IS_CONCURRENT_LOCAL_, TENANT_ID_, REV_ ) values ( ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, 1 )
2019-02-07T13:47:31,571 DEBUG [pool-4-thread-1] org.camunda.bpm.engine.impl.persistence.entity.VariableInstanceEntity.insertVariableInstance: ==> Parameters: 88a938b3-2ad6-11e9-9613-0a0027000004(String), string(String), shutdownVariable(String), 8803a9dc-2ad6-11e9-9613-0a0027000004(String), 8803a9dc-2ad6-11e9-9613-0a0027000004(String), null, null, null, null, null, null, ssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssss(String), null, 8803a9dc-2ad6-11e9-9613-0a0027000004(String), 1(Long), false(Boolean), null
2019-02-07T13:47:31,571 DEBUG [pool-4-thread-1] org.camunda.bpm.engine.impl.persistence.entity.JobEntity.insertMessage: ==> Preparing: insert into ACT_RU_JOB ( ID_, TYPE_, LOCK_OWNER_, LOCK_EXP_TIME_, EXCLUSIVE_, EXECUTION_ID_, PROCESS_INSTANCE_ID_, PROCESS_DEF_ID_, PROCESS_DEF_KEY_, RETRIES_, EXCEPTION_STACK_ID_, EXCEPTION_MSG_, DUEDATE_, HANDLER_TYPE_, HANDLER_CFG_, DEPLOYMENT_ID_, SUSPENSION_STATE_, JOB_DEF_ID_, PRIORITY_, SEQUENCE_COUNTER_, TENANT_ID_, CREATE_TIME_, REV_ ) values (?, ‘message’, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, 1 )
2019-02-07T13:47:31,573 DEBUG [pool-4-thread-1] org.camunda.bpm.engine.impl.persistence.entity.JobEntity.insertMessage: ==> Parameters: 88a9d4f4-2ad6-11e9-9613-0a0027000004(String), f3f9aea5-c7a4-4674-ad64-eb49e0b532e8(String), 2019-02-07 13:17:31.571(Timestamp), true(Boolean), 8803a9dc-2ad6-11e9-9613-0a0027000004(String), 8803a9dc-2ad6-11e9-9613-0a0027000004(String), shutdown:2:55634336-2ad5-11e9-a293-0a0027000004(String), shutdown(String), 3(Integer), null, null, null, async-continuation(String), transition-create-scope(String), 554b0044-2ad5-11e9-a293-0a0027000004(String), 1(Integer), 55634339-2ad5-11e9-a293-0a0027000004(String), 0(Long), 1(Long), null, 2019-02-07 12:47:31.571(Timestamp)
2019-02-07T13:47:31,573 DEBUG [pool-4-thread-1] org.camunda.bpm.engine.impl.persistence.entity.JobEntity.deleteMessage: ==> Preparing: delete from ACT_RU_JOB where ID_ = ? and REV_ = ?
2019-02-07T13:47:31,573 DEBUG [pool-4-thread-1] org.camunda.bpm.engine.impl.persistence.entity.JobEntity.deleteMessage: ==> Parameters: 88a3e181-2ad6-11e9-9613-0a0027000004(String), 1(Integer)
2019-02-07T13:47:31,573 DEBUG [pool-4-thread-1] org.camunda.bpm.engine.impl.persistence.entity.ExecutionEntity.updateExecution: ==> Preparing: update ACT_RU_EXECUTION set REV_ = ?, PROC_DEF_ID_ = ?, BUSINESS_KEY_ = ?, ACT_ID_ = ?, ACT_INST_ID_ = ?, IS_ACTIVE_ = ?, IS_CONCURRENT_ = ?, IS_SCOPE_ = ?, IS_EVENT_SCOPE_ = ?, PARENT_ID_ = ?, SUPER_EXEC_ = ?, SUSPENSION_STATE_ = ?, CACHED_ENT_STATE_ = ?, SEQUENCE_COUNTER_ = ?, TENANT_ID_ = ? where ID_ = ? and REV_ = ?
2019-02-07T13:47:31,573 DEBUG [pool-4-thread-1] org.camunda.bpm.engine.impl.persistence.entity.ExecutionEntity.updateExecution: ==> Parameters: 3(Integer), shutdown:2:55634336-2ad5-11e9-a293-0a0027000004(String), null, Task_12tr4uw(String), null, true(Boolean), false(Boolean), true(Boolean), false(Boolean), null, null, 1(Integer), 20(Integer), 6(Long), null, 8803a9dc-2ad6-11e9-9613-0a0027000004(String), 2(Integer)
2019-02-07T13:47:31,585 ERROR [pool-4-thread-1] org.camunda.bpm.engine.context: ENGINE-16004 Exception while closing command context: ENGINE-03083 Exception while executing Batch Database Operations with message ’
Error flushing statements. Cause: org.apache.ibatis.executor.BatchExecutorException: org.camunda.bpm.engine.impl.persistence.entity.VariableInstanceEntity.insertVariableInstance (batch index #1) failed. Cause: java.sql.BatchUpdateException: Zeichenfolgen- oder Binärdaten würden abgeschnitten.
Cause: org.apache.ibatis.executor.BatchExecutorException: org.camunda.bpm.engine.impl.persistence.entity.VariableInstanceEntity.insertVariableInstance (batch index #1) failed. Cause: java.sql.BatchUpdateException: Zeichenfolgen- oder Binärdaten würden abgeschnitten.
java.sql.BatchUpdateException: Zeichenfolgen- oder Binärdaten würden abgeschnitten.
'. Flush summary:
[
INSERT VariableInstanceEntity[88a938b3-2ad6-11e9-9613-0a0027000004]
INSERT MessageEntity[88a9d4f4-2ad6-11e9-9613-0a0027000004]
DELETE MessageEntity[88a3e181-2ad6-11e9-9613-0a0027000004]
UPDATE ExecutionEntity[8803a9dc-2ad6-11e9-9613-0a0027000004]
]

Olivier_Albertini · April 18, 2019, 9:31pm

Hi,

I have the same error. What did you do to fix this issue ?

stefan_geiss · April 25, 2019, 6:39am

Hello @Olivier_Albertini,

this issue occurrs, when you try to insert some value into ACT_RU_VARIABLE, that is too big to fit into the appropriate column.

For instance:
The TEXT_ column (which was the one that caused my problem) has the default size of 4000 characters.
So if you try to insert a string that is longer than 4000 characters this exception is thrown.

My solution:
I changed the size of the TEXT_ column to “nvarchar(max)”.

Olivier_Albertini · April 29, 2019, 5:56pm

Thanks for the reply!

system · January 30, 2024, 11:33am