HTTP binding outages of 1-3 minutes - why?

  • Platform information:
    • Hardware: virtual Machine on ESX Server
    • OS: Suse Linux Enterprise Server 15
    • Java Runtime Environment: zulu8.33.0.1-jdk8.0.192
    • openHAB version: 2.3.0
  • Issue of the topic: HTTP binding read in shows dropouts of about 1-2 minutes after OpenHAB ran for a day
  • Please post configurations (if applicable):
    • Items configuration related to the issue
Number:ElectricPotential ALL4176_Voltage   "Voltage [%.2f V]"  <line> { http="<[http://<ipaddres>/xml/json.php?mode=sensor&id=14{Authorization=Basic <username/password>==}:10000:JSONPATH($[0].value)]" }

After I switched to a Linux environment with my OpenHAB installation, I can see weird dropouts in HTTP binding value readings which I didn’t see (or just didn’t recognize?) on Windows. I have some Item s configured (about eight for that hardware) that get their value with HTTP binding, see example above. Measured value is net voltage with two decimals, so this value will change on every measure. I configured a granularity of 10 seconds (10000 milliseconds), and for debugging purposes I configured a EveryChange persistence for this item. After OpenHAB running some time, I can see the dropouts.

On 2018-12-13 10:16 I restarted OpenHAB and the dropouts disappeared (see lower right pane, one log every 10 to 11 seconds):

One day later, 2018-12-14 13:13:54 - 13:16:13 is the first outage, no data gets read in, despites CPU load and memory usage are still the same:

This continues even until today:

Logs shows same behavior, but Grafana it more graphic :slight_smile:

What’s the problem here?

Thanks in advance!

Try debugging the http binding and see what happens when the requests fail …

Okay I figured it out. I issued a log:set DEBUG org.openhab.binding.http on command line and got some logs:

openhab.log

2018-12-17 11:56:41.915 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Voltage' is about to be refreshed now
2018-12-17 11:56:41.964 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is '227.75'
2018-12-17 11:56:41.964 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Current' is about to be refreshed now
2018-12-17 11:56:42.048 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is '0.18'
2018-12-17 11:56:42.048 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais1Status' is fetched from cache
2018-12-17 11:56:42.048 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais1StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=1&get')
2018-12-17 11:56:42.081 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'ON'
2018-12-17 11:56:42.082 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais4Status' is fetched from cache
2018-12-17 11:56:42.082 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais4StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=4&get')
2018-12-17 11:56:42.114 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'OFF'
2018-12-17 11:56:43.114 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais2Status' is fetched from cache
2018-12-17 11:56:43.115 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais2StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=2&get')
2018-12-17 11:56:43.139 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'OFF'
2018-12-17 11:56:43.140 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais3Status' is fetched from cache
2018-12-17 11:56:43.140 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais3StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=3&get')
2018-12-17 11:56:43.160 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'OFF'
2018-12-17 11:56:43.160 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais6Status' is fetched from cache
2018-12-17 11:56:43.160 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais6StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=6&get')
2018-12-17 11:56:43.179 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'OFF'
2018-12-17 11:56:43.180 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais5Status' is fetched from cache
2018-12-17 11:56:43.180 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais5StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=5&get')
2018-12-17 11:56:43.202 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'OFF'
2018-12-17 11:56:43.202 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais1Status' is fetched from cache
2018-12-17 11:56:43.203 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais1StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=1&get')
2018-12-17 11:56:43.221 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'ON'
2018-12-17 11:56:43.222 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais4Status' is fetched from cache
2018-12-17 11:56:43.222 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais4StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=4&get')
2018-12-17 11:56:43.241 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'OFF'
2018-12-17 11:56:44.242 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais2Status' is fetched from cache
2018-12-17 11:56:44.242 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais2StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=2&get')
2018-12-17 11:56:44.262 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'OFF'
2018-12-17 11:56:44.263 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais3Status' is fetched from cache
2018-12-17 11:56:44.263 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais3StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=3&get')
2018-12-17 11:56:44.282 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'OFF'
2018-12-17 11:56:44.283 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais6Status' is fetched from cache
2018-12-17 11:56:44.283 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais6StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=6&get')
2018-12-17 11:56:44.301 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'OFF'
2018-12-17 11:56:44.302 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais5Status' is fetched from cache
2018-12-17 11:56:44.302 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais5StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=5&get')
2018-12-17 11:56:44.335 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'OFF'
2018-12-17 11:56:44.335 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais1Status' is fetched from cache
2018-12-17 11:56:44.335 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais1StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=1&get')
2018-12-17 11:56:44.373 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'ON'
2018-12-17 11:56:44.374 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais4Status' is fetched from cache
2018-12-17 11:56:44.374 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais4StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=4&get')
2018-12-17 11:56:44.392 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'OFF'
2018-12-17 11:56:45.393 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais2Status' is fetched from cache
2018-12-17 11:56:45.393 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais2StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=2&get')
2018-12-17 11:56:45.413 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'OFF'
2018-12-17 11:56:45.413 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais3Status' is fetched from cache
2018-12-17 11:56:45.413 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais3StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=3&get')
2018-12-17 11:56:45.436 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'OFF'
2018-12-17 11:56:45.436 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais6Status' is fetched from cache
2018-12-17 11:56:45.436 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais6StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=6&get')
2018-12-17 11:56:45.459 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'OFF'
2018-12-17 11:56:45.460 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais5Status' is fetched from cache
2018-12-17 11:56:45.460 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais5StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=5&get')
2018-12-17 11:56:45.513 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'OFF'
2018-12-17 11:56:45.514 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais1Status' is fetched from cache
2018-12-17 11:56:45.514 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais1StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=1&get')
2018-12-17 11:56:45.534 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'ON'
2018-12-17 11:56:45.535 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais4Status' is fetched from cache
2018-12-17 11:56:45.535 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais4StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=4&get')
2018-12-17 11:56:45.554 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'OFF'
2018-12-17 11:56:46.554 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais2Status' is fetched from cache
2018-12-17 11:56:46.554 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais2StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=2&get')
2018-12-17 11:56:46.577 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'OFF'
2018-12-17 11:56:46.578 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais3Status' is fetched from cache
2018-12-17 11:56:46.578 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais3StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=3&get')
2018-12-17 11:56:46.596 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'OFF'
2018-12-17 11:56:46.597 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais6Status' is fetched from cache
2018-12-17 11:56:46.597 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais6StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=6&get')
2018-12-17 11:56:46.616 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'OFF'
2018-12-17 11:56:46.616 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais5Status' is fetched from cache
2018-12-17 11:56:46.616 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais5StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=5&get')
2018-12-17 11:56:46.635 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'OFF'
2018-12-17 11:56:46.653 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais1Status' is fetched from cache
2018-12-17 11:56:46.653 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais1StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=1&get')
2018-12-17 11:56:46.684 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'ON'
2018-12-17 11:56:46.685 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais4Status' is fetched from cache
2018-12-17 11:56:46.685 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais4StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=4&get')
2018-12-17 11:56:46.715 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'OFF'
2018-12-17 11:56:47.716 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais2Status' is fetched from cache
2018-12-17 11:56:47.716 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais2StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=2&get')
2018-12-17 11:56:47.738 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'OFF'
2018-12-17 11:56:47.738 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais3Status' is fetched from cache
2018-12-17 11:56:47.739 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais3StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=3&get')
2018-12-17 11:56:47.760 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'OFF'
2018-12-17 11:56:47.760 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais6Status' is fetched from cache
2018-12-17 11:56:47.760 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais6StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=6&get')
2018-12-17 11:56:47.800 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'OFF'
2018-12-17 11:56:47.800 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais5Status' is fetched from cache
2018-12-17 11:56:47.801 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais5StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=5&get')
2018-12-17 11:56:47.856 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'OFF'
2018-12-17 11:56:47.856 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais1Status' is fetched from cache
2018-12-17 11:56:47.856 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais1StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=1&get')
2018-12-17 11:56:47.875 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'ON'
2018-12-17 11:56:47.876 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais4Status' is fetched from cache
2018-12-17 11:56:47.876 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais4StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=4&get')
2018-12-17 11:58:58.927 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'OFF'
2018-12-17 11:58:59.928 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais2Status' is fetched from cache
2018-12-17 11:58:59.928 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais2StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=2&get')
2018-12-17 11:58:59.952 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'OFF'
2018-12-17 11:58:59.952 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais3Status' is fetched from cache
2018-12-17 11:58:59.953 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais3StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=3&get')
2018-12-17 11:58:59.976 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'OFF'
2018-12-17 11:58:59.976 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais6Status' is fetched from cache
2018-12-17 11:58:59.976 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais6StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=6&get')
2018-12-17 11:58:59.996 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'OFF'
2018-12-17 11:58:59.996 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'SV_Jenkins_2_json' is fetched from cache
2018-12-17 11:58:59.997 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'jenkins2Cache' ('https://[...]/api/json')
2018-12-17 11:59:00.671 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is '[...]'
2018-12-17 11:59:00.672 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'SV_Jenkins_1_json' is fetched from cache
2018-12-17 11:59:00.673 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'jenkins1Cache' ('https://[...]/api/json')
2018-12-17 11:59:01.299 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is '[...]'
2018-12-17 11:59:01.300 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais5Status' is fetched from cache
2018-12-17 11:59:01.300 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais5StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=5&get')
2018-12-17 11:59:01.324 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'OFF'
2018-12-17 11:59:01.325 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Voltage' is about to be refreshed now
2018-12-17 11:59:01.374 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is '228.30'
2018-12-17 11:59:01.375 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Current' is about to be refreshed now
2018-12-17 11:59:01.423 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is '0.18'

So because of updating cache for 'ALL4176_Relais4StatusCache at 11:56:47.876 did take two minutes all other HTTP requests got delayed, correct? Or what did happen here?
Is it possible to configure more than one worker?

Seems like it, but I don’t know how the http binding handles its “workers” or threads. According to the docs there’s no configuration for this AFAIK.

An alternative approach is using an external script (python etc.) to handle the requests and update OH via MQTT or similar.

It’s even getting worse today:

I analyzed the logs from yesterday, it’s always the same:

2018-12-17 11:53:27.344 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais5Status' is fetched from cache
2018-12-17 11:53:27.345 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais5StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=5&get')
2018-12-17 11:55:38.221 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'OFF'

2018-12-17 11:56:47.876 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais4Status' is fetched from cache
2018-12-17 11:56:47.876 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais4StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=4&get')
2018-12-17 11:58:58.927 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'OFF'

2018-12-17 12:04:54.569 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais4Status' is fetched from cache
2018-12-17 12:04:54.569 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais4StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=4&get')
2018-12-17 12:07:04.303 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'OFF'

2018-12-17 12:10:19.941 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais1RedLampStatus' is fetched from cache
2018-12-17 12:10:19.941 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais1StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=1&get')
2018-12-17 12:12:29.931 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'ON'

2018-12-17 12:14:57.226 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais6Status' is fetched from cache
2018-12-17 12:14:57.227 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais6StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=6&get')
2018-12-17 12:17:06.415 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'OFF'

2018-12-17 12:17:34.704 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais4Status' is fetched from cache
2018-12-17 12:17:34.705 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais4StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=4&get')
2018-12-17 12:19:44.110 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'OFF'

Yeah, one could use an external script - but why, when OpenHAB provides HTTP functionality? It would be better to fix that than to write someting external.

I did a log with TRACE some minutes ago, but I can only analyze that later, stay tuned.

So here are the logs with TRACE level. Seems as the caches are a bit intereaved, but I still can’t see a root cause:.
Outages are at the end of each log, you can see the timestamps.

2018-12-18 10:51:29.851 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Current' is about to be refreshed now
2018-12-18 10:51:29.901 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is '0.15'
2018-12-18 10:51:29.902 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais1Status' is fetched from cache
2018-12-18 10:51:29.902 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais1StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=1&get')
2018-12-18 10:51:29.902 [TRACE] [ab.binding.http.internal.HttpBinding] - Couldn't find matching binding provider [itemName=ALL4176_Current, command=CHANGED]
2018-12-18 10:51:29.932 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'OFF'
2018-12-18 10:51:29.932 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais4Status' is fetched from cache
2018-12-18 10:51:29.932 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais4StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=4&get')
2018-12-18 10:51:29.933 [TRACE] [ab.binding.http.internal.HttpBinding] - Couldn't find matching binding provider [itemName=ALL4176_Relais1Status, command=CHANGED]
2018-12-18 10:51:29.982 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'OFF'
2018-12-18 10:51:29.983 [TRACE] [ab.binding.http.internal.HttpBinding] - Couldn't find matching binding provider [itemName=ALL4176_Relais4Status, command=CHANGED]
2018-12-18 10:51:30.983 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais2Status' is fetched from cache
2018-12-18 10:51:30.983 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais2StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=2&get')
2018-12-18 10:51:31.003 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'ON'
2018-12-18 10:51:31.003 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais3Status' is fetched from cache
2018-12-18 10:51:31.003 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais3StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=3&get')
2018-12-18 10:51:31.004 [TRACE] [ab.binding.http.internal.HttpBinding] - Couldn't find matching binding provider [itemName=ALL4176_Relais2Status, command=CHANGED]
2018-12-18 10:53:41.330 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'OFF'
2018-12-18 10:53:41.331 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais6Status' is fetched from cache
2018-12-18 10:53:41.331 [TRACE] [ab.binding.http.internal.HttpBinding] - Couldn't find matching binding provider [itemName=ALL4176_Relais3Status, command=CHANGED]
2018-12-18 10:53:41.331 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais6StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=6&get')
2018-12-18 10:53:41.361 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'OFF'
2018-12-18 10:53:48.479 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais3Status' is fetched from cache
2018-12-18 10:53:48.480 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais3StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=3&get')
2018-12-18 10:53:48.480 [TRACE] [ab.binding.http.internal.HttpBinding] - Couldn't find matching binding provider [itemName=ALL4176_Relais2Status, command=CHANGED]
2018-12-18 10:53:48.500 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'OFF'
2018-12-18 10:53:48.500 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais6Status' is fetched from cache
2018-12-18 10:53:48.500 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais6StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=6&get')
2018-12-18 10:53:48.500 [TRACE] [ab.binding.http.internal.HttpBinding] - Couldn't find matching binding provider [itemName=ALL4176_Relais3Status, command=CHANGED]
2018-12-18 10:53:48.544 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'OFF'
2018-12-18 10:53:48.545 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais5Status' is fetched from cache
2018-12-18 10:53:48.545 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais5StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=5&get')
2018-12-18 10:53:48.545 [TRACE] [ab.binding.http.internal.HttpBinding] - Couldn't find matching binding provider [itemName=ALL4176_Relais6Status, command=CHANGED]
2018-12-18 10:53:48.575 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'OFF'
2018-12-18 10:53:48.576 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais1Status' is fetched from cache
2018-12-18 10:53:48.576 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais1StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=1&get')
2018-12-18 10:53:48.576 [TRACE] [ab.binding.http.internal.HttpBinding] - Couldn't find matching binding provider [itemName=ALL4176_Relais5Status, command=CHANGED]
2018-12-18 10:53:48.596 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'OFF'
2018-12-18 10:53:48.596 [TRACE] [ab.binding.http.internal.HttpBinding] - Couldn't find matching binding provider [itemName=ALL4176_Relais1Status, command=CHANGED]
2018-12-18 10:53:48.597 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais4Status' is fetched from cache
2018-12-18 10:53:48.597 [DEBUG] [ab.binding.http.internal.HttpBinding] - updating cache for 'ALL4176_Relais4StatusCache' ('http://<ipaddress>/xml/jsonswitch.php?id=4&get')
2018-12-18 10:55:58.545 [DEBUG] [ab.binding.http.internal.HttpBinding] - transformed response is 'OFF'
2018-12-18 10:55:58.545 [TRACE] [ab.binding.http.internal.HttpBinding] - Couldn't find matching binding provider [itemName=ALL4176_Relais4Status, command=CHANGED]
2018-12-18 10:55:59.545 [DEBUG] [ab.binding.http.internal.HttpBinding] - item 'ALL4176_Relais2Status' is fetched from cache

Some days later I finally restarted OpenHAB and target hardware - and still experienced the outages.

Then finally on December 27th in the middle of the night, it worked again (until now).
I didn’t change anything there, openhab.log and events.log don’t tell interesting things for that time, even syslog is empty between 2:00 and 3:00 am.

So I currently don’t know where to look for tracking down the root cause, but I’ll try to reduce the number of HTTP requests and caches.

Update earlier than I thought… About 12:05 the server started to go wild. I also have a network:pingdevice set up for the device, this was always ON and now started to switch to OFF and back about every second minute - despites a (system) ping worked flawlessly during this time. Updates to Influxdb also got less and less.

I did a OpenHAB restart at about 12:30 and now it works again - I suppose that’s the behaviour I observed at the beginning of this thread.

Log showed errors like this:

==> /log/openhab2/openhab.log <==
2019-01-02 12:27:08.173 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.core.internal.items.ItemUpdater@6b47eff4' takes more than 5000ms.

2019-01-02 12:30:12.722 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception
java.lang.OutOfMemoryError: Java heap space
	at java.io.BufferedReader.<init>(BufferedReader.java:105) ~[?:?]
	at java.io.BufferedReader.<init>(BufferedReader.java:116) ~[?:?]
	at java.nio.file.Files.newBufferedReader(Files.java:2785) ~[?:?]
	at java.nio.file.Files.readAllLines(Files.java:3202) ~[?:?]
	at oshi.util.FileUtil.readFile(FileUtil.java:75) ~[?:?]
	at oshi.util.FileUtil.readFile(FileUtil.java:56) ~[?:?]
	at oshi.software.os.linux.LinuxFileSystem.getFileStores(LinuxFileSystem.java:133) ~[?:?]
	at org.openhab.binding.systeminfo.internal.model.OshiSysteminfo.getStorageUsedPercent(OshiSysteminfo.java:251) ~[?:?]
	at org.openhab.binding.systeminfo.handler.SysteminfoHandler.getInfoForChannel(SysteminfoHandler.java:400) ~[?:?]
	at org.openhab.binding.systeminfo.handler.SysteminfoHandler.publishDataForChannel(SysteminfoHandler.java:249) ~[?:?]
	at org.openhab.binding.systeminfo.handler.SysteminfoHandler.publishData(SysteminfoHandler.java:242) ~[?:?]
	at org.openhab.binding.systeminfo.handler.SysteminfoHandler.lambda$0(SysteminfoHandler.java:221) ~[?:?]
	at org.openhab.binding.systeminfo.handler.SysteminfoHandler$$Lambda$237/192177765.run(Unknown Source) ~[?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:?]
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
	at java.lang.Thread.run(Thread.java:748) [?:?]
2019-01-02 12:30:40.242 [ERROR] [io.openhabcloud.internal.CloudClient] - Socket.IO error: {}
io.socket.engineio.client.EngineIOException: websocket error
	at io.socket.engineio.client.Transport.onError(Transport.java:71) [211:org.openhab.io.openhabcloud:2.3.0]
	at io.socket.engineio.client.transports.WebSocket.access$500(WebSocket.java:28) [211:org.openhab.io.openhabcloud:2.3.0]
	at io.socket.engineio.client.transports.WebSocket$2$5.run(WebSocket.java:150) [211:org.openhab.io.openhabcloud:2.3.0]
	at io.socket.thread.EventThread$2.run(EventThread.java:80) [211:org.openhab.io.openhabcloud:2.3.0]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
	at java.lang.Thread.run(Thread.java:748) [?:?]
Caused by: java.io.EOFException
	at okio.RealBufferedSource.require(RealBufferedSource.java:59) ~[?:?]
	at okio.RealBufferedSource.readByte(RealBufferedSource.java:72) ~[?:?]
	at okhttp3.internal.ws.WebSocketReader.readHeader(WebSocketReader.java:115) ~[?:?]
	at okhttp3.internal.ws.WebSocketReader.processNextFrame(WebSocketReader.java:104) ~[?:?]
	at okhttp3.internal.ws.RealWebSocket.readMessage(RealWebSocket.java:97) ~[?:?]
	at okhttp3.ws.WebSocketCall.createWebSocket(WebSocketCall.java:152) ~[?:?]
	at okhttp3.ws.WebSocketCall.access$000(WebSocketCall.java:41) ~[?:?]
	at okhttp3.ws.WebSocketCall$1.onResponse(WebSocketCall.java:97) ~[?:?]
	at okhttp3.RealCall$AsyncCall.execute(RealCall.java:126) ~[?:?]
	at okhttp3.internal.NamedRunnable.run(NamedRunnable.java:32) ~[?:?]
	... 3 more
2019-01-02 12:30:38.117 [WARN ] [eclipse.jetty.servlet.ServletHandler] - Error for /rest/sitemaps/events/subscribe
java.lang.OutOfMemoryError: Java heap space
2019-01-02 12:30:38.116 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception
java.lang.OutOfMemoryError: Java heap space

2019-01-02 12:33:15.076 [WARN ] [eclipse.jetty.servlet.ServletHandler] - 
javax.servlet.ServletException: A MultiException has 1 exceptions.  They are:
1. java.lang.IllegalStateException: ServiceLocatorImpl(__HK2_Generated_1,2,18838638) has been shut down
	at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:489) [167:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
	at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:427) [167:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:388) [167:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:341) [167:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
	at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:228) [167:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
	at com.eclipsesource.jaxrs.publisher.internal.ServletContainerBridge.service(ServletContainerBridge.java:76) [15:com.eclipsesource.jaxrs.publisher:5.3.1.201602281253]
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:848) [85:org.eclipse.jetty.servlet:9.3.21.v20170918]
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:584) [85:org.eclipse.jetty.servlet:9.3.21.v20170918]
	at org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:71) [183:org.ops4j.pax.web.pax-web-jetty:6.0.9]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548) [82:org.eclipse.jetty.security:9.3.21.v20170918]
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:226) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1180) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:284) [183:org.ops4j.pax.web.pax-web-jetty:6.0.9]
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:512) [85:org.eclipse.jetty.servlet:9.3.21.v20170918]
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1112) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:80) [183:org.ops4j.pax.web.pax-web-jetty:6.0.9]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.Server.handle(Server.java:534) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:333) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:251) [84:org.eclipse.jetty.server:9.3.21.v20170918]
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:283) [76:org.eclipse.jetty.io:9.3.21.v20170918]
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:108) [76:org.eclipse.jetty.io:9.3.21.v20170918]
	at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:93) [76:org.eclipse.jetty.io:9.3.21.v20170918]
	at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.executeProduceConsume(ExecuteProduceConsume.java:303) [87:org.eclipse.jetty.util:9.3.21.v20170918]
	at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceConsume(ExecuteProduceConsume.java:148) [87:org.eclipse.jetty.util:9.3.21.v20170918]
	at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:136) [87:org.eclipse.jetty.util:9.3.21.v20170918]
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:671) [87:org.eclipse.jetty.util:9.3.21.v20170918]
	at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:589) [87:org.eclipse.jetty.util:9.3.21.v20170918]
	at java.lang.Thread.run(Thread.java:748) [?:?]
Caused by: org.glassfish.hk2.api.MultiException: A MultiException has 1 exceptions.  They are:
1. java.lang.IllegalStateException: ServiceLocatorImpl(__HK2_Generated_1,2,18838638) has been shut down
	at org.jvnet.hk2.internal.FactoryCreator.getFactoryHandle(FactoryCreator.java:106) ~[?:?]
	at org.jvnet.hk2.internal.FactoryCreator.dispose(FactoryCreator.java:173) ~[?:?]
	at org.jvnet.hk2.internal.SystemDescriptor.dispose(SystemDescriptor.java:526) ~[?:?]
	at org.glassfish.jersey.process.internal.RequestScope$Instance.remove(RequestScope.java:532) ~[169:org.glassfish.jersey.core.jersey-common:2.22.2]
	at org.glassfish.jersey.process.internal.RequestScope$Instance.release(RequestScope.java:549) ~[169:org.glassfish.jersey.core.jersey-common:2.22.2]
	at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:319) ~[169:org.glassfish.jersey.core.jersey-common:2.22.2]
	at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:305) ~[170:org.glassfish.jersey.core.jersey-server:2.22.2]
	at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:1154) ~[170:org.glassfish.jersey.core.jersey-server:2.22.2]
	at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:473) ~[167:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
	... 31 more
Caused by: java.lang.IllegalStateException: ServiceLocatorImpl(__HK2_Generated_1,2,18838638) has been shut down
	at org.jvnet.hk2.internal.ServiceLocatorImpl.checkState(ServiceLocatorImpl.java:2288) ~[?:?]
	at org.jvnet.hk2.internal.ServiceLocatorImpl.getServiceHandleImpl(ServiceLocatorImpl.java:629) ~[?:?]
	at org.jvnet.hk2.internal.ServiceLocatorImpl.getServiceHandle(ServiceLocatorImpl.java:622) ~[?:?]
	at org.jvnet.hk2.internal.ServiceLocatorImpl.getServiceHandle(ServiceLocatorImpl.java:640) ~[?:?]
	at org.jvnet.hk2.internal.FactoryCreator.getFactoryHandle(FactoryCreator.java:103) ~[?:?]
	at org.jvnet.hk2.internal.FactoryCreator.dispose(FactoryCreator.java:173) ~[?:?]
	at org.jvnet.hk2.internal.SystemDescriptor.dispose(SystemDescriptor.java:526) ~[?:?]
	at org.glassfish.jersey.process.internal.RequestScope$Instance.remove(RequestScope.java:532) ~[169:org.glassfish.jersey.core.jersey-common:2.22.2]
	at org.glassfish.jersey.process.internal.RequestScope$Instance.release(RequestScope.java:549) ~[169:org.glassfish.jersey.core.jersey-common:2.22.2]
	at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:319) ~[169:org.glassfish.jersey.core.jersey-common:2.22.2]
	at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:305) ~[170:org.glassfish.jersey.core.jersey-server:2.22.2]
	at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:1154) ~[170:org.glassfish.jersey.core.jersey-server:2.22.2]
	at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:473) ~[167:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
	... 31 more

… and yes, I can see a drop in memory usage (and swap usage I added before restart).
So it looks like a plain memory leak?

… and same symptoms again starting at 17:01 - I didn’t change anything but the added swap used Item and logging with persistence. Why is OpenHAB running wild?

(data between 17:34 and 18:00 is invalid because it’s interpolated linearly)

It ran for about half a month, and now isn’t even able to run half a day?

Logs:

2019-01-02 17:01:56.737 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.core.internal.items.ItemUpdater@3cb00f4d' takes more than 5000ms.
2019-01-02 17:14:08.005 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.core.internal.items.ItemUpdater@3cb00f4d' takes more than 5000ms.
2019-01-02 17:18:36.365 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.io.monitor.internal.EventLogger@699eab9' takes more than 5000ms.
2019-01-02 17:21:35.989 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.core.internal.items.ItemUpdater@3cb00f4d' takes more than 5000ms.
2019-01-02 17:26:59.872 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.core.thing.internal.CommunicationManager@a3de4c9' takes more than 5000ms.
2019-01-02 17:27:15.972 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.io.monitor.internal.EventLogger@699eab9' takes more than 5000ms.
2019-01-02 17:27:15.972 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'EventSubscriber.receive()' on 'org.eclipse.smarthome.io.monitor.internal.EventLogger@699eab9': Java heap space
java.lang.OutOfMemoryError: Java heap space
        at java.util.HashMap.resize(HashMap.java:704) ~[?:?]
        at java.util.HashMap.putVal(HashMap.java:629) ~[?:?]
        at java.util.HashMap.put(HashMap.java:612) ~[?:?]
        at java.util.HashSet.add(HashSet.java:220) ~[?:?]
        at org.apache.felix.eventadmin.impl.handler.EventHandlerTracker.checkHandlerAndAdd(EventHandlerTracker.java:272) ~[?:?]
        at org.apache.felix.eventadmin.impl.handler.EventHandlerTracker.getHandlers(EventHandlerTracker.java:237) ~[?:?]
        at org.apache.felix.eventadmin.impl.handler.EventAdminImpl.postEvent(EventAdminImpl.java:180) ~[?:?]
        at org.apache.felix.eventadmin.impl.security.EventAdminSecurityDecorator.postEvent(EventAdminSecurityDecorator.java:79) ~[?:?]
        at org.ops4j.pax.logging.internal.eventadmin.EventAdminTracker.deliver(EventAdminTracker.java:115) ~[7:org.ops4j.pax.logging.pax-logging-log4j2:1.10.1]
        at org.ops4j.pax.logging.internal.eventadmin.EventAdminTracker.postEvent(EventAdminTracker.java:68) ~[7:org.ops4j.pax.logging.pax-logging-log4j2:1.10.1]
        at org.ops4j.pax.logging.log4j2.internal.PaxLoggingServiceImpl.handleEvents(PaxLoggingServiceImpl.java:378) ~[7:org.ops4j.pax.logging.pax-logging-log4j2:1.10.1]
        at org.ops4j.pax.logging.log4j2.internal.PaxLoggerImpl.doLog0(PaxLoggerImpl.java:153) ~[7:org.ops4j.pax.logging.pax-logging-log4j2:1.10.1]
        at org.ops4j.pax.logging.log4j2.internal.PaxLoggerImpl.doLog(PaxLoggerImpl.java:144) ~[7:org.ops4j.pax.logging.pax-logging-log4j2:1.10.1]
        at org.ops4j.pax.logging.log4j2.internal.PaxLoggerImpl.inform(PaxLoggerImpl.java:176) ~[7:org.ops4j.pax.logging.pax-logging-log4j2:1.10.1]
        at org.ops4j.pax.logging.internal.TrackingLogger.inform(TrackingLogger.java:86) ~[6:org.ops4j.pax.logging.pax-logging-api:1.10.1]
        at org.ops4j.pax.logging.slf4j.Slf4jLogger.info(Slf4jLogger.java:495) ~[6:org.ops4j.pax.logging.pax-logging-api:1.10.1]
        at org.eclipse.smarthome.io.monitor.internal.EventLogger.receive(EventLogger.java:53) ~[?:?]
        at sun.reflect.GeneratedMethodAccessor15.invoke(Unknown Source) ~[?:?]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
        at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
        at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [101:org.eclipse.smarthome.core:0.10.0.oh230]
        at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [101:org.eclipse.smarthome.core:0.10.0.oh230]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
        at java.lang.Thread.run(Thread.java:748) [?:?]

I tried a openhab-cli clean-cache before I started OpenHAB again, but I’m not sure if that helps. Any other suggestions?

Maybe the bugs are known issues and already fixed in 2.4.0? I’d update to that version and if the bugs are still there, put some more effort into it. E.g. by finding the cause of a OutOfMemoryError.

Yeah maybe - I just was curious that it could run so long, and then crash after a restart.
Hopefully I don’t have to put some more effort in it :wink:

This night it ran flawlessly.

This morning I now did:

So let’s see - first 20 minutes look god, hopefully next 20 days too.

… and there it is again, started at 2019-01-15 8:50: