openHAB 4.0 Milestone discussion

moody_blue · May 26, 2023, 5:17pm

After converting from M2 to M3 I have these WARN’s in the log

2023-05-25 12:25:29.910 [WARN ] [d4j.internal.RRD4jPersistenceService] - Could not persist 'Videoporteiro__Silenciar_campainha_Running' to rrd4j database: Bad sample time: 1685013929. Last update time was 1685013929, at least one second step is required
2023-05-25 14:37:06.196 [WARN ] [d4j.internal.RRD4jPersistenceService] - Could not persist 'Sensormovimentopiso1_Occupancy' to rrd4j database: Bad sample time: 1685021821. Last update time was 1685021822, at least one second step is required
2023-05-25 20:47:06.428 [WARN ] [d4j.internal.RRD4jPersistenceService] - Could not persist 'Sensorhumidadeetemperaturacave_Temperature' to rrd4j database: Bad sample time: 1685044021. Last update time was 1685044023, at least one second step is required

Should I care about this ?

davesen · May 26, 2023, 8:42pm

Updated to M3 and now “myStrom” binding updates an item from a thing every defined refresh interval, so log will be spammed, although state of this item never changes. Here a sample, refresh interval is 10s default. Until M1 it worked correctly:

2023-05-26 22:37:07.081 [INFO ] [openhab.event.ItemStateUpdatedEvent ] - Item 'Ladegeraet' updated to OFF
2023-05-26 22:37:17.103 [INFO ] [openhab.event.ItemStateUpdatedEvent ] - Item 'Ladegeraet' updated to OFF
2023-05-26 22:37:27.127 [INFO ] [openhab.event.ItemStateUpdatedEvent ] - Item 'Ladegeraet' updated to OFF
2023-05-26 22:37:37.158 [INFO ] [openhab.event.ItemStateUpdatedEvent ] - Item 'Ladegeraet' updated to OFF
2023-05-26 22:37:47.184 [INFO ] [openhab.event.ItemStateUpdatedEvent ] - Item 'Ladegeraet' updated to OFF
2023-05-26 22:37:57.207 [INFO ] [openhab.event.ItemStateUpdatedEvent ] - Item 'Ladegeraet' updated to OFF
2023-05-26 22:38:07.234 [INFO ] [openhab.event.ItemStateUpdatedEvent ] - Item 'Ladegeraet' updated to OFF
2023-05-26 22:38:17.262 [INFO ] [openhab.event.ItemStateUpdatedEvent ] - Item 'Ladegeraet' updated to OFF
2023-05-26 22:38:27.286 [INFO ] [openhab.event.ItemStateUpdatedEvent ] - Item 'Ladegeraet' updated to OFF
2023-05-26 22:38:37.316 [INFO ] [openhab.event.ItemStateUpdatedEvent ] - Item 'Ladegeraet' updated to OFF
2023-05-26 22:38:47.348 [INFO ] [openhab.event.ItemStateUpdatedEvent ] - Item 'Ladegeraet' updated to OFF
2023-05-26 22:38:57.368 [INFO ] [openhab.event.ItemStateUpdatedEvent ] - Item 'Ladegeraet' updated to OFF
2023-05-26 22:39:07.397 [INFO ] [openhab.event.ItemStateUpdatedEvent ] - Item 'Ladegeraet' updated to OFF

Udo_Hartmann · May 26, 2023, 8:51pm

Set the suitable logger log level to ERROR. Log in to the Karaf Console, then

                           _   _     _     ____
   ___   ___   ___   ___  | | | |   / \   | __ )
  / _ \ / _ \ / _ \ / _ \ | |_| |  / _ \  |  _ \
 | (_) | (_) |  __/| | | ||  _  | / ___ \ | |_) )
  \___/|  __/ \___/|_| |_||_| |_|/_/   \_\|____/
       |_|       3.4.4 - Release Build

Use '<tab>' for a list of available commands
and '[cmd] --help' for help on a specific command.
To exit, use '<ctrl-d>' or 'logout'.

openhab> log:set ERROR openhab.event.ItemStateUpdatedEvent

(Version here is the stable, too lazy to do it with the stopped test system )

sijohula · May 27, 2023, 6:30am

Hello everyone,

I’m having the same issue OMR described.
After upgrading to OH4 M3, rules are no longer triggered. I’m using file based Rules DSL only.

uname output and java version are equal to those OMR already posted.

EDIT: I just noticed, that CPU consumption heavily increased after the upgrade. It seems to me, that one of the OH threads is looping infinitely. My OH instance is running inside a proxmox VM having 8 CPU threads.

J-N-K · May 27, 2023, 6:43am

But what is in the logs? Without logs it‘s nearly impossible to find out what is wrong.

sijohula · May 27, 2023, 6:58am

please find the openhab.log contents below.

2023-05-27 08:44:08.770 [INFO ] [org.openhab.core.Activator          ] - Starting openHAB 4.0.0.M3 (build Milestone Build)
2023-05-27 08:44:09.085 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Time zone set to 'Europe/Berlin'.
2023-05-27 08:44:09.086 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Locale set to 'de_DE'.
2023-05-27 08:44:09.086 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Measurement system set to 'SI'.
2023-05-27 08:44:09.374 [WARN ] [.transport.servlet.ServletController] - Can't find the request for http://openhab1....:8080/rest/events's Observer
2023-05-27 08:44:09.981 [WARN ] [emeris.internal.EphemerisManagerImpl] - Erroneous day set definition dayset-school: No enum constant java.time.DayOfWeek.
2023-05-27 08:44:09.982 [WARN ] [emeris.internal.EphemerisManagerImpl] - Erroneous day set definition dayset-weekend: No enum constant java.time.DayOfWeek.
2023-05-27 08:44:11.071 [WARN ] [core.karaf.internal.FeatureInstaller] - The binding add-on 'darksky' does not exist - ignoring it.
2023-05-27 08:44:11.085 [WARN ] [core.karaf.internal.FeatureInstaller] - The transformation add-on 'javascript' does not exist - ignoring it.
2023-05-27 08:44:11.090 [WARN ] [.transport.servlet.ServletController] - Can't find the request for http://192.168.81.4:8080/rest/events/states/4772f652-702e-4859-80ba-9ee84108115b's Observer
2023-05-27 08:44:12.208 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'opnsense.items'
2023-05-27 08:44:12.427 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'knx.items'
2023-05-27 08:44:15.017 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'idm_terra_swm.items'
2023-05-27 08:44:15.113 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'telegram.items'
2023-05-27 08:44:15.128 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'astro.items'
2023-05-27 08:44:15.149 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'pollen.items'
2023-05-27 08:44:15.238 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'ntp.items'
2023-05-27 08:44:15.244 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'walltablets.items'
2023-05-27 08:44:15.514 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'weather.items'
2023-05-27 08:44:15.546 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'waermepumpenzaehler.items'
2023-05-27 08:44:15.596 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'komfovent.items'
2023-05-27 08:44:15.689 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'nad_receiver.items'
2023-05-27 08:44:15.703 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'energymgmt.items'
2023-05-27 08:44:15.733 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'onewire_base.items'
2023-05-27 08:44:15.998 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'renault.items'
2023-05-27 08:44:16.013 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'openWB.items'
2023-05-27 08:44:16.040 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'Wall-E.items'
2023-05-27 08:44:16.044 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'APC_SmartUPS.items'
2023-05-27 08:44:16.063 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'touch1.items'
2023-05-27 08:44:16.068 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'kodi.items'
2023-05-27 08:44:16.087 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'fronius.items'
2023-05-27 08:44:16.177 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'dwdPVforcast.items'
2023-05-27 08:44:16.321 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'homeconnect.items'
2023-05-27 08:44:16.367 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model '0_semantic_model.items'
2023-05-27 08:44:16.475 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'knx_manual.items'
2023-05-27 08:44:16.565 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'hcl.items'
2023-05-27 08:44:16.590 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'lueftungStudio.items'
2023-05-27 08:44:16.607 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model '0_generic_groups.items'
2023-05-27 08:44:16.625 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'caldav.items'
2023-05-27 08:44:16.790 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'influxdb.persist'
2023-05-27 08:44:17.277 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mobotix.things'
2023-05-27 08:44:17.287 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'renault.things'
2023-05-27 08:44:17.294 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mqtt.things'
2023-05-27 08:44:17.317 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'onewire_base_hwif_og1.things'
2023-05-27 08:44:17.322 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'dwd_pollen.things'
2023-05-27 08:44:17.325 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'homeconnect.things'
2023-05-27 08:44:17.328 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'touch1.things'
2023-05-27 08:44:17.330 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'darksky.things'
2023-05-27 08:44:17.334 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'ntp.things'
2023-05-27 08:44:17.336 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'opnsense.things'
2023-05-27 08:44:17.339 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'komfovent.things'
2023-05-27 08:44:17.350 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'walltablet.things'
2023-05-27 08:44:17.358 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'fronius.things'
2023-05-27 08:44:17.363 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'telegram.things'
2023-05-27 08:44:17.365 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'onewire_base_hwif_kg.things'
2023-05-27 08:44:17.373 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'astro.things'
2023-05-27 08:44:17.375 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'knx.things'
2023-05-27 08:44:17.522 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'idm_terra_swm.things'
2023-05-27 08:44:17.529 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'onewire_base_hwif_og1-garage.things'
2023-05-27 08:44:17.533 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'kodi.things'
2023-05-27 08:44:21.600 [INFO ] [.core.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2023-05-27 08:44:21.726 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'nad_receiver.rules'
2023-05-27 08:44:22.851 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'komfovent.rules'
2023-05-27 08:44:23.980 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'knx.rules'
2023-05-27 08:44:25.977 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'cyclicRead.rules'
2023-05-27 08:44:26.374 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'fronius.rules'
2023-05-27 08:44:28.021 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'energymgmt.rules'
2023-05-27 08:44:28.661 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'walltablet.rules'
2023-05-27 08:44:29.498 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'opnsense.rules'
2023-05-27 08:44:29.790 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'hcl.rules'
2023-05-27 08:44:30.914 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'risk.rules'
2023-05-27 08:44:31.225 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'dwdPVforcast.rules'
2023-05-27 08:44:31.572 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'jalousie.rules'
2023-05-27 08:44:31.993 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'taupunkt.rules'
2023-05-27 08:44:31.999 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'vsbmlw.rules'
2023-05-27 08:44:32.284 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'idm_terra_swm.rules'
2023-05-27 08:44:32.622 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'pollen.rules'
2023-05-27 08:44:33.051 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'heating.rules'
2023-05-27 08:44:33.443 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'onewire.rules'
2023-05-27 08:44:33.444 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'telegram.rules'
2023-05-27 08:44:33.618 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'touch1.rules'
2023-05-27 08:44:33.619 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'lueftungStudio.rules'
2023-05-27 08:44:36.338 [INFO ] [o.internal.handler.AstroThingHandler] - Scheduled Positional job astro:sun:home every 60 seconds
2023-05-27 08:44:37.012 [INFO ] [rt.modbus.internal.ModbusManagerImpl] - Modbus manager activated
2023-05-27 08:44:37.319 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to 'localhost' with clientid 073ecb0a-0646-4c57-9344-e9cf9f2d4b4a
2023-05-27 08:44:38.591 [INFO ] [.influxdb.InfluxDBPersistenceService] - InfluxDB persistence service started.
2023-05-27 08:44:38.759 [INFO ] [ab.ui.habpanel.internal.HABPanelTile] - Started HABPanel at /habpanel
2023-05-27 08:44:48.933 [WARN ] [el.core.internal.ModelRepositoryImpl] - Configuration model 'taupunkt.rules' is either empty or cannot be parsed correctly!
2023-05-27 08:44:50.252 [WARN ] [el.core.internal.ModelRepositoryImpl] - Configuration model 'onewire.rules' is either empty or cannot be parsed correctly!
2023-05-27 08:44:50.525 [WARN ] [el.core.internal.ModelRepositoryImpl] - Configuration model 'touch1.rules' is either empty or cannot be parsed correctly!
2023-05-27 08:44:54.827 [WARN ] [sistence.internal.PersistenceManager] - Querying persistence service 'influxdb' takes more than 5000ms.

sijohula · May 27, 2023, 7:37am

after some more digging it seems to be some kind of intermittent problem.
I restarted OH about 10 times. In two out of ten cases, the rules engine came up fine and rules were processed as expected.

Please find the beginning of the openhab.log of the last successful start below:

2023-05-27 09:19:38.430 [INFO ] [org.openhab.core.Activator          ] - Starting openHAB 4.0.0.M3 (build Milestone Build)
2023-05-27 09:19:38.665 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Time zone set to 'Europe/Berlin'.
2023-05-27 09:19:38.666 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Locale set to 'de_DE'.
2023-05-27 09:19:38.667 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Measurement system set to 'SI'.
2023-05-27 09:19:39.394 [WARN ] [emeris.internal.EphemerisManagerImpl] - Erroneous day set definition dayset-school: No enum constant java.time.DayOfWeek.
2023-05-27 09:19:39.396 [WARN ] [emeris.internal.EphemerisManagerImpl] - Erroneous day set definition dayset-weekend: No enum constant java.time.DayOfWeek.
2023-05-27 09:19:39.442 [WARN ] [.transport.servlet.ServletController] - Can't find the request for http://openhab1....:8080/rest/events's Observer
2023-05-27 09:19:40.409 [WARN ] [.transport.servlet.ServletController] - Can't find the request for http://192.168.81.4:8080/rest/events/states/f9bfc959-3599-48a2-af97-629e97bab988's Observer
2023-05-27 09:19:40.433 [WARN ] [core.karaf.internal.FeatureInstaller] - The binding add-on 'darksky' does not exist - ignoring it.
2023-05-27 09:19:40.438 [WARN ] [.transport.servlet.ServletController] - Can't find the request for http://192.168.81.4:8080/rest/events/states/ce7df01d-d4d8-4699-828f-606d0ab220b8's Observer
2023-05-27 09:19:40.452 [WARN ] [core.karaf.internal.FeatureInstaller] - The transformation add-on 'javascript' does not exist - ignoring it.
2023-05-27 09:19:41.156 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'opnsense.items'
2023-05-27 09:19:41.364 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'knx.items'
2023-05-27 09:19:44.210 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'idm_terra_swm.items'
2023-05-27 09:19:44.304 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'telegram.items'
2023-05-27 09:19:44.320 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'astro.items'
2023-05-27 09:19:44.341 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'pollen.items'
2023-05-27 09:19:44.435 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'ntp.items'
2023-05-27 09:19:44.441 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'walltablets.items'
2023-05-27 09:19:44.710 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'weather.items'
2023-05-27 09:19:44.755 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'waermepumpenzaehler.items'
2023-05-27 09:19:44.827 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'komfovent.items'
2023-05-27 09:19:44.962 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'nad_receiver.items'
2023-05-27 09:19:44.980 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'energymgmt.items'
2023-05-27 09:19:45.018 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'onewire_base.items'
2023-05-27 09:19:45.250 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'renault.items'
2023-05-27 09:19:45.265 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'openWB.items'
2023-05-27 09:19:45.292 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'Wall-E.items'
2023-05-27 09:19:45.296 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'APC_SmartUPS.items'
2023-05-27 09:19:45.314 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'touch1.items'
2023-05-27 09:19:45.319 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'kodi.items'
2023-05-27 09:19:45.336 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'fronius.items'
2023-05-27 09:19:45.424 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'dwdPVforcast.items'
2023-05-27 09:19:45.570 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'homeconnect.items'
2023-05-27 09:19:45.618 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model '0_semantic_model.items'
2023-05-27 09:19:45.739 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'knx_manual.items'
2023-05-27 09:19:45.838 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'hcl.items'
2023-05-27 09:19:45.864 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'lueftungStudio.items'
2023-05-27 09:19:45.881 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model '0_generic_groups.items'
2023-05-27 09:19:45.899 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'caldav.items'
2023-05-27 09:19:46.048 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'influxdb.persist'
2023-05-27 09:19:46.249 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'all.sitemap'
2023-05-27 09:19:46.558 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mobotix.things'
2023-05-27 09:19:46.574 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'renault.things'
2023-05-27 09:19:46.586 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mqtt.things'
2023-05-27 09:19:46.636 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'onewire_base_hwif_og1.things'
2023-05-27 09:19:46.645 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'dwd_pollen.things'
2023-05-27 09:19:46.650 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'homeconnect.things'
2023-05-27 09:19:46.654 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'touch1.things'
2023-05-27 09:19:46.658 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'darksky.things'
2023-05-27 09:19:46.663 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'ntp.things'
2023-05-27 09:19:46.666 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'opnsense.things'
2023-05-27 09:19:46.670 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'komfovent.things'
2023-05-27 09:19:46.684 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'walltablet.things'
2023-05-27 09:19:46.693 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'fronius.things'
2023-05-27 09:19:46.701 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'telegram.things'
2023-05-27 09:19:46.705 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'onewire_base_hwif_kg.things'
2023-05-27 09:19:46.714 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'astro.things'
2023-05-27 09:19:46.718 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'knx.things'
2023-05-27 09:19:46.906 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'idm_terra_swm.things'
2023-05-27 09:19:46.914 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'onewire_base_hwif_og1-garage.things'
2023-05-27 09:19:46.918 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'kodi.things'
2023-05-27 09:19:49.074 [INFO ] [.core.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2023-05-27 09:19:49.176 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'nad_receiver.rules'
2023-05-27 09:19:50.376 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'komfovent.rules'
2023-05-27 09:19:51.694 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'knx.rules'
2023-05-27 09:19:53.746 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'cyclicRead.rules'
2023-05-27 09:19:54.174 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'fronius.rules'
2023-05-27 09:19:56.091 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'energymgmt.rules'
2023-05-27 09:19:56.790 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'walltablet.rules'
2023-05-27 09:19:57.653 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'opnsense.rules'
2023-05-27 09:19:57.946 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'hcl.rules'
2023-05-27 09:19:59.056 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'risk.rules'
2023-05-27 09:19:59.389 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'dwdPVforcast.rules'
2023-05-27 09:19:59.730 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'jalousie.rules'
2023-05-27 09:20:00.177 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'vsbmlw.rules'
2023-05-27 09:20:00.378 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'idm_terra_swm.rules'
2023-05-27 09:20:00.771 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'pollen.rules'
2023-05-27 09:20:01.251 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'heating.rules'
2023-05-27 09:20:01.726 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'telegram.rules'
2023-05-27 09:20:01.951 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'lueftungStudio.rules'
2023-05-27 09:20:02.599 [WARN ] [el.core.internal.ModelRepositoryImpl] - Configuration model 'mobotix.things' is either empty or cannot be parsed correctly!
2023-05-27 09:20:04.785 [INFO ] [o.internal.handler.AstroThingHandler] - Scheduled Positional job astro:sun:home every 60 seconds
2023-05-27 09:20:05.475 [INFO ] [rt.modbus.internal.ModbusManagerImpl] - Modbus manager activated
2023-05-27 09:20:05.620 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to 'localhost' with clientid c3ea9c62-55ee-44a9-8976-c386555911ef
2023-05-27 09:20:05.629 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to '192.168.82.41' with clientid 4dd0283a-cb5c-491c-af3f-99b8e7b613a5
2023-05-27 09:20:06.909 [INFO ] [.influxdb.InfluxDBPersistenceService] - InfluxDB persistence service started.
2023-05-27 09:20:07.105 [INFO ] [ab.ui.habpanel.internal.HABPanelTile] - Started HABPanel at /habpanel
2023-05-27 09:20:29.720 [INFO ] [enhab.core.model.script.NAD Receiver] - rule has been triggered. Scheduling Timer to run actual initialization process...
2023-05-27 09:20:29.722 [INFO ] [ript.KNX initialize control channels] - rule has been triggered. Scheduling Timer to run actual initialization process...
2023-05-27 09:20:29.723 [INFO ] [e.automation.internal.RuleEngineImpl] - Rule engine started.

jimmbimm · May 27, 2023, 8:42am

I started to prepare for OH4 and encountered the same issue also with a clean install of openhabian on a rpi4 with Java17, OH 4.0.0.M3 and Enocean USB300 and nothing else but the Enocean binding.

The same settings work fine with OH 3.4.4.

Any ideas or help would be highly appreciated.

glen_m · May 28, 2023, 7:52am

Just in case anyone else trips up over this issue, In APT upgrade on Ubuntu, Ctrl-C didn’t seem to be an option to halt the process (maybe was spawned?).

Connect to the server via a separate SSH session and:

user@server:~$ sudo ps -ef |grep openhab
### Following list shortened for clarity

root      804149  804144  0 18:12 pts/2    00:00:00 /bin/sh /var/lib/dpkg/info/openhab.postinst configure 4.0.0~M2-1
root      804218  804149  0 18:12 pts/2    00:00:00 java -jar /usr/share/openhab/runtime/bin/upgradetool.jar


user@server:~$ sudo kill 804218

Obviously replacing the Process ID with the actual one (on the LH side column) of the upgradetool.jar process

Back over on the session where the APT upgrade running, the bottom 3 lines (below section) will then appear, and things will carry on.

Setting up openhab (4.0.0~M3-1) ...

[openHAB] Running JSON Database upgrade tool (${OPENHAB_RUNTIME}/bin/upgradetool.jar).
[main] INFO org.openhab.core.tools.internal.Upgrader - Copying item unit from state description to metadata in database '/var/lib/openhab/jsondb/org.openhab.core.items.Item.json'
Exception in thread "main" java.lang.NullPointerException: Cannot invoke "String.contains(java.lang.CharSequence)" because "pattern" is null
	at org.openhab.core.tools.internal.Upgrader.lambda$0(Upgrader.java:104)
	at java.base/java.util.concurrent.ConcurrentHashMap$KeySetView.forEach(ConcurrentHashMap.java:4706)
	at org.openhab.core.tools.internal.Upgrader.itemCopyUnitToMetadata(Upgrader.java:93)
	at org.openhab.core.tools.UpgradeTool.main(UpgradeTool.java:79)
[openHAB] WARNING: internal database upgrade tool failed.
[openHAB] please check the openHAB website (www.openhab.org) for upgrade requirements.
Setting up openhab-addons (4.0.0~M3-1) ...

After that, rebooted the system (but a service restart would be fine), and left plenty of time for OpenHAB to start, as I usually see some funky stuff after any upgrade, which comes right after a while.

Seem to be running ok on 4.0.0-M3 now after the above intervention.

OMR · May 28, 2023, 8:23am

I’m away from home, but I too get the influxDB timeout, so that is a common denominator and that sticks out as a difference in your 2 logs.

OMR · May 28, 2023, 11:15am

Here is the log from a M3 startup that failed to start the rules engine.
After 10min I downgraded to M2 again.
The influxDB timeout is present on M2 as well. Will start a separate thread on that issue.

omr@shs2:~$ zcat /var/log/openhab/openhab.log.1.gz
2023-05-25 23:30:13.633 [INFO ] [org.openhab.core.Activator          ] - Starting openHAB 4.0.0.M3 (build Milestone Build)
2023-05-25 23:30:14.731 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Time zone set to 'Europe/Oslo'.
2023-05-25 23:30:14.742 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Location set to '59.9026989087956,10.495143905282024'.
2023-05-25 23:30:14.746 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Locale set to 'en_NO'.
2023-05-25 23:30:14.748 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Measurement system set to 'SI'.
2023-05-25 23:30:15.543 [WARN ] [.transport.servlet.ServletController] - Can't find the request for http://shs2:8080/rest/events's Observer
2023-05-25 23:30:15.548 [WARN ] [.transport.servlet.ServletController] - Can't find the request for http://shs2:8080/rest/events's Observer
2023-05-25 23:30:17.493 [WARN ] [emeris.internal.EphemerisManagerImpl] - Erroneous day set definition dayset-workday: No enum constant java.time.DayOfWeek.
2023-05-25 23:30:17.496 [WARN ] [emeris.internal.EphemerisManagerImpl] - Erroneous day set definition dayset-default: No enum constant java.time.DayOfWeek.
2023-05-25 23:30:17.499 [WARN ] [emeris.internal.EphemerisManagerImpl] - Erroneous day set definition dayset-trash: No enum constant java.time.DayOfWeek.
2023-05-25 23:30:17.505 [WARN ] [emeris.internal.EphemerisManagerImpl] - Erroneous day set definition dayset-weekend: No enum constant java.time.DayOfWeek.
2023-05-25 23:30:17.564 [WARN ] [.transport.servlet.ServletController] - Can't find the request for http://shs2:8080/rest/events's Observer
2023-05-25 23:30:17.566 [WARN ] [.transport.servlet.ServletController] - Can't find the request for http://shs2:8080/rest/events's Observer
2023-05-25 23:30:17.708 [WARN ] [.transport.servlet.ServletController] - Can't find the request for http://localhost:8080/rest/items/GTV7PowerConsumption's Observer
2023-05-25 23:30:19.960 [WARN ] [core.karaf.internal.FeatureInstaller] - The transformation add-on 'javascript' does not exist - ignoring it.
2023-05-25 23:30:21.718 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'hue.items'
2023-05-25 23:30:22.576 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'LAN.items'
2023-05-25 23:30:22.687 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'Z-wave.items'
2023-05-25 23:30:23.460 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'automower.items'
2023-05-25 23:30:23.542 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'nanoleaf.items'
2023-05-25 23:30:23.574 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'AC.items'
2023-05-25 23:30:23.599 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'Tradfri.items'
2023-05-25 23:30:23.660 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mi.items'
2023-05-25 23:30:23.791 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'Virtual.items'
2023-05-25 23:30:24.135 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'deconz.items'
2023-05-25 23:30:24.232 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'Squeezebox.items'
2023-05-25 23:30:24.294 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'Groups.items'
2023-05-25 23:30:24.963 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'influxdb.persist'
2023-05-25 23:30:25.458 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'GTV7.sitemap'
2023-05-25 23:30:26.345 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'automower.things'
2023-05-25 23:30:26.401 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mail.things'
2023-05-25 23:30:26.405 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'squeeze.things'
2023-05-25 23:30:26.416 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'astro.things'
2023-05-25 23:30:26.427 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'deconz.things'
2023-05-25 23:30:32.758 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'allOff.script'
2023-05-25 23:30:34.979 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'masterBathOn.script'
2023-05-25 23:30:36.419 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'masterBathOff.script'
2023-05-25 23:30:37.229 [INFO ] [.core.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2023-05-25 23:30:37.522 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'keyfob.rules'
2023-05-25 23:30:38.675 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'nanoleaf.rules'
2023-05-25 23:30:39.112 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'fan.rules'
2023-05-25 23:30:39.674 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'wallSwitches.rules'
2023-05-25 23:30:44.278 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mi.rules'
2023-05-25 23:30:46.354 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'timeofday.rules'
2023-05-25 23:31:00.313 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'scripts.rules'
2023-05-25 23:31:01.553 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'harmony.rules'
2023-05-25 23:31:01.833 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'hvac.rules'
2023-05-25 23:31:04.876 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'deconz.rules'
2023-05-25 23:31:06.935 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'update.rules'
2023-05-25 23:31:09.849 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'ac.rules'
2023-05-25 23:31:10.115 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'timer.rules'
2023-05-25 23:31:10.839 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'motion.rules'
2023-05-25 23:31:15.725 [WARN ] [el.core.internal.ModelRepositoryImpl] - Configuration model 'mail.things' is either empty or cannot be parsed correctly!
2023-05-25 23:31:19.850 [WARN ] [core.karaf.internal.FeatureInstaller] - The transformation add-on 'javascript' does not exist - ignoring it.
2023-05-25 23:31:24.237 [WARN ] [ty.util.ssl.SslContextFactory.config] - Trusting all certificates configured for Client@362836de[provider=null,keyStore=null,trustStore=null]
2023-05-25 23:31:24.238 [WARN ] [ty.util.ssl.SslContextFactory.config] - No Client EndPointIdentificationAlgorithm configured for Client@362836de[provider=null,keyStore=null,trustStore=null]
2023-05-25 23:31:26.459 [INFO ] [nternal.manager.ShellyManagerServlet] - Shelly Manager started at http(s)://192.168.1.7:8080/shelly/manager
2023-05-25 23:31:27.363 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'squeezebox:squeezeboxserver:DC536DCE-16D6-415B-A214-2239E4DDAA68' to inbox.
2023-05-25 23:31:29.090 [INFO ] [io.openhabcloud.internal.CloudClient] - Connected to the openHAB Cloud service (UUID = 39...46, base URL = http://localhost:8080)
2023-05-25 23:31:30.096 [INFO ] [.influxdb.InfluxDBPersistenceService] - InfluxDB persistence service started.
2023-05-25 23:31:30.607 [WARN ] [.transport.servlet.ServletController] - Can't find the request for http://localhost:8080/rest/items/GTV7PowerConsumption's Observer
2023-05-25 23:31:30.742 [INFO ] [ab.ui.habpanel.internal.HABPanelTile] - Started HABPanel at /habpanel
2023-05-25 23:31:36.439 [WARN ] [dule.handler.ItemStateTriggerHandler] - Item 'WashingRooomHumidity' needed for rule 'fan-2' is missing. Trigger '2' will not work.
2023-05-25 23:31:40.803 [INFO ] [ternal.dhcp.DHCPPacketListenerServer] - DHCP request packet listener online
2023-05-25 23:31:42.448 [INFO ] [zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null
2023-05-25 23:31:46.954 [INFO ] [.onkyo.internal.handler.OnkyoHandler] - Using configuration: ipAddress = 192.168.1.30, port = 60128, udn = 15b0ac73-adac-73b9-7ba5-7309adb9a41d, refreshInterval = 0, volumeLimit = 100, volumeScale = 1.0
2023-05-25 23:31:48.012 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2023-05-25 23:31:48.013 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
2023-05-25 23:31:50.224 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 137: Not initialized (ie node unknown), ignoring message.
2023-05-25 23:31:50.305 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 137: Not initialized (ie node unknown), ignoring message.
2023-05-25 23:31:50.500 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 137: Not initialized (ie node unknown), ignoring message.
2023-05-25 23:31:50.992 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 57: Not initialized (ie node unknown), ignoring message.
2023-05-25 23:31:55.473 [WARN ] [hi.software.os.linux.LinuxFileSystem] - Failed to get information to use statvfs. path: /home/omr/.cache/gvfs, Error code: 13
2023-05-25 23:31:55.481 [WARN ] [hi.software.os.linux.LinuxFileSystem] - Failed to get information to use statvfs. path: /home/omr/.cache/doc, Error code: 13
2023-05-25 23:32:04.646 [WARN ] [sistence.internal.PersistenceManager] - Querying persistence service 'influxdb' takes more than 5000ms.
2023-05-25 23:32:09.641 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'QueryablePersistenceService.query()' on 'org.openhab.persistence.influxdb.InfluxDBPersistenceService@830d1fd': timeout
com.influxdb.exceptions.InfluxException: timeout
        at com.influxdb.internal.AbstractQueryApi.lambda$static$1(AbstractQueryApi.java:72) ~[?:?]
        at com.influxdb.internal.AbstractRestClient.catchOrPropagateException(AbstractRestClient.java:142) ~[?:?]
        at com.influxdb.internal.AbstractQueryApi.query(AbstractQueryApi.java:195) ~[?:?]
        at com.influxdb.internal.AbstractQueryApi.query(AbstractQueryApi.java:104) ~[?:?]
        at com.influxdb.client.internal.QueryApiImpl.query(QueryApiImpl.java:803) ~[?:?]
        at com.influxdb.client.internal.QueryApiImpl.query(QueryApiImpl.java:105) ~[?:?]
        at com.influxdb.client.internal.QueryApiImpl.query(QueryApiImpl.java:83) ~[?:?]
        at com.influxdb.client.internal.QueryApiImpl.query(QueryApiImpl.java:73) ~[?:?]
        at org.openhab.persistence.influxdb.internal.influx2.InfluxDB2RepositoryImpl.query(InfluxDB2RepositoryImpl.java:210) ~[?:?]
        at org.openhab.persistence.influxdb.InfluxDBPersistenceService.query(InfluxDBPersistenceService.java:246) ~[?:?]
        at jdk.internal.reflect.GeneratedMethodAccessor106.invoke(Unknown Source) ~[?:?]
        at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
        at java.lang.reflect.Method.invoke(Method.java:568) ~[?:?]
        at org.openhab.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:147) ~[?:?]
        at org.openhab.core.internal.common.Invocation.call(Invocation.java:52) ~[?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[?:?]
        at java.lang.Thread.run(Thread.java:833) ~[?:?]
Caused by: java.net.SocketTimeoutException: timeout
        at okio.Okio$4.newTimeoutException(Okio.java:232) ~[?:?]
        at okio.AsyncTimeout.exit(AsyncTimeout.java:286) ~[?:?]
        at okio.AsyncTimeout$2.read(AsyncTimeout.java:241) ~[?:?]
        at okio.RealBufferedSource.indexOf(RealBufferedSource.java:358) ~[?:?]
        at okio.RealBufferedSource.readUtf8LineStrict(RealBufferedSource.java:230) ~[?:?]
        at okhttp3.internal.http1.Http1ExchangeCodec.readHeaderLine(Http1ExchangeCodec.java:242) ~[?:?]
        at okhttp3.internal.http1.Http1ExchangeCodec.readResponseHeaders(Http1ExchangeCodec.java:213) ~[?:?]
        at okhttp3.internal.connection.Exchange.readResponseHeaders(Exchange.java:115) ~[?:?]
        at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.java:94) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142) ~[?:?]
        at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.java:43) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:117) ~[?:?]
        at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.java:94) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:117) ~[?:?]
        at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.java:93) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142) ~[?:?]
        at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.java:88) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:117) ~[?:?]
        at com.influxdb.client.internal.GzipInterceptor.intercept(GzipInterceptor.java:91) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:117) ~[?:?]
        at com.influxdb.client.internal.AuthenticateInterceptor.intercept(AuthenticateInterceptor.java:97) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:117) ~[?:?]
        at okhttp3.logging.HttpLoggingInterceptor.intercept(HttpLoggingInterceptor.java:152) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:117) ~[?:?]
        at com.influxdb.internal.UserAgentInterceptor.intercept(UserAgentInterceptor.java:60) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:117) ~[?:?]
        at okhttp3.RealCall.getResponseWithInterceptorChain(RealCall.java:229) ~[?:?]
        at okhttp3.RealCall.execute(RealCall.java:81) ~[?:?]
        at retrofit2.OkHttpCall.execute(OkHttpCall.java:188) ~[?:?]
        at com.influxdb.internal.AbstractQueryApi.query(AbstractQueryApi.java:192) ~[?:?]
        ... 16 more
Caused by: java.net.SocketException: Socket closed
        at sun.nio.ch.NioSocketImpl.endRead(NioSocketImpl.java:248) ~[?:?]
        at sun.nio.ch.NioSocketImpl.implRead(NioSocketImpl.java:327) ~[?:?]
        at sun.nio.ch.NioSocketImpl.read(NioSocketImpl.java:350) ~[?:?]
        at sun.nio.ch.NioSocketImpl$1.read(NioSocketImpl.java:803) ~[?:?]
        at java.net.Socket$SocketInputStream.read(Socket.java:966) ~[?:?]
        at okio.Okio$2.read(Okio.java:140) ~[?:?]
        at okio.AsyncTimeout$2.read(AsyncTimeout.java:237) ~[?:?]
        at okio.RealBufferedSource.indexOf(RealBufferedSource.java:358) ~[?:?]
        at okio.RealBufferedSource.readUtf8LineStrict(RealBufferedSource.java:230) ~[?:?]
        at okhttp3.internal.http1.Http1ExchangeCodec.readHeaderLine(Http1ExchangeCodec.java:242) ~[?:?]
        at okhttp3.internal.http1.Http1ExchangeCodec.readResponseHeaders(Http1ExchangeCodec.java:213) ~[?:?]
        at okhttp3.internal.connection.Exchange.readResponseHeaders(Exchange.java:115) ~[?:?]
        at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.java:94) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142) ~[?:?]
        at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.java:43) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:117) ~[?:?]
        at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.java:94) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:117) ~[?:?]
        at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.java:93) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142) ~[?:?]
        at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.java:88) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:117) ~[?:?]
        at com.influxdb.client.internal.GzipInterceptor.intercept(GzipInterceptor.java:91) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:117) ~[?:?]
        at com.influxdb.client.internal.AuthenticateInterceptor.intercept(AuthenticateInterceptor.java:97) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:117) ~[?:?]
        at okhttp3.logging.HttpLoggingInterceptor.intercept(HttpLoggingInterceptor.java:152) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:117) ~[?:?]
        at com.influxdb.internal.UserAgentInterceptor.intercept(UserAgentInterceptor.java:60) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:117) ~[?:?]
        at okhttp3.RealCall.getResponseWithInterceptorChain(RealCall.java:229) ~[?:?]
        at okhttp3.RealCall.execute(RealCall.java:81) ~[?:?]
        at retrofit2.OkHttpCall.execute(OkHttpCall.java:188) ~[?:?]
        at com.influxdb.internal.AbstractQueryApi.query(AbstractQueryApi.java:192) ~[?:?]
        ... 16 more
2023-05-25 23:32:09.707 [ERROR] [sistence.internal.PersistenceManager] - Exception occurred while querying persistence service 'influxdb': timeout
com.influxdb.exceptions.InfluxException: timeout
        at com.influxdb.internal.AbstractQueryApi.lambda$static$1(AbstractQueryApi.java:72) ~[?:?]
        at com.influxdb.internal.AbstractRestClient.catchOrPropagateException(AbstractRestClient.java:142) ~[?:?]
        at com.influxdb.internal.AbstractQueryApi.query(AbstractQueryApi.java:195) ~[?:?]
        at com.influxdb.internal.AbstractQueryApi.query(AbstractQueryApi.java:104) ~[?:?]
        at com.influxdb.client.internal.QueryApiImpl.query(QueryApiImpl.java:803) ~[?:?]
        at com.influxdb.client.internal.QueryApiImpl.query(QueryApiImpl.java:105) ~[?:?]
        at com.influxdb.client.internal.QueryApiImpl.query(QueryApiImpl.java:83) ~[?:?]
        at com.influxdb.client.internal.QueryApiImpl.query(QueryApiImpl.java:73) ~[?:?]
        at org.openhab.persistence.influxdb.internal.influx2.InfluxDB2RepositoryImpl.query(InfluxDB2RepositoryImpl.java:210) ~[?:?]
        at org.openhab.persistence.influxdb.InfluxDBPersistenceService.query(InfluxDBPersistenceService.java:246) ~[?:?]
        at jdk.internal.reflect.GeneratedMethodAccessor106.invoke(Unknown Source) ~[?:?]
        at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
        at java.lang.reflect.Method.invoke(Method.java:568) ~[?:?]
        at org.openhab.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:147) ~[?:?]
        at org.openhab.core.internal.common.Invocation.call(Invocation.java:52) ~[?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[?:?]
        at java.lang.Thread.run(Thread.java:833) ~[?:?]
Caused by: java.net.SocketTimeoutException: timeout
        at okio.Okio$4.newTimeoutException(Okio.java:232) ~[?:?]
        at okio.AsyncTimeout.exit(AsyncTimeout.java:286) ~[?:?]
        at okio.AsyncTimeout$2.read(AsyncTimeout.java:241) ~[?:?]
        at okio.RealBufferedSource.indexOf(RealBufferedSource.java:358) ~[?:?]
        at okio.RealBufferedSource.readUtf8LineStrict(RealBufferedSource.java:230) ~[?:?]
        at okhttp3.internal.http1.Http1ExchangeCodec.readHeaderLine(Http1ExchangeCodec.java:242) ~[?:?]
        at okhttp3.internal.http1.Http1ExchangeCodec.readResponseHeaders(Http1ExchangeCodec.java:213) ~[?:?]
        at okhttp3.internal.connection.Exchange.readResponseHeaders(Exchange.java:115) ~[?:?]
        at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.java:94) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142) ~[?:?]
        at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.java:43) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:117) ~[?:?]
        at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.java:94) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:117) ~[?:?]
        at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.java:93) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142) ~[?:?]
        at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.java:88) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:117) ~[?:?]
        at com.influxdb.client.internal.GzipInterceptor.intercept(GzipInterceptor.java:91) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:117) ~[?:?]
        at com.influxdb.client.internal.AuthenticateInterceptor.intercept(AuthenticateInterceptor.java:97) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:117) ~[?:?]
        at okhttp3.logging.HttpLoggingInterceptor.intercept(HttpLoggingInterceptor.java:152) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:117) ~[?:?]
        at com.influxdb.internal.UserAgentInterceptor.intercept(UserAgentInterceptor.java:60) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:117) ~[?:?]
        at okhttp3.RealCall.getResponseWithInterceptorChain(RealCall.java:229) ~[?:?]
        at okhttp3.RealCall.execute(RealCall.java:81) ~[?:?]
        at retrofit2.OkHttpCall.execute(OkHttpCall.java:188) ~[?:?]
        at com.influxdb.internal.AbstractQueryApi.query(AbstractQueryApi.java:192) ~[?:?]
        ... 16 more
Caused by: java.net.SocketException: Socket closed
        at sun.nio.ch.NioSocketImpl.endRead(NioSocketImpl.java:248) ~[?:?]
        at sun.nio.ch.NioSocketImpl.implRead(NioSocketImpl.java:327) ~[?:?]
        at sun.nio.ch.NioSocketImpl.read(NioSocketImpl.java:350) ~[?:?]
        at sun.nio.ch.NioSocketImpl$1.read(NioSocketImpl.java:803) ~[?:?]
        at java.net.Socket$SocketInputStream.read(Socket.java:966) ~[?:?]
        at okio.Okio$2.read(Okio.java:140) ~[?:?]
        at okio.AsyncTimeout$2.read(AsyncTimeout.java:237) ~[?:?]
        at okio.RealBufferedSource.indexOf(RealBufferedSource.java:358) ~[?:?]
        at okio.RealBufferedSource.readUtf8LineStrict(RealBufferedSource.java:230) ~[?:?]
        at okhttp3.internal.http1.Http1ExchangeCodec.readHeaderLine(Http1ExchangeCodec.java:242) ~[?:?]
        at okhttp3.internal.http1.Http1ExchangeCodec.readResponseHeaders(Http1ExchangeCodec.java:213) ~[?:?]
        at okhttp3.internal.connection.Exchange.readResponseHeaders(Exchange.java:115) ~[?:?]
        at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.java:94) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142) ~[?:?]
        at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.java:43) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:117) ~[?:?]
        at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.java:94) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:117) ~[?:?]
        at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.java:93) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142) ~[?:?]
        at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.java:88) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:117) ~[?:?]
        at com.influxdb.client.internal.GzipInterceptor.intercept(GzipInterceptor.java:91) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:117) ~[?:?]
        at com.influxdb.client.internal.AuthenticateInterceptor.intercept(AuthenticateInterceptor.java:97) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:117) ~[?:?]
        at okhttp3.logging.HttpLoggingInterceptor.intercept(HttpLoggingInterceptor.java:152) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:117) ~[?:?]
        at com.influxdb.internal.UserAgentInterceptor.intercept(UserAgentInterceptor.java:60) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:117) ~[?:?]
        at okhttp3.RealCall.getResponseWithInterceptorChain(RealCall.java:229) ~[?:?]
        at okhttp3.RealCall.execute(RealCall.java:81) ~[?:?]
        at retrofit2.OkHttpCall.execute(OkHttpCall.java:188) ~[?:?]
        at com.influxdb.internal.AbstractQueryApi.query(AbstractQueryApi.java:192) ~[?:?]
        ... 16 more
2023-05-25 23:32:30.593 [WARN ] [dule.handler.ItemStateTriggerHandler] - Item 'vMasterBathState' needed for rule 'update-5' is missing. Trigger '0' will not work.
2023-05-25 23:32:38.817 [WARN ] [dule.handler.ItemStateTriggerHandler] - Item 'WashingRooomHumidity' needed for rule 'fan-2' is missing. Trigger '2' will not work.
2023-05-25 23:32:40.340 [WARN ] [dule.handler.ItemStateTriggerHandler] - Item 'vMasterBathState' needed for rule 'update-5' is missing. Trigger '0' will not work.
2023-05-25 23:32:50.110 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Exception during ZWave thread.
java.lang.IllegalStateException: Queue full
        at java.util.AbstractQueue.add(AbstractQueue.java:98) ~[?:?]
        at java.util.concurrent.ArrayBlockingQueue.add(ArrayBlockingQueue.java:329) ~[?:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.processReceiveMessage(ZWaveTransactionManager.java:447) ~[?:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveController.incomingPacket(ZWaveController.java:1094) ~[?:?]
        at org.openhab.binding.zwave.handler.ZWaveControllerHandler.incomingMessage(ZWaveControllerHandler.java:462) ~[?:?]
        at org.openhab.binding.zwave.handler.ZWaveSerialHandler$ZWaveReceiveThread.run(ZWaveSerialHandler.java:427) ~[?:?]
2023-05-25 23:33:00.301 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2023-05-25 23:33:00.302 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
2023-05-25 23:33:00.315 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 137: Not initialized (ie node unknown), ignoring message.
2023-05-25 23:33:00.318 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 137: Not initialized (ie node unknown), ignoring message.
2023-05-25 23:33:00.320 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 30: Not initialized (ie node unknown), ignoring message.
2023-05-25 23:33:00.498 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 137: Not initialized (ie node unknown), ignoring message.
2023-05-25 23:33:00.806 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 29: Not initialized (ie node unknown), ignoring message.
2023-05-25 23:34:04.044 [WARN ] [core.thing.internal.ThingManagerImpl] - Channel types or config descriptions for thing 'shelly:shelly1:76a54a' are missing in the respective registry for more than 120s. In case it does not happen immediately after an upgrade, it should be fixed in the binding.
2023-05-25 23:36:09.738 [INFO ] [b.core.model.script.HVACBoilerSwitch] - ON
2023-05-25 23:36:09.754 [INFO ] [org.openhab.core.model.script.System] - DAY=THURSDAY
2023-05-25 23:36:09.772 [WARN ] [o.internal.handler.AstroThingHandler] - The Astro-Binding is a read-only binding and can not handle commands
2023-05-25 23:36:09.778 [WARN ] [o.internal.handler.AstroThingHandler] - The Astro-Binding is a read-only binding and can not handle commands
2023-05-25 23:36:19.950 [INFO ] [b.core.model.script.HVACBoilerSwitch] - OFF
2023-05-25 23:46:13.106 [INFO ] [ab.ui.habpanel.internal.HABPanelTile] - Stopped HABPanel
2023-05-25 23:46:13.135 [INFO ] [basic.internal.servlet.WebAppServlet] - Stopped Basic UI
2023-05-25 23:46:13.176 [INFO ] [.influxdb.InfluxDBPersistenceService] - InfluxDB persistence service stopped.
2023-05-25 23:46:13.185 [INFO ] [io.openhabcloud.internal.CloudClient] - Shutting down openHAB Cloud service connection
2023-05-25 23:46:13.205 [WARN ] [io.openhabcloud.internal.CloudClient] - Socket.IO disconnected: io client disconnect
2023-05-25 23:46:13.205 [INFO ] [io.openhabcloud.internal.CloudClient] - Disconnected from the openHAB Cloud service (UUID = 39...46, base URL = http://localhost:8080)
2023-05-25 23:46:20.378 [WARN ] [.transport.servlet.ServletController] - Can't find the request for http://shs2:8080/css/0.app.08f90a178b660c2a2443.css's Observer
2023-05-25 23:46:20.378 [WARN ] [.transport.servlet.ServletController] - Can't find the request for http://shs2:8080/js/0.app.08f90a178b660c2a2443.js's Observer
2023-05-25 23:46:25.429 [WARN ] [service.spi.util.WebContainerManager] - Can't get a WebContainer service from {org.osgi.service.http.HttpService, org.ops4j.pax.web.service.WebContainer}={org.ops4j.pax.web.log.ncsa.extended=true, org.ops4j.pax.web.ssl.keystore.password=********, service.scope=bundle, org.ops4j.pax.web.ssl.key.password=********, org.ops4j.pax.web.session.cookie.name=JSESSIONID, org.osgi.service.http.connector.name=default, org.ops4j.pax.web.enc.iterationcount=1000, org.ops4j.pax.web.log.ncsa.file=yyyy_mm_dd.request.log, org.ops4j.pax.web.server.eventDispatcherThreadCount=1, org.osgi.service.http.checkForwardedHeaders=false, org.ops4j.pax.web.enc.suffix=), org.ops4j.pax.web.digestAuth.maxNonceAge=60000, org.ops4j.pax.web.ssl.ciphersuites.included=, org.ops4j.pax.web.session.url=jsessionid, org.ops4j.pax.web.formAuth.errorRedirect=false, org.ops4j.pax.web.ssl.ciphersuites.excluded=^.*_(MD5|SHA|SHA1)$,^TLS_RSA_.*$,^SSL_.*$,^.*_NULL_.*$,^.*_anon_.*, org.ops4j.pax.web.enc.prefix=ENC(, org.ops4j.pax.web.server.maxThreads=50, org.ops4j.pax.web.validatePeerCerts=false, service.id=151, org.ops4j.pax.web.session.cookie.maxAge=-1, org.ops4j.pax.web.ssl.truststore.password=********, org.ops4j.pax.web.ssl.session.cacheSize=-1, org.ops4j.pax.web.ssl.truststore.type=JKS, org.ops4j.pax.web.ssl.keystore.type=JKS, org.ops4j.pax.web.ssl.session.enabled=true, org.ops4j.pax.web.ssl.protocol=TLSv1.3, org.osgi.service.http.port=8080, org.ops4j.pax.web.log.ncsa.file.date.format=yyyy-MM-dd, org.ops4j.pax.web.ssl.renegotiationLimit=-1, org.osgi.service.http.secure.enabled=true, org.osgi.service.http.enabled=true, org.ops4j.pax.web.server.idleTimeout=300000, org.ops4j.pax.web.log.ncsa.retaindays=90, org.ops4j.pax.web.log.ncsa.logtimezone=GMT, org.ops4j.pax.web.enc.algorithm=PBEWithHmacSHA256AndAES_128, org.ops4j.pax.web.validateCerts=false, org.ops4j.pax.web.config.files=/usr/share/openhab/runtime/etc/jetty.xml, org.ops4j.pax.web.ssl.renegotiationAllowed=true, org.ops4j.pax.web.digestAuth.maxNonceCount=1024, org.ops4j.pax.web.enableOCSP=false, org.ops4j.pax.web.ssl.clientauth.needed=false, org.ops4j.pax.web.enc.enabled=false, org.osgi.service.http.port.secure=8443, javax.servlet.context.tempdir=/var/lib/openhab/tmp, org.ops4j.pax.web.enableCRLDP=false, org.ops4j.pax.web.server.connector.idleTimeout=30000, org.ops4j.pax.web.session.timeout=10, org.ops4j.pax.web.ssl.clientauth.wanted=false, org.ops4j.pax.web.ssl.protocols.excluded=SSL,SSLv2,SSLv2Hello,SSLv3, service.bundleid=222, org.ops4j.pax.web.server.minThreads=2, org.ops4j.pax.web.session.cookie.secure=false, org.ops4j.pax.web.enc.masterpassword=********, org.ops4j.pax.web.log.ncsa.append=true, org.osgi.service.http.secure.connector.name=secureDefault, org.ops4j.pax.web.ssl.session.timeout=-1, org.ops4j.pax.web.listening.addresses=0.0.0.0, org.ops4j.pax.web.log.ncsa.buffered=true, org.ops4j.pax.web.session.cookie.sameSite=unset, org.ops4j.pax.web.log.ncsa.enabled=false, org.ops4j.pax.web.ssl.protocols.included=, org.ops4j.pax.web.session.cookie.httpOnly=true, org.ops4j.pax.web.server.showStacks=false}

J-N-K · May 28, 2023, 11:26am

When that happens, can you please go to the API explorer, and request /systeminfo? The result should look like

{
  "systemInfo": {
    "configFolder": "/Users/jan/Downloads/openhab-4/conf",
    "userdataFolder": "/Users/jan/Downloads/openhab-4/userdata",
    "logFolder": "/Users/jan/Downloads/openhab-4/userdata/logs",
    "javaVersion": "17.0.7",
    "javaVendor": "Homebrew",
    "javaVendorVersion": "Homebrew",
    "osName": "Mac OS X",
    "osVersion": "13.4",
    "osArchitecture": "aarch64",
    "availableProcessors": 8,
    "freeMemory": 356190960,
    "totalMemory": 557842432,
    "startLevel": 100
  }
}

I have the feeling that the exception in InfluxDB prevents the system from reaching the next start-level when trying to restore item-states.

OMR · May 28, 2023, 11:48am

Will do, but not remotely
Perhaps mid next week.
FYI:

Edit: I will not try M3 again until back home, but I checked the current startlevel on M2 and it’s 70, not 100 as your example:

{
  "systemInfo": {
    "configFolder": "/etc/openhab",
    "userdataFolder": "/var/lib/openhab",
    "logFolder": "/var/log/openhab",
    "javaVersion": "17.0.7",
    "javaVendor": "Private Build",
    "osName": "Linux",
    "osVersion": "5.15.0-72-generic",
    "osArchitecture": "amd64",
    "availableProcessors": 2,
    "freeMemory": 417191504,
    "totalMemory": 1004535808,
    "startLevel": 70
  }
}

Checked my OH3 system where I’m at at the moment and that is 100.

Lolodomo · May 28, 2023, 2:21pm

moody_blue:

After converting from M2 to M3 I have these WARN’s in the log

2023-05-25 12:25:29.910 [WARN ] [d4j.internal.RRD4jPersistenceService] - Could not persist 'Videoporteiro__Silenciar_campainha_Running' to rrd4j database: Bad sample time: 1685013929. Last update time was 1685013929, at least one second step is required
2023-05-25 14:37:06.196 [WARN ] [d4j.internal.RRD4jPersistenceService] - Could not persist 'Sensormovimentopiso1_Occupancy' to rrd4j database: Bad sample time: 1685021821. Last update time was 1685021822, at least one second step is required
2023-05-25 20:47:06.428 [WARN ] [d4j.internal.RRD4jPersistenceService] - Could not persist 'Sensorhumidadeetemperaturacave_Temperature' to rrd4j database: Bad sample time: 1685044021. Last update time was 1685044023, at least one second step is required

Should I care about this ?

@J-N-K : we have to decide what to do. We have to be sure that at least the last value is recorded.
You did an analysis of the problem but I do not find it anymore. I do not remember if it was in Github or in forum.

J-N-K · May 28, 2023, 2:40pm

The issue is that two events arrive within a second. We can’t do anything to ensure we persist the later one. We could probably add some more re-tries before failing.

milo · May 28, 2023, 3:07pm

This issue is only relevant for rrdj4 persistance or for all persistence services?

J-N-K · May 28, 2023, 3:08pm

I guess that’s an issue for all persistence services, but it’s most obvious in rrd4j

milo · May 28, 2023, 3:14pm

Because ofslow writing time?

J-N-K · May 28, 2023, 3:18pm

Because most databases use the timestamp as index and duplicate indices are not supported. It of course depends on the storage, if fractions of seconds are stored or not. RRD4j truncates timestamps to full send (internally, we have no control over that), so we run into that issue more often.

Lolodomo · May 28, 2023, 3:22pm

But what was the situation in OH 3?