Door opening SOMETIMES triggers alarm

execution
alarm
triggers

#1

1) Give a description of the problem

I have a virtual contact sensor called “Alarm Triggered” that should be opened when any door opens and the alarm is set to armed.

2) What is the expected behaviour?

Any of the three doors opening should open the virtual contact sensor when the alarm is armed.

3) What is happening/not happening?

Sometimes it all works fine and the alarm is triggered. But this morning, for example, I forgot to disarm the alarm and walked out the door. I closed the door without anything being tripped. So my girlfriend assumed the alarm was already unarmed and she tripped it when she opened another door about 6 minutes later.

Could it have something to do with me closing the door “too quickly”? For some reason Webcore shows only about 1/2 second between “door open” and “door closed” piston executions even though I know it took me around 10 second to leave since I was carrying stuff out. I am guessing the first execution lagged for some reason while the second one was done pretty much immediately. This makes reproducing the issue a bit difficult. In any case, if that is the reason, I can’t guarantee burglars will keep the door open long enough when they come in :rofl::rofl::rofl: so it’s something that I need to fix anyway.

I have read a lot about Task Cancellation Policies but it is most of the time related to a wait in an inner “with” block. But does it also work when a condition changes state during regular execution? And if so, where should it be placed if there is no wait?

4) Post a Green Snapshot of the pistonimage

5) Attach logs after turning logging level to Full

This is me opening the door and the alarm NOT being triggered (I have marked what seems suspicious to me in bold):

18/06/2020, 08:44:52 +534ms
+1ms ╔Received event [Main Door].contact = open with a delay of 75ms
+108ms ║RunTime Analysis CS > 15ms > PS > 31ms > PE > 62ms > CE
+111ms ║Runtime (43155 bytes) successfully initialized in 31ms (v0.3.110.20191009) (109ms)
+112ms ║╔Execution stage started
+120ms ║║Comparison (string) :00d9fccffd94105c2738f1609244e192: is (string) :00d9fccffd94105c2738f1609244e192: = true (1ms)
+122ms ║║Cancelling condition #10’s schedules…
+123ms ║║Condition #10 evaluated true (6ms)
+125ms ║║Cancelling condition #8’s schedules…
+126ms ║║Condition group #8 evaluated true (state changed) (8ms)
+138ms ║║Comparison (enum) open changes_to (string) open = false (1ms)
+144ms ║║Condition #9 evaluated false (17ms)
+145ms ║║Cancelling condition #8’s schedules…
+146ms ║║Condition group #8 evaluated false (state changed) (20ms)
+153ms ║║Comparison (string) :00d9fccffd94105c2738f1609244e192: is_any_of (string) :dfde6a6e2dfa518a0913959c04ab8ba8:,:2065d56276b3c07c95d21f09b242b343: = false (2ms)
+155ms ║║Condition #5 evaluated false (6ms)
+156ms ║║Condition group #1 evaluated false (state did not change) (7ms)
+164ms ║║Condition #23 evaluated false (4ms)
+165ms ║║Condition group #22 evaluated false (state did not change) (6ms)
+167ms ║╚Execution stage complete. (55ms)
+168ms ╚Event processed successfully (168ms)

This is me closing the door when I left:

18/06/2020, 08:45:28 +871ms
+1ms ╔Received event [Main Door].contact = closed with a delay of 71ms
+106ms ║RunTime Analysis CS > 18ms > PS > 37ms > PE > 52ms > CE
+109ms ║Runtime (43158 bytes) successfully initialized in 37ms (v0.3.110.20191009) (108ms)
+110ms ║╔Execution stage started
+117ms ║║Comparison (string) :00d9fccffd94105c2738f1609244e192: is (string) :00d9fccffd94105c2738f1609244e192: = true (1ms)
+118ms ║║Condition #10 evaluated true (4ms)
+119ms ║║Cancelling condition #8’s schedules…
+120ms ║║Condition group #8 evaluated true (state changed) (6ms)
+131ms ║║Comparison (enum) closed changes_to (string) open = false (1ms)
+136ms ║║Condition #9 evaluated false (15ms)
+137ms ║║Cancelling condition #8’s schedules…
+138ms ║║Condition group #8 evaluated false (state changed) (17ms)
+144ms ║║Comparison (string) :00d9fccffd94105c2738f1609244e192: is_any_of (string) :dfde6a6e2dfa518a0913959c04ab8ba8:,:2065d56276b3c07c95d21f09b242b343: = false (2ms)
+145ms ║║Condition #5 evaluated false (4ms)
+146ms ║║Condition group #1 evaluated false (state did not change) (6ms)
+153ms ║║Condition #23 evaluated false (4ms)
+154ms ║║Condition group #22 evaluated false (state did not change) (6ms)
+156ms ║╚Execution stage complete. (45ms)
+157ms ╚Event processed successfully (158ms)

This is my girlfriend opening the door and the alarm being tripped, as expected:

18/06/2020, 08:50:32 +72ms
+1ms ╔Received event [BR Door].contact = open with a delay of 105ms
+95ms ║RunTime Analysis CS > 14ms > PS > 30ms > PE > 51ms > CE
+97ms ║Runtime (43156 bytes) successfully initialized in 30ms (v0.3.110.20191009) (96ms)
+98ms ║╔Execution stage started
+105ms ║║Comparison (string) :00d9fccffd94105c2738f1609244e192: is (string) :00d9fccffd94105c2738f1609244e192: = true (1ms)
+107ms ║║Condition #10 evaluated true (4ms)
+108ms ║║Cancelling condition #8’s schedules…
+108ms ║║Condition group #8 evaluated true (state changed) (6ms)
+119ms ║║Comparison (enum) open changes_to (string) open = true (0ms)
+124ms ║║Cancelling condition #9’s schedules…
+125ms ║║Condition #9 evaluated true (16ms)
+126ms ║║Condition group #8 evaluated true (state did not change) (17ms)
+128ms ║║Cancelling statement #11’s schedules…
+161ms ║║Executed physical command [Alarm Triggered].open() (29ms)
+162ms ║║Executed [Alarm Triggered].open (31ms)
+164ms ║║Cancelling statement #25’s schedules…
+168ms ║║Executed virtual command setVariable (0ms)
+174ms ║║Comparison (string) :00d9fccffd94105c2738f1609244e192: is_any_of (string) :dfde6a6e2dfa518a0913959c04ab8ba8:,:2065d56276b3c07c95d21f09b242b343: = false (2ms)
+175ms ║║Condition #5 evaluated false (5ms)
+176ms ║║Condition group #1 evaluated false (state did not change) (6ms)
+183ms ║║Condition #23 evaluated false (3ms)
+184ms ║║Condition group #22 evaluated false (state did not change) (5ms)
+186ms ║╚Execution stage complete. (87ms)
+187ms ╚Event processed successfully (186ms)


#2

I see a thirty-six second delay between open and close.

The problem seems to be that, when you opened a door, the piston already believed it was open and so there was no ‘change’ to be detected.

The comparison used for ‘changes to’ triggers is between the value carried in the event and a cached previous value. I have never worked out when that cached value is created.

If I had to speculate really wildly, and quite possibly end up talking complete bollocks, I would say that the cache might not get updated if the piston doesn’t check the the value for some reason, and I notice the restrictions you have mean that the contact sensor triggers are only evaluated when the mode is night, vacation or away. So what happens if the door is last closed in another mode?

I just don’t like restrictions (the ‘only when’ statements). Too much weird stuff seems to happen with them around. However I think the key point may actually be, if you are going to have explicit triggers in a piston, you probably ought to make sure they are evaluated when the piston runs.

Personally, I’d construct the piston along the lines of:

If any contacts change to open
Then
    If location is night
    Then
    ...
    Endif
    If location is vacation or away
    Then
    ...
    Endif
Endif

#3

Thanks for the reply!

Hahaha. You’re right. I read the times wrong. So that mistery is solved :blush:

Short answer: no idea. I had never considered the fact that this could cause any issues. I’ve always thought that the “cached state” was stored somewhere in ST backend and was not stored in a way that made it piston specific.

I will create a copy following your suggestion and test again. Let’s see if it works. But even if it does, it would be nice to know why.


#4

I agree wholeheartedly!

I will almost always choose an indented IF instead of using ONLY WHEN.


#5

Events sometimes get delayed, sometimes they arrive in the ‘wrong’ order, and sometimes they just don’t arrive. When it comes to triggers, the pistons are working with what turns up so they keep their own record of the ‘previous value’ of an attribute. It just isn’t clear when that value is updated. We’ve had some problem pistons come up on this forum that just don’t look like they should be failing, and the problem is often that ‘changes to’ is giving the “wrong” answer. It just isn’t always clear why.

There was a variation where a ‘changes to’ trigger was returning false even though there were obvious changes shown in the logs. However the current value of the same attribute was being evaluated before the trigger was evaluated, and that seemed to cause the trigger to return false, presumably because it changed its idea of what the previous value is.

You will often see comments on this forum suggesting you have the triggers at the outer level of nesting and preferably nearer the top. Also when you have several comparisons in an ‘if’, it is suggested that the trigger comes first. On the face of it, it seems like it shouldn’t really matter and it is just considered good style. However I think there is probably more to it than that. I am just not entirely sure what it is.


#6

Those insights are great to know! I’ll make sure to be careful about those in the future.

Would something like this take into consideration the recommendations of you both?

I haven’t had time to test it yet because the family has gone to sleep but if it’s in line with what you suggested, let me know and I’ll do testing over the weekend.


#7

So it took waaaaaaay longer than I expected to get around to testing this properly to be able to reply. Sorry about that.

The good news is that after having changed ALL of my pistons to use IFs instead of "Only When"s some weeks ago, I don’t appear to be experiencing any unexpected behaviors anymore. Things are running smoothly and as intended. I will report back if this changes.

It might just be superstition to replace "Only When"s. I suppose the source of the issue could have also been that I had a piston, which I have since modified, that was polling power readings from a socket (potentially polling several times a minute) and that might have caused timeouts on other pistons when they ran but at this point there’s no way of knowing. In any case, it was a good thing to rule out any other potential sources.

Thank you for your help! And I’ll be sure to take into consideration your suggestions for future pistons I write.