Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Closed
wants to merge 6 commits into from
Closed

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

wants to merge 6 commits into from

Conversation

tkobayas
Copy link
Contributor

@tkobayas tkobayas changed the title [incubator-kie-drools-6093] flaky test: org.drools.compiler.integrationtests.TimerAndCalendarFireUntilHaltTest [DO-NOT-MERGE] [incubator-kie-drools-6093] flaky test: org.drools.compiler.integrationtests.TimerAndCalendarFireUntilHaltTest Sep 20, 2024
@tkobayas
Copy link
Contributor Author 

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
Copy link
Contributor Author

tkobayas commented Sep 20, 2024 •
edited
Loading 

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
Copy link

kie-ci3 commented Sep 20, 2024

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

Reproducer

build-chain build full_downstream -f 'https://raw.githubusercontent.com/${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
Copy link

kie-ci3 commented Sep 20, 2024

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

Reproducer

build-chain build full_downstream -f 'https://raw.githubusercontent.com/${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
Copy link
Contributor Author

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

@tkobayas tkobayas mentioned this pull request Sep 20, 2024
Merged
@tkobayas tkobayas closed this Sep 25, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers
No reviews
Assignees
No one assigned
Labels
do-not-merge skip-ci
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
2 participants
@tkobayas @kie-ci3