Piston triggering when it shouldn't be


#1

1) Give a description of the problem
The branch of this piston which leads to the “Away lighting simulation ended…” message has recently started triggering every night even though Location mode is set to Home at those times.

2) What is the expected behaviour?
This branch should only trigger if location mode is away, then changes to ‘Home’ and the time is between the specified window.

3) What is happening/not happening?
The piston seems to be getting the impression that location mode is changing from away to home every night during the hours specified. I haven’t changed anything in this piston and it was previously working as expected so I’m not sure what’s going on. I’m wondering whether if location mode was away at 3pm say and then we got home at 4 and location mode set to ‘Home’. The piston is remembering that change and at sunset, it is evaluating true and triggering that branch?

4) Post a Green Snapshot of the pistonimage

5) Attach logs after turning logging level to Full
8/19/2021, 6:59:59 AM +747ms
+0ms ╔Received event [Home].mode = Home with a delay of 137ms
+86ms ║RunTime Analysis CS > 21ms > PS > 7ms > PE > 57ms > CE
+88ms ║Runtime (47776 bytes) successfully initialized in 7ms (v0.3.110.20191009) (87ms)
+89ms ║╔Execution stage started
+151ms ║║Comparison (time) 25199841 is_between (time) 1629400620000 … (time) 84600000 = false (12ms)
+154ms ║║Condition #32 evaluated false (61ms)
+155ms ║║Cancelling statement #32’s schedules…
+167ms ║║Requesting time schedule wake up at Thu, Aug 19 2021 @ 8:32:00 PM BST
+170ms ║║Condition group #18 evaluated false (state did not change) (77ms)
+186ms ║║Comparison (time) 25199920 is_between (time) 1629400620000 … (time) 84600000 = false (9ms)
+188ms ║║Condition #28 evaluated false (14ms)
+189ms ║║Condition group #12 evaluated false (state did not change) (17ms)
+195ms ║║Comparison (time) 25199938 happens_daily_at (time) 84600000 = false (1ms)
+197ms ║║Cancelling condition #39’s schedules…
+198ms ║║Condition #39 evaluated false (6ms)
+199ms ║║Cancelling statement #39’s schedules…
+204ms ║║Requesting time schedule wake up at Thu, Aug 19 2021 @ 11:35:00 PM BST
+206ms ║║Condition group #36 evaluated false (state did not change) (15ms)
+209ms ║╚Execution stage complete. (120ms)
+211ms ║Setting up scheduled job for Thu, Aug 19 2021 @ 8:32:00 PM BST (in 48720.043s), with 1 more job pending
+221ms ╚Event processed successfully (221ms)
8/18/2021, 11:34:59 PM +89ms
+1ms ╔Received event [Home].time = 1629326100000 with a delay of -911ms
+146ms ║RunTime Analysis CS > 79ms > PS > 7ms > PE > 60ms > CE
+149ms ║Runtime (47788 bytes) successfully initialized in 7ms (v0.3.110.20191009) (147ms)
+150ms ║╔Execution stage started
+292ms ║║Comparison (time) 84899249 is_between (time) 1629314340000 … (time) 84600000 = false (10ms)
+294ms ║║Condition #32 evaluated false (134ms)
+296ms ║║Cancelling statement #32’s schedules…
+307ms ║║Requesting time schedule wake up at Thu, Aug 19 2021 @ 8:34:00 PM BST
+309ms ║║Condition group #18 evaluated false (state did not change) (150ms)
+328ms ║║Comparison (time) 84899401 is_between (time) 1629314340000 … (time) 84600000 = false (10ms)
+329ms ║║Condition #28 evaluated false (17ms)
+330ms ║║Condition group #12 evaluated false (state did not change) (19ms)
+339ms ║║Comparison (time) 84899422 happens_daily_at (time) 84600000 = true (0ms)
+340ms ║║Time restriction check passed
+342ms ║║Cancelling condition #39’s schedules…
+343ms ║║Condition #39 evaluated true (10ms)
+394ms ║║Cancelling statement #39’s schedules…
+401ms ║║Requesting time schedule wake up at Thu, Aug 19 2021 @ 11:35:00 PM BST
+408ms ║║Comparison (string) :c465aace1b0b65e0843af2bee0c2ad3e: is (string) :7aecdb081afd252257c7be17fc2fa71e: = false (2ms)
+409ms ║║Condition #40 evaluated false (6ms)
+410ms ║║Condition group #36 evaluated false (state did not change) (77ms)
+414ms ║╚Execution stage complete. (264ms)
+416ms ║Setting up scheduled job for Thu, Aug 19 2021 @ 8:34:00 PM BST (in 75540.496s), with 1 more job pending
+424ms ╚Event processed successfully (424ms)
8/18/2021, 11:29:59 PM +49ms
+0ms ╔Received event [Home].time = 1629325800000 with a delay of -951ms
+72ms ║RunTime Analysis CS > 17ms > PS > 5ms > PE > 50ms > CE
+75ms ║Runtime (47785 bytes) successfully initialized in 5ms (v0.3.110.20191009) (74ms)
+76ms ║╔Execution stage started
+126ms ║║Comparison (time) 84599131 is_between (time) 1629314340000 … (time) 84600000 = false (10ms)
+128ms ║║Cancelling condition #32’s schedules…
+128ms ║║Condition #32 evaluated false (46ms)
+130ms ║║Cancelling statement #32’s schedules…
+140ms ║║Requesting time schedule wake up at Thu, Aug 19 2021 @ 8:34:00 PM BST
+143ms ║║Condition group #18 evaluated false (state did not change) (60ms)
+160ms ║║Comparison (time) 84599194 is_between (time) 1629314340000 … (time) 84600000 = false (10ms)
+162ms ║║Cancelling condition #28’s schedules…
+163ms ║║Condition #28 evaluated false (18ms)
+164ms ║║Condition group #12 evaluated false (state did not change) (19ms)
+171ms ║║Comparison (time) 84599216 happens_daily_at (time) 84600000 = false (0ms)
+173ms ║║Condition #39 evaluated false (6ms)
+182ms ║║Cancelling statement #39’s schedules…
+187ms ║║Requesting time schedule wake up at Wed, Aug 18 2021 @ 11:35:00 PM BST
+190ms ║║Condition group #36 evaluated false (state did not change) (23ms)
+193ms ║╚Execution stage complete. (117ms)
+195ms ║Setting up scheduled job for Wed, Aug 18 2021 @ 11:35:00 PM BST (in 300.757s), with 1 more job pending
+202ms ╚Event processed successfully (201ms)
8/18/2021, 10:42:07 PM +751ms
+1ms ╔Received event [Home].mode = Night with a delay of 180ms
+76ms ║RunTime Analysis CS > 20ms > PS > 9ms > PE > 46ms > CE
+78ms ║Runtime (47771 bytes) successfully initialized in 9ms (v0.3.110.20191009) (77ms)
+79ms ║╔Execution stage started
+123ms ║║Comparison (time) 81727833 is_between (time) 1629314340000 … (time) 84600000 = true (7ms)
+124ms ║║Time restriction check passed
+125ms ║║Condition #32 evaluated true (43ms)
+126ms ║║Cancelling statement #32’s schedules…
+133ms ║║Requesting time schedule wake up at Wed, Aug 18 2021 @ 11:30:00 PM BST
+137ms ║║Comparison (string) :c465aace1b0b65e0843af2bee0c2ad3e: is (string) :7aecdb081afd252257c7be17fc2fa71e: = false (1ms)
+138ms ║║Condition #5 evaluated false (4ms)
+139ms ║║Condition group #18 evaluated false (state did not change) (57ms)
+151ms ║║Comparison (time) 81727892 is_between (time) 1629314340000 … (time) 84600000 = true (7ms)
+152ms ║║Time restriction check passed
+153ms ║║Condition #28 evaluated true (12ms)
+156ms ║║Comparison (string) :c465aace1b0b65e0843af2bee0c2ad3e: changes_to (string) :d3dc195c6ea99304d142f80151ca8da2: = false (1ms)
+157ms ║║Cancelling condition #15’s schedules…
+158ms ║║Condition #15 evaluated false (3ms)
+158ms ║║Cancelling condition #12’s schedules…
+159ms ║║Condition group #12 evaluated false (state changed) (18ms)
+164ms ║║Comparison (time) 81727912 happens_daily_at (time) 84600000 = false (1ms)
+165ms ║║Condition #39 evaluated false (4ms)
+166ms ║║Cancelling statement #39’s schedules…
+170ms ║║Requesting time schedule wake up at Wed, Aug 18 2021 @ 11:35:00 PM BST
+171ms ║║Condition group #36 evaluated false (state did not change) (10ms)
+174ms ║╚Execution stage complete. (94ms)
+175ms ║Setting up scheduled job for Wed, Aug 18 2021 @ 11:30:00 PM BST (in 2872.075s), with 1 more job pending
+185ms ╚Event processed successfully (185ms)
8/18/2021, 8:34:09 PM +110ms
+0ms ╔Received event [Home].time = 1629315250279 with a delay of -1170ms
+105ms ║RunTime Analysis CS > 36ms > PS > 6ms > PE > 64ms > CE
+108ms ║Runtime (47783 bytes) successfully initialized in 6ms (v0.3.110.20191009) (107ms)
+109ms ║╔Execution stage started
+140ms ║║Calculating (integer) 7 - (integer) 1 >> (integer) 6
+171ms ║║Executed virtual command sendPushNotification (12ms)
+173ms ║║Cancelling statement #26’s schedules…
+186ms ║║Executed physical command [Hallway Spotlight].on() (9ms)
+186ms ║║Executed [Hallway Spotlight].on (10ms)
+196ms ║║Executed physical command [Hallway Spotlight].setLevel([50]) (7ms)
+197ms ║║Executed [Hallway Spotlight].setLevel (8ms)
+201ms ║╚Execution stage complete. (92ms)
+202ms ║Setting up scheduled job for Wed, Aug 18 2021 @ 11:30:00 PM BST (in 10550.688s), with 1 more job pending
+211ms ╚Event processed successfully (212ms)
8/18/2021, 8:33:59 PM +83ms
+1ms ╔Received event [Home].time = 1629315240000 with a delay of -917ms
+126ms ║RunTime Analysis CS > 23ms > PS > 5ms > PE > 97ms > CE
+129ms ║Runtime (47788 bytes) successfully initialized in 5ms (v0.3.110.20191009) (127ms)
+130ms ║╔Execution stage started
+193ms ║║Comparison (time) 74039218 is_between (time) 1629314340000 … (time) 84600000 = true (13ms)
+194ms ║║Time restriction check passed
+196ms ║║Cancelling condition #32’s schedules…
+198ms ║║Condition #32 evaluated true (62ms)
+199ms ║║Cancelling statement #32’s schedules…
+210ms ║║Requesting time schedule wake up at Wed, Aug 18 2021 @ 11:30:00 PM BST
+216ms ║║Comparison (string) :d3dc195c6ea99304d142f80151ca8da2: is (string) :7aecdb081afd252257c7be17fc2fa71e: = false (2ms)
+217ms ║║Condition #5 evaluated false (5ms)
+218ms ║║Condition group #18 evaluated false (state did not change) (83ms)
+234ms ║║Comparison (time) 74039304 is_between (time) 1629314340000 … (time) 84600000 = true (8ms)
+235ms ║║Time restriction check passed
+236ms ║║Cancelling condition #28’s schedules…
+237ms ║║Condition #28 evaluated true (16ms)
+240ms ║║Comparison (string) :d3dc195c6ea99304d142f80151ca8da2: changes_to (string) :d3dc195c6ea99304d142f80151ca8da2: = true (1ms)
+242ms ║║Cancelling condition #15’s schedules…
+243ms ║║Condition #15 evaluated true (4ms)
+244ms ║║Cancelling condition #12’s schedules…
+245ms ║║Condition group #12 evaluated true (state changed) (23ms)
+247ms ║║Cancelling statement #24’s schedules…
+258ms ║║Skipped execution of physical command [3rd Bed Lights].off([]) because it would make no change to the device. (3ms)
+259ms ║║Executed [3rd Bed Lights].off (5ms)
+265ms ║║Skipped execution of physical command [Girls’ bedroom Light].off([]) because it would make no change to the device. (5ms)
+266ms ║║Executed [Girls’ bedroom Light].off (5ms)
+272ms ║║Skipped execution of physical command [Playroom Lights].off([]) because it would make no change to the device. (4ms)
+273ms ║║Executed [Playroom Lights].off (6ms)
+1157ms ║║Executed physical command [Landing Lights].off() (881ms)
+1158ms ║║Executed [Landing Lights].off (883ms)
+1165ms ║║Skipped execution of physical command [Lounge Lights].off([]) because it would make no change to the device. (5ms)
+1166ms ║║Executed [Lounge Lights].off (6ms)
+1173ms ║║Skipped execution of physical command [Master Bed Lights].off([]) because it would make no change to the device. (4ms)
+1174ms ║║Executed [Master Bed Lights].off (6ms)
+1183ms ║║Skipped execution of physical command [Utility Lights].off([]) because it would make no change to the device. (5ms)
+1185ms ║║Executed [Utility Lights].off (8ms)
+1189ms ║║Cancelling statement #33’s schedules…
+1194ms ║║Executed virtual command wait (1ms)
+1195ms ║║Requesting a wake up for Wed, Aug 18 2021 @ 8:34:10 PM BST (in 10.0s)
+1207ms ║║Comparison (time) 74040285 happens_daily_at (time) 84600000 = false (1ms)
+1209ms ║║Condition #39 evaluated false (6ms)
+1210ms ║║Cancelling statement #39’s schedules…
+1217ms ║║Requesting time schedule wake up at Wed, Aug 18 2021 @ 11:35:00 PM BST
+1220ms ║║Condition group #36 evaluated false (state did not change) (19ms)
+1225ms ║╚Execution stage complete. (1095ms)
+1227ms ║Setting up scheduled job for Wed, Aug 18 2021 @ 8:34:10 PM BST (in 9.969s), with 2 more jobs pending
+1237ms ╚Event processed successfully (1237ms)
8/18/2021, 6:59:59 AM +496ms
+0ms ╔Received event [Home].mode = Home with a delay of 76ms
+99ms ║RunTime Analysis CS > 9ms > PS > 8ms > PE > 81ms > CE
+101ms ║Runtime (47774 bytes) successfully initialized in 8ms (v0.3.110.20191009) (100ms)
+102ms ║╔Execution stage started
+151ms ║║Comparison (time) 25199604 is_between (time) 1629314340000 … (time) 84600000 = false (9ms)
+153ms ║║Condition #32 evaluated false (45ms)
+154ms ║║Cancelling statement #32’s schedules…
+162ms ║║Requesting time schedule wake up at Wed, Aug 18 2021 @ 8:34:00 PM BST
+165ms ║║Condition group #18 evaluated false (state did not change) (57ms)
+180ms ║║Comparison (time) 25199664 is_between (time) 1629314340000 … (time) 84600000 = false (9ms)
+181ms ║║Condition #28 evaluated false (14ms)
+182ms ║║Condition group #12 evaluated false (state did not change) (15ms)
+188ms ║║Comparison (time) 25199681 happens_daily_at (time) 84600000 = false (0ms)
+190ms ║║Cancelling condition #39’s schedules…
+191ms ║║Condition #39 evaluated false (5ms)
+192ms ║║Cancelling statement #39’s schedules…
+196ms ║║Requesting time schedule wake up at Wed, Aug 18 2021 @ 11:35:00 PM BST
+199ms ║║Condition group #36 evaluated false (state did not change) (14ms)
+201ms ║╚Execution stage complete. (99ms)
+203ms ║Setting up scheduled job for Wed, Aug 18 2021 @ 8:34:00 PM BST (in 48840.302s), with 1 more job pending
+211ms ╚Event processed successfully (211ms)
8/17/2021, 11:34:59 PM +78ms
+0ms ╔Received event [Home].time = 1629239700000 with a delay of -922ms
+91ms ║RunTime Analysis CS > 25ms > PS > 6ms > PE > 59ms > CE
+93ms ║Runtime (47786 bytes) successfully initialized in 6ms (v0.3.110.20191009) (92ms)
+94ms ║╔Execution stage started
+146ms ║║Comparison (time) 84899177 is_between (time) 1629228120000 … (time) 84600000 = false (8ms)
+147ms ║║Condition #32 evaluated false (48ms)
+151ms ║║Cancelling statement #32’s schedules…
+159ms ║║Requesting time schedule wake up at Wed, Aug 18 2021 @ 8:37:00 PM BST
+161ms ║║Condition group #18 evaluated false (state did not change) (62ms)
+176ms ║║Comparison (time) 84899242 is_between (time) 1629228120000 … (time) 84600000 = false (9ms)
+177ms ║║Condition #28 evaluated false (13ms)
+178ms ║║Condition group #12 evaluated false (state did not change) (15ms)
+184ms ║║Comparison (time) 84899259 happens_daily_at (time) 84600000 = true (0ms)
+185ms ║║Time restriction check passed
+187ms ║║Cancelling condition #39’s schedules…
+187ms ║║Condition #39 evaluated true (6ms)
+194ms ║║Cancelling statement #39’s schedules…
+199ms ║║Requesting time schedule wake up at Wed, Aug 18 2021 @ 11:35:00 PM BST
+204ms ║║Comparison (string) :c465aace1b0b65e0843af2bee0c2ad3e: is (string) :7aecdb081afd252257c7be17fc2fa71e: = false (2ms)
+205ms ║║Condition #40 evaluated false (4ms)
+206ms ║║Condition group #36 evaluated false (state did not change) (26ms)
+209ms ║╚Execution stage complete. (115ms)
+210ms ║Setting up scheduled job for Wed, Aug 18 2021 @ 8:37:00 PM BST (in 75720.712s), with 1 more job pending
+219ms ╚Event processed successfully (218ms)


#2

I’d try flipping the positions of lines 44 and 46 so ‘location changes to home’ always gets evaluated first.

The thing about ‘changes to’ is that the change it is looking for is between the current value and the value it was last time the condition was evaluated. The last location event was at 7am and because that was outside the time range there was no need to evaluate the ‘changes to home’ line and so the piston doesn’t know about it. If you evaluate the location first it will always know about it.

What is slightly puzzling me is that ‘changes’ normally looks at the event that is being handled. So for example, a switch could only ‘change to on’ if the current event being processed is ‘switch = on’ (and that would carry across ‘waits’ as it is still the original event being processed). However in this case it is a time event that is being handled, not a location event, so I don’t understand how it is interpreted as having changed. Maybe things work differently with locations and I’ve never noticed.


#3

Good shout. That’s plausible so I’ve swapped the condition evaluation statements. In fact, I’ve swapped them for lines 27 and 29 and 63 and 65 because by the logic you mention, it makes sense for the location mode to be evaluated first for all the if statements. I’ll see if that does it tonight and report back.


#4

That seems to have fixed it. So odd that the original coding worked perfectly for over a year but oh well, thanks for helping get that sorted :slight_smile: