- Platform information:
- Hardware: raspberry3
- OS: openhabian
- openHAB version: 2.2
- Issue of the topic:
I restartet openHAB2 via console with sudo restart now.
First the restart looks pretty good. All my items are showing up in the logfile. But suddenly several things are deleted. After comming back the default bindings are installed where most of them I deinstalled via PaperUI before. But my MAXbinding was not installed anymore.
The part of the logfile is more than 600 lines. I now try to post the most relevant:
2018-01-31 19:24:01.499 [vent.ItemStateChangedEvent] - maxValveBuero changed from 16 to 0
2018-01-31 19:24:01.519 [vent.ItemStateChangedEvent] - maxActualTempBuero changed from 23.7 to 24.7
2018-01-31 19:24:01.530 [vent.ItemStateChangedEvent] - max_thermostat_NEQ0101554_NEQ0100856_actual_temp changed from 23.7 to 24.7
2018-01-31 19:24:54.843 [vent.ItemStateChangedEvent] - ntp_ntp_local_dateTime changed from 2018-01-31T19:23:54.810+0100 to 2018-01-31T19:24:54.823+0100
2018-01-31 19:24:54.849 [vent.ItemStateChangedEvent] - ntp_ntp_local_string changed from 2018-01-31 19:23:54 CET to 2018-01-31 19:24:54 CET
2018-01-31 19:25:18.556 [hingStatusInfoChangedEvent] - 'ntp:ntp:forstweg' changed from ONLINE to UNINITIALIZED
2018-01-31 19:25:18.562 [hingStatusInfoChangedEvent] - 'ntp:ntp:forstweg' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2018-01-31 19:25:18.566 [hingStatusInfoChangedEvent] - 'ntp:ntp:local' changed from ONLINE to UNINITIALIZED
2018-01-31 19:25:18.575 [hingStatusInfoChangedEvent] - 'ntp:ntp:local' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2018-01-31 19:25:18.644 [hingStatusInfoChangedEvent] - 'max:thermostat:NEQ0101554:NEQ0100856' changed from ONLINE to UNINITIALIZED
2018-01-31 19:25:18.652 [hingStatusInfoChangedEvent] - 'max:thermostat:NEQ0101554:NEQ0100856' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
...
around 19:25 I restarted the system
...
2018-01-31 19:25:19.576 [temChannelLinkRemovedEvent] - Link 'maxModeBuero => max:thermostat:NEQ0101554:NEQ0100856:mode' has been removed.
2018-01-31 19:25:19.578 [temChannelLinkRemovedEvent] - Link 'maxSetTempBuero => max:thermostat:NEQ0101554:NEQ0100856:set_temp' has been removed.
...
all channnels have been removed
...
2018-01-31 19:25:53.583 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Locale set to de_DE, Location set to null, Time zone set to Europe/Berlin
2018-01-31 19:26:14.035 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'themostate.items'
2018-01-31 19:26:16.091 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'rrd4j.persist'
2018-01-31 19:26:21.790 [ERROR] [org.apache.felix.scr ] - Circular reference detected trying to get service {org.openhab.ui.dashboard.DashboardTile}={component.name=org.openhab.io.rest.docs.dashboardtile, component.id=139, service.id=238, service.bundleid=261, service.scope=bundle}
stack of references: ServiceReference: {org.openhab.ui.dashboard.DashboardTile}={component.name=org.openhab.io.rest.docs.dashboardtile, component.id=139, service.id=238, service.bundleid=261, service.scope=bundle}
...
thermostate.items and rrd4j.persist are reloded. Than an error was showing (I do not understand). After that a lott of numbers and letters. I guess some not readable data plus at the end a long stack trace…
After that we can see the following:
2018-01-31 19:26:22.376 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at http://192.168.1.110:8080
2018-01-31 19:26:22.295 [WARN ] [org.openhab.io.rest.docs ] - FrameworkEvent WARNING - org.openhab.io.rest.docs
org.osgi.framework.ServiceException: org.apache.felix.scr.impl.manager.SingleComponentManager.getService() returned a null service object
no idea if relevant
2018-01-31 19:26:22.475 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at https://192.168.1.110:8443
2018-01-31 19:26:24.212 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2018-01-31 19:26:25.858 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2018-01-31 19:26:29.997 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'demo.script'
2018-01-31 19:26:30.330 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'forstweg.sitemap'
2018-01-31 19:26:32.334 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2018-01-31 19:26:32.662 [vent.ItemStateChangedEvent] - maxSetTempBuero changed from NULL to 21.5
2018-01-31 19:26:32.676 [vent.ItemStateChangedEvent] - maxActualTempBuero changed from NULL to 24.699999999999999289457264239899814128875732421875
2018-01-31 19:26:32.701 [vent.ItemStateChangedEvent] - maxValveBuero changed from NULL to 0
2018-01-31 19:26:32.717 [vent.ItemStateChangedEvent] - maxWandBuero changed from NULL to 22.89999999999999857891452847979962825775146484375
2018-01-31 19:26:32.725 [vent.ItemStateChangedEvent] - maxWandSollBuero changed from NULL to 21.5
2018-01-31 19:26:32.761 [vent.ItemStateChangedEvent] - maxWandBadOben changed from NULL to 18.10000000000000142108547152020037174224853515625
...
Now all values are restored (great! That I was testing by the way)
2018-01-31 19:26:39.204 [vent.ItemStateChangedEvent] - ntp_ntp_local_string changed from NULL to 2018-01-31 19:26:38 CET
2018-01-31 19:26:39.521 [hingStatusInfoChangedEvent] - 'yahooweather:weather:bd6a79ad' changed from INITIALIZING to ONLINE
2018-01-31 19:26:39.527 [vent.ItemStateChangedEvent] - yahooweather_weather_bd6a79ad_temperature changed from NULL to 4
2018-01-31 19:26:39.538 [vent.ItemStateChangedEvent] - yahooweather_weather_bd6a79ad_humidity changed from NULL to 92
2018-01-31 19:26:39.546 [vent.ItemStateChangedEvent] - yahooweather_weather_bd6a79ad_pressure changed from NULL to 985.00
2018-01-31 19:26:39.624 [home.event.InboxAddedEvent] - Discovery Result with UID 'avmfritz:fritzbox:192_168_1_1' has been added.
2018-01-31 19:26:39.614 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'avmfritz:fritzbox:192_168_1_1' to inbox.
...
the above log is the rest of restoring. But stop! Why the FritzBox is added? I did not have had this configured I selected for my FritzBox to be hidden.
2018-01-31 19:26:45.081 [INFO ] [assic.internal.servlet.WebAppServlet] - Started Classic UI at /classicui/app
2018-01-31 19:26:45.259 [INFO ] [ulation.internal.HueEmulationServlet] - Started Hue Emulation service at /api
Why suddenly the Hue Emulation was started? I deleted the Hue Binding in PaperUI before!
2018-01-31 19:26:45.374 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Started HABmin servlet at /habmin
2018-01-31 19:26:45.431 [ERROR] [core.karaf.internal.FeatureInstaller] - Failed installing 'openhab-binding-hue, openhab-binding-ipp, openhab-misc-homekit, openhab-misc-restdocs, openhab-binding-astro, openhab-binding-wemo, openhab-binding-sonos, openhab-misc-hueemulation': Error restarting bundles:
Unable to acquire the state change lock for the module: osgi.identity; type="osgi.bundle"; version:Version="0.10.0.b1"; osgi.identity="org.eclipse.smarthome.model.script.runtime"; singleton:="true" [id=147] STARTED [STARTED]
All these bindings I deleted already. Why they do apear here?
2018-01-31 19:26:51.088 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'EG_Buero_thermostate.rules'
2018-01-31 19:26:54.398 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'sarah_thermostate.rules'
2018-01-31 19:26:55.160 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
until now I am not unhappy. But now I am confused:
2018-01-31 19:26:57.509 [INFO ] [core.karaf.internal.FeatureInstaller] - Uninstalled 'openhab-persistence-mapdb'
==> /var/log/openhab2/events.log <==
2018-01-31 19:26:57.526 [thome.event.ExtensionEvent] - Extension 'persistence-mapdb' has been uninstalled.
==> /var/log/openhab2/openhab.log <==
2018-01-31 19:27:04.057 [INFO ] [me.model.script.OG_Buero_thermostate] - Büro Temperatur mit tempMid initialisiert: 21.5 Fenster CLOSED
2018-01-31 19:27:04.057 [INFO ] [me.model.script.OG_Buero_thermostate] - Büro 21.5 vs Thermostat 21.5 Fenster CLOSED 0
2018-01-31 19:27:07.549 [INFO ] [core.karaf.internal.FeatureInstaller] - Uninstalled 'openhab-binding-silvercrestwifisocket'
==> /var/log/openhab2/events.log <==
2018-01-31 19:27:07.557 [thome.event.ExtensionEvent] - Extension 'binding-silvercrestwifisocket' has been uninstalled.
==> /var/log/openhab2/openhab.log <==
2018-01-31 19:27:12.926 [INFO ] [assic.internal.servlet.WebAppServlet] - Stopped Classic UI
2018-01-31 19:27:13.020 [INFO ] [core.karaf.internal.FeatureInstaller] - Uninstalled 'openhab-ui-classic'
==> /var/log/openhab2/events.log <==
2018-01-31 19:27:13.025 [thome.event.ExtensionEvent] - Extension 'ui-classic' has been uninstalled.
==> /var/log/openhab2/openhab.log <==
2018-01-31 19:27:19.144 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Stopped HABmin servlet
2018-01-31 19:27:19.235 [INFO ] [core.karaf.internal.FeatureInstaller] - Uninstalled 'openhab-ui-habmin'
==> /var/log/openhab2/events.log <==
2018-01-31 19:27:19.239 [thome.event.ExtensionEvent] - Extension 'ui-habmin' has been uninstalled.
==> /var/log/openhab2/openhab.log <==
2018-01-31 19:27:26.207 [INFO ] [core.karaf.internal.FeatureInstaller] - Uninstalled 'openhab-binding-network'
...
Now all the installed getting uninstalled! Why?
...
2018-01-31 19:27:33.697 [hingStatusInfoChangedEvent] - 'max:shuttercontact:NEQ0101554:NEQ0100026' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2018-01-31 19:27:33.705 [hingStatusInfoChangedEvent] - 'max:bridge:NEQ0101554' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
==> /var/log/openhab2/openhab.log <==
2018-01-31 19:27:33.744 [INFO ] [core.karaf.internal.FeatureInstaller] - Uninstalled 'openhab-binding-max'
...
at the end my MAX binding got uninstalled as well.
After reinstalling the MAX binding via PaperUI all items are reinstalled.
What did I wrong? All demo binding are again there but I unistalled them before my restart (days ago). My important MAX Binding was missing.
How can I make my installation more robust?
Is it me or is it a bug?