Zigbee binding 3.0 problems with Bitron Video ZigBee USB Funkstick

Lorenzo · December 31, 2020, 5:18pm

I migrated to Openhab 3.0 and I’m finding a lot of issues with Zigbee binding.
The same configuration that was working with the latest openhab 2.5 version doesn’t work on a fresh Openhab 3 installation.
My hardware is Raspberry PI3 and Bitron Video ZigBee USB Funkstick

At least once per day the binding starts a strange behavior until reboot, then everything restart to work fine for some hours
Everything seems to start with a
2020-12-31 18:01:35.154 [WARN ] [e.ember.internal.ash.AshFrameHandler] - ASH: ERROR received (code 81). Disconnecting.

==> /var/log/openhab/events.log <==
2020-12-31 18:01:35.195 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:coordinator_ember:01380F03' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR)
2020-12-31 18:01:35.203 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:01380F03:00158d0004516178' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2020-12-31 18:01:35.207 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:01380F03:00124b001efe4fee' changed from OFFLINE to OFFLINE (BRIDGE_OFFLINE)
2020-12-31 18:01:35.212 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:01380F03:00158d00040221f8' changed from OFFLINE to OFFLINE (BRIDGE_OFFLINE)
2020-12-31 18:01:35.216 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:01380F03:00158d0004514c4b' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2020-12-31 18:01:35.220 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:01380F03:7cb03eaa00aba09b' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2020-12-31 18:01:35.225 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:01380F03:7cb03eaa00aec851' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
==> /var/log/openhab/openhab.log <==
2020-12-31 18:01:36.221 [INFO ] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee dongle inactivity timer. Reinitializing ZigBee
==> /var/log/openhab/events.log <==
2020-12-31 18:01:37.382 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:01380F03:7cb03eaa00aba09b' changed from OFFLINE (BRIDGE_OFFLINE) to OFFLINE
2020-12-31 18:01:37.391 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:coordinator_ember:01380F03' changed from OFFLINE (COMMUNICATION_ERROR) to UNKNOWN
==> /var/log/openhab/openhab.log <==
2020-12-31 18:01:44.037 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 7CB03EAA00ABA09B: Starting ZigBee device discovery
2020-12-31 18:01:44.087 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 7CB03EAA00AEC851: Starting ZigBee device discovery
2020-12-31 18:01:44.089 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 00158D0004514C4B: Starting ZigBee device discovery
2020-12-31 18:01:44.097 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 00124B001EFE4FEE: Starting ZigBee device discovery
2020-12-31 18:01:44.104 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 00158D0004516178: Starting ZigBee device discovery
2020-12-31 18:01:44.130 [WARN ] [zsmartsystems.zigbee.ZigBeeExecutors] - Uncaught exception in thread NotificationService-thread-4

java.lang.NullPointerException: null
	at org.openhab.binding.zigbee.handler.ZigBeeThingHandler.nodeUpdated(ZigBeeThingHandler.java:872) ~[?:?]
	at org.openhab.binding.zigbee.handler.ZigBeeThingHandler.nodeAdded(ZigBeeThingHandler.java:815) ~[?:?]
	at com.zsmartsystems.zigbee.ZigBeeNetworkManager$7.run(ZigBeeNetworkManager.java:1333) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[?:?]
	at java.lang.Thread.run(Thread.java:834) [?:?]

2020-12-31 18:01:44.353 [WARN ] [zsmartsystems.zigbee.ZigBeeExecutors] - Uncaught exception in thread NotificationService-thread-19

java.lang.NullPointerException: null
	at org.openhab.binding.zigbee.handler.ZigBeeThingHandler.nodeUpdated(ZigBeeThingHandler.java:872) ~[?:?]
	at com.zsmartsystems.zigbee.ZigBeeNetworkManager$14.run(ZigBeeNetworkManager.java:1733) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[?:?]
	at java.lang.Thread.run(Thread.java:834) [?:?]

2020-12-31 18:01:44.369 [WARN ] [zsmartsystems.zigbee.ZigBeeExecutors] - Uncaught exception in thread NotificationService-thread-3

java.lang.NullPointerException: null
	at org.openhab.binding.zigbee.handler.ZigBeeThingHandler.nodeUpdated(ZigBeeThingHandler.java:872) ~[?:?]
	at com.zsmartsystems.zigbee.ZigBeeNetworkManager$14.run(ZigBeeNetworkManager.java:1733) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[?:?]
	at java.lang.Thread.run(Thread.java:834) [?:?]

2020-12-31 18:01:44.654 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 00158D0004232414: Starting ZigBee device discovery

2020-12-31 18:01:44.661 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 00158D00040221F8: Starting ZigBee device discovery

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

2020-12-31 18:01:44.103 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:coordinator_ember:01380F03' changed from UNKNOWN to ONLINE
2020-12-31 18:01:44.106 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:01380F03:00158d0004516178' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2020-12-31 18:01:44.113 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:01380F03:00158d00040221f8' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2020-12-31 18:01:44.118 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:01380F03:00158d0004232414' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE

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

2020-12-31 18:01:45.994 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 00158D00040221F8: Starting ZigBee device discovery

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

2020-12-31 18:01:53.833 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:01380F03:7cb03eaa00aec851' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE

After a lot of
2020-12-31 18:07:32.796 [WARN ] [nding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: Serial buffer overrun

Again
2020-12-31 18:07:32.881 [WARN ] [e.ember.internal.ash.AshFrameHandler] - ASH: ERROR received (code 81). Disconnecting.

Someone could help?

Bruce_Osborne · December 31, 2020, 5:41pm

Perhaps turning on DEBUG logging as instructed in the binding documentation and posting an unfiltered segment starting just before the problem occurs?

Lorenzo · January 1, 2021, 7:57pm

Just happened again. Here the debug openhab.log from a couple of minutes before the “ASH: ERROR received (code 81)” to some minutes after. Until the “ASH: ERROR” everything seems to work fine
log.txt (227.3 KB)

Lorenzo · February 28, 2021, 2:04pm

Solved installing Zigbee2MQTT.
My Raspberry Pi3 seems to go out of RAM after about 20 hours if Zigbee binding and ZRAM are running.