Piston not firing Echo Speaks after wait

sartzava · 2020-05-17 23:14:41 UTC

1) Give a description of the problem
I have been working on my SHM piston over the last few days. It watches for changes to the front and back door locks (based on this awesome example: Door Locks and User Codes). It also watches for changes in occupancy levels (based on another example I found a few days ago).

2) What is the expected behaviour?
When the piston is triggered to execute, it is supposed to do a few things, then wait for there to be activity on the relevant motion sensor, then speak a random welcome home phrase.

3) What is happening/not happening?
The speaking is not happening. I can’t tell if there’s something wrong with how I have the Wait command working or if there’s something wrong with the speaking itself. The rest of the piston triggers successfully.

I’m also surprised that the While command seems to be causing the entire piston to fire a second time, then it just ends. I thought While would continue running. Maybe there’s a better way to do that than using a Wait inside the White?

**4) Post a Green Snapshot of the piston!

5) Attach logs after turning logging level to Full
5/17/2020, 4:11:48 PM +88ms
+0ms ╔Received event [Home].time = 1589757109440 with a delay of -1353ms
+143ms ║RunTime Analysis CS > 18ms > PS > 60ms > PE > 65ms > CE
+147ms ║Runtime (76995 bytes) successfully initialized in 60ms (v0.3.110.20191009) (146ms)
+148ms ║╔Execution stage started
+154ms ║║Evaluating switch with values [[i:2:null:0, v:[t:dynamic, v:keypad]]]
+157ms ║║Comparison (dynamic) keypad is (string) manual = false (1ms)
+162ms ║║Comparison (dynamic) keypad is (string) keypad = true (1ms)
+167ms ║║Evaluating switch with values [[i:24:null:0, v:[t:boolean, v:false, d:2, vt:string]]]
+170ms ║║Comparison (boolean) false is (boolean) false = true (1ms)
+183ms ║║Evaluating switch with values [[i::473ef8ef2e026802057d9bd6a0fb5adf::lock, v:[t:enum, v:unlocked, d::473ef8ef2e026802057d9bd6a0fb5adf:, a:lock, i:[], x:false, vt:string]]]
+186ms ║║Comparison (enum) unlocked is (string) locked = false (1ms)
+190ms ║║Comparison (enum) unlocked is (string) unknown = false (1ms)
+199ms ║║Evaluating switch with values [[i:122:null:0, v:[t:dynamic, v:keypad]]]
+201ms ║║Comparison (dynamic) keypad is (string) manual = false (1ms)
+206ms ║║Comparison (dynamic) keypad is (string) keypad = true (1ms)
+211ms ║║Evaluating switch with values [[i:131:null:0, v:[t:boolean, v:false, d:2, vt:string]]]
+214ms ║║Comparison (boolean) false is (boolean) false = true (1ms)
+225ms ║║Evaluating switch with values [[i::473ef8ef2e026802057d9bd6a0fb5adf::lock, v:[t:enum, v:unlocked, d::473ef8ef2e026802057d9bd6a0fb5adf:, a:lock, i:[], x:false, vt:string]]]
+228ms ║║Comparison (enum) unlocked is (string) locked = false (1ms)
+233ms ║║Comparison (enum) unlocked is (string) unknown = false (1ms)
+313ms ║║Comparison (enum) active is (string) inactive = false (2ms)
+314ms ║║Cancelling condition #169’s schedules…
+315ms ║║Condition #169 evaluated false (7ms)
+316ms ║║Cancelling condition #168’s schedules…
+317ms ║║Condition group #168 evaluated false (state changed) (10ms)
+319ms ║║Cancelling statement #172’s schedules…
+390ms ║║Executed physical command [Echo - Kitchen Echo Dot].playText([What’s up?, 5]) (60ms)
+391ms ║║Executed [Echo - Kitchen Echo Dot].playText (61ms)
+396ms ║║Comparison (dynamic) null changes_to (string) Keypad = false (1ms)
+397ms ║║Condition #198 evaluated false (3ms)
+398ms ║║Condition group #197 evaluated false (state did not change) (4ms)
+400ms ║╚Execution stage complete. (253ms)
+401ms ╚Event processed successfully (401ms)
5/17/2020, 4:11:44 PM +98ms
+1ms ╔Received event [Home].time = 1589757105436 with a delay of -1338ms
+152ms ║RunTime Analysis CS > 21ms > PS > 62ms > PE > 69ms > CE
+157ms ║Runtime (76995 bytes) successfully initialized in 62ms (v0.3.110.20191009) (154ms)
+157ms ║╔Execution stage started
+163ms ║║Evaluating switch with values [[i:2:null:0, v:[t:dynamic, v:keypad]]]
+166ms ║║Comparison (dynamic) keypad is (string) manual = false (1ms)
+171ms ║║Comparison (dynamic) keypad is (string) keypad = true (1ms)
+177ms ║║Evaluating switch with values [[i:24:null:0, v:[t:boolean, v:false, d:1, vt:string]]]
+180ms ║║Comparison (boolean) false is (boolean) false = true (2ms)
+194ms ║║Evaluating switch with values [[i::473ef8ef2e026802057d9bd6a0fb5adf::lock, v:[t:enum, v:unlocked, d::473ef8ef2e026802057d9bd6a0fb5adf:, a:lock, i:[], x:false, vt:string]]]
+197ms ║║Comparison (enum) unlocked is (string) locked = false (1ms)
+202ms ║║Comparison (enum) unlocked is (string) unknown = false (1ms)
+210ms ║║Evaluating switch with values [[i:122:null:0, v:[t:dynamic, v:keypad]]]
+213ms ║║Comparison (dynamic) keypad is (string) manual = false (1ms)
+218ms ║║Comparison (dynamic) keypad is (string) keypad = true (1ms)
+224ms ║║Evaluating switch with values [[i:131:null:0, v:[t:boolean, v:false, d:1, vt:string]]]
+227ms ║║Comparison (boolean) false is (boolean) false = true (2ms)
+240ms ║║Evaluating switch with values [[i::473ef8ef2e026802057d9bd6a0fb5adf::lock, v:[t:enum, v:unlocked, d::473ef8ef2e026802057d9bd6a0fb5adf:, a:lock, i:[], x:false, vt:string]]]
+243ms ║║Comparison (enum) unlocked is (string) locked = false (2ms)
+247ms ║║Comparison (enum) unlocked is (string) unknown = false (1ms)
+332ms ║║Comparison (enum) inactive is (string) inactive = true (2ms)
+334ms ║║Condition #169 evaluated true (9ms)
+335ms ║║Condition group #168 evaluated true (state did not change) (10ms)
+337ms ║║Cancelling statement #170’s schedules…
+340ms ║║Executed virtual command wait (0ms)
+342ms ║║Requesting a wake up for Sun, May 17 2020 @ 4:11:49 PM PDT (in 5.0s)
+346ms ║╚Execution stage complete. (189ms)
+348ms ║Setting up scheduled job for Sun, May 17 2020 @ 4:11:49 PM PDT (in 4.995s)
+355ms ╚Event processed successfully (355ms)
5/17/2020, 4:11:40 PM +104ms
+1ms ╔Received event [Home].time = 1589757101357 with a delay of -1253ms
+143ms ║RunTime Analysis CS > 20ms > PS > 55ms > PE > 68ms > CE
+148ms ║Runtime (76995 bytes) successfully initialized in 55ms (v0.3.110.20191009) (147ms)
+149ms ║╔Execution stage started
+155ms ║║Evaluating switch with values [[i:2:null:0, v:[t:dynamic, v:keypad]]]
+158ms ║║Comparison (dynamic) keypad is (string) manual = false (1ms)
+163ms ║║Comparison (dynamic) keypad is (string) keypad = true (1ms)
+169ms ║║Evaluating switch with values [[i:24:null:0, v:[t:boolean, v:false, d:2, vt:string]]]
+172ms ║║Comparison (boolean) false is (boolean) false = true (1ms)
+185ms ║║Evaluating switch with values [[i::473ef8ef2e026802057d9bd6a0fb5adf::lock, v:[t:enum, v:unlocked, d::473ef8ef2e026802057d9bd6a0fb5adf:, a:lock, i:[], x:false, vt:string]]]
+188ms ║║Comparison (enum) unlocked is (string) locked = false (2ms)
+193ms ║║Comparison (enum) unlocked is (string) unknown = false (1ms)
+202ms ║║Evaluating switch with values [[i:122:null:0, v:[t:dynamic, v:keypad]]]
+205ms ║║Comparison (dynamic) keypad is (string) manual = false (2ms)
+210ms ║║Comparison (dynamic) keypad is (string) keypad = true (1ms)
+216ms ║║Evaluating switch with values [[i:131:null:0, v:[t:boolean, v:false, d:2, vt:string]]]
+219ms ║║Comparison (boolean) false is (boolean) false = true (1ms)
+231ms ║║Evaluating switch with values [[i::473ef8ef2e026802057d9bd6a0fb5adf::lock, v:[t:enum, v:unlocked, d::473ef8ef2e026802057d9bd6a0fb5adf:, a:lock, i:[], x:false, vt:string]]]
+234ms ║║Comparison (enum) unlocked is (string) locked = false (1ms)
+239ms ║║Comparison (enum) unlocked is (string) unknown = false (2ms)
+322ms ║║Comparison (enum) inactive is (string) inactive = true (1ms)
+323ms ║║Condition #169 evaluated true (8ms)
+324ms ║║Condition group #168 evaluated true (state did not change) (10ms)
+326ms ║║Cancelling statement #170’s schedules…
+330ms ║║Executed virtual command wait (1ms)
+331ms ║║Requesting a wake up for Sun, May 17 2020 @ 4:11:45 PM PDT (in 5.0s)
+336ms ║╚Execution stage complete. (187ms)
+337ms ║Setting up scheduled job for Sun, May 17 2020 @ 4:11:45 PM PDT (in 4.995s)
+346ms ╚Event processed successfully (346ms)
5/17/2020, 4:11:26 PM +78ms
+1ms ╔Received event [Back Door].lock = unlocked with a delay of 126ms
+9984ms ║RunTime Analysis CS > 94ms > PS > 9822ms > PE > 69ms > CE
+9985ms ║Piston waited at a semaphore for 9770ms
+9989ms ║Runtime (77084 bytes) successfully initialized in 9822ms (v0.3.110.20191009) (9987ms)
+9990ms ║╔Execution stage started
+9996ms ║║Evaluating switch with values [[i:2:null:0, v:[t:dynamic, v:keypad]]]
+9999ms ║║Comparison (dynamic) keypad is (string) manual = false (1ms)
+10002ms ║║Comparison (dynamic) keypad is (string) keypad = true (1ms)
+10004ms ║║Cancelling statement #9’s schedules…
+10010ms ║║Executed virtual command setVariable (3ms)
+10015ms ║║Evaluating switch with values [[i:24:null:0, v:[t:boolean, v:false, d:2, vt:string]]]
+10019ms ║║Comparison (boolean) false is (boolean) false = true (2ms)
+10021ms ║║Cancelling statement #29’s schedules…
+10026ms ║║Executed virtual command setVariable (3ms)
+10032ms ║║Executed virtual command setVariable (3ms)
+10036ms ║║Evaluating switch with values [[i::473ef8ef2e026802057d9bd6a0fb5adf::lock, v:[t:enum, v:unlocked, d::473ef8ef2e026802057d9bd6a0fb5adf:, a:lock, i:[], x:false, vt:string]]]
+10040ms ║║Comparison (enum) unlocked is (string) locked = false (2ms)
+10043ms ║║Comparison (enum) unlocked is (string) unknown = false (2ms)
+10045ms ║║Cancelling statement #39’s schedules…
+10051ms ║║Executed virtual command setVariable (2ms)
+10054ms ║║Cancelling statement #45’s schedules…
+10062ms ║║Executed virtual command setVariable (4ms)
+10069ms ║║Comparison (dynamic) 2 rises = false (1ms)
+10070ms ║║Condition #70 evaluated false (3ms)
+10071ms ║║Condition group #69 evaluated false (state did not change) (4ms)
+10074ms ║║Cancelling statement #56’s schedules…
+10078ms ║║Calculating (string) Last event occurred on + (string) Sun, May 17 2020 @ 4:11:36 PM PDT >> (string) Last event occurred on Sun, May 17 2020 @ 4:11:36 PM PDT
+10081ms ║║Executed virtual command setState (1ms)
+10086ms ║║Comparison (dynamic) Keypad changes_to (string) Keypad = true (0ms)
+10087ms ║║Cancelling condition #119’s schedules…
+10088ms ║║Condition #119 evaluated true (5ms)
+10092ms ║║Comparison (dynamic) Unlocked is (string) Unlocked = true (1ms)
+10093ms ║║Condition #156 evaluated true (4ms)
+10094ms ║║Cancelling condition #155’s schedules…
+10095ms ║║Condition group #155 evaluated true (state changed) (12ms)
+10106ms ║║Comparison (time) 58296175 is_between (time) 79200000 … (time) 18000000 = false (7ms)
+10108ms ║║Condition #159 evaluated false (11ms)
+10109ms ║║Condition group #157 evaluated false (state did not change) (13ms)
+10120ms ║║Comparison (time) 58296188 is_between (time) 75600000 … (time) 79200000 = false (7ms)
+10121ms ║║Condition #174 evaluated false (11ms)
+10122ms ║║Condition group #158 evaluated false (state did not change) (12ms)
+10125ms ║║Cancelling statement #160’s schedules…
+10162ms ║║Executed virtual command setAlarmSystemStatus (34ms)
+10199ms ║║Executed virtual command setLocationMode (35ms)
+10209ms ║║Calculating (string) Smart Home Monitor SHM is + (string) Disarmed >> (string) Smart Home Monitor SHM is Disarmed
+10211ms ║║Calculating (string) Smart Home Monitor SHM is Disarmed + (string) . Mode is Home. >> (string) Smart Home Monitor SHM is Disarmed. Mode is Home.
+10237ms ║║Executed virtual command sendPushNotification (22ms)
+10240ms ║║Cancelling statement #164’s schedules…
+10245ms ║║Skipped execution of physical command [Back Door].unlock([]) because it would make no change to the device. (1ms)
+10246ms ║║Executed [Back Door].unlock (3ms)
+10249ms ║║Cancelling statement #166’s schedules…
+10256ms ║║Skipped execution of physical command [Kitchen Main Lights].on([]) because it would make no change to the device. (2ms)
+10256ms ║║Executed [Kitchen Main Lights].on (4ms)
+10267ms ║║Comparison (enum) inactive is (string) inactive = true (2ms)
+10268ms ║║Cancelling condition #169’s schedules…
+10269ms ║║Condition #169 evaluated true (10ms)
+10270ms ║║Cancelling condition #168’s schedules…
+10271ms ║║Condition group #168 evaluated true (state changed) (12ms)
+10274ms ║║Cancelling statement #170’s schedules…
+10277ms ║║Executed virtual command wait (0ms)
+10279ms ║║Requesting a wake up for Sun, May 17 2020 @ 4:11:41 PM PDT (in 5.0s)
+10283ms ║╚Execution stage complete. (293ms)
+10290ms ║Setting up scheduled job for Sun, May 17 2020 @ 4:11:41 PM PDT (in 4.99s)
+10298ms ╚Event processed successfully (10299ms)
5/17/2020, 4:11:25 PM +835ms
+2ms ╔Received event [Back Door].lock = unlocked with a delay of 106ms
+134ms ║RunTime Analysis CS > 19ms > PS > 51ms > PE > 64ms > CE
+138ms ║Runtime (76996 bytes) successfully initialized in 51ms (v0.3.110.20191009) (136ms)
+139ms ║╔Execution stage started
+145ms ║║Evaluating switch with values [[i:2:null:0, v:[t:dynamic, v:null]]]
+147ms ║║Comparison (dynamic) null is (string) manual = false (1ms)
+151ms ║║Comparison (dynamic) null is (string) keypad = false (1ms)
+153ms ║║Cancelling statement #5’s schedules…
+158ms ║║Executed virtual command setVariable (3ms)
+163ms ║║Executed virtual command setVariable (3ms)
+167ms ║║Executed virtual command setVariable (2ms)
+171ms ║║Evaluating switch with values [[i::473ef8ef2e026802057d9bd6a0fb5adf::lock, v:[t:enum, v:unlocked, d::473ef8ef2e026802057d9bd6a0fb5adf:, a:lock, i:[], x:false, vt:string]]]
+174ms ║║Comparison (enum) unlocked is (string) locked = false (1ms)
+177ms ║║Comparison (enum) unlocked is (string) unknown = false (1ms)
+179ms ║║Cancelling statement #39’s schedules…
+184ms ║║Executed virtual command setVariable (3ms)
+187ms ║║Cancelling statement #45’s schedules…
+194ms ║║Executed virtual command setVariable (3ms)
+200ms ║║Comparison (dynamic) 2 rises = false (1ms)
+201ms ║║Condition #70 evaluated false (3ms)
+202ms ║║Condition group #69 evaluated false (state did not change) (4ms)
+204ms ║║Cancelling statement #56’s schedules…
+209ms ║║Calculating (string) Last event occurred on + (string) Sun, May 17 2020 @ 4:11:26 PM PDT >> (string) Last event occurred on Sun, May 17 2020 @ 4:11:26 PM PDT
+211ms ║║Executed virtual command setState (0ms)
+216ms ║║Comparison (dynamic) Programically changes_to (string) Keypad = false (0ms)
+218ms ║║Condition #119 evaluated false (3ms)
+219ms ║║Condition group #155 evaluated false (state did not change) (4ms)
+223ms ║║Comparison (dynamic) null changes_to (string) Keypad = false (1ms)
+224ms ║║Condition #198 evaluated false (3ms)
+225ms ║║Condition group #197 evaluated false (state did not change) (5ms)
+227ms ║╚Execution stage complete. (88ms)
+228ms ╚Event processed successfully (228ms)

Terminal · 2020-05-18 02:18:34 UTC

Just did a cursory look and there is a quite a bit to look through. But maybe look at the Task Cancellation Policy (TCP) of some of your code. Each time a trigger fires the Piston starts back at the beginning.
The condition you describe of the piston firing again is specifically what the TCP can help mitigate.

Maybe you already thought of this, here is a link to a wiki article.

sartzava · 2020-05-18 04:12:53 UTC

Thanks, I did think about that after posting, and I’ve changed it. I will have to test it tomorrow.

Terminal · 2020-05-18 11:28:19 UTC

Something else that may be problematic, is using a global variable as a trigger. Maybe it will work, but as I understand it globals don’t get updated in the piston until it fires? So I am not sure it will ever fire.

So I am curious if that works or not.

sartzava · 2020-05-18 13:27:08 UTC

Yes, the Occupancy variable works fine. The event is definitely triggering when that changes.

sartzava · 2020-05-19 13:28:34 UTC

Come to find out the problem with this is actually with Echo Speaks not using the speak variable. The solution was provided in this other post.

Regarding the pause, I was able to find some other details about waiting functions, and instead used the Followed By condition group to set it up to play the message when the motion detector “followed within 10 minutes” with activation.