Frequent Luup Restarts

kandlg · April 22, 2015, 11:11pm

So I have been having an ongoing discussion with Vera Support through a ticket about luup restarts that happen 8-10 times per day. Through 4 back and fourth questions they have said the logs show that third party plug-ins are causing the problem and I should uninstall them because they are causing the problem and are not supported. Well I am tired of uninstalling plug-ins. The last time I sent them a section of the log that appears (in my limited understanding) to show that there is some z-wave issue and once again they said to uninstall two more plug-ins. I would appreciate it if someone would tell me if this looks like a plug-in issue or something else. Most of the crashes look something like this with restart at 15:05:12.630:

02 04/22/15 15:05:11.220 e[33;1mZWaveJobHandler::UpdateNodes not configuring node 16 because it's not listeninge[0m <0x2bf89680> 09 04/22/15 15:05:11.221 ZWaveJobHandler::UpdateNodes node 16 pnp 0 Device_NumTemplate D_MotionSensor1.xml type ZWaveBinarySensor Device_Num 159 Room 1 auto-conf -1 cap 0x53 sec 0x9c res 0x0 bas 0x4 gen 0x20 spe 0x1 config 1 secure 0 Garage Door classes 30,70,71,72,80,84,85,86, mfr: / mfr: 0x14a prodtype: 0x1 prodid: 0x3 notlistening: 1 list:0 rout:1 beam:1 rtsl:1 sec:0 1k:0 250:0 <0x2bf89680> 06 04/22/15 15:05:11.221 Device_Variable::m_szValue_set device: 1 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: e[35;1mNetStatusIDe[0m was: 7 now: 5 #hooks: 0 upnp: 0 v:0xc19010/NONE duplicate:0 <0x2bf89680> 06 04/22/15 15:05:11.221 Device_Variable::m_szValue_set device: 1 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: e[35;1mNetStatusTexte[0m was: Starting ZWave Network now: Configuring ZWave devices #hooks: 0 upnp: 0 v:0xc1b528/NONE duplicate:0 <0x2bf89680> 04 04/22/15 15:05:11.223 <Job ID="1" Name="getnodes" Device="" Created="2015-04-22 15:05:10" Started="2015-04-22 15:05:10" Completed="2015-04-22 15:05:11" Duration="0.324569000" Runtime="0.318038000" Status="Successful" LastNote=""/> <0x2bf89680> 02 04/22/15 15:05:12.948 e[33;1mJobHandler_LuaUPnP::StartUPnPServices starting with /etc/cmh-ludl/ / http://192.168.1.176:49451/luaupnp.xmle[0m <0x2b455000> 02 04/22/15 15:05:13.100 e[33;1mZWaveJobHandler::SetDeviceStatus XXX2 0/0/0/0e[0m <0x2bb89680>

[Big thanks to RexBeckett BTW for his code for logging restarts and capturing the log]

RichardTSchaefer · April 22, 2015, 11:18pm

That’s not enough of a log to really understand what is happening …
Do you have a Vera Lite ?

kandlg · April 22, 2015, 11:24pm

Yes sorry. VeraLite on 5. Happy to post more log on that but not sure how far to go. I had assumed that it was one of the last few events that caused it.

08 04/22/15 15:02:53.100 Scene::RunScene running 101 Check A/C Temp <0x2be15680> 50 04/22/15 15:02:53.101 luup_log:0: Upstairs A/C mode:Idle <0x2be15680> 50 04/22/15 15:02:53.101 luup_log:0: Downstairs A/C setpoint:76 <0x2be15680> 50 04/22/15 15:02:53.101 luup_log:0: Downstairs A/C OK <0x2be15680> 08 04/22/15 15:02:53.102 JobHandler_LuaUPnP::AlarmCallback Ran scene:101 Check A/C Temp / timer:11 Minutes next at 1429733633 now 1429732973 <0x2be15680> 50 04/22/15 15:03:05.154 luup_log:74: ISYController: debug: Daemon is running and connected. <0x2f215680> 03 04/22/15 15:05:03.568 LuaUPNP: starting bLogUPnP 0 <0x2b455000> 02 04/22/15 15:05:03.598 e[33;1mJobHandler_LuaUPnP::Run: pid 19714 didn't exite[0m <0x2b455000> 02 04/22/15 15:05:04.146 e[33;1mUserData::LoadUserData previous: 0 from *1.5.622*e[0m <0x2b455000> 09 04/22/15 15:05:04.147 UserData::ParseRooms 1 Locks <0x2b455000> 09 04/22/15 15:05:04.147 UserData::ParseRooms 2 MBR <0x2b455000> 09 04/22/15 15:05:04.148 UserData::ParseRooms 3 Upstairs <0x2b455000> 09 04/22/15 15:05:04.148 UserData::ParseRooms 4 Outside Lights <0x2b455000> 09 04/22/15 15:05:04.148 UserData::ParseRooms 5 Kitchen <0x2b455000> 09 04/22/15 15:05:04.149 UserData::ParseRooms 6 Living Room <0x2b455000> 09 04/22/15 15:05:04.149 UserData::ParseRooms 7 A/C Control <0x2b455000> 09 04/22/15 15:05:04.149 UserData::ParseRooms 8 Arduino <0x2b455000> 09 04/22/15 15:05:04.149 UserData::ParseRooms 9 Timers <0x2b455000> 09 04/22/15 15:05:04.150 UserData::ParseRooms 10 ZJunk <0x2b455000> 09 04/22/15 15:05:04.150 UserData::ParseRooms 11 Study <0x2b455000> 09 04/22/15 15:05:04.150 UserData::ParseRooms 12 Pool <0x2b455000> 03 04/22/15 15:05:04.277 UserData::LoadUserData BuildVersion: *1.5.622* SvnVersion: *7546* Model: 33 MiCasaVerde VeraLite flush: 0 changed: 0 resync: 6713 syncdevice:0 <0x2b455000> 02 04/22/15 15:05:05.321 e[33;1mDevice_Service::MatchupUpnpServices no upnp service for urn:micasaverde-com:serviceId:ZWaveDevice1e[0m <0x2b455000> 02 04/22/15 15:05:05.325 e[33;1mDevice_Service::MatchupUpnpServices no upnp service for urn:micasaverde-com:serviceId:ZWaveDevice1e[0m <0x2b455000> 02 04/22/15 15:05:05.343 e[33;1mDevice_Service::MatchupUpnpServices no upnp service for urn:micasaverde-com:serviceId:ZWaveDevice1e[0m <0x2b455000> 02 04/22/15 15:05:05.347 e[33;1mDevice_Service::MatchupUpnpServices no upnp service for urn:micasaverde-com:serviceId:ZWaveDevice1e[0m <0x2b455000> 02 04/22/15 15:05:05.398 e[33;1mDevice_Service::MatchupUpnpServices no upnp service for urn:micasaverde-com:serviceId:ZWaveDevice1e[0m <0x2b455000> 06 04/22/15 15:05:05.888 Device_Variable::m_szValue_set device: 1 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: e[35;1mLastUpdatee[0m was: 1429724393 now: 1429733105 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2b455000> 06 04/22/15 15:05:05.889 Device_Variable::m_szValue_set device: 1 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: e[35;1mNetStatusIDe[0m was: 1 now: 7 #hooks: 0 upnp: 0 v:0xc19010/NONE duplicate:0 <0x2b455000> 06 04/22/15 15:05:05.890 Device_Variable::m_szValue_set device: 1 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: e[35;1mNetStatusTexte[0m was: OK now: Starting ZWave Network #hooks: 0 upnp: 0 v:0xc1b528/NONE duplicate:0 <0x2b455000> 02 04/22/15 15:05:06.045 e[33;1mZWaveJobHandler::Run connect to /dev/ttyS0 -0 lock 1e[0m <0x2bf89680> 02 04/22/15 15:05:06.095 e[33;1mZWaveJobHandler::Run connected to /dev/ttyS0=1 i=0e[0m <0x2bf89680> 06 04/22/15 15:05:06.146 Device_Variable::m_szValue_set device: 1 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: e[35;1mNetStatusIDe[0m was: 7 now: 7 #hooks: 0 upnp: 0 v:0xc19010/NONE duplicate:1 <0x2bf89680> 06 04/22/15 15:05:06.147 Device_Variable::m_szValue_set device: 1 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: e[35;1mNetStatusTexte[0m was: Starting ZWave Network now: Starting ZWave Network #hooks: 0 upnp: 0 v:0xc1b528/NONE duplicate:1 <0x2bf89680> 03 04/22/15 15:05:10.805 ZWJob_Initialize::JobDone version 3.20 type 1 role is 0 house id 17afce0 node id 1 suc 0 IsSecondary 0 bOnOtherNetwork 0 NodeIdServerPresent 0 IsRealPrimary 1 IsSuc 0 locale 1 <0x2bf89680> 06 04/22/15 15:05:10.806 Device_Variable::m_szValue_set device: 1 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: e[35;1mVersionInfoe[0m was: 3.20 L:1 now: 3.20 L:1 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2bf89680> 06 04/22/15 15:05:10.807 Device_Variable::m_szValue_set device: 1 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: e[35;1mHomeIDe[0m was: House: 17afce0 Node 1 Suc 0 now: House: 17afce0 Node 1 Suc 0 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2bf89680> 06 04/22/15 15:05:10.807 Device_Variable::m_szValue_set device: 1 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: e[35;1mRolee[0m was: Master SIS:NO PRI:YES now: Master SIS:NO PRI:YES #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2bf89680> 04 04/22/15 15:05:10.808 <Job ID="0" Name="init" Device="1" Created="2015-04-22 15:05:06" Started="2015-04-22 15:05:06" Completed="2015-04-22 15:05:10" Duration="4.416080000" Runtime="4.415479000" Status="Successful" LastNote=""/> <0x2bf89680> 02 04/22/15 15:05:10.897 e[33;1mZWave::Start reset 0 inter 0 upgrade 0 use45:1 minor:20 model:33 port:/dev/ttyS0 nodes:5e[0m <0x2b455000> 02 04/22/15 15:05:10.900 e[33;1mJobHandler_LuaUPnP::StartPlugins Energy STARTEDe[0m <0x2b455000> 02 04/22/15 15:05:11.195 e[33;1mXXXX setinitial UpdateManualRoute node 1 = (null)e[0m <0x2bf89680> 02 04/22/15 15:05:11.195 e[33;1mXXXX UpdateManualRoute setinitial node 1 m_cRoutePosition 0e[0m <0x2bf89680> 02 04/22/15 15:05:11.196 e[33;1mZWaveNode::UpdateCommandClasses node 1 empty -- --e[0m <0x2bf89680> 09 04/22/15 15:05:11.196 ZWaveJobHandler::FindCustomDeviceType node 10/0 has custom 2043 file class desc _Schlage Deadbolt <0x2bf89680> 02 04/22/15 15:05:11.196 e[33;1mZWaveNode::GetCustomZWaveNode bad node 10 class e[0m <0x2bf89680> 02 04/22/15 15:05:11.197 e[33;1mXXXX setinitial UpdateManualRoute node 10 = 0-73xe[0m <0x2bf89680> 02 04/22/15 15:05:11.197 e[33;1mUpdateManualRoute XXX1 node 10 route 0-73xe[0m <0x2bf89680> 02 04/22/15 15:05:11.197 e[33;1mXXXX UpdateManualRoute setinitial node 10 m_cRoutePosition 0e[0m <0x2bf89680> 06 04/22/15 15:05:11.200 Device_Variable::m_szValue_set device: 5 service: urn:micasaverde-com:serviceId:HaDevice1 variable: e[35;1mConfigurede[0m was: 1 now: 1 #hooks: 0 upnp: 0 v:0x9dfa28/NONE duplicate:1 <0x2bf89680> 06 04/22/15 15:05:11.201 Device_Variable::m_szValue_set device: 5 service: urn:micasaverde-com:serviceId:HaDevice1 variable: e[35;1mConfigurede[0m was: 1 now: 1 #hooks: 0 upnp: 0 v:0x9dfa28/NONE duplicate:1 <0x2bf89680> 09 04/22/15 15:05:11.201 ZWaveJobHandler::FindCustomDeviceType node 13/0 has custom 2043 file class desc _Schlage Deadbolt <0x2bf89680> 02 04/22/15 15:05:11.202 e[33;1mZWaveNode::GetCustomZWaveNode bad node 13 class e[0m <0x2bf89680> 02 04/22/15 15:05:11.202 e[33;1mXXXX setinitial UpdateManualRoute node 13 = 0-184xe[0m <0x2bf89680> 02 04/22/15 15:05:11.202 e[33;1mUpdateManualRoute XXX1 node 13 route 0-184xe[0m <0x2bf89680> 02 04/22/15 15:05:11.202 e[33;1mXXXX UpdateManualRoute setinitial node 13 m_cRoutePosition 0e[0m <0x2bf89680> 06 04/22/15 15:05:11.206 Device_Variable::m_szValue_set device: 20 service: urn:micasaverde-com:serviceId:HaDevice1 variable: e[35;1mConfigurede[0m was: 1 now: 1 #hooks: 0 upnp: 0 v:0x9dfa28/NONE duplicate:1 <0x2bf89680> 06 04/22/15 15:05:11.206 Device_Variable::m_szValue_set device: 20 service: urn:micasaverde-com:serviceId:HaDevice1 variable: e[35;1mConfigurede[0m was: 1 now: 1 #hooks: 0 upnp: 0 v:0x9dfa28/NONE duplicate:1 <0x2bf89680> 09 04/22/15 15:05:11.207 ZWaveJobHandler::FindCustomDeviceType node 15/0 has custom 2043 file class desc _Schlage Deadbolt <0x2bf89680> 02 04/22/15 15:05:11.207 e[33;1mZWaveNode::GetCustomZWaveNode bad node 15 class e[0m <0x2bf89680> 02 04/22/15 15:05:11.207 e[33;1mXXXX setinitial UpdateManualRoute node 15 = 0-184xe[0m <0x2bf89680> 02 04/22/15 15:05:11.208 e[33;1mUpdateManualRoute XXX1 node 15 route 0-184xe[0m <0x2bf89680> 02 04/22/15 15:05:11.208 e[33;1mXXXX UpdateManualRoute setinitial node 15 m_cRoutePosition 0e[0m <0x2bf89680> 06 04/22/15 15:05:11.211 Device_Variable::m_szValue_set device: 24 service: urn:micasaverde-com:serviceId:HaDevice1 variable: e[35;1mConfigurede[0m was: 1 now: 1 #hooks: 0 upnp: 0 v:0x9dfa28/NONE duplicate:1 <0x2bf89680> 06 04/22/15 15:05:11.211 Device_Variable::m_szValue_set device: 24 service: urn:micasaverde-com:serviceId:HaDevice1 variable: e[35;1mConfigurede[0m was: 1 now: 1 #hooks: 0 upnp: 0 v:0x9dfa28/NONE duplicate:1 <0x2bf89680> 02 04/22/15 15:05:11.212 e[33;1mXXXX setinitial UpdateManualRoute node 16 = (null)e[0m <0x2bf89680> 02 04/22/15 15:05:11.212 e[33;1mXXXX UpdateManualRoute setinitial node 16 m_cRoutePosition 0e[0m <0x2bf89680> 06 04/22/15 15:05:11.213 Device_Variable::m_szValue_set device: 159 service: urn:micasaverde-com:serviceId:HaDevice1 variable: e[35;1mConfigurede[0m was: 1 now: 1 #hooks: 0 upnp: 0 v:0x9dfa28/NONE duplicate:1 <0x2bf89680> 06 04/22/15 15:05:11.213 Device_Variable::m_szValue_set device: 159 service: urn:micasaverde-com:serviceId:HaDevice1 variable: e[35;1mConfigurede[0m was: 1 now: 1 #hooks: 0 upnp: 0 v:0x9dfa28/NONE duplicate:1 <0x2bf89680> 09 04/22/15 15:05:11.214 ZWaveJobHandler::UpdateNodes dongle is node 1 device 2 iExtraNodesForTest 0 <0x2bf89680> 06 04/22/15 15:05:11.214 Device_Variable::m_szValue_set device: 2 service: urn:micasaverde-com:serviceId:SceneController1 variable: e[35;1mScenese[0m was: now: #hooks: 0 upnp: 0 v:0x9e2510/NONE duplicate:1 <0x2bf89680> 09 04/22/15 15:05:11.218 ZWaveJobHandler::UpdateNodes node 10 pnp 2043 Device_NumTemplate D_DoorLock1.xml type ZWaveDoorlock Device_Num 5 Room 1 auto-conf -1 cap 0x53 sec 0xdc res 0x0 bas 0x4 gen 0x40 spe 0x3 config 1 secure 1 Carport classes 20-s,22,5d-s,62-s,63-s,70-s,71-s,72,7a,80-s,85-s,86,98, mfr: Schlage/ mfr: 0x3b prodtype: 0x6341 prodid: 0x5044 notlistening: 0 list:0 rout:1 beam:1 rtsl:1 sec:0 1k:1 250:0 <0x2bf89680> 09 04/22/15 15:05:11.219 ZWaveJobHandler::UpdateNodes node 13 pnp 2043 Device_NumTemplate D_DoorLock1.xml type ZWaveDoorlock Device_Num 20 Room 1 auto-conf -1 cap 0x53 sec 0xdc res 0x0 bas 0x4 gen 0x40 spe 0x3 config 1 secure 1 Back Door classes 20-s,22,5d-s,62-s,63-s,70-s,71-s,72,7a,80-s,85-s,86,98, mfr: Schlage/ mfr: 0x3b prodtype: 0x6341 prodid: 0x5044 notlistening: 0 list:0 rout:1 beam:1 rtsl:1 sec:0 1k:1 250:0 <0x2bf89680> 09 04/22/15 15:05:11.220 ZWaveJobHandler::UpdateNodes node 15 pnp 2043 Device_NumTemplate D_DoorLock1.xml type ZWaveDoorlock Device_Num 24 Room 1 auto-conf -1 cap 0x53 sec 0xdc res 0x0 bas 0x4 gen 0x40 spe 0x3 config 1 secure 1 Front Door classes 20-s,22,5d-s,62-s,63-s,70-s,71-s,72,7a,80-s,85-s,86,98, mfr: Schlage/ mfr: 0x3b prodtype: 0x6341 prodid: 0x5044 notlistening: 0 list:0 rout:1 beam:1 rtsl:1 sec:0 1k:1 250:0 <0x2bf89680> 02 04/22/15 15:05:11.220 e[33;1mZWaveJobHandler::UpdateNodes not configuring node 16 because it's not listeninge[0m <0x2bf89680> 09 04/22/15 15:05:11.221 ZWaveJobHandler::UpdateNodes node 16 pnp 0 Device_NumTemplate D_MotionSensor1.xml type ZWaveBinarySensor Device_Num 159 Room 1 auto-conf -1 cap 0x53 sec 0x9c res 0x0 bas 0x4 gen 0x20 spe 0x1 config 1 secure 0 Garage Door classes 30,70,71,72,80,84,85,86, mfr: / mfr: 0x14a prodtype: 0x1 prodid: 0x3 notlistening: 1 list:0 rout:1 beam:1 rtsl:1 sec:0 1k:0 250:0 <0x2bf89680> 06 04/22/15 15:05:11.221 Device_Variable::m_szValue_set device: 1 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: e[35;1mNetStatusIDe[0m was: 7 now: 5 #hooks: 0 upnp: 0 v:0xc19010/NONE duplicate:0 <0x2bf89680> 06 04/22/15 15:05:11.221 Device_Variable::m_szValue_set device: 1 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: e[35;1mNetStatusTexte[0m was: Starting ZWave Network now: Configuring ZWave devices #hooks: 0 upnp: 0 v:0xc1b528/NONE duplicate:0 <0x2bf89680> 04 04/22/15 15:05:11.223 <Job ID="1" Name="getnodes" Device="" Created="2015-04-22 15:05:10" Started="2015-04-22 15:05:10" Completed="2015-04-22 15:05:11" Duration="0.324569000" Runtime="0.318038000" Status="Successful" LastNote=""/> <0x2bf89680> 02 04/22/15 15:05:12.948 e[33;1mJobHandler_LuaUPnP::StartUPnPServices starting with /etc/cmh-ludl/ / http://192.168.1.176:49451/luaupnp.xmle[0m <0x2b455000> 02 04/22/15 15:05:13.100 e[33;1mZWaveJobHandler::SetDeviceStatus XXX2 0/0/0/0e[0m <0x2bb89680>

RichardTSchaefer · April 23, 2015, 12:05am

It’s best to have the LAST 10 minutes before the restart.
Vera Lite is “LITE ON MEMORY”
What devices (kind and how many) … you can exclude Z-Wave devices and any devices that are part of an alarm system.