TStats getting set to Off during running of LUUP code for no apparent reason

Other Devices & Integrations Climate Control & Temperature Sensors
1

I have an odd scenario with a Vera version 1.7.481 where after running my LUUP code to check the settings on 2 TStats they both get set to Off even if I make no changes (like when everything is within bounds).

In the log output below, my LUUP code spits out messages prefixed with “MVRZ_DEBUG” as it checks things.
The 2 TStats are devices 4 and 25 - I’ve indicated below in the log where the TStats get set to Off along with more info/requests - scroll 3/4 of the way down to the first of 2 “>>>> HERE <<<<” texts to begin with.

08	02/24/15 10:42:57.690	JobHandler_LuaUPnP::HandleActionRequest device: 0 service: urn:micasaverde-com:serviceId:HomeAutomationGateway1 action:  [36;1mRunScene [0m <0x2debc680>
08	02/24/15 10:42:57.690	JobHandler_LuaUPnP::HandleActionRequest argument serviceId=urn:micasaverde-com:serviceId:HomeAutomationGateway1 <0x2debc680>
08	02/24/15 10:42:57.690	JobHandler_LuaUPnP::HandleActionRequest argument action=RunScene <0x2debc680>
08	02/24/15 10:42:57.690	JobHandler_LuaUPnP::HandleActionRequest argument SceneNum=2 <0x2debc680>
08	02/24/15 10:42:57.691	JobHandler_LuaUPnP::HandleActionRequest argument rand=0.8110651592724025 <0x2debc680>
08	02/24/15 10:42:57.691	Scene::RunScene running 2 Check Temperatures Now <0x2debc680>
08	02/24/15 10:42:57.691	JobHandler_LuaUPnP::HandleActionRequest device: 28 service: urn:myvrzone-com:serviceId:CheckTemperatureSettings1 action:  [36;1mCheckTemperatureSettings [0m <0x2debc680>
50	02/24/15 10:42:57.692	luup_log:28: MVRZ_DEBUG:I CheckTemperatureSettings Action <0x2debc680>
50	02/24/15 10:42:57.692	luup_log:28: MVRZ_DEBUG:mvrz_doChecks(), mode=0 <0x2debc680>
50	02/24/15 10:42:57.692	luup_log:28: MVRZ_DEBUG:getMode() <0x2debc680>
50	02/24/15 10:42:57.692	luup_log:28: MVRZ_DEBUG:getSetting(turn-on-before-arrival-mins) <0x2debc680>
50	02/24/15 10:42:57.693	luup_log:28: MVRZ_DEBUG:getSetting(turn-on-before-arrival-mins,120)=120 <0x2debc680>
50	02/24/15 10:42:57.693	luup_log:28: MVRZ_DEBUG:getSetting(turn-off-after-departure-mins) <0x2debc680>
50	02/24/15 10:42:57.693	luup_log:28: MVRZ_DEBUG:getSetting(turn-off-after-departure-mins,0)=0 <0x2debc680>
50	02/24/15 10:42:57.694	luup_log:28: MVRZ_DEBUG:getSetting(skip-unoccupied-gap-days) <0x2debc680>
50	02/24/15 10:42:57.694	luup_log:28: MVRZ_DEBUG:getSetting(skip-unoccupied-gap-days,0)=0 <0x2debc680>
50	02/24/15 10:42:57.695	luup_log:28: MVRZ_DEBUG:settingsTable is nil <0x2debc680>
50	02/24/15 10:42:57.695	luup_log:28: MVRZ_DEBUG:mvrz_setHomeMode(0,0) mvrz_gHomeMode=0 <0x2debc680>
50	02/24/15 10:42:57.695	luup_log:28: MVRZ_DEBUG:saveFile(/www/.mvrz.lastMode.txt, CONTENT LEN=1 ) <0x2debc680>
06	02/24/15 10:42:57.696	Device_Variable::m_szValue_set device: 28 service: urn:upnp-org:serviceId:SwitchPower1 variable:  [35;1mStatus [0m was: 0 now: 0 #hooks: 0 upnp: 0 skip: 0 v:0x9642a8/NONE duplicate:1 <0x2debc680>
50	02/24/15 10:42:57.696	luup_log:28: MVRZ_DEBUG:mvrz_getPeriod() <0x2debc680>
50	02/24/15 10:42:57.696	luup_log:28: MVRZ_DEBUG:mvrz_getPeriod(), gPeriod=0 <0x2debc680>
50	02/24/15 10:42:57.697	luup_log:28: MVRZ_DEBUG:mvrz_getPeriod: UNOCCUPIED - skipping Period settings <0x2debc680>
50	02/24/15 10:42:57.697	luup_log:28: MVRZ_DEBUG:mvrz_check(0), mode=0 <0x2debc680>
50	02/24/15 10:42:57.697	luup_log:28: MVRZ_DEBUG:readFile(/www/.mvrz.lastCheckTimestamp.txt) <0x2debc680>
50	02/24/15 10:42:57.698	luup_log:28: MVRZ_DEBUG:readFile(/www/.mvrz.lastCheckTimestamp.txt, CONTENT LEN=10 ) <0x2debc680>
50	02/24/15 10:42:57.698	luup_log:28: MVRZ_DEBUG:mvrz_check on Thermostat4:: i=1, deviceId=4 <0x2debc680>
50	02/24/15 10:42:57.699	luup_log:28: MVRZ_DEBUG:mvrz_readThermostatHeatPoint(): deviceIndex=1 <0x2debc680>
50	02/24/15 10:42:57.699	luup_log:28: MVRZ_DEBUG:mvrz_readThermostat(4,urn:upnp-org:serviceId:TemperatureSetpoint1_Heat,CurrentSetpoint) <0x2debc680>
50	02/24/15 10:42:57.699	luup_log:28: MVRZ_DEBUG:mvrz_readThermostat() returning 58 <0x2debc680>
50	02/24/15 10:42:57.700	luup_log:28: MVRZ_DEBUG:mvrz_readThermostatCoolPoint(): deviceIndex=1 <0x2debc680>
50	02/24/15 10:42:57.700	luup_log:28: MVRZ_DEBUG:mvrz_readThermostat(4,urn:upnp-org:serviceId:TemperatureSetpoint1_Cool,CurrentSetpoint) <0x2debc680>
50	02/24/15 10:42:57.700	luup_log:28: MVRZ_DEBUG:mvrz_readThermostat() returning 84 <0x2debc680>
50	02/24/15 10:42:57.701	luup_log:28: MVRZ_DEBUG:mvrz_readThermostatTemperature(): deviceIndex=1 <0x2debc680>
50	02/24/15 10:42:57.701	luup_log:28: MVRZ_DEBUG:mvrz_readThermostat(4,urn:upnp-org:serviceId:TemperatureSensor1,CurrentTemperature) <0x2debc680>
50	02/24/15 10:42:57.701	luup_log:28: MVRZ_DEBUG:mvrz_readThermostat() returning 58 <0x2debc680>
50	02/24/15 10:42:57.702	luup_log:28: MVRZ_DEBUG:mvrz_readThermostatMode(): deviceIndex=1 <0x2debc680>
50	02/24/15 10:42:57.702	luup_log:28: MVRZ_DEBUG:mvrz_readThermostat(4,urn:upnp-org:serviceId:HVAC_UserOperatingMode1,ModeStatus) <0x2debc680>
50	02/24/15 10:42:57.702	luup_log:28: MVRZ_DEBUG:mvrz_readThermostat() returning HeatOn <0x2debc680>
50	02/24/15 10:42:57.702	luup_log:28: MVRZ_DEBUG:Doing extreme temp bug workarounds <0x2debc680>
50	02/24/15 10:42:57.703	luup_log:28: MVRZ_DEBUG:Checking for setpoint changes <0x2debc680>
50	02/24/15 10:42:57.704	luup_log:28: MVRZ_DEBUG:CheckInit Current::[
1=[
  2=[0]
  3=[HeatOn]
  4=[58]
  5=[84]
  6=[58]
  7=[0]
  8=[0]]
2=[
  2=[0]
  3=[HeatOn]
  4=[58]
  5=[78]
  6=[59]
  7=[0]
  8=[0]]] <0x2debc680>
50	02/24/15 10:42:57.705	luup_log:28: MVRZ_DEBUG:*********** Delaying Heat Check by 2 at 1424796177 <0x2debc680>
50	02/24/15 10:42:57.706	luup_log:28: MVRZ_DEBUG:*********** Delaying Cool Check by 4 at 1424796177 <0x2debc680>
50	02/24/15 10:42:57.706	luup_log:28: MVRZ_DEBUG:mvrz_switchStateCheck(4,0) <0x2debc680>
50	02/24/15 10:42:57.707	luup_log:28: MVRZ_DEBUG:mvrz_getThermostatDeviceSetting(1,0,switchToCool) <0x2debc680>
50	02/24/15 10:42:57.707	luup_log:28: MVRZ_DEBUG:mvrz_getThermostatDeviceSetting() returning 5 <0x2debc680>
50	02/24/15 10:42:57.707	luup_log:28: MVRZ_DEBUG:mvrz_getThermostatDeviceSetting(1,0,switchToHeat) <0x2debc680>
50	02/24/15 10:42:57.707	luup_log:28: MVRZ_DEBUG:mvrz_getThermostatDeviceSetting() returning 5 <0x2debc680>
50	02/24/15 10:42:57.708	luup_log:28: MVRZ_DEBUG:mvrz_switchStateCheck() deviceId=4, avg=71, remaining at existing setting of HeatOn <0x2debc680>
50	02/24/15 10:42:57.708	luup_log:28: MVRZ_DEBUG:mvrz_switchStateCheck() deviceId=4, mvrz_gHomeMode=0, luup_currentMode=HeatOn, new lmode=HeatOn, luup_currentTemp=58, switchToCoolTemp=89, switchToHeatTemp=53 <0x2debc680>
50	02/24/15 10:42:57.709	luup_log:28: MVRZ_DEBUG:mvrz_switchStateCheck() - Cool/Heat check OK, mode stays the same at HeatOn <0x2debc680>
50	02/24/15 10:42:57.709	luup_log:28: MVRZ_DEBUG:mvrz_switchStateCheck - DONE <0x2debc680>
50	02/24/15 10:42:57.710	luup_log:28: MVRZ_DEBUG:mvrz_check on Thermostat25:: i=2, deviceId=25 <0x2debc680>
50	02/24/15 10:42:57.710	luup_log:28: MVRZ_DEBUG:mvrz_readThermostatHeatPoint(): deviceIndex=2 <0x2debc680>
50	02/24/15 10:42:57.710	luup_log:28: MVRZ_DEBUG:mvrz_readThermostat(25,urn:upnp-org:serviceId:TemperatureSetpoint1_Heat,CurrentSetpoint) <0x2debc680>
50	02/24/15 10:42:57.711	luup_log:28: MVRZ_DEBUG:mvrz_readThermostat() returning 58 <0x2debc680>
50	02/24/15 10:42:57.711	luup_log:28: MVRZ_DEBUG:mvrz_readThermostatCoolPoint(): deviceIndex=2 <0x2debc680>
50	02/24/15 10:42:57.711	luup_log:28: MVRZ_DEBUG:mvrz_readThermostat(25,urn:upnp-org:serviceId:TemperatureSetpoint1_Cool,CurrentSetpoint) <0x2debc680>
50	02/24/15 10:42:57.712	luup_log:28: MVRZ_DEBUG:mvrz_readThermostat() returning 78 <0x2debc680>
50	02/24/15 10:42:57.712	luup_log:28: MVRZ_DEBUG:mvrz_readThermostatTemperature(): deviceIndex=2 <0x2debc680>
50	02/24/15 10:42:57.712	luup_log:28: MVRZ_DEBUG:mvrz_readThermostat(25,urn:upnp-org:serviceId:TemperatureSensor1,CurrentTemperature) <0x2debc680>
50	02/24/15 10:42:57.712	luup_log:28: MVRZ_DEBUG:mvrz_readThermostat() returning 59 <0x2debc680>
50	02/24/15 10:42:57.713	luup_log:28: MVRZ_DEBUG:mvrz_readThermostatMode(): deviceIndex=2 <0x2debc680>
50	02/24/15 10:42:57.713	luup_log:28: MVRZ_DEBUG:mvrz_readThermostat(25,urn:upnp-org:serviceId:HVAC_UserOperatingMode1,ModeStatus) <0x2debc680>
50	02/24/15 10:42:57.713	luup_log:28: MVRZ_DEBUG:mvrz_readThermostat() returning HeatOn <0x2debc680>
50	02/24/15 10:42:57.714	luup_log:28: MVRZ_DEBUG:Doing extreme temp bug workarounds <0x2debc680>
50	02/24/15 10:42:57.714	luup_log:28: MVRZ_DEBUG:Checking for setpoint changes <0x2debc680>
50	02/24/15 10:42:57.715	luup_log:28: MVRZ_DEBUG:CheckInit Current::[
1=[
  2=[0]
  3=[HeatOn]
  4=[58]
  5=[84]
  6=[58]
  7=[0]
  8=[0]]
2=[
  2=[0]
  3=[HeatOn]
  4=[58]
  5=[78]
  6=[59]
  7=[0]
  8=[0]]] <0x2debc680>
50	02/24/15 10:42:57.716	luup_log:28: MVRZ_DEBUG:*********** Delaying Heat Check by 8 at 1424796177 <0x2debc680>
50	02/24/15 10:42:57.717	luup_log:28: MVRZ_DEBUG:*********** Delaying Cool Check by 10 at 1424796177 <0x2debc680>
50	02/24/15 10:42:57.717	luup_log:28: MVRZ_DEBUG:mvrz_switchStateCheck(25,0) <0x2debc680>
50	02/24/15 10:42:57.718	luup_log:28: MVRZ_DEBUG:mvrz_getThermostatDeviceSetting(2,0,switchToCool) <0x2debc680>
50	02/24/15 10:42:57.718	luup_log:28: MVRZ_DEBUG:mvrz_getThermostatDeviceSetting() returning 5 <0x2debc680>
50	02/24/15 10:42:57.718	luup_log:28: MVRZ_DEBUG:mvrz_getThermostatDeviceSetting(2,0,switchToHeat) <0x2debc680>
50	02/24/15 10:42:57.719	luup_log:28: MVRZ_DEBUG:mvrz_getThermostatDeviceSetting() returning 5 <0x2debc680>
50	02/24/15 10:42:57.719	luup_log:28: MVRZ_DEBUG:mvrz_switchStateCheck() deviceId=25, avg=68, remaining at existing setting of HeatOn <0x2debc680>
50	02/24/15 10:42:57.720	luup_log:28: MVRZ_DEBUG:mvrz_switchStateCheck() deviceId=25, mvrz_gHomeMode=0, luup_currentMode=HeatOn, new lmode=HeatOn, luup_currentTemp=59, switchToCoolTemp=83, switchToHeatTemp=53 <0x2debc680>
50	02/24/15 10:42:57.720	luup_log:28: MVRZ_DEBUG:mvrz_switchStateCheck() - Cool/Heat check OK, mode stays the same at HeatOn <0x2debc680>
50	02/24/15 10:42:57.720	luup_log:28: MVRZ_DEBUG:mvrz_switchStateCheck - DONE <0x2debc680>
50	02/24/15 10:42:57.721	luup_log:28: MVRZ_DEBUG:saveFile(/www/.mvrz.lastCheckTimestamp.txt, CONTENT LEN=10 ) <0x2debc680>

>>>> HERE <<<<
>>>> The above is the last line of the code that gets run in this sequence - but there are delayed function calls pending.
>>>> The output at timestamp 10:42:57.720 shows the luup_currentMode (what was read from the TStat) to be HeatOn - which was correct.
>>>> I can't work out where the next lines in the log filecome from. It only happens if my code gets run but I make no changes to any TStat settings - all I do is read the TStat status earlier on.
>>>> Nothing was done manually at this time via the interface.
>>>> Plugins in use are: ERGY and HouseModes
>>>> TStats are MVC ZTS-110. 
>>>> The same LUUP code in UI5 systems with other TStats brands do not have this issue. This is the first time I have used UI7 and these TStats.
>>>> How do I figure out what instigated this change for sure - I have to think it was something that I did in my code that triggered it but the code does not seem faulty. 
>>>> Is there any known issue with any of the functions called in the saveFile() function (shown below) that could explain this:

	function saveFile(fileName, content, filemode)
		mvrz_debug ("saveFile("..fileName..", CONTENT LEN=" .. string.len(content) .. " )")
		if filemode == nil then filemode = "w" end
		--mvrz_debug ("writing content: "..content)
		local file = io.open(fileName, filemode)
		if file == nil then 
      			--mvrz_debug ("File not present, creating...")
			os.execute("touch " .. fileName) 
            		file = io.open(fileName, filemode)
        	else
      			--mvrz_debug ("File already present")
		end
      
		if file ~= nil then 
      		  	--mvrz_debug ("Writing to file")
                  	file:write(content)
                  	io.close(file)
        	else
            		--mvrz_debug ("Failed to open file for writing")
        	end
	end

08	02/24/15 10:42:57.728	JobHandler_LuaUPnP::HandleActionRequest device: 25 service: urn:upnp-org:serviceId:HVAC_UserOperatingMode1 action:  [36;1mSetModeTarget [0m <0x2debc680>
08	02/24/15 10:42:57.729	JobHandler_LuaUPnP::HandleActionRequest argument NewModeTarget=Off <0x2debc680>
06	02/24/15 10:42:57.729	Device_Variable::m_szValue_set device: 25 service: urn:upnp-org:serviceId:HVAC_UserOperatingMode1 variable:  [35;1mModeTarget [0m was: HeatOn now: Off #hooks: 0 upnp: 0 skip: 0 v:0x9361e8/NONE duplicate:0 <0x2debc680>
08	02/24/15 10:42:57.732	JobHandler_LuaUPnP::HandleActionRequest device: 4 service: urn:upnp-org:serviceId:HVAC_UserOperatingMode1 action:  [36;1mSetModeTarget [0m <0x2debc680>
08	02/24/15 10:42:57.732	JobHandler_LuaUPnP::HandleActionRequest argument NewModeTarget=Off <0x2debc680>
06	02/24/15 10:42:57.732	Device_Variable::m_szValue_set device: 4 service: urn:upnp-org:serviceId:HVAC_UserOperatingMode1 variable:  [35;1mModeTarget [0m was: HeatOn now: Off #hooks: 0 upnp: 0 skip: 0 v:0x9361e8/NONE duplicate:0 <0x2debc680>
04	02/24/15 10:42:57.742	<Job ID="9" Name="pollnode #3 7 cmds" Device="25" Created="2015-02-24 10:42:57" Started="2015-02-24 10:42:57" Completed="2015-02-24 10:42:57" Duration="0.640944000" Runtime="0.639954000" Status="Aborted" LastNote="" Node="3" NodeType="ZWaveThermostat" NodeDescription="Thermostat Main"/> <0x2b2bc680>
06	02/24/15 10:42:57.839	Device_Variable::m_szValue_set device: 25 service: urn:upnp-org:serviceId:HVAC_UserOperatingMode1 variable:  [35;1mModeStatus [0m was: HeatOn now: Off #hooks: 0 upnp: 0 skip: 0 v:0x9363a8/NONE duplicate:0 <0x2b2bc680>
04	02/24/15 10:42:57.840	<Job ID="10" Name="Off node 3" Device="25" Created="2015-02-24 10:42:57" Started="2015-02-24 10:42:57" Completed="2015-02-24 10:42:57" Duration="0.109539000" Runtime="0.96775000" Status="Successful" LastNote="SUCCESS! Transmit was OK" Node="3" NodeType="ZWaveThermostat" NodeDescription="Thermostat Main"/> <0x2b2bc680>

>>>> HERE <<<<
>>>> This is where the earliest delayed function call starts


50	02/24/15 10:42:59.101	luup_log:28: MVRZ_DEBUG:stringToArgs(1,0, DELAYED_BY_2_CALLED_1424796177) = [
1=[1]
2=[0]
3=[DELAYED_BY_2_CALLED_1424796177]] <0x2c4bc680>
50	02/24/15 10:42:59.102	luup_log:28: MVRZ_DEBUG:mvrz_heatCheck(4,0) <0x2c4bc680>
.
.
.

Any suggestions for what to try are welcomed.

Thanks,
Neil

2

Hi Neil

Did you get a resolution for this as I think I am getting a similar problem.

I have two Secure 302 boiler controllers that require a keep alive at least every hour, so I read the ModeTarget value and send it back to the device every half hour. It appears that the act of reading the value resets the ModeStatus so I end up with ModeTarget = HeatOn and ModeStatus = Off which switches the boiler off.

Ian

3

I did not get a resolution. I ended up not using UI7.

Neil