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

.github/workflows/pr-backporting.yml

@@ -27,7 +27,8 @@ env:
 
 jobs:
   compute-targets:
-    if: ${{ github.event.pull_request.state == 'closed' && github.event.pull_request.merged }}
+    if: false
+    #if: ${{ github.event.pull_request.state == 'closed' && github.event.pull_request.merged }}
     runs-on: ubuntu-latest
     outputs:
       target-branches: ${{ steps.set-targets.outputs.targets }}

.github/workflows/pr-downstream-full.yml

@@ -35,7 +35,8 @@ on:
 
 jobs:
   build-chain:
-    if: contains(github.event.pull_request.labels.*.name, 'run_fdb')
+    if: false
+    #if: contains(github.event.pull_request.labels.*.name, 'run_fdb')
     concurrency:
       group: fdb-drools_${{ matrix.os }}_${{ matrix.java-version }}_${{ matrix.maven-version }}_${{ github.head_ref }}
       cancel-in-progress: true

.github/workflows/pr-downstream.yml

@@ -33,6 +33,7 @@ on:
 
 jobs:
   kogito-downstream-build:
+    if: false
     concurrency:
       group: pr-${{ matrix.job_name }}_${{ matrix.os }}_${{ matrix.java-version }}_${{ matrix.maven-version }}_${{ github.head_ref }}
       cancel-in-progress: true

.github/workflows/pr-drools-ansible.yml

@@ -33,6 +33,7 @@ on:
 
 jobs:
   drools-ansible:
+    if: false
     concurrency:
       group: pr-drools_ansible_${{ matrix.os }}_${{ matrix.java-version }}_${{ matrix.maven-version }}_${{ github.head_ref }}
       cancel-in-progress: true

.github/workflows/pr-drools-docs.yml

@@ -27,6 +27,7 @@ on:
 
 jobs:
   drools-build:
+    if: false
     concurrency:
       group: pr-drools_docs_${{ matrix.os }}_${{ matrix.java-version }}_${{ matrix.maven-version }}_${{ github.head_ref }}
       cancel-in-progress: true

.github/workflows/pr-drools.yml

@@ -39,7 +39,7 @@ jobs:
     timeout-minutes: 120
     strategy:
       matrix:
-        os: [ubuntu-latest, windows-latest]
+        os: [ubuntu-latest]
         java-version: [17]
         maven-version: ['3.9.6']
       fail-fast: false
@@ -52,23 +52,22 @@ jobs:
       - name: Support long paths
         if: ${{ matrix.os == 'windows-latest' }}
         uses: apache/incubator-kie-kogito-pipelines/.ci/actions/long-paths@main
+      - uses: actions/checkout@v3
       - name: Java and Maven Setup
         uses: apache/incubator-kie-kogito-pipelines/.ci/actions/maven@main
         with:
           java-version: ${{ matrix.java-version }}
           maven-version: ${{ matrix.maven-version }}
           cache-key-prefix: ${{ runner.os }}-${{ matrix.java-version }}-maven${{ matrix.maven-version }}
-      - name: Build Chain
-        uses: apache/incubator-kie-kogito-pipelines/.ci/actions/build-chain@main
-        env:
-          BUILD_MVN_OPTS_CURRENT: '-Dfull -Dreproducible'
-          MAVEN_OPTS: "-Dfile.encoding=UTF-8"
-        with:
-          definition-file: https://raw.githubusercontent.com/${GROUP:apache}/incubator-kie-kogito-pipelines/${BRANCH:main}/.ci/pull-request-config.yaml
-          annotations-prefix: ${{ runner.os }}-${{ matrix.java-version }}/${{ matrix.maven-version }}
-          github-token: "${{ secrets.GITHUB_TOKEN }}"
-      - name: Surefire Report
-        uses: apache/incubator-kie-kogito-pipelines/.ci/actions/surefire-report@main
-        if: ${{ always() }}
-        with:
-          report_paths: '**/*-reports/TEST-*.xml'
+          allow-snapshots: true
+      - name: Build drools-core
+        run: mvn -B clean install -Dquickly --file drools-core/pom.xml
+#      - name: Build drools-compiler
+#        run: mvn -B clean install -Dquickly --file drools-compiler/pom.xml
+      - name:  Run loop Linux
+        if: ${{ matrix.os == 'ubuntu-latest' }}
+        run: |
+          for i in {1..10}; do
+            echo "Iteration $i"
+            mvn -B clean test --file drools-test-coverage/test-compiler-integration/pom.xml -Dtest=ConcurrentBasesParallelTest,org.drools.compiler.integrationtests.TimerAndCalendarFireUntilHaltTest
+          done

.github/workflows/pr-jenkins.yml

@@ -28,6 +28,7 @@ on:
 
 jobs:
   dsl-tests:
+    if: false
     concurrency:
       group: ${{ github.repository.name }}_dsl_tests-${{ github.head_ref }}
       cancel-in-progress: true

drools-core/src/main/java/org/drools/core/phreak/PhreakTimerNode.java

@@ -279,12 +279,16 @@ private void scheduleTimer(TimerNode timerNode,
             return;
         }
 
+        log.info("scheduleTimer: trigger.hasNextFireTime() = " + trigger.hasNextFireTime().getTime() + ", timestamp = " + timestamp);
+
         if ( trigger.hasNextFireTime().getTime() <= timestamp ) {
             // first execution is straight away, so void Scheduling
             if ( log.isTraceEnabled() ) {
                 log.trace( "Timer Fire Now {}", leftTuple );
             }
 
+            log.info("  ok, this one fires now");
+
             TupleImpl childLeftTuple = doPropagateChildLeftTuple(sink, trgLeftTuples, stagedLeftTuples, leftTuple );
             if (childLeftTuple.getStagedType() != LeftTuple.NONE) {
                 // Flag the newly created childLeftTuple to avoid a reevaluation in case it gets
@@ -305,6 +309,8 @@ private void scheduleTimer(TimerNode timerNode,
             TimerNodeJob job = new TimerNodeJob();
             TimerNodeJobContext jobCtx = new TimerNodeJobContext( timerNode.getId(), trigger, leftTuple, tm, sink, smem.getPathMemories(), reteEvaluator );
 
+            log.info("  then, schedule the next one");
+
             DefaultJobHandle jobHandle = (DefaultJobHandle) timerService.scheduleJob( job, jobCtx, trigger );
             leftTuple.setContextObject( jobHandle );
 

drools-core/src/main/java/org/drools/core/time/impl/PseudoClockScheduler.java

@@ -102,6 +102,7 @@ public JobHandle scheduleJob(Job job, JobContext ctx, Trigger trigger) {
         TimerJobInstance jobInstance = jobFactoryManager.createTimerJobInstance( job, ctx, trigger, jobHandle, this );
         jobHandle.setTimerJobInstance( jobInstance );
         internalSchedule( jobInstance );
+        logger.info("  scheduleJob : jobHandleId = " + jobHandle.getId() + ", fireTime = " + trigger.hasNextFireTime().getTime() );
         return jobHandle;
     }
 
@@ -150,6 +151,9 @@ private synchronized long runCallBacksAndIncreaseTimer( long increase ) {
         TimerJobInstance item = peek();
         long fireTime;
         while (item != null && item.getTrigger().hasNextFireTime() != null && (fireTime = item.getTrigger().hasNextFireTime().getTime()) <= endTime) {
+
+            logger.info("  runCallBacksAndIncreaseTimer : jobHandleId = " + item.getJobHandle().getId() + ", fireTime = " + item.getTrigger().hasNextFireTime().getTime() );
+
             // remove the head
             queue.poll();
 

drools-test-coverage/test-compiler-integration/src/test/java/org/drools/compiler/integrationtests/TimerAndCalendarFireUntilHaltTest.java

@@ -41,17 +41,21 @@
 import org.kie.api.runtime.KieSession;
 import org.kie.api.runtime.KieSessionConfiguration;
 import org.kie.api.runtime.rule.FactHandle;
+import org.slf4j.Logger;
 
 import static org.awaitility.Awaitility.await;
 
 @RunWith(Parameterized.class)
 public class TimerAndCalendarFireUntilHaltTest {
 
+    private static final Logger LOG = org.slf4j.LoggerFactory.getLogger(TimerAndCalendarFireUntilHaltTest.class);
+
     private final class RecordingRulesListener extends  DefaultAgendaEventListener {
         private Map<String, Integer> firedRules = new HashMap<>();
 
 
         public int timesRulesHasFired(String ruleName) {
+            LOG.info("    firedRules.get(ruleName) = " + firedRules.get(ruleName));
             if (firedRules.containsKey(ruleName)) {
                 return firedRules.get(ruleName).intValue();
             }
@@ -61,12 +65,15 @@ public int timesRulesHasFired(String ruleName) {
 
         @Override
         public void afterMatchFired(AfterMatchFiredEvent event) {
+            LOG.info("    afterMatchFired! : event.getMatch = " + Integer.toHexString(System.identityHashCode(event.getMatch())));
+            LOG.info("                     : event.getFH = " + event.getMatch().getFactHandles());
             String ruleName = event.getMatch().getRule().getName();
             if (!firedRules.containsKey(ruleName)) {
                 firedRules.put(ruleName, Integer.valueOf(0));
             } 
 
             firedRules.put(ruleName, firedRules.get(ruleName).intValue()+1);
+            LOG.info("    afterMatchFired! : firedRules.get(ruleName) = " + firedRules.get(ruleName));
         }
     }
 
@@ -97,6 +104,8 @@ public void after() throws Exception {
 
     @Test(timeout = 10000)
     public void testTimerRuleFires() throws Exception {
+        LOG.info("### testTimerRuleFires");
+        long start = System.currentTimeMillis();
         final String drl = "// fire once, for a String, create an Integer\n" +
                            "rule TimerRule\n" +
                            "timer(int:0 1000)\n" +
@@ -109,13 +118,20 @@ public void testTimerRuleFires() throws Exception {
         startEngine();
 
         activateRule();
-        advanceTimerOneSecond();
-
         await().until(ruleHasFired("TimerRule", 1));
+        advanceTimerOneSecond();
+
+        LOG.info("  -- before await : elapsed " + (System.currentTimeMillis() - start) + "ms");
+        await().until(ruleHasFired("TimerRule", 2));
+        LOG.info("  -- end : elapsed " + (System.currentTimeMillis() - start) + "ms");
+
+        stopEngine();
     }
 
     @Test(timeout = 10000)
     public void testTimerRuleHaltStopsFiring() throws Exception {
+        LOG.info("### testTimerRuleHaltStopsFiring");
+        long start = System.currentTimeMillis();
         final String drl = "// fire once, for a String, create an Integer\n" +
                            "rule TimerRule\n" +
                            "timer(int:0 1000)\n" +
@@ -127,17 +143,24 @@ public void testTimerRuleHaltStopsFiring() throws Exception {
         setupKSessionFor(drl);
         startEngine();
         activateRule();
-        advanceTimerOneSecond();
         await().until(ruleHasFired("TimerRule", 1));
+        advanceTimerOneSecond();
+        LOG.info("  -- before await : elapsed " + (System.currentTimeMillis() - start) + "ms");
+        await().until(ruleHasFired("TimerRule", 2));
 
         stopEngine();
 
         advanceTimerOneSecond();
-        await().during(Duration.ofSeconds(1)).atMost(Duration.ofSeconds(2)).until(ruleHasFired("TimerRule", 1));
+
+        LOG.info("  -- before 2nd await : elapsed " + (System.currentTimeMillis() - start) + "ms");
+        await().during(Duration.ofSeconds(1)).atMost(Duration.ofSeconds(2)).until(ruleHasFired("TimerRule", 2));
+        LOG.info("  -- end : elapsed " + (System.currentTimeMillis() - start) + "ms");
     }
 
     @Test(timeout = 10000)
     public void testTimerRuleRestartsAfterStop() throws Exception {
+        LOG.info("### testTimerRuleRestartsAfterStop");
+        long start = System.currentTimeMillis();
         final String drl = "// fire once, for a String, create an Integer\n" +
                            "rule TimerRule\n" +
                            "timer(int:0 1000)\n" +
@@ -149,18 +172,27 @@ public void testTimerRuleRestartsAfterStop() throws Exception {
         setupKSessionFor(drl);
         startEngine();
         activateRule();
-        advanceTimerOneSecond();
         await().until(ruleHasFired("TimerRule", 1));
+        advanceTimerOneSecond();
+        LOG.info("  -- before await : elapsed " + (System.currentTimeMillis() - start) + "ms");
+        await().until(ruleHasFired("TimerRule", 2));
 
         stopEngine();
         startEngine();
 
         advanceTimerOneSecond();
-        await().during(Duration.ofSeconds(1)).atMost(Duration.ofSeconds(2)).until(ruleHasFired("TimerRule", 2));
+
+        LOG.info("  -- before 2nd await : elapsed " + (System.currentTimeMillis() - start) + "ms");
+        await().during(Duration.ofSeconds(1)).atMost(Duration.ofSeconds(2)).until(ruleHasFired("TimerRule", 3));
+        LOG.info("  -- end : elapsed " + (System.currentTimeMillis() - start) + "ms");
+
+        stopEngine();
     }
 
     @Test(timeout = 10000)
     public void testTimerRuleDoesRestartsIfNoLongerHolds() throws Exception {
+        LOG.info("### testTimerRuleDoesRestartsIfNoLongerHolds");
+        long start = System.currentTimeMillis();
         final String drl = "// fire once, for a String, create an Integer\n" +
                            "rule TimerRule\n" +
                            "timer(int:0 1000)\n" +
@@ -172,27 +204,36 @@ public void testTimerRuleDoesRestartsIfNoLongerHolds() throws Exception {
         setupKSessionFor(drl);
         startEngine();
         activateRule();
-        advanceTimerOneSecond();
-
         await().until(ruleHasFired("TimerRule", 1));
+        advanceTimerOneSecond();
+
+        LOG.info("  -- before await : elapsed " + (System.currentTimeMillis() - start) + "ms");
+        await().until(ruleHasFired("TimerRule", 2));
 
         stopEngine();
         disactivateRule();
         startEngine();
 
         advanceTimerOneSecond();
 
-        await().during(Duration.ofSeconds(1)).atMost(Duration.ofSeconds(2)).until(ruleHasFired("TimerRule", 1));
+        LOG.info("  -- before 2nd await : elapsed " + (System.currentTimeMillis() - start) + "ms");
+        await().during(Duration.ofSeconds(1)).atMost(Duration.ofSeconds(2)).until(ruleHasFired("TimerRule", 2));
+        LOG.info("  -- end : elapsed " + (System.currentTimeMillis() - start) + "ms");
+
+        stopEngine();
     }
 
 
     private void setupKSessionFor(final String drl) {
+        LOG.info("  ** exec-model : " + kieBaseTestConfiguration.isExecutableModel());
+        long start = System.currentTimeMillis();
         kbase = KieBaseUtil.getKieBaseFromKieModuleFromDrl("timer-and-calendar-test", kieBaseTestConfiguration, drl);
         KieSessionConfiguration kieSessionConfiguration = KieSessionTestConfiguration.STATEFUL_PSEUDO.getKieSessionConfiguration();
         ksession = kbase.newKieSession(kieSessionConfiguration, null);      
         listener = new RecordingRulesListener();
         ksession.addEventListener(listener);
         timeService = ksession.getSessionClock();
+        LOG.info("  setupKSessionFor : " + (System.currentTimeMillis() - start) + "ms");
     }
 
     private void startEngine() throws InterruptedException {
@@ -218,10 +259,12 @@ private Callable<Boolean> ruleHasFired(String ruleName, int times) {
     }
 
     private void advanceTimerOneSecond() {
+        LOG.info("  -- advanceTimerOneSecond");
         timeService.advanceTime(1, TimeUnit.SECONDS);
     }
 
     private void activateRule() {
+        LOG.info("  -- insert trigger");
         triggerHandle = ksession.insert("trigger");
     }
 

drools-test-coverage/test-compiler-integration/src/test/resources/logback-test.xml

@@ -35,6 +35,9 @@
 <!--    <logger name="org.drools.modelcompiler.builder" level="debug"/>-->
 <!--    <logger name="org.drools.ancompiler" level="debug"/>-->
 
+    <logger name="org.drools.compiler.integrationtests" level="info"/>
+    <logger name="org.drools.core" level="info"/>
+
     <root level="warn">
         <appender-ref ref="consoleAppender" />
     </root>

pom.xml

@@ -198,32 +198,32 @@
     <module>drools-beliefs</module>
     <module>drools-serialization-protobuf</module>
     <module>drools-traits</module>
-    <module>drools-verifier</module>
+<!--    <module>drools-verifier</module>-->
     <module>drools-persistence</module>
     <module>drools-templates</module>
     <module>drools-decisiontables</module>
-    <module>drools-examples</module>
+<!--    <module>drools-examples</module>-->
     <module>kie-ci</module>
     <module>drools-model</module>
-    <module>drools-examples-api</module>
+<!--    <module>drools-examples-api</module>-->
     <module>drools-test-coverage</module>
-    <module>drools-scenario-simulation</module>
-    <module>drools-metric</module>
-    <module>drools-alphanetwork-compiler</module>
-    <module>drools-engine</module>
-    <module>drools-engine-classic</module>
-    <module>drools-impact-analysis</module>
-    <module>drools-retediagram</module>
-    <module>drools-fastutil</module>
-    <module>efesto</module>
-    <module>kie-drl</module>
-    <module>kie-dmn</module>
-    <module>kie-pmml-trusty</module>
-    <module>kie-maven-plugin</module>
-    <module>kie-archetypes</module>
-    <module>drools-quarkus-extension</module>
-    <module>drools-reliability</module>
-    <module>drools-drlonyaml-parent</module>
+<!--    <module>drools-scenario-simulation</module>-->
+<!--    <module>drools-metric</module>-->
+<!--    <module>drools-alphanetwork-compiler</module>-->
+<!--    <module>drools-engine</module>-->
+<!--    <module>drools-engine-classic</module>-->
+<!--    <module>drools-impact-analysis</module>-->
+<!--    <module>drools-retediagram</module>-->
+<!--    <module>drools-fastutil</module>-->
+<!--    <module>efesto</module>-->
+<!--    <module>kie-drl</module>-->
+<!--    <module>kie-dmn</module>-->
+<!--    <module>kie-pmml-trusty</module>-->
+<!--    <module>kie-maven-plugin</module>-->
+<!--    <module>kie-archetypes</module>-->
+<!--    <module>drools-quarkus-extension</module>-->
+<!--    <module>drools-reliability</module>-->
+<!--    <module>drools-drlonyaml-parent</module>-->
   </modules>
 
   <profiles>