Followed by not working for simple piston

ptdalen · 2018-02-27 17:17:57 UTC

1) Give a description of the problem
I got a new motion sensor and thought I’d try to have my bedroom lights turn on as I’m heading to bed

2) What is the expected behavior?
Turn on Switch 1 (Virtual Switch used for goodnight routine), then If if motion is detected within one minute, turn on my bedroom lights

3) What is happening/not happening?
Switch turns on, motion is detected, lights not turning on. Seems so simple, not sure what I’m missing,

4) Post a Green Snapshot of the piston

5) Attach any logs (From ST IDE and by turning logging level to Full)
(PASTE YOUR LOGS HERE BETWEEN THE MARKS THEN HIGHLIGHT ALL OF THE LOGS SND CLICK ON THE </> ICON TO FORMAT THEM)

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

pnbruckner · 2018-02-27 18:45:35 UTC

Good question. I had a similar issue with followed by, except in the opposite direction. I.e., I had a if “switch x changes” followed within 5 seconds by “switch x changes”, and one switch change event caused it to blow by both steps. (To be specific, the first switch change event “made progress, at step 1 of 2”, and then 5 seconds later, a time event caused it to think progress was made again - step 2 of 2 - even though there was not another switch change event.)

In any case, I’m curious to know more about how “followed by” works and is intended to be used.

Mike1616 · 2018-02-27 20:30:45 UTC

I believe that is how it’s supposed to work. Trigger followed by Trigger. Yet I’ve seen similar results at times as well, where the two events actually do happen and yet the evaluate to False in the full logs.

That’s probably where you need to start with this one though. Run a test and post up the Full logs so that we can see what’s going on here.

ptdalen · 2018-02-27 23:00:39 UTC

This is my log. I got it to work one time by setting level vs turn on for the light, but then it stopped working,

2/27/2018, 5:58:19 PM +175ms
+1ms ╔Received event [Motion Sensor (Hallway)].motion = active with a delay of 647ms
+97ms ║RunTime Analysis CS > 14ms > PS > 37ms > PE > 46ms > CE
+100ms ║Runtime (41229 bytes) successfully initialized in 37ms (v0.3.000.20180224) (97ms)
+101ms ║╔Execution stage started
+141ms ║║Duration 1080692ms for is >= 60000ms threshold = true
+142ms ║║Comparison (enum) inactive was (string) inactive = true (29ms)
+143ms ║║Condition #6 evaluated true (37ms)
+144ms ║║Condition group #1 evaluated true (state did not change) (38ms)
+150ms ║║Comparison (enum) active changes_to (string) active = false (1ms)
+151ms ║║Condition #5 evaluated false (4ms)
+154ms ║╚Execution stage complete. (54ms)
+155ms ║Setting up scheduled job for Tue, Feb 27 2018 @ 5:59:08 PM EST (in 49.061s)
+167ms ╚Event processed successfully (167ms)
2/27/2018, 5:58:08 PM +182ms
+1ms ╔Received event [Stairwell Light].switch = on with a delay of 653ms
+133ms ║RunTime Analysis CS > 26ms > PS > 43ms > PE > 64ms > CE
+136ms ║Runtime (41208 bytes) successfully initialized in 43ms (v0.3.000.20180224) (134ms)
+137ms ║╔Execution stage started
+192ms ║║Duration 1069750ms for is >= 60000ms threshold = true
+193ms ║║Comparison (enum) inactive was (string) inactive = true (43ms)
+194ms ║║Condition #6 evaluated true (51ms)
+195ms ║║Condition group #1 evaluated true (state did not change) (53ms)
+201ms ║║Comparison (enum) on changes_to (string) on = true (1ms)
+203ms ║║Cancelling condition #4’s schedules…
+204ms ║║Condition #4 evaluated true (7ms)
+205ms ║║Cancelling statement #1’s schedules…
+206ms ║║Condition group #1 made progress up the ladder, currently at step 1 of 2
+213ms ║╚Execution stage complete. (76ms)
+215ms ║Setting up scheduled job for Tue, Feb 27 2018 @ 5:59:08 PM EST (in 59.995s)
+222ms ╚Event processed successfully (222ms)

ptdalen · 2018-02-27 23:12:08 UTC

I ended up just chaging the piston to motion changes, and Switch changed in the past 30 seconds. The virtual switch I use to trigger goodnight only gets turned on/off for that routine. Seems to be working as expected and easier that troubleshooting the followed by.

Mike1616 · 2018-02-27 23:36:42 UTC

So there’s what I was seeing as well. The logs show it should have worked, but the event evaluated False for some reason that I do not understand. I suppose I agree with your assessment of changing to a different trigger, this one seems like it does not work in the manner one would think it should.

Any of the @webCoRE_Minions have any thoughts on this one?

ipaterson · 2018-02-27 23:44:11 UTC

I can take a look at this tomorrow, would one of you please run a quick test to see whether a piston with just the motion sensor changes to active part works as expected for this device? It would help to determine whether the Followed By has anything to do with this result.

ptdalen · 2018-02-27 23:45:58 UTC

Same sensor and switches works without followed by (ignore the restrictions, I added that after)

Robin · 2018-02-27 23:55:41 UTC

Tested this on my virtual hub and I’m getting same bug…

pnbruckner · 2018-02-28 01:25:44 UTC

If someone is going to look into this, here is another scenario that doesn’t quite work right (or, at least, how I’d expect):

Below is a log showing the switch changing to on and then not changing for over 10 seconds, yet 10 seconds after it changed to on, the piston runs again (as expected), but it decides the second step of the ladder happened (not as expected.)

Then, the switch is changed to off, again not changing for 10 seconds afterwards. This time the ladder is canceled (as I think is correct.)

Here is the log:

2/27/2018, 7:19:57 PM +695ms
+8ms	╔Received event [Doral Ct].time = 1519780797827 with a delay of -143ms
+155ms	║RunTime Analysis CS > 49ms > PS > 58ms > PE > 54ms > CE
+165ms	║Runtime (37639 bytes) successfully initialized in 58ms (v0.3.000.20180224) (149ms)
+170ms	║╔Execution stage started
+275ms	║║Conditional ladder step failed due to a timeout
+279ms	║║Cancelling statement #1's schedules...
+290ms	║║Cancelling condition #1's schedules...
+292ms	║║Condition group #1 evaluated false (state changed) (46ms)
+328ms	║╚Execution stage complete. (162ms)
+341ms	╚Event processed successfully (344ms)
2/27/2018, 7:19:47 PM +720ms
+1ms	╔Received event [Hallway Niche Light].switch = off with a delay of 690ms
+89ms	║RunTime Analysis CS > 17ms > PS > 55ms > PE > 18ms > CE
+91ms	║Runtime (37627 bytes) successfully initialized in 55ms (v0.3.000.20180224) (89ms)
+93ms	║╔Execution stage started
+102ms	║║Comparison (enum) off changes = true (1ms)
+104ms	║║Condition #4 evaluated true (4ms)
+105ms	║║Cancelling statement #1's schedules...
+105ms	║║Condition group #1 made progress up the ladder, currently at step 1 of 2
+111ms	║╚Execution stage complete. (19ms)
+113ms	║Setting up scheduled job for Tue, Feb 27 2018 @ 7:19:57 PM CST (in 9.995s)
+120ms	╚Event processed successfully (120ms)
2/27/2018, 7:19:26 PM +289ms
+1ms	╔Received event [Doral Ct].time = 1519780767772 with a delay of -1483ms
+98ms	║RunTime Analysis CS > 19ms > PS > 63ms > PE > 16ms > CE
+101ms	║Runtime (37642 bytes) successfully initialized in 63ms (v0.3.000.20180224) (98ms)
+102ms	║╔Execution stage started
+113ms	║║Cancelling statement #1's schedules...
+114ms	║║Condition group #1 made progress up the ladder, currently at step 2 of 2
+115ms	║║Cancelling statement #1's schedules...
+116ms	║║Cancelling condition #1's schedules...
+117ms	║║Condition group #1 evaluated true (state changed) (8ms)
+124ms	║║Cancelling statement #2's schedules...
+135ms	║║Switch changed twice withing 10 sec.
+136ms	║║Executed virtual command log (2ms)
+142ms	║╚Execution stage complete. (41ms)
+144ms	╚Event processed successfully (144ms)
2/27/2018, 7:19:17 PM +542ms
+5ms	╔Received event [Hallway Niche Light].switch = on with a delay of 736ms
+102ms	║RunTime Analysis CS > 36ms > PS > 46ms > PE > 24ms > CE
+111ms	║Runtime (37632 bytes) successfully initialized in 46ms (v0.3.000.20180224) (100ms)
+115ms	║╔Execution stage started
+197ms	║║Comparison (enum) on changes = true (10ms)
+203ms	║║Condition #4 evaluated true (41ms)
+208ms	║║Cancelling statement #1's schedules...
+209ms	║║Condition group #1 made progress up the ladder, currently at step 1 of 2
+295ms	║╚Execution stage complete. (182ms)
+333ms	║Setting up scheduled job for Tue, Feb 27 2018 @ 7:19:27 PM CST (in 9.905s)
+341ms	╚Event processed successfully (343ms)

ipaterson · 2018-02-28 16:35:23 UTC

I’m starting here since it was an easier scenario to reproduce and could hopefully be related to OP.

This seems to be the key. The scheduled wakeup to handle the cancellation of the followed by can happen significantly earlier than expected (in this case about 1 1/2 seconds) in which case the time has not yet expired. On my end this simple condition evaluated incorrectly as you’ve shown about 25% of the time and each time the schedule fired early. This confuses the pass/fail logic, I’ll dig deeper to figure out exactly what is happening.

ptdalen · 2018-03-01 13:58:32 UTC

Not sure is this will help, but I changed my piston just to be
if Motion changes to active
and
switch changed in the last 30 seconds
then
turn on lights

It works, sometimes. In my testing I was having the motion and switch changes happening pretty close and thought it was good to go, but last night when I exepected it to work for real it failed.

Here is a log from failing
2/28/2018, 10:36:42 PM +930ms
+2ms ╔Received event [Motion Sensor (Hallway)].motion = active with a delay of 548ms
+157ms ║RunTime Analysis CS > 33ms > PS > 53ms > PE > 71ms > CE
+160ms ║Runtime (42102 bytes) successfully initialized in 53ms (v0.3.000.20180224) (157ms)
+161ms ║╔Execution stage started
+201ms ║║Comparison (enum) off did_not_change = true (28ms)
+202ms ║║Cancelling condition #6’s schedules…
+203ms ║║Condition #6 evaluated true (36ms)
+212ms ║║Comparison (enum) off is_not (string) on = true (2ms)
+214ms ║║Condition #8 evaluated true (9ms)
+215ms ║║Cancelling condition #1’s schedules…
+216ms ║║Condition group #1 evaluated true (state changed) (49ms)
+220ms ║║Comparison (enum) active changes_to (string) active = false (1ms)
+221ms ║║Condition #5 evaluated false (4ms)
+222ms ║║Cancelling condition #1’s schedules…
+223ms ║║Condition group #1 evaluated false (state changed) (7ms)
+226ms ║╚Execution stage complete. (65ms)
+227ms ╚Event processed successfully (227ms)

and this is the timestamp for when the switch changed to ON
2018-02-28 10:36:21.869 PM EST (2018-03-01T03:36:21.869Z)

maybe its not followed by as much as it is a timing issue?

Anyway, I think you guys already know all this, but figure the logs cannot hurt. pistonlight

EDIT:
Here is a good run from this morning, same piston, no changes. Only difference is motion was very close to the time I turned on the switch

3/1/2018, 7:43:27 AM +687ms
+1ms ╔Received event [Motion Sensor (Hallway)].motion = active with a delay of 603ms
+190ms ║RunTime Analysis CS > 16ms > PS > 106ms > PE > 69ms > CE
+193ms ║Runtime (42105 bytes) successfully initialized in 106ms (v0.3.000.20180224) (192ms)
+194ms ║╔Execution stage started
+235ms ║║Comparison (enum) off did_not_change = true (28ms)
+236ms ║║Condition #6 evaluated true (37ms)
+245ms ║║Comparison (enum) off is_not (string) on = true (2ms)
+246ms ║║Condition #8 evaluated true (9ms)
+247ms ║║Cancelling condition #1’s schedules…
+248ms ║║Condition group #1 evaluated true (state changed) (49ms)
+253ms ║║Comparison (enum) active changes_to (string) active = true (1ms)
+254ms ║║Cancelling condition #5’s schedules…
+255ms ║║Condition #5 evaluated true (6ms)
+283ms ║║Comparison (enum) on changed = true (22ms)
+284ms ║║Cancelling condition #4’s schedules…
+285ms ║║Condition #4 evaluated true (29ms)
+286ms ║║Condition group #1 evaluated true (state did not change) (37ms)
+289ms ║║Cancelling statement #2’s schedules…
+306ms ║║Executed physical command [Bedroom Ceiling Light].on() (15ms)
+307ms ║║Executed [Bedroom Ceiling Light].on (17ms)
+310ms ║╚Execution stage complete. (117ms)
+311ms ╚Event processed successfully (311ms)

Goodnight switch Changed Timestamp
2018-03-01 7:43:21.580 AM EST (2018-03-01T12:43:21.580Z)

ipaterson · 2018-03-01 14:27:51 UTC

Thanks for the follow-up. I was getting conflicting results yesterday so I was probably not on the right track with it being just related to timing. I noticed a number of things that seemed odd but still haven’t tracked down any root problems here.

Testing with a momentary button wired to a contact switch and a separate contact switch for the followed by since both can be triggered from my desk many, many times. I don’t trust that virtual devices will necessarily behave the same way so this seems reasonable

ptdalen · 2018-03-01 14:30:15 UTC

Seems fair. If it’s not obvious, my Goodnight switch is virtual, but the rest are physical.

pnbruckner · 2018-03-08 15:56:25 UTC

Have you discovered anything about why the wakeup is happening too soon? I’ve run into another similar issue where a wakeup for a wait happens too soon that results in the following statements getting run twice.

In the log (below) you can clearly see the “delay” for the wait is negative. And you can see the statements after the wait getting invoked once (when the wait completes), and then a second time when an event happens that the statements after the wait cause. I think the issue is that when the piston runs for the event after the wait, the time is still before the time the wait should have completed, so in both invocations WC decides to run the tasks after the wait. BTW, this behavior is not consistent. Sometimes it happens and sometimes it doesn’t. E.g., changing the wait time seems to have some effect.

The piston and log follow. In my description above I’m referring to the statements inside do statement #126.

3/8/2018, 9:54:28 AM +854ms
+0ms	╔Received event [Doral Ct].:efb0da26275d7c058b6660da9b00b206: = @IanWiFiPresent with a delay of 138ms
+216ms	║RunTime Analysis CS > 25ms > PS > 54ms > PE > 137ms > CE
+221ms	║Runtime (70538 bytes) successfully initialized in 54ms (v0.3.000.20180224) (219ms)
+222ms	║╔Execution stage started
+233ms	║║Comparison (boolean) true is_not (boolean) true = false (2ms)
+235ms	║║Cancelling condition #9's schedules...
+236ms	║║Condition #9 evaluated false (8ms)
+237ms	║║Cancelling condition #1's schedules...
+237ms	║║Condition group #1 evaluated false (state changed) (10ms)
+245ms	║║Comparison (boolean) false changes_to (boolean) true = false (1ms)
+246ms	║║Condition #33 evaluated false (4ms)
+247ms	║║Condition group #26 evaluated false (state did not change) (6ms)
+253ms	║║Comparison (boolean) false changes_to (boolean) false = true (1ms)
+255ms	║║Cancelling condition #37's schedules...
+256ms	║║Condition #37 evaluated true (5ms)
+257ms	║║Cancelling condition #36's schedules...
+257ms	║║Condition group #36 evaluated true (state changed) (7ms)
+268ms	║║Comparison (enum) present is (string) present = true (2ms)
+269ms	║║Condition #29 evaluated true (9ms)
+270ms	║║Condition group #27 evaluated true (state did not change) (11ms)
+271ms	║║Cancelling statement #27's schedules...
+366ms	║║Executed physical command [null].departed() (92ms)
+367ms	║║Executed [Ian].departed (94ms)
+375ms	║║Comparison (dynamic) null is (string) Ian = false (1ms)
+376ms	║║Cancelling condition #14's schedules...
+377ms	║║Condition #14 evaluated false (7ms)
+378ms	║║Cancelling condition #11's schedules...
+379ms	║║Condition group #11 evaluated false (state changed) (9ms)
+385ms	║║Comparison (boolean) false is (boolean) true = false (1ms)
+387ms	║║Condition #25 evaluated false (5ms)
+388ms	║║Condition group #15 evaluated false (state did not change) (6ms)
+389ms	║║Skipping execution for statement #126 because condition state did not change
+399ms	║║Condition #57 evaluated false (6ms)
+400ms	║║Condition group #52 evaluated false (state did not change) (7ms)
+410ms	║║Condition #79 evaluated false (6ms)
+411ms	║║Condition group #76 evaluated false (state did not change) (7ms)
+417ms	║║Comparison (boolean) true changes_to (boolean) true = false (0ms)
+418ms	║║Condition #84 evaluated false (4ms)
+424ms	║║Condition #85 evaluated false (5ms)
+425ms	║║Condition group #80 evaluated false (state did not change) (12ms)
+431ms	║║Comparison (boolean) true changes_to (boolean) false = false (0ms)
+432ms	║║Condition #90 evaluated false (4ms)
+438ms	║║Condition #91 evaluated false (5ms)
+439ms	║║Condition group #86 evaluated false (state did not change) (12ms)
+446ms	║║Comparison (dynamic) null is (string) Nancy = false (1ms)
+447ms	║║Condition #62 evaluated false (5ms)
+448ms	║║Condition group #59 evaluated false (state did not change) (6ms)
+455ms	║║Comparison (boolean) true is (boolean) true = true (2ms)
+456ms	║║Condition #75 evaluated true (5ms)
+457ms	║║Condition group #63 evaluated true (state did not change) (6ms)
+458ms	║║Skipping execution for statement #73 because condition state did not change
+469ms	║║Condition #113 evaluated false (6ms)
+470ms	║║Condition group #110 evaluated false (state did not change) (8ms)
+475ms	║║Comparison (boolean) false changes_to (boolean) true = false (0ms)
+477ms	║║Condition #118 evaluated false (5ms)
+484ms	║║Condition #119 evaluated false (6ms)
+485ms	║║Condition group #114 evaluated false (state did not change) (12ms)
+490ms	║║Comparison (boolean) false changes_to (boolean) false = false (0ms)
+492ms	║║Condition #124 evaluated false (4ms)
+498ms	║║Condition #125 evaluated false (5ms)
+499ms	║║Condition group #120 evaluated false (state did not change) (12ms)
+506ms	║║Comparison (dynamic) null is (string) Phillip = false (1ms)
+508ms	║║Condition #96 evaluated false (6ms)
+509ms	║║Condition group #93 evaluated false (state did not change) (7ms)
+516ms	║║Comparison (boolean) false is (boolean) true = false (2ms)
+518ms	║║Condition #109 evaluated false (6ms)
+519ms	║║Condition group #97 evaluated false (state did not change) (7ms)
+521ms	║║Skipping execution for statement #98 because condition state did not change
+525ms	║║Fast executing schedules, waiting for 115ms to sync up
+681ms	║║Cancelling statement #17's schedules...
+690ms	║║Calculating (string) Ian + (string) 's WiFi stayed disconnected for >> (string) Ian's WiFi stayed disconnected for
+693ms	║║Calculating (string) Ian's WiFi stayed disconnected for + (string) 10 >> (string) Ian's WiFi stayed disconnected for 10
+696ms	║║Calculating (string) Ian's WiFi stayed disconnected for 10 + (string) minutes. >> (string) Ian's WiFi stayed disconnected for 10 minutes.
+700ms	║║Ian's WiFi stayed disconnected for 10 minutes.
+703ms	║║Executed virtual command log (3ms)
+713ms	║║Calculating (integer) 11 + (integer) 2 >> (integer) 13
+727ms	║║Calculating (string) IWA22:36:52, IWA22:36:53, IWC09:43:43, IWD09:44:29, IWA09:54:28 + (string) , >> (string) IWA22:36:52, IWA22:36:53, IWC09:43:43, IWD09:44:29, IWA09:54:28,
+730ms	║║Calculating (string) IWA22:36:52, IWA22:36:53, IWC09:43:43, IWD09:44:29, IWA09:54:28, + (string) I >> (string) IWA22:36:52, IWA22:36:53, IWC09:43:43, IWD09:44:29, IWA09:54:28, I
+733ms	║║Calculating (string) IWA22:36:52, IWA22:36:53, IWC09:43:43, IWD09:44:29, IWA09:54:28, I + (string) WA >> (string) IWA22:36:52, IWA22:36:53, IWC09:43:43, IWD09:44:29, IWA09:54:28, IWA
+735ms	║║Calculating (string) IWA22:36:52, IWA22:36:53, IWC09:43:43, IWD09:44:29, IWA09:54:28, IWA + (string) 09:54:29 >> (string) IWA22:36:52, IWA22:36:53, IWC09:43:43, IWD09:44:29, IWA09:54:28, IWA09:54:29
+740ms	║║Executed virtual command setVariable (3ms)
+743ms	║║Executed virtual command setState (0ms)
+746ms	║║Cancelling statement #128's schedules...
+750ms	║║Executed virtual command setVariable (1ms)
+754ms	║╚Execution stage complete. (532ms)
+755ms	╚Event processed successfully (756ms)
3/8/2018, 9:54:28 AM +255ms
+0ms	╔Received event [Doral Ct].time = 1520524469494 with a delay of -1240ms
+235ms	║RunTime Analysis CS > 18ms > PS > 60ms > PE > 157ms > CE
+239ms	║Runtime (70507 bytes) successfully initialized in 60ms (v0.3.000.20180224) (238ms)
+240ms	║╔Execution stage started
+279ms	║║Cancelling statement #17's schedules...
+293ms	║║Calculating (string) Ian + (string) 's WiFi stayed disconnected for >> (string) Ian's WiFi stayed disconnected for
+296ms	║║Calculating (string) Ian's WiFi stayed disconnected for + (string) 10 >> (string) Ian's WiFi stayed disconnected for 10
+299ms	║║Calculating (string) Ian's WiFi stayed disconnected for 10 + (string) minutes. >> (string) Ian's WiFi stayed disconnected for 10 minutes.
+303ms	║║Ian's WiFi stayed disconnected for 10 minutes.
+306ms	║║Executed virtual command log (4ms)
+316ms	║║Calculating (integer) 11 + (integer) 2 >> (integer) 13
+329ms	║║Calculating (string) IWD22:26:53, IWA22:36:52, IWA22:36:53, IWC09:43:43, IWD09:44:29 + (string) , >> (string) IWD22:26:53, IWA22:36:52, IWA22:36:53, IWC09:43:43, IWD09:44:29,
+332ms	║║Calculating (string) IWD22:26:53, IWA22:36:52, IWA22:36:53, IWC09:43:43, IWD09:44:29, + (string) I >> (string) IWD22:26:53, IWA22:36:52, IWA22:36:53, IWC09:43:43, IWD09:44:29, I
+335ms	║║Calculating (string) IWD22:26:53, IWA22:36:52, IWA22:36:53, IWC09:43:43, IWD09:44:29, I + (string) WA >> (string) IWD22:26:53, IWA22:36:52, IWA22:36:53, IWC09:43:43, IWD09:44:29, IWA
+338ms	║║Calculating (string) IWD22:26:53, IWA22:36:52, IWA22:36:53, IWC09:43:43, IWD09:44:29, IWA + (string) 09:54:28 >> (string) IWD22:26:53, IWA22:36:52, IWA22:36:53, IWC09:43:43, IWD09:44:29, IWA09:54:28
+343ms	║║Executed virtual command setVariable (3ms)
+346ms	║║Executed virtual command setState (0ms)
+349ms	║║Cancelling statement #128's schedules...
+353ms	║║Executed virtual command setVariable (1ms)
+357ms	║╚Execution stage complete. (116ms)
+358ms	╚Event processed successfully (358ms)
3/8/2018, 9:44:29 AM +130ms
+0ms	╔Received event [Doral Ct].execute = :a66070471b9dc25914828c97f1453c89: with a delay of 94ms
+198ms	║RunTime Analysis CS > 24ms > PS > 55ms > PE > 119ms > CE
+202ms	║Runtime (70527 bytes) successfully initialized in 55ms (v0.3.000.20180224) (201ms)
+203ms	║╔Execution stage started
+215ms	║║Comparison (boolean) false is_not (boolean) true = true (2ms)
+217ms	║║Cancelling condition #9's schedules...
+217ms	║║Condition #9 evaluated true (8ms)
+218ms	║║Cancelling condition #1's schedules...
+219ms	║║Condition group #1 evaluated true (state changed) (10ms)
+221ms	║║Cancelling statement #2's schedules...
+227ms	║║Calculating (dynamic) disconnected from == (dynamic) connected to >> (boolean) false
+232ms	║║Executed virtual command setVariable (3ms)
+235ms	║║Cancelling statement #5's schedules...
+247ms	║║Calculating (string) Ian + (string) 's WiFi >> (string) Ian's WiFi
+249ms	║║Calculating (string) Ian's WiFi + (string) disconnected >> (string) Ian's WiFi disconnected
+252ms	║║Calculating (string) Ian's WiFi disconnected + (string) . >> (string) Ian's WiFi disconnected.
+256ms	║║Ian's WiFi disconnected.
+259ms	║║Executed virtual command log (3ms)
+269ms	║║Calculating (integer) 11 + (integer) 2 >> (integer) 13
+286ms	║║Calculating (string) IWC22:24:57, IWD22:26:53, IWA22:36:52, IWA22:36:53, IWC09:43:43 + (string) , >> (string) IWC22:24:57, IWD22:26:53, IWA22:36:52, IWA22:36:53, IWC09:43:43,
+289ms	║║Calculating (string) IWC22:24:57, IWD22:26:53, IWA22:36:52, IWA22:36:53, IWC09:43:43, + (string) I >> (string) IWC22:24:57, IWD22:26:53, IWA22:36:52, IWA22:36:53, IWC09:43:43, I
+292ms	║║Calculating (string) IWC22:24:57, IWD22:26:53, IWA22:36:52, IWA22:36:53, IWC09:43:43, I + (string) W >> (string) IWC22:24:57, IWD22:26:53, IWA22:36:52, IWA22:36:53, IWC09:43:43, IW
+295ms	║║Calculating (string) IWC22:24:57, IWD22:26:53, IWA22:36:52, IWA22:36:53, IWC09:43:43, IW + (string) D >> (string) IWC22:24:57, IWD22:26:53, IWA22:36:52, IWA22:36:53, IWC09:43:43, IWD
+298ms	║║Calculating (string) IWC22:24:57, IWD22:26:53, IWA22:36:52, IWA22:36:53, IWC09:43:43, IWD + (string) 09:44:29 >> (string) IWC22:24:57, IWD22:26:53, IWA22:36:52, IWA22:36:53, IWC09:43:43, IWD09:44:29
+304ms	║║Executed virtual command setVariable (4ms)
+307ms	║║Executed virtual command setState (1ms)
+314ms	║║Comparison (boolean) true changes_to (boolean) true = false (0ms)
+316ms	║║Cancelling condition #33's schedules...
+317ms	║║Condition #33 evaluated false (5ms)
+318ms	║║Cancelling condition #26's schedules...
+318ms	║║Condition group #26 evaluated false (state changed) (7ms)
+324ms	║║Comparison (boolean) true changes_to (boolean) false = false (1ms)
+325ms	║║Condition #37 evaluated false (4ms)
+326ms	║║Condition group #36 evaluated false (state did not change) (5ms)
+333ms	║║Comparison (dynamic) Ian is (string) Ian = true (1ms)
+335ms	║║Cancelling condition #14's schedules...
+335ms	║║Condition #14 evaluated true (6ms)
+336ms	║║Cancelling condition #11's schedules...
+337ms	║║Condition group #11 evaluated true (state changed) (8ms)
+339ms	║║Cancelling statement #12's schedules...
+345ms	║║Executed virtual command setVariable (2ms)
+352ms	║║Comparison (boolean) false is (boolean) true = false (1ms)
+353ms	║║Cancelling condition #25's schedules...
+354ms	║║Condition #25 evaluated false (6ms)
+355ms	║║Cancelling condition #15's schedules...
+356ms	║║Condition group #15 evaluated false (state changed) (8ms)
+359ms	║║Cancelling statement #127's schedules...
+362ms	║║Executed virtual command wait (0ms)
+363ms	║║Requesting a wake up for Thu, Mar 8 2018 @ 9:54:29 AM CST (in 600.0s)
+376ms	║║Condition #57 evaluated false (5ms)
+377ms	║║Condition group #52 evaluated false (state did not change) (7ms)
+387ms	║║Condition #79 evaluated false (5ms)
+388ms	║║Condition group #76 evaluated false (state did not change) (7ms)
+394ms	║║Comparison (boolean) true changes_to (boolean) true = false (1ms)
+396ms	║║Condition #84 evaluated false (4ms)
+401ms	║║Condition #85 evaluated false (5ms)
+402ms	║║Condition group #80 evaluated false (state did not change) (11ms)
+408ms	║║Comparison (boolean) true changes_to (boolean) false = false (1ms)
+409ms	║║Condition #90 evaluated false (4ms)
+416ms	║║Condition #91 evaluated false (6ms)
+417ms	║║Condition group #86 evaluated false (state did not change) (12ms)
+424ms	║║Comparison (dynamic) Ian is (string) Nancy = false (2ms)
+425ms	║║Condition #62 evaluated false (5ms)
+426ms	║║Condition group #59 evaluated false (state did not change) (7ms)
+433ms	║║Comparison (boolean) true is (boolean) true = true (1ms)
+434ms	║║Condition #75 evaluated true (5ms)
+435ms	║║Condition group #63 evaluated true (state did not change) (7ms)
+436ms	║║Skipping execution for statement #73 because condition state did not change
+446ms	║║Condition #113 evaluated false (6ms)
+447ms	║║Condition group #110 evaluated false (state did not change) (7ms)
+453ms	║║Comparison (boolean) false changes_to (boolean) true = false (1ms)
+454ms	║║Condition #118 evaluated false (4ms)
+464ms	║║Condition #119 evaluated false (9ms)
+465ms	║║Condition group #114 evaluated false (state did not change) (15ms)
+471ms	║║Comparison (boolean) false changes_to (boolean) false = false (1ms)
+472ms	║║Condition #124 evaluated false (4ms)
+479ms	║║Condition #125 evaluated false (6ms)
+480ms	║║Condition group #120 evaluated false (state did not change) (11ms)
+487ms	║║Comparison (dynamic) Ian is (string) Phillip = false (1ms)
+488ms	║║Condition #96 evaluated false (5ms)
+489ms	║║Condition group #93 evaluated false (state did not change) (7ms)
+496ms	║║Comparison (boolean) false is (boolean) true = false (1ms)
+497ms	║║Condition #109 evaluated false (5ms)
+498ms	║║Condition group #97 evaluated false (state did not change) (7ms)
+499ms	║║Skipping execution for statement #98 because condition state did not change
+502ms	║╚Execution stage complete. (299ms)
+504ms	║Setting up scheduled job for Thu, Mar 8 2018 @ 9:54:29 AM CST (in 599.861s)
+510ms	╚Event processed successfully (511ms)
3/8/2018, 9:43:43 AM +817ms
+1ms	╔Received event [Doral Ct].:efb0da26275d7c058b6660da9b00b206: = @IanWiFiPresent with a delay of 103ms
+182ms	║RunTime Analysis CS > 23ms > PS > 39ms > PE > 119ms > CE
+186ms	║Runtime (70537 bytes) successfully initialized in 39ms (v0.3.000.20180224) (184ms)
+187ms	║╔Execution stage started
+199ms	║║Comparison (boolean) true is_not (boolean) true = false (2ms)
+200ms	║║Condition #9 evaluated false (7ms)
+201ms	║║Condition group #1 evaluated false (state did not change) (9ms)
+209ms	║║Comparison (boolean) true changes_to (boolean) true = true (0ms)
+210ms	║║Cancelling condition #33's schedules...
+211ms	║║Condition #33 evaluated true (6ms)
+212ms	║║Cancelling condition #26's schedules...
+213ms	║║Condition group #26 evaluated true (state changed) (7ms)
+222ms	║║Comparison (enum) not present is (string) not present = true (1ms)
+223ms	║║Condition #32 evaluated true (8ms)
+224ms	║║Condition group #30 evaluated true (state did not change) (9ms)
+225ms	║║Cancelling statement #30's schedules...
+253ms	║║Executed physical command [null].arrived() (26ms)
+254ms	║║Executed [Ian].arrived (28ms)
+260ms	║║Comparison (boolean) true changes_to (boolean) false = false (0ms)
+262ms	║║Cancelling condition #37's schedules...
+263ms	║║Condition #37 evaluated false (5ms)
+264ms	║║Cancelling condition #36's schedules...
+265ms	║║Condition group #36 evaluated false (state changed) (7ms)
+272ms	║║Comparison (dynamic) null is (string) Ian = false (1ms)
+273ms	║║Condition #14 evaluated false (5ms)
+274ms	║║Condition group #11 evaluated false (state did not change) (7ms)
+280ms	║║Comparison (boolean) true is (boolean) true = true (1ms)
+282ms	║║Cancelling condition #25's schedules...
+283ms	║║Condition #25 evaluated true (6ms)
+284ms	║║Cancelling condition #15's schedules...
+285ms	║║Condition group #15 evaluated true (state changed) (8ms)
+287ms	║║Cancelling statement #23's schedules...
+291ms	║║Executed virtual command setVariable (1ms)
+318ms	║║Condition #57 evaluated false (22ms)
+319ms	║║Condition group #52 evaluated false (state did not change) (23ms)
+329ms	║║Condition #79 evaluated false (5ms)
+330ms	║║Condition group #76 evaluated false (state did not change) (7ms)
+336ms	║║Comparison (boolean) true changes_to (boolean) true = false (0ms)
+337ms	║║Condition #84 evaluated false (4ms)
+343ms	║║Condition #85 evaluated false (5ms)
+344ms	║║Condition group #80 evaluated false (state did not change) (12ms)
+350ms	║║Comparison (boolean) true changes_to (boolean) false = false (1ms)
+351ms	║║Condition #90 evaluated false (4ms)
+358ms	║║Condition #91 evaluated false (6ms)
+359ms	║║Condition group #86 evaluated false (state did not change) (12ms)
+366ms	║║Comparison (dynamic) null is (string) Nancy = false (2ms)
+368ms	║║Condition #62 evaluated false (5ms)
+368ms	║║Condition group #59 evaluated false (state did not change) (7ms)
+375ms	║║Comparison (boolean) true is (boolean) true = true (1ms)
+377ms	║║Condition #75 evaluated true (6ms)
+378ms	║║Condition group #63 evaluated true (state did not change) (7ms)
+379ms	║║Skipping execution for statement #73 because condition state did not change
+389ms	║║Condition #113 evaluated false (6ms)
+390ms	║║Condition group #110 evaluated false (state did not change) (7ms)
+396ms	║║Comparison (boolean) false changes_to (boolean) true = false (0ms)
+397ms	║║Condition #118 evaluated false (4ms)
+403ms	║║Condition #119 evaluated false (5ms)
+404ms	║║Condition group #114 evaluated false (state did not change) (12ms)
+410ms	║║Comparison (boolean) false changes_to (boolean) false = false (1ms)
+411ms	║║Condition #124 evaluated false (4ms)
+418ms	║║Condition #125 evaluated false (6ms)
+419ms	║║Condition group #120 evaluated false (state did not change) (13ms)
+426ms	║║Comparison (dynamic) null is (string) Phillip = false (1ms)
+428ms	║║Condition #96 evaluated false (6ms)
+429ms	║║Condition group #93 evaluated false (state did not change) (6ms)
+435ms	║║Comparison (boolean) false is (boolean) true = false (2ms)
+437ms	║║Condition #109 evaluated false (4ms)
+438ms	║║Condition group #97 evaluated false (state did not change) (6ms)
+439ms	║║Skipping execution for statement #98 because condition state did not change
+442ms	║╚Execution stage complete. (254ms)
+443ms	╚Event processed successfully (443ms)
3/8/2018, 9:43:43 AM +147ms
+1ms	╔Received event [Doral Ct].execute = :d91059d87d41aa4bec58689d2adc907d: with a delay of 70ms
+189ms	║RunTime Analysis CS > 21ms > PS > 59ms > PE > 108ms > CE
+193ms	║Runtime (70531 bytes) successfully initialized in 59ms (v0.3.000.20180224) (191ms)
+194ms	║╔Execution stage started
+208ms	║║Comparison (boolean) false is_not (boolean) true = true (2ms)
+210ms	║║Cancelling condition #9's schedules...
+211ms	║║Condition #9 evaluated true (10ms)
+212ms	║║Cancelling condition #1's schedules...
+213ms	║║Condition group #1 evaluated true (state changed) (13ms)
+215ms	║║Cancelling statement #2's schedules...
+221ms	║║Calculating (dynamic) connected to == (dynamic) connected to >> (boolean) true
+226ms	║║Executed virtual command setVariable (3ms)
+229ms	║║Cancelling statement #5's schedules...
+241ms	║║Calculating (string) Ian + (string) 's WiFi >> (string) Ian's WiFi
+244ms	║║Calculating (string) Ian's WiFi + (string) connected >> (string) Ian's WiFi connected
+247ms	║║Calculating (string) Ian's WiFi connected + (string) . >> (string) Ian's WiFi connected.
+250ms	║║Ian's WiFi connected.
+253ms	║║Executed virtual command log (3ms)
+263ms	║║Calculating (integer) 11 + (integer) 2 >> (integer) 13
+280ms	║║Calculating (string) IWA22:21:55, IWC22:24:57, IWD22:26:53, IWA22:36:52, IWA22:36:53 + (string) , >> (string) IWA22:21:55, IWC22:24:57, IWD22:26:53, IWA22:36:52, IWA22:36:53,
+283ms	║║Calculating (string) IWA22:21:55, IWC22:24:57, IWD22:26:53, IWA22:36:52, IWA22:36:53, + (string) I >> (string) IWA22:21:55, IWC22:24:57, IWD22:26:53, IWA22:36:52, IWA22:36:53, I
+287ms	║║Calculating (string) IWA22:21:55, IWC22:24:57, IWD22:26:53, IWA22:36:52, IWA22:36:53, I + (string) W >> (string) IWA22:21:55, IWC22:24:57, IWD22:26:53, IWA22:36:52, IWA22:36:53, IW
+289ms	║║Calculating (string) IWA22:21:55, IWC22:24:57, IWD22:26:53, IWA22:36:52, IWA22:36:53, IW + (string) C >> (string) IWA22:21:55, IWC22:24:57, IWD22:26:53, IWA22:36:52, IWA22:36:53, IWC
+292ms	║║Calculating (string) IWA22:21:55, IWC22:24:57, IWD22:26:53, IWA22:36:52, IWA22:36:53, IWC + (string) 09:43:43 >> (string) IWA22:21:55, IWC22:24:57, IWD22:26:53, IWA22:36:52, IWA22:36:53, IWC09:43:43
+296ms	║║Executed virtual command setVariable (2ms)
+299ms	║║Executed virtual command setState (0ms)
+307ms	║║Comparison (boolean) false changes_to (boolean) true = false (0ms)
+309ms	║║Condition #33 evaluated false (5ms)
+310ms	║║Condition group #26 evaluated false (state did not change) (6ms)
+316ms	║║Comparison (boolean) false changes_to (boolean) false = false (0ms)
+317ms	║║Cancelling condition #37's schedules...
+318ms	║║Condition #37 evaluated false (5ms)
+319ms	║║Cancelling condition #36's schedules...
+320ms	║║Condition group #36 evaluated false (state changed) (7ms)
+327ms	║║Comparison (dynamic) Ian is (string) Ian = true (2ms)
+328ms	║║Cancelling condition #14's schedules...
+329ms	║║Condition #14 evaluated true (6ms)
+330ms	║║Cancelling condition #11's schedules...
+331ms	║║Condition group #11 evaluated true (state changed) (9ms)
+333ms	║║Cancelling statement #12's schedules...
+339ms	║║Executed virtual command setVariable (3ms)
+346ms	║║Comparison (boolean) true is (boolean) true = true (2ms)
+348ms	║║Cancelling condition #25's schedules...
+348ms	║║Condition #25 evaluated true (6ms)
+349ms	║║Cancelling condition #15's schedules...
+350ms	║║Condition group #15 evaluated true (state changed) (8ms)
+352ms	║║Cancelling statement #23's schedules...
+357ms	║║Executed virtual command setVariable (1ms)
+367ms	║║Condition #57 evaluated false (5ms)
+368ms	║║Condition group #52 evaluated false (state did not change) (7ms)
+378ms	║║Condition #79 evaluated false (4ms)
+379ms	║║Condition group #76 evaluated false (state did not change) (6ms)
+385ms	║║Comparison (boolean) true changes_to (boolean) true = false (0ms)
+386ms	║║Condition #84 evaluated false (5ms)
+392ms	║║Condition #85 evaluated false (5ms)
+393ms	║║Condition group #80 evaluated false (state did not change) (12ms)
+399ms	║║Comparison (boolean) true changes_to (boolean) false = false (0ms)
+401ms	║║Condition #90 evaluated false (4ms)
+407ms	║║Condition #91 evaluated false (6ms)
+408ms	║║Condition group #86 evaluated false (state did not change) (12ms)
+415ms	║║Comparison (dynamic) Ian is (string) Nancy = false (1ms)
+417ms	║║Condition #62 evaluated false (6ms)
+418ms	║║Condition group #59 evaluated false (state did not change) (6ms)
+424ms	║║Comparison (boolean) true is (boolean) true = true (1ms)
+426ms	║║Condition #75 evaluated true (6ms)
+427ms	║║Condition group #63 evaluated true (state did not change) (6ms)
+428ms	║║Skipping execution for statement #73 because condition state did not change
+438ms	║║Condition #113 evaluated false (6ms)
+439ms	║║Condition group #110 evaluated false (state did not change) (7ms)
+445ms	║║Comparison (boolean) false changes_to (boolean) true = false (1ms)
+446ms	║║Condition #118 evaluated false (4ms)
+453ms	║║Condition #119 evaluated false (5ms)
+454ms	║║Condition group #114 evaluated false (state did not change) (11ms)
+459ms	║║Comparison (boolean) false changes_to (boolean) false = false (0ms)
+461ms	║║Condition #124 evaluated false (5ms)
+467ms	║║Condition #125 evaluated false (5ms)
+468ms	║║Condition group #120 evaluated false (state did not change) (11ms)
+475ms	║║Comparison (dynamic) Ian is (string) Phillip = false (2ms)
+476ms	║║Condition #96 evaluated false (5ms)
+477ms	║║Condition group #93 evaluated false (state did not change) (7ms)
+484ms	║║Comparison (boolean) false is (boolean) true = false (2ms)
+485ms	║║Condition #109 evaluated false (5ms)
+486ms	║║Condition group #97 evaluated false (state did not change) (6ms)
+487ms	║║Skipping execution for statement #98 because condition state did not change
+490ms	║╚Execution stage complete. (296ms)
+492ms	╚Event processed successfully (491ms)

ipaterson · 2018-03-09 12:02:09 UTC

Thanks for following up. I assume that the scheduling precision is a characteristic of SmartThings rather than webCoRE but perhaps someone can correct me or provide more insight into that.

With regard to OP, I’m still tracking through the debug trail on Followed By. So far I came across a few potential issues but it’s a challenge to isolate exactly what is happening. The most concrete issue that I’ve found so far is related to the fastForwardTo functionality when a piston wakes back up. It is used for the followed by ladder in a way that conflicts with how conditions are evaluated. The fastForwardTo in this case causes it to return an old cached value for the condition rather than actually checking the condition. I’m testing a fix for that but there are still other issues popping up.

pnbruckner · 2018-03-09 14:32:18 UTC

Sorry for the potentially silly question, but what is “OP”? I’ve seen that acronym used several times but so far I’ve not been able to deduce what it stands for. Probably just a mental block!

ipaterson · 2018-03-09 14:35:05 UTC

“original post” in this case or “original poster” if talking about the person who made the first post in this topic.

pnbruckner · 2018-03-09 18:47:23 UTC

I’m sure there’s some inaccuracy/skew from the underlying ST system. Nothing is perfect. However, there’s also the calculations being done in WC - i.e., what it’s passing to RunIn (or whatever is the case if there’s other ways to schedule things in SmartApps.) I’m wondering if the (majority of the) problem is there, or in the timestamps it’s using in the calculations (e.g., current event time vs now, cached vs uncached values, when exactly the timestamps are getting recorded, etc.)

I’m seeing more and more cases where pistons are running too early and causing time related triggers/conditions to cause statements to run multiple times. And very often I see “fast execution” (or whatever the phrase is) followed by syncing in the logs when this happens, but not always. E.g., in trying to help other people, I throw together various test pistons and I see this behavior. I’ve seen it with “happens daily at”, “Date & Time are between x and y”, waits, etc. Oh, wait, that reminds me, I did a test with “Date & Time is between x and y”, and the piston did run too early, and the log even showed that the raw time integer value was between x and y, but the statement evaluated to false! There must be something in this rule implementation that accounts for this sort of thing.

If it helps, I can post examples of these problems, either here or somewhere else, if you or anyone else who knows about these things would like if it would help diagnose why they’re happening. (I’ve probably side tracked this topic too much already.)

bryantrichar · 2018-11-11 23:02:56 UTC

Any resolution on followed by commands ? I need to do this or find a substitute for stringing actions in sequence.