Piston fires even when restriction should prevent it

kshoemaker · 2024-05-27 15:05:47 UTC

1) Give a description of the problem
Piston is restricted to night mode but still executes after mode has changed to day.

2) What is the expected behaviour?
This piston should not fire if location mode is day.
See night mode restriction restriction on lines 25 & 26.
Logic beginning on line 68 executes even after mode has changed to day.

3) What is happening/not happening?
Location mode changes from night to day but the piston fires anyway.

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

5) Attach logs after turning logging level to Full
These aren’t the full logs but you can see the key events gerenated by the 2 pistons
app:946 2024-05-26 06:34:41.976 AM info ║ Bedroom Sensor triggered OFF
app:1486 2024-05-26 06:25:42.012 AM info ║ Mode became Day from Night
app:946 2024-05-26 06:25:41.591 AM info ║ Bedroom Sensor triggered DAY mode 🟡
app:946 2024-05-25 06:01:41.949 AM info ║ Great Room Sensor triggered OFF
app:1486 2024-05-25 05:52:41.954 AM info ║ Mode became Day from Night
app:946 2024-05-25 05:52:41.645 AM info ║ Great Room Sensor triggered DAY mode 🟡

E_Sch · 2024-05-27 19:03:13 UTC

Will need logs that show the executions…

Pantheon · 2024-05-27 19:44:28 UTC

Yep, what he said. And a trace might help as well.

kshoemaker · 2024-05-27 21:46:52 UTC

Ok, I’ll turn up the logging. Hopefully it happens again within a few days because it is not very consistent.

kshoemaker · 2024-05-30 10:52:21 UTC

I got the bad behavior this morning. It seems like it fired more than once so some of the logs aged out before I copied them. Here are the webCoRE logs:
5/30/2024, 5:42:18 AM +292ms
+3ms ╔Received event [Great Room Sensor].motion = inactive with a delay of 27ms, canQueue: true, calledMyself: false
+19ms ║Runtime (15539 bytes) initialized 13 LockT > 0ms > r9T > 2ms > pistonT > 0ms (first state access 7 m:4 4 9) (v0.3.114.20240115_HE)
+21ms ║╔Execution stage started
+27ms ║║Comparison (enum) :32e164a2e42f34f83c6d5126248c9a8d: is (string) :db51cd17b1529242205547665623a183: = false (1ms)
+28ms ║║Condition #1 evaluated false (4ms)
+29ms ║║Piston execution aborted due to restrictions in effect; updating piston states
+37ms ║║Comparison changes_to = false (event device/attr eXcluded)
+38ms ║║Comparison changes_to = false (event device/attr eXcluded)
+39ms ║║Comparison (enum) inactive changes_to (string) active = false (0ms)
+48ms ║║Comparison changes_to = false (event device/attr eXcluded)
+48ms ║║Comparison changes_to = false (event device/attr eXcluded)
+49ms ║║Comparison changes_to = false (event device/attr eXcluded)
+50ms ║║Comparison changes_to = false (event device/attr eXcluded)
+69ms ║║Comparison (time) 20538000 is_between (time) 19800000 … (time) 23100000 = true (7ms)
+70ms ║║Time restriction check passed
+78ms ║║Comparison (enum) off is (string) off = true (1ms)
+89ms ║║Comparison (enum) closed stays (string) closed = true (1ms)
+91ms ║║Comparison (enum) closed stays (string) closed = true (1ms)
+92ms ║║Comparison (enum) closed stays (string) closed = true (1ms)
+129ms ║║Found matching value, duration 414042ms for is < 240000ms threshold = false
+129ms ║║Comparison (enum) inactive was (string) inactive = false (33ms)
+134ms ║║Comparison (enum) inactive stays (string) inactive = true (1ms)
+160ms ║║Comparison (enum) closed did_not_change = true (20ms)
+167ms ║╚Execution stage complete. (146ms)
+171ms ╚Event processed successfully (169ms)
5/30/2024, 5:42:04 AM +903ms
+5ms ╔Received event [Shoe’s].time = 1717065724875 with a delay of 28ms, canQueue: true, calledMyself: false
+21ms ║Runtime (15656 bytes) initialized 16 LockT > 1ms > r9T > 2ms > pistonT > 1ms (first state access 7 m:6 7 9) (v0.3.114.20240115_HE)
+28ms ║╔Execution stage started
+38ms ║║Condition #23 evaluated true (0ms)
+62ms ║║Comparison (enum) closed did_not_change = true (20ms)
+63ms ║║Condition #24 evaluated true (25ms)
+64ms ║║Condition group #22 evaluated true (condition did not change) (27ms)
+66ms ║║Condition group #18 evaluated true (condition did not change) (29ms)
+70ms ║║Command optimization: Skipped execution of device command [Cabinet Lights].off() because it would make no change to the device. (1ms)
+73ms ║║Command optimization: Skipped execution of device command [Fireplace Lights].off() because it would make no change to the device. (1ms)
+81ms ║║Calculating (string)Thu 5/30 5:42:04 + (string) - >> (string)Thu 5/30 5:42:04 -
+83ms ║║Calculating (string)Thu 5/30 5:42:04 - + (string)Bedroom Sensor >> (string)Thu 5/30 5:42:04 - Bedroom Sensor
+84ms ║║Calculating (string)Thu 5/30 5:42:04 - Bedroom Sensor + (string) triggered OFF >> (string)Thu 5/30 5:42:04 - Bedroom Sensor triggered OFF
+87ms ║║Piston state changed
+88ms ║║Executed virtual command [Cabinet Lights, Fireplace Lights].setState (1ms)
+92ms ║║Calculating (string)Bedroom Sensor + (string) triggered OFF >> (string)Bedroom Sensor triggered OFF
+95ms ║║Bedroom Sensor triggered OFF
+98ms ║║Executed virtual command [Cabinet Lights, Fireplace Lights].log (3ms)
+102ms ║╚Execution stage complete. (73ms)
+106ms ╚Event processed successfully (102ms)
5/30/2024, 5:40:08 AM +391ms
+9ms ╔Received event [Mudroom Door].contact = closed with a delay of 438ms, canQueue: true, calledMyself: false
+26ms ║Runtime (15533 bytes) initialized 20 LockT > 0ms > r9T > 2ms > pistonT > 0ms (first state access 7 m:11 10 10) (v0.3.114.20240115_HE)
+27ms ║╔Execution stage started
+35ms ║║Comparison (enum) :32e164a2e42f34f83c6d5126248c9a8d: is (string) :db51cd17b1529242205547665623a183: = false (1ms)
+38ms ║║Condition #1 evaluated false (4ms)
+46ms ║║Piston execution aborted due to restrictions in effect; updating piston states
+62ms ║║Comparison changes_to = false (event device/attr eXcluded)
+65ms ║║Comparison changes_to = false (event device/attr eXcluded)
+66ms ║║Comparison changes_to = false (event device/attr eXcluded)
+91ms ║║Comparison changes_to = false (event device/attr eXcluded)
+92ms ║║Comparison changes_to = false (event device/attr eXcluded)
+93ms ║║Comparison (enum) closed changes_to (string) open = false (0ms)
+94ms ║║Comparison changes_to = false (event device/attr eXcluded)
+175ms ║║Comparison (time) 20408000 is_between (time) 19800000 … (time) 23100000 = true (32ms)
+177ms ║║Time restriction check passed
+187ms ║║Comparison (enum) off is (string) off = true (1ms)
+203ms ║║Comparison (enum) closed stays (string) closed = true (3ms)
+205ms ║║Comparison (enum) closed stays (string) closed = true (1ms)
+207ms ║║Comparison (enum) closed stays (string) closed = true (2ms)
+278ms ║║Found matching value, duration 284290ms for is < 240000ms threshold = false
+279ms ║║Comparison (enum) inactive was (string) inactive = false (66ms)
+284ms ║║Comparison (enum) inactive stays (string) inactive = true (1ms)
+322ms ║║Comparison (enum) closed did_not_change = true (33ms)
+333ms ║╚Execution stage complete. (307ms)
+418ms ║Setting up scheduled job for Thu, May 30 2024 @ 5:42:04 AM CDT (in 116119ms)
+420ms ╚Event processed successfully (412ms)
5/30/2024, 5:39:57 AM +156ms
+3ms ╔Received event [Mudroom Door].contact = open with a delay of 47ms, canQueue: true, calledMyself: false
+19ms ║Runtime (15530 bytes) initialized 13 LockT > 1ms > r9T > 2ms > pistonT > 0ms (first state access 7 m:3 4 9) (v0.3.114.20240115_HE)
+20ms ║╔Execution stage started
+27ms ║║Comparison (enum) :32e164a2e42f34f83c6d5126248c9a8d: is (string) :db51cd17b1529242205547665623a183: = false (1ms)
+28ms ║║Condition #1 evaluated false (4ms)
+29ms ║║Piston execution aborted due to restrictions in effect; updating piston states
+37ms ║║Comparison changes_to = false (event device/attr eXcluded)
+38ms ║║Comparison changes_to = false (event device/attr eXcluded)
+38ms ║║Comparison changes_to = false (event device/attr eXcluded)
+47ms ║║Comparison changes_to = false (event device/attr eXcluded)
+47ms ║║Comparison changes_to = false (event device/attr eXcluded)
+49ms ║║Comparison (enum) open changes_to (string) open = false (0ms)
+50ms ║║Comparison changes_to = false (event device/attr eXcluded)
+72ms ║║Comparison (time) 20397000 is_between (time) 19800000 … (time) 23100000 = true (9ms)
+74ms ║║Time restriction check passed
+83ms ║║Comparison (enum) off is (string) off = true (1ms)
+109ms ║║Comparison (enum) closed stays (string) closed = true (1ms)
+112ms ║║Comparison (enum) closed stays (string) closed = true (1ms)
+114ms ║║Comparison (enum) closed stays (string) closed = true (1ms)
+162ms ║║Found matching value, duration 272939ms for is < 240000ms threshold = false
+163ms ║║Comparison (enum) inactive was (string) inactive = false (45ms)
+169ms ║║Comparison (enum) inactive stays (string) inactive = true (1ms)
+201ms ║║Comparison (enum) closed did_not_change = true (27ms)

And the hubitat logs:
app:9462024-05-30 05:42:18.496 AMdebugReleased Lock and exiting
app:9462024-05-30 05:42:05.042 AMdebugReleased Lock and exiting
app:9462024-05-30 05:42:04.999 AMinfo ║║ Bedroom Sensor triggered OFF
app:9462024-05-30 05:40:08.846 AMdebugReleased Lock and exiting
app:9462024-05-30 05:39:57.465 AMdebugReleased Lock and exiting
app:9462024-05-30 05:38:44.756 AMdebugReleased Lock and exiting
app:9462024-05-30 05:38:05.270 AMdebugReleased Lock and exiting
app:9462024-05-30 05:38:05.170 AMinfo ║║ Bedroom Sensor triggered OFF
app:9462024-05-30 05:38:05.120 AMwarn ║║ stays check stays isStays: true result: true options: [devices:[matched:[:c5302f51c1357b383e65b5c3b074dc1c:], unmatched:[]], matches:true, forceAll:true]
app:9462024-05-30 05:38:05.050 AMinfo ║║ Bedroom Sensor triggered OFF
app:9462024-05-30 05:38:04.999 AMwarn ║║ stays check stays isStays: true result: true options: [devices:[matched:[:c5302f51c1357b383e65b5c3b074dc1c:], unmatched:[]], matches:true, forceAll:true]
app:9462024-05-30 05:38:04.928 AMinfo ║║ Bedroom Sensor triggered OFF
app:9462024-05-30 05:38:04.871 AMwarn ║║ stays check stays isStays: true result: true options: [devices:[matched:[:c5302f51c1357b383e65b5c3b074dc1c:], unmatched:[]], matches:true, forceAll:true]

E_Sch · 2024-05-30 17:43:07 UTC

My first read is the stays timer fired, so that is a resume vs. a start from the top of the piston.

michicago · 2024-05-31 15:45:36 UTC

Your restriction is actually outside your Execute section, so it does nothing to stop it. Edit your piston and put your Restriction criteria where the green circle is and you should be good to go.

kshoemaker · 2024-06-03 14:52:55 UTC

I was assuming the “only when” above your green circle applies to the entire piston so I would not need the restriction inside the execute statement. Am I wrong?

kshoemaker · 2024-06-03 14:56:52 UTC

I agree that the stays timer is firing, but that timer is started when the motion sensor goes inactive which after the location mode has changed to day. It seems like it shouldn’t even get to that part of the piston since the piston restriction should block execution. Maybe I just don’t understand the piston restriction correctly.

kshoemaker · 2024-06-06 11:39:04 UTC

Here are the logs from the latest misfire.

Hubitat logs:
app:9462024-06-06 06:25:31.632 AMdebugReleased Lock and exiting
app:9462024-06-06 06:25:31.536 AMinfo ║║ Bedroom Sensor triggered OFF
app:9462024-06-06 06:25:31.484 AMwarn ║║ stays check stays isStays: true result: true options: [devices:[matched:[:c5302f51c1357b383e65b5c3b074dc1c:], unmatched:[]], matches:true, forceAll:true]
app:9462024-06-06 06:25:31.413 AMinfo ║║ Bedroom Sensor triggered OFF
app:9462024-06-06 06:25:31.360 AMwarn ║║ stays check stays isStays: true result: true options: [devices:[matched:[:c5302f51c1357b383e65b5c3b074dc1c:], unmatched:[]], matches:true, forceAll:true]
app:9462024-06-06 06:25:31.287 AMinfo ║║ Bedroom Sensor triggered OFF
app:9462024-06-06 06:25:31.227 AMwarn ║║ stays check stays isStays: true result: true options: [devices:[matched:[:c5302f51c1357b383e65b5c3b074dc1c:], unmatched:[]], matches:true, forceAll:true]
app:9502024-06-06 06:25:00.184 AMinfo ║ Shadow mode set to Day
app:9462024-06-06 06:22:50.256 AMdebugReleased Lock and exiting
dev:14962024-06-06 06:22:49.912 AMinfoBedroom Sensor motion became inactive
app:9462024-06-06 06:22:32.176 AMdebugReleased Lock and exiting
app:9462024-06-06 06:22:28.817 AMdebugReleased Lock and exiting
app:9462024-06-06 06:21:13.179 AMdebugReleased Lock and exiting
app:9462024-06-06 06:21:10.056 AMdebugReleased Lock and exiting
dev:13022024-06-06 06:20:40.939 AMinfoCabinet Lights power is 3.516 W
dev:13022024-06-06 06:20:37.669 AMinfoCabinet Lights Switch is on
dev:14492024-06-06 06:20:37.268 AMinfoMantle switch is on
dev:14502024-06-06 06:20:37.082 AMinfoSeasonal 1 was turned on [digital]
app:9482024-06-06 06:20:36.923 AMinfo ║ DAY mode 🟡
dev:10082024-06-06 06:20:36.890 AMinfoCouch Light was turned on [digital]
dev:13962024-06-06 06:20:36.881 AMinfoFireplace Lights is off [digital]
dev:14512024-06-06 06:20:36.760 AMinfoSeasonal Lights switch was turned on
app:14222024-06-06 06:20:36.756 AMinfoOn: Seasonal 1
app:14222024-06-06 06:20:36.737 AMinfoOn: Mantle
app:14862024-06-06 06:20:31.397 AMinfo ║ Mode became Day from Night
app:9462024-06-06 06:20:31.261 AMdebugReleased Lock and exiting
app:9462024-06-06 06:20:31.117 AMwarn ║║ stays check stays isStays: true result: false options: [devices:[matched:[], unmatched:[:c5302f51c1357b383e65b5c3b074dc1c:]], matches:true, forceAll:true]
app:9462024-06-06 06:20:31.093 AMwarn ║║ stays check stays isStays: true result: true options: [devices:[matched:[:249f4ceacaed26fcec0f1c3da97f266d:, :635085f5f83511ac85d2722896cb5858:, :40dd9a4b70f5fd0d062af7de56919ea0:], unmatched:[]], matches:true, forceAll:true]
app:9462024-06-06 06:20:31.076 AMinfo ║║ Bedroom Sensor triggered DAY mode 🟡
dev:14962024-06-06 06:20:30.889 AMinfoBedroom Sensor motion became active

Webcore logs:
6/6/2024, 6:25:31 AM +124ms
+5ms ╔Received event [Shoe’s].time = 1717673131100 with a delay of 24ms, canQueue: true, calledMyself: false
+27ms ║Runtime (15215 bytes) initialized 22 LockT > 1ms > r9T > 2ms > pistonT > 0ms (first state access 14 m:5 6 16) (v0.3.114.20240115_HE)
+36ms ║╔Execution stage started
+46ms ║║Condition #20 evaluated true (0ms)
+92ms ║║Found matching value, duration 161300ms for is < 240000ms threshold = true
+93ms ║║Comparison (enum) inactive was (string) inactive = true (44ms)
+95ms ║║Condition #21 evaluated true (48ms)
+97ms ║║Condition group #19 evaluated true (condition changed) (52ms)
+102ms ║║Comparison (enum) inactive stays (string) inactive = true (0ms)
+110ms ║║Adding a timed trigger schedule stays result true scheduling timer for condition 23 wake up at Thu, Jun 6 2024 @ 6:29:31 AM CDT (in 239998ms) for 23 (st:23)
+112ms ║║Condition #23 evaluated false (13ms)
+114ms ║║Condition group #22 evaluated false (condition changed) (16ms)
+115ms ║║Condition group #18 evaluated true (condition did not change) (70ms)
+138ms ║║Executed device command [Cabinet Lights].off() (18ms)
+141ms ║║Command optimization: Skipped execution of device command [Fireplace Lights].off() because it would make no change to the device. (1ms)
+149ms ║║Calculating (string)Thu 6/6 6:25:31 + (string) - >> (string)Thu 6/6 6:25:31 -
+151ms ║║Calculating (string)Thu 6/6 6:25:31 - + (string)Bedroom Sensor >> (string)Thu 6/6 6:25:31 - Bedroom Sensor
+152ms ║║Calculating (string)Thu 6/6 6:25:31 - Bedroom Sensor + (string) triggered OFF >> (string)Thu 6/6 6:25:31 - Bedroom Sensor triggered OFF
+155ms ║║Piston state changed
+156ms ║║Executed virtual command [Cabinet Lights, Fireplace Lights].setState (1ms)
+160ms ║║Calculating (string)Bedroom Sensor + (string) triggered OFF >> (string)Bedroom Sensor triggered OFF
+163ms ║║Bedroom Sensor triggered OFF
+165ms ║║Executed virtual command [Cabinet Lights, Fireplace Lights].log (3ms)
+172ms ║╚Execution stage complete. (137ms)
+178ms ║Processing timer time = 1717673131103
+179ms ║╔Execution stage started
+188ms ║║Condition #20 evaluated true (1ms)
+227ms ║║Found matching value, duration 161435ms for is < 240000ms threshold = true
+228ms ║║Comparison (enum) inactive was (string) inactive = true (37ms)
+229ms ║║Condition #21 evaluated true (39ms)
+230ms ║║Condition group #19 evaluated true (condition did not change) (42ms)
+235ms ║║Comparison (enum) inactive stays (string) inactive = true (1ms)
+241ms ║║Doing nothing found timed trigger schedule stays result true found timer for condition 23
+242ms ║║Condition #23 evaluated false (11ms)
+243ms ║║Condition group #22 evaluated false (condition did not change) (12ms)
+244ms ║║Condition group #18 evaluated true (condition did not change) (56ms)
+264ms ║║Executed device command [Cabinet Lights].off() (16ms)
+266ms ║║Command optimization: Skipped execution of device command [Fireplace Lights].off() because it would make no change to the device. (1ms)
+274ms ║║Calculating (string)Thu 6/6 6:25:31 + (string) - >> (string)Thu 6/6 6:25:31 -
+276ms ║║Calculating (string)Thu 6/6 6:25:31 - + (string)Bedroom Sensor >> (string)Thu 6/6 6:25:31 - Bedroom Sensor
+278ms ║║Calculating (string)Thu 6/6 6:25:31 - Bedroom Sensor + (string) triggered OFF >> (string)Thu 6/6 6:25:31 - Bedroom Sensor triggered OFF
+280ms ║║Piston state changed
+281ms ║║Executed virtual command [Cabinet Lights, Fireplace Lights].setState (1ms)
+285ms ║║Calculating (string)Bedroom Sensor + (string) triggered OFF >> (string)Bedroom Sensor triggered OFF
+289ms ║║Bedroom Sensor triggered OFF
+291ms ║║Executed virtual command [Cabinet Lights, Fireplace Lights].log (3ms)
+298ms ║╚Execution stage complete. (119ms)
+304ms ║Processing timer time = 1717673131106
+305ms ║╔Execution stage started

Pantheon · 2024-06-06 14:40:48 UTC

For me, a trace with this log would be very helpful. Can you include a trace? Others may not need it.

E_Sch · 2024-06-06 19:49:04 UTC

There is a command in webCoRE cancel all tasks, that you could execute if you know that you are changing mode and don’t want the stays timers to be active any more.

You might try that

kshoemaker · 2024-06-07 10:44:50 UTC

I’ve already got a cancel pending tasks commend in there.

I just read the trace article. It’s tricky with this piston because the logs age out too quickly. I’ll close this thread and try to recreate the conditions in a new piston with fewer trigger devices.

Thanks for all the pointers so far.