Delays not working as expected

[jsimmo]

I seem to be having some issues with delays, so I set up a test as follows:

If the second rule is disabled, the first rule works as I expect - when motion is detected in the Hall, the Hall lamp switches on and then off again 10 seconds later.

With both rules enabled - when motion is detected in the Hall the Hall lamp switches on, but then if motion is detected in the Dining room, the Dining room lamp switches on, but the Hall lamp does not switch off after the 10 seconds , but after the 30 seconds when both lamps switch off at the same time.

Is this a bug, or just my understanding of how it should work?

[toggledbits]

You've screen shotted the rules without showing the delays. I can't tell what delay option you've chosen and how you've set it up.

[jsimmo]

Not sure I understand what you mean by delay option. Is there something else I should be setting?

[toggledbits]

OK. one aspect of the circumstances you describe could be a bug, and I will dig into that.

But the way you are approaching solving your problem is, I'm guessing, not really what you want. I think what you really want is that the light remain on as long as the sensor continues to indicate there is motion in the room and then turn off X seconds after no motion has been detected. This is the purpose of "delay reset" on the "Follow" output mode. You would then turn on the light via the SET reaction, and turn it off via the RESET reaction. No delay in the actions; just one action in each reaction (light on or light off).

The way you've implemented this with pulse output and a delay on actions, the lights will go on when motion is first sensed, but will go off at the prescribed time later whether you are still in the room or not, whether the motion sensor trips more or not. This may be, in part, contributing to your unexpected behavior. I'm going to dig deeper on specifically what you've done, because at the very least, it would be my expectation that your 10-second delay ended on time, but that would also depend on if you have anything in the reset reactions (do you?), and if any motion was sensed on the 10-second rule after the 3-second pulse, that would cause the SET reaction to re-fire and restart, eliminating the previous delay and starting a new one. So the test needs to be done very carefully, and if the two motion sensors are in close proximity or other people are moving in the area of either as well, there's ample reason to see how the delay could be cancelled and restart. Another reason not to use pulse and action delays.

[jsimmo]

Ok. Thanks for the explanation. You guessed right about how I want it to work. I'll try using "delay reset" on the "Follow" output mode instead.

I was careful about how I did the test and have just carried it out again. There is nothing in the reset reactions of either rule and I made sure not re-activate the motion sensor associated with the 10 second rule after the 3 second pulse. I'm the only one in the house at the moment, so no-one else interfering with the test.
It's always the case that the first timer does not end on time once the second timer is started.

[toggledbits]

Cool. I'll see if I can reproduce those conditions in my test setup. If it's that predictable, should be no problem.

[toggledbits]

OK. I found it. Simple, stupid mistake, will be fixed in today's daily build. It's PR#64.

[jsimmo]

That's great that you found it.

I modified both my test rules to use the "delay reset" on the "Follow" output mode and changed the Set Reaction to switch the lights on and the Reset Reaction to switch them off again (much better way of doing it). Unfortunately, it hasn't fixed the problem, so I'm guessing the error you found affects this way of doing it as well. Will wait for the next daily build and test it again.

[toggledbits]

Can you post some screen shots of your work? Remember to show everything!

The action (reaction) delays are entirely different from the condition-based delays.

[jsimmo]

Ok, so this is how the rules for Delay1 and Delay 2 are now setup.

Each rule works perfectly fine when run on its own. The problem I have now is when one runs at the same time as the other.

To prevent any conflict, all my other rules in MSR are disabled, as are my Reactors in Vera.

In the following screenshot, Delay 2 (20s) is started and shortly after Delay 1 (10s) is started. Delay 1 completes first and its associated lamp switches off. Then Delay 2 completes but its associated lamp remains on.
What can't be seen in the screenshot is as well as the text being green for Delay 2 the whole box is also flashing green.
Everything works ok, except the lamp does not switch off after Delay 2 completes.

As can be seen from the logs, Delay 2 <Reset> does not occur.

2021-02-27T01:31:12.388Z Engine:INFO Delay 1<SET> all actions completed.
2021-02-27T01:31:29.320Z Rule:INFO Rule#rule-klmc7wxx (Delay 2) reset.
2021-02-27T01:31:29.328Z Rule:INFO Rule#rule-klifbnfi (Delay 1) reset.
2021-02-27T01:31:29.332Z Engine:INFO Enqueueing "Delay 2<RESET>" (rule-klmc7wxx:R)
2021-02-27T01:31:29.333Z Engine:INFO Enqueueing "Delay 1<RESET>" (rule-klifbnfi:R)
2021-02-27T01:31:29.334Z Engine:NOTICE Starting reaction Delay 2<RESET> [RuleReaction#rule-klmc7wxx:R]
2021-02-27T01:31:29.336Z Engine:NOTICE Starting reaction Delay 1<RESET> [RuleReaction#rule-klifbnfi:R]
2021-02-27T01:31:29.357Z Engine:NOTICE Resuming reaction Delay 2<RESET> from step 1
2021-02-27T01:31:29.359Z Engine:INFO Delay 2<RESET> all actions completed.
2021-02-27T01:31:29.431Z Engine:NOTICE Resuming reaction Delay 1<RESET> from step 1
2021-02-27T01:31:29.433Z Engine:INFO Delay 1<RESET> all actions completed.
2021-02-27T01:31:57.809Z Rule:NOTICE Rule#rule-klmc7wxx configuration changed; reloading
2021-02-27T01:31:57.812Z Rule:NOTICE Rule#rule-klmc7wxx stopping rule
2021-02-27T01:31:57.819Z Rule:NOTICE Rule Rule#rule-klmc7wxx stopped
2021-02-27T01:31:57.820Z Rule:INFO Rule#rule-klmc7wxx (Delay 2) started
2021-02-27T01:32:07.911Z Rule:INFO Rule#rule-klifbnfi (Delay 1) triggered!
2021-02-27T01:32:07.915Z Engine:INFO Enqueueing "Delay 1<SET>" (rule-klifbnfi:S)
2021-02-27T01:32:07.916Z Engine:NOTICE Starting reaction Delay 1<SET> [RuleReaction#rule-klifbnfi:S]
2021-02-27T01:32:07.979Z Engine:NOTICE Resuming reaction Delay 1<SET> from step 1
2021-02-27T01:32:07.980Z Engine:INFO Delay 1<SET> all actions completed.
2021-02-27T01:32:24.901Z Rule:INFO Rule#rule-klifbnfi (Delay 1) reset.
2021-02-27T01:32:24.905Z Engine:INFO Enqueueing "Delay 1<RESET>" (rule-klifbnfi:R)
2021-02-27T01:32:24.906Z Engine:NOTICE Starting reaction Delay 1<RESET> [RuleReaction#rule-klifbnfi:R]
2021-02-27T01:32:24.974Z Engine:NOTICE Resuming reaction Delay 1<RESET> from step 1
2021-02-27T01:32:24.975Z Engine:INFO Delay 1<RESET> all actions completed.
2021-02-27T01:32:29.114Z Rule:INFO Rule#rule-klmc7wxx (Delay 2) triggered!
2021-02-27T01:32:29.124Z Engine:INFO Enqueueing "Delay 2<SET>" (rule-klmc7wxx:S)
2021-02-27T01:32:29.125Z Engine:NOTICE Starting reaction Delay 2<SET> [RuleReaction#rule-klmc7wxx:S]
2021-02-27T01:32:29.175Z Engine:NOTICE Resuming reaction Delay 2<SET> from step 1
2021-02-27T01:32:29.176Z Engine:INFO Delay 2<SET> all actions completed.
2021-02-27T01:32:34.920Z Rule:INFO Rule#rule-klifbnfi (Delay 1) triggered!
2021-02-27T01:32:34.924Z Engine:INFO Enqueueing "Delay 1<SET>" (rule-klifbnfi:S)
2021-02-27T01:32:34.926Z Engine:NOTICE Starting reaction Delay 1<SET> [RuleReaction#rule-klifbnfi:S]
2021-02-27T01:32:34.973Z Engine:NOTICE Resuming reaction Delay 1<SET> from step 1
2021-02-27T01:32:34.974Z Engine:INFO Delay 1<SET> all actions completed.
2021-02-27T01:32:51.969Z Rule:INFO Rule#rule-klifbnfi (Delay 1) reset.
2021-02-27T01:32:51.974Z Engine:INFO Enqueueing "Delay 1<RESET>" (rule-klifbnfi:R)
2021-02-27T01:32:51.975Z Engine:NOTICE Starting reaction Delay 1<RESET> [RuleReaction#rule-klifbnfi:R]
2021-02-27T01:32:52.047Z Engine:NOTICE Resuming reaction Delay 1<RESET> from step 1
2021-02-27T01:32:52.049Z Engine:INFO Delay 1<RESET> all actions completed.

[toggledbits]

On this one, I'm guessing you copied one rule from the other and modified it, yes?

Edit: interesting that two entirely different bugs would produce such similar result. In any case, they are PR#64 and 65. The latter will be fixed in 21058 (tomorrow). If you need to work around it, delete one of the two rules and create it entirely from scratch, not by copying (the bug is caused by a duplicate condition ID that appears both in the original and the copy).

[jsimmo]

Thanks for the fixes Patrick.

I've now tried them on my test rules and both (PR#64 and 65) work fine.

I've also updated all my imported rules to use the "delay reset" on the "Follow" output mode. These are all working now with the added bonus of being able to monitor the delays counting down.

Thanks again for the brilliant MSR.