Webserver seems to freeze

Hello everybody,

I’m using OpenHAB since a few months, but it seems to freeze after an undefined amount of time. I can’t reach the control panel. Nether via intranet or via the cloud service.

My configuration:

Raspberry Pi 4 Model B - 2GB
openHABian with openHAB 3.3.0

At first I did what every beginner does I guess: Just restart it by restarting the Raspberry Pi. Then I found out that I could just restart the service.

But when it kept freezing and I kept restarting I of course wanted to know what could be done about it. I’ve looked into the “status” command and at the moment I can’t reach the webinterface (so when it’s “frozen”), it comes back like this:

A systemd service configuration exists...
Use 'sudo /bin/systemctl status openhab.service' to find the status of an openHAB service
openHAB is running with PID: 2**8 and has been running for 33-22:59:35

Then I tried the suggestion which came back, and use the command as stated above and the following came back:

● openhab.service - openHAB - empowering the smart home
     Loaded: loaded (/lib/systemd/system/openhab.service; enabled; vendor preset: enabled)
    Drop-In: /etc/systemd/system/openhab.service.d
             └─override.conf
     Active: active (running) since Mon 2022-09-26 11:25:00 CEST; 1 months 3 days ago
       Docs: https://www.openhab.org/docs/
             https://community.openhab.org
   Main PID: 2**8 (java)
      Tasks: 268 (limit: 4455)
        CPU: 1d 8h 10min 23.013s
     CGroup: /system.slice/openhab.service
             └─2**8 /usr/bin/java -XX:-UsePerfData -Dopenhab.home=/usr/share/openhab -Dopenhab.conf=/etc/openhab -Dopenhab.runtime=/usr/share/openhab/runtime -Dopenhab.userdat>

Warning: journal has been rotated since unit was started, output may be incomplete.

As a total beginner to, well everything, I think this means that everything is running OK. Could it just be that the webserver freezes and that’s the reason I can’t connect?

I’ve also checked the logs and the output is as follows:

==> /var/log/openhab/audit.log <==

==> /var/log/openhab/events.log <==
2022-10-03 23:54:38.949 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Humidifier_RunTime' changed from 14021.316944444445 h to 14021.325277777778 h
2022-10-03 23:54:42.942 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Consuela_Batterijniveau' changed from 72 to 71
2022-10-03 23:54:42.948 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Consuela_Status_Clean_Area' changed from 31.06 to 31.16
2022-10-03 23:54:42.955 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Consuela_CleaningTime' changed from 33 to 34
2022-10-03 23:54:43.460 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Consuela_CleaningMap' changed from raw type (image/jpeg): 22175 bytes to raw type (image/jpeg): 22388 bytes
2022-10-03 23:55:08.902 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Humidifier_RunTime' changed from 14021.325277777778 h to 14021.333611111111 h
2022-10-03 23:55:12.954 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Consuela_Status_Clean_Area' changed from 31.16 to 31.27
2022-10-03 23:55:13.460 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Consuela_CleaningMap' changed from raw type (image/jpeg): 22388 bytes to raw type (image/jpeg): 22380 bytes
2022-10-03 23:55:38.845 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Humidifier_RunTime' changed from 14021.333611111111 h to 14021.341944444444 h
2022-10-03 23:55:42.971 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Consuela_Batterijniveau' changed from 71 to 70

==> /var/log/openhab/openhab.log <==
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:409) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034) [bundleFile:9.4.46.v20220331]
	at java.lang.Thread.run(Thread.java:829) [?:?]

It seems like the last thing it did was some status-change on 10-03-2022 (I’ve been on holiday, so I didn’t use the system).

At the moment I haven’t restarted or did anything, so maybe I could get some tips about how to troubleshoot this further.

Edit: I just found out that the log-file was bigger than shown in the terminal. I’ve copied the last rows where there are warnings. Those warnings seem to have something to do with the Mi-connection. I see some disconnect, after that some connect. I don’t really know what to make of it…

2022-09-29 06:27:16.837 [INFO ] [miio.internal.cloud.MiCloudConnector] - Repeated errors logging on to Xiaomi cloud. Cleaning stored cookies
2022-09-29 06:27:17.040 [INFO ] [miio.internal.cloud.MiCloudConnector] - Cannot execute request. service token or userId missing
2022-09-29 14:08:32.687 [INFO ] [io.openhabcloud.internal.CloudClient] - Disconnected from the openHAB Cloud service (UUID = 66ed6414-bf69-43a3-affd-6b522d6b5b62, base URL = http://localhost:8080)
2022-09-29 14:12:15.343 [WARN ] [e.californium.scandium.DTLSConnector] - Shutdown DTLS connector on [0.0.0.0/0.0.0.0:33568] executor not terminated in time!
2022-09-29 14:15:22.143 [WARN ] [e.californium.scandium.DTLSConnector] - Shutdown DTLS connector on [0.0.0.0/0.0.0.0:39092] executor not terminated in time!
2022-09-29 14:16:24.767 [WARN ] [e.californium.scandium.DTLSConnector] - Shutdown DTLS connector on [0.0.0.0/0.0.0.0:58431] executor not terminated in time!
2022-09-29 14:20:02.607 [WARN ] [e.californium.scandium.DTLSConnector] - Shutdown DTLS connector on [0.0.0.0/0.0.0.0:43784] executor not terminated in time!
2022-09-29 14:21:36.271 [WARN ] [e.californium.scandium.DTLSConnector] - Shutdown DTLS connector on [0.0.0.0/0.0.0.0:47484] executor not terminated in time!
2022-09-29 14:23:40.982 [WARN ] [e.californium.scandium.DTLSConnector] - Shutdown DTLS connector on [0.0.0.0/0.0.0.0:53299] executor not terminated in time!
2022-09-29 14:29:14.599 [INFO ] [io.openhabcloud.internal.CloudClient] - Connected to the openHAB Cloud service (UUID = 66ed6414-bf69-43a3-affd-6b522d6b5b62, base URL = http://localhost:8080)
2022-09-29 14:29:44.525 [INFO ] [io.openhabcloud.internal.CloudClient] - Disconnected from the openHAB Cloud service (UUID = 66ed6414-bf69-43a3-affd-6b522d6b5b62, base URL = http://localhost:8080)
2022-09-29 14:29:48.998 [INFO ] [io.openhabcloud.internal.CloudClient] - Connected to the openHAB Cloud service (UUID = 66ed6414-bf69-43a3-affd-6b522d6b5b62, base URL = http://localhost:8080)
2022-10-03 15:07:16.470 [INFO ] [miio.internal.cloud.MiCloudConnector] - Repeated errors logging on to Xiaomi cloud. Cleaning stored cookies
2022-10-03 15:07:16.648 [INFO ] [miio.internal.cloud.MiCloudConnector] - Cannot execute request. service token or userId missing
2022-10-03 23:15:36.414 [WARN ] [e.internal.SseItemStatesEventBuilder] - Attempting to send a state update of an item which doesn't exist: gWindowLights
2022-10-03 23:15:57.870 [WARN ] [e.internal.SseItemStatesEventBuilder] - Attempting to send a state update of an item which doesn't exist: gWindowLights
2022-10-03 23:15:59.543 [WARN ] [e.internal.SseItemStatesEventBuilder] - Attempting to send a state update of an item which doesn't exist: gWindowLights
2022-10-03 23:16:04.030 [WARN ] [e.internal.SseItemStatesEventBuilder] - Attempting to send a state update of an item which doesn't exist: gWindowLights
2022-10-03 23:16:05.884 [WARN ] [e.internal.SseItemStatesEventBuilder] - Attempting to send a state update of an item which doesn't exist: gWindowLights
2022-10-03 23:19:27.044 [WARN ] [e.internal.SseItemStatesEventBuilder] - Attempting to send a state update of an item which doesn't exist: gWindowLights
2022-10-03 23:19:30.475 [WARN ] [e.internal.SseItemStatesEventBuilder] - Attempting to send a state update of an item which doesn't exist: gWindowLights
2022-10-03 23:55:47.971 [WARN ] [ab.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.io.monitor.internal.EventLogger@19e82dc' takes more than 5000ms.
2022-10-04 02:14:03.302 [WARN ] [org.eclipse.jetty.server.HttpChannel] - google.com:443
java.lang.StringIndexOutOfBoundsException: begin 0, end -1, length 14
	at java.lang.String.checkBoundsBeginEnd(String.java:3319) ~[?:?]
	at java.lang.String.substring(String.java:1874) ~[?:?]
	at org.ops4j.pax.web.service.spi.model.ServerModel.matchPathToContext(ServerModel.java:370) ~[?:?]
	at org.ops4j.pax.web.service.spi.model.ServerModel.matchPathToContext(ServerModel.java:310) ~[?:?]
	at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:73) ~[?:?]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.server.Server.handle(Server.java:516) ~[bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:487) ~[bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:732) ~[bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:479) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:409) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034) [bundleFile:9.4.46.v20220331]
	at java.lang.Thread.run(Thread.java:829) [?:?]

Which specific version of OH 3?

I don’t think there is enough information here. Do you see any OutOfMemory errors in openHAB log?

What’s in openHAB log at and around OH first stopped responding?

What add-ons are installed?

Thank you for your response. I’ve added the specific version to the original post: 3.3.0.

It seems to me like the last thing that is being logged is:

2022-10-04 02:14:03.302 [WARN ] [org.eclipse.jetty.server.HttpChannel] - google.com:443
java.lang.StringIndexOutOfBoundsException: begin 0, end -1, length 14
	at java.lang.String.checkBoundsBeginEnd(String.java:3319) ~[?:?]
	at java.lang.String.substring(String.java:1874) ~[?:?]
	at org.ops4j.pax.web.service.spi.model.ServerModel.matchPathToContext(ServerModel.java:370) ~[?:?]
	at org.ops4j.pax.web.service.spi.model.ServerModel.matchPathToContext(ServerModel.java:310) ~[?:?]
	at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:73) ~[?:?]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.server.Server.handle(Server.java:516) ~[bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:487) ~[bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:732) ~[bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:479) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:409) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883) [bundleFile:9.4.46.v20220331]
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034) [bundleFile:9.4.46.v20220331]
	at java.lang.Thread.run(Thread.java:829) [?:?]

After that nothing. As for add-ons, I have the following real add-ons:

  • openHAB Cloud Connector
  • RRD4j Persistence

And I have the following bindings:

  • Chromecast Binding
  • Hue Binding
  • OpenWeatherMap Binding
  • TRÅDFRI Binding
  • Xiaomi Wifi devices (Mi IO) Binding

The Mi-binding seems to give some errors in the log. But there just “INFO” and not “WARN”. I have now disabled it, restarted and will wait if it freezes again. Is it so that an error in one of the bindings can bring the whole system down?

Are you using Google Assistant integration? The warning appears to be complaining about some sort of attempt to do some sort of HTTP operation with google.com:443.

That URL isn’t necessarily the problem. It’s trying to look at the string between 0 and -1 which, of course, doesn’t make sense so it can’t process beyond that point.

Usually only if there is a memory leak in the binding.

The Google Assistant is integrated via the MyOpenHAB-cloud. I’ve disabled it for the time being. I also disabled the Chromecast Binding.

I will try to let it run for a while now, then the next step is maybe to disable the MI-binding (because it gave a few warnings), but that binding is an important part of my home-automation.