[RESOLVED] Announce Presence stopped working properly

[pmjoen]

1) Give a description of the problem
This was copied from another persons example, and worked great for a few months. This piston is duplicating the announce once with the incorrect person, then with the correct.

2) What is the expected behaviour?
If someone arrives speak message on specified echo, if someone leaves speak on specified echo.

3) What is happening/not happening?
The logs are detecting the correct person leaving and arriving, but when someone leaves or arrives it is now announcing incorrectly once, then a moment later the correct announcement

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

5) Attach logs after turning logging level to Full
4/30/2019, 10:13:05 AM +119ms
+1ms ╔Received event [Mojo Manor].time = 1556637185810 with a delay of -691ms
+175ms ║RunTime Analysis CS > 28ms > PS > 97ms > PE > 50ms > CE
+178ms ║Runtime (46385 bytes) successfully initialized in 97ms (v0.3.10a.20190223) (176ms)
+179ms ║╔Execution stage started
+187ms ║║Cancelling condition #1’s schedules…
+209ms ║║Calculating (string) Well, it seems that + (string) Eric >> (string) Well, it seems that Eric
+213ms ║║Calculating (string) Well, it seems that Eric + (string) has left the house, >> (string) Well, it seems that Eric has left the house,
+217ms ║║Calculating (string) Well, it seems that Eric has left the house, + (string) oh thank god >> (string) Well, it seems that Eric has left the house, oh thank god
+223ms ║║Executed virtual command setVariable (3ms)
+225ms ║║Condition #10 evaluated true (31ms)
+226ms ║║Condition group #9 evaluated true (state did not change) (33ms)
+229ms ║║Cancelling statement #33’s schedules…
+333ms ║║Executed physical command [Echo - Kitchen].speak([ Well, it seems that Eric has left the house, oh thank god]) (97ms)
+334ms ║║Executed [Echo - Kitchen].speak (99ms)
+337ms ║╚Execution stage complete. (158ms)
+338ms ╚Event processed successfully (338ms)
4/30/2019, 10:12:55 AM +536ms
+1ms ╔Received event [Eric].presence = not present with a delay of 96ms
+138ms ║RunTime Analysis CS > 14ms > PS > 78ms > PE > 45ms > CE
+141ms ║Runtime (46383 bytes) successfully initialized in 78ms (v0.3.10a.20190223) (138ms)
+144ms ║╔Execution stage started
+162ms ║║Comparison (time) 36775685 is_between (time) 28800000 … (time) 75600000 = true (10ms)
+164ms ║║Time restriction check passed
+166ms ║║Condition #32 evaluated true (17ms)
+167ms ║║Condition group #null evaluated true (state did not change) (18ms)
+205ms ║║Comparison (enum) not present changes_to (string) present = false (1ms)
+210ms ║║Condition #2 evaluated false (40ms)
+211ms ║║Cancelling statement #1’s schedules…
+213ms ║║Condition group #1 evaluated false (state did not change) (42ms)
+245ms ║║Comparison (enum) not present changes_to (string) not present = true (1ms)
+255ms ║║Cancelling condition #10’s schedules…
+258ms ║║Cancelling statement #26’s schedules…
+266ms ║║Executed virtual command setVariable (4ms)
+271ms ║║Executed virtual command wait (1ms)
+273ms ║║Requesting a wake up for Tue, Apr 30 2019 @ 10:13:05 AM CDT (in 10.0s)
+277ms ║║Condition #10 evaluated true (61ms)
+278ms ║║Cancelling condition #9’s schedules…
+279ms ║║Condition group #9 evaluated true (state changed) (63ms)
+282ms ║║Cancelling statement #33’s schedules…
+566ms ║║Executed physical command [Echo - Kitchen].speak([ Well, it seems that Patrick has left the house, oh thank you jesus]) (277ms)
+567ms ║║Executed [Echo - Kitchen].speak (279ms)
+573ms ║╚Execution stage complete. (432ms)
+575ms ║Setting up scheduled job for Tue, Apr 30 2019 @ 10:13:05 AM CDT (in 9.7s)
+584ms ╚Event processed successfully (584ms)

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

[WCmore]

It helps to include a green snapshot with TRACE turned on. This adds numbers to the end of each line that matches up with the log.

---

oh thank you jesus

I do not see this code anywhere in your piston, so you must have made changes to your piston since the snapshot and the log…

[eibyer]

Is a miracle

[pmjoen]

I actually changed recently to “oh thank god”… lol

[WCmore]

Too funny!

I will re-look at your piston when you’ve posted a matching log & snapshot (w/Trace).
It makes debugging so much easier.

I currently suspect deleting the WAIT on line 49 (or moving it lower in the code) will resolve it.
(Due to your ASYNC)

[pmjoen]

Trace Logs:

4/30/2019, 3:47:34 PM +138ms
+0ms ╔Received event [Mojo Manor].time = 1556657255390 with a delay of -1253ms
+177ms ║RunTime Analysis CS > 27ms > PS > 98ms > PE > 52ms > CE
+180ms ║Runtime (46373 bytes) successfully initialized in 98ms (v0.3.10a.20190223) (178ms)
+181ms ║╔Execution stage started
+191ms ║║Cancelling condition #1’s schedules…
+215ms ║║Calculating (string) Well, it seems that + (string) Eric >> (string) Well, it seems that Eric
+220ms ║║Calculating (string) Well, it seems that Eric + (string) has left the house, >> (string) Well, it seems that Eric has left the house,
+224ms ║║Calculating (string) Well, it seems that Eric has left the house, + (string) good rittance >> (string) Well, it seems that Eric has left the house, good rittance
+231ms ║║Executed virtual command setVariable (4ms)
+233ms ║║Condition #10 evaluated true (35ms)
+234ms ║║Condition group #9 evaluated true (state did not change) (37ms)
+237ms ║║Cancelling statement #33’s schedules…
+353ms ║║Executed physical command [Echo - Kitchen].speak([ Well, it seems that Eric has left the house, good rittance]) (108ms)
+355ms ║║Executed [Echo - Kitchen].speak (110ms)
+358ms ║╚Execution stage complete. (177ms)
+359ms ╚Event processed successfully (359ms)
4/30/2019, 3:47:25 PM +72ms
+1ms ╔Received event [Eric].presence = not present with a delay of 83ms
+191ms ║RunTime Analysis CS > 20ms > PS > 123ms > PE > 48ms > CE
+194ms ║Runtime (46369 bytes) successfully initialized in 123ms (v0.3.10a.20190223) (192ms)
+195ms ║╔Execution stage started
+213ms ║║Comparison (time) 56845272 is_between (time) 28800000 … (time) 75600000 = true (10ms)
+214ms ║║Time restriction check passed
+216ms ║║Condition #32 evaluated true (16ms)
+218ms ║║Condition group #null evaluated true (state did not change) (18ms)
+255ms ║║Comparison (enum) not present changes_to (string) present = false (1ms)
+260ms ║║Condition #2 evaluated false (38ms)
+261ms ║║Cancelling statement #1’s schedules…
+262ms ║║Condition group #1 evaluated false (state did not change) (42ms)
+296ms ║║Comparison (enum) not present changes_to (string) not present = true (1ms)
+299ms ║║Cancelling condition #10’s schedules…
+302ms ║║Cancelling statement #26’s schedules…
+311ms ║║Executed virtual command setVariable (3ms)
+315ms ║║Executed virtual command wait (1ms)
+317ms ║║Requesting a wake up for Tue, Apr 30 2019 @ 3:47:35 PM CDT (in 10.0s)
+321ms ║║Condition #10 evaluated true (55ms)
+322ms ║║Cancelling condition #9’s schedules…
+323ms ║║Condition group #9 evaluated true (state changed) (58ms)
+326ms ║║Cancelling statement #33’s schedules…
+634ms ║║Executed physical command [Echo - Kitchen].speak([Welcome Back Lexi, let’s get this party started]) (300ms)
+635ms ║║Executed [Echo - Kitchen].speak (303ms)
+638ms ║╚Execution stage complete. (443ms)
+640ms ║Setting up scheduled job for Tue, Apr 30 2019 @ 3:47:35 PM CDT (in 9.679s)
+651ms ╚Event processed successfully (651ms)

[WCmore]

Thanks for the update… I think my hunch is correct.

I would move the WAIT down a bit - Somewhere below the “Set variable {ReceivedMsg}” on line 50. It is ok to wait before the Speak command, but you want to set that variable as soon as possible.

---

I believe all this is because you have “when true” on line 47.
Using “when true” with a WAIT can make things happen out of order…
(which is why it’s speaking the old variable first)

Normally, I would code that last block like this:

IF any of X, Y, Z changes to not present
THEN
    Set variable 1, set variable 2, wait, speak
END IF

[pmjoen]

I removed the wait, Ill see if that works (Not sure why I added the wait)

[pmjoen]

Still seeing an issue, below are updated logs after removing the wait. Didn’t update the message after “Lauren” was present. Also never announced the arrival:

5/1/2019, 10:43:39 AM +211ms
+1ms ╔Received event [Front Door].contact = closed with a delay of 114ms
+173ms ║RunTime Analysis CS > 27ms > PS > 89ms > PE > 58ms > CE
+178ms ║Runtime (46244 bytes) successfully initialized in 89ms (v0.3.10a.20190223) (176ms)
+179ms ║╔Execution stage started
+198ms ║║Comparison (time) 38619396 is_between (time) 28800000 … (time) 75600000 = true (11ms)
+199ms ║║Time restriction check passed
+202ms ║║Condition #32 evaluated true (17ms)
+203ms ║║Condition group #null evaluated true (state did not change) (19ms)
+250ms ║║Condition #2 evaluated false (44ms)
+251ms ║║Cancelling statement #1’s schedules…
+253ms ║║Condition group #1 evaluated false (state did not change) (48ms)
+292ms ║║Condition #10 evaluated false (35ms)
+293ms ║║Condition group #9 evaluated false (state did not change) (37ms)
+296ms ║╚Execution stage complete. (117ms)
+298ms ╚Event processed successfully (297ms)
5/1/2019, 10:43:33 AM +541ms
+2ms ╔Received event [Front Door].contact = open with a delay of 187ms
+202ms ║RunTime Analysis CS > 27ms > PS > 121ms > PE > 54ms > CE
+205ms ║Runtime (46242 bytes) successfully initialized in 121ms (v0.3.10a.20190223) (203ms)
+206ms ║╔Execution stage started
+225ms ║║Comparison (time) 38613752 is_between (time) 28800000 … (time) 75600000 = true (10ms)
+226ms ║║Time restriction check passed
+228ms ║║Condition #32 evaluated true (17ms)
+230ms ║║Condition group #null evaluated true (state did not change) (19ms)
+281ms ║║Cancelling condition #2’s schedules…
+282ms ║║Condition #2 evaluated false (49ms)
+284ms ║║Cancelling statement #1’s schedules…
+285ms ║║Cancelling condition #1’s schedules…
+286ms ║║Condition group #1 evaluated false (state changed) (54ms)
+324ms ║║Condition #10 evaluated false (34ms)
+325ms ║║Condition group #9 evaluated false (state did not change) (36ms)
+328ms ║╚Execution stage complete. (122ms)
+329ms ╚Event processed successfully (329ms)
5/1/2019, 10:42:25 AM +195ms
+1ms ╔Received event [Mojo Manor].time = 1556725346501 with a delay of -1306ms
+218ms ║RunTime Analysis CS > 34ms > PS > 120ms > PE > 64ms > CE
+221ms ║Runtime (46263 bytes) successfully initialized in 120ms (v0.3.10a.20190223) (219ms)
+222ms ║╔Execution stage started
+240ms ║║Cancelling statement #1’s schedules…
+245ms ║║Condition group #1 made progress up the ladder, currently at step 2 of 2
+248ms ║║Cancelling statement #1’s schedules…
+250ms ║║Cancelling condition #1’s schedules…
+251ms ║║Condition group #1 evaluated true (state changed) (20ms)
+254ms ║║Cancelling statement #30’s schedules…
+360ms ║║Executed physical command [Echo - Front Room].speak([ Well, it seems that Eric has left the house, good rittance]) (100ms)
+362ms ║║Executed [Echo - Front Room].speak (103ms)
+413ms ║║Condition #10 evaluated false (44ms)
+416ms ║║Condition group #9 evaluated false (state did not change) (47ms)
+420ms ║╚Execution stage complete. (197ms)
+422ms ╚Event processed successfully (421ms)
5/1/2019, 10:40:26 AM +220ms
+1ms ╔Received event [Lauren].presence = present with a delay of 142ms
+184ms ║RunTime Analysis CS > 29ms > PS > 93ms > PE > 63ms > CE
+187ms ║Runtime (46246 bytes) successfully initialized in 93ms (v0.3.10a.20190223) (185ms)
+188ms ║╔Execution stage started
+206ms ║║Comparison (time) 38426413 is_between (time) 28800000 … (time) 75600000 = true (10ms)
+208ms ║║Time restriction check passed
+210ms ║║Condition #32 evaluated true (17ms)
+211ms ║║Condition group #null evaluated true (state did not change) (18ms)
+253ms ║║Comparison (enum) present changes_to (string) present = true (1ms)
+257ms ║║Cancelling condition #2’s schedules…
+261ms ║║Cancelling statement #21’s schedules…
+272ms ║║Executed virtual command setVariable (4ms)
+275ms ║║Condition #2 evaluated true (59ms)
+277ms ║║Cancelling statement #1’s schedules…
+278ms ║║Condition group #1 made progress up the ladder, currently at step 1 of 2
+316ms ║║Comparison (enum) present changes_to (string) not present = false (1ms)
+321ms ║║Condition #10 evaluated false (34ms)
+322ms ║║Condition group #9 evaluated false (state did not change) (36ms)
+326ms ║╚Execution stage complete. (137ms)
+328ms ║Setting up scheduled job for Wed, May 1 2019 @ 10:42:26 AM CDT (in 119.954s)
+337ms ╚Event processed successfully (338ms)

[WCmore]

Well, it took Lauren 3:13 to close the door, so the Speak should not have executed…

… but …

It actually still spoke the old variable 2 minutes after she arrived. (she was still outside and likely did not hear the alert)

I would avoid using “WHEN TRUE” whenever possible, and use normal IF, THEN commands instead.

Specifically, line 35 should move down a bit inside the THEN section. (before the Speak)

Also, it is important to note that your “followed within 2 minutes by” is not checking the door. The Speak command (using the old variable) is executing two minutes after Lauren came home, regardless of the door’s status.