Simple timer expires, turn switch off

dotJson · 2022-08-30 18:19:00 UTC

1) Give a description of the problem
Bathroom has 2 switches: light and fan. They could be turned on at different times so each has its own timer. Both are the same duration. Piston has 2 while loops, both wait 2 mins (testing timer), but when second event triggers, the first scheduled task executes and the second restarts the 2 minutes

2) What is the expected behaviour?
Both timers expire and execute without restarting

3) What is happening/not happening?
The second trigger sets a scheduled event but restarts timer instead of firing

4) Post a Green Snapshot of the piston

5) Attach logs after turning logging level to Full
8/30/2022, 11:17:20 AM +525ms
+3ms ╔Received event [Pool Bath Fan].switch = off with a delay of 45ms, canQueue: true, calledMyself: false
+11ms ║RunTime initialize > 11 LockT > 0ms > r9T > 1ms > pistonT > 0ms (first state access 10 4 7)
+13ms ║Runtime (5986 bytes) initialized in 1ms (v0.3.114.20220822_HE)
+15ms ║╔Execution stage started
+18ms ║║Comparison (enum) off is (string) on = false (1ms)
+20ms ║║Condition #2 evaluated false (3ms)
+22ms ║║Canceling condition #1’s schedules…3 (st:4)
+23ms ║║Condition group #1 evaluated false (condition changed) (6ms)
+26ms ║║Comparison (enum) off is (string) on = false (0ms)
+27ms ║║Condition #7 evaluated false (3ms)
+27ms ║║Condition group #6 evaluated false (condition did not change) (4ms)
+31ms ║╚Execution stage complete. (17ms)
+42ms ╚Event processed successfully (39ms)
8/30/2022, 11:17:20 AM +39ms
+3ms ╔Received event [Cobalt].time = 1661883439997 with a delay of 42ms, canQueue: true, calledMyself: false
+11ms ║RunTime initialize > 11 LockT > 0ms > r9T > 1ms > pistonT > 0ms (first state access 10 4 7)
+13ms ║Runtime (5983 bytes) initialized in 1ms (v0.3.114.20220822_HE)
+19ms ║╔Execution stage started
+36ms ║║Executed physical command [Pool Bath Fan].off() (11ms)
+36ms ║║Executed [Pool Bath Fan].off (12ms)
+40ms ║║Comparison (enum) on is (string) on = true (1ms)
+41ms ║║Condition #2 evaluated true (4ms)
+42ms ║║Condition group #1 evaluated true (condition did not change) (5ms)
+48ms ║║Executed virtual command [Pool Bath Fan].wait (0ms)
+50ms ║║Requesting wake up at Tue, Aug 30 2022 @ 11:19:20 AM MST (in 119999ms) for 3 (st:4)
+55ms ║╚Execution stage complete. (35ms)
+76ms ║Setting up scheduled job for Tue, Aug 30 2022 @ 11:19:20 AM MST (in 120021ms)
+78ms ╚Event processed successfully (75ms)
8/30/2022, 11:17:19 AM +560ms
+4ms ╔Received event [Cobalt].time = 1661883439518 with a delay of 42ms, canQueue: true, calledMyself: false
+12ms ║RunTime initialize > 12 LockT > 1ms > r9T > 2ms > pistonT > 1ms (first state access 9 5 7)
+14ms ║Runtime (5975 bytes) initialized in 2ms (v0.3.114.20220822_HE)
+20ms ║╔Execution stage started
+27ms ║║Skipped execution of physical command [Pool Bath Light].off([]) because it would make no change to the device. (1ms)
+28ms ║║Executed [Pool Bath Light].off (1ms)
+31ms ║║Comparison (enum) off is (string) on = false (0ms)
+32ms ║║Condition #7 evaluated false (3ms)
+34ms ║║Condition group #6 evaluated false (condition changed) (6ms)
+39ms ║╚Execution stage complete. (19ms)
+61ms ║Setting up scheduled job for Tue, Aug 30 2022 @ 11:17:19 AM MST (in 426ms)
+63ms ╚Event processed successfully (59ms)
8/30/2022, 11:15:19 AM +971ms
+3ms ╔Received event [Pool Bath Light].switch = off with a delay of 47ms, canQueue: true, calledMyself: false
+11ms ║RunTime initialize > 10 LockT > 0ms > r9T > 1ms > pistonT > 0ms (first state access 9 3 7)
+13ms ║Runtime (5972 bytes) initialized in 1ms (v0.3.114.20220822_HE)
+14ms ║╔Execution stage started
+19ms ║║Comparison (enum) on is (string) on = true (1ms)
+20ms ║║Condition #2 evaluated true (3ms)
+20ms ║║Condition group #1 evaluated true (condition did not change) (4ms)
+23ms ║║Canceling statement #3’s schedules…3 (st:4)
+26ms ║║Executed virtual command [Pool Bath Fan].wait (0ms)
+28ms ║║Requesting wake up at Tue, Aug 30 2022 @ 11:17:19 AM MST (in 119999ms) for 3 (st:4)
+44ms ║╚Execution stage complete. (30ms)
+69ms ║Setting up scheduled job for Tue, Aug 30 2022 @ 11:17:19 AM MST (in 119530ms),with 1 more job pending
+70ms ╚Event processed successfully (68ms)
8/30/2022, 11:15:19 AM +469ms
+5ms ╔Received event [Cobalt].time = 1661883319427 with a delay of 42ms, canQueue: true, calledMyself: false
+12ms ║RunTime initialize > 12 LockT > 0ms > r9T > 1ms > pistonT > 0ms (first state access 11 5 7)
+14ms ║Runtime (5967 bytes) initialized in 1ms (v0.3.114.20220822_HE)
+21ms ║╔Execution stage started
+38ms ║║Executed physical command [Pool Bath Light].off() (11ms)
+39ms ║║Executed [Pool Bath Light].off (12ms)
+42ms ║║Comparison (enum) on is (string) on = true (1ms)
+43ms ║║Condition #7 evaluated true (3ms)
+44ms ║║Condition group #6 evaluated true (condition did not change) (4ms)
+48ms ║║Executed virtual command [Pool Bath Light].wait (0ms)
+50ms ║║Requesting wake up at Tue, Aug 30 2022 @ 11:17:19 AM MST (in 119999ms) for 8 (st:9)
+56ms ║╚Execution stage complete. (35ms)
+82ms ║Setting up scheduled job for Tue, Aug 30 2022 @ 11:15:36 AM MST (in 17412ms),with 1 more job pending
+84ms ╚Event processed successfully (79ms)
8/30/2022, 11:13:36 AM +883ms
+3ms ╔Received event [Pool Bath Fan].switch = on with a delay of 49ms, canQueue: true, calledMyself: false
+10ms ║RunTime initialize > 9 LockT > 1ms > r9T > 1ms > pistonT > 0ms (first state access 7 4 5)
+12ms ║Runtime (5952 bytes) initialized in 1ms (v0.3.114.20220822_HE)
+13ms ║╔Execution stage started
+17ms ║║Comparison (enum) on is (string) on = true (1ms)
+20ms ║║Condition #2 evaluated true (4ms)
+21ms ║║Condition group #1 evaluated true (condition changed) (6ms)
+26ms ║║Executed virtual command [Pool Bath Fan].wait (0ms)
+28ms ║║Requesting wake up at Tue, Aug 30 2022 @ 11:15:36 AM MST (in 119999ms) for 3 (st:4)
+44ms ║╚Execution stage complete. (31ms)
+68ms ║Setting up scheduled job for Tue, Aug 30 2022 @ 11:15:19 AM MST (in 102528ms),with 1 more job pending
+70ms ╚Event processed successfully (67ms)
8/30/2022, 11:13:19 AM +369ms
+3ms ╔Received event [Pool Bath Light].switch = on with a delay of 60ms, canQueue: true, calledMyself: false
+31ms ║RunTime initialize > 30 LockT > 0ms > r9T > 23ms > pistonT > 22ms (first state access 7 3 27)
+33ms ║Runtime (6007 bytes) initialized in 23ms (v0.3.114.20220822_HE)
+35ms ║╔Execution stage started
+43ms ║║Comparison (enum) off is (string) on = false (1ms)
+44ms ║║Condition #2 evaluated false (6ms)
+45ms ║║Condition group #1 evaluated false (condition did not change) (8ms)
+48ms ║║Comparison (enum) on is (string) on = true (0ms)
+51ms ║║Condition #7 evaluated true (4ms)
+52ms ║║Condition group #6 evaluated true (condition changed) (6ms)
+58ms ║║Executed virtual command [Pool Bath Light].wait (1ms)
+60ms ║║Requesting wake up at Tue, Aug 30 2022 @ 11:15:19 AM MST (in 119999ms) for 8 (st:9)
+68ms ║╚Execution stage complete. (35ms)
+94ms ║Setting up scheduled job for Tue, Aug 30 2022 @ 11:15:19 AM MST (in 120014ms)
+95ms ╚Event processed successfully (93ms)
8/30/2022, 11:13:06 AM +841ms
+163ms ╔Subscribing to devices…
+198ms ║Device missing from piston. Loading all from parent (31ms)
+206ms ║subscriptions: no triggers, promoting conditions
+207ms ║Subscribing to Pool Bath Fan.switch…
+327ms ║subscriptions: no triggers, promoting conditions
+328ms ║Subscribing to Pool Bath Light.switch…
+422ms ╚Finished subscribing (415ms)
+435ms ║Comparison (enum) off is (string) on = false (0ms)
+440ms ║Comparison (enum) off is (string) on = false (1ms)
+455ms ╔Starting piston… (v0.3.114.20220822_HE)
+456ms ╚Piston started (450ms)

Clear

Full

eibyer · 2022-08-30 20:29:43 UTC

Any particular reason you don’t want to separate the switches into its own piston?

dotJson · 2022-08-30 20:34:01 UTC

Not really. I’m moving from WC on ST where I had a gazillion pistons, was taking this opportunity to “clean things up”.
Is it not possible to have multiple, unique timers in one piston? If I could do this, I’d have like 35 less rules for such a simple thing. So it’s housekeeping, no other reason.

eibyer · 2022-08-30 20:45:23 UTC

I’m sure someone creative can make it work but most of the time simple makes it easier to troubleshoot.

If you ever used the HE native Rule Machine, the first thing you’ll get as far as advice is “rules are free”.

dotJson · 2022-08-30 20:51:28 UTC

Ahhh yes, the HE mantra… rules are free. I interpret that to mean, yeah we know RM is sad, but it’s supported. Thanks anyway

eibyer · 2022-08-30 20:57:24 UTC

Anyways, what I’d try to do in your sample piston above is to set the Task Cancelation Policy on both Withs to Never Cancel. It will let the timer run through even when the Switch turns off.

dotJson · 2022-08-30 21:11:41 UTC

Yep, I used the combo of TCP and TSP. I’m not sure if the TSP was needed to allow multiple schedules, but as the final wait timers are long enough to need a schedule, I set it. Thanks

orangebucket · 2022-08-31 19:11:12 UTC

A couple of thoughts.

Why while loops? They don’t loop.
What about if SwitchN switch stays on for two minutes for the conditions, instead of the wait? That way they won’t interfere with each other.

dotJson · 2022-08-31 23:45:36 UTC

I did work around this already, but do you think the while loops are really a problem? I did it this way because it made sense to me that the timer could extinguish if somebody manually turned the switch off early. So the while fails, thus no further action.

orangebucket · 2022-09-01 21:03:48 UTC

it wasn’t that the while loops are a problem, simply that they don’t do anything an if wouldn’t do just as well.

The reason I suggested different code is I couldn’t see how the original code worked, regardless of TCP or TSP. It looks to me that if you turn the light on when the fan is already on the first condition is true so the fan has to be turned off before the second block is reached.