Debug Log

17:41:09.623 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 00124B000EE99EED: Node updated - ZigBeeNode [state=ONLINE, IEEE=00124B000EE99EED, NWK=0847, endpoints=[]]
17:41:09.624 [WARN ] [.zsmartsystems.zigbee.ZigBeeExecutors] - Uncaught exception in thread NotificationService-thread-27
java.lang.NullPointerException: null
        at org.openhab.binding.zigbee.handler.ZigBeeThingHandler.nodeUpdated(ZigBeeThingHandler.java:862) ~[?:?]
        at com.zsmartsystems.zigbee.ZigBeeNetworkManager$14.run(ZigBeeNetworkManager.java:1815) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[?:?]
        at java.lang.Thread.run(Thread.java:829) [?:?]
17:41:09.876 [DEBUG] [nding.zigbee.internal.ZigBeeDataStore] - 00124B000EE99EED: ZigBee saving network state complete.
17:41:20.515 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - 00124B000EE99DC7: Discovery: Starting discovery for existing device
17:41:20.516 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - 00124B000EE99EED: Discovery: Starting discovery for existing device
17:41:20.517 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - Starting ZigBee scan for zigbee:coordinator_cc2531:91ce26ffb4
17:41:20.526 [INFO ] [gbee.discovery.ZigBeeDiscoveryService] - 00124B000EE99DC7: Starting ZigBee device discovery
17:41:20.527 [INFO ] [gbee.discovery.ZigBeeDiscoveryService] - 00124B000EE99EED: Starting ZigBee device discovery
17:41:20.528 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - 00124B000EE99DC7: Creating ZigBee device zigbee:device with bridge zigbee:coordinator_cc2531:91ce26ffb4
17:41:20.528 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - 00124B000EE99EED: Creating ZigBee device zigbee:device with bridge zigbee:coordinator_cc2531:91ce26ffb4
17:41:20.528 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - 00124B000EE99DC7: Node discovery not complete
17:41:20.530 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - 00124B000EE99EED: Node discovery not complete
17:42:31.953 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00124B000EE99DC7 queueTime=8013, state=FAILED, sendCnt=1, command=PowerDescriptorRequest [0000/0 -> 435D/0, cluster=0003, TID=8B, nwkAddrOfInterest=435D]]
17:42:31.954 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
17:42:31.954 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00124B000EE99DC7: transactionComplete, state=FAILED, outstanding=0
17:42:31.954 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00124B000EE99DC7: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00124B000EE99DC7 queueTime=8014, state=WAITING, sendCnt=1, command=PowerDescriptorRequest [0000/0 -> 435D/0, cluster=0003, TID=8B, nwkAddrOfInterest=435D]]
17:42:31.954 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=2, sleepy=0/3
17:42:31.955 [DEBUG] [.transaction.ZigBeeTransactionManager] - 435D/0: Sending ZigBeeTransaction [ieeeAddress=00124B000EE99DC7 queueTime=8015, state=WAITING, sendCnt=1, command=PowerDescriptorRequest [0000/0 -> 435D/0, cluster=0003, TID=8B, nwkAddrOfInterest=435D]]
17:42:31.955 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
17:42:31.955 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: PowerDescriptorRequest [0000/0 -> 435D/0, cluster=0003, TID=8B, nwkAddrOfInterest=435D]
17:42:31.956 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=435D/0, profile=0000, cluster=0003, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=DD, rssi=--, lqi=--, payload=8B 5D 43]
17:42:31.956 [DEBUG] [531.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=13, apiId=24 01, data=FE 0D 24 01 5D 43 00 00 03 00 DD 30 08 03 8B 5D 43 46, checksum=46, error=false)
17:42:31.975 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
17:42:31.976 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=8B state=TX_ACK
17:42:31.976 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=8B, state=TX_ACK, outstanding=1
17:42:31.977 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=435D, TID=8B, event=TX_ACK, state=TRANSMITTED
17:42:36.478 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 00124B000EE99EED: Node SVC Discovery: running NWK_ADDRESS
17:42:36.479 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00124B000EE99EED: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00124B000EE99EED queueTime=0, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> 0847/0, cluster=0000, TID=--, ieeeAddr=00124B000EE99EED, requestType=0, startIndex=0]]
17:42:36.480 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=2, sleepy=0/3
17:42:36.482 [DEBUG] [.transaction.ZigBeeTransactionManager] - 0847/0: Sending ZigBeeTransaction [ieeeAddress=00124B000EE99EED queueTime=3, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> 0847/0, cluster=0000, TID=8C, ieeeAddr=00124B000EE99EED, requestType=0, startIndex=0]]
17:42:36.482 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
17:42:36.484 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0000/0 -> 0847/0, cluster=0000, TID=8C, ieeeAddr=00124B000EE99EED, requestType=0, startIndex=0]
17:42:36.484 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0847/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=DE, rssi=--, lqi=--, payload=8C ED 9E E9 0E 00 4B 12 00 00 00]
17:42:36.485 [DEBUG] [531.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=21, apiId=24 01, data=FE 15 24 01 47 08 00 00 00 00 DE 30 08 0B 8C ED 9E E9 0E 00 4B 12 00 00 00 D3, checksum=D3, error=false)
17:42:36.509 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
17:42:36.510 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=8C state=TX_ACK
17:42:36.511 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=8C, state=TX_ACK, outstanding=2
17:42:36.512 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=0847, TID=8C, event=TX_ACK, state=TRANSMITTED
17:42:36.557 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 0D 45 FF 47 08 00 00 80 00 8C 00 00 84 00 00 00 70)
17:42:36.558 [DEBUG] [531.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=13, apiId=45 FF, data=FE 0D 45 FF 47 08 00 00 80 00 8C 00 00 84 00 00 00 70, checksum=70, error=false
17:42:36.559 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0847/0, destinationAddress=0000/0, profile=0000, cluster=8000, addressMode=null, radius=0, apsSecurity=false, ackRequest=false, apsCounter=--, rssi=--, lqi=--, payload=00 84 00 00 00]
17:42:36.560 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 00124B000EE99EED: Node update. NWK Address=0847
17:42:36.561 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 00124B000EE99EED: Node 0847 is not updated
17:42:36.562 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: NetworkAddressResponse [0847/0 -> 0000/0, cluster=8000, TID=00, status=NOT_SUPPORTED, ieeeAddrRemoteDev=null, nwkAddrRemoteDev=NULL, startIndex=null, nwkAddrAssocDevList=[]]
17:42:36.563 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NetworkAddressResponse [0847/0 -> 0000/0, cluster=8000, TID=00, status=NOT_SUPPORTED, ieeeAddrRemoteDev=null, nwkAddrRemoteDev=NULL, startIndex=null, nwkAddrAssocDevList=[]]
17:42:36.577 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-- ZB_FIND_DEVICE_CONFIRM (FE 0B 46 85 01 08 00 00 80 00 8C 00 00 84 00 49)
17:42:36.578 [DEBUG] [531.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=11, apiId=46 85, data=FE 0B 46 85 01 08 00 00 80 00 8C 00 00 84 00 49, checksum=49, error=false
17:42:36.580 [DEBUG] [ee.dongle.cc2531.ZigBeeDongleTiCc2531] - Unhandled ZToolPacket type 0x4685
17:42:39.977 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00124B000EE99DC7 queueTime=16037, state=FAILED, sendCnt=2, command=PowerDescriptorRequest [0000/0 -> 435D/0, cluster=0003, TID=8B, nwkAddrOfInterest=435D]]
17:42:39.979 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
17:42:39.980 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00124B000EE99DC7: transactionComplete, state=FAILED, outstanding=0
17:42:39.981 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00124B000EE99DC7: transactionComplete exceeded max retries 2
17:42:39.982 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction cancelled: ZigBeeTransaction [ieeeAddress=00124B000EE99DC7 queueTime=16042, state=CANCELLED, sendCnt=2, command=PowerDescriptorRequest [0000/0 -> 435D/0, cluster=0003, TID=8B, nwkAddrOfInterest=435D]]
17:42:39.984 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00124B000EE99DC7 queueTime=16044, state=CANCELLED, sendCnt=2, command=PowerDescriptorRequest [0000/0 -> 435D/0, cluster=0003, TID=8B, nwkAddrOfInterest=435D]]
17:42:39.984 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 00124B000EE99DC7: Node SVC Discovery: PowerDescriptorResponse returned null
17:42:39.985 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
17:42:39.985 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 00124B000EE99DC7: Node SVC Discovery: request POWER_DESCRIPTOR failed. Retry 1, wait 2109ms before retry.
17:42:39.986 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00124B000EE99DC7: transactionComplete but not outstanding, state=CANCELLED, outstanding=0
17:42:39.987 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3
17:42:39.988 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3
17:42:42.096 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 00124B000EE99DC7: Node SVC Discovery: running POWER_DESCRIPTOR
17:42:42.098 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00124B000EE99DC7: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00124B000EE99DC7 queueTime=0, state=WAITING, sendCnt=0, command=PowerDescriptorRequest [0000/0 -> 435D/0, cluster=0003, TID=--, nwkAddrOfInterest=435D]]
17:42:42.100 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=2, sleepy=0/3
17:42:42.101 [DEBUG] [.transaction.ZigBeeTransactionManager] - 435D/0: Sending ZigBeeTransaction [ieeeAddress=00124B000EE99DC7 queueTime=5, state=WAITING, sendCnt=0, command=PowerDescriptorRequest [0000/0 -> 435D/0, cluster=0003, TID=8D, nwkAddrOfInterest=435D]]
17:42:42.102 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
17:42:42.103 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: PowerDescriptorRequest [0000/0 -> 435D/0, cluster=0003, TID=8D, nwkAddrOfInterest=435D]
17:42:42.105 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=435D/0, profile=0000, cluster=0003, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=DF, rssi=--, lqi=--, payload=8D 5D 43]
17:42:42.106 [DEBUG] [531.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=13, apiId=24 01, data=FE 0D 24 01 5D 43 00 00 03 00 DF 30 08 03 8D 5D 43 42, checksum=42, error=false)
17:42:42.125 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
17:42:42.126 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=8D state=TX_ACK
17:42:42.127 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=8D, state=TX_ACK, outstanding=2
17:42:42.127 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=435D, TID=8D, event=TX_ACK, state=TRANSMITTED
17:42:44.512 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00124B000EE99EED queueTime=8033, state=FAILED, sendCnt=1, command=NetworkAddressRequest [0000/0 -> 0847/0, cluster=0000, TID=8C, ieeeAddr=00124B000EE99EED, requestType=0, startIndex=0]]
17:42:44.514 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
17:42:44.514 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00124B000EE99EED: transactionComplete, state=FAILED, outstanding=0
17:42:44.515 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00124B000EE99EED: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00124B000EE99EED queueTime=8035, state=WAITING, sendCnt=1, command=NetworkAddressRequest [0000/0 -> 0847/0, cluster=0000, TID=8C, ieeeAddr=00124B000EE99EED, requestType=0, startIndex=0]]
17:42:44.515 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=2, sleepy=0/3
17:42:44.515 [DEBUG] [.transaction.ZigBeeTransactionManager] - 0847/0: Sending ZigBeeTransaction [ieeeAddress=00124B000EE99EED queueTime=8036, state=WAITING, sendCnt=1, command=NetworkAddressRequest [0000/0 -> 0847/0, cluster=0000, TID=8C, ieeeAddr=00124B000EE99EED, requestType=0, startIndex=0]]
17:42:44.516 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
17:42:44.516 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0000/0 -> 0847/0, cluster=0000, TID=8C, ieeeAddr=00124B000EE99EED, requestType=0, startIndex=0]
17:42:44.517 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0847/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=E0, rssi=--, lqi=--, payload=8C ED 9E E9 0E 00 4B 12 00 00 00]
17:42:44.517 [DEBUG] [531.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=21, apiId=24 01, data=FE 15 24 01 47 08 00 00 00 00 E0 30 08 0B 8C ED 9E E9 0E 00 4B 12 00 00 00 ED, checksum=ED, error=false)
17:42:44.531 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
17:42:44.533 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=8C state=TX_ACK
17:42:44.534 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=8C, state=TX_ACK, outstanding=2
17:42:44.538 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=0847, TID=8C, event=TX_ACK, state=TRANSMITTED
17:42:44.829 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 0D 45 FF 47 08 00 00 80 00 8C 00 00 84 00 00 00 70)
17:42:44.830 [DEBUG] [531.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=13, apiId=45 FF, data=FE 0D 45 FF 47 08 00 00 80 00 8C 00 00 84 00 00 00 70, checksum=70, error=false
17:42:44.832 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0847/0, destinationAddress=0000/0, profile=0000, cluster=8000, addressMode=null, radius=0, apsSecurity=false, ackRequest=false, apsCounter=--, rssi=--, lqi=--, payload=00 84 00 00 00]
17:42:44.833 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 00124B000EE99EED: Node update. NWK Address=0847
17:42:44.834 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 00124B000EE99EED: Node 0847 is not updated
17:42:44.835 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: NetworkAddressResponse [0847/0 -> 0000/0, cluster=8000, TID=00, status=NOT_SUPPORTED, ieeeAddrRemoteDev=null, nwkAddrRemoteDev=NULL, startIndex=null, nwkAddrAssocDevList=[]]
17:42:44.837 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NetworkAddressResponse [0847/0 -> 0000/0, cluster=8000, TID=00, status=NOT_SUPPORTED, ieeeAddrRemoteDev=null, nwkAddrRemoteDev=NULL, startIndex=null, nwkAddrAssocDevList=[]]
17:42:44.850 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-- ZB_FIND_DEVICE_CONFIRM (FE 0B 46 85 01 08 00 00 80 00 8C 00 00 84 00 49)
17:42:44.851 [DEBUG] [531.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=11, apiId=46 85, data=FE 0B 46 85 01 08 00 00 80 00 8C 00 00 84 00 49, checksum=49, error=false
17:42:44.852 [DEBUG] [ee.dongle.cc2531.ZigBeeDongleTiCc2531] - Unhandled ZToolPacket type 0x4685
17:42:50.128 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00124B000EE99DC7 queueTime=8032, state=FAILED, sendCnt=1, command=PowerDescriptorRequest [0000/0 -> 435D/0, cluster=0003, TID=8D, nwkAddrOfInterest=435D]]
17:42:50.129 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
17:42:50.130 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00124B000EE99DC7: transactionComplete, state=FAILED, outstanding=0
17:42:50.131 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00124B000EE99DC7: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00124B000EE99DC7 queueTime=8035, state=WAITING, sendCnt=1, command=PowerDescriptorRequest [0000/0 -> 435D/0, cluster=0003, TID=8D, nwkAddrOfInterest=435D]]
17:42:50.132 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=2, sleepy=0/3
17:42:50.133 [DEBUG] [.transaction.ZigBeeTransactionManager] - 435D/0: Sending ZigBeeTransaction [ieeeAddress=00124B000EE99DC7 queueTime=8037, state=WAITING, sendCnt=1, command=PowerDescriptorRequest [0000/0 -> 435D/0, cluster=0003, TID=8D, nwkAddrOfInterest=435D]]
17:42:50.133 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
17:42:50.134 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: PowerDescriptorRequest [0000/0 -> 435D/0, cluster=0003, TID=8D, nwkAddrOfInterest=435D]
17:42:50.134 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=435D/0, profile=0000, cluster=0003, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=E1, rssi=--, lqi=--, payload=8D 5D 43]
17:42:50.135 [DEBUG] [531.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=13, apiId=24 01, data=FE 0D 24 01 5D 43 00 00 03 00 E1 30 08 03 8D 5D 43 7C, checksum=7C, error=false)
17:42:50.147 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
17:42:50.149 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=8D state=TX_ACK
17:42:50.150 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=8D, state=TX_ACK, outstanding=2
17:42:50.151 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=435D, TID=8D, event=TX_ACK, state=TRANSMITTED
17:42:50.828 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - 00124B000EE99DC7: Discovery: Starting discovery for existing device
17:42:50.830 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - 00124B000EE99EED: Discovery: Starting discovery for existing device
17:42:50.832 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - Starting ZigBee scan for zigbee:coordinator_cc2531:91ce26ffb4
17:42:50.833 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - Permit join to FFFC/0 for 60 seconds.
17:42:50.834 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - Broadcast: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=null queueTime=0, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true]]
17:42:50.834 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=2, outstandingQueues=2, sleepy=0/3
17:42:50.836 [DEBUG] [.transaction.ZigBeeTransactionManager] - FFFC/0: Sending ZigBeeTransaction [ieeeAddress=null queueTime=3, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=8E, permitDuration=60, tcSignificance=true]]
17:42:50.837 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 3 outstanding
17:42:50.837 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=8E, permitDuration=60, tcSignificance=true]
17:42:50.837 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=FFFC/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=E2, rssi=--, lqi=--, payload=8E 3C 01]
17:42:50.838 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00124B001CDD447D: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00124B001CDD447D queueTime=0, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true]]
17:42:50.838 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=3, outstandingQueues=2, sleepy=0/3
17:42:50.839 [DEBUG] [.transaction.ZigBeeTransactionManager] - 0000/0: Sending ZigBeeTransaction [ieeeAddress=00124B001CDD447D queueTime=0, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=8F, permitDuration=60, tcSignificance=true]]
17:42:50.839 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 4 outstanding
17:42:50.839 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=8F, permitDuration=60, tcSignificance=true]
17:42:50.840 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=E3, rssi=--, lqi=--, payload=8F 3C 01]
17:42:50.840 [INFO ] [gbee.discovery.ZigBeeDiscoveryService] - 00124B000EE99DC7: Starting ZigBee device discovery
17:42:50.840 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - 00124B000EE99DC7: Creating ZigBee device zigbee:device with bridge zigbee:coordinator_cc2531:91ce26ffb4
17:42:50.845 [INFO ] [gbee.discovery.ZigBeeDiscoveryService] - 00124B000EE99EED: Starting ZigBee device discovery
17:42:50.849 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - 00124B000EE99EED: Creating ZigBee device zigbee:device with bridge zigbee:coordinator_cc2531:91ce26ffb4
17:42:50.845 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - 00124B000EE99DC7: Node discovery not complete
17:42:50.851 [DEBUG] [531.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=13, apiId=24 01, data=FE 0D 24 01 FC FF 00 00 36 00 E2 30 08 03 8E 3C 01 77, checksum=77, error=false)
17:42:50.852 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - 00124B000EE99EED: Node discovery not complete
17:42:50.864 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
17:42:50.866 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=8E state=TX_ACK
17:42:50.867 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=8E, state=TX_ACK, outstanding=4
17:42:50.868 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=null queueTime=35, state=COMPLETE, sendCnt=1, command=ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=8E, permitDuration=60, tcSignificance=true]]
17:42:50.869 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 3 outstanding
17:42:50.870 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete, state=COMPLETE, outstanding=0
17:42:50.870 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=3, outstandingQueues=1, sleepy=0/3
17:42:50.871 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=FFFC, TID=8E, event=TX_ACK, state=COMPLETE
17:42:50.872 [DEBUG] [531.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=13, apiId=24 01, data=FE 0D 24 01 00 00 00 00 36 00 E3 30 08 03 8F 3C 01 74, checksum=74, error=false)
17:42:50.885 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
17:42:50.886 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=8F state=TX_ACK
17:42:50.888 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=8F, state=TX_ACK, outstanding=3
17:42:50.890 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00124B001CDD447D queueTime=52, state=COMPLETE, sendCnt=1, command=ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=8F, permitDuration=60, tcSignificance=true]]
17:42:50.892 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 2 outstanding
17:42:50.893 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00124B001CDD447D: transactionComplete, state=COMPLETE, outstanding=0
17:42:50.894 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=2, outstandingQueues=1, sleepy=0/3
17:42:50.895 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=0000, TID=8F, event=TX_ACK, state=COMPLETE
17:42:50.905 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 01 45 CB 3C B3)
17:42:50.906 [DEBUG] [531.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=1, apiId=45 CB, data=FE 01 45 CB 3C B3, checksum=B3, error=false
17:42:50.907 [DEBUG] [ee.dongle.cc2531.ZigBeeDongleTiCc2531] - Unhandled ZToolPacket type 0x45cb
17:42:50.908 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 03 45 B6 00 00 00 F0)
17:42:50.909 [DEBUG] [531.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=3, apiId=45 B6, data=FE 03 45 B6 00 00 00 F0, checksum=F0, error=false
17:42:50.910 [DEBUG] [ee.dongle.cc2531.ZigBeeDongleTiCc2531] - Unhandled ZToolPacket type 0x45b6
17:42:50.910 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 0A 45 FF 00 00 00 36 80 00 8F 00 00 00 89)
17:42:50.911 [DEBUG] [531.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=10, apiId=45 FF, data=FE 0A 45 FF 00 00 00 36 80 00 8F 00 00 00 89, checksum=89, error=false
17:42:50.913 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=8036, addressMode=null, radius=0, apsSecurity=false, ackRequest=false, apsCounter=--, rssi=--, lqi=--, payload=00 00]
17:42:50.914 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 00124B001CDD447D: Node update. NWK Address=0000
17:42:50.915 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 00124B001CDD447D: Node 0000 is not updated
17:42:50.916 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningResponse [0000/0 -> 0000/0, cluster=8036, TID=00, status=SUCCESS]
17:42:50.917 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0000/0 -> 0000/0, cluster=8036, TID=00, status=SUCCESS]
17:42:52.538 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00124B000EE99EED queueTime=16059, state=FAILED, sendCnt=2, command=NetworkAddressRequest [0000/0 -> 0847/0, cluster=0000, TID=8C, ieeeAddr=00124B000EE99EED, requestType=0, startIndex=0]]
17:42:52.540 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
17:42:52.541 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00124B000EE99EED: transactionComplete, state=FAILED, outstanding=0
17:42:52.541 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00124B000EE99EED: transactionComplete exceeded max retries 2
17:42:52.543 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction cancelled: ZigBeeTransaction [ieeeAddress=00124B000EE99EED queueTime=16064, state=CANCELLED, sendCnt=2, command=NetworkAddressRequest [0000/0 -> 0847/0, cluster=0000, TID=8C, ieeeAddr=00124B000EE99EED, requestType=0, startIndex=0]]
17:42:52.544 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 00124B000EE99EED: Node SVC Discovery: NetworkAddressRequest returned null
17:42:52.544 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00124B000EE99EED queueTime=16065, state=CANCELLED, sendCnt=2, command=NetworkAddressRequest [0000/0 -> 0847/0, cluster=0000, TID=8C, ieeeAddr=00124B000EE99EED, requestType=0, startIndex=0]]
17:42:52.546 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
17:42:52.547 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00124B000EE99EED: transactionComplete but not outstanding, state=CANCELLED, outstanding=0
17:42:52.548 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3
17:42:52.548 [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 -> FFFF/0, cluster=0000, TID=--, ieeeAddr=00124B000EE99EED, requestType=0, startIndex=0]]
17:42:52.550 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=2, sleepy=0/3
17:42:52.551 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=2, sleepy=0/3
17:42:53.362 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 07 45 83 5D 43 00 5D 43 21 82 62)
17:42:53.363 [DEBUG] [531.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=7, apiId=45 83, data=FE 07 45 83 5D 43 00 5D 43 21 82 62, checksum=62, error=false
17:42:53.364 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=435D/0, destinationAddress=0000/0, profile=0000, cluster=8003, addressMode=null, radius=0, apsSecurity=false, ackRequest=false, apsCounter=--, rssi=--, lqi=--, payload=43 00 5D 43 21 82]
17:42:53.365 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 00124B000EE99DC7: Node update. NWK Address=435D
17:42:53.365 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 00124B000EE99DC7: Node 435D is not updated
17:42:53.366 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: PowerDescriptorResponse [435D/0 -> 0000/0, cluster=8003, TID=43, status=SUCCESS, nwkAddrOfInterest=435D, powerDescriptor=PowerDescriptor [currentPowerMode=RECEIVER_ON_PERIODICALLY, availablePowerSources=[RECHARGABLE_BATTERY], currentPowerSource=RECHARGABLE_BATTERY, powerLevel=MEDIUM]]
17:42:53.367 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionCommand: PowerDescriptorResponse [435D/0 -> 0000/0, cluster=8003, TID=43, status=SUCCESS, nwkAddrOfInterest=435D, powerDescriptor=PowerDescriptor [currentPowerMode=RECEIVER_ON_PERIODICALLY, availablePowerSources=[RECHARGABLE_BATTERY], currentPowerSource=RECHARGABLE_BATTERY, powerLevel=MEDIUM]]
17:42:53.367 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 0E 45 FF 5D 43 00 03 80 00 8D 00 00 00 5D 43 21 82 19)
17:42:53.369 [DEBUG] [531.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=14, apiId=45 FF, data=FE 0E 45 FF 5D 43 00 03 80 00 8D 00 00 00 5D 43 21 82 19, checksum=19, error=false
17:42:53.369 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=435D/0, destinationAddress=0000/0, profile=0000, cluster=8003, addressMode=null, radius=0, apsSecurity=false, ackRequest=false, apsCounter=--, rssi=--, lqi=--, payload=00 00 5D 43 21 82]
17:42:53.370 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 00124B000EE99DC7: Node update. NWK Address=435D
17:42:53.370 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 00124B000EE99DC7: Node 435D is not updated
17:42:53.370 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: PowerDescriptorResponse [435D/0 -> 0000/0, cluster=8003, TID=00, status=SUCCESS, nwkAddrOfInterest=435D, powerDescriptor=PowerDescriptor [currentPowerMode=RECEIVER_ON_PERIODICALLY, availablePowerSources=[RECHARGABLE_BATTERY], currentPowerSource=RECHARGABLE_BATTERY, powerLevel=MEDIUM]]
17:42:53.371 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionCommand: PowerDescriptorResponse [435D/0 -> 0000/0, cluster=8003, TID=00, status=SUCCESS, nwkAddrOfInterest=435D, powerDescriptor=PowerDescriptor [currentPowerMode=RECEIVER_ON_PERIODICALLY, availablePowerSources=[RECHARGABLE_BATTERY], currentPowerSource=RECHARGABLE_BATTERY, powerLevel=MEDIUM]]
17:42:58.151 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00124B000EE99DC7 queueTime=16055, state=FAILED, sendCnt=2, command=PowerDescriptorRequest [0000/0 -> 435D/0, cluster=0003, TID=8D, nwkAddrOfInterest=435D]]
17:42:58.152 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
17:42:58.153 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00124B000EE99DC7: transactionComplete, state=FAILED, outstanding=0
17:42:58.154 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00124B000EE99DC7: transactionComplete exceeded max retries 2
17:42:58.155 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction cancelled: ZigBeeTransaction [ieeeAddress=00124B000EE99DC7 queueTime=16059, state=CANCELLED, sendCnt=2, command=PowerDescriptorRequest [0000/0 -> 435D/0, cluster=0003, TID=8D, nwkAddrOfInterest=435D]]
17:42:58.156 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 00124B000EE99DC7: Node SVC Discovery: PowerDescriptorResponse returned null
17:42:58.157 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 00124B000EE99DC7: Node SVC Discovery: request POWER_DESCRIPTOR failed. Retry 2, wait 2109ms before retry.
17:42:58.159 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00124B000EE99DC7 queueTime=16062, state=CANCELLED, sendCnt=2, command=PowerDescriptorRequest [0000/0 -> 435D/0, cluster=0003, TID=8D, nwkAddrOfInterest=435D]]
17:42:58.160 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
17:42:58.161 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00124B000EE99DC7: transactionComplete but not outstanding, state=CANCELLED, outstanding=0
17:42:58.162 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=2, sleepy=0/3
17:42:58.163 [DEBUG] [.transaction.ZigBeeTransactionManager] - FFFF/0: Sending ZigBeeTransaction [ieeeAddress=null queueTime=5615, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=90, ieeeAddr=00124B000EE99EED, requestType=0, startIndex=0]]
17:42:58.164 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
17:42:58.165 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=90, ieeeAddr=00124B000EE99EED, requestType=0, startIndex=0]
17:42:58.166 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=FFFF/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=E4, rssi=--, lqi=--, payload=90 ED 9E E9 0E 00 4B 12 00 00 00]
17:42:58.168 [DEBUG] [531.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=21, apiId=24 01, data=FE 15 24 01 FF FF 00 00 00 00 E4 30 08 0B 90 ED 9E E9 0E 00 4B 12 00 00 00 BA, checksum=BA, error=false)
17:42:58.169 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3
17:42:58.191 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
17:42:58.192 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=90 state=TX_ACK
17:42:58.193 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=90, state=TX_ACK, outstanding=1
17:42:58.194 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=FFFF, TID=90, event=TX_ACK, state=TRANSMITTED
17:43:00.267 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 00124B000EE99DC7: Node SVC Discovery: running POWER_DESCRIPTOR
17:43:00.268 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00124B000EE99DC7: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00124B000EE99DC7 queueTime=0, state=WAITING, sendCnt=0, command=PowerDescriptorRequest [0000/0 -> 435D/0, cluster=0003, TID=--, nwkAddrOfInterest=435D]]
17:43:00.269 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=2, sleepy=0/3
17:43:00.269 [DEBUG] [.transaction.ZigBeeTransactionManager] - 435D/0: Sending ZigBeeTransaction [ieeeAddress=00124B000EE99DC7 queueTime=1, state=WAITING, sendCnt=0, command=PowerDescriptorRequest [0000/0 -> 435D/0, cluster=0003, TID=91, nwkAddrOfInterest=435D]]
17:43:00.270 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
17:43:00.270 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: PowerDescriptorRequest [0000/0 -> 435D/0, cluster=0003, TID=91, nwkAddrOfInterest=435D]
17:43:00.271 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=435D/0, profile=0000, cluster=0003, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=E5, rssi=--, lqi=--, payload=91 5D 43]
17:43:00.272 [DEBUG] [531.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=13, apiId=24 01, data=FE 0D 24 01 5D 43 00 00 03 00 E5 30 08 03 91 5D 43 64, checksum=64, error=false)
17:43:00.285 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
17:43:00.287 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=91 state=TX_ACK
17:43:00.288 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=91, state=TX_ACK, outstanding=2
17:43:00.289 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=435D, TID=91, event=TX_ACK, state=TRANSMITTED

17:43:06.194 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=null queueTime=13646, state=FAILED, sendCnt=1, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=90, ieeeAddr=00124B000EE99EED, requestType=0, startIndex=0]]
17:43:06.195 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
17:43:06.196 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete, state=FAILED, outstanding=0
17:43:06.196 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete exceeded max retries 1
17:43:06.197 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction cancelled: ZigBeeTransaction [ieeeAddress=null queueTime=13649, state=CANCELLED, sendCnt=1, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=90, ieeeAddr=00124B000EE99EED, requestType=0, startIndex=0]]
17:43:06.198 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 00124B000EE99EED: Node SVC Discovery: NetworkAddressRequest returned null
17:43:06.198 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 00124B000EE99EED: Node SVC Discovery: NetworkAddressRequest failed after unicast and broadcast
17:43:06.199 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 00124B000EE99EED: Node SVC Discovery: request NWK_ADDRESS failed. Retry 4, wait 4298ms before retry.
17:43:06.199 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=null queueTime=13650, state=CANCELLED, sendCnt=1, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=90, ieeeAddr=00124B000EE99EED, requestType=0, startIndex=0]]
17:43:06.200 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
17:43:06.202 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete but not outstanding, state=CANCELLED, outstanding=0
17:43:06.202 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3
17:43:06.204 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3
17:43:08.289 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00124B000EE99DC7 queueTime=8021, state=FAILED, sendCnt=1, command=PowerDescriptorRequest [0000/0 -> 435D/0, cluster=0003, TID=91, nwkAddrOfInterest=435D]]
17:43:08.290 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
17:43:08.291 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00124B000EE99DC7: transactionComplete, state=FAILED, outstanding=0
17:43:08.292 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00124B000EE99DC7: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00124B000EE99DC7 queueTime=8024, state=WAITING, sendCnt=1, command=PowerDescriptorRequest [0000/0 -> 435D/0, cluster=0003, TID=91, nwkAddrOfInterest=435D]]
17:43:08.294 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=2, sleepy=0/3
17:43:08.294 [DEBUG] [.transaction.ZigBeeTransactionManager] - 435D/0: Sending ZigBeeTransaction [ieeeAddress=00124B000EE99DC7 queueTime=8026, state=WAITING, sendCnt=1, command=PowerDescriptorRequest [0000/0 -> 435D/0, cluster=0003, TID=91, nwkAddrOfInterest=435D]]
17:43:08.294 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
17:43:08.295 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: PowerDescriptorRequest [0000/0 -> 435D/0, cluster=0003, TID=91, nwkAddrOfInterest=435D]
17:43:08.295 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=435D/0, profile=0000, cluster=0003, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=E6, rssi=--, lqi=--, payload=91 5D 43]
17:43:08.295 [DEBUG] [531.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=13, apiId=24 01, data=FE 0D 24 01 5D 43 00 00 03 00 E6 30 08 03 91 5D 43 67, checksum=67, error=false)
17:43:08.308 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
17:43:08.309 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=91 state=TX_ACK
17:43:08.310 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=91, state=TX_ACK, outstanding=1
17:43:08.311 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=435D, TID=91, event=TX_ACK, state=TRANSMITTED
17:43:10.498 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 00124B000EE99EED: Node SVC Discovery: running NWK_ADDRESS
17:43:10.499 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00124B000EE99EED: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00124B000EE99EED queueTime=0, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> 0847/0, cluster=0000, TID=--, ieeeAddr=00124B000EE99EED, requestType=0, startIndex=0]]
17:43:10.500 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=2, sleepy=0/3
17:43:10.500 [DEBUG] [.transaction.ZigBeeTransactionManager] - 0847/0: Sending ZigBeeTransaction [ieeeAddress=00124B000EE99EED queueTime=1, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> 0847/0, cluster=0000, TID=92, ieeeAddr=00124B000EE99EED, requestType=0, startIndex=0]]
17:43:10.501 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
17:43:10.503 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0000/0 -> 0847/0, cluster=0000, TID=92, ieeeAddr=00124B000EE99EED, requestType=0, startIndex=0]
17:43:10.504 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0847/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=E7, rssi=--, lqi=--, payload=92 ED 9E E9 0E 00 4B 12 00 00 00]
17:43:10.506 [DEBUG] [531.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=21, apiId=24 01, data=FE 15 24 01 47 08 00 00 00 00 E7 30 08 0B 92 ED 9E E9 0E 00 4B 12 00 00 00 F4, checksum=F4, error=false)
17:43:10.520 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
17:43:10.521 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=92 state=TX_ACK
17:43:10.522 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=92, state=TX_ACK, outstanding=2
17:43:10.523 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=0847, TID=92, event=TX_ACK, state=TRANSMITTED
17:43:10.978 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 0D 45 FF 47 08 00 00 80 00 92 00 00 84 00 00 00 6E)
17:43:10.979 [DEBUG] [531.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=13, apiId=45 FF, data=FE 0D 45 FF 47 08 00 00 80 00 92 00 00 84 00 00 00 6E, checksum=6E, error=false
17:43:10.979 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0847/0, destinationAddress=0000/0, profile=0000, cluster=8000, addressMode=null, radius=0, apsSecurity=false, ackRequest=false, apsCounter=--, rssi=--, lqi=--, payload=00 84 00 00 00]
17:43:10.980 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 00124B000EE99EED: Node update. NWK Address=0847
17:43:10.980 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 00124B000EE99EED: Node 0847 is not updated
17:43:10.981 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: NetworkAddressResponse [0847/0 -> 0000/0, cluster=8000, TID=00, status=NOT_SUPPORTED, ieeeAddrRemoteDev=null, nwkAddrRemoteDev=NULL, startIndex=null, nwkAddrAssocDevList=[]]
17:43:10.981 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NetworkAddressResponse [0847/0 -> 0000/0, cluster=8000, TID=00, status=NOT_SUPPORTED, ieeeAddrRemoteDev=null, nwkAddrRemoteDev=NULL, startIndex=null, nwkAddrAssocDevList=[]]
17:43:11.021 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-- ZB_FIND_DEVICE_CONFIRM (FE 0B 46 85 01 08 00 00 80 00 92 00 00 84 00 57)
17:43:11.022 [DEBUG] [531.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=11, apiId=46 85, data=FE 0B 46 85 01 08 00 00 80 00 92 00 00 84 00 57, checksum=57, error=false
17:43:11.023 [DEBUG] [ee.dongle.cc2531.ZigBeeDongleTiCc2531] - Unhandled ZToolPacket type 0x4685
17:43:16.311 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00124B000EE99DC7 queueTime=16043, state=FAILED, sendCnt=2, command=PowerDescriptorRequest [0000/0 -> 435D/0, cluster=0003, TID=91, nwkAddrOfInterest=435D]]
17:43:16.312 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
17:43:16.312 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00124B000EE99DC7: transactionComplete, state=FAILED, outstanding=0
17:43:16.313 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00124B000EE99DC7: transactionComplete exceeded max retries 2
17:43:16.314 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction cancelled: ZigBeeTransaction [ieeeAddress=00124B000EE99DC7 queueTime=16045, state=CANCELLED, sendCnt=2, command=PowerDescriptorRequest [0000/0 -> 435D/0, cluster=0003, TID=91, nwkAddrOfInterest=435D]]
17:43:16.315 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 00124B000EE99DC7: Node SVC Discovery: PowerDescriptorResponse returned null
17:43:16.315 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 00124B000EE99DC7: Node SVC Discovery: request POWER_DESCRIPTOR failed. Retry 3, wait 6327ms before retry.
17:43:16.316 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00124B000EE99DC7 queueTime=16048, state=CANCELLED, sendCnt=2, command=PowerDescriptorRequest [0000/0 -> 435D/0, cluster=0003, TID=91, nwkAddrOfInterest=435D]]
17:43:16.317 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
17:43:16.318 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00124B000EE99DC7: transactionComplete but not outstanding, state=CANCELLED, outstanding=0
17:43:16.319 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3
17:43:16.319 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3
17:43:18.523 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00124B000EE99EED queueTime=8024, state=FAILED, sendCnt=1, command=NetworkAddressRequest [0000/0 -> 0847/0, cluster=0000, TID=92, ieeeAddr=00124B000EE99EED, requestType=0, startIndex=0]]
17:43:18.525 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
17:43:18.525 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00124B000EE99EED: transactionComplete, state=FAILED, outstanding=0
17:43:18.526 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00124B000EE99EED: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00124B000EE99EED queueTime=8027, state=WAITING, sendCnt=1, command=NetworkAddressRequest [0000/0 -> 0847/0, cluster=0000, TID=92, ieeeAddr=00124B000EE99EED, requestType=0, startIndex=0]]
17:43:18.527 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=2, sleepy=0/3
17:43:18.527 [DEBUG] [.transaction.ZigBeeTransactionManager] - 0847/0: Sending ZigBeeTransaction [ieeeAddress=00124B000EE99EED queueTime=8028, state=WAITING, sendCnt=1, command=NetworkAddressRequest [0000/0 -> 0847/0, cluster=0000, TID=92, ieeeAddr=00124B000EE99EED, requestType=0, startIndex=0]]
17:43:18.528 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
17:43:18.528 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0000/0 -> 0847/0, cluster=0000, TID=92, ieeeAddr=00124B000EE99EED, requestType=0, startIndex=0]
17:43:18.528 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0847/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=E8, rssi=--, lqi=--, payload=92 ED 9E E9 0E 00 4B 12 00 00 00]
17:43:18.529 [DEBUG] [531.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=21, apiId=24 01, data=FE 15 24 01 47 08 00 00 00 00 E8 30 08 0B 92 ED 9E E9 0E 00 4B 12 00 00 00 FB, checksum=FB, error=false)
17:43:18.542 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
17:43:18.543 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=92 state=TX_ACK
17:43:18.543 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=92, state=TX_ACK, outstanding=1
17:43:18.544 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=0847, TID=92, event=TX_ACK, state=TRANSMITTED
17:43:18.705 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 0D 45 FF 47 08 00 00 80 00 92 00 00 84 00 00 00 6E)
17:43:18.706 [DEBUG] [531.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=13, apiId=45 FF, data=FE 0D 45 FF 47 08 00 00 80 00 92 00 00 84 00 00 00 6E, checksum=6E, error=false
17:43:18.706 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0847/0, destinationAddress=0000/0, profile=0000, cluster=8000, addressMode=null, radius=0, apsSecurity=false, ackRequest=false, apsCounter=--, rssi=--, lqi=--, payload=00 84 00 00 00]
17:43:18.707 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 00124B000EE99EED: Node update. NWK Address=0847
17:43:18.707 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 00124B000EE99EED: Node 0847 is not updated
17:43:18.708 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: NetworkAddressResponse [0847/0 -> 0000/0, cluster=8000, TID=00, status=NOT_SUPPORTED, ieeeAddrRemoteDev=null, nwkAddrRemoteDev=NULL, startIndex=null, nwkAddrAssocDevList=[]]
17:43:18.708 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NetworkAddressResponse [0847/0 -> 0000/0, cluster=8000, TID=00, status=NOT_SUPPORTED, ieeeAddrRemoteDev=null, nwkAddrRemoteDev=NULL, startIndex=null, nwkAddrAssocDevList=[]]
17:43:18.725 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-- ZB_FIND_DEVICE_CONFIRM (FE 0B 46 85 01 08 00 00 80 00 92 00 00 84 00 57)
17:43:18.726 [DEBUG] [531.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=11, apiId=46 85, data=FE 0B 46 85 01 08 00 00 80 00 92 00 00 84 00 57, checksum=57, error=false
17:43:18.727 [DEBUG] [ee.dongle.cc2531.ZigBeeDongleTiCc2531] - Unhandled ZToolPacket type 0x4685
17:43:22.643 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 00124B000EE99DC7: Node SVC Discovery: running POWER_DESCRIPTOR
17:43:22.645 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00124B000EE99DC7: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00124B000EE99DC7 queueTime=0, state=WAITING, sendCnt=0, command=PowerDescriptorRequest [0000/0 -> 435D/0, cluster=0003, TID=--, nwkAddrOfInterest=435D]]
17:43:22.646 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=2, sleepy=0/3
17:43:22.647 [DEBUG] [.transaction.ZigBeeTransactionManager] - 435D/0: Sending ZigBeeTransaction [ieeeAddress=00124B000EE99DC7 queueTime=3, state=WAITING, sendCnt=0, command=PowerDescriptorRequest [0000/0 -> 435D/0, cluster=0003, TID=93, nwkAddrOfInterest=435D]]
17:43:22.648 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
17:43:22.648 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: PowerDescriptorRequest [0000/0 -> 435D/0, cluster=0003, TID=93, nwkAddrOfInterest=435D]
17:43:22.649 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=435D/0, profile=0000, cluster=0003, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=E9, rssi=--, lqi=--, payload=93 5D 43]
17:43:22.650 [DEBUG] [531.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=13, apiId=24 01, data=FE 0D 24 01 5D 43 00 00 03 00 E9 30 08 03 93 5D 43 6A, checksum=6A, error=false)
17:43:22.663 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
17:43:22.664 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=93 state=TX_ACK
17:43:22.665 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=93, state=TX_ACK, outstanding=2
17:43:22.666 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=435D, TID=93, event=TX_ACK, state=TRANSMITTED
17:43:26.544 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00124B000EE99EED queueTime=16045, state=FAILED, sendCnt=2, command=NetworkAddressRequest [0000/0 -> 0847/0, cluster=0000, TID=92, ieeeAddr=00124B000EE99EED, requestType=0, startIndex=0]]
17:43:26.546 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
17:43:26.547 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00124B000EE99EED: transactionComplete, state=FAILED, outstanding=0
17:43:26.548 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00124B000EE99EED: transactionComplete exceeded max retries 2
17:43:26.548 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction cancelled: ZigBeeTransaction [ieeeAddress=00124B000EE99EED queueTime=16049, state=CANCELLED, sendCnt=2, command=NetworkAddressRequest [0000/0 -> 0847/0, cluster=0000, TID=92, ieeeAddr=00124B000EE99EED, requestType=0, startIndex=0]]
17:43:26.549 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00124B000EE99EED queueTime=16050, state=CANCELLED, sendCnt=2, command=NetworkAddressRequest [0000/0 -> 0847/0, cluster=0000, TID=92, ieeeAddr=00124B000EE99EED, requestType=0, startIndex=0]]
17:43:26.549 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
17:43:26.550 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00124B000EE99EED: transactionComplete but not outstanding, state=CANCELLED, outstanding=0
17:43:26.550 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3
17:43:26.551 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3
17:43:26.549 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 00124B000EE99EED: Node SVC Discovery: NetworkAddressRequest returned null
17:43:26.552 [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 -> FFFF/0, cluster=0000, TID=--, ieeeAddr=00124B000EE99EED, requestType=0, startIndex=0]]
17:43:26.552 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=2, sleepy=0/3
17:43:26.553 [DEBUG] [.transaction.ZigBeeTransactionManager] - FFFF/0: Sending ZigBeeTransaction [ieeeAddress=null queueTime=1, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=94, ieeeAddr=00124B000EE99EED, requestType=0, startIndex=0]]
17:43:26.553 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
17:43:26.554 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=94, ieeeAddr=00124B000EE99EED, requestType=0, startIndex=0]
17:43:26.554 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=FFFF/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=EA, rssi=--, lqi=--, payload=94 ED 9E E9 0E 00 4B 12 00 00 00]
17:43:26.555 [DEBUG] [531.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=21, apiId=24 01, data=FE 15 24 01 FF FF 00 00 00 00 EA 30 08 0B 94 ED 9E E9 0E 00 4B 12 00 00 00 B0, checksum=B0, error=false)
17:43:26.571 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
17:43:26.572 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=94 state=TX_ACK
17:43:26.573 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=94, state=TX_ACK, outstanding=2
17:43:26.574 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=FFFF, TID=94, event=TX_ACK, state=TRANSMITTED
17:43:27.305 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 0D 45 C9 47 08 ED 9E E9 0E 00 4B 12 00 00 00 00 03)
17:43:27.308 [DEBUG] [531.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=13, apiId=45 C9, data=FE 0D 45 C9 47 08 ED 9E E9 0E 00 4B 12 00 00 00 00 03, checksum=03, error=false
17:43:27.308 [DEBUG] [ee.dongle.cc2531.ZigBeeDongleTiCc2531] - Unhandled ZToolPacket type 0x45c9
17:43:30.667 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00124B000EE99DC7 queueTime=8022, state=FAILED, sendCnt=1, command=PowerDescriptorRequest [0000/0 -> 435D/0, cluster=0003, TID=93, nwkAddrOfInterest=435D]]
17:43:30.667 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
17:43:30.668 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00124B000EE99DC7: transactionComplete, state=FAILED, outstanding=0
17:43:30.669 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00124B000EE99DC7: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00124B000EE99DC7 queueTime=8025, state=WAITING, sendCnt=1, command=PowerDescriptorRequest [0000/0 -> 435D/0, cluster=0003, TID=93, nwkAddrOfInterest=435D]]
17:43:30.670 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=2, sleepy=0/3
17:43:30.670 [DEBUG] [.transaction.ZigBeeTransactionManager] - 435D/0: Sending ZigBeeTransaction [ieeeAddress=00124B000EE99DC7 queueTime=8026, state=WAITING, sendCnt=1, command=PowerDescriptorRequest [0000/0 -> 435D/0, cluster=0003, TID=93, nwkAddrOfInterest=435D]]
17:43:30.671 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
17:43:30.671 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: PowerDescriptorRequest [0000/0 -> 435D/0, cluster=0003, TID=93, nwkAddrOfInterest=435D]
17:43:30.672 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=435D/0, profile=0000, cluster=0003, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=EB, rssi=--, lqi=--, payload=93 5D 43]
17:43:30.673 [DEBUG] [531.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=13, apiId=24 01, data=FE 0D 24 01 5D 43 00 00 03 00 EB 30 08 03 93 5D 43 68, checksum=68, error=false)
17:43:30.686 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
17:43:30.687 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=93 state=TX_ACK
17:43:30.688 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=93, state=TX_ACK, outstanding=2
17:43:30.689 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=435D, TID=93, event=TX_ACK, state=TRANSMITTED
17:43:32.121 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 0C 45 CA 78 D4 ED 9E E9 0E 00 4B 12 00 00 00 E2)
17:43:32.122 [DEBUG] [531.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=12, apiId=45 CA, data=FE 0C 45 CA 78 D4 ED 9E E9 0E 00 4B 12 00 00 00 E2, checksum=E2, error=false
17:43:32.123 [DEBUG] [ee.dongle.cc2531.ZigBeeDongleTiCc2531] - Unhandled ZToolPacket type 0x45ca
17:43:34.038 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 0C 45 CA 78 D4 ED 9E E9 0E 00 4B 12 00 00 00 E2)
17:43:34.039 [DEBUG] [531.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=12, apiId=45 CA, data=FE 0C 45 CA 78 D4 ED 9E E9 0E 00 4B 12 00 00 00 E2, checksum=E2, error=false
17:43:34.040 [DEBUG] [ee.dongle.cc2531.ZigBeeDongleTiCc2531] - Unhandled ZToolPacket type 0x45ca
17:43:34.575 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=null queueTime=8023, state=FAILED, sendCnt=1, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=94, ieeeAddr=00124B000EE99EED, requestType=0, startIndex=0]]
17:43:34.576 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
17:43:34.577 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete, state=FAILED, outstanding=0
17:43:34.578 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete exceeded max retries 1
17:43:34.578 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction cancelled: ZigBeeTransaction [ieeeAddress=null queueTime=8026, state=CANCELLED, sendCnt=1, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=94, ieeeAddr=00124B000EE99EED, requestType=0, startIndex=0]]
17:43:34.583 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=null queueTime=8030, state=CANCELLED, sendCnt=1, command=NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=94, ieeeAddr=00124B000EE99EED, requestType=0, startIndex=0]]
17:43:34.583 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 00124B000EE99EED: Node SVC Discovery: NetworkAddressRequest returned null
17:43:34.586 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 00124B000EE99EED: Node SVC Discovery: NetworkAddressRequest failed after unicast and broadcast
17:43:34.588 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 00124B000EE99EED: Node SVC Discovery: request NWK_ADDRESS failed. Retry 5, wait 8596ms before retry.
17:43:34.588 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
17:43:34.589 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete but not outstanding, state=CANCELLED, outstanding=0
17:43:34.591 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3
17:43:34.591 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3
17:43:34.651 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 0D 45 C1 78 D4 78 D4 ED 9E E9 0E 00 4B 12 00 80 C4)
17:43:34.652 [DEBUG] [531.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=13, apiId=45 C1, data=FE 0D 45 C1 78 D4 78 D4 ED 9E E9 0E 00 4B 12 00 80 C4, checksum=C4, error=false
17:43:34.652 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=D478/0, destinationAddress=0000/0, profile=0000, cluster=0013, addressMode=null, radius=0, apsSecurity=false, ackRequest=false, apsCounter=--, rssi=--, lqi=--, payload=D4 78 D4 ED 9E E9 0E 00 4B 12 00 80]
17:43:34.653 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - Incoming message from unknown node D478: Notifying announce listeners
17:43:34.654 [DEBUG] [app.discovery.ZigBeeNetworkDiscoverer] - NWK Discovery for D478 scheduling node discovery
17:43:34.654 [DEBUG] [app.discovery.ZigBeeNetworkDiscoverer] - NWK Discovery for D478 starting node discovery
17:43:34.655 [DEBUG] [.transaction.ZigBeeTransactionManager] - Attempt to send command with unknown destination: ZigBeeTransaction [ieeeAddress=null queueTime=-, state=WAITING, sendCnt=0, command=IeeeAddressRequest [0000/0 -> D478/0, cluster=0001, TID=--, nwkAddrOfInterest=D478, requestType=0, startIndex=0]]
17:43:34.655 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: DeviceAnnounce [D478/0 -> 0000/0, cluster=0013, TID=D4, nwkAddrOfInterest=D478, ieeeAddr=00124B000EE99EED, capability=80]
17:43:34.657 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - Default: Added transaction to queue, len=3, transaction=ZigBeeTransaction [ieeeAddress=null queueTime=0, state=WAITING, sendCnt=0, command=IeeeAddressRequest [0000/0 -> D478/0, cluster=0001, TID=--, nwkAddrOfInterest=D478, requestType=0, startIndex=0]]
17:43:34.657 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionCommand: DeviceAnnounce [D478/0 -> 0000/0, cluster=0013, TID=D4, nwkAddrOfInterest=D478, ieeeAddr=00124B000EE99EED, capability=80]
17:43:34.659 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3
17:43:34.659 [DEBUG] [app.discovery.ZigBeeNetworkDiscoverer] - 00124B000EE99EED: Device announce received. From D478, for D478
17:43:34.660 [DEBUG] [app.discovery.ZigBeeNetworkDiscoverer] - 00124B000EE99EED: NWK Discovery add node D478
17:43:34.661 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 00124B000EE99EED: Updating node NWK=D478
17:43:34.661 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 00124B000EE99EED: Node update. NWK Address=D478
17:43:34.661 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode  ] - 00124B000EE99EED: Network address updated from 2119 to 54392
17:43:34.659 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 14 45 FF 78 D4 01 13 00 00 00 00 00 78 D4 ED 9E E9 0E 00 4B 12 00 80 F1)
17:43:34.662 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 00124B000EE99EED: Node D478 discovery is not complete - sending nodeUpdated notification to inform listeners
17:43:34.662 [DEBUG] [database.ZigBeeNetworkDatabaseManager] - 00124B000EE99EED: Data store: Deferring write for 250ms.
17:43:34.663 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00124B000EE99EED: Set profile to ZigBeeTransactionProfile [maxOutstandingTransactions=1, interTransactionDelay=50, maxRetries=2]
17:43:34.662 [DEBUG] [531.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=20, apiId=45 FF, data=FE 14 45 FF 78 D4 01 13 00 00 00 00 00 78 D4 ED 9E E9 0E 00 4B 12 00 80 F1, checksum=F1, error=false
17:43:34.663 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=D478/0, destinationAddress=0000/0, profile=0000, cluster=0013, addressMode=null, radius=0, apsSecurity=false, ackRequest=false, apsCounter=--, rssi=--, lqi=--, payload=00 78 D4 ED 9E E9 0E 00 4B 12 00 80]
17:43:34.664 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 00124B000EE99EED: Node update. NWK Address=D478
17:43:34.664 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 00124B000EE99EED: Node D478 is not updated
17:43:34.665 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: DeviceAnnounce [D478/0 -> 0000/0, cluster=0013, TID=00, nwkAddrOfInterest=D478, ieeeAddr=00124B000EE99EED, capability=80]
17:43:34.665 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionCommand: DeviceAnnounce [D478/0 -> 0000/0, cluster=0013, TID=00, nwkAddrOfInterest=D478, ieeeAddr=00124B000EE99EED, capability=80]
17:43:34.666 [DEBUG] [app.discovery.ZigBeeNetworkDiscoverer] - 00124B000EE99EED: Device announce received. From D478, for D478
17:43:34.666 [DEBUG] [app.discovery.ZigBeeNetworkDiscoverer] - 00124B000EE99EED: NWK Discovery add node D478
17:43:34.666 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 00124B000EE99EED: Updating node NWK=D478
17:43:34.667 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 00124B000EE99EED: Node update. NWK Address=D478
17:43:34.667 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 00124B000EE99EED: Node D478 is not updated
17:43:34.676 [DEBUG] [pp.discovery.ZigBeeDiscoveryExtension] - 00124B000EE99EED: DISCOVERY Extension: Creating new discoverer for node
17:43:34.676 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 00124B000EE99EED: Node updated - ZigBeeNode [state=ONLINE, IEEE=00124B000EE99EED, NWK=D478, endpoints=[]]
17:43:34.676 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 00124B000EE99EED: Node SVC Discovery: stopped
17:43:34.678 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 00124B000EE99EED: Node SVC Discovery: created discoverer
17:43:34.679 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 00124B000EE99EED: Node SVC Discovery: start discovery
17:43:34.679 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 00124B000EE99EED: Node SVC Discovery: starting new tasks [ACTIVE_ENDPOINTS, POWER_DESCRIPTOR, NWK_ADDRESS, NODE_DESCRIPTOR]
17:43:34.680 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 00124B000EE99EED: Node SVC Discovery: scheduled [NWK_ADDRESS, NODE_DESCRIPTOR, POWER_DESCRIPTOR, ACTIVE_ENDPOINTS]
17:43:34.684 [WARN ] [.zsmartsystems.zigbee.ZigBeeExecutors] - Uncaught exception in thread NotificationService-thread-33
java.lang.NullPointerException: null
        at org.openhab.binding.zigbee.handler.ZigBeeThingHandler.nodeUpdated(ZigBeeThingHandler.java:862) ~[?:?]
        at com.zsmartsystems.zigbee.ZigBeeNetworkManager$14.run(ZigBeeNetworkManager.java:1815) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[?:?]
        at java.lang.Thread.run(Thread.java:829) [?:?]
17:43:34.876 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-- AF_INCOMING_MSG (FE 1B 44 81 00 00 00 05 78 D4 01 01 00 37 00 A3 79 29 00 00 07 19 01 01 15 00 01 10 78 D4 1D 18)
17:43:34.878 [DEBUG] [531.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=27, apiId=44 81, data=FE 1B 44 81 00 00 00 05 78 D4 01 01 00 37 00 A3 79 29 00 00 07 19 01 01 15 00 01 10 78 D4 1D 18, checksum=18, error=false
17:43:34.878 [DEBUG] [ee.dongle.cc2531.ZigBeeDongleTiCc2531] - Unhandled ZToolPacket type 0x4481
17:43:34.879 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=D478/1, destinationAddress=0000/1, profile=0104, cluster=0500, addressMode=null, radius=0, apsSecurity=false, ackRequest=false, apsCounter=--, rssi=--, lqi=--, payload=19 01 01 15 00 01 10]
17:43:34.880 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 00124B000EE99EED: Node update. NWK Address=D478
17:43:34.881 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 00124B000EE99EED: Node D478 is not updated
17:43:34.881 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=CLUSTER_SPECIFIC_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=1, commandId=1]
17:43:34.883 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 00124B000EE99EED: Endpoint 1. Unknown remote endpoint
17:43:34.883 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - Incoming message from node D478 did not translate to command
17:43:34.913 [DEBUG] [database.ZigBeeNetworkDatabaseManager] - 00124B000EE99EED: Data store: Writing node.
17:43:34.918 [DEBUG] [nding.zigbee.internal.ZigBeeDataStore] - 00124B000EE99EED: ZigBee saving network state complete.
17:43:35.183 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 00124B000EE99EED: Node SVC Discovery: running NWK_ADDRESS
17:43:35.184 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00124B000EE99EED: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00124B000EE99EED queueTime=0, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> D478/0, cluster=0000, TID=--, ieeeAddr=00124B000EE99EED, requestType=0, startIndex=0]]
17:43:35.184 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=2, sleepy=0/3
17:43:35.185 [DEBUG] [.transaction.ZigBeeTransactionManager] - D478/0: Sending ZigBeeTransaction [ieeeAddress=00124B000EE99EED queueTime=1, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> D478/0, cluster=0000, TID=95, ieeeAddr=00124B000EE99EED, requestType=0, startIndex=0]]
17:43:35.186 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
17:43:35.187 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0000/0 -> D478/0, cluster=0000, TID=95, ieeeAddr=00124B000EE99EED, requestType=0, startIndex=0]
17:43:35.188 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=D478/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=EC, rssi=--, lqi=--, payload=95 ED 9E E9 0E 00 4B 12 00 00 00]
17:43:35.188 [DEBUG] [531.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=21, apiId=24 01, data=FE 15 24 01 78 D4 00 00 00 00 EC 30 08 0B 95 ED 9E E9 0E 00 4B 12 00 00 00 1B, checksum=1B, error=false)
17:43:35.201 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
17:43:35.204 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=95 state=TX_ACK
17:43:35.205 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=95, state=TX_ACK, outstanding=2
17:43:35.206 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=D478, TID=95, event=TX_ACK, state=TRANSMITTED
17:43:35.646 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 0D 45 FF 78 D4 00 00 80 00 95 00 00 84 00 00 00 8A)
17:43:35.647 [DEBUG] [531.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=13, apiId=45 FF, data=FE 0D 45 FF 78 D4 00 00 80 00 95 00 00 84 00 00 00 8A, checksum=8A, error=false
17:43:35.647 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=D478/0, destinationAddress=0000/0, profile=0000, cluster=8000, addressMode=null, radius=0, apsSecurity=false, ackRequest=false, apsCounter=--, rssi=--, lqi=--, payload=00 84 00 00 00]
17:43:35.648 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 00124B000EE99EED: Node update. NWK Address=D478
17:43:35.648 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 00124B000EE99EED: Node D478 is not updated
17:43:35.649 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: NetworkAddressResponse [D478/0 -> 0000/0, cluster=8000, TID=00, status=NOT_SUPPORTED, ieeeAddrRemoteDev=null, nwkAddrRemoteDev=NULL, startIndex=null, nwkAddrAssocDevList=[]]
17:43:35.649 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NetworkAddressResponse [D478/0 -> 0000/0, cluster=8000, TID=00, status=NOT_SUPPORTED, ieeeAddrRemoteDev=null, nwkAddrRemoteDev=NULL, startIndex=null, nwkAddrAssocDevList=[]]
17:43:35.666 [DEBUG] [531.network.impl.CommandInterfaceImpl] - <-- ZB_FIND_DEVICE_CONFIRM (FE 0B 46 85 01 D4 00 00 80 00 95 00 00 84 00 8C)
17:43:35.667 [DEBUG] [531.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=11, apiId=46 85, data=FE 0B 46 85 01 D4 00 00 80 00 95 00 00 84 00 8C, checksum=8C, error=false
17:43:35.667 [DEBUG] [ee.dongle.cc2531.ZigBeeDongleTiCc2531] - Unhandled ZToolPacket type 0x4685
17:43:38.689 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00124B000EE99DC7 queueTime=16045, state=FAILED, sendCnt=2, command=PowerDescriptorRequest [0000/0 -> 435D/0, cluster=0003, TID=93, nwkAddrOfInterest=435D]]
17:43:38.691 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
17:43:38.691 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00124B000EE99DC7: transactionComplete, state=FAILED, outstanding=0
17:43:38.692 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00124B000EE99DC7: transactionComplete exceeded max retries 2
17:43:38.692 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction cancelled: ZigBeeTransaction [ieeeAddress=00124B000EE99DC7 queueTime=16048, state=CANCELLED, sendCnt=2, command=PowerDescriptorRequest [0000/0 -> 435D/0, cluster=0003, TID=93, nwkAddrOfInterest=435D]]
17:43:38.693 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 00124B000EE99DC7: Node SVC Discovery: PowerDescriptorResponse returned null
17:43:38.694 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 00124B000EE99DC7: Node SVC Discovery: request POWER_DESCRIPTOR failed. Retry 4, wait 10545ms before retry.
17:43:38.694 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00124B000EE99DC7 queueTime=16050, state=CANCELLED, sendCnt=2, command=PowerDescriptorRequest [0000/0 -> 435D/0, cluster=0003, TID=93, nwkAddrOfInterest=435D]]
17:43:38.695 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
17:43:38.696 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 00124B000EE99DC7: transactionComplete but not outstanding, state=CANCELLED, outstanding=0
17:43:38.696 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3
17:43:38.696 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3