Fix system started DSL rules #3725

J-N-K · 2023-07-22T18:20:59Z

@lolodomo can you test if that resolves your issues? On my system it seems to work fine.

Signed-off-by: Jan N. Klug <[email protected]>

J-N-K · 2023-07-22T18:37:48Z

I don't have a good setup to test this (and no time), since I neither use file-based rules nor scripts. It should be tested that

rules/scripts can be added
rules/scripts can be modified, only show up once and execute the new code
rules/scripts can be removed

lolodomo · 2023-07-22T18:45:31Z

After a bundle update and a OH server restart; the warning has disappeared but now the rule is run twice, apparently the second just after the first:

20:39:59.891 [INFO ] [org.openhab.core.model.script.Rule   ] - Démarrage début
20:39:59.907 [INFO ] [org.openhab.core.model.script.Rule   ] - Démarrage fin
20:40:00.002 [INFO ] [org.openhab.core.model.script.Rule   ] - Démarrage début
20:40:00.034 [INFO ] [org.openhab.core.model.script.Rule   ] - Démarrage fin
20:40:00.064 [INFO ] [re.automation.internal.RuleEngineImpl] - Rule engine started.

Signed-off-by: Jan N. Klug <[email protected]>

J-N-K · 2023-07-22T19:01:27Z

I have no idea why that happens, maybe a check for the start-level is missing. Can you post a file that shows this behavior? In my tests the rues run exactly once. Unfortunately I can't work on that today.

kaikreuzer · 2023-07-22T21:54:03Z

Can you post a file that shows this behavior?

This file will actually do (adding some logging to it).

I get this result at startup:

23:51:13.363 [INFO ] [org.openhab.core.Activator          ] - Starting openHAB 4.0.0 (build Unknown Build No.)
23:51:16.033 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'demo.items'
23:51:16.368 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mapdb.persist'
23:51:16.549 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'demo.sitemap'
23:51:16.660 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'demo.things'
23:51:18.436 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'demo.rules'
23:51:23.795 [INFO ] [org.openhab.core.model.script.TEST  ] - Rule executed.
23:51:28.769 [INFO ] [org.openhab.core.model.script.TEST  ] - Rule executed.
23:51:28.772 [INFO ] [e.automation.internal.RuleEngineImpl] - Rule engine started.
23:51:28.773 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'DemoDateTime' changed from 2023-07-22T23:51:23.799362+0200 to 2023-07-22T23:51:28.771569+0200

So indeed the rule is executed twice and the first time happens quite a time before the rule engine is officially started.

lolodomo · 2023-07-22T22:27:54Z

I tried again with the last change in the PR but same result, that is rule run twice.

Additionally, fix nullable error and warning in Eclipse IDE Signed-off-by: Kai Kreuzer <[email protected]>

kaikreuzer · 2023-07-22T22:35:56Z

...ore.model.rule.runtime/src/org/openhab/core/model/rule/runtime/internal/DSLRuleProvider.java

        return s.lines().map(line -> (line.startsWith(indentation) ? line.substring(indentation.length()) : line))
                .collect(Collectors.joining("\n"));
    }

    private @Nullable Trigger mapTrigger(EventTrigger t) {
        if (t instanceof SystemOnStartupTrigger) {
            Configuration cfg = new Configuration();
-            cfg.put("startlevel", 20);
+            cfg.put("startlevel", 40);


This change fixes the issue for me. I have no idea, why I have ever set it to 20 in the first place.
According to the documentation at https://www.openhab.org/docs/configuration/rules-dsl.html#system-based-triggers, "startlevels less than 40 are not available as triggers". Setting it to 40 will only execute them once during startup.

kaikreuzer · 2023-07-22T22:36:34Z

@lolodomo I just pushed a commit that fixes the issue for me. Would you be able to test this as well, please?

lolodomo · 2023-07-22T22:40:23Z

@lolodomo I just pushed a commit that fixes the issue for me. Would you be able to test this as well, please?

I do it now...

kaikreuzer · 2023-07-22T22:43:59Z

Thanks for your nightshift.

lolodomo · 2023-07-22T22:51:12Z

Kai, it looks like the rule is run twice but now the second time occurs very late at startup when everything is loaded.

00:46:13.976 [INFO ] [org.openhab.core.model.script.Rule   ] - Démarrage début
00:46:14.005 [INFO ] [org.openhab.core.model.script.Rule   ] - Démarrage fin
00:46:14.036 [INFO ] [re.automation.internal.RuleEngineImpl] - Rule engine started.

...

00:47:34.478 [INFO ] [org.openhab.core.model.script.Rule   ] - Démarrage début
00:47:34.489 [INFO ] [org.openhab.core.model.script.Rule   ] - Démarrage fin

kaikreuzer · 2023-07-22T22:53:20Z

I assume your rule has a simple "System started" trigger and nothing else?

lolodomo · 2023-07-22T22:54:49Z

But I believe it was already happening in the past that this rule was run a second time very late at startup.
Maybe we are back to the previous behaviour.

Signed-off-by: Kai Kreuzer <[email protected]>

lolodomo · 2023-07-22T22:57:34Z

I assume your rule has a simple "System started" trigger and nothing else?

Yes

rule "Démarrage"
when
	System started
then
	logInfo("Rule","Démarrage début")
	lastDesarmTime = now.minusDays(1)
	lastMinimoteTime = now
	patternVoice = Pattern::compile("(donner|donne|passer en hors gel|passer en mode confort|passer en mode réduit) (le |la |les |l'|du )(.*) (du |de la |de l'|dans le |dans la |dans l')(.*)")
	logInfo("Rule","Démarrage fin")
end

lolodomo · 2023-07-22T23:02:10Z

I can try quickly with snapshot 3544 to confirm that the rule was already run a second time very late.

kaikreuzer · 2023-07-22T23:02:13Z

But I believe it was already happening in the past

Which is still very weird - I never had startup rules being triggered twice.
Is there maybe some mechanism on your system that touches these rules, so that they are reloaded for some reason?

kaikreuzer · 2023-07-22T23:04:42Z

I can try quickly with snapshot 3544 to confirm that the rule was already run a second time very late.

Yeah, would be great.

lolodomo · 2023-07-22T23:10:25Z

I can confirm that the behaviour with snapshot 3544 is the same as the current with this PR.
So there is probably an issue because this rule is run a second time very late but it is not new.

If your tests are positive, I believe we can go with that.

kaikreuzer

Ok, thanks for testing - then this at least is nothing newly introduced by this PR.
I hereby approved the changes done by @J-N-K and leave it to him to merge the PR if he approves my changes as well.

J-N-K

LGTM

J-N-K added the bug An unexpected problem or unintended behavior of the Core label Jul 22, 2023

J-N-K requested a review from a team as a code owner July 22, 2023 18:20

J-N-K added 3 commits July 22, 2023 20:35

Fix system started DSL rules

938e049

Signed-off-by: Jan N. Klug <[email protected]>

improvement

15659e5

Signed-off-by: Jan N. Klug <[email protected]>

fix

91dc7fc

Signed-off-by: Jan N. Klug <[email protected]>

J-N-K force-pushed the fix-dsl branch from 2577efe to 91dc7fc Compare July 22, 2023 18:35

J-N-K requested a review from lolodomo July 22, 2023 18:38

fix

8bfc3f6

Signed-off-by: Jan N. Klug <[email protected]>

Fix start level for "system started" triggers

0cfa107

Additionally, fix nullable error and warning in Eclipse IDE Signed-off-by: Kai Kreuzer <[email protected]>

kaikreuzer reviewed Jul 22, 2023

View reviewed changes

Fix test

68cd181

Signed-off-by: Kai Kreuzer <[email protected]>

kaikreuzer approved these changes Jul 22, 2023

View reviewed changes

J-N-K added this to the 4.0 milestone Jul 23, 2023

J-N-K commented Jul 23, 2023

View reviewed changes

J-N-K merged commit 546e342 into openhab:main Jul 23, 2023
2 checks passed

J-N-K deleted the fix-dsl branch July 23, 2023 08:21

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix system started DSL rules #3725

Fix system started DSL rules #3725

J-N-K commented Jul 22, 2023

J-N-K commented Jul 22, 2023 •

edited

Loading

lolodomo commented Jul 22, 2023

J-N-K commented Jul 22, 2023

kaikreuzer commented Jul 22, 2023

lolodomo commented Jul 22, 2023

kaikreuzer Jul 22, 2023

kaikreuzer commented Jul 22, 2023

lolodomo commented Jul 22, 2023

kaikreuzer commented Jul 22, 2023

lolodomo commented Jul 22, 2023

kaikreuzer commented Jul 22, 2023

lolodomo commented Jul 22, 2023

lolodomo commented Jul 22, 2023

lolodomo commented Jul 22, 2023

kaikreuzer commented Jul 22, 2023

kaikreuzer commented Jul 22, 2023

lolodomo commented Jul 22, 2023

kaikreuzer left a comment

J-N-K left a comment

Fix system started DSL rules #3725

Fix system started DSL rules #3725

Conversation

J-N-K commented Jul 22, 2023

J-N-K commented Jul 22, 2023 • edited Loading

lolodomo commented Jul 22, 2023

J-N-K commented Jul 22, 2023

kaikreuzer commented Jul 22, 2023

lolodomo commented Jul 22, 2023

kaikreuzer Jul 22, 2023

Choose a reason for hiding this comment

kaikreuzer commented Jul 22, 2023

lolodomo commented Jul 22, 2023

kaikreuzer commented Jul 22, 2023

lolodomo commented Jul 22, 2023

kaikreuzer commented Jul 22, 2023

lolodomo commented Jul 22, 2023

lolodomo commented Jul 22, 2023

lolodomo commented Jul 22, 2023

kaikreuzer commented Jul 22, 2023

kaikreuzer commented Jul 22, 2023

lolodomo commented Jul 22, 2023

kaikreuzer left a comment

Choose a reason for hiding this comment

J-N-K left a comment

Choose a reason for hiding this comment

J-N-K commented Jul 22, 2023 •

edited

Loading