Startup of openhab - user logic starting too soon

Hi,
we are using in our new home openhab on top of some technology stacks (KNX, MQTT, OneWire). A great system thanks for all the hard work that went into it.

We have encounteried a rather major issue after a reboot of the openhab server (wanted or unwanted - recently forced on us due to some KNX detach events, but that’s a separate topic):
The restart of the system is not taking into consideration the logical sequence of bindings/services: to start first with all bindings/services before any on-top-logic with items/rules and sitemaps may follow. items and rules are already starting before the needed bindings have been loaded (see log extract at the end of this post). This is causing some issues as rules and state forwarding do not work under these conditions.

And btw we are running on the latest snapshot of openhab:

103 │ Active   │  80 │ 0.9.0.201711242229     │ Eclipse SmartHome Config Core
185 │ Active   │  90 │ 2.2.0.201711242225     │ openHAB Core

So my question is: is there a way to influence and postpone the activation of user-logic until all the fundamental binding/service-infrastructure has started?
And yes - I am aware of the “System started” event and I am using it (already waiting for a minute to do stuff), but it does not help for direct links of items like this one:

Number N_EG_PYSY_T_Flur_Ist			"Ist-Temperatur Flur [%.1f °C]"	<temperature>	(Persistence) {onewire="deviceId=28_Temp_EGPYSY_Flur;propertyName=temperature", knx="4/1/5"}

nor can I determine within that rule whether a binding is already properly working.
Thank you very much for some guidance / help.
Regards,
Jens

Please see attached an extract of the openhab log that displays the sequence of startup activities [shortened due to the 32k character limit, so if you need more detail on some error messages, please let me know].

2017-11-25 16:56:56.529 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'muell.items'
2017-11-25 16:56:57.742 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'pumpe.items'
2017-11-25 16:56:58.378 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'UG_PYSY.items'
2017-11-25 16:56:59.212 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'persistence.items'
2017-11-25 16:56:59.921 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'DG_PYSY.items'
2017-11-25 16:57:01.044 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'lichter.items'
2017-11-25 16:57:01.627 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'fenster.items'
2017-11-25 16:57:03.269 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'EG_PYSY.items'
2017-11-25 16:57:05.573 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'externes.items'
2017-11-25 16:57:07.371 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'test.items'
2017-11-25 16:57:11.477 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'influxdb.persist'
2017-11-25 16:57:28.645 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'internet.sitemap', using it anyway:
Sitemap should contain either only frames or none at all
2017-11-25 16:57:28.704 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'internet.sitemap'
2017-11-25 16:57:29.981 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'heizung.sitemap'
2017-11-25 16:57:30.652 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'PySyBurg.sitemap'
2017-11-25 16:57:31.425 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'SyBurg.sitemap', using it anyway:
Sitemap should contain either only frames or none at all
2017-11-25 16:57:31.461 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'SyBurg.sitemap'
2017-11-25 16:57:32.220 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'wetter.sitemap'
2017-11-25 16:57:32.604 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'test.sitemap', using it anyway:
Sitemap should contain either only frames or none at all
2017-11-25 16:57:32.636 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'test.sitemap'
2017-11-25 16:57:48.434 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'reset.rules'
2017-11-25 16:57:48.788 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'admin.sitemap', using it anyway:
Sitemap should contain either only frames or none at all
2017-11-25 16:57:48.814 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'admin.sitemap'
2017-11-25 16:58:43.429 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'externes.rules', using it anyway:
The value of the local variable info1 is not used
The value of the local variable info2 is not used
The value of the local variable info3 is not used
2017-11-25 16:58:43.464 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'externes.rules'
2017-11-25 16:58:44.744 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'PyBurg.sitemap'
2017-11-25 16:58:46.386 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'ntp:ntp:local' to inbox.
2017-11-25 16:58:49.682 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2017-11-25 16:58:49.962 [ERROR] [org.apache.felix.scr                ] - Circular reference detected trying to get service {org.openhab.ui.dashboard.DashboardTile}={component.name=org.openhab.ui.basicui.dashboardtile, component.id=169, service.id=288, service.bundleid=210, service.scope=bundle}
	at  ....

2017-11-25 16:58:53.672 [INFO ] [nternal.connection.OneWireConnection] - Connected to owserver [IP '127.0.0.1' Port '4304']
2017-11-25 16:59:04.064 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'pumpen.rules'
2017-11-25 16:59:05.169 [INFO ] [penhab.io.transport.mqtt.MqttService] - MQTT Service initialization completed.
2017-11-25 16:59:05.196 [INFO ] [t.mqtt.internal.MqttBrokerConnection] - Starting MQTT broker connection 'altenburg'
2017-11-25 16:59:15.541 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'DG_PYSY.rules'
2017-11-25 16:59:16.768 [WARN ] [org.pcap4j.util.PropertiesLoader    ] - [org/pcap4j/pcap4j.properties] Could not get value by org.pcap4j.af.inet, use default value: null
2017-11-25 16:59:16.788 [WARN ] [org.pcap4j.util.PropertiesLoader    ] - [org/pcap4j/pcap4j.properties] Could not get value by org.pcap4j.af.inet6, use default value: null
2017-11-25 16:59:16.796 [WARN ] [org.pcap4j.util.PropertiesLoader    ] - [org/pcap4j/pcap4j.properties] Could not get value by org.pcap4j.af.packet, use default value: null
2017-11-25 16:59:16.808 [WARN ] [org.pcap4j.util.PropertiesLoader    ] - [org/pcap4j/pcap4j.properties] Could not get value by org.pcap4j.af.link, use default value: null
2017-11-25 16:59:17.079 [WARN ] [org.pcap4j.util.PropertiesLoader    ] - [org/pcap4j/pcap4j.properties] Could not get value by org.pcap4j.dlt.raw, use default value: null
2017-11-25 17:00:36.639 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'EG_PYSY.rules'
2017-11-25 17:00:47.243 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'UG_PYSY.rules', using it anyway:
The import 'org.joda.time.DateTime' is never used.
The value of the local variable raum1 is not used
The value of the local variable raum2 is not used
The value of the local variable raum3 is not used
2017-11-25 17:00:47.275 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'UG_PYSY.rules'
2017-11-25 17:00:51.481 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'test.rules'
2017-11-25 17:00:54.045 [INFO ] [thome.model.lsp.internal.ModelServer] - Language Server started on port 5007
2017-11-25 17:00:56.842 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'PySyBurg.things'
2017-11-25 17:00:58.445 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:sun:home
2017-11-25 17:00:59.092 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:moon:home
2017-11-25 17:00:59.175 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled Positional job astro:moon:home every 60 seconds
2017-11-25 17:00:59.556 [INFO ] [thome.binding.astro.internal.job.Job] - Scheduled Astro event-jobs for thing astro:moon:home
2017-11-25 17:00:59.587 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled Positional job astro:moon:home every 60 seconds
2017-11-25 17:01:05.320 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2017-11-25 17:01:06.701 [INFO ] [b.core.service.AbstractActiveService] - Exec Refresh Service has been started
2017-11-25 17:02:08.829 [INFO ] [e.smarthome.model.script.EG_PY_Rules] - sysStartLocalEG has been Set!
2017-11-25 17:02:15.908 [INFO ] [smarthome.model.script.UG_PYSY.rules] - Setze Heizung
2017-11-25 17:02:40.659 [INFO ] [.smarthome.model.script.pumpen.rules] - sysStartLocalPumpe has been Set!
2017-11-25 17:02:40.671 [INFO ] [smarthome.model.script.UG_PYSY.rules] - Setze Heizung, Wochentag=6, Index=34
2017-11-25 17:02:45.824 [INFO ] [marthome.model.script.externes.rules] - sysStartLocalExtern has been Set!
2017-11-25 17:02:45.830 [INFO ] [.smarthome.model.script.UGPYSY.rules] - sysStartLocalUG has been Set!
2017-11-25 17:02:45.880 [INFO ] [e.smarthome.model.script.DG_PY_Rules] - sysStartLocalOG has been Set!
2017-11-25 17:02:45.900 [INFO ] [marthome.model.script.externes.rules] - sysStartLocalExtern has been Set!
2017-11-25 17:02:45.903 [INFO ] [e.smarthome.model.script.DG_PY_Rules] - sysStartLocalOG has been Set!
2017-11-25 17:02:45.961 [INFO ] [.smarthome.model.script.UGPYSY.rules] - sysStartLocalUG has been Set!
2017-11-25 17:02:58.808 [WARN ] [ing.fritzboxtr064.internal.Tr064Comm] - No tr064 service found for service id urn:WLANConfiguration-com:serviceId:WLANConfiguration3
2017-11-25 17:02:58.863 [INFO ] [b.core.service.AbstractActiveService] - FritzboxTr064 Refresh Service has been started
2017-11-25 17:02:58.892 [INFO ] [tzboxtr064.internal.PhonebookManager] - Downloading phonebook ID 0
2017-11-25 17:03:00.805 [INFO ] [nx.internal.connection.KNXConnection] - Established connection to KNX bus on 192.168.0.200:3671 in mode TUNNEL.
2017-11-25 17:03:07.823 [INFO ] [g.fritzboxtr064.internal.CallMonitor] - Callmonitor Thread [312] attempting connection to FritzBox on 192.168.0.241:1012..
2017-11-25 17:03:07.831 [INFO ] [g.fritzboxtr064.internal.CallMonitor] - Connected to FritzBox on 192.168.0.241:1012
2017-11-25 17:04:02.285 [INFO ] [e.smarthome.model.script.EG_PY.rules] - sysStartLocalEG has been reset!
2017-11-25 17:04:02.278 [INFO ] [.smarthome.model.script.UGPYSY.rules] - sysStartLocalUG has been Set!
2017-11-25 17:04:02.303 [INFO ] [marthome.model.script.externes.rules] - sysStartLocalExtern has been Set!
2017-11-25 17:04:11.535 [INFO ] [.smarthome.model.script.pumpen.rules] - sysStartLocalPumpe has been reset!
2017-11-25 17:04:20.251 [INFO ] [.smarthome.model.script.pumpen.rules] - Betriebsstunden: 0.01 vs 0.0
2017-11-25 17:04:20.345 [INFO ] [smarthome.model.script.EG_PYSY_Rules] - Taster WZ wurde gedrückt
2017-11-25 17:04:20.353 [INFO ] [.smarthome.model.script.pumpen.rules] - Für das nächste mal ist die Pumpe Nr. 2 dran...
2017-11-25 17:04:20.359 [INFO ] [smarthome.model.script.EG_PYSY_Rules] - Taster WZ wurde gedrückt
2017-11-25 17:04:20.416 [INFO ] [marthome.model.script.externes.rules] - sysStartLocalExternes has been reset!

They are working on this: https://github.com/eclipse/smarthome/issues/1896

I observed similar things (see post).

Thanks a lot for the answer Dries, sounds like this a known problem, but unfortunately without priority? I have to say, I don’t agree on that - a system that’s not (recovery) fail-safe is very hard to manage…
But at least I learned that the usage of item.state == null and item.previousState=null might be a feasible workaround to identify uninitialised services.