Wait being unexpectedly interrupted

RayK18 · 2019-08-14 15:01:57 UTC

1) Give a description of the problem
This piston supervises the garage door. If left open for a long duration it will close it. The duration for use will be longer (25 minutes), however, for testing it is currently at 2 minutes. The closing of the garage door is accomplished by a garage door remote that I have connected to a smart outlet. This all works well.

HOWEVER, what does not work is the 24-hour lockout. On the trace I see the 24-hour wait start counting but when the garage contact is closed it breaks the wait loop and is ready to start another supervisory period if the contact is opened.

I have tried everything: making the WHILE clause never break, the WITH clause never break, the IF clause automatic subscribe or always subscribe.

Why is the 24-hour wait being interrupted? Seems like it should not.

Thanks in advance

Cheers, Ray

2) What is the expected behaviour?
(PUT YOUR INFO HERE)

3) What is happening/not happening?
(PUT YOUR INFO HERE)

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

5) Attach logs after turning logging level to Full
(PASTE YOUR LOGS HERE THEN HIGHLIGHT ALL OF THE LOGS AND CLICK ON THE </> ICON TO FORMAT THEM CORRECTLY)

8/14/2019, 10:40:19 AM +430ms
+2ms ╔Received event [Desk Chair].contact = closed with a delay of 95ms
+95ms ║RunTime Analysis CS > 21ms > PS > 48ms > PE > 25ms > CE
+97ms ║Runtime (44303 bytes) successfully initialized in 48ms (v0.3.10e.20190628) (95ms)
+98ms ║╔Execution stage started
+108ms ║║Comparison (enum) closed changes_to (string) open = false (1ms)
+110ms ║║Cancelling condition #3’s schedules…
+110ms ║║Condition #3 evaluated false (7ms)
+111ms ║║Cancelling condition #2’s schedules…
+112ms ║║Condition group #2 evaluated false (state changed) (9ms)
+113ms ║║Cancelling condition #1’s schedules…
+114ms ║║Condition group #1 evaluated false (state changed) (12ms)
+117ms ║╚Execution stage complete. (19ms)
+119ms ║Setting up scheduled job for Thu, Aug 15 2019 @ 10:39:48 AM EDT (in 86369.28s)
+131ms ╚Event processed successfully (131ms)
8/14/2019, 10:40:08 AM +512ms
+1ms ╔Received event [Desk Chair].contact = open with a delay of 108ms
+92ms ║RunTime Analysis CS > 22ms > PS > 47ms > PE > 23ms > CE
+94ms ║Runtime (44310 bytes) successfully initialized in 47ms (v0.3.10e.20190628) (92ms)
+95ms ║╔Execution stage started
+105ms ║║Comparison (enum) open changes_to (string) open = true (1ms)
+107ms ║║Cancelling condition #3’s schedules…
+108ms ║║Condition #3 evaluated true (7ms)
+113ms ║║Comparison (boolean) false is_not (boolean) true = true (2ms)
+115ms ║║Condition #4 evaluated true (6ms)
+116ms ║║Cancelling condition #2’s schedules…
+116ms ║║Condition group #2 evaluated true (state changed) (16ms)
+117ms ║║Cancelling condition #1’s schedules…
+118ms ║║Condition group #1 evaluated true (state changed) (19ms)
+122ms ║║Cancelling statement #6’s schedules…
+127ms ║║Executed virtual command setVariable (3ms)
+135ms ║║Comparison (enum) open is (string) open = true (1ms)
+137ms ║║Condition #9 evaluated true (7ms)
+143ms ║║Comparison (boolean) false is_not (boolean) true = true (2ms)
+144ms ║║Condition #10 evaluated true (6ms)
+145ms ║║Condition group #8 evaluated true (state did not change) (15ms)
+148ms ║║Cancelling statement #11’s schedules…
+153ms ║║Calculating (integer) 0 + (integer) 1 >> (integer) 1
+158ms ║║Executed virtual command setVariable (3ms)
+163ms ║║Executed virtual command wait (1ms)
+164ms ║║Requesting a wake up for Wed, Aug 14 2019 @ 10:41:08 AM EDT (in 60.0s)
+170ms ║╚Execution stage complete. (75ms)
+172ms ║Setting up scheduled job for Wed, Aug 14 2019 @ 10:41:08 AM EDT (in 59.994s), with 1 more job pending
+185ms ╚Event processed successfully (185ms)
8/14/2019, 10:39:56 AM +3ms
+1ms ╔Received event [Desk Chair].contact = closed with a delay of 96ms
+105ms ║RunTime Analysis CS > 30ms > PS > 52ms > PE > 23ms > CE
+108ms ║Runtime (44304 bytes) successfully initialized in 52ms (v0.3.10e.20190628) (106ms)
+109ms ║╔Execution stage started
+118ms ║║Comparison (enum) closed changes_to (string) open = false (1ms)
+120ms ║║Cancelling condition #3’s schedules…
+121ms ║║Condition #3 evaluated false (6ms)
+122ms ║║Cancelling condition #2’s schedules…
+123ms ║║Condition group #2 evaluated false (state changed) (9ms)
+124ms ║║Cancelling condition #1’s schedules…
+124ms ║║Condition group #1 evaluated false (state changed) (11ms)
+127ms ║╚Execution stage complete. (18ms)
+128ms ║Setting up scheduled job for Thu, Aug 15 2019 @ 10:39:48 AM EDT (in 86392.697s)
+140ms ╚Event processed successfully (140ms)
8/14/2019, 10:39:47 AM +121ms
+0ms ╔Received event [Home].time = 1565793588244 with a delay of -1124ms
+90ms ║RunTime Analysis CS > 26ms > PS > 43ms > PE > 21ms > CE
+92ms ║Runtime (44306 bytes) successfully initialized in 43ms (v0.3.10e.20190628) (91ms)
+93ms ║╔Execution stage started
+112ms ║║Comparison (integer) 2 is_equal_to (integer) 2 = true (1ms)
+114ms ║║Cancelling condition #15’s schedules…
+115ms ║║Condition #15 evaluated true (6ms)
+116ms ║║Cancelling condition #14’s schedules…
+117ms ║║Condition group #14 evaluated true (state changed) (8ms)
+120ms ║║Cancelling statement #17’s schedules…
+136ms ║║Executed physical command [Bedroom Light].on() (12ms)
+137ms ║║Executed [Bedroom Light].on (14ms)
+143ms ║║Executed virtual command [Bedroom Light].wait (1ms)
+145ms ║║Waiting for 1500ms
+1658ms ║║Executed physical command [Bedroom Light].off() (10ms)
+1659ms ║║Executed [Bedroom Light].off (12ms)
+1663ms ║║Executed virtual command [Bedroom Light].setVariable (1ms)
+1700ms ║║Executed virtual command [Bedroom Light].sendSMSNotification (30ms)
+1705ms ║║Executed virtual command [Bedroom Light].wait (0ms)
+1706ms ║║Requesting a wake up for Thu, Aug 15 2019 @ 10:39:48 AM EDT (in 86400.0s)
+1711ms ║╚Execution stage complete. (1618ms)
+1713ms ║Setting up scheduled job for Thu, Aug 15 2019 @ 10:39:48 AM EDT (in 86399.995s)
+1721ms ╚Event processed successfully (1720ms)
8/14/2019, 10:38:48 AM +84ms
+1ms ╔Received event [Home].time = 1565793529914 with a delay of -1830ms
+87ms ║RunTime Analysis CS > 19ms > PS > 45ms > PE > 23ms > CE
+90ms ║Runtime (44304 bytes) successfully initialized in 45ms (v0.3.10e.20190628) (88ms)
+91ms ║╔Execution stage started
+113ms ║║Comparison (integer) 1 is_equal_to (integer) 2 = false (2ms)
+115ms ║║Cancelling condition #15’s schedules…
+116ms ║║Condition #15 evaluated false (7ms)
+117ms ║║Cancelling condition #14’s schedules…
+118ms ║║Condition group #14 evaluated false (state changed) (10ms)
+130ms ║║Comparison (enum) open is (string) open = true (2ms)
+132ms ║║Condition #9 evaluated true (11ms)
+138ms ║║Comparison (boolean) false is_not (boolean) true = true (2ms)
+139ms ║║Condition #10 evaluated true (6ms)
+140ms ║║Condition group #8 evaluated true (state did not change) (21ms)
+143ms ║║Cancelling statement #11’s schedules…
+149ms ║║Calculating (integer) 1 + (integer) 1 >> (integer) 2
+154ms ║║Executed virtual command setVariable (3ms)
+158ms ║║Executed virtual command wait (1ms)
+159ms ║║Requesting a wake up for Wed, Aug 14 2019 @ 10:39:48 AM EDT (in 60.0s)
+164ms ║╚Execution stage complete. (73ms)
+166ms ║Setting up scheduled job for Wed, Aug 14 2019 @ 10:39:48 AM EDT (in 59.995s)
+173ms ╚Event processed successfully (173ms)
8/14/2019, 10:37:49 AM +759ms
+1ms ╔Received event [Desk Chair].contact = open with a delay of 94ms
+80ms ║RunTime Analysis CS > 18ms > PS > 44ms > PE > 19ms > CE
+83ms ║Runtime (44311 bytes) successfully initialized in 44ms (v0.3.10e.20190628) (81ms)
+84ms ║╔Execution stage started
+94ms ║║Comparison (enum) open changes_to (string) open = true (0ms)
+95ms ║║Cancelling condition #3’s schedules…
+96ms ║║Condition #3 evaluated true (7ms)
+102ms ║║Comparison (boolean) false is_not (boolean) true = true (1ms)
+103ms ║║Condition #4 evaluated true (6ms)
+104ms ║║Cancelling condition #2’s schedules…
+105ms ║║Condition group #2 evaluated true (state changed) (16ms)
+106ms ║║Cancelling condition #1’s schedules…
+107ms ║║Condition group #1 evaluated true (state changed) (19ms)
+110ms ║║Cancelling statement #6’s schedules…
+116ms ║║Executed virtual command setVariable (3ms)
+124ms ║║Comparison (enum) open is (string) open = true (1ms)
+126ms ║║Cancelling condition #9’s schedules…
+127ms ║║Condition #9 evaluated true (8ms)
+132ms ║║Comparison (boolean) false is_not (boolean) true = true (1ms)
+134ms ║║Condition #10 evaluated true (6ms)
+135ms ║║Cancelling condition #8’s schedules…
+136ms ║║Condition group #8 evaluated true (state changed) (18ms)
+138ms ║║Cancelling statement #11’s schedules…
+143ms ║║Calculating (integer) 0 + (integer) 1 >> (integer) 1
+148ms ║║Executed virtual command setVariable (3ms)
+153ms ║║Executed virtual command wait (0ms)
+154ms ║║Requesting a wake up for Wed, Aug 14 2019 @ 10:38:49 AM EDT (in 60.0s)
+159ms ║╚Execution stage complete. (75ms)
+161ms ║Setting up scheduled job for Wed, Aug 14 2019 @ 10:38:49 AM EDT (in 59.995s)
+174ms ╚Event processed successfully (175ms)

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

ike2018 · 2019-08-14 19:15:04 UTC

i’m not a coder or an expert on WC and not sure if I can help you with this piston
but just wanted to understand why your piston is so complicated?

Why something as simple as this wouldn’t work?

IF garage door contact STAYS open 25 minutes
Then 
With garage door outlet
Do 
Turn OFF

Robin · 2019-08-14 20:22:31 UTC

Without looking too hard, it may be to do with your use of the changes to trigger on line 36.

Changes to has a habit of not lasting very long, I think about 10 seconds after the change it reverts to false, so it triggers and then cancels your piston shortly after.

You might be better off using a condition instead, such as ‘is’.

For pistons such as this I often make use of the age() function, to check the age of the current state of a device, i.e

IF age([garage door : contact]) is greater than X…

RayK18 · 2019-08-14 21:13:59 UTC

Thanks for your thoughts.

The issue at hand is not that the piston doesn’t work properly but rather why the WAIT is interrupted by a switch change.

Regarding it seeming complications the piston has more goals than your sketch. It samples the garage door open interval into 5-minute segments and not just sample once, after 25 minutes. This because the door could have been open for 5 minutes, closed for 10 minutes and then be open again only for 5 minutes when your 25-minute timer would see it as having been open for 25 minutes. I won’t get into the other goals: sending a text message, lock out protection, the fact that opening the door requires a pulse, etc. because, as you suggest you are not a WC coder.

Robin · 2019-08-14 21:23:47 UTC

By default waits and stays will reset the timer on each change, so you don’t need to worry about the whole 5/10/5/25 minute thing… @ike2018’s suggestion would only ever fire after the door stays open for a full uninterrupted 25 minutes.

I’d suggest you’ve gone down a rabbit hole of complication and don’t want to backtrack, undoing your hard work.

You can add your pulse and overrides around the basic example, rather than trying to fix your over complicated example.

Robin · 2019-08-14 21:31:04 UTC

IF garage Door is Open
   THEN
      WITH garage door outlet
         wait 25 minutes (this timer will cancel if door closes)
         turn on
         wait x miliseconds
         turn off
         send SMS
      END WITH
END IF

RayK18 · 2019-08-14 21:34:09 UTC

Robin, thanks for your reply.

The piston executes well with the CHANGES TO trigger construct in place. I have experimented with the IS condition as well. The problem is not that it doesn’t execute correctly (with one exception) it is that the closing of the garage door switch retriggers the piston, it then finds the IF at line #34 is false (as it should), however, this retrigger action cancels the WAIT running at line at line #71.

I have experimented with another very simple piston to try to make the WAIT immune to this, but I can’t. Not changing the trigger nor protecting it by using Never Cancel.

I’m very familiar with real time, interrupt driven, firmware design but I do find some of these issues puzzling.

Thanks again.

Robin · 2019-08-14 21:36:06 UTC

What exactly is the purpose of locking things out for 24 hours?

Have you actually tested this over a 24 hour period or are you watching the trace in the dashboard? When using ‘never cancel’ the trace moves on, yet the timmer is actually still running despite not showing on the dashboard anymore.

Might I suggest a second piston for the 24h lockout… use it to set a global Boolean variable and set that variable as a restriction in the first piston.

RayK18 · 2019-08-14 21:59:21 UTC

The 24 hours lock out is with an abundance of caution. I live in a 25-unit condo building and if the sensor went astray and the garage door when up and down….

I could probably leave it out, however that would still leave the WAIT mystery unsolved.

That said the closing of the garage door retriggers the piston, as I described above, and then it can “see” the garage door open again and react to that.

I agree that the timing display of the WAIT is erased with the new trace so I can’t tell if it is running or not.

I have done most of my testing at much faster intervals (minutes, not hours) by changing the parameters. That is why so many are named instead of directly coded.

Maybe the question I need to understand better is why is the piston retriggered when the switch closes when it is set to CHANGES TO Open?

Your suggestion for a separate piston for the lockout timer with a global flag sounds like a possible solution.

Thanks again.

Robin · 2019-08-14 22:14:49 UTC

You talk about a switch, but your piston is looking at a contact sensor??

Is that just a lost in translation thing?

The piston is looking at all events… a ‘closed’ event is not a ‘changes to Open’ event, thus the evaluation returns false.

WCmore · 2019-08-14 22:23:59 UTC

If you are subscribed (with a lightning bolt) to:
IF Garage's contact changes to open
then webCoRE will be watching for ANY event from Garage’s contact, and that piston will trigger whenever Garage’s contact changes to open OR CLOSE.

It is up to the conditions below to determine what path to take from there.

RayK18 · 2019-08-14 22:26:38 UTC

Yes, sorry for my imprecision (contact).

Thanks for the clarification on the “closed event”

I will let you know how the separate WAIT piston works out.

Cheers, Ray

RayK18 · 2019-08-14 22:27:54 UTC

Thank you for that clarification. I appreciate the help.

RayK18 · 2019-08-14 23:18:01 UTC

Robin

I have isolated the lockout wait timing function in a separate piston with a passed global flag. It solves the problem!

That said, are all WAITs susceptible to cancelation unless isolated in a separate piston. Food for thought.

Regardless, this workaround solves my immediate problem

Once again, thanks for the help.

Cheers, Ray