Flaky test TimerStartEventTest.shouldTriggerOnlyTwice #10169

korthout · 2022-08-24T13:02:11Z

Summary

Try to answer the following as best as possible

How often does the test fail? it failed once here while attempting to merge Reject modify command when an element for activation is unknown #10153
Does it block your work? It blocked a merge and may block future ones
Do we suspect that it is a real failure? No, this seems like a timing issue. The test only has a window of a few seconds. When it's slow (e.g. on CI), it could be unstable.

Failures

Outline known failure cases, e.g. a failed assertion and its stacktrace obtained from Jenkins

Example assertion failure

Error:  Failures: 
Error:    TimerStartEventTest.shouldTriggerOnlyTwice:1107 
Expecting actual:
  [2251799813685249L, 2251799813685252L, 2251799813685249L, 2251799813685252L]
to contain exactly (and in same order):
  [2251799813685249L,
    2251799813685252L,
    2251799813685249L,
    2251799813685252L,
    2251799813685252L]
but could not find the following elements:
  [2251799813685252L]

Hypotheses

List any hypotheses if you have one; can be ommitted

The test is based on seconds. If the test takes longer than those few seconds it could break.

Logs

If possible, provide more context here, e.g. standard output logs, link to build, etc.

The following logs are from a local reproduction, as the CI didn't show the actual logs.

I was able to reproduce it locally by pinning the Engine clock's time at the start of test and then running the test repeatedly until failure.

engine.getClock().pinCurrentTime();
// ... rest of the test

Logs from local reproduction

--------
	[Timestamp] [Partition] ['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'
--------
14:32:02 C DPLY      CREATE            - #001->  -1   -1 - 
14:32:02 E PROC      CREATED           - #002->#001 K001 - process.xml -> "process_1" (version:1)
14:32:02 E TIME      CREATED           - #003->#001 K003 -  @"start_1"[  -1]  in  due T14:32:12.462 reps
14:32:02 E DPLY      CREATED           - #004->#001 K002 - process.xml
14:32:02 E DPLY      FULLY_DISTRIBUTED - #005->#001 K002 - 
14:32:02 C DPLY      CREATE            - #006->  -1   -1 - 
14:32:02 E PROC      CREATED           - #007->#006 K004 - process.xml -> "process_2" (version:1)
14:32:02 E TIME      CREATED           - #008->#006 K006 -  @"start_2"[  -1]  in  due T14:32:12.463 reps
14:32:02 E DPLY      CREATED           - #009->#006 K005 - process.xml
14:32:02 E DPLY      FULLY_DISTRIBUTED - #010->#006 K005 - 
14:32:17 C TIME      TRIGGER           - #011->  -1 K003 -  @"start_1"[  -1]  in  due T14:32:12.462 reps
14:32:17 C TIME      TRIGGER           - #012->  -1 K006 -  @"start_2"[  -1]  in  due T14:32:12.463 reps
14:32:17 E TIME      TRIGGERED         - #013->#011 K003 -  @"start_1"[  -1]  in  due T14:32:12.462 reps
14:32:17 E PROC_EVNT TRIGGERING        - #014->#011 K008 -  @"start_1"[K001] in  (no vars)
14:32:17 C PI        ACTIVATE          - #015->#011 K007 - PROCESS "process_1" in 
14:32:17 E TIME      CREATED           - #016->#011 K009 -  @"start_1"[  -1]  in  due T14:32:22.46
14:32:17 E TIME      TRIGGERED         - #017->#012 K006 -  @"start_2"[  -1]  in  due T14:32:12.463 reps
14:32:17 E PROC_EVNT TRIGGERING        - #018->#012 K011 -  @"start_2"[K004] in  (no vars)
14:32:17 C PI        ACTIVATE          - #019->#012 K010 - PROCESS "process_2" in 
14:32:17 E TIME      CREATED           - #020->#012 K012 -  @"start_2"[  -1]  in  due T14:32:22.462 reps
14:32:17 E PI        ACTIVATING        - #021->#015 K007 - PROCESS "process_1" in 
14:32:17 E PI        ACTIVATED         - #022->#015 K007 - PROCESS "process_1" in 
14:32:17 E PROC_EVNT TRIGGERED         - #023->#015 K008 -  @"start_1"[K001] in  (no vars)
14:32:17 E PI        ACTIVATING        - #024->#015 K013 - START_EVENT "start_1" in 
14:32:17 E PI        ACTIVATED         - #025->#015 K013 - START_EVENT "start_1" in 
14:32:17 C PI        COMPLETE          - #026->#015 K013 - START_EVENT "start_1" in 
14:32:22 E PI        ACTIVATING        - #027->#019 K010 - PROCESS "process_2" in 
14:32:22 E PI        ACTIVATED         - #028->#019 K010 - PROCESS "process_2" in 
14:32:22 E PROC_EVNT TRIGGERED         - #029->#019 K011 -  @"start_2"[K004] in  (no vars)
14:32:22 E PI        ACTIVATING        - #030->#019 K014 - START_EVENT "start_2" in 
14:32:22 E PI        ACTIVATED         - #031->#019 K014 - START_EVENT "start_2" in 
14:32:22 C PI        COMPLETE          - #032->#019 K014 - START_EVENT "start_2" in 
14:32:22 E PI        COMPLETING        - #033->#026 K013 - START_EVENT "start_1" in 
14:32:22 E PI        COMPLETED         - #034->#026 K013 - START_EVENT "start_1" in 
14:32:22 E PI        SEQ_FLOW_TAKEN    - #035->#026 K015 - SEQUENCE_FLOW "sequenc..030bc05" in 
14:32:22 C PI        ACTIVATE          - #036->#026 K016 - END_EVENT "end_1" in 
14:32:22 E PI        COMPLETING        - #037->#032 K014 - START_EVENT "start_2" in 
14:32:22 E PI        COMPLETED         - #038->#032 K014 - START_EVENT "start_2" in 
14:32:22 E PI        SEQ_FLOW_TAKEN    - #039->#032 K017 - SEQUENCE_FLOW "sequenc..c40f048" in 
14:32:22 C PI        ACTIVATE          - #040->#032 K018 - END_EVENT "end_2" in 
14:32:22 E PI        ACTIVATING        - #041->#036 K016 - END_EVENT "end_1" in 
14:32:22 E PI        ACTIVATED         - #042->#036 K016 - END_EVENT "end_1" in 
14:32:22 E PI        COMPLETING        - #043->#036 K016 - END_EVENT "end_1" in 
14:32:22 E PI        COMPLETED         - #044->#036 K016 - END_EVENT "end_1" in 
14:32:22 C PI        COMPLETE          - #045->#036 K007 - PROCESS "process_1" in 
14:32:22 C TIME      TRIGGER           - #046->  -1 K009 -  @"start_1"[  -1]  in  due T14:32:22.46
14:32:22 C TIME      TRIGGER           - #047->  -1 K012 -  @"start_2"[  -1]  in  due T14:32:22.462 reps
14:32:22 C TIME      TRIGGER           - #048->  -1 K009 -  @"start_1"[  -1]  in  due T14:32:22.46
14:32:22 C TIME      TRIGGER           - #049->  -1 K012 -  @"start_2"[  -1]  in  due T14:32:22.462 reps
14:32:22 E PI        ACTIVATING        - #050->#040 K018 - END_EVENT "end_2" in 
14:32:22 E PI        ACTIVATED         - #051->#040 K018 - END_EVENT "end_2" in 
14:32:22 E PI        COMPLETING        - #052->#040 K018 - END_EVENT "end_2" in 
14:32:22 E PI        COMPLETED         - #053->#040 K018 - END_EVENT "end_2" in 
14:32:22 C PI        COMPLETE          - #054->#040 K010 - PROCESS "process_2" in 
14:32:22 C TIME      TRIGGER           - #055->  -1 K009 -  @"start_1"[  -1]  in  due T14:32:22.46
14:32:22 C TIME      TRIGGER           - #056->  -1 K012 -  @"start_2"[  -1]  in  due T14:32:22.462 reps
14:32:22 E PI        COMPLETING        - #057->#045 K007 - PROCESS "process_1" in 
14:32:22 E PI        COMPLETED         - #058->#045 K007 - PROCESS "process_1" in 
14:32:22 E TIME      TRIGGERED         - #059->#046 K009 -  @"start_1"[  -1]  in  due T14:32:22.46
14:32:22 E PROC_EVNT TRIGGERING        - #060->#046 K020 -  @"start_1"[K001] in  (no vars)
14:32:22 C PI        ACTIVATE          - #061->#046 K019 - PROCESS "process_1" in 
14:32:22 E TIME      TRIGGERED         - #062->#047 K012 -  @"start_2"[  -1]  in  due T14:32:22.462 reps
14:32:22 E PROC_EVNT TRIGGERING        - #063->#047 K022 -  @"start_2"[K004] in  (no vars)
14:32:22 C PI        ACTIVATE          - #064->#047 K021 - PROCESS "process_2" in 
14:32:22 E TIME      CREATED           - #065->#047 K023 -  @"start_2"[  -1]  in  due T14:32:32.46
14:32:32 R TIME      TRIGGER           - #066->#048 K009 -  @"start_1"[  -1]  in  due T14:32:22.46 !NOT_FOUND (Expected to trigger timer with key '2251799813685257', but no such timer was found)
14:32:32 R TIME      TRIGGER           - #067->#049 K012 -  @"start_2"[  -1]  in  due T14:32:22.462 reps !NOT_FOUND (Expected to trigger timer with key '2251799813685260', but no such timer was found)
14:32:32 E PI        COMPLETING        - #068->#054 K010 - PROCESS "process_2" in 
14:32:32 E PI        COMPLETED         - #069->#054 K010 - PROCESS "process_2" in 
14:32:32 R TIME      TRIGGER           - #070->#055 K009 -  @"start_1"[  -1]  in  due T14:32:22.46 !NOT_FOUND (Expected to trigger timer with key '2251799813685257', but no such timer was found)
14:32:32 R TIME      TRIGGER           - #071->#056 K012 -  @"start_2"[  -1]  in  due T14:32:22.462 reps !NOT_FOUND (Expected to trigger timer with key '2251799813685260', but no such timer was found)
14:32:32 E PI        ACTIVATING        - #072->#061 K019 - PROCESS "process_1" in 
14:32:32 E PI        ACTIVATED         - #073->#061 K019 - PROCESS "process_1" in 
14:32:32 E PROC_EVNT TRIGGERED         - #074->#061 K020 -  @"start_1"[K001] in  (no vars)
14:32:32 E PI        ACTIVATING        - #075->#061 K024 - START_EVENT "start_1" in 
14:32:32 E PI        ACTIVATED         - #076->#061 K024 - START_EVENT "start_1" in 
14:32:32 C PI        COMPLETE          - #077->#061 K024 - START_EVENT "start_1" in 
14:32:32 E PI        ACTIVATING        - #078->#064 K021 - PROCESS "process_2" in 
14:32:32 E PI        ACTIVATED         - #079->#064 K021 - PROCESS "process_2" in 
14:32:32 E PROC_EVNT TRIGGERED         - #080->#064 K022 -  @"start_2"[K004] in  (no vars)
14:32:32 E PI        ACTIVATING        - #081->#064 K025 - START_EVENT "start_2" in 
14:32:32 E PI        ACTIVATED         - #082->#064 K025 - START_EVENT "start_2" in 
14:32:32 C PI        COMPLETE          - #083->#064 K025 - START_EVENT "start_2" in 
14:32:32 E PI        COMPLETING        - #084->#077 K024 - START_EVENT "start_1" in 
14:32:32 E PI        COMPLETED         - #085->#077 K024 - START_EVENT "start_1" in 
14:32:32 E PI        SEQ_FLOW_TAKEN    - #086->#077 K026 - SEQUENCE_FLOW "sequenc..030bc05" in 
14:32:32 C PI        ACTIVATE          - #087->#077 K027 - END_EVENT "end_1" in 
14:32:32 E PI        COMPLETING        - #088->#083 K025 - START_EVENT "start_2" in 
14:32:32 E PI        COMPLETED         - #089->#083 K025 - START_EVENT "start_2" in 
14:32:32 E PI        SEQ_FLOW_TAKEN    - #090->#083 K028 - SEQUENCE_FLOW "sequenc..c40f048" in 
14:32:32 C PI        ACTIVATE          - #091->#083 K029 - END_EVENT "end_2" in 
14:32:32 E PI        ACTIVATING        - #092->#087 K027 - END_EVENT "end_1" in 
14:32:32 E PI        ACTIVATED         - #093->#087 K027 - END_EVENT "end_1" in 
14:32:32 E PI        COMPLETING        - #094->#087 K027 - END_EVENT "end_1" in 
14:32:32 E PI        COMPLETED         - #095->#087 K027 - END_EVENT "end_1" in 
14:32:32 C PI        COMPLETE          - #096->#087 K019 - PROCESS "process_1" in 
14:32:32 E PI        ACTIVATING        - #097->#091 K029 - END_EVENT "end_2" in 
14:32:32 E PI        ACTIVATED         - #098->#091 K029 - END_EVENT "end_2" in 
14:32:32 E PI        COMPLETING        - #099->#091 K029 - END_EVENT "end_2" in 
14:32:32 E PI        COMPLETED         - #100->#091 K029 - END_EVENT "end_2" in 
14:32:32 C PI        COMPLETE          - #101->#091 K021 - PROCESS "process_2" in 
14:32:32 E PI        COMPLETING        - #102->#096 K019 - PROCESS "process_1" in 
14:32:32 E PI        COMPLETED         - #103->#096 K019 - PROCESS "process_1" in 
14:32:32 E PI        COMPLETING        - #104->#101 K021 - PROCESS "process_2" in 
14:32:32 E PI        COMPLETED         - #105->#101 K021 - PROCESS "process_2" in 
-------------- Deployed Processes ----------------------

process.xml -> "process_1" (version:1)[K001] ------


  
    
      sequenceFlow_770fab2d-9719-44ae-b876-c237c030bc05
      
        R2/2022-08-24T14:32:12.460+02:00[Europe/Berlin]/PT10S
      
    
    
      sequenceFlow_770fab2d-9719-44ae-b876-c237c030bc05
    
    
  
  
    
      
        
      
      
        
      
      
        
        
      
    
  

process.xml -> "process_2" (version:1)[K004] ------


  
    
      sequenceFlow_bb8b06e2-2aea-4b24-a6fe-9eeddc40f048
      
        R3/2022-08-24T14:32:12.460+02:00[Europe/Berlin]/PT10S
      
    
    
      sequenceFlow_bb8b06e2-2aea-4b24-a6fe-9eeddc40f048
    
    
  
  
    
      
        
      
      
        
      
      
        
        
      
    
  

--------------- Decomposed keys (for debugging) -----------------

-1 <-> -1

K001 <-> 2251799813685249

K002 <-> 2251799813685250

K003 <-> 2251799813685251

K004 <-> 2251799813685252

K005 <-> 2251799813685253

K006 <-> 2251799813685254

K007 <-> 2251799813685255

K008 <-> 2251799813685256

K009 <-> 2251799813685257

K010 <-> 2251799813685258

K011 <-> 2251799813685259

K012 <-> 2251799813685260

K013 <-> 2251799813685261

K014 <-> 2251799813685262

K015 <-> 2251799813685263

K016 <-> 2251799813685264

K017 <-> 2251799813685265

K018 <-> 2251799813685266

K019 <-> 2251799813685267

K020 <-> 2251799813685268

K021 <-> 2251799813685269

K022 <-> 2251799813685270

K023 <-> 2251799813685271

K024 <-> 2251799813685272

K025 <-> 2251799813685273

K026 <-> 2251799813685274

K027 <-> 2251799813685275

K028 <-> 2251799813685276

K029 <-> 2251799813685277
14:32:07.690 [] DEBUG io.camunda.zeebe.broker.logstreams - Close stream processor

...
java.lang.AssertionError:

Expecting actual:

[2251799813685249L, 2251799813685252L, 2251799813685249L, 2251799813685252L]

to contain exactly (and in same order):

[2251799813685249L,

2251799813685252L,

2251799813685249L,

2251799813685252L,

2251799813685252L]

but could not find the following elements:

[2251799813685252L]

korthout · 2022-08-24T13:02:53Z

Looking at these logs, we see that the 5th timer is CREATED. So the system works correctly, I don't expect a real bug.

However, no TRIGGER command is written for it yet which is why the test fails. Perhaps the DueDateTimerChecker is causing issues here 🤔

Zelldon · 2022-08-24T13:10:28Z

Could be related to our recent scheduling changes 🤔

10170: Print record timestamp in compact record logger r=korthout a=korthout ## Description  When troubleshooting issues (or writing tests) for Timer related topics, we're often interested in both the Timer record's Duedate, as well as the actual time that the record was written, i.e. the record's Timestamp. This PR adds the Timestamp to the compact record logger when there are Timer records on the recorded log. While working on this, I also noticed that the compact record logger's Legend could be improved to only include Partition related info when the partition is actually printed as well (i.e. when there are multiple partitions). This is another PR in a series of QoL improvements I've recently made to the compact record logger. - #10156 - #10144 - #9885 ### Before ``` -------- [Partition] ['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 DPLY CREATE - #1->-1 -1 - E PROC CREATED - #2->#1 K1 - process.xml -> "process" (version:1) E TIME CREATED - #3->#1 K3 - `@"start_1"[-1]` in <process "K1"[?]> due T15:10:34.329 E DPLY CREATED - #4->#1 K2 - process.xml E DPLY FULLY_DISTRIBUTED - #5->#1 K2 - ``` ### After With Timer records: ``` -------- [Timestamp] ['C'ommand/'E'event/'R'ejection] [valueType] [intent] - #[position]->#[source record position] 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' -------- 15:28:01 C DPLY CREATE - #1->-1 -1 - 15:28:02 E PROC CREATED - #2->#1 K1 - process.xml -> "process" (version:1) 15:28:02 E TIME CREATED - #3->#1 K3 - `@"start_1"[-1]` in <process "K1"[?]> due T15:28:03.087 15:28:02 E DPLY CREATED - #4->#1 K2 - process.xml 15:28:02 E DPLY FULLY_DISTRIBUTED - #5->#1 K2 - ``` Without Timer records: ``` -------- ['C'ommand/'E'event/'R'ejection] [valueType] [intent] - #[position]->#[source record position] 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 DPLY CREATE - #1-> -1 -1 - E PROC CREATED - #2->#1 K01 - process.xml -> "process" (version:1) E DPLY CREATED - #3->#1 K02 - process.xml E DPLY FULLY_DISTRIBUTED - #4->#1 K02 - ``` When there are multiple partitions: ``` -------- [Partition] ['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' -------- 1 C DPLY CREATE - #1->-1 -1 - 1 E PROC CREATED - #2->#1 P1K1 - process.bpmn -> "shouldR..ecovery" (version:1) 1 E DPLY CREATED - #3->#1 P1K2 - process.bpmn 1 E DSTR DISTRIBUTING - #4->#1 P1K2 - on partition 2 1 E DSTR DISTRIBUTING - #5->#1 P1K2 - on partition 3 1 C DSTR COMPLETE - #6->-1 P1K2 - on partition 2 1 C DSTR COMPLETE - #7->-1 P1K2 - on partition 3 1 E DSTR COMPLETED - #8->#6 P1K2 - on partition 2 1 E DSTR COMPLETED - #9->#7 P1K2 - on partition 3 1 E DPLY FULLY_DISTRIBUTED - #10->#7 P1K2 - 2 C DPLY DISTRIBUTE - #1->-1 P1K2 - process.bpmn 2 E DPLY DISTRIBUTED - #2->#1 P1K2 - process.bpmn 3 C DPLY DISTRIBUTE - #1->-1 P1K2 - process.bpmn 3 E DPLY DISTRIBUTED - #2->#1 P1K2 - process.bpmn ``` ## Related issues  relates to #10169 Co-authored-by: Nico Korthout <nico.korthout@camunda.com>

10176: [Backport stable/8.0] Print record timestamp in compact record logger r=korthout a=backport-action # Description Backport of #10170 to `stable/8.0`. relates to #10156 #10144 #9885 #10169 Co-authored-by: Nico Korthout <nico.korthout@camunda.com>

10175: [Backport stable/1.3] Print record timestamp in compact record logger r=korthout a=backport-action # Description Backport of #10170 to `stable/1.3`. relates to #10156 #10144 #9885 #10169 Co-authored-by: Nico Korthout <nico.korthout@camunda.com>

Zelldon · 2022-08-25T07:07:34Z

It failed on main again as well two times, looks like easily reproducible

https://camunda.slack.com/archives/C013MEVQ4M9/p1661353038445929
https://camunda.slack.com/archives/C013MEVQ4M9/p1661353841886639

Would you mind to take a look @korthout ?

korthout · 2022-08-25T07:18:18Z

Thanks for highlighting @Zelldon

I can take a look into it after my current topic is completed :)

Could you maybe point me to the specific scheduler changes that might affect this? Was there really a scheduler change or do you mean that the engine switches to a different way to schedule a repeating task?

Zelldon · 2022-08-25T07:26:58Z

It was a change in the abstraction, that scheduled Tasks are only executed during Processing Phase and only if not in between ongoing processing, to avoid execution of tasks which might been scheduled during processing which want to access the database.

#10112

Zelldon · 2022-08-25T11:55:14Z

Not sure but the tests seems to expect that the second model triggers three times:


    final BpmnModelInstance firstModel =
        Bpmn.createExecutableProcess("process_1")
            .startEvent("start_1")
            .timerWithCycle(String.format("R2/%s/PT10S", start))
            .endEvent("end_1")
            .done();

    final BpmnModelInstance secondModel =
        Bpmn.createExecutableProcess("process_2")
            .startEvent("start_2")
            .timerWithCycle(String.format("R3/%s/PT10S", start))
            .endEvent("end_2")
            .done();

This assert:

    assertThat(RecordingExporter.timerRecords(TimerIntent.TRIGGERED).limit(5))
        .extracting(record -> record.getValue().getProcessDefinitionKey())
        .containsExactly(
            firstDeploymentProcessDefinitionKey,
            secondDeploymentProcessDefinitionKey,
            firstDeploymentProcessDefinitionKey,
            secondDeploymentProcessDefinitionKey,
            secondDeploymentProcessDefinitionKey);

fails with:

java.lang.AssertionError: 
Expecting actual:
  [2251799813685249L, 2251799813685252L, 2251799813685249L, 2251799813685252L]
to contain exactly (and in same order):
  [2251799813685249L,
    2251799813685252L,
    2251799813685249L,
    2251799813685252L,
    2251799813685252L]
but could not find the following elements:
  [2251799813685252L]


	at io.camunda.zeebe.engine.processing.timer.TimerStartEventTest.shouldTriggerOnlyTwice(TimerStartEventTest.java:1107)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
	at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:61)
	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
	at org.junit.rules.RunRules.evaluate(RunRules.java:20)
	at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
	at org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100)
	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:366)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:103)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:63)
	at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
	at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
	at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
	at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
	at com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:69)
	at com.intellij.rt.junit.IdeaTestRunner$Repeater$1.execute(IdeaTestRunner.java:38)
	at com.intellij.rt.execution.junit.TestsRepeater.repeat(TestsRepeater.java:30)
	at com.intellij.rt.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:35)
	at com.intellij.rt.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:235)
	at com.intellij.rt.junit.JUnitStarter.main(JUnitStarter.java:54)

Details

``` 13:49:42.842 [Broker-0-LogStream-1] DEBUG io.camunda.zeebe.logstreams - Configured log appender back pressure at partition 1 as AppenderVegasCfg{initialLimit=1024, maxConcurrency=32768, alphaLimit=0.7, betaLimit=0.95}. Window limiting is disabled 13:49:42.897 [Broker-0-StreamProcessor-1] DEBUG io.camunda.zeebe.logstreams - Recovering state of partition 1 from snapshot 13:49:42.897 [Broker-0-StreamProcessor-1] INFO org.camunda.feel.FeelEngine - Engine created. [value-mapper: CompositeValueMapper(List(io.camunda.zeebe.feel.impl.MessagePackValueMapper@6a070fe5)), function-provider: io.camunda.zeebe.feel.impl.FeelFunctionProvider@64c0fcd5, clock: io.camunda.zeebe.el.impl.ZeebeFeelEngineClock@60ff6495, configuration: Configuration(false)] 13:49:42.907 [Broker-0-StreamProcessor-1] INFO io.camunda.zeebe.logstreams - Recovered state of partition 1 from snapshot at position -1 13:49:42.908 [Broker-0-StreamProcessor-1] INFO org.camunda.feel.FeelEngine - Engine created. [value-mapper: CompositeValueMapper(List(io.camunda.zeebe.feel.impl.MessagePackValueMapper@25fdf6ee)), function-provider: io.camunda.zeebe.feel.impl.FeelFunctionProvider@77d7bd93, clock: io.camunda.zeebe.el.impl.ZeebeFeelEngineClock@1412d1e8, configuration: Configuration(false)] 13:49:42.909 [Broker-0-StreamProcessor-1] INFO org.camunda.feel.FeelEngine - Engine created. [value-mapper: CompositeValueMapper(List(io.camunda.zeebe.feel.impl.MessagePackValueMapper@fd2c433)), function-provider: io.camunda.zeebe.feel.impl.FeelFunctionProvider@45d209a1, clock: io.camunda.zeebe.el.impl.ZeebeFeelEngineClock@fa31fad, configuration: Configuration(false)] 13:49:42.910 [Broker-0-StreamProcessor-1] INFO org.camunda.dmn.DmnEngine - DMN-Engine created. [value-mapper: CompositeValueMapper(List(io.camunda.zeebe.feel.impl.MessagePackValueMapper@1a85ee25)), function-provider: org.camunda.feel.context.FunctionProvider$EmptyFunctionProvider$@780ed8a8, audit-loggers: List(), configuration: Configuration(false,false,false)] 13:49:42.910 [Broker-0-StreamProcessor-1] INFO org.camunda.feel.FeelEngine - Engine created. [value-mapper: CompositeValueMapper(List(org.camunda.dmn.NoUnpackValueMapper@3abfd797)), function-provider: org.camunda.feel.context.FunctionProvider$EmptyFunctionProvider$@780ed8a8, clock: SystemClock, configuration: Configuration(false)] 13:49:42.911 [Broker-0-StreamProcessor-1] INFO org.camunda.feel.FeelEngine - Engine created. [value-mapper: CompositeValueMapper(List(io.camunda.zeebe.feel.impl.MessagePackValueMapper@441d55b2)), function-provider: io.camunda.zeebe.feel.impl.FeelFunctionProvider@56bcd2ce, clock: io.camunda.zeebe.el.impl.ZeebeFeelEngineClock@637deafa, configuration: Configuration(false)] 13:49:42.912 [Broker-0-StreamProcessor-1] INFO org.camunda.feel.FeelEngine - Engine created. [value-mapper: CompositeValueMapper(List(io.camunda.zeebe.feel.impl.MessagePackValueMapper@27ba8a6d)), function-provider: io.camunda.zeebe.feel.impl.FeelFunctionProvider@9a4ebed, clock: io.camunda.zeebe.el.impl.ZeebeFeelEngineClock@393e62b5, configuration: Configuration(false)] 13:49:42.914 [Broker-0-StreamProcessor-1] INFO org.camunda.dmn.DmnEngine - DMN-Engine created. [value-mapper: CompositeValueMapper(List(io.camunda.zeebe.feel.impl.MessagePackValueMapper@1e6f4bc)), function-provider: org.camunda.feel.context.FunctionProvider$EmptyFunctionProvider$@780ed8a8, audit-loggers: List(), configuration: Configuration(false,false,false)] 13:49:42.914 [Broker-0-StreamProcessor-1] INFO org.camunda.feel.FeelEngine - Engine created. [value-mapper: CompositeValueMapper(List(org.camunda.dmn.NoUnpackValueMapper@5127ed58)), function-provider: org.camunda.feel.context.FunctionProvider$EmptyFunctionProvider$@780ed8a8, clock: SystemClock, configuration: Configuration(false)] 13:49:42.915 [Broker-0-StreamProcessor-1] INFO io.camunda.zeebe.processor - Processor starts replay of events. [snapshot-position: -1, replay-mode: PROCESSING] 13:49:42.916 [Broker-0-StreamProcessor-1] INFO io.camunda.zeebe.processor - Processor finished replay, with [lastProcessedPosition: -1, lastWrittenPosition: -1] 13:49:42.916 [Broker-0-StreamProcessor-1] INFO io.camunda.zeebe.engine.state.migration - Starting processing of migration tasks (use LogLevel.DEBUG for more details) ... 13:49:42.916 [Broker-0-StreamProcessor-1] DEBUG io.camunda.zeebe.engine.state.migration - Found 3 migration tasks: ProcessMessageSubscriptionSentTimeMigration, MessageSubscriptionSentTimeMigration, TemporaryVariableMigration 13:49:42.916 [Broker-0-StreamProcessor-1] INFO io.camunda.zeebe.engine.state.migration - Skipping ProcessMessageSubscriptionSentTimeMigration migration (1/3). It was determined it does not need to run right now. 13:49:42.916 [Broker-0-StreamProcessor-1] INFO io.camunda.zeebe.engine.state.migration - Skipping MessageSubscriptionSentTimeMigration migration (2/3). It was determined it does not need to run right now. 13:49:42.917 [Broker-0-StreamProcessor-1] INFO io.camunda.zeebe.engine.state.migration - Skipping TemporaryVariableMigration migration (3/3). It was determined it does not need to run right now. 13:49:42.917 [Broker-0-StreamProcessor-1] INFO io.camunda.zeebe.engine.state.migration - Completed processing of migration tasks (use LogLevel.DEBUG for more details) ... 13:49:42.917 [Broker-0-StreamProcessor-1] DEBUG io.camunda.zeebe.engine.state.migration - Executed 0 migration tasks: 13:49:48.073 [] INFO io.camunda.zeebe.test - Test failed, following records were exported: 13:49:48.248 [] INFO io.camunda.zeebe.test - Compact log representation: -------- [Timestamp] ['C'ommand/'E'event/'R'ejection] [valueType] [intent] - #[position]->#[source record position] 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' -------- 13:49:42 C DPLY CREATE - #1-> -1 -1 - 13:49:42 E PROC CREATED - #2->#1 K001 - process.xml -> "process_1" (version:1) 13:49:42 E TIME CREATED - #3->#1 K003 - @"start_1"[ -1] in due T13:49:52.9172 reps 13:49:42 E DPLY CREATED - #4->#1 K002 - process.xml 13:49:42 E DPLY FULLY_DISTRIBUTED - #5->#1 K002 - 13:49:42 C DPLY CREATE - #6-> -1 -1 - 13:49:42 E PROC CREATED - #7->#6 K004 - process.xml -> "process_2" (version:1) 13:49:42 E TIME CREATED - #8->#6 K006 - @"start_2"[ -1] in due T13:49:52.9173 reps 13:49:42 E DPLY CREATED - #9->#6 K005 - process.xml 13:49:42 E DPLY FULLY_DISTRIBUTED - #10->#6 K005 - 13:49:58 C TIME TRIGGER - #11-> -1 K003 - @"start_1"[ -1] in due T13:49:52.9172 reps 13:49:58 C TIME TRIGGER - #12-> -1 K006 - @"start_2"[ -1] in due T13:49:52.9173 reps 13:49:58 E TIME TRIGGERED - #13->#11 K003 - @"start_1"[ -1] in due T13:49:52.9172 reps 13:49:58 E PROC_EVNT TRIGGERING - #14->#11 K008 - @"start_1"[K001] in (no vars) 13:49:58 C PI ACTIVATE - #15->#11 K007 - PROCESS "process_1" in 13:49:58 E TIME CREATED - #16->#11 K009 - @"start_1"[ -1] in due T13:50:02.917 13:49:58 C TIME TRIGGER - #17-> -1 K006 - @"start_2"[ -1] in due T13:49:52.9173 reps 13:49:58 E TIME TRIGGERED - #18->#12 K006 - @"start_2"[ -1] in due T13:49:52.9173 reps 13:49:58 E PROC_EVNT TRIGGERING - #19->#12 K011 - @"start_2"[K004] in (no vars) 13:49:58 C PI ACTIVATE - #20->#12 K010 - PROCESS "process_2" in 13:49:58 E TIME CREATED - #21->#12 K012 - @"start_2"[ -1] in due T13:50:02.9172 reps 13:50:03 C TIME TRIGGER - #22-> -1 K009 - @"start_1"[ -1] in due T13:50:02.917 13:50:03 C TIME TRIGGER - #23-> -1 K012 - @"start_2"[ -1] in due T13:50:02.9172 reps 13:50:03 E PI ACTIVATING - #24->#15 K007 - PROCESS "process_1" in 13:50:03 E PI ACTIVATED - #25->#15 K007 - PROCESS "process_1" in 13:50:03 E PROC_EVNT TRIGGERED - #26->#15 K008 - @"start_1"[K001] in (no vars) 13:50:03 E PI ACTIVATING - #27->#15 K013 - START_EVENT "start_1" in 13:50:03 E PI ACTIVATED - #28->#15 K013 - START_EVENT "start_1" in 13:50:03 C PI COMPLETE - #29->#15 K013 - START_EVENT "start_1" in 13:50:03 R TIME TRIGGER - #30->#17 K006 - @"start_2"[ -1] in due T13:49:52.9173 reps !NOT_FOUND (Expected to trigger timer with key '2251799813685254', but no such timer was found) 13:50:03 C TIME TRIGGER - #31-> -1 K009 - @"start_1"[ -1] in due T13:50:02.917 13:50:03 C TIME TRIGGER - #32-> -1 K012 - @"start_2"[ -1] in due T13:50:02.9172 reps 13:50:03 E PI ACTIVATING - #33->#20 K010 - PROCESS "process_2" in 13:50:03 E PI ACTIVATED - #34->#20 K010 - PROCESS "process_2" in 13:50:03 E PROC_EVNT TRIGGERED - #35->#20 K011 - @"start_2"[K004] in (no vars) 13:50:03 E PI ACTIVATING - #36->#20 K014 - START_EVENT "start_2" in 13:50:03 E PI ACTIVATED - #37->#20 K014 - START_EVENT "start_2" in 13:50:03 C PI COMPLETE - #38->#20 K014 - START_EVENT "start_2" in 13:50:03 E TIME TRIGGERED - #39->#22 K009 - @"start_1"[ -1] in due T13:50:02.917 13:50:03 E PROC_EVNT TRIGGERING - #40->#22 K016 - @"start_1"[K001] in (no vars) 13:50:03 C PI ACTIVATE - #41->#22 K015 - PROCESS "process_1" in 13:50:03 E TIME TRIGGERED - #42->#23 K012 - @"start_2"[ -1] in due T13:50:02.9172 reps 13:50:03 E PROC_EVNT TRIGGERING - #43->#23 K018 - @"start_2"[K004] in (no vars) 13:50:03 C PI ACTIVATE - #44->#23 K017 - PROCESS "process_2" in 13:50:03 E TIME CREATED - #45->#23 K019 - @"start_2"[ -1] in due T13:50:12.917 13:50:13 E PI COMPLETING - #46->#29 K013 - START_EVENT "start_1" in 13:50:13 E PI COMPLETED - #47->#29 K013 - START_EVENT "start_1" in 13:50:13 E PI SEQ_FLOW_TAKEN - #48->#29 K020 - SEQUENCE_FLOW "sequenc..549f327" in 13:50:13 C PI ACTIVATE - #49->#29 K021 - END_EVENT "end_1" in 13:50:13 R TIME TRIGGER - #50->#31 K009 - @"start_1"[ -1] in due T13:50:02.917 !NOT_FOUND (Expected to trigger timer with key '2251799813685257', but no such timer was found) 13:50:13 R TIME TRIGGER - #51->#32 K012 - @"start_2"[ -1] in due T13:50:02.9172 reps !NOT_FOUND (Expected to trigger timer with key '2251799813685260', but no such timer was found) 13:50:13 E PI COMPLETING - #52->#38 K014 - START_EVENT "start_2" in 13:50:13 E PI COMPLETED - #53->#38 K014 - START_EVENT "start_2" in 13:50:13 E PI SEQ_FLOW_TAKEN - #54->#38 K022 - SEQUENCE_FLOW "sequenc..4c33552" in 13:50:13 C PI ACTIVATE - #55->#38 K023 - END_EVENT "end_2" in 13:50:13 E PI ACTIVATING - #56->#41 K015 - PROCESS "process_1" in 13:50:13 E PI ACTIVATED - #57->#41 K015 - PROCESS "process_1" in 13:50:13 E PROC_EVNT TRIGGERED - #58->#41 K016 - @"start_1"[K001] in (no vars) 13:50:13 E PI ACTIVATING - #59->#41 K024 - START_EVENT "start_1" in 13:50:13 E PI ACTIVATED - #60->#41 K024 - START_EVENT "start_1" in 13:50:13 C PI COMPLETE - #61->#41 K024 - START_EVENT "start_1" in 13:50:13 E PI ACTIVATING - #62->#44 K017 - PROCESS "process_2" in 13:50:13 E PI ACTIVATED - #63->#44 K017 - PROCESS "process_2" in 13:50:13 E PROC_EVNT TRIGGERED - #64->#44 K018 - @"start_2"[K004] in (no vars) 13:50:13 E PI ACTIVATING - #65->#44 K025 - START_EVENT "start_2" in 13:50:13 E PI ACTIVATED - #66->#44 K025 - START_EVENT "start_2" in 13:50:13 C PI COMPLETE - #67->#44 K025 - START_EVENT "start_2" in 13:50:13 E PI ACTIVATING - #68->#49 K021 - END_EVENT "end_1" in 13:50:13 E PI ACTIVATED - #69->#49 K021 - END_EVENT "end_1" in 13:50:13 E PI COMPLETING - #70->#49 K021 - END_EVENT "end_1" in 13:50:13 E PI COMPLETED - #71->#49 K021 - END_EVENT "end_1" in 13:50:13 C PI COMPLETE - #72->#49 K007 - PROCESS "process_1" in 13:50:13 E PI ACTIVATING - #73->#55 K023 - END_EVENT "end_2" in 13:50:13 E PI ACTIVATED - #74->#55 K023 - END_EVENT "end_2" in 13:50:13 E PI COMPLETING - #75->#55 K023 - END_EVENT "end_2" in 13:50:13 E PI COMPLETED - #76->#55 K023 - END_EVENT "end_2" in 13:50:13 C PI COMPLETE - #77->#55 K010 - PROCESS "process_2" in 13:50:13 E PI COMPLETING - #78->#61 K024 - START_EVENT "start_1" in 13:50:13 E PI COMPLETED - #79->#61 K024 - START_EVENT "start_1" in 13:50:13 E PI SEQ_FLOW_TAKEN - #80->#61 K026 - SEQUENCE_FLOW "sequenc..549f327" in 13:50:13 C PI ACTIVATE - #81->#61 K027 - END_EVENT "end_1" in 13:50:13 E PI COMPLETING - #82->#67 K025 - START_EVENT "start_2" in 13:50:13 E PI COMPLETED - #83->#67 K025 - START_EVENT "start_2" in 13:50:13 E PI SEQ_FLOW_TAKEN - #84->#67 K028 - SEQUENCE_FLOW "sequenc..4c33552" in 13:50:13 C PI ACTIVATE - #85->#67 K029 - END_EVENT "end_2" in 13:50:13 E PI COMPLETING - #86->#72 K007 - PROCESS "process_1" in 13:50:13 E PI COMPLETED - #87->#72 K007 - PROCESS "process_1" in 13:50:13 E PI COMPLETING - #88->#77 K010 - PROCESS "process_2" in 13:50:13 E PI COMPLETED - #89->#77 K010 - PROCESS "process_2" in 13:50:13 E PI ACTIVATING - #90->#81 K027 - END_EVENT "end_1" in 13:50:13 E PI ACTIVATED - #91->#81 K027 - END_EVENT "end_1" in 13:50:13 E PI COMPLETING - #92->#81 K027 - END_EVENT "end_1" in 13:50:13 E PI COMPLETED - #93->#81 K027 - END_EVENT "end_1" in 13:50:13 C PI COMPLETE - #94->#81 K015 - PROCESS "process_1" in 13:50:13 E PI ACTIVATING - #95->#85 K029 - END_EVENT "end_2" in 13:50:13 E PI ACTIVATED - #96->#85 K029 - END_EVENT "end_2" in 13:50:13 E PI COMPLETING - #97->#85 K029 - END_EVENT "end_2" in 13:50:13 E PI COMPLETED - #98->#85 K029 - END_EVENT "end_2" in 13:50:13 C PI COMPLETE - #99->#85 K017 - PROCESS "process_2" in 13:50:13 E PI COMPLETING - #100->#94 K015 - PROCESS "process_1" in 13:50:13 E PI COMPLETED - #101->#94 K015 - PROCESS "process_1" in 13:50:13 E PI COMPLETING - #102->#99 K017 - PROCESS "process_2" in 13:50:13 E PI COMPLETED - #103->#99 K017 - PROCESS "process_2" in

-------------- Deployed Processes ----------------------
process.xml -> "process_1" (version:1)[K001] ------

sequenceFlow_1c206563-d354-4448-bce6-1c05b549f327 R2/2022-08-25T13:49:52.917+02:00[Europe/Berlin]/PT10S sequenceFlow_1c206563-d354-4448-bce6-1c05b549f327

process.xml -> "process_2" (version:1)[K004] ------

sequenceFlow_fde20e38-fe7a-4be3-818a-d11524c33552 R3/2022-08-25T13:49:52.917+02:00[Europe/Berlin]/PT10S sequenceFlow_fde20e38-fe7a-4be3-818a-d11524c33552

--------------- Decomposed keys (for debugging) -----------------
-1 <-> -1
K001 <-> 2251799813685249
K002 <-> 2251799813685250
K003 <-> 2251799813685251
K004 <-> 2251799813685252
K005 <-> 2251799813685253
K006 <-> 2251799813685254
K007 <-> 2251799813685255
K008 <-> 2251799813685256
K009 <-> 2251799813685257
K010 <-> 2251799813685258
K011 <-> 2251799813685259
K012 <-> 2251799813685260
K013 <-> 2251799813685261
K014 <-> 2251799813685262
K015 <-> 2251799813685263
K016 <-> 2251799813685264
K017 <-> 2251799813685265
K018 <-> 2251799813685266
K019 <-> 2251799813685267
K020 <-> 2251799813685268
K021 <-> 2251799813685269
K022 <-> 2251799813685270
K023 <-> 2251799813685271
K024 <-> 2251799813685272
K025 <-> 2251799813685273
K026 <-> 2251799813685274
K027 <-> 2251799813685275
K028 <-> 2251799813685276
K029 <-> 2251799813685277

13:49:48.250 [] DEBUG io.camunda.zeebe.broker.logstreams - Close stream processor
13:49:48.250 [Broker-0-StreamProcessor-1] DEBUG io.camunda.zeebe.logstreams - Closed stream processor controller Broker-0-StreamProcessor-1.
13:49:48.294 [Broker-0-LogStream-1] INFO io.camunda.zeebe.logstreams - Close appender for log stream stream-1
13:49:48.294 [stream-1-write-buffer] DEBUG io.camunda.zeebe.dispatcher - Dispatcher closed
13:49:48.294 [Broker-0-LogStream-1] INFO io.camunda.zeebe.logstreams - On closing logstream stream-1 close 2 readers
13:49:48.294 [] DEBUG io.camunda.zeebe.broker.test - Clean up test files on path /tmp/junit14901977728875490396
13:49:48.295 [] DEBUG io.camunda.zeebe.util.actor - Closing actor thread ground '-zb-fs-workers'
13:49:48.295 [] DEBUG io.camunda.zeebe.util.actor - Closing actor thread ground '-zb-actors'
13:49:48.296 [] DEBUG io.camunda.zeebe.util.actor - Closing actor thread ground '-zb-actors': closed successfully
13:49:48.296 [] DEBUG io.camunda.zeebe.util.actor - Closing actor thread ground '-zb-fs-workers': closed successfully

java.lang.AssertionError:
Expecting actual:
[2251799813685249L, 2251799813685252L, 2251799813685249L, 2251799813685252L]
to contain exactly (and in same order):
[2251799813685249L,
2251799813685252L,
2251799813685249L,
2251799813685252L,
2251799813685252L]
but could not find the following elements:
[2251799813685252L]

at io.camunda.zeebe.engine.processing.timer.TimerStartEventTest.shouldTriggerOnlyTwice(TimerStartEventTest.java:1107)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:568)
at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:61)
at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
at org.junit.rules.RunRules.evaluate(RunRules.java:20)
at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
at org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100)
at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:366)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:103)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:63)
at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
at com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:69)
at com.intellij.rt.junit.IdeaTestRunner$Repeater$1.execute(IdeaTestRunner.java:38)
at com.intellij.rt.execution.junit.TestsRepeater.repeat(TestsRepeater.java:30)
at com.intellij.rt.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:35)
at com.intellij.rt.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:235)
at com.intellij.rt.junit.JUnitStarter.main(JUnitStarter.java:54)

</details>

npepinpe · 2024-05-06T14:25:58Z

Occurred again, with a likely explanation provided by @korthout: #17254 (comment)

See: https://github.com/camunda/zeebe/actions/runs/8970247080/job/24633352874

## Description Unflake tests that rely on time travel to trigger timers. This was unstable because the due date checker was scheduled with a delay, which is used to determine an actual deadline later during the actor's scheduling of the TimerSubscription. The instability arose because the task can be scheduled async, which means that the deadline was calculated async as well, so it could happen that the deadline was determined after the test had already traveled through time. This problem is resolved by introducing a new `runAt` method, which allows scheduling a task at a specific timestamp. When the async scheduling is postponed until after the time traveling, the task will trigger immediately if the timestamp is now in the past. This changes the following modules: - `schedule` introduces a new `runAt` method that can schedule Timer tasks (TimerSubscription) by timestamp - `stream-platform` introduces a new `runAt` method for the engine to schedule tasks at a timestamp that can produce processing results - `engine` uses the new `runAt` method to (re)schedule the DueDateChecker ## Related issues closes #17254 closes #10169 closes #18462

@korthout

# Description Backport of #18508 to `stable/8.5`. relates to #17254 #10169 #18462 original author: @korthout

@korthout

# Description Backport of #18508 to `stable/8.4`. relates to #17254 #10169 #18462 original author: @korthout

@korthout

# Description Backport of #18508 to `stable/8.3`. relates to #17254 #10169 #18462 original author: @korthout

@korthout

# Description Backport of #18508 to `stable/8.2`. relates to #17254 #10169 #18462 original author: @korthout

korthout added the kind/flake Categorizes issue or PR as related to a flaky test label Aug 24, 2022

korthout mentioned this issue Aug 24, 2022

Reject modify command when an element for activation is unknown #10153

Merged

10 tasks

korthout mentioned this issue Aug 24, 2022

Print record timestamp in compact record logger #10170

Merged

10 tasks

This was referenced Aug 24, 2022

[Backport stable/1.3] Print record timestamp in compact record logger #10175

Merged

[Backport stable/8.0] Print record timestamp in compact record logger #10176

Merged

korthout self-assigned this Aug 25, 2022

korthout mentioned this issue Aug 29, 2022

Unflake TimerStartEventTest.shouldTriggerOnlyTwice #10214

Merged

10 tasks

zeebe-bors-camunda bot closed this as completed in f4751bf Aug 30, 2022

saig0 added release/8.0.8 version:1.3.14 Marks an issue as being completely or in parts released in 1.3.14 labels Sep 1, 2022

deepthidevaki added the release/8.1.0-alpha5 label Sep 6, 2022

Zelldon added the version:8.1.0 Marks an issue as being completely or in parts released in 8.1.0 label Oct 4, 2022

npepinpe reopened this May 6, 2024

korthout mentioned this issue May 6, 2024

Flaky: io.camunda.zeebe.engine.processing.multitenancy.TenantAwareTimerCatchEventTest.shouldRescheduleTimer #17254

Closed

korthout mentioned this issue May 14, 2024

Schedule tasks by timestamp #18508

Merged

korthout closed this as completed in #18508 May 27, 2024

backport-action mentioned this issue May 27, 2024

[Backport stable/8.5] Schedule tasks by timestamp #18857

Merged

This was referenced May 28, 2024

[Backport stable/8.2] Schedule tasks by timestamp #18893

Merged

[Backport stable/8.3] Schedule tasks by timestamp #18894

Merged

[Backport stable/8.4] Schedule tasks by timestamp #18895

Merged

github-merge-queue bot pushed a commit that referenced this issue May 31, 2024

[Backport stable/8.5] Schedule tasks by timestamp (#18857)

221b9cd

# Description Backport of #18508 to `stable/8.5`. relates to #17254 #10169 #18462 original author: @korthout

github-merge-queue bot pushed a commit that referenced this issue Jun 3, 2024

[Backport stable/8.4] Schedule tasks by timestamp (#18895)

8b4c1ec

# Description Backport of #18508 to `stable/8.4`. relates to #17254 #10169 #18462 original author: @korthout

github-merge-queue bot pushed a commit that referenced this issue Jun 3, 2024

[Backport stable/8.3] Schedule tasks by timestamp (#18894)

348d183

# Description Backport of #18508 to `stable/8.3`. relates to #17254 #10169 #18462 original author: @korthout

github-actions bot added version:8.5.2 Label that represents issues released on version 8.5.2 version:8.3.12 Label that represents issues released on version 8.3.12 version:8.4.8 Label that represents issues released on version 8.4.8 labels Jun 4, 2024

korthout added the version:8.6.0-alpha2 Marks an issue as being completely or in parts released in 8.6.0-alpha2 label Jun 4, 2024

github-merge-queue bot pushed a commit that referenced this issue Jun 11, 2024

[Backport stable/8.2] Schedule tasks by timestamp (#18893)

46745a8

# Description Backport of #18508 to `stable/8.2`. relates to #17254 #10169 #18462 original author: @korthout

github-actions bot added the version:8.2.29 Marks an issue as being completely or in parts released in 8.2.29 label Jun 26, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Flaky test TimerStartEventTest.shouldTriggerOnlyTwice #10169

Flaky test TimerStartEventTest.shouldTriggerOnlyTwice #10169

korthout commented Aug 24, 2022

korthout commented Aug 24, 2022 •

edited

Loading

Zelldon commented Aug 24, 2022

Zelldon commented Aug 25, 2022

korthout commented Aug 25, 2022

Zelldon commented Aug 25, 2022

Zelldon commented Aug 25, 2022 •

edited

Loading

npepinpe commented May 6, 2024 •

edited

Loading

Flaky test TimerStartEventTest.shouldTriggerOnlyTwice #10169

Flaky test TimerStartEventTest.shouldTriggerOnlyTwice #10169

Comments

korthout commented Aug 24, 2022

korthout commented Aug 24, 2022 • edited Loading

Zelldon commented Aug 24, 2022

Zelldon commented Aug 25, 2022

korthout commented Aug 25, 2022

Zelldon commented Aug 25, 2022

Zelldon commented Aug 25, 2022 • edited Loading

npepinpe commented May 6, 2024 • edited Loading

korthout commented Aug 24, 2022 •

edited

Loading

Zelldon commented Aug 25, 2022 •

edited

Loading

npepinpe commented May 6, 2024 •

edited

Loading