Ikea Tradfri bulbs not recognized since OH3 upgrade

Hi,

After I have migrated from OH2.5 to OH3, I decided to add my Zigbee coordinator via the new webinterface and remove the text-based one, as per the recommendation. As a consequence, I had to re-add all my Zigbee devices to the Zigbee network. So far I tried 3 different Ikea Tradfri bulbs, but none of them got recognized. They only appear as “Unknown Zigbee Device” in the inbox.

The documentation of the Zigbee Binding recommends turning on debug logging via de OpenHAB console. So I did, and I started a discovery session with one of the bulbs. I did factory reset the bulb by turning it on and off 6 times. Here’s the log:

2020-12-30 14:55:14.774 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 000D6FFFFE03C639: Discovery: Starting discovery for existing device

2020-12-30 14:55:14.788 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 000D6FFFFE03C639: Starting ZigBee device discovery

2020-12-30 14:55:14.795 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 000D6FFFFE03C639: Creating ZigBee device zigbee:device with bridge zigbee:coordinator_ember:a5254cef6e

2020-12-30 14:55:14.813 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 000D6FFFFE03C639: ZigBee node property discovery start

2020-12-30 14:55:14.821 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 000D6FFFFE03C639: ZigBee node property discovery using basic cluster on endpoint 0103/1

2020-12-30 14:55:14.865 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=--, identifiers=[5, 4, 3, 2, 6, 0, 1]]]

2020-12-30 14:55:14.870 [DEBUG] [transaction.ZigBeeTransactionManager] - 0103/1: Sending ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=5, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=9C, identifiers=[5, 4, 3, 2, 6, 0, 1]]]

2020-12-30 14:55:19.618 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=4753, state=FAILED, sendCnt=1, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=9C, identifiers=[5, 4, 3, 2, 6, 0, 1]]]

2020-12-30 14:55:19.623 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: transactionComplete, state=FAILED, outstanding=0

2020-12-30 14:55:19.625 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=4761, state=WAITING, sendCnt=1, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=9C, identifiers=[5, 4, 3, 2, 6, 0, 1]]]

2020-12-30 14:55:19.632 [DEBUG] [transaction.ZigBeeTransactionManager] - 0103/1: Sending ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=4767, state=WAITING, sendCnt=1, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=9C, identifiers=[5, 4, 3, 2, 6, 0, 1]]]

2020-12-30 14:55:24.357 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=9492, state=FAILED, sendCnt=2, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=9C, identifiers=[5, 4, 3, 2, 6, 0, 1]]]

2020-12-30 14:55:24.385 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: transactionComplete, state=FAILED, outstanding=0

2020-12-30 14:55:24.388 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: transactionComplete exceeded max retries 2

2020-12-30 14:55:24.392 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction cancelled: ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=9526, state=CANCELLED, sendCnt=2, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=9C, identifiers=[5, 4, 3, 2, 6, 0, 1]]]

2020-12-30 14:55:24.396 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=9531, state=CANCELLED, sendCnt=2, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=9C, identifiers=[5, 4, 3, 2, 6, 0, 1]]]

2020-12-30 14:55:24.400 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: transactionComplete but not outstanding, state=CANCELLED, outstanding=0

2020-12-30 14:55:24.451 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=--, identifiers=[4]]]

2020-12-30 14:55:24.456 [DEBUG] [transaction.ZigBeeTransactionManager] - 0103/1: Sending ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=4, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=A0, identifiers=[4]]]

2020-12-30 14:55:29.183 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=4731, state=FAILED, sendCnt=1, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=A0, identifiers=[4]]]

2020-12-30 14:55:29.187 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: transactionComplete, state=FAILED, outstanding=0

2020-12-30 14:55:29.190 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=4738, state=WAITING, sendCnt=1, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=A0, identifiers=[4]]]

2020-12-30 14:55:29.195 [DEBUG] [transaction.ZigBeeTransactionManager] - 0103/1: Sending ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=4743, state=WAITING, sendCnt=1, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=A0, identifiers=[4]]]

2020-12-30 14:55:33.951 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=9499, state=FAILED, sendCnt=2, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=A0, identifiers=[4]]]

2020-12-30 14:55:33.964 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: transactionComplete, state=FAILED, outstanding=0

2020-12-30 14:55:33.966 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: transactionComplete exceeded max retries 2

2020-12-30 14:55:33.969 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction cancelled: ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=9517, state=CANCELLED, sendCnt=2, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=A0, identifiers=[4]]]

2020-12-30 14:55:33.971 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 000D6FFFFE03C639: Manufacturer request failed

2020-12-30 14:55:33.973 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=9520, state=CANCELLED, sendCnt=2, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=A0, identifiers=[4]]]

2020-12-30 14:55:33.980 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: transactionComplete but not outstanding, state=CANCELLED, outstanding=0

2020-12-30 14:55:33.988 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=--, identifiers=[5]]]

2020-12-30 14:55:33.993 [DEBUG] [transaction.ZigBeeTransactionManager] - 0103/1: Sending ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=6, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=A3, identifiers=[5]]]

2020-12-30 14:55:38.759 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=4767, state=FAILED, sendCnt=1, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=A3, identifiers=[5]]]

2020-12-30 14:55:38.767 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: transactionComplete, state=FAILED, outstanding=0

2020-12-30 14:55:38.772 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=4783, state=WAITING, sendCnt=1, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=A3, identifiers=[5]]]

2020-12-30 14:55:38.780 [DEBUG] [transaction.ZigBeeTransactionManager] - 0103/1: Sending ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=4792, state=WAITING, sendCnt=1, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=A3, identifiers=[5]]]

2020-12-30 14:55:43.522 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=9534, state=FAILED, sendCnt=2, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=A3, identifiers=[5]]]

2020-12-30 14:55:43.532 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: transactionComplete, state=FAILED, outstanding=0

2020-12-30 14:55:43.536 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: transactionComplete exceeded max retries 2

2020-12-30 14:55:43.541 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction cancelled: ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=9551, state=CANCELLED, sendCnt=2, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=A3, identifiers=[5]]]

2020-12-30 14:55:43.545 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 000D6FFFFE03C639: Model request failed

2020-12-30 14:55:43.549 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=9557, state=CANCELLED, sendCnt=2, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=A3, identifiers=[5]]]

2020-12-30 14:55:43.557 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: transactionComplete but not outstanding, state=CANCELLED, outstanding=0

2020-12-30 14:55:43.567 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=--, identifiers=[3]]]

2020-12-30 14:55:43.572 [DEBUG] [transaction.ZigBeeTransactionManager] - 0103/1: Sending ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=7, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=A6, identifiers=[3]]]

2020-12-30 14:55:46.279 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=0103, newNodeEui64=000D6FFFFE03C639, status=EMBER_STANDARD_SECURITY_UNSECURED_JOIN, policyDecision=EMBER_SEND_KEY_IN_THE_CLEAR, parentOfNewNodeId=0000]

2020-12-30 14:55:46.281 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 000D6FFFFE03C639: nodeStatusUpdate - node status is UNSECURED_JOIN, network address is 0103.

2020-12-30 14:55:46.284 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 000D6FFFFE03C639: Device status updated. NWK=0103

2020-12-30 14:55:46.288 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 000D6FFFFE03C639: NWK Discovery add node 0103

2020-12-30 14:55:46.290 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 000D6FFFFE03C639: Node state updated from UNKNOWN to ONLINE

2020-12-30 14:55:46.293 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 000D6FFFFE03C639: Updating node NWK=0103

2020-12-30 14:55:46.295 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 000D6FFFFE03C639: Node update. NWK Address=0103

2020-12-30 14:55:46.298 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 000D6FFFFE03C639: Node 0103 is not updated

2020-12-30 14:55:46.753 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=0103, sourceEui=000D6FFFFE03C639, lastHopLqi=255, lastHopRssi=-39, relayList=]

2020-12-30 14:55:53.579 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=10013, state=FAILED, sendCnt=1, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=A6, identifiers=[3]]]

2020-12-30 14:55:53.588 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: transactionComplete, state=FAILED, outstanding=0

2020-12-30 14:55:53.592 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=10026, state=WAITING, sendCnt=1, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=A6, identifiers=[3]]]

2020-12-30 14:55:53.598 [DEBUG] [transaction.ZigBeeTransactionManager] - 0103/1: Sending ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=10032, state=WAITING, sendCnt=1, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=A6, identifiers=[3]]]

2020-12-30 14:55:58.323 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=14757, state=FAILED, sendCnt=2, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=A6, identifiers=[3]]]

2020-12-30 14:55:58.331 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: transactionComplete, state=FAILED, outstanding=0

2020-12-30 14:55:58.333 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: transactionComplete exceeded max retries 2

2020-12-30 14:55:58.335 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction cancelled: ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=14770, state=CANCELLED, sendCnt=2, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=A6, identifiers=[3]]]

2020-12-30 14:55:58.338 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 000D6FFFFE03C639: Hardware version failed

2020-12-30 14:55:58.338 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=14772, state=CANCELLED, sendCnt=2, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=A6, identifiers=[3]]]

2020-12-30 14:55:58.342 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: transactionComplete but not outstanding, state=CANCELLED, outstanding=0

2020-12-30 14:55:58.349 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=--, identifiers=[1]]]

2020-12-30 14:55:58.353 [DEBUG] [transaction.ZigBeeTransactionManager] - 0103/1: Sending ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=5, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=A9, identifiers=[1]]]

2020-12-30 14:56:03.072 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=4723, state=FAILED, sendCnt=1, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=A9, identifiers=[1]]]

2020-12-30 14:56:03.076 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: transactionComplete, state=FAILED, outstanding=0

2020-12-30 14:56:03.078 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=4729, state=WAITING, sendCnt=1, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=A9, identifiers=[1]]]

2020-12-30 14:56:03.083 [DEBUG] [transaction.ZigBeeTransactionManager] - 0103/1: Sending ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=4734, state=WAITING, sendCnt=1, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=A9, identifiers=[1]]]

2020-12-30 14:56:07.804 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=0103, newNodeEui64=000D6FFFFE03C639, status=EMBER_STANDARD_SECURITY_UNSECURED_JOIN, policyDecision=EMBER_SEND_KEY_IN_THE_CLEAR, parentOfNewNodeId=0000]

2020-12-30 14:56:07.806 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=9457, state=FAILED, sendCnt=2, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=A9, identifiers=[1]]]

2020-12-30 14:56:07.809 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: transactionComplete, state=FAILED, outstanding=0

2020-12-30 14:56:07.808 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 000D6FFFFE03C639: nodeStatusUpdate - node status is UNSECURED_JOIN, network address is 0103.

2020-12-30 14:56:07.811 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: transactionComplete exceeded max retries 2

2020-12-30 14:56:07.813 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 000D6FFFFE03C639: Device status updated. NWK=0103

2020-12-30 14:56:07.815 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 000D6FFFFE03C639: NWK Discovery add node 0103

2020-12-30 14:56:07.818 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 000D6FFFFE03C639: Node state updated from UNKNOWN to ONLINE

2020-12-30 14:56:07.818 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction cancelled: ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=9469, state=CANCELLED, sendCnt=2, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=A9, identifiers=[1]]]

2020-12-30 14:56:07.821 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 000D6FFFFE03C639: Updating node NWK=0103

2020-12-30 14:56:07.823 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 000D6FFFFE03C639: Node update. NWK Address=0103

2020-12-30 14:56:07.824 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=9475, state=CANCELLED, sendCnt=2, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=A9, identifiers=[1]]]

2020-12-30 14:56:07.828 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 000D6FFFFE03C639: Application version failed

2020-12-30 14:56:07.827 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 000D6FFFFE03C639: Node 0103 is not updated

2020-12-30 14:56:07.831 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: transactionComplete but not outstanding, state=CANCELLED, outstanding=0

2020-12-30 14:56:07.849 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=--, identifiers=[2]]]

2020-12-30 14:56:07.868 [DEBUG] [transaction.ZigBeeTransactionManager] - 0103/1: Sending ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=7, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=AC, identifiers=[2]]]

2020-12-30 14:56:07.918 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=0103, sourceEui=000D6FFFFE03C639, lastHopLqi=255, lastHopRssi=-39, relayList=]

2020-12-30 14:56:17.874 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=10025, state=FAILED, sendCnt=1, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=AC, identifiers=[2]]]

2020-12-30 14:56:17.884 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: transactionComplete, state=FAILED, outstanding=0

2020-12-30 14:56:17.888 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=10039, state=WAITING, sendCnt=1, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=AC, identifiers=[2]]]

2020-12-30 14:56:17.897 [DEBUG] [transaction.ZigBeeTransactionManager] - 0103/1: Sending ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=10048, state=WAITING, sendCnt=1, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=AC, identifiers=[2]]]

2020-12-30 14:56:22.649 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=14800, state=FAILED, sendCnt=2, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=AC, identifiers=[2]]]

2020-12-30 14:56:22.653 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: transactionComplete, state=FAILED, outstanding=0

2020-12-30 14:56:22.655 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: transactionComplete exceeded max retries 2

2020-12-30 14:56:22.658 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction cancelled: ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=14809, state=CANCELLED, sendCnt=2, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=AC, identifiers=[2]]]

2020-12-30 14:56:22.660 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 000D6FFFFE03C639: Stack version failed

2020-12-30 14:56:22.660 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=14811, state=CANCELLED, sendCnt=2, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=AC, identifiers=[2]]]

2020-12-30 14:56:22.665 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: transactionComplete but not outstanding, state=CANCELLED, outstanding=0

2020-12-30 14:56:22.673 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=1, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=--, identifiers=[0]]]

2020-12-30 14:56:22.679 [DEBUG] [transaction.ZigBeeTransactionManager] - 0103/1: Sending ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=7, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=B1, identifiers=[0]]]

2020-12-30 14:56:27.408 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=4736, state=FAILED, sendCnt=1, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=B1, identifiers=[0]]]

2020-12-30 14:56:27.413 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: transactionComplete, state=FAILED, outstanding=0

2020-12-30 14:56:27.417 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=4745, state=WAITING, sendCnt=1, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=B1, identifiers=[0]]]

2020-12-30 14:56:27.423 [DEBUG] [transaction.ZigBeeTransactionManager] - 0103/1: Sending ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=4751, state=WAITING, sendCnt=1, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=B1, identifiers=[0]]]

2020-12-30 14:56:32.160 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=9488, state=FAILED, sendCnt=2, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=B1, identifiers=[0]]]

2020-12-30 14:56:32.167 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: transactionComplete, state=FAILED, outstanding=0

2020-12-30 14:56:32.170 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: transactionComplete exceeded max retries 2

2020-12-30 14:56:32.173 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction cancelled: ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=9501, state=CANCELLED, sendCnt=2, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=B1, identifiers=[0]]]

2020-12-30 14:56:32.177 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 000D6FFFFE03C639: ZCL version failed

2020-12-30 14:56:32.177 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=9505, state=CANCELLED, sendCnt=2, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=B1, identifiers=[0]]]

2020-12-30 14:56:32.182 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: transactionComplete but not outstanding, state=CANCELLED, outstanding=0

2020-12-30 14:56:32.190 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=--, identifiers=[6]]]

2020-12-30 14:56:32.195 [DEBUG] [transaction.ZigBeeTransactionManager] - 0103/1: Sending ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=5, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=B4, identifiers=[6]]]

2020-12-30 14:56:36.914 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=4724, state=FAILED, sendCnt=1, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=B4, identifiers=[6]]]

2020-12-30 14:56:36.918 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: transactionComplete, state=FAILED, outstanding=0

2020-12-30 14:56:36.921 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=4731, state=WAITING, sendCnt=1, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=B4, identifiers=[6]]]

2020-12-30 14:56:36.926 [DEBUG] [transaction.ZigBeeTransactionManager] - 0103/1: Sending ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=4736, state=WAITING, sendCnt=1, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=B4, identifiers=[6]]]

2020-12-30 14:56:41.644 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=9454, state=FAILED, sendCnt=2, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=B4, identifiers=[6]]]

2020-12-30 14:56:41.648 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: transactionComplete, state=FAILED, outstanding=0

2020-12-30 14:56:41.650 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: transactionComplete exceeded max retries 2

2020-12-30 14:56:41.653 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction cancelled: ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=9463, state=CANCELLED, sendCnt=2, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=B4, identifiers=[6]]]

2020-12-30 14:56:41.656 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 000D6FFFFE03C639: Date code failed

2020-12-30 14:56:41.659 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 000D6FFFFE03C639: ZigBee node property discovery using OTA cluster on endpoint 0103/1

2020-12-30 14:56:41.660 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=9470, state=CANCELLED, sendCnt=2, command=ReadAttributesCommand [Basic: 0000/0 -> 0103/1, cluster=0000, TID=B4, identifiers=[6]]]

2020-12-30 14:56:41.663 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: transactionComplete but not outstanding, state=CANCELLED, outstanding=0

2020-12-30 14:56:41.671 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Ota Upgrade: 0000/0 -> 0103/1, cluster=0019, TID=--, identifiers=[2]]]

2020-12-30 14:56:41.678 [DEBUG] [transaction.ZigBeeTransactionManager] - 0103/1: Sending ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=7, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Ota Upgrade: 0000/0 -> 0103/1, cluster=0019, TID=B5, identifiers=[2]]]

2020-12-30 14:56:46.407 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=4736, state=FAILED, sendCnt=1, command=ReadAttributesCommand [Ota Upgrade: 0000/0 -> 0103/1, cluster=0019, TID=B5, identifiers=[2]]]

2020-12-30 14:56:46.413 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: transactionComplete, state=FAILED, outstanding=0

2020-12-30 14:56:46.418 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=4747, state=WAITING, sendCnt=1, command=ReadAttributesCommand [Ota Upgrade: 0000/0 -> 0103/1, cluster=0019, TID=B5, identifiers=[2]]]

2020-12-30 14:56:46.423 [DEBUG] [transaction.ZigBeeTransactionManager] - 0103/1: Sending ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=4753, state=WAITING, sendCnt=1, command=ReadAttributesCommand [Ota Upgrade: 0000/0 -> 0103/1, cluster=0019, TID=B5, identifiers=[2]]]

2020-12-30 14:56:51.148 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=9477, state=FAILED, sendCnt=2, command=ReadAttributesCommand [Ota Upgrade: 0000/0 -> 0103/1, cluster=0019, TID=B5, identifiers=[2]]]

2020-12-30 14:56:51.152 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: transactionComplete, state=FAILED, outstanding=0

2020-12-30 14:56:51.153 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: transactionComplete exceeded max retries 2

2020-12-30 14:56:51.156 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction cancelled: ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=9485, state=CANCELLED, sendCnt=2, command=ReadAttributesCommand [Ota Upgrade: 0000/0 -> 0103/1, cluster=0019, TID=B5, identifiers=[2]]]

2020-12-30 14:56:51.159 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 000D6FFFFE03C639: Could not get OTA firmware version from device

2020-12-30 14:56:51.159 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=000D6FFFFE03C639 queueTime=9488, state=CANCELLED, sendCnt=2, command=ReadAttributesCommand [Ota Upgrade: 0000/0 -> 0103/1, cluster=0019, TID=B5, identifiers=[2]]]

2020-12-30 14:56:51.162 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 000D6FFFFE03C639: ZigBee node property discovery complete: {zigbee_logicaltype=ROUTER, zigbee_powerlevel=FULL, zigbee_manufacturercode=0x117c, zigbee_networkaddress=259, zigbee_powermode=RECEIVER_ON_IDLE, zigbee_powersources=[MAINS], zigbee_powersource=MAINS}

2020-12-30 14:56:51.164 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6FFFFE03C639: transactionComplete but not outstanding, state=CANCELLED, outstanding=0

2020-12-30 14:56:51.169 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 000D6FFFFE03C639: Data store: Deferring write for 250ms.

2020-12-30 14:56:51.423 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 000D6FFFFE03C639: Data store: Writing node.

2020-12-30 14:56:51.591 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 000D6FFFFE03C639: ZigBee saving network state complete.

There’s a lot of information in this log. As far as I understand it, the device is discovered, and then some commands are sent to it to get information like manufacturer, type, etc. It seems the bulb won’t answer those questions.

What’s going wrong here? I did add those bulbs to my previous setup successfully. The bulbs aren’t changed. I see the binding is updated to also support Zigbee 3.0, which my bulbs obviously don’t support. Maybe there’s something going wrong in that area? What can I do to get my bulbs recognized again?

@chris Can you help? I’m a developer myself, so I’m not afraid to try funky stuff on a console or something… :wink: Thanks in advance for any help!

Best regards,
Bart

I do not use Zigbee devices but the log viewer should be of some help.

Thanks, @Bruce_Osborne! I did know that tool. I see it’s improved since the last time I used it, a long time ago. However, it doesn’t give me extra information. I guess I need help from someone familiar with the internal workings of the Zigbee binding…

1 Like

Ok,
The location moved last year. After that the old server died a hardware death.

Well, this is quite short, and I’m not really sure what the log is showing - there is next to nothing in it, so it’s really hard to say what is happening.

No - there has not been any change. The 2.5 binding already supports ZB3.0 features and has done for a few years (depending on the coordinator of course).

In general, there’s not a lot of difference between the 2.5 and 3.0 bindings.

Are you sure you viewed the whole log? (Did you notice there is a scroll bar inside the text block?) It starts at 14:55:14 and stops at 14:56:51 and shows the entire discovery cycle. I see the bulb being discovered, various requests being sent and no answers coming back, as I understand it correct.

Please, tell me what more information you need to see what is going on here. And sorry for being misinformed about the Zigbee 3.0 support and making wrong assumptions!

Yes.

Yes, of course - yours isn’t my first log. Most logs I get are megabytes long - yours is only 140 lines long - this is very very far from the whole discovery. Maybe you have some logging disabled? I’m not really sure, but all I can say is there is not really a lot to go on with such a short log.

Well, you see more than me then :slight_smile: Yes, there is more going on, but it’s not being logged so I really have no idea what’s happening. Maybe you have the wrong log settings?

Please read the binding docs - at the bottom there is a section called something like “what to do when things don’t go as planned”. This should tell you how to enable logging.

1 Like

I know where to find those. I even contributed to the docs a while ago. (I added details of the baud rate settings among other things.) I enabled logging as described there. But since you’re saying you expect megabytes, I’ll double check the log settings and come back later. Are there any specific log lines you are missing? Would be helpful what to look for…

He needs unfiltered Zigbee logs for troubleshooting.

So, this time I double checked the log settings:

openhab> log:get | grep zigbee
com.zsmartsystems.zigbee                           │ DEBUG
com.zsmartsystems.zigbee.dongle.ember.internal.ash │ INFO
org.openhab.binding.zigbee                         │ DEBUG

Exactly as advised in the documentation. And here’s the result. Again, this is one discovery cycle, with one bulb hadding a factory reset at the start of the cycle.

bart.log (256.1 KB)
(Still no megabytes, but at least is was too long to paste into this message… :wink: )

I hope you will be able to draw conclusions based on this log. Please let me know if you need more information, other log levels set, whatever. Any help would be really appreciated!

Best regards,
Bart

DAE1.log (123.4 KB)

And here’s another log, of another bulb. This time, I tried ‘adding’ the device from the inbox, even though it was only recognized as “generic Zigbee device”. It stays in status UNKNOWN for a while, but evetually changes to ONLINE. However, I can’t still do anything with it, since it’s a generic device and has no channels. But it seems there is some data transferred: in the openHAB UI, I can see some properties:

    zigbee_logicaltype             ROUTER
    zigbee_powerlevel              FULL
    zigbee_manufacturercode        0x117c
    zigbee_networkaddress          56033
    zigbee_powermode               RECEIVER_ON_IDLE
    zigbee_powersources            [MAINS]
    zigbee_powersource             MAINS
    zigbee_device_initialised      false

Apart from trying to find the cause of the failing recognition, is there a way to manually add the right parameters, so that OpenHAB knows that this is a bulb and which channels it has?

This log shows no data being received from any devices. It’s pretty hard to really say what is happening, but clearly if devices aren’t communicating, it won’t work well :wink:

Well, there is some data received. Otherwise OpenHAB wouldn’t even know the device exists. Any idea what I can try to get the devices talking to each other again?

Not from devices - only from the coordinator. If you think that’s wrong, then please show me what you mean?

As an example -:

Yes, and how does the coordinator know of the existence of those devices?

Sorry - what’s your point?

My point is that the coordinator must have received data from the devices. Otherwise it wouldn’t even know that those devices exist, right?

Ok, yes, that’s correct.

So, there is communication between the coordinator and the bulbs.

Is there?

I think we can say there WAS at some point - but do you know if it’s still working?

Do you have a sniffer log? This will tell us what the coordinator is doing over the air. Otherwise, I can only go on what the coordinator sends to the binding - NOT what the coordinator may, or may not, be sending to any device.

I stated above that there is no communication in the log with any devices - only with the coordinator. This is still 100% correct in the log I looked at. If you have a sniffer log, then I’d be happy to take a look at that as it might help to understand what’s happening.