Why my Vera reloads every day at same hour ?

Plugins & Plugin Development openHAB MiOS Binding
#1

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 ?

#2

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 ([tt]OH/logs/events.log[/tt]) to see exactly what is changing at that time, and of course the regular [tt]OH/logs/openhab.log[/tt] 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)

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 :wink:

#3

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

#4

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.

#5

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.

#6

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) )

#7

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

#8

Here is a bigger part of my Vera log file just before the crash:

[code]
04 03/20/15 16:12:04.680 <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 <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 <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 <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 <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[/code]

#9

It’s likely going to come down to what causes this:

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)?

#10

[quote=“guessed, post:9, topic:186523”]It’s likely going to come down to what causes this:

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)?[/quote]

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

#11

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.

#12

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 !

#13

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 !

#14

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.

#15

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.

#16

I just disabled the automatic creation option in the alarm plugin. I will see tomorrow what will happen.

#17

Here is my (very small) NetworkMonitor.log file.

02 03/21/15 15:48:02.771 Finished rotate logs <0x2b521460> 02 03/21/15 16:14:23.426 NetworkMonitor: CheckReport required handling <0x2b521460> 02 03/21/15 16:14:23.795 NetworkMonitor: CheckPortForward required handling <0x2b521460> 02 03/21/15 16:14:29.249 CheckHttpd does not exist /proc/10084/ <0x2b521460> 02 03/21/15 16:14:36.253 CheckHttpd slept 7 seconds, now will try again <0x2b521460>

while lua rpocess terminated at 16:14:28.

2015-03-21 16:14:28 - LuaUPnP Terminated with Exit Code: 250^[[1;00m

Is the CheckReport and CheckPortForward just 5 seconds before interesting ?

#18

Probably interesting things from logreader:

Mar 21 16:14:23 MiOS_35101033 user.notice mios_services[11976]: BEGIN Mar 21 16:14:23 MiOS_35101033 user.notice mios_services[11976]: Vera model is 'MiCasaVerde VeraLite', checking Z-Wave locale ... Mar 21 16:14:23 MiOS_35101033 user.notice mios_services[11976]: Same eu zw locale detected. Nothing to do. Mar 21 16:14:23 MiOS_35101033 user.notice mios_services[11976]: No update required for servers Mar 21 16:14:23 MiOS_35101033 user.notice mios_services[11976]: Sync MiOS Users required Mar 21 16:14:23 MiOS_35101033 user.notice mios_services[11976]: No update required for ergy conf Mar 21 16:14:23 MiOS_35101033 user.notice mios_services[11976]: MiOS RC: Got Values: (RA_Port|RA_Dissalowed) File: (0|0) Param: (0|0) Mar 21 16:14:23 MiOS_35101033 user.notice mios_services[11976]: No changes required for config_mios_rc Mar 21 16:14:23 MiOS_35101033 user.notice mios_services[11976]: No changes required for branding. Unit allready branded with FK_Branding=1. Mar 21 16:14:23 MiOS_35101033 user.notice mios_services[11976]: auto-upgrade is off Mar 21 16:14:23 MiOS_35101033 user.notice mios-sync_users[12024]: BEGIN Mar 21 16:14:23 MiOS_35101033 user.notice mios_services[11976]: auto-upgrade not pressent in cron Mar 21 16:14:23 MiOS_35101033 user.notice mios_services[11976]: No update required for locator.json Mar 21 16:14:23 MiOS_35101033 user.notice mios_services[11976]: END Mar 21 16:14:23 MiOS_35101033 user.notice mios-sync_users[12024]: Returning working server for MAIN=sta1.mios.com BCK=sta2.mios.com LAST=sta1.mios.com UseBCK(USE_ST_SRV_BCK=0) with do_report=0 Mar 21 16:14:23 MiOS_35101033 user.notice mios-sync_users[12024]: Testing connection to: sta1.mios.com on Port: 443 Mar 21 16:14:24 MiOS_35101033 user.notice mios-sync_users[12024]: 1 got response from sta1.mios.com Mar 21 16:14:24 MiOS_35101033 user.notice mios-sync_users[12024]: TestSeq=1 - Connection to: sta1.mios.com is 1 Mar 21 16:14:24 MiOS_35101033 user.notice mios-sync_users[12024]: sta1.mios.com Reached. Proceeding... Mar 21 16:14:24 MiOS_35101033 user.notice mios-sync_users[12024]: MAIN Working Mar 21 16:14:25 MiOS_35101033 user.notice mios-sync_users[12024]: Clearing all MiOS users Mar 21 16:14:25 MiOS_35101033 user.notice mios-sync_users[12024]: Clearing all Lighttpd users Mar 21 16:14:25 MiOS_35101033 user.notice mios-sync_users[12024]: ===AddMiosUsers: === Mar 21 16:14:25 MiOS_35101033 user.notice mios-sync_users[12024]: === Reload http server === Mar 21 16:14:25 MiOS_35101033 user.notice mios-sync_users[12024]: === Request LuaUPnP Reload === Mar 21 16:14:25 MiOS_35101033 user.notice set_led[12121]: === New call to /usr/bin/set_led.sh off zwave from /bin/sh -c /usr/bin/set_led.sh off zwave [12120] with parent /usr/bin/LuaUPnP [28574] === Mar 21 16:14:26 MiOS_35101033 user.notice mios-sync_users[12024]: END

I hope there is no critical information in this log.

Last lines could be interesting (mios-sync_users): Clearing all MiOS users then AddMiosUsers then Reload http server then Request LuaUPnP Reload

#19

[quote=“guessed, post:14, topic:186523”]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[/quote]

It looks like my today reload is exactly what you described.
And yes, I have disabled the Vera tunnel.
I tried your solution consisting in adding a # in the file /etc/cmh/users.conf
Will see tomorrow.

#20

Yup, there are a zillion ways Vera can kill itself off… 8)