Sometimes Switch does not shut-off

[TonyK1321]

1) Give a description of the problem
I have a Webcore piston that occasionally does not shut-off a switch as it should.

2) What is the expected behavior?
The switch is supposed to turn on for 2.5 min then turn-off.

3) What is happening/not happening?
Sometimes the switch turns on but after the 2.5 min time, does not shut-off.

**4) Post a Green Snapshot of the piston!
How do I attach a file?

5) Attach any logs (From ST IDE and by turning logging level to Full)
(PASTE YOUR LOGS HERE BETWEEN THE MARKS THEN HIGHLIGHT ALL OF THE LOGS SND CLICK ON THE </> ICON TO FORMAT THEM)

REMOVE BELOW AFTER READING

[rsmith179]

Under the piston, click on the green snapshot button. It will bring up an image with your piston. Just right-click on that image and select copy. You can then just paste it into this thread so we can see how your piston is set up.

[TonyK1321]

Ah, got it now. You have to upload an image. For me, copy and paste did not work.

Here are the logs at the time that it happened.

2/8/2018, 9:51:10 AM +343ms
+0ms ╔Received event [Home].time = 1518108671628 with a delay of -1286ms
+237ms ║Runtime (44427 bytes) successfully initialized in 90ms (v0.2.102.20180116) (234ms)
+238ms ║╔Execution stage started
+285ms ║╚Execution stage complete. (48ms)
+287ms ║Setting up scheduled job for Thu, Feb 8 2018 @ 10:01:11 AM MST (in 600.999s)
+295ms ╚Event processed successfully (295ms)
2/8/2018, 9:41:11 AM +416ms
+0ms ╔Received event [Home].time = 1518108071628 with a delay of -213ms
+282ms ║Runtime (44427 bytes) successfully initialized in 119ms (v0.2.102.20180116) (280ms)
+283ms ║╔Execution stage started
+333ms ║╚Execution stage complete. (49ms)
+334ms ║Setting up scheduled job for Thu, Feb 8 2018 @ 9:51:11 AM MST (in 599.878s)
+341ms ╚Event processed successfully (341ms)
2/8/2018, 9:33:41 AM +937ms
+1ms ╔Received event [Home].time = 1518107621640 with a delay of 297ms
+333ms ║Runtime (44425 bytes) successfully initialized in 128ms (v0.2.102.20180116) (330ms)
+334ms ║╔Execution stage started
+610ms ║╚Execution stage complete. (276ms)
+612ms ║Setting up scheduled job for Thu, Feb 8 2018 @ 9:41:11 AM MST (in 449.08s)
+622ms ╚Event processed successfully (622ms)
2/8/2018, 9:31:10 AM +356ms
+1ms ╔Received event [Home].time = 1518107471628 with a delay of -1272ms
+1097ms ║Runtime (44427 bytes) successfully initialized in 110ms (v0.2.102.20180116) (1096ms)
+1099ms ║╔Execution stage started
+1272ms ║║Executed [Water Recirculation].on (34ms)
+1282ms ║║Executed virtual command [Water Recirculation].wait (1ms)
+1283ms ║║Requesting a wake up for Thu, Feb 8 2018 @ 9:33:41 AM MST (in 150.0s)
+1291ms ║╚Execution stage complete. (193ms)
+1293ms ║Setting up scheduled job for Thu, Feb 8 2018 @ 9:33:41 AM MST (in 149.992s), with 1 more job pending
+1302ms ╚Event processed successfully (1302ms)
2/8/2018, 9:23:40 AM +359ms
+1ms ╔Received event [Home].time = 1518107021765 with a delay of -1406ms
+255ms ║Runtime (44426 bytes) successfully initialized in 94ms (v0.2.102.20180116) (253ms)
+256ms ║╔Execution stage started
+305ms ║║Executed [Water Recirculation].off (17ms)
+312ms ║╚Execution stage complete. (56ms)
+314ms ║Setting up scheduled job for Thu, Feb 8 2018 @ 9:31:11 AM MST (in 450.956s)
+322ms ╚Event processed successfully (321ms)
2/8/2018, 9:21:11 AM +358ms
+1ms ╔Received event [Home].time = 1518106871628 with a delay of -270ms
+250ms ║Runtime (44427 bytes) successfully initialized in 74ms (v0.2.102.20180116) (248ms)
+251ms ║╔Execution stage started
+398ms ║║Executed [Water Recirculation].on (18ms)
+405ms ║║Executed virtual command [Water Recirculation].wait (1ms)
+406ms ║║Requesting a wake up for Thu, Feb 8 2018 @ 9:23:41 AM MST (in 150.0s)
+414ms ║╚Execution stage complete. (164ms)
+416ms ║Setting up scheduled job for Thu, Feb 8 2018 @ 9:23:41 AM MST (in 149.991s), with 1 more job pending
+424ms ╚Event processed successfully (424ms)

Ah the bottom is a sequence that shows it working correctly. At 9:21, pump went on. At 9:23 it went off. Then at 9:31, pump went on, and the follow-up schedule to turn it off at 9:33 was created. Then at 9:33, the timer went off, but the pump did not turn off. The at 9:41, the piston executed again (every 10 min), but because the pump was on, then nothing happened. Same at 9:51. So the problem was at 9:33 that prevented the pump to turn off. Any thoughts on why that would happen?

[JohnHoke]

Would be better if you had logging set to full in WebCore and turn on trace … my head is swimming in If/Then statements

Also, do not use the RED camera button - use the GREEN button for your screenshots

[TonyK1321]

Yea, I figured that would be a comment. I now have it set for Full. But if I let it go too long, I will not see the event because it filled up with working events. To help that, I have another piston setup to detect when this one fails that will send me a text when the pump does not shut-off. That may allow me to capture the event when it happens if I have my phone with me. And Trace is on but it is not copied if do either red or green capture. I could do a screen capture but probably would not catch the failure at the time that it occurred.

By way of explanation, this piston runs every 10 min. When it runs and if current time is in either of the 2 time windows at the top, then the pump will run for 13 min then quit. If not in those windows, then I am looking for house activity by looking at TV power, or if any motion occurred. Or, if TV power was on within the last 15 min. Or if time is 1st thing in the morning. In those cases, if the pump was idle for more than 30 min, then the pump will run for 12 min then turn off. Otherwise it will run for 2.5 min then off. It is this last situation that is normal during the day when we are home, and the one that I believe is the failure.

[TonyK1321]

I saw that ST had trouble controlling some devices yesterday. Is that the reason for the troubles that I had? So far, last night and today, the piston is working as expected.

[TonyK1321]

I just captured a failure. See the revised piston.

Here are the logs at the time of the failure. The 1st 2 are operation normal, followed by the failure.

2/9/2018, 11:12:39 AM +376ms
+0ms ╔Received event [Home].time = 1518199959739 with a delay of -363ms
+262ms ║RunTime Analysis CS > 22ms > PS > 113ms > PE > 126ms > CE
+265ms ║Runtime (44118 bytes) successfully initialized in 113ms (v0.2.102.20180116) (264ms)
+266ms ║╔Execution stage started
+455ms ║║Comparison (enum) off was (string) off = false (169ms)
+457ms ║║Condition #7 evaluated false (179ms)
+458ms ║║Condition group #2 evaluated false (state did not change) (180ms)
+462ms ║╚Execution stage complete. (197ms)
+464ms ║Setting up scheduled job for Fri, Feb 9 2018 @ 11:22:39 AM MST (in 599.9s)
+473ms ╚Event processed successfully (473ms)
2/9/2018, 11:02:39 AM +402ms
+0ms ╔Received event [Home].time = 1518199359739 with a delay of -338ms
+220ms ║RunTime Analysis CS > 23ms > PS > 81ms > PE > 117ms > CE
+223ms ║Runtime (44116 bytes) successfully initialized in 81ms (v0.2.102.20180116) (222ms)
+224ms ║╔Execution stage started
+265ms ║║Comparison (enum) on was (string) off = false (22ms)
+267ms ║║Condition #7 evaluated false (30ms)
+268ms ║║Condition group #2 evaluated false (state did not change) (31ms)
+271ms ║╚Execution stage complete. (47ms)
+273ms ║Setting up scheduled job for Fri, Feb 9 2018 @ 11:12:39 AM MST (in 600.065s)
+283ms ╚Event processed successfully (284ms)
2/9/2018, 10:55:07 AM +342ms
+0ms ╔Received event [Home].time = 1518198908726 with a delay of -1385ms
+223ms ║RunTime Analysis CS > 20ms > PS > 90ms > PE > 114ms > CE
+226ms ║Runtime (44116 bytes) successfully initialized in 90ms (v0.2.102.20180116) (225ms)
+227ms ║╔Execution stage started
+351ms ║║Comparison (enum) on was (string) off = false (105ms)
+353ms ║║Cancelling condition #7’s schedules…
+353ms ║║Condition #7 evaluated false (114ms)
+354ms ║║Cancelling condition #2’s schedules…
+355ms ║║Condition group #2 evaluated false (state changed) (116ms)
+359ms ║╚Execution stage complete. (132ms)
+360ms ║Setting up scheduled job for Fri, Feb 9 2018 @ 11:02:39 AM MST (in 452.037s)
+370ms ╚Event processed successfully (369ms)
2/9/2018, 10:52:38 AM +329ms
+1ms ╔Received event [Home].time = 1518198759739 with a delay of -1410ms
+219ms ║RunTime Analysis CS > 17ms > PS > 76ms > PE > 126ms > CE
+222ms ║Runtime (44116 bytes) successfully initialized in 76ms (v0.2.102.20180116) (220ms)
+223ms ║╔Execution stage started
+269ms ║║Comparison (enum) off was (string) off = true (27ms)
+271ms ║║Condition #7 evaluated true (35ms)
+272ms ║║Condition group #2 evaluated true (state did not change) (36ms)
+287ms ║║Comparison (time) 39158605 is_between (time) 61200000 … (time) 61800000 = false (9ms)
+289ms ║║Condition #22 evaluated false (13ms)
+290ms ║║Condition group #20 evaluated false (state did not change) (14ms)
+291ms ║║Condition group #9 evaluated false (state did not change) (15ms)
+309ms ║║Comparison (decimal) 0.4 is_greater_than (integer) 40 = false (2ms)
+312ms ║║Comparison (decimal) 101.8 is_greater_than (integer) 40 = true (1ms)
+314ms ║║Condition #40 evaluated true (21ms)
+315ms ║║Condition group #10 evaluated true (state did not change) (22ms)
+350ms ║║Comparison (enum) off was (string) off = false (25ms)
+352ms ║║Condition #39 evaluated false (34ms)
+353ms ║║Condition group #30 evaluated false (state did not change) (36ms)
+356ms ║║Cancelling statement #31’s schedules…
+384ms ║║Executed physical command [Water Recirculation].on() (26ms)
+385ms ║║Executed [Water Recirculation].on (28ms)
+391ms ║║Calculating (decimal) 2.5 * (decimal) 60.0 >> (decimal) 150.0
+395ms ║║Executed virtual command [Water Recirculation].wait (1ms)
+396ms ║║Requesting a wake up for Fri, Feb 9 2018 @ 10:55:08 AM MST (in 150.0s)
+405ms ║╚Execution stage complete. (183ms)
+408ms ║Setting up scheduled job for Fri, Feb 9 2018 @ 10:55:08 AM MST (in 149.99s), with 1 more job pending
+418ms ╚Event processed successfully (418ms)
2/9/2018, 10:45:07 AM +404ms
+1ms ╔Received event [Home].time = 1518198308712 with a delay of -1308ms
+292ms ║RunTime Analysis CS > 17ms > PS > 119ms > PE > 156ms > CE
+295ms ║Runtime (44118 bytes) successfully initialized in 119ms (v0.2.102.20180116) (294ms)
+297ms ║╔Execution stage started
+361ms ║║Executed physical command [Water Recirculation].off() (31ms)
+362ms ║║Executed [Water Recirculation].off (33ms)
+368ms ║╚Execution stage complete. (72ms)
+370ms ║Setting up scheduled job for Fri, Feb 9 2018 @ 10:52:39 AM MST (in 451.966s)
+380ms ╚Event processed successfully (379ms)
2/9/2018, 10:42:38 AM +326ms
+0ms ╔Received event [Home].time = 1518198159739 with a delay of -1414ms
+218ms ║RunTime Analysis CS > 14ms > PS > 86ms > PE > 118ms > CE
+220ms ║Runtime (44116 bytes) successfully initialized in 86ms (v0.2.102.20180116) (219ms)
+222ms ║╔Execution stage started
+269ms ║║Comparison (enum) off was (string) off = true (29ms)
+271ms ║║Condition #7 evaluated true (36ms)
+271ms ║║Condition group #2 evaluated true (state did not change) (38ms)
+284ms ║║Comparison (time) 38558601 is_between (time) 61200000 … (time) 61800000 = false (7ms)
+286ms ║║Condition #22 evaluated false (11ms)
+287ms ║║Condition group #20 evaluated false (state did not change) (13ms)
+288ms ║║Condition group #9 evaluated false (state did not change) (14ms)
+304ms ║║Comparison (decimal) 0.4 is_greater_than (integer) 40 = false (2ms)
+307ms ║║Comparison (decimal) 101.4 is_greater_than (integer) 40 = true (1ms)
+308ms ║║Condition #40 evaluated true (18ms)
+309ms ║║Condition group #10 evaluated true (state did not change) (19ms)
+340ms ║║Comparison (enum) off was (string) off = false (23ms)
+341ms ║║Condition #39 evaluated false (29ms)
+342ms ║║Condition group #30 evaluated false (state did not change) (31ms)
+345ms ║║Cancelling statement #31’s schedules…
+375ms ║║Executed physical command [Water Recirculation].on() (28ms)
+376ms ║║Executed [Water Recirculation].on (30ms)
+381ms ║║Calculating (decimal) 2.5 * (decimal) 60.0 >> (decimal) 150.0
+384ms ║║Executed virtual command [Water Recirculation].wait (1ms)
+385ms ║║Requesting a wake up for Fri, Feb 9 2018 @ 10:45:08 AM MST (in 150.0s)
+392ms ║╚Execution stage complete. (171ms)
+394ms ║Setting up scheduled job for Fri, Feb 9 2018 @ 10:45:08 AM MST (in 149.993s), with 1 more job pending
+404ms ╚Event processed successfully (404ms)

At 10:55:07, that sequence is different from previous sequences when the pump was to be turned off. It looks like rather than just executing just the Turn Off command, that the whole piston was reevaluated when it should not have been.

[TonyK1321]

I restructured the piston to hopefully make it more readable. I was also hoping that by resturcturing it that I would stop occasionally failing, but the fails are still happening. Here is the revised piston, and the logs that show it working OK and when it fails.

2/11/2018, 8:41:31 AM +361ms
+0ms ╔Received event [Home].time = 1518363692473 with a delay of -1113ms
+232ms ║RunTime Analysis CS > 15ms > PS > 82ms > PE > 135ms > CE
+235ms ║Runtime (43999 bytes) successfully initialized in 82ms (v0.2.102.20180116) (234ms)
+237ms ║╔Execution stage started
+294ms ║║Comparison (enum) on was (string) off = false (28ms)
+295ms ║║Condition #7 evaluated false (36ms)
+297ms ║║Condition group #2 evaluated false (state did not change) (38ms)
+304ms ║╚Execution stage complete. (68ms)
+306ms ║Setting up scheduled job for Sun, Feb 11 2018 @ 8:51:32 AM MST (in 600.807s)
+314ms ╚Event processed successfully (313ms)
2/11/2018, 8:34:01 AM +134ms
+1ms ╔Received event [Home].time = 1518363242851 with a delay of -1717ms
+412ms ║RunTime Analysis CS > 171ms > PS > 92ms > PE > 148ms > CE
+414ms ║Runtime (43999 bytes) successfully initialized in 92ms (v0.2.102.20180116) (412ms)
+415ms ║╔Execution stage started
+458ms ║║Comparison (enum) on was (string) off = false (22ms)
+459ms ║║Cancelling condition #7’s schedules…
+460ms ║║Condition #7 evaluated false (33ms)
+461ms ║║Cancelling condition #2’s schedules…
+462ms ║║Condition group #2 evaluated false (state changed) (35ms)
+466ms ║╚Execution stage complete. (51ms)
+468ms ║Setting up scheduled job for Sun, Feb 11 2018 @ 8:41:32 AM MST (in 450.872s)
+493ms ╚Event processed successfully (493ms)
2/11/2018, 8:31:32 AM +337ms
+0ms ╔Received event [Home].time = 1518363092473 with a delay of -137ms
+230ms ║RunTime Analysis CS > 20ms > PS > 85ms > PE > 125ms > CE
+232ms ║Runtime (43997 bytes) successfully initialized in 85ms (v0.2.102.20180116) (231ms)
+234ms ║╔Execution stage started
+273ms ║║Comparison (enum) off was (string) off = true (22ms)
+274ms ║║Condition #7 evaluated true (30ms)
+292ms ║║Comparison (decimal) 0.4 is_greater_than (integer) 40 = false (2ms)
+294ms ║║Comparison (decimal) 0.1 is_greater_than (integer) 40 = false (1ms)
+296ms ║║Comparison (decimal) 0.3 is_greater_than (integer) 40 = false (1ms)
+298ms ║║Condition #28 evaluated false (22ms)
+337ms ║║Comparison (decimal) 0.4 was_less_than (integer) 20 = false (26ms)
+358ms ║║Comparison (decimal) 0.1 was_less_than (integer) 20 = false (19ms)
+379ms ║║Comparison (decimal) 0.3 was_less_than (integer) 20 = false (20ms)
+380ms ║║Condition #29 evaluated false (81ms)
+436ms ║║Comparison (enum) inactive changed = true (31ms)
+437ms ║║Condition #30 evaluated true (56ms)
+438ms ║║Condition group #27 evaluated true (state did not change) (163ms)
+439ms ║║Condition group #2 evaluated true (state did not change) (195ms)
+469ms ║║Comparison (enum) off was (string) off = false (23ms)
+471ms ║║Condition #25 evaluated false (30ms)
+480ms ║║Comparison (time) 30692809 is_between (time) 61200000 … (time) 61800000 = false (6ms)
+482ms ║║Condition #26 evaluated false (11ms)
+483ms ║║Condition group #9 evaluated false (state did not change) (41ms)
+485ms ║║Cancelling statement #21’s schedules…
+504ms ║║Executed physical command [Water Recirculation].on() (17ms)
+505ms ║║Executed [Water Recirculation].on (19ms)
+509ms ║║Calculating (decimal) 2.5 * (decimal) 60.0 >> (decimal) 150.0
+512ms ║║Executed virtual command [Water Recirculation].wait (1ms)
+513ms ║║Requesting a wake up for Sun, Feb 11 2018 @ 8:34:02 AM MST (in 150.0s)
+519ms ║╚Execution stage complete. (286ms)
+521ms ║Setting up scheduled job for Sun, Feb 11 2018 @ 8:34:02 AM MST (in 149.994s), with 1 more job pending
+529ms ╚Event processed successfully (529ms)
2/11/2018, 8:24:01 AM +150ms
+0ms ╔Received event [Home].time = 1518362642190 with a delay of -1041ms
+256ms ║RunTime Analysis CS > 17ms > PS > 110ms > PE > 129ms > CE
+258ms ║Runtime (44000 bytes) successfully initialized in 110ms (v0.2.102.20180116) (257ms)
+259ms ║╔Execution stage started
+300ms ║║Executed physical command [Water Recirculation].off() (18ms)
+301ms ║║Executed [Water Recirculation].off (20ms)
+305ms ║╚Execution stage complete. (46ms)
+307ms ║Setting up scheduled job for Sun, Feb 11 2018 @ 8:31:32 AM MST (in 451.017s)
+315ms ╚Event processed successfully (315ms)

Outlet 6 is the Water Recirculation switch. At 8:24 it shut-off as it was supposed to. At 8:31 it turned on OK. At 8:34, it was supposed to shut-off like at 8:24 but it did not. This is the failure. The pump kept running, so at 8:41, nothing happened because the pump was not off for 5 min. What would keep the switch from shutting off only once in a while but otherwise works like it is supposed to?

[TonyK1321]

I guess the question is, is this a failure of the Z-Wave communication protocol, the ST hub, or WebCore? What can I do to make this more robust? I’m thinking of a test after the Off command that if it is not off, then try to off it again. Anything else I could try?

[TonyK1321]

Here’s an update. I made a change to the piston to add a 10 sec delay after the turn-off, then check if it is off, and if not, then text me. Well, in the 4 days that I’ve been running this, I have had no text messages, which means the piston has not failed. Whereas without the new delay, it was failing once a day. So I’m going to experiment by keeping in the 10 sec delay but taking out the following If statements. Then if OK after a few days, then take out the delay and see if it still fails. Stay tuned.

[TonyK1321]

Well, that piston has been working fine for about 2 wks. In that time, WebCore got updated, so maybe that was part of the success. So much so that I was thinking of going for the gold and eliminating the 10 delay, but today i happened on my PC and found that that the time had failed. Here are the logs:

3/5/2018, 5:02:11 PM +374ms
+1ms ╔Received event [Home].time = 1520294531517 with a delay of -143ms
+271ms ║RunTime Analysis CS > 15ms > PS > 134ms > PE > 122ms > CE
+274ms ║Runtime (44815 bytes) successfully initialized in 134ms (v0.3.000.20180224) (273ms)
+275ms ║╔Execution stage started
+336ms ║║Comparison (enum) on was (string) off = false (40ms)
+337ms ║║Condition #7 evaluated false (50ms)
+338ms ║║Condition group #2 evaluated false (state did not change) (51ms)
+342ms ║╚Execution stage complete. (66ms)
+343ms ║Setting up scheduled job for Mon, Mar 5 2018 @ 5:12:11 PM MST (in 599.801s)
+353ms ╚Event processed successfully (353ms)
3/5/2018, 4:54:40 PM +409ms
+0ms ╔Received event [Home].time = 1520294081329 with a delay of -920ms
+438ms ║RunTime Analysis CS > 18ms > PS > 91ms > PE > 329ms > CE
+442ms ║Runtime (44812 bytes) successfully initialized in 91ms (v0.3.000.20180224) (440ms)
+443ms ║╔Execution stage started
+886ms ║║Comparison (enum) on was (string) off = false (419ms)
+888ms ║║Cancelling condition #7’s schedules…
+889ms ║║Condition #7 evaluated false (430ms)
+890ms ║║Cancelling condition #2’s schedules…
+891ms ║║Condition group #2 evaluated false (state changed) (432ms)
+895ms ║╚Execution stage complete. (452ms)
+897ms ║Setting up scheduled job for Mon, Mar 5 2018 @ 5:02:11 PM MST (in 450.212s)
+906ms ╚Event processed successfully (906ms)
3/5/2018, 4:52:10 PM +427ms
+1ms ╔Received event [Home].time = 1520293931517 with a delay of -1090ms
+278ms ║RunTime Analysis CS > 19ms > PS > 119ms > PE > 139ms > CE
+282ms ║Runtime (44815 bytes) successfully initialized in 119ms (v0.3.000.20180224) (279ms)
+283ms ║╔Execution stage started
+339ms ║║Duration 449038ms for is >= 300000ms threshold = true
+340ms ║║Comparison (enum) off was (string) off = true (33ms)
+342ms ║║Condition #7 evaluated true (43ms)
+368ms ║║Comparison (decimal) 0.4 is_greater_than (integer) 40 = false (4ms)
+372ms ║║Comparison (decimal) 0.1 is_greater_than (integer) 40 = false (2ms)
+376ms ║║Comparison (decimal) 0.3 is_greater_than (integer) 40 = false (3ms)
+378ms ║║Condition #28 evaluated false (34ms)
+427ms ║║Duration 13434694ms for was_less_than < 900000ms threshold = false
+428ms ║║Comparison (decimal) 0.4 was_less_than (integer) 20 = false (34ms)
+458ms ║║Duration 3822159ms for was_less_than < 900000ms threshold = false
+459ms ║║Comparison (decimal) 0.1 was_less_than (integer) 20 = false (30ms)
+490ms ║║Duration 15203664ms for was_less_than < 900000ms threshold = false
+491ms ║║Comparison (decimal) 0.3 was_less_than (integer) 20 = false (31ms)
+493ms ║║Condition #29 evaluated false (113ms)
+549ms ║║Comparison (enum) inactive changed = false (32ms)
+786ms ║║Comparison (enum) inactive changed = true (236ms)
+789ms ║║Condition #30 evaluated true (295ms)
+791ms ║║Condition group #27 evaluated true (state did not change) (447ms)
+792ms ║║Condition group #2 evaluated true (state did not change) (494ms)
+836ms ║║Duration 449532ms for is >= 1800000ms threshold = false
+837ms ║║Comparison (enum) off was (string) off = false (33ms)
+838ms ║║Condition #25 evaluated false (43ms)
+851ms ║║Comparison (time) 60731267 is_between (time) 61200000 … (time) 61800000 = false (9ms)
+853ms ║║Condition #26 evaluated false (14ms)
+854ms ║║Condition group #9 evaluated false (state did not change) (60ms)
+857ms ║║Cancelling statement #21’s schedules…
+886ms ║║Executed physical command [Water Recirculation].on() (25ms)
+887ms ║║Executed [Water Recirculation].on (28ms)
+895ms ║║Calculating (decimal) 2.5 * (decimal) 60.0 >> (decimal) 150.0
+899ms ║║Executed virtual command [Water Recirculation].wait (1ms)
+901ms ║║Requesting a wake up for Mon, Mar 5 2018 @ 4:54:41 PM MST (in 150.0s)
+909ms ║╚Execution stage complete. (625ms)
+911ms ║Setting up scheduled job for Mon, Mar 5 2018 @ 4:54:41 PM MST (in 149.992s), with 1 more job pending
+920ms ╚Event processed successfully (919ms)
3/5/2018, 4:44:50 PM +370ms
+0ms ╔Received event [Home].time = 1520293491716 with a delay of -1347ms
+253ms ║RunTime Analysis CS > 17ms > PS > 98ms > PE > 138ms > CE
+256ms ║Runtime (44813 bytes) successfully initialized in 98ms (v0.3.000.20180224) (254ms)
+257ms ║╔Execution stage started
+284ms ║╚Execution stage complete. (27ms)
+285ms ║Setting up scheduled job for Mon, Mar 5 2018 @ 4:52:11 PM MST (in 440.862s)
+294ms ╚Event processed successfully (294ms)
3/5/2018, 4:44:41 PM +400ms
+0ms ╔Received event [Home].time = 1520293482935 with a delay of -1536ms
+262ms ║RunTime Analysis CS > 18ms > PS > 115ms > PE > 129ms > CE
+265ms ║Runtime (44815 bytes) successfully initialized in 115ms (v0.3.000.20180224) (263ms)
+266ms ║╔Execution stage started
+309ms ║║Executed physical command [Water Recirculation].off() (17ms)
+309ms ║║Executed [Water Recirculation].off (18ms)
+314ms ║║Executed virtual command [Water Recirculation].wait (0ms)
+315ms ║║Requesting a wake up for Mon, Mar 5 2018 @ 4:44:51 PM MST (in 10.0s)
+327ms ║╚Execution stage complete. (61ms)
+329ms ║Setting up scheduled job for Mon, Mar 5 2018 @ 4:44:51 PM MST (in 9.988s), with 1 more job pending
+337ms ╚Event processed successfully (337ms)
3/5/2018, 4:42:11 PM +489ms
+1ms ╔Received event [Home].time = 1520293331517 with a delay of -28ms
+377ms ║RunTime Analysis CS > 19ms > PS > 191ms > PE > 166ms > CE
+379ms ║Runtime (44813 bytes) successfully initialized in 191ms (v0.3.000.20180224) (377ms)
+381ms ║╔Execution stage started
+648ms ║║Duration 451869ms for is >= 300000ms threshold = true
+649ms ║║Comparison (enum) off was (string) off = true (247ms)
+651ms ║║Condition #7 evaluated true (257ms)
+674ms ║║Comparison (decimal) 0.4 is_greater_than (integer) 40 = false (2ms)
+678ms ║║Comparison (decimal) 0.1 is_greater_than (integer) 40 = false (3ms)
+682ms ║║Comparison (decimal) 0.3 is_greater_than (integer) 40 = false (3ms)
+685ms ║║Condition #28 evaluated false (32ms)
+958ms ║║Duration 12836284ms for was_less_than < 900000ms threshold = false
+959ms ║║Comparison (decimal) 0.4 was_less_than (integer) 20 = false (247ms)
+1219ms ║║Duration 3223983ms for was_less_than < 900000ms threshold = false
+1220ms ║║Comparison (decimal) 0.1 was_less_than (integer) 20 = false (260ms)
+1251ms ║║Duration 14605487ms for was_less_than < 900000ms threshold = false
+1251ms ║║Comparison (decimal) 0.3 was_less_than (integer) 20 = false (30ms)
+1253ms ║║Condition #29 evaluated false (568ms)
+1328ms ║║Comparison (enum) inactive changed = false (53ms)
+1353ms ║║Comparison (enum) inactive changed = true (24ms)
+1355ms ║║Condition #30 evaluated true (101ms)
+1356ms ║║Condition group #27 evaluated true (state did not change) (704ms)
+1357ms ║║Condition group #2 evaluated true (state did not change) (963ms)
+1390ms ║║Duration 452609ms for is >= 1800000ms threshold = false
+1390ms ║║Comparison (enum) off was (string) off = false (25ms)
+1392ms ║║Condition #25 evaluated false (33ms)
+1402ms ║║Comparison (time) 60132882 is_between (time) 61200000 … (time) 61800000 = false (7ms)
+1403ms ║║Condition #26 evaluated false (11ms)
+1404ms ║║Condition group #9 evaluated false (state did not change) (45ms)
+1407ms ║║Cancelling statement #21’s schedules…
+1435ms ║║Executed physical command [Water Recirculation].on() (26ms)
+1436ms ║║Executed [Water Recirculation].on (27ms)
+1441ms ║║Calculating (decimal) 2.5 * (decimal) 60.0 >> (decimal) 150.0
+1444ms ║║Executed virtual command [Water Recirculation].wait (1ms)
+1445ms ║║Requesting a wake up for Mon, Mar 5 2018 @ 4:44:42 PM MST (in 150.0s)
+1451ms ║╚Execution stage complete. (1071ms)
+1453ms ║Setting up scheduled job for Mon, Mar 5 2018 @ 4:44:42 PM MST (in 149.994s), with 1 more job pending
+1463ms ╚Event processed successfully (1463ms)

The bottom logs show how it is working as it should (on at 4:42, off at 4:44, 10 sec delay to 4:44+change). The top 2 show the failure (on at 4:52, no off at 4:54, no 10 sec delay). Then at 5:02, since the sw was on, then it did not turn on. My separate timeout timer fired at 5:12 telling me the sw did not shut off. So, somehow when the 2.5 min timer was to expire, it did not go to the line of execution where it was supposed to go, and hence failed. Here is the piston if you want to follow the logic, but like I said, it’s been solid for 2 wks and just now failed.

Let me know if you want any further info, or if I can help in any way to solve this problem.