System started triggered every minute with 2.5.0 stable


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

fyi @cweitkamp

I was finally able to resolve this issue for my installation. This pointed me in the proper direction. Apparently a few thing definitions for zwave things had been changed leading to a re-read of my rules file every time one of them received an update. Per design this triggered the ‘system started’ rule. Due to the size of the rules file this took around 25-30 seconds, slowing down the system and making it difficult to correlate cause and effect. After deleting and rediscovering all zwave things the frequent system started triggers subsided and everything again works like a charm.

Nice to hear. In my config there is no zwave however :thinking:

It’s possible that one of the bindings you use had an updated Thing definition, which would need to be updated for existing Things just as the zwave Things are (delete and rediscover/recreate).

and that makes me wonder, @stefaanbolle how are your things defined? Are your things defined in Paper UI or text files? Sorry if I missed that info somewhere in previous post

That is probably still the case in my system. When restarting the system I still get 4 or 5 system started triggers, instead of a single one under 2.4. Those are obviously not triggered by zwave things any more, so there must be another binding causing the trouble. Will have to go through the release notes once more and maybe update those other things as well.

Out of interest: would defining things via text files make for automatic updating of things after changes to thing definitions? My things are all defined in Paper UI but it might be worth the trouble switching to text files if there is a benefit to it.

No, there is still no mechanism to update Thing definitions (see post 19). With non-managed Things, you need to remove the Thing files and then add them again to update the Thing definition. For zwave, you also can’t update your configuration parameters if using non-managed Things.

People claim it is better to use non-managed Things, since they can edit the files. But managed Things are stored in the JSONDB, which are files that can also be backed-up, edited, etc. There is no benefit at all and it is much more error-prone, so best to use managed Things.

1 Like

I agree Scott but what I’m wondering and why I asked stefaanbolle is because say this… a user uses a binding with a text file thing configuration and upgrades and the thing definition has changed and the text file thing is now incorrect. Could this possibly be what causes the problem with system started triggering repeatly

@mstormi put together a list of issues people have found in 2.5…

Thing definitions are a new angle on the issue. I would think incorrect manual Thing configuration could also cause issues, but I would expect that there would be errors from validation or the binding, if the configuration of a Thing in a .things file was incorrect. It may cause the startup issue too.

Thanks for the explanation! Still it seems much more appealing to me to remove and re-add my thing definition files than deleting and rediscovering all zwave things via Paper UI. After all, with no changes to the core planned until 3.0 I expect this problem to appear each time I upgrade the addons. I guess I will have a look into how to define things in text files and then decide which one is the lesser of two evils.

I stumbled upon your rule for automatic rediscovery as well, but didn’t dare to use it for fear of not being able to troubleshoot it if anything went wrong :grinning:. All this is still a little bit over my head.

Hi, I’m suffering this issue since 2.5.0, and had to rollback to 2.4.0 that is more than stable for me. Now thanks to this thread I decided to give a try to 2.5.2-1 and managed to delete and re-add some z-wave items and it is better now as it only fires “System restarted” a bunch of times around 2:30 am, the rest of the day it is fine (before it was restarting every few minutes all around the day in a quite random way)
But still some of the items I deleted and re-discovered continue generating the “Thing updated” message (always with messages stating that the item value changed from NULL to something) and then a System started

2020-03-21 02:36:48.266 [vent.ItemStateChangedEvent] - zwave_device_c464a06d_node5_blinds_control changed from NULL to 100
2020-03-21 02:36:48.282 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:c464a06d:node5' has been updated.
2020-03-21 02:36:49.673 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:c464a06d:node6' has been updated.
2020-03-21 02:36:49.710 [vent.ItemStateChangedEvent] - zwave_device_c464a06d_node10_switch_dimmer1 changed from NULL to 0
2020-03-21 02:36:49.719 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:c464a06d:node10' has been updated.
2020-03-21 02:36:49.800 [vent.ItemStateChangedEvent] - zwave_device_c464a06d_node11_meter_kwh changed from NULL to 15.49
2020-03-21 02:36:49.813 [vent.ItemStateChangedEvent] - zwave_device_c464a06d_node11_meter_watts changed from NULL to 0.8
2020-03-21 02:36:49.839 [vent.ItemStateChangedEvent] - zwave_device_c464a06d_node11_scene_number changed from NULL to 2.0
2020-03-21 02:36:49.864 [vent.ItemStateChangedEvent] - zwave_device_c464a06d_node11_switch_binary1 changed from NULL to OFF
2020-03-21 02:36:49.877 [vent.ItemStateChangedEvent] - zwave_device_c464a06d_node11_meter_kwh1 changed from NULL to 15.49
2020-03-21 02:36:49.889 [vent.ItemStateChangedEvent] - zwave_device_c464a06d_node11_meter_watts1 changed from NULL to 0.8
2020-03-21 02:36:49.900 [vent.ItemStateChangedEvent] - zwave_device_c464a06d_node11_switch_binary2 changed from NULL to OFF
2020-03-21 02:36:49.913 [vent.ItemStateChangedEvent] - zwave_device_c464a06d_node11_meter_kwh2 changed from NULL to 45.4
2020-03-21 02:36:49.925 [vent.ItemStateChangedEvent] - zwave_device_c464a06d_node11_meter_watts2 changed from NULL to 0
2020-03-21 02:36:49.930 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:c464a06d:node11' has been updated.
2020-03-21 02:36:56.349 [vent.ItemStateChangedEvent] - zwave_device_c464a06d_node10_switch_dimmer1 changed from NULL to 0
2020-03-21 02:36:56.364 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:c464a06d:node10' has been updated.

I tried to clear cache, restarting several times, but nothing