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

https://github.com/openhab/openhab-core/issues/286

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!