"Stays away from" and "Stays any of" triggers unexpected behavior

[Rezer]

1) Give a description of the problem
I’m trying to use either “Lock stays away from locked” or “Lock stays any of unlocked, unknown” for 30 seconds to trigger an error message texted to my phone (via tmomail.net email). Unfortunately, I don’t seem to have a full understanding of the way the Stays trigger operates since both of those options seem to always send the email. The idea is to only send the email if the lock completely fails to lock, but don’t send an email if it locks but is then immediately unlocked manually.

2) What is the expected behaviour?
I expect the lock to be locked after the door is unlocked and closed for 30 seconds, which works. I then expect the stays away from trigger to wait 30 seconds, and if the lock isn’t locked within that time period then a text message is sent.

3) What is happening/not happening?
The trigger waits 30 seconds as expected, but then at the end of the wait it always evaluates as true, even though the lock was successfully locked and it’s current state is equal to the “stays away from” condition. I am able to force it to work by putting a wait 30 after the lock command with TCP set to never, but I still fail to understand why the “stays away from” command is not being evaluated in an intuitive manner.

4)

5) Attach logs after turning logging level to Full
1/17/2021, 6:13:09 PM +34ms
+3ms ╔Received event [Redacted’s House].wc_async_reply = sendEmail with a delay of 1ms, canQueue: true, calledMyself: false
+26ms ║RunTime initialize > 25 LockT > 1ms > rtDT > 1ms > pistonT > 0ms (first state access 23 5 20)
+29ms ║Runtime (6948 bytes) successfully initialized in 1ms (v0.3.110.20201015_HE)
+35ms ║╔Execution stage started
+49ms ║╚Execution stage complete. (13ms)
+74ms ╚Event processed successfully (72ms)
1/17/2021, 6:13:07 PM +961ms
+5ms ╔Received event [Redacted’s House].time = 1610935988361 with a delay of -400ms, canQueue: true, calledMyself: false
+30ms ║RunTime initialize > 29 LockT > 1ms > rtDT > 1ms > pistonT > 0ms (first state access 27 6 23)
+32ms ║Runtime (6942 bytes) successfully initialized in 1ms (v0.3.110.20201015_HE)
+36ms ║Synchronizing scheduled event, waiting for 365ms
+408ms ║╔Execution stage started
+432ms ║║Cancelling condition #15’s schedules…
+434ms ║║Condition #15 evaluated true (2ms)
+436ms ║║Cancelling condition #14’s schedules…
+438ms ║║Condition group #14 evaluated true (state changed) (7ms)
+440ms ║║Cancelling statement #24’s schedules…
+449ms ║║Executed virtual command sendEmail (2ms)
+451ms ║║Requesting a wake up for Sun, Jan 17 2021 @ 6:13:32 PM PST (in 24s)
+461ms ║╚Execution stage complete. (54ms)
+502ms ║Setting up scheduled job for Sun, Jan 17 2021 @ 6:13:32 PM PST (in 24s)
+504ms ╚Event processed successfully (502ms)
1/17/2021, 6:12:40 PM +829ms
+3ms ╔Received event [Front Door Lock].lock = locked with a delay of 44ms, canQueue: true, calledMyself: false
+25ms ║RunTime initialize > 23 LockT > 2ms > rtDT > 1ms > pistonT > 0ms (first state access 20 5 18)
+27ms ║Runtime (6926 bytes) successfully initialized in 1ms (v0.3.110.20201015_HE)
+28ms ║╔Execution stage started
+40ms ║║Comparison (enum) closed is (string) closed = true (3ms)
+42ms ║║Condition #3 evaluated true (9ms)
+50ms ║║Comparison (enum) locked is (string) unlocked = false (1ms)
+52ms ║║Cancelling condition #21’s schedules…
+53ms ║║Condition #21 evaluated false (9ms)
+55ms ║║Cancelling condition #2’s schedules…
+56ms ║║Condition group #2 evaluated false (state changed) (23ms)
+58ms ║║Cancelling condition #1’s schedules…
+59ms ║║Condition group #1 evaluated false (state changed) (27ms)
+65ms ║╚Execution stage complete. (37ms)
+121ms ║Setting up scheduled job for Sun, Jan 17 2021 @ 6:13:08 PM PST (in 27s)
+123ms ╚Event processed successfully (122ms)
1/17/2021, 6:12:38 PM +244ms
+3ms ╔Received event [Redacted’s House].time = 1610935958119 with a delay of 125ms, canQueue: true, calledMyself: false
+65ms ║RunTime initialize > 64 LockT > 1ms > rtDT > 2ms > pistonT > 1ms (first state access 61 4 60)
+67ms ║Runtime (6929 bytes) successfully initialized in 2ms (v0.3.110.20201015_HE)
+72ms ║╔Execution stage started
+84ms ║║Cancelling statement #5’s schedules…
+100ms ║║Executed physical command [Front Door Lock].lock() (11ms)
+102ms ║║Executed [Front Door Lock].lock (13ms)
+112ms ║║Comparison (enum) unlocked stays_away_from (string) locked = true (1ms)
+117ms ║║Adding a timed trigger schedule for condition 15
+119ms ║║Condition #15 evaluated false (15ms)
+121ms ║║Condition group #14 evaluated false (state did not change) (16ms)
+128ms ║╚Execution stage complete. (55ms)
+162ms ║Setting up scheduled job for Sun, Jan 17 2021 @ 6:13:08 PM PST (in 30s)
+164ms ╚Event processed successfully (163ms)
1/17/2021, 6:12:07 PM +976ms
+4ms ╔Received event [Front Door Lock].lock = unlocked with a delay of 69ms, canQueue: true, calledMyself: false
+73ms ║RunTime initialize > 72 LockT > 3ms > rtDT > 53ms > pistonT > 52ms (first state access 16 7 65)
+77ms ║Runtime (6865 bytes) successfully initialized in 53ms (v0.3.110.20201015_HE)
+80ms ║╔Execution stage started
+96ms ║║Comparison (enum) closed is (string) closed = true (2ms)
+99ms ║║Condition #3 evaluated true (11ms)
+110ms ║║Comparison (enum) unlocked is (string) unlocked = true (4ms)
+112ms ║║Cancelling condition #21’s schedules…
+114ms ║║Condition #21 evaluated true (13ms)
+117ms ║║Cancelling condition #2’s schedules…
+119ms ║║Condition group #2 evaluated true (state changed) (32ms)
+121ms ║║Cancelling condition #1’s schedules…
+124ms ║║Condition group #1 evaluated true (state changed) (38ms)
+127ms ║║Cancelling statement #22’s schedules…
+136ms ║║Executed virtual command wait (1ms)
+142ms ║║Requesting a wake up for Sun, Jan 17 2021 @ 6:12:38 PM PST (in 30s)
+161ms ║╚Execution stage complete. (81ms)
+258ms ║Setting up scheduled job for Sun, Jan 17 2021 @ 6:12:38 PM PST (in 30s)
+260ms ╚Event processed successfully (260ms)

[orangebucket]

I can suggest a failure mechanism:

The stays doesn’t know the door is locked initially because the piston is still processing an event saying it is unlocked and that is always checked first.

The stays returns false and also schedules a wake up because that is how it works. The door locked event that comes along never reaches the stays trigger so it doesn’t cancel that wake up. It wakes up, returns true and sends the e-mail.

The problem I have is why your fix works. If you simply added a long wait after the lock with TCP left alone I’d understand it as the locked event would cause it to be cancelled and the stays would never be reached. However with TCP set to Never Cancel I don’t know.

[Pantheon]

Maybe this falls into the observations that @WCmore has made : stays unchanged

[Rezer]

Yes, the lock event seems to take 3-4 seconds to process so when the “stays” trigger is first encountered it’s always still unlocked, but by the time 30 seconds have expired and the subscribed event is resolved the lock has long since reported the “locked” event. At that point the “stays unlocked” condition should fail, or so I would think. Do the stay conditions not process any events that occur during the period from when the trigger starts to when it is resolved? That seems not a little counterintuitive, and if so it makes me question what utility “stays” triggers have.

The reason the wait workaround works, as I understand it, is because by the time the wait event expires the lock has already reported back that it’s locked, so both when the “stays” trigger starts and when it ends the condition on the stays trigger evaluates to false.

[Rezer]

Is this a known (if undocumented) issue then? I’m very new to webcore and tried to search for a breakdown of how the different triggers and conditions are evaluated, but didn’t come up with anything other than a broad description of how triggers are different from conditions. While informative, that doesn’t help me determine how the inputs to different types of triggers are processed or when the time period starts/ends. Perhaps them being half broken is why the documentation is a bit lacking…

[orangebucket]

Consider a simple condition like Door contact is open. If you run a piston containing that condition using the Test button it will look at the current value of the Door contact attribute to see if it is open. If, however, the piston has fired because of a Door contact event, the piston will look at the event value instead. The values can be different.

The stays condition is an unusual one. It is classed as a trigger and that means the piston subscribes to the device attribute it uses. The actual comparisons are like conditions though. A trigger condition can normally only evaluate to true if the piston is currently processing the trigger event, but stays doesn’t work like that.

Considering stays away from locked for 30 seconds, the piston starts by looking to see if the lock status is locked. If it is (bearing in mind the value may come from the event) the comparison returns false, job done.

If the lock status is not locked, the piston sets a timer for 30 seconds time but also immediately returns false and continues.

After 30 seconds the piston wakes up, and unless it has been cancelled, continues where it left off, returning true. This is why it sometimes gets called a timed trigger.

In order to stop the piston returning true, an event has to occur in those thirty seconds to make it run again, which in your case is the locked event. The first ‘if’ group will now return false and cancel any scheduled events set up last time around when it was true. However it would appear that the stays timer doesn’t count as a scheduled task and that the stays trigger actually needs to be evaluated again for it to see the lock status has changed.

That’s how I see things but there are bits where I am really fuzzy about the details. For instance a long wait, implemented by an exit and a wake up, doesn’t seem to turn the piston’s idea of the current event into a timer, it seems to leave it alone.

[Rezer]

So if I’m understanding you correctly the stays trigger only works properly if the event it’s waiting for is able to invoke a new instance of the piston and get to the point in the code where the stays trigger is located, otherwise the value it’s watching will always be evaluated the same as it was when the trigger timer was started?

[orangebucket]

So if I’m understanding you correctly

I think you probably are. I’m not saying I’m correct but that is what I think happens. It is similar in principle to the TCP cancelling scheduled tasks. It is all down to the piston executing a new instance and conditions giving different results to previously.

[Rezer]

I’ve just made the simplest test I can think of to check this, and it seems you’ve nailed it. I made a test that will respond to the door lock being unlocked by immediately locking it then waiting for 30 seconds to see if the lock status is changed to locked. If it fails to lock, it then turns off a light as an indicator. The following works as expected, where the light stays on if the lock locks and turns off if it fails to lock for any reason:

The following does not, and the only difference is that now the initial trigger does not include the locked state, which makes more sense on its face but prevents instances of the piston started due to “locked” events from progressing to the “stays” condition. No matter what happens, this one will always turn off the lights:

So the only way the “stays” triggers will work as expected is if you ensure that all potential events that can occur during the wait period will initiate a new instance of the piston, while also meeting all conditions to progress to the “stays” statement, otherwise the events are never “seen” by the original piston instance. This seems to severely limit the utility of the “stays” statement, such that it is difficult to incorporate properly unless it’s the very first condition statement hit in a piston.

This being the case, I don’t see any way to do what I want outside of defining a global variable and having a separate piston with the global variable acting as a restriction which just locks the door then has the “stays” trigger within there, resetting the global variable afterward. Does that sound about right, or might there be a more straightforward approach to watching for whether a lock successfully locks?

[Pantheon]

@WCmore

[E_Sch]

If you have an HE system, I have fixes for “stays*” that I’m looking for a tester.

It passes my initial tests.

[Rezer]

I guess I forgot to mention that, but yes it is an HE system. I’m willing to give it a shot, where can I go about getting the changes?

[E_Sch]

The HE repo is updated with these changes.

If you use HPM on HE, you will need to do a repair, as I have not updated the HPM config file (ie I’m not forcing it as an advertised update to everyone.)

[Rezer]

I updated it from github directly since I’m not using HPM, but the behavior doesn’t seem to have changed. I ran the following as a test:

It still always turns off the lights regardless of whether the lock action is successful or not. Am I misunderstanding what was changed? Here is the log:

1/22/2021, 12:23:41 PM +962ms
+4ms 	╔Received event [Redacted's House].time = 1611347021523 with a delay of 439ms, canQueue: true, calledMyself: false
+24ms 	║RunTime initialize > 23 LockT > 1ms > rtDT > 2ms > pistonT > 1ms (first state access 20 6 17)
+26ms 	║Runtime (5860 bytes) successfully initialized in 2ms (v0.3.110.20210122_HE)
+30ms 	║╔Execution stage started
+36ms 	║║Cancelling condition #6's schedules...
+37ms 	║║Condition #6 evaluated true (1ms)
+38ms 	║║Cancelling condition #5's schedules...
+40ms 	║║Condition group #5 evaluated true (state changed) (5ms)
+41ms 	║║Cancelling statement #7's schedules...
+64ms 	║║Executed physical command [Living Room Lights].setLevel([0], ) (16ms)
+65ms 	║║Executed [Living Room Lights].setLevel (19ms)
+71ms 	║╚Execution stage complete. (41ms)
+74ms 	╚Event processed successfully (72ms)
1/22/2021, 12:23:13 PM +851ms
+2ms 	╔Received event [Front Door Lock].lock = locked with a delay of 42ms, canQueue: true, calledMyself: false
+29ms 	║RunTime initialize > 28 LockT > 1ms > rtDT > 1ms > pistonT > 0ms (first state access 26 4 24)
+32ms 	║Runtime (5846 bytes) successfully initialized in 1ms (v0.3.110.20210122_HE)
+33ms 	║╔Execution stage started
+43ms 	║║Comparison (enum) locked is (string) unlocked = false (2ms)
+45ms 	║║Cancelling condition #2's schedules...
+46ms 	║║Condition #2 evaluated false (10ms)
+48ms 	║║Cancelling condition #1's schedules...
+49ms 	║║Condition group #1 evaluated false (state changed) (13ms)
+54ms 	║╚Execution stage complete. (22ms)
+146ms 	║Setting up scheduled job for Fri, Jan 22 2021 @ 12:23:41 PM PST (in 28s)
+148ms 	╚Event processed successfully (147ms)
1/22/2021, 12:23:11 PM +314ms
+9ms 	╔Received event [Front Door Lock].lock = unlocked with a delay of 72ms, canQueue: true, calledMyself: false
+25ms 	║RunTime initialize > 23 LockT > 2ms > rtDT > 2ms > pistonT > 1ms (first state access 19 11 12)
+28ms 	║Runtime (5797 bytes) successfully initialized in 2ms (v0.3.110.20210122_HE)
+29ms 	║╔Execution stage started
+38ms 	║║Comparison (enum) unlocked is (string) unlocked = true (1ms)
+40ms 	║║Cancelling condition #2's schedules...
+47ms 	║║Condition #2 evaluated true (15ms)
+49ms 	║║Cancelling condition #1's schedules...
+51ms 	║║Condition group #1 evaluated true (state changed) (18ms)
+52ms 	║║Cancelling statement #3's schedules...
+83ms 	║║Executed physical command [Front Door Lock].lock() (27ms)
+85ms 	║║Executed [Front Door Lock].lock (29ms)
+205ms 	║║Comparison (enum) unlocked stays_away_from (string) locked = false (112ms)
+209ms 	║║Adding a timed trigger schedule for condition 6
+211ms 	║║Cancelling condition #6's schedules...
+213ms 	║║Condition #6 evaluated false (124ms)
+215ms 	║║Cancelling condition #5's schedules...
+216ms 	║║Condition group #5 evaluated false (state changed) (128ms)
+223ms 	║╚Execution stage complete. (193ms)
+257ms 	║Setting up scheduled job for Fri, Jan 22 2021 @ 12:23:41 PM PST (in 30s)
+260ms 	╚Event processed successfully (258ms)

[E_Sch]

So things look right to me.

You nested the check for ‘stays away from’. I get the impression you don’t want it nested.

In general nesting triggers is a bad idea, as the code for the trigger may not run due to the nesting.

I otherwise see the right scheduling, and execution.

[Rezer]

Oh ok, I just misunderstood then. What was it that these changes fix then?

[orangebucket]

I suspect you might be better off not using stays away from locked in your case. You might find you can replace it with

   if Lock 1 is unlocked
   then
        wait 30 seconds
        <take whatever action you want>
   endif

Then if the locked event does arrive the cancellation of scheduled tasks will cascade down and stop the action task happening.

[Rezer]

I had already considered that, and it handles the cases where the lock is completely unresponsive just fine. However, in cases where the lock is physically obstructed the status changes to “unknown” and the wait is canceled all the same. Is there a method for continuing execution at some point after the wait event when the wait is canceled, or does it just exit the piston completely in all cases when TCP is set to condition change? I do have a piston that works appropriately with both the stays event and using the wait as you suggest (plus a bit more to handle unknown cases), it’s just a bit more convoluted than I had expected for so simple a task.

[orangebucket]

However, in cases where the lock is physically obstructed the status changes to “unknown” and the wait is canceled all the same.

It may be that you need to handle ‘unknown’ as a special case and that what seems convoluted is the best solution.

[E_Sch]

Just as reference, I added more of a writeup on

‘did not change’

vs. various forms of ‘stays’

here:

How to make a piston fire only if switch is not already on

So I have been looking at all this more. I don’t think webCoRE is broken (but there are improvements in labeling I think) ‘did not change’ is a condition. (and it looks backward in time, IT DOES NOT SET A FUTURE TIMER) when the piston runs (because of some other event), it looks backwards in time to see if the variable changed or not within the specified duration (assuming there are enough events (in HE for example, one could set the db that there is very limited history)) there is no co…