Lights won't turn off...used to..bug?

Automate85 · 2017-08-22 03:01:00 UTC

So this Piston used to work…and now it doesn’t. The lights turn on when motion is sensed, but never turn off after the 5 minute timer. The last log entry shows setting up the timer, but I wait and wait and nothing happens. It’s like the scheduled job was never scheduled and thus the lights don’t turn off.

Logs:
8/21/2017, 7:50:57 PM +186ms
+2ms ╔Received event [Doorbell-Front].motion = active with a delay of 94ms
+166ms ║RunTime Analysis CS > 22ms > PS > 65ms > PE > 79ms > CE
+174ms ║Runtime (36944 bytes) successfully initialized in 65ms (v0.2.0e5.20170812) (171ms)
+176ms ║╔Execution stage started
+198ms ║║Comparison (enum) active changes_to (string) active = true (1ms)
+200ms ║║Cancelling condition #8’s schedules…
+201ms ║║Condition #8 evaluated true (13ms)
+203ms ║║Cancelling condition #1’s schedules…
+204ms ║║Condition group #1 evaluated true (state changed) (17ms)
+256ms ║║Comparison (time) 71457395 is_between (time) 1503368820000 … (time) 1503321360000 = true (14ms)
+258ms ║║Time restriction check passed
+261ms ║║Condition #7 evaluated true (51ms)
+262ms ║║Condition group #2 evaluated true (state did not change) (54ms)
+266ms ║║Cancelling statement #3’s schedules…
+496ms ║║Executed physical command [Light-1st FL stairs].setLevel([100]) (219ms)
+497ms ║║Executed [Light-1st FL stairs].setLevel (221ms)
+547ms ║║Executed physical command [Light-Entry].setLevel([100]) (46ms)
+548ms ║║Executed [Light-Entry].setLevel (48ms)
+594ms ║║Executed physical command [Light-Porch].setLevel([100]) (43ms)
+595ms ║║Executed [Light-Porch].setLevel (45ms)
+601ms ║║Skipped execution of physical command [Light-1st FL stairs].on([]) because it would make no change to the device. (3ms)
+602ms ║║Executed [Light-1st FL stairs].on (5ms)
+607ms ║║Skipped execution of physical command [Light-Entry].on([]) because it would make no change to the device. (3ms)
+608ms ║║Executed [Light-Entry].on (5ms)
+614ms ║║Skipped execution of physical command [Light-Porch].on([]) because it would make no change to the device. (4ms)
+615ms ║║Executed [Light-Porch].on (6ms)
+621ms ║║Executed virtual command [Light-1st FL stairs, Light-Entry, Light-Porch].wait (1ms)
+623ms ║║Requesting a wake up for Mon, Aug 21 2017 @ 7:55:57 PM PDT (in 300.0s)
+634ms ║╚Execution stage complete. (458ms)
+636ms ║Setting up scheduled job for Mon, Aug 21 2017 @ 7:55:57 PM PDT (in 299.989s)
+654ms ╚Event processed successfully (653ms)

c1arkbar · 2017-08-22 11:40:01 UTC

Can you see in the quick facts that the job is scheduled?

Automate85 · 2017-08-22 21:19:34 UTC

Last executed: 8/22/2017, 1:59:48 PM

Next scheduled: never

c1arkbar · 2017-08-22 22:28:45 UTC

I don’t know why it wouldn’t schedule it when the logs are saying it’s secheduled. Have you tried executing it while watching the live logs on ST?

Automate85 · 2017-08-22 22:31:15 UTC

Where/how do I do that?

c1arkbar · 2017-08-22 22:33:23 UTC

Log into the ST IDE and select live logging. Then trigger your piston by activating the motion. Come back and check out the logs generated for webcore and that piston name

Automate85 · 2017-08-23 04:15:55 UTC

I looked at the live logs but no idea what I’m looking for. I filtered on ‘webcore’ in the live logs and there were no entries.

c1arkbar · 2017-08-23 04:20:38 UTC

Also check under the pistons name

Automate85 · 2017-08-23 04:23:14 UTC

20e7c44a-9fc9-459e-8530-74eef9195a28 9:22:10 PM: info ╔ Event processed successfully (423ms)
20e7c44a-9fc9-459e-8530-74eef9195a28 9:22:10 PM: trace ║╔ Execution stage complete. (35ms)
20e7c44a-9fc9-459e-8530-74eef9195a28 9:22:10 PM: debug ║║ Condition group #1 evaluated false (state changed) (17ms)
20e7c44a-9fc9-459e-8530-74eef9195a28 9:22:10 PM: debug ║║ Cancelling condition #1’s schedules…
20e7c44a-9fc9-459e-8530-74eef9195a28 9:22:10 PM: debug ║║ Condition #8 evaluated false (13ms)
20e7c44a-9fc9-459e-8530-74eef9195a28 9:22:10 PM: debug ║║ Cancelling condition #8’s schedules…
20e7c44a-9fc9-459e-8530-74eef9195a28 9:22:10 PM: debug ║║ Comparison (enum) inactive changes_to (string) active = false (1ms)
20e7c44a-9fc9-459e-8530-74eef9195a28 9:22:10 PM: trace ║╚ Execution stage started
20e7c44a-9fc9-459e-8530-74eef9195a28 9:22:10 PM: trace ║ Runtime (38034 bytes) successfully initialized in 67ms (v0.2.0e5.20170812) (375ms)
20e7c44a-9fc9-459e-8530-74eef9195a28 9:22:10 PM: debug ║ RunTime Analysis CS > 25ms > PS > 67ms > PE > 181ms > CE
20e7c44a-9fc9-459e-8530-74eef9195a28 9:22:10 PM: info ╚ Received event [Doorbell-Front].motion = inactive with a delay of 180ms
20e7c44a-9fc9-459e-8530-74eef9195a28 9:21:40 PM: info ║ Setting up scheduled job for Tue, Aug 22 2017 @ 9:26:40 PM PDT (in 299.988s)
20e7c44a-9fc9-459e-8530-74eef9195a28 9:21:40 PM: trace ║║ Executed [Light-Entry].on (6ms)
20e7c44a-9fc9-459e-8530-74eef9195a28 9:21:40 PM: debug ║║ Executed physical command [Light-Entry].setLevel([80]) (73ms)
20e7c44a-9fc9-459e-8530-74eef9195a28 9:21:40 PM: info ╔ Event processed successfully (560ms)
20e7c44a-9fc9-459e-8530-74eef9195a28 9:21:40 PM: debug ║║ Cancelling statement #3’s schedules…
20e7c44a-9fc9-459e-8530-74eef9195a28 9:21:40 PM: trace ║╔ Execution stage complete. (286ms)
20e7c44a-9fc9-459e-8530-74eef9195a28 9:21:40 PM: debug ║║ Condition group #2 evaluated true (state did not change) (80ms)
20e7c44a-9fc9-459e-8530-74eef9195a28 9:21:40 PM: trace ║║ Executed virtual command [Light-Entry, Light-Porch].wait (1ms)
20e7c44a-9fc9-459e-8530-74eef9195a28 9:21:40 PM: debug ║║ Skipped execution of physical command [Light-Porch].on([]) because it would make no change to the device. (5ms)
20e7c44a-9fc9-459e-8530-74eef9195a28 9:21:40 PM: trace ║║ Executed [Light-Porch].setLevel (47ms)
20e7c44a-9fc9-459e-8530-74eef9195a28 9:21:40 PM: debug ║║ Executed physical command [Light-Porch].setLevel([80]) (45ms)
20e7c44a-9fc9-459e-8530-74eef9195a28 9:21:40 PM: debug ║║ Time restriction check passed
20e7c44a-9fc9-459e-8530-74eef9195a28 9:21:40 PM: debug ║║ Condition group #1 evaluated true (state changed) (16ms)
20e7c44a-9fc9-459e-8530-74eef9195a28 9:21:40 PM: debug ║║ Condition #7 evaluated true (77ms)
20e7c44a-9fc9-459e-8530-74eef9195a28 9:21:40 PM: debug ║║ Comparison (time) 76900527 is_between (time) 1503455160000 … (time) 1503407820000 = true (16ms)
20e7c44a-9fc9-459e-8530-74eef9195a28 9:21:40 PM: debug ║║ Cancelling condition #1’s schedules…
20e7c44a-9fc9-459e-8530-74eef9195a28 9:21:40 PM: debug ║║ Condition #8 evaluated true (12ms)
20e7c44a-9fc9-459e-8530-74eef9195a28 9:21:40 PM: trace ║╚ Execution stage started
20e7c44a-9fc9-459e-8530-74eef9195a28 9:21:40 PM: debug ║ RunTime Analysis CS > 20ms > PS > 51ms > PE > 170ms > CE
20e7c44a-9fc9-459e-8530-74eef9195a28 9:21:40 PM: debug ║║ Cancelling condition #8’s schedules…
20e7c44a-9fc9-459e-8530-74eef9195a28 9:21:40 PM: debug ║║ Comparison (enum) active changes_to (string) active = true (1ms)
20e7c44a-9fc9-459e-8530-74eef9195a28 9:21:40 PM: trace ║ Runtime (38039 bytes) successfully initialized in 51ms (v0.2.0e5.20170812) (249ms)
20e7c44a-9fc9-459e-8530-74eef9195a28 9:21:40 PM: info ╚ Received event [Doorbell-Front].motion = active with a delay of 144ms

c1arkbar · 2017-08-23 05:01:48 UTC

Ok so I imported your piston and triggered it without making any changes. It turned the lights on and started the countdown to turning them off. See below screen shot

Under quick facts it has it scheduled

And the logs for the triggered event

After the time expired it shut off all the lights.

My best guess is that you should restore it from backup code and see if that solves some mystery issue

Automate85 · 2017-08-24 02:13:46 UTC

Nope…did a backup and restore, then paused the old Piston. Still broke…lights do NOT turn off…ever. “next scheduled” is always “never”.

c1arkbar · 2017-08-24 02:16:36 UTC

This baffles me. Cause it worked for me first go

Automate85 · 2017-08-24 02:33:24 UTC

I did a page refresh right after I triggered motion, and the next scheduled did populate. However, that time passed and lights are still on.

Automate85 · 2017-08-24 03:03:37 UTC

Ok this is interesting. If I change the timer to be 15 seconds, the lights go off after 15 seconds. Changing the timeout to 45 seconds results in lights staying on “forever”.

c1arkbar · 2017-08-24 03:14:25 UTC

Have you viewed the trace after triggering it?

Automate85 · 2017-08-24 03:29:16 UTC

Updated the piston to really show the weirdness. The first set of lights now never turn off with the 30 second timer. Change it to 20, and they turn off in 20 seconds. The second set of lights, even if the first get stuck on, do turn off after 25 seconds. Go past 30 on the second set of lights and they too get stuck on.

The trace didn’t really speak to me…

c1arkbar · 2017-08-24 13:23:46 UTC

I am at a loss here. @ady624 any ideas?

ady624 · 2017-08-24 14:23:40 UTC

30s seems like the threshold of motion (motion becomes inactive) - causing cancellations.

Try setting the Never Cancel on the actions themselves, rather than the IF - that should do the trick, I guess the TCP does not trickle down to be inherited by child statements. Please let me know if that fixes it.

c1arkbar · 2017-08-24 15:36:03 UTC

I was under the impression that the never cancel was applied to everything it encompassed.

And it would make sense why it worked in the virtual hub I tested it with above. I activated the motion then set my phone down and watched the trace/logs while browsing the forum. I never flipped it back to inactive.

Automate85 · 2017-08-25 02:48:17 UTC

I put a never cancel on the async with and with lines, and now it works as expected. I would have never figured this out on my own. Can I assume this is some type of bug? I saw someone on facebook have the exact same problem just today with a Piston that had the same functionality.