2019-11-29 16:03:26.325 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 14B457FFFE7E88DF: Discovery: Starting discovery for existing device
2019-11-29 16:03:26.329 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - Starting ZigBee scan for zigbee:coordinator_ember:0137F165
2019-11-29 16:03:26.333 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Permit join to 65532/0 for 60 seconds.
2019-11-29 16:03:26.336 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=1, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true]]
2019-11-29 16:03:26.340 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 14B457FFFE7E88DF: Starting ZigBee device discovery
2019-11-29 16:03:26.339 [DEBUG] [transaction.ZigBeeTransactionManager] - 65532/0: Sending ZigBeeTransaction [queueTime=4, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=3E, permitDuration=60, tcSignificance=true]]
2019-11-29 16:03:26.343 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2019-11-29 16:03:26.345 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 14B457FFFE7E88DF: Creating ZigBee device zigbee:device with bridge zigbee:coordinator_ember:0137F165
2019-11-29 16:03:26.347 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=3E, permitDuration=60, tcSignificance=true]
2019-11-29 16:03:26.351 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=65532/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=66, payload=00 3C 01]
2019-11-29 16:03:26.355 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 14B457FFFE7E88DF: Node discovery not complete
2019-11-29 16:03:26.355 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6F000D3B11CE: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=1, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true]]
2019-11-29 16:03:26.359 [DEBUG] [transaction.ZigBeeTransactionManager] - 0/0: Sending ZigBeeTransaction [queueTime=4, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=3F, permitDuration=60, tcSignificance=true]]
2019-11-29 16:03:26.361 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2019-11-29 16:03:26.365 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=3F, permitDuration=60, tcSignificance=true]
2019-11-29 16:03:26.368 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=67, payload=00 3C 01]
2019-11-29 16:03:26.371 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendBroadcastResponse [status=EMBER_SUCCESS, sequence=4C]
2019-11-29 16:03:26.380 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_BROADCAST_LOOPBACK, apsFrame=EmberApsFrame [profileId=0, clusterId=54, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=4C], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 3C 01]
2019-11-29 16:03:26.382 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0036, addressMode=null, radius=0, apsSecurity=false, apsCounter=4C, payload=00 3C 01]
2019-11-29 16:03:26.385 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true]
2019-11-29 16:03:26.387 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true]
2019-11-29 16:03:26.390 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] ZigBeeTransaction [queueTime=35, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=3F, permitDuration=60, tcSignificance=true]]
2019-11-29 16:03:26.391 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] ZigBeeTransaction [queueTime=56, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=3E, permitDuration=60, tcSignificance=true]]
2019-11-29 16:03:26.415 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=4D]
2019-11-29 16:03:26.439 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=54, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=4D], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 3C 01]
2019-11-29 16:03:26.440 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0036, addressMode=null, radius=0, apsSecurity=false, apsCounter=4D, payload=00 3C 01]
2019-11-29 16:03:26.442 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true]
2019-11-29 16:03:26.443 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true]
2019-11-29 16:03:26.444 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] ZigBeeTransaction [queueTime=90, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=3F, permitDuration=60, tcSignificance=true]]
2019-11-29 16:03:26.445 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] ZigBeeTransaction [queueTime=110, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=3E, permitDuration=60, tcSignificance=true]]
2019-11-29 16:03:26.448 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=32822, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=4E], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00]
2019-11-29 16:03:26.449 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=8036, addressMode=null, radius=0, apsSecurity=false, apsCounter=4E, payload=00 00]
2019-11-29 16:03:26.450 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS]
2019-11-29 16:03:26.451 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS]
2019-11-29 16:03:26.452 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] ZigBeeTransaction [queueTime=98, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=3F, permitDuration=60, tcSignificance=true]]
2019-11-29 16:03:26.454 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] ZigBeeTransaction [queueTime=118, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=3E, permitDuration=60, tcSignificance=true]]
2019-11-29 16:03:26.456 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=0, apsFrame=EmberApsFrame [profileId=0, clusterId=54, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=4D], messageTag=3F, status=EMBER_SUCCESS, messageContents=]
2019-11-29 16:03:26.457 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=3F state=RX_ACK
2019-11-29 16:03:26.458 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=3F, state=RX_ACK, outstanding=2
2019-11-29 16:03:26.459 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=105, state=COMPLETE, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=3F, permitDuration=60, tcSignificance=true]]
2019-11-29 16:03:26.460 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2019-11-29 16:03:26.461 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6F000D3B11CE: transactionComplete COMPLETE 0
2019-11-29 16:03:26.463 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 3F -> RX_ACK == COMPLETE
2019-11-29 16:03:27.271 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_BROADCAST, indexOrDestination=65532, apsFrame=EmberApsFrame [profileId=0, clusterId=54, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=4C], messageTag=3E, status=EMBER_SUCCESS, messageContents=]
2019-11-29 16:03:27.276 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=3E state=RX_ACK
2019-11-29 16:03:27.279 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=3E, state=RX_ACK, outstanding=1
2019-11-29 16:03:27.286 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=951, state=COMPLETE, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=3E, permitDuration=60, tcSignificance=true]]
2019-11-29 16:03:27.288 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2019-11-29 16:03:27.290 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete COMPLETE 0
2019-11-29 16:03:27.293 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 3E -> RX_ACK == COMPLETE
2019-11-29 16:03:48.186 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspChildJoinHandler [index=1, joining=true, childId=26337, childEui64=14B457FFFE954ACB, childType=EMBER_SLEEPY_END_DEVICE]
2019-11-29 16:03:48.189 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 14B457FFFE954ACB: nodeStatusUpdate - node status is UNSECURED_JOIN, network address is 26337.
2019-11-29 16:03:48.191 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 14B457FFFE954ACB: Device status updated. NWK=26337
2019-11-29 16:03:48.194 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 14B457FFFE954ACB: NWK Discovery add node 26337
2019-11-29 16:03:48.196 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 14B457FFFE954ACB: Node state updated from UNKNOWN to ONLINE
2019-11-29 16:03:48.199 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 14B457FFFE954ACB: Updating node NWK=26337
2019-11-29 16:03:48.202 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 14B457FFFE954ACB: Data store: Deferring write for 250ms.
2019-11-29 16:03:48.205 [DEBUG] [p.discovery.ZigBeeDiscoveryExtension] - 14B457FFFE954ACB: DISCOVERY Extension: Adding discoverer for added node
2019-11-29 16:03:48.207 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 14B457FFFE954ACB: Node SVC Discovery: created discoverer
2019-11-29 16:03:48.210 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 14B457FFFE954ACB: Node SVC Discovery: start discovery
2019-11-29 16:03:48.212 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 14B457FFFE954ACB: Starting ZigBee device discovery
2019-11-29 16:03:48.212 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 14B457FFFE954ACB: Node SVC Discovery: starting new tasks [POWER_DESCRIPTOR, ACTIVE_ENDPOINTS, NODE_DESCRIPTOR, NWK_ADDRESS]
2019-11-29 16:03:48.215 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 14B457FFFE954ACB: Node SVC Discovery: scheduled [POWER_DESCRIPTOR, ACTIVE_ENDPOINTS, NODE_DESCRIPTOR, NWK_ADDRESS]
2019-11-29 16:03:48.215 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 14B457FFFE954ACB: Creating ZigBee device zigbee:device with bridge zigbee:coordinator_ember:0137F165
2019-11-29 16:03:48.221 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zigbee:device:0137F165:14b457fffe954acb' to inbox.
2019-11-29 16:03:48.225 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 14B457FFFE954ACB: Node discovery not complete
2019-11-29 16:03:48.392 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [newNodeId=26337, newNodeEui64=14B457FFFE954ACB, status=EMBER_STANDARD_SECURITY_UNSECURED_JOIN, policyDecision=EMBER_SEND_KEY_IN_THE_CLEAR, parentOfNewNodeId=0]
2019-11-29 16:03:48.395 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 14B457FFFE954ACB: nodeStatusUpdate - node status is UNSECURED_JOIN, network address is 26337.
2019-11-29 16:03:48.397 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 14B457FFFE954ACB: Device status updated. NWK=26337
2019-11-29 16:03:48.400 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 14B457FFFE954ACB: NWK Discovery add node 26337
2019-11-29 16:03:48.403 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 14B457FFFE954ACB: Node state updated from UNKNOWN to ONLINE
2019-11-29 16:03:48.406 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 14B457FFFE954ACB: Updating node NWK=26337
2019-11-29 16:03:48.408 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 14B457FFFE954ACB: Node 26337 update
2019-11-29 16:03:48.411 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 14B457FFFE954ACB: Node 26337 is not updated
2019-11-29 16:03:48.455 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 14B457FFFE954ACB: Data store: Writing node.
2019-11-29 16:03:48.474 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 14B457FFFE954ACB: ZigBee saving network state complete.
2019-11-29 16:03:50.242 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 14B457FFFE954ACB: Node SVC Discovery: running POWER_DESCRIPTOR
2019-11-29 16:03:50.245 [DEBUG] [transaction.ZigBeeTransactionManager] - 14B457FFFE954ACB: Creating new Transaction Queue
2019-11-29 16:03:50.249 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 14B457FFFE954ACB: Set profile to ZigBeeTransactionProfile [maxOutstandingTransactions=2, interTransactionDelay=50, maxRetries=2]
2019-11-29 16:03:50.252 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 14B457FFFE954ACB: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=--, nwkAddrOfInterest=26337]]
2019-11-29 16:03:50.254 [DEBUG] [transaction.ZigBeeTransactionManager] - 26337/0: Sending ZigBeeTransaction [queueTime=3, state=WAITING, sendCnt=0, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=40, nwkAddrOfInterest=26337]]
2019-11-29 16:03:50.258 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2019-11-29 16:03:50.261 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=40, nwkAddrOfInterest=26337]
2019-11-29 16:03:50.264 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=26337/0, profile=0000, cluster=0003, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=68, payload=00 E1 66]
2019-11-29 16:03:50.278 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=50]
2019-11-29 16:03:57.777 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=26337]
2019-11-29 16:04:00.261 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=10009, state=FAILED, sendCnt=1, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=40, nwkAddrOfInterest=26337]]
2019-11-29 16:04:00.263 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2019-11-29 16:04:00.265 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 14B457FFFE954ACB: transactionComplete FAILED 0
2019-11-29 16:04:00.267 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 14B457FFFE954ACB: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=10016, state=WAITING, sendCnt=1, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=40, nwkAddrOfInterest=26337]]
2019-11-29 16:04:02.268 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 14B457FFFE954ACB: Node SVC Discovery: PowerDescriptorResponse returned null
2019-11-29 16:04:02.270 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 14B457FFFE954ACB: Node SVC Discovery: request POWER_DESCRIPTOR failed. Retry 1, wait 2197ms before retry.
2019-11-29 16:04:04.470 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 14B457FFFE954ACB: Node SVC Discovery: running POWER_DESCRIPTOR
2019-11-29 16:04:04.473 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 14B457FFFE954ACB: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=--, nwkAddrOfInterest=26337]]
2019-11-29 16:04:04.475 [DEBUG] [transaction.ZigBeeTransactionManager] - 26337/0: Sending ZigBeeTransaction [queueTime=14223, state=WAITING, sendCnt=1, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=40, nwkAddrOfInterest=26337]]
2019-11-29 16:04:04.477 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2019-11-29 16:04:04.479 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=40, nwkAddrOfInterest=26337]
2019-11-29 16:04:04.481 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=26337/0, profile=0000, cluster=0003, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=69, payload=00 E1 66]
2019-11-29 16:04:04.494 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=51]
2019-11-29 16:04:04.525 [DEBUG] [transaction.ZigBeeTransactionManager] - 26337/0: Sending ZigBeeTransaction [queueTime=52, state=WAITING, sendCnt=0, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=41, nwkAddrOfInterest=26337]]
2019-11-29 16:04:04.528 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2019-11-29 16:04:04.530 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=41, nwkAddrOfInterest=26337]
2019-11-29 16:04:04.533 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=26337/0, profile=0000, cluster=0003, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=6A, payload=00 E1 66]
2019-11-29 16:04:04.547 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=52]
2019-11-29 16:04:06.841 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=26337]
2019-11-29 16:04:11.993 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=26337]
2019-11-29 16:04:12.046 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=26337]
2019-11-29 16:04:14.479 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=24228, state=FAILED, sendCnt=2, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=40, nwkAddrOfInterest=26337]]
2019-11-29 16:04:14.482 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2019-11-29 16:04:14.484 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 14B457FFFE954ACB: transactionComplete FAILED 1
2019-11-29 16:04:14.486 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 14B457FFFE954ACB: transactionComplete exceeded retries 2
2019-11-29 16:04:14.489 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=24237, state=FAILED, sendCnt=2, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=40, nwkAddrOfInterest=26337]]
2019-11-29 16:04:14.530 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=10058, state=FAILED, sendCnt=1, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=41, nwkAddrOfInterest=26337]]
2019-11-29 16:04:14.532 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2019-11-29 16:04:14.534 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 14B457FFFE954ACB: transactionComplete FAILED 0
2019-11-29 16:04:14.537 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 14B457FFFE954ACB: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=10064, state=WAITING, sendCnt=1, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=41, nwkAddrOfInterest=26337]]
2019-11-29 16:04:15.903 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=26337]
2019-11-29 16:04:16.484 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 14B457FFFE954ACB: Node SVC Discovery: PowerDescriptorResponse returned null
2019-11-29 16:04:16.487 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 14B457FFFE954ACB: Node SVC Discovery: request POWER_DESCRIPTOR failed. Retry 2, wait 4394ms before retry.
2019-11-29 16:04:17.469 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=26337, apsFrame=EmberApsFrame [profileId=0, clusterId=3, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=50], messageTag=40, status=EMBER_DELIVERY_FAILED, messageContents=]
2019-11-29 16:04:17.473 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=40 state=RX_NAK
2019-11-29 16:04:17.475 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=40, state=RX_NAK, outstanding=0
2019-11-29 16:04:20.883 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 14B457FFFE954ACB: Node SVC Discovery: running POWER_DESCRIPTOR
2019-11-29 16:04:20.886 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 14B457FFFE954ACB: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=--, nwkAddrOfInterest=26337]]
2019-11-29 16:04:20.888 [DEBUG] [transaction.ZigBeeTransactionManager] - 26337/0: Sending ZigBeeTransaction [queueTime=16416, state=WAITING, sendCnt=1, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=41, nwkAddrOfInterest=26337]]
2019-11-29 16:04:20.890 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2019-11-29 16:04:20.893 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=41, nwkAddrOfInterest=26337]
2019-11-29 16:04:20.896 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=26337/0, profile=0000, cluster=0003, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=6B, payload=00 E1 66]
2019-11-29 16:04:20.910 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=53]
2019-11-29 16:04:20.938 [DEBUG] [transaction.ZigBeeTransactionManager] - 26337/0: Sending ZigBeeTransaction [queueTime=53, state=WAITING, sendCnt=0, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=42, nwkAddrOfInterest=26337]]
2019-11-29 16:04:20.941 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2019-11-29 16:04:20.943 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=42, nwkAddrOfInterest=26337]
2019-11-29 16:04:20.946 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=26337/0, profile=0000, cluster=0003, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=6C, payload=00 E1 66]
2019-11-29 16:04:20.960 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=54]
2019-11-29 16:04:21.057 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=26337]
2019-11-29 16:04:21.113 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=26337]
2019-11-29 16:04:21.117 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=26337]
2019-11-29 16:04:21.121 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=26337]
2019-11-29 16:04:21.676 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=32824, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=55], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00 00 F8 FF 07 16 00 12 00 10 B6 EF F0 B3 D4 D6 CC A9 C8 BE C9 BF C8 C9 D1 E1]
2019-11-29 16:04:21.681 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=8038, addressMode=null, radius=0, apsSecurity=false, apsCounter=55, payload=00 00 00 F8 FF 07 16 00 12 00 10 B6 EF F0 B3 D4 D6 CC A9 C8 BE C9 BF C8 C9 D1 E1]
2019-11-29 16:04:21.684 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementNetworkUpdateNotify [0/0 -> 0/0, cluster=8038, TID=--, status=SUCCESS, scannedChannels=134215680, totalTransmissions=22, transmissionFailures=18, energyValues=[182, 239, 240, 179, 212, 214, 204, 169, 200, 190, 201, 191, 200, 201, 209, 225]]
2019-11-29 16:04:21.687 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementNetworkUpdateNotify [0/0 -> 0/0, cluster=8038, TID=--, status=SUCCESS, scannedChannels=134215680, totalTransmissions=22, transmissionFailures=18, energyValues=[182, 239, 240, 179, 212, 214, 204, 169, 200, 190, 201, 191, 200, 201, 209, 225]]
2019-11-29 16:04:21.690 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementNetworkUpdateNotify [0/0 -> 0/0, cluster=8038, TID=--, status=SUCCESS, scannedChannels=134215680, totalTransmissions=22, transmissionFailures=18, energyValues=[182, 239, 240, 179, 212, 214, 204, 169, 200, 190, 201, 191, 200, 201, 209, 225]] ZigBeeTransaction [queueTime=805, state=DISPATCHED, sendCnt=1, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=42, nwkAddrOfInterest=26337]]
2019-11-29 16:04:21.693 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementNetworkUpdateNotify [0/0 -> 0/0, cluster=8038, TID=--, status=SUCCESS, scannedChannels=134215680, totalTransmissions=22, transmissionFailures=18, energyValues=[182, 239, 240, 179, 212, 214, 204, 169, 200, 190, 201, 191, 200, 201, 209, 225]] ZigBeeTransaction [queueTime=17221, state=DISPATCHED, sendCnt=2, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=41, nwkAddrOfInterest=26337]]
2019-11-29 16:04:30.120 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=26337]
2019-11-29 16:04:30.171 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=26337]
2019-11-29 16:04:30.893 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=26421, state=FAILED, sendCnt=2, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=41, nwkAddrOfInterest=26337]]
2019-11-29 16:04:30.895 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2019-11-29 16:04:30.897 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 14B457FFFE954ACB: transactionComplete FAILED 1
2019-11-29 16:04:30.899 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 14B457FFFE954ACB: transactionComplete exceeded retries 2
2019-11-29 16:04:30.901 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=26429, state=FAILED, sendCnt=2, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=41, nwkAddrOfInterest=26337]]
2019-11-29 16:04:30.944 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=10058, state=FAILED, sendCnt=1, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=42, nwkAddrOfInterest=26337]]
2019-11-29 16:04:30.946 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2019-11-29 16:04:30.948 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 14B457FFFE954ACB: transactionComplete FAILED 0
2019-11-29 16:04:30.951 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 14B457FFFE954ACB: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=10066, state=WAITING, sendCnt=1, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=42, nwkAddrOfInterest=26337]]
2019-11-29 16:04:31.686 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=26337, apsFrame=EmberApsFrame [profileId=0, clusterId=3, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=51], messageTag=40, status=EMBER_DELIVERY_FAILED, messageContents=]
2019-11-29 16:04:31.688 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=40 state=RX_NAK
2019-11-29 16:04:31.691 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=40, state=RX_NAK, outstanding=0
2019-11-29 16:04:31.737 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=26337, apsFrame=EmberApsFrame [profileId=0, clusterId=3, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=52], messageTag=41, status=EMBER_DELIVERY_FAILED, messageContents=]
2019-11-29 16:04:31.740 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=41 state=RX_NAK
2019-11-29 16:04:31.742 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=41, state=RX_NAK, outstanding=0
2019-11-29 16:04:32.899 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 14B457FFFE954ACB: Node SVC Discovery: PowerDescriptorResponse returned null
2019-11-29 16:04:32.901 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 14B457FFFE954ACB: Node SVC Discovery: request POWER_DESCRIPTOR failed. Retry 3, wait 2197ms before retry.
2019-11-29 16:04:35.101 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 14B457FFFE954ACB: Node SVC Discovery: running POWER_DESCRIPTOR
2019-11-29 16:04:35.104 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 14B457FFFE954ACB: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=--, nwkAddrOfInterest=26337]]
2019-11-29 16:04:35.106 [DEBUG] [transaction.ZigBeeTransactionManager] - 26337/0: Sending ZigBeeTransaction [queueTime=14221, state=WAITING, sendCnt=1, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=42, nwkAddrOfInterest=26337]]
2019-11-29 16:04:35.109 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2019-11-29 16:04:35.111 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=42, nwkAddrOfInterest=26337]
2019-11-29 16:04:35.114 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=26337/0, profile=0000, cluster=0003, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=6D, payload=00 E1 66]
2019-11-29 16:04:35.136 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=56]
2019-11-29 16:04:35.157 [DEBUG] [transaction.ZigBeeTransactionManager] - 26337/0: Sending ZigBeeTransaction [queueTime=53, state=WAITING, sendCnt=0, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=43, nwkAddrOfInterest=26337]]
2019-11-29 16:04:35.159 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2019-11-29 16:04:35.161 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=43, nwkAddrOfInterest=26337]
2019-11-29 16:04:35.164 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=26337/0, profile=0000, cluster=0003, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=6E, payload=00 E1 66]
2019-11-29 16:04:35.177 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=57]
2019-11-29 16:04:37.471 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=26337]
2019-11-29 16:04:37.521 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=26337]
2019-11-29 16:04:42.636 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=26337]
2019-11-29 16:04:42.677 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=26337]
2019-11-29 16:04:45.111 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=24226, state=FAILED, sendCnt=2, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=42, nwkAddrOfInterest=26337]]
2019-11-29 16:04:45.113 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2019-11-29 16:04:45.115 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 14B457FFFE954ACB: transactionComplete FAILED 1
2019-11-29 16:04:45.117 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 14B457FFFE954ACB: transactionComplete exceeded retries 2
2019-11-29 16:04:45.120 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=24234, state=FAILED, sendCnt=2, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=42, nwkAddrOfInterest=26337]]
2019-11-29 16:04:45.162 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=10058, state=FAILED, sendCnt=1, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=43, nwkAddrOfInterest=26337]]
2019-11-29 16:04:45.164 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2019-11-29 16:04:45.166 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 14B457FFFE954ACB: transactionComplete FAILED 0
2019-11-29 16:04:45.169 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 14B457FFFE954ACB: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=10066, state=WAITING, sendCnt=1, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=43, nwkAddrOfInterest=26337]]
2019-11-29 16:04:46.533 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=26337]
2019-11-29 16:04:46.584 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=26337]
2019-11-29 16:04:47.126 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 14B457FFFE954ACB: Node SVC Discovery: PowerDescriptorResponse returned null
2019-11-29 16:04:47.129 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 14B457FFFE954ACB: Node SVC Discovery: request POWER_DESCRIPTOR failed. Retry 4, wait 8788ms before retry.
2019-11-29 16:04:48.098 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=26337, apsFrame=EmberApsFrame [profileId=0, clusterId=3, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=53], messageTag=41, status=EMBER_DELIVERY_FAILED, messageContents=]
2019-11-29 16:04:48.101 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=41 state=RX_NAK
2019-11-29 16:04:48.103 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=41, state=RX_NAK, outstanding=0
2019-11-29 16:04:48.149 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=26337, apsFrame=EmberApsFrame [profileId=0, clusterId=3, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=54], messageTag=42, status=EMBER_DELIVERY_FAILED, messageContents=]
2019-11-29 16:04:48.151 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=42 state=RX_NAK
2019-11-29 16:04:48.154 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=42, state=RX_NAK, outstanding=0
2019-11-29 16:04:51.697 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=26337]
2019-11-29 16:04:51.743 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=26337]
2019-11-29 16:04:55.919 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 14B457FFFE954ACB: Node SVC Discovery: running POWER_DESCRIPTOR
2019-11-29 16:04:55.920 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 14B457FFFE954ACB: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=--, nwkAddrOfInterest=26337]]
2019-11-29 16:04:55.921 [DEBUG] [transaction.ZigBeeTransactionManager] - 26337/0: Sending ZigBeeTransaction [queueTime=20818, state=WAITING, sendCnt=1, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=43, nwkAddrOfInterest=26337]]
2019-11-29 16:04:55.922 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2019-11-29 16:04:55.923 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=43, nwkAddrOfInterest=26337]
2019-11-29 16:04:55.926 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=26337/0, profile=0000, cluster=0003, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=6F, payload=00 E1 66]
2019-11-29 16:04:55.937 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=58]
2019-11-29 16:04:55.971 [DEBUG] [transaction.ZigBeeTransactionManager] - 26337/0: Sending ZigBeeTransaction [queueTime=51, state=WAITING, sendCnt=0, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=44, nwkAddrOfInterest=26337]]
2019-11-29 16:04:55.972 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2019-11-29 16:04:55.973 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=44, nwkAddrOfInterest=26337]
2019-11-29 16:04:55.975 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=26337/0, profile=0000, cluster=0003, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=70, payload=00 E1 66]
2019-11-29 16:04:55.985 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=59]
2019-11-29 16:05:00.759 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=26337]
2019-11-29 16:05:00.804 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=26337]
2019-11-29 16:05:02.326 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=26337, apsFrame=EmberApsFrame [profileId=0, clusterId=3, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=56], messageTag=42, status=EMBER_DELIVERY_FAILED, messageContents=]
2019-11-29 16:05:02.328 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=42 state=RX_NAK
2019-11-29 16:05:02.331 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=42, state=RX_NAK, outstanding=2
2019-11-29 16:05:02.367 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=26337, apsFrame=EmberApsFrame [profileId=0, clusterId=3, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=57], messageTag=43, status=EMBER_DELIVERY_FAILED, messageContents=]
2019-11-29 16:05:02.369 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=43 state=RX_NAK
2019-11-29 16:05:02.371 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=43, state=RX_NAK, outstanding=2
2019-11-29 16:05:02.378 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=27274, state=FAILED, sendCnt=2, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=43, nwkAddrOfInterest=26337]]
2019-11-29 16:05:02.380 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2019-11-29 16:05:02.381 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 14B457FFFE954ACB: transactionComplete FAILED 1
2019-11-29 16:05:02.383 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 14B457FFFE954ACB: transactionComplete exceeded retries 2
2019-11-29 16:05:02.385 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=27281, state=FAILED, sendCnt=2, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=43, nwkAddrOfInterest=26337]]
2019-11-29 16:05:02.387 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 43 -> RX_NAK == FAILED
2019-11-29 16:05:03.438 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=26337]
2019-11-29 16:05:03.486 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=26337]
2019-11-29 16:05:05.974 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=10053, state=FAILED, sendCnt=1, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=44, nwkAddrOfInterest=26337]]
2019-11-29 16:05:05.976 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2019-11-29 16:05:05.978 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 14B457FFFE954ACB: transactionComplete FAILED 0
2019-11-29 16:05:05.981 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 14B457FFFE954ACB: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=10060, state=WAITING, sendCnt=1, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=44, nwkAddrOfInterest=26337]]
2019-11-29 16:05:07.928 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 14B457FFFE954ACB: Node SVC Discovery: PowerDescriptorResponse returned null
2019-11-29 16:05:07.931 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 14B457FFFE954ACB: Node SVC Discovery: request POWER_DESCRIPTOR failed. Retry 5, wait 4394ms before retry.
2019-11-29 16:05:12.328 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 14B457FFFE954ACB: Node SVC Discovery: running POWER_DESCRIPTOR
2019-11-29 16:05:12.330 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 14B457FFFE954ACB: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=--, nwkAddrOfInterest=26337]]
2019-11-29 16:05:12.332 [DEBUG] [transaction.ZigBeeTransactionManager] - 26337/0: Sending ZigBeeTransaction [queueTime=16412, state=WAITING, sendCnt=1, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=44, nwkAddrOfInterest=26337]]
2019-11-29 16:05:12.334 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2019-11-29 16:05:12.337 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=44, nwkAddrOfInterest=26337]
2019-11-29 16:05:12.340 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=26337/0, profile=0000, cluster=0003, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=71, payload=00 E1 66]
2019-11-29 16:05:12.354 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=5A]
2019-11-29 16:05:12.383 [DEBUG] [transaction.ZigBeeTransactionManager] - 26337/0: Sending ZigBeeTransaction [queueTime=54, state=WAITING, sendCnt=0, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=45, nwkAddrOfInterest=26337]]
2019-11-29 16:05:12.385 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2019-11-29 16:05:12.388 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=45, nwkAddrOfInterest=26337]
2019-11-29 16:05:12.391 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=26337/0, profile=0000, cluster=0003, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=72, payload=00 E1 66]
2019-11-29 16:05:12.405 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=5B]
2019-11-29 16:05:12.500 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=26337]
2019-11-29 16:05:12.548 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=26337]
2019-11-29 16:05:17.041 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 14B457FFFE954ACB: Initializing ZigBee thing handler zigbee:device:0137F165:14b457fffe954acb
2019-11-29 16:05:17.046 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 14B457FFFE954ACB: Coordinator status changed to ONLINE.
2019-11-29 16:05:17.050 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 14B457FFFE954ACB: Coordinator is ONLINE. Starting device initialisation.
2019-11-29 16:05:17.053 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 14B457FFFE954ACB: NWK Discovery starting node rediscovery
2019-11-29 16:05:17.057 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=--, ieeeAddr=14B457FFFE954ACB, requestType=0, startIndex=0]]
2019-11-29 16:05:17.061 [DEBUG] [transaction.ZigBeeTransactionManager] - 65533/0: Sending ZigBeeTransaction [queueTime=4, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=46, ieeeAddr=14B457FFFE954ACB, requestType=0, startIndex=0]]
2019-11-29 16:05:17.063 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 14B457FFFE954ACB: Node has not finished discovery
2019-11-29 16:05:17.066 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 3 outstanding
2019-11-29 16:05:17.072 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=46, ieeeAddr=14B457FFFE954ACB, requestType=0, startIndex=0]
2019-11-29 16:05:17.074 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=65533/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=73, payload=00 CB 4A 95 FE FF 57 B4 14 00 00]
2019-11-29 16:05:17.086 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendBroadcastResponse [status=EMBER_SUCCESS, sequence=5C]
2019-11-29 16:05:17.110 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_BROADCAST_LOOPBACK, apsFrame=EmberApsFrame [profileId=0, clusterId=0, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=5C], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 CB 4A 95 FE FF 57 B4 14 00 00]
2019-11-29 16:05:17.111 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0000, addressMode=null, radius=0, apsSecurity=false, apsCounter=5C, payload=00 CB 4A 95 FE FF 57 B4 14 00 00]
2019-11-29 16:05:17.113 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: NetworkAddressRequest [0/0 -> 0/0, cluster=0000, TID=--, ieeeAddr=14B457FFFE954ACB, requestType=0, startIndex=0]
2019-11-29 16:05:17.114 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NetworkAddressRequest [0/0 -> 0/0, cluster=0000, TID=--, ieeeAddr=14B457FFFE954ACB, requestType=0, startIndex=0]
2019-11-29 16:05:17.115 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NetworkAddressRequest [0/0 -> 0/0, cluster=0000, TID=--, ieeeAddr=14B457FFFE954ACB, requestType=0, startIndex=0] ZigBeeTransaction [queueTime=4786, state=DISPATCHED, sendCnt=1, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=45, nwkAddrOfInterest=26337]]
2019-11-29 16:05:17.117 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NetworkAddressRequest [0/0 -> 0/0, cluster=0000, TID=--, ieeeAddr=14B457FFFE954ACB, requestType=0, startIndex=0] ZigBeeTransaction [queueTime=60, state=DISPATCHED, sendCnt=1, command=NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=46, ieeeAddr=14B457FFFE954ACB, requestType=0, startIndex=0]]
2019-11-29 16:05:17.118 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NetworkAddressRequest [0/0 -> 0/0, cluster=0000, TID=--, ieeeAddr=14B457FFFE954ACB, requestType=0, startIndex=0] ZigBeeTransaction [queueTime=21198, state=DISPATCHED, sendCnt=2, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=44, nwkAddrOfInterest=26337]]
2019-11-29 16:05:17.121 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=32768, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=5D], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00 CB 4A 95 FE FF 57 B4 14 E1 66]
2019-11-29 16:05:17.122 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=8000, addressMode=null, radius=0, apsSecurity=false, apsCounter=5D, payload=00 00 CB 4A 95 FE FF 57 B4 14 E1 66]
2019-11-29 16:05:17.124 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: NetworkAddressResponse [0/0 -> 0/0, cluster=8000, TID=--, status=SUCCESS, ieeeAddrRemoteDev=14B457FFFE954ACB, nwkAddrRemoteDev=26337, startIndex=null, nwkAddrAssocDevList=[]]
2019-11-29 16:05:17.125 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NetworkAddressResponse [0/0 -> 0/0, cluster=8000, TID=--, status=SUCCESS, ieeeAddrRemoteDev=14B457FFFE954ACB, nwkAddrRemoteDev=26337, startIndex=null, nwkAddrAssocDevList=[]]
2019-11-29 16:05:17.126 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NetworkAddressResponse [0/0 -> 0/0, cluster=8000, TID=--, status=SUCCESS, ieeeAddrRemoteDev=14B457FFFE954ACB, nwkAddrRemoteDev=26337, startIndex=null, nwkAddrAssocDevList=[]] ZigBeeTransaction [queueTime=4797, state=DISPATCHED, sendCnt=1, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=45, nwkAddrOfInterest=26337]]
2019-11-29 16:05:17.128 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NetworkAddressResponse [0/0 -> 0/0, cluster=8000, TID=--, status=SUCCESS, ieeeAddrRemoteDev=14B457FFFE954ACB, nwkAddrRemoteDev=26337, startIndex=null, nwkAddrAssocDevList=[]] ZigBeeTransaction [queueTime=72, state=DISPATCHED, sendCnt=1, command=NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=46, ieeeAddr=14B457FFFE954ACB, requestType=0, startIndex=0]]
2019-11-29 16:05:17.129 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 14B457FFFE954ACB: NWK Discovery add node 26337
2019-11-29 16:05:17.129 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=73, state=COMPLETE, sendCnt=1, command=NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=46, ieeeAddr=14B457FFFE954ACB, requestType=0, startIndex=0]]
2019-11-29 16:05:17.131 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NetworkAddressResponse [0/0 -> 0/0, cluster=8000, TID=--, status=SUCCESS, ieeeAddrRemoteDev=14B457FFFE954ACB, nwkAddrRemoteDev=26337, startIndex=null, nwkAddrAssocDevList=[]] ZigBeeTransaction [queueTime=21211, state=DISPATCHED, sendCnt=2, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=44, nwkAddrOfInterest=26337]]
2019-11-29 16:05:17.131 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 14B457FFFE954ACB: Node state updated from UNKNOWN to ONLINE
2019-11-29 16:05:17.132 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 2 outstanding
2019-11-29 16:05:17.133 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete COMPLETE 0
2019-11-29 16:05:17.134 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 14B457FFFE954ACB: Updating node NWK=26337
2019-11-29 16:05:17.136 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 14B457FFFE954ACB: Node 26337 update
2019-11-29 16:05:17.140 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 14B457FFFE954ACB: Node 26337 is not updated
2019-11-29 16:05:17.142 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 26337: NWK Discovery scheduling node discovery
2019-11-29 16:05:17.143 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 26337: NWK Discovery starting node discovery
2019-11-29 16:05:17.143 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 14B457FFFE954ACB: NWK Discovery finishing node rediscovery after 0 attempts
2019-11-29 16:05:17.144 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 14B457FFFE954ACB: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=IeeeAddressRequest [0/0 -> 26337/0, cluster=0001, TID=--, nwkAddrOfInterest=26337, requestType=1, startIndex=0]]
2019-11-29 16:05:18.006 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_BROADCAST, indexOrDestination=65533, apsFrame=EmberApsFrame [profileId=0, clusterId=0, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=5C], messageTag=46, status=EMBER_SUCCESS, messageContents=]
2019-11-29 16:05:18.008 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=46 state=RX_ACK
2019-11-29 16:05:18.010 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=46, state=RX_ACK, outstanding=2
2019-11-29 16:05:19.852 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=26337]
2019-11-29 16:05:19.903 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=26337]
2019-11-29 16:05:21.563 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=26337]
2019-11-29 16:05:21.609 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=26337]
2019-11-29 16:05:22.337 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=26417, state=FAILED, sendCnt=2, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=44, nwkAddrOfInterest=26337]]
2019-11-29 16:05:22.343 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2019-11-29 16:05:22.344 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 14B457FFFE954ACB: transactionComplete FAILED 1
2019-11-29 16:05:22.345 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 14B457FFFE954ACB: transactionComplete exceeded retries 2
2019-11-29 16:05:22.346 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=26426, state=FAILED, sendCnt=2, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=44, nwkAddrOfInterest=26337]]
2019-11-29 16:05:22.348 [DEBUG] [transaction.ZigBeeTransactionManager] - 26337/0: Sending ZigBeeTransaction [queueTime=5203, state=WAITING, sendCnt=0, command=IeeeAddressRequest [0/0 -> 26337/0, cluster=0001, TID=47, nwkAddrOfInterest=26337, requestType=1, startIndex=0]]
2019-11-29 16:05:22.349 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2019-11-29 16:05:22.350 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: IeeeAddressRequest [0/0 -> 26337/0, cluster=0001, TID=47, nwkAddrOfInterest=26337, requestType=1, startIndex=0]
2019-11-29 16:05:22.351 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=26337/0, profile=0000, cluster=0001, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=74, payload=00 E1 66 01 00]
2019-11-29 16:05:22.363 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=5E]
2019-11-29 16:05:22.386 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=26337, apsFrame=EmberApsFrame [profileId=0, clusterId=1, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=5E], messageTag=47, status=EMBER_SUCCESS, messageContents=]
2019-11-29 16:05:22.387 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=47 state=RX_ACK
2019-11-29 16:05:22.388 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=10059, state=FAILED, sendCnt=1, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=45, nwkAddrOfInterest=26337]]
2019-11-29 16:05:22.389 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=32769, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=5F], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00 CB 4A 95 FE FF 57 B4 14 E1 66 00]
2019-11-29 16:05:22.389 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=47, state=RX_ACK, outstanding=2
2019-11-29 16:05:22.389 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2019-11-29 16:05:22.391 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=8001, addressMode=null, radius=0, apsSecurity=false, apsCounter=5F, payload=00 00 CB 4A 95 FE FF 57 B4 14 E1 66 00]
2019-11-29 16:05:22.391 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 47 -> RX_ACK == ACKED
2019-11-29 16:05:22.392 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: IeeeAddressResponse [0/0 -> 0/0, cluster=8001, TID=--, status=SUCCESS, ieeeAddrRemoteDev=14B457FFFE954ACB, nwkAddrRemoteDev=26337, startIndex=null, nwkAddrAssocDevList=[]]
2019-11-29 16:05:22.392 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 14B457FFFE954ACB: transactionComplete FAILED 1
2019-11-29 16:05:22.393 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: IeeeAddressResponse [0/0 -> 0/0, cluster=8001, TID=--, status=SUCCESS, ieeeAddrRemoteDev=14B457FFFE954ACB, nwkAddrRemoteDev=26337, startIndex=null, nwkAddrAssocDevList=[]]
2019-11-29 16:05:22.393 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 14B457FFFE954ACB: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=10064, state=WAITING, sendCnt=1, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=45, nwkAddrOfInterest=26337]]
2019-11-29 16:05:22.394 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: IeeeAddressResponse [0/0 -> 0/0, cluster=8001, TID=--, status=SUCCESS, ieeeAddrRemoteDev=14B457FFFE954ACB, nwkAddrRemoteDev=26337, startIndex=null, nwkAddrAssocDevList=[]] ZigBeeTransaction [queueTime=5250, state=ACKED, sendCnt=1, command=IeeeAddressRequest [0/0 -> 26337/0, cluster=0001, TID=47, nwkAddrOfInterest=26337, requestType=1, startIndex=0]]
2019-11-29 16:05:22.396 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=5251, state=COMPLETE, sendCnt=1, command=IeeeAddressRequest [0/0 -> 26337/0, cluster=0001, TID=47, nwkAddrOfInterest=26337, requestType=1, startIndex=0]]
2019-11-29 16:05:22.396 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 26337: NWK Discovery IeeeAddressRequest returned IeeeAddressResponse [0/0 -> 0/0, cluster=8001, TID=--, status=SUCCESS, ieeeAddrRemoteDev=14B457FFFE954ACB, nwkAddrRemoteDev=26337, startIndex=null, nwkAddrAssocDevList=[]]
2019-11-29 16:05:22.397 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 26337: NWK Discovery ending node discovery. Success=true.
2019-11-29 16:05:22.397 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2019-11-29 16:05:22.398 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 14B457FFFE954ACB: transactionComplete COMPLETE 0
2019-11-29 16:05:23.129 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=26337, apsFrame=EmberApsFrame [profileId=0, clusterId=3, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=58], messageTag=43, status=EMBER_DELIVERY_FAILED, messageContents=]
2019-11-29 16:05:23.131 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=43 state=RX_NAK
2019-11-29 16:05:23.133 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=43, state=RX_NAK, outstanding=0
2019-11-29 16:05:23.176 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=26337, apsFrame=EmberApsFrame [profileId=0, clusterId=3, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=59], messageTag=44, status=EMBER_DELIVERY_FAILED, messageContents=]
2019-11-29 16:05:23.178 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=44 state=RX_NAK
2019-11-29 16:05:23.181 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=44, state=RX_NAK, outstanding=0
2019-11-29 16:05:24.343 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 14B457FFFE954ACB: Node SVC Discovery: PowerDescriptorResponse returned null
2019-11-29 16:05:24.346 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 14B457FFFE954ACB: Node SVC Discovery: request POWER_DESCRIPTOR failed. Retry 6, wait 15379ms before retry.
2019-11-29 16:05:28.914 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=26337]
2019-11-29 16:05:28.965 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=26337]
2019-11-29 16:05:37.978 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=26337]
2019-11-29 16:05:38.028 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=26337]
2019-11-29 16:05:39.543 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=26337, apsFrame=EmberApsFrame [profileId=0, clusterId=3, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=5A], messageTag=44, status=EMBER_DELIVERY_FAILED, messageContents=]
2019-11-29 16:05:39.546 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=44 state=RX_NAK
2019-11-29 16:05:39.548 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=44, state=RX_NAK, outstanding=0
2019-11-29 16:05:39.594 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=26337, apsFrame=EmberApsFrame [profileId=0, clusterId=3, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=5B], messageTag=45, status=EMBER_DELIVERY_FAILED, messageContents=]
2019-11-29 16:05:39.597 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=45 state=RX_NAK
2019-11-29 16:05:39.599 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=45, state=RX_NAK, outstanding=0
2019-11-29 16:05:39.728 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 14B457FFFE954ACB: Node SVC Discovery: running POWER_DESCRIPTOR
2019-11-29 16:05:39.730 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 14B457FFFE954ACB: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=--, nwkAddrOfInterest=26337]]
2019-11-29 16:05:39.733 [DEBUG] [transaction.ZigBeeTransactionManager] - 26337/0: Sending ZigBeeTransaction [queueTime=27403, state=WAITING, sendCnt=1, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=45, nwkAddrOfInterest=26337]]
2019-11-29 16:05:39.734 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2019-11-29 16:05:39.737 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=45, nwkAddrOfInterest=26337]
2019-11-29 16:05:39.739 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=26337/0, profile=0000, cluster=0003, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=75, payload=00 E1 66]
2019-11-29 16:05:39.761 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=60]
2019-11-29 16:05:39.783 [DEBUG] [transaction.ZigBeeTransactionManager] - 26337/0: Sending ZigBeeTransaction [queueTime=52, state=WAITING, sendCnt=0, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=48, nwkAddrOfInterest=26337]]
2019-11-29 16:05:39.785 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2019-11-29 16:05:39.787 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=48, nwkAddrOfInterest=26337]
2019-11-29 16:05:39.790 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=26337/0, profile=0000, cluster=0003, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=76, payload=00 E1 66]
2019-11-29 16:05:39.804 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=61]
2019-11-29 16:05:47.263 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=26337]
2019-11-29 16:05:47.305 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=26337]
2019-11-29 16:05:49.737 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=37408, state=FAILED, sendCnt=2, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=45, nwkAddrOfInterest=26337]]
2019-11-29 16:05:49.740 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2019-11-29 16:05:49.742 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 14B457FFFE954ACB: transactionComplete FAILED 1
2019-11-29 16:05:49.744 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 14B457FFFE954ACB: transactionComplete exceeded retries 2
2019-11-29 16:05:49.746 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=37417, state=FAILED, sendCnt=2, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=45, nwkAddrOfInterest=26337]]
2019-11-29 16:05:49.788 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=10057, state=FAILED, sendCnt=1, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=48, nwkAddrOfInterest=26337]]
2019-11-29 16:05:49.789 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2019-11-29 16:05:49.791 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 14B457FFFE954ACB: transactionComplete FAILED 0
2019-11-29 16:05:49.794 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 14B457FFFE954ACB: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=10063, state=WAITING, sendCnt=1, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=48, nwkAddrOfInterest=26337]]
2019-11-29 16:05:51.752 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 14B457FFFE954ACB: Node SVC Discovery: PowerDescriptorResponse returned null
2019-11-29 16:05:51.754 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 14B457FFFE954ACB: Node SVC Discovery: request POWER_DESCRIPTOR failed. Retry 7, wait 8788ms before retry.
2019-11-29 16:05:56.326 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=26337]
2019-11-29 16:05:56.367 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=26337]
2019-11-29 16:06:00.544 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 14B457FFFE954ACB: Node SVC Discovery: running POWER_DESCRIPTOR
2019-11-29 16:06:00.546 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 14B457FFFE954ACB: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=--, nwkAddrOfInterest=26337]]
2019-11-29 16:06:00.549 [DEBUG] [transaction.ZigBeeTransactionManager] - 26337/0: Sending ZigBeeTransaction [queueTime=20818, state=WAITING, sendCnt=1, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=48, nwkAddrOfInterest=26337]]
2019-11-29 16:06:00.550 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2019-11-29 16:06:00.553 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=48, nwkAddrOfInterest=26337]
2019-11-29 16:06:00.555 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=26337/0, profile=0000, cluster=0003, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=77, payload=00 E1 66]
2019-11-29 16:06:00.568 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=62]
2019-11-29 16:06:00.599 [DEBUG] [transaction.ZigBeeTransactionManager] - 26337/0: Sending ZigBeeTransaction [queueTime=52, state=WAITING, sendCnt=0, command=PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=49, nwkAddrOfInterest=26337]]
2019-11-29 16:06:00.601 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2019-11-29 16:06:00.604 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: PowerDescriptorRequest [0/0 -> 26337/0, cluster=0003, TID=49, nwkAddrOfInterest=26337]
2019-11-29 16:06:00.606 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=26337/0, profile=0000, cluster=0003, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=78, payload=00 E1 66]
2019-11-29 16:06:00.620 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=63]