ZigBee stick AV2010/10 (Ember, Bitron Video) scanning never find devices

Add-ons Bindings
1

Hi,

I never used the ZigBee binding in OpenHAB before and can’t get it to work. I’m running OH 3.0.2 with a lot of different bindings (also Z-Wave USB stick with may devices) and everything works great - but I have no experience with ZigBee. I love Z-Wave, but I’ve bought a smart vertical blind wand which only supports ZigBee, so I’ve bought a ZigBee stick and hoped it will be as easy as with Z-Wave - but it’s not (or maybe not for me).

My OH 3.0.2 runs in a docker container already with Z-Wave USB on port /dev/ttyACM0 and I’ve set up the correct drivers also for the new ZigBee USB stick on port /dev/ttyUSB0
Access rights are ok and the status in the things view is “green”, online.

It’s a Bitron Video, ZigBee USB Radio Stick, AV2010/10

dmesg
...
[353525.652220] usb 2-4: new full-speed USB device number 10 using xhci_hcd
[353525.805694] usb 2-4: New USB device found, idVendor=10c4, idProduct=8b34, bcdDevice= 1.00
[353525.805697] usb 2-4: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[353525.805698] usb 2-4: Product: BV 2010/10
[353525.805700] usb 2-4: Manufacturer: Silicon Labs
[353525.805701] usb 2-4: SerialNumber: 013E75C1
[353525.807169] cp210x 2-4:1.0: cp210x converter detected
[353525.810338] usb 2-4: cp210x converter now attached to ttyUSB0
...

I’ve set all ZigBee log levels to debug and I see NO error, warnings, info messages and none of the debug messages indicates an error or problem, everything looks ok for me. Here is are the ZigBee log entries after a fresh restart of my OH 3.0.2 (it’s not complete to be accepted for a post, so I’ve deleted some lines in the middle with other debug success messages):

2021-07-20 18:06:34.973 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - Starting ZigBeeDiscoveryService
2021-07-20 18:06:45.888 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Initializing ZigBee network [zigbee:coordinator_ember:c7b0cb48f4].
2021-07-20 18:06:45.912 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Channel 25
2021-07-20 18:06:45.913 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - PANID 48261
2021-07-20 18:06:45.914 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - EPANID EEE8BCB7B2C846E6
2021-07-20 18:06:45.923 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Network Key A72D3A4D4425C3F891CCD1587A1326F4
2021-07-20 18:06:45.940 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Link Key 5A6967426565416C6C69616E63653039
2021-07-20 18:06:45.944 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Config: zigbee_initialise found, initializeNetwork=false
2021-07-20 18:06:45.960 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Network Key String A72D3A4D4425C3F891CCD1587A1326F4
2021-07-20 18:06:45.962 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Network key final array A72D3A4D4425C3F891CCD1587A1326F4
2021-07-20 18:06:45.963 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Link Key String 5A6967426565416C6C69616E63653039
2021-07-20 18:06:45.964 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Link key final array 5A6967426565416C6C69616E63653039
2021-07-20 18:06:45.992 [DEBUG] [ng.zigbee.ember.handler.EmberHandler] - Initializing ZigBee Ember serial bridge handler.
2021-07-20 18:06:46.106 [DEBUG] [ng.zigbee.ember.handler.EmberHandler] - ZigBee Ember Coordinator opening Port:'/dev/ttyUSB0' PAN:bc85, EPAN:EEE8BCB7B2C846E6, Channel:25
2021-07-20 18:06:46.119 [DEBUG] [ng.zigbee.ember.handler.EmberHandler] - Ember end device poll timeout set to (169 * 2^9) = 86528 seconds
2021-07-20 18:06:46.131 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Scheduling ZigBee start
2021-07-20 18:06:47.144 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee network starting
2021-07-20 18:06:47.145 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Initialising ZigBee coordinator
2021-07-20 18:06:47.202 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Default: Set profile to ZigBeeTransactionProfile [maxOutstandingTransactions=1, interTransactionDelay=50, maxRetries=2]
...
2021-07-20 18:06:47.228 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - ZigBeeNetworkManager initialize: networkState=UNINITIALISED
2021-07-20 18:06:47.241 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Network state is updated to INITIALISING
2021-07-20 18:06:47.261 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: networkStateUpdated called with state=INITIALISING
2021-07-20 18:06:47.321 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 000D6F000DB9E768: ZigBee reading network state complete.
2021-07-20 18:06:47.329 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 000D6F000DB9E768: Data store: Node was restored.
2021-07-20 18:06:47.330 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 000D6F000DB9E768: Updating node NWK=0000
2021-07-20 18:06:47.331 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EZSP Dongle: Initialize with protocol ASH2.
2021-07-20 18:06:47.332 [DEBUG] [nding.zigbee.serial.ZigBeeSerialPort] - Connecting to serial port [/dev/ttyUSB0] at 57600 baud, flow control FLOWCONTROL_OUT_XONOFF.
2021-07-20 18:06:47.490 [DEBUG] [nding.zigbee.serial.ZigBeeSerialPort] - Serial port [/dev/ttyUSB0] is initialized.
2021-07-20 18:06:49.833 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Ember: Link State change to true, initialised=false, networkStateUp=false
2021-07-20 18:06:49.833 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Ember: Link State change to true ignored.
2021-07-20 18:06:49.845 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspVersionResponse [networkId=0, protocolVersion=4, stackType=2, stackVersion=5810]
2021-07-20 18:06:49.845 [DEBUG] [systems.zigbee.dongle.ember.EmberNcp] - EzspVersionResponse [networkId=0, protocolVersion=4, stackType=2, stackVersion=5810]
2021-07-20 18:06:49.860 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspGetStandaloneBootloaderVersionPlatMicroPhyResponse [networkId=0, bootloaderVersion=5810, nodePlat=4, nodeMicro=14, nodePhy=3]
2021-07-20 18:06:50.513 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspGetConfigurationValueResponse [networkId=0, status=EZSP_SUCCESS, value=6]
2021-07-20 18:06:50.513 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Configuration state EZSP_CONFIG_SUPPORTED_NETWORKS = 1
..
2021-07-20 18:06:50.527 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Configuration state EZSP_CONFIG_MAX_HOPS = 30
2021-07-20 18:06:50.540 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspGetPolicyResponse [networkId=0, status=EZSP_SUCCESS, decisionId=01]
...
2021-07-20 18:06:50.621 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Policy state EZSP_MESSAGE_CONTENTS_IN_CALLBACK_POLICY = EZSP_MESSAGE_TAG_ONLY_IN_CALLBACK [40]
2021-07-20 18:06:50.622 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Policy state EZSP_BINDING_MODIFICATION_POLICY = EZSP_DISALLOW_BINDING_MODIFICATION [10]
2021-07-20 18:06:50.623 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Policy state EZSP_APP_KEY_REQUEST_POLICY = EZSP_ALLOW_APP_KEY_REQUESTS [61]
2021-07-20 18:06:50.623 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Policy state EZSP_TC_KEY_REQUEST_POLICY = EZSP_DENY_TC_KEY_REQUESTS [50]
2021-07-20 18:06:50.629 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Policy state EZSP_TRUST_CENTER_POLICY = EZSP_ALLOW_PRECONFIGURED_KEY_JOINS [01]
...
2021-07-20 18:06:51.204 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSetConfigurationValueResponse [networkId=0, status=EZSP_SUCCESS]
...
2021-07-20 18:06:51.801 [DEBUG] [systems.zigbee.dongle.ember.EmberNcp] - EzspGetConfigurationValueResponse [networkId=0, status=EZSP_SUCCESS, value=9]
2021-07-20 18:06:51.802 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Configuration state EZSP_CONFIG_SUPPORTED_NETWORKS = 1
...
2021-07-20 18:06:51.836 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSetPolicyResponse [networkId=0, status=EZSP_SUCCESS]
...
2021-07-20 18:06:52.026 [DEBUG] [systems.zigbee.dongle.ember.EmberNcp] - EzspGetPolicyResponse [networkId=0, status=EZSP_SUCCESS, decisionId=60]
2021-07-20 18:06:52.027 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Policy state EZSP_MESSAGE_CONTENTS_IN_CALLBACK_POLICY = EZSP_MESSAGE_TAG_ONLY_IN_CALLBACK [40]
2021-07-20 18:06:52.027 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Policy state EZSP_BINDING_MODIFICATION_POLICY = EZSP_CHECK_BINDING_MODIFICATIONS_ARE_VALID_ENDPOINT_CLUSTERS [12]
2021-07-20 18:06:52.028 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Policy state EZSP_APP_KEY_REQUEST_POLICY = EZSP_DENY_APP_KEY_REQUESTS [60]
2021-07-20 18:06:52.028 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Policy state EZSP_TC_KEY_REQUEST_POLICY = EZSP_ALLOW_TC_KEY_REQUESTS_AND_SEND_CURRENT_KEY [51]
2021-07-20 18:06:52.029 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Policy state EZSP_TRUST_CENTER_POLICY = EZSP_ALLOW_PRECONFIGURED_KEY_JOINS [01]
2021-07-20 18:06:52.051 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Ember initial network parameters are EmberNetworkParameters [extendedPanId=EEE8BCB7B2C846E6, panId=BC85, radioTxPower=-1, radioChannel=25, joinMethod=EMBER_USE_MAC_ASSOCIATION, nwkManagerId=0000, nwkUpdateId=0, channels=07FFF800]
2021-07-20 18:06:52.051 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspGetNetworkParametersResponse [networkId=0, status=EMBER_SUCCESS, nodeType=EMBER_COORDINATOR, parameters=EmberNetworkParameters [extendedPanId=EEE8BCB7B2C846E6, panId=BC85, radioTxPower=-1, radioChannel=25, joinMethod=EMBER_USE_MAC_ASSOCIATION, nwkManagerId=0000, nwkUpdateId=0, channels=07FFF800]]
2021-07-20 18:06:52.087 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspGetEui64Response [networkId=0, eui64=000D6F000DB9E768]
2021-07-20 18:06:52.090 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Ember local IEEE Address is 000D6F000DB9E768
2021-07-20 18:06:52.107 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspGetNetworkParametersResponse [networkId=0, status=EMBER_SUCCESS, nodeType=EMBER_COORDINATOR, parameters=EmberNetworkParameters [extendedPanId=EEE8BCB7B2C846E6, panId=BC85, radioTxPower=-1, radioChannel=25, joinMethod=EMBER_USE_MAC_ASSOCIATION, nwkManagerId=0000, nwkUpdateId=0, channels=07FFF800]]
2021-07-20 18:06:52.109 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EZSP Dongle: initialize done
2021-07-20 18:06:52.111 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Mesh Update Period 86400
2021-07-20 18:06:52.114 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported client cluster 0500
2021-07-20 18:06:52.117 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher starting for endpoint 1 with profile ID 0104 (ZIGBEE_HOME_AUTOMATION)
2021-07-20 18:06:52.118 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding client cluster 0500
2021-07-20 18:06:52.119 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Adding supported server cluster 0019
...
2021-07-20 18:06:52.215 [DEBUG] [stems.zigbee.internal.ClusterMatcher] - ClusterMatcher adding server cluster 0000
2021-07-20 18:06:52.217 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee Initialise: Previous device configuration was: channel=CHANNEL_25, PanID=48261, EPanId=EEE8BCB7B2C846E6
2021-07-20 18:06:52.217 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - Config: zigbee_trustcentremode=TC_JOIN_INSECURE
2021-07-20 18:06:52.228 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSetPolicyResponse [networkId=0, status=EZSP_SUCCESS]
2021-07-20 18:06:52.232 [DEBUG] [systems.zigbee.dongle.ember.EmberNcp] - EzspSetPolicyResponse [networkId=0, status=EZSP_SUCCESS]
2021-07-20 18:06:52.248 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSetConcentratorResponse [networkId=0, status=EZSP_SUCCESS]
2021-07-20 18:06:52.249 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EzspSetConcentratorResponse [networkId=0, status=EZSP_SUCCESS]
2021-07-20 18:06:52.249 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - ZigBeeNetworkManager startup: reinitialize=false, networkState=INITIALISING
2021-07-20 18:06:52.250 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EZSP Dongle: Startup - reinitialize=false
2021-07-20 18:06:52.251 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EZSP Adding Endpoint: ProfileID=0104, DeviceID=0050
2021-07-20 18:06:52.251 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EZSP Adding Endpoint: Input Clusters   0000
2021-07-20 18:06:52.252 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EZSP Adding Endpoint: Output Clusters  0000
2021-07-20 18:06:52.272 [DEBUG] [systems.zigbee.dongle.ember.EmberNcp] - EzspAddEndpointResponse [networkId=0, status=EZSP_SUCCESS]
2021-07-20 18:06:52.272 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspAddEndpointResponse [networkId=0, status=EZSP_SUCCESS]
2021-07-20 18:06:52.317 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspNetworkInitResponse [networkId=0, status=EMBER_SUCCESS]
2021-07-20 18:06:52.319 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspStackStatusHandler [networkId=0, status=EMBER_NETWORK_UP]
2021-07-20 18:06:52.320 [DEBUG] [systems.zigbee.dongle.ember.EmberNcp] - EzspNetworkInitResponse [networkId=0, status=EMBER_SUCCESS]
2021-07-20 18:06:52.320 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Ember: Link State change to true, initialised=false, networkStateUp=false
2021-07-20 18:06:52.320 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Ember: Link State change to true ignored.
2021-07-20 18:06:52.346 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspGetCurrentSecurityStateResponse [networkId=0, status=EMBER_SUCCESS, state=EmberCurrentSecurityState [bitmask=[EMBER_GLOBAL_LINK_KEY, EMBER_TRUST_CENTER_USES_HASHED_LINK_KEY, EMBER_HAVE_TRUST_CENTER_LINK_KEY], trustCenterLongAddress=000D6F000DB9E768]]
2021-07-20 18:06:52.347 [DEBUG] [systems.zigbee.dongle.ember.EmberNcp] - EzspGetCurrentSecurityStateResponse [networkId=0, status=EMBER_SUCCESS, state=EmberCurrentSecurityState [bitmask=[EMBER_GLOBAL_LINK_KEY, EMBER_TRUST_CENTER_USES_HASHED_LINK_KEY, EMBER_HAVE_TRUST_CENTER_LINK_KEY], trustCenterLongAddress=000D6F000DB9E768]]
2021-07-20 18:06:52.365 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EZSP networkStateResponse EMBER_JOINED_NETWORK
2021-07-20 18:06:52.385 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspGetNetworkParametersResponse [networkId=0, status=EMBER_SUCCESS, nodeType=EMBER_COORDINATOR, parameters=EmberNetworkParameters [extendedPanId=EEE8BCB7B2C846E6, panId=BC85, radioTxPower=-1, radioChannel=25, joinMethod=EMBER_USE_MAC_ASSOCIATION, nwkManagerId=0000, nwkUpdateId=0, channels=07FFF800]]
2021-07-20 18:06:52.410 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EZSP networkState after online wait EMBER_JOINED_NETWORK
2021-07-20 18:06:52.432 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspGetCurrentSecurityStateResponse [networkId=0, status=EMBER_SUCCESS, state=EmberCurrentSecurityState [bitmask=[EMBER_GLOBAL_LINK_KEY, EMBER_TRUST_CENTER_USES_HASHED_LINK_KEY, EMBER_HAVE_TRUST_CENTER_LINK_KEY], trustCenterLongAddress=000D6F000DB9E768]]
2021-07-20 18:06:52.432 [DEBUG] [systems.zigbee.dongle.ember.EmberNcp] - EzspGetCurrentSecurityStateResponse [networkId=0, status=EMBER_SUCCESS, state=EmberCurrentSecurityState [bitmask=[EMBER_GLOBAL_LINK_KEY, EMBER_TRUST_CENTER_USES_HASHED_LINK_KEY, EMBER_HAVE_TRUST_CENTER_LINK_KEY], trustCenterLongAddress=000D6F000DB9E768]]
2021-07-20 18:06:52.433 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EZSP Current Security State = EmberCurrentSecurityState [bitmask=[EMBER_GLOBAL_LINK_KEY, EMBER_TRUST_CENTER_USES_HASHED_LINK_KEY, EMBER_HAVE_TRUST_CENTER_LINK_KEY], trustCenterLongAddress=000D6F000DB9E768]
2021-07-20 18:06:52.449 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSetRadioPowerResponse [networkId=0, status=EMBER_SUCCESS]
2021-07-20 18:06:52.469 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspGetNodeIdResponse [networkId=0, nodeId=0000]
2021-07-20 18:06:52.470 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EZSP Dongle: Startup complete. NWK Address = 0000, State = EMBER_JOINED_NETWORK
2021-07-20 18:06:52.470 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Ember: Link State change to true, initialised=true, networkStateUp=false
2021-07-20 18:06:52.472 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Ember: Link State up running
2021-07-20 18:06:52.496 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendManyToOneRouteRequestResponse [networkId=0, status=EMBER_SUCCESS]
2021-07-20 18:06:52.497 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Network state is updated to ONLINE
2021-07-20 18:06:52.498 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - ZigBee initialise done. channel=CHANNEL_25, PanId=48261  EPanId=EEE8BCB7B2C846E6
2021-07-20 18:06:52.500 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Network state ONLINE: Process running. 1 Nodes in network.
2021-07-20 18:06:52.500 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 000D6F000DB9E768: Adding local node to network, NWK=0000
2021-07-20 18:06:52.501 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 000D6F000DB9E768: Updating node NWK=0000
2021-07-20 18:06:52.501 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 000D6F000DB9E768: Node update. NWK Address=0000
2021-07-20 18:06:52.501 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 000D6F000DB9E768: Node 0000 is not updated
2021-07-20 18:06:52.503 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Permit join to FFFC/0 for 0 seconds.
2021-07-20 18:06:52.511 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=null queueTime=0, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=--, permitDuration=0, tcSignificance=true]]
2021-07-20 18:06:52.532 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspGetNodeIdResponse [networkId=0, nodeId=0000]
2021-07-20 18:06:52.532 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
2021-07-20 18:06:52.537 [DEBUG] [transaction.ZigBeeTransactionManager] - FFFC/0: Sending ZigBeeTransaction [ieeeAddress=null queueTime=25, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=00, permitDuration=0, tcSignificance=true]]
2021-07-20 18:06:52.538 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2021-07-20 18:06:52.544 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - ZigBeeNetworkManager transport state updated to ONLINE
2021-07-20 18:06:52.556 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=00, permitDuration=0, tcSignificance=true]
2021-07-20 18:06:52.578 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=FFFC/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=00, rssi=--, lqi=--, payload=00 00 01]
2021-07-20 18:06:52.592 [DEBUG] [transaction.ZigBeeTransactionManager] - 000D6F000DB9E768: Creating new Transaction Queue
2021-07-20 18:06:52.593 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6F000DB9E768: Set profile to ZigBeeTransactionProfile [maxOutstandingTransactions=1, interTransactionDelay=50, maxRetries=2]
2021-07-20 18:06:52.594 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6F000DB9E768: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=000D6F000DB9E768 queueTime=0, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=--, permitDuration=0, tcSignificance=true]]
2021-07-20 18:06:52.594 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3
2021-07-20 18:06:52.595 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendBroadcastResponse [networkId=0, status=EMBER_SUCCESS, sequence=B6]
2021-07-20 18:06:52.595 [DEBUG] [transaction.ZigBeeTransactionManager] - 0000/0: Sending ZigBeeTransaction [ieeeAddress=000D6F000DB9E768 queueTime=1, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=01, permitDuration=0, tcSignificance=true]]
2021-07-20 18:06:52.596 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2021-07-20 18:06:52.596 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=01, permitDuration=0, tcSignificance=true]
2021-07-20 18:06:52.597 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=01, rssi=--, lqi=--, payload=01 00 01]
2021-07-20 18:06:52.597 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_BROADCAST_LOOPBACK, apsFrame=EmberApsFrame [profileId=0000, clusterId=0036, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=B6], lastHopLqi=255, lastHopRssi=0, sender=0000, bindingIndex=255, addressIndex=255, messageContents=00 00 01]
2021-07-20 18:06:52.608 [DEBUG] [p.discovery.ZigBeeDiscoveryExtension] - DISCOVERY Extension: Startup
2021-07-20 18:06:52.611 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - Network discovery task: starting
2021-07-20 18:06:52.615 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - NWK Discovery for 0000 scheduling node discovery
2021-07-20 18:06:52.622 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=B7]
2021-07-20 18:06:52.626 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - NWK Discovery for 0000 starting node discovery
2021-07-20 18:06:52.628 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Network state ONLINE: Notifying node 000D6F000DB9E768 [0000]
2021-07-20 18:06:52.644 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6F000DB9E768: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=000D6F000DB9E768 queueTime=0, state=WAITING, sendCnt=0, command=IeeeAddressRequest [0000/0 -> 0000/0, cluster=0001, TID=--, nwkAddrOfInterest=0000, requestType=1, startIndex=0]]
2021-07-20 18:06:52.645 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=2, outstandingQueues=1, sleepy=0/3
2021-07-20 18:06:52.645 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=0036, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=B7], lastHopLqi=255, lastHopRssi=0, sender=0000, bindingIndex=255, addressIndex=255, messageContents=01 00 01]
2021-07-20 18:06:52.648 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=B7, rssi=0, lqi=FF, payload=01 00 01]
2021-07-20 18:06:52.652 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - 000D6F000DB9E768: NodeDescriptor passed to Ember NCP NodeDescriptor [apsFlags=0, bufferSize=82, complexDescriptorAvailable=false, manufacturerCode=ABCD, logicalType=COORDINATOR, serverCapabilities=[PRIMARY_TRUST_CENTER, NETWORK_MANAGER], incomingTransferSize=128, outgoingTransferSize=128, userDescriptorAvailable=false, frequencyBands=[FREQ_2400_MHZ], macCapabilities=[ALTERNATIVE_PAN, FULL_FUNCTION_DEVICE, MAINS_POWER, RECEIVER_ON_WHEN_IDLE], extendedEndpointListAvailable=false, extendedSimpleDescriptorListAvailable=false, stackCompliance=21]
2021-07-20 18:06:52.656 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 000D6F000DB9E768: Data store: Deferring write for 250ms.
2021-07-20 18:06:52.672 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - null: networkStateUpdated called with state=ONLINE
2021-07-20 18:06:52.673 [DEBUG] [p.discovery.ZigBeeDiscoveryExtension] - DISCOVERY Extension: Starting mesh update
2021-07-20 18:06:52.712 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6F000DB9E768: Set profile to ZigBeeTransactionProfile [maxOutstandingTransactions=1, interTransactionDelay=50, maxRetries=2]
2021-07-20 18:06:52.751 [DEBUG] [p.discovery.ZigBeeDiscoveryExtension] - 000D6F000DB9E768: DISCOVERY Extension: Adding discoverer for node
2021-07-20 18:06:52.766 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000DB9E768: Node SVC Discovery: created discoverer
2021-07-20 18:06:52.767 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000DB9E768: Node SVC Discovery: start discovery
2021-07-20 18:06:52.781 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000DB9E768: Node SVC Discovery: starting new tasks []
2021-07-20 18:06:52.782 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000DB9E768: Node SVC Discovery: has no new tasks to perform
2021-07-20 18:06:52.795 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=01, permitDuration=0, tcSignificance=true]
2021-07-20 18:06:52.796 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=01, permitDuration=0, tcSignificance=true] 
2021-07-20 18:06:52.809 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=8036, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=B8], lastHopLqi=255, lastHopRssi=0, sender=0000, bindingIndex=255, addressIndex=255, messageContents=01 00]
2021-07-20 18:06:52.810 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=8036, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=B8, rssi=0, lqi=FF, payload=01 00]
2021-07-20 18:06:52.811 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningResponse [0000/0 -> 0000/0, cluster=8036, TID=01, status=SUCCESS]
2021-07-20 18:06:52.812 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0000/0 -> 0000/0, cluster=8036, TID=01, status=SUCCESS] 
2021-07-20 18:06:52.821 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=0000, apsFrame=EmberApsFrame [profileId=0000, clusterId=0036, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=B7], messageTag=01, status=EMBER_SUCCESS, messageContents=]
2021-07-20 18:06:52.822 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=01 state=RX_ACK
2021-07-20 18:06:52.823 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=01, state=RX_ACK, outstanding=2
2021-07-20 18:06:52.829 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=000D6F000DB9E768 queueTime=235, state=COMPLETE, sendCnt=1, command=ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=01, permitDuration=0, tcSignificance=true]]
2021-07-20 18:06:52.830 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2021-07-20 18:06:52.830 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6F000DB9E768: transactionComplete, state=COMPLETE, outstanding=0
2021-07-20 18:06:52.830 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3
2021-07-20 18:06:52.831 [DEBUG] [transaction.ZigBeeTransactionManager] - 0000/0: Sending ZigBeeTransaction [ieeeAddress=000D6F000DB9E768 queueTime=187, state=WAITING, sendCnt=0, command=IeeeAddressRequest [0000/0 -> 0000/0, cluster=0001, TID=02, nwkAddrOfInterest=0000, requestType=1, startIndex=0]]
2021-07-20 18:06:52.831 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2021-07-20 18:06:52.844 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: IeeeAddressRequest [0000/0 -> 0000/0, cluster=0001, TID=02, nwkAddrOfInterest=0000, requestType=1, startIndex=0]
2021-07-20 18:06:52.844 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=0001, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=02, rssi=--, lqi=--, payload=02 00 00 01 00]
2021-07-20 18:06:52.856 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=0000, TID=01, event=RX_ACK, state=COMPLETE
2021-07-20 18:06:52.857 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=B9]
2021-07-20 18:06:52.880 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=0001, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=B9], lastHopLqi=255, lastHopRssi=0, sender=0000, bindingIndex=255, addressIndex=255, messageContents=02 00 00 01 00]
2021-07-20 18:06:52.881 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=0001, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=B9, rssi=0, lqi=FF, payload=02 00 00 01 00]
2021-07-20 18:06:52.882 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: IeeeAddressRequest [0000/0 -> 0000/0, cluster=0001, TID=02, nwkAddrOfInterest=0000, requestType=1, startIndex=0]
2021-07-20 18:06:52.882 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: IeeeAddressRequest [0000/0 -> 0000/0, cluster=0001, TID=02, nwkAddrOfInterest=0000, requestType=1, startIndex=0] 
2021-07-20 18:06:52.883 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=8001, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=BA], lastHopLqi=255, lastHopRssi=0, sender=0000, bindingIndex=255, addressIndex=255, messageContents=02 00 68 E7 B9 0D 00 6F 0D 00 00 00 00]
2021-07-20 18:06:52.884 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=8001, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=BA, rssi=0, lqi=FF, payload=02 00 68 E7 B9 0D 00 6F 0D 00 00 00 00]
2021-07-20 18:06:52.885 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: IeeeAddressResponse [0000/0 -> 0000/0, cluster=8001, TID=02, status=SUCCESS, ieeeAddrRemoteDev=000D6F000DB9E768, nwkAddrRemoteDev=0000, startIndex=null, nwkAddrAssocDevList=[]]
2021-07-20 18:06:52.886 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: IeeeAddressResponse [0000/0 -> 0000/0, cluster=8001, TID=02, status=SUCCESS, ieeeAddrRemoteDev=000D6F000DB9E768, nwkAddrRemoteDev=0000, startIndex=null, nwkAddrAssocDevList=[]] 
2021-07-20 18:06:52.893 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=000D6F000DB9E768 queueTime=248, state=COMPLETE, sendCnt=1, command=IeeeAddressRequest [0000/0 -> 0000/0, cluster=0001, TID=02, nwkAddrOfInterest=0000, requestType=1, startIndex=0]]
2021-07-20 18:06:52.893 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2021-07-20 18:06:52.893 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - NWK Discovery for 0000 IeeeAddressRequest returned IeeeAddressResponse [0000/0 -> 0000/0, cluster=8001, TID=02, status=SUCCESS, ieeeAddrRemoteDev=000D6F000DB9E768, nwkAddrRemoteDev=0000, startIndex=null, nwkAddrAssocDevList=[]]
2021-07-20 18:06:52.894 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6F000DB9E768: transactionComplete, state=COMPLETE, outstanding=0
2021-07-20 18:06:52.894 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=0, sleepy=0/3
2021-07-20 18:06:52.895 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=0000, apsFrame=EmberApsFrame [profileId=0000, clusterId=0001, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=B9], messageTag=02, status=EMBER_SUCCESS, messageContents=]
2021-07-20 18:06:52.895 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=02 state=RX_ACK
2021-07-20 18:06:52.895 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=02, state=RX_ACK, outstanding=1
2021-07-20 18:06:52.907 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 000D6F000DB9E768: Data store: Writing node.
2021-07-20 18:06:52.953 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 000D6F000DB9E768: ZigBee saving network state complete.
2021-07-20 18:06:53.629 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_BROADCAST, indexOrDestination=FFFC, apsFrame=EmberApsFrame [profileId=0000, clusterId=0036, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=B6], messageTag=00, status=EMBER_DELIVERY_FAILED, messageContents=]
2021-07-20 18:06:53.629 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=00 state=RX_NAK
2021-07-20 18:06:53.630 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=00, state=RX_NAK, outstanding=1
2021-07-20 18:06:53.630 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=null queueTime=1119, state=FAILED, sendCnt=1, command=ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=00, permitDuration=0, tcSignificance=true]]
2021-07-20 18:06:53.630 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2021-07-20 18:06:53.631 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete, state=FAILED, outstanding=0
2021-07-20 18:06:53.631 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete exceeded max retries 1
2021-07-20 18:06:53.631 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction cancelled: ZigBeeTransaction [ieeeAddress=null queueTime=1120, state=CANCELLED, sendCnt=1, command=ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=00, permitDuration=0, tcSignificance=true]]
2021-07-20 18:06:53.632 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=null queueTime=1120, state=CANCELLED, sendCnt=1, command=ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=00, permitDuration=0, tcSignificance=true]]
2021-07-20 18:06:53.632 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2021-07-20 18:06:53.632 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete but not outstanding, state=CANCELLED, outstanding=0
2021-07-20 18:06:53.632 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=0, sleepy=0/3
2021-07-20 18:06:53.633 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=0, sleepy=0/3
2021-07-20 18:06:53.633 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=FFFC, TID=00, event=RX_NAK, state=CANCELLED

When I start the scanning for new ZigBee devices in OH, I see the following log entries:

2021-07-20 18:13:40.185 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - Starting ZigBee scan for zigbee:coordinator_ember:c7b0cb48f4
2021-07-20 18:13:40.187 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Permit join to FFFC/0 for 60 seconds.
2021-07-20 18:13:40.188 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=null queueTime=0, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true]]
2021-07-20 18:13:40.189 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
2021-07-20 18:13:40.190 [DEBUG] [transaction.ZigBeeTransactionManager] - FFFC/0: Sending ZigBeeTransaction [ieeeAddress=null queueTime=2, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=03, permitDuration=60, tcSignificance=true]]
2021-07-20 18:13:40.190 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2021-07-20 18:13:40.191 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=03, permitDuration=60, tcSignificance=true]
2021-07-20 18:13:40.192 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=FFFC/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=03, rssi=--, lqi=--, payload=03 3C 01]
2021-07-20 18:13:40.193 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6F000DB9E768: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=000D6F000DB9E768 queueTime=0, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true]]
2021-07-20 18:13:40.194 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3
2021-07-20 18:13:40.198 [DEBUG] [transaction.ZigBeeTransactionManager] - 0000/0: Sending ZigBeeTransaction [ieeeAddress=000D6F000DB9E768 queueTime=5, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=04, permitDuration=60, tcSignificance=true]]
2021-07-20 18:13:40.199 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2021-07-20 18:13:40.200 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=04, permitDuration=60, tcSignificance=true]
2021-07-20 18:13:40.201 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=04, rssi=--, lqi=--, payload=04 3C 01]
2021-07-20 18:13:40.213 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendBroadcastResponse [networkId=0, status=EMBER_SUCCESS, sequence=BB]
2021-07-20 18:13:40.214 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_BROADCAST_LOOPBACK, apsFrame=EmberApsFrame [profileId=0000, clusterId=0036, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=BB], lastHopLqi=255, lastHopRssi=0, sender=0000, bindingIndex=255, addressIndex=255, messageContents=03 3C 01]
2021-07-20 18:13:40.254 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=BC]
2021-07-20 18:13:40.275 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=0036, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=BC], lastHopLqi=255, lastHopRssi=0, sender=0000, bindingIndex=255, addressIndex=255, messageContents=04 3C 01]
2021-07-20 18:13:40.276 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=BC, rssi=0, lqi=FF, payload=04 3C 01]
2021-07-20 18:13:40.278 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=04, permitDuration=60, tcSignificance=true]
2021-07-20 18:13:40.278 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=04, permitDuration=60, tcSignificance=true] 
2021-07-20 18:13:40.280 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=8036, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=BD], lastHopLqi=255, lastHopRssi=0, sender=0000, bindingIndex=255, addressIndex=255, messageContents=04 00]
2021-07-20 18:13:40.280 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=8036, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=BD, rssi=0, lqi=FF, payload=04 00]
2021-07-20 18:13:40.281 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningResponse [0000/0 -> 0000/0, cluster=8036, TID=04, status=SUCCESS]
2021-07-20 18:13:40.281 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0000/0 -> 0000/0, cluster=8036, TID=04, status=SUCCESS] 
2021-07-20 18:13:40.283 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=0000, apsFrame=EmberApsFrame [profileId=0000, clusterId=0036, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=BC], messageTag=04, status=EMBER_SUCCESS, messageContents=]
2021-07-20 18:13:40.283 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=04 state=RX_ACK
2021-07-20 18:13:40.284 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=04, state=RX_ACK, outstanding=2
2021-07-20 18:13:40.284 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=000D6F000DB9E768 queueTime=91, state=COMPLETE, sendCnt=1, command=ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=04, permitDuration=60, tcSignificance=true]]
2021-07-20 18:13:40.285 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2021-07-20 18:13:40.285 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6F000DB9E768: transactionComplete, state=COMPLETE, outstanding=0
2021-07-20 18:13:40.286 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=0, sleepy=0/3
2021-07-20 18:13:40.286 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=0000, TID=04, event=RX_ACK, state=COMPLETE
2021-07-20 18:13:41.158 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_BROADCAST, indexOrDestination=FFFC, apsFrame=EmberApsFrame [profileId=0000, clusterId=0036, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=BB], messageTag=03, status=EMBER_DELIVERY_FAILED, messageContents=]
2021-07-20 18:13:41.159 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=03 state=RX_NAK
2021-07-20 18:13:41.160 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=03, state=RX_NAK, outstanding=1
2021-07-20 18:13:41.161 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=null queueTime=973, state=FAILED, sendCnt=1, command=ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=03, permitDuration=60, tcSignificance=true]]
2021-07-20 18:13:41.162 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2021-07-20 18:13:41.162 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete, state=FAILED, outstanding=0
2021-07-20 18:13:41.162 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete exceeded max retries 1
2021-07-20 18:13:41.163 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction cancelled: ZigBeeTransaction [ieeeAddress=null queueTime=975, state=CANCELLED, sendCnt=1, command=ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=03, permitDuration=60, tcSignificance=true]]
2021-07-20 18:13:41.163 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=null queueTime=975, state=CANCELLED, sendCnt=1, command=ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=03, permitDuration=60, tcSignificance=true]]
2021-07-20 18:13:41.163 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2021-07-20 18:13:41.164 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete but not outstanding, state=CANCELLED, outstanding=0
2021-07-20 18:13:41.164 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=0, sleepy=0/3
2021-07-20 18:13:41.165 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=0, sleepy=0/3
2021-07-20 18:13:41.165 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=FFFC, TID=03, event=RX_NAK, state=CANCELLED

While scanning is in progress, I try to set the ZigBee device in JOIN mode, but nothing happens - no logging, no device found while scanning. My first guess was a problem with my smart blind wand and so I’ve bought a cheap ZigBee smart plug to try it with a different device. But same problem, nothing found!

I’ve tried to play around with different ZigBee channels (because of possible Wi-Fi interference), also changed join modes secure to insecure and other things, but nothing helped so far. Usually I set up all things manually via things file, but after that fails I’ve also tried it with the GUI, but also without success. Here is the thing definition used with my last test:

UID: zigbee:coordinator_ember:c7b0cb48f4
label: Ember EM35x Coordinator
thingTypeUID: zigbee:coordinator_ember
configuration:
  zigbee_port: /dev/ttyUSB0
  zigbee_initialise: false
  zigbee_channel: 25
  zigbee_concentrator: 1
  zigbee_trustcentremode: TC_JOIN_INSECURE
  zigbee_extendedpanid: EEE8BCB7B2C846E6
  zigbee_flowcontrol: 2
  zigbee_baud: 57600
  zigbee_panid: 48261
  zigbee_powermode: 1
  zigbee_txpower: 0
  zigbee_networksize: 25
  zigbee_linkkey: 5A6967426565416C6C69616E63653039
  zigbee_childtimeout: 86400
  zigbee_networkkey: A72D3A4D4425C3F891CCD1587A1326F4
  zigbee_meshupdateperiod: 86400

Does somebody has any idea what may cause this problem?

Btw, does anyone know about the blue status LED on this ZigBee stick, it stays always on - no blinking, no color changing, etc. - is this usual? On my Z-Wave stick, I can see status information on the LED, but not on this ZigBee stick…

Thank’s in advance,
Frank

2

cont. just to add some more information.

The ZigBee plug which I try to use as an other (simple) device is called " DOGAIN Zigbee Smart Plug, ASIN‏: ‎ B08PYWS43S" (bought from Amazon). The final device which I really would like to connect via ZigBee is a smart vertical blinds wand, called “E-Wand Gen. 2 Hybrid” (https://www.myewand.com/product-page/gen-2-hybrid-e-wand-single-unit).

For further analyzing and debugging of the problem, I’ve created temporarily 6 items with the ZigBee stick channels “Data frames” send and rec, “NAK frames” send and rec. and “ACK frames” send and rec. and try to scan again. But unfortunately all 6 values stays at “NULL” permanently.

For me, it looks like that the ZigBee stick does not communicate with radio at all, even if it’s status is “online” (green).

Maybe somebody also owns this ZigBee stick and could send me a log excerpt of the openhab.log (grep -i zigbee) for the init phase and from a scanning phase so I would be able to compare that to my log output.

After digging deeper in the log files, I assume, that the serial communication with the stick works (it also has a “online” green status). Here are some of these messages…

2021-07-21 06:03:19.303 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=3, notRdy=false]
2021-07-21 06:03:20.299 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1
2021-07-21 06:03:20.300 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=6, ackNum=3, reTx=false, data=46 00 18]
2021-07-21 06:03:20.304 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=3, ackNum=7, reTx=false, data=46 80 18 02]
2021-07-21 06:03:20.304 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=6, ackNum=3, reTx=false, data=46 00 18]

But I’ve no found possible error hint’s in the logfile while scanning for new ZigBee devices:

...
2021-07-21 06:31:06.397 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_BROADCAST, indexOrDestination=FFFC, apsFrame=EmberApsFrame [profileId=0000, clusterId=0036, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=C7], messageTag=0B, status=EMBER_DELIVERY_FAILED, messageContents=]
...
2021-07-21 06:31:06.399 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=null queueTime=985, state=FAILED, sendCnt=1, command=ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=0B, permitDuration=60, tcSignificance=true]]
...
2021-07-21 06:31:06.400 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete, state=FAILED, outstanding=0
...
2021-07-21 06:31:06.400 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction cancelled: ZigBeeTransaction [ieeeAddress=null queueTime=986, state=CANCELLED, sendCnt=1, command=ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=0B, permitDuration=60, tcSignificance=true]]
2021-07-21 06:31:06.400 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=null queueTime=986, state=CANCELLED, sendCnt=1, command=ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=0B, permitDuration=60, tcSignificance=true]]
2021-07-21 06:31:06.401 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2021-07-21 06:31:06.401 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete but not outstanding, state=CANCELLED, outstanding=0
2021-07-21 06:31:06.401 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=0, sleepy=0/3
2021-07-21 06:31:06.401 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=0, sleepy=0/3
2021-07-21 06:31:06.401 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=FFFC, TID=0B, event=RX_NAK, state=CANCELLED

Also to note, my thing properties are:

    zigbee_logicaltype: COORDINATOR
    zigbee_lastupdate:
    zigbee_macaddress: 000D6F000DB9E768
    zigbee_networkaddress: 0
    firmwareVersion: 5.8.1.0
    zigbee_neighbors: []
    zigbee_routes: []
    zigbee_devices: []```
3

I see the same, none of these get values.
This has been the case for some months. I do not know how it was before as I never added the Items…

I just switched from the Bitronvideo stick to the Itead USB zb3 stick on my production system.
I do not remember if the led stay on solid or not.

The Bitronvideo has a very old firmware so it will have trouble with zigbee v3 devices.
But I belive some communication should show up in the log before v3 devices decides to leave the network.

4

Hi Nils,

thanks for your help. As far as I understand, you’ve used the Bitronvideo successfully previously in your OH (2.x or 3.x ?) installation and only theses 6 items to monitor the stick itself have not worked!?Scanning and using other ZigBee devices worked for you with this stick?

I should consider also to change to a different ZigBee stick. Where have you bought this stick? Was it already flashed with the correct/final firmware or did you do the flashing by yourself? I found one offer of a CC2531 based stick in ebay Germany and the seller is able to sent it to me to the US - but it uses the Zigbee2MQTT custom firmware… don’t know, if this would be a good idea…

Thanks,
Frank

5

Yes, the Bitronvideo stick(s) has worked for me from 2.x and up several versions and snapshots to 3.1.0 when I switched to a Itead stick.
I have devices from Ikea, Ledvance, Hue and then some.
Including new devices has not been a problem (except for some Aqara sensors
Edit: and the newer zigbee v3 devices).
The Itead stick is not availible from Itead right now as it was a preproduction run. I have seen them on Ebay…
If I could find newer firmware for the Bitronvideos I would continue to use them.
The Itead sticks are just printboards, no case…
…but as I have two of them I put one on my production system.
My system has less than a week uptime with the Itead so far so I still consider these:

6

Both probably need a firmware upgrade to work with zigbee v3 devices.
I belive the Popp has the newest firmware version avalible.
(Quality check that :wink: )

Also, people have reported problems with zigbee v3 devices on the older cc sticks.
I am not shure how good the newer chips from Ti is supported, if at all.

7

Forgot to answer this: no I have not seen the “monitor” items working (that
I can remember)

8

I think this was caused by the change in the way channel linking worked in OH3.0 - it was fixed in OH3.1.

9

Ah, I see them now :slight_smile:
Either it takes a long time from the .items file is edited or the binding needs a restart for them to change from NULL. Probably just takes a while before the item fall into its place in OH.

However, rx_ack seems stuck at zero. Is that right?

10

It should be every 30 seconds - right from the start I believe. Certainly when I fixed this it seemed to work immediately and did not “take a while”.

No - it should count up, but I also see the same here. I seldom look at these and the problem is probably just in the reporting and not in the communications since it is definitely working ok.

1 Like
11

After reading this hint about a fix in OH 3.1 with the ZigBee binding, I gave it a try and also tried OH 3.2.0-SNAPSHOT. In the newer versions I have now access to these 6 different ZigBee stick items (Data sent/rec, ACK sent/rec and NAK sent/rec).

But the scanning for new ZigBee devices is still not successful (I’ve tried with 3 different ZigBee devices). But I can see now an heavy increase of the ACK sent (+100 after scanning) , Data sent and receive (both about +100 after scanning) item values which shows me, that the ZigBee radio is sending and receiving at all…

Unfortunately, I still have no debug messages while scanning is in progress…

12

Why not? Have you enabled logging as per the binding documentation? If you have, then you should have debug messages unless something is very fundamentally not working. You need to get debug logging working - without this it’s really difficult/impossible to provide a lot of help.

13

I already set the following log settings, like the documentation describes:

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

I see a lot of ZigBee debug messages when starting the scan process. Here are these lines from just starting the scanning process in OH - all these log messages happen in about 1 second:

2021-07-20 18:13:40.185 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - Starting ZigBee scan for zigbee:coordinator_ember:c7b0cb48f4
2021-07-20 18:13:40.187 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Permit join to FFFC/0 for 60 seconds.
2021-07-20 18:13:40.188 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=null queueTime=0, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true]]
2021-07-20 18:13:40.189 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
2021-07-20 18:13:40.190 [DEBUG] [transaction.ZigBeeTransactionManager] - FFFC/0: Sending ZigBeeTransaction [ieeeAddress=null queueTime=2, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=03, permitDuration=60, tcSignificance=true]]
2021-07-20 18:13:40.190 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2021-07-20 18:13:40.191 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=03, permitDuration=60, tcSignificance=true]
2021-07-20 18:13:40.192 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=FFFC/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=03, rssi=--, lqi=--, payload=03 3C 01]
2021-07-20 18:13:40.193 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6F000DB9E768: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=000D6F000DB9E768 queueTime=0, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true]]
2021-07-20 18:13:40.194 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3
2021-07-20 18:13:40.198 [DEBUG] [transaction.ZigBeeTransactionManager] - 0000/0: Sending ZigBeeTransaction [ieeeAddress=000D6F000DB9E768 queueTime=5, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=04, permitDuration=60, tcSignificance=true]]
2021-07-20 18:13:40.199 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2021-07-20 18:13:40.200 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=04, permitDuration=60, tcSignificance=true]
2021-07-20 18:13:40.201 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=04, rssi=--, lqi=--, payload=04 3C 01]
2021-07-20 18:13:40.213 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendBroadcastResponse [networkId=0, status=EMBER_SUCCESS, sequence=BB]
2021-07-20 18:13:40.214 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_BROADCAST_LOOPBACK, apsFrame=EmberApsFrame [profileId=0000, clusterId=0036, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=BB], lastHopLqi=255, lastHopRssi=0, sender=0000, bindingIndex=255, addressIndex=255, messageContents=03 3C 01]
2021-07-20 18:13:40.254 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=BC]
2021-07-20 18:13:40.275 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=0036, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=BC], lastHopLqi=255, lastHopRssi=0, sender=0000, bindingIndex=255, addressIndex=255, messageContents=04 3C 01]
2021-07-20 18:13:40.276 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=BC, rssi=0, lqi=FF, payload=04 3C 01]
2021-07-20 18:13:40.278 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=04, permitDuration=60, tcSignificance=true]
2021-07-20 18:13:40.278 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=04, permitDuration=60, tcSignificance=true] 
2021-07-20 18:13:40.280 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=8036, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=BD], lastHopLqi=255, lastHopRssi=0, sender=0000, bindingIndex=255, addressIndex=255, messageContents=04 00]
2021-07-20 18:13:40.280 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=8036, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=BD, rssi=0, lqi=FF, payload=04 00]
2021-07-20 18:13:40.281 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningResponse [0000/0 -> 0000/0, cluster=8036, TID=04, status=SUCCESS]
2021-07-20 18:13:40.281 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0000/0 -> 0000/0, cluster=8036, TID=04, status=SUCCESS] 
2021-07-20 18:13:40.283 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=0000, apsFrame=EmberApsFrame [profileId=0000, clusterId=0036, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=BC], messageTag=04, status=EMBER_SUCCESS, messageContents=]
2021-07-20 18:13:40.283 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=04 state=RX_ACK
2021-07-20 18:13:40.284 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=04, state=RX_ACK, outstanding=2
2021-07-20 18:13:40.284 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=000D6F000DB9E768 queueTime=91, state=COMPLETE, sendCnt=1, command=ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=04, permitDuration=60, tcSignificance=true]]
2021-07-20 18:13:40.285 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2021-07-20 18:13:40.285 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6F000DB9E768: transactionComplete, state=COMPLETE, outstanding=0
2021-07-20 18:13:40.286 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=0, sleepy=0/3
2021-07-20 18:13:40.286 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=0000, TID=04, event=RX_ACK, state=COMPLETE
2021-07-20 18:13:41.158 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_BROADCAST, indexOrDestination=FFFC, apsFrame=EmberApsFrame [profileId=0000, clusterId=0036, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=BB], messageTag=03, status=EMBER_DELIVERY_FAILED, messageContents=]
2021-07-20 18:13:41.159 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=03 state=RX_NAK
2021-07-20 18:13:41.160 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=03, state=RX_NAK, outstanding=1
2021-07-20 18:13:41.161 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=null queueTime=973, state=FAILED, sendCnt=1, command=ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=03, permitDuration=60, tcSignificance=true]]
2021-07-20 18:13:41.162 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2021-07-20 18:13:41.162 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete, state=FAILED, outstanding=0
2021-07-20 18:13:41.162 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete exceeded max retries 1
2021-07-20 18:13:41.163 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction cancelled: ZigBeeTransaction [ieeeAddress=null queueTime=975, state=CANCELLED, sendCnt=1, command=ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=03, permitDuration=60, tcSignificance=true]]
2021-07-20 18:13:41.163 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=null queueTime=975, state=CANCELLED, sendCnt=1, command=ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=03, permitDuration=60, tcSignificance=true]]
2021-07-20 18:13:41.163 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2021-07-20 18:13:41.164 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete but not outstanding, state=CANCELLED, outstanding=0
2021-07-20 18:13:41.164 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=0, sleepy=0/3
2021-07-20 18:13:41.165 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=0, sleepy=0/3
2021-07-20 18:13:41.165 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=FFFC, TID=03, event=RX_NAK, state=CANCELLED

There will be no additional log message while the 60 seconds scan is in progress - even when I put the ZigBee devices in the meantime to join mode - absolutely no additional log entries while scanning. I would assume, that I would see some log debug messages if the controller would find a new device which would like to join…

14

Hi Chris,
I found the reason, why there is no logging while the discovery between ZigBee stick and ZigBee device is in progress. Unfortunately, I’ve overlooked this in the documentation.

Note that logs can only show what is happening at a high level - it can’t show all data exchanges between the device and the coordinator - just what the coordinator sends to the binding. For this reason it can be difficult to debug issues where devices are not joining the network, or other low level issues need resolving. In such cases a network sniffer log is required, which requires additional hardware and software.

Now it’s clear, why I can’t see log entries while scanning is in progress. But it makes it even harder for me to find the reason for my problem (none of my devices are found by the coordinator).

15

Hi Chris,
to dig deeper in this problem, I found a hint about the tool ZigBeeConsoleCommand. I’s not included in the OH 3.2.0-SNAPSHOT ZigBee bundle distribution (at least I was not able to find it there). But I was able to find it on GitHub - zsmartsystems/com.zsmartsystems.zigbee: ZigBee Cluster Library Java framework supporting multiple dongles and built it locally with Zulu 11 and finally I was able to start it. Without using the OH installation inside my docker container, I assume this makes it a lot easier to analyze the problem. After building it, I found the file here

./com.zsmartsystems.zigbee/com.zsmartsystems.zigbee.console.main/target/com.zsmartsystems.zigbee.console.main-1.4.1-SNAPSHOT-jar-with-dependencies.jar

I don’t know anything about this tool and try to look around and found it reacts on entered command via stdin and I’ve tried some which are described on github. Here are some examples which I’ve played around with (I’ve set the debug level to info in the log4j.xml for a first test):

java -jar com.zsmartsystems.zigbee.console.main-1.4.1-SNAPSHOT-jar-with-dependencies.jar  --dongle EMBER --port /dev/ttyUSB0 --baud 57600 --flow software --channel 11 -pan 0x2000 -epan 987654321 -nwkkey AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA -reset

Initialising ZigBee console...
ZigBee network state updated to INITIALISING
14:01:32 708  INFO   000D6F000DB9E768: ZigBee reading network state complete.
networkManager.initialize returned SUCCESS
PAN ID          = 40465
Extended PAN ID = 02E5F43ECE6C656F
Channel         = CHANNEL_11
*** Resetting network
  * Channel                = 11
  * PAN ID                 = 8192
  * Extended PAN ID        = 0000000987654321
  * Link Key               = 5A6967426565416C6C69616E63653039
  * Network Key            = AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
ZigBee console starting up ... [OK]
ZigBee console ready.p...
PAN ID          = 8192
Extended PAN ID = 0000000987654321
Channel         = CHANNEL_11
Node Added ZigBeeNode [state=UNKNOWN, IEEE=000D6F000DB9E768, NWK=0000, Type=COORDINATOR, endpoints=[]]
ZigBee network state updated to ONLINE
Node Added ZigBeeNode [state=ONLINE, IEEE=000D6F000DB9E768, NWK=0000, Type=COORDINATOR, endpoints=[]]
14:01:39 062  INFO   000D6F000DB9E768: ZigBee saving network state complete.

nodes

Total known nodes in network: 1
Network  Addr  IEEE Address      Logical Type  State      EP   Profile                    Device Type                Manufacturer     Model          
      0  0000  000D6F000DB9E768  COORDINATOR   ONLINE

node 0

IEEE Address     : 000D6F000DB9E768
Network Address  : 0
Node Descriptor  : NodeDescriptor [apsFlags=0, bufferSize=82, complexDescriptorAvailable=false, manufacturerCode=ABCD, logicalType=COORDINATOR, serverCapabilities=[PRIMARY_TRUST_CENTER, NETWORK_MANAGER], incomingTransferSize=128, outgoingTransferSize=128, userDescriptorAvailable=false, frequencyBands=[FREQ_2400_MHZ], macCapabilities=[ALTERNATIVE_PAN, FULL_FUNCTION_DEVICE, MAINS_POWER, RECEIVER_ON_WHEN_IDLE], extendedEndpointListAvailable=false, extendedSimpleDescriptorListAvailable=false, stackCompliance=21]
Power Descriptor : PowerDescriptor [currentPowerMode=RECEIVER_ON_IDLE, availablePowerSources=[MAINS], currentPowerSource=MAINS, powerLevel=FULL]
Associations     : []
Endpoints        : 
Neighbors:
Routes:

ncpversion
Ember NCP version 5.8.1.0, EZSP version 4

queues

ZigBeeTransactionQueue [queueName=000D6F000DB9E768, deviceIeeeAddress=000D6F000DB9E768, sleepy=false, queued=0, outstandingTransactions=0, profile=ZigBeeTransactionProfile [maxOutstandingTransactions=1, interTransactionDelay=50, maxRetries=2]]

routingtable 0

Total routes: 1
Destination Address   Status                Memory Constrained    Many To One           Route Record Required  Next Hop Address    
0                     INACTIVE              false                 false                 false                 0

So overall, I’m able to see some status information and play around. I have an idea of some of these parameters, but because I have no knowledge about the ZigBee protocol and it’s implementation details, I’m still a bit helpless.

Maybe you can provide me some commands, which I may try to be able to get an idea why the stick can’t find any of my ZigBee devices?

Thanks in advance,
Frank

16

Not really - you should still see some activity when a device joins. This note means that the very low level communications is not seen, but if a device joins the network, then you should still see zigbee messages - even if there are then problems.

Yes, it has been included in the distro for a long time. You can use the zigbee command in the console.

It is not a separate tool - it is just the openhab console. Please read the OH docs on how to access the console if you’re not sure.

The console won’t really help with this. If devices are really not even joining the network, then you would require a sniffer. If they are joining the network, then the packets will be seen in the log with debug enabled as per the binding docs.

17

Problem is solved :slightly_smiling_face:

My guess was, it must have to do something with a radio signal problem. I’ve just tested to attach the stick at the end of a 3 feet USB extension cord instead of directly putting the stick into the PC (it’s an Intel NUC). On the same Intel NUC, there is already a Z-Wave stick directly attached. I’ve used the same USB socket on my Intel NUC PC which I’ve used before directly with the ZigBee stick - that solved the problem!

Maybe the ZigBee interfered with the close Z-Wave (but I don’t think so because of the different frequecies), but the Intel NUC has also an integrated Wi-Fi and that may be the reason for the problem…

Now th OH scanning find my ZigBee devices!

Thanks for all your help,
Frank

1 Like
18

A brief summary that may help other users

If ZigBee discovery won’t work even with no errors reported in the (debug) log and/or no other reasons found and/or no debug logging WHILE scanning is in progress, it could be a radio interference like

  • The ZigBee stick is too close to the PC itself (CPU or other PC components may interfere)
  • The ZigBee stick is too close to a WiFi device
  • The ZigBee stick is too close to an other radio transmitting device

Try an USB extension cord to connect the ZigBee stick! This solved all my problems.

19

So I looked this over, and it is normal. Given that all commands are sent from the binding will solicit a response, the controller sends back DATA packets, and not ACK packets. DATA packets contain implicit ACKS.

So, this is actually normal :slight_smile:

1 Like