Piston 'wait 10 minutes' schedules, but when it wakes up nothing happens

jimbonyc · 2018-11-09 22:57:21 UTC

1) Give a description of the problem
I have a mini-split system that does not work with SmartThings so I have a zwave controller unit I use to turn it on and off. The mini-split’s minimum temperature is 60º but this is at a house that is unoccupied sometimes and only needs to maintain 45º to prevent pipes from freezing.

2) What is the expected behavior?
The system should detect when any thermostat hits 45º and turn the mini-split on, setting it to 65º and waiting 10 minutes before checking in again.

I do not want it to rapidly cycle the system on and off so I have created two global variables to use as semaphores - IsMiniSplitHeatTurningOn and IsMiniSplitHeatTurningOff. The reason I did this is because I noticed that if a thermostat subscription reported in in the middle of turning on the system it would often cancel it out halfway and leave the system in a bad state. This way I can prevent the piston from running if another is in mid-execution.

I would like the TurningOn state to remain for at least 10 minutes to give the system time to warm up and heat the house. The system blows pretty close to one thermostat also so it’s possible that it would heat that one up erroneously. This gives it time to sufficiently heat up the whole house before turning off again.

Note: the short delays in between the mode switches are just to give the IR time to travel and the mini-split unit to respond. They work fine. I turn the system off in the heating step just to ensure if someone has manually messed with it (say someone who went to check on the house) that it gets reset to a known state before continuing.

3) What is happening/not happening?
In the screenshot you can see the Wait 10 minutes step. The full logs say this is scheduled however there it no countdown timer in webcore’s dashboard (I have other things like random light pistons which I can see the timers counting down as it’s waiting to trigger over and over). Even without this timer you can see in the log that it does eventually fire, but it doesn’t reset the variable after the wait. It seems to just fire and die without doing anything. I have to manually set IsMiniSplitHeatTurningOn to false again for it to finally check if the house is warm enough (above 50º at any thermostat) and turn it off.

4) Post a Green Snapshot of the piston

5) Attach any logs (From ST IDE and by turning logging level to Full)

11/9/2018, 5:45:06 PM +274ms
+0ms	╔Received event [Camp Mooney].time = 1541803503546 with a delay of 2727ms
+792ms	║RunTime Analysis CS > 338ms > PS > 367ms > PE > 87ms > CE
+795ms	║Runtime (44844 bytes) successfully initialized in 367ms (v0.3.108.20180906) (793ms)
+796ms	║╔Execution stage started
+797ms	║╚Execution stage complete. (2ms)
+799ms	╚Event processed successfully (798ms)

11/9/2018, 5:35:02 PM +725ms
+1ms	╔Received event [Camp Mooney].time = 1541802902260 with a delay of 465ms
+600ms	║RunTime Analysis CS > 243ms > PS > 272ms > PE > 84ms > CE
+603ms	║Runtime (44839 bytes) successfully initialized in 272ms (v0.3.108.20180906) (601ms)
+605ms	║╔Execution stage started
+690ms	║║Executed virtual command [Temp - LG Mini Split].iftttMaker (59ms)
+800ms	║║Executed physical command [Temp - LG Mini Split].setHeatingSetpoint([65.0]) (106ms)
+803ms	║║Executed [Temp - LG Mini Split].setHeatingSetpoint (109ms)
+811ms	║║Skipped execution of physical command [Temp - LG Mini Split].fanAuto([]) because it would make no change to the device. (3ms)
+812ms	║║Executed [Temp - LG Mini Split].fanAuto (7ms)
+818ms	║║Executed virtual command [Temp - LG Mini Split].wait (1ms)
+820ms	║║Requesting a wake up for Fri, Nov 9 2018 @ 5:45:03 PM EST (in 600.0s)
+828ms	║╚Execution stage complete. (224ms)
+830ms	║Setting up scheduled job for Fri, Nov 9 2018 @ 5:45:03 PM EST (in 599.991s)
+839ms	╚Event processed successfully (838ms)

11/9/2018, 5:34:55 PM +87ms
+1ms	╔Received event [Camp Mooney].time = 1541802896481 with a delay of -1395ms
+462ms	║RunTime Analysis CS > 46ms > PS > 342ms > PE > 75ms > CE
+466ms	║Runtime (44840 bytes) successfully initialized in 342ms (v0.3.108.20180906) (463ms)
+468ms	║╔Execution stage started
+2159ms	║║Executed physical command [Temp - LG Mini Split].setThermostatMode([heat]) (1664ms)
+2161ms	║║Executed [Temp - LG Mini Split].setThermostatMode (1667ms)
+2169ms	║║Executed virtual command [Temp - LG Mini Split].wait (1ms)
+2171ms	║║Requesting a wake up for Fri, Nov 9 2018 @ 5:35:02 PM EST (in 5.0s)
+2180ms	║╚Execution stage complete. (1713ms)
+2184ms	║Setting up scheduled job for Fri, Nov 9 2018 @ 5:35:02 PM EST (in 4.991s)
+2192ms	╚Event processed successfully (2192ms)

11/9/2018, 5:34:45 PM +936ms
+2ms	╔Received event [Thermostat - 1st Bedroom].temperature = 45.0 with a delay of 98ms
+152ms	║RunTime Analysis CS > 21ms > PS > 69ms > PE > 62ms > CE
+155ms	║Runtime (44852 bytes) successfully initialized in 69ms (v0.3.108.20180906) (152ms)
+157ms	║╔Execution stage started
+168ms	║║Comparison (string) away is (string) away = true (1ms)
+170ms	║║Condition #44 evaluated true (8ms)
+175ms	║║Comparison (dynamic) false is (boolean) false = true (2ms)
+177ms	║║Condition #45 evaluated true (6ms)
+182ms	║║Comparison (dynamic) false is (boolean) false = true (2ms)
+184ms	║║Condition #46 evaluated true (6ms)
+185ms	║║Condition group #null evaluated true (state did not change) (24ms)
+484ms	║║Comparison (decimal) 48.0 is_less_than_or_equal_to (integer) 45 = false (2ms)
+488ms	║║Comparison (decimal) 46.0 is_less_than_or_equal_to (integer) 45 = false (2ms)
+491ms	║║Comparison (decimal) 45.0 is_less_than_or_equal_to (integer) 45 = true (2ms)
+495ms	║║Cancelling condition #7's schedules...
+496ms	║║Condition #7 evaluated true (308ms)
+506ms	║║Comparison (enum) off is_not (string) heat = true (3ms)
+508ms	║║Condition #34 evaluated true (11ms)
+510ms	║║Cancelling condition #1's schedules...
+511ms	║║Condition group #1 evaluated true (state changed) (324ms)
+516ms	║║Cancelling statement #3's schedules...
+525ms	║║Executed virtual command [Temp - LG Mini Split].setVariable (2ms)
+534ms	║║Skipped execution of physical command [Temp - LG Mini Split].setThermostatMode([off]) because it would make no change to the device. (2ms)
+535ms	║║Executed [Temp - LG Mini Split].setThermostatMode (6ms)
+541ms	║║Executed virtual command [Temp - LG Mini Split].wait (1ms)
+544ms	║║Requesting a wake up for Fri, Nov 9 2018 @ 5:34:56 PM EST (in 10.0s)
+550ms	║╚Execution stage complete. (394ms)
+553ms	║Setting up scheduled job for Fri, Nov 9 2018 @ 5:34:56 PM EST (in 9.993s)
+562ms	╚Event processed successfully (562ms)

WCmore · 2018-11-10 05:12:09 UTC

I currently don’t have any freetime to dig deeper, but I suspect this is what is happening:

only when variable is false
IF it is cold
    Then set variable to true
    Do stuff
    Wait 10 minutes

After the 10 minutes have passed, the variable is still true, so nothing more can happen.

I think you need to move the "set variable to false" outside of the “Only when” restriction

616fun · 2018-11-10 16:34:58 UTC

I had the same thing happen. I have a garage light and inside lights come on between sunset and sunrise when the garage door opens. I had a wait on the garage lights to turn off because the event (garage door changes to open) became false. The piston would turn the garage lights on but not shut them off. To resolve it I adjusted the statement to fire when the garage door status changed (not firing on open or close disposition). Works like a charm now.

616fun · 2018-11-10 16:36:08 UTC

In an odd parallel the function worked fine to fire when the door opened in Core, but won’t do so in WebCore.

jimbonyc · 2018-11-11 00:50:40 UTC

I have resolved the issue. i moved the wait 10 minutes and the flipping off of the semaphores outside of the two if statements. Now, if either semaphore is on, it will start waiting 10 minutes and then turn it off. Task Cancellation Policy is in effect because if this runs multiple times, multiple 10-minute timers will start, but the first one to flip off the semaphores will effectively cancel all of the other waiting timers.