Inconsistency in execution

#1

1) Give a description of the problem
Piston is supposed to control hue lightstrip with two motion sensors. Sometime works, sometime it does not

2) What is the expected behaviour?
The piston is supposed to execute Executed physical command [Hue Bedroom].off() and turn off the light

3) What is happening/not happening?
Sometimes the light get turned off sometimes does not. here is an example
1/14/2020, 6:02:44 AM +81ms
+0ms ╔Received event [Home].time = 1578999765065 with a delay of -984ms
+127ms ║RunTime Analysis CS > 27ms > PS > 55ms > PE > 45ms > CE
+130ms ║Runtime (43313 bytes) successfully initialized in 55ms (v0.3.110.20191009) (128ms)
+131ms ║╔Execution stage started
+170ms ║║Executed physical command [Hue Bedroom].off() (10ms)
+172ms ║║Executed [Hue Bedroom].off (12ms)
+174ms ║╚Execution stage complete. (43ms)
+176ms ╚Event processed successfully (176ms)
1/14/2020, 7:12:07 AM +153ms
+0ms ╔Received event [Home].time = 1579003928507 with a delay of -1354ms
+186ms ║RunTime Analysis CS > 69ms > PS > 67ms > PE > 50ms > CE
+189ms ║Runtime (43312 bytes) successfully initialized in 67ms (v0.3.110.20191009) (188ms)
+190ms ║╔Execution stage started
+191ms ║╚Execution stage complete. (0ms)
+192ms ╚Event processed successfully (191ms)

**4) Post a Green Snapshot of the piston![image|45x37]

image
image.png1178×1137 57.4 KB

5) Attach logs after turning logging level to Full
1/14/2020, 7:12:07 AM +153ms
+0ms ╔Received event [Home].time = 1579003928507 with a delay of -1354ms
+186ms ║RunTime Analysis CS > 69ms > PS > 67ms > PE > 50ms > CE
+189ms ║Runtime (43312 bytes) successfully initialized in 67ms (v0.3.110.20191009) (188ms)
+190ms ║╔Execution stage started
+191ms ║╚Execution stage complete. (0ms)
+192ms ╚Event processed successfully (191ms)

1/14/2020, 7:09:08 AM +235ms
+2ms ╔Received event [Bedroom Motion].motion = inactive with a delay of 123ms
+175ms ║RunTime Analysis CS > 56ms > PS > 64ms > PE > 55ms > CE
+178ms ║Runtime (43310 bytes) successfully initialized in 64ms (v0.3.110.20191009) (174ms)
+178ms ║╔Execution stage started
+223ms ║║Comparison (time) 25748416 is_between (time) 1579037760000 … (time) 1579003920000 = true (7ms)
+224ms ║║Time restriction check passed
+225ms ║║Condition #41 evaluated true (44ms)
+226ms ║║Condition group #null evaluated true (state did not change) (45ms)
+235ms ║║Comparison (enum) inactive changes_to (string) active = false (0ms)
+237ms ║║Cancelling condition #2’s schedules…
+238ms ║║Condition #2 evaluated false (9ms)
+239ms ║║Cancelling condition #1’s schedules…
+239ms ║║Condition group #1 evaluated false (state changed) (12ms)
+245ms ║║Comparison (enum) inactive changes_to (string) inactive = true (0ms)
+247ms ║║Condition #19 evaluated true (7ms)
+254ms ║║Comparison (enum) on is (string) on = true (1ms)
+255ms ║║Condition #32 evaluated true (8ms)
+256ms ║║Condition group #18 evaluated true (state did not change) (16ms)
+261ms ║║Comparison (string) :74a897f25ee3b31d6c771c70eb36e3fb: is (string) :74a897f25ee3b31d6c771c70eb36e3fb: = true (1ms)
+262ms ║║Cancelling condition #23’s schedules…
+263ms ║║Condition #23 evaluated true (5ms)
+264ms ║║Cancelling condition #20’s schedules…
+265ms ║║Condition group #20 evaluated true (state changed) (7ms)
+266ms ║║Cancelling statement #20’s schedules…
+270ms ║║Executed virtual command [Hue Bedroom].wait (0ms)
+271ms ║║Requesting a wake up for Tue, Jan 14 2020 @ 7:12:08 AM EST (in 180.0s)
+275ms ║╚Execution stage complete. (97ms)
+353ms ║Setting up scheduled job for Tue, Jan 14 2020 @ 7:12:08 AM EST (in 179.919s)
+360ms ╚Event processed successfully (360ms

1/14/2020, 7:08:41 AM +81ms
+1ms ╔Received event [Bedroom Motion].motion = active with a delay of 88ms
+118ms ║RunTime Analysis CS > 25ms > PS > 43ms > PE > 50ms > CE
+120ms ║Runtime (43316 bytes) successfully initialized in 43ms (v0.3.110.20191009) (118ms)
+121ms ║╔Execution stage started
+160ms ║║Comparison (time) 25721205 is_between (time) 1579037760000 … (time) 1579003920000 = true (7ms)
+161ms ║║Time restriction check passed
+162ms ║║Condition #41 evaluated true (38ms)
+163ms ║║Condition group #null evaluated true (state did not change) (39ms)
+171ms ║║Comparison (enum) active changes_to (string) active = true (1ms)
+172ms ║║Cancelling condition #2’s schedules…
+173ms ║║Condition #2 evaluated true (8ms)
+180ms ║║Comparison (enum) off is (string) off = true (1ms)
+181ms ║║Condition #3 evaluated true (7ms)
+182ms ║║Cancelling condition #1’s schedules…
+183ms ║║Condition group #1 evaluated true (state changed) (19ms)
+188ms ║║Comparison (string) :74a897f25ee3b31d6c771c70eb36e3fb: is (string) :74a897f25ee3b31d6c771c70eb36e3fb: = true (1ms)
+189ms ║║Cancelling condition #10’s schedules…
+190ms ║║Condition #10 evaluated true (5ms)
+198ms ║║Comparison (enum) off is (string) off = true (1ms)
+199ms ║║Cancelling condition #33’s schedules…
+200ms ║║Condition #33 evaluated true (9ms)
+201ms ║║Cancelling condition #4’s schedules…
+202ms ║║Condition group #4 evaluated true (state changed) (16ms)
+203ms ║║Cancelling statement #4’s schedules…
+214ms ║║Executed physical command [Hue Bedroom].setLevel([50]) (8ms)
+215ms ║║Executed [Hue Bedroom].setLevel (10ms)
+221ms ║║Comparison (string) :74a897f25ee3b31d6c771c70eb36e3fb: is (string) :98a779fd563e96b34cce96ff82913e82: = false (1ms)
+222ms ║║Cancelling condition #17’s schedules…
+223ms ║║Condition #17 evaluated false (6ms)
+224ms ║║Cancelling condition #11’s schedules…
+225ms ║║Condition group #11 evaluated false (state changed) (7ms)
+227ms ║╚Execution stage complete. (106ms)
+228ms ╚Event processed successfully (228ms)

1/14/2020, 6:02:44 AM +81ms
+0ms ╔Received event [Home].time = 1578999765065 with a delay of -984ms
+127ms ║RunTime Analysis CS > 27ms > PS > 55ms > PE > 45ms > CE
+130ms ║Runtime (43313 bytes) successfully initialized in 55ms (v0.3.110.20191009) (128ms)
+131ms ║╔Execution stage started
+170ms ║║Executed physical command [Hue Bedroom].off() (10ms)
+172ms ║║Executed [Hue Bedroom].off (12ms)
+174ms ║╚Execution stage complete. (43ms)
+176ms ╚Event processed successfully (176ms)

1/14/2020, 6:01:44 AM +814ms
+2ms ╔Received event [Bedroom Motion].motion = inactive with a delay of 111ms
+141ms ║RunTime Analysis CS > 27ms > PS > 61ms > PE > 53ms > CE
+144ms ║Runtime (43313 bytes) successfully initialized in 61ms (v0.3.110.20191009) (141ms)
+145ms ║╔Execution stage started
+189ms ║║Comparison (time) 21704962 is_between (time) 1579037760000 … (time) 1579003920000 = true (7ms)
+190ms ║║Time restriction check passed
+191ms ║║Condition #41 evaluated true (43ms)
+192ms ║║Condition group #null evaluated true (state did not change) (45ms)
+203ms ║║Comparison (enum) inactive changes_to (string) active = false (1ms)
+205ms ║║Cancelling condition #2’s schedules…
+206ms ║║Condition #2 evaluated false (12ms)
+207ms ║║Cancelling condition #1’s schedules…
+208ms ║║Condition group #1 evaluated false (state changed) (14ms)
+216ms ║║Comparison (enum) inactive changes_to (string) inactive = true (1ms)
+218ms ║║Condition #19 evaluated true (9ms)
+226ms ║║Comparison (enum) on is (string) on = true (2ms)
+227ms ║║Condition #32 evaluated true (8ms)
+228ms ║║Condition group #18 evaluated true (state did not change) (19ms)
+233ms ║║Comparison (string) :98a779fd563e96b34cce96ff82913e82: is (string) :74a897f25ee3b31d6c771c70eb36e3fb: = false (1ms)
+235ms ║║Condition #23 evaluated false (5ms)
+236ms ║║Condition group #20 evaluated false (state did not change) (6ms)
+241ms ║║Comparison (string) :98a779fd563e96b34cce96ff82913e82: is (string) :98a779fd563e96b34cce96ff82913e82: = true (1ms)
+243ms ║║Condition #27 evaluated true (5ms)
+244ms ║║Condition group #24 evaluated true (state did not change) (6ms)
+245ms ║║Cancelling statement #24’s schedules…
+249ms ║║Executed virtual command [Hue Bedroom].wait (0ms)
+250ms ║║Requesting a wake up for Tue, Jan 14 2020 @ 6:02:45 AM EST (in 60.0s)
+254ms ║╚Execution stage complete. (109ms)
+255ms ║Setting up scheduled job for Tue, Jan 14 2020 @ 6:02:45 AM EST (in 59.996s)
+269ms ╚Event processed successfully (269ms)

1/14/2020, 6:01:19 AM +213ms
+2ms ╔Received event [Bedroom Motion].motion = active with a delay of 110ms
+140ms ║RunTime Analysis CS > 23ms > PS > 51ms > PE > 65ms > CE
+142ms ║Runtime (43318 bytes) successfully initialized in 51ms (v0.3.110.20191009) (139ms)
+143ms ║╔Execution stage started
+188ms ║║Comparison (time) 21679360 is_between (time) 1579037760000 … (time) 1579003920000 = true (8ms)
+189ms ║║Time restriction check passed
+190ms ║║Condition #41 evaluated true (44ms)
+191ms ║║Condition group #null evaluated true (state did not change) (45ms)
+200ms ║║Comparison (enum) active changes_to (string) active = true (0ms)
+201ms ║║Cancelling condition #2’s schedules…
+202ms ║║Condition #2 evaluated true (9ms)
+210ms ║║Comparison (enum) off is (string) off = true (1ms)
+211ms ║║Condition #3 evaluated true (8ms)
+212ms ║║Cancelling condition #1’s schedules…
+213ms ║║Condition group #1 evaluated true (state changed) (19ms)
+218ms ║║Comparison (string) :98a779fd563e96b34cce96ff82913e82: is (string) :74a897f25ee3b31d6c771c70eb36e3fb: = false (2ms)
+219ms ║║Condition #10 evaluated false (4ms)
+220ms ║║Condition group #4 evaluated false (state did not change) (6ms)
+226ms ║║Comparison (string) :98a779fd563e96b34cce96ff82913e82: is (string) :98a779fd563e96b34cce96ff82913e82: = true (1ms)
+227ms ║║Condition #17 evaluated true (4ms)
+234ms ║║Comparison (enum) off is (string) off = true (2ms)
+235ms ║║Cancelling condition #34’s schedules…
+236ms ║║Condition #34 evaluated true (8ms)
+237ms ║║Cancelling condition #11’s schedules…
+238ms ║║Condition group #11 evaluated true (state changed) (16ms)
+239ms ║║Cancelling statement #11’s schedules…
+257ms ║║Executed physical command [Hue Bedroom].setLevel([25]) (14ms)
+258ms ║║Executed [Hue Bedroom].setLevel (15ms)
+260ms ║╚Execution stage complete. (117ms)
+261ms ╚Event processed successfully (261ms)

#2

The WITH on line 49 should have TCP set to Never, so it continues after the WAIT.
I am pretty sure that the WITH on line 57 will need the same…

(both failures occurred after the WAIT)

#3

You may want to move everything below the Else If section into a separate IF Block outside of the first IF BLOCK… so basically two IF Blocks… one for active and one for when it changes to inactive :slight_smile:

#4

I have just changed the TCP params but not sure how that will solve the inconsistency issue. I have couple of other pistons involving WeMo mini switches… turns on a fan and sometime turns it off sometimes it does not after 15 minutes wait time. I have pause all my pistons and had to use smartthings app
Thank you

#5

I have been having some hue integration issues lately on pistons that have been working reliably for months. It maybe just the platform being unstable.

#6

Interesting. The 6am(-ish) run shows a 1 minute wait being scheduled with a normal wake up and the light being turned off. The 7am(-ish) run shows a 3 minute wait being scheduled but the wake up looks like it does when the scheduled task has been cancelled. Except there isn’t sign of any intermediate run of the piston to have caused the task to be cancelled. I’m missing something.

The only thing I notice is that sunrise where you are seems to have been at 12 minutes past the hour. If that was 7:12am that would have placed the wake up after sunrise. Unfortunately I think that is pure coincidence and it has no bearing on how the piston wakes up.

#7

It could be because of the sunrise time that kicked in in the meantime but the wake up call to turn the lights off was already set so I would not expect that outcome. Might be some coincidence but I’ve been getting some inconsistencies with other pistons lately and can’t figure what’s going on: my local wifi network or the cloud to smartthings hub issue… I haven’t seen those issues when using smartapps in smartthings classic app. Hmmm… Thank you for your reply. Much appreciated