Zigbee connect Innr bulb using Nortek HUZBZB-1

Mjohannessen · September 6, 2021, 11:10pm

I’m using OH3.0.1 and installed the Zigbee binding and trying to hook up an Innr AE 280 C color bulb. I’m using a Nortek HUZBZB-1 USB stick which is recognized as an Ember serial bridge, which appears to be connected properly:

15:51:34.974 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - ZigBee network starting
15:51:34.974 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Initialising ZigBee coordinator
15:51:34.976 [DEBUG] [inding.zigbee.serial.ZigBeeSerialPort] - Connecting to serial port [/dev/cu.GoControl_zigbee] at 57600 baud, flow control FLOWCONTROL_OUT_XONOFF.
15:51:34.977 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - null: networkStateUpdated called with state=INITIALISING
15:51:35.003 [DEBUG] [inding.zigbee.serial.ZigBeeSerialPort] - Serial port [/dev/cu.GoControl_zigbee] is initialized.
15:51:39.435 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Mesh Update Period 86400
15:51:39.437 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - ZigBee Initialise: Previous device configuration was: channel=CHANNEL_11, PanID=59279, EPanId=7F36B4F0B81E4B42
15:51:39.437 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Link key initialise xxxxxxxxxxxxxxxxxxxxxxxxxx [obscured]
15:51:39.437 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Network key initialise 
xxxxxxxxxxxxxxxxxxxxxxxxxx [obscured]
15:51:39.437 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Config: zigbee_trustcentremode=TC_JOIN_SECURE
15:51:42.575 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - ZigBee initialise done. channel=CHANNEL_11, PanId=55679  EPanId=A81453E4716E7902
15:51:42.580 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - null: networkStateUpdated called with state=ONLINE
15:51:42.834 [DEBUG] [nding.zigbee.internal.ZigBeeDataStore] - 000D6F0017209191: ZigBee saving network state complete.
15:51:44.205 [DEBUG] [nding.zigbee.internal.ZigBeeDataStore] - 000D6F0017209191: ZigBee saving network state complete.
15:51:53.536 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - Starting ZigBee scan for zigbee:coordinator_ember:26cffdadc9

However, after trying to discover the light (it’s turned on), the light is not found. Per the Zigbee readme at ZigBee - Bindings | openHAB this combo of USB stick and Innr light should work, correct?

NilsOF · September 7, 2021, 4:44am

What is the firmware version on the zigbee part of the stick?

This one? https://zigbeealliance.org/zigbee_products/innr-zigbee-3-0-a19-bulb-rgbw/

See HUSBZB-1 (Combo Zigbee and ZWave stick) Should I bother flashing its firmware to latest?

Do you have other zigbee devices?
I think the innr bulb still should show up in inbox when scanning for zigbee devices. But it probably will leave the network shortly ( if stick firmware is old).

chris · September 7, 2021, 5:58am

Please can you advise what the link key is?

Mjohannessen · September 7, 2021, 2:57pm

Sure - here is the log starting from removing the binding to re-adding it:

openhab> log:tail org.openhab.binding.zigbee                                                                                                                                  
07:53:50.418 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - null: networkStateUpdated called with state=SHUTDOWN
07:53:50.422 [DEBUG] [nding.zigbee.internal.ZigBeeDataStore] - 000D6F0017209191: ZigBee saving network state complete.
07:53:50.534 [DEBUG] [inding.zigbee.serial.ZigBeeSerialPort] - Serial port '/dev/cu.GoControl_zigbee' closed.
07:53:50.534 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - ZigBee network [zigbee:coordinator_ember:26cffdadc9] closed.
07:54:19.913 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - Starting ZigBeeDiscoveryService
07:54:19.967 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Initializing ZigBee network [zigbee:coordinator_ember:26cffdadc9].
07:54:19.968 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Channel 11
07:54:19.968 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - PANID 55679
07:54:19.968 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - EPANID A81453E4716E7902
07:54:19.968 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Network Key BDDD6B12CF23F1A309DC231B6A48CE0E
07:54:19.969 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Link Key 5A6967426565416C6C69616E63653039
07:54:19.969 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Config: zigbee_initialise found, initializeNetwork=false
07:54:19.969 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Network Key String BDDD6B12CF23F1A309DC231B6A48CE0E
07:54:19.969 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Network key final array BDDD6B12CF23F1A309DC231B6A48CE0E
07:54:19.969 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Link Key String 5A6967426565416C6C69616E63653039
07:54:19.969 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Link key final array 5A6967426565416C6C69616E63653039
07:54:19.969 [DEBUG] [ing.zigbee.ember.handler.EmberHandler] - Initializing ZigBee Ember serial bridge handler.
07:54:19.978 [DEBUG] [ing.zigbee.ember.handler.EmberHandler] - ZigBee Ember Coordinator opening Port:'/dev/cu.GoControl_zigbee' PAN:d97f, EPAN:A81453E4716E7902, Channel:11
07:54:19.978 [DEBUG] [ing.zigbee.ember.handler.EmberHandler] - Ember end device poll timeout set to (169 * 2^9) = 86528 seconds
07:54:19.980 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Scheduling ZigBee start
07:54:20.984 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - ZigBee network starting
07:54:20.985 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Initialising ZigBee coordinator
07:54:20.995 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - null: networkStateUpdated called with state=INITIALISING
Security framework of XStream not explicitly initialized, using predefined black list on your own risk.
07:54:21.002 [DEBUG] [nding.zigbee.internal.ZigBeeDataStore] - 000D6F0017209191: ZigBee reading network state complete.
07:54:21.002 [DEBUG] [inding.zigbee.serial.ZigBeeSerialPort] - Connecting to serial port [/dev/cu.GoControl_zigbee] at 57600 baud, flow control FLOWCONTROL_OUT_XONOFF.
07:54:21.025 [DEBUG] [inding.zigbee.serial.ZigBeeSerialPort] - Serial port [/dev/cu.GoControl_zigbee] is initialized.
07:54:25.259 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Mesh Update Period 86400
07:54:25.276 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - ZigBee Initialise: Previous device configuration was: channel=CHANNEL_11, PanID=55679, EPanId=A81453E4716E7902
07:54:25.276 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Config: zigbee_trustcentremode=TC_JOIN_SECURE
07:54:25.545 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - ZigBee initialise done. channel=CHANNEL_11, PanId=55679  EPanId=A81453E4716E7902
07:54:25.557 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - null: networkStateUpdated called with state=ONLINE
07:54:25.813 [DEBUG] [nding.zigbee.internal.ZigBeeDataStore] - 000D6F0017209191: ZigBee saving network state complete.
07:54:28.095 [DEBUG] [nding.zigbee.internal.ZigBeeDataStore] - 000D6F0017209191: ZigBee saving network state complete.

Mjohannessen · September 7, 2021, 3:06pm

That is the bulb I have with the E26/24 base. I do not have any other ZigBee devices as this is a new project to expand to ZigBee (I have been using ZWave). I do have a few of these https://www.amazon.com/gp/product/B08V1937FT/ref=ppx_yo_dt_b_asin_title_o06_s00?ie=UTF8&psc=1 but they are not specifically Hue compatible and also don’t show up. I purchased the Nortek this year: https://www.amazon.com/gp/product/B0157GOEA8/ref=ppx_yo_dt_b_asin_title_o04_s00?ie=UTF8&psc=1 so I would think it has the latest firmware??

NilsOF · September 7, 2021, 4:10pm

The sticks I have seen is delivered with the firmware that matched in somehow in the production run.
So most likely old firmware…
You can see it the UI.

Mjohannessen · September 7, 2021, 6:48pm

I successfully upgraded the firmware from 5.4.1.0 to 6.7.8.0. I deleted the Zigbee binding and Ember thing, added the Zigbee binding and did a search for the bulb - still no luck:

11:38:28.484 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - Starting ZigBeeDiscoveryService
11:40:18.091 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Initializing ZigBee network [zigbee:coordinator_ember:ae4af677b6].
11:40:18.091 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Channel 0
11:40:18.091 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - PANID 0
11:40:18.092 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - EPANID 0000000000000000
11:40:18.092 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Network Key 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
11:40:18.092 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Link Key 5A 69 67 42 65 65 41 6C 6C 69 61 6E 63 65 30 39
11:40:18.093 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Config: zigbee_initialise found, initializeNetwork=false
11:40:18.093 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - ExtendedPanId or PanId not set: initializeNetwork=true
11:40:18.093 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Network Key String 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
11:40:18.093 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Network key initialised 3BF80B9994BCC00B6E32E67A20A3B6F2
11:40:18.093 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Network key final array 3BF80B9994BCC00B6E32E67A20A3B6F2
11:40:18.093 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Link Key String 5A 69 67 42 65 65 41 6C 6C 69 61 6E 63 65 30 39
11:40:18.094 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Initialising network
11:40:18.094 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Channel set to 11.
11:40:18.097 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Created random ZigBee PAN ID [5230].
11:40:18.097 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Created random ZigBee extended PAN ID [6D748EFEAEFCBA5C].
11:40:18.098 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Link key final array 5A6967426565416C6C69616E63653039
11:40:18.099 [DEBUG] [ing.zigbee.ember.handler.EmberHandler] - Initializing ZigBee Ember serial bridge handler.
11:40:18.109 [DEBUG] [ing.zigbee.ember.handler.EmberHandler] - ZigBee Ember Coordinator opening Port:'/dev/tty.GoControl_zigbee' PAN:5230, EPAN:6D748EFEAEFCBA5C, Channel:11
11:40:18.109 [DEBUG] [ing.zigbee.ember.handler.EmberHandler] - Ember end device poll timeout set to (169 * 2^9) = 86528 seconds
11:40:18.111 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Scheduling ZigBee start
11:40:19.114 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - ZigBee network starting
11:40:19.115 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Initialising ZigBee coordinator
11:40:19.124 [DEBUG] [nding.zigbee.internal.ZigBeeDataStore] - Creating ZigBee persistence folder /Users/haussomogio/Documents/openhab-3.0.1/userdata/zigbee/zigbee_coordinator_ember_ae4af677b6/
11:40:19.125 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - null: networkStateUpdated called with state=INITIALISING
11:40:19.125 [DEBUG] [inding.zigbee.serial.ZigBeeSerialPort] - Connecting to serial port [/dev/tty.GoControl_zigbee] at 57600 baud, flow control FLOWCONTROL_OUT_XONOFF.
11:40:19.150 [DEBUG] [inding.zigbee.serial.ZigBeeSerialPort] - Serial port [/dev/tty.GoControl_zigbee] is initialized.
11:40:23.723 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Mesh Update Period 86400
11:40:23.743 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - ZigBee Initialise: Previous device configuration was: channel=CHANNEL_11, PanID=65535, EPanId=A81453E4716E7902
11:40:23.743 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Link key initialise 5A6967426565416C6C69616E63653039
11:40:23.743 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Network key initialise 3BF80B9994BCC00B6E32E67A20A3B6F2
11:40:23.743 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Config: zigbee_trustcentremode=TC_JOIN_SECURE
11:40:27.054 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - ZigBee initialise done. channel=CHANNEL_11, PanId=21040  EPanId=6D748EFEAEFCBA5C
11:40:27.067 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - null: networkStateUpdated called with state=ONLINE
11:40:27.539 [DEBUG] [nding.zigbee.internal.ZigBeeDataStore] - 000D6F0017209191: ZigBee saving network state complete.
11:41:00.462 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - Starting ZigBee scan for zigbee:coordinator_ember:ae4af677b6

chris · September 7, 2021, 7:41pm

Thanks. I just wanted to check that you hadn’t changed the link key - it’s well known so there’s no need to obscure it and if you change it, devices will not be able to join.

It would be interesting to see a full debug log during the discovery. I suspect it’s not being picked up by the coordinator for some reason, and probably the debug log won’t provide a lot more information, but it will allow me to confirm that the issue is somewhere in the network communications in which case the only way to see more is with a sniffer.

This firmware should be good - it’s reasonably recent so will work with ZB3.0 devices. However this was clearly not the issue as even such devices will join, so you will see them in the inbox - they just won’t work afterwards with old firmware.

Mjohannessen · September 7, 2021, 9:04pm

This is the full DEBUG after trying to add a thing using the ZigBee binding:

13:56:35.345 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - Starting ZigBee scan for zigbee:coordinator_ember:ae4af677b6

That’s it. No things discovered.

chris · September 7, 2021, 9:05pm

Please can you enable debugging as described in the binding docs - there is a lot more available. Again, it may not help - I suspect the issue is with the devices, but it is still best to have all the debug so I can confirm this.

Mjohannessen · September 8, 2021, 12:05am

I set the logging as follows:

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

Here is the log (openhab> log:tail):

16:57:27.447 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - Starting ZigBee scan for zigbee:coordinator_ember:ae4af677b6
16:57:27.447 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - Permit join to FFFC/0 for 60 seconds.
16:57:27.448 [DEBUG] [ee.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]]
16:57:27.448 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
16:57:27.448 [DEBUG] [.transaction.ZigBeeTransactionManager] - FFFC/0: Sending ZigBeeTransaction [ieeeAddress=null queueTime=0, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=13, permitDuration=60, tcSignificance=true]]
16:57:27.448 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
16:57:27.448 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=13, permitDuration=60, tcSignificance=true]
16:57:27.449 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=FFFC/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=13, rssi=--, lqi=--, payload=13 3C 01]
16:57:27.449 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 000D6F0017209191: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=000D6F0017209191 queueTime=0, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true]]
16:57:27.449 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3
16:57:27.449 [DEBUG] [.transaction.ZigBeeTransactionManager] - 0000/0: Sending ZigBeeTransaction [ieeeAddress=000D6F0017209191 queueTime=0, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=14, permitDuration=60, tcSignificance=true]]
16:57:27.450 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
16:57:27.450 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=14, permitDuration=60, tcSignificance=true]
16:57:27.450 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=14, rssi=--, lqi=--, payload=14 3C 01]
16:57:27.462 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendBroadcastResponse [networkId=0, status=EMBER_SUCCESS, sequence=0C]
16:57:27.483 [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=0C], lastHopLqi=255, lastHopRssi=0, sender=0000, bindingIndex=255, addressIndex=255, messageContents=13 3C 01]
16:57:27.504 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=0D]
16:57:27.504 [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_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=0D], lastHopLqi=255, lastHopRssi=0, sender=0000, bindingIndex=255, addressIndex=255, messageContents=14 3C 01]
16:57:27.504 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=0D, rssi=0, lqi=FF, payload=14 3C 01]
16:57:27.505 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=14, permitDuration=60, tcSignificance=true]
16:57:27.505 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=14, permitDuration=60, tcSignificance=true] 
16:57:27.528 [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_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=0E], lastHopLqi=255, lastHopRssi=0, sender=0000, bindingIndex=255, addressIndex=255, messageContents=14 80]
16:57:27.529 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=8036, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=0E, rssi=0, lqi=FF, payload=14 80]
16:57:27.529 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningResponse [0000/0 -> 0000/0, cluster=8036, TID=14, status=INV_REQUESTTYPE]
16:57:27.529 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0000/0 -> 0000/0, cluster=8036, TID=14, status=INV_REQUESTTYPE] 
16:57:27.530 [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_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=0D], messageTag=14, status=EMBER_SUCCESS, messageContents=]
16:57:27.530 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=14 state=RX_ACK
16:57:27.530 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=14, state=RX_ACK, outstanding=2
16:57:27.532 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=000D6F0017209191 queueTime=83, state=COMPLETE, sendCnt=1, command=ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=14, permitDuration=60, tcSignificance=true]]
16:57:27.532 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
16:57:27.532 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 000D6F0017209191: transactionComplete, state=COMPLETE, outstanding=0
16:57:27.532 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=0, sleepy=0/3
16:57:27.532 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=0000, TID=14, event=RX_ACK, state=COMPLETE
16:57:28.451 [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=0C], messageTag=13, status=EMBER_DELIVERY_FAILED, messageContents=]
16:57:28.452 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=13 state=RX_NAK
16:57:28.452 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=13, state=RX_NAK, outstanding=1
16:57:28.453 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=null queueTime=1005, state=FAILED, sendCnt=1, command=ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=13, permitDuration=60, tcSignificance=true]]
16:57:28.453 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
16:57:28.453 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete, state=FAILED, outstanding=0
16:57:28.453 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete exceeded max retries 1
16:57:28.453 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction cancelled: ZigBeeTransaction [ieeeAddress=null queueTime=1005, state=CANCELLED, sendCnt=1, command=ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=13, permitDuration=60, tcSignificance=true]]
16:57:28.453 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=null queueTime=1005, state=CANCELLED, sendCnt=1, command=ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=13, permitDuration=60, tcSignificance=true]]
16:57:28.454 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
16:57:28.454 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete but not outstanding, state=CANCELLED, outstanding=0
16:57:28.454 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=0, sleepy=0/3
16:57:28.454 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=0, sleepy=0/3
16:57:28.454 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=FFFC, TID=13, event=RX_NAK, state=CANCELLED

Question: The binding docs say that “ZigBee 3.0 requires that devices use an install code to securely join the network. This must be added to the binding before the discovery starts. Install codes should be printed on the box the device came in, or possibly on the device itself. … The install code must be entered into the coordinator settings before starting the discovery process.”

I do not have the box for the Nortek and there is no install code on the device, nor is there an install code on the bulb, or the box for the bulb.

chris · September 8, 2021, 1:03am

Thanks - so this shows the binding going in to discovery mode. Are you then putting the device into discovery as well? (I assume so, but just checking).

If so, it seems the device simply isn’t communicating (as best as can be seen here). It could be a problem with one of the devices possibly - it’s impossible to tell further without a sniffer.

It is not applicable for the dongle - you don’t add the dongle to the network - the dongle is the trust centre / coordinator.

That’s fine - in most cases devices will use the standard link key - this is why I was asking earlier what this was. I have a few Innr bulbs here and they don’t require an install code.

Mjohannessen · September 8, 2021, 7:44pm

In terms of device discovery mode, from the information online using a Hue hub, the bulb needs just to be turned on for discovery. I have two of the Innr AE 280 C bulbs and neither can be discovered. The other “Smart LED Bulb” can be reinitialized by switching it on and off 6 times, and then flashes like its discoverable - and that fails. Any other suggestions?

chris · September 8, 2021, 7:51pm

That’s incorrect then. Yes, this MIGHT work, but it is NOT guaranteed. Anyway, why are you reading the Hue documentation? I thought you were using the Zigbee binding?

No - if you are resetting the bulb as described in the documentation, then I have no other ideas without seeing a sniffer log.

Mjohannessen · September 8, 2021, 8:00pm

I’ve looked other hints on how to get this to work by looking at Hue hub info, but am using the Zigbee binding. The Innr bulbs are supposed to be Hue compatible, but apparently not close enough for the Zigbee binding.

I would be interested investigating this with a sniffer. Any pointers on where to start with that?

chris · September 8, 2021, 8:04pm

The bulbs should be the same, but you MUST make sure that the bulbs have been reset or they will not join a network. If they are reset out of the box, then fine, but if they have ever been used and joined to any network, then you must reset them or they will not join another network. This is why it is simply safer to have them reset as part of the discovery process.

You can use a second HUSBZB-1 if you want. I have software to create a sniffer using Wireshark - see below -:

Mjohannessen · September 8, 2021, 10:03pm

Great, thanks Chris - I ordered another HUSBZB-1 and will try this out.

Mjohannessen · September 14, 2021, 10:25pm

I set up another HUSBZB-1, and using Wireshark and the ZigBee sniffer at:

https://github.com/zsmartsystems/com.zsmartsystems.zigbee.sniffer.

here’s what I have when the bulb is turned on (an Innr AE 280 C). Is this helpful?

chris · September 14, 2021, 11:04pm

The beacon requests are likely coming from the bulb, but there is nothing at all here from the coordinator. There should be responses to the beacon requests, but also when the coordinator is put into discovery mode it sends out a few request which will show up here as well.

So, possibly the coordinator is broken, or possibly it’s on a different channel - either way there is no communications between the device and coordinator.

Mjohannessen · September 15, 2021, 11:06pm

Does the OH3 ZigBee binding broadcast anything or is it a listener for ZigBee device broadcasts? The reason I ask is that I have set up the binding in OH3 (Ember EM35x Coordinator), which appears to be ONLINE and running on Channel 11. When I turn on the Innr light it broadcasts on Channel 11 as reflected in Wireshark. Now when I try to add a Thing using the ZigBee binding by scanning, I do not see any activity in Wireshark. However, in a terminal window using ZigBeeSniffer.jar I get this chatter which looks like its from the dongle:

No NCP data received for 30 seconds. Restarting NCP!
NCP shutting down...
DEBUG  15:53:07.195  TX EZSP: EzspMfglibEndRequest []
DEBUG  15:53:07.195  ASH: TX EZSP queue size: 1
DEBUG  15:53:07.195  --> TX ASH frame: AshFrameData [frmNum=5, ackNum=5, reTx=false, data=4E 00 01 84 00]
DEBUG  15:53:07.200  <-- RX ASH frame: AshFrameData [frmNum=5, ackNum=6, reTx=false, data=4E 80 01 84 00 00]
DEBUG  15:53:07.200  ASH: Frame acked and removed AshFrameData [frmNum=5, ackNum=5, reTx=false, data=4E 00 01 84 00]
DEBUG  15:53:07.201  RX EZSP: EzspMfglibEndResponse [networkId=0, status=EMBER_SUCCESS]
DEBUG  15:53:07.201  --> TX ASH frame: AshFrameAck [ackNum=6, notRdy=false]
DEBUG  15:53:07.201  EzspMfglibEndResponse [networkId=0, status=EMBER_SUCCESS]
DEBUG  15:53:07.201  EZSP Dongle: Shutdown
DEBUG  15:53:07.201  AshFrameHandler close.
DEBUG  15:53:07.201  Ember: Link State change to false, initialised=false, networkStateUp=false
DEBUG  15:53:07.201  Ember: Link State change to false ignored.
DEBUG  15:53:07.201  AshFrameHandler exited.
DEBUG  15:53:07.201  AshFrameHandler close complete.
INFO   15:53:07.206  Serial port '/dev/cu.GoControl_zigbee6' closed.
NCP initialisation starting...
Opened serial port /dev/cu.GoControl_zigbee6 at 57600
DEBUG  15:53:07.207  Opening port /dev/cu.GoControl_zigbee6 at 57600 baud with FLOWCONTROL_OUT_XONOFF.
DEBUG  15:53:07.216  ASH: Connect
DEBUG  15:53:07.216  ASH: Reconnect
DEBUG  15:53:07.216  AshFrameHandler thread started
DEBUG  15:53:07.216  --> TX ASH frame: AshFrameRst []
DEBUG  15:53:07.216  TX EZSP: EzspVersionRequest [networkId=0, desiredProtocolVersion=8]
DEBUG  15:53:07.216  ASH: TX EZSP queue size: 1
DEBUG  15:53:08.637  <-- RX ASH frame: AshFrameRstAck [version=2, resetCode=11, Reset: Software]
DEBUG  15:53:09.890  ASH: Connected
DEBUG  15:53:09.890  Ember: Link State change to true, initialised=false, networkStateUp=false
DEBUG  15:53:09.890  Ember: Link State change to true ignored.
DEBUG  15:53:09.890  --> TX ASH frame: AshFrameData [frmNum=0, ackNum=0, reTx=false, data=4F 00 01 00 00 08]
DEBUG  15:53:09.898  <-- RX ASH frame: AshFrameData [frmNum=0, ackNum=1, reTx=false, data=4F 80 01 00 00 08 02 80 67]
DEBUG  15:53:09.898  ASH: Frame acked and removed AshFrameData [frmNum=0, ackNum=0, reTx=false, data=4F 00 01 00 00 08]
DEBUG  15:53:09.898  RX EZSP: EzspVersionResponse [networkId=0, protocolVersion=8, stackType=2, stackVersion=6780]
DEBUG  15:53:09.898  --> TX ASH frame: AshFrameAck [ackNum=1, notRdy=false]
DEBUG  15:53:09.898  EzspVersionResponse [networkId=0, protocolVersion=8, stackType=2, stackVersion=6780]
DEBUG  15:53:09.898  TX EZSP: EzspGetStandaloneBootloaderVersionPlatMicroPhyRequest []
DEBUG  15:53:09.898  ASH: TX EZSP queue size: 1
DEBUG  15:53:09.898  --> TX ASH frame: AshFrameData [frmNum=1, ackNum=1, reTx=false, data=50 00 01 91 00]
DEBUG  15:53:09.904  <-- RX ASH frame: AshFrameData [frmNum=1, ackNum=2, reTx=false, data=50 80 01 91 00 10 54 04 0A 03]
DEBUG  15:53:09.905  ASH: Frame acked and removed AshFrameData [frmNum=1, ackNum=1, reTx=false, data=50 00 01 91 00]
DEBUG  15:53:09.905  RX EZSP: EzspGetStandaloneBootloaderVersionPlatMicroPhyResponse [networkId=0, bootloaderVersion=5410, nodePlat=4, nodeMicro=10, nodePhy=3]
DEBUG  15:53:09.905  --> TX ASH frame: AshFrameAck [ackNum=2, notRdy=false]
Ember NCP version     : 6.7.8.0
DEBUG  15:53:09.905  TX EZSP: EzspGetEui64Request []
DEBUG  15:53:09.905  ASH: TX EZSP queue size: 1
DEBUG  15:53:09.905  --> TX ASH frame: AshFrameData [frmNum=2, ackNum=2, reTx=false, data=51 00 01 26 00]
DEBUG  15:53:09.913  <-- RX ASH frame: AshFrameData [frmNum=2, ackNum=3, reTx=false, data=51 80 01 26 00 91 91 20 17 00 6F 0D 00]
DEBUG  15:53:09.913  ASH: Frame acked and removed AshFrameData [frmNum=2, ackNum=2, reTx=false, data=51 00 01 26 00]
DEBUG  15:53:09.913  RX EZSP: EzspGetEui64Response [networkId=0, eui64=000D6F0017209191]
DEBUG  15:53:09.913  --> TX ASH frame: AshFrameAck [ackNum=3, notRdy=false]
Ember NCP EUI         : 000D6F0017209191
DEBUG  15:53:09.913  TX EZSP: EzspMfglibStartRequest [networkId=0, rxCallback=true]
DEBUG  15:53:09.913  ASH: TX EZSP queue size: 1
DEBUG  15:53:09.914  --> TX ASH frame: AshFrameData [frmNum=3, ackNum=3, reTx=false, data=52 00 01 83 00 01]
DEBUG  15:53:09.920  <-- RX ASH frame: AshFrameData [frmNum=3, ackNum=4, reTx=false, data=52 80 01 83 00 00]
DEBUG  15:53:09.920  ASH: Frame acked and removed AshFrameData [frmNum=3, ackNum=3, reTx=false, data=52 00 01 83 00 01]
DEBUG  15:53:09.920  RX EZSP: EzspMfglibStartResponse [networkId=0, status=EMBER_SUCCESS]
DEBUG  15:53:09.920  --> TX ASH frame: AshFrameAck [ackNum=4, notRdy=false]
DEBUG  15:53:09.920  EzspMfglibStartResponse [networkId=0, status=EMBER_SUCCESS]
DEBUG  15:53:09.920  TX EZSP: EzspMfglibSetChannelRequest [networkId=0, channel=11]
DEBUG  15:53:09.920  ASH: TX EZSP queue size: 1
DEBUG  15:53:09.920  --> TX ASH frame: AshFrameData [frmNum=4, ackNum=4, reTx=false, data=53 00 01 8A 00 0B]
DEBUG  15:53:09.927  <-- RX ASH frame: AshFrameData [frmNum=4, ackNum=5, reTx=false, data=53 80 01 8A 00 00]
DEBUG  15:53:09.927  ASH: Frame acked and removed AshFrameData [frmNum=4, ackNum=4, reTx=false, data=53 00 01 8A 00 0B]
DEBUG  15:53:09.927  RX EZSP: EzspMfglibSetChannelResponse [networkId=0, status=EMBER_SUCCESS]
DEBUG  15:53:09.927  --> TX ASH frame: AshFrameAck [ackNum=5, notRdy=false]
DEBUG  15:53:09.927  EzspMfglibSetChannelResponse [networkId=0, status=EMBER_SUCCESS]
NCP initialisation complete...
Wireshark destination : /127.0.0.1:17754
Logging on channel    : 11
No device ID set. Last 16 bits of device EUID will be used.

I have the sniffer dongle on another Mac than the OH3 Mac.

Is the dongle not communicating with the ZigBee binding?