Zigbee Binding - Renaming Thing triggers node discovery

giuseppeiannello · April 27, 2020, 7:50pm

Summoning @chris our zigbee overlord.

As I’m adding more and more devices to my network (CC2531 coordinator with source_routing firmware from zigbee2mqtt, everything configured via PaperUI), and I’ve noticed that even a simple operation like renaming a Thing causes a node rediscovery. Is this expected, a bug, or an unwanted side effect? Even if this is normally an operation that is not executed so often, it create unnecessary load on the network, especially when renaming/reconfiguring multiple END-DEVICEs in a short time.

21:32:02.125 [INFO ] [smarthome.event.ThingUpdatedEvent    ] - Thing 'zigbee:device:9974248b:00158d00040e727a' has been updated.
21:32:02.125 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00158D00040E727A: Added transaction to queue, len=2, transaction=ZigBeeTransaction [ieeeAddress=00158D00040E727A queueTime=0, state=WAITING, sendCnt=0, command=BindRequest [0000/0 -> FF24/0, cluster=0021, TID=--, srcAddress=00158D00040E727A, srcEndpoint=1, bindCluster=6, dstAddrMode=3, dstAddress=00124B0009EF006A, dstEndpoint=1]]
21:32:02.134 [DEBUG] [.transaction.ZigBeeTransactionManager] - FF24/1: Sending ZigBeeTransaction [ieeeAddress=00158D00040E727A queueTime=594137, state=WAITING, sendCnt=1, command=ReadAttributesCommand [On/Off: 0000/0 -> FF24/1, cluster=0006, TID=4F, identifiers=[0]]]
21:32:02.138 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
21:32:02.144 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [On/Off: 0000/0 -> FF24/1, cluster=0006, TID=4F, identifiers=[0]]
21:32:02.149 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=79, commandId=0]
21:32:02.154 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=FF24/1, profile=0104, cluster=0006, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=C3, rssi=--, lqi=--, payload=00 4F 00 00 00]
21:32:02.160 [DEBUG] [531.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=15, apiId=24 01, data=FE 0F 24 01 24 FF 01 01 06 00 C3 30 1F 05 00 4F 00 00 00 51, checksum=51, error=false) 
21:32:02.180 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
21:32:02.185 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=4F state=TX_ACK
21:32:02.189 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=4F, state=TX_ACK, outstanding=1
21:32:02.194 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 4F -> TX_ACK == TRANSMITTED
21:32:07.204 [INFO ] [smarthome.event.ThingUpdatedEvent    ] - Thing 'zigbee:device:9974248b:00158d00040e727a' has been updated.
21:32:08.193 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-- AF_DATA_CONFIRM (FE 03 44 80 CD 01 C3 C8)
21:32:08.196 [DEBUG] [531.network.impl.CommandInterfaceImpl] - Received Async Cmd: AF_DATA_CONFIRM(Endpoint=1, Status=Z_NWK_NO_ROUTE(205), TransID=195)
21:32:08.200 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=4F state=RX_NAK
21:32:08.203 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=4F, state=RX_NAK, outstanding=1
21:32:08.207 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00158D00040E727A queueTime=600211, state=FAILED, sendCnt=2, command=ReadAttributesCommand [On/Off: 0000/0 -> FF24/1, cluster=0006, TID=4F, identifiers=[0]]]
21:32:08.212 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
21:32:08.216 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00158D00040E727A: transactionComplete FAILED 0
21:32:08.219 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00158D00040E727A: transactionComplete exceeded retries 2
21:32:08.223 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [ieeeAddress=00158D00040E727A queueTime=600226, state=FAILED, sendCnt=2, command=ReadAttributesCommand [On/Off: 0000/0 -> FF24/1, cluster=0006, TID=4F, identifiers=[0]]]
21:32:08.226 [DEBUG] [.transaction.ZigBeeTransactionManager] - FF24/0: Sending ZigBeeTransaction [ieeeAddress=00158D00040E727A queueTime=6102, state=WAITING, sendCnt=0, command=BindRequest [0000/0 -> FF24/0, cluster=0021, TID=99, srcAddress=00158D00040E727A, srcEndpoint=1, bindCluster=6, dstAddrMode=3, dstAddress=00124B0009EF006A, dstEndpoint=1]]
21:32:08.230 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
21:32:08.233 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: BindRequest [0000/0 -> FF24/0, cluster=0021, TID=99, srcAddress=00158D00040E727A, srcEndpoint=1, bindCluster=6, dstAddrMode=3, dstAddress=00124B0009EF006A, dstEndpoint=1]
21:32:08.237 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=FF24/0, profile=0000, cluster=0021, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=C4, rssi=--, lqi=--, payload=99 7A 72 0E 04 00 8D 15 00 01 06 00 03 6A 00 EF 09 00 4B 12 00 01]
21:32:08.240 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 4F -> RX_NAK == FAILED
21:32:08.241 [DEBUG] [531.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=32, apiId=24 01, data=FE 20 24 01 24 FF 00 00 21 00 C4 30 1F 16 99 7A 72 0E 04 00 8D 15 00 01 06 00 03 6A 00 EF 09 00 4B 12 00 01 D1, checksum=D1, error=false) 
21:32:08.264 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
21:32:08.267 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=99 state=TX_ACK
21:32:08.270 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=99, state=TX_ACK, outstanding=1
21:32:08.274 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 99 -> TX_ACK == TRANSMITTED
21:32:14.163 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zigbee:device:9974248b:00158d00040e727a' changed from ONLINE to UNKNOWN
21:32:14.164 [DEBUG] [app.discovery.ZigBeeNetworkDiscoverer] - 00158D00040E727A: NWK Discovery starting node rediscovery
21:32:14.174 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - Broadcast: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=null queueTime=0, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> FFFD/0, cluster=0000, TID=--, ieeeAddr=00158D00040E727A, requestType=0, startIndex=0]]
21:32:14.180 [DEBUG] [.transaction.ZigBeeTransactionManager] - FFFD/0: Sending ZigBeeTransaction [ieeeAddress=null queueTime=9, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> FFFD/0, cluster=0000, TID=9A, ieeeAddr=00158D00040E727A, requestType=0, startIndex=0]]
21:32:14.185 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
21:32:14.190 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0000/0 -> FFFD/0, cluster=0000, TID=9A, ieeeAddr=00158D00040E727A, requestType=0, startIndex=0]
21:32:14.195 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=FFFD/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=C5, rssi=--, lqi=--, payload=9A 7A 72 0E 04 00 8D 15 00 00 00]
21:32:14.200 [DEBUG] [531.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=21, apiId=24 01, data=FE 15 24 01 FD FF 00 00 00 00 C5 30 1F 0B 9A 7A 72 0E 04 00 8D 15 00 00 00 D3, checksum=D3, error=false) 
21:32:14.225 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
21:32:14.230 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=9A state=TX_ACK
21:32:14.234 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=9A, state=TX_ACK, outstanding=2
21:32:14.238 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 9A -> TX_ACK == TRANSMITTED
21:32:14.257 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 03 45 C4 56 C4 00 10)
21:32:14.261 [DEBUG] [531.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=3, apiId=45 C4, data=FE 03 45 C4 56 C4 00 10, checksum=10, error=false
21:32:14.264 [DEBUG] [ee.dongle.cc2531.ZigBeeDongleTiCc2531] - Unhandled ZToolPacket type 0x45c4
21:32:14.266 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00158D00040E727A: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00158D00040E727A queueTime=0, state=WAITING, sendCnt=0, command=DiscoverAttributesCommand [On/Off: 0000/0 -> FF24/1, cluster=0006, TID=--, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]]
21:32:14.322 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 0D 45 80 00 7A 72 0E 04 00 8D 15 00 24 FF 61 00 E8)
21:32:14.324 [DEBUG] [531.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=13, apiId=45 80, data=FE 0D 45 80 00 7A 72 0E 04 00 8D 15 00 24 FF 61 00 E8, checksum=E8, error=false
21:32:14.325 [DEBUG] [ee.dongle.cc2531.ZigBeeDongleTiCc2531] - Unhandled ZToolPacket type 0x4580
21:32:14.342 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 14 45 FF 56 C4 00 00 80 00 9A 00 00 00 7A 72 0E 04 00 8D 15 00 24 FF 67)
21:32:14.344 [DEBUG] [531.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=20, apiId=45 FF, data=FE 14 45 FF 56 C4 00 00 80 00 9A 00 00 00 7A 72 0E 04 00 8D 15 00 24 FF 67, checksum=67, error=false
21:32:14.346 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=C456/0, destinationAddress=0000/0, profile=0000, cluster=8000, addressMode=null, radius=0, apsSecurity=false, ackRequest=false, apsCounter=--, rssi=--, lqi=--, payload=00 00 7A 72 0E 04 00 8D 15 00 24 FF]
21:32:14.348 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: NetworkAddressResponse [C456/0 -> 0000/0, cluster=8000, TID=00, status=SUCCESS, ieeeAddrRemoteDev=00158D00040E727A, nwkAddrRemoteDev=FF24, startIndex=null, nwkAddrAssocDevList=[]]
21:32:14.350 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NetworkAddressResponse [C456/0 -> 0000/0, cluster=8000, TID=00, status=SUCCESS, ieeeAddrRemoteDev=00158D00040E727A, nwkAddrRemoteDev=FF24, startIndex=null, nwkAddrAssocDevList=[]] 
21:32:14.352 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NetworkAddressResponse [C456/0 -> 0000/0, cluster=8000, TID=00, status=SUCCESS, ieeeAddrRemoteDev=00158D00040E727A, nwkAddrRemoteDev=FF24, startIndex=null, nwkAddrAssocDevList=[]] ZigBeeTransaction [ieeeAddress=null queueTime=181, state=TRANSMITTED, sendCnt=1, command=NetworkAddressRequest [0000/0 -> FFFD/0, cluster=0000, TID=9A, ieeeAddr=00158D00040E727A, requestType=0, startIndex=0]]
21:32:14.355 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NetworkAddressResponse [C456/0 -> 0000/0, cluster=8000, TID=00, status=SUCCESS, ieeeAddrRemoteDev=00158D00040E727A, nwkAddrRemoteDev=FF24, startIndex=null, nwkAddrAssocDevList=[]] ZigBeeTransaction [ieeeAddress=00158D00040E727A queueTime=12231, state=TRANSMITTED, sendCnt=1, command=BindRequest [0000/0 -> FF24/0, cluster=0021, TID=99, srcAddress=00158D00040E727A, srcEndpoint=1, bindCluster=6, dstAddrMode=3, dstAddress=00124B0009EF006A, dstEndpoint=1]]
21:32:14.355 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction response received - waiting TX_ACK: ZigBeeTransaction [ieeeAddress=null queueTime=183, state=RESPONDED, sendCnt=1, command=NetworkAddressRequest [0000/0 -> FFFD/0, cluster=0000, TID=9A, ieeeAddr=00158D00040E727A, requestType=0, startIndex=0]]
21:32:14.358 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-- ZB_FIND_DEVICE_CONFIRM (FE 0B 46 85 01 24 FF 7A 72 0E 04 00 8D 15 00 88)
21:32:14.359 [DEBUG] [531.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=11, apiId=46 85, data=FE 0B 46 85 01 24 FF 7A 72 0E 04 00 8D 15 00 88, checksum=88, error=false
21:32:14.361 [DEBUG] [ee.dongle.cc2531.ZigBeeDongleTiCc2531] - Unhandled ZToolPacket type 0x4685
21:32:16.275 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00158D00040E727A queueTime=14150, state=FAILED, sendCnt=1, command=BindRequest [0000/0 -> FF24/0, cluster=0021, TID=99, srcAddress=00158D00040E727A, srcEndpoint=1, bindCluster=6, dstAddrMode=3, dstAddress=00124B0009EF006A, dstEndpoint=1]]
21:32:16.280 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
21:32:16.283 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00158D00040E727A: transactionComplete FAILED 0
21:32:16.288 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00158D00040E727A: Added transaction to queue, len=2, transaction=ZigBeeTransaction [ieeeAddress=00158D00040E727A queueTime=14163, state=WAITING, sendCnt=1, command=BindRequest [0000/0 -> FF24/0, cluster=0021, TID=99, srcAddress=00158D00040E727A, srcEndpoint=1, bindCluster=6, dstAddrMode=3, dstAddress=00124B0009EF006A, dstEndpoint=1]]
21:32:16.293 [DEBUG] [.transaction.ZigBeeTransactionManager] - FF24/0: Sending ZigBeeTransaction [ieeeAddress=00158D00040E727A queueTime=14168, state=WAITING, sendCnt=1, command=BindRequest [0000/0 -> FF24/0, cluster=0021, TID=99, srcAddress=00158D00040E727A, srcEndpoint=1, bindCluster=6, dstAddrMode=3, dstAddress=00124B0009EF006A, dstEndpoint=1]]
21:32:16.297 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
21:32:16.302 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: BindRequest [0000/0 -> FF24/0, cluster=0021, TID=99, srcAddress=00158D00040E727A, srcEndpoint=1, bindCluster=6, dstAddrMode=3, dstAddress=00124B0009EF006A, dstEndpoint=1]
21:32:16.307 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=FF24/0, profile=0000, cluster=0021, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=C6, rssi=--, lqi=--, payload=99 7A 72 0E 04 00 8D 15 00 01 06 00 03 6A 00 EF 09 00 4B 12 00 01]
21:32:16.311 [DEBUG] [531.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=32, apiId=24 01, data=FE 20 24 01 24 FF 00 00 21 00 C6 30 1F 16 99 7A 72 0E 04 00 8D 15 00 01 06 00 03 6A 00 EF 09 00 4B 12 00 01 D3, checksum=D3, error=false) 
21:32:16.334 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
21:32:16.337 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=99 state=TX_ACK
21:32:16.339 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=99, state=TX_ACK, outstanding=2
21:32:16.342 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 99 -> TX_ACK == TRANSMITTED
21:32:22.239 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=null queueTime=8067, state=COMPLETE, sendCnt=1, command=NetworkAddressRequest [0000/0 -> FFFD/0, cluster=0000, TID=9A, ieeeAddr=00158D00040E727A, requestType=0, startIndex=0]]
21:32:22.238 [DEBUG] [app.discovery.ZigBeeNetworkDiscoverer] - 00158D00040E727A: NWK Discovery add node FF24
21:32:22.243 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
21:32:22.245 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode  ] - 00158D00040E727A: Node state updated from UNKNOWN to ONLINE
21:32:22.248 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete COMPLETE 0
21:32:22.250 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 00158D00040E727A: Updating node NWK=FF24
21:32:22.255 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 00158D00040E727A: Node FF24 update
21:32:22.260 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 00158D00040E727A: Node FF24 is not updated
21:32:22.263 [DEBUG] [app.discovery.ZigBeeNetworkDiscoverer] - NWK Discovery for FF24 scheduling node discovery
21:32:22.268 [DEBUG] [app.discovery.ZigBeeNetworkDiscoverer] - NWK Discovery for FF24 starting node discovery
21:32:22.271 [DEBUG] [app.discovery.ZigBeeNetworkDiscoverer] - 00158D00040E727A: NWK Discovery finishing node rediscovery after 0 attempts
21:32:22.272 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00158D00040E727A: Added transaction to queue, len=2, transaction=ZigBeeTransaction [ieeeAddress=00158D00040E727A queueTime=0, state=WAITING, sendCnt=0, command=IeeeAddressRequest [0000/0 -> FF24/0, cluster=0001, TID=--, nwkAddrOfInterest=FF24, requestType=1, startIndex=0]]
21:32:24.343 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00158D00040E727A queueTime=22218, state=FAILED, sendCnt=2, command=BindRequest [0000/0 -> FF24/0, cluster=0021, TID=99, srcAddress=00158D00040E727A, srcEndpoint=1, bindCluster=6, dstAddrMode=3, dstAddress=00124B0009EF006A, dstEndpoint=1]]
21:32:24.347 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
21:32:24.351 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00158D00040E727A: transactionComplete FAILED 0
21:32:24.355 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00158D00040E727A: transactionComplete exceeded retries 2
21:32:24.359 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [ieeeAddress=00158D00040E727A queueTime=22234, state=FAILED, sendCnt=2, command=BindRequest [0000/0 -> FF24/0, cluster=0021, TID=99, srcAddress=00158D00040E727A, srcEndpoint=1, bindCluster=6, dstAddrMode=3, dstAddress=00124B0009EF006A, dstEndpoint=1]]
21:32:24.364 [DEBUG] [.transaction.ZigBeeTransactionManager] - FF24/1: Sending ZigBeeTransaction [ieeeAddress=00158D00040E727A queueTime=10098, state=WAITING, sendCnt=0, command=DiscoverAttributesCommand [On/Off: 0000/0 -> FF24/1, cluster=0006, TID=9B, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]]
21:32:24.368 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
21:32:24.372 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: DiscoverAttributesCommand [On/Off: 0000/0 -> FF24/1, cluster=0006, TID=9B, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]
21:32:24.375 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=155, commandId=12]
21:32:24.379 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=FF24/1, profile=0104, cluster=0006, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=C7, rssi=--, lqi=--, payload=00 9B 0C 00 00 0A]
21:32:24.383 [DEBUG] [531.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=16, apiId=24 01, data=FE 10 24 01 24 FF 01 01 06 00 C7 30 1F 06 00 9B 0C 00 00 0A 9B, checksum=9B, error=false) 
21:32:24.401 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
21:32:24.405 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=9B state=TX_ACK
21:32:24.408 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=9B, state=TX_ACK, outstanding=1
21:32:24.411 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 9B -> TX_ACK == TRANSMITTED
21:32:26.272 [DEBUG] [m.zsmartsystems.zigbee.zcl.ZclCluster] - readSync request: 0
21:32:26.277 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00158D00040E727A: Added transaction to queue, len=2, transaction=ZigBeeTransaction [ieeeAddress=00158D00040E727A queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [On/Off: 0000/0 -> FF24/1, cluster=0006, TID=--, identifiers=[0]]]
21:32:30.414 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-- AF_DATA_CONFIRM (FE 03 44 80 CD 01 C7 CC)
21:32:30.418 [DEBUG] [531.network.impl.CommandInterfaceImpl] - Received Async Cmd: AF_DATA_CONFIRM(Endpoint=1, Status=Z_NWK_NO_ROUTE(205), TransID=199)
21:32:30.422 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=9B state=RX_NAK
21:32:30.425 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=9B, state=RX_NAK, outstanding=1
21:32:30.429 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00158D00040E727A queueTime=16164, state=FAILED, sendCnt=1, command=DiscoverAttributesCommand [On/Off: 0000/0 -> FF24/1, cluster=0006, TID=9B, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]]
21:32:30.434 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
21:32:30.437 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00158D00040E727A: transactionComplete FAILED 0
21:32:30.441 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00158D00040E727A: Added transaction to queue, len=3, transaction=ZigBeeTransaction [ieeeAddress=00158D00040E727A queueTime=16175, state=WAITING, sendCnt=1, command=DiscoverAttributesCommand [On/Off: 0000/0 -> FF24/1, cluster=0006, TID=9B, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]]
21:32:30.446 [DEBUG] [.transaction.ZigBeeTransactionManager] - FF24/1: Sending ZigBeeTransaction [ieeeAddress=00158D00040E727A queueTime=16180, state=WAITING, sendCnt=1, command=DiscoverAttributesCommand [On/Off: 0000/0 -> FF24/1, cluster=0006, TID=9B, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]]
21:32:30.450 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
21:32:30.454 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: DiscoverAttributesCommand [On/Off: 0000/0 -> FF24/1, cluster=0006, TID=9B, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]
21:32:30.458 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=155, commandId=12]
21:32:30.462 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=FF24/1, profile=0104, cluster=0006, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=C8, rssi=--, lqi=--, payload=00 9B 0C 00 00 0A]
21:32:30.466 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 9B -> RX_NAK == DISPATCHED
21:32:30.466 [DEBUG] [531.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=16, apiId=24 01, data=FE 10 24 01 24 FF 01 01 06 00 C8 30 1F 06 00 9B 0C 00 00 0A 94, checksum=94, error=false) 
21:32:30.488 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
21:32:30.492 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=9B state=TX_ACK
21:32:30.496 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=9B, state=TX_ACK, outstanding=1
21:32:30.499 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 9B -> TX_ACK == TRANSMITTED
21:32:35.779 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00158D00040E727A: Added transaction to queue, len=3, transaction=ZigBeeTransaction [ieeeAddress=00158D00040E727A queueTime=0, state=WAITING, sendCnt=0, command=IeeeAddressRequest [0000/0 -> FF24/0, cluster=0001, TID=--, nwkAddrOfInterest=FF24, requestType=1, startIndex=0]]
21:32:36.501 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-- AF_DATA_CONFIRM (FE 03 44 80 CD 01 C8 C3)
21:32:36.505 [DEBUG] [531.network.impl.CommandInterfaceImpl] - Received Async Cmd: AF_DATA_CONFIRM(Endpoint=1, Status=Z_NWK_NO_ROUTE(205), TransID=200)
21:32:36.509 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=9B state=RX_NAK
21:32:36.513 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=9B, state=RX_NAK, outstanding=1
21:32:36.518 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00158D00040E727A queueTime=22252, state=FAILED, sendCnt=2, command=DiscoverAttributesCommand [On/Off: 0000/0 -> FF24/1, cluster=0006, TID=9B, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]]
21:32:36.522 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
21:32:36.525 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00158D00040E727A: transactionComplete FAILED 0
21:32:36.529 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00158D00040E727A: transactionComplete exceeded retries 2
21:32:36.532 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [ieeeAddress=00158D00040E727A queueTime=22267, state=FAILED, sendCnt=2, command=DiscoverAttributesCommand [On/Off: 0000/0 -> FF24/1, cluster=0006, TID=9B, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]]
21:32:36.536 [DEBUG] [.transaction.ZigBeeTransactionManager] - FF24/0: Sending ZigBeeTransaction [ieeeAddress=00158D00040E727A queueTime=14264, state=WAITING, sendCnt=0, command=IeeeAddressRequest [0000/0 -> FF24/0, cluster=0001, TID=9C, nwkAddrOfInterest=FF24, requestType=1, startIndex=0]]
21:32:36.539 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
21:32:36.543 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: IeeeAddressRequest [0000/0 -> FF24/0, cluster=0001, TID=9C, nwkAddrOfInterest=FF24, requestType=1, startIndex=0]
21:32:36.546 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=FF24/0, profile=0000, cluster=0001, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=C9, rssi=--, lqi=--, payload=9C 24 FF 01 00]
21:32:36.550 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 9B -> RX_NAK == FAILED
21:32:36.550 [DEBUG] [531.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=15, apiId=24 01, data=FE 0F 24 01 24 FF 00 00 01 00 C9 30 1F 05 9C 24 FF 01 00 55, checksum=55, error=false) 
21:32:36.570 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
21:32:36.574 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=9C state=TX_ACK
21:32:36.577 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=9C, state=TX_ACK, outstanding=1
21:32:36.580 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 9C -> TX_ACK == TRANSMITTED
21:32:38.283 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00158D00040E727A: Added transaction to queue, len=3, transaction=ZigBeeTransaction [ieeeAddress=00158D00040E727A queueTime=0, state=WAITING, sendCnt=0, command=ConfigureReportingCommand [On/Off: 0000/0 -> FF24/1, cluster=0006, TID=--, records=[AttributeReportingConfigurationRecord [attributeDataType=BOOLEAN, attributeIdentifier=0, direction=0, minimumReportingInterval=1, maximumReportingInterval=900]]]]
21:32:44.581 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00158D00040E727A queueTime=22308, state=FAILED, sendCnt=1, command=IeeeAddressRequest [0000/0 -> FF24/0, cluster=0001, TID=9C, nwkAddrOfInterest=FF24, requestType=1, startIndex=0]]
21:32:44.585 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
21:32:44.589 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00158D00040E727A: transactionComplete FAILED 0
21:32:44.593 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00158D00040E727A: Added transaction to queue, len=4, transaction=ZigBeeTransaction [ieeeAddress=00158D00040E727A queueTime=22321, state=WAITING, sendCnt=1, command=IeeeAddressRequest [0000/0 -> FF24/0, cluster=0001, TID=9C, nwkAddrOfInterest=FF24, requestType=1, startIndex=0]]
21:32:44.598 [DEBUG] [.transaction.ZigBeeTransactionManager] - FF24/0: Sending ZigBeeTransaction [ieeeAddress=00158D00040E727A queueTime=22326, state=WAITING, sendCnt=1, command=IeeeAddressRequest [0000/0 -> FF24/0, cluster=0001, TID=9C, nwkAddrOfInterest=FF24, requestType=1, startIndex=0]]
21:32:44.603 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
21:32:44.607 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: IeeeAddressRequest [0000/0 -> FF24/0, cluster=0001, TID=9C, nwkAddrOfInterest=FF24, requestType=1, startIndex=0]
21:32:44.612 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=FF24/0, profile=0000, cluster=0001, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=CA, rssi=--, lqi=--, payload=9C 24 FF 01 00]
21:32:44.616 [DEBUG] [531.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=15, apiId=24 01, data=FE 0F 24 01 24 FF 00 00 01 00 CA 30 1F 05 9C 24 FF 01 00 56, checksum=56, error=false) 
21:32:44.636 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
21:32:44.640 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=9C state=TX_ACK
21:32:44.644 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=9C, state=TX_ACK, outstanding=1
21:32:44.647 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 9C -> TX_ACK == TRANSMITTED
21:32:49.285 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00158D00040E727A: Added transaction to queue, len=4, transaction=ZigBeeTransaction [ieeeAddress=00158D00040E727A queueTime=0, state=WAITING, sendCnt=0, command=IeeeAddressRequest [0000/0 -> FF24/0, cluster=0001, TID=--, nwkAddrOfInterest=FF24, requestType=1, startIndex=0]]
21:32:50.290 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00158D00040E727A: Added transaction to queue, len=5, transaction=ZigBeeTransaction [ieeeAddress=00158D00040E727A queueTime=0, state=WAITING, sendCnt=0, command=ManagementBindRequest [0000/0 -> FF24/0, cluster=0033, TID=--, startIndex=0]]
21:32:52.648 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00158D00040E727A queueTime=30375, state=FAILED, sendCnt=2, command=IeeeAddressRequest [0000/0 -> FF24/0, cluster=0001, TID=9C, nwkAddrOfInterest=FF24, requestType=1, startIndex=0]]
21:32:52.652 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
21:32:52.656 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00158D00040E727A: transactionComplete FAILED 0
21:32:52.660 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00158D00040E727A: transactionComplete exceeded retries 2
21:32:52.665 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [ieeeAddress=00158D00040E727A queueTime=30392, state=FAILED, sendCnt=2, command=IeeeAddressRequest [0000/0 -> FF24/0, cluster=0001, TID=9C, nwkAddrOfInterest=FF24, requestType=1, startIndex=0]]
21:32:52.669 [DEBUG] [.transaction.ZigBeeTransactionManager] - FF24/1: Sending ZigBeeTransaction [ieeeAddress=00158D00040E727A queueTime=26393, state=WAITING, sendCnt=0, command=ReadAttributesCommand [On/Off: 0000/0 -> FF24/1, cluster=0006, TID=9D, identifiers=[0]]]
21:32:52.674 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
21:32:52.678 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [On/Off: 0000/0 -> FF24/1, cluster=0006, TID=9D, identifiers=[0]]
21:32:52.682 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=157, commandId=0]
21:32:52.687 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=FF24/1, profile=0104, cluster=0006, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=CB, rssi=--, lqi=--, payload=00 9D 00 00 00]
21:32:52.692 [DEBUG] [531.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=15, apiId=24 01, data=FE 0F 24 01 24 FF 01 01 06 00 CB 30 1F 05 00 9D 00 00 00 8B, checksum=8B, error=false) 
21:32:52.711 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
21:32:52.714 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=9D state=TX_ACK
21:32:52.716 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=9D, state=TX_ACK, outstanding=1
21:32:52.719 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 9D -> TX_ACK == TRANSMITTED
21:32:58.731 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-- AF_DATA_CONFIRM (FE 03 44 80 CD 01 CB C0)
21:32:58.735 [DEBUG] [531.network.impl.CommandInterfaceImpl] - Received Async Cmd: AF_DATA_CONFIRM(Endpoint=1, Status=Z_NWK_NO_ROUTE(205), TransID=203)
21:32:58.739 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=9D state=RX_NAK
21:32:58.743 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=9D, state=RX_NAK, outstanding=1
21:32:58.747 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00158D00040E727A queueTime=32471, state=FAILED, sendCnt=1, command=ReadAttributesCommand [On/Off: 0000/0 -> FF24/1, cluster=0006, TID=9D, identifiers=[0]]]
21:32:58.752 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
21:32:58.756 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00158D00040E727A: transactionComplete FAILED 0
21:32:58.760 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00158D00040E727A: Added transaction to queue, len=5, transaction=ZigBeeTransaction [ieeeAddress=00158D00040E727A queueTime=32483, state=WAITING, sendCnt=1, command=ReadAttributesCommand [On/Off: 0000/0 -> FF24/1, cluster=0006, TID=9D, identifiers=[0]]]
21:32:58.765 [DEBUG] [.transaction.ZigBeeTransactionManager] - FF24/1: Sending ZigBeeTransaction [ieeeAddress=00158D00040E727A queueTime=32488, state=WAITING, sendCnt=1, command=ReadAttributesCommand [On/Off: 0000/0 -> FF24/1, cluster=0006, TID=9D, identifiers=[0]]]
21:32:58.769 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
21:32:58.774 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [On/Off: 0000/0 -> FF24/1, cluster=0006, TID=9D, identifiers=[0]]
21:32:58.778 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=157, commandId=0]
21:32:58.782 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=FF24/1, profile=0104, cluster=0006, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=CC, rssi=--, lqi=--, payload=00 9D 00 00 00]
21:32:58.787 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 9D -> RX_NAK == DISPATCHED
21:32:58.787 [DEBUG] [531.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=15, apiId=24 01, data=FE 0F 24 01 24 FF 01 01 06 00 CC 30 1F 05 00 9D 00 00 00 8C, checksum=8C, error=false) 
21:32:58.809 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
21:32:58.813 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=9D state=TX_ACK
21:32:58.817 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=9D, state=TX_ACK, outstanding=1
21:32:58.820 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 9D -> TX_ACK == TRANSMITTED
21:33:02.297 [DEBUG] [database.ZigBeeNetworkDatabaseManager] - 00158D00040E727A: Data store: Deferring write for 250ms.
21:33:02.298 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zigbee:device:9974248b:00158d00040e727a' changed from UNKNOWN to ONLINE
21:33:02.552 [DEBUG] [database.ZigBeeNetworkDatabaseManager] - 00158D00040E727A: Data store: Writing node.

5iver · April 27, 2020, 8:04pm

I believe what you are seeing is the result of the serial transport restarting, which then restarts the bundles that depend on it, including the Zigbee binding. Several intertwined issues have been reported about this…

Bruce_Osborne · April 27, 2020, 8:24pm

I removed the Zigbee tag because you indicate you are using zigbee2mqtt and not the zigbee binding written by Chris.

Somebody else wrote & maintains that binding.

chris · April 27, 2020, 9:06pm

I think that’s wrong and this is related to the zigbee binding - not zigbee2mqtt…

giuseppeiannello · April 27, 2020, 9:30pm

A restart of the binding would be visible in the logs, and it doesn’t seem to be the case.

chris · April 27, 2020, 9:58pm

Can you please provide a log showing what happens when you update something in the device - I’ll take a look at what I can see.

Bruce_Osborne · April 27, 2020, 10:47pm

That is why I thought it was zigbee2mqtt

chris · April 27, 2020, 10:48pm

It just means he was using the zigbee2mqtt version of the CC2531 firmware - but with the ZigBee binding…

giuseppeiannello · April 28, 2020, 7:34am

Any specific class you want set to DEBUG?

chris · April 28, 2020, 7:37am

I don’t see anythign in the log for the ZigBeeThingHandler - I assumed this is because this short log just didn’t show the reconfiguration you’re mentioning, but it could also be that logging on the binding is not enabled?

giuseppeiannello · April 28, 2020, 7:51am

Here you go: https://pastebin.com/UsDDptdk

From PaperUI, I edited one Thing, changed its name and location and saved. Logs end as soon as the Thing is ONLINE again.

chris · April 28, 2020, 6:27pm

I’ve made a change although I’m not convinced it will help. Please try the latest snapshot (from tomorrow) and let’s take it from there.

giuseppeiannello · April 28, 2020, 7:21pm

Will do. I’m right now adding even more nodes, and it’s soooooooooooooooo slow compared to zigbee2mqtt.
The automatic channel detection/no need for a device database is great, but pairing devices on a running network with ~20 nodes is painful - getting rid of those extra packets might be helpful.

giuseppeiannello · April 28, 2020, 7:49pm

I don’t want to pollute the thread with unrelated questions, but otherwise I’ll forget by tomorrow - it seems I’ve reached a point where it’s hard to pair new nodes.

The logs start with the click of Inbox -> + -> Zigbee Binding. For 2:30 minutes after the trigger, the network (especially the end devices) are slow - sensors are firing with 15/20 seconds of delay, or not firing at all. Even the ‘expire’ binding doesn’t turn off my lights.

https://pastebin.com/DStScsLQ

EDIT: all of a sudden, a device appeared in the inbox, even if the last attempt at actually pairing was ~20 minutes before this log was saved.
It could be one of the devices that I tried to pair and failed to get properly discovered - will check tomorrow.

giuseppeiannello · April 29, 2020, 9:21am

https://pastebin.com/sber6P0H

logs with latest snapshot build, after changing the name of a thing from PaperUI.

chris · April 29, 2020, 12:54pm

This should now be fixed.

giuseppeiannello · April 29, 2020, 7:23pm

Nope

This also fixes the pairing issue, as the root cause is similar.

chris · April 29, 2020, 7:25pm

Why do you think that changing the discovery makes a difference? The issue you reported was when you saved the device it would perform the reinitialisation and this was fixed already.

This PR seems related to something else with scanning for new devices?

giuseppeiannello · April 29, 2020, 7:44pm

Sorry, your last change didn’t fix the issue. initialize() gets called anyway, and subsequently bridgeStatusChanged() which in turn rediscovers the node.

The other commit tackles the other issue I mentioned in this thread (can’t join new devices, network slow after starting a scan).

chris · April 29, 2020, 7:48pm

Ok, I don’t really see how that works from a quick look, but I’ll take a look at it when I get a chance (it might be a few days).

With the second issue this needs some more thought as well as it may have side effects.