Timer not resetting during wait in while loop

GeorgeH · 2018-10-03 20:02:55 UTC

1) Give a description of the problem
Timer within while loop is not being reset on motion activity.

2) What is the expected behavior?
What I want to have happen is the wait timer to expire after N (10 in this example) minutes of the garage door having been open while no motion activity happened. If there’s motion (in the garage), then reset the time to start over. Basically timeout should happen after 10 minutes with no motion and the door’s being left open.

3) What is happening/not happening?
Motion acttivity (which I have confirmed is being reported by the sensor in its event log) does not cause the wait timer to be reset. The log snippet I’ve posted shows the timer starting, and timer expiration – no other piston execution between that (when there was motion activity occurring).
I have read several related posts, and think I still don’t understand something about the piston execution basics. I think that motion sensor inactive event should cause the inner loop (where wait exists) to cease, and further “Inactivity” of the motion sensor cause that inner loop to be restarted.

I’ve only setup the first “if”, where contact changes to open as a trigger (garage door first opening should start the timeout check process)… maybe I also need to setup the later Motion Sensor “if” test conditions as another trigger – or explicitly subscribe to the motion sensor events under the settings cog?
Or, maybe I need to add an explicit “else” statement for the case of motion inactive in the inner if/then section (not logical this would be needed but whatever…)

TCP is left at default.

4) Post a Green Snapshot of the piston
(UPLOAD YOUR IMAGE HERE)

5) Attach any logs (From ST IDE and by turning logging level to Full)

10/3/2018, 8:43:53 AM +68ms
+2ms	╔Received event [HayekHome].time = 1538581434213 with a delay of -1146ms
+173ms	║Runtime (42730 bytes) successfully initialized in 119ms (v0.3.108.20180906) (169ms)
+175ms	║╔Execution stage started
+300ms	║║Executed virtual command sendPushNotification (92ms)
+314ms	║║timeout timer expired
+316ms	║║Executed virtual command log (3ms)
+325ms	║╚Execution stage complete. (151ms)
+327ms	╚Event processed successfully (327ms)
10/3/2018, 8:33:47 AM +257ms
+1ms	╔Received event [Garage Door - Ctr].contact = open with a delay of 259ms
+142ms	║Runtime (42735 bytes) successfully initialized in 91ms (v0.3.108.20180906) (140ms)
+143ms	║╔Execution stage started
+175ms	║║door opening detected
+176ms	║║Executed virtual command log (2ms)
+6939ms	║║about to start timeout timer wait
+6941ms	║║Executed virtual command log (3ms)
+6952ms	║║Executed virtual command wait (1ms)
+6955ms	║║Requesting a wake up for Wed, Oct 3 2018 @ 8:43:54 AM PDT (in 600.0s)
+6966ms	║╚Execution stage complete. (6823ms)
+6969ms	║Setting up scheduled job for Wed, Oct 3 2018 @ 8:43:54 AM PDT (in 599.988s)
+6981ms	╚Event processed successfully (6980ms)

REMOVE BELOW AFTER READING
If a solution is found for your question then please mark the post as the solution.

eibyer · 2018-10-03 20:57:03 UTC

See if it works as expected if set up this way…

GeorgeH · 2018-10-04 00:57:56 UTC

Tried this one, and it doesn’t really do what I need. I see 2 issues with its logic:

If the motion sensor is active when the door opens (a common situation), then the while test evaluates false and the timer is not started. Since there are no new “changes to open” events, the timer is never started while the door remains open.

If the motion sensor is inactive when the door opens, the timer does get started. However, while subsequent motion while the timer is running does stop the timer it never gets restarted because the while test checks for contact changes to open – the door has remained open so that test is false.

I remember that is why I had put both a “changes to” and a “while” loop in my piston – first to trigger on opening of the door (independent of any motion event) and then to check things while the door was open (a static condition).

Any suggestions why mine doesn’t work? I think its something to do about not being subscribed to motion sensor events but am not sure.

eibyer · 2018-10-04 01:30:00 UTC

Ah, yep, it helps if I test it

how about this one…

WCmore · 2018-10-04 01:31:19 UTC

From your description, it sounds like the main subscription should be the motion sensor (top level).

I would structure something like this:

IF 
    Motion sensor stays inactive for 10 min  (ϟ Trigger)
Then
    IF
       Contact sensor is open                (Condition)
       and
       Time is after sunrise                 (Condition)
    Then
        Do stuff
    END IF
END IF

(and if you want to be notified when the door opens, add the following in a new block)

If Contact sensor changes to open            (ϟ Trigger)
Write to Log (or whatever)
END IF

GeorgeH · 2018-10-04 04:51:03 UTC

My wish is to get notified if the garage door has been open for >10minutes AND no motion activity has happened during that time. (Use case is I’m happy with door open if I’m working in the garage, but if I’m not there and the door’s been open that’s a problem.)

What I’d like to understand is why the logic flow I put together doesn’t work - I suspect it has something to do with the wait timer not getting reset. If the purpose of the “trigger” is to kick off everything in the piston, it seems to me that should be the garage door opening event. Then while the door is open, check for the activity to reset a watchdog timer.

The logical flow is easy to describe, which the piston’s code matches fairly well. Lacking a clear understanding of why it is not working I will keep at the trial and error approach and report back if I find what works.

michicago · 2018-10-04 15:18:14 UTC

First lets start with why your original doesn’t work. You are correct that the logic flows in a means to behave the way you want it to, but there’s one small thing catching you out: your while loop doesn’t subscribe to your motion sensor.

When a piston ‘subscribes’ to something, it means the piston is notified when a parameter on the subscribed device changes. In this example, if it’s subscribed to your motion sensor’s MOTION parameter, the piston will be notified (and will run) each time the state changes - whether it’s inactive or active.

The way your piston is written now, your contact sensor (line 26 in your green snapshot) triggers the piston to run when your sensor reports a change in its CONTACT status. This is signified by the orange lightning bolt next to the line number.

Once the loop begins, there’s nothing subscribed in that part of the code so it will just wait for the 10 minutes to pass and send the push notification.

Quick fix: Click on line 37 in your green snapshot in post 1 (the line number may be different in your piston edit screen), then on the right side of the screen change your ‘Subscription’ option from Auto to Always:

Try your piston again and see if that changes the behavior. It should, but if it doesn’t we can make another change or two to get it there.

Edit to add: I missed the response from @eibyer before I posted - you’ll notice the number of orange lightning bolts in his example compared to the one in your first post… that’s the key difference. There are at least a dozen different ways to get what you want to work - you had it 99% of the way there in your first post and the example from eibyer would work too.

GeorgeH · 2018-10-04 15:52:17 UTC

I’m closer to understanding the gaps - thanks. Below is my updated piston, with a couple of more logging statements plus the motion event subscribed (plus a smaller timeout for ease of testing). Things are not quite there, but I think I know why now. I’ve attached a log of the case where the there’s some motion activity after the timer has started.

When the motion is detected (after timer started), on that piston firing the condition #17 – the first “if” checking for garage door opening event – is evaluated as FALSE. I had incorrectly assumed that on reentry it would “remember” that test was previously satisfied and jump into the middle of the while loop – apparently that is not what happens (earlier section of the piston code need to be satisfied again to drop through to while loop?). So I need to change that section of the code (either lose the check for 1st opening or add some variable to “remember” that happened for later reentry. I put the opening event check in thinking that would yield a more “efficient” piston, only firing when the door occasionally opened vs. always checking open/close state… maybe I should not worry about that).

Also, I was a bit surprised that the timer itself (wait task) was not really cancelled when the motion went active – the timeout did occur and the piston ran, as the final(top) bit of log shows. TCP was set to default, which I understood to allow cancellation if the conditions changed (which I think they did in this case).

My last unrelated question is whether the “trace” feature’s “color coding” is described anywhere? I turned trace on, and it seemed to add some useful debug info to the side of the piston, color coded bars etc… but I was curious what the different colors (blue, “rust?”, green) really meant… seems to show the execution flow of the piston on last firing.)

Thanks again!

10/4/2018, 8:31:12 AM +46ms
+1ms ╔Received event [HayekHome].time = 1538667073968 with a delay of -1922ms
+137ms ║RunTime Analysis CS &gt; 14ms &gt; PS &gt; 101ms &gt; PE &gt; 21ms &gt; CE
+139ms ║Runtime (43424 bytes) successfully initialized in 101ms (v0.3.108.20180906) (137ms)
+141ms ║╔Execution stage started
+142ms ║╚Execution stage complete. (2ms)
+144ms ╚Event processed successfully (143ms)
10/4/2018, 8:30:04 AM +631ms
+2ms ╔Received event [Garage Multi Sensor].motion = inactive with a delay of 962ms
+168ms ║RunTime Analysis CS &gt; 31ms &gt; PS &gt; 112ms &gt; PE &gt; 25ms &gt; CE
+171ms ║Runtime (43429 bytes) successfully initialized in 112ms (v0.3.108.20180906) (168ms)
+172ms ║╔Execution stage started
+197ms ║║Condition #17 evaluated false (18ms)
+198ms ║║Condition group #16 evaluated false (state did not change) (20ms)
+201ms ║╚Execution stage complete. (28ms)
+202ms ╚Event processed successfully (202ms)
10/4/2018, 8:29:49 AM +629ms
+2ms ╔Received event [Garage Multi Sensor].motion = active with a delay of 950ms
+159ms ║RunTime Analysis CS &gt; 17ms &gt; PS &gt; 115ms &gt; PE &gt; 26ms &gt; CE
+162ms ║Runtime (43425 bytes) successfully initialized in 115ms (v0.3.108.20180906) (160ms)
+163ms ║╔Execution stage started
+188ms ║║Cancelling condition #17's schedules...
+190ms ║║Condition #17 evaluated false (20ms)
+191ms ║║Cancelling condition #16's schedules...
+192ms ║║Condition group #16 evaluated false (state changed) (23ms)
+195ms ║╚Execution stage complete. (32ms)
+197ms ╚Event processed successfully (197ms)
10/4/2018, 8:29:13 AM +504ms
+2ms ╔Received event [Garage Door - Left].contact = open with a delay of 961ms
+150ms ║RunTime Analysis CS &gt; 20ms &gt; PS &gt; 108ms &gt; PE &gt; 21ms &gt; CE
+152ms ║Runtime (43427 bytes) successfully initialized in 108ms (v0.3.108.20180906) (149ms)
+154ms ║╔Execution stage started
+173ms ║║Comparison (enum) open changes_to (string) open = true (1ms)
+176ms ║║Cancelling condition #17's schedules...
+177ms ║║Condition #17 evaluated true (17ms)
+178ms ║║Cancelling condition #16's schedules...
+179ms ║║Condition group #16 evaluated true (state changed) (20ms)
+182ms ║║Cancelling statement #18's schedules...
+190ms ║║door opening detected
+191ms ║║Executed virtual command log (2ms)
+367ms ║║Comparison (enum) closed is (string) open = false (162ms)
+370ms ║║Comparison (enum) open is (string) open = true (2ms)
+373ms ║║Condition #11 evaluated true (177ms)
+413ms ║║Comparison (time) 30553878 is_between (time) 1538661780000 .. (time) 1538636400000 = true (15ms)
+415ms ║║Time restriction check passed
+417ms ║║Condition #12 evaluated true (43ms)
+423ms ║║Comparison (string) :3fc4535970ba0dda3531ef97b85c1207: is (string) :3fc4535970ba0dda3531ef97b85c1207: = true (2ms)
+425ms ║║Condition #13 evaluated true (7ms)
+426ms ║║Condition group #10 evaluated true (state did not change) (232ms)
+439ms ║║Comparison (enum) inactive is (string) inactive = true (2ms)
+441ms ║║Condition #6 evaluated true (12ms)
+442ms ║║Condition group #5 evaluated true (state did not change) (13ms)
+446ms ║║Cancelling statement #7's schedules...
+454ms ║║about to start timeout timer wait
+455ms ║║Executed virtual command log (2ms)
+461ms ║║Executed virtual command wait (1ms)
+463ms ║║Requesting a wake up for Thu, Oct 4 2018 @ 8:31:13 AM PDT (in 120.0s)
+470ms ║╚Execution stage complete. (317ms)
+472ms ║Setting up scheduled job for Thu, Oct 4 2018 @ 8:31:13 AM PDT (in 119.993s)
+480ms ╚Event processed successfully (480ms)

GeorgeH · 2018-10-04 22:19:11 UTC

Sorry for the rambling/multiple postings… I’ve modified the piston to remove the 1st “IF”, subscribed to more events (as indicated in the snapshot) and it now seems to work as I expect… almost.

There seems an inconsistency in how the subscription to line 26 (contact sensors) and line 33 (motion sensor IF) behave. For line 33, the log ONLY shows the “inactive” event invoking the piston, i.e.:

╔Received event [Garage Multi Sensor].motion = inactive

I would have expected either an active or inactive event to invoke the piston. I never get the log info for the related “log info” statement executed either, nor a received event in the log showing motion = active.

But, for the line 26 “subscription”, that seems to invoke the piston both when the sensor changes to OPEN and also when the sensor changes to CLOSED state (as shown in the log snipped, at least the close case).

The line 26 subscription was setup as “automatic”, whereas the latter line 33 subscription I forced to “always subscribe” … but I would not expect a difference in behavior due to that.

So I guess my question is whether subscriptions are to the event itself, or the instead to a qualified condition specified in the relevant piston statement (i.e. event qualified by a condition test)? Both cases seem to be exhibited by my piston, which confuses me! (Admittedly easily confused these days;-).

Oh, and any guidance on the “trace” information from my prior post would still be welcome.

10/4/2018, 2:54:43 PM +919ms
+1ms ╔Received event [Garage Door - Left].contact = closed with a delay of 1011ms
+161ms ║RunTime Analysis CS &gt; 24ms &gt; PS &gt; 115ms &gt; PE &gt; 22ms &gt; CE
+163ms ║Runtime (42029 bytes) successfully initialized in 115ms (v0.3.108.20180906) (161ms)
+164ms ║╔Execution stage started
+185ms ║║Comparison (enum) closed is (string) open = false (2ms)
+188ms ║║Comparison (enum) closed is (string) open = false (2ms)
+191ms ║║Comparison (enum) closed is (string) open = false (2ms)
+193ms ║║Cancelling condition #11's schedules...
+195ms ║║Condition #11 evaluated false (24ms)
+196ms ║║Cancelling condition #10's schedules...
+197ms ║║Condition group #10 evaluated false (state changed) (27ms)
+207ms ║╚Execution stage complete. (43ms)
+209ms ║Setting up scheduled job for Fri, Oct 5 2018 @ 12:00:00 AM PDT (in 32715.873s)
+222ms ╚Event processed successfully (222ms)
10/4/2018, 2:54:16 PM +70ms
+0ms ╔Received event [HayekHome].time/recovery = 1538690056068 with a delay of 1ms
+156ms ║RunTime Analysis CS &gt; 16ms &gt; PS &gt; 117ms &gt; PE &gt; 23ms &gt; CE
+159ms ║Runtime (42030 bytes) successfully initialized in 117ms (v0.3.108.20180906) (157ms)
+167ms ║╔Execution stage started
+169ms ║╚Execution stage complete. (9ms)
+172ms ║Setting up scheduled job for Thu, Oct 4 2018 @ 2:56:13 PM PDT (in 117.646s), with 1 more job pending
+186ms ╚Event processed successfully (186ms)
10/4/2018, 2:54:13 PM +575ms
+2ms ╔Received event [Garage Multi Sensor].motion = inactive with a delay of 1011ms
+168ms ║RunTime Analysis CS &gt; 30ms &gt; PS &gt; 114ms &gt; PE &gt; 23ms &gt; CE
+171ms ║Runtime (42031 bytes) successfully initialized in 114ms (v0.3.108.20180906) (167ms)
+172ms ║╔Execution stage started
+198ms ║║Comparison (enum) closed is (string) open = false (2ms)
+201ms ║║Comparison (enum) open is (string) open = true (2ms)
+204ms ║║Condition #11 evaluated true (26ms)
+244ms ║║Comparison (time) 53653780 is_between (time) 1538661780000 .. (time) 1538636400000 = true (14ms)
+245ms ║║Time restriction check passed
+247ms ║║Condition #12 evaluated true (42ms)
+249ms ║║Cancelling statement #12's schedules...
+263ms ║║Requesting time schedule wake up at Fri, Oct 5 2018 @ 12:00:00 AM PDT
+272ms ║║Comparison (string) :3fc4535970ba0dda3531ef97b85c1207: is (string) :3fc4535970ba0dda3531ef97b85c1207: = true (3ms)
+274ms ║║Condition #13 evaluated true (7ms)
+275ms ║║Condition group #10 evaluated true (state did not change) (97ms)
+285ms ║║Comparison (enum) inactive is (string) inactive = true (2ms)
+287ms ║║Condition #6 evaluated true (8ms)
+289ms ║║Condition group #5 evaluated true (state did not change) (10ms)
+292ms ║║Cancelling statement #7's schedules...
+301ms ║║about to start timeout timer wait
+303ms ║║Executed virtual command log (2ms)
+310ms ║║Executed virtual command wait (1ms)
+311ms ║║Requesting a wake up for Thu, Oct 4 2018 @ 2:56:13 PM PDT (in 120.0s)
+319ms ║╚Execution stage complete. (148ms)
+322ms ║Setting up scheduled job for Thu, Oct 4 2018 @ 2:56:13 PM PDT (in 119.991s), with 1 more job pending
+334ms ╚Event processed successfully (334ms)

WCmore · 2018-10-04 23:13:08 UTC

Well, I think I am tapping out of this one…
Having 4 triggers in one block can turn our hair grey much too quickly, LOL

I still think the solution is post #5 above.
(I just added your new time condition to that post)

GeorgeH · 2018-10-04 23:50:23 UTC

Triggering on motion as the sole thing doesn’t really satisfy my use case, nor does timing inactivity of that alone. Perhaps the result of “door is open AND inactivity” test would do it, but I still need to choose triggers for the piston. Effectively that is what I coded with the nested while/ifs.

Is there documentation on the expected behavior of “subscription” somewhere? I haven’t found anything that answers the question I last posed, but admit to not having searched through all possibly relevant posts.

Thanks!

michicago · 2018-10-06 15:48:52 UTC

I may be missing something - can you elaborate on that? What part of your use case is not satisfied if only triggering on motion?

GeorgeH · 2018-10-07 15:16:10 UTC

The use case is that I want to be notified if the garage door’s been left open for N minutes, however if there’s been recent motion in the area – usually meaning I’m working there or something – I don’t need the notification since I’m (usually) aware its open. (Day vs night policies will differ, once I get the basic piston working.)

Looking at the post#5 solution above that trigger on inactivity timeout would cause the notification if the garage door has just been opened when the inactivity timeout expires.

Also, if I understand the “trigger” correctly, won’t it just run the piston to check for the door open once at the 10 minute mark – so if the door opens after that time (e.g. after 20 minutes of inactivity) will that event be seen?

WCmore · 2018-10-07 16:48:50 UTC

I believe all these scenarios will be resolved with this version:

In block #1:
When the motion has been inactive for 10 minutes, it checks the door’s status.

In block #2:
When the door has been open for 10 minutes, it checks the motion sensor’s status.

That should catch everything you mentioned in this thread.

GeorgeH · 2018-10-07 17:33:50 UTC

It’s close… I still think block#1 would generate false positives at times when the door has not been open the required number of minutes - although admittedly I haven’t tested to confirm.

My last version above (bckm) is working now. I removed the unnecessary time and location mode subscriptions, so there are just 2 subscriptions to both motion and the door sensor events.

I am still curious about subscription behavior though, if anyone can shed light on what I saw in the logs:

GeorgeH:

There seems an inconsistency in how the subscription to line 26 (contact sensors) and line 33 (motion sensor IF) behave. For line 33, the log ONLY shows the “inactive” event invoking the piston, i.e.:

╔Received event [Garage Multi Sensor].motion = inactive

I would have expected either an active or inactive event to invoke the piston. I never get the log info for the related “log info” statement executed either, nor a received event in the log showing motion = active.

But, for the line 26 “subscription”, that seems to invoke the piston both when the sensor changes to OPEN and also when the sensor changes to CLOSED state (as shown in the log snipped, at least the close case).

The line 26 subscription was setup as “automatic”, whereas the latter line 33 subscription I forced to “always subscribe” … but I would not expect a difference in behavior due to that.

So I guess my question is whether subscriptions are to the event itself, or the instead to a qualified condition specified in the relevant piston statement (i.e. event qualified by a condition test)? Both cases seem to be exhibited by my piston, which confuses me! (Admittedly easily confused these days;-).

WCmore · 2018-10-07 17:55:48 UTC

The possibility can occur if you tripped the motion sensor, but did not open the door… Lets say 8 minutes pass, and then you open the door without being near the motion sensor. In that rare case, the alert would be sent in two minutes, UNLESS you walked by the motion sensor in that time…

I have one last piston to offer…

This one guarantees that both door open and inactivity BOTH have to be 10 minutes.

GeorgeH · 2018-10-07 21:44:59 UTC

Agree that should work – appreciate the suggestions!

Do you know whether the line 25 subscription causes the piston to fire for any contact sensor event change, or only when the contact sensor has stayed open for N minutes? (basically the question I had posed above).

WCmore · 2018-10-07 23:42:56 UTC

I believe when you subscribe to a device, and that device reports a change, the piston runs thru the code to see if anything is true. This means, unless you add conflicting code, the only thing that could possibly be executed is the final block. (governed by the 2 conditions)

The good news is, even if the wind blowing executed the piston, nothing in the code above would actually do anything unless it was past the 10 minute mark on both devices. (notice they are all triggers, except the last block is all conditions)