openHAB 4.0 Milestone discussion

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.

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}

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.

Will do, but not remotely :slight_smile:
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.

1 Like

@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.

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.

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

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

Because ofslow writing time?

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.

But what was the situation in OH 3?

Infinite retries with increased timestamp until successful. The problems that this again will lead to a situation where we build up scheduled tasks until resources are exhausted. Maybe we can increase the limit to 10 retried instead of 1, but I doubt it will solve the issue. It would probably be better to apply a time filter that discards values that are updated too frequently.

Yes, I still haver to write documentation for persistence filters. It’s on my list.

What is the fastest time between 2 persistence points?

From core perspective? Probably a few milli-second. It really depends what the persistence service can store, not so much on core performance. For influxdb writes to the database are queued and batched if possible.

1 Like

I recently switched to JPA backed by Postgres/TimescaleDB for persistence, with a custom unique constraint on (name, timestamp) (JPA doesn’t actually enforce that with the default schema it creates). Postgres persists microsecond precision (and it appears that openHAB passes with that much precision). I still get a few times a day that that unique constraint is violated, and occasionally with different state values.

2 Likes

Sorry that’s no solution, because I want the logs, when states changes. But not all x seconds, when nothing changes.

Yes, it is. There is a logger ItemStateUpdatedEvent and a logger ItemStateChangedEvent (name may vary).
The point is: in openHAB (since version 1.x? up to openHAB 3.4.4) the logger always was set to ERROR level and accidentally was set to INFO for openHAB4.0.

Ah sorry then I didn’t understand you before, but now. Thanks a lot Udo, I will try to reduce log level.

A minor quibble. It’s actually a new event. Previously there was ItemStateEvent only. Now, in addition, there is ItemStateUpdatedEvent and GroupStateUpdatedEvent. Since these events are new, they are not part of log4j2.xml and may need to be added with the level set to ERROR.

The upgrade script should now deploy the new log4j2.xml file but if you’ve changed that fine on the past apt/yum will ask if you want to keep the old or replace it with the new. If you keep the old these events will not be suppressed. I don’t know how manual install updates handle it.

Thank you for the answer…I am not complaining I just for my interest…