One error is logged multiple times

Camunda 7 Topics Discussion & Questions
1

Hello,

I see that if an uncaught exception occurs in a process activity, it gets logged multiple times (three in my experience) by the camunda engine.

For example, I created a process delegate with just the following code as the body:

throw new RuntimeException("***** TEST ERROR");

In the log, I see the following entries (I cut the long stack traces):

2019-05-29 14:55:59,515 ERROR [camundaTaskExecutor-1] context: ENGINE-16004 Exception while closing command context: ***** TEST ERROR
java.lang.RuntimeException: ***** TEST ERROR

2019-05-29 14:55:59,518 WARN  [camundaTaskExecutor-1] jobexecutor: ENGINE-14006 Exception while executing job 1aec7622-8211-11e9-b54f-84bb9855545b: 
java.lang.RuntimeException: ***** TEST ERROR

2019-05-29 14:55:59,548 WARN  [camundaTaskExecutor-1] jobexecutor: ENGINE-14006 Exception while executing job 1aec7622-8211-11e9-b54f-84bb9855545b: 
java.lang.RuntimeException: ***** TEST ERROR

(The second and the third entries seem to be completely identical.)

Is it intentionally that one error is logged multiple times? I’d rather have it so that one error is logged only once, because otherwise it’s very confusing.

How do you handle this?

Thank you for any hints!

2

Hi @fml2,

it’s explained here: https://docs.camunda.org/manual/latest/user-guide/process-engine/the-job-executor/#failed-jobs.

Hope this helps, Ingo

3

Hello @Ingo_Richtsmeier,

do you mean that the three log entries come from the fact that the engine per default executes a job three times before giving up?

I assure this is not the case. The three log entries are issued during one job execution. When the job is executed the second and the third time, the three entries appear again (each time). The only difference (in my experiment) were different time stamps and thread names (“camundaTaskExecutor-2” and “camundaTaskExecutor-3”).

Sorry, I failed to mention that in my original post.

My impression (from the previous experience in some other java projects) is that an exception is caught somewhere in the code, gets logged and is then passed up the call stack. There it’s logged again and is again passed further.

4

Hi @fml2,

I’m pretty sure that these are the retries from the engine.

You can configure a different retry time cycle in the async before like R3/PT10S and inspect the log.

Have a look at the docs for further information here: https://docs.camunda.org/manual/latest/user-guide/process-engine/the-job-executor/#retry-time-cycle-configuration.

Hope this helps, Ingo

5

Hello,

I’ve run the process model with the setting “R1/PT1S” which guarantees that the job is executed only once.

I still see that there are multiple entries in the log. There are even four of them:

  1. 2019-06-06 11:04:39,708 ERROR [camundaTaskExecutor-1] context: ENGINE-16006 BPMN Stack Trace:

  2. 2019-06-06 11:04:39,714 ERROR [camundaTaskExecutor-1] context: ENGINE-16004 Exception while closing command context: ***** TEST (1); ProcessInstance[1cd80320-883a-11e9-8118-84bb9855545b]

  3. 2019-06-06 11:04:39,717 WARN [camundaTaskExecutor-1] jobexecutor: ENGINE-14006 Exception while executing job 1d5fa9b3-883a-11e9-8118-84bb9855545b:
    java.lang.RuntimeException: ***** TEST (1); ProcessInstance[1cd80320-883a-11e9-8118-84bb9855545b]

  4. 2019-06-06 11:04:39,825 WARN [camundaTaskExecutor-1] jobexecutor: ENGINE-14006 Exception while executing job 1d5fa9b3-883a-11e9-8118-84bb9855545b:
    java.lang.RuntimeException: ***** TEST (1); ProcessInstance[1cd80320-883a-11e9-8118-84bb9855545b]

Some of them have different log levels and error code, hence I conclude they are really multiple log entries.

The 3rd and the 4th entries seem to be completely identical.

6

Hi @fml2,

ah, now I got your point.

If you want, you can suppress the last two outputs with setting the level of the logging category org.camunda.bpm.engine.jobexecutor to ERROR.

The first two outputs are important to find the root cause of any execption.

The last outputs are logged here: https://github.com/camunda/camunda-bpm-platform/blob/master/engine/src/main/java/org/camunda/bpm/engine/impl/jobexecutor/ExecuteJobHelper.java#L35 and here: https://github.com/camunda/camunda-bpm-platform/blob/master/engine/src/main/java/org/camunda/bpm/engine/impl/jobexecutor/ExecuteJobsRunnable.java#L64.

Hope this helps, Ingo

7

Thank you Ingo!

I’ll set the log threshold for the job executor to ERROR, hope I won’t miss some important entries after that.

Just a couple of thoughts:

  1. IMO it’s not good that the job executor logs the same exception twice. Setting the threshold to ERROR eliminates the problem for the user, but it sill exists in the code.

  2. It would be even better if the context would produce just one log entry with all the information combined.

Thank you again for your quick help!

8