1) Give a description of the problem
There is a set level command being sent by one of my pistons, and I can’t understand why. “White Bulb 2” is “Front Pot Lights”.
2) What is the expected behavior?
Lights turn on at 6:10AM, and off at sunrise.
3) What is happening/not happening?
Lights turn on at 6:10AM, and off at sunrise, then back on a few minutes later.
**4) Post a Green Snapshot of the piston
5) Attach any logs (From ST IDE and by turning logging level to Full)
Even if it is, that shouldn’t cause the piston to fire because it also needs to meet the condition of the switch being on, which it isn’t.
Again it was just a guess. Can’t say for certain until there are some logs to look through.
Today, the light came back on at 7:45AM, and there is nothing that appears in the WebCore logs, yet the IDE logs note that it was this piston that sent the set level command.
12/11/2017, 7:41:13 AM +296ms
+0ms
╔Received event [Home].time = 1512996074276 with a delay of -981ms
+447ms
║RunTime Analysis CS > 31ms > PS > 314ms > PE > 102ms > CE
+465ms
║Runtime (39930 bytes) successfully initialized in 314ms (v0.2.0ff.20171129) (463ms)
+467ms
║╔Execution stage started
+513ms
║║Executed physical command [Front Pot Lights].off() (12ms)
+514ms
║║Executed [Front Pot Lights].off (15ms)
+521ms
║╚Execution stage complete. (53ms)
+524ms
║Setting up scheduled job for Tue, Dec 12 2017 @ 6:10:00 AM EST (in 80926.181s), with 1 more job pending
+539ms
╚Event processed successfully (539ms)
12/11/2017, 7:41:04 AM +105ms
+1ms
╔Received event [Home].time = 1512996064643 with a delay of -538ms
+137ms
║RunTime Analysis CS > 19ms > PS > 45ms > PE > 72ms > CE
+148ms
║Runtime (39927 bytes) successfully initialized in 45ms (v0.2.0ff.20171129) (146ms)
+149ms
║╔Execution stage started
+170ms
║║Executed virtual command [Front Pot Lights].wait (0ms)
+171ms
║║Requesting a wake up for Mon, Dec 11 2017 @ 7:41:14 AM EST (in 10.0s)
+176ms
║╚Execution stage complete. (27ms)
+178ms
║Setting up scheduled job for Mon, Dec 11 2017 @ 7:41:14 AM EST (in 9.993s), with 2 more jobs pending
+193ms
╚Event processed successfully (192ms)
12/11/2017, 7:40:59 AM +128ms
+0ms
╔Received event [Home].time = 1512996060000 with a delay of -873ms
+169ms
║RunTime Analysis CS > 26ms > PS > 62ms > PE > 82ms > CE
+183ms
║Runtime (39931 bytes) successfully initialized in 62ms (v0.2.0ff.20171129) (182ms)
+185ms
║╔Execution stage started
+199ms
║║Comparison (time) 27659324 happens_daily_at (time) 22200000 = false (1ms)
+202ms
║║Cancelling condition #19’s schedules…
+203ms
║║Condition #19 evaluated false (7ms)
+206ms
║║Cancelling statement #19’s schedules…
+210ms
║║Requesting time schedule wake up at Tue, Dec 12 2017 @ 6:10:00 AM EST
+215ms
║║Condition group #15 evaluated false (state did not change) (20ms)
+257ms
║║Comparison (time) 27659348 happens_daily_at (datetime) 1512996060000 = true (1ms)
+259ms
║║Time restriction check passed
+261ms
║║Cancelling condition #24’s schedules…
+263ms
║║Condition #24 evaluated true (42ms)
+265ms
║║Cancelling statement #24’s schedules…
+272ms
║║Requesting time schedule wake up at Tue, Dec 12 2017 @ 7:41:00 AM EST
+286ms
║║Comparison (enum) on is (string) on = true (2ms)
+288ms
║║Condition #73 evaluated true (12ms)
+289ms
║║Cancelling condition #20’s schedules…
+291ms
║║Condition group #20 evaluated true (state changed) (71ms)
+295ms
║║Cancelling statement #21’s schedules…
+323ms
║║Executed virtual command [Front Pot Lights].sendPushNotification (21ms)
+341ms
║║Skipped execution of physical command [Front Pot Lights].setLevel([60]) because it would make no change to the device. (6ms)
+349ms
║║Executed physical command [Front Pot Lights].setLevel([55], [delay: 500]) (6ms)
+356ms
║║Executed physical command [Front Pot Lights].setLevel([50], [delay: 1000]) (5ms)
+361ms
║║Executed physical command [Front Pot Lights].setLevel([45], [delay: 1500]) (3ms)
+369ms
║║Executed physical command [Front Pot Lights].setLevel([40], [delay: 2000]) (5ms)
+375ms
║║Executed physical command [Front Pot Lights].setLevel([35], [delay: 2500]) (4ms)
+381ms
║║Executed physical command [Front Pot Lights].setLevel([30], [delay: 3000]) (5ms)
+388ms
║║Executed physical command [Front Pot Lights].setLevel([25], [delay: 3500]) (5ms)
+393ms
║║Executed physical command [Front Pot Lights].setLevel([20], [delay: 4000]) (3ms)
+399ms
║║Executed physical command [Front Pot Lights].setLevel([15], [delay: 4500]) (5ms)
+404ms
║║Executed physical command [Front Pot Lights].setLevel([10], [delay: 5000]) (3ms)
+410ms
║║Executed physical command [Front Pot Lights].setLevel([10], [delay: 5099]) (5ms)
+412ms
║║Executed virtual command [Front Pot Lights].fadeLevel (82ms)
+414ms
║║Requesting a wake up for Mon, Dec 11 2017 @ 7:41:04 AM EST (in 5.1s)
+422ms
║╚Execution stage complete. (238ms)
+425ms
║Setting up scheduled job for Mon, Dec 11 2017 @ 7:41:04 AM EST (in 5.091s), with 2 more jobs pending
+442ms
╚Event processed successfully (442ms)
12/11/2017, 6:09:59 AM +101ms
+1ms
╔Received event [Home].time = 1512990600000 with a delay of -900ms
+123ms
║RunTime Analysis CS > 18ms > PS > 36ms > PE > 69ms > CE
+134ms
║Runtime (39931 bytes) successfully initialized in 36ms (v0.2.0ff.20171129) (133ms)
+135ms
║╔Execution stage started
+145ms
║║Comparison (time) 22199244 happens_daily_at (time) 22200000 = true (0ms)
+147ms
║║Time restriction check passed
+148ms
║║Cancelling condition #19’s schedules…
+149ms
║║Condition #19 evaluated true (6ms)
+150ms
║║Cancelling statement #19’s schedules…
+154ms
║║Requesting time schedule wake up at Tue, Dec 12 2017 @ 6:10:00 AM EST
+164ms
║║Comparison (enum) on is (string) off = false (2ms)
+166ms
║║Cancelling condition #75’s schedules…
+167ms
║║Condition #75 evaluated false (11ms)
+168ms
║║Condition group #15 evaluated false (state did not change) (26ms)
+199ms
║║Comparison (time) 22199273 happens_daily_at (datetime) 1512996060000 = false (1ms)
+201ms
║║Condition #24 evaluated false (29ms)
+202ms
║║Cancelling statement #24’s schedules…
+207ms
║║Requesting time schedule wake up at Mon, Dec 11 2017 @ 7:41:00 AM EST
+210ms
║║Condition group #20 evaluated false (state did not change) (39ms)
+214ms
║╚Execution stage complete. (79ms)
+216ms
║Setting up scheduled job for Mon, Dec 11 2017 @ 7:41:00 AM EST (in 5460.684s), with 1 more job pending
+334ms
╚Event processed successfully (334ms)
See…no logs from WebCore about it turning back on…
On a possibly/possibly not related note, it looks like the ‘Set Level’ is being sent 3:45 after the piston is sending the ‘Turn Off’ command in both the examples above.
For some reason your fade commands are coming in super fast - I think your switch is getting overwhelmed/behind and sending status updates to the piston after it’s done executing. I’ve had lights turn on back on in similar situations (mine was a DTH issue but same end-result where the lights would switch back on).
Notice you’re not getting responses from your light for each dimmer level - and some are only thousands of a second apart. Try changing 10 seconds to 1,000 to see what it does for you. I’ve inexplicably had a couple pistons where even those I select “seconds” the delay is set in milliseconds, too. Never figured that out but jacked up my delay numbers and they seem happy.
║║Executed physical command [Front Pot Lights].setLevel([55], [delay: 500]) (6ms)
+356ms
║║Executed physical command [Front Pot Lights].setLevel([50], [delay: 1000]) (5ms)
+361ms
║║Executed physical command [Front Pot Lights].setLevel([45], [delay: 1500]) (3ms)
+369ms
║║Executed physical command [Front Pot Lights].setLevel([40], [delay: 2000]) (5ms)
+375ms
║║Executed physical command [Front Pot Lights].setLevel([35], [delay: 2500]) (4ms)
+381ms
║║Executed physical command [Front Pot Lights].setLevel([30], [delay: 3000]) (5ms)
+388ms
║║Executed physical command [Front Pot Lights].setLevel([25], [delay: 3500]) (5ms)
+393ms
║║Executed physical command [Front Pot Lights].setLevel([20], [delay: 4000]) (3ms)
+399ms
║║Executed physical command [Front Pot Lights].setLevel([15], [delay: 4500]) (5ms)
+404ms
║║Executed physical command [Front Pot Lights].setLevel([10], [delay: 5000]) (3ms)
+410ms
║║Executed physical command [Front Pot Lights].setLevel([10], [delay: 5099]) (5ms)
^That’s 11 commands in 50 milliseconds, despite your command being 5 seconds. Your dimmer doesn’t stand a chance. 
Edit to add: with my DTH, I’d send an off command to a dimmer and it would begin shutting off. By default, it had about a 3 second fade-to-off feature. My DTH would ping it for status after 1.5 seconds, and the dimmer would respond “I’m at 25%”. The piston would treat that like a new event and set the light at 25%.
Slightly different but I think the same thing is happening to you when your dimmer gets behind the commands from your piston.
Interesting thought, thanks! I’ve upped all the fade times, as well as the wait after, and will see what happens tonight!
Disregard my comment about changing 10 to 1000, change your 5 seconds to 5000. Too much jet lag today.
I think your delay is trying to execute in 5ms but that’s faster than webcore can physically execute, so the 50ms is just a coincidence. You want to test your delay at 1000x to see if it’ll fix it. You can also change “seconds” to “milliseconds” at the same time. It’ll still make a 5 second delay but avoid the scenario where “seconds” works propane you end up with about a 90 minute delay.
Increasing the delays seems to have helped - the morning piston is now working (it was previously turning back on too), but the evening one is still not working. Will tweak timing/delays a bit more and report back.
TLDR; Using FADE TO over a short time (<3-5ish seconds) can overwhelm the switches (in this case, Leviton DZ6HD) causing them to run SET LEVEL commands out of order with other commands thereby turning lights back on/off when they shouldn’t be. Fix is (so far) to increase time overwhich fade is applied. Still testing, but progress made.
It looks like the root cause here was exactly what @michicago said, it was fading over too short of a time. Since increasing the fade time to 7500ms from 5sec, it is working flawlessly now.
