From 2ceb4e6947b424b3d006d453f7fbd962ff4b7072 Mon Sep 17 00:00:00 2001 From: Toshiya Kobayashi Date: Fri, 20 Sep 2024 12:22:39 +0900 Subject: [PATCH 1/6] debug log --- .../TimerAndCalendarFireUntilHaltTest.java | 28 +++++++++++++++++-- 1 file changed, 26 insertions(+), 2 deletions(-) diff --git a/drools-test-coverage/test-compiler-integration/src/test/java/org/drools/compiler/integrationtests/TimerAndCalendarFireUntilHaltTest.java b/drools-test-coverage/test-compiler-integration/src/test/java/org/drools/compiler/integrationtests/TimerAndCalendarFireUntilHaltTest.java index c36fac63bc9..070f39e2cfb 100644 --- a/drools-test-coverage/test-compiler-integration/src/test/java/org/drools/compiler/integrationtests/TimerAndCalendarFireUntilHaltTest.java +++ b/drools-test-coverage/test-compiler-integration/src/test/java/org/drools/compiler/integrationtests/TimerAndCalendarFireUntilHaltTest.java @@ -97,6 +97,8 @@ public void after() throws Exception { @Test(timeout = 10000) public void testTimerRuleFires() throws Exception { + System.out.println("### 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" + @@ -110,12 +112,16 @@ public void testTimerRuleFires() throws Exception { activateRule(); advanceTimerOneSecond(); - + + System.out.println(" -- before await : elapsed " + (System.currentTimeMillis() - start) + "ms"); await().until(ruleHasFired("TimerRule", 1)); + System.out.println(" -- end : elapsed " + (System.currentTimeMillis() - start) + "ms"); } @Test(timeout = 10000) public void testTimerRuleHaltStopsFiring() throws Exception { + System.out.println("### 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" + @@ -128,16 +134,22 @@ public void testTimerRuleHaltStopsFiring() throws Exception { startEngine(); activateRule(); advanceTimerOneSecond(); + System.out.println(" -- before await : elapsed " + (System.currentTimeMillis() - start) + "ms"); await().until(ruleHasFired("TimerRule", 1)); stopEngine(); advanceTimerOneSecond(); + + System.out.println(" -- before 2nd await : elapsed " + (System.currentTimeMillis() - start) + "ms"); await().during(Duration.ofSeconds(1)).atMost(Duration.ofSeconds(2)).until(ruleHasFired("TimerRule", 1)); + System.out.println(" -- end : elapsed " + (System.currentTimeMillis() - start) + "ms"); } @Test(timeout = 10000) public void testTimerRuleRestartsAfterStop() throws Exception { + System.out.println("### 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" + @@ -150,17 +162,23 @@ public void testTimerRuleRestartsAfterStop() throws Exception { startEngine(); activateRule(); advanceTimerOneSecond(); + System.out.println(" -- before await : elapsed " + (System.currentTimeMillis() - start) + "ms"); await().until(ruleHasFired("TimerRule", 1)); stopEngine(); startEngine(); advanceTimerOneSecond(); + + System.out.println(" -- before 2nd await : elapsed " + (System.currentTimeMillis() - start) + "ms"); await().during(Duration.ofSeconds(1)).atMost(Duration.ofSeconds(2)).until(ruleHasFired("TimerRule", 2)); + System.out.println(" -- end : elapsed " + (System.currentTimeMillis() - start) + "ms"); } @Test(timeout = 10000) public void testTimerRuleDoesRestartsIfNoLongerHolds() throws Exception { + System.out.println("### 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" + @@ -173,7 +191,8 @@ public void testTimerRuleDoesRestartsIfNoLongerHolds() throws Exception { startEngine(); activateRule(); advanceTimerOneSecond(); - + + System.out.println(" -- before await : elapsed " + (System.currentTimeMillis() - start) + "ms"); await().until(ruleHasFired("TimerRule", 1)); stopEngine(); @@ -182,17 +201,22 @@ public void testTimerRuleDoesRestartsIfNoLongerHolds() throws Exception { advanceTimerOneSecond(); + System.out.println(" -- before 2nd await : elapsed " + (System.currentTimeMillis() - start) + "ms"); await().during(Duration.ofSeconds(1)).atMost(Duration.ofSeconds(2)).until(ruleHasFired("TimerRule", 1)); + System.out.println(" -- end : elapsed " + (System.currentTimeMillis() - start) + "ms"); } private void setupKSessionFor(final String drl) { + System.out.println(" ** 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(); + System.out.println(" setupKSessionFor : " + (System.currentTimeMillis() - start) + "ms"); } private void startEngine() throws InterruptedException { From 58e8354695cf32ff85a6730ec6094d223979725c Mon Sep 17 00:00:00 2001 From: Toshiya Kobayashi Date: Fri, 20 Sep 2024 14:20:09 +0900 Subject: [PATCH 2/6] quick test --- .github/workflows/pr-backporting.yml | 3 +- .github/workflows/pr-downstream-full.yml | 3 +- .github/workflows/pr-downstream.yml | 1 + .github/workflows/pr-drools-ansible.yml | 1 + .github/workflows/pr-drools-docs.yml | 1 + .github/workflows/pr-drools.yml | 29 +++++++------- .github/workflows/pr-jenkins.yml | 1 + .../TimerAndCalendarFireUntilHaltTest.java | 1 + pom.xml | 40 +++++++++---------- 9 files changed, 43 insertions(+), 37 deletions(-) diff --git a/.github/workflows/pr-backporting.yml b/.github/workflows/pr-backporting.yml index c9dc69c0eda..f6ea73f1f1d 100644 --- a/.github/workflows/pr-backporting.yml +++ b/.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 }} diff --git a/.github/workflows/pr-downstream-full.yml b/.github/workflows/pr-downstream-full.yml index 4dafc9f7ea5..fb3cd9c0af9 100644 --- a/.github/workflows/pr-downstream-full.yml +++ b/.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 diff --git a/.github/workflows/pr-downstream.yml b/.github/workflows/pr-downstream.yml index 575f4ec6dfe..fbccd515f42 100644 --- a/.github/workflows/pr-downstream.yml +++ b/.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 diff --git a/.github/workflows/pr-drools-ansible.yml b/.github/workflows/pr-drools-ansible.yml index 82181f67532..234a68700b5 100644 --- a/.github/workflows/pr-drools-ansible.yml +++ b/.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 diff --git a/.github/workflows/pr-drools-docs.yml b/.github/workflows/pr-drools-docs.yml index d33c9cdc022..8a21a376f6b 100644 --- a/.github/workflows/pr-drools-docs.yml +++ b/.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 diff --git a/.github/workflows/pr-drools.yml b/.github/workflows/pr-drools.yml index d1f5f77b4f7..a58c471dfe9 100644 --- a/.github/workflows/pr-drools.yml +++ b/.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 diff --git a/.github/workflows/pr-jenkins.yml b/.github/workflows/pr-jenkins.yml index 1566cdc1188..e6437d3c29b 100644 --- a/.github/workflows/pr-jenkins.yml +++ b/.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 diff --git a/drools-test-coverage/test-compiler-integration/src/test/java/org/drools/compiler/integrationtests/TimerAndCalendarFireUntilHaltTest.java b/drools-test-coverage/test-compiler-integration/src/test/java/org/drools/compiler/integrationtests/TimerAndCalendarFireUntilHaltTest.java index 070f39e2cfb..c8381657352 100644 --- a/drools-test-coverage/test-compiler-integration/src/test/java/org/drools/compiler/integrationtests/TimerAndCalendarFireUntilHaltTest.java +++ b/drools-test-coverage/test-compiler-integration/src/test/java/org/drools/compiler/integrationtests/TimerAndCalendarFireUntilHaltTest.java @@ -52,6 +52,7 @@ private final class RecordingRulesListener extends DefaultAgendaEventListener { public int timesRulesHasFired(String ruleName) { + System.out.println(" firedRules.get(ruleName) = " + firedRules.get(ruleName)); if (firedRules.containsKey(ruleName)) { return firedRules.get(ruleName).intValue(); } diff --git a/pom.xml b/pom.xml index c23c483f355..22b7007e81d 100644 --- a/pom.xml +++ b/pom.xml @@ -198,32 +198,32 @@ drools-beliefs drools-serialization-protobuf drools-traits - drools-verifier + drools-persistence drools-templates drools-decisiontables - drools-examples + kie-ci drools-model - drools-examples-api + drools-test-coverage - drools-scenario-simulation - drools-metric - drools-alphanetwork-compiler - drools-engine - drools-engine-classic - drools-impact-analysis - drools-retediagram - drools-fastutil - efesto - kie-drl - kie-dmn - kie-pmml-trusty - kie-maven-plugin - kie-archetypes - drools-quarkus-extension - drools-reliability - drools-drlonyaml-parent + + + + + + + + + + + + + + + + + From 6751ddb2a21af8962a85e638e2f84cc044ac45a0 Mon Sep 17 00:00:00 2001 From: Toshiya Kobayashi Date: Fri, 20 Sep 2024 15:05:35 +0900 Subject: [PATCH 3/6] log afterMatchFired --- .../TimerAndCalendarFireUntilHaltTest.java | 41 +++++++++++-------- .../src/test/resources/logback-test.xml | 2 + 2 files changed, 25 insertions(+), 18 deletions(-) diff --git a/drools-test-coverage/test-compiler-integration/src/test/java/org/drools/compiler/integrationtests/TimerAndCalendarFireUntilHaltTest.java b/drools-test-coverage/test-compiler-integration/src/test/java/org/drools/compiler/integrationtests/TimerAndCalendarFireUntilHaltTest.java index c8381657352..d70832639a0 100644 --- a/drools-test-coverage/test-compiler-integration/src/test/java/org/drools/compiler/integrationtests/TimerAndCalendarFireUntilHaltTest.java +++ b/drools-test-coverage/test-compiler-integration/src/test/java/org/drools/compiler/integrationtests/TimerAndCalendarFireUntilHaltTest.java @@ -41,18 +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 firedRules = new HashMap<>(); public int timesRulesHasFired(String ruleName) { - System.out.println(" firedRules.get(ruleName) = " + firedRules.get(ruleName)); + LOG.info(" firedRules.get(ruleName) = " + firedRules.get(ruleName)); if (firedRules.containsKey(ruleName)) { return firedRules.get(ruleName).intValue(); } @@ -62,12 +65,14 @@ public int timesRulesHasFired(String ruleName) { @Override public void afterMatchFired(AfterMatchFiredEvent event) { + LOG.info(" afterMatchFired!"); 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)); } } @@ -98,7 +103,7 @@ public void after() throws Exception { @Test(timeout = 10000) public void testTimerRuleFires() throws Exception { - System.out.println("### testTimerRuleFires"); + LOG.info("### testTimerRuleFires"); long start = System.currentTimeMillis(); final String drl = "// fire once, for a String, create an Integer\n" + "rule TimerRule\n" + @@ -114,14 +119,14 @@ public void testTimerRuleFires() throws Exception { activateRule(); advanceTimerOneSecond(); - System.out.println(" -- before await : elapsed " + (System.currentTimeMillis() - start) + "ms"); + LOG.info(" -- before await : elapsed " + (System.currentTimeMillis() - start) + "ms"); await().until(ruleHasFired("TimerRule", 1)); - System.out.println(" -- end : elapsed " + (System.currentTimeMillis() - start) + "ms"); + LOG.info(" -- end : elapsed " + (System.currentTimeMillis() - start) + "ms"); } @Test(timeout = 10000) public void testTimerRuleHaltStopsFiring() throws Exception { - System.out.println("### testTimerRuleHaltStopsFiring"); + LOG.info("### testTimerRuleHaltStopsFiring"); long start = System.currentTimeMillis(); final String drl = "// fire once, for a String, create an Integer\n" + "rule TimerRule\n" + @@ -135,21 +140,21 @@ public void testTimerRuleHaltStopsFiring() throws Exception { startEngine(); activateRule(); advanceTimerOneSecond(); - System.out.println(" -- before await : elapsed " + (System.currentTimeMillis() - start) + "ms"); + LOG.info(" -- before await : elapsed " + (System.currentTimeMillis() - start) + "ms"); await().until(ruleHasFired("TimerRule", 1)); stopEngine(); advanceTimerOneSecond(); - System.out.println(" -- before 2nd await : elapsed " + (System.currentTimeMillis() - start) + "ms"); + LOG.info(" -- before 2nd await : elapsed " + (System.currentTimeMillis() - start) + "ms"); await().during(Duration.ofSeconds(1)).atMost(Duration.ofSeconds(2)).until(ruleHasFired("TimerRule", 1)); - System.out.println(" -- end : elapsed " + (System.currentTimeMillis() - start) + "ms"); + LOG.info(" -- end : elapsed " + (System.currentTimeMillis() - start) + "ms"); } @Test(timeout = 10000) public void testTimerRuleRestartsAfterStop() throws Exception { - System.out.println("### testTimerRuleRestartsAfterStop"); + LOG.info("### testTimerRuleRestartsAfterStop"); long start = System.currentTimeMillis(); final String drl = "// fire once, for a String, create an Integer\n" + "rule TimerRule\n" + @@ -163,7 +168,7 @@ public void testTimerRuleRestartsAfterStop() throws Exception { startEngine(); activateRule(); advanceTimerOneSecond(); - System.out.println(" -- before await : elapsed " + (System.currentTimeMillis() - start) + "ms"); + LOG.info(" -- before await : elapsed " + (System.currentTimeMillis() - start) + "ms"); await().until(ruleHasFired("TimerRule", 1)); stopEngine(); @@ -171,14 +176,14 @@ public void testTimerRuleRestartsAfterStop() throws Exception { advanceTimerOneSecond(); - System.out.println(" -- before 2nd await : elapsed " + (System.currentTimeMillis() - start) + "ms"); + LOG.info(" -- before 2nd await : elapsed " + (System.currentTimeMillis() - start) + "ms"); await().during(Duration.ofSeconds(1)).atMost(Duration.ofSeconds(2)).until(ruleHasFired("TimerRule", 2)); - System.out.println(" -- end : elapsed " + (System.currentTimeMillis() - start) + "ms"); + LOG.info(" -- end : elapsed " + (System.currentTimeMillis() - start) + "ms"); } @Test(timeout = 10000) public void testTimerRuleDoesRestartsIfNoLongerHolds() throws Exception { - System.out.println("### testTimerRuleDoesRestartsIfNoLongerHolds"); + LOG.info("### testTimerRuleDoesRestartsIfNoLongerHolds"); long start = System.currentTimeMillis(); final String drl = "// fire once, for a String, create an Integer\n" + "rule TimerRule\n" + @@ -193,7 +198,7 @@ public void testTimerRuleDoesRestartsIfNoLongerHolds() throws Exception { activateRule(); advanceTimerOneSecond(); - System.out.println(" -- before await : elapsed " + (System.currentTimeMillis() - start) + "ms"); + LOG.info(" -- before await : elapsed " + (System.currentTimeMillis() - start) + "ms"); await().until(ruleHasFired("TimerRule", 1)); stopEngine(); @@ -202,14 +207,14 @@ public void testTimerRuleDoesRestartsIfNoLongerHolds() throws Exception { advanceTimerOneSecond(); - System.out.println(" -- before 2nd await : elapsed " + (System.currentTimeMillis() - start) + "ms"); + LOG.info(" -- before 2nd await : elapsed " + (System.currentTimeMillis() - start) + "ms"); await().during(Duration.ofSeconds(1)).atMost(Duration.ofSeconds(2)).until(ruleHasFired("TimerRule", 1)); - System.out.println(" -- end : elapsed " + (System.currentTimeMillis() - start) + "ms"); + LOG.info(" -- end : elapsed " + (System.currentTimeMillis() - start) + "ms"); } private void setupKSessionFor(final String drl) { - System.out.println(" ** exec-model : " + kieBaseTestConfiguration.isExecutableModel()); + 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(); @@ -217,7 +222,7 @@ private void setupKSessionFor(final String drl) { listener = new RecordingRulesListener(); ksession.addEventListener(listener); timeService = ksession.getSessionClock(); - System.out.println(" setupKSessionFor : " + (System.currentTimeMillis() - start) + "ms"); + LOG.info(" setupKSessionFor : " + (System.currentTimeMillis() - start) + "ms"); } private void startEngine() throws InterruptedException { diff --git a/drools-test-coverage/test-compiler-integration/src/test/resources/logback-test.xml b/drools-test-coverage/test-compiler-integration/src/test/resources/logback-test.xml index ce4cf145c90..b9013a7bbdd 100644 --- a/drools-test-coverage/test-compiler-integration/src/test/resources/logback-test.xml +++ b/drools-test-coverage/test-compiler-integration/src/test/resources/logback-test.xml @@ -35,6 +35,8 @@ + + From c9701610f1fea82a95b24ae6d576cb373538bef5 Mon Sep 17 00:00:00 2001 From: Toshiya Kobayashi Date: Fri, 20 Sep 2024 15:27:01 +0900 Subject: [PATCH 4/6] log match and FH --- .../integrationtests/TimerAndCalendarFireUntilHaltTest.java | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/drools-test-coverage/test-compiler-integration/src/test/java/org/drools/compiler/integrationtests/TimerAndCalendarFireUntilHaltTest.java b/drools-test-coverage/test-compiler-integration/src/test/java/org/drools/compiler/integrationtests/TimerAndCalendarFireUntilHaltTest.java index d70832639a0..37494cbe71a 100644 --- a/drools-test-coverage/test-compiler-integration/src/test/java/org/drools/compiler/integrationtests/TimerAndCalendarFireUntilHaltTest.java +++ b/drools-test-coverage/test-compiler-integration/src/test/java/org/drools/compiler/integrationtests/TimerAndCalendarFireUntilHaltTest.java @@ -65,7 +65,8 @@ public int timesRulesHasFired(String ruleName) { @Override public void afterMatchFired(AfterMatchFiredEvent event) { - LOG.info(" afterMatchFired!"); + 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)); From 7aca1fdce56b8ad554f9ba10700d330594a2bbbd Mon Sep 17 00:00:00 2001 From: Toshiya Kobayashi Date: Fri, 20 Sep 2024 16:19:01 +0900 Subject: [PATCH 5/6] more logging in drools-core --- .github/workflows/pr-drools.yml | 4 ++-- .../main/java/org/drools/core/phreak/PhreakTimerNode.java | 6 ++++++ .../org/drools/core/time/impl/PseudoClockScheduler.java | 4 ++++ .../integrationtests/TimerAndCalendarFireUntilHaltTest.java | 2 ++ .../src/test/resources/logback-test.xml | 1 + 5 files changed, 15 insertions(+), 2 deletions(-) diff --git a/.github/workflows/pr-drools.yml b/.github/workflows/pr-drools.yml index a58c471dfe9..86c52ca7bf7 100644 --- a/.github/workflows/pr-drools.yml +++ b/.github/workflows/pr-drools.yml @@ -60,8 +60,8 @@ jobs: maven-version: ${{ matrix.maven-version }} cache-key-prefix: ${{ runner.os }}-${{ matrix.java-version }}-maven${{ matrix.maven-version }} allow-snapshots: true -# - name: Build drools-core -# run: mvn -B clean install -Dquickly --file drools-core/pom.xml + - 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 diff --git a/drools-core/src/main/java/org/drools/core/phreak/PhreakTimerNode.java b/drools-core/src/main/java/org/drools/core/phreak/PhreakTimerNode.java index a895bfc6f64..49b48fcdd84 100644 --- a/drools-core/src/main/java/org/drools/core/phreak/PhreakTimerNode.java +++ b/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 ); diff --git a/drools-core/src/main/java/org/drools/core/time/impl/PseudoClockScheduler.java b/drools-core/src/main/java/org/drools/core/time/impl/PseudoClockScheduler.java index 5be7a8f171f..a06aefc550e 100644 --- a/drools-core/src/main/java/org/drools/core/time/impl/PseudoClockScheduler.java +++ b/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(); diff --git a/drools-test-coverage/test-compiler-integration/src/test/java/org/drools/compiler/integrationtests/TimerAndCalendarFireUntilHaltTest.java b/drools-test-coverage/test-compiler-integration/src/test/java/org/drools/compiler/integrationtests/TimerAndCalendarFireUntilHaltTest.java index 37494cbe71a..832d54ae892 100644 --- a/drools-test-coverage/test-compiler-integration/src/test/java/org/drools/compiler/integrationtests/TimerAndCalendarFireUntilHaltTest.java +++ b/drools-test-coverage/test-compiler-integration/src/test/java/org/drools/compiler/integrationtests/TimerAndCalendarFireUntilHaltTest.java @@ -249,10 +249,12 @@ private Callable 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"); } diff --git a/drools-test-coverage/test-compiler-integration/src/test/resources/logback-test.xml b/drools-test-coverage/test-compiler-integration/src/test/resources/logback-test.xml index b9013a7bbdd..494ff803987 100644 --- a/drools-test-coverage/test-compiler-integration/src/test/resources/logback-test.xml +++ b/drools-test-coverage/test-compiler-integration/src/test/resources/logback-test.xml @@ -36,6 +36,7 @@ + From 092668abfd75e5d35756d8cceb855e3378084cc3 Mon Sep 17 00:00:00 2001 From: Toshiya Kobayashi Date: Fri, 20 Sep 2024 17:23:03 +0900 Subject: [PATCH 6/6] change assertion. add stopEngine --- .../TimerAndCalendarFireUntilHaltTest.java | 24 +++++++++++++------ 1 file changed, 17 insertions(+), 7 deletions(-) diff --git a/drools-test-coverage/test-compiler-integration/src/test/java/org/drools/compiler/integrationtests/TimerAndCalendarFireUntilHaltTest.java b/drools-test-coverage/test-compiler-integration/src/test/java/org/drools/compiler/integrationtests/TimerAndCalendarFireUntilHaltTest.java index 832d54ae892..a7cb7b14fb3 100644 --- a/drools-test-coverage/test-compiler-integration/src/test/java/org/drools/compiler/integrationtests/TimerAndCalendarFireUntilHaltTest.java +++ b/drools-test-coverage/test-compiler-integration/src/test/java/org/drools/compiler/integrationtests/TimerAndCalendarFireUntilHaltTest.java @@ -118,11 +118,14 @@ public void testTimerRuleFires() throws Exception { startEngine(); activateRule(); + await().until(ruleHasFired("TimerRule", 1)); advanceTimerOneSecond(); LOG.info(" -- before await : elapsed " + (System.currentTimeMillis() - start) + "ms"); - await().until(ruleHasFired("TimerRule", 1)); + await().until(ruleHasFired("TimerRule", 2)); LOG.info(" -- end : elapsed " + (System.currentTimeMillis() - start) + "ms"); + + stopEngine(); } @Test(timeout = 10000) @@ -140,16 +143,17 @@ public void testTimerRuleHaltStopsFiring() throws Exception { setupKSessionFor(drl); startEngine(); activateRule(); + await().until(ruleHasFired("TimerRule", 1)); advanceTimerOneSecond(); LOG.info(" -- before await : elapsed " + (System.currentTimeMillis() - start) + "ms"); - await().until(ruleHasFired("TimerRule", 1)); + await().until(ruleHasFired("TimerRule", 2)); stopEngine(); advanceTimerOneSecond(); LOG.info(" -- before 2nd await : elapsed " + (System.currentTimeMillis() - start) + "ms"); - await().during(Duration.ofSeconds(1)).atMost(Duration.ofSeconds(2)).until(ruleHasFired("TimerRule", 1)); + await().during(Duration.ofSeconds(1)).atMost(Duration.ofSeconds(2)).until(ruleHasFired("TimerRule", 2)); LOG.info(" -- end : elapsed " + (System.currentTimeMillis() - start) + "ms"); } @@ -168,9 +172,10 @@ public void testTimerRuleRestartsAfterStop() throws Exception { setupKSessionFor(drl); startEngine(); activateRule(); + await().until(ruleHasFired("TimerRule", 1)); advanceTimerOneSecond(); LOG.info(" -- before await : elapsed " + (System.currentTimeMillis() - start) + "ms"); - await().until(ruleHasFired("TimerRule", 1)); + await().until(ruleHasFired("TimerRule", 2)); stopEngine(); startEngine(); @@ -178,8 +183,10 @@ public void testTimerRuleRestartsAfterStop() throws Exception { advanceTimerOneSecond(); LOG.info(" -- before 2nd await : elapsed " + (System.currentTimeMillis() - start) + "ms"); - await().during(Duration.ofSeconds(1)).atMost(Duration.ofSeconds(2)).until(ruleHasFired("TimerRule", 2)); + 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) @@ -197,10 +204,11 @@ public void testTimerRuleDoesRestartsIfNoLongerHolds() throws Exception { setupKSessionFor(drl); startEngine(); activateRule(); + await().until(ruleHasFired("TimerRule", 1)); advanceTimerOneSecond(); LOG.info(" -- before await : elapsed " + (System.currentTimeMillis() - start) + "ms"); - await().until(ruleHasFired("TimerRule", 1)); + await().until(ruleHasFired("TimerRule", 2)); stopEngine(); disactivateRule(); @@ -209,8 +217,10 @@ public void testTimerRuleDoesRestartsIfNoLongerHolds() throws Exception { advanceTimerOneSecond(); LOG.info(" -- before 2nd await : elapsed " + (System.currentTimeMillis() - start) + "ms"); - await().during(Duration.ofSeconds(1)).atMost(Duration.ofSeconds(2)).until(ruleHasFired("TimerRule", 1)); + await().during(Duration.ofSeconds(1)).atMost(Duration.ofSeconds(2)).until(ruleHasFired("TimerRule", 2)); LOG.info(" -- end : elapsed " + (System.currentTimeMillis() - start) + "ms"); + + stopEngine(); }