Why Does this Lock LUUP when on a Schedule?

*** UPDATE 6/24/2014 *****

This has been confirmed as a bug in firmware 1.6.641 and has been forwarded to the software developers for a future fix.

“It seems there is an issue in UI6 which causes LuaUPnP to crash when a Lua scene is active with a recurrent schedule (e.g. every X minutes).”


Wrote a very simple script that compares the temperature on the first floor to that of the second floor and kicks on some low powered in-line duct fans if the second floor is hotter than the first. Works great to balance temperatures on both floors.

The problem I’m having is that if I schedule this script to run every 15 minutes it causes LUUP (and the Vera) to lock up, but only after it’s been running for many hours. I’ve been doing a Vera Reset and Restore from backup to get it back to functioning.

Anyone know why this would lock LUUP up when put on a 15 minute schedule?

local tup = luup.variable_get("urn:upnp-org:serviceId:TemperatureSensor1","CurrentTemperature", 58) local tdn = luup.variable_get("urn:upnp-org:serviceId:TemperatureSensor1","CurrentTemperature", 73)

tup = tonumber(tup)
tdn = tonumber(tdn)

if (tup > tdn) then
luup.call_action(“urn:upnp-org:serviceId:SwitchPower1”,“SetTarget”,{ newTargetValue=“1” },76)
luup.call_action(“urn:upnp-org:serviceId:SwitchPower1”,“SetTarget”,{ newTargetValue=“1” },77)
else
luup.call_action(“urn:upnp-org:serviceId:SwitchPower1”,“SetTarget”,{ newTargetValue=“0” },76)
luup.call_action(“urn:upnp-org:serviceId:SwitchPower1”,“SetTarget”,{ newTargetValue=“0” },77)
end

return true

Device 58 is an Everspring ST814 Temperature/Humidity Detector.
Device 73 is an EcoBee Thermostat connected through the plug-in.
Devices 76 and 77 are Aeon Labs DSC06106-ZWUS Smart Energy Switches.

The fact it takes hours to happen makes me think it’s a resource issue.

[quote=“AEBogdan, post:1, topic:181576”]Wrote a very simple script that compares the temperature on the first floor to that of the second floor and kicks on some low powered in-line duct fans if the second floor is hotter than the first. Works great to balance temperatures on both floors.

The problem I’m having is that if I schedule this script to run every 15 minutes it causes LUUP (and the Vera) to lock up, but only after it’s been running for many hours. I’ve been doing a Vera Reset and Restore from backup to get it back to functioning.

Anyone know why this would lock LUUP up when put on a 15 minute schedule?

local tup = luup.variable_get("urn:upnp-org:serviceId:TemperatureSensor1","CurrentTemperature", 58) local tdn = luup.variable_get("urn:upnp-org:serviceId:TemperatureSensor1","CurrentTemperature", 73)

tup = tonumber(tup)
tdn = tonumber(tdn)

if (tup > tdn) then
luup.call_action(“urn:upnp-org:serviceId:SwitchPower1”,“SetTarget”,{ newTargetValue=“1” },76)
luup.call_action(“urn:upnp-org:serviceId:SwitchPower1”,“SetTarget”,{ newTargetValue=“1” },77)
else
luup.call_action(“urn:upnp-org:serviceId:SwitchPower1”,“SetTarget”,{ newTargetValue=“0” },76)
luup.call_action(“urn:upnp-org:serviceId:SwitchPower1”,“SetTarget”,{ newTargetValue=“0” },77)
end

return true

Device 58 is an Everspring ST814 Temperature/Humidity Detector.
Device 73 is an EcoBee Thermostat connected through the plug-in.
Devices 76 and 77 are Aeon Labs DSC06106-ZWUS Smart Energy Switches.

The fact it takes hours to happen makes me think it’s a resource issue.[/quote]

have you been able to capture the vera log on this restart?

It may be resource limitations but from something else

Here are some log items that stand out.

I see a memory leak listed. How do you know what device is causing it since it appears randomly between various meter readings?

06 06/13/14 10:43:58.690 Device_Variable::m_szValue_set device: 77 service: urn:micasaverde-com:serviceId:EnergyMetering1 variable: KWH was: 0.4710 now: 0.4720 #hooks: 0 upnp: 0 v:0xf4c2e8/NONE duplicate:0 <0x2b521680> 06 06/13/14 10:43:58.691 Device_Variable::m_szValue_set device: 77 service: urn:micasaverde-com:serviceId:EnergyMetering1 variable: KWHReading was: 1402670578 now: 1402670638 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2b521680> 02 06/13/14 10:43:59.010 LOG_CHECK_MEMORY_LEAK pMem start 0x161f000 now 0x17cf000 last 0x179b000 leaked 1769472 <0x2b521680> 06 06/13/14 10:44:00.000 Device_Variable::m_szValue_set device: 65 service: urn:micasaverde-com:serviceId:EnergyMetering1 variable: Watts was: 7 now: 7 #hooks: 0 upnp: 0 v:0xf80298/NONE duplicate:1 <0x2b521680> 06 06/13/14 10:44:00.001 Device_Variable::m_szValue_set device: 65 service: urn:micasaverde-com:serviceId:EnergyMetering1 variable: ActualUsage was: 1 now: 1 #hooks: 0 upnp: 0 v:0xf802d8/NONE duplicate:1 <0x2b521680>
06 06/13/14 10:59:15.240 Device_Variable::m_szValue_set device: 65 service: urn:micasaverde-com:serviceId:EnergyMetering1 variable: Watts was: 9 now: 8 #hooks: 0 upnp: 0 v:0x105abc0/NONE duplicate:0 <0x2ba11680> 06 06/13/14 10:59:15.241 Device_Variable::m_szValue_set device: 65 service: urn:micasaverde-com:serviceId:EnergyMetering1 variable: Log was: 9,3,14,1402671552,1753 now: 8,3,14,1402671555,1756 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2ba11680> 06 06/13/14 10:59:15.241 Device_Variable::m_szValue_set device: 65 service: urn:micasaverde-com:serviceId:EnergyMetering1 variable: ActualUsage was: 1 now: 1 #hooks: 0 upnp: 0 v:0x105ac00/NONE duplicate:1 <0x2ba11680> 02 06/13/14 10:59:16.100 LOG_CHECK_MEMORY_LEAK pMem start 0x17e3000 now 0x180a000 last 0x1808000 leaked 159744 <0x2ba11680> 06 06/13/14 10:59:18.240 Device_Variable::m_szValue_set device: 65 service: urn:micasaverde-com:serviceId:EnergyMetering1 variable: Watts was: 8 now: 9 #hooks: 0 upnp: 0 v:0x105abc0/NONE duplicate:0 <0x2ba11680> 06 06/13/14 10:59:18.241 Device_Variable::m_szValue_set device: 65 service: urn:micasaverde-com:serviceId:EnergyMetering1 variable: Log was: 8,3,14,1402671555,1756 now: 9,3,14,1402671558,1759 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2ba11680> 06 06/13/14 10:59:18.242 Device_Variable::m_szValue_set device: 65 service: urn:micasaverde-com:serviceId:EnergyMetering1 variable: ActualUsage was: 1 now: 1 #hooks: 0 upnp: 0 v:0x105ac00/NONE duplicate:1 <0x2ba11680>
06 06/13/14 10:43:45.000 Device_Variable::m_szValue_set device: 65 service: urn:micasaverde-com:serviceId:EnergyMetering1 variable: Watts was: 9 now: 5 #hooks: 0 upnp: 0 v:0xf80298/NONE duplicate:0 <0x2b521680> 06 06/13/14 10:43:45.001 Device_Variable::m_szValue_set device: 65 service: urn:micasaverde-com:serviceId:EnergyMetering1 variable: Log was: 9,4,14,1402670619,820 now: 5,4,14,1402670624,825 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2b521680> 06 06/13/14 10:43:45.001 Device_Variable::m_szValue_set device: 65 service: urn:micasaverde-com:serviceId:EnergyMetering1 variable: ActualUsage was: 1 now: 1 #hooks: 0 upnp: 0 v:0xf802d8/NONE duplicate:1 <0x2b521680> 02 06/13/14 10:43:46.431 ZWaveSerial::GetFrame 0x2b920f58 timed out now 0 m_listGetFramePending 0 <0x2b921680> 02 06/13/14 10:43:46.431 ZWaveJobHandler::SendDataAbort got m_iFrameID 0 <0x2b921680> 01 06/13/14 10:43:46.432 ZWJob_PollNode::Run job job#40 :pollnode #43 dev:76 (0x15d0f50) N:43 P:100 S:1 ZW_Send_Data to node 43 failed 1 req 0x15d4028/1 abort m_iFrameID 0 <0x2b921680> 02 06/13/14 10:43:46.432 ZWJob_PollNode::PollFailed job job#40 :pollnode #43 dev:76 (0x15d0f50) N:43 P:100 S:1 node 43 battery 0 <0x2b921680> 06 06/13/14 10:43:46.432 Device_Variable::m_szValue_set device: 1 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: LastError was: Poll failed now: Poll failed #hooks: 0 upnp: 0 v:0x11cdba8/NONE duplicate:1 <0x2b921680> 04 06/13/14 10:43:46.433 <0x2b921680> 02 06/13/14 10:43:46.434 JobHandler::PurgeCompletedJobs purge job#40 :pollnode #43 dev:76 (0x15d0f50) N:43 P:100 S:2 pollnode #43 4 cmds status 2 <0x2b921680> 06 06/13/14 10:43:48.222 Device_Variable::m_szValue_set device: 65 service: urn:micasaverde-com:serviceId:EnergyMetering1 variable: Watts was: 5 now: 7 #hooks: 0 upnp: 0 v:0xf80298/NONE duplicate:0 __LEAK__ this:212992 start:2297856 to 0x17cf000 <0x2b521680> 06 06/13/14 10:43:48.223 Device_Variable::m_szValue_set device: 65 service: urn:micasaverde-com:serviceId:EnergyMetering1 variable: Log was: 5,4,14,1402670624,825 now: 7,4,14,1402670628,829 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2b521680> 06 06/13/14 10:43:48.223 Device_Variable::m_szValue_set device: 65 service: urn:micasaverde-com:serviceId:EnergyMetering1 variable: ActualUsage was: 1 now: 1 #hooks: 0 upnp: 0 v:0xf802d8/NONE duplicate:1 <0x2b521680>
06 06/13/14 10:41:38.980 Device_Variable::m_szValue_set device: 65 service: urn:micasaverde-com:serviceId:EnergyMetering1 variable: Watts was: 7 now: 8 #hooks: 0 upnp: 0 v:0xf80298/NONE duplicate:0 <0x2b521680> 06 06/13/14 10:41:38.981 Device_Variable::m_szValue_set device: 65 service: urn:micasaverde-com:serviceId:EnergyMetering1 variable: Log was: 7,4,14,1402670495,696 now: 8,4,14,1402670498,699 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2b521680> 06 06/13/14 10:41:38.981 Device_Variable::m_szValue_set device: 65 service: urn:micasaverde-com:serviceId:EnergyMetering1 variable: ActualUsage was: 1 now: 1 #hooks: 0 upnp: 0 v:0xf802d8/NONE duplicate:1 <0x2b521680> 01 06/13/14 10:41:39.222 luup_log:66: ecobee: Error: nil: no valid JSON value (reached the end) <0x2d121680> 06 06/13/14 10:41:39.223 Device_Variable::m_szValue_set device: 66 service: urn:ecobee-com:serviceId:Ecobee1 variable: status was: 1 now: 0 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2d121680> 01 06/13/14 10:41:39.224 luup_log:66: ecobee: Unable to getThermostatSummary; skipping status update. <0x2d121680>
01 06/13/14 10:57:47.104 JobHandler_LuaUPnP::GetPluginVersionOnline failed to convert 4756 <0x2bc11680> 01 06/13/14 10:57:47.903 JobHandler_LuaUPnP::GetPluginVersionOnline failed to convert 5836 <0x2bc11680> 06 06/13/14 10:57:48.210 Device_Variable::m_szValue_set device: 65 service: urn:micasaverde-com:serviceId:EnergyMetering1 variable: Watts was: 12 now: 6 #hooks: 0 upnp: 0 v:0x105abc0/NONE duplicate:0 <0x2ba11680> 06 06/13/14 10:57:48.211 Device_Variable::m_szValue_set device: 65 service: urn:micasaverde-com:serviceId:EnergyMetering1 variable: Log was: 12,3,14,1402671465,1666 now: 6,3,14,1402671468,1669 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2ba11680> 06 06/13/14 10:57:48.212 Device_Variable::m_szValue_set device: 65 service: urn:micasaverde-com:serviceId:EnergyMetering1 variable: ActualUsage was: 1 now: 1 #hooks: 0 upnp: 0 v:0x105ac00/NONE duplicate:1 <0x2ba11680> 01 06/13/14 10:57:48.416 JobHandler_LuaUPnP::GetPluginVersionOnline failed to convert 3586 <0x2bc11680>

May be something to do with device 65 since it is listed so often. It’s a Aeon Labs Aeotec Z-Wave Micro Smart Energy Switch.

Yep … the Energy plugin can cause your Vera to become unstable.

Hopefully this is solved.

I unplugged and replugged the two Aeon Labs DSC06106-ZWUS Smart Energy Switches, the ones controlled by the script above, and now I no longer see the memory leak error in the logs.

*** UPDATED ***

NOPE. Memory leak errors returned after a while…

No help from support.

Been trying to figure this out for a week now. May need to slowly rip my Vera setup apart piece by piece or reset the VERA and start from scratch.

Your script only retrieves the temperature from the Ecobee thermostat but does not otherwise exercise the code in any particular way. My Vera, with one Smart SI thermostat and a standard array of switches, cameras, motion sensors, a Nest, etc., does not show any stability problems. It’s not to say that there isn’t any odd interaction behind the scenes with the plugin, but I tend to think the problem lies elsewhere.

I see the lines in your logs:

01 06/13/14 10:41:39.222 luup_log:66: ecobee: Error: nil: no valid JSON value (reached the end) <0x2d121680> 06 06/13/14 10:41:39.223 Device_Variable::m_szValue_set device: 66 service: urn:ecobee-com:serviceId:Ecobee1 variable: status was: 1 now: 0 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2d121680> 01 06/13/14 10:41:39.224 luup_log:66: ecobee: Unable to getThermostatSummary; skipping status update. <0x2d121680>

But I think this is likely due to an out-of-memory situation caused by some other leaking code. You might have to turn off the plugin Richard pointed out to see if that’s the culprit.

watou

I don’t have the special ENERGY (ERGY) plug-in enabled. Only the standard Vera energy readings should be taking place.

The logs seem to point toward standard physical switches as causing the issue. I’m now getting messages like these fairly regularly from various devices.

02 06/13/14 15:57:04.444 ZWaveSerial::GetFrame 0x2b8fcf58 timed out now 0 m_listGetFramePending 0 <0x2b8fd680> 02 06/13/14 15:57:04.444 ZWaveJobHandler::SendDataAbort got m_iFrameID 0 <0x2b8fd680> 01 06/13/14 15:57:04.445 ZWJob_PollNode::Run job job#29 :pollnode #5 dev:18 (0x16a42e8) N:5 P:100 S:1 ZW_Send_Data to node 5 failed 1 req 0x1745520/6 abort m_iFrameID 0 <0x2b8fd680> 02 06/13/14 15:57:04.445 ZWJob_PollNode::PollFailed job job#29 :pollnode #5 dev:18 (0x16a42e8) N:5 P:100 S:1 node 5 battery 0 <0x2b8fd680> 06 06/13/14 15:57:04.445 Device_Variable::m_szValue_set device: 1 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: LastError was: Poll failed now: Poll failed #hooks: 0 upnp: 0 v:0x1220078/NONE duplicate:1 <0x2b8fd680> 04 06/13/14 15:57:04.446 <0x2b8fd680> 02 06/13/14 15:57:04.447 JobHandler::PurgeCompletedJobs purge job#29 :pollnode #5 dev:18 (0x16a42e8) N:5 P:100 S:2 pollnode #5 1 cmds status 2 <0x2b8fd680>

I’ve only owned the Vera for about a month. Had trouble when I tried to revert it back to version 5, so I left it on version 1.6.641.

Have the following plug-ins:
Global Cache GC100 1.0
Wake-on-LAN 1.62
Yamaha Network Control Alias Plugin 2.5
Foscam IP Camera 2.6
VistaCam SD, PT & HD for UI6 1.82
VistaCam SD, PT & HD for UI5 1.44
VeraAlerts 5.7
Squeezebox Control 1.0
MultiSwitch 1.3
Countdown timer 6.0
ecobee Thermostat 0.9
MiOS Update Utility

[quote=“AEBogdan, post:8, topic:181576”]The logs seem to point toward standard physical switches as causing the issue. I’m now getting messages like these fairly regularly from various devices.

02 06/13/14 15:57:04.444 ZWaveSerial::GetFrame 0x2b8fcf58 timed out now 0 m_listGetFramePending 0 <0x2b8fd680> 02 06/13/14 15:57:04.444 ZWaveJobHandler::SendDataAbort got m_iFrameID 0 <0x2b8fd680> 01 06/13/14 15:57:04.445 ZWJob_PollNode::Run job job#29 :pollnode #5 dev:18 (0x16a42e8) N:5 P:100 S:1 ZW_Send_Data to node 5 failed 1 req 0x1745520/6 abort m_iFrameID 0 <0x2b8fd680> 02 06/13/14 15:57:04.445 ZWJob_PollNode::PollFailed job job#29 :pollnode #5 dev:18 (0x16a42e8) N:5 P:100 S:1 node 5 battery 0 <0x2b8fd680> 06 06/13/14 15:57:04.445 Device_Variable::m_szValue_set device: 1 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: LastError was: Poll failed now: Poll failed #hooks: 0 upnp: 0 v:0x1220078/NONE duplicate:1 <0x2b8fd680> 04 06/13/14 15:57:04.446 <0x2b8fd680> 02 06/13/14 15:57:04.447 JobHandler::PurgeCompletedJobs purge job#29 :pollnode #5 dev:18 (0x16a42e8) N:5 P:100 S:2 pollnode #5 1 cmds status 2 <0x2b8fd680>

I’ve only owned the Vera for about a month. Had trouble when I tried to revert it back to version 5, so I left it on version 1.6.641.

Have the following plug-ins:
Global Cache GC100 1.0
Wake-on-LAN 1.62
Yamaha Network Control Alias Plugin 2.5
Foscam IP Camera 2.6
VistaCam SD, PT & HD for UI6 1.82
VistaCam SD, PT & HD for UI5 1.44
VeraAlerts 5.7
Squeezebox Control 1.0
MultiSwitch 1.3
Countdown timer 6.0
ecobee Thermostat 0.9
MiOS Update Utility[/quote]

you may want to put more effort to getting back to the mores stable version 5. Having tried the upgrade, I was frustrated and reverted too. Not ready for prime time that version 6, in my opinion.

plus, you may want to see where you are with system resources, particularly if you are on a vera lite.

Loaded the System Monitor plug-in. It reports I have about 35 Meg left.

It appears this did have something to do with device 65, the Aeon Labs Aeotec Z-Wave Micro Smart Energy Switch. I removed that switch and all the memory leak errors vanished from the logs.

Wonder if the device was corrupting the energy monitoring process as a whole, making all energy monitoring switches unstable, including the two turned on and off by the Scene above.

Sure learned a lot about: Resets, Restores, Healing, monitoring the Logs and System Memory

After further testing, I have come to the conclusion that this issue is caused by any Aeon Labs Smart Energy Switch, like the ones that are turned on by the script listed above. I can create Memory Leak errors in the logs by turning any of my Smart Energy switches on and off.

This would explain why running the script would causes my Vera to become unstable. I am using the current latest version of the Vera firmware, 1.6.641, and have the MiOS Update plug-in installed, so this should be under the latest Vera code.

Looks like the memory leaks were not the problem, as LUUP locked up even after removing the switch.

I decided to try a factory refresh and rebuild my system from scratch. As soon as I added the above scene and assigned it to a 15 minute schedule LUUP started locking up again.

Decided to try an experiment. I replaced the 15 minute schedule with a Countdown Timer plugin assigned to a 15 minute duration that repeated. Vera has been running fine for a few days now. I’ve been able to edit scenes again without LUUP freezing my Vera.

*** UPDATE 6/24/2014 *****

This has been confirmed as a bug in firmware 1.6.641 and has been forwarded to the software developers for a future fix.

“It seems there is an issue in UI6 which causes LuaUPnP to crash when a Lua scene is active with a recurrent schedule (e.g. every X minutes).”


I also experienced this issue and have been fighting it for the last 2 days. Thank you very much for your post! Hopefully this gets fixed in the next release.