OH4 M2&M3 influxDB restoreOnStartup fails. Timeout exceptions in startup logs

OMR · May 28, 2023, 11:42am

Persistence of new values works fine.
restoreOnStartup does not, leading to a messy startup with lights changing states all over.
It worked fine on OH3.
Note that during startup, top shows java consuming >100% for some minutes.
Maybe some timeouts have been tightened a bit too much.
My x86_64 Asus shoebox computer is not the fastest, so things could be slow.

omr@shs2:~$ cat /proc/cpuinfo
processor       : 0
vendor_id       : GenuineIntel
cpu family      : 6
model           : 69
model name      : Intel(R) Celeron(R) 2957U @ 1.40GHz
stepping        : 1
microcode       : 0x26
cpu MHz         : 1396.758
cache size      : 2048 KB
physical id     : 0
siblings        : 2
core id         : 0
cpu cores       : 2
apicid          : 0
initial apicid  : 0
fpu             : yes
fpu_exception   : yes
cpuid level     : 13
wp              : yes
flags           : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc cpuid aperfmperf pni pclmulqdq dtes64 monitor ds_cpl est tm2 ssse3 sdbg cx16 xtpr pdcm pcid sse4_1 sse4_2 movbe popcnt tsc_deadline_timer xsave rdrand lahf_lm abm cpuid_fault epb invpcid_single pti ssbd ibrs ibpb stibp fsgsbase tsc_adjust erms invpcid xsaveopt dtherm arat pln pts md_clear flush_l1d
bugs            : cpu_meltdown spectre_v1 spectre_v2 spec_store_bypass l1tf mds swapgs itlb_multihit srbds mmio_unknown
bogomips        : 2793.51
clflush size    : 64
cache_alignment : 64
address sizes   : 39 bits physical, 48 bits virtual
power management:

processor       : 1
vendor_id       : GenuineIntel
cpu family      : 6
model           : 69
model name      : Intel(R) Celeron(R) 2957U @ 1.40GHz
stepping        : 1
microcode       : 0x26
cpu MHz         : 1396.854
cache size      : 2048 KB
physical id     : 0
siblings        : 2
core id         : 1
cpu cores       : 2
apicid          : 2
initial apicid  : 2
fpu             : yes
fpu_exception   : yes
cpuid level     : 13
wp              : yes
flags           : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc cpuid aperfmperf pni pclmulqdq dtes64 monitor ds_cpl est tm2 ssse3 sdbg cx16 xtpr pdcm pcid sse4_1 sse4_2 movbe popcnt tsc_deadline_timer xsave rdrand lahf_lm abm cpuid_fault epb invpcid_single pti ssbd ibrs ibpb stibp fsgsbase tsc_adjust erms invpcid xsaveopt dtherm arat pln pts md_clear flush_l1d
bugs            : cpu_meltdown spectre_v1 spectre_v2 spec_store_bypass l1tf mds swapgs itlb_multihit srbds mmio_unknown
bogomips        : 2793.51
clflush size    : 64
cache_alignment : 64
address sizes   : 39 bits physical, 48 bits virtual
power management:

omr@shs2:~$ uname -a
Linux shs2 5.15.0-72-generic #79-Ubuntu SMP Wed Apr 19 08:22:18 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux
omr@shs2:~$ java --version
openjdk 17.0.7 2023-04-18
OpenJDK Runtime Environment (build 17.0.7+7-Ubuntu-0ubuntu122.04.2)
OpenJDK 64-Bit Server VM (build 17.0.7+7-Ubuntu-0ubuntu122.04.2, mixed mode, sharing)

Typical startup log:

2023-05-25 23:57:28.359 [INFO ] [org.openhab.core.Activator          ] - Starting openHAB 4.0.0.M2 (build Milestone Build)
2023-05-25 23:57:29.299 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Time zone set to 'Europe/Oslo'.
2023-05-25 23:57:29.315 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Location set to '59.9026989087956,10.495143905282024'.
2023-05-25 23:57:29.331 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Locale set to 'en_NO'.
2023-05-25 23:57:29.339 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Measurement system set to 'SI'.
2023-05-25 23:57:31.176 [WARN ] [.transport.servlet.ServletController] - Can't find the request for http://localhost:8080/rest/items/GTV7PowerConsumption's Observer
2023-05-25 23:57:32.277 [WARN ] [emeris.internal.EphemerisManagerImpl] - Erroneous day set definition dayset-workday: No enum constant java.time.DayOfWeek.
2023-05-25 23:57:32.292 [WARN ] [emeris.internal.EphemerisManagerImpl] - Erroneous day set definition dayset-default: No enum constant java.time.DayOfWeek.
2023-05-25 23:57:32.301 [WARN ] [emeris.internal.EphemerisManagerImpl] - Erroneous day set definition dayset-trash: No enum constant java.time.DayOfWeek.
2023-05-25 23:57:32.302 [WARN ] [emeris.internal.EphemerisManagerImpl] - Erroneous day set definition dayset-weekend: No enum constant java.time.DayOfWeek.
2023-05-25 23:57:32.771 [WARN ] [.transport.servlet.ServletController] - Can't find the request for http://localhost:8080/rest/items/GTV7PowerConsumption's Observer
2023-05-25 23:57:34.836 [WARN ] [.transport.servlet.ServletController] - Can't find the request for http://localhost:8080/rest/items/GTV7PowerConsumption's Observer
2023-05-25 23:57:34.909 [WARN ] [core.karaf.internal.FeatureInstaller] - The transformation add-on 'javascript' does not exist - ignoring it.
2023-05-25 23:57:36.572 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'hue.items'
2023-05-25 23:57:37.391 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'LAN.items'
2023-05-25 23:57:37.518 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'Z-wave.items'
2023-05-25 23:57:37.979 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'automower.items'
2023-05-25 23:57:38.034 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'nanoleaf.items'
2023-05-25 23:57:38.073 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'AC.items'
2023-05-25 23:57:38.106 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'Tradfri.items'
2023-05-25 23:57:38.211 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mi.items'
2023-05-25 23:57:38.372 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'Virtual.items'
2023-05-25 23:57:38.652 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'deconz.items'
2023-05-25 23:57:38.737 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'Squeezebox.items'
2023-05-25 23:57:38.790 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'Groups.items'
2023-05-25 23:57:39.325 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'influxdb.persist'
2023-05-25 23:57:40.060 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'GTV7.sitemap'
2023-05-25 23:57:40.584 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'automower.things'
2023-05-25 23:57:40.658 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mail.things'
2023-05-25 23:57:40.665 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'squeeze.things'
2023-05-25 23:57:40.699 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'astro.things'
2023-05-25 23:57:40.710 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'deconz.things'
2023-05-25 23:57:42.670 [WARN ] [.transport.servlet.ServletController] - Can't find the request for http://shs2:8080/basicui/app's Observer
2023-05-25 23:57:42.865 [WARN ] [.transport.servlet.ServletController] - Can't find the request for http://shs2:8080/favicon.ico's Observer
2023-05-25 23:57:45.657 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'allOff.script'
2023-05-25 23:57:47.554 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'masterBathOn.script'
2023-05-25 23:57:47.782 [WARN ] [.transport.servlet.ServletController] - Can't find the request for http://shs2:8080/settings/rules/'s Observer
2023-05-25 23:57:49.125 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'masterBathOff.script'
2023-05-25 23:57:50.033 [INFO ] [.core.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2023-05-25 23:57:50.341 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'keyfob.rules'
2023-05-25 23:57:51.480 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'nanoleaf.rules'
2023-05-25 23:57:52.060 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'fan.rules'
2023-05-25 23:57:52.811 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'wallSwitches.rules'
2023-05-25 23:57:58.468 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mi.rules'
2023-05-25 23:58:00.766 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'timeofday.rules'
2023-05-25 23:58:18.193 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'scripts.rules'
2023-05-25 23:58:19.564 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'harmony.rules'
2023-05-25 23:58:19.904 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'hvac.rules'
2023-05-25 23:58:23.519 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'deconz.rules'
2023-05-25 23:58:25.914 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'update.rules'
2023-05-25 23:58:29.300 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'ac.rules'
2023-05-25 23:58:29.618 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'timer.rules'
2023-05-25 23:58:30.544 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'motion.rules'
2023-05-25 23:58:34.807 [WARN ] [core.karaf.internal.FeatureInstaller] - The transformation add-on 'javascript' does not exist - ignoring it.
2023-05-25 23:58:35.892 [WARN ] [.transport.servlet.ServletController] - Can't find the request for http://localhost:8080/rest/items/GTV7PowerConsumption's Observer
2023-05-25 23:58:36.187 [WARN ] [el.core.internal.ModelRepositoryImpl] - Configuration model 'mail.things' is either empty or cannot be parsed correctly!
2023-05-25 23:58:44.055 [WARN ] [ty.util.ssl.SslContextFactory.config] - Trusting all certificates configured for Client@5615dd9[provider=null,keyStore=null,trustStore=null]
2023-05-25 23:58:44.056 [WARN ] [ty.util.ssl.SslContextFactory.config] - No Client EndPointIdentificationAlgorithm configured for Client@5615dd9[provider=null,keyStore=null,trustStore=null]
2023-05-25 23:58:46.097 [INFO ] [nternal.manager.ShellyManagerServlet] - Shelly Manager started at http(s)://192.168.1.7:8080/shelly/manager
2023-05-25 23:58:48.447 [INFO ] [io.openhabcloud.internal.CloudClient] - Connected to the openHAB Cloud service (UUID = 39...46, base URL = http://localhost:8080)
2023-05-25 23:58:49.453 [INFO ] [.influxdb.InfluxDBPersistenceService] - InfluxDB persistence service started.
2023-05-25 23:58:49.795 [INFO ] [ab.ui.habpanel.internal.HABPanelTile] - Started HABPanel at /habpanel
2023-05-25 23:58:49.909 [WARN ] [.transport.servlet.ServletController] - Can't find the request for http://localhost:8080/rest/items/GTV7PowerConsumption's Observer
2023-05-25 23:58:56.531 [WARN ] [dule.handler.ItemStateTriggerHandler] - Item 'WashingRooomHumidity' needed for rule 'fan-2' is missing. Trigger '2' will not work.
2023-05-25 23:59:00.495 [INFO ] [ternal.dhcp.DHCPPacketListenerServer] - DHCP request packet listener online
2023-05-25 23:59:01.767 [INFO ] [zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null
2023-05-25 23:59:04.473 [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:59:07.115 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2023-05-25 23:59:07.118 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
2023-05-25 23:59:10.087 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 137: Not initialized (ie node unknown), ignoring message.
2023-05-25 23:59:10.133 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 137: Not initialized (ie node unknown), ignoring message.
2023-05-25 23:59:10.329 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 137: Not initialized (ie node unknown), ignoring message.
2023-05-25 23:59:12.748 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 29: Not initialized (ie node unknown), ignoring message.
2023-05-25 23:59:24.515 [WARN ] [ence.internal.PersistenceManagerImpl] - Querying persistence service 'influxdb' takes more than 5000ms.
2023-05-25 23:59:29.516 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'QueryablePersistenceService.query()' on 'org.openhab.persistence.influxdb.InfluxDBPersistenceService@241d8ae7': 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:157) ~[?:?]
        at org.openhab.persistence.influxdb.InfluxDBPersistenceService.query(InfluxDBPersistenceService.java:187) ~[?:?]
        at jdk.internal.reflect.GeneratedMethodAccessor105.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:59:29.613 [ERROR] [ence.internal.PersistenceManagerImpl] - 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:157) ~[?:?]
        at org.openhab.persistence.influxdb.InfluxDBPersistenceService.query(InfluxDBPersistenceService.java:187) ~[?:?]
        at jdk.internal.reflect.GeneratedMethodAccessor105.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:59:50.382 [ERROR] [org.openhab.core.items.GenericItem  ] - Tried to set invalid state raw type (image/jpeg): 24152 bytes (StringType) on item SqueezeboxTouchHTPC_CoverArt of type ImageItem, ignoring it
2023-05-25 23:59:53.179 [ERROR] [org.openhab.core.items.GenericItem  ] - Tried to set invalid state PAUSE (StringType) on item SqueezeboxTouchHTPC_Control of type PlayerItem, ignoring it
2023-05-25 23:59:54.424 [ERROR] [org.openhab.core.items.GenericItem  ] - Tried to set invalid state PAUSE (StringType) on item SqueezeBoxTouchControl of type PlayerItem, ignoring it
2

I cannot find any corollated log entries from influxDB in the journal. they are all from 2min before.
Open store Start → End is more than 13s though. Could that be related to the 5s timeout exception logged later?

May 25 23:57:23 shs2 influxd[1598]: ts=2023-05-25T21:57:23.710961Z lvl=info msg="Opened shard" log_id=0i1EVW7G000 service=storage-engine op_name=tsdb_open index_version=tsi1 path=/root/.influxdbv2/engine/data/a47a21fbd735261c/autogen/1940 duration=67.828ms
May 25 23:57:23 shs2 influxd[1598]: ts=2023-05-25T21:57:23.722078Z lvl=info msg="Opened shard" log_id=0i1EVW7G000 service=storage-engine op_name=tsdb_open index_version=tsi1 path=/root/.influxdbv2/engine/data/a47a21fbd735261c/autogen/1949 duration=77.921ms
May 25 23:57:23 shs2 influxd[1598]: ts=2023-05-25T21:57:23.771121Z lvl=info msg="Opened shard" log_id=0i1EVW7G000 service=storage-engine op_name=tsdb_open index_version=tsi1 path=/root/.influxdbv2/engine/data/a47a21fbd735261c/autogen/1958 duration=60.102ms
May 25 23:57:23 shs2 influxd[1598]: ts=2023-05-25T21:57:23.879130Z lvl=info msg="Opened shard" log_id=0i1EVW7G000 service=storage-engine op_name=tsdb_open index_version=tsi1 path=/root/.influxdbv2/engine/data/a47a21fbd735261c/autogen/1967 duration=156.994ms
May 25 23:57:23 shs2 influxd[1598]: ts=2023-05-25T21:57:23.884477Z lvl=info msg="Opened shard" log_id=0i1EVW7G000 service=storage-engine op_name=tsdb_open index_version=tsi1 path=/root/.influxdbv2/engine/data/a47a21fbd735261c/autogen/1976 duration=113.302ms
May 25 23:57:24 shs2 influxd[1598]: ts=2023-05-25T21:57:24.012566Z lvl=info msg="Opened shard" log_id=0i1EVW7G000 service=storage-engine op_name=tsdb_open index_version=tsi1 path=/root/.influxdbv2/engine/data/a47a21fbd735261c/autogen/1985 duration=130.941ms
May 25 23:57:24 shs2 influxd[1598]: ts=2023-05-25T21:57:24.059731Z lvl=info msg="Opened shard" log_id=0i1EVW7G000 service=storage-engine op_name=tsdb_open index_version=tsi1 path=/root/.influxdbv2/engine/data/a47a21fbd735261c/autogen/1994 duration=174.837ms
May 25 23:57:24 shs2 dbus-daemon[1106]: [system] Activating via systemd: service name='com.canonical.UbuntuAdvantage' unit='ubuntu-advantage-desktop-daemon.service' requested by ':1.114' (uid=1000 pid=2269 comm="/usr/bin/python3 /usr/bin/software-properties-gtk " label="unconfined")
May 25 23:57:24 shs2 systemd[1]: Starting Desktop service for Ubuntu Advantage...
May 25 23:57:24 shs2 influxd[1598]: ts=2023-05-25T21:57:24.208336Z lvl=info msg="Opened shard" log_id=0i1EVW7G000 service=storage-engine op_name=tsdb_open index_version=tsi1 path=/root/.influxdbv2/engine/data/a47a21fbd735261c/autogen/2012 duration=148.545ms
May 25 23:57:24 shs2 influxd[1598]: ts=2023-05-25T21:57:24.230161Z lvl=info msg="Opened shard" log_id=0i1EVW7G000 service=storage-engine op_name=tsdb_open index_version=tsi1 path=/root/.influxdbv2/engine/data/a47a21fbd735261c/autogen/2003 duration=217.524ms
May 25 23:57:24 shs2 dbus-daemon[1106]: [system] Successfully activated service 'com.canonical.UbuntuAdvantage'
May 25 23:57:24 shs2 systemd[1]: Started Desktop service for Ubuntu Advantage.
May 25 23:57:24 shs2 influxd[1598]: ts=2023-05-25T21:57:24.372708Z lvl=info msg="Opened shard" log_id=0i1EVW7G000 service=storage-engine op_name=tsdb_open index_version=tsi1 path=/root/.influxdbv2/engine/data/a47a21fbd735261c/autogen/2021 duration=164.317ms
May 25 23:57:24 shs2 influxd[1598]: ts=2023-05-25T21:57:24.411445Z lvl=info msg="Opened shard" log_id=0i1EVW7G000 service=storage-engine op_name=tsdb_open index_version=tsi1 path=/root/.influxdbv2/engine/data/a47a21fbd735261c/autogen/2030 duration=181.221ms
May 25 23:57:24 shs2 sudo[3576]:     root : PWD=/ ; USER=root ; COMMAND=/bin/echo -e k
May 25 23:57:24 shs2 sudo[3576]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0)
May 25 23:57:24 shs2 sudo[3576]: pam_unix(sudo:session): session closed for user root
May 25 23:57:24 shs2 bash[1377]: File changed
May 25 23:57:24 shs2 bash[1377]: 1428
May 25 23:57:24 shs2 influxd[1598]: ts=2023-05-25T21:57:24.537470Z lvl=info msg="Opened shard" log_id=0i1EVW7G000 service=storage-engine op_name=tsdb_open index_version=tsi1 path=/root/.influxdbv2/engine/data/a47a21fbd735261c/autogen/2039 duration=164.351ms
May 25 23:57:24 shs2 influxd[1598]: ts=2023-05-25T21:57:24.545718Z lvl=info msg="Opened shard" log_id=0i1EVW7G000 service=storage-engine op_name=tsdb_open index_version=tsi1 path=/root/.influxdbv2/engine/data/a47a21fbd735261c/autogen/2048 duration=134.217ms
May 25 23:57:24 shs2 bash[3588]:   % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
May 25 23:57:24 shs2 bash[3588]:                                  Dload  Upload   Total   Spent    Left  Speed
May 25 23:57:24 shs2 bash[3588]: [158B blob data]
May 25 23:57:24 shs2 bash[3588]: curl: (7) Failed to connect to localhost port 8080 after 0 ms: Connection refused
May 25 23:57:24 shs2 influxd[1598]: ts=2023-05-25T21:57:24.654873Z lvl=info msg="Opened shard" log_id=0i1EVW7G000 service=storage-engine op_name=tsdb_open index_version=tsi1 path=/root/.influxdbv2/engine/data/a47a21fbd735261c/autogen/2057 duration=117.061ms
May 25 23:57:24 shs2 influxd[1598]: ts=2023-05-25T21:57:24.763916Z lvl=info msg="Opened shard" log_id=0i1EVW7G000 service=storage-engine op_name=tsdb_open index_version=tsi1 path=/root/.influxdbv2/engine/data/a47a21fbd735261c/autogen/2066 duration=218.115ms
May 25 23:57:24 shs2 influxd[1598]: ts=2023-05-25T21:57:24.935220Z lvl=info msg="Opened shard" log_id=0i1EVW7G000 service=storage-engine op_name=tsdb_open index_version=tsi1 path=/root/.influxdbv2/engine/data/a47a21fbd735261c/autogen/983 duration=171.247ms
May 25 23:57:25 shs2 influxd[1598]: ts=2023-05-25T21:57:25.082933Z lvl=info msg="Opened shard" log_id=0i1EVW7G000 service=storage-engine op_name=tsdb_open index_version=tsi1 path=/root/.influxdbv2/engine/data/a47a21fbd735261c/autogen/986 duration=147.654ms
May 25 23:57:26 shs2 sudo[3642]:     root : PWD=/ ; USER=root ; COMMAND=/bin/echo -e k
May 25 23:57:26 shs2 sudo[3642]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0)
May 25 23:57:26 shs2 sudo[3642]: pam_unix(sudo:session): session closed for user root
May 25 23:57:26 shs2 influxd[1598]: ts=2023-05-25T21:57:26.570124Z lvl=info msg="Opened shard" log_id=0i1EVW7G000 service=storage-engine op_name=tsdb_open index_version=tsi1 path=/root/.influxdbv2/engine/data/a47a21fbd735261c/autogen/2075 duration=1915.174ms
May 25 23:57:26 shs2 influxd[1598]: ts=2023-05-25T21:57:26.585636Z lvl=info msg="Open store (end)" log_id=0i1EVW7G000 service=storage-engine op_name=tsdb_open op_event=end op_elapsed=13194.569ms
May 25 23:57:26 shs2 influxd[1598]: ts=2023-05-25T21:57:26.586087Z lvl=info msg="Starting retention policy enforcement service" log_id=0i1EVW7G000 service=retention check_interval=30m
May 25 23:57:26 shs2 influxd[1598]: ts=2023-05-25T21:57:26.586440Z lvl=info msg="Starting precreation service" log_id=0i1EVW7G000 service=shard-precreation check_interval=10m advance_period=30m
May 25 23:57:26 shs2 influxd[1598]: ts=2023-05-25T21:57:26.587449Z lvl=info msg="Starting query controller" log_id=0i1EVW7G000 service=storage-reads concurrency_quota=10 initial_memory_bytes_quota_per_query=9223372036854775807 memory_bytes_quota_per_query=9223372036854775807 max_memory>
May 25 23:57:26 shs2 influxd[1598]: ts=2023-05-25T21:57:26.593353Z lvl=info msg="Configuring InfluxQL statement executor (zeros indicate unlimited)." log_id=0i1EVW7G000 max_select_point=0 max_select_series=0 max_select_buckets=0
May 25 23:57:26 shs2 org.xfce.ScreenSaver[1514]: Xlib:  extension "DPMS" missing on display ":1".
May 25 23:57:26 shs2 influxd[1598]: ts=2023-05-25T21:57:26.905266Z lvl=info msg=Listening log_id=0i1EVW7G000 transport=http addr=:8086 port=8086
May 25 23:57:26 shs2 influxd[1598]: ts=2023-05-25T21:57:26.905359Z lvl=info msg=Starting log_id=0i1EVW7G000 service=telemetry interval=8h
May 25 23:57:27 shs2 pkexec[3672]: omr: Error executing command as another user: Not authorized [USER=root] [TTY=unknown] [CWD=/home/omr] [COMMAND=/usr/lib/update-notifier/package-system-locked]
May 25 23:57:28 shs2 sudo[3701]:     root : PWD=/ ; USER=root ; COMMAND=/bin/echo -e k
May 25 23:57:28 shs2 sudo[3701]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0)

Please advice if more info is needed.

Other user with the same issue: (last log entry)

J-N-K · June 8, 2023, 5:59pm

I don’t think there has been a change in OH4, maybe the startup process is a bit more complex now than it was before, but it is also more deterministic and fail-safe.

The influxdb service does not properly handle exceptions, this will be fixed in [influxdb] Handle exceptions gracefully by J-N-K · Pull Request #15062 · openhab/openhab-addons · GitHub, but it does not remove the timeout issue. It seem that the timeout comes from the service itself, maybe the upgraded influx library has stricter timeouts and we hit those when querying a lot of values at the same time when restoring values on startup.

How many items do you have and how many of these are restored at startup?

OMR · June 8, 2023, 6:19pm

Strategies {
    everyMinute : "0 * * * * ?"
    everyHour   : "0 0 * * * ?"
    everyDay    : "0 0 0 * * ?"
}

Items {
    *  : strategy = everyChange, everyHour, restoreOnStartup
}

I also noticed, watching top during startup, that the influxdb process also consumed a lot of CPU, it and java being the two on top.

M2 is usable, ending up on runLevel 70
M3 unusable, since the rule engine never starts. (havn’t check runLevel on M3)

J-N-K · June 8, 2023, 7:05pm

It could be that this is the result of a more efficient processing in core which results in more queries in the same time (restoring 1000 items requires at least 1000 requests).

OMR · June 8, 2023, 7:16pm

Yes. A more failsafe way would be to reset the timer every time an item was read, and not assume anything about how long reading them all is gonna take?
I haven’t looked at the code. Is the timeout per query, or max allowed time for the full restore?

Edit: did a quick test. With the system up and running, I watched top when doing a

 sudo systemctl restart influxdb

influxdb consumed 99% for 18-20s seconds before settling down.
So, during a system startup alongside java, we are looking at even longer times.

J-N-K · June 8, 2023, 7:28pm

I believe it is the timeout of the OkHttpClient and that is 10s, which should in general be enough. If you would like to try I can create a special version that extends the timeouts to 60s and we can see if that helps.

OMR · June 8, 2023, 7:37pm

Sure. Thanks.
But I leave for the weekend soon, so it will be Sunday or early next week until I can test.

Edit: just remembered this from the log:

It’s a 5s timer that times out …

J-N-K · June 9, 2023, 6:52pm

That’s another issue. What you see above is a timeout from the persistence service. I’m not sure what would be the best way to handle this.

OMR · June 10, 2023, 10:20am

But I was under the impression that it was this persistence timeout exception that prevented reaching the correct startLevel? (100)

zinnik · August 28, 2023, 4:27pm

Hallo gibt es jetzt zu der Fehlermeldung schon eine Lösung , wenn ja wo kann ich sie finden?
Ich habe das gleich Problem mit genau der Gleichen Fehler im LOG.
Ich nutze openhab 4.0.1 und influxdb 1.8.2

Bitte um Hilfe.
Lg zinnik

Hello, is there already a solution to the error message, if so where can I find it?
I have the same problem with exactly the same error in the LOG.
I use openhab 4.0.1 and influxdb 1.8.2

Please help.
Hello zinnik

OMR · August 30, 2023, 8:24pm

Things are much better in 4.0.2, but some rapid changing items with a long history still fails:

omr@shs2:~$ grep -i influxdb /var/log/openhab/openhab.log | grep -i 'more than'
2023-08-22 20:17:59.016 [WARN ] [sistence.internal.PersistenceManager] - Querying persistence service 'influxdb' to restore 'ZWaveNode123FGBS222SmartImplantSewerPump_Input1Voltage' takes more than 5000ms.
2023-08-22 20:18:22.994 [WARN ] [sistence.internal.PersistenceManager] - Querying persistence service 'influxdb' to restore 'ZWaveNode137ZW078HeavyDutySwitchBoiler_Electricmetervolts' takes more than 5000ms.
2023-08-22 20:18:29.167 [WARN ] [sistence.internal.PersistenceManager] - Querying persistence service 'influxdb' to restore 'kWHhourlyConsumption' takes more than 5000ms.
2023-08-22 20:19:56.510 [WARN ] [sistence.internal.PersistenceManager] - Querying persistence service 'influxdb' to restore 'ZWaveNode137ZW078HeavyDutySwitchBoiler_Electricmetervolts' takes more than 5000ms.