i migrated my system from oh3.4.x to oh4.0.3. I’m using openhabian on a rpi4.
I mirgated the system via backup and restore.
It seems to work fine. But i have one big problem the things (still defined as text, and i don’t want to change it), don’t get reloaded when i reboot the rpi. Only if i clean the cache before reboot (via openhab-cli clean-cache) they get read, otherwise the first thing that gets parsed during starup are the *.items.
So of course this leads to problems, if the *.things are not loaded before the *.items.
Here is a part of the openhab.log. Can somebody help me?
2023-10-18 17:26:30.383 [INFO ] [org.openhab.core.Activator ] - Starting openHAB 4.0.3 (build Release Build)
2023-10-18 17:26:31.072 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Time zone set to 'Europe/Vienna'.
2023-10-18 17:26:31.087 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Location set to ''.
2023-10-18 17:26:31.089 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Locale set to 'de_DE'.
2023-10-18 17:26:31.090 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Measurement system set to 'SI'.
2023-10-18 17:26:58.184 [WARN ] [e.internal.SseItemStatesEventBuilder] - Attempting to send a state update of an item which doesn't exist: s_smartphone_thomas_state
2023-10-18 17:26:58.186 [WARN ] [e.internal.SseItemStatesEventBuilder] - Attempting to send a state update of an item which doesn't exist: s_smartphone_rebecca_state
2023-10-18 17:26:58.187 [WARN ] [e.internal.SseItemStatesEventBuilder] - Attempting to send a state update of an item which doesn't exist: n_waterTemp
2023-10-18 17:26:58.189 [WARN ] [e.internal.SseItemStatesEventBuilder] - Attempting to send a state update of an item which doesn't exist: n_pufferTempMean
2023-10-18 17:26:58.191 [WARN ] [e.internal.SseItemStatesEventBuilder] - Attempting to send a state update of an item which doesn't exist: Weather_Barometer
2023-10-18 17:26:58.192 [WARN ] [e.internal.SseItemStatesEventBuilder] - Attempting to send a state update of an item which doesn't exist: Weather_Temperature_2m
2023-10-18 17:26:58.194 [WARN ] [e.internal.SseItemStatesEventBuilder] - Attempting to send a state update of an item which doesn't exist: Weather_Humidity_2m
2023-10-18 17:26:58.196 [WARN ] [e.internal.SseItemStatesEventBuilder] - Attempting to send a state update of an item which doesn't exist: undefined
2023-10-18 17:26:58.197 [WARN ] [e.internal.SseItemStatesEventBuilder] - Attempting to send a state update of an item which doesn't exist: s_HeatingPower
2023-10-18 17:26:58.711 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'loc_firstfloor.items'
2023-10-18 17:26:59.238 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'non_loc_ical.items'
2023-10-18 17:26:59.422 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'non_loc.items'
2023-10-18 17:26:59.458 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'loc_sf_dressingroom.items'
2023-10-18 17:26:59.498 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'iRobot.items'
2023-10-18 17:26:59.521 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'loc_cellar.items'
2023-10-18 17:26:59.601 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'non_loc_system.items'
2023-10-18 17:26:59.649 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'loc_ff_livingroom.items'
2023-10-18 17:26:59.732 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'non_loc_fronius.items'
2023-10-18 17:26:59.835 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'loc_ff_toilet.items'
It’s never been the case that Things are initialized before the Items. The system runlevels are:
40: Rules Loaded
50: Rules Engine Started
70: User Interface Started 80: Things Initialized
100: Startup Complete
I can’t find the list of events that occur before 40 but IIRC 20 is bindings loaded and 30 is Items loaded.
What problems are you seeing (besides the Things not being loaded in the first place)?
Those “Attempting to send a state update” warnings are coming from your UI (Sitemap or MainUI). These subscribe to the event stream and depending on what’s loaded and being shown on the page at a given time you’ll see these these errors during startup because the event stream comes up before the Items are loaded.
There should be no problems if the Things are loaded and initialized after the Items.
The fact that the Things are not loaded at all is a problem. I have seen some file loader issues go by in openhab-core. I don’t pay too much attention to those but a quick search there might show if what you are seeing is a known problem or something new.
Ok. I didn’t know that, but these log say others anyway
2023-10-18 17:43:12.141 [INFO ] [org.openhab.core.Activator ] - Starting openHAB 4.0.3 (build Release Build)
2023-10-18 17:43:14.797 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Time zone set to 'Europe/Vienna'.
2023-10-18 17:43:14.811 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Location set to ''.
2023-10-18 17:43:14.812 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Locale set to 'de_DE'.
2023-10-18 17:43:14.814 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Measurement system set to 'SI'.
2023-10-18 17:43:32.458 [INFO ] [.core.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2023-10-18 17:43:34.872 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'iRobot.things'
2023-10-18 17:43:35.328 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'ipcamera.things'
2023-10-18 17:43:35.348 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'gardena.things'
2023-10-18 17:43:35.357 [WARN ] [el.core.internal.ModelRepositoryImpl] - Configuration model 'gardena.things' is either empty or cannot be parsed correctly!
2023-10-18 17:43:35.359 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'OoklasSpeedtest.things'
2023-10-18 17:43:35.771 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'remoteopenhab.things'
2023-10-18 17:43:35.792 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'knx.things'
2023-10-18 17:43:35.994 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'fritzbox.things'
2023-10-18 17:43:36.013 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'harmonyhub.things'
2023-10-18 17:43:36.038 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'systeminfo.things'
2023-10-18 17:43:36.059 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'ical.things'
2023-10-18 17:43:36.092 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'openweathermap.things'
2023-10-18 17:43:36.110 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'exec.things'
2023-10-18 17:43:36.128 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'shelly.things'
2023-10-18 17:43:36.147 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'ntp.things'
2023-10-18 17:43:36.164 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'bosesoundtouch.things'
2023-10-18 17:43:36.183 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'astro.things'
2023-10-18 17:43:36.200 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'fronius.things'
2023-10-18 17:43:36.222 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'jdbc.persist'
2023-10-18 17:43:36.525 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'loc_ff_kitchen.rules'
2023-10-18 17:43:38.847 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'non_loc_fronius.rules'
2023-10-18 17:43:42.778 [WARN ] [e.internal.SseItemStatesEventBuilder] - Attempting to send a state update of an item which doesn't exist: n_waterTemp
2023-10-18 17:43:42.779 [WARN ] [e.internal.SseItemStatesEventBuilder] - Attempting to send a state update of an item which doesn't exist: n_pufferTempMean
2023-10-18 17:43:42.781 [WARN ] [e.internal.SseItemStatesEventBuilder] - Attempting to send a state update of an item which doesn't exist: Weather_Barometer
2023-10-18 17:43:42.782 [WARN ] [e.internal.SseItemStatesEventBuilder] - Attempting to send a state update of an item which doesn't exist: Weather_Temperature_2m
2023-10-18 17:43:42.784 [WARN ] [e.internal.SseItemStatesEventBuilder] - Attempting to send a state update of an item which doesn't exist: Weather_Humidity_2m
2023-10-18 17:43:42.785 [WARN ] [e.internal.SseItemStatesEventBuilder] - Attempting to send a state update of an item which doesn't exist: undefined
2023-10-18 17:43:42.786 [WARN ] [e.internal.SseItemStatesEventBuilder] - Attempting to send a state update of an item which doesn't exist: s_HeatingPower
2023-10-18 17:43:42.994 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'loc_sf_bedroom.rules'
2023-10-18 17:43:43.585 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'loc_sf_bathroom.rules'
2023-10-18 17:43:46.518 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'loc_secondfloor.rules'
2023-10-18 17:43:51.139 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'loc_sf_livingroom_harmonyhub.rules'
2023-10-18 17:43:53.385 [INFO ] [nternal.manager.ShellyManagerServlet] - Shelly Manager gestartet und erreichbar unter http(s)://192.168.0.67:8080/shelly/manager
2023-10-18 17:43:53.580 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::openConnection: Driver is available::Yank setupDataSource
2023-10-18 17:43:55.255 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'non_loc_system.rules'
2023-10-18 17:43:55.612 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'loc_cellar.rules'
2023-10-18 17:43:56.250 [WARN ] [e.jpa.internal.JpaPersistenceService] - Connection URL is required in JPA configuration!
2023-10-18 17:43:56.471 [WARN ] [ty.util.ssl.SslContextFactory.config] - Trusting all certificates configured for Client@4aaaae[provider=null,keyStore=null,trustStore=null]
2023-10-18 17:43:56.472 [WARN ] [ty.util.ssl.SslContextFactory.config] - No Client EndPointIdentificationAlgorithm configured for Client@4aaaae[provider=null,keyStore=null,trustStore=null]
2023-10-18 17:43:56.473 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'loc_house.rules'
2023-10-18 17:43:56.605 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'loc_ff_livingroom.rules'
2023-10-18 17:43:57.223 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'loc_sf_housekeeping.rules'
2023-10-18 17:43:57.568 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'loc_firstfloor.items'
2023-10-18 17:43:57.823 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'non_loc_ical.items'
*.things get loaded before *.itmes. These logs are after cleaning the cache.
Anyway. This is not my problem. My problem is, that the Things don’t get loaded at all, when rebooting the rpi. There are no things after reboot. Even startup is at state 100!
The files get loaded but the Things don’t become initialized until after the Items are created. Until they are initialized, they don’t exist.
Agreed, which is why I recommended looking to see if the already open issues on .things files match what you are seeing or if you have a new problem. In either case, a fix is likely only going to be released to OH 4.1 so you might consider testing it in the latest milestone. Maybe it’s already fixed.
We haven’t been able to reproduce it but there will be some additional debug logging in OH 4.0.4 which can be enabled and may explain why it happens, see:
