We have moved at community.getvera.com

Author Topic: Why my Vera reloads every day at same hour ?  (Read 6398 times)

Offline lolodomo

  • Beta Testers
  • Master Member
  • *****
  • Posts: 3484
  • Karma: +74/-10
Why my Vera reloads every day at same hour ?
« on: March 20, 2015, 06:19:49 pm »
At the end of 2014, I was able to keep my Vera in life without any lua reloads during 7 consecutive days.

Today, while I have uninstalled new additional plugins in my Vera, my Vera is now reloading everyday exactly at the same time, in the middle of the afternoon when nothing special happens in the house. That's probably the Vera health daily process.

Between December and now, main changes were:
1 - I upgraded Vera to 1.5.672
2 - I installed last version of the MiOS binding

@guessed: do you think that your last version could have changed something to Vera stability ?
« Last Edit: March 23, 2015, 04:15:33 pm by lolodomo »

Offline guessed

  • Moderator
  • Master Member
  • *****
  • Posts: 5301
  • Karma: +92/-22
  • Release compat is not a bolted-on afterthought
Re: Using openHAB to minimizing Vera reloads
« Reply #1 on: March 20, 2015, 06:56:49 pm »
The health-process should be 2:00am local time.  Unless your clock is way-off, or the TZ incorrect, I'd be surprised if it's that.


You can use the openHAB Events log (OH/logs/events.log) to see exactly what is changing at that time, and of course the regular OH/logs/openhab.log to see when it's having connectivity issues with your Vera.

For reference, a Heal operation looks like the following set of ZWave changes, from the openHAB perspective.  I've filtered out some of the background noise so it's clearer to see the changes being made at a high level.

(and yes, my clocks are slightly out of sync)

Code: [Select]
2015-03-20 01:59:52 - ZWaveDeviceStatus state updated to PENDING
2015-03-20 01:59:52 - ZWaveLastHeal state updated to Uninitialized
2015-03-20 01:59:52 - ZWaveId state updated to 1
2015-03-20 02:33:02 - FamilyTheatreLightsDeviceStatus state updated to ERROR
2015-03-20 02:33:02 - FamilyMainLightsDeviceStatus state updated to ERROR
2015-03-20 02:33:02 - FamilyCabinetLightsLDeviceStatus state updated to ERROR
2015-03-20 02:33:02 - BackyardFloodLightsDeviceStatus state updated to ERROR
2015-03-20 02:33:02 - FamilyCabinetLightsRDeviceStatus state updated to ERROR
2015-03-20 02:33:02 - LivingPictureLightsDeviceStatus state updated to ERROR
2015-03-20 02:33:02 - LivingMainLightsDeviceStatus state updated to ERROR
2015-03-20 02:33:02 - LivingLampLightDeviceStatus state updated to ERROR
2015-03-20 02:33:02 - DiningMainLightsDeviceStatus state updated to ERROR
2015-03-20 02:33:02 - KitchenMainLightsDeviceStatus state updated to ERROR
2015-03-20 02:33:02 - KitchenIslandLightsDeviceStatus state updated to ERROR
2015-03-20 02:33:02 - KitchenCounterLightsDeviceStatus state updated to ERROR
2015-03-20 02:33:02 - PorchLightDeviceStatus state updated to ERROR
2015-03-20 02:33:02 - MasterLampDeviceStatus state updated to ERROR
2015-03-20 02:33:02 - LaundryModuleDeviceStatus state updated to ERROR
2015-03-20 02:33:02 - BackyardLightsDeviceStatus state updated to ERROR
2015-03-20 02:33:02 - UpstairsHallwayLightsDeviceStatus state updated to ERROR
2015-03-20 02:33:02 - GarageEntryLightsDeviceStatus state updated to ERROR
2015-03-20 02:33:02 - FrontEntryLightDeviceStatus state updated to ERROR
2015-03-20 02:33:02 - StaircaseLightsDeviceStatus state updated to ERROR
2015-03-20 02:33:02 - KitchenSinkLightDeviceStatus state updated to ERROR
2015-03-20 02:33:02 - MasterCeilingFanDeviceStatus state updated to ERROR
2015-03-20 02:33:02 - MasterLightsDeviceStatus state updated to ERROR
2015-03-20 02:33:02 - GuestBedroom3LightsDeviceStatus state updated to ERROR
2015-03-20 02:33:02 - FamilyCeilingFanDeviceStatus state updated to ERROR
2015-03-20 02:33:02 - LivingControllerDeviceStatus state updated to ERROR
2015-03-20 02:33:02 - MasterControllerDeviceStatus state updated to ERROR
2015-03-20 02:33:02 - PowerHotWaterPumpDeviceStatus state updated to ERROR
2015-03-20 02:33:02 - FamilyControllerDeviceStatus state updated to ERROR
2015-03-20 02:33:02 - FamilyLampLightDeviceStatus state updated to ERROR
2015-03-20 02:33:02 - GuestBedroom2LightsDeviceStatus state updated to ERROR
2015-03-20 02:33:02 - FamilyPictureLightDeviceStatus state updated to ERROR
2015-03-20 02:33:02 - KitchenPantryLightDeviceStatus state updated to ERROR
2015-03-20 02:33:02 - GarageDeadboltDeviceStatus state updated to ERROR
2015-03-20 02:33:02 - GarageLightsDeviceStatus state updated to ERROR
2015-03-20 02:33:02 - FamilySubwooferDeviceStatus state updated to ERROR
2015-03-20 02:33:02 - HallwayModuleDeviceStatus state updated to ERROR
2015-03-20 02:33:02 - MasterClosetLightsDeviceStatus state updated to ERROR
2015-03-20 02:33:02 - MasterMinimoteDeviceStatus state updated to ERROR
2015-03-20 02:33:02 - GuestBathFanDeviceStatus state updated to ERROR
2015-03-20 02:33:02 - MasterBathFanDeviceStatus state updated to ERROR
2015-03-20 02:33:02 - GarageSideLightDeviceStatus state updated to ERROR
2015-03-20 02:33:02 - PorchApplianceModuleDeviceStatus state updated to ERROR
2015-03-20 02:33:02 - GarageApplianceModuleDeviceStatus state updated to ERROR
2015-03-20 02:33:02 - MasterClosetFibaroLightDeviceStatus state updated to ERROR
2015-03-20 02:33:02 - ZWaveDeviceStatus state updated to SUCCESS
2015-03-20 02:33:02 - ZWaveLastHeal state updated to 2015-03-20T02:33:10
2015-03-20 02:33:02 - ZWaveId state updated to 1
2015-03-20 02:33:23 - ZWaveZWLastUpdate state updated to 2015-03-20T02:33:22
2015-03-20 02:33:23 - ZWaveNetStatusID state updated to 5
2015-03-20 02:33:23 - ZWaveNetStatusText state updated to #14: Getting the name
2015-03-20 02:33:23 - FamilyTheatreLightsDeviceStatus state updated to NONE
2015-03-20 02:33:23 - FamilyMainLightsDeviceStatus state updated to NONE
2015-03-20 02:33:23 - FamilyCabinetLightsLDeviceStatus state updated to NONE
2015-03-20 02:33:23 - BackyardFloodLightsDeviceStatus state updated to NONE
2015-03-20 02:33:24 - FamilyCabinetLightsRDeviceStatus state updated to NONE
2015-03-20 02:33:24 - LivingPictureLightsDeviceStatus state updated to NONE
2015-03-20 02:33:24 - LivingMainLightsDeviceStatus state updated to NONE
2015-03-20 02:33:24 - LivingLampLightDeviceStatus state updated to NONE
2015-03-20 02:33:24 - DiningMainLightsDeviceStatus state updated to NONE
2015-03-20 02:33:24 - KitchenMainLightsDeviceStatus state updated to NONE
2015-03-20 02:33:24 - KitchenIslandLightsDeviceStatus state updated to NONE
2015-03-20 02:33:24 - KitchenCounterLightsDeviceStatus state updated to NONE
2015-03-20 02:33:24 - PorchLightDeviceStatus state updated to NONE
2015-03-20 02:33:24 - MasterLampDeviceStatus state updated to NONE
2015-03-20 02:33:24 - LaundryModuleDeviceStatus state updated to NONE
2015-03-20 02:33:24 - BackyardLightsDeviceStatus state updated to NONE
2015-03-20 02:33:24 - UpstairsHallwayLightsDeviceStatus state updated to NONE
2015-03-20 02:33:24 - GarageEntryLightsDeviceStatus state updated to NONE
2015-03-20 02:33:24 - FrontEntryLightDeviceStatus state updated to NONE
2015-03-20 02:33:24 - StaircaseLightsDeviceStatus state updated to NONE
2015-03-20 02:33:24 - KitchenSinkLightDeviceStatus state updated to NONE
2015-03-20 02:33:24 - MasterCeilingFanDeviceStatus state updated to NONE
2015-03-20 02:33:24 - MasterLightsDeviceStatus state updated to NONE
2015-03-20 02:33:24 - GuestBedroom3LightsDeviceStatus state updated to NONE
2015-03-20 02:33:24 - FamilyCeilingFanDeviceStatus state updated to NONE
2015-03-20 02:33:24 - LivingControllerDeviceStatus state updated to PENDING
2015-03-20 02:33:24 - MasterControllerDeviceStatus state updated to PENDING
2015-03-20 02:33:24 - GarageDeadboltDeviceStatus state updated to NONE
2015-03-20 02:33:24 - GarageLightsDeviceStatus state updated to NONE
2015-03-20 02:33:24 - FamilySubwooferDeviceStatus state updated to NONE
2015-03-20 02:33:24 - PowerHotWaterPumpDeviceStatus state updated to NONE
2015-03-20 02:33:25 - HallwayModuleDeviceStatus state updated to NONE
2015-03-20 02:33:25 - MasterClosetLightsDeviceStatus state updated to NONE
2015-03-20 02:33:25 - MasterMinimoteDeviceStatus state updated to NONE
2015-03-20 02:33:25 - FamilyControllerDeviceStatus state updated to PENDING
2015-03-20 02:33:25 - FamilyLampLightDeviceStatus state updated to NONE
2015-03-20 02:33:25 - GuestBedroom2LightsDeviceStatus state updated to NONE
2015-03-20 02:33:25 - FamilyPictureLightDeviceStatus state updated to NONE
2015-03-20 02:33:25 - GuestBathFanDeviceStatus state updated to NONE
2015-03-20 02:33:25 - MasterBathFanDeviceStatus state updated to NONE
2015-03-20 02:33:25 - KitchenPantryLightDeviceStatus state updated to NONE
2015-03-20 02:33:25 - GarageSideLightDeviceStatus state updated to NONE
2015-03-20 02:33:25 - PorchApplianceModuleDeviceStatus state updated to NONE
2015-03-20 02:33:25 - GarageApplianceModuleDeviceStatus state updated to NONE
2015-03-20 02:33:25 - MasterClosetFibaroLightDeviceStatus state updated to NONE
2015-03-20 02:33:25 - ZWaveNetStatusText state updated to Configuring ZWave devices
2015-03-20 02:33:25 - ZWaveId state updated to 1
2015-03-20 02:33:26 - ZWaveNetStatusText state updated to #14: Setting special association
2015-03-20 02:33:26 - ZWaveId state updated to 1
2015-03-20 02:33:26 - ZWaveNetStatusText state updated to #51: Getting the name
2015-03-20 02:33:26 - ZWaveId state updated to 1
2015-03-20 02:33:26 - FamilyControllerDeviceStatus state updated to NONE
2015-03-20 02:33:27 - ZWaveNetStatusText state updated to #51: Purging associations
2015-03-20 02:33:27 - ZWaveId state updated to 1
2015-03-20 02:33:28 - ZWaveNetStatusText state updated to #51: Setting special association
2015-03-20 02:33:28 - ZWaveId state updated to 1
2015-03-20 02:33:33 - ZWaveNetStatusText state updated to #51: Setting user configuration
2015-03-20 02:33:33 - ZWaveId state updated to 1
2015-03-20 02:33:34 - LivingControllerDeviceStatus state updated to NONE
2015-03-20 02:33:34 - ZWaveNetStatusText state updated to #71: Getting the name
2015-03-20 02:33:34 - ZWaveId state updated to 1
2015-03-20 02:33:35 - ZWaveNetStatusText state updated to #71: Getting the manufacturer
2015-03-20 02:33:35 - ZWaveId state updated to 1
2015-03-20 02:33:35 - ZWaveNetStatusText state updated to #71: Purging associations
2015-03-20 02:33:35 - ZWaveId state updated to 1
2015-03-20 02:33:35 - ZWaveLastError state updated to Node 71 failed
2015-03-20 02:33:35 - ZWaveLastRouteFailure state updated to 2015-03-20T02:33:43
2015-03-20 02:33:35 - ZWaveId state updated to 1
2015-03-20 02:33:36 - ZWaveNetStatusText state updated to #71: Setting special association
2015-03-20 02:33:36 - ZWaveId state updated to 1
2015-03-20 02:33:44 - ZWaveNetStatusText state updated to #71: Setting user configuration
2015-03-20 02:33:44 - ZWaveId state updated to 1
2015-03-20 02:33:44 - MasterControllerDeviceStatus state updated to NONE
2015-03-20 02:33:47 - ZWaveNetStatusID state updated to 1
2015-03-20 02:33:47 - ZWaveId state updated to 1
2015-03-20 02:33:47 - ZWaveNetStatusText state updated to OK
2015-03-20 02:33:47 - ZWaveId state updated to 1
2015-03-20 02:34:07 - ZWaveDeviceStatus state updated to NONE
2015-03-20 02:48:54 - ZWaveLastError state updated to Poll failed
2015-03-20 02:48:54 - ZWaveId state updated to 1

The code hasn't been changed in a few weeks, but the latest code "filters" some of the actual state-changes going on during this time, so that openHAB won't see the 1000's of duplicate messages that MiOS spews out.

Due to the volume of unnecessary/duplicate crap they emit during the heal process, my Vera will often restart during that time...   Presumably this would also be true for any other control-point that's attached to your Vera during the Heal...

I was tempted to add some dynamic throttling to haul back openHAB when it detects that Vera is flapping, but I'd prefer they fix their bugs because the faster these control-point machines get, the worse that will be for the resource-constrained Vera units. 


Anyhow, if you want to email me your sanitized logs (gather them all) then I'm more than happy to look over them for you and make an assessment.

There are a zillion things that can trigger Vera to go bonkers ;)

Offline lolodomo

  • Beta Testers
  • Master Member
  • *****
  • Posts: 3484
  • Karma: +74/-10
Re: Using openHAB to minimizing Vera reloads
« Reply #2 on: March 20, 2015, 07:18:24 pm »
Here are my Vera logs the last minute before the crash (exit code 250):

Edit: extended traces provided later

I can see in the last lines: JobHandler_LuaUPnP::Reload: reload Critical 1 m_bCriticalOnly 0 dirty data 1
« Last Edit: March 20, 2015, 07:58:41 pm by lolodomo »

Offline guessed

  • Moderator
  • Master Member
  • *****
  • Posts: 5301
  • Karma: +92/-22
  • Release compat is not a bolted-on afterthought
Re: Using openHAB to minimizing Vera reloads
« Reply #3 on: March 20, 2015, 07:29:42 pm »
I typically want > 62 seconds, just in case.  I think you've only got 54s there, so the leading-edge indicators are missing.

PS: nice edit on the line truncate... but I still need 62 seconds worth.



Anyhow, a complete set would be:
a) openHAB logs/openhab.log
b) openHAB logs/events.log
c) Vera /var/logs/cmh/LuaUPnP.log
d) Vera /var/logs/cmh/NetworkMonitor.log
e) Vera output of "logread"
f) Vera output of "df -k"


Since there may be sensitive data, feel free to tarball them and send them to my private email.

Offline lolodomo

  • Beta Testers
  • Master Member
  • *****
  • Posts: 3484
  • Karma: +74/-10
Re: Using openHAB to minimizing Vera reloads
« Reply #4 on: March 20, 2015, 07:39:21 pm »
For your information, there is nothing special in my 2 openHAB log files except cyclic errors that are relative to the Netatmo binding. But that is not at the time the Vera reloads.

Offline guessed

  • Moderator
  • Master Member
  • *****
  • Posts: 5301
  • Karma: +92/-22
  • Release compat is not a bolted-on afterthought
Re: Using openHAB to minimizing Vera reloads
« Reply #5 on: March 20, 2015, 07:45:17 pm »
For the openHAB bits, I wanted to see how it handled the restart, and whether it was doing anything just prior that might have exacerbated the situation (higher rate of calls being the most common example). 

Most of these would require DEBUG Level tracing in openHAB.


For example, when I was looking at Vera's Heal operations, it was this rate-of-change information that let me know about the problems Vera has (well, this one 8) )

Offline lolodomo

  • Beta Testers
  • Master Member
  • *****
  • Posts: 3484
  • Karma: +74/-10
Re: Using openHAB to minimizing Vera reloads
« Reply #6 on: March 20, 2015, 07:46:11 pm »
Result of df -k

Filesystem           1K-blocks      Used Available Use% Mounted on
/dev/root                 4608      4608         0 100% /rom
tmpfs                    31240      5496     25744  18% /tmp
tmpfs                      512         0       512   0% /dev
/dev/mtdblock7           11264      6076      5188  54% /overlay
overlayfs:/overlay       11264      6076      5188  54% /
/dev/mtdblock8            4480      4480         0 100% /mios

Offline lolodomo

  • Beta Testers
  • Master Member
  • *****
  • Posts: 3484
  • Karma: +74/-10
Re: Using openHAB to minimizing Vera reloads
« Reply #7 on: March 20, 2015, 07:56:12 pm »
Here is a bigger part of my Vera log file just before the crash:

Code: [Select]
04      03/20/15 16:12:04.680   <Job ID="3563" Name="pollnode #35 4 cmds" Device="493" Created="2015-03-20 16:11:58" Started="2015-03-20 16:11:58" Completed="2015-03-20 16:12:04" Duration="6.578590000" Runtime="6.577202000" Status="Successful" LastNote="" Node="35" NodeType="ZWaveNonDimmableLight" NodeDescription="Lampe salon"/> <0x2be29680>
06      03/20/15 16:12:13.411   Device_Variable::m_szValue_set device: 203 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 01 7C 42 01 00 AE 23 02 69  now: 0A 52 01 7D C3 04 01 60 12 02 69  #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2dc7d680>
06      03/20/15 16:12:13.412   Device_Variable::m_szValue_set device: 203 service: urn:micasaverde-com:serviceId:HaDevice1 variable: CommFailure was: 0 now: 0 #hooks: 0 upnp: 0 v:0xa89c90/NONE duplicate:1 <0x2dc7d680>
06      03/20/15 16:12:13.417   Device_Variable::m_szValue_set device: 498 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1426864290 now: 1426864333 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2dc7d680>
06      03/20/15 16:12:13.439   Device_Variable::m_szValue_set device: 499 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1426864290 now: 1426864333 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2dc7d680>
06      03/20/15 16:12:13.850   Device_Variable::m_szValue_set device: 203 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 01 7D C3 04 01 60 12 02 69  now: 0A 52 01 7E 7D 02 00 AB 25 02 69  #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2dc7d680>
06      03/20/15 16:12:13.851   Device_Variable::m_szValue_set device: 203 service: urn:micasaverde-com:serviceId:HaDevice1 variable: CommFailure was: 0 now: 0 #hooks: 0 upnp: 0 v:0xa89c90/NONE duplicate:1 <0x2dc7d680>
06      03/20/15 16:12:13.854   Device_Variable::m_szValue_set device: 209 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1426864292 now: 1426864333 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2dc7d680>
06      03/20/15 16:12:13.856   Device_Variable::m_szValue_set device: 208 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1426864292 now: 1426864333 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2dc7d680>
06      03/20/15 16:12:24.150   Device_Variable::m_szValue_set device: 203 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 01 7E 7D 02 00 AB 25 02 69  now: 0A 52 01 7F 42 01 00 AE 23 02 69  #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2dc7d680>
06      03/20/15 16:12:24.151   Device_Variable::m_szValue_set device: 203 service: urn:micasaverde-com:serviceId:HaDevice1 variable: CommFailure was: 0 now: 0 #hooks: 0 upnp: 0 v:0xa89c90/NONE duplicate:1 <0x2dc7d680>
06      03/20/15 16:12:24.155   Device_Variable::m_szValue_set device: 496 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1426864305 now: 1426864344 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2dc7d680>
06      03/20/15 16:12:24.157   Device_Variable::m_szValue_set device: 497 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1426864305 now: 1426864344 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2dc7d680>
02      03/20/15 16:12:28.102   ZW_Send_Data node 3 NO ROUTE (nil) <0x2c229680>
04      03/20/15 16:12:28.229   <Job ID="3564" Name="pollnode #3 1 cmds" Device="4" Created="2015-03-20 16:12:28" Started="2015-03-20 16:12:28" Completed="2015-03-20 16:12:28" Duration="0.127266000" Runtime="0.126349000" Status="Successful" LastNote="" Node="3" NodeType="ZWaveNonDimmableLight" NodeDescription="Lampe chambre"/> <0x2be29680>
06      03/20/15 16:12:46.108   Device_Variable::m_szValue_set device: 493 service: urn:micasaverde-com:serviceId:EnergyMetering1 variable: KWH was: 6.3460 now: 6.3460 #hooks: 0 upnp: 0 v:0xa91bc8/NONE duplicate:1 <0x2be29680>
06      03/20/15 16:12:46.108   Device_Variable::m_szValue_set device: 493 service: urn:micasaverde-com:serviceId:EnergyMetering1 variable: KWHReading was: 1426864322 now: 1426864366 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2be29680>
06      03/20/15 16:12:46.724   Device_Variable::m_szValue_set device: 203 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 01 7F 42 01 00 AE 23 02 69  now: 0A 52 01 80 7D 02 00 AB 25 02 69  #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2dc7d680>
06      03/20/15 16:12:46.725   Device_Variable::m_szValue_set device: 203 service: urn:micasaverde-com:serviceId:HaDevice1 variable: CommFailure was: 0 now: 0 #hooks: 0 upnp: 0 v:0xa89c90/NONE duplicate:1 <0x2dc7d680>
06      03/20/15 16:12:46.728   Device_Variable::m_szValue_set device: 209 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1426864333 now: 1426864366 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2dc7d680>
06      03/20/15 16:12:46.746   Device_Variable::m_szValue_set device: 208 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1426864333 now: 1426864366 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2dc7d680>
06      03/20/15 16:12:48.294   Device_Variable::m_szValue_set device: 203 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 01 80 7D 02 00 AB 25 02 69  now: 0A 52 01 81 C3 04 01 60 12 02 69  #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2dc7d680>
06      03/20/15 16:12:48.295   Device_Variable::m_szValue_set device: 203 service: urn:micasaverde-com:serviceId:HaDevice1 variable: CommFailure was: 0 now: 0 #hooks: 0 upnp: 0 v:0xa89c90/NONE duplicate:1 <0x2dc7d680>
06      03/20/15 16:12:48.299   Device_Variable::m_szValue_set device: 498 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1426864333 now: 1426864368 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2dc7d680>
06      03/20/15 16:12:48.321   Device_Variable::m_szValue_set device: 499 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1426864333 now: 1426864368 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2dc7d680>
06      03/20/15 16:12:55.024   Device_Variable::m_szValue_set device: 203 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 01 81 C3 04 01 60 12 02 69  now: 0A 52 01 82 42 01 00 AE 23 02 69  #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2dc7d680>
06      03/20/15 16:12:55.025   Device_Variable::m_szValue_set device: 203 service: urn:micasaverde-com:serviceId:HaDevice1 variable: CommFailure was: 0 now: 0 #hooks: 0 upnp: 0 v:0xa89c90/NONE duplicate:1 <0x2dc7d680>
06      03/20/15 16:12:55.028   Device_Variable::m_szValue_set device: 496 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1426864344 now: 1426864375 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2dc7d680>
06      03/20/15 16:12:55.041   Device_Variable::m_szValue_set device: 497 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1426864344 now: 1426864375 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2dc7d680>
02      03/20/15 16:12:58.103   ZW_Send_Data node 8 NO ROUTE (nil) <0x2c229680>
04      03/20/15 16:12:58.241   <Job ID="3565" Name="pollnode #8 1 cmds" Device="7" Created="2015-03-20 16:12:58" Started="2015-03-20 16:12:58" Completed="2015-03-20 16:12:58" Duration="0.139887000" Runtime="0.138655000" Status="Successful" LastNote="" Node="8" NodeType="ZWaveDimmableLight" NodeDescription="Bandeau √©cran"/> <0x2be29680>
06      03/20/15 16:13:27.734   Device_Variable::m_szValue_set device: 203 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 01 82 42 01 00 AE 23 02 69  now: 0A 52 01 83 7D 02 00 AB 25 02 69  #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2dc7d680>
06      03/20/15 16:13:27.735   Device_Variable::m_szValue_set device: 203 service: urn:micasaverde-com:serviceId:HaDevice1 variable: CommFailure was: 0 now: 0 #hooks: 0 upnp: 0 v:0xa89c90/NONE duplicate:1 <0x2dc7d680>
06      03/20/15 16:13:27.738   Device_Variable::m_szValue_set device: 209 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1426864366 now: 1426864407 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2dc7d680>
06      03/20/15 16:13:27.759   Device_Variable::m_szValue_set device: 208 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1426864366 now: 1426864407 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2dc7d680>
02      03/20/15 16:13:28.103   ZW_Send_Data node 11 NO ROUTE (nil) <0x2c229680>
04      03/20/15 16:13:28.241   <Job ID="3566" Name="pollnode #11 1 cmds" Device="83" Created="2015-03-20 16:13:28" Started="2015-03-20 16:13:28" Completed="2015-03-20 16:13:28" Duration="0.139838000" Runtime="0.138577000" Status="Successful" LastNote="" Node="11" NodeType="ZWaveDimmableLight" NodeDescription="Lampe perron"/> <0x2be29680>
06      03/20/15 16:13:31.303   Device_Variable::m_szValue_set device: 203 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 01 83 7D 02 00 AB 25 02 69  now: 0A 52 01 84 C3 04 01 60 12 02 69  #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2dc7d680>
06      03/20/15 16:13:31.304   Device_Variable::m_szValue_set device: 203 service: urn:micasaverde-com:serviceId:HaDevice1 variable: CommFailure was: 0 now: 0 #hooks: 0 upnp: 0 v:0xa89c90/NONE duplicate:1 <0x2dc7d680>
06      03/20/15 16:13:31.308   Device_Variable::m_szValue_set device: 498 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1426864368 now: 1426864411 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2dc7d680>
06      03/20/15 16:13:31.328   Device_Variable::m_szValue_set device: 499 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1426864368 now: 1426864411 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2dc7d680>
06      03/20/15 16:13:34.034   Device_Variable::m_szValue_set device: 203 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 01 84 C3 04 01 60 12 02 69  now: 0A 52 01 85 42 01 00 AE 23 02 69  #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2dc7d680>
06      03/20/15 16:13:34.035   Device_Variable::m_szValue_set device: 203 service: urn:micasaverde-com:serviceId:HaDevice1 variable: CommFailure was: 0 now: 0 #hooks: 0 upnp: 0 v:0xa89c90/NONE duplicate:1 <0x2dc7d680>
06      03/20/15 16:13:34.038   Device_Variable::m_szValue_set device: 496 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1426864375 now: 1426864414 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2dc7d680>
06      03/20/15 16:13:34.059   Device_Variable::m_szValue_set device: 497 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1426864375 now: 1426864414 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2dc7d680>
06      03/20/15 16:13:38.010   Device_Variable::m_szValue_set device: 493 service: urn:micasaverde-com:serviceId:EnergyMetering1 variable: KWH was: 6.3460 now: 6.3460 #hooks: 0 upnp: 0 v:0xa91bc8/NONE duplicate:1 <0x2be29680>
06      03/20/15 16:13:38.011   Device_Variable::m_szValue_set device: 493 service: urn:micasaverde-com:serviceId:EnergyMetering1 variable: KWHReading was: 1426864366 now: 1426864418 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2be29680>
02      03/20/15 16:13:58.103   ZW_Send_Data node 32 NO ROUTE (nil) <0x2c229680>
04      03/20/15 16:13:58.241   <Job ID="3567" Name="pollnode #32 1 cmds" Device="360" Created="2015-03-20 16:13:58" Started="2015-03-20 16:13:58" Completed="2015-03-20 16:13:58" Duration="0.139802000" Runtime="0.138547000" Status="Successful" LastNote="" Node="32" NodeType="ZWaveDimmableLight" NodeDescription="Plafonnier Salon"/> <0x2be29680>
06      03/20/15 16:14:08.744   Device_Variable::m_szValue_set device: 203 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 01 85 42 01 00 AE 23 02 69  now: 0A 52 01 86 7D 02 00 AB 25 02 69  #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2dc7d680>
06      03/20/15 16:14:08.745   Device_Variable::m_szValue_set device: 203 service: urn:micasaverde-com:serviceId:HaDevice1 variable: CommFailure was: 0 now: 0 #hooks: 0 upnp: 0 v:0xa89c90/NONE duplicate:1 <0x2dc7d680>
06      03/20/15 16:14:08.748   Device_Variable::m_szValue_set device: 209 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1426864407 now: 1426864448 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2dc7d680>
06      03/20/15 16:14:08.760   Device_Variable::m_szValue_set device: 208 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1426864407 now: 1426864448 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2dc7d680>
06      03/20/15 16:14:13.044   Device_Variable::m_szValue_set device: 203 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 01 86 7D 02 00 AB 25 02 69  now: 0A 52 01 87 42 01 00 AE 23 02 69  #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2dc7d680>
06      03/20/15 16:14:13.045   Device_Variable::m_szValue_set device: 203 service: urn:micasaverde-com:serviceId:HaDevice1 variable: CommFailure was: 0 now: 0 #hooks: 0 upnp: 0 v:0xa89c90/NONE duplicate:1 <0x2dc7d680>
06      03/20/15 16:14:13.048   Device_Variable::m_szValue_set device: 496 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1426864414 now: 1426864453 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2dc7d680>
06      03/20/15 16:14:13.061   Device_Variable::m_szValue_set device: 497 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1426864414 now: 1426864453 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2dc7d680>
06      03/20/15 16:14:14.304   Device_Variable::m_szValue_set device: 203 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 01 87 42 01 00 AE 23 02 69  now: 0A 52 01 88 C3 04 01 5F 12 02 69  #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2dc7d680>
06      03/20/15 16:14:14.305   Device_Variable::m_szValue_set device: 203 service: urn:micasaverde-com:serviceId:HaDevice1 variable: CommFailure was: 0 now: 0 #hooks: 0 upnp: 0 v:0xa89c90/NONE duplicate:1 <0x2dc7d680>
06      03/20/15 16:14:14.309   Device_Variable::m_szValue_set device: 498 service: urn:upnp-org:serviceId:TemperatureSensor1 variable: CurrentTemperature was: 35.2 now: 35.1 #hooks: 0 upnp: 0 v:0xabe760/NONE duplicate:0 <0x2dc7d680>
06      03/20/15 16:14:14.328   Device_Variable::m_szValue_set device: 498 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1426864411 now: 1426864454 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2dc7d680>
06      03/20/15 16:14:14.351   Device_Variable::m_szValue_set device: 499 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1426864411 now: 1426864454 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2dc7d680>
03      03/20/15 16:14:18.727   JobHandler_LuaUPnP::Reload: reload Critical 1 m_bCriticalOnly 0 dirty data 1 <0x2ee7d680>
06      03/20/15 16:14:19.066   Device_Variable::m_szValue_set device: 1 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: NetStatusID was: 1 now: 2 #hooks: 0 upnp: 0 v:0xc2d8f0/NONE duplicate:0 <0x2ee7d680>
06      03/20/15 16:14:19.066   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:0xc4a4b0/NONE duplicate:0 <0x2ee7d680>
01      03/20/15 16:14:19.294   Mongoose XXX-mg_stop1 0xa4dd38 1 2 <0x2b6f6000>
02      03/20/15 16:14:19.358   luup_log:203: RFXtrx: warning: Bad starting message; ignore byte 69 <0x2dc7d680>
01      03/20/15 16:14:21.296   Mongoose XXX-mg_stop2 0xa4dd38 2 2 <0x2b6f6000>
01      03/20/15 16:14:21.296   Mongoose XXX-mg_stop3 0xa4dd38 2 2 <0x2b6f6000>
01      03/20/15 16:14:21.297   Mongoose XXX-mg_stop4 0xa4dd38 14485072 2 <0x2b6f6000>


2015-03-20 16:14:21 - LuaUPnP Terminated with Exit Code: 250



2015-03-20 16:14:21 - LuaUPnP crash

Offline guessed

  • Moderator
  • Master Member
  • *****
  • Posts: 5301
  • Karma: +92/-22
  • Release compat is not a bolted-on afterthought
Re: Using openHAB to minimizing Vera reloads
« Reply #8 on: March 20, 2015, 08:18:02 pm »
It's likely going to come down to what causes this:
Code: [Select]
    03      03/20/15 16:14:18.727   JobHandler_LuaUPnP::Reload: reload Critical 1 m_bCriticalOnly 0 dirty data 1 <0x2ee7d680>

and, backtracking a little, are any of the dying moment RFX Data packets (LastReceivedMsg) triggering the use of your AutoCreate Mode (or similar)?

Offline lolodomo

  • Beta Testers
  • Master Member
  • *****
  • Posts: 3484
  • Karma: +74/-10
Re: Using openHAB to minimizing Vera reloads
« Reply #9 on: March 21, 2015, 04:30:25 am »
It's likely going to come down to what causes this:
Code: [Select]
    03      03/20/15 16:14:18.727   JobHandler_LuaUPnP::Reload: reload Critical 1 m_bCriticalOnly 0 dirty data 1 <0x2ee7d680>

and, backtracking a little, are any of the dying moment RFX Data packets (LastReceivedMsg) triggering the use of your AutoCreate Mode (or similar)?

No, auto create is disabled and no new devices were created in the Vera.

Offline lolodomo

  • Beta Testers
  • Master Member
  • *****
  • Posts: 3484
  • Karma: +74/-10
Re: Using openHAB to minimize Vera reloads
« Reply #10 on: March 21, 2015, 04:36:26 am »
The last error relative to RFXtrx is not normal but I assume it is only a consequence of the crash.

By the way, I have a little fix to do because it was not my wish to have the CommFailure variable set at each message received.
« Last Edit: March 21, 2015, 04:40:49 am by lolodomo »

Offline lolodomo

  • Beta Testers
  • Master Member
  • *****
  • Posts: 3484
  • Karma: +74/-10
Re: Using openHAB to minimize Vera reloads
« Reply #11 on: March 21, 2015, 04:54:09 am »
I take a look what is my device 493, it is my Aeon Labs Smart Energy switch. It looks that it takes energy even when off. I hope that the unit is not what let suppose the name of the variable kWh !
« Last Edit: March 21, 2015, 04:55:47 am by lolodomo »

Offline lolodomo

  • Beta Testers
  • Master Member
  • *****
  • Posts: 3484
  • Karma: +74/-10
Re: Using openHAB to minimize Vera reloads
« Reply #12 on: March 21, 2015, 07:28:20 am »
One point to mention: the time in day when my Vera reloads is always the same when I don't change anything inside the Vera. But if I change something including manual Vera reloads, this time in the day will change.
For example, this morning, I have applied few changes to my RFXtrx plugin and so reloaded several times the Vera, I am almost certain that the unexpected reload will not occur at the same time as the previous days. But unfortunately, it will occur !

Offline guessed

  • Moderator
  • Master Member
  • *****
  • Posts: 5301
  • Karma: +92/-22
  • Release compat is not a bolted-on afterthought
Re: Using openHAB to minimize Vera reloads
« Reply #13 on: March 21, 2015, 11:07:42 am »
Given it's predictable, you'll need Verbose logs AND the other log data I indicated above.

It very well could be a Plugin, or even Vera, that's initiating the Reload action.  The Verbose logs, combined with the other Vera log I was looking for, will give a better picture.

Check out this for an example of "quirky" reload behavior introduced by Vera itself, for example:
    http://forum.micasaverde.com/index.php/topic,4782.msg159481.html#msg159481

and if a Plugin ever creates Devices on-the-fly, there's the potential for Vera (UI4/UI5) to trigger a reload, so it would be worthwhile triple-checking the codepaths to anything that use chdev and friends.

Offline lolodomo

  • Beta Testers
  • Master Member
  • *****
  • Posts: 3484
  • Karma: +74/-10
Re: Using openHAB to minimize Vera reloads
« Reply #14 on: March 21, 2015, 11:38:19 am »
Finally Vera reloaded today exactly at the same time as previous days...

Considering the small number of plugins now installed in my Vera,  I think only 2 of them are managing child devices, my  RFXtrx plugin that I know cannot be the problem (device creation is disabled) and the alarm plugin. I will add a log when this plugin changes child devices.