System started triggered every minute with 2.5.0 stable

I migrated from 2.5M4 to 2.5 andsince the migration, the system started rule is triggered almost every minute. The logs give no clue what is the reason.
Who can help me with the correct troubleshooting proces to find the cause. With M4 the problem was not there

1 Like

One of the most common reason for that is the addons.conf file has bad entries (if so, OH2 will try to reload files every minutes, which triggers the event you are seeing). Frequently, the restdocs is the culprit as it moved from misc to ui. There are multiple/many threads regarding this issue, in case you need more info.

1 Like

Mine wasn’t restarting every minute, but it was every few hours.

Eventually I noticed that there was an entry in the openhab.log reporting that misc-restdocs wasn’t being installed.

The Rest UI was installed and working, so I guessed it was something to do with the change between 2.4 and 2.5.

Sure enough, a little search on here found this… And now it’s back to a nice stable platform :slight_smile:

#1534 --- Failed installing 'openhab-misc-restdocs'

Read all of this thread, it certainly have me the right answer.

Obviously the cause of your restarts could be something totally different :frowning:

I do not think restdocs poses the problem

log:

2020-01-10 11:11:55.628 [INFO ] [lipse.smarthome.model.script.startup] - System initialised. System is now fully ready!
2020-01-10 11:12:56.683 [INFO ] [lipse.smarthome.model.script.startup] - System booted, now starting initialisation
2020-01-10 11:13:59.287 [INFO ] [lipse.smarthome.model.script.startup] - System booted, now starting initialisation
2020-01-10 11:13:59.344 [INFO ] [lipse.smarthome.model.script.startup] - System initialised. System is now fully ready!
2020-01-10 11:14:56.079 [INFO ] [lipse.smarthome.model.script.startup] - System booted, now starting initialisation
2020-01-10 11:15:56.686 [INFO ] [lipse.smarthome.model.script.startup] - System booted, now starting initialisation
2020-01-10 11:15:56.762 [INFO ] [lipse.smarthome.model.script.startup] - System initialised. System is now fully ready!
2020-01-10 11:16:56.140 [INFO ] [lipse.smarthome.model.script.startup] - System booted, now starting initialisation

cat /var/lib/openhab2/config/org/openhab/addons.config gives

:org.apache.felix.configadmin.revision:=L"33"
action=“mios”
binding=“airquality,astro,exec,http1,netatmo,network,ntp,samsungtv,openuv,mqtt,solarlog,openweathermap,logreader,icloud,chromecast,nikobus,tplinksmarthome,telegram,systeminfo”
felix.fileinstall.filename=“file:/var/lib/openhab2/etc/org.openhab.addons.cfg”
legacy=“false”
misc=“homekit,imperihome,ruleengine”
package=“minimal”
persistence=“gcal,mapdb,rrd4j”
remote=“true”
service.pid=“org.openhab.addons”
transformation=“exec,javascript,map,regex,jsonpath”
ui=“basic,paper,habpanel”
voice=“voicerss,googletts”

Remove the systeminfo binding per the upgrade notes.

Systeminfo Binding

The ‘cpu#load’ channel has been removed because the OSHI library no longer provides this information.

You will need to remove it from /var/lib/openhab2/config/org/openhab/addons.config but stop OH first, remove it, then clean the cache and reboot.

Followed your instructions, but same problem
cat /var/lib/openhab2/config/org/openhab/addons.config

:org.apache.felix.configadmin.revision:=L"33"
action=“mios”
binding=“airquality,astro,exec,http1,netatmo,network,ntp,samsungtv,openuv,mqtt,solarlog,openweathermap,logreader,icloud,chromecast,nikobus,tplinksmarthome,telegram”
felix.fileinstall.filename=“file:/var/lib/openhab2/etc/org.openhab.addons.cfg”
legacy=“false”
misc=“homekit,imperihome,ruleengine”
package=“minimal”
persistence=“gcal,mapdb,rrd4j”
remote=“true”
service.pid=“org.openhab.addons”
transformation=“exec,javascript,map,regex,jsonpath”
ui=“basic,paper,habpanel”
voice=“voicerss,googletts”

tail -f /var/log/openhab2/openhab.log

2020-01-10 20:40:35.069 [INFO ] [lipse.smarthome.model.script.startup] - System initialised. System is now fully ready!
2020-01-10 20:41:30.601 [INFO ] [lipse.smarthome.model.script.startup] - System booted, now starting initialisation
2020-01-10 20:42:34.789 [INFO ] [lipse.smarthome.model.script.startup] - System booted, now starting initialisation
2020-01-10 20:42:34.849 [INFO ] [lipse.smarthome.model.script.startup] - System initialised. System is now fully ready!
2020-01-10 20:43:33.460 [INFO ] [lipse.smarthome.model.script.startup] - System booted, now starting initialisation
2020-01-10 20:43:33.501 [INFO ] [lipse.smarthome.model.script.startup] - System initialised. System is now fully ready!
2020-01-10 20:44:32.223 [INFO ] [lipse.smarthome.model.script.startup] - System booted, now starting initialisation

I recently had the same thing after upgrading to 2.5 stable. In fact I did not find a solution and instead reinstated my former 2.4 installation. In my case the trigger for starting the system started rule was any change to a z-wave thing, e.g. a change of parameters. As one of my z-wave things receives a parameter update in the very same system started rule this led to an endless loop with 3 minutes cycle time (due to a built-in delay in execution of the rule).

I am still searching for a solution to this, but maybe the info helps you to troubleshoot your problem.

Thanks! I have no z-wave. Must be some thing change that triggers, but no clue how to find the culprit

Try stopping OH and cleaning the cache then restart OH (just clean cache once) a few times.

sudo systemclt stop openhab2

sudo openhab-cli clean-cache

sudo systemctl start openhab2 or sudo reboot

After OH has fully restarted, will take a few minuets after cleaning the cache, restart a few times. Just allow OH to fully load up between restarts.

sudo systemctl restart openhab2

Followed your instructions, but still the same. Will first upgrazde to v2.5.1 and check what that gives.

Another things to try is using the openhabain-config tool to set your rules to load after OH has started.

Uneducated comment only:
There are a bunch of threads knocking about with variations on this theme, 2.5 Thing updates triggering various levels of system start, Items reset to NULL, etc.

I note that 2.5 supposedly incorporates fixes over 2.4 for “ignored” Thing updates e.g. thing edit no longer requiring binding restart to pickup changes.

I can’t help think there is a connection. It might not be the “fault” of the changes directly, perhaps actions that didn’t used to invoke resets (but should have) now do.


I think your right. I am trying to find out whatbinding causes the trigger. However, I have no clue where or how to look for it.

The upgrade to 2.5.1-2 did not resolve the problem. It started with the stable release, the Milestone builds did not have the issue.

Thanks for that info! I am again on 2.5.0; not sure whether I’ll update from here or stay until 3.0 is released. For now I have worked around the issue and apart from that everything works fine. I have set up a rule with system started trigger creating a log entry, though. I’ll check for that regularly and report here when I have been able to isolate additional triggers.

Thanks for that. Due to the continue startup trigger, rules behave strange because cpu/OH is continuously busy with its system started trigger rule.

I’m experiencing the same issue, running 2.5.1 stable on a Raspberry Pi. I updated from 2.4 last week, but the intermittent triggering of my ‘System started’ rule only started happening yesterday. I set openhab logging to DEBUG but I’m not seeing a clear correlation with any preceding events or errors. [Edit: I’ve also cleared the cache]

The only suspicious thing is that I have a bunch of these “failed uninstalling openhab-ui-dashboard” errors, which I’ve seen mentioned on other threads. I’m not sure if it’s related.

2020-01-17 15:14:59.572 [DEBUG] [core.karaf.internal.FeatureInstaller] - Running scheduled sync job
2020-01-17 15:14:59.627 [DEBUG] [core.karaf.internal.FeatureInstaller] - Failed uninstalling 'openhab-ui-dashboard': Feature named 'openhab-ui-dashboard/0' is not installed
2020-01-17 15:15:00.682 [INFO ] [smarthome.model.script.default.rules] - System Started Rule Triggered

In the meantime, I’m logging when the rule gets triggered and I’ve moved my actual startup rules to be manually triggered with a switch.

Hello, I also had the same issue, a rule with “system started” triggered every minute after updating from 2.4 to 2.5.

I had moved from a Raspberry Pi3 with OH 2.4 (backup) to a Pi4 with 2.5 (restore from backup on a clean install).

After enabling the DEBUG log in
/var/lib/openhab2/etc/org.ops4j.pax.logging.cfg
editing this following line
log4j2.logger.smarthome.level = INFO
to
log4j2.logger.smarthome.level = DEBUG
I noticed that before the lines like “Refreshing resource ‘xxx.rules’” two “Update Element” lines were present:

[DEBUG] [mon.registry.AbstractManagedProvider] - Updated element yamahareceiver:zone:xxxx:Zone_2 in ManagedThingProvider.
[DEBUG] [mon.registry.AbstractManagedProvider] - Updated element yamahareceiver:zone:xxxx:Main_Zone in ManagedThingProvider.

so I completely uninstalled the Yamaha binding and things, restarted, re-added the binding and things, and now the rule with system started works as expected (not every minute!).
So after two crazy days I found that my offending binding was the Yamaha binding.
The thing had a different definition in the previous OH version, so maybe the new version was not detecting the new one correctly?

Hope this helps troubleshooting someone else.

Hi,

I and Sone others have also experienced this:


But for now, I have no solution…

In OH 2.5, there is no mechanism for a Thing to update when the definition is updated. When you upgrade a binding that had an updated Thing definition, such as the Z-Wave binding, you need to delete the Thing and add (or rediscover) it again. Hopefully, this will be one of the things added to the backlog for OH 3.0.

Nice, also has the Yamaha receiver binding, that could be the crulpit