Zigbee controller and things suddenly all in status "unknown" (Openhabian 1.5, RPi 4, Razberry 2 Z-Wave, ITStuff CC2531 Zigbee USB)

Hi all,
two weeks ago I started setting up my openHAB kit (Openhabian 1.5 on RPi 4, Razberry 2 Z-Wave, ITStuff CC2531 Zigbee USB).
The bindings I am using are: zwave,zigbee,astro
Thanks to the help of the community members here, I was able to to connect around 20 Z-Wave and Zigbee things, among which Popp Z-Wave Thermostats and several Osram Zigbee components such as a plug, flex and Classic E27 dimmables. I set up a well working sitemap and the first rule based automations were working fine.
Today I first added successfully a Fibaro Z-Wave wall plug.
Then, after adding the first Ledvance E14 bulb via Zigbee, I suddenly noted that it was no longer possible to control any Zigbee thing any more.
I rebooted the RPi4, and the situation is now as follows:

  • In the PaperUI, all Zigbee things (incl. the coordinator) are in status “unknown” or “offline”, no control possible any more
  • the Z-Wave things are in status “online” and can be controlled
    The log entries (filtered by “zigbee”) after a reboot look like that:
2020-09-09 15:25:57.699 [hingStatusInfoChangedEvent] - 'zigbee:device:zbstick:f0d1b800001478da' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2020-09-09 15:25:57.702 [hingStatusInfoChangedEvent] - 'zigbee:device:zbstick:f0d1b80000102a99' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2020-09-09 15:25:57.706 [hingStatusInfoChangedEvent] - 'zigbee:device:zbstick:7cb03eaa0a038478' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2020-09-09 15:25:57.719 [hingStatusInfoChangedEvent] - 'zigbee:device:zbstick:7cb03eaa0a08cbe7' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2020-09-09 15:25:57.721 [hingStatusInfoChangedEvent] - 'zigbee:device:zbstick:7cb03eaa0a006389' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2020-09-09 15:25:57.723 [hingStatusInfoChangedEvent] - 'zigbee:device:zbstick:7cb03eaa0a03c548' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2020-09-09 15:25:57.726 [hingStatusInfoChangedEvent] - 'zigbee:device:zbstick:7cb03eaa0a049aa5' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2020-09-09 15:25:57.919 [hingStatusInfoChangedEvent] - 'zigbee:coordinator_cc2531:zbstick' changed from UNINITIALIZED to INITIALIZING
2020-09-09 15:25:58.196 [hingStatusInfoChangedEvent] - 'zigbee:coordinator_cc2531:zbstick' changed from INITIALIZING to UNKNOWN
2020-09-09 15:25:58.328 [hingStatusInfoChangedEvent] - 'zigbee:device:zbstick:7cb03eaa0a08cbe7' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2020-09-09 15:25:58.335 [hingStatusInfoChangedEvent] - 'zigbee:device:zbstick:7cb03eaa0a006389' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2020-09-09 15:25:58.337 [hingStatusInfoChangedEvent] - 'zigbee:device:zbstick:f0d1b800001478da' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2020-09-09 15:25:58.344 [hingStatusInfoChangedEvent] - 'zigbee:device:zbstick:f0d1b80000102a99' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2020-09-09 15:25:58.347 [hingStatusInfoChangedEvent] - 'zigbee:device:zbstick:7cb03eaa0a038478' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2020-09-09 15:25:58.380 [hingStatusInfoChangedEvent] - 'zigbee:device:zbstick:7cb03eaa0a08cbe7' changed from INITIALIZING to UNKNOWN
2020-09-09 15:25:58.415 [hingStatusInfoChangedEvent] - 'zigbee:device:zbstick:7cb03eaa0a006389' changed from INITIALIZING to UNKNOWN
2020-09-09 15:25:58.420 [hingStatusInfoChangedEvent] - 'zigbee:device:zbstick:f0d1b80000102a99' changed from INITIALIZING to UNKNOWN
2020-09-09 15:25:58.439 [hingStatusInfoChangedEvent] - 'zigbee:device:zbstick:f0d1b800001478da' changed from INITIALIZING to UNKNOWN
2020-09-09 15:25:58.448 [hingStatusInfoChangedEvent] - 'zigbee:device:zbstick:7cb03eaa0a038478' changed from INITIALIZING to UNKNOWN
2020-09-09 15:25:58.458 [hingStatusInfoChangedEvent] - 'zigbee:device:zbstick:7cb03eaa0a03c548' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2020-09-09 15:25:58.461 [hingStatusInfoChangedEvent] - 'zigbee:device:zbstick:7cb03eaa0a049aa5' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
2020-09-09 15:25:58.474 [hingStatusInfoChangedEvent] - 'zigbee:device:zbstick:7cb03eaa0a03c548' changed from INITIALIZING to UNKNOWN
2020-09-09 15:25:58.485 [hingStatusInfoChangedEvent] - 'zigbee:device:zbstick:7cb03eaa0a049aa5' changed from INITIALIZING to UNKNOWN
2020-09-09 15:26:03.488 [me.event.ThingUpdatedEvent] - Thing 'zigbee:coordinator_cc2531:zbstick' has been updated.
2020-09-09 15:32:30.486 [nt.FirmwareStatusInfoEvent] - Firmware status of thing zigbee:device:zbstick:f0d1b800001478da changed to UNKNOWN.
2020-09-09 15:32:30.518 [nt.FirmwareStatusInfoEvent] - Firmware status of thing zigbee:device:zbstick:f0d1b80000102a99 changed to UNKNOWN.
2020-09-09 15:32:30.559 [nt.FirmwareStatusInfoEvent] - Firmware status of thing zigbee:device:zbstick:7cb03eaa0a038478 changed to UNKNOWN.
2020-09-09 15:32:30.573 [nt.FirmwareStatusInfoEvent] - Firmware status of thing zigbee:device:zbstick:7cb03eaa0a08cbe7 changed to UNKNOWN.
2020-09-09 15:32:30.593 [nt.FirmwareStatusInfoEvent] - Firmware status of thing zigbee:device:zbstick:7cb03eaa0a006389 changed to UNKNOWN.
2020-09-09 15:32:30.614 [nt.FirmwareStatusInfoEvent] - Firmware status of thing zigbee:device:zbstick:7cb03eaa0a03c548 changed to UNKNOWN.
2020-09-09 15:32:30.637 [nt.FirmwareStatusInfoEvent] - Firmware status of thing zigbee:device:zbstick:7cb03eaa0a049aa5 changed to UNKNOWN.
2020-09-09 15:44:48.778 [ome.event.ItemCommandEvent] - Item 'zigbee_device_zbstick_7cb03eaa0a049aa5_7CB03EAA0A049AA5_3_dimmer' received command 43
2020-09-09 15:44:48.788 [nt.ItemStatePredictedEvent] - zigbee_device_zbstick_7cb03eaa0a049aa5_7CB03EAA0A049AA5_3_dimmer predicted to become NULL
2020-09-09 15:44:48.807 [hingStatusInfoChangedEvent] - 'zigbee:device:zbstick:7cb03eaa0a049aa5' changed from UNKNOWN to OFFLINE
2020-09-09 15:46:40.849 [ome.event.ItemCommandEvent] - Item 'zigbee_device_zbstick_7cb03eaa0a006389_7CB03EAA0A006389_3_colortemperature' received command 0
2020-09-09 15:46:40.852 [nt.ItemStatePredictedEvent] - zigbee_device_zbstick_7cb03eaa0a006389_7CB03EAA0A006389_3_colortemperature predicted to become NULL
2020-09-09 15:46:40.872 [hingStatusInfoChangedEvent] - 'zigbee:device:zbstick:7cb03eaa0a006389' changed from UNKNOWN to OFFLINE

Do you have any advice for me in this situation?

TIA!

M.

Check out the binding documentation - there’s a section there about what to do when things don’t go as planned. It will tell you how to enable debug logging that will help you understand what’s happening.

1 Like

Thanks @chris - I will take a look right away!

The, uh, thing that stands out in the log is the coordinator Thing getting updated (not status, the Thing properties).
I would expect that to reinitialize all subsidiary Things.

Hello @chris, as described in https://www.openhab.org/addons/bindings/zigbee/#when-things-don-t-appear-to-be-working , I have activated debug type logging via the karaf commands

log:set debug org.openhab.binding.zigbee
log:set debug com.zsmartsystems.zigbee
log:set info com.zsmartsystems.zigbee.dongle.ember.internal.ash

Then I rebooted the RPi 4 again and this is what I got in openhab.log:

2020-09-09 16:50:10.570 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Time zone set to 'Europe/Berlin'.
2020-09-09 16:50:10.619 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Location set to '50.8254083,7.2680097'.
2020-09-09 16:50:10.628 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Locale set to 'en_DE'.
2020-09-09 16:50:20.947 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'popp.items'
2020-09-09 16:50:21.912 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'rrd4j.persist'
2020-09-09 16:50:23.015 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'popp.sitemap'
2020-09-09 16:50:23.489 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'zigbee.things'
2020-09-09 16:50:30.007 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'demo.script'
2020-09-09 16:50:31.199 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2020-09-09 16:50:33.830 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at http://192.168.14.165:8080
2020-09-09 16:50:33.833 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at https://192.168.14.165:8443
2020-09-09 16:50:36.661 [INFO ] [mekit.internal.HomekitChangeListener] - Created 0 HomeKit items.
2020-09-09 16:50:37.892 [INFO ] [io.hueemulation.internal.ConfigStore] - Using discovery ip 192.168.14.165
2020-09-09 16:50:37.895 [INFO ] [io.hueemulation.internal.ConfigStore] - Hue Emulation pairing disabled
2020-09-09 16:50:38.965 [WARN ] [ulation.internal.HueEmulationService] - The UPnP Server service has not been started!
2020-09-09 16:50:38.968 [INFO ] [ulation.internal.HueEmulationService] - Hue Emulation service available under /api
2020-09-09 16:50:39.746 [INFO ] [ueemulation.internal.upnp.UpnpServer] - Hue Emulation UPNP server started on 127.0.0.1:8080
2020-09-09 16:50:39.955 [INFO ] [ulation.internal.HueEmulationService] - Hue Emulation service available under /api
2020-09-09 16:50:41.518 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2020-09-09 16:50:41.762 [INFO ] [openhab.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2020-09-09 16:50:42.838 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - Starting ZigBeeDiscoveryService
2020-09-09 16:50:43.498 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Initializing ZigBee network [zigbee:coordinator_cc2531:zbstick].
2020-09-09 16:50:43.502 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Channel 0
2020-09-09 16:50:43.504 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - PANID 17201
2020-09-09 16:50:43.506 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - EPANID 642D9925DBDE25DD
2020-09-09 16:50:43.515 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Network Key B515035238163CE0AF538F7DB07B80C3
2020-09-09 16:50:43.517 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Link Key null
2020-09-09 16:50:43.519 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Config: zigbee_initialise found, initializeNetwork=false
2020-09-09 16:50:43.521 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Network Key String B515035238163CE0AF538F7DB07B80C3
2020-09-09 16:50:43.525 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Network key final array B515035238163CE0AF538F7DB07B80C3
2020-09-09 16:50:43.527 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Link Key String 
2020-09-09 16:50:43.528 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Link Key String has invalid format. Revert to default key.
2020-09-09 16:50:43.532 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Link key final array 5A6967426565416C6C69616E63653039
2020-09-09 16:50:43.533 [DEBUG] [.zigbee.cc2531.handler.CC2531Handler] - Initializing ZigBee CC2531 serial bridge handler.
2020-09-09 16:50:43.613 [DEBUG] [.zigbee.cc2531.handler.CC2531Handler] - ZigBee CC2531 Coordinator opening Port:'/dev/ttyACM0' PAN:4331, EPAN:642D9925DBDE25DD, Channel:0
2020-09-09 16:50:43.650 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Scheduling ZigBee start
2020-09-09 16:50:43.771 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - F0D1B800001478DA: Initializing ZigBee thing handler zigbee:device:zbstick:f0d1b800001478da
2020-09-09 16:50:43.788 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - F0D1B800001478DA: Coordinator status changed to UNKNOWN.
2020-09-09 16:50:43.791 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - F0D1B800001478DA: Coordinator is unknown or not online.
2020-09-09 16:50:43.797 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - F0D1B800001478DA: Channel zigbee:device:zbstick:f0d1b800001478da:F0D1B800001478DA_1_dimmer linked - polling started.
2020-09-09 16:50:43.800 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - F0D1B800001478DA: Channel zigbee:device:zbstick:f0d1b800001478da:F0D1B800001478DA_1_dimmer linked - no channel found.
2020-09-09 16:50:43.802 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - F0D1B80000102A99: Initializing ZigBee thing handler zigbee:device:zbstick:f0d1b80000102a99
2020-09-09 16:50:43.805 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A08CBE7: Initializing ZigBee thing handler zigbee:device:zbstick:7cb03eaa0a08cbe7
2020-09-09 16:50:43.808 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A006389: Initializing ZigBee thing handler zigbee:device:zbstick:7cb03eaa0a006389
2020-09-09 16:50:43.808 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A08CBE7: Coordinator status changed to UNKNOWN.
2020-09-09 16:50:43.811 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A08CBE7: Coordinator is unknown or not online.
2020-09-09 16:50:43.811 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A006389: Coordinator status changed to UNKNOWN.
2020-09-09 16:50:43.818 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A006389: Coordinator is unknown or not online.
2020-09-09 16:50:43.819 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - F0D1B80000102A99: Coordinator status changed to UNKNOWN.
2020-09-09 16:50:43.834 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A08CBE7: Channel zigbee:device:zbstick:7cb03eaa0a08cbe7:7CB03EAA0A08CBE7_3_activepower linked - polling started.
2020-09-09 16:50:43.838 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - F0D1B80000102A99: Coordinator is unknown or not online.
2020-09-09 16:50:43.841 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A08CBE7: Channel zigbee:device:zbstick:7cb03eaa0a08cbe7:7CB03EAA0A08CBE7_3_activepower linked - no channel found.
2020-09-09 16:50:43.843 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A08CBE7: Channel zigbee:device:zbstick:7cb03eaa0a08cbe7:7CB03EAA0A08CBE7_3_switch linked - polling started.
2020-09-09 16:50:43.831 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A038478: Initializing ZigBee thing handler zigbee:device:zbstick:7cb03eaa0a038478
2020-09-09 16:50:43.846 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A08CBE7: Channel zigbee:device:zbstick:7cb03eaa0a08cbe7:7CB03EAA0A08CBE7_3_switch linked - no channel found.
2020-09-09 16:50:43.871 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A006389: Channel zigbee:device:zbstick:7cb03eaa0a006389:7CB03EAA0A006389_3_color linked - polling started.
2020-09-09 16:50:43.871 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A006389: Channel zigbee:device:zbstick:7cb03eaa0a006389:7CB03EAA0A006389_3_colortemperature linked - polling started.
2020-09-09 16:50:43.873 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A006389: Channel zigbee:device:zbstick:7cb03eaa0a006389:7CB03EAA0A006389_3_color linked - no channel found.
2020-09-09 16:50:43.873 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A006389: Channel zigbee:device:zbstick:7cb03eaa0a006389:7CB03EAA0A006389_3_colortemperature linked - no channel found.
2020-09-09 16:50:43.882 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A049AA5: Initializing ZigBee thing handler zigbee:device:zbstick:7cb03eaa0a049aa5
2020-09-09 16:50:43.879 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - F0D1B80000102A99: Channel zigbee:device:zbstick:f0d1b80000102a99:F0D1B80000102A99_1_dimmer linked - polling started.
2020-09-09 16:50:43.888 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A038478: Channel zigbee:device:zbstick:7cb03eaa0a038478:7CB03EAA0A038478_3_dimmer linked - polling started.
2020-09-09 16:50:43.889 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A049AA5: Coordinator status changed to UNKNOWN.
2020-09-09 16:50:43.890 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A038478: Channel zigbee:device:zbstick:7cb03eaa0a038478:7CB03EAA0A038478_3_dimmer linked - no channel found.
2020-09-09 16:50:43.892 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A049AA5: Coordinator is unknown or not online.
2020-09-09 16:50:43.885 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A038478: Coordinator status changed to UNKNOWN.
2020-09-09 16:50:43.893 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - F0D1B80000102A99: Channel zigbee:device:zbstick:f0d1b80000102a99:F0D1B80000102A99_1_dimmer linked - no channel found.
2020-09-09 16:50:43.895 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A038478: Coordinator is unknown or not online.
2020-09-09 16:50:43.901 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A049AA5: Channel zigbee:device:zbstick:7cb03eaa0a049aa5:7CB03EAA0A049AA5_3_dimmer linked - polling started.
2020-09-09 16:50:43.904 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A049AA5: Channel zigbee:device:zbstick:7cb03eaa0a049aa5:7CB03EAA0A049AA5_3_dimmer linked - no channel found.
2020-09-09 16:50:43.912 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A03C548: Initializing ZigBee thing handler zigbee:device:zbstick:7cb03eaa0a03c548
2020-09-09 16:50:43.916 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A03C548: Coordinator status changed to UNKNOWN.
2020-09-09 16:50:43.929 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A03C548: Channel zigbee:device:zbstick:7cb03eaa0a03c548:7CB03EAA0A03C548_3_dimmer linked - polling started.
2020-09-09 16:50:43.930 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A03C548: Coordinator is unknown or not online.
2020-09-09 16:50:43.932 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A03C548: Channel zigbee:device:zbstick:7cb03eaa0a03c548:7CB03EAA0A03C548_3_dimmer linked - no channel found.
2020-09-09 16:50:45.127 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee network starting
2020-09-09 16:50:45.130 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Initialising ZigBee coordinator
2020-09-09 16:50:45.272 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Default: Set profile to ZigBeeTransactionProfile [maxOutstandingTransactions=2, interTransactionDelay=50, maxRetries=2]
2020-09-09 16:50:45.274 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: Set profile to ZigBeeTransactionProfile [maxOutstandingTransactions=2, interTransactionDelay=4000, maxRetries=0]
2020-09-09 16:50:45.276 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Multicast: Set profile to ZigBeeTransactionProfile [maxOutstandingTransactions=3, interTransactionDelay=1200, maxRetries=0]
2020-09-09 16:50:45.288 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - ZigBeeNetworkManager initialize: networkState=UNINITIALISED
2020-09-09 16:50:45.290 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Network state is updated to INITIALISING
2020-09-09 16:50:45.305 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: networkStateUpdated called with state=INITIALISING
2020-09-09 16:50:45.747 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 7CB03EAA0A08CBE7: ZigBee reading network state complete.
2020-09-09 16:50:46.028 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 7CB03EAA0A08CBE7: Endpoint 3. Unsupported cluster 1000 - using ZclCustomCluster
2020-09-09 16:50:46.325 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 7CB03EAA0A08CBE7: Endpoint 3. Unsupported cluster FC0F - using ZclCustomCluster
2020-09-09 16:50:46.350 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 7CB03EAA0A08CBE7: Data store: Node was restored.
2020-09-09 16:50:46.353 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 7CB03EAA0A08CBE7: Updating node NWK=E195
2020-09-09 16:50:46.564 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 7CB03EAA0A038478: ZigBee reading network state complete.
2020-09-09 16:50:46.581 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 7CB03EAA0A038478: Endpoint 3. Unsupported cluster 1000 - using ZclCustomCluster
2020-09-09 16:50:46.602 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 7CB03EAA0A038478: Endpoint 3. Unsupported cluster FC0F - using ZclCustomCluster
2020-09-09 16:50:46.606 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 7CB03EAA0A038478: Data store: Node was restored.
2020-09-09 16:50:46.609 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 7CB03EAA0A038478: Updating node NWK=6251
2020-09-09 16:50:46.627 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 00124B0014D9A5A6: ZigBee reading network state complete.
2020-09-09 16:50:46.630 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 00124B0014D9A5A6: Data store: Node was restored.
2020-09-09 16:50:46.633 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00124B0014D9A5A6: Updating node NWK=0000
2020-09-09 16:50:46.762 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - F0D1B800001478DA: ZigBee reading network state complete.
2020-09-09 16:50:46.765 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - F0D1B800001478DA: Endpoint 1. Unsupported cluster 1000 - using ZclCustomCluster
2020-09-09 16:50:46.777 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - F0D1B800001478DA: Endpoint 1. Unsupported cluster FC0F - using ZclCustomCluster
2020-09-09 16:50:46.808 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - F0D1B800001478DA: Data store: Node was restored.
2020-09-09 16:50:46.810 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - F0D1B800001478DA: Updating node NWK=1357
2020-09-09 16:50:46.914 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - F0D1B80000102A99: ZigBee reading network state complete.
2020-09-09 16:50:46.917 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - F0D1B80000102A99: Endpoint 1. Unsupported cluster 1000 - using ZclCustomCluster
2020-09-09 16:50:46.922 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - F0D1B80000102A99: Endpoint 1. Unsupported cluster FC0F - using ZclCustomCluster
2020-09-09 16:50:46.925 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - F0D1B80000102A99: Data store: Node was restored.
2020-09-09 16:50:46.927 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - F0D1B80000102A99: Updating node NWK=F05F
2020-09-09 16:50:46.998 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 7CB03EAA0A049AA5: ZigBee reading network state complete.
2020-09-09 16:50:47.000 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 7CB03EAA0A049AA5: Endpoint 3. Unsupported cluster 1000 - using ZclCustomCluster
2020-09-09 16:50:47.005 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 7CB03EAA0A049AA5: Endpoint 3. Unsupported cluster FC0F - using ZclCustomCluster
2020-09-09 16:50:47.008 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 7CB03EAA0A049AA5: Data store: Node was restored.
2020-09-09 16:50:47.010 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 7CB03EAA0A049AA5: Updating node NWK=0DA5
2020-09-09 16:50:47.079 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 7CB03EAA0A03C548: ZigBee reading network state complete.
2020-09-09 16:50:47.081 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 7CB03EAA0A03C548: Endpoint 3. Unsupported cluster 1000 - using ZclCustomCluster
2020-09-09 16:50:47.085 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 7CB03EAA0A03C548: Endpoint 3. Unsupported cluster FC0F - using ZclCustomCluster
2020-09-09 16:50:47.088 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 7CB03EAA0A03C548: Data store: Node was restored.
2020-09-09 16:50:47.090 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 7CB03EAA0A03C548: Updating node NWK=5847
2020-09-09 16:50:47.178 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 7CB03EAA0A006389: ZigBee reading network state complete.
2020-09-09 16:50:47.180 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 7CB03EAA0A006389: Endpoint 3. Unsupported cluster 1000 - using ZclCustomCluster
2020-09-09 16:50:47.212 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 7CB03EAA0A006389: Endpoint 3. Unsupported cluster FC0F - using ZclCustomCluster
2020-09-09 16:50:47.214 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 7CB03EAA0A006389: Data store: Node was restored.
2020-09-09 16:50:47.216 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 7CB03EAA0A006389: Updating node NWK=15BB
2020-09-09 16:50:47.218 [DEBUG] [e.dongle.cc2531.ZigBeeDongleTiCc2531] - CC2531 transport initialize
2020-09-09 16:50:47.221 [DEBUG] [ding.zigbee.handler.ZigBeeSerialPort] - Connecting to serial port [/dev/ttyACM0] at 38400 baud, flow control FLOWCONTROL_OUT_RTSCTS.
2020-09-09 16:50:47.301 [DEBUG] [ding.zigbee.handler.ZigBeeSerialPort] - Serial port [/dev/ttyACM0] is initialized.
2020-09-09 16:50:47.318 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  SYS_RESET (Packet: subsystem=null, length=1, apiId=41 00, data=FE 01 41 00 01 41, checksum=41, error=false) 
2020-09-09 16:50:48.606 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- SYS_RESET_RESPONSE (FE 06 41 80 00 02 00 02 06 03 C2)
2020-09-09 16:50:48.612 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=6, apiId=41 80, data=FE 06 41 80 00 02 00 02 06 03 C2, checksum=C2, error=false
2020-09-09 16:50:48.617 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  SYS_VERSION (Packet: subsystem=null, length=0, apiId=21 02, data=FE 00 21 02 23, checksum=23, error=false) 
2020-09-09 16:50:48.623 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  SYS_VERSION_RESPONSE (FE 0E 61 02 02 00 02 06 03 90 15 34 01 02 00 00 00 00 DA)
2020-09-09 16:50:48.625 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - CC2531 version is Software=2.6 Product=0 Hardware=3 Transport=2
2020-09-09 16:50:48.628 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  ZB_GET_DEVICE_INFO (Packet: subsystem=null, length=1, apiId=26 06, data=FE 01 26 06 01 20, checksum=20, error=false) 
2020-09-09 16:50:48.643 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  ZB_GET_DEVICE_INFO_RSP (FE 09 66 06 01 A6 A5 D9 14 00 4B 12 00 FF)
2020-09-09 16:50:48.669 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Mesh Update Period 86400
2020-09-09 16:50:48.680 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported client cluster 0500
2020-09-09 16:50:48.687 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher starting for endpoint 1 with profile ID 0104 (ZIGBEE_HOME_AUTOMATION)
2020-09-09 16:50:48.689 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding client cluster 0500
2020-09-09 16:50:48.694 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported server cluster 0019
2020-09-09 16:50:48.695 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding server cluster 0019
2020-09-09 16:50:48.787 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported client cluster 0001
2020-09-09 16:50:48.789 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding client cluster 0001
2020-09-09 16:50:48.791 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported client cluster 0006
2020-09-09 16:50:48.792 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding client cluster 0006
2020-09-09 16:50:48.794 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported client cluster 0008
2020-09-09 16:50:48.796 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding client cluster 0008
2020-09-09 16:50:48.798 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported client cluster 000F
2020-09-09 16:50:48.799 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding client cluster 000F
2020-09-09 16:50:48.802 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported client cluster 0101
2020-09-09 16:50:48.803 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding client cluster 0101
2020-09-09 16:50:48.805 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported client cluster 0102
2020-09-09 16:50:48.807 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding client cluster 0102
2020-09-09 16:50:48.809 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported client cluster 0201
2020-09-09 16:50:48.811 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding client cluster 0201
2020-09-09 16:50:48.813 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported client cluster 0202
2020-09-09 16:50:48.814 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding client cluster 0202
2020-09-09 16:50:48.816 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported client cluster 0300
2020-09-09 16:50:48.818 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding client cluster 0300
2020-09-09 16:50:48.821 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported client cluster 0400
2020-09-09 16:50:48.822 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding client cluster 0400
2020-09-09 16:50:48.824 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported client cluster 0402
2020-09-09 16:50:48.826 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding client cluster 0402
2020-09-09 16:50:48.828 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported client cluster 0403
2020-09-09 16:50:48.830 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding client cluster 0403
2020-09-09 16:50:48.832 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported client cluster 0405
2020-09-09 16:50:48.833 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding client cluster 0405
2020-09-09 16:50:48.835 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported client cluster 0406
2020-09-09 16:50:48.837 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding client cluster 0406
2020-09-09 16:50:48.839 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported client cluster 0500
2020-09-09 16:50:48.841 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding client cluster 0500
2020-09-09 16:50:48.843 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported client cluster 0502
2020-09-09 16:50:48.844 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding client cluster 0502
2020-09-09 16:50:48.846 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported client cluster 0B04
2020-09-09 16:50:48.848 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding client cluster 0B04
2020-09-09 16:50:48.858 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported server cluster 0005
2020-09-09 16:50:48.860 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding server cluster 0005
2020-09-09 16:50:48.862 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported server cluster 0006
2020-09-09 16:50:48.863 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding server cluster 0006
2020-09-09 16:50:48.865 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported server cluster 0008
2020-09-09 16:50:48.867 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding server cluster 0008
2020-09-09 16:50:48.869 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported server cluster 0402
2020-09-09 16:50:48.871 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding server cluster 0402
2020-09-09 16:50:48.873 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported client cluster 0000
2020-09-09 16:50:48.874 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding client cluster 0000
2020-09-09 16:50:48.876 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported client cluster 0019
2020-09-09 16:50:48.878 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding client cluster 0019
2020-09-09 16:50:48.880 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported server cluster 0000
2020-09-09 16:50:48.882 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding server cluster 0000
2020-09-09 16:50:48.884 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  ZB_GET_DEVICE_INFO (Packet: subsystem=null, length=1, apiId=26 06, data=FE 01 26 06 05 24, checksum=24, error=false) 
2020-09-09 16:50:48.890 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  ZB_GET_DEVICE_INFO_RSP (FE 09 66 06 05 0B A5 D9 14 00 4B 12 00 56)
2020-09-09 16:50:48.895 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  ZB_GET_DEVICE_INFO (Packet: subsystem=null, length=1, apiId=26 06, data=FE 01 26 06 06 27, checksum=27, error=false) 
2020-09-09 16:50:48.910 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  ZB_GET_DEVICE_INFO_RSP (FE 09 66 06 06 31 43 D9 14 00 4B 12 00 89)
2020-09-09 16:50:48.912 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  ZB_GET_DEVICE_INFO (Packet: subsystem=null, length=1, apiId=26 06, data=FE 01 26 06 07 26, checksum=26, error=false) 
2020-09-09 16:50:48.931 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  ZB_GET_DEVICE_INFO_RSP (FE 09 66 06 07 DD 25 DE DB 25 99 2D 64 66)
2020-09-09 16:50:48.933 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee Initialise: Previous device configuration was: channel=CHANNEL_11, PanID=17201, EPanId=642D9925DBDE25DD
2020-09-09 16:50:48.936 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - ZigBeeNetworkManager startup: reinitialize=false, networkState=INITIALISING
2020-09-09 16:50:48.938 [DEBUG] [e.dongle.cc2531.ZigBeeDongleTiCc2531] - CC2531 transport startup
2020-09-09 16:50:48.940 [DEBUG] [.cc2531.network.ZigBeeNetworkManager] - Creating network as Coordinator
2020-09-09 16:50:48.941 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  ZDO_MSG_CB_REGISTER (Packet: subsystem=null, length=2, apiId=25 3E, data=FE 02 25 3E FF FF 19, checksum=19, error=false) 
2020-09-09 16:50:48.951 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  ZDO_MSG_CB_REGISTER_SRSP (FE 01 65 3E 00 5A)
2020-09-09 16:50:48.953 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  ZB_WRITE_CONFIGURATION (Packet: subsystem=null, length=3, apiId=26 05, data=FE 03 26 05 8F 01 01 AF, checksum=AF, error=false) 
2020-09-09 16:50:48.971 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  ZB_WRITE_CONFIGURATION_RSP (FE 01 66 05 00 62)
2020-09-09 16:50:48.973 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  ZDO_STARTUP_FROM_APP (Packet: subsystem=null, length=2, apiId=25 40, data=FE 02 25 40 00 00 67, checksum=67, error=false) 
2020-09-09 16:50:49.655 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  ZDO_STARTUP_FROM_APP_SRSP (FE 01 65 40 00 24)
2020-09-09 16:50:49.657 [INFO ] [.cc2531.network.ZigBeeNetworkManager] - Initialized ZigBee network with existing network state.
2020-09-09 16:50:53.623 [INFO ] [zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null
2020-09-09 16:50:58.948 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2020-09-09 16:50:58.950 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
2020-09-09 16:50:58.967 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 10: Not initialized (ie node unknown), ignoring message.
2020-09-09 16:50:58.998 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 10: Not initialized (ie node unknown), ignoring message.
2020-09-09 16:50:59.028 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 10: Not initialized (ie node unknown), ignoring message.
2020-09-09 16:51:53.730 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'rules.rules'
2020-09-09 17:00:42.010 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A08CBE7: Command for channel zigbee:device:zbstick:7cb03eaa0a08cbe7:7CB03EAA0A08CBE7_3_switch --> ON [OnOffType]
2020-09-09 17:00:42.012 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A08CBE7: Coordinator handler not found. Cannot handle command without coordinator.
2020-09-09 17:00:43.961 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A08CBE7: Command for channel zigbee:device:zbstick:7cb03eaa0a08cbe7:7CB03EAA0A08CBE7_3_switch --> ON [OnOffType]
2020-09-09 17:00:43.964 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A08CBE7: Coordinator handler not found. Cannot handle command without coordinator.

From my layman’s perspective, all seems to go well until

2020-09-09 16:50:43.788 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - F0D1B800001478DA: Coordinator status changed to UNKNOWN.
2020-09-09 16:50:43.791 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - F0D1B800001478DA: Coordinator is unknown or not online.

Does that indicate that the USB CC2531 might already be malfunctioning?
Best,
M.

Another observation - on the USB ITStuff CC2531 Stick, a green LED used to be on during “normal” operation, now a red LED is on.

Just for completeness, here comes the entry from the things file for the USB ITStuff CC2531:

Thing zigbee:coordinator_cc2531:zbstick "Zigbee USB Stick" [zigbee_port="/dev/ttyACM0", zigbee_baud=38400, zigbee_panid=17201, zigbee_extendedpanid="642D9925DBDE25DD", zigbee_networkkey="B515035238163CE0AF538F7DB07B80C3"]

I’m not super familiar with the CC2531 as I mostly develop with the Ember NCP these days, but it seems strange that there is nothing returned following this command. This tells the 2531 to start communicating on the network, and I think it should respond a few seconds later, and then it should come ONLINE.

Maybe the dongle is not working well maybe - I’m not 100% sure though and don’t have a 2531 system here to compare against.

Thanks @chris!
I have just contacted the dealer / manufacturer of the CC2531 device, who kindly offered to provide me with a replacement.
Once this arrives, I will test again and let the community know here about the results …

Hello all,
I have received today the new CC2531 device. It’s being recognized as online in the Paper UI, but I find it odd that although I am using the same entry in the things file for it as for the old/broken one

Thing zigbee:coordinator_cc2531:zbstick "Zigbee USB Stick" [zigbee_port="/dev/ttyACM0", zigbee_baud=38400, zigbee_panid=17201, zigbee_extendedpanid="642D9925DBDE25DD", zigbee_networkkey="B515035238163CE0AF538F7DB07B80C3"]

there are different values for PAN ID and extended PAN ID shown in the Paper UI for it.

I suspect that this is also the reason why the other Zigbee Things are all shown as “Offline-Gone”:

I had actually hoped that by using the same parameters for the new hardware would avoid the need to reconnect all things again.

I have also tried to change the differing parameters for the Zigbee USB stick in the Paper UI to match the ones in the things file, but whenever I am doing that, I am getting the error message “ERROR: 409 Conflict” in the lower right side of the browser.

Does anyone have a good idea how to get the PAN ID and extended PAN ID matching from the things file enforced?

Zigbee related logs:
I still have the debug mode on as @chris had advised earlier, therefore there is a huge amount of zigbee related entries in the log.

One can see that the parameters from the things file are read:

2020-09-11 13:39:36.626 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - PANID 17201
2020-09-11 13:39:36.628 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - EPANID 642D9925DBDE25DD
2020-09-11 13:39:36.637 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Network Key B515035238163CE0AF538F7DB07B80C3

but a bit later

2020-09-11 13:39:41.565 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee Initialise: Previous device configuration was: channel=CHANNEL_11, PanID=60911, EPanId=F62E4FD0B65143B7

and then

2020-09-11 13:39:42.490 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee initialise done. channel=CHANNEL_11, PanId=60911  EPanId=F62E4FD0B65143B7

No - this is not possible with the TI stick. The ZigBee security will not allow this unless special configuration is made.

You need to reinitialse the stick, and add your devices into the new network.

Thanks for the clarification @chris !
I will try this out :slight_smile:

1 Like

So this afternoon I reconnected the previously connected devices (several Osram LED bulbs, one Osram Flex and an Osram Plug). This went well except the fact that after I think it was the fifth device the Zigbee part of the system got kind of hung, i.e. I wasn’t able to switch any Zigbee device any more. A reboot after every added Zigbee device helped me out then. As the last device I added successfully an Tradfri bulb, which previously I had not worked with. Now I am struggling with adding a Tradfri motion sensor, which turns out to be challenging - but for the latter, I will open a new thread … :slight_smile:
Thanks @chris for helping me to get through this!

@chris - maybe of interest for you:
When I just tried to add another Osram bulb, the Zigbee part of the system hung again and looks like exactly at that time the following log entries were generated:

2020-09-11 18:20:46.670 [ERROR] [531.network.packet.ZToolPacketStream] - Checksum of packet failed: received =226 expected = 230. Len = 3, ApiId = 0x4681, Packet = [7, 0, 33]
2020-09-11 18:20:46.673 [ERROR] [531.network.packet.ZToolPacketStream] - Packet parsing failed due to exception.
com.zsmartsystems.zigbee.dongle.cc2531.network.packet.ZToolParseException: Packet checksum failed
	at com.zsmartsystems.zigbee.dongle.cc2531.network.packet.ZToolPacketStream.parsePacket(ZToolPacketStream.java:125) [bundleFile:?]
	at com.zsmartsystems.zigbee.dongle.cc2531.network.packet.ZToolPacketParser.run(ZToolPacketParser.java:107) [bundleFile:?]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_265]

I don’t have a TI system so can’t really do a lot of development here unfortunately. If the checksum is just a transient, then it should automatically recover.

Hi @chris , good morning :slight_smile:
This morning I experienced the same problem with the Zigbee part auf my automation “hanging”/becoming unresponsive after switching an Osram bulb physically off and on again (testing what I call the “emergency feature” of switching a lamp on when the smartphone with the remote control is not at reach).
After that switching activity, the following entries were in the log:

2020-09-12 07:44:56.638 [ERROR] [531.network.packet.ZToolPacketStream] - Checksum of packet failed: received =135 expected = 130. Len = 72, ApiId = 0x45b1, Packet = [234, 115, 0, 8, 0, 3, 113, 209, 164, 220, 79, 37, 15, 179, 165, 154, 4, 10, 170, 62, 176, 124, 82, 11, 37, 2, 15, 254, 113, 209, 164, 220, 79, 37, 15, 179, 137, 99, 0, 10, 170, 62, 176, 124, 213, 35, 37, 2, 15, 251, 113, 209, 164, 220, 79, 37, 15, 179, 218, 120, 20, 0, 0, 184, 209, 240, 107, 107, 5, 2, 15, 254]
2020-09-12 07:44:56.641 [ERROR] [531.network.packet.ZToolPacketStream] - Packet parsing failed due to exception.
com.zsmartsystems.zigbee.dongle.cc2531.network.packet.ZToolParseException: Packet checksum failed
	at com.zsmartsystems.zigbee.dongle.cc2531.network.packet.ZToolPacketStream.parsePacket(ZToolPacketStream.java:125) [bundleFile:?]
	at com.zsmartsystems.zigbee.dongle.cc2531.network.packet.ZToolPacketParser.run(ZToolPacketParser.java:107) [bundleFile:?]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_265]

Unfortunately, the system does not recover from this situation by itself, the only way I am currently aware of to resolve is a reboot of the RPi 4.

What’s the total number of devices that you now have paired through the CC2531? It can’t handle too many devices, with experiences varying from about 15 devices upwards…

Hi @hafniumzinc, at the moment, there are 9 devices connected to the Zigbee part (7 bulbs (6 Osram, 1 Tradfri), 1 Osram flex and 1 Osram plug).

1 Like

The number of devices will be set in the firmware, but shouldn’t hopefully be less than 10.

I’m not sure why there seems to be a systematic CRC error with this frame - CRC errors will, of course occur from time to time, but they should recover. Without seeing a log I can’t comment too much more, but it’s a little strange that you’re having this issue when I think lots of others are using the CC2531 without problems

I’m not sure what firmware you have - maybe there’s an incompatibility there. If you provide a log I’ll take a quick look to see what I can see, but unfortunately as I said earlier I don’t have a test setup with this dongle so can’t really do too much investigation.

Hi @chris, thanks, the cc2531 usb stick I am using comes with a preinstalled firmware which the shop here in Germany describes as “latest from Koenkk” .

I am able to reproduce the issue now by simply switching off electricity for a zigbee bulb and switch electricity on again. I am attaching here the debug log entries that are created in the seconds after switching the electricity on:

events.log (9.8 KB) openhab.log (349.7 KB)