[SOLVED] Issues with zwave controller and OutOfMemory after switching to docker and OH 2.5.1

fronti90 · February 10, 2020, 1:21pm

Platform information:
- Hardware: RPi4 4GB
- OS: HypriotOS (debian)
- openHAB version: 2.5.1
Issue of the topic: After switching to a docker setup and updating to OH 2.5.1 and also switching from a RPi3 to RPi4 (old one broke down) all zwave things keep getting set offline and back to online. Additionally the docker container keeps running into OutOfMemory. I think the first issue is causing the OutofMemory issue (i will attach logs for that next time it happens).
Please post configurations (if applicable):
docker-compose.yml:

version: '3.7'
services:
  openhab:
    image: "openhab/openhab:2.5.1"
    restart: always
    network_mode: host
    volumes:
     - "/etc/localtime:/etc/localtime:ro"
     - "/etc/timezone:/etc/timezone:ro"
     - "/opt/openhab/addons:/openhab/addons"
     - "/opt/openhab/conf:/openhab/conf"
     - "/opt/openhab/userdata:/openhab/userdata"
     - "/mnt/hdd/logs:/openhab/userdata/logs"
    environment:
      OPENHAB_HTTP_PORT: "8080"
      OPENHAB_HTTPS_PORT: "8443"
      EXTRA_JAVA_OPTS: "-Duser.timezone=Europe/Berlin"
      CRYPTO_POLICY: "unlimited"
    devices:
     - "/dev/serial/by-id/usb-Silicon_Labs_Qivicon_ZigBee_Device_05000678-if00-port0:/dev/ttyUSB0"
     - "/dev/serial/by-id/usb-0658_0200-if00:/dev/ttyACM0"

If logs where generated please post these here using code fences:

2020-02-10 14:16:31.189 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node4' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2020-02-10 14:16:31.196 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node9' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2020-02-10 14:16:31.200 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node6' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING
2020-02-10 14:16:31.203 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node3' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2020-02-10 14:16:31.207 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node12' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2020-02-10 14:16:31.218 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node11' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2020-02-10 14:16:31.225 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node2' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2020-02-10 14:16:31.230 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node6' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
==> /mnt/hdd/logs/openhab.log <==
2020-02-10 14:13:27.400 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 2: Device discovery could not resolve to a thingType! 0002:0005:0004::1.1
2020-02-10 14:13:27.402 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 4: Device discovery could not resolve to a thingType! 0002:0005:0004::1.1
2020-02-10 14:13:27.398 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 3: Device discovery could not resolve to a thingType! 0002:0005:0004::1.1
2020-02-10 14:14:12.568 [ERROR] [core.karaf.internal.FeatureInstaller] - Failed installing 'openhab-ui-habadmin'
2020-02-10 14:15:10.090 [ERROR] [core.karaf.internal.FeatureInstaller] - Failed installing 'openhab-ui-habadmin'
2020-02-10 14:15:42.774 [INFO ] [veClimateControlScheduleCommandClass] - NODE 6 reported: Override type: NO_OVERRIDE, ScheduleState: [UNUSED]
2020-02-10 14:16:18.163 [ERROR] [core.karaf.internal.FeatureInstaller] - Failed installing 'openhab-ui-habadmin'
2020-02-10 14:16:21.576 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 7CB03EAA0A01C16A: Starting ZigBee device discovery
2020-02-10 14:16:26.070 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 7CB03EAA0A01C16A: Starting ZigBee device discovery
2020-02-10 14:16:30.961 [INFO ] [zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null
==> /mnt/hdd/logs/events.log <==
2020-02-10 14:16:34.218 [me.event.ThingUpdatedEvent] - Thing 'zigbee:device:05000678:7cb03eaa0a01c16a' has been updated.
==> /mnt/hdd/logs/openhab.log <==
2020-02-10 14:16:36.104 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2020-02-10 14:16:36.106 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
2020-02-10 14:16:53.844 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 4: Device discovery could not resolve to a thingType! 0002:0005:0004::1.1
2020-02-10 14:16:53.848 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 2: Device discovery could not resolve to a thingType! 0002:0005:0004::1.1
2020-02-10 14:16:53.848 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 6: Device discovery could not resolve to a thingType! 0002:0005:0004::1.1
2020-02-10 14:16:53.854 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 3: Device discovery could not resolve to a thingType! 0002:0005:0004::1.1
==> /mnt/hdd/logs/events.log <==
2020-02-10 14:16:53.935 [hingStatusInfoChangedEvent] - 'zwave:serial_zstick:f03965e4' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
2020-02-10 14:16:53.945 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node5' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
2020-02-10 14:16:53.953 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node13' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
2020-02-10 14:16:53.981 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node7' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
2020-02-10 14:16:53.997 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node9' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
2020-02-10 14:16:53.999 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node8' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
2020-02-10 14:16:54.002 [me.event.ThingUpdatedEvent] - Thing 'zwave:serial_zstick:f03965e4' has been updated.
2020-02-10 14:16:54.003 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node5' changed from ONLINE to ONLINE: Node initialising: REQUEST_NIF
2020-02-10 14:16:54.015 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node13' changed from ONLINE to ONLINE: Node initialising: REQUEST_NIF
2020-02-10 14:16:54.074 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node8' changed from ONLINE to ONLINE: Node initialising: PING
2020-02-10 14:16:54.105 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node9' changed from ONLINE to ONLINE: Node initialising: REQUEST_NIF
2020-02-10 14:16:54.125 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node15' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
2020-02-10 14:16:54.129 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node3' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
2020-02-10 14:16:54.134 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node12' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
2020-02-10 14:16:54.143 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node2' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
2020-02-10 14:16:54.149 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node4' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
2020-02-10 14:16:54.152 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node11' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
2020-02-10 14:16:54.154 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node14' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
2020-02-10 14:16:54.157 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node6' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
2020-02-10 14:16:54.159 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node8' changed from ONLINE: Node initialising: PING to ONLINE: Node initialising: REQUEST_NIF
2020-02-10 14:16:54.691 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node9' changed from ONLINE: Node initialising: REQUEST_NIF to ONLINE
2020-02-10 14:16:54.741 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node8' changed from ONLINE: Node initialising: REQUEST_NIF to ONLINE
2020-02-10 14:17:12.443 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node13' changed from ONLINE: Node initialising: REQUEST_NIF to UNINITIALIZED
2020-02-10 14:17:12.510 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node13' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2020-02-10 14:17:12.513 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node8' changed from ONLINE to UNINITIALIZED
2020-02-10 14:17:12.561 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node8' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2020-02-10 14:17:12.563 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node9' changed from ONLINE to UNINITIALIZED
2020-02-10 14:17:12.611 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node9' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2020-02-10 14:17:12.613 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node7' changed from ONLINE to UNINITIALIZED
2020-02-10 14:17:12.646 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node7' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2020-02-10 14:17:12.651 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node5' changed from ONLINE: Node initialising: REQUEST_NIF to UNINITIALIZED
2020-02-10 14:17:12.684 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node5' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2020-02-10 14:17:12.686 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node14' changed from ONLINE to UNINITIALIZED
2020-02-10 14:17:12.732 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node14' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2020-02-10 14:17:12.734 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node15' changed from ONLINE to UNINITIALIZED
2020-02-10 14:17:12.775 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node15' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2020-02-10 14:17:12.777 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node11' changed from ONLINE to UNINITIALIZED
2020-02-10 14:17:12.811 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node11' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2020-02-10 14:17:12.813 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node12' changed from ONLINE to UNINITIALIZED
2020-02-10 14:17:12.843 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node12' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2020-02-10 14:17:12.845 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node3' changed from ONLINE to UNINITIALIZED
2020-02-10 14:17:12.877 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node3' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2020-02-10 14:17:12.879 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node2' changed from ONLINE to UNINITIALIZED
2020-02-10 14:17:12.907 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node2' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2020-02-10 14:17:12.909 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node4' changed from ONLINE to UNINITIALIZED
2020-02-10 14:17:12.944 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node4' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2020-02-10 14:17:12.946 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node6' changed from ONLINE to UNINITIALIZED
2020-02-10 14:17:12.975 [hingStatusInfoChangedEvent] - 'zwave:device:f03965e4:node6' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2020-02-10 14:17:12.976 [hingStatusInfoChangedEvent] - 'zwave:serial_zstick:f03965e4' changed from ONLINE to UNINITIALIZED
2020-02-10 14:17:13.283 [hingStatusInfoChangedEvent] - 'zwave:serial_zstick:f03965e4' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2020-02-10 14:17:17.627 [hingStatusInfoChangedEvent] - 'zigbee:device:05000678:7cb03eaa0a01c16a' changed from ONLINE to UNINITIALIZED
2020-02-10 14:17:17.646 [hingStatusInfoChangedEvent] - 'zigbee:device:05000678:7cb03eaa0a01c16a' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2020-02-10 14:17:17.948 [hingStatusInfoChangedEvent] - 'zigbee:coordinator_telegesis:05000678' changed from ONLINE to UNINITIALIZED
2020-02-10 14:17:17.949 [hingStatusInfoChangedEvent] - 'zigbee:coordinator_telegesis:05000678' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2020-02-10 14:17:18.325 [hingStatusInfoChangedEvent] - 'zigbee:device:05000678:7cb03eaa0a01c16a' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2020-02-10 14:17:20.278 [me.event.ThingUpdatedEvent] - Thing 'zigbee:coordinator_telegesis:05000678' has been updated.
2020-02-10 14:17:20.351 [hingStatusInfoChangedEvent] - 'zigbee:coordinator_telegesis:05000678' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING
2020-02-10 14:17:20.376 [hingStatusInfoChangedEvent] - 'zigbee:coordinator_telegesis:05000678' changed from INITIALIZING to UNKNOWN
2020-02-10 14:17:20.396 [hingStatusInfoChangedEvent] - 'zigbee:device:05000678:7cb03eaa0a01c16a' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2020-02-10 14:17:20.413 [hingStatusInfoChangedEvent] - 'zigbee:device:05000678:7cb03eaa0a01c16a' changed from INITIALIZING to UNKNOWN

Bruce_Osborne · February 10, 2020, 1:25pm

You likely have an invalid addon listed in addons.config in the userdata folder. The loader then restarts all addons every minute trying to load the invalid one.
One common culprit is restdocs since it moved from misc to ui. Stop OH before editing addons.config since it is usually maintained by OH.

Also, please use code fences.
How to use code fences - Tutorials & Examples - openHAB Community

fronti90 · February 10, 2020, 1:32pm

Thanks for your quick feedback! Fixed the code fences, there was something messed up with the formatting, hope it’s readable like this.
I don’t think there is any invalid config for my addons, here is my textual configuration (/opt/openhab/conf/services/addons.cfg):

binding = astro,homematic,zwave,zigbee,ntp,mqtt,fritzboxtr0641
ui =  basic,paper,habadmin
persistence = mapdb,influxdb
transformation = map
misc = openhabcloud

And this is the one in userdata (/opt/openhab/userdata/config/org/openhab/addons.config):

:org.apache.felix.configadmin.revision:=L"10"
binding="astro,homematic,zwave,zigbee,ntp,mqtt,fritzboxtr0641"
misc="openhabcloud"
package="minimal"
persistence="mapdb,influxdb"
service.pid="org.openhab.addons"
transformation="map"
ui="basic,paper,habadmin"

I am getting a bunch of errors about habadmin though, any way to debug this further?

2020-02-10 14:15:10.090 [ERROR] [core.karaf.internal.FeatureInstaller] - Failed installing 'openhab-ui-habadmin'

Thedannymullen · February 10, 2020, 1:41pm

Is the ui habmin or habadmin? Do you have a typo?

fronti90 · February 10, 2020, 1:44pm

It’s “habadmin” in openhab/conf and openhab/userdata. Which one is correct?

Bruce_Osborne · February 10, 2020, 1:46pm

habmin that is likely your issue.

fronti90 · February 10, 2020, 1:55pm

Thank you both Danny and Bruce, changed it to “habmin”. Seems a lot more stable now.
I’ll keep an eye on the OutOfMemory errors for the next few days.

Andrew_Rowe · February 10, 2020, 2:00pm

Good job Danny and Bruce, 35 minutes to a solution, nobody can say this community is not responsive and quick with help for new users!

mhilbush · February 10, 2020, 2:01pm

I expect fixing the incorrectly named addon will fix the OOM issue.

github.com/openhab/openhab-core

Invalid binding name in addons.cfg causes memory usage to increase continuously

opened 10:08PM - 02 Feb 18 UTC

closed 07:21PM - 04 Nov 20 UTC

mhilbush

@kaikreuzer This is the issue I mentioned here https://github.com/eclipse/smarth…ome/issues/4871#issuecomment-362714353 In the course of analyzing https://github.com/eclipse/smarthome/issues/4871, I noticed an unrelated condition where memory utilization would increase continuously. The condition was caused by entering an invalid binding name in `services/addons.cfg`. Since an error is not logged due to an invalid binding name in addons.cfg, it's possible that a user would not easily be able to determine the cause. Here's the base memory data collected while I had sar running. [openhab-pidstat.txt](https://github.com/openhab/openhab-core/files/1690954/openhab-pidstat.txt) I used the following command, where `12299` was the pid of the openhab java process. ``` sudo pidstat -r 6 -p 12299 ``` Here's a graph of minflt/s and RSS plotted over time. - The memory began to increase every minute (presumably when the feature installer runs) as soon as I added an invalid binding name to addons.cfg. - The memory consumption flattened out as soon as I removed the invalid binding name from addons.cfg ![sar-minflt-rss](https://user-images.githubusercontent.com/19286354/35756490-953b5c8e-0839-11e8-9a69-f3a8bdff3a9b.jpg) This was a short duration test to illustrate the issue. I had other tests that ran much longer. Edit: Note that I was running build 1194.

Bruce_Osborne · February 10, 2020, 2:05pm

Since Kai indicated this as an issue, any ideas why it has not yet been addressed? 2 years is a long time for an issue like this. I guess OH is supposedly stable but not robust??

mhilbush · February 10, 2020, 2:13pm

I suspect the leak might be in Karaf feature installer, or in the way OH is using the feature installer. I looked at it a bit, but quickly got in way over my head once my troubleshooting took me inside the Karaf feature installer.

Besides, other than this most recent release, which moved a few bundles around, the problem didn’t happen very often.

Bruce_Osborne · February 10, 2020, 2:17pm

Karaf was updated late in the Milestone cycle too.

mhilbush · February 10, 2020, 2:38pm

Yeah, I usually check to see if the problem is fixed after every Karaf update. One day maybe I’ll have some time to determine where the leak is coming from so I can open a bug report containing more detail…

Thedannymullen · February 10, 2020, 3:31pm

@Andrew_Rowe thanks!