Zigbee binding

chris · December 19, 2017, 2:35pm

I don’t think we ever actually caught the exception AND the log leading up to it did we? I looked back through some of your logs posted in this ticket last night and couldn’t find anything. At the time I added protection around the error and this one looks slightly different than the previous one so I’d like to see the full discovery of the node causing the problem.

5iver · December 19, 2017, 6:15pm

You’re right… this is the SimpleDescriptorResponse NPE! We never had logs for this one. I logged one this morning and have put it into the ticket.

chris · December 19, 2017, 6:17pm

Thanks.

TheNetStriker · December 21, 2017, 12:08am

@chris I still got the CEL MeshConnect ZigBee usb sticks. Did you manage to get them working and do you have new firmware for those usb sticks that works with the 2.2 version of the ZigBee binding?

chris · December 21, 2017, 12:34am

These sticks should work (it’s the same as the other Ember devices people are using). It should work with all firmware up to 5.8 - after than Silabs have made some changes and I’m not fully implemented the new protocol yet.

Sometimes with these sticks the device doesn’t initialise - this is what we saw with your stick in the past. Normally it will sort its self out - I spent some time working with Silabs to try and resolve this, but as it’s intermittent, it’s not easy to find and Silabs were not able to provide much insight. It’s something I need to look at again in the new year.

TheNetStriker · December 21, 2017, 1:45pm

Thanks, I will try again if it works better than with the last version. The reason why I would want to try this again is that I have some annoying problems with the Hue binding since the OH 2.2 update which I described here: Hue bridge and lamps offline after OH 2.2 update

Maybe you could also take a look at this thread or tell me which person I could ask regarding the Hue binding.

AFromD · December 22, 2017, 12:48pm

I am having problems with my Ember dongle. After some time it just stops working, although OH acts like everything is OK. So one minute, all devices work as expected, the next minute everything stops reacting. When I command something through Alexa, it responds “ok” and commands are being executed in the paper UI. However, nothing is effected on the Zigbee devices. All my things show as “online”.

I have tried restarting OH, and rebooting the Windows 10 PC. Sometimes this restores it to working order, but it will always drop out again over time.

I have activated debug logging, here is a piece. Last part shows my trying to change color on Hue lamps. But also my motion sensor and Osram socket is not reacting or updating.

[type=EMBER_OUTGOING_DIRECT, indexOrDestination=29299, apsFrame=EmberApsFrame [profileId=0, clusterId=50, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=146], messageTag=59, status=EMBER_SUCCESS, messageContents=]
2017-12-22 13:41:07.171 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=4]
2017-12-22 13:41:07.176 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - Sent queue larger than window [1 > 1].
2017-12-22 13:41:07.182 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=4, ackNum=6, reTx=false, data=3B 90 45 00 00 00 32 80 00 00 40 01 00 00 D4 FF B3 73 72 FF FF 0F 00 00 02 00 02 00 00 00 00 00 AB 6C 00 AB 6C]
2017-12-22 13:41:07.184 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=32818, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=212], lastHopLqi=255, lastHopRssi=-77, sender=29299, bindingIndex=255, addressIndex=255, messageContents=00 00 02 00 02 00 00 00 00 00 AB 6C 00 AB 6C]
2017-12-22 13:41:07.186 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=32818, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=212], lastHopLqi=255, lastHopRssi=-77, sender=29299, bindingIndex=255, addressIndex=255, messageContents=00 00 02 00 02 00 00 00 00 00 AB 6C 00 AB 6C]
2017-12-22 13:41:07.188 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=29299/0, destinationAddress=0/0, profile=0000, cluster=32818, addressMode=null, radius=0, sequence=59, payload=00 00 02 00 02 00 00 00 00 00 AB 6C 00 AB 6C]
2017-12-22 13:41:07.190 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementRoutingResponse [29299/0 -> 0/0, cluster=8032, TID=NULL, status=SUCCESS, routingTableEntries=2, startIndex=0, routingTableListCount=2, routingTableList=[RoutingTable [destinationAddress=0, status=ACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=27819, status=ACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=27819]]]
2017-12-22 13:41:07.192 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=5]
2017-12-22 13:41:07.193 [DEBUG] [tems.zigbee.ZigBeeNetworkMeshMonitor] - 29299: Ending mesh update
2017-12-22 13:41:07.196 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - Sent queue larger than window [1 > 1].
2017-12-22 13:41:07.198 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameNak [ackNum=6]
2017-12-22 13:41:07.200 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=6, ackNum=5, reTx=true, data=3C 00 34 00 92 B0 00 00 01 00 00 00 40 11 00 00 3C 3C 05 00 92 B0 01 00]
2017-12-22 13:41:07.210 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - Sent queue larger than window [1 > 1].
2017-12-22 13:41:07.322 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameAck [ackNum=7]
2017-12-22 13:41:07.324 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=5, ackNum=7, reTx=false, data=3C 80 34 00 93]
2017-12-22 13:41:07.326 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=147]
2017-12-22 13:41:07.327 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=147]
2017-12-22 13:41:07.328 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=147]
2017-12-22 13:41:07.329 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=6]
2017-12-22 13:41:12.130 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=6, ackNum=7, reTx=false, data=3C 90 3F 00 92 B0 00 00 01 00 00 00 40 11 00 00 93 3C 66 00]
2017-12-22 13:41:12.132 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=45202, apsFrame=EmberApsFrame [profileId=0, clusterId=1, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=147], messageTag=60, status=EMBER_DELIVERY_FAILED, messageContents=]
2017-12-22 13:41:12.134 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=45202, apsFrame=EmberApsFrame [profileId=0, clusterId=1, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=147], messageTag=60, status=EMBER_DELIVERY_FAILED, messageContents=]
2017-12-22 13:41:12.135 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=45202, apsFrame=EmberApsFrame [profileId=0, clusterId=1, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=147], messageTag=60, status=EMBER_DELIVERY_FAILED, messageContents=]
2017-12-22 13:41:12.136 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=7]
2017-12-22 13:41:16.271 [DEBUG] [bee.internal.ZigBeeNetworkDiscoverer] - 45202: Discovery request IEEE_ADDRESS failed. Wait before retry.
2017-12-22 13:41:17.773 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: IeeeAddressRequest [0/0 -> 45202/0, cluster=0001, TID=3D, nwkAddrOfInterest=45202, requestType=1, startIndex=0]
2017-12-22 13:41:17.776 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=45202/0, profile=0000, cluster=1, addressMode=DEVICE, radius=31, sequence=61, payload=00 92 B0 01 00]
2017-12-22 13:41:17.778 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EzspSendUnicastRequest [type=EMBER_OUTGOING_DIRECT, indexOrDestination=45202, apsFrame=EmberApsFrame [profileId=0, clusterId=1, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=61], messageTag=61, messageContents=00 92 B0 01 00]
2017-12-22 13:41:17.780 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - TX EZSP queue: 12
2017-12-22 13:41:17.782 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - TX EZSP: EzspSendUnicastRequest [type=EMBER_OUTGOING_DIRECT, indexOrDestination=45202, apsFrame=EmberApsFrame [profileId=0, clusterId=1, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=61], messageTag=61, messageContents=00 92 B0 01 00]
2017-12-22 13:41:17.785 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=7, ackNum=7, reTx=false, data=3D 00 34 00 92 B0 00 00 01 00 00 00 40 11 00 00 3D 3D 05 00 92 B0 01 00]
2017-12-22 13:41:17.913 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=7, ackNum=0, reTx=false, data=3D 80 34 00 94]
2017-12-22 13:41:17.916 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=148]
2017-12-22 13:41:17.918 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=148]
2017-12-22 13:41:17.919 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=148]
2017-12-22 13:41:17.920 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=0]
2017-12-22 13:41:19.570 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=0, ackNum=0, reTx=false, data=3D 90 45 00 04 01 06 00 03 01 00 00 00 00 C2 FF A9 7E 04 FF FF 07 18 83 0A 00 00 10 00]
2017-12-22 13:41:19.573 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=260, clusterId=6, sourceEndpoint=3, destinationEndpoint=1, options=[], groupId=0, sequence=194], lastHopLqi=255, lastHopRssi=-87, sender=1150, bindingIndex=255, addressIndex=255, messageContents=18 83 0A 00 00 10 00]
2017-12-22 13:41:19.574 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=260, clusterId=6, sourceEndpoint=3, destinationEndpoint=1, options=[], groupId=0, sequence=194], lastHopLqi=255, lastHopRssi=-87, sender=1150, bindingIndex=255, addressIndex=255, messageContents=18 83 0A 00 00 10 00]
2017-12-22 13:41:19.576 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=1150/3, destinationAddress=0/1, profile=0104, cluster=6, addressMode=null, radius=0, sequence=61, payload=18 83 0A 00 00 10 00]
2017-12-22 13:41:19.578 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=131, commandId=10]
2017-12-22 13:41:19.581 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReportAttributesCommand [On/Off: 1150/3 -> 0/1, cluster=0006, TID=83, reports=[Attribute Report: attributeDataType=BOOLEAN, attributeIdentifier=0, attributeValue=false]]
2017-12-22 13:41:19.591 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=1]
2017-12-22 13:41:22.618 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=1, ackNum=0, reTx=false, data=3D 90 3F 00 92 B0 00 00 01 00 00 00 40 11 00 00 94 3D 66 00]
2017-12-22 13:41:22.620 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=45202, apsFrame=EmberApsFrame [profileId=0, clusterId=1, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=148], messageTag=61, status=EMBER_DELIVERY_FAILED, messageContents=]
2017-12-22 13:41:22.622 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=45202, apsFrame=EmberApsFrame [profileId=0, clusterId=1, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=148], messageTag=61, status=EMBER_DELIVERY_FAILED, messageContents=]
2017-12-22 13:41:22.623 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=45202, apsFrame=EmberApsFrame [profileId=0, clusterId=1, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=148], messageTag=61, status=EMBER_DELIVERY_FAILED, messageContents=]
2017-12-22 13:41:22.624 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=2]
2017-12-22 13:41:22.854 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=2, ackNum=0, reTx=false, data=3D 90 45 04 00 00 06 00 00 00 08 00 00 00 A9 FF A9 E3 EF FF FF 09 DF FD FF 04 01 01 19 00 00]
2017-12-22 13:41:22.856 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_BROADCAST, apsFrame=EmberApsFrame [profileId=0, clusterId=6, sourceEndpoint=0, destinationEndpoint=0, options=[], groupId=0, sequence=169], lastHopLqi=255, lastHopRssi=-87, sender=61411, bindingIndex=255, addressIndex=255, messageContents=DF FD FF 04 01 01 19 00 00]
2017-12-22 13:41:22.858 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingMessageHandler [type=EMBER_INCOMING_BROADCAST, apsFrame=EmberApsFrame [profileId=0, clusterId=6, sourceEndpoint=0, destinationEndpoint=0, options=[], groupId=0, sequence=169], lastHopLqi=255, lastHopRssi=-87, sender=61411, bindingIndex=255, addressIndex=255, messageContents=DF FD FF 04 01 01 19 00 00]
2017-12-22 13:41:22.861 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=61411/0, destinationAddress=0/0, profile=0000, cluster=6, addressMode=null, radius=0, sequence=61, payload=DF FD FF 04 01 01 19 00 00]
2017-12-22 13:41:22.864 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: MatchDescriptorRequest [61411/0 -> 0/0, cluster=0006, TID=NULL, nwkAddrOfInterest=65533, profileId=260, inClusterCount=1, inClusterList=[25], outClusterCount=0, outClusterList=[]]
2017-12-22 13:41:22.866 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=3]
2017-12-22 13:41:27.805 [DEBUG] [bee.internal.ZigBeeNetworkDiscoverer] - 45202: Discovery request IEEE_ADDRESS failed. Wait before retry.
2017-12-22 13:41:29.307 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: IeeeAddressRequest [0/0 -> 45202/0, cluster=0001, TID=3E, nwkAddrOfInterest=45202, requestType=1, startIndex=0]
2017-12-22 13:41:29.310 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=45202/0, profile=0000, cluster=1, addressMode=DEVICE, radius=31, sequence=62, payload=00 92 B0 01 00]
2017-12-22 13:41:29.315 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EzspSendUnicastRequest [type=EMBER_OUTGOING_DIRECT, indexOrDestination=45202, apsFrame=EmberApsFrame [profileId=0, clusterId=1, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=62], messageTag=62, messageContents=00 92 B0 01 00]
2017-12-22 13:41:29.316 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - TX EZSP queue: 12
2017-12-22 13:41:29.319 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - TX EZSP: EzspSendUnicastRequest [type=EMBER_OUTGOING_DIRECT, indexOrDestination=45202, apsFrame=EmberApsFrame [profileId=0, clusterId=1, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=62], messageTag=62, messageContents=00 92 B0 01 00]
2017-12-22 13:41:29.322 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=0, ackNum=3, reTx=false, data=3E 00 34 00 92 B0 00 00 01 00 00 00 40 11 00 00 3E 3E 05 00 92 B0 01 00]
2017-12-22 13:41:29.446 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=3, ackNum=1, reTx=false, data=3E 80 34 00 95]
2017-12-22 13:41:29.447 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=149]
2017-12-22 13:41:29.450 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=149]
2017-12-22 13:41:29.451 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=149]
2017-12-22 13:41:29.452 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=4]
2017-12-22 13:41:34.255 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=4, ackNum=1, reTx=false, data=3E 90 3F 00 92 B0 00 00 01 00 00 00 40 11 00 00 95 3E 66 00]
2017-12-22 13:41:34.260 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=45202, apsFrame=EmberApsFrame [profileId=0, clusterId=1, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=149], messageTag=62, status=EMBER_DELIVERY_FAILED, messageContents=]
2017-12-22 13:41:34.263 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=45202, apsFrame=EmberApsFrame [profileId=0, clusterId=1, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=149], messageTag=62, status=EMBER_DELIVERY_FAILED, messageContents=]
2017-12-22 13:41:34.265 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=45202, apsFrame=EmberApsFrame [profileId=0, clusterId=1, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=149], messageTag=62, status=EMBER_DELIVERY_FAILED, messageContents=]
2017-12-22 13:41:34.266 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=5]
2017-12-22 13:41:39.339 [DEBUG] [bee.internal.ZigBeeNetworkDiscoverer] - 45202: Discovery request IEEE_ADDRESS failed. Wait before retry.
2017-12-22 13:41:40.844 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: IeeeAddressRequest [0/0 -> 45202/0, cluster=0001, TID=3F, nwkAddrOfInterest=45202, requestType=1, startIndex=0]
2017-12-22 13:41:40.847 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=45202/0, profile=0000, cluster=1, addressMode=DEVICE, radius=31, sequence=63, payload=00 92 B0 01 00]
2017-12-22 13:41:40.850 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EzspSendUnicastRequest [type=EMBER_OUTGOING_DIRECT, indexOrDestination=45202, apsFrame=EmberApsFrame [profileId=0, clusterId=1, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=63], messageTag=63, messageContents=00 92 B0 01 00]
2017-12-22 13:41:40.890 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - TX EZSP queue: 12
2017-12-22 13:41:40.891 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - TX EZSP: EzspSendUnicastRequest [type=EMBER_OUTGOING_DIRECT, indexOrDestination=45202, apsFrame=EmberApsFrame [profileId=0, clusterId=1, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=63], messageTag=63, messageContents=00 92 B0 01 00]
2017-12-22 13:41:40.892 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=1, ackNum=5, reTx=false, data=3F 00 34 00 92 B0 00 00 01 00 00 00 40 11 00 00 3F 3F 05 00 92 B0 01 00]
2017-12-22 13:41:41.008 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=5, ackNum=2, reTx=false, data=3F 80 34 00 96]
2017-12-22 13:41:41.010 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=150]
2017-12-22 13:41:41.012 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=150]
2017-12-22 13:41:41.013 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=150]
2017-12-22 13:41:41.015 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=6]
2017-12-22 13:41:45.817 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=6, ackNum=2, reTx=false, data=3F 90 3F 00 92 B0 00 00 01 00 00 00 40 11 00 00 96 3F 66 00]
2017-12-22 13:41:45.820 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=45202, apsFrame=EmberApsFrame [profileId=0, clusterId=1, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=150], messageTag=63, status=EMBER_DELIVERY_FAILED, messageContents=]
2017-12-22 13:41:45.822 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=45202, apsFrame=EmberApsFrame [profileId=0, clusterId=1, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=150], messageTag=63, status=EMBER_DELIVERY_FAILED, messageContents=]
2017-12-22 13:41:45.823 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=45202, apsFrame=EmberApsFrame [profileId=0, clusterId=1, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=150], messageTag=63, status=EMBER_DELIVERY_FAILED, messageContents=]
2017-12-22 13:41:45.825 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=7]
2017-12-22 13:41:50.898 [DEBUG] [bee.internal.ZigBeeNetworkDiscoverer] - 45202: Discovery request IEEE_ADDRESS failed. Wait before retry.
2017-12-22 13:41:52.401 [DEBUG] [bee.internal.ZigBeeNetworkDiscoverer] - 45202: Ending node discovery
2017-12-22 13:42:03.368 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=7, ackNum=2, reTx=false, data=3F 90 45 00 04 01 02 04 02 01 00 01 00 00 AA FF AF E3 EF FF FF 08 08 30 0A 00 00 29 58 07]
2017-12-22 13:42:03.373 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=260, clusterId=1026, sourceEndpoint=2, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=170], lastHopLqi=255, lastHopRssi=-81, sender=61411, bindingIndex=255, addressIndex=255, messageContents=08 30 0A 00 00 29 58 07]
2017-12-22 13:42:03.375 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=260, clusterId=1026, sourceEndpoint=2, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=170], lastHopLqi=255, lastHopRssi=-81, sender=61411, bindingIndex=255, addressIndex=255, messageContents=08 30 0A 00 00 29 58 07]
2017-12-22 13:42:03.378 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=61411/2, destinationAddress=0/1, profile=0104, cluster=1026, addressMode=null, radius=0, sequence=63, payload=08 30 0A 00 00 29 58 07]
2017-12-22 13:42:03.379 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=48, commandId=10]
2017-12-22 13:42:03.382 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReportAttributesCommand [Temperature measurement: 61411/2 -> 0/1, cluster=0402, TID=30, reports=[Attribute Report: attributeDataType=SIGNED_16_BIT_INTEGER, attributeIdentifier=0, attributeValue=1880]]
2017-12-22 13:42:03.384 [DEBUG] [bee.dongle.ember.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=0]
2017-12-22 13:42:13.515 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 0017880102F1AE8C: Command for channel zigbee:device:3e5f29cf:0017880102f1ae8c:0017880102F1AE8C_11_color_color --> 0
2017-12-22 13:42:13.517 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - No handler found for zigbee:device:3e5f29cf:0017880102f1ae8c:0017880102F1AE8C_11_color_color
2017-12-22 13:42:13.518 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00178801021DC6C4: Command for channel zigbee:device:3e5f29cf:00178801021dc6c4:00178801021DC6C4_11_color_color --> 0
2017-12-22 13:42:13.519 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - No handler found for zigbee:device:3e5f29cf:00178801021dc6c4:00178801021DC6C4_11_color_color
2017-12-22 13:42:14.362 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 0017880102F1AE8C: Command for channel zigbee:device:3e5f29cf:0017880102f1ae8c:0017880102F1AE8C_11_color_color --> OFF
2017-12-22 13:42:14.363 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - No handler found for zigbee:device:3e5f29cf:0017880102f1ae8c:0017880102F1AE8C_11_color_color
2017-12-22 13:42:14.368 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00178801021DC6C4: Command for channel zigbee:device:3e5f29cf:00178801021dc6c4:00178801021DC6C4_11_color_color --> OFF
2017-12-22 13:42:14.369 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - No handler found for zigbee:device:3e5f29cf:00178801021dc6c4:00178801021DC6C4_11_color_color

weakfl · December 22, 2017, 2:41pm

@AFromD this is a known issue.

I’ve currently set a cron rule that restarts the binding every hour as a workaround until this gets fixed.

jj_hh · December 22, 2017, 4:07pm

hi,I am a newcomer in openhab. Now, I have the same trouble as yours，And It has troubled me for three days.I can’t find any good ways to solve.Can I ask you how to solve it? thank you very much.

TheNetStriker · December 24, 2017, 12:51pm

Hi jj, do you mean the problems with the Phillips Hue binding or with the ZigBee binding?

@chris: I did get the Ember stick with firmware 5.8 working with the 2.2 release of the Zigbee binding, but there are still some issues. These are the ones I encountered:

The channels inside a lamp do no update each other. (e.g. if I update the switch channel it does not automatically update the color and dimmer channel to zero or the actual color)
It takes a long time until all lamps are online. (there are 32 lamps in my setup)
The delay when switching a light is still still much bigger than with the hue binding. (about 1 second with the Hue binding and about 3 to 4 seconds with the Zigbee binding)
As you said the Ember stick does not always initialize on the first try. I had to restart the binding a few times.
I also found several errors in the log regarding discovery:

java.lang.NullPointerException: null
	at com.zsmartsystems.zigbee.internal.ZigBeeNetworkDiscoverer.updateEndpoint(ZigBeeNetworkDiscoverer.java:598) [254:org.openhab.binding.zigbee:2.2.0]
	at com.zsmartsystems.zigbee.internal.ZigBeeNetworkDiscoverer.getSimpleDescriptor(ZigBeeNetworkDiscoverer.java:565) [254:org.openhab.binding.zigbee:2.2.0]
	at com.zsmartsystems.zigbee.internal.ZigBeeNetworkDiscoverer.access$800(ZigBeeNetworkDiscoverer.java:61) [254:org.openhab.binding.zigbee:2.2.0]
	at com.zsmartsystems.zigbee.internal.ZigBeeNetworkDiscoverer$3.run(ZigBeeNetworkDiscoverer.java:340) [254:org.openhab.binding.zigbee:2.2.0]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
	at java.lang.Thread.run(Thread.java:748) [?:?]

Are some of these errors maybe already fixed in the latest snapshot of the binding?

chris · December 24, 2017, 1:48pm

Hi
Thee should not be any long delays in the binding unless there are timeouts. Please check the logs.

If lamps support reporting then they should update the binding if they are changed. However please remember there is a lot of development going on at the moment so for sure there will still be some issues. Maybe some devices are not responding well and this is causing both of these - it’s hard to say without seeing what is happening.

The NpE I’ve probably fixed but it’s not in the latest binding yet - I will resolve this when I get home from holiday in a few days.

TheNetStriker · December 24, 2017, 1:56pm

Hi Chris, I did not find any timeouts in the log. (with ERROR log level) Also I remember that I read somewhere that the official Hue lamps do not support reporting the status. I don’t know how exactly that works on the Hue binding.

chris · December 24, 2017, 2:19pm

Timeouts won’t be logged at error level - errors are meant for major system problems which I don’t thing a timeout like this is. So you will need to use debug I think.

I’ve not yet added polling - so if the device doesnt report then it probably won’t update. I’ll look at this when I get back from holiday in a few days.

jj_hh · December 25, 2017, 3:56pm

hi,David，Thanks for your reply，I’m mean the problem with the Zigbee binding ;
The log is same with yours

And the Zigbee always offline.

TheNetStriker · December 25, 2017, 4:28pm

No I ha da different error with the Ember stick and it was solved simply by restarting the binding a few times.

chris · December 25, 2017, 8:13pm

Is it possible for your to send me (maybe via email) a debug log during the binding initialisation so I can see what the Hue responds to for some of the messages. If it is rejecting the reporting command then I can use this to trigger polling automatically (I’ve added polling yesterday, although I need to test it when I get home before releasing this).

TheNetStriker · December 26, 2017, 1:11pm

Hi Chris, I just sent you an email containing the log from the initialization. I only commented out my network key, network id etc. Sadly I wasn’t able to create a log while toggle a light because for some reason the lights didn’t want to change to online this time. I hope you can figure out whats going on.

chris · December 26, 2017, 11:07pm

Got it - thanks.

chris · December 26, 2017, 11:26pm

Can you confirm that node 26 is one of the Hue devices?

TheNetStriker · December 27, 2017, 12:11am

I only have hue devices in my setup. Some are older ones, but most of them are newer ones that also support color temperature.