[DO-NOT-MERGE] [incubator-kie-drools-6093] flaky test: org.drools.compiler.integrationtests.TimerAndCalendarFireUntilHaltTest

[tkobayas]

Issue:

• flaky test: org.drools.compiler.integrationtests.TimerAndCalendarFireUntilHaltTest #6093

debug log only

[tkobayas]

2024-09-20T06:30:33.1495020Z 06:30:33.092 [Time-limited test] INFO  o.d.c.i.TimerAndCalendarFireUntilHaltTest.testTimerRuleFires:107 - ### testTimerRuleFires
2024-09-20T06:30:33.1501202Z 06:30:33.093 [Time-limited test] INFO  o.d.c.i.TimerAndCalendarFireUntilHaltTest.setupKSessionFor:218 -   ** exec-model : true
2024-09-20T06:30:33.4517092Z 06:30:33.353 [Time-limited test] INFO  o.d.c.i.TimerAndCalendarFireUntilHaltTest.setupKSessionFor:226 -   setupKSessionFor : 260ms
2024-09-20T06:30:33.4523986Z 06:30:33.355 [Thread-12] INFO  o.d.c.i.TimerAndCalendarFireUntilHaltTest$RecordingRulesListener.afterMatchFired:68 -     afterMatchFired! : event.getMatch = 71551303
2024-09-20T06:30:33.4527560Z 06:30:33.356 [Thread-12] INFO  o.d.c.i.TimerAndCalendarFireUntilHaltTest$RecordingRulesListener.afterMatchFired:69 -                      : event.getFH = [[fact 0:1:1467082313:-1059891784:1:DEFAULT:NON_TRAIT:java.lang.String:trigger]]
2024-09-20T06:30:33.4532059Z 06:30:33.356 [Thread-12] INFO  o.d.c.i.TimerAndCalendarFireUntilHaltTest$RecordingRulesListener.afterMatchFired:76 -     afterMatchFired! : firedRules.get(ruleName) = 1
2024-09-20T06:30:33.4534963Z 06:30:33.356 [Time-limited test] INFO  o.d.c.i.TimerAndCalendarFireUntilHaltTest.testTimerRuleFires:123 -   -- before await : elapsed 263ms
2024-09-20T06:30:33.4538458Z 06:30:33.356 [Thread-12] INFO  o.d.c.i.TimerAndCalendarFireUntilHaltTest$RecordingRulesListener.afterMatchFired:68 -     afterMatchFired! : event.getMatch = 71551303
2024-09-20T06:30:33.4542003Z 06:30:33.356 [Thread-12] INFO  o.d.c.i.TimerAndCalendarFireUntilHaltTest$RecordingRulesListener.afterMatchFired:69 -                      : event.getFH = [[fact 0:1:1467082313:-1059891784:1:DEFAULT:NON_TRAIT:java.lang.String:trigger]]
2024-09-20T06:30:33.4545512Z 06:30:33.356 [Thread-12] INFO  o.d.c.i.TimerAndCalendarFireUntilHaltTest$RecordingRulesListener.afterMatchFired:76 -     afterMatchFired! : firedRules.get(ruleName) = 2
2024-09-20T06:30:33.5518265Z 06:30:33.457 [awaitility-thread] INFO  o.d.c.i.TimerAndCalendarFireUntilHaltTest$RecordingRulesListener.timesRulesHasFired:58 -     firedRules.get(ruleName) = 2
2024-09-20T06:30:33.6525394Z 06:30:33.558 [awaitility-thread] INFO  o.d.c.i.TimerAndCalendarFireUntilHaltTest$RecordingRulesListener.timesRulesHasFired:58 -     firedRules.get(ruleName) = 2
2024-09-20T06:30:33.7558935Z 06:30:33.659 [awaitility-thread] INFO  o.d.c.i.TimerAndCalendarFireUntilHaltTest$RecordingRulesListener.timesRulesHasFired:58 -     firedRules.get(ruleName) = 2

Hmm, why the rule matches twice?

[tkobayas]

2024-09-20T07:21:52.2170034Z 07:21:52.120 [Time-limited test] INFO  o.d.c.i.TimerAndCalendarFireUntilHaltTest.testTimerRuleDoesRestartsIfNoLongerHolds:187 - ### testTimerRuleDoesRestartsIfNoLongerHolds
2024-09-20T07:21:52.2172993Z 07:21:52.120 [Time-limited test] INFO  o.d.c.i.TimerAndCalendarFireUntilHaltTest.setupKSessionFor:218 -   ** exec-model : false
2024-09-20T07:21:52.2175352Z 07:21:52.200 [Time-limited test] INFO  o.d.c.i.TimerAndCalendarFireUntilHaltTest.setupKSessionFor:226 -   setupKSessionFor : 80ms
2024-09-20T07:21:52.2177850Z 07:21:52.201 [Time-limited test] INFO  o.d.c.i.TimerAndCalendarFireUntilHaltTest.activateRule:257 -   -- insert trigger
2024-09-20T07:21:52.2180394Z 07:21:52.202 [Thread-3] INFO  o.drools.core.phreak.PhreakTimerNode.scheduleTimer:282 - scheduleTimer: trigger.hasNextFireTime() = 0, timestamp = 0
2024-09-20T07:21:52.2208495Z 07:21:52.203 [Thread-3] INFO  o.drools.core.phreak.PhreakTimerNode.scheduleTimer:290 -   ok, this one fires now
2024-09-20T07:21:52.2210660Z 07:21:52.203 [Thread-3] INFO  o.drools.core.phreak.PhreakTimerNode.scheduleTimer:312 -   then, schedule the next one
2024-09-20T07:21:52.2213394Z 07:21:52.203 [Thread-3] INFO  o.d.c.time.impl.PseudoClockScheduler.scheduleJob:105 -   scheduleJob : jobHandleId = 0, fireTime = 1000
2024-09-20T07:21:52.2215887Z 07:21:52.204 [Time-limited test] INFO  o.d.c.i.TimerAndCalendarFireUntilHaltTest.advanceTimerOneSecond:252 -   -- advanceTimerOneSecond
2024-09-20T07:21:52.2218814Z 07:21:52.204 [Time-limited test] INFO  o.d.c.time.impl.PseudoClockScheduler.runCallBacksAndIncreaseTimer:155 -   runCallBacksAndIncreaseTimer : jobHandleId = 0, fireTime = 1000
2024-09-20T07:21:52.2221893Z 07:21:52.205 [Time-limited test] INFO  o.d.c.i.TimerAndCalendarFireUntilHaltTest.testTimerRuleDoesRestartsIfNoLongerHolds:202 -   -- before await : elapsed 85ms
2024-09-20T07:21:52.2224808Z 07:21:52.206 [Thread-3] INFO  o.d.c.i.TimerAndCalendarFireUntilHaltTest$RecordingRulesListener.afterMatchFired:68 -     afterMatchFired! : event.getMatch = ea95af4
2024-09-20T07:21:52.2229229Z 07:21:52.206 [Thread-3] INFO  o.d.c.i.TimerAndCalendarFireUntilHaltTest$RecordingRulesListener.afterMatchFired:69 -                      : event.getFH = [[fact 0:1:1467082313:-1059891784:1:DEFAULT:NON_TRAIT:java.lang.String:trigger]]
2024-09-20T07:21:52.2240988Z 07:21:52.207 [Thread-3] INFO  o.d.c.i.TimerAndCalendarFireUntilHaltTest$RecordingRulesListener.afterMatchFired:76 -     afterMatchFired! : firedRules.get(ruleName) = 1
2024-09-20T07:21:52.2243947Z 07:21:52.207 [Thread-3] INFO  o.d.c.i.TimerAndCalendarFireUntilHaltTest$RecordingRulesListener.afterMatchFired:68 -     afterMatchFired! : event.getMatch = ea95af4
2024-09-20T07:21:52.2264876Z 07:21:52.207 [Thread-3] INFO  o.d.c.i.TimerAndCalendarFireUntilHaltTest$RecordingRulesListener.afterMatchFired:69 -                      : event.getFH = [[fact 0:1:1467082313:-1059891784:1:DEFAULT:NON_TRAIT:java.lang.String:trigger]]
2024-09-20T07:21:52.2267975Z 07:21:52.207 [Thread-3] INFO  o.d.c.i.TimerAndCalendarFireUntilHaltTest$RecordingRulesListener.afterMatchFired:76 -     afterMatchFired! : firedRules.get(ruleName) = 2

The problem is scheduleTimer: trigger.hasNextFireTime() = 0, timestamp = 0. The match may be created before advanceTimerOneSecond. It results in 2 firings -- for 0ms and 1000ms pseudo clock timestamp.

In a local fast environment, advanceTimerOneSecond comes first before the fireUntilHalt thread creates a match, so we usually observe scheduleTimer: trigger.hasNextFireTime() = 1000, timestamp = 1000. Then, the assertion ruleHasFired("TimerRule", 1) works for it. However, considering the timer setting in the rule timer(int:0 1000), we should expect one firing at timestamp 0ms, then another firing at timestamp 1000ms.

[kie-ci3]

PR job #5 was: UNSTABLE
Possible explanation: This should be test failures

Reproducer

build-chain build full_downstream -f 'https://github.com/raw/${AUTHOR:apache}/incubator-kie-kogito-pipelines/${BRANCH:main}/.ci/buildchain-config-pr-cdb.yaml' -o 'bc' -p apache/incubator-kie-drools -u #6095 --skipParallelCheckout

NOTE: To install the build-chain tool, please refer to https://github.com/kiegroup/github-action-build-chain#local-execution

Please look here: https://ci-builds.apache.org/job/KIE/job/drools/job/main/job/pullrequest_jobs/job/drools-pr/job/PR-6095/5/display/redirect

Test results:

• PASSED: 10201
• FAILED: 2

Those are the test failures:

org.drools.core.time.impl.PseudoClockSchedulerTest.timerIsResetWhenJobThrowsExceptions

Cannot invoke "java.util.Date.getTime()" because the return value of "org.drools.base.time.Trigger.hasNextFireTime()" is null

org.drools.core.time.impl.PseudoClockSchedulerTest.timerIsSetToJobTriggerTimeForExecution

Cannot invoke "java.util.Date.getTime()" because the return value of "org.drools.base.time.Trigger.hasNextFireTime()" is null

[kie-ci3]

PR job #6 was: UNSTABLE
Possible explanation: This should be test failures

Reproducer

build-chain build full_downstream -f 'https://github.com/raw/${AUTHOR:apache}/incubator-kie-kogito-pipelines/${BRANCH:main}/.ci/buildchain-config-pr-cdb.yaml' -o 'bc' -p apache/incubator-kie-drools -u #6095 --skipParallelCheckout

NOTE: To install the build-chain tool, please refer to https://github.com/kiegroup/github-action-build-chain#local-execution

Please look here: https://ci-builds.apache.org/job/KIE/job/drools/job/main/job/pullrequest_jobs/job/drools-pr/job/PR-6095/6/display/redirect

Test results:

• PASSED: 10201
• FAILED: 2

Those are the test failures:

org.drools.core.time.impl.PseudoClockSchedulerTest.timerIsResetWhenJobThrowsExceptions

Cannot invoke "java.util.Date.getTime()" because the return value of "org.drools.base.time.Trigger.hasNextFireTime()" is null

org.drools.core.time.impl.PseudoClockSchedulerTest.timerIsSetToJobTriggerTimeForExecution

Cannot invoke "java.util.Date.getTime()" because the return value of "org.drools.base.time.Trigger.hasNextFireTime()" is null

[tkobayas]

Jenkins: The errors in PseudoClockSchedulerTest came from debug logging. We can ignore them,