There’s no systematic approach. As you spoke about a rule that takes 20 mins to load, I would believe you are in some form hitting or changing your .things, .items or .rules files.
ANY file modification (and be it just the file modification date or some editor to auto-save) will result in a reload AND THEY QUEUE UP. So if you edit a rules file and quickly save three times, your RPi will be busy for a full hour.
So on the one hand side try to reduce load times. It’s often primitives like .intValue() . Try if you can reduce usage.
On the other hand, validate your editing process. I have seen this at times when using VScode, maybe it does some sort of intermediate save of project data to affect your items or rules files.
Hi Markus,
thanks for your answer. I know the system can get clogged when editing rules on-the-fly. Usually I edit them in vim and that also is not the best idea.
But even without editing anything, the system startup rule seems to fire too often, doesn’t it? (That’s where I put the logInfo “READING RULES”)
Should it not only fire on startup of openhab?
Edit1: I think i have found something that coincides with the reloading of rule files!
2019-12-22 10:52:46.048 [vent.ItemStateChangedEvent] - zwave_device_Razberry2_node8_sensor_door changed from NULL to CLOSED
2019-12-22 10:52:46.225 [vent.ItemStateChangedEvent] - zwave_device_Razberry2_node8_battery_level changed from NULL to 100.0
2019-12-22 10:52:46.235 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:Razberry2:node8' has been updated.
and
2019-12-22 11:06:54.397 [vent.ItemStateChangedEvent] - zwave_device_Razberry2_node9_sensor_door changed from NULL to CLOSED
2019-12-22 11:06:54.449 [vent.ItemStateChangedEvent] - zwave_device_Razberry2_node9_battery_level changed from NULL to 100.0
2019-12-22 11:06:54.456 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:Razberry2:node9' has been updated.
Both being my zwave door sensors. I don’t know why they always change from NULL to CLOSED, even though they’re not triggered at all. I will try and find out what’s wrong here…
@mark_leonard_tuil I see you’re using zwave as well. Ca you check if you have something similar around the times where your rules reload?
Edit2: So my zwave door-sensors had a wake up interval of 3600 and every time they woke, the zwave thing got updated and the rules got reloaded. Which would be twice an hour because I have two sensors with the same configuration.
No I have set the wakeup interval of the thing to 36000 and voila, no rule reloading anymore!
I have seen the same behaviour since a couple of weeks. Not a clue to what is happening.
Are you sure? 2.5 has been released for only a week.
Many people have had issues with addons restarting once a minute due to bad entries, especially restdocs since it got moved from misc to ui, as documented in the Release Notes.
This was in the test version.
As I already wrote, for me it was because two zwave things were reconfigured every hour and that triggered a reloading of the rules.
Now I don’t think that this is supposed to happen, but at leas I was able to mitigate the impact by defining a longer wakeup interval.
Yes, I see something similar. Around the time that the rules restart, I see the following lines:
2019-12-23 05:48:12.750 [vent.ItemStateChangedEvent] - MotionSensorDouche_SensorLuminance changed from NULL to 0
2019-12-23 05:48:12.783 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:a93e88d5:node44' has been updated.
2019-12-23 05:48:16.696 [vent.ItemStateChangedEvent] - MotionSensorDouche_SensorLuminance changed from NULL to 0
2019-12-23 05:48:16.710 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:a93e88d5:node44' has been updated.
This is a Fibaro motion sensor. I have about ten of them around the house, but this is the only one that gives these kinds of lines (“changed from NULL to 0”). The wakeup interval is 7200 seconds, which is 2 hours, which corresponds to the rule reloading.
Edit:
To see if changing the wakeup time helps, I changed it to 720000. To speed up the change I pressed the button on the device 3 times. The rules are now reloading.
OK so we seem to have tracked it down to what might be the cause:
Zwave things get reconfigured and trigger a reload of the rules including the system startup trigger.
@mark_leonard_tuil can you try and get some debug log when you press the button? (in the console: log:set DEBUG org.openhab.binding.zwave)
I have done the same and we’ll see what it brings up…
1 Like
I have made a log. I must say I don’t see anything obvious, but then again, I don’t know what I am looking for. Just to give some background so far:
- My rules get reloaded every 2 hours.
- This corresponds to Z-wave node 44 (fibaro motion sensor) getting updated.
- I have replaced the battery of that device.
- I can trigger this by pressing the b-button 3x on this device.
- Pressing the b-button 3x on other devices does not have the same effect.
- I have made a log that starts with me pressing the b-button and stops with the first message of rules reloading.
openhab.log (71.9 KB)
I did another test. I use the Max! binding. It is a system to control heating radiators. Max! uses a local hub called the cube. The various radiotors get their imput form the cube. With the binding you can reset the cube. This results in the same reloading of rules behaviour. I have attached the log. I do not think there are entries that (should) account for the rules reloading behaviour. What I see is lines like:
2019-12-23 15:15:22.581 [hingStatusInfoChangedEvent] - 'max:bridge:KEQ0536973' changed from ONLINE to OFFLINE: Rebooting
2019-12-23 15:15:22.593 [hingStatusInfoChangedEvent] - 'max:wallthermostat:KEQ0536973:OEQ1035689' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2019-12-23 15:15:38.142 [me.event.ThingUpdatedEvent] - Thing 'max:bridge:KEQ0536973' has been updated.
2019-12-23 15:15:38.641 [me.event.ThingUpdatedEvent] - Thing 'max:wallthermostat:KEQ0536973:OEQ1035689' has been updated.
2019-12-23 15:15:38.684 [vent.ItemStateChangedEvent] - WallmountedThermostatSlaapkamer_SetTemperature changed from NULL to 16.0
2019-12-23 15:15:39.487 [hingStatusInfoChangedEvent] - 'max:wallthermostat:KEQ0536973:OEQ1035689' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-12-23 15:15:40.052 [vent.ItemStateChangedEvent] - ThermostatRadiatorWoonkamerRechts_SetTemperature changed from 20.5 to 0.0
However, I don’t think these events should cause the rules to reload. Nothing is changing about the things and items. All that is happening is things going offline and online and (as a result) things being updated.
Full log:
openhab.log (7.3 KB)
I have two situation where this happens. One is
2019-12-24 08:38:14.811 [WARN ] [o.internal.handler.SysteminfoHandler] - No information for channel battery#remainingCapacity with device index 0 :
2019-12-24 08:38:14.813 [WARN ] [o.internal.handler.SysteminfoHandler] - No information for channel battery#remainingTime with device index 0 :
2019-12-24 08:38:34.016 [INFO ] [.smarthome.model.script.System Rules] - System (re)started
and the other is
2019-12-24 09:48:59.284 [INFO ] [l.script.OUTSIDEDIMMABLELIGHTS_RULES] - astro_sun_local_phase_name.state: DAYLIGHT
2019-12-24 09:48:59.285 [INFO ] [.smarthome.model.script.System Rules] - System (re)started
Does this make sense to anyone?
The last one seems to be triggered by the astro add-on.
I have also the same behaviour with my fibaro motion sensor since openhab 2.5. After a thing update from my fibaro motion sensor my “system start” rule is triggered.
2019-12-25 14:38:12.393 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:f7e712f7:node25' has been updated.
2019-12-25 14:38:27.905 [INFO ] [e.smarthome.model.script.Systemstart] - Das System wurde neu gestartetIt seems like updates to things or things configurations or properties trigger the startup rules.
I tried to retrace the call stack (manually, not sure if this is 100% correct) and is something like this:
BaseThingHandler.updateThing | updateProperties | updateConfiguration
ThingManagerImpl.ThingHandlerCallback.thingUpdated
AbstractManagedProvider.update
AbstractProvider.notifyListeners
AbstractRegistry.updated
ThingRegistryImpl.notifyListenersAboutUpdatedElement
AbstractRegistry.notifyListenersAboutUpdatedElement
AbstractRegistry.notifyListeners
RuleEngineImpl.updated
RuleEngineImpl.added
RuleEngineImpl.scheduleStartupRules
I assume this is a desired behaviour by openHab (?) so the issue might be the bindings updating the things periodically. Now clear why this started apprearing with OH 2.5 though…
I notice the same, every few minutes thje system started rule is fired. However I do not see anything weird in the logs or events files. Did not occur with 2.5.Mx versions, only with the release version
I experienced the same.
For my particular box I solved it by 1) removing restdocs from misc in addons.cfg and restarting OH.
Surprisingly that fixed my zwave binding restarting issues
Same setup and behaviour here. My addons.cfg file is as defaults with all commented out (/etc/openhab2/services/addons.cfg, right?). I cleared cache and reseted a dozen of times. I receive the System started notification ramdomly, nothing special in the logs
I’m rolling back to my well proven and stable 2.4 by now… 
- Hardware: Rapsberry pi 3b+
- OS: Raspbian GNU/Linux 9 (stretch)
- Java Runtime Environment: openjdk version “1.8.0_222”
- openHAB version: 2.5.0.1
Need to verify addons.config also. Location is /var/lib/openhab2/config/org/openhab/addons.config
Do not make a change to this file with OH running. Stop OH, make change, clean cache, and restart.
Does this work like other 1.x style config files? i.e. don’t mess with it … just stop OH, delete addons.config, make sure addons.cfg is as you want it, reboot (addons.config recreated automatically)