Unflake timer start event test #10867

korthout · 2022-10-31T15:29:36Z

Description

Most cases in the timer start event test were suffering from flakiness. This stabilizes these tests again.

The cause of the flakiness was a race condition between time traveling and scheduling an upcoming timer:

the time would be increased after the deployment is completed
that includes writing all the deployment events (up to and including fully_distributed)
it does not await post-commit task execution
upcoming timers are scheduled in a post-commit task
this post-commit task could be executed after the time traveling
in that case the timer does not trigger after the time travel, as it is scheduled in the future

This changes the time travel to guarantee that the post-commit tasks have been executed. It does that by awaiting that the engine reaches the end of the log.

Related issues

closes #10272

Definition of Done

Not all items need to be done depending on the issue and the pull request.

Code changes:

The changes are backwards compatibility with previous versions
If it fixes a bug then PRs are created to backport the fix to the last two minor versions. You can trigger a backport by assigning labels (e.g. backport stable/1.3) to the PR, in case that fails you need to create backports manually.

Testing:

There are unit/integration tests that verify all acceptance criterias of the issue
New tests are written to ensure backwards compatibility with further versions
The behavior is tested manually
The change has been verified by a QA run
The impact of the changes is verified by a benchmark

Documentation:

The documentation is updated (e.g. BPMN reference, configuration, examples, get-started guides, etc.)
If the PR changes how BPMN processes are validated (e.g. support new BPMN element) then the Camunda modeling team should be informed to adjust the BPMN linting.

Please refer to our review guidelines.

Pretty much all timer start event tests increase the engine time to test the timer scheduling. These tests can all suffer from unwanted race conditions becaue the timer is scheduled in a post-commit task. There is no clear way to await for this post-commit task to be executed, except for awaiting the engine to reach the end of the log. Since we generally only want to time travel in tests when there is something related to the timer scheduling, it makes sense to hide this in the `increaseTime` method of the EngineRule. Also note that this only matters when the streamprocessor is currently processing. If the engine is paused, the hasReachedEnd method cannot be called because the relevant actor is also paused. Co-authored-by: Remco Westerhoud <remco@westerhoud.nl> Co-authored-by: Philipp Ossler <philipp.ossler@gmail.com>

If you want to increase the time, we're now using the streamprocessor directly. But in the shouldAvoidTriggeringMultipleTimes test case, the engine was stopped before increasing the time. When the engine is stopped, the stream processor is removed. However, this test just wants to verify wht happens if the scheduled timer triggers and the upcoming due date would also be in the past. That can be achieved as well by pausing the engine instead of stopping it completely. Note that when the engine is paused, we don't have to reset the recording exporter (on restart it would re-export all records again). Co-authored-by: Remco Westerhoud <remco@westerhoud.nl> Co-authored-by: Philipp Ossler <philipp.ossler@gmail.com>

Co-authored-by: Remco Westerhoud <remco@westerhoud.nl> Co-authored-by: Philipp Ossler <philipp.ossler@gmail.com>

Now that the EngineRule.increaseTime can guarantee that timers are scheduled before time traveling, we no longer need Awaitility to repeatedly check that the timer triggered. Co-authored-by: Remco Westerhoud <remco@westerhoud.nl> Co-authored-by: Philipp Ossler <philipp.ossler@gmail.com>

github-actions · 2022-10-31T15:44:44Z

Test Results

  951 files ±    0   951 suites ±0 1h 44m 17s ⏱️ +33s
7 599 tests - 237 7 592 ✔️ - 237 7 💤 ±0 0 ❌ ±0
7 797 runs - 237 7 788 ✔️ - 237 9 💤 ±0 0 ❌ ±0

Results for commit 5c467e4. ± Comparison against base commit 858ee74.

♻️ This comment has been updated with latest results.

saig0

@korthout 👍

remcowesterhoud

LGTM!

bors merge

10867: Unflake timer start event test r=remcowesterhoud a=korthout ## Description  Most cases in the timer start event test were suffering from flakiness. This stabilizes these tests again. The cause of the flakiness was a race condition between time traveling and scheduling an upcoming timer: - the time would be increased after the deployment is completed - that includes writing all the deployment events (up to and including fully_distributed) - it does not await post-commit task execution - upcoming timers are scheduled in a post-commit task - this post-commit task could be executed after the time traveling - in that case the timer does not trigger after the time travel, as it is scheduled in the future This changes the time travel to guarantee that the post-commit tasks have been executed. It does that by awaiting that the engine reaches the end of the log. ## Related issues  closes #10272 Co-authored-by: Nico Korthout <nico.korthout@camunda.com>

zeebe-bors-camunda · 2022-11-01T13:47:17Z

Build failed:

Test summary

korthout · 2022-11-01T15:36:25Z

There was another timer related test that flaked. We should investigate it before merging this, to avoid this creating a bigger problem than it tries to resolve.

remcowesterhoud · 2022-11-02T11:00:53Z

I had a peek at the test. It is flaky because the test case was flawed to begin with. It relied upon the engine increasing its time before the timer was scheduled.
I have pushed a new commit to fix it. @korthout I can't assign you as reviewer as you created the PR, but please have a look 👀

engine/src/test/java/io/camunda/zeebe/engine/processing/timer/TimerCatchEventTest.java

This test was flawed as it creates a timer with a duration of 100ms. Then it continues to verify it has been triggered after 1 second. This worked because the engine increased it's time. This happened before the timer was scheduled so in reality the timer would trigger after 1.1 seconds. With the change in the increase time method to wait until the engine is idle before increasing the time this broke, as the timer would now be scheduled for the 100ms mark as expected.

remcowesterhoud · 2022-11-02T13:38:04Z

bors merge

zeebe-bors-camunda · 2022-11-02T14:00:11Z

Build succeeded:

Test summary

backport-action · 2022-11-02T14:01:08Z

Backport failed for stable/8.0, because it was unable to cherry-pick the commit(s).

Please cherry-pick the changes locally.

git fetch origin stable/8.0
git worktree add -d .worktree/backport-10867-to-stable/8.0 origin/stable/8.0
cd .worktree/backport-10867-to-stable/8.0
git checkout -b backport-10867-to-stable/8.0
ancref=$(git merge-base 858ee7460b931bd325305e6a730ec3c77b4a7e78 5c467e439fefd179cd86aa0ad8112f1a059a3305)
git cherry-pick -x $ancref..5c467e439fefd179cd86aa0ad8112f1a059a3305

backport-action · 2022-11-02T14:01:14Z

Successfully created backport PR #10891 for stable/8.1.

10891: [Backport stable/8.1] Unflake timer start event test r=korthout a=backport-action # Description Backport of #10867 to `stable/8.1`. relates to #10272 Co-authored-by: Nico Korthout <nico.korthout@camunda.com> Co-authored-by: Remco Westerhoud <remco@westerhoud.nl>

10893: [Backport stable/8.0] Unflake timer start event test r=remcowesterhoud a=korthout # Description Backport of #10867 to `stable/8.0`. relates to #10272 --- Reviewer, I had to resolve a few conflicts: - some import changes - new tests in TimerStartEventTest were changed, but these tests don't exist in 8.0 Co-authored-by: Nico Korthout <nico.korthout@camunda.com> Co-authored-by: Remco Westerhoud <remco@westerhoud.nl>

korthout and others added 4 commits October 31, 2022 15:53

docs(engine): clarify awaitility expectation

9d51bfd

Co-authored-by: Remco Westerhoud <remco@westerhoud.nl> Co-authored-by: Philipp Ossler <philipp.ossler@gmail.com>

korthout requested review from saig0 and remcowesterhoud October 31, 2022 15:29

korthout marked this pull request as ready for review October 31, 2022 15:29

korthout added backport stable/8.0 labels Oct 31, 2022

saig0 approved these changes Nov 1, 2022

View reviewed changes

remcowesterhoud approved these changes Nov 1, 2022

View reviewed changes

korthout commented Nov 2, 2022

View reviewed changes

engine/src/test/java/io/camunda/zeebe/engine/processing/timer/TimerCatchEventTest.java Show resolved Hide resolved

remcowesterhoud force-pushed the flaky-start-timer-event-test-10272 branch from ab1232a to 5c467e4 Compare November 2, 2022 13:07

zeebe-bors-camunda bot merged commit f93a7e1 into main Nov 2, 2022

zeebe-bors-camunda bot deleted the flaky-start-timer-event-test-10272 branch November 2, 2022 14:00

backport-action mentioned this pull request Nov 2, 2022

[Backport stable/8.1] Unflake timer start event test #10891

Merged

korthout mentioned this pull request Nov 2, 2022

[Backport stable/8.0] Unflake timer start event test #10893

Merged

remcowesterhoud added the version:8.1.4 Marks an issue as being completely or in parts released in 8.1.4 label Nov 22, 2022

remcowesterhoud added the release/8.0.9 label Dec 6, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Unflake timer start event test #10867

Unflake timer start event test #10867

korthout commented Oct 31, 2022 •

edited

Loading

github-actions bot commented Oct 31, 2022 •

edited

Loading

saig0 left a comment

remcowesterhoud left a comment

zeebe-bors-camunda bot commented Nov 1, 2022

korthout commented Nov 1, 2022

remcowesterhoud commented Nov 2, 2022 •

edited

Loading

remcowesterhoud commented Nov 2, 2022

zeebe-bors-camunda bot commented Nov 2, 2022

backport-action commented Nov 2, 2022

backport-action commented Nov 2, 2022

Unflake timer start event test #10867

Unflake timer start event test #10867

Conversation

korthout commented Oct 31, 2022 • edited Loading

Description

Related issues

Definition of Done

github-actions bot commented Oct 31, 2022 • edited Loading

Test Results

saig0 left a comment

Choose a reason for hiding this comment

remcowesterhoud left a comment

Choose a reason for hiding this comment

zeebe-bors-camunda bot commented Nov 1, 2022

korthout commented Nov 1, 2022

remcowesterhoud commented Nov 2, 2022 • edited Loading

remcowesterhoud commented Nov 2, 2022

zeebe-bors-camunda bot commented Nov 2, 2022

backport-action commented Nov 2, 2022

backport-action commented Nov 2, 2022

korthout commented Oct 31, 2022 •

edited

Loading

github-actions bot commented Oct 31, 2022 •

edited

Loading

remcowesterhoud commented Nov 2, 2022 •

edited

Loading