Inform developer about incidents happening in a test case (possibly marking invalid expressions)

[berndruecker]

When I run a process test, I might encounter situations I have not foreseen, this is exactly the nature of writing tests :-)

I used zeebe-process-test 1.3.3 to test this process and actually used an invalid expression in the user task assignment. I can see this clearly in Operate if I run the process manually:

However, in my test case, I simply see, that I do not "arrive" in the user task, without any information about what just happened.

So in my case, I did some manual exploration to finally see the problem, which is now easy to fix. But this was an annoying detour.

I think we need to guide the user better than this. Spontaneous ideas:

• Log a warning every time an incident is created? I know that there might be situations where you want to test the incident, but I consider this rare - and the bigger problem is actually incidents going unnoticed, like in my example.
• Probably introduce some method to verify that there are no incidents. But I actually would assume that people do not know about it and forget to call it. Probably inMemoryEngine.waitForIdleState() should throw an exception if it ends with an incident?
• ?

[remcowesterhoud]

@berndruecker Thanks for creating this issue.

What currently happens is when a test fails the annotation will take care of printing the record stream which should make for easy debugging, eg:

===== Test failed! Printing records from the stream:
[main] INFO io.camunda.zeebe.test - Compact log representation:
--------
	['C'ommand/'E'event/'R'ejection] [valueType] [intent] - #[position]->#[source record position]  P[partitionId]K[key] - [summary of value]
	P9K999 - key; #999 - record position; "ID" element/process id; @"elementid"/[P9K999] - element with ID and key
	Keys are decomposed into partition id and per partition key (e.g. 2251799813685253 -> P1K005). If single partition, the partition is omitted.
	Long IDs are shortened (e.g. 'startEvent_5d56488e-0570-416c-ba2d-36d2a3acea78' -> 'star..acea78'
--------
C DEPLOYMENT         CREATE         - #01-> -1  -1 - 
E PROC               CREATED        - #02->#01 K01 - looping-servicetask.bpmn -> "looping..icetask" (version:1)
E DEPLOYMENT         CREATED        - #03->#01 K02 - looping-servicetask.bpmn
E DEPLOYMENT         FULLY_DISTR    - #04->#01 K02 - 
C PROC_INST_CREATION CREATE         - #05-> -1  -1 - new <process "looping..icetask"> (no vars)
C PROC_INST          ACTIVATE       - #06->#05 K03 - PROCESS "looping..icetask" in <process "looping..icetask"[K03]>
E PROC_INST_CREATION CREATED        - #07->#05 K04 - new <process "looping..icetask"> (no vars)
E PROC_INST          ACTIVATING     - #08->#06 K03 - PROCESS "looping..icetask" in <process "looping..icetask"[K03]>
E PROC_INST          ACTIVATED      - #09->#06 K03 - PROCESS "looping..icetask" in <process "looping..icetask"[K03]>
C PROC_INST          ACTIVATE       - #10->#06  -1 - START_EVENT "startevent" in <process "looping..icetask"[K03]>
E PROC_INST          ACTIVATING     - #11->#10 K05 - START_EVENT "startevent" in <process "looping..icetask"[K03]>
E PROC_INST          ACTIVATED      - #12->#10 K05 - START_EVENT "startevent" in <process "looping..icetask"[K03]>
C PROC_INST          COMPLETE       - #13->#10 K05 - START_EVENT "startevent" in <process "looping..icetask"[K03]>
E PROC_INST          COMPLETING     - #14->#13 K05 - START_EVENT "startevent" in <process "looping..icetask"[K03]>
E VAR                CREATED        - #15->#13 K06 - loopAmount->0 in <process [K03]>
E PROC_INST          COMPLETED      - #16->#13 K05 - START_EVENT "startevent" in <process "looping..icetask"[K03]>
E PROC_INST          SEQ_FLOW_TAKEN - #17->#13 K07 - SEQUENCE_FLOW "Flow_0gk7cr0" in <process "looping..icetask"[K03]>
C PROC_INST          ACTIVATE       - #18->#13 K08 - SERVICE_TASK "servicetask" in <process "looping..icetask"[K03]>
E PROC_INST          ACTIVATING     - #19->#18 K08 - SERVICE_TASK "servicetask" in <process "looping..icetask"[K03]>
E JOB                CREATED        - #20->#18 K09 - K09 "test" @"servicetask"[K08] 1 retries, in <process "looping..icetask"[K03]> (no vars)
E PROC_INST          ACTIVATED      - #21->#18 K08 - SERVICE_TASK "servicetask" in <process "looping..icetask"[K03]>
C JOB_BATCH          ACTIVATE       - #22-> -1  -1 - "test" max: 1
E JOB_BATCH          ACTIVATED      - #23->#22 K10 - "test" 1/1
                         K09 "test" @"servicetask"[K08] 1 retries, in <process "looping..icetask"[K03]> with variables: {loopAmount=0}
C JOB                THROW_ERROR    - #24-> -1 K09 - K09 -1 retries, error:error occurred in <process ?[?]> (no vars)
E JOB                ERROR_THROWN   - #25->#24 K09 - K09 "test" @"NO_CATC..T_FOUND"[K08] 1 retries, error:error occurred in <process "looping..icetask"[K03]> (no vars)
E INCIDENT           CREATED        - #26->#24 K11 - UNHANDLED_ERROR_EVENT Expected to throw an error event with the code 'error' with message 'error occurred', but it was not caught. No error events are available in the scope., joBKey: K09  @"NO_CATC..T_FOUND"[K08] in <process "looping..icetask"[K03]>

Do you think this is not enough information for users?

[berndruecker]

It is actually too much, the part you showed might be great - but also the BPMN XML and some other things are printed.

Also the current format is still a bit cryptic - but probably some good basis to iterate on.

I could imagine that there are different requirements if you test the core engine and if you use the engine to develop your process solution