2019-12-07 03:21:11.572 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - Starting ZigBee scan for zigbee:coordinator_ember:cc9950e6 2019-12-07 03:21:11.573 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Permit join to 65532/0 for 60 seconds. 2019-12-07 03:21:11.574 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true]] 2019-12-07 03:21:11.575 [DEBUG] [transaction.ZigBeeTransactionManager] - 65532/0: Sending ZigBeeTransaction [queueTime=1, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=06, permitDuration=60, tcSignificance=true]] 2019-12-07 03:21:11.576 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding 2019-12-07 03:21:11.577 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=06, permitDuration=60, tcSignificance=true] 2019-12-07 03:21:11.577 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=65532/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=0C, payload=00 3C 01] 2019-12-07 03:21:11.578 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6F000DD02801: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true]] 2019-12-07 03:21:11.580 [DEBUG] [transaction.ZigBeeTransactionManager] - 0/0: Sending ZigBeeTransaction [queueTime=1, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=07, permitDuration=60, tcSignificance=true]] 2019-12-07 03:21:11.580 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding 2019-12-07 03:21:11.581 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=07, permitDuration=60, tcSignificance=true] 2019-12-07 03:21:11.582 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=0D, payload=00 3C 01] 2019-12-07 03:21:11.595 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendBroadcastResponse [status=EMBER_SUCCESS, sequence=60] 2019-12-07 03:21:11.603 [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=60], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 3C 01] 2019-12-07 03:21:11.604 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0036, addressMode=null, radius=0, apsSecurity=false, apsCounter=60, payload=00 3C 01] 2019-12-07 03:21:11.604 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] 2019-12-07 03:21:11.605 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] 2019-12-07 03:21:11.605 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] ZigBeeTransaction [queueTime=27, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=07, permitDuration=60, tcSignificance=true]] 2019-12-07 03:21:11.606 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] ZigBeeTransaction [queueTime=32, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=06, permitDuration=60, tcSignificance=true]] 2019-12-07 03:21:11.633 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=61] 2019-12-07 03:21:11.636 [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=61], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 3C 01] 2019-12-07 03:21:11.636 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0036, addressMode=null, radius=0, apsSecurity=false, apsCounter=61, payload=00 3C 01] 2019-12-07 03:21:11.637 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] 2019-12-07 03:21:11.637 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] 2019-12-07 03:21:11.638 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] ZigBeeTransaction [queueTime=60, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=07, permitDuration=60, tcSignificance=true]] 2019-12-07 03:21:11.638 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] ZigBeeTransaction [queueTime=64, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=06, permitDuration=60, tcSignificance=true]] 2019-12-07 03:21:11.642 [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=62], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00] 2019-12-07 03:21:11.643 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=8036, addressMode=null, radius=0, apsSecurity=false, apsCounter=62, payload=00 00] 2019-12-07 03:21:11.644 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] 2019-12-07 03:21:11.644 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] 2019-12-07 03:21:11.645 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] ZigBeeTransaction [queueTime=67, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=07, permitDuration=60, tcSignificance=true]] 2019-12-07 03:21:11.646 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] ZigBeeTransaction [queueTime=72, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=06, permitDuration=60, tcSignificance=true]] 2019-12-07 03:21:11.648 [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_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=61], messageTag=07, status=EMBER_SUCCESS, messageContents=] 2019-12-07 03:21:11.649 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=07 state=RX_ACK 2019-12-07 03:21:11.649 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=07, state=RX_ACK, outstanding=2 2019-12-07 03:21:11.650 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=72, state=COMPLETE, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=07, permitDuration=60, tcSignificance=true]] 2019-12-07 03:21:11.651 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding 2019-12-07 03:21:11.651 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6F000DD02801: transactionComplete COMPLETE 0 2019-12-07 03:21:11.652 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 07 -> RX_ACK == COMPLETE 2019-12-07 03:21:12.539 [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=60], messageTag=06, status=EMBER_SUCCESS, messageContents=] 2019-12-07 03:21:12.539 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=06 state=RX_ACK 2019-12-07 03:21:12.540 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=06, state=RX_ACK, outstanding=1 2019-12-07 03:21:12.542 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=968, state=COMPLETE, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=06, permitDuration=60, tcSignificance=true]] 2019-12-07 03:21:12.543 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding 2019-12-07 03:21:12.544 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete COMPLETE 0 2019-12-07 03:21:12.544 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 06 -> RX_ACK == COMPLETE 2019-12-07 03:21:13.515 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspChildJoinHandler [index=0, joining=true, childId=55072, childEui64=00158D0001FF8F6A, childType=EMBER_SLEEPY_END_DEVICE] 2019-12-07 03:21:13.517 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: nodeStatusUpdate - node status is UNSECURED_JOIN, network address is 55072. 2019-12-07 03:21:13.520 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D0001FF8F6A: Device status updated. NWK=55072 2019-12-07 03:21:13.520 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D0001FF8F6A: NWK Discovery add node 55072 2019-12-07 03:21:13.521 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00158D0001FF8F6A: Node state updated from UNKNOWN to ONLINE 2019-12-07 03:21:13.521 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Updating node NWK=55072 2019-12-07 03:21:13.523 [DEBUG] [p.discovery.ZigBeeDiscoveryExtension] - 00158D0001FF8F6A: DISCOVERY Extension: Adding discoverer for added node 2019-12-07 03:21:13.523 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 00158D0001FF8F6A: Data store: Deferring write for 250ms. 2019-12-07 03:21:13.524 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: created discoverer 2019-12-07 03:21:13.525 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: start discovery 2019-12-07 03:21:13.525 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: starting new tasks [POWER_DESCRIPTOR, NODE_DESCRIPTOR, NWK_ADDRESS, ACTIVE_ENDPOINTS] 2019-12-07 03:21:13.526 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: scheduled [POWER_DESCRIPTOR, NODE_DESCRIPTOR, NWK_ADDRESS, ACTIVE_ENDPOINTS] 2019-12-07 03:21:13.536 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 00158D0001FF8F6A: Starting ZigBee device discovery 2019-12-07 03:21:13.537 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 00158D0001FF8F6A: Creating ZigBee device zigbee:device with bridge zigbee:coordinator_ember:cc9950e6 2019-12-07 03:21:13.545 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zigbee:device:cc9950e6:00158d0001ff8f6a' to inbox. 2019-12-07 03:21:13.546 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 00158D0001FF8F6A: Node discovery not complete 2019-12-07 03:21:13.775 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 00158D0001FF8F6A: Data store: Writing node. 2019-12-07 03:21:13.781 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 00158D0001FF8F6A: ZigBee saving network state complete. 2019-12-07 03:21:14.017 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [newNodeId=55072, newNodeEui64=00158D0001FF8F6A, status=EMBER_STANDARD_SECURITY_UNSECURED_JOIN, policyDecision=EMBER_USE_PRECONFIGURED_KEY, parentOfNewNodeId=0] 2019-12-07 03:21:14.018 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: nodeStatusUpdate - node status is UNSECURED_JOIN, network address is 55072. 2019-12-07 03:21:14.018 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D0001FF8F6A: Device status updated. NWK=55072 2019-12-07 03:21:14.020 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D0001FF8F6A: NWK Discovery add node 55072 2019-12-07 03:21:14.021 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00158D0001FF8F6A: Node state updated from UNKNOWN to ONLINE 2019-12-07 03:21:14.022 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Updating node NWK=55072 2019-12-07 03:21:14.022 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Node 55072 update 2019-12-07 03:21:14.023 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Node 55072 is not updated 2019-12-07 03:21:14.303 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_BROADCAST, apsFrame=EmberApsFrame [profileId=0, clusterId=19, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=A6], lastHopLqi=255, lastHopRssi=-13, sender=55072, bindingIndex=255, addressIndex=255, messageContents=F3 20 D7 6A 8F FF 01 00 8D 15 00 80] 2019-12-07 03:21:14.303 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=55072/0, destinationAddress=0/0, profile=0000, cluster=0013, addressMode=null, radius=0, apsSecurity=false, apsCounter=A6, payload=F3 20 D7 6A 8F FF 01 00 8D 15 00 80] 2019-12-07 03:21:14.304 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: DeviceAnnounce [55072/0 -> 0/0, cluster=0013, TID=--, nwkAddrOfInterest=55072, ieeeAddr=00158D0001FF8F6A, capability=128] 2019-12-07 03:21:14.305 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: DeviceAnnounce [55072/0 -> 0/0, cluster=0013, TID=--, nwkAddrOfInterest=55072, ieeeAddr=00158D0001FF8F6A, capability=128] 2019-12-07 03:21:14.305 [DEBUG] [p.discovery.ZigBeeDiscoveryExtension] - DISCOVERY Extension: Mesh related command received. Triggering mesh update. 2019-12-07 03:21:14.306 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D0001FF8F6A: Device announce received. NWK=55072 2019-12-07 03:21:14.306 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D0001FF8F6A: NWK Discovery add node 55072 2019-12-07 03:21:14.306 [DEBUG] [p.discovery.ZigBeeDiscoveryExtension] - DISCOVERY Extension: Start mesh update task with interval of 86400 seconds 2019-12-07 03:21:14.307 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00158D0001FF8F6A: Node state updated from UNKNOWN to ONLINE 2019-12-07 03:21:14.307 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Updating node NWK=55072 2019-12-07 03:21:14.308 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Node 55072 update 2019-12-07 03:21:14.311 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Node 55072 is not updated 2019-12-07 03:21:14.318 [DEBUG] [p.discovery.ZigBeeDiscoveryExtension] - DISCOVERY Extension: Starting mesh update 2019-12-07 03:21:14.319 [DEBUG] [p.discovery.ZigBeeDiscoveryExtension] - 000D6F000DD02801: DISCOVERY Extension: Starting mesh update 2019-12-07 03:21:14.319 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000DD02801: Node SVC Discovery: Update mesh 2019-12-07 03:21:14.320 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000DD02801: Node SVC Discovery: starting new tasks [ROUTES, NEIGHBORS] 2019-12-07 03:21:14.321 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000DD02801: Node SVC Discovery: scheduled [ROUTES, NEIGHBORS] 2019-12-07 03:21:14.321 [DEBUG] [p.discovery.ZigBeeDiscoveryExtension] - 00158D0001FF8F6A: DISCOVERY Extension: Starting mesh update 2019-12-07 03:21:14.322 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: Update mesh 2019-12-07 03:21:14.324 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: starting new tasks [ROUTES, NEIGHBORS] 2019-12-07 03:21:14.324 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: already scheduled or running 2019-12-07 03:21:14.325 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: scheduled [POWER_DESCRIPTOR, NODE_DESCRIPTOR, NWK_ADDRESS, ACTIVE_ENDPOINTS, ROUTES, NEIGHBORS] 2019-12-07 03:21:14.670 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000DD02801: Node SVC Discovery: running ROUTES 2019-12-07 03:21:14.671 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6F000DD02801: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=--, startIndex=0]] 2019-12-07 03:21:14.671 [DEBUG] [transaction.ZigBeeTransactionManager] - 0/0: Sending ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=08, startIndex=0]] 2019-12-07 03:21:14.672 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding 2019-12-07 03:21:14.672 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=08, startIndex=0] 2019-12-07 03:21:14.673 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0032, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=0E, payload=00 00] 2019-12-07 03:21:14.686 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=65] 2019-12-07 03:21:14.717 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=50, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=65], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00] 2019-12-07 03:21:14.718 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0032, addressMode=null, radius=0, apsSecurity=false, apsCounter=65, payload=00 00] 2019-12-07 03:21:14.718 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=--, startIndex=0] 2019-12-07 03:21:14.719 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=--, startIndex=0] 2019-12-07 03:21:14.719 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=--, startIndex=0] ZigBeeTransaction [queueTime=48, state=DISPATCHED, sendCnt=1, command=ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=08, startIndex=0]] 2019-12-07 03:21:14.723 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=32818, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=66], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00 10 00 0F 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00] 2019-12-07 03:21:14.724 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=8032, addressMode=null, radius=0, apsSecurity=false, apsCounter=66, payload=00 00 10 00 0F 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00] 2019-12-07 03:21:14.725 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementRoutingResponse [0/0 -> 0/0, cluster=8032, TID=--, status=SUCCESS, routingTableEntries=16, startIndex=0, routingTableList=[RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0]]] 2019-12-07 03:21:14.726 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementRoutingResponse [0/0 -> 0/0, cluster=8032, TID=--, status=SUCCESS, routingTableEntries=16, startIndex=0, routingTableList=[RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0]]] 2019-12-07 03:21:14.727 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementRoutingResponse [0/0 -> 0/0, cluster=8032, TID=--, status=SUCCESS, routingTableEntries=16, startIndex=0, routingTableList=[RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0]]] ZigBeeTransaction [queueTime=56, state=DISPATCHED, sendCnt=1, command=ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=08, startIndex=0]] 2019-12-07 03:21:14.729 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000DD02801: Node SVC Discovery: ManagementRoutingRequest returned CommandResult [SUCCESS, ManagementRoutingResponse [0/0 -> 0/0, cluster=8032, TID=--, status=SUCCESS, routingTableEntries=16, startIndex=0, routingTableList=[RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0]]]] 2019-12-07 03:21:14.729 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=58, state=COMPLETE, sendCnt=1, command=ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=08, startIndex=0]] 2019-12-07 03:21:14.731 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding 2019-12-07 03:21:14.731 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=0, apsFrame=EmberApsFrame [profileId=0, clusterId=50, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=65], messageTag=08, status=EMBER_SUCCESS, messageContents=] 2019-12-07 03:21:14.731 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6F000DD02801: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=--, startIndex=15]] 2019-12-07 03:21:14.732 [DEBUG] [transaction.ZigBeeTransactionManager] - 0/0: Sending ZigBeeTransaction [queueTime=1, state=WAITING, sendCnt=0, command=ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=09, startIndex=15]] 2019-12-07 03:21:14.732 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding 2019-12-07 03:21:14.733 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=08 state=RX_ACK 2019-12-07 03:21:14.733 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=09, startIndex=15] 2019-12-07 03:21:14.734 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=08, state=RX_ACK, outstanding=1 2019-12-07 03:21:14.736 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0032, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=0F, payload=00 0F] 2019-12-07 03:21:14.737 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6F000DD02801: transactionComplete COMPLETE 1 2019-12-07 03:21:14.750 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=67] 2019-12-07 03:21:14.767 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=50, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=67], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 0F] 2019-12-07 03:21:14.767 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0032, addressMode=null, radius=0, apsSecurity=false, apsCounter=67, payload=00 0F] 2019-12-07 03:21:14.768 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=--, startIndex=15] 2019-12-07 03:21:14.769 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=--, startIndex=15] 2019-12-07 03:21:14.770 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=--, startIndex=15] ZigBeeTransaction [queueTime=38, state=DISPATCHED, sendCnt=1, command=ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=09, startIndex=15]] 2019-12-07 03:21:14.773 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=32818, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=68], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00 10 0F 01 00 00 03 00 00] 2019-12-07 03:21:14.774 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=8032, addressMode=null, radius=0, apsSecurity=false, apsCounter=68, payload=00 00 10 0F 01 00 00 03 00 00] 2019-12-07 03:21:14.774 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementRoutingResponse [0/0 -> 0/0, cluster=8032, TID=--, status=SUCCESS, routingTableEntries=16, startIndex=15, routingTableList=[RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0]]] 2019-12-07 03:21:14.775 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementRoutingResponse [0/0 -> 0/0, cluster=8032, TID=--, status=SUCCESS, routingTableEntries=16, startIndex=15, routingTableList=[RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0]]] 2019-12-07 03:21:14.776 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementRoutingResponse [0/0 -> 0/0, cluster=8032, TID=--, status=SUCCESS, routingTableEntries=16, startIndex=15, routingTableList=[RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0]]] ZigBeeTransaction [queueTime=44, state=DISPATCHED, sendCnt=1, command=ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=09, startIndex=15]] 2019-12-07 03:21:14.776 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=45, state=COMPLETE, sendCnt=1, command=ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=09, startIndex=15]] 2019-12-07 03:21:14.776 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000DD02801: Node SVC Discovery: ManagementRoutingRequest returned CommandResult [SUCCESS, ManagementRoutingResponse [0/0 -> 0/0, cluster=8032, TID=--, status=SUCCESS, routingTableEntries=16, startIndex=15, routingTableList=[RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0]]]] 2019-12-07 03:21:14.777 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding 2019-12-07 03:21:14.777 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000DD02801: Node SVC Discovery: ManagementLqiRequest complete [1 routes] 2019-12-07 03:21:14.777 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6F000DD02801: transactionComplete COMPLETE 0 2019-12-07 03:21:14.778 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 000D6F000DD02801: Routing table NEW: [RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0]] 2019-12-07 03:21:14.778 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 000D6F000DD02801: Routing table OLD: [] 2019-12-07 03:21:14.779 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 000D6F000DD02801: Routing table updated: [RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0]] 2019-12-07 03:21:14.779 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000DD02801: Node SVC Discovery: request ROUTES successful. Advancing to NEIGHBORS. 2019-12-07 03:21:14.780 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=0, apsFrame=EmberApsFrame [profileId=0, clusterId=50, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=67], messageTag=09, status=EMBER_SUCCESS, messageContents=] 2019-12-07 03:21:14.780 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000DD02801: Node SVC Discovery: running NEIGHBORS 2019-12-07 03:21:14.780 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=09 state=RX_ACK 2019-12-07 03:21:14.780 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6F000DD02801: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ManagementLqiRequest [0/0 -> 0/0, cluster=0031, TID=--, startIndex=0]] 2019-12-07 03:21:14.781 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=09, state=RX_ACK, outstanding=0 2019-12-07 03:21:14.783 [DEBUG] [transaction.ZigBeeTransactionManager] - 0/0: Sending ZigBeeTransaction [queueTime=3, state=WAITING, sendCnt=0, command=ManagementLqiRequest [0/0 -> 0/0, cluster=0031, TID=0A, startIndex=0]] 2019-12-07 03:21:14.784 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding 2019-12-07 03:21:14.784 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementLqiRequest [0/0 -> 0/0, cluster=0031, TID=0A, startIndex=0] 2019-12-07 03:21:14.785 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0031, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=10, payload=00 00] 2019-12-07 03:21:14.799 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=69] 2019-12-07 03:21:14.815 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: running POWER_DESCRIPTOR 2019-12-07 03:21:14.816 [DEBUG] [transaction.ZigBeeTransactionManager] - 00158D0001FF8F6A: Creating new Transaction Queue 2019-12-07 03:21:14.816 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Set profile to ZigBeeTransactionProfile [maxOutstandingTransactions=2, interTransactionDelay=50, maxRetries=2] 2019-12-07 03:21:14.817 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=PowerDescriptorRequest [0/0 -> 55072/0, cluster=0003, TID=--, nwkAddrOfInterest=55072]] 2019-12-07 03:21:14.818 [DEBUG] [transaction.ZigBeeTransactionManager] - 55072/0: Sending ZigBeeTransaction [queueTime=1, state=WAITING, sendCnt=0, command=PowerDescriptorRequest [0/0 -> 55072/0, cluster=0003, TID=0B, nwkAddrOfInterest=55072]] 2019-12-07 03:21:14.818 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding 2019-12-07 03:21:14.819 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: PowerDescriptorRequest [0/0 -> 55072/0, cluster=0003, TID=0B, nwkAddrOfInterest=55072] 2019-12-07 03:21:14.819 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=55072/0, profile=0000, cluster=0003, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=11, payload=00 20 D7] 2019-12-07 03:21:14.821 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=49, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=69], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00] 2019-12-07 03:21:14.822 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0031, addressMode=null, radius=0, apsSecurity=false, apsCounter=69, payload=00 00] 2019-12-07 03:21:14.823 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementLqiRequest [0/0 -> 0/0, cluster=0031, TID=--, startIndex=0] 2019-12-07 03:21:14.823 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementLqiRequest [0/0 -> 0/0, cluster=0031, TID=--, startIndex=0] 2019-12-07 03:21:14.824 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementLqiRequest [0/0 -> 0/0, cluster=0031, TID=--, startIndex=0] ZigBeeTransaction [queueTime=7, state=DISPATCHED, sendCnt=1, command=PowerDescriptorRequest [0/0 -> 55072/0, cluster=0003, TID=0B, nwkAddrOfInterest=55072]] 2019-12-07 03:21:14.825 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementLqiRequest [0/0 -> 0/0, cluster=0031, TID=--, startIndex=0] ZigBeeTransaction [queueTime=44, state=DISPATCHED, sendCnt=1, command=ManagementLqiRequest [0/0 -> 0/0, cluster=0031, TID=0A, startIndex=0]] 2019-12-07 03:21:14.830 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=32817, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=6A], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00 01 00 01 33 9A 88 7B 08 39 69 07 6A 8F FF 01 00 8D 15 00 20 D7 12 00 01 FF] 2019-12-07 03:21:14.831 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=8031, addressMode=null, radius=0, apsSecurity=false, apsCounter=6A, payload=00 00 01 00 01 33 9A 88 7B 08 39 69 07 6A 8F FF 01 00 8D 15 00 20 D7 12 00 01 FF] 2019-12-07 03:21:14.838 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementLqiResponse [0/0 -> 0/0, cluster=8031, TID=--, status=SUCCESS, neighborTableEntries=1, startIndex=0, neighborTableList=[NeighborTable [extendedPanId=076939087B889A33, extendedAddress=00158D0001FF8F6A, networkAddress=55072, deviceType=END_DEVICE, rxOnWhenIdle=RX_OFF, relationship=CHILD, permitJoining=DISABLED, depth=1, lqi=255]]] 2019-12-07 03:21:14.839 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementLqiResponse [0/0 -> 0/0, cluster=8031, TID=--, status=SUCCESS, neighborTableEntries=1, startIndex=0, neighborTableList=[NeighborTable [extendedPanId=076939087B889A33, extendedAddress=00158D0001FF8F6A, networkAddress=55072, deviceType=END_DEVICE, rxOnWhenIdle=RX_OFF, relationship=CHILD, permitJoining=DISABLED, depth=1, lqi=255]]] 2019-12-07 03:21:14.840 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementLqiResponse [0/0 -> 0/0, cluster=8031, TID=--, status=SUCCESS, neighborTableEntries=1, startIndex=0, neighborTableList=[NeighborTable [extendedPanId=076939087B889A33, extendedAddress=00158D0001FF8F6A, networkAddress=55072, deviceType=END_DEVICE, rxOnWhenIdle=RX_OFF, relationship=CHILD, permitJoining=DISABLED, depth=1, lqi=255]]] ZigBeeTransaction [queueTime=23, state=DISPATCHED, sendCnt=1, command=PowerDescriptorRequest [0/0 -> 55072/0, cluster=0003, TID=0B, nwkAddrOfInterest=55072]] 2019-12-07 03:21:14.843 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementLqiResponse [0/0 -> 0/0, cluster=8031, TID=--, status=SUCCESS, neighborTableEntries=1, startIndex=0, neighborTableList=[NeighborTable [extendedPanId=076939087B889A33, extendedAddress=00158D0001FF8F6A, networkAddress=55072, deviceType=END_DEVICE, rxOnWhenIdle=RX_OFF, relationship=CHILD, permitJoining=DISABLED, depth=1, lqi=255]]] ZigBeeTransaction [queueTime=62, state=DISPATCHED, sendCnt=1, command=ManagementLqiRequest [0/0 -> 0/0, cluster=0031, TID=0A, startIndex=0]] 2019-12-07 03:21:14.844 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=64, state=COMPLETE, sendCnt=1, command=ManagementLqiRequest [0/0 -> 0/0, cluster=0031, TID=0A, startIndex=0]] 2019-12-07 03:21:14.845 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000DD02801: Node SVC Discovery: ManagementLqiRequest response CommandResult [SUCCESS, ManagementLqiResponse [0/0 -> 0/0, cluster=8031, TID=--, status=SUCCESS, neighborTableEntries=1, startIndex=0, neighborTableList=[NeighborTable [extendedPanId=076939087B889A33, extendedAddress=00158D0001FF8F6A, networkAddress=55072, deviceType=END_DEVICE, rxOnWhenIdle=RX_OFF, relationship=CHILD, permitJoining=DISABLED, depth=1, lqi=255]]]] 2019-12-07 03:21:14.845 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding 2019-12-07 03:21:14.846 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6F000DD02801: transactionComplete COMPLETE 0 2019-12-07 03:21:14.846 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000DD02801: Node SVC Discovery: ManagementLqiRequest complete [1 neighbors] 2019-12-07 03:21:14.847 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 000D6F000DD02801: Neighbor table updated: [NeighborTable [extendedPanId=076939087B889A33, extendedAddress=00158D0001FF8F6A, networkAddress=55072, deviceType=END_DEVICE, rxOnWhenIdle=RX_OFF, relationship=CHILD, permitJoining=DISABLED, depth=1, lqi=255]] 2019-12-07 03:21:14.848 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000DD02801: Node SVC Discovery: request NEIGHBORS successful. Advancing to null. 2019-12-07 03:21:14.848 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000DD02801: Node SVC Discovery: complete 2019-12-07 03:21:14.849 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=0, apsFrame=EmberApsFrame [profileId=0, clusterId=49, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=69], messageTag=0A, status=EMBER_SUCCESS, messageContents=] 2019-12-07 03:21:14.849 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 000D6F000DD02801: Updating node NWK=0 2019-12-07 03:21:14.850 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 000D6F000DD02801: Node 0 update 2019-12-07 03:21:14.851 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 000D6F000DD02801: Neighbors updated 2019-12-07 03:21:14.852 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspZigbeeKeyEstablishmentHandler [partner=00158D0001FF8F6A, status=UNKNOWN] 2019-12-07 03:21:14.853 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 000D6F000DD02801: Data store: Deferring write for 250ms. 2019-12-07 03:21:14.853 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6F000DD02801: Set profile to ZigBeeTransactionProfile [maxOutstandingTransactions=2, interTransactionDelay=50, maxRetries=2] 2019-12-07 03:21:14.854 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=6B] 2019-12-07 03:21:14.856 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=0A state=RX_ACK 2019-12-07 03:21:14.856 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=0A, state=RX_ACK, outstanding=1 2019-12-07 03:21:15.046 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=55072, apsFrame=EmberApsFrame [profileId=0, clusterId=3, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=6B], messageTag=0B, status=EMBER_SUCCESS, messageContents=] 2019-12-07 03:21:15.047 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=0B state=RX_ACK 2019-12-07 03:21:15.047 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=0B, state=RX_ACK, outstanding=1 2019-12-07 03:21:15.048 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 0B -> RX_ACK == ACKED 2019-12-07 03:21:15.054 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=32771, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=A9], lastHopLqi=255, lastHopRssi=-16, sender=55072, bindingIndex=255, addressIndex=255, messageContents=00 00 20 D7 40 C4] 2019-12-07 03:21:15.055 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=55072/0, destinationAddress=0/0, profile=0000, cluster=8003, addressMode=null, radius=0, apsSecurity=false, apsCounter=A9, payload=00 00 20 D7 40 C4] 2019-12-07 03:21:15.057 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: PowerDescriptorResponse [55072/0 -> 0/0, cluster=8003, TID=--, status=SUCCESS, nwkAddrOfInterest=55072, powerDescriptor=PowerDescriptor [currentPowerMode=RECEIVER_ON_IDLE, availablePowerSources=[DISPOSABLE_BATTERY], currentPowerSource=DISPOSABLE_BATTERY, powerLevel=FULL]] 2019-12-07 03:21:15.058 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: PowerDescriptorResponse [55072/0 -> 0/0, cluster=8003, TID=--, status=SUCCESS, nwkAddrOfInterest=55072, powerDescriptor=PowerDescriptor [currentPowerMode=RECEIVER_ON_IDLE, availablePowerSources=[DISPOSABLE_BATTERY], currentPowerSource=DISPOSABLE_BATTERY, powerLevel=FULL]] 2019-12-07 03:21:15.059 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: PowerDescriptorResponse [55072/0 -> 0/0, cluster=8003, TID=--, status=SUCCESS, nwkAddrOfInterest=55072, powerDescriptor=PowerDescriptor [currentPowerMode=RECEIVER_ON_IDLE, availablePowerSources=[DISPOSABLE_BATTERY], currentPowerSource=DISPOSABLE_BATTERY, powerLevel=FULL]] ZigBeeTransaction [queueTime=242, state=ACKED, sendCnt=1, command=PowerDescriptorRequest [0/0 -> 55072/0, cluster=0003, TID=0B, nwkAddrOfInterest=55072]] 2019-12-07 03:21:15.061 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=244, state=COMPLETE, sendCnt=1, command=PowerDescriptorRequest [0/0 -> 55072/0, cluster=0003, TID=0B, nwkAddrOfInterest=55072]] 2019-12-07 03:21:15.061 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: PowerDescriptorResponse returned PowerDescriptorResponse [55072/0 -> 0/0, cluster=8003, TID=--, status=SUCCESS, nwkAddrOfInterest=55072, powerDescriptor=PowerDescriptor [currentPowerMode=RECEIVER_ON_IDLE, availablePowerSources=[DISPOSABLE_BATTERY], currentPowerSource=DISPOSABLE_BATTERY, powerLevel=FULL]] 2019-12-07 03:21:15.062 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding 2019-12-07 03:21:15.062 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: request POWER_DESCRIPTOR successful. Advancing to NODE_DESCRIPTOR. 2019-12-07 03:21:15.063 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: running NODE_DESCRIPTOR 2019-12-07 03:21:15.062 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete COMPLETE 0 2019-12-07 03:21:15.066 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=NodeDescriptorRequest [0/0 -> 55072/0, cluster=0002, TID=--, nwkAddrOfInterest=55072]] 2019-12-07 03:21:15.067 [DEBUG] [transaction.ZigBeeTransactionManager] - 55072/0: Sending ZigBeeTransaction [queueTime=1, state=WAITING, sendCnt=0, command=NodeDescriptorRequest [0/0 -> 55072/0, cluster=0002, TID=0C, nwkAddrOfInterest=55072]] 2019-12-07 03:21:15.068 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding 2019-12-07 03:21:15.069 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NodeDescriptorRequest [0/0 -> 55072/0, cluster=0002, TID=0C, nwkAddrOfInterest=55072] 2019-12-07 03:21:15.069 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=55072/0, profile=0000, cluster=0002, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=12, payload=00 20 D7] 2019-12-07 03:21:15.082 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=6C] 2019-12-07 03:21:15.104 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 000D6F000DD02801: Data store: Writing node. 2019-12-07 03:21:15.111 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 000D6F000DD02801: ZigBee saving network state complete. 2019-12-07 03:21:15.352 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=55072, apsFrame=EmberApsFrame [profileId=0, clusterId=2, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=6C], messageTag=0C, status=EMBER_SUCCESS, messageContents=] 2019-12-07 03:21:15.353 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=0C state=RX_ACK 2019-12-07 03:21:15.354 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=0C, state=RX_ACK, outstanding=1 2019-12-07 03:21:15.354 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 0C -> RX_ACK == ACKED 2019-12-07 03:21:15.369 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=32770, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=AA], lastHopLqi=254, lastHopRssi=-22, sender=55072, bindingIndex=255, addressIndex=255, messageContents=00 00 20 D7 02 40 80 37 10 7F 64 00 00 2C 64 00 00] 2019-12-07 03:21:15.370 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=55072/0, destinationAddress=0/0, profile=0000, cluster=8002, addressMode=null, radius=0, apsSecurity=false, apsCounter=AA, payload=00 00 20 D7 02 40 80 37 10 7F 64 00 00 2C 64 00 00] 2019-12-07 03:21:15.372 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: NodeDescriptorResponse [55072/0 -> 0/0, cluster=8002, TID=--, status=SUCCESS, nwkAddrOfInterest=55072, nodeDescriptor=NodeDescriptor [apsFlags=0, bufferSize=127, complexDescriptorAvailable=false, manufacturerCode=4151, logicalType=END_DEVICE, serverCapabilities=[], incomingTransferSize=100, outgoingTransferSize=100, userDescriptorAvailable=false, frequencyBands=[FREQ_2400_MHZ], macCapabilities=[REDUCED_FUNCTION_DEVICE], extendedEndpointListAvailable=false, extendedSimpleDescriptorListAvailable=false, stackCompliance=22]] 2019-12-07 03:21:15.373 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NodeDescriptorResponse [55072/0 -> 0/0, cluster=8002, TID=--, status=SUCCESS, nwkAddrOfInterest=55072, nodeDescriptor=NodeDescriptor [apsFlags=0, bufferSize=127, complexDescriptorAvailable=false, manufacturerCode=4151, logicalType=END_DEVICE, serverCapabilities=[], incomingTransferSize=100, outgoingTransferSize=100, userDescriptorAvailable=false, frequencyBands=[FREQ_2400_MHZ], macCapabilities=[REDUCED_FUNCTION_DEVICE], extendedEndpointListAvailable=false, extendedSimpleDescriptorListAvailable=false, stackCompliance=22]] 2019-12-07 03:21:15.374 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NodeDescriptorResponse [55072/0 -> 0/0, cluster=8002, TID=--, status=SUCCESS, nwkAddrOfInterest=55072, nodeDescriptor=NodeDescriptor [apsFlags=0, bufferSize=127, complexDescriptorAvailable=false, manufacturerCode=4151, logicalType=END_DEVICE, serverCapabilities=[], incomingTransferSize=100, outgoingTransferSize=100, userDescriptorAvailable=false, frequencyBands=[FREQ_2400_MHZ], macCapabilities=[REDUCED_FUNCTION_DEVICE], extendedEndpointListAvailable=false, extendedSimpleDescriptorListAvailable=false, stackCompliance=22]] ZigBeeTransaction [queueTime=308, state=ACKED, sendCnt=1, command=NodeDescriptorRequest [0/0 -> 55072/0, cluster=0002, TID=0C, nwkAddrOfInterest=55072]] 2019-12-07 03:21:15.375 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=309, state=COMPLETE, sendCnt=1, command=NodeDescriptorRequest [0/0 -> 55072/0, cluster=0002, TID=0C, nwkAddrOfInterest=55072]] 2019-12-07 03:21:15.375 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: NodeDescriptorResponse returned NodeDescriptorResponse [55072/0 -> 0/0, cluster=8002, TID=--, status=SUCCESS, nwkAddrOfInterest=55072, nodeDescriptor=NodeDescriptor [apsFlags=0, bufferSize=127, complexDescriptorAvailable=false, manufacturerCode=4151, logicalType=END_DEVICE, serverCapabilities=[], incomingTransferSize=100, outgoingTransferSize=100, userDescriptorAvailable=false, frequencyBands=[FREQ_2400_MHZ], macCapabilities=[REDUCED_FUNCTION_DEVICE], extendedEndpointListAvailable=false, extendedSimpleDescriptorListAvailable=false, stackCompliance=22]] 2019-12-07 03:21:15.376 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding 2019-12-07 03:21:15.376 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete COMPLETE 0 2019-12-07 03:21:15.376 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: request NODE_DESCRIPTOR successful. Advancing to NWK_ADDRESS. 2019-12-07 03:21:15.377 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: running NWK_ADDRESS 2019-12-07 03:21:15.378 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0/0 -> 65535/0, cluster=0000, TID=--, ieeeAddr=00158D0001FF8F6A, requestType=0, startIndex=0]] 2019-12-07 03:21:15.379 [DEBUG] [transaction.ZigBeeTransactionManager] - 65535/0: Sending ZigBeeTransaction [queueTime=1, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0/0 -> 65535/0, cluster=0000, TID=0D, ieeeAddr=00158D0001FF8F6A, requestType=0, startIndex=0]] 2019-12-07 03:21:15.379 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding 2019-12-07 03:21:15.380 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0/0 -> 65535/0, cluster=0000, TID=0D, ieeeAddr=00158D0001FF8F6A, requestType=0, startIndex=0] 2019-12-07 03:21:15.380 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=65535/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=13, payload=00 6A 8F FF 01 00 8D 15 00 00 00] 2019-12-07 03:21:15.399 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendBroadcastResponse [status=EMBER_SUCCESS, sequence=6D] 2019-12-07 03:21:15.421 [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=6D], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 6A 8F FF 01 00 8D 15 00 00 00] 2019-12-07 03:21:15.422 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0000, addressMode=null, radius=0, apsSecurity=false, apsCounter=6D, payload=00 6A 8F FF 01 00 8D 15 00 00 00] 2019-12-07 03:21:15.423 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: NetworkAddressRequest [0/0 -> 0/0, cluster=0000, TID=--, ieeeAddr=00158D0001FF8F6A, requestType=0, startIndex=0] 2019-12-07 03:21:15.424 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NetworkAddressRequest [0/0 -> 0/0, cluster=0000, TID=--, ieeeAddr=00158D0001FF8F6A, requestType=0, startIndex=0] 2019-12-07 03:21:15.425 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NetworkAddressRequest [0/0 -> 0/0, cluster=0000, TID=--, ieeeAddr=00158D0001FF8F6A, requestType=0, startIndex=0] ZigBeeTransaction [queueTime=47, state=DISPATCHED, sendCnt=1, command=NetworkAddressRequest [0/0 -> 65535/0, cluster=0000, TID=0D, ieeeAddr=00158D0001FF8F6A, requestType=0, startIndex=0]] 2019-12-07 03:21:15.428 [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=6E], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00 6A 8F FF 01 00 8D 15 00 20 D7] 2019-12-07 03:21:15.428 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=8000, addressMode=null, radius=0, apsSecurity=false, apsCounter=6E, payload=00 00 6A 8F FF 01 00 8D 15 00 20 D7] 2019-12-07 03:21:15.430 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: NetworkAddressResponse [0/0 -> 0/0, cluster=8000, TID=--, status=SUCCESS, ieeeAddrRemoteDev=00158D0001FF8F6A, nwkAddrRemoteDev=55072, startIndex=null, nwkAddrAssocDevList=[]] 2019-12-07 03:21:15.430 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NetworkAddressResponse [0/0 -> 0/0, cluster=8000, TID=--, status=SUCCESS, ieeeAddrRemoteDev=00158D0001FF8F6A, nwkAddrRemoteDev=55072, startIndex=null, nwkAddrAssocDevList=[]] 2019-12-07 03:21:15.431 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NetworkAddressResponse [0/0 -> 0/0, cluster=8000, TID=--, status=SUCCESS, ieeeAddrRemoteDev=00158D0001FF8F6A, nwkAddrRemoteDev=55072, startIndex=null, nwkAddrAssocDevList=[]] ZigBeeTransaction [queueTime=53, state=DISPATCHED, sendCnt=1, command=NetworkAddressRequest [0/0 -> 65535/0, cluster=0000, TID=0D, ieeeAddr=00158D0001FF8F6A, requestType=0, startIndex=0]] 2019-12-07 03:21:15.434 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: NetworkAddressRequest returned NetworkAddressResponse [0/0 -> 0/0, cluster=8000, TID=--, status=SUCCESS, ieeeAddrRemoteDev=00158D0001FF8F6A, nwkAddrRemoteDev=55072, startIndex=null, nwkAddrAssocDevList=[]] 2019-12-07 03:21:15.433 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=55, state=COMPLETE, sendCnt=1, command=NetworkAddressRequest [0/0 -> 65535/0, cluster=0000, TID=0D, ieeeAddr=00158D0001FF8F6A, requestType=0, startIndex=0]] 2019-12-07 03:21:15.435 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding 2019-12-07 03:21:15.435 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: request NWK_ADDRESS successful. Advancing to ACTIVE_ENDPOINTS. 2019-12-07 03:21:15.435 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete COMPLETE 0 2019-12-07 03:21:15.436 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: running ACTIVE_ENDPOINTS 2019-12-07 03:21:15.437 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ActiveEndpointsRequest [0/0 -> 55072/0, cluster=0005, TID=--, nwkAddrOfInterest=55072]] 2019-12-07 03:21:15.438 [DEBUG] [transaction.ZigBeeTransactionManager] - 55072/0: Sending ZigBeeTransaction [queueTime=1, state=WAITING, sendCnt=0, command=ActiveEndpointsRequest [0/0 -> 55072/0, cluster=0005, TID=0E, nwkAddrOfInterest=55072]] 2019-12-07 03:21:15.438 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding 2019-12-07 03:21:15.439 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ActiveEndpointsRequest [0/0 -> 55072/0, cluster=0005, TID=0E, nwkAddrOfInterest=55072] 2019-12-07 03:21:15.439 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=55072/0, profile=0000, cluster=0005, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=14, payload=00 20 D7] 2019-12-07 03:21:15.452 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=6F] 2019-12-07 03:21:15.644 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=55072, apsFrame=EmberApsFrame [profileId=0, clusterId=5, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=6F], messageTag=0E, status=EMBER_SUCCESS, messageContents=] 2019-12-07 03:21:15.644 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=0E state=RX_ACK 2019-12-07 03:21:15.645 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=0E, state=RX_ACK, outstanding=1 2019-12-07 03:21:15.645 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 0E -> RX_ACK == ACKED 2019-12-07 03:21:15.665 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=32773, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=AB], lastHopLqi=255, lastHopRssi=-23, sender=55072, bindingIndex=255, addressIndex=255, messageContents=00 00 20 D7 01 01] 2019-12-07 03:21:15.665 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=55072/0, destinationAddress=0/0, profile=0000, cluster=8005, addressMode=null, radius=0, apsSecurity=false, apsCounter=AB, payload=00 00 20 D7 01 01] 2019-12-07 03:21:15.666 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ActiveEndpointsResponse [55072/0 -> 0/0, cluster=8005, TID=--, status=SUCCESS, nwkAddrOfInterest=55072, activeEpList=[1]] 2019-12-07 03:21:15.667 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ActiveEndpointsResponse [55072/0 -> 0/0, cluster=8005, TID=--, status=SUCCESS, nwkAddrOfInterest=55072, activeEpList=[1]] 2019-12-07 03:21:15.667 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ActiveEndpointsResponse [55072/0 -> 0/0, cluster=8005, TID=--, status=SUCCESS, nwkAddrOfInterest=55072, activeEpList=[1]] ZigBeeTransaction [queueTime=230, state=ACKED, sendCnt=1, command=ActiveEndpointsRequest [0/0 -> 55072/0, cluster=0005, TID=0E, nwkAddrOfInterest=55072]] 2019-12-07 03:21:15.668 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=231, state=COMPLETE, sendCnt=1, command=ActiveEndpointsRequest [0/0 -> 55072/0, cluster=0005, TID=0E, nwkAddrOfInterest=55072]] 2019-12-07 03:21:15.668 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: ActiveEndpointsResponse returned CommandResult [SUCCESS, ActiveEndpointsResponse [55072/0 -> 0/0, cluster=8005, TID=--, status=SUCCESS, nwkAddrOfInterest=55072, activeEpList=[1]]] 2019-12-07 03:21:15.668 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding 2019-12-07 03:21:15.669 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete COMPLETE 0 2019-12-07 03:21:15.670 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=SimpleDescriptorRequest [0/0 -> 55072/0, cluster=0004, TID=--, nwkAddrOfInterest=55072, endpoint=1]] 2019-12-07 03:21:15.670 [DEBUG] [transaction.ZigBeeTransactionManager] - 55072/0: Sending ZigBeeTransaction [queueTime=1, state=WAITING, sendCnt=0, command=SimpleDescriptorRequest [0/0 -> 55072/0, cluster=0004, TID=0F, nwkAddrOfInterest=55072, endpoint=1]] 2019-12-07 03:21:15.671 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding 2019-12-07 03:21:15.671 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: SimpleDescriptorRequest [0/0 -> 55072/0, cluster=0004, TID=0F, nwkAddrOfInterest=55072, endpoint=1] 2019-12-07 03:21:15.672 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=55072/0, profile=0000, cluster=0004, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=15, payload=00 20 D7 01] 2019-12-07 03:21:15.684 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=70] 2019-12-07 03:21:15.957 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=55072, apsFrame=EmberApsFrame [profileId=0, clusterId=4, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=70], messageTag=0F, status=EMBER_SUCCESS, messageContents=] 2019-12-07 03:21:15.957 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=0F state=RX_ACK 2019-12-07 03:21:15.958 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=0F, state=RX_ACK, outstanding=1 2019-12-07 03:21:15.958 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 0F -> RX_ACK == ACKED 2019-12-07 03:21:15.978 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=32772, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=AC], lastHopLqi=255, lastHopRssi=-21, sender=55072, bindingIndex=255, addressIndex=255, messageContents=00 00 20 D7 22 01 04 01 01 03 01 06 00 00 01 00 03 00 01 02 19 00 0A 00 07 00 00 01 00 03 00 04 00 01 02 19 00 0A 00] 2019-12-07 03:21:15.978 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=55072/0, destinationAddress=0/0, profile=0000, cluster=8004, addressMode=null, radius=0, apsSecurity=false, apsCounter=AC, payload=00 00 20 D7 22 01 04 01 01 03 01 06 00 00 01 00 03 00 01 02 19 00 0A 00 07 00 00 01 00 03 00 04 00 01 02 19 00 0A 00] 2019-12-07 03:21:15.980 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: SimpleDescriptorResponse [55072/0 -> 0/0, cluster=8004, TID=--, status=SUCCESS, nwkAddrOfInterest=55072, length=34, simpleDescriptor=SimpleDescriptor [endpoint=1, profileId=0104, deviceId=769, deviceVersion=1, inputClusterList=[0, 1, 3, 513, 25, 10], outputClusterList=[0, 1, 3, 4, 513, 25, 10]]] 2019-12-07 03:21:15.980 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: SimpleDescriptorResponse [55072/0 -> 0/0, cluster=8004, TID=--, status=SUCCESS, nwkAddrOfInterest=55072, length=34, simpleDescriptor=SimpleDescriptor [endpoint=1, profileId=0104, deviceId=769, deviceVersion=1, inputClusterList=[0, 1, 3, 513, 25, 10], outputClusterList=[0, 1, 3, 4, 513, 25, 10]]] 2019-12-07 03:21:15.981 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: SimpleDescriptorResponse [55072/0 -> 0/0, cluster=8004, TID=--, status=SUCCESS, nwkAddrOfInterest=55072, length=34, simpleDescriptor=SimpleDescriptor [endpoint=1, profileId=0104, deviceId=769, deviceVersion=1, inputClusterList=[0, 1, 3, 513, 25, 10], outputClusterList=[0, 1, 3, 4, 513, 25, 10]]] ZigBeeTransaction [queueTime=312, state=ACKED, sendCnt=1, command=SimpleDescriptorRequest [0/0 -> 55072/0, cluster=0004, TID=0F, nwkAddrOfInterest=55072, endpoint=1]] 2019-12-07 03:21:15.982 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=312, state=COMPLETE, sendCnt=1, command=SimpleDescriptorRequest [0/0 -> 55072/0, cluster=0004, TID=0F, nwkAddrOfInterest=55072, endpoint=1]] 2019-12-07 03:21:15.982 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding 2019-12-07 03:21:15.982 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: SimpleDescriptorResponse returned SimpleDescriptorResponse [55072/0 -> 0/0, cluster=8004, TID=--, status=SUCCESS, nwkAddrOfInterest=55072, length=34, simpleDescriptor=SimpleDescriptor [endpoint=1, profileId=0104, deviceId=769, deviceVersion=1, inputClusterList=[0, 1, 3, 513, 25, 10], outputClusterList=[0, 1, 3, 4, 513, 25, 10]]] 2019-12-07 03:21:15.983 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete COMPLETE 0 2019-12-07 03:21:15.988 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 55072/1: Setting input clusters [0, 1, 3, 513, 25, 10] 2019-12-07 03:21:16.164 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 55072/1: Setting server cluster 0000 Basic 2019-12-07 03:21:16.167 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 55072/1: Setting server cluster 0001 Power Configuration 2019-12-07 03:21:16.170 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 55072/1: Setting server cluster 0003 Identify 2019-12-07 03:21:16.178 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 55072/1: Setting server cluster 0201 Thermostat 2019-12-07 03:21:16.188 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 55072/1: Setting server cluster 0019 Ota Upgrade 2019-12-07 03:21:16.189 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 55072/1: Setting server cluster 000A Time 2019-12-07 03:21:16.190 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 55072/1: Setting output clusters [0, 1, 3, 4, 513, 25, 10] 2019-12-07 03:21:16.190 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 55072/1: Setting client cluster 0000 Basic 2019-12-07 03:21:16.191 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 55072/1: Setting client cluster 0001 Power Configuration 2019-12-07 03:21:16.191 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 55072/1: Setting client cluster 0003 Identify 2019-12-07 03:21:16.197 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 55072/1: Setting client cluster 0004 Groups 2019-12-07 03:21:16.198 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 55072/1: Setting client cluster 0201 Thermostat 2019-12-07 03:21:16.198 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 55072/1: Setting client cluster 0019 Ota Upgrade 2019-12-07 03:21:16.199 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 55072/1: Setting client cluster 000A Time 2019-12-07 03:21:16.200 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: request ACTIVE_ENDPOINTS successful. Advancing to ROUTES. 2019-12-07 03:21:16.201 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: running ROUTES 2019-12-07 03:21:16.201 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ManagementRoutingRequest [0/0 -> 55072/0, cluster=0032, TID=--, startIndex=0]] 2019-12-07 03:21:16.202 [DEBUG] [transaction.ZigBeeTransactionManager] - 55072/0: Sending ZigBeeTransaction [queueTime=1, state=WAITING, sendCnt=0, command=ManagementRoutingRequest [0/0 -> 55072/0, cluster=0032, TID=10, startIndex=0]] 2019-12-07 03:21:16.202 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding 2019-12-07 03:21:16.202 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementRoutingRequest [0/0 -> 55072/0, cluster=0032, TID=10, startIndex=0] 2019-12-07 03:21:16.203 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=55072/0, profile=0000, cluster=0032, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=16, payload=00 00] 2019-12-07 03:21:16.215 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=71] 2019-12-07 03:21:16.244 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=55072, apsFrame=EmberApsFrame [profileId=0, clusterId=50, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=71], messageTag=10, status=EMBER_SUCCESS, messageContents=] 2019-12-07 03:21:16.244 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=10 state=RX_ACK 2019-12-07 03:21:16.245 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=10, state=RX_ACK, outstanding=1 2019-12-07 03:21:16.246 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 10 -> RX_ACK == ACKED 2019-12-07 03:21:16.247 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=32818, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=AD], lastHopLqi=254, lastHopRssi=-24, sender=55072, bindingIndex=255, addressIndex=255, messageContents=00 84] 2019-12-07 03:21:16.248 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=55072/0, destinationAddress=0/0, profile=0000, cluster=8032, addressMode=null, radius=0, apsSecurity=false, apsCounter=AD, payload=00 84] 2019-12-07 03:21:16.249 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementRoutingResponse [55072/0 -> 0/0, cluster=8032, TID=--, status=NOT_SUPPORTED, routingTableEntries=null, startIndex=null, routingTableList=[]] 2019-12-07 03:21:16.249 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementRoutingResponse [55072/0 -> 0/0, cluster=8032, TID=--, status=NOT_SUPPORTED, routingTableEntries=null, startIndex=null, routingTableList=[]] 2019-12-07 03:21:16.249 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementRoutingResponse [55072/0 -> 0/0, cluster=8032, TID=--, status=NOT_SUPPORTED, routingTableEntries=null, startIndex=null, routingTableList=[]] ZigBeeTransaction [queueTime=48, state=ACKED, sendCnt=1, command=ManagementRoutingRequest [0/0 -> 55072/0, cluster=0032, TID=10, startIndex=0]] 2019-12-07 03:21:16.250 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=49, state=COMPLETE, sendCnt=1, command=ManagementRoutingRequest [0/0 -> 55072/0, cluster=0032, TID=10, startIndex=0]] 2019-12-07 03:21:16.250 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding 2019-12-07 03:21:16.251 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete COMPLETE 0 2019-12-07 03:21:16.252 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: ManagementRoutingRequest returned CommandResult [ERROR (UNKNOWN,0xFF), ManagementRoutingResponse [55072/0 -> 0/0, cluster=8032, TID=--, status=NOT_SUPPORTED, routingTableEntries=null, startIndex=null, routingTableList=[]]] 2019-12-07 03:21:16.252 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery ManagementLqiRequest not supported 2019-12-07 03:21:16.253 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: request ROUTES successful. Advancing to NEIGHBORS. 2019-12-07 03:21:16.253 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: running NEIGHBORS 2019-12-07 03:21:16.254 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ManagementLqiRequest [0/0 -> 55072/0, cluster=0031, TID=--, startIndex=0]] 2019-12-07 03:21:16.254 [DEBUG] [transaction.ZigBeeTransactionManager] - 55072/0: Sending ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ManagementLqiRequest [0/0 -> 55072/0, cluster=0031, TID=11, startIndex=0]] 2019-12-07 03:21:16.255 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding 2019-12-07 03:21:16.255 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementLqiRequest [0/0 -> 55072/0, cluster=0031, TID=11, startIndex=0] 2019-12-07 03:21:16.256 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=55072/0, profile=0000, cluster=0031, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=17, payload=00 00] 2019-12-07 03:21:16.268 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=72] 2019-12-07 03:21:16.554 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=55072, apsFrame=EmberApsFrame [profileId=0, clusterId=49, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=72], messageTag=11, status=EMBER_SUCCESS, messageContents=] 2019-12-07 03:21:16.555 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=11 state=RX_ACK 2019-12-07 03:21:16.556 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=11, state=RX_ACK, outstanding=1 2019-12-07 03:21:16.556 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 11 -> RX_ACK == ACKED 2019-12-07 03:21:16.573 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=32817, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=AE], lastHopLqi=255, lastHopRssi=-24, sender=55072, bindingIndex=255, addressIndex=255, messageContents=00 00 01 00 01 33 9A 88 7B 08 39 69 07 01 28 D0 0D 00 6F 0D 00 00 00 04 02 00 A0] 2019-12-07 03:21:16.573 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=55072/0, destinationAddress=0/0, profile=0000, cluster=8031, addressMode=null, radius=0, apsSecurity=false, apsCounter=AE, payload=00 00 01 00 01 33 9A 88 7B 08 39 69 07 01 28 D0 0D 00 6F 0D 00 00 00 04 02 00 A0] 2019-12-07 03:21:16.574 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementLqiResponse [55072/0 -> 0/0, cluster=8031, TID=--, status=SUCCESS, neighborTableEntries=1, startIndex=0, neighborTableList=[NeighborTable [extendedPanId=076939087B889A33, extendedAddress=000D6F000DD02801, networkAddress=0, deviceType=COORDINATOR, rxOnWhenIdle=RX_ON, relationship=PARENT, permitJoining=UNKNOWN, depth=0, lqi=160]]] 2019-12-07 03:21:16.575 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementLqiResponse [55072/0 -> 0/0, cluster=8031, TID=--, status=SUCCESS, neighborTableEntries=1, startIndex=0, neighborTableList=[NeighborTable [extendedPanId=076939087B889A33, extendedAddress=000D6F000DD02801, networkAddress=0, deviceType=COORDINATOR, rxOnWhenIdle=RX_ON, relationship=PARENT, permitJoining=UNKNOWN, depth=0, lqi=160]]] 2019-12-07 03:21:16.575 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementLqiResponse [55072/0 -> 0/0, cluster=8031, TID=--, status=SUCCESS, neighborTableEntries=1, startIndex=0, neighborTableList=[NeighborTable [extendedPanId=076939087B889A33, extendedAddress=000D6F000DD02801, networkAddress=0, deviceType=COORDINATOR, rxOnWhenIdle=RX_ON, relationship=PARENT, permitJoining=UNKNOWN, depth=0, lqi=160]]] ZigBeeTransaction [queueTime=321, state=ACKED, sendCnt=1, command=ManagementLqiRequest [0/0 -> 55072/0, cluster=0031, TID=11, startIndex=0]] 2019-12-07 03:21:16.576 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=322, state=COMPLETE, sendCnt=1, command=ManagementLqiRequest [0/0 -> 55072/0, cluster=0031, TID=11, startIndex=0]] 2019-12-07 03:21:16.576 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding 2019-12-07 03:21:16.576 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: ManagementLqiRequest response CommandResult [SUCCESS, ManagementLqiResponse [55072/0 -> 0/0, cluster=8031, TID=--, status=SUCCESS, neighborTableEntries=1, startIndex=0, neighborTableList=[NeighborTable [extendedPanId=076939087B889A33, extendedAddress=000D6F000DD02801, networkAddress=0, deviceType=COORDINATOR, rxOnWhenIdle=RX_ON, relationship=PARENT, permitJoining=UNKNOWN, depth=0, lqi=160]]]] 2019-12-07 03:21:16.577 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete COMPLETE 0 2019-12-07 03:21:16.577 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: ManagementLqiRequest complete [1 neighbors] 2019-12-07 03:21:16.578 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00158D0001FF8F6A: Neighbor table updated: [NeighborTable [extendedPanId=076939087B889A33, extendedAddress=000D6F000DD02801, networkAddress=0, deviceType=COORDINATOR, rxOnWhenIdle=RX_ON, relationship=PARENT, permitJoining=UNKNOWN, depth=0, lqi=160]] 2019-12-07 03:21:16.578 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: request NEIGHBORS successful. Advancing to null. 2019-12-07 03:21:16.579 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: complete 2019-12-07 03:21:16.579 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Updating node NWK=55072 2019-12-07 03:21:16.580 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Node 55072 update 2019-12-07 03:21:16.580 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00158D0001FF8F6A: Node descriptor updated 2019-12-07 03:21:16.581 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00158D0001FF8F6A: Power descriptor updated 2019-12-07 03:21:16.581 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00158D0001FF8F6A: Neighbors updated 2019-12-07 03:21:16.582 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00158D0001FF8F6A: Endpoint 1 added 2019-12-07 03:21:16.583 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Set profile to ZigBeeTransactionProfile [maxOutstandingTransactions=1, interTransactionDelay=50, maxRetries=2] 2019-12-07 03:21:16.585 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Updated sleepy state from false to true 2019-12-07 03:21:16.585 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 00158D0001FF8F6A: Data store: Deferring write for 250ms. 2019-12-07 03:21:16.585 [DEBUG] [transaction.ZigBeeTransactionManager] - Sleepy transaction count resynchronised: was 0, now 0 2019-12-07 03:21:16.597 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 00158D0001FF8F6A: Starting ZigBee device discovery 2019-12-07 03:21:16.598 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 00158D0001FF8F6A: Creating ZigBee device zigbee:device with bridge zigbee:coordinator_ember:cc9950e6 2019-12-07 03:21:16.605 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 00158D0001FF8F6A: ZigBee node property discovery start 2019-12-07 03:21:16.608 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 00158D0001FF8F6A: ZigBee node property discovery using basic cluster on endpoint 55072/1 2019-12-07 03:21:16.612 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Basic: 0/0 -> 55072/1, cluster=0000, TID=--, identifiers=[5, 4, 3, 2, 6, 0, 1]]] 2019-12-07 03:21:16.613 [DEBUG] [transaction.ZigBeeTransactionManager] - 55072/1: Sending ZigBeeTransaction [queueTime=1, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Basic: 0/0 -> 55072/1, cluster=0000, TID=12, identifiers=[5, 4, 3, 2, 6, 0, 1]]] 2019-12-07 03:21:16.614 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding 2019-12-07 03:21:16.614 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Basic: 0/0 -> 55072/1, cluster=0000, TID=12, identifiers=[5, 4, 3, 2, 6, 0, 1]] 2019-12-07 03:21:16.619 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=18, commandId=0] 2019-12-07 03:21:16.620 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=55072/1, profile=0104, cluster=0000, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=18, payload=00 12 00 05 00 04 00 03 00 02 00 06 00 00 00 01 00] 2019-12-07 03:21:16.637 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=73] 2019-12-07 03:21:16.837 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 00158D0001FF8F6A: Data store: Writing node. 2019-12-07 03:21:16.900 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 00158D0001FF8F6A: ZigBee saving network state complete. 2019-12-07 03:21:16.920 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=55072, apsFrame=EmberApsFrame [profileId=260, clusterId=0, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=73], messageTag=12, status=EMBER_SUCCESS, messageContents=] 2019-12-07 03:21:16.921 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=12 state=RX_ACK 2019-12-07 03:21:16.921 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=12, state=RX_ACK, outstanding=1 2019-12-07 03:21:16.922 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 12 -> RX_ACK == ACKED 2019-12-07 03:21:16.938 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=260, clusterId=0, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=AF], lastHopLqi=255, lastHopRssi=-22, sender=55072, bindingIndex=255, addressIndex=255, messageContents=18 12 01 05 00 00 42 08 53 50 5A 42 30 30 30 31 04 00 00 42 0A 45 75 72 6F 74 72 6F 6E 69 63 03 00 00 20 23 02 00 00 20 05 06 00 00 42 08 32 30 31 39 31 30 31 34 00 00 00 20 02 01 00 00 20 16] 2019-12-07 03:21:16.939 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=55072/1, destinationAddress=0/1, profile=0104, cluster=0000, addressMode=null, radius=0, apsSecurity=false, apsCounter=AF, payload=18 12 01 05 00 00 42 08 53 50 5A 42 30 30 30 31 04 00 00 42 0A 45 75 72 6F 74 72 6F 6E 69 63 03 00 00 20 23 02 00 00 20 05 06 00 00 42 08 32 30 31 39 31 30 31 34 00 00 00 20 02 01 00 00 20 16] 2019-12-07 03:21:16.939 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=18, commandId=1] 2019-12-07 03:21:16.941 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReadAttributesResponse [Basic: 55072/1 -> 0/1, cluster=0000, TID=12, records=[ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=5, status=SUCCESS, attributeValue=SPZB0001], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=4, status=SUCCESS, attributeValue=Eurotronic], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=3, status=SUCCESS, attributeValue=35], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=2, status=SUCCESS, attributeValue=5], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=6, status=SUCCESS, attributeValue=20191014], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, status=SUCCESS, attributeValue=2], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=1, status=SUCCESS, attributeValue=22]]] 2019-12-07 03:21:16.942 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [Basic: 55072/1 -> 0/1, cluster=0000, TID=12, records=[ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=5, status=SUCCESS, attributeValue=SPZB0001], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=4, status=SUCCESS, attributeValue=Eurotronic], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=3, status=SUCCESS, attributeValue=35], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=2, status=SUCCESS, attributeValue=5], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=6, status=SUCCESS, attributeValue=20191014], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, status=SUCCESS, attributeValue=2], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=1, status=SUCCESS, attributeValue=22]]] 2019-12-07 03:21:16.942 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [Basic: 55072/1 -> 0/1, cluster=0000, TID=12, records=[ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=5, status=SUCCESS, attributeValue=SPZB0001], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=4, status=SUCCESS, attributeValue=Eurotronic], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=3, status=SUCCESS, attributeValue=35], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=2, status=SUCCESS, attributeValue=5], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=6, status=SUCCESS, attributeValue=20191014], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, status=SUCCESS, attributeValue=2], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=1, status=SUCCESS, attributeValue=22]]] ZigBeeTransaction [queueTime=330, state=ACKED, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 55072/1, cluster=0000, TID=12, identifiers=[5, 4, 3, 2, 6, 0, 1]]] 2019-12-07 03:21:16.943 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=331, state=COMPLETE, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 55072/1, cluster=0000, TID=12, identifiers=[5, 4, 3, 2, 6, 0, 1]]] 2019-12-07 03:21:16.944 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding 2019-12-07 03:21:16.944 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete COMPLETE 0 2019-12-07 03:21:16.948 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 00158D0001FF8F6A: ZigBee node property discovery using OTA cluster on endpoint 55072/1 2019-12-07 03:21:16.948 [DEBUG] [.zsmartsystems.zigbee.zcl.ZclCluster] - readSync request: 2 2019-12-07 03:21:16.949 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Ota Upgrade: 0/0 -> 55072/1, cluster=0019, TID=--, identifiers=[2]]] 2019-12-07 03:21:16.950 [DEBUG] [transaction.ZigBeeTransactionManager] - 55072/1: Sending ZigBeeTransaction [queueTime=1, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Ota Upgrade: 0/0 -> 55072/1, cluster=0019, TID=13, identifiers=[2]]] 2019-12-07 03:21:16.950 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding 2019-12-07 03:21:16.951 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Ota Upgrade: 0/0 -> 55072/1, cluster=0019, TID=13, identifiers=[2]] 2019-12-07 03:21:16.951 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=19, commandId=0] 2019-12-07 03:21:16.952 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=55072/1, profile=0104, cluster=0019, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=19, payload=08 13 00 02 00] 2019-12-07 03:21:16.985 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_BROADCAST, indexOrDestination=65535, apsFrame=EmberApsFrame [profileId=0, clusterId=0, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=6D], messageTag=0D, status=EMBER_SUCCESS, messageContents=] 2019-12-07 03:21:16.987 [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=B0], lastHopLqi=255, lastHopRssi=-22, sender=55072, bindingIndex=255, addressIndex=255, messageContents=00 00 6A 8F FF 01 00 8D 15 00 20 D7] 2019-12-07 03:21:16.988 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=55072/0, destinationAddress=0/0, profile=0000, cluster=8000, addressMode=null, radius=0, apsSecurity=false, apsCounter=B0, payload=00 00 6A 8F FF 01 00 8D 15 00 20 D7] 2019-12-07 03:21:16.988 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: NetworkAddressResponse [55072/0 -> 0/0, cluster=8000, TID=--, status=SUCCESS, ieeeAddrRemoteDev=00158D0001FF8F6A, nwkAddrRemoteDev=55072, startIndex=null, nwkAddrAssocDevList=[]] 2019-12-07 03:21:16.989 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NetworkAddressResponse [55072/0 -> 0/0, cluster=8000, TID=--, status=SUCCESS, ieeeAddrRemoteDev=00158D0001FF8F6A, nwkAddrRemoteDev=55072, startIndex=null, nwkAddrAssocDevList=[]] 2019-12-07 03:21:16.989 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NetworkAddressResponse [55072/0 -> 0/0, cluster=8000, TID=--, status=SUCCESS, ieeeAddrRemoteDev=00158D0001FF8F6A, nwkAddrRemoteDev=55072, startIndex=null, nwkAddrAssocDevList=[]] ZigBeeTransaction [queueTime=40, state=DISPATCHED, sendCnt=1, command=ReadAttributesCommand [Ota Upgrade: 0/0 -> 55072/1, cluster=0019, TID=13, identifiers=[2]]] 2019-12-07 03:21:16.991 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=74] 2019-12-07 03:21:16.992 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=0D state=RX_ACK 2019-12-07 03:21:16.993 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=0D, state=RX_ACK, outstanding=1 2019-12-07 03:21:17.164 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=55072, apsFrame=EmberApsFrame [profileId=260, clusterId=25, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=74], messageTag=13, status=EMBER_SUCCESS, messageContents=] 2019-12-07 03:21:17.165 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=13 state=RX_ACK 2019-12-07 03:21:17.165 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=13, state=RX_ACK, outstanding=1 2019-12-07 03:21:17.166 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 13 -> RX_ACK == ACKED 2019-12-07 03:21:17.185 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=260, clusterId=25, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=B1], lastHopLqi=255, lastHopRssi=-21, sender=55072, bindingIndex=255, addressIndex=255, messageContents=10 13 01 02 00 00 23 D2 E9 62 01] 2019-12-07 03:21:17.186 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=55072/1, destinationAddress=0/1, profile=0104, cluster=0019, addressMode=null, radius=0, apsSecurity=false, apsCounter=B1, payload=10 13 01 02 00 00 23 D2 E9 62 01] 2019-12-07 03:21:17.187 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=19, commandId=1] 2019-12-07 03:21:17.187 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReadAttributesResponse [Ota Upgrade: 55072/1 -> 0/1, cluster=0019, TID=13, records=[ReadAttributeStatusRecord [attributeDataType=UNSIGNED_32_BIT_INTEGER, attributeIdentifier=2, status=SUCCESS, attributeValue=23259602]]] 2019-12-07 03:21:17.187 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [Ota Upgrade: 55072/1 -> 0/1, cluster=0019, TID=13, records=[ReadAttributeStatusRecord [attributeDataType=UNSIGNED_32_BIT_INTEGER, attributeIdentifier=2, status=SUCCESS, attributeValue=23259602]]] 2019-12-07 03:21:17.188 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [Ota Upgrade: 55072/1 -> 0/1, cluster=0019, TID=13, records=[ReadAttributeStatusRecord [attributeDataType=UNSIGNED_32_BIT_INTEGER, attributeIdentifier=2, status=SUCCESS, attributeValue=23259602]]] ZigBeeTransaction [queueTime=239, state=ACKED, sendCnt=1, command=ReadAttributesCommand [Ota Upgrade: 0/0 -> 55072/1, cluster=0019, TID=13, identifiers=[2]]] 2019-12-07 03:21:17.188 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=239, state=COMPLETE, sendCnt=1, command=ReadAttributesCommand [Ota Upgrade: 0/0 -> 55072/1, cluster=0019, TID=13, identifiers=[2]]] 2019-12-07 03:21:17.189 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding 2019-12-07 03:21:17.189 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 00158D0001FF8F6A: ZigBee node property discovery complete: {zigbee_logicaltype=END_DEVICE, zigbee_powerlevel=FULL, zigbee_manufacturercode=0x1037, modelId=SPZB0001, zigbee_networkaddress=55072, zigbee_powersource=DISPOSABLE_BATTERY, zigbee_stkversion=5, zigbee_datecode=20191014, zigbee_zclversion=2, vendor=Eurotronic, zigbee_powermode=RECEIVER_ON_IDLE, zigbee_powersources=[DISPOSABLE_BATTERY], hardwareVersion=35, firmwareVersion=0x0162E9D2, zigbee_applicationVersion=22} 2019-12-07 03:21:17.189 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete COMPLETE 0 2019-12-07 03:21:17.192 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 00158D0001FF8F6A: Update ZigBee device zigbee:device with bridge zigbee:coordinator_ember:cc9950e6, label 'Eurotronic SPZB0001' 2019-12-07 03:21:17.193 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 00158D0001FF8F6A: Data store: Deferring write for 250ms. 2019-12-07 03:21:17.445 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 00158D0001FF8F6A: Data store: Writing node. 2019-12-07 03:21:17.494 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 00158D0001FF8F6A: ZigBee saving network state complete. 2019-12-07 03:21:19.798 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspZigbeeKeyEstablishmentHandler [partner=00158D0001FF8F6A, status=UNKNOWN] 2019-12-07 03:21:24.797 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspZigbeeKeyEstablishmentHandler [partner=00158D0001FF8F6A, status=UNKNOWN] 2019-12-07 03:21:29.803 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspChildJoinHandler [index=0, joining=false, childId=55072, childEui64=00158D0001FF8F6A, childType=EMBER_SLEEPY_END_DEVICE] 2019-12-07 03:21:29.804 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: nodeStatusUpdate - node status is DEVICE_LEFT, network address is 55072. 2019-12-07 03:21:29.804 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00158D0001FF8F6A: Node state updated from ONLINE to OFFLINE 2019-12-07 03:21:29.805 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Updating node NWK=55072 2019-12-07 03:21:29.806 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Node 55072 update 2019-12-07 03:21:29.806 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Node 55072 is not updated 2019-12-07 03:21:29.809 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [newNodeId=55072, newNodeEui64=00158D0001FF8F6A, status=EMBER_DEVICE_LEFT, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=65535] 2019-12-07 03:21:29.809 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: nodeStatusUpdate - node status is DEVICE_LEFT, network address is 55072. 2019-12-07 03:21:29.810 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Updating node NWK=55072 2019-12-07 03:21:29.810 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Node 55072 update 2019-12-07 03:21:29.811 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Node 55072 is not updated 2019-12-07 03:21:39.063 [INFO ] [el.script.Temp_Outside_MinMaxAverage] - I_Geb_OutsideTemp24HMin set to -3.7 2019-12-07 03:21:39.108 [INFO ] [el.script.Temp_Outside_MinMaxAverage] - I_Geb_OutsideTemp24HMax set to 7.4 2019-12-07 03:21:39.132 [INFO ] [el.script.Temp_Outside_MinMaxAverage] - I_Geb_OutsideTemp24HAvg set to 1.541886012447541 2019-12-07 03:22:28.324 [INFO ] [pse.smarthome.model.script.AstroRule] - Calculated projected angle: -57.35462680420073 2019-12-07 03:22:28.326 [INFO ] [pse.smarthome.model.script.AstroRule] - Calculated projected angle: Less than 0 2019-12-07 03:22:28.328 [INFO ] [pse.smarthome.model.script.AstroRule] - Calculated projected angle for facade 1: -1.0E-4 2019-12-07 03:22:28.335 [INFO ] [pse.smarthome.model.script.AstroRule] - Calculated projected angle: -50.90377392196482 2019-12-07 03:22:28.337 [INFO ] [pse.smarthome.model.script.AstroRule] - Calculated projected angle: Less than 0 2019-12-07 03:22:28.339 [INFO ] [pse.smarthome.model.script.AstroRule] - Calculated projected angle for facade 2: -1.0E-4 2019-12-07 03:22:28.342 [INFO ] [pse.smarthome.model.script.AstroRule] - Calculated projected angle: 57.35462680420073 2019-12-07 03:22:28.344 [INFO ] [pse.smarthome.model.script.AstroRule] - Calculated projected angle for facade 3: 57.35462680420073 2019-12-07 03:22:28.347 [INFO ] [pse.smarthome.model.script.AstroRule] - Calculated projected angle: 50.90377392196482 2019-12-07 03:22:28.349 [INFO ] [pse.smarthome.model.script.AstroRule] - Calculated projected angle for facade 4: 50.90377392196482 2019-12-07 03:22:28.364 [INFO ] [e.smarthome.model.script.PowerInput4] - PowerInput4 set to 0 2019-12-07 03:22:28.367 [INFO ] [e.smarthome.model.script.PowerInput1] - PowerInput1 set to 0 2019-12-07 03:22:28.370 [INFO ] [e.smarthome.model.script.PowerInput2] - PowerInput2 set to 0 2019-12-07 03:22:28.372 [INFO ] [e.smarthome.model.script.PowerInput3] - PowerInput3 set to 0 2019-12-07 03:22:38.998 [INFO ] [el.script.Temp_Outside_MinMaxAverage] - I_Geb_OutsideTemp24HMin set to -3.7 2019-12-07 03:22:39.104 [INFO ] [el.script.Temp_Outside_MinMaxAverage] - I_Geb_OutsideTemp24HMax set to 7.4 2019-12-07 03:22:39.150 [INFO ] [el.script.Temp_Outside_MinMaxAverage] - I_Geb_OutsideTemp24HAvg set to 1.549273115964112 2019-12-07 03:22:40.257 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00158D0001FF8F6A: Initializing ZigBee thing handler zigbee:device:cc9950e6:00158d0001ff8f6a 2019-12-07 03:22:40.258 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00158D0001FF8F6A: Coordinator status changed to ONLINE. 2019-12-07 03:22:40.259 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00158D0001FF8F6A: Coordinator is ONLINE. Starting device initialisation. 2019-12-07 03:22:40.262 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D0001FF8F6A: NWK Discovery starting node rediscovery 2019-12-07 03:22:40.263 [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=00158D0001FF8F6A, requestType=0, startIndex=0]] 2019-12-07 03:22:40.264 [DEBUG] [transaction.ZigBeeTransactionManager] - 65533/0: Sending ZigBeeTransaction [queueTime=1, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=14, ieeeAddr=00158D0001FF8F6A, requestType=0, startIndex=0]] 2019-12-07 03:22:40.264 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding 2019-12-07 03:22:40.265 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=14, ieeeAddr=00158D0001FF8F6A, requestType=0, startIndex=0] 2019-12-07 03:22:40.265 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=65533/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=1A, payload=00 6A 8F FF 01 00 8D 15 00 00 00] 2019-12-07 03:22:40.275 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00158D0001FF8F6A: Start initialising ZigBee Thing handler 2019-12-07 03:22:40.295 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 00158D0001FF8F6A: ZigBee node property discovery start 2019-12-07 03:22:40.296 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 00158D0001FF8F6A: ZigBee node property discovery using basic cluster on endpoint 55072/1 2019-12-07 03:22:40.297 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 00158D0001FF8F6A: ZigBee node property discovery using OTA cluster on endpoint 55072/1 2019-12-07 03:22:40.298 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 00158D0001FF8F6A: ZigBee node property discovery complete: {zigbee_logicaltype=END_DEVICE, zigbee_powerlevel=FULL, zigbee_manufacturercode=0x1037, modelId=SPZB0001, zigbee_networkaddress=55072, zigbee_powersource=DISPOSABLE_BATTERY, zigbee_stkversion=5, zigbee_datecode=20191014, zigbee_zclversion=2, vendor=Eurotronic, zigbee_powermode=RECEIVER_ON_IDLE, zigbee_powersources=[DISPOSABLE_BATTERY], hardwareVersion=35, firmwareVersion=0x0162E9D2, zigbee_applicationVersion=22} 2019-12-07 03:22:40.304 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00158D0001FF8F6A: Checking endpoint 1 channels 2019-12-07 03:22:40.325 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=DiscoverAttributesCommand [Power Configuration: 0/0 -> 55072/1, cluster=0001, TID=--, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:22:40.325 [DEBUG] [transaction.ZigBeeTransactionManager] - 55072/1: Sending ZigBeeTransaction [queueTime=1, state=WAITING, sendCnt=0, command=DiscoverAttributesCommand [Power Configuration: 0/0 -> 55072/1, cluster=0001, TID=15, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:22:40.326 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding 2019-12-07 03:22:40.326 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: DiscoverAttributesCommand [Power Configuration: 0/0 -> 55072/1, cluster=0001, TID=15, startAttributeIdentifier=0, maximumAttributeIdentifiers=10] 2019-12-07 03:22:40.326 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=21, commandId=12] 2019-12-07 03:22:40.327 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=55072/1, profile=0104, cluster=0001, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=1B, payload=00 15 0C 00 00 0A] 2019-12-07 03:22:40.356 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendBroadcastResponse [status=EMBER_SUCCESS, sequence=75] 2019-12-07 03:22:40.362 [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=75], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 6A 8F FF 01 00 8D 15 00 00 00] 2019-12-07 03:22:40.363 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0000, addressMode=null, radius=0, apsSecurity=false, apsCounter=75, payload=00 6A 8F FF 01 00 8D 15 00 00 00] 2019-12-07 03:22:40.364 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: NetworkAddressRequest [0/0 -> 0/0, cluster=0000, TID=--, ieeeAddr=00158D0001FF8F6A, requestType=0, startIndex=0] 2019-12-07 03:22:40.364 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NetworkAddressRequest [0/0 -> 0/0, cluster=0000, TID=--, ieeeAddr=00158D0001FF8F6A, requestType=0, startIndex=0] 2019-12-07 03:22:40.365 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NetworkAddressRequest [0/0 -> 0/0, cluster=0000, TID=--, ieeeAddr=00158D0001FF8F6A, requestType=0, startIndex=0] ZigBeeTransaction [queueTime=102, state=DISPATCHED, sendCnt=1, command=NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=14, ieeeAddr=00158D0001FF8F6A, requestType=0, startIndex=0]] 2019-12-07 03:22:40.365 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NetworkAddressRequest [0/0 -> 0/0, cluster=0000, TID=--, ieeeAddr=00158D0001FF8F6A, requestType=0, startIndex=0] ZigBeeTransaction [queueTime=41, state=DISPATCHED, sendCnt=1, command=DiscoverAttributesCommand [Power Configuration: 0/0 -> 55072/1, cluster=0001, TID=15, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:22:40.411 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=76] 2019-12-07 03:22:41.297 [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=75], messageTag=14, status=EMBER_SUCCESS, messageContents=] 2019-12-07 03:22:41.298 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=14 state=RX_ACK 2019-12-07 03:22:41.299 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=14, state=RX_ACK, outstanding=2 2019-12-07 03:22:41.300 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 14 -> RX_ACK == ACKED 2019-12-07 03:22:45.100 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=55072, apsFrame=EmberApsFrame [profileId=260, clusterId=1, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=76], messageTag=15, status=EMBER_DELIVERY_FAILED, messageContents=] 2019-12-07 03:22:45.101 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=15 state=RX_NAK 2019-12-07 03:22:45.102 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=15, state=RX_NAK, outstanding=2 2019-12-07 03:22:45.102 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=4778, state=FAILED, sendCnt=1, command=DiscoverAttributesCommand [Power Configuration: 0/0 -> 55072/1, cluster=0001, TID=15, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:22:45.103 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding 2019-12-07 03:22:45.103 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete FAILED 0 2019-12-07 03:22:45.104 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=4780, state=WAITING, sendCnt=1, command=DiscoverAttributesCommand [Power Configuration: 0/0 -> 55072/1, cluster=0001, TID=15, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:22:45.105 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 15 -> RX_NAK == WAITING 2019-12-07 03:22:50.265 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=10002, state=FAILED, sendCnt=1, command=NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=14, ieeeAddr=00158D0001FF8F6A, requestType=0, startIndex=0]] 2019-12-07 03:22:50.265 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding 2019-12-07 03:22:50.266 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete FAILED 0 2019-12-07 03:22:50.266 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete exceeded retries 1 2019-12-07 03:22:50.267 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=10004, state=FAILED, sendCnt=1, command=NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=14, ieeeAddr=00158D0001FF8F6A, requestType=0, startIndex=0]] 2019-12-07 03:22:50.268 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D0001FF8F6A: NWK Discovery node rediscovery request failed. Wait before retry. 2019-12-07 03:22:51.769 [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=00158D0001FF8F6A, requestType=0, startIndex=0]] 2019-12-07 03:22:51.770 [DEBUG] [transaction.ZigBeeTransactionManager] - 65533/0: Sending ZigBeeTransaction [queueTime=1, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=16, ieeeAddr=00158D0001FF8F6A, requestType=0, startIndex=0]] 2019-12-07 03:22:51.770 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding 2019-12-07 03:22:51.771 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=16, ieeeAddr=00158D0001FF8F6A, requestType=0, startIndex=0] 2019-12-07 03:22:51.771 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=65533/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=1C, payload=00 6A 8F FF 01 00 8D 15 00 00 00] 2019-12-07 03:22:51.789 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendBroadcastResponse [status=EMBER_SUCCESS, sequence=77] 2019-12-07 03:22:51.795 [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=77], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 6A 8F FF 01 00 8D 15 00 00 00] 2019-12-07 03:22:51.796 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0000, addressMode=null, radius=0, apsSecurity=false, apsCounter=77, payload=00 6A 8F FF 01 00 8D 15 00 00 00] 2019-12-07 03:22:51.797 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: NetworkAddressRequest [0/0 -> 0/0, cluster=0000, TID=--, ieeeAddr=00158D0001FF8F6A, requestType=0, startIndex=0] 2019-12-07 03:22:51.798 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NetworkAddressRequest [0/0 -> 0/0, cluster=0000, TID=--, ieeeAddr=00158D0001FF8F6A, requestType=0, startIndex=0] 2019-12-07 03:22:51.799 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NetworkAddressRequest [0/0 -> 0/0, cluster=0000, TID=--, ieeeAddr=00158D0001FF8F6A, requestType=0, startIndex=0] ZigBeeTransaction [queueTime=30, state=DISPATCHED, sendCnt=1, command=NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=16, ieeeAddr=00158D0001FF8F6A, requestType=0, startIndex=0]] 2019-12-07 03:22:52.342 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=DiscoverAttributesCommand [Power Configuration: 0/0 -> 55072/1, cluster=0001, TID=--, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:22:52.343 [DEBUG] [transaction.ZigBeeTransactionManager] - 55072/1: Sending ZigBeeTransaction [queueTime=12019, state=WAITING, sendCnt=1, command=DiscoverAttributesCommand [Power Configuration: 0/0 -> 55072/1, cluster=0001, TID=15, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:22:52.344 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding 2019-12-07 03:22:52.345 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: DiscoverAttributesCommand [Power Configuration: 0/0 -> 55072/1, cluster=0001, TID=15, startAttributeIdentifier=0, maximumAttributeIdentifiers=10] 2019-12-07 03:22:52.346 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=21, commandId=12] 2019-12-07 03:22:52.346 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=55072/1, profile=0104, cluster=0001, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=1D, payload=00 15 0C 00 00 0A] 2019-12-07 03:22:52.364 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=78] 2019-12-07 03:22:52.729 [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=77], messageTag=16, status=EMBER_SUCCESS, messageContents=] 2019-12-07 03:22:52.730 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=16 state=RX_ACK 2019-12-07 03:22:52.730 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=16, state=RX_ACK, outstanding=2 2019-12-07 03:22:52.732 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 16 -> RX_ACK == ACKED 2019-12-07 03:22:57.054 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=55072, apsFrame=EmberApsFrame [profileId=260, clusterId=1, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=78], messageTag=15, status=EMBER_DELIVERY_FAILED, messageContents=] 2019-12-07 03:22:57.055 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=15 state=RX_NAK 2019-12-07 03:22:57.056 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=15, state=RX_NAK, outstanding=2 2019-12-07 03:22:57.056 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=16732, state=FAILED, sendCnt=2, command=DiscoverAttributesCommand [Power Configuration: 0/0 -> 55072/1, cluster=0001, TID=15, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:22:57.057 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding 2019-12-07 03:22:57.057 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete FAILED 0 2019-12-07 03:22:57.058 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete exceeded retries 2 2019-12-07 03:22:57.059 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=16735, state=FAILED, sendCnt=2, command=DiscoverAttributesCommand [Power Configuration: 0/0 -> 55072/1, cluster=0001, TID=15, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:22:57.059 [DEBUG] [transaction.ZigBeeTransactionManager] - 55072/1: Sending ZigBeeTransaction [queueTime=4717, state=WAITING, sendCnt=0, command=DiscoverAttributesCommand [Power Configuration: 0/0 -> 55072/1, cluster=0001, TID=17, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:22:57.060 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding 2019-12-07 03:22:57.060 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: DiscoverAttributesCommand [Power Configuration: 0/0 -> 55072/1, cluster=0001, TID=17, startAttributeIdentifier=0, maximumAttributeIdentifiers=10] 2019-12-07 03:22:57.061 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=23, commandId=12] 2019-12-07 03:22:57.061 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=55072/1, profile=0104, cluster=0001, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=1E, payload=00 17 0C 00 00 0A] 2019-12-07 03:22:57.062 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 15 -> RX_NAK == FAILED 2019-12-07 03:22:57.072 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=79] 2019-12-07 03:23:01.763 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=55072, apsFrame=EmberApsFrame [profileId=260, clusterId=1, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=79], messageTag=17, status=EMBER_DELIVERY_FAILED, messageContents=] 2019-12-07 03:23:01.764 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=17 state=RX_NAK 2019-12-07 03:23:01.764 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=17, state=RX_NAK, outstanding=2 2019-12-07 03:23:01.765 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=9423, state=FAILED, sendCnt=1, command=DiscoverAttributesCommand [Power Configuration: 0/0 -> 55072/1, cluster=0001, TID=17, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:23:01.765 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding 2019-12-07 03:23:01.766 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete FAILED 0 2019-12-07 03:23:01.766 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=9424, state=WAITING, sendCnt=1, command=DiscoverAttributesCommand [Power Configuration: 0/0 -> 55072/1, cluster=0001, TID=17, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:23:01.766 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 17 -> RX_NAK == WAITING 2019-12-07 03:23:01.770 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=10001, state=FAILED, sendCnt=1, command=NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=16, ieeeAddr=00158D0001FF8F6A, requestType=0, startIndex=0]] 2019-12-07 03:23:01.770 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding 2019-12-07 03:23:01.771 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete FAILED 0 2019-12-07 03:23:01.771 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete exceeded retries 1 2019-12-07 03:23:01.771 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=10002, state=FAILED, sendCnt=1, command=NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=16, ieeeAddr=00158D0001FF8F6A, requestType=0, startIndex=0]] 2019-12-07 03:23:01.772 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D0001FF8F6A: NWK Discovery node rediscovery request failed. Wait before retry. 2019-12-07 03:23:03.273 [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=00158D0001FF8F6A, requestType=0, startIndex=0]] 2019-12-07 03:23:03.274 [DEBUG] [transaction.ZigBeeTransactionManager] - 65533/0: Sending ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=18, ieeeAddr=00158D0001FF8F6A, requestType=0, startIndex=0]] 2019-12-07 03:23:03.274 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding 2019-12-07 03:23:03.275 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=18, ieeeAddr=00158D0001FF8F6A, requestType=0, startIndex=0] 2019-12-07 03:23:03.275 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=65533/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=1F, payload=00 6A 8F FF 01 00 8D 15 00 00 00] 2019-12-07 03:23:03.290 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendBroadcastResponse [status=EMBER_SUCCESS, sequence=7A] 2019-12-07 03:23:03.296 [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=7A], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 6A 8F FF 01 00 8D 15 00 00 00] 2019-12-07 03:23:03.297 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0000, addressMode=null, radius=0, apsSecurity=false, apsCounter=7A, payload=00 6A 8F FF 01 00 8D 15 00 00 00] 2019-12-07 03:23:03.298 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: NetworkAddressRequest [0/0 -> 0/0, cluster=0000, TID=--, ieeeAddr=00158D0001FF8F6A, requestType=0, startIndex=0] 2019-12-07 03:23:03.298 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NetworkAddressRequest [0/0 -> 0/0, cluster=0000, TID=--, ieeeAddr=00158D0001FF8F6A, requestType=0, startIndex=0] 2019-12-07 03:23:03.299 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NetworkAddressRequest [0/0 -> 0/0, cluster=0000, TID=--, ieeeAddr=00158D0001FF8F6A, requestType=0, startIndex=0] ZigBeeTransaction [queueTime=25, state=DISPATCHED, sendCnt=1, command=NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=18, ieeeAddr=00158D0001FF8F6A, requestType=0, startIndex=0]] 2019-12-07 03:23:04.214 [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=7A], messageTag=18, status=EMBER_SUCCESS, messageContents=] 2019-12-07 03:23:04.215 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=18 state=RX_ACK 2019-12-07 03:23:04.216 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=18, state=RX_ACK, outstanding=1 2019-12-07 03:23:04.218 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 18 -> RX_ACK == ACKED 2019-12-07 03:23:04.352 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=DiscoverAttributesCommand [Power Configuration: 0/0 -> 55072/1, cluster=0001, TID=--, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:23:04.352 [DEBUG] [transaction.ZigBeeTransactionManager] - 55072/1: Sending ZigBeeTransaction [queueTime=12010, state=WAITING, sendCnt=1, command=DiscoverAttributesCommand [Power Configuration: 0/0 -> 55072/1, cluster=0001, TID=17, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:23:04.353 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding 2019-12-07 03:23:04.353 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: DiscoverAttributesCommand [Power Configuration: 0/0 -> 55072/1, cluster=0001, TID=17, startAttributeIdentifier=0, maximumAttributeIdentifiers=10] 2019-12-07 03:23:04.354 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=23, commandId=12] 2019-12-07 03:23:04.354 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=55072/1, profile=0104, cluster=0001, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=20, payload=00 17 0C 00 00 0A] 2019-12-07 03:23:04.369 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=7B] 2019-12-07 03:23:09.059 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=55072, apsFrame=EmberApsFrame [profileId=260, clusterId=1, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=7B], messageTag=17, status=EMBER_DELIVERY_FAILED, messageContents=] 2019-12-07 03:23:09.060 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=17 state=RX_NAK 2019-12-07 03:23:09.061 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=17, state=RX_NAK, outstanding=2 2019-12-07 03:23:09.062 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=16720, state=FAILED, sendCnt=2, command=DiscoverAttributesCommand [Power Configuration: 0/0 -> 55072/1, cluster=0001, TID=17, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:23:09.063 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding 2019-12-07 03:23:09.064 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete FAILED 0 2019-12-07 03:23:09.064 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete exceeded retries 2 2019-12-07 03:23:09.065 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=16723, state=FAILED, sendCnt=2, command=DiscoverAttributesCommand [Power Configuration: 0/0 -> 55072/1, cluster=0001, TID=17, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:23:09.065 [DEBUG] [transaction.ZigBeeTransactionManager] - 55072/1: Sending ZigBeeTransaction [queueTime=4713, state=WAITING, sendCnt=0, command=DiscoverAttributesCommand [Power Configuration: 0/0 -> 55072/1, cluster=0001, TID=19, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:23:09.066 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding 2019-12-07 03:23:09.066 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: DiscoverAttributesCommand [Power Configuration: 0/0 -> 55072/1, cluster=0001, TID=19, startAttributeIdentifier=0, maximumAttributeIdentifiers=10] 2019-12-07 03:23:09.067 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=25, commandId=12] 2019-12-07 03:23:09.067 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=55072/1, profile=0104, cluster=0001, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=21, payload=00 19 0C 00 00 0A] 2019-12-07 03:23:09.068 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 17 -> RX_NAK == FAILED 2019-12-07 03:23:09.083 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=7C] 2019-12-07 03:23:13.275 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=10002, state=FAILED, sendCnt=1, command=NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=18, ieeeAddr=00158D0001FF8F6A, requestType=0, startIndex=0]] 2019-12-07 03:23:13.276 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding 2019-12-07 03:23:13.276 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete FAILED 0 2019-12-07 03:23:13.277 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete exceeded retries 1 2019-12-07 03:23:13.278 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=10005, state=FAILED, sendCnt=1, command=NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=18, ieeeAddr=00158D0001FF8F6A, requestType=0, startIndex=0]] 2019-12-07 03:23:13.279 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D0001FF8F6A: NWK Discovery node rediscovery request failed. Wait before retry. 2019-12-07 03:23:13.774 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=55072, apsFrame=EmberApsFrame [profileId=260, clusterId=1, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=7C], messageTag=19, status=EMBER_DELIVERY_FAILED, messageContents=] 2019-12-07 03:23:13.775 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=19 state=RX_NAK 2019-12-07 03:23:13.776 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=19, state=RX_NAK, outstanding=1 2019-12-07 03:23:13.776 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=9424, state=FAILED, sendCnt=1, command=DiscoverAttributesCommand [Power Configuration: 0/0 -> 55072/1, cluster=0001, TID=19, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:23:13.777 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding 2019-12-07 03:23:13.777 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete FAILED 0 2019-12-07 03:23:13.778 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=9425, state=WAITING, sendCnt=1, command=DiscoverAttributesCommand [Power Configuration: 0/0 -> 55072/1, cluster=0001, TID=19, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:23:13.785 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 19 -> RX_NAK == WAITING 2019-12-07 03:23:14.779 [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=00158D0001FF8F6A, requestType=0, startIndex=0]] 2019-12-07 03:23:14.780 [DEBUG] [transaction.ZigBeeTransactionManager] - 65533/0: Sending ZigBeeTransaction [queueTime=1, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=1A, ieeeAddr=00158D0001FF8F6A, requestType=0, startIndex=0]] 2019-12-07 03:23:14.781 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding 2019-12-07 03:23:14.782 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=1A, ieeeAddr=00158D0001FF8F6A, requestType=0, startIndex=0] 2019-12-07 03:23:14.783 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=65533/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=22, payload=00 6A 8F FF 01 00 8D 15 00 00 00] 2019-12-07 03:23:14.801 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendBroadcastResponse [status=EMBER_SUCCESS, sequence=7D] 2019-12-07 03:23:14.807 [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=7D], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 6A 8F FF 01 00 8D 15 00 00 00] 2019-12-07 03:23:14.808 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0000, addressMode=null, radius=0, apsSecurity=false, apsCounter=7D, payload=00 6A 8F FF 01 00 8D 15 00 00 00] 2019-12-07 03:23:14.809 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: NetworkAddressRequest [0/0 -> 0/0, cluster=0000, TID=--, ieeeAddr=00158D0001FF8F6A, requestType=0, startIndex=0] 2019-12-07 03:23:14.809 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NetworkAddressRequest [0/0 -> 0/0, cluster=0000, TID=--, ieeeAddr=00158D0001FF8F6A, requestType=0, startIndex=0] 2019-12-07 03:23:14.810 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NetworkAddressRequest [0/0 -> 0/0, cluster=0000, TID=--, ieeeAddr=00158D0001FF8F6A, requestType=0, startIndex=0] ZigBeeTransaction [queueTime=31, state=DISPATCHED, sendCnt=1, command=NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=1A, ieeeAddr=00158D0001FF8F6A, requestType=0, startIndex=0]] 2019-12-07 03:23:15.725 [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=7D], messageTag=1A, status=EMBER_SUCCESS, messageContents=] 2019-12-07 03:23:15.726 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=1A state=RX_ACK 2019-12-07 03:23:15.727 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=1A, state=RX_ACK, outstanding=1 2019-12-07 03:23:15.728 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 1A -> RX_ACK == ACKED 2019-12-07 03:23:16.357 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=DiscoverAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=--, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:23:16.358 [DEBUG] [transaction.ZigBeeTransactionManager] - 55072/1: Sending ZigBeeTransaction [queueTime=12006, state=WAITING, sendCnt=1, command=DiscoverAttributesCommand [Power Configuration: 0/0 -> 55072/1, cluster=0001, TID=19, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:23:16.358 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding 2019-12-07 03:23:16.359 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: DiscoverAttributesCommand [Power Configuration: 0/0 -> 55072/1, cluster=0001, TID=19, startAttributeIdentifier=0, maximumAttributeIdentifiers=10] 2019-12-07 03:23:16.359 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=25, commandId=12] 2019-12-07 03:23:16.360 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=55072/1, profile=0104, cluster=0001, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=23, payload=00 19 0C 00 00 0A] 2019-12-07 03:23:16.373 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=7E] 2019-12-07 03:23:21.064 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=55072, apsFrame=EmberApsFrame [profileId=260, clusterId=1, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=7E], messageTag=19, status=EMBER_DELIVERY_FAILED, messageContents=] 2019-12-07 03:23:21.065 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=19 state=RX_NAK 2019-12-07 03:23:21.065 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=19, state=RX_NAK, outstanding=2 2019-12-07 03:23:21.067 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=16714, state=FAILED, sendCnt=2, command=DiscoverAttributesCommand [Power Configuration: 0/0 -> 55072/1, cluster=0001, TID=19, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:23:21.067 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding 2019-12-07 03:23:21.067 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete FAILED 0 2019-12-07 03:23:21.068 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete exceeded retries 2 2019-12-07 03:23:21.068 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=16716, state=FAILED, sendCnt=2, command=DiscoverAttributesCommand [Power Configuration: 0/0 -> 55072/1, cluster=0001, TID=19, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:23:21.069 [DEBUG] [transaction.ZigBeeTransactionManager] - 55072/1: Sending ZigBeeTransaction [queueTime=4711, state=WAITING, sendCnt=0, command=DiscoverAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=1B, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:23:21.069 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding 2019-12-07 03:23:21.069 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: DiscoverAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=1B, startAttributeIdentifier=0, maximumAttributeIdentifiers=10] 2019-12-07 03:23:21.072 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=27, commandId=12] 2019-12-07 03:23:21.072 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=55072/1, profile=0104, cluster=0201, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=24, payload=00 1B 0C 00 00 0A] 2019-12-07 03:23:21.073 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 19 -> RX_NAK == FAILED 2019-12-07 03:23:21.082 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=7F] 2019-12-07 03:23:24.782 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=10003, state=FAILED, sendCnt=1, command=NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=1A, ieeeAddr=00158D0001FF8F6A, requestType=0, startIndex=0]] 2019-12-07 03:23:24.783 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding 2019-12-07 03:23:24.784 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete FAILED 0 2019-12-07 03:23:24.784 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete exceeded retries 1 2019-12-07 03:23:24.785 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=10006, state=FAILED, sendCnt=1, command=NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=1A, ieeeAddr=00158D0001FF8F6A, requestType=0, startIndex=0]] 2019-12-07 03:23:24.786 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D0001FF8F6A: NWK Discovery node rediscovery request failed. Wait before retry. 2019-12-07 03:23:25.775 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=55072, apsFrame=EmberApsFrame [profileId=260, clusterId=513, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=7F], messageTag=1B, status=EMBER_DELIVERY_FAILED, messageContents=] 2019-12-07 03:23:25.777 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=1B state=RX_NAK 2019-12-07 03:23:25.782 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=1B, state=RX_NAK, outstanding=1 2019-12-07 03:23:25.786 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=9429, state=FAILED, sendCnt=1, command=DiscoverAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=1B, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:23:25.787 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding 2019-12-07 03:23:25.788 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete FAILED 0 2019-12-07 03:23:25.789 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=9432, state=WAITING, sendCnt=1, command=DiscoverAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=1B, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:23:25.790 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 1B -> RX_NAK == WAITING 2019-12-07 03:23:26.286 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D0001FF8F6A: NWK Discovery finishing node rediscovery after 4 attempts 2019-12-07 03:23:28.360 [DEBUG] [.zsmartsystems.zigbee.zcl.ZclCluster] - readSync request: ZclAttribute [cluster=com.zsmartsystems.zigbee.zcl.clusters.ZclThermostatCluster@1a6ca67a, id=18, name=Occupied Heating Setpoint, dataType=SIGNED_16_BIT_INTEGER, lastValue=null] 2019-12-07 03:23:28.360 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=--, identifiers=[18]]] 2019-12-07 03:23:28.361 [DEBUG] [transaction.ZigBeeTransactionManager] - 55072/1: Sending ZigBeeTransaction [queueTime=12004, state=WAITING, sendCnt=1, command=DiscoverAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=1B, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:23:28.361 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding 2019-12-07 03:23:28.362 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: DiscoverAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=1B, startAttributeIdentifier=0, maximumAttributeIdentifiers=10] 2019-12-07 03:23:28.362 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=27, commandId=12] 2019-12-07 03:23:28.362 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=55072/1, profile=0104, cluster=0201, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=25, payload=00 1B 0C 00 00 0A] 2019-12-07 03:23:28.373 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=80] 2019-12-07 03:23:33.065 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=55072, apsFrame=EmberApsFrame [profileId=260, clusterId=513, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=80], messageTag=1B, status=EMBER_DELIVERY_FAILED, messageContents=] 2019-12-07 03:23:33.066 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=1B state=RX_NAK 2019-12-07 03:23:33.067 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=1B, state=RX_NAK, outstanding=1 2019-12-07 03:23:33.068 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=16711, state=FAILED, sendCnt=2, command=DiscoverAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=1B, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:23:33.068 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding 2019-12-07 03:23:33.069 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete FAILED 0 2019-12-07 03:23:33.069 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete exceeded retries 2 2019-12-07 03:23:33.070 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=16712, state=FAILED, sendCnt=2, command=DiscoverAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=1B, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:23:33.070 [DEBUG] [transaction.ZigBeeTransactionManager] - 55072/1: Sending ZigBeeTransaction [queueTime=4710, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=1C, identifiers=[18]]] 2019-12-07 03:23:33.070 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding 2019-12-07 03:23:33.071 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=1C, identifiers=[18]] 2019-12-07 03:23:33.071 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=28, commandId=0] 2019-12-07 03:23:33.072 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=55072/1, profile=0104, cluster=0201, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=26, payload=00 1C 00 12 00] 2019-12-07 03:23:33.072 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 1B -> RX_NAK == FAILED 2019-12-07 03:23:33.087 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=81] 2019-12-07 03:23:37.782 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=55072, apsFrame=EmberApsFrame [profileId=260, clusterId=513, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=81], messageTag=1C, status=EMBER_DELIVERY_FAILED, messageContents=] 2019-12-07 03:23:37.784 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=1C state=RX_NAK 2019-12-07 03:23:37.785 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=1C, state=RX_NAK, outstanding=1 2019-12-07 03:23:37.786 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=9426, state=FAILED, sendCnt=1, command=ReadAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=1C, identifiers=[18]]] 2019-12-07 03:23:37.786 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding 2019-12-07 03:23:37.787 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete FAILED 0 2019-12-07 03:23:37.788 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=9428, state=WAITING, sendCnt=1, command=ReadAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=1C, identifiers=[18]]] 2019-12-07 03:23:37.789 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 1C -> RX_NAK == WAITING 2019-12-07 03:23:39.524 [INFO ] [el.script.Temp_Outside_MinMaxAverage] - I_Geb_OutsideTemp24HMin set to -3.7 2019-12-07 03:23:39.547 [INFO ] [el.script.Temp_Outside_MinMaxAverage] - I_Geb_OutsideTemp24HMax set to 7.4 2019-12-07 03:23:39.558 [INFO ] [el.script.Temp_Outside_MinMaxAverage] - I_Geb_OutsideTemp24HAvg set to 1.556736920734584 2019-12-07 03:23:40.368 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=1, state=WAITING, sendCnt=0, command=DiscoverAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=--, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:23:40.369 [DEBUG] [transaction.ZigBeeTransactionManager] - 55072/1: Sending ZigBeeTransaction [queueTime=12009, state=WAITING, sendCnt=1, command=ReadAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=1C, identifiers=[18]]] 2019-12-07 03:23:40.370 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding 2019-12-07 03:23:40.370 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=1C, identifiers=[18]] 2019-12-07 03:23:40.371 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=28, commandId=0] 2019-12-07 03:23:40.372 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=55072/1, profile=0104, cluster=0201, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=27, payload=00 1C 00 12 00] 2019-12-07 03:23:40.386 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=82] 2019-12-07 03:23:45.076 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=55072, apsFrame=EmberApsFrame [profileId=260, clusterId=513, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=82], messageTag=1C, status=EMBER_DELIVERY_FAILED, messageContents=] 2019-12-07 03:23:45.077 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=1C state=RX_NAK 2019-12-07 03:23:45.078 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=1C, state=RX_NAK, outstanding=1 2019-12-07 03:23:45.079 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=16719, state=FAILED, sendCnt=2, command=ReadAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=1C, identifiers=[18]]] 2019-12-07 03:23:45.080 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding 2019-12-07 03:23:45.080 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete FAILED 0 2019-12-07 03:23:45.081 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete exceeded retries 2 2019-12-07 03:23:45.082 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=16722, state=FAILED, sendCnt=2, command=ReadAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=1C, identifiers=[18]]] 2019-12-07 03:23:45.083 [DEBUG] [transaction.ZigBeeTransactionManager] - 55072/1: Sending ZigBeeTransaction [queueTime=4715, state=WAITING, sendCnt=0, command=DiscoverAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=1D, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:23:45.083 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding 2019-12-07 03:23:45.084 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: DiscoverAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=1D, startAttributeIdentifier=0, maximumAttributeIdentifiers=10] 2019-12-07 03:23:45.085 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=29, commandId=12] 2019-12-07 03:23:45.085 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=55072/1, profile=0104, cluster=0201, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=28, payload=00 1D 0C 00 00 0A] 2019-12-07 03:23:45.086 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 1C -> RX_NAK == FAILED 2019-12-07 03:23:45.101 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=83] 2019-12-07 03:23:49.793 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=55072, apsFrame=EmberApsFrame [profileId=260, clusterId=513, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=83], messageTag=1D, status=EMBER_DELIVERY_FAILED, messageContents=] 2019-12-07 03:23:49.795 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=1D state=RX_NAK 2019-12-07 03:23:49.796 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=1D, state=RX_NAK, outstanding=1 2019-12-07 03:23:49.797 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=9430, state=FAILED, sendCnt=1, command=DiscoverAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=1D, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:23:49.798 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding 2019-12-07 03:23:49.798 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete FAILED 0 2019-12-07 03:23:49.799 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=9432, state=WAITING, sendCnt=1, command=DiscoverAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=1D, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:23:49.800 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 1D -> RX_NAK == WAITING 2019-12-07 03:23:52.373 [DEBUG] [.zsmartsystems.zigbee.zcl.ZclCluster] - readSync request: ZclAttribute [cluster=com.zsmartsystems.zigbee.zcl.clusters.ZclThermostatCluster@1a6ca67a, id=28, name=System Mode, dataType=ENUMERATION_8_BIT, lastValue=null] 2019-12-07 03:23:52.374 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=--, identifiers=[28]]] 2019-12-07 03:23:52.376 [DEBUG] [transaction.ZigBeeTransactionManager] - 55072/1: Sending ZigBeeTransaction [queueTime=12007, state=WAITING, sendCnt=1, command=DiscoverAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=1D, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:23:52.376 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding 2019-12-07 03:23:52.377 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: DiscoverAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=1D, startAttributeIdentifier=0, maximumAttributeIdentifiers=10] 2019-12-07 03:23:52.377 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=29, commandId=12] 2019-12-07 03:23:52.378 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=55072/1, profile=0104, cluster=0201, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=29, payload=00 1D 0C 00 00 0A] 2019-12-07 03:23:52.392 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=84] 2019-12-07 03:23:57.081 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=55072, apsFrame=EmberApsFrame [profileId=260, clusterId=513, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=84], messageTag=1D, status=EMBER_DELIVERY_FAILED, messageContents=] 2019-12-07 03:23:57.082 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=1D state=RX_NAK 2019-12-07 03:23:57.083 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=1D, state=RX_NAK, outstanding=1 2019-12-07 03:23:57.083 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=16716, state=FAILED, sendCnt=2, command=DiscoverAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=1D, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:23:57.084 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding 2019-12-07 03:23:57.084 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete FAILED 0 2019-12-07 03:23:57.085 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete exceeded retries 2 2019-12-07 03:23:57.085 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=16718, state=FAILED, sendCnt=2, command=DiscoverAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=1D, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:23:57.086 [DEBUG] [transaction.ZigBeeTransactionManager] - 55072/1: Sending ZigBeeTransaction [queueTime=4712, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=1E, identifiers=[28]]] 2019-12-07 03:23:57.086 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding 2019-12-07 03:23:57.086 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=1E, identifiers=[28]] 2019-12-07 03:23:57.087 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=30, commandId=0] 2019-12-07 03:23:57.087 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=55072/1, profile=0104, cluster=0201, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=2A, payload=00 1E 00 1C 00] 2019-12-07 03:23:57.088 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 1D -> RX_NAK == FAILED 2019-12-07 03:23:57.101 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=85] 2019-12-07 03:24:01.793 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=55072, apsFrame=EmberApsFrame [profileId=260, clusterId=513, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=85], messageTag=1E, status=EMBER_DELIVERY_FAILED, messageContents=] 2019-12-07 03:24:01.794 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=1E state=RX_NAK 2019-12-07 03:24:01.795 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=1E, state=RX_NAK, outstanding=1 2019-12-07 03:24:01.795 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=9421, state=FAILED, sendCnt=1, command=ReadAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=1E, identifiers=[28]]] 2019-12-07 03:24:01.796 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding 2019-12-07 03:24:01.796 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete FAILED 0 2019-12-07 03:24:01.796 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=9422, state=WAITING, sendCnt=1, command=ReadAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=1E, identifiers=[28]]] 2019-12-07 03:24:01.797 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 1E -> RX_NAK == WAITING 2019-12-07 03:24:04.387 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=DiscoverAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=--, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:24:04.388 [DEBUG] [transaction.ZigBeeTransactionManager] - 55072/1: Sending ZigBeeTransaction [queueTime=12014, state=WAITING, sendCnt=1, command=ReadAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=1E, identifiers=[28]]] 2019-12-07 03:24:04.389 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding 2019-12-07 03:24:04.389 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=1E, identifiers=[28]] 2019-12-07 03:24:04.390 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=30, commandId=0] 2019-12-07 03:24:04.390 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=55072/1, profile=0104, cluster=0201, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=2B, payload=00 1E 00 1C 00] 2019-12-07 03:24:04.404 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=86] 2019-12-07 03:24:09.096 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=55072, apsFrame=EmberApsFrame [profileId=260, clusterId=513, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=86], messageTag=1E, status=EMBER_DELIVERY_FAILED, messageContents=] 2019-12-07 03:24:09.096 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=1E state=RX_NAK 2019-12-07 03:24:09.097 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=1E, state=RX_NAK, outstanding=1 2019-12-07 03:24:09.098 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=16724, state=FAILED, sendCnt=2, command=ReadAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=1E, identifiers=[28]]] 2019-12-07 03:24:09.099 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding 2019-12-07 03:24:09.099 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete FAILED 0 2019-12-07 03:24:09.100 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete exceeded retries 2 2019-12-07 03:24:09.100 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=16726, state=FAILED, sendCnt=2, command=ReadAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=1E, identifiers=[28]]] 2019-12-07 03:24:09.101 [DEBUG] [transaction.ZigBeeTransactionManager] - 55072/1: Sending ZigBeeTransaction [queueTime=4714, state=WAITING, sendCnt=0, command=DiscoverAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=1F, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:24:09.102 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding 2019-12-07 03:24:09.102 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: DiscoverAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=1F, startAttributeIdentifier=0, maximumAttributeIdentifiers=10] 2019-12-07 03:24:09.103 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=31, commandId=12] 2019-12-07 03:24:09.103 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=55072/1, profile=0104, cluster=0201, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=2C, payload=00 1F 0C 00 00 0A] 2019-12-07 03:24:09.104 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 1E -> RX_NAK == FAILED 2019-12-07 03:24:09.117 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=87] 2019-12-07 03:24:13.812 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=55072, apsFrame=EmberApsFrame [profileId=260, clusterId=513, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=87], messageTag=1F, status=EMBER_DELIVERY_FAILED, messageContents=] 2019-12-07 03:24:13.812 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=1F state=RX_NAK 2019-12-07 03:24:13.813 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=1F, state=RX_NAK, outstanding=1 2019-12-07 03:24:13.814 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=9427, state=FAILED, sendCnt=1, command=DiscoverAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=1F, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:24:13.815 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding 2019-12-07 03:24:13.816 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete FAILED 0 2019-12-07 03:24:13.816 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=9429, state=WAITING, sendCnt=1, command=DiscoverAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=1F, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:24:13.817 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 1F -> RX_NAK == WAITING 2019-12-07 03:24:16.392 [DEBUG] [.zsmartsystems.zigbee.zcl.ZclCluster] - readSync request: ZclAttribute [cluster=com.zsmartsystems.zigbee.zcl.clusters.ZclThermostatCluster@1a6ca67a, id=17, name=Occupied Cooling Setpoint, dataType=SIGNED_16_BIT_INTEGER, lastValue=null] 2019-12-07 03:24:16.392 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=--, identifiers=[17]]] 2019-12-07 03:24:16.393 [DEBUG] [transaction.ZigBeeTransactionManager] - 55072/1: Sending ZigBeeTransaction [queueTime=12005, state=WAITING, sendCnt=1, command=DiscoverAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=1F, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:24:16.393 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding 2019-12-07 03:24:16.394 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: DiscoverAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=1F, startAttributeIdentifier=0, maximumAttributeIdentifiers=10] 2019-12-07 03:24:16.394 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=31, commandId=12] 2019-12-07 03:24:16.395 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=55072/1, profile=0104, cluster=0201, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=2D, payload=00 1F 0C 00 00 0A] 2019-12-07 03:24:16.409 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=88] 2019-12-07 03:24:21.102 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=55072, apsFrame=EmberApsFrame [profileId=260, clusterId=513, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=88], messageTag=1F, status=EMBER_DELIVERY_FAILED, messageContents=] 2019-12-07 03:24:21.102 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=1F state=RX_NAK 2019-12-07 03:24:21.103 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=1F, state=RX_NAK, outstanding=1 2019-12-07 03:24:21.104 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=16717, state=FAILED, sendCnt=2, command=DiscoverAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=1F, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:24:21.105 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding 2019-12-07 03:24:21.105 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete FAILED 0 2019-12-07 03:24:21.106 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete exceeded retries 2 2019-12-07 03:24:21.106 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=16719, state=FAILED, sendCnt=2, command=DiscoverAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=1F, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:24:21.107 [DEBUG] [transaction.ZigBeeTransactionManager] - 55072/1: Sending ZigBeeTransaction [queueTime=4715, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=20, identifiers=[17]]] 2019-12-07 03:24:21.108 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding 2019-12-07 03:24:21.108 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=20, identifiers=[17]] 2019-12-07 03:24:21.109 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=32, commandId=0] 2019-12-07 03:24:21.110 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=55072/1, profile=0104, cluster=0201, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=2E, payload=00 20 00 11 00] 2019-12-07 03:24:21.111 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 1F -> RX_NAK == FAILED 2019-12-07 03:24:21.126 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=89] 2019-12-07 03:24:25.817 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=55072, apsFrame=EmberApsFrame [profileId=260, clusterId=513, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=89], messageTag=20, status=EMBER_DELIVERY_FAILED, messageContents=] 2019-12-07 03:24:25.818 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=20 state=RX_NAK 2019-12-07 03:24:25.819 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=20, state=RX_NAK, outstanding=1 2019-12-07 03:24:25.820 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=9428, state=FAILED, sendCnt=1, command=ReadAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=20, identifiers=[17]]] 2019-12-07 03:24:25.821 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding 2019-12-07 03:24:25.822 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete FAILED 0 2019-12-07 03:24:25.822 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=9430, state=WAITING, sendCnt=1, command=ReadAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=20, identifiers=[17]]] 2019-12-07 03:24:25.823 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 20 -> RX_NAK == WAITING 2019-12-07 03:24:28.402 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=DiscoverAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=--, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:24:28.403 [DEBUG] [transaction.ZigBeeTransactionManager] - 55072/1: Sending ZigBeeTransaction [queueTime=12011, state=WAITING, sendCnt=1, command=ReadAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=20, identifiers=[17]]] 2019-12-07 03:24:28.403 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding 2019-12-07 03:24:28.404 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=20, identifiers=[17]] 2019-12-07 03:24:28.404 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=32, commandId=0] 2019-12-07 03:24:28.405 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=55072/1, profile=0104, cluster=0201, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=2F, payload=00 20 00 11 00] 2019-12-07 03:24:28.418 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=8A] 2019-12-07 03:24:33.108 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=55072, apsFrame=EmberApsFrame [profileId=260, clusterId=513, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=8A], messageTag=20, status=EMBER_DELIVERY_FAILED, messageContents=] 2019-12-07 03:24:33.109 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=20 state=RX_NAK 2019-12-07 03:24:33.110 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=20, state=RX_NAK, outstanding=1 2019-12-07 03:24:33.111 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=16718, state=FAILED, sendCnt=2, command=ReadAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=20, identifiers=[17]]] 2019-12-07 03:24:33.111 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding 2019-12-07 03:24:33.111 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete FAILED 0 2019-12-07 03:24:33.112 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete exceeded retries 2 2019-12-07 03:24:33.112 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=16720, state=FAILED, sendCnt=2, command=ReadAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=20, identifiers=[17]]] 2019-12-07 03:24:33.113 [DEBUG] [transaction.ZigBeeTransactionManager] - 55072/1: Sending ZigBeeTransaction [queueTime=4711, state=WAITING, sendCnt=0, command=DiscoverAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=21, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:24:33.113 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding 2019-12-07 03:24:33.114 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: DiscoverAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=21, startAttributeIdentifier=0, maximumAttributeIdentifiers=10] 2019-12-07 03:24:33.114 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=33, commandId=12] 2019-12-07 03:24:33.114 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=55072/1, profile=0104, cluster=0201, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=30, payload=00 21 0C 00 00 0A] 2019-12-07 03:24:33.115 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 20 -> RX_NAK == FAILED 2019-12-07 03:24:33.130 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=8B] 2019-12-07 03:24:37.823 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=55072, apsFrame=EmberApsFrame [profileId=260, clusterId=513, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=8B], messageTag=21, status=EMBER_DELIVERY_FAILED, messageContents=] 2019-12-07 03:24:37.823 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=21 state=RX_NAK 2019-12-07 03:24:37.824 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=21, state=RX_NAK, outstanding=1 2019-12-07 03:24:37.825 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=9423, state=FAILED, sendCnt=1, command=DiscoverAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=21, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:24:37.826 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding 2019-12-07 03:24:37.827 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete FAILED 0 2019-12-07 03:24:37.827 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=9425, state=WAITING, sendCnt=1, command=DiscoverAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=21, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:24:37.828 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 21 -> RX_NAK == WAITING 2019-12-07 03:24:38.786 [INFO ] [el.script.Temp_Outside_MinMaxAverage] - I_Geb_OutsideTemp24HMin set to -3.7 2019-12-07 03:24:38.824 [INFO ] [el.script.Temp_Outside_MinMaxAverage] - I_Geb_OutsideTemp24HMax set to 7.4 2019-12-07 03:24:38.850 [INFO ] [el.script.Temp_Outside_MinMaxAverage] - I_Geb_OutsideTemp24HAvg set to 1.564132832184115 2019-12-07 03:24:40.405 [DEBUG] [.zsmartsystems.zigbee.zcl.ZclCluster] - readSync request: ZclAttribute [cluster=com.zsmartsystems.zigbee.zcl.clusters.ZclThermostatCluster@1a6ca67a, id=30, name=Thermostat Running Mode, dataType=ENUMERATION_8_BIT, lastValue=null] 2019-12-07 03:24:40.406 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=--, identifiers=[30]]] 2019-12-07 03:24:40.406 [DEBUG] [transaction.ZigBeeTransactionManager] - 55072/1: Sending ZigBeeTransaction [queueTime=12004, state=WAITING, sendCnt=1, command=DiscoverAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=21, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:24:40.407 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding 2019-12-07 03:24:40.407 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: DiscoverAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=21, startAttributeIdentifier=0, maximumAttributeIdentifiers=10] 2019-12-07 03:24:40.408 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=33, commandId=12] 2019-12-07 03:24:40.408 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=55072/1, profile=0104, cluster=0201, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=31, payload=00 21 0C 00 00 0A] 2019-12-07 03:24:40.423 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=8C] 2019-12-07 03:24:45.113 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=55072, apsFrame=EmberApsFrame [profileId=260, clusterId=513, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=8C], messageTag=21, status=EMBER_DELIVERY_FAILED, messageContents=] 2019-12-07 03:24:45.114 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=21 state=RX_NAK 2019-12-07 03:24:45.115 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=21, state=RX_NAK, outstanding=1 2019-12-07 03:24:45.116 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=16713, state=FAILED, sendCnt=2, command=DiscoverAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=21, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:24:45.116 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding 2019-12-07 03:24:45.117 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete FAILED 0 2019-12-07 03:24:45.117 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete exceeded retries 2 2019-12-07 03:24:45.118 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=16716, state=FAILED, sendCnt=2, command=DiscoverAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=21, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]] 2019-12-07 03:24:45.118 [DEBUG] [transaction.ZigBeeTransactionManager] - 55072/1: Sending ZigBeeTransaction [queueTime=4712, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=22, identifiers=[30]]] 2019-12-07 03:24:45.119 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding 2019-12-07 03:24:45.120 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Thermostat: 0/0 -> 55072/1, cluster=0201, TID=22, identifiers=[30]] 2019-12-07 03:24:45.121 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=34, commandId=0] 2019-12-07 03:24:45.121 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=55072/1, profile=0104, cluster=0201, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=32, payload=00 22 00 1E 00] 2019-12-07 03:24:45.122 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 21 -> RX_NAK == FAILED 2019-12-07 03:24:45.136 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=8D]