We have moved at community.getvera.com

Author Topic: Setup: instability  (Read 1857 times)

Offline ChrisFSB

  • Sr. Newbie
  • *
  • Posts: 33
  • Karma: +1/-0
Setup: instability
« on: October 21, 2012, 07:08:13 pm »
Hi,

I'm not having much success getting Version 86 to load.

After loading the Caddx module the Vera system becomes unstable.  After removing the Caddx module and a hard reboot stability returns. 

Is there any other debug I can provide?

The Vera is connected to the Caddx using a UDS-10.  I'm just starting to use the Caddx plugin - the only other component installed is the "Radio Thermostat Wi-Fi Plugin"; but that's been stable since I started using Vera (2 months).

Thanks, Chris.



On boot it errors with:

50   10/21/12 15:54:51.980   luup_log:143: Initializing Caddx NX-584 __LEAK__ this:200704 start:1544192 to 0x1212000 <0x2b799680>
50   10/21/12 15:54:51.981   luup_log:143: Opening socket to 10.1.1.126 port 10001 <0x2b799680>
50   10/21/12 15:54:52.334   luup_log:143: All message codes are supported. <0x2b799680>
50   10/21/12 15:54:52.335   luup_log:143: Zone Name enabled <0x2b799680>
50   10/21/12 15:54:52.335   luup_log:143: Log Event enabled <0x2b799680>
50   10/21/12 15:54:52.335   luup_log:143: Set Clock enabled <0x2b799680>
50   10/21/12 15:54:52.336   luup_log:143: Primary Keypad Function with PIN enabled <0x2b799680>
50   10/21/12 15:54:52.336   luup_log:143: Secondary Keypad Function enabled <0x2b799680>
50   10/21/12 15:54:52.336   luup_log:143: Zone bypass enabled <0x2b799680>
02   10/21/12 15:54:53.769   JobHandler::Run job#72 :pollnode_hau #109 (0x1172e20) N:109 P:32 S:0 is 5.163641000 seconds old <0x2b999680>
02   10/21/12 15:54:53.770   ZW_Send_Data node 109 USING ROUTE 255.114.101.100 <0x2b999680>
06   10/21/12 15:54:53.906   Device_Variable::m_szValue_set device: 111 service: urn:upnp-org:serviceId:SwitchPower1 variable: Status was: 1 now: 0 #hooks: 0 upnp: 0 v:0xd1b610/NONE duplicate:0 <0x2b599680>
06   10/21/12 15:54:53.906   Device_Variable::m_szValue_set device: 111 service: urn:upnp-org:serviceId:Dimming1 variable: LoadLevelStatus was: 89 now: 0 #hooks: 3 upnp: 0 v:0xd1b678/NONE duplicate:0 <0x2b599680>
04   10/21/12 15:54:53.908    <0x2b599680>
02   10/21/12 15:54:54.039   luup_log:13: RTCOA INFO (callThermostatAPI:315) - Received succesful response, path = /tstat, response = { ["tstate"] = 0,["override"] = 1,["tmode"] = 2,["fmode"] = 0,["t_cool"] = 84,["t_type_post"] = 0,["hold"] = 1,["temp"] = 72,["fstate"] = 0,["time"] = { ["minute"] = 54,["hour"] = 15,["day"] = 6,} ,}  <0x2c599680>
06   10/21/12 15:54:54.040   Device_Variable::m_szValue_set device: 13 service: urn:upnp-org:serviceId:TemperatureSensor1 variable: CurrentTemperature was: 72 now: 72 #hooks: 1 upnp: 0 v:0xd5f758/NONE duplicate:1 <0x2c599680>
06   10/21/12 15:54:54.040   Device_Variable::m_szValue_set device: 13 service: urn:upnp-org:serviceId:HVAC_UserOperatingMode1 variable: ModeStatus was: CoolOn now: CoolOn #hooks: 1 upnp: 0 v:0xd551e0/NONE duplicate:1 <0x2c599680>
06   10/21/12 15:54:54.041   Device_Variable::m_szValue_set device: 13 service: urn:micasaverde-com:serviceId:HVAC_OperatingState1 variable: ModeState was: Idle now: Idle #hooks: 0 upnp: 0 v:0xd55200/NONE duplicate:1 <0x2c599680>
06   10/21/12 15:54:54.041   Device_Variable::m_szValue_set device: 13 service: urn:upnp-org:serviceId:HVAC_FanOperatingMode1 variable: Mode was: Auto now: Auto #hooks: 1 upnp: 0 v:0xd40c08/NONE duplicate:1 <0x2c599680>
06   10/21/12 15:54:54.041   Device_Variable::m_szValue_set device: 13 service: urn:upnp-org:serviceId:HVAC_FanOperatingMode1 variable: FanStatus was: Off now: Off #hooks: 0 upnp: 0 v:0xd41d28/NONE duplicate:1 <0x2c599680>
06   10/21/12 15:54:54.042   Device_Variable::m_szValue_set device: 13 service: urn:hugheaves-com:serviceId:HVAC_RTCOA_TemperatureHold1 variable: Status was: 1 now: 1 #hooks: 0 upnp: 0 v:0xd74618/NONE duplicate:1 <0x2c599680>
06   10/21/12 15:54:54.042   Device_Variable::m_szValue_set device: 13 service: urn:upnp-org:serviceId:TemperatureSetpoint1_Cool variable: CurrentSetpoint was: 84 now: 84 #hooks: 1 upnp: 0 v:0xd67108/NONE duplicate:1 <0x2c599680>
06   10/21/12 15:54:54.042   Device_Variable::m_szValue_set device: 13 service: urn:micasaverde-com:serviceId:HaDevice1 variable: LastUpdate was: 1350860091 now: 1350860094 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2c599680>
06   10/21/12 15:54:54.043   Device_Variable::m_szValue_set device: 13 service: urn:hugheaves-com:serviceId:HVAC_RTCOA_Wifi1 variable: Programs was:  now:  #hooks: 0 upnp: 0 v:0xd69498/NONE duplicate:1 <0x2c599680>
02   10/21/12 15:54:54.044   luup_log:13: RTCOA INFO (callThermostatAPI:296) - Calling thermostat API, path = /tstat/pma, requestParameters = { ["mode"] = 0,} , noRetry = nil <0x2c599680>
02   10/21/12 15:54:54.393   luup_log:13: RTCOA INFO (callThermostatAPI:315) - Received succesful response, path = /tstat/pma, response = { ["success"] = 0,}  __LEAK__ this:8192 start:1552384 to 0x1214000 <0x2c599680>
02   10/21/12 15:54:54.395   luup_log:13: RTCOA INFO (callThermostatAPI:296) - Calling thermostat API, path = /tstat/remote_temp, requestParameters = { ["rem_mode"] = 0,} , noRetry = nil <0x2c599680>
02   10/21/12 15:54:54.677   luup_log:13: RTCOA INFO (callThermostatAPI:315) - Received succesful response, path = /tstat/remote_temp, response = { ["success"] = 0,}  __LEAK__ this:8192 start:1560576 to 0x1216000 <0x2c599680>
50   10/21/12 15:55:07.327   luup_log:143: Valid partition 1 __LEAK__ this:8192 start:1568768 to 0x1218000 <0x2b799680>
50   10/21/12 15:55:07.328   luup_log:143: PIN length is 4 <0x2b799680>
06   10/21/12 15:55:07.328   Device_Variable::m_szValue_set device: 143 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryLevel was: EMPTY now: 10 #hooks: 0 upnp: 0 v:0xd2a3d0/NONE duplicate:0 <0x2b799680>
06   10/21/12 15:55:07.330   Device_Variable::m_szValue_set device: 143 service: urn:futzle-com:serviceId:CaddxNX584Security1 variable: StackPointer was: EMPTY now: 184 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2b799680>
09   10/21/12 15:55:11.709   Child_Devices::ProcessChildDevice created device 144 id Partition-1bis under 143 topmost parent 143 __LEAK__ this:8192 start:1576960 to 0x121a000 <0x2b799680>
03   10/21/12 15:55:12.107   JobHandler_LuaUPnP::Reload: ChildDevices Critical 0 m_bCriticalOnly 0 dirty data 0 <0x2b799680>
06   10/21/12 15:55:12.246   Device_Variable::m_szValue_set device: 1 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: NetStatusID was: 1 now: 2 #hooks: 0 upnp: 0 v:0xdd2e20/NONE duplicate:0 <0x2b799680>
06   10/21/12 15:55:12.532   Device_Variable::m_szValue_set device: 1 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: NetStatusText was: OK now: Resetting ZWave Network #hooks: 0 upnp: 0 v:0xdd4c48/NONE duplicate:0 <0x2b799680>
01   10/21/12 15:55:12.534   luup_task interface 0xeea908 args 3 <0x2b799680>
01   10/21/12 15:55:13.041   Mongoose XXX-mg_stop1 0xcd00d8 1 1 <0x2ae66000>
01   10/21/12 15:55:15.042   Mongoose XXX-mg_stop2 0xcd00d8 2 1 <0x2ae66000>
01   10/21/12 15:55:15.042   Mongoose XXX-mg_stop3 0xcd00d8 2 1 <0x2ae66000>
01   10/21/12 15:55:15.042   Mongoose XXX-mg_stop4 0xcd00d8 18845408 1 <0x2ae66000>


2012-10-21 15:55:15 - LuaUPnP Terminated with Exit Code: 250



2012-10-21 15:55:15 - LuaUPnP crash

01 2012-10-21 15:54:17 caught signal 6 <0x2c795680>
01 2012-10-21 15:55:15 caught signal 6 <0x2bb99680>
---------------exited-------------
« Last Edit: March 30, 2013, 02:35:24 am by futzle »

Offline futzle

  • Moderator
  • Master Member
  • *****
  • Posts: 3260
  • Karma: +192/-9
Re: Plugin for Caddx/GE/Networx NX-584/NX-8E security system
« Reply #1 on: October 22, 2012, 05:29:35 pm »
I'm not having much success getting Version 86 to load.

This is a weird one.  On startup the plugin auto-detects any partitions on the system, and creates child devices for them.  This appears to have been successful, according to the log, but then the Luup engine restarts.

Right now I'm suspecting either a corrupted file, or you are on an unexpected firmware version.

What Vera hardware do you have, and what firmware version are you on?

How did you install the plugin? Through apps.mios.com, or by downloading the files individually from code.mios.com?

Can you attach the whole startup log, even from before the plugin starts up?

Offline ChrisFSB

  • Sr. Newbie
  • *
  • Posts: 33
  • Karma: +1/-0
Re: Re: Plugin for Caddx/GE/Networx NX-584/NX-8E security system
« Reply #2 on: October 23, 2012, 12:30:45 pm »
Quote
This is a weird one.  On startup the plugin auto-detects any partitions on the system, and creates child devices for them.  This appears to have been successful, according to the log, but then the Luup engine restarts.
After reloading the plugin I'm unable to get that far anymore

Quote
Right now I'm suspecting either a corrupted file, or you are on an unexpected firmware version.

What Vera hardware do you have, and what firmware version are you on?
Running Vera 3 1.5.408

Quote
How did you install the plugin? Through apps.mios.com, or by downloading the files individually from code.mios.com?
From the App install feature in UI5

Quote
Can you attach the whole startup log, even from before the plugin starts up?
Attached

Thanks! Chris.

Offline futzle

  • Moderator
  • Master Member
  • *****
  • Posts: 3260
  • Karma: +192/-9
Re: Re: Plugin for Caddx/GE/Networx NX-584/NX-8E security system
« Reply #3 on: October 23, 2012, 06:19:30 pm »
ChrisFSB,

This is all that your log has now:
Code: [Select]
50      10/23/12 9:24:13.417    luup_log:143: Initializing Caddx NX-584 __LEAK__ this:200704 start:2064384 to 0x1299000 <
0x2b487680>
50      10/23/12 9:24:13.418    luup_log:143: Opening socket to 10.1.1.126 port 10001 <0x2b487680>

Looks like your IP-serial device at 10.1.1.126 isn't listening any more.  Perhaps it needs to be reset.

What I'm looking for in the log is whether the child partition device exists right from the Luup engine restart.  If it doesn't, then it explains why the Luup engine restarts (when the plugin enumerates its child devices and they differ from the last time it enumerated them), but it raises a different question instead: why aren't the child devices sticking?  If it's not that, then how is the plugin bringing down the whole Luup engine?  No plugin should be able to do that.

Thanks for the other info.  Your setup isn't unique, with the possible exception of the specific IP-serial device that you use.

Offline ChrisFSB

  • Sr. Newbie
  • *
  • Posts: 33
  • Karma: +1/-0
Re: Re: Plugin for Caddx/GE/Networx NX-584/NX-8E security system
« Reply #4 on: October 24, 2012, 12:13:23 am »
Hi Futzle,

Quote
Looks like your IP-serial device at 10.1.1.126 isn't listening any more.  Perhaps it needs to be reset.
Fixed this - so the connect works...

Quote
What I'm looking for in the log is whether the child partition device exists right from the Luup engine restart.  If it doesn't, then it explains why the Luup engine restarts (when the plugin enumerates its child devices and they differ from the last time it enumerated them), but it raises a different question instead: why aren't the child devices sticking?  If it's not that, then how is the plugin bringing down the whole Luup engine?  No plugin should be able to do that.

Thanks for the other info.  Your setup isn't unique, with the possible exception of the specific IP-serial device that you use.

Full logs are attached; the complaint seems to be about a failed lock/deadlock

Code: [Select]
50 10/23/12 20:55:45.008 luup_log:143: Opening socket to 10.1.1.126 port 10001 <0x2bb05680>
<SNIP>
02 10/23/12 20:56:41.101 LOG_CHECK_MEMORY_LEAK pMem start 0x1021000 now 0x1025000 last 0x1021000 leaked 16384 <0x2b905680>
01 10/23/12 20:56:45.014 Failed to get lock(0xc6e5f4) Lua: LuaInterface.cpp:1870 last used LuaInterface.cpp:769  first used LuaInterface.cpp:1800  thread: 0x2bb05680 (>17651)  handler 0x42459c bOkToFail 0 <0x2cf05680>
02 10/23/12 20:56:45.016 Dumping 15 locks <0x2cf05680>
02 10/23/12 20:56:45.016 finished check for exceptions <0x2cf05680>
02 10/23/12 20:56:45.016 finished check for exceptions <0x2cf05680>
02 10/23/12 20:56:45.017 finished check for exceptions <0x2cf05680>
02 10/23/12 20:56:45.017 finished check for exceptions <0x2cf05680>
02 10/23/12 20:56:45.017 finished check for exceptions <0x2cf05680>
02 10/23/12 20:56:45.017 finished check for exceptions <0x2cf05680>
02 10/23/12 20:56:45.018 finished check for exceptions <0x2cf05680>
02 10/23/12 20:56:45.018 finished check for exceptions <0x2cf05680>
02 10/23/12 20:56:45.018 finished check for exceptions <0x2cf05680>
02 10/23/12 20:56:45.018 OL: (0x71b194) (>5467) ThreadedClass ../JobHandler/JobHandler.cpp l:394 time: 4:00:00p (1351051005 s) thread: 0x2b1d1000 Rel: Y Got: Y <0x2cf05680>
02 10/23/12 20:56:45.019 finished check for exceptions <0x2cf05680>
02 10/23/12 20:56:45.019 OL: (0xbd503c) (>15215) ThreadedClass ../JobHandler/JobHandler.cpp l:394 time: 4:00:00p (1351051005 s) thread: 0x2bd05680 Rel: Y Got: Y <0x2cf05680>
02 10/23/12 20:56:45.019 finished check for exceptions <0x2cf05680>
02 10/23/12 20:56:45.019 OL: (0xc6e5f4) (>17648) Lua LuaInterface.cpp l:1800 time: *****DL******8:55:44p (61 s) thread: 0x2bb05680 Rel: N Got: Y <0x2cf05680>
02 10/23/12 20:56:45.020 finished check for exceptions <0x2cf05680>
02 10/23/12 20:56:45.020 OL: (0x71b194) (>17936) ThreadedClass Device_LuaUPnP.cpp l:380 time: 8:55:45p (60 s) thread: 0x2cf05680 Rel: Y Got: Y <0x2cf05680>
02 10/23/12 20:56:45.020 finished check for exceptions <0x2cf05680>
02 10/23/12 20:56:45.020 OL: (0x71b204) (>17937) Variable Device_LuaUPnP.cpp l:399 time: 8:55:45p (60 s) thread: 0x2cf05680 Rel: Y Got: Y <0x2cf05680>
02 10/23/12 20:56:45.020 finished check for exceptions <0x2cf05680>
02 10/23/12 20:56:45.021 OL: (0xc6e5f4) (>17938) Lua LuaInterface.cpp l:1870 time: 8:55:45p (60 s) thread: 0x2cf05680 Rel: N Got: N <0x2cf05680>
02 10/23/12 20:56:45.021 finished check for exceptions <0x2cf05680>
02 10/23/12 20:56:45.021 OL: (0x71b204) (>19298) Variable JobHandler_LuaUPnP.cpp l:6769 time: 4:00:00p (1351051005 s) thread: 0x2e132680 Rel: Y Got: Y <0x2cf05680>
01 10/23/12 20:56:45.021 Deadlock problem. going to reload and quit <0x2cf05680>

<SNIP>

03 10/23/12 20:56:45.022 JobHandler_LuaUPnP::Reload: deadlock Critical 1 m_bCriticalOnly 0 dirty data 1 <0x2cf05680>
01 10/23/12 20:56:52.246 Main WatchDogRoutine: blocked - terminating 1 <0x2d705680>
02 10/23/12 20:56:52.248 Dumping 15 locks <0x2d705680>
02 10/23/12 20:56:52.248 finished check for exceptions <0x2d705680>
02 10/23/12 20:56:52.249 finished check for exceptions <0x2d705680>
02 10/23/12 20:56:52.249 finished check for exceptions <0x2d705680>
02 10/23/12 20:56:52.249 finished check for exceptions <0x2d705680>
02 10/23/12 20:56:52.249 finished check for exceptions <0x2d705680>
02 10/23/12 20:56:52.250 finished check for exceptions <0x2d705680>
02 10/23/12 20:56:52.250 finished check for exceptions <0x2d705680>
02 10/23/12 20:56:52.250 finished check for exceptions <0x2d705680>
02 10/23/12 20:56:52.250 OL: (0x71b194) (>5467) ThreadedClass ../JobHandler/JobHandler.cpp l:394 time: 4:00:00p (1351051012 s) thread: 0x2b1d1000 Rel: Y Got: Y <0x2d705680>
02 10/23/12 20:56:52.250 finished check for exceptions <0x2d705680>
02 10/23/12 20:56:52.251 OL: (0xbd503c) (>15215) ThreadedClass ../JobHandler/JobHandler.cpp l:394 time: 4:00:00p (1351051012 s) thread: 0x2bd05680 Rel: Y Got: Y <0x2d705680>
02 10/23/12 20:56:52.251 finished check for exceptions <0x2d705680>
02 10/23/12 20:56:52.251 OL: (0xc6e5f4) (>17648) Lua LuaInterface.cpp l:1800 time: *****DL******8:55:44p (68 s) thread: 0x2bb05680 Rel: N Got: Y <0x2d705680>
02 10/23/12 20:56:52.251 finished check for exceptions <0x2d705680>
02 10/23/12 20:56:52.251 OL: (0x71b194) (>17936) ThreadedClass Device_LuaUPnP.cpp l:380 time: 8:55:45p (67 s) thread: 0x2cf05680 Rel: Y Got: Y <0x2d705680>
02 10/23/12 20:56:52.252 finished check for exceptions <0x2d705680>
02 10/23/12 20:56:52.252 OL: (0x71b204) (>17937) Variable Device_LuaUPnP.cpp l:399 time: 8:55:45p (67 s) thread: 0x2cf05680 Rel: Y Got: Y <0x2d705680>
02 10/23/12 20:56:52.252 finished check for exceptions <0x2d705680>
02 10/23/12 20:56:52.252 OL: (0xc6e5f4) (>17938) Lua LuaInterface.cpp l:1870 time: 8:55:45p (67 s) thread: 0x2cf05680 Rel: N Got: N <0x2d705680>
02 10/23/12 20:56:52.252 finished check for exceptions <0x2d705680>
02 10/23/12 20:56:52.253 OL: (0x71c3bc) (>19329) alarm AlarmManager.cpp l:109 time: 8:56:45p (7 s) thread: 0x2cf05680 Rel: Y Got: Y <0x2d705680>
02 10/23/12 20:56:52.253 finished check for exceptions <0x2d705680>
02 10/23/12 20:56:52.253 OL: (0xc4aa6c) (>19345) Lua LuaInterface.cpp l:1984 time: 8:56:50p (2 s) thread: 0x2c905680 Rel: N Got: Y <0x2d705680>


2012-10-23 20:56:52 - LuaUPnP Terminated with Exit Code: 137

Offline ChrisFSB

  • Sr. Newbie
  • *
  • Posts: 33
  • Karma: +1/-0
Re: Re: Plugin for Caddx/GE/Networx NX-584/NX-8E security system
« Reply #5 on: October 24, 2012, 12:30:43 am »
In the time it took me to post the previous reply the NX-8e / Vera started communicating.  It's pulling Zone info, etc. now. 

So - not sure what removed the deadlock; but things are moving forward!

Thx, Chris.

Offline futzle

  • Moderator
  • Master Member
  • *****
  • Posts: 3260
  • Karma: +192/-9
Re: Re: Plugin for Caddx/GE/Networx NX-584/NX-8E security system
« Reply #6 on: October 24, 2012, 03:13:06 am »
not sure what removed the deadlock; but things are moving forward!

Hrm.  If it goes away by itself, it can come back by itself.

I'm worried that your IP-Serial device is trying to be too clever, and dropping the connection after inactivity.  Or if something else on your LAN is also trying to talk to it.  It's hard to know without seeing the underlying IP packets, which Vera doesn't help you do.  I don't suppose you have the option of trying a direct connection (with a USB adapter), or a computer running something like ser2net?