Fade over time and task cancellation


#8

^^This makes perfect sense now… Thanks again, now I have more ammo to create better and more efficient pistons.

woot!


#9

okay, so the piston still won’t cancel when the switch’s level or switch changes… Am I missing something here, any ideas?


EDIT: I’ve also tried structuring it as:
ON EVENTS FROM
Dimmer5 or $lights
Cancel all pending tasks


that didn’t work either


#10

Interesting that the dimmer 5 didn’t work. Can you turn logs on full and post?


#11

okay, so here’s the logging output… During the transition, I went into smartthings and turned off one of the lights (which was turned back on and didn’t cancel all pending tasks).

12/15/2017, 10:01:29 AM +860ms

+1ms ╔Received event [Dinner Table #1].switch = on with a delay of 925ms
+10427ms ║RunTime Analysis CS > 21ms > PS > 10258ms > PE > 148ms > CE
+10428ms ║Piston waited at a semaphore for 10219ms
+10431ms ║Runtime (41679 bytes) successfully initialized in 10258ms (v0.2.100.20171211) (10429ms)
+10432ms ║╔Execution stage started
+10449ms ║║Comparison (enum) off is (string) off = true (3ms)
+10451ms ║║Condition #9 evaluated true (12ms)
+10452ms ║║Condition group #1 evaluated true (state did not change) (13ms)
+10473ms ║║Comparison (enum) off is (string) off = true (3ms)
+10474ms ║║Condition #10 evaluated true (10ms)
+10475ms ║║Condition group #6 evaluated true (state did not change) (11ms)
+10495ms ║║Cancelling statement #16’s schedules…
+10497ms ║║Executed virtual command cancelTasks (1ms)
+10500ms ║╚Execution stage complete. (68ms)
+10502ms ║Setting up scheduled job for Fri, Dec 15 2017 @ 10:30:00 PM EST (in 44899.639s), with 1 more job pending
+10512ms ╚Event processed successfully (10513ms)
12/15/2017, 10:01:30 AM +134ms
+1ms ╔Received event [Dinner Table #4].level = 11 with a delay of 946ms
+9892ms ║RunTime Analysis CS > 11ms > PS > 9794ms > PE > 87ms > CE
+9893ms ║Piston waited at a semaphore for 9767ms
+9896ms ║Runtime (41671 bytes) successfully initialized in 9794ms (v0.2.100.20171211) (9893ms)
+9897ms ║╔Execution stage started
+9914ms ║║Comparison (enum) off is (string) off = true (2ms)
+9915ms ║║Condition #9 evaluated true (13ms)
+9916ms ║║Condition group #1 evaluated true (state did not change) (15ms)
+9932ms ║║Comparison (enum) off is (string) off = true (2ms)
+9933ms ║║Condition #10 evaluated true (7ms)
+9934ms ║║Condition group #6 evaluated true (state did not change) (8ms)
+9947ms ║║Cancelling statement #16’s schedules…
+9949ms ║║Executed virtual command cancelTasks (1ms)
+9955ms ║╚Execution stage complete. (59ms)
+9957ms ║Setting up scheduled job for Fri, Dec 15 2017 @ 10:30:00 PM EST (in 44899.91s), with 1 more job pending
+9966ms ╚Event processed successfully (9966ms)
12/15/2017, 10:01:29 AM +911ms
+1ms ╔Received event [Dinner Table #2].level = 11 with a delay of 927ms
+10074ms ║RunTime Analysis CS > 14ms > PS > 9970ms > PE > 91ms > CE
+10075ms ║Piston waited at a semaphore for 9939ms
+10078ms ║Runtime (41673 bytes) successfully initialized in 9970ms (v0.2.100.20171211) (10075ms)
+10079ms ║╔Execution stage started
+10092ms ║║Comparison (enum) off is (string) off = true (1ms)
+10093ms ║║Condition #9 evaluated true (9ms)
+10094ms ║║Condition group #1 evaluated true (state did not change) (10ms)
+10110ms ║║Comparison (enum) off is (string) off = true (2ms)
+10111ms ║║Condition #10 evaluated true (8ms)
+10112ms ║║Condition group #6 evaluated true (state did not change) (9ms)
+10131ms ║║Cancelling statement #16’s schedules…
+10133ms ║║Executed virtual command cancelTasks (0ms)
+10135ms ║╚Execution stage complete. (57ms)
+10137ms ║Setting up scheduled job for Fri, Dec 15 2017 @ 10:30:00 PM EST (in 44899.953s), with 1 more job pending
+10144ms ╚Event processed successfully (10144ms)
12/15/2017, 10:01:32 AM +495ms
+137ms ╔Stopping piston…
+320ms ╚Piston successfully stopped (184ms)
12/15/2017, 10:01:30 AM +200ms
+1ms ╔Received event [Dinner Table #3].level = 11 with a delay of 1107ms
+173ms ║RunTime Analysis CS > 18ms > PS > 34ms > PE > 121ms > CE
+175ms ║Runtime (41599 bytes) successfully initialized in 34ms (v0.2.100.20171211) (174ms)
+176ms ║╔Execution stage started
+190ms ║║Comparison (enum) off is (string) off = true (1ms)
+191ms ║║Condition #9 evaluated true (9ms)
+192ms ║║Condition group #1 evaluated true (state did not change) (11ms)
+208ms ║║Comparison (enum) off is (string) off = true (2ms)
+209ms ║║Condition #10 evaluated true (7ms)
+210ms ║║Condition group #6 evaluated true (state did not change) (9ms)
+224ms ║║Cancelling statement #16’s schedules…
+226ms ║║Executed virtual command cancelTasks (1ms)
+251ms ║╚Execution stage complete. (75ms)
+264ms ║Setting up scheduled job for Fri, Dec 15 2017 @ 10:01:59 AM EST (in 28.974s), with 41 more jobs pending
+273ms ╚Event processed successfully (274ms)
12/15/2017, 10:01:29 AM +842ms
+1ms ╔Received event [Dinner Table #1].level = 11 with a delay of 912ms
+135ms ║RunTime Analysis CS > 18ms > PS > 28ms > PE > 90ms > CE
+138ms ║Runtime (41597 bytes) successfully initialized in 28ms (v0.2.100.20171211) (136ms)
+139ms ║╔Execution stage started
+151ms ║║Comparison (enum) off is (string) off = true (2ms)
+152ms ║║Condition #9 evaluated true (8ms)
+153ms ║║Condition group #1 evaluated true (state did not change) (10ms)
+169ms ║║Comparison (enum) off is (string) off = true (2ms)
+170ms ║║Condition #10 evaluated true (7ms)
+171ms ║║Condition group #6 evaluated true (state did not change) (8ms)
+185ms ║║Cancelling statement #16’s schedules…
+187ms ║║Executed virtual command cancelTasks (1ms)
+219ms ║║Executed physical command [Dinner Table #1].setLevel([11]) (8ms)
+238ms ║║Executed physical command [Dinner Table #2].setLevel([11]) (8ms)
+256ms ║║Executed physical command [Dinner Table #3].setLevel([11]) (7ms)
+274ms ║║Executed physical command [Dinner Table #4].setLevel([11]) (7ms)
+285ms ║╚Execution stage complete. (147ms)
+296ms ║Setting up scheduled job for Fri, Dec 15 2017 @ 10:01:59 AM EST (in 29.299s), with 41 more jobs pending
+317ms ╚Event processed successfully (317ms)
12/15/2017, 10:01:29 AM +413ms
+1ms ╔Received event [Home].time = 1513350089437 with a delay of -24ms
+170ms ║RunTime Analysis CS > 41ms > PS > 31ms > PE > 98ms > CE
+173ms ║Runtime (41596 bytes) successfully initialized in 31ms (v0.2.100.20171211) (171ms)
+174ms ║╔Execution stage started
+195ms ║║Executed physical command [Dinner Table #1].setLevel([11]) (6ms)
+218ms ║║Executed physical command [Dinner Table #2].setLevel([11]) (6ms)
+236ms ║║Executed physical command [Dinner Table #3].setLevel([11]) (6ms)
+254ms ║║Executed physical command [Dinner Table #4].setLevel([11]) (6ms)
+266ms ║╚Execution stage complete. (92ms)
+278ms ║Setting up scheduled job for Fri, Dec 15 2017 @ 10:01:59 AM EST (in 29.747s), with 41 more jobs pending
+286ms ╚Event processed successfully (285ms)
12/15/2017, 10:01:15 AM +835ms
+1ms ╔Received event [Dinner Table #1].switch = off with a delay of 942ms
+154ms ║RunTime Analysis CS > 17ms > PS > 42ms > PE > 96ms > CE
+157ms ║Runtime (41599 bytes) successfully initialized in 42ms (v0.2.100.20171211) (153ms)
+158ms ║╔Execution stage started
+171ms ║║Comparison (enum) off is (string) off = true (1ms)
+173ms ║║Condition #9 evaluated true (10ms)
+174ms ║║Condition group #1 evaluated true (state did not change) (11ms)
+191ms ║║Comparison (enum) off is (string) off = true (2ms)
+192ms ║║Condition #10 evaluated true (8ms)
+193ms ║║Condition group #6 evaluated true (state did not change) (9ms)
+208ms ║║Cancelling statement #16’s schedules…
+210ms ║║Executed virtual command cancelTasks (1ms)
+236ms ║╚Execution stage complete. (79ms)
+249ms ║Setting up scheduled job for Fri, Dec 15 2017 @ 10:01:29 AM EST (in 13.353s), with 45 more jobs pending
+260ms ╚Event processed successfully (260ms)
12/15/2017, 10:01:00 AM +177ms
+1ms ╔Received event [Dinner Table #3].level = 10 with a delay of 942ms
+10383ms ║RunTime Analysis CS > 21ms > PS > 10196ms > PE > 166ms > CE
+10384ms ║Piston waited at a semaphore for 10155ms
+10387ms ║Runtime (41678 bytes) successfully initialized in 10196ms (v0.2.100.20171211) (10384ms)
+10388ms ║╔Execution stage started
+10402ms ║║Comparison (enum) off is (string) off = true (2ms)
+10404ms ║║Condition #9 evaluated true (9ms)
+10405ms ║║Condition group #1 evaluated true (state did not change) (11ms)
+10424ms ║║Comparison (enum) off is (string) off = true (2ms)
+10426ms ║║Condition #10 evaluated true (9ms)
+10427ms ║║Condition group #6 evaluated true (state did not change) (11ms)
+10444ms ║║Cancelling statement #16’s schedules…
+10446ms ║║Executed virtual command cancelTasks (1ms)
+10468ms ║╚Execution stage complete. (81ms)
+10483ms ║Setting up scheduled job for Fri, Dec 15 2017 @ 10:01:29 AM EST (in 18.778s), with 45 more jobs pending
+10494ms ╚Event processed successfully (10493ms)
12/15/2017, 10:01:00 AM +275ms
+1ms ╔Received event [Dinner Table #4].level = 10 with a delay of 949ms
+10047ms ║RunTime Analysis CS > 17ms > PS > 9877ms > PE > 154ms > CE
+10049ms ║Piston waited at a semaphore for 9838ms
+10051ms ║Runtime (41674 bytes) successfully initialized in 9877ms (v0.2.100.20171211) (10049ms)
+10052ms ║╔Execution stage started
+10066ms ║║Comparison (enum) off is (string) off = true (2ms)
+10067ms ║║Condition #9 evaluated true (10ms)
+10068ms ║║Condition group #1 evaluated true (state did not change) (11ms)
+10087ms ║║Comparison (enum) off is (string) off = true (1ms)
+10088ms ║║Condition #10 evaluated true (9ms)
+10089ms ║║Condition group #6 evaluated true (state did not change) (10ms)
+10104ms ║║Cancelling statement #16’s schedules…
+10105ms ║║Executed virtual command cancelTasks (0ms)
+10126ms ║╚Execution stage complete. (75ms)
+10139ms ║Setting up scheduled job for Fri, Dec 15 2017 @ 10:01:29 AM EST (in 19.024s), with 45 more jobs pending
+10149ms ╚Event processed successfully (10149ms)
12/15/2017, 10:00:59 AM +807ms
+1ms ╔Received event [Dinner Table #3].switch = on with a delay of 925ms
+10301ms ║RunTime Analysis CS > 13ms > PS > 10208ms > PE > 80ms > CE
+10302ms ║Piston waited at a semaphore for 10178ms
+10304ms ║Runtime (41678 bytes) successfully initialized in 10208ms (v0.2.100.20171211) (10303ms)
+10305ms ║╔Execution stage started
+10317ms ║║Comparison (enum) off is (string) off = true (1ms)
+10319ms ║║Condition #9 evaluated true (9ms)
+10320ms ║║Condition group #1 evaluated true (state did not change) (10ms)
+10337ms ║║Comparison (enum) off is (string) off = true (2ms)
+10338ms ║║Condition #10 evaluated true (8ms)
+10339ms ║║Condition group #6 evaluated true (state did not change) (9ms)
+10354ms ║║Cancelling statement #16’s schedules…
+10356ms ║║Executed virtual command cancelTasks (0ms)
+10377ms ║╚Execution stage complete. (71ms)
+10390ms ║Setting up scheduled job for Fri, Dec 15 2017 @ 10:01:29 AM EST (in 19.241s), with 45 more jobs pending
+10402ms ╚Event processed successfully (10403ms)
12/15/2017, 10:00:59 AM +772ms
+0ms ╔Received event [Dinner Table #1].switch = on with a delay of 1048ms
+10278ms ║RunTime Analysis CS > 17ms > PS > 10174ms > PE > 87ms > CE
+10279ms ║Piston waited at a semaphore for 10145ms
+10281ms ║Runtime (41679 bytes) successfully initialized in 10174ms (v0.2.100.20171211) (10280ms)
+10282ms ║╔Execution stage started
+10294ms ║║Comparison (enum) off is (string) off = true (1ms)
+10296ms ║║Condition #9 evaluated true (8ms)
+10296ms ║║Condition group #1 evaluated true (state did not change) (9ms)
+10317ms ║║Comparison (enum) off is (string) off = true (1ms)
+10318ms ║║Condition #10 evaluated true (8ms)
+10319ms ║║Condition group #6 evaluated true (state did not change) (10ms)
+10333ms ║║Cancelling statement #16’s schedules…
+10334ms ║║Executed virtual command cancelTasks (0ms)
+10354ms ║╚Execution stage complete. (73ms)
+10370ms ║Setting up scheduled job for Fri, Dec 15 2017 @ 10:01:29 AM EST (in 19.296s), with 45 more jobs pending
+10380ms ╚Event processed successfully (10380ms)
12/15/2017, 10:01:00 AM +96ms
+1ms ╔Received event [Dinner Table #2].level = 10 with a delay of 968ms
+137ms ║RunTime Analysis CS > 18ms > PS > 32ms > PE > 87ms > CE
+139ms ║Runtime (41597 bytes) successfully initialized in 32ms (v0.2.100.20171211) (138ms)
+140ms ║╔Execution stage started
+155ms ║║Comparison (enum) off is (string) off = true (2ms)
+156ms ║║Condition #9 evaluated true (10ms)
+157ms ║║Condition group #1 evaluated true (state did not change) (12ms)
+175ms ║║Comparison (enum) off is (string) off = true (1ms)
+176ms ║║Condition #10 evaluated true (8ms)
+177ms ║║Condition group #6 evaluated true (state did not change) (9ms)
+192ms ║║Cancelling statement #16’s schedules…
+194ms ║║Executed virtual command cancelTasks (1ms)
+223ms ║╚Execution stage complete. (83ms)
+237ms ║Setting up scheduled job for Fri, Dec 15 2017 @ 10:01:29 AM EST (in 29.105s), with 45 more jobs pending
+245ms ╚Event processed successfully (245ms)
12/15/2017, 10:00:59 AM +732ms
+1ms ╔Received event [Dinner Table #2].switch = on with a delay of 968ms
+134ms ║RunTime Analysis CS > 18ms > PS > 33ms > PE > 83ms > CE
+137ms ║Runtime (41598 bytes) successfully initialized in 33ms (v0.2.100.20171211) (135ms)
+138ms ║╔Execution stage started
+152ms ║║Comparison (enum) off is (string) off = true (1ms)
+153ms ║║Condition #9 evaluated true (9ms)
+154ms ║║Condition group #1 evaluated true (state did not change) (11ms)
+171ms ║║Comparison (enum) off is (string) off = true (1ms)
+173ms ║║Condition #10 evaluated true (8ms)
+174ms ║║Condition group #6 evaluated true (state did not change) (10ms)
+189ms ║║Cancelling statement #16’s schedules…
+191ms ║║Executed virtual command cancelTasks (1ms)
+220ms ║╚Execution stage complete. (82ms)
+233ms ║Setting up scheduled job for Fri, Dec 15 2017 @ 10:01:29 AM EST (in 29.473s), with 45 more jobs pending
+245ms ╚Event processed successfully (245ms)
12/15/2017, 10:00:59 AM +143ms
+1ms ╔Received event [Home].time = 1513350060000 with a delay of -857ms
+136ms ║RunTime Analysis CS > 16ms > PS > 43ms > PE > 76ms > CE
+138ms ║Runtime (41597 bytes) successfully initialized in 43ms (v0.2.100.20171211) (136ms)
+139ms ║╔Execution stage started
+155ms ║║Cancelling statement #2’s schedules…
+172ms ║║Executed physical command [Dinner Table #1].on() (11ms)
+173ms ║║Executed [Dinner Table #1].on (13ms)
+188ms ║║Executed physical command [Dinner Table #2].on() (10ms)
+188ms ║║Executed [Dinner Table #2].on (13ms)
+203ms ║║Executed physical command [Dinner Table #3].on() (11ms)
+204ms ║║Executed [Dinner Table #3].on (13ms)
+217ms ║║Executed physical command [Dinner Table #4].on() (10ms)
+218ms ║║Executed [Dinner Table #4].on (11ms)
+236ms ║║Executed physical command [Dinner Table #1].setLevel([10]) (8ms)
+237ms ║║Executed [Dinner Table #1].setLevel (16ms)
+246ms ║║Executed physical command [Dinner Table #2].setLevel([10]) (8ms)
+247ms ║║Executed [Dinner Table #2].setLevel (10ms)
+256ms ║║Executed physical command [Dinner Table #3].setLevel([10]) (8ms)
+257ms ║║Executed [Dinner Table #3].setLevel (8ms)
+265ms ║║Executed physical command [Dinner Table #4].setLevel([10]) (7ms)
+266ms ║║Executed [Dinner Table #4].setLevel (9ms)
+289ms ║║Executed physical command [Dinner Table #1].setLevel([10]) (8ms)
+302ms ║║Executed virtual command [Dinner Table #1].fadeLevel (30ms)
+312ms ║║Executed physical command [Dinner Table #2].setLevel([10]) (8ms)
+318ms ║║Executed virtual command [Dinner Table #2].fadeLevel (15ms)
+328ms ║║Executed physical command [Dinner Table #3].setLevel([10]) (8ms)
+334ms ║║Executed virtual command [Dinner Table #3].fadeLevel (15ms)
+344ms ║║Executed physical command [Dinner Table #4].setLevel([10]) (7ms)
+349ms ║║Executed virtual command [Dinner Table #4].fadeLevel (14ms)
+350ms ║║Requesting a wake up for Fri, Dec 15 2017 @ 10:05:59 AM EST (in 300.1s)
+391ms ║╚Execution stage complete. (252ms)
+404ms ║Setting up scheduled job for Fri, Dec 15 2017 @ 10:01:29 AM EST (in 29.891s), with 46 more jobs pending
+411ms ╚Event processed successfully (411ms)
12/15/2017, 10:00:35 AM +232ms
+1ms ╔Received event [Home].execute = recovery with a delay of 85ms
+129ms ║RunTime Analysis CS > 16ms > PS > 30ms > PE > 83ms > CE
+132ms ║Runtime (41593 bytes) successfully initialized in 30ms (v0.2.100.20171211) (130ms)
+133ms ║╔Execution stage started
+146ms ║║Comparison (enum) off is (string) off = true (1ms)
+148ms ║║Condition #9 evaluated true (9ms)
+149ms ║║Condition group #1 evaluated true (state did not change) (11ms)
+158ms ║║Comparison (enum) off is (string) off = true (2ms)
+159ms ║║Condition #10 evaluated true (7ms)
+160ms ║║Condition group #6 evaluated true (state did not change) (9ms)
+166ms ║╚Execution stage complete. (33ms)
+167ms ║Setting up scheduled job for Fri, Dec 15 2017 @ 10:01:00 AM EST (in 24.601s), with 1 more job pending
+178ms ╚Event processed successfully (177ms)
12/15/2017, 10:00:34 AM +391ms
+1ms ╔Starting piston… (v0.2.100.20171211)
+219ms ║╔Subscribing to devices…
+247ms ║║Subscribing to Kitchen Sink.level…
+263ms ║║Subscribing to Dinner Table #1.level…
+278ms ║║Subscribing to Dinner Table #2.level…
+295ms ║║Subscribing to Dinner Table #3.level…
+311ms ║║Subscribing to Dinner Table #4.level…
+325ms ║║Subscribing to Kitchen Sink.switch…
+339ms ║║Subscribing to Dinner Table #1.switch…
+352ms ║║Subscribing to Dinner Table #2.switch…
+366ms ║║Subscribing to Dinner Table #3.switch…
+379ms ║║Subscribing to Dinner Table #4.switch…
+524ms ║║Subscribing to Party…
+525ms ║╚Finished subscribing (312ms)
+557ms ║Comparison (enum) off is (string) off = true (2ms)
+622ms ║Comparison (enum) off is (string) off = true (1ms)
+648ms ║Setting up scheduled job for Fri, Dec 15 2017 @ 10:01:00 AM EST (in 24.962s), with 1 more job pending
+659ms ╚Piston successfully started (659ms)


#12

That’s interesting - the part of the log you highlighted shows it cancelled tasks and the very next command set the next wake-up time.

Out of curiosity, what happens if you change the active device for Cancel All Pending Tasks to “Location”… where you currently have it as Dimmer 5 and Lights? I wonder if the pending tasks, since it’s a webCoRE timed level change, is associated with Home.[time] and not being cancelled.

Only one more flight and I should be home and able to help better… assuming the 8 hour backwards time change doesn’t make me pass out as soon as I get home, lol.


#13

Whoa, 8 hour time change? That’s a heck of a flight…

So I’ve been toying with this piston and it still doesn’t work. I even tried putting the “cancel all tasks” inside the “every day at…” as shown below… Here’s a pic of the current piston and some more logs.

12/16/2017, 10:27:29 AM +727ms
+1ms ╔Received event [Dinner Table #1].switch = on with a delay of 430ms
+141ms ║RunTime Analysis CS > 16ms > PS > 29ms > PE > 96ms > CE
+144ms ║Runtime (41903 bytes) successfully initialized in 29ms (v0.2.100.20171211) (142ms)
+145ms ║╔Execution stage started
+158ms ║║Comparison (enum) off is (string) off = true (2ms)
+159ms ║║Condition #9 evaluated true (9ms)
+160ms ║║Condition group #1 evaluated true (state did not change) (10ms)
+177ms ║║Comparison (enum) off is (string) off = true (2ms)
+178ms ║║Condition #10 evaluated true (8ms)
+179ms ║║Condition group #6 evaluated true (state did not change) (9ms)
+213ms ║║Condition #18 evaluated false (24ms)
+233ms ║║Comparison (enum) on changes = true (1ms)
+235ms ║║Condition #19 evaluated true (21ms)
+236ms ║║Condition group #15 evaluated true (state did not change) (47ms)
+238ms ║║Cancelling statement #16’s schedules…
+240ms ║║Executed virtual command cancelTasks (0ms)
+278ms ║║Executed physical command [Dinner Table #1].setLevel([11]) (6ms)
+297ms ║║Executed physical command [Dinner Table #2].setLevel([11]) (6ms)
+315ms ║║Executed physical command [Dinner Table #3].setLevel([11]) (6ms)
+332ms ║║Executed physical command [Dinner Table #4].setLevel([11]) (6ms)
+344ms ║╚Execution stage complete. (198ms)
+356ms ║Setting up scheduled job for Sat, Dec 16 2017 @ 10:27:59 AM EST (in 29.411s), with 41 more jobs pending
+365ms ╚Event processed successfully (365ms)
12/16/2017, 10:27:29 AM +295ms
+0ms ╔Received event [Home].time = 1513438049492 with a delay of -198ms
+160ms ║RunTime Analysis CS > 18ms > PS > 43ms > PE > 96ms > CE
+165ms ║Runtime (41902 bytes) successfully initialized in 43ms (v0.2.100.20171211) (164ms)
+169ms ║╔Execution stage started
+194ms ║║Executed physical command [Dinner Table #1].setLevel([11]) (10ms)
+202ms ║║Fast executing schedules, waiting for 15ms to sync up
+236ms ║║Executed physical command [Dinner Table #2].setLevel([11]) (10ms)
+256ms ║║Executed physical command [Dinner Table #3].setLevel([11]) (10ms)
+278ms ║║Executed physical command [Dinner Table #4].setLevel([11]) (12ms)
+291ms ║╚Execution stage complete. (124ms)
+304ms ║Setting up scheduled job for Sat, Dec 16 2017 @ 10:27:59 AM EST (in 29.895s), with 41 more jobs pending
+314ms ╚Event processed successfully (314ms)
12/16/2017, 10:27:22 AM +765ms
+1ms ╔Received event [Dinner Table #1].switch = off with a delay of 451ms
+139ms ║RunTime Analysis CS > 12ms > PS > 34ms > PE > 92ms > CE
+141ms ║Runtime (41907 bytes) successfully initialized in 34ms (v0.2.100.20171211) (139ms)
+142ms ║╔Execution stage started
+155ms ║║Comparison (enum) off is (string) off = true (1ms)
+157ms ║║Condition #9 evaluated true (9ms)
+158ms ║║Condition group #1 evaluated true (state did not change) (10ms)
+176ms ║║Comparison (enum) off is (string) off = true (2ms)
+177ms ║║Condition #10 evaluated true (8ms)
+178ms ║║Condition group #6 evaluated true (state did not change) (10ms)
+214ms ║║Condition #18 evaluated false (25ms)
+233ms ║║Comparison (enum) off changes = true (1ms)
+235ms ║║Cancelling condition #19’s schedules…
+236ms ║║Condition #19 evaluated true (21ms)
+237ms ║║Cancelling condition #15’s schedules…
+238ms ║║Condition group #15 evaluated true (state changed) (48ms)
+240ms ║║Cancelling statement #16’s schedules…
+241ms ║║Executed virtual command cancelTasks (0ms)
+282ms ║╚Execution stage complete. (140ms)
+295ms ║Setting up scheduled job for Sat, Dec 16 2017 @ 10:27:29 AM EST (in 6.432s), with 45 more jobs pending
+309ms ╚Event processed successfully (309ms)
12/16/2017, 10:27:00 AM +976ms
+1ms ╔Received event [Dinner Table #2].level = 10 with a delay of 1018ms
+10049ms ║RunTime Analysis CS > 16ms > PS > 9899ms > PE > 134ms > CE
+10050ms ║Piston waited at a semaphore for 9858ms
+10053ms ║Runtime (41983 bytes) successfully initialized in 9899ms (v0.2.100.20171211) (10050ms)
+10054ms ║╔Execution stage started
+10066ms ║║Comparison (enum) off is (string) off = true (1ms)
+10068ms ║║Condition #9 evaluated true (9ms)
+10069ms ║║Condition group #1 evaluated true (state did not change) (10ms)
+10086ms ║║Comparison (enum) off is (string) off = true (2ms)
+10087ms ║║Condition #10 evaluated true (8ms)
+10088ms ║║Condition group #6 evaluated true (state did not change) (9ms)
+10118ms ║║Comparison (integer) 10 changes = false (0ms)
+10121ms ║║Condition #18 evaluated false (22ms)
+10185ms ║║Condition #19 evaluated false (63ms)
+10186ms ║║Condition group #15 evaluated false (state did not change) (87ms)
+10193ms ║╚Execution stage complete. (139ms)
+10207ms ║Setting up scheduled job for Sat, Dec 16 2017 @ 10:27:29 AM EST (in 18.31s), with 45 more jobs pending
+10220ms ╚Event processed successfully (10220ms)
12/16/2017, 10:27:00 AM +509ms
+1ms ╔Received event [Dinner Table #3].level = 10 with a delay of 459ms
+10080ms ║RunTime Analysis CS > 72ms > PS > 9886ms > PE > 123ms > CE
+10081ms ║Piston waited at a semaphore for 9848ms
+10083ms ║Runtime (41979 bytes) successfully initialized in 9886ms (v0.2.100.20171211) (10081ms)
+10084ms ║╔Execution stage started
+10099ms ║║Comparison (enum) off is (string) off = true (1ms)
+10100ms ║║Condition #9 evaluated true (10ms)
+10101ms ║║Condition group #1 evaluated true (state did not change) (12ms)
+10119ms ║║Comparison (enum) off is (string) off = true (1ms)
+10121ms ║║Condition #10 evaluated true (8ms)
+10121ms ║║Condition group #6 evaluated true (state did not change) (9ms)
+10161ms ║║Comparison (integer) 10 changes = false (1ms)
+10163ms ║║Condition #18 evaluated false (31ms)
+10186ms ║║Condition #19 evaluated false (22ms)
+10187ms ║║Condition group #15 evaluated false (state did not change) (55ms)
+10194ms ║╚Execution stage complete. (110ms)
+10207ms ║Setting up scheduled job for Sat, Dec 16 2017 @ 10:27:29 AM EST (in 18.777s), with 45 more jobs pending
+10279ms ╚Event processed successfully (10280ms)
12/16/2017, 10:27:00 AM +602ms
+1ms ╔Received event [Dinner Table #4].level = 10 with a delay of 446ms
+9964ms ║RunTime Analysis CS > 16ms > PS > 9815ms > PE > 134ms > CE
+9965ms ║Piston waited at a semaphore for 9776ms
+9968ms ║Runtime (41977 bytes) successfully initialized in 9815ms (v0.2.100.20171211) (9965ms)
+9969ms ║╔Execution stage started
+9983ms ║║Comparison (enum) off is (string) off = true (2ms)
+9985ms ║║Condition #9 evaluated true (10ms)
+9986ms ║║Condition group #1 evaluated true (state did not change) (12ms)
+10005ms ║║Comparison (enum) off is (string) off = true (1ms)
+10006ms ║║Condition #10 evaluated true (9ms)
+10007ms ║║Condition group #6 evaluated true (state did not change) (11ms)
+10045ms ║║Comparison (integer) 10 changes = false (0ms)
+10047ms ║║Condition #18 evaluated false (27ms)
+10072ms ║║Condition #19 evaluated false (25ms)
+10073ms ║║Condition group #15 evaluated false (state did not change) (54ms)
+10079ms ║╚Execution stage complete. (111ms)
+10092ms ║Setting up scheduled job for Sat, Dec 16 2017 @ 10:27:29 AM EST (in 18.799s), with 45 more jobs pending
+10104ms ╚Event processed successfully (10104ms)
12/16/2017, 10:26:59 AM +530ms
+1ms ╔Received event [Dinner Table #1].switch = on with a delay of 427ms
+9936ms ║RunTime Analysis CS > 22ms > PS > 9803ms > PE > 112ms > CE
+9937ms ║Piston waited at a semaphore for 9761ms
+9940ms ║Runtime (41975 bytes) successfully initialized in 9803ms (v0.2.100.20171211) (9937ms)
+9941ms ║╔Execution stage started
+9955ms ║║Comparison (enum) off is (string) off = true (2ms)
+9956ms ║║Condition #9 evaluated true (10ms)
+9957ms ║║Condition group #1 evaluated true (state did not change) (11ms)
+9975ms ║║Comparison (enum) off is (string) off = true (1ms)
+9976ms ║║Condition #10 evaluated true (8ms)
+9977ms ║║Condition group #6 evaluated true (state did not change) (9ms)
+10017ms ║║Cancelling condition #18’s schedules…
+10018ms ║║Condition #18 evaluated false (30ms)
+10038ms ║║Comparison (enum) on changes = false (1ms)
+10041ms ║║Cancelling condition #19’s schedules…
+10042ms ║║Condition #19 evaluated false (22ms)
+10043ms ║║Cancelling condition #15’s schedules…
+10044ms ║║Condition group #15 evaluated false (state changed) (55ms)
+10062ms ║╚Execution stage complete. (122ms)
+10076ms ║Setting up scheduled job for Sat, Dec 16 2017 @ 10:27:29 AM EST (in 19.887s), with 45 more jobs pending
+10089ms ╚Event processed successfully (10089ms)
12/16/2017, 10:27:00 AM +798ms
+1ms ╔Received event [Dinner Table #2].level = 10 with a delay of 471ms
+148ms ║RunTime Analysis CS > 22ms > PS > 39ms > PE > 87ms > CE
+151ms ║Runtime (41900 bytes) successfully initialized in 39ms (v0.2.100.20171211) (149ms)
+152ms ║╔Execution stage started
+167ms ║║Comparison (enum) off is (string) off = true (2ms)
+169ms ║║Condition #9 evaluated true (9ms)
+170ms ║║Condition group #1 evaluated true (state did not change) (11ms)
+190ms ║║Comparison (enum) off is (string) off = true (2ms)
+191ms ║║Condition #10 evaluated true (9ms)
+192ms ║║Condition group #6 evaluated true (state did not change) (10ms)
+230ms ║║Comparison (integer) 10 changes = true (1ms)
+232ms ║║Cancelling condition #18’s schedules…
+233ms ║║Condition #18 evaluated true (27ms)
+235ms ║║Condition group #15 evaluated true (state did not change) (29ms)
+238ms ║║Cancelling statement #16’s schedules…
+240ms ║║Executed virtual command cancelTasks (0ms)
+277ms ║╚Execution stage complete. (125ms)
+290ms ║Setting up scheduled job for Sat, Dec 16 2017 @ 10:27:29 AM EST (in 28.404s), with 45 more jobs pending
+303ms ╚Event processed successfully (302ms)
12/16/2017, 10:27:00 AM +319ms
+1ms ╔Received event [Dinner Table #4].switch = on with a delay of 482ms
+128ms ║RunTime Analysis CS > 17ms > PS > 27ms > PE > 84ms > CE
+131ms ║Runtime (41901 bytes) successfully initialized in 27ms (v0.2.100.20171211) (128ms)
+132ms ║╔Execution stage started
+146ms ║║Comparison (enum) off is (string) off = true (1ms)
+147ms ║║Condition #9 evaluated true (10ms)
+148ms ║║Condition group #1 evaluated true (state did not change) (11ms)
+166ms ║║Comparison (enum) off is (string) off = true (1ms)
+168ms ║║Condition #10 evaluated true (8ms)
+168ms ║║Condition group #6 evaluated true (state did not change) (9ms)
+203ms ║║Condition #18 evaluated false (24ms)
+221ms ║║Comparison (enum) on changes = true (1ms)
+223ms ║║Condition #19 evaluated true (19ms)
+224ms ║║Condition group #15 evaluated true (state did not change) (45ms)
+227ms ║║Cancelling statement #16’s schedules…
+228ms ║║Executed virtual command cancelTasks (0ms)
+262ms ║╚Execution stage complete. (131ms)
+276ms ║Setting up scheduled job for Sat, Dec 16 2017 @ 10:27:29 AM EST (in 28.898s), with 45 more jobs pending
+288ms ╚Event processed successfully (288ms)
12/16/2017, 10:26:59 AM +738ms
+1ms ╔Received event [Dinner Table #3].switch = on with a delay of 463ms
+173ms ║RunTime Analysis CS > 18ms > PS > 29ms > PE > 127ms > CE
+176ms ║Runtime (41909 bytes) successfully initialized in 29ms (v0.2.100.20171211) (174ms)
+177ms ║╔Execution stage started
+191ms ║║Comparison (enum) off is (string) off = true (1ms)
+192ms ║║Condition #9 evaluated true (9ms)
+193ms ║║Condition group #1 evaluated true (state did not change) (11ms)
+211ms ║║Comparison (enum) off is (string) off = true (2ms)
+212ms ║║Condition #10 evaluated true (8ms)
+213ms ║║Condition group #6 evaluated true (state did not change) (9ms)
+249ms ║║Condition #18 evaluated false (25ms)
+268ms ║║Comparison (enum) on changes = true (0ms)
+270ms ║║Cancelling condition #19’s schedules…
+271ms ║║Condition #19 evaluated true (21ms)
+272ms ║║Cancelling condition #15’s schedules…
+273ms ║║Condition group #15 evaluated true (state changed) (49ms)
+275ms ║║Cancelling statement #16’s schedules…
+277ms ║║Executed virtual command cancelTasks (0ms)
+315ms ║╚Execution stage complete. (138ms)
+329ms ║Setting up scheduled job for Sat, Dec 16 2017 @ 10:27:29 AM EST (in 29.426s), with 45 more jobs pending
+342ms ╚Event processed successfully (342ms)
12/16/2017, 10:26:59 AM +112ms
+1ms ╔Received event [Home].time = 1513438020000 with a delay of -888ms
+163ms ║RunTime Analysis CS > 17ms > PS > 45ms > PE > 101ms > CE
+166ms ║Runtime (41908 bytes) successfully initialized in 45ms (v0.2.100.20171211) (164ms)
+167ms ║╔Execution stage started
+187ms ║║Cancelling statement #2’s schedules…
+205ms ║║Executed physical command [Dinner Table #1].on() (10ms)
+206ms ║║Executed [Dinner Table #1].on (11ms)
+217ms ║║Executed physical command [Dinner Table #2].on() (9ms)
+218ms ║║Executed [Dinner Table #2].on (11ms)
+288ms ║║Executed physical command [Dinner Table #3].on() (68ms)
+289ms ║║Executed [Dinner Table #3].on (69ms)
+302ms ║║Executed physical command [Dinner Table #4].on() (10ms)
+303ms ║║Executed [Dinner Table #4].on (12ms)
+315ms ║║Executed physical command [Dinner Table #1].setLevel([10]) (7ms)
+316ms ║║Executed [Dinner Table #1].setLevel (9ms)
+327ms ║║Executed physical command [Dinner Table #2].setLevel([10]) (8ms)
+327ms ║║Executed [Dinner Table #2].setLevel (11ms)
+338ms ║║Executed physical command [Dinner Table #3].setLevel([10]) (8ms)
+339ms ║║Executed [Dinner Table #3].setLevel (11ms)
+348ms ║║Executed physical command [Dinner Table #4].setLevel([10]) (7ms)
+349ms ║║Executed [Dinner Table #4].setLevel (8ms)
+374ms ║║Executed physical command [Dinner Table #1].setLevel([10]) (8ms)
+388ms ║║Executed virtual command [Dinner Table #1].fadeLevel (32ms)
+399ms ║║Executed physical command [Dinner Table #2].setLevel([10]) (7ms)
+408ms ║║Executed virtual command [Dinner Table #2].fadeLevel (17ms)
+418ms ║║Executed physical command [Dinner Table #3].setLevel([10]) (7ms)
+425ms ║║Executed virtual command [Dinner Table #3].fadeLevel (15ms)
+436ms ║║Executed physical command [Dinner Table #4].setLevel([10]) (9ms)
+442ms ║║Executed virtual command [Dinner Table #4].fadeLevel (17ms)
+444ms ║║Requesting a wake up for Sat, Dec 16 2017 @ 10:31:59 AM EST (in 300.1s)
+508ms ║╚Execution stage complete. (341ms)
+523ms ║Setting up scheduled job for Sat, Dec 16 2017 @ 10:27:29 AM EST (in 29.858s), with 46 more jobs pending
+532ms ╚Event processed successfully (532ms)
12/16/2017, 10:26:32 AM +998ms
+0ms ╔Starting piston… (v0.2.100.20171211)
+301ms ║╔Subscribing to devices…
+360ms ║║Subscribing to Kitchen Sink.level…
+378ms ║║Subscribing to Dinner Table #1.level…
+396ms ║║Subscribing to Dinner Table #2.level…
+414ms ║║Subscribing to Dinner Table #3.level…
+432ms ║║Subscribing to Dinner Table #4.level…
+450ms ║║Subscribing to Kitchen Sink.switch…
+465ms ║║Subscribing to Dinner Table #1.switch…
+480ms ║║Subscribing to Dinner Table #2.switch…
+496ms ║║Subscribing to Dinner Table #3.switch…
+512ms ║║Subscribing to Dinner Table #4.switch…
+667ms ║║Subscribing to Party…
+668ms ║╚Finished subscribing (374ms)
+709ms ║Comparison (enum) off is (string) off = true (1ms)
+748ms ║Comparison (enum) off is (string) off = true (1ms)
+975ms ║Setting up scheduled job for Sat, Dec 16 2017 @ 10:27:00 AM EST (in 26.028s), with 1 more job pending
+1015ms ╚Piston successfully started (1015ms)


#14

Yeah, I flew from Jeddah, Saudi Arabia to Frankfurt to Chicago and then home to NC. I was only there for a few days for a conference… just long enough to completely hose my body clock!

I notice in your logs something is taking 10 seconds to execute, too. That shouldn’t happen - is this piston colliding with another piston that is controlling these lights?

Either way, it’s really puzzling the piston is setting a wake-up time immediately after cancelling all tasks. Just for grins, what happens if you create a new piston that does something like this:

Fade lights X and Y from 0 to 100% over 10 minutes.
If switch X level changes, cancel all pending tasks.

If you run that and alter switch X’s level after 5 minutes, what happens and what shows up in the log? I’m almost wondering if the 10 second execution and 45 pending jobs for the piston we’re messing around with are causing odd behavior and have us chasing our tails.


#15

okay, brand new piston, using only 1 light… should be super-simple, right? Still doesn’t work for some reason.

Note the above piston, I did change the AND to an OR re: cancel all pending tasks (just didn’t upload a fresh pic)

12/16/2017, 3:39:32 PM +842ms
+1ms ╔Received event [Dinner Table #1].level = 11 with a delay of 1230ms
+90ms ║RunTime Analysis CS > 18ms > PS > 32ms > PE > 39ms > CE
+92ms ║Runtime (36909 bytes) successfully initialized in 32ms (v0.2.100.20171211) (90ms)
+93ms ║╔Execution stage started
+99ms ║║Cancelling statement #1’s schedules…
+116ms ║║Executed physical command [Dinner Table #1].setLevel([10]) (8ms)
+163ms ║║Executed virtual command [Dinner Table #1].fadeLevel (55ms)
+164ms ║║Requesting a wake up for Sat, Dec 16 2017 @ 3:59:33 PM EST (in 1200.1s)
+211ms ║╚Execution stage complete. (118ms)
+238ms ║Setting up scheduled job for Sat, Dec 16 2017 @ 3:39:46 PM EST (in 13.217s), with 91 more jobs pending
+248ms ╚Event processed successfully (248ms)
12/16/2017, 3:39:32 PM +278ms
+1ms ╔Received event [Home].time = 1513456772945 with a delay of -667ms
+92ms ║RunTime Analysis CS > 14ms > PS > 33ms > PE > 44ms > CE
+94ms ║Runtime (36908 bytes) successfully initialized in 33ms (v0.2.100.20171211) (92ms)
+96ms ║╔Execution stage started
+125ms ║║Executed physical command [Dinner Table #1].setLevel([11]) (7ms)
+152ms ║╚Execution stage complete. (56ms)
+179ms ║Setting up scheduled job for Sat, Dec 16 2017 @ 3:39:46 PM EST (in 13.823s), with 90 more jobs pending
+188ms ╚Event processed successfully (188ms)
12/16/2017, 3:39:19 PM +502ms
+1ms ╔Received event [Dinner Table #1].switch = on with a delay of 980ms
+88ms ║RunTime Analysis CS > 18ms > PS > 33ms > PE > 37ms > CE
+90ms ║Runtime (36909 bytes) successfully initialized in 33ms (v0.2.100.20171211) (89ms)
+91ms ║╔Execution stage started
+97ms ║║Cancelling statement #1’s schedules…
+110ms ║║Skipped execution of physical command [Dinner Table #1].setLevel([10]) because it would make no change to the device. (2ms)
+149ms ║║Executed virtual command [Dinner Table #1].fadeLevel (44ms)
+150ms ║║Requesting a wake up for Sat, Dec 16 2017 @ 3:59:19 PM EST (in 1200.1s)
+196ms ║╚Execution stage complete. (105ms)
+222ms ║Setting up scheduled job for Sat, Dec 16 2017 @ 3:39:32 PM EST (in 13.222s), with 91 more jobs pending
+234ms ╚Event processed successfully (235ms)
12/16/2017, 3:39:18 PM +918ms
+1ms ╔Received event [Dinner Table #1].switch = off with a delay of 1008ms
+100ms ║RunTime Analysis CS > 12ms > PS > 52ms > PE > 35ms > CE
+102ms ║Runtime (36912 bytes) successfully initialized in 52ms (v0.2.100.20171211) (100ms)
+103ms ║╔Execution stage started
+108ms ║║Cancelling statement #1’s schedules…
+127ms ║║Executed physical command [Dinner Table #1].setLevel([10]) (9ms)
+357ms ║║Executed virtual command [Dinner Table #1].fadeLevel (241ms)
+359ms ║║Requesting a wake up for Sat, Dec 16 2017 @ 3:59:19 PM EST (in 1200.1s)
+405ms ║╚Execution stage complete. (303ms)
+430ms ║Setting up scheduled job for Sat, Dec 16 2017 @ 3:39:32 PM EST (in 13.032s), with 91 more jobs pending
+443ms ╚Event processed successfully (443ms)
12/16/2017, 3:39:12 PM +392ms
+2ms ╔Received event [Dinner Table #1].level = 10 with a delay of 1084ms
+103ms ║RunTime Analysis CS > 23ms > PS > 44ms > PE > 35ms > CE
+105ms ║Runtime (36910 bytes) successfully initialized in 44ms (v0.2.100.20171211) (102ms)
+106ms ║╔Execution stage started
+112ms ║║Cancelling statement #1’s schedules…
+131ms ║║Executed physical command [Dinner Table #1].setLevel([10]) (9ms)
+171ms ║║Executed virtual command [Dinner Table #1].fadeLevel (50ms)
+172ms ║║Requesting a wake up for Sat, Dec 16 2017 @ 3:59:12 PM EST (in 1200.1s)
+217ms ║╚Execution stage complete. (111ms)
+242ms ║Setting up scheduled job for Sat, Dec 16 2017 @ 3:39:25 PM EST (in 13.224s), with 91 more jobs pending
+254ms ╚Event processed successfully (253ms)


#16

I also tried using a different light (and different brand [sengled vs. hue]), which I know has nothing else controlling it, same result. It actually even got stranger, I kept seeing the logs adjust it to 10, then adjust it to 12, then adjust it back to 10, back to 12, etc…


#17

Usually my litmus test is going to basics to prove functionality, then rebuilding the complexities around it. I can’t understand why what you wrote there didn’t work… :white_flag:

paging @webCoRE_Minions to see if they can help!


#18

I swear it seems the cancel pending events stanza is subscribing to the events occurring in the fade to level stanza.


#19

New to this thread so I apologise if I’ve missed something but what is the trigger for the piston in post 15.


#20

The trigger appears to be a level change, and the action is a level change, so you’ve created an endless loop which will keep reverting to 10%


#21

Ugh, it’s always the simple things.

For some reason though, in my piston it worked the way I tried to for @allrak. I had 3 dimmer switches increasing to 100% over 5 minutes, and I set a “if level or switch of any of those 3 change, then cancel all pending tasks” command. It worked… changes from the piston didn’t trigger the cancellation, but physical changes did. Is it a difference in DTH?

What is another simple way to help OP cancel a fade initiated by a piston?


#22

Cancelling fades is tricky and highly unreliable due to, I think, ST latency… or it might be a WC bug???


#23

okay, I think I’ll just give up and skip the fade in…

Thanks!
-jeff


#24

I too am looking for a solution if you’ve come up with something. I have my wife’s bedside light turn on and fade up from 2% to 75% over 20 minutes, wait for 15 then set the level back to 5%. If she shuts the light off the piston will turn it back on at the next increase in percentage. I’ve tried basically everything I can think of. If I pause the piston it seems to work. However then I’ll have to go in and check the piston every day and turn it back on. Will the piston pick up where it left off once reactivated? That seems like a total pain, I suppose I could also write another piston to check the status of this one and reactivate it if it has been paused.


#25

This is how I’ve set up my fade. When the condition of the IF statement goes FALSE the statement stops running. I can then turn off the light without worrying about it coming back on. Currently the statement goes false after a period of time or if I manually turn off the virtual switch that triggers everything. It’s a two step approach so I can’t just turn the light off with a single click (I’m using this as an “alarm clock”). There might be better methods but it works for my needs. Hope it helps.


#26

If I might ask, @simplygenius, when you refer to “the condition of the if statement” going false, which if statement within your code might you be referring to there?


#27

If the first one checking for the MBL1-Sunrise goes FALSE, the fade is cancelled due the the “Task cancellation policy” of the IF statement (click the Gear symbol when in the IF setup).