2019-12-07 00:54:01.704 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 7CB03EAA00B286AC: Discovery: Starting discovery for existing device
2019-12-07 00:54:01.705 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 7CB03EAA0A002E4F: Discovery: Starting discovery for existing device
2019-12-07 00:54:01.707 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 7CB03EAA0A002ADD: Discovery: Starting discovery for existing device
2019-12-07 00:54:01.707 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - Starting ZigBee scan for zigbee:coordinator_ember:cc9950e6
2019-12-07 00:54:01.708 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Permit join to 65532/0 for 60 seconds.
2019-12-07 00:54:01.709 [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 00:54:01.710 [DEBUG] [transaction.ZigBeeTransactionManager] - 65532/0: Sending ZigBeeTransaction [queueTime=1, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=3F, permitDuration=60, tcSignificance=true]]
2019-12-07 00:54:01.710 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2019-12-07 00:54:01.711 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=3F, permitDuration=60, tcSignificance=true]
2019-12-07 00:54:01.712 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=65532/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=3F, payload=00 3C 01]
2019-12-07 00:54:01.713 [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 00:54:01.714 [DEBUG] [transaction.ZigBeeTransactionManager] - 0/0: Sending ZigBeeTransaction [queueTime=1, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=40, permitDuration=60, tcSignificance=true]]
2019-12-07 00:54:01.715 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2019-12-07 00:54:01.716 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=40, permitDuration=60, tcSignificance=true]
2019-12-07 00:54:01.717 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 7CB03EAA0A002E4F: Starting ZigBee device discovery
2019-12-07 00:54:01.717 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 7CB03EAA00B286AC: Starting ZigBee device discovery
2019-12-07 00:54:01.718 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 7CB03EAA0A002E4F: Creating ZigBee device zigbee:device with bridge zigbee:coordinator_ember:cc9950e6
2019-12-07 00:54:01.717 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=40, payload=00 3C 01]
2019-12-07 00:54:01.718 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 7CB03EAA00B286AC: Creating ZigBee device zigbee:device with bridge zigbee:coordinator_ember:cc9950e6
2019-12-07 00:54:01.719 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 7CB03EAA0A002E4F: ZigBee node property discovery start
2019-12-07 00:54:01.719 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 7CB03EAA0A002ADD: Starting ZigBee device discovery
2019-12-07 00:54:01.720 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 7CB03EAA0A002E4F: ZigBee node property discovery using basic cluster on endpoint 14815/3
2019-12-07 00:54:01.720 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 7CB03EAA00B286AC: ZigBee node property discovery start
2019-12-07 00:54:01.721 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 7CB03EAA0A002ADD: Creating ZigBee device zigbee:device with bridge zigbee:coordinator_ember:cc9950e6
2019-12-07 00:54:01.721 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A002E4F: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Basic: 0/0 -> 14815/3, cluster=0000, TID=--, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-07 00:54:01.722 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 7CB03EAA00B286AC: ZigBee node property discovery using basic cluster on endpoint 37449/3
2019-12-07 00:54:01.722 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 7CB03EAA0A002ADD: ZigBee node property discovery start
2019-12-07 00:54:01.723 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 7CB03EAA0A002ADD: ZigBee node property discovery using basic cluster on endpoint 23788/3
2019-12-07 00:54:01.723 [DEBUG] [transaction.ZigBeeTransactionManager] - 14815/3: Sending ZigBeeTransaction [queueTime=2, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Basic: 0/0 -> 14815/3, cluster=0000, TID=41, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-07 00:54:01.724 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 3 outstanding
2019-12-07 00:54:01.725 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Basic: 0/0 -> 14815/3, cluster=0000, TID=41, identifiers=[5, 4, 3, 2, 6, 0, 1]]
2019-12-07 00:54:01.725 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=65, commandId=0]
2019-12-07 00:54:01.726 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=14815/3, profile=0104, cluster=0000, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=41, payload=00 41 00 05 00 04 00 03 00 02 00 06 00 00 00 01 00]
2019-12-07 00:54:01.727 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A002ADD: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Basic: 0/0 -> 23788/3, cluster=0000, TID=--, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-07 00:54:01.727 [DEBUG] [transaction.ZigBeeTransactionManager] - 23788/3: Sending ZigBeeTransaction [queueTime=1, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Basic: 0/0 -> 23788/3, cluster=0000, TID=42, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-07 00:54:01.727 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 4 outstanding
2019-12-07 00:54:01.728 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Basic: 0/0 -> 23788/3, cluster=0000, TID=42, identifiers=[5, 4, 3, 2, 6, 0, 1]]
2019-12-07 00:54:01.729 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=66, commandId=0]
2019-12-07 00:54:01.730 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=23788/3, profile=0104, cluster=0000, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=42, payload=00 42 00 05 00 04 00 03 00 02 00 06 00 00 00 01 00]
2019-12-07 00:54:01.731 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA00B286AC: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Basic: 0/0 -> 37449/3, cluster=0000, TID=--, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-07 00:54:01.731 [DEBUG] [transaction.ZigBeeTransactionManager] - 37449/3: Sending ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Basic: 0/0 -> 37449/3, cluster=0000, TID=43, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-07 00:54:01.732 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendBroadcastResponse [status=EMBER_SUCCESS, sequence=B9]
2019-12-07 00:54:01.732 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 5 outstanding
2019-12-07 00:54:01.733 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Basic: 0/0 -> 37449/3, cluster=0000, TID=43, identifiers=[5, 4, 3, 2, 6, 0, 1]]
2019-12-07 00:54:01.734 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=67, commandId=0]
2019-12-07 00:54:01.735 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=37449/3, profile=0104, cluster=0000, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=43, payload=00 43 00 05 00 04 00 03 00 02 00 06 00 00 00 01 00]
2019-12-07 00:54:01.743 [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=B9], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 3C 01]
2019-12-07 00:54:01.744 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0036, addressMode=null, radius=0, apsSecurity=false, apsCounter=B9, payload=00 3C 01]
2019-12-07 00:54:01.744 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true]
2019-12-07 00:54:01.745 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] 
2019-12-07 00:54:01.745 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] ZigBeeTransaction [queueTime=24, state=DISPATCHED, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 14815/3, cluster=0000, TID=41, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-07 00:54:01.746 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] ZigBeeTransaction [queueTime=20, state=DISPATCHED, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 23788/3, cluster=0000, TID=42, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-07 00:54:01.747 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] ZigBeeTransaction [queueTime=16, state=DISPATCHED, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 37449/3, cluster=0000, TID=43, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-07 00:54:01.748 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] ZigBeeTransaction [queueTime=39, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=3F, permitDuration=60, tcSignificance=true]]
2019-12-07 00:54:01.748 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] ZigBeeTransaction [queueTime=35, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=40, permitDuration=60, tcSignificance=true]]
2019-12-07 00:54:01.762 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=BA]
2019-12-07 00:54:01.778 [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=BA], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 3C 01]
2019-12-07 00:54:01.779 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0036, addressMode=null, radius=0, apsSecurity=false, apsCounter=BA, payload=00 3C 01]
2019-12-07 00:54:01.779 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true]
2019-12-07 00:54:01.780 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] 
2019-12-07 00:54:01.780 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] ZigBeeTransaction [queueTime=59, state=DISPATCHED, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 14815/3, cluster=0000, TID=41, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-07 00:54:01.782 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] ZigBeeTransaction [queueTime=55, state=DISPATCHED, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 23788/3, cluster=0000, TID=42, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-07 00:54:01.783 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] ZigBeeTransaction [queueTime=51, state=DISPATCHED, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 37449/3, cluster=0000, TID=43, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-07 00:54:01.784 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] ZigBeeTransaction [queueTime=75, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=3F, permitDuration=60, tcSignificance=true]]
2019-12-07 00:54:01.785 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] ZigBeeTransaction [queueTime=72, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=40, permitDuration=60, tcSignificance=true]]
2019-12-07 00:54:01.788 [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=BB], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00]
2019-12-07 00:54:01.789 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=8036, addressMode=null, radius=0, apsSecurity=false, apsCounter=BB, payload=00 00]
2019-12-07 00:54:01.789 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS]
2019-12-07 00:54:01.790 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] 
2019-12-07 00:54:01.790 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] ZigBeeTransaction [queueTime=69, state=DISPATCHED, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 14815/3, cluster=0000, TID=41, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-07 00:54:01.791 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] ZigBeeTransaction [queueTime=64, state=DISPATCHED, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 23788/3, cluster=0000, TID=42, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-07 00:54:01.791 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] ZigBeeTransaction [queueTime=60, state=DISPATCHED, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 37449/3, cluster=0000, TID=43, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-07 00:54:01.791 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] ZigBeeTransaction [queueTime=82, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=3F, permitDuration=60, tcSignificance=true]]
2019-12-07 00:54:01.792 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] ZigBeeTransaction [queueTime=79, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=40, permitDuration=60, tcSignificance=true]]
2019-12-07 00:54:01.794 [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=BA], messageTag=40, status=EMBER_SUCCESS, messageContents=]
2019-12-07 00:54:01.813 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=BC]
2019-12-07 00:54:01.850 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=BD]
2019-12-07 00:54:01.934 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteRecordHandler [source=23788, sourceEui=7CB03EAA0A002ADD, lastHopLqi=255, lastHopRssi=-64, relayList=]
2019-12-07 00:54:01.937 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=23788, apsFrame=EmberApsFrame [profileId=260, clusterId=0, sourceEndpoint=1, destinationEndpoint=3, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=BD], messageTag=42, status=EMBER_SUCCESS, messageContents=]
2019-12-07 00:54:01.941 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteRecordHandler [source=23788, sourceEui=7CB03EAA0A002ADD, lastHopLqi=255, lastHopRssi=-64, relayList=]
2019-12-07 00:54:01.951 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=260, clusterId=0, sourceEndpoint=3, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY], groupId=0, sequence=76], lastHopLqi=255, lastHopRssi=-64, sender=23788, bindingIndex=255, addressIndex=255, messageContents=18 42 01 05 00 00 42 07 50 6C 75 67 20 30 31 04 00 00 42 05 4F 53 52 41 4D 03 00 00 20 01 02 00 00 20 02 06 00 00 42 10 32 30 31 34 30 33 33 31 44 45 4F 53 2A 2A 2A 2A 00 00 00 20 01 01 00 00 20 0C]
2019-12-07 00:54:01.952 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=23788/3, destinationAddress=0/1, profile=0104, cluster=0000, addressMode=null, radius=0, apsSecurity=false, apsCounter=76, payload=18 42 01 05 00 00 42 07 50 6C 75 67 20 30 31 04 00 00 42 05 4F 53 52 41 4D 03 00 00 20 01 02 00 00 20 02 06 00 00 42 10 32 30 31 34 30 33 33 31 44 45 4F 53 2A 2A 2A 2A 00 00 00 20 01 01 00 00 20 0C]
2019-12-07 00:54:01.953 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=66, commandId=1]
2019-12-07 00:54:01.954 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReadAttributesResponse [Basic: 23788/3 -> 0/1, cluster=0000, TID=42, records=[ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=5, status=SUCCESS, attributeValue=Plug 01], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=4, status=SUCCESS, attributeValue=OSRAM], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=3, status=SUCCESS, attributeValue=1], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=2, status=SUCCESS, attributeValue=2], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=6, status=SUCCESS, attributeValue=20140331DEOS****], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, status=SUCCESS, attributeValue=1], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=1, status=SUCCESS, attributeValue=12]]]
2019-12-07 00:54:01.954 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [Basic: 23788/3 -> 0/1, cluster=0000, TID=42, records=[ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=5, status=SUCCESS, attributeValue=Plug 01], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=4, status=SUCCESS, attributeValue=OSRAM], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=3, status=SUCCESS, attributeValue=1], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=2, status=SUCCESS, attributeValue=2], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=6, status=SUCCESS, attributeValue=20140331DEOS****], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, status=SUCCESS, attributeValue=1], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=1, status=SUCCESS, attributeValue=12]]] 
2019-12-07 00:54:01.955 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [Basic: 23788/3 -> 0/1, cluster=0000, TID=42, records=[ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=5, status=SUCCESS, attributeValue=Plug 01], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=4, status=SUCCESS, attributeValue=OSRAM], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=3, status=SUCCESS, attributeValue=1], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=2, status=SUCCESS, attributeValue=2], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=6, status=SUCCESS, attributeValue=20140331DEOS****], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, status=SUCCESS, attributeValue=1], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=1, status=SUCCESS, attributeValue=12]]] ZigBeeTransaction [queueTime=234, state=DISPATCHED, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 14815/3, cluster=0000, TID=41, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-07 00:54:01.955 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [Basic: 23788/3 -> 0/1, cluster=0000, TID=42, records=[ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=5, status=SUCCESS, attributeValue=Plug 01], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=4, status=SUCCESS, attributeValue=OSRAM], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=3, status=SUCCESS, attributeValue=1], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=2, status=SUCCESS, attributeValue=2], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=6, status=SUCCESS, attributeValue=20140331DEOS****], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, status=SUCCESS, attributeValue=1], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=1, status=SUCCESS, attributeValue=12]]] ZigBeeTransaction [queueTime=229, state=DISPATCHED, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 23788/3, cluster=0000, TID=42, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-07 00:54:01.956 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [Basic: 23788/3 -> 0/1, cluster=0000, TID=42, records=[ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=5, status=SUCCESS, attributeValue=Plug 01], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=4, status=SUCCESS, attributeValue=OSRAM], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=3, status=SUCCESS, attributeValue=1], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=2, status=SUCCESS, attributeValue=2], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=6, status=SUCCESS, attributeValue=20140331DEOS****], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, status=SUCCESS, attributeValue=1], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=1, status=SUCCESS, attributeValue=12]]] ZigBeeTransaction [queueTime=225, state=DISPATCHED, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 37449/3, cluster=0000, TID=43, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-07 00:54:01.957 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [Basic: 23788/3 -> 0/1, cluster=0000, TID=42, records=[ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=5, status=SUCCESS, attributeValue=Plug 01], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=4, status=SUCCESS, attributeValue=OSRAM], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=3, status=SUCCESS, attributeValue=1], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=2, status=SUCCESS, attributeValue=2], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=6, status=SUCCESS, attributeValue=20140331DEOS****], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, status=SUCCESS, attributeValue=1], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=1, status=SUCCESS, attributeValue=12]]] ZigBeeTransaction [queueTime=248, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=3F, permitDuration=60, tcSignificance=true]]
2019-12-07 00:54:01.957 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [Basic: 23788/3 -> 0/1, cluster=0000, TID=42, records=[ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=5, status=SUCCESS, attributeValue=Plug 01], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=4, status=SUCCESS, attributeValue=OSRAM], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=3, status=SUCCESS, attributeValue=1], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=2, status=SUCCESS, attributeValue=2], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=6, status=SUCCESS, attributeValue=20140331DEOS****], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, status=SUCCESS, attributeValue=1], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=1, status=SUCCESS, attributeValue=12]]] ZigBeeTransaction [queueTime=244, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=40, permitDuration=60, tcSignificance=true]]
2019-12-07 00:54:01.961 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=235, state=COMPLETE, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 23788/3, cluster=0000, TID=42, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-07 00:54:01.961 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 7CB03EAA0A002ADD: ZigBee node property discovery using OTA cluster on endpoint 23788/3
2019-12-07 00:54:01.962 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 4 outstanding
2019-12-07 00:54:01.962 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A002ADD: transactionComplete COMPLETE 0
2019-12-07 00:54:01.962 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 7CB03EAA0A002ADD: ZigBee node property discovery complete: {zigbee_logicaltype=ROUTER, zigbee_powerlevel=FULL, zigbee_manufacturercode=0xbbaa, modelId=Plug 01, zigbee_networkaddress=23788, zigbee_powersource=MAINS, zigbee_stkversion=2, zigbee_datecode=20140331DEOS****, zigbee_zclversion=1, vendor=OSRAM, zigbee_powermode=RECEIVER_ON_IDLE, zigbee_powersources=[RECHARGABLE_BATTERY, MAINS, DISPOSABLE_BATTERY], hardwareVersion=1, firmwareVersion=0x01020412, zigbee_applicationVersion=12}
2019-12-07 00:54:01.963 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 7CB03EAA0A002ADD: Update ZigBee device zigbee:device with bridge zigbee:coordinator_ember:cc9950e6, label 'OSRAM Plug 01'
2019-12-07 00:54:01.963 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=BE]
2019-12-07 00:54:01.964 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 7CB03EAA0A002ADD: Data store: Deferring write for 250ms.
2019-12-07 00:54:01.964 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=40 state=RX_ACK
2019-12-07 00:54:01.965 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=40, state=RX_ACK, outstanding=4
2019-12-07 00:54:01.966 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=42 state=RX_ACK
2019-12-07 00:54:01.966 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=42, state=RX_ACK, outstanding=4
2019-12-07 00:54:01.969 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=256, state=COMPLETE, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=40, permitDuration=60, tcSignificance=true]]
2019-12-07 00:54:01.970 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 3 outstanding
2019-12-07 00:54:01.971 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6F000DD02801: transactionComplete COMPLETE 0
2019-12-07 00:54:01.971 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 40 -> RX_ACK == COMPLETE
2019-12-07 00:54:02.066 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_SOURCE_ROUTE_FAILURE, target=14815]
2019-12-07 00:54:02.185 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_SOURCE_ROUTE_FAILURE, target=37449]
2019-12-07 00:54:02.215 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 7CB03EAA0A002ADD: Data store: Writing node.
2019-12-07 00:54:02.237 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 7CB03EAA0A002ADD: ZigBee saving network state complete.
2019-12-07 00:54:02.654 [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=B9], messageTag=3F, status=EMBER_DELIVERY_FAILED, messageContents=]
2019-12-07 00:54:02.655 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=3F state=RX_NAK
2019-12-07 00:54:02.655 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=3F, state=RX_NAK, outstanding=3
2019-12-07 00:54:02.656 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=947, state=FAILED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=3F, permitDuration=60, tcSignificance=true]]
2019-12-07 00:54:02.656 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 2 outstanding
2019-12-07 00:54:02.657 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete FAILED 0
2019-12-07 00:54:02.657 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete exceeded retries 1
2019-12-07 00:54:02.657 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=948, state=FAILED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=3F, permitDuration=60, tcSignificance=true]]
2019-12-07 00:54:02.658 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 3F -> RX_NAK == FAILED
2019-12-07 00:54:03.652 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_SOURCE_ROUTE_FAILURE, target=14815]
2019-12-07 00:54:03.771 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_SOURCE_ROUTE_FAILURE, target=37449]
2019-12-07 00:54:05.214 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_SOURCE_ROUTE_FAILURE, target=14815]
2019-12-07 00:54:05.338 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_SOURCE_ROUTE_FAILURE, target=37449]
2019-12-07 00:54:05.818 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspChildJoinHandler [index=0, joining=true, childId=58947, childEui64=00158D0001FF8F6A, childType=EMBER_SLEEPY_END_DEVICE]
2019-12-07 00:54:05.892 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: nodeStatusUpdate - node status is UNSECURED_JOIN, network address is 58947.
2019-12-07 00:54:05.898 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D0001FF8F6A: Device status updated. NWK=58947
2019-12-07 00:54:05.899 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D0001FF8F6A: NWK Discovery add node 58947
2019-12-07 00:54:05.900 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00158D0001FF8F6A: Node state updated from UNKNOWN to ONLINE
2019-12-07 00:54:05.903 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Updating node NWK=58947
2019-12-07 00:54:05.915 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 00158D0001FF8F6A: Data store: Deferring write for 250ms.
2019-12-07 00:54:05.917 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 00158D0001FF8F6A: Starting ZigBee device discovery
2019-12-07 00:54:05.917 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 00158D0001FF8F6A: Creating ZigBee device zigbee:device with bridge zigbee:coordinator_ember:cc9950e6
2019-12-07 00:54:05.921 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zigbee:device:cc9950e6:00158d0001ff8f6a' to inbox.
2019-12-07 00:54:05.922 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 00158D0001FF8F6A: Node discovery not complete
2019-12-07 00:54:05.931 [DEBUG] [p.discovery.ZigBeeDiscoveryExtension] - 00158D0001FF8F6A: DISCOVERY Extension: Adding discoverer for added node
2019-12-07 00:54:05.932 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: created discoverer
2019-12-07 00:54:05.932 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: start discovery
2019-12-07 00:54:05.933 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: starting new tasks [ACTIVE_ENDPOINTS, POWER_DESCRIPTOR, NWK_ADDRESS, NODE_DESCRIPTOR]
2019-12-07 00:54:05.933 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: scheduled [ACTIVE_ENDPOINTS, POWER_DESCRIPTOR, NWK_ADDRESS, NODE_DESCRIPTOR]
2019-12-07 00:54:06.179 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 00158D0001FF8F6A: Data store: Writing node.
2019-12-07 00:54:06.183 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 00158D0001FF8F6A: ZigBee saving network state complete.
2019-12-07 00:54:06.316 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [newNodeId=58947, newNodeEui64=00158D0001FF8F6A, status=EMBER_STANDARD_SECURITY_UNSECURED_JOIN, policyDecision=EMBER_USE_PRECONFIGURED_KEY, parentOfNewNodeId=0]
2019-12-07 00:54:06.317 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: nodeStatusUpdate - node status is UNSECURED_JOIN, network address is 58947.
2019-12-07 00:54:06.317 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D0001FF8F6A: Device status updated. NWK=58947
2019-12-07 00:54:06.317 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D0001FF8F6A: NWK Discovery add node 58947
2019-12-07 00:54:06.318 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00158D0001FF8F6A: Node state updated from UNKNOWN to ONLINE
2019-12-07 00:54:06.318 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Updating node NWK=58947
2019-12-07 00:54:06.318 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Node 58947 update
2019-12-07 00:54:06.319 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Node 58947 is not updated
2019-12-07 00:54:06.509 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=14815, apsFrame=EmberApsFrame [profileId=260, clusterId=0, sourceEndpoint=1, destinationEndpoint=3, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=BC], messageTag=41, status=EMBER_DELIVERY_FAILED, messageContents=]
2019-12-07 00:54:06.511 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=41 state=RX_NAK
2019-12-07 00:54:06.511 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=41, state=RX_NAK, outstanding=2
2019-12-07 00:54:06.512 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=4791, state=FAILED, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 14815/3, cluster=0000, TID=41, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-07 00:54:06.513 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2019-12-07 00:54:06.513 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A002E4F: transactionComplete FAILED 0
2019-12-07 00:54:06.514 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A002E4F: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=4793, state=WAITING, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 14815/3, cluster=0000, TID=41, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-07 00:54:06.514 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 41 -> RX_NAK == WAITING
2019-12-07 00:54:06.633 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=37449, apsFrame=EmberApsFrame [profileId=260, clusterId=0, sourceEndpoint=1, destinationEndpoint=3, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=BE], messageTag=43, status=EMBER_DELIVERY_FAILED, messageContents=]
2019-12-07 00:54:06.633 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=43 state=RX_NAK
2019-12-07 00:54:06.634 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=43, state=RX_NAK, outstanding=1
2019-12-07 00:54:06.635 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=4903, state=FAILED, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 37449/3, cluster=0000, TID=43, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-07 00:54:06.635 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2019-12-07 00:54:06.635 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA00B286AC: transactionComplete FAILED 0
2019-12-07 00:54:06.636 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA00B286AC: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=4905, state=WAITING, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 37449/3, cluster=0000, TID=43, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-07 00:54:06.636 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 43 -> RX_NAK == WAITING
2019-12-07 00:54:08.023 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: running ACTIVE_ENDPOINTS
2019-12-07 00:54:08.025 [DEBUG] [transaction.ZigBeeTransactionManager] - 00158D0001FF8F6A: Creating new Transaction Queue
2019-12-07 00:54:08.026 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Set profile to ZigBeeTransactionProfile [maxOutstandingTransactions=2, interTransactionDelay=50, maxRetries=2]
2019-12-07 00:54:08.028 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=--, nwkAddrOfInterest=58947]]
2019-12-07 00:54:08.029 [DEBUG] [transaction.ZigBeeTransactionManager] - 58947/0: Sending ZigBeeTransaction [queueTime=2, state=WAITING, sendCnt=0, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=44, nwkAddrOfInterest=58947]]
2019-12-07 00:54:08.030 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2019-12-07 00:54:08.031 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=44, nwkAddrOfInterest=58947]
2019-12-07 00:54:08.032 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=58947/0, profile=0000, cluster=0005, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=44, payload=00 43 E6]
2019-12-07 00:54:08.048 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=C0]
2019-12-07 00:54:08.142 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=58947, 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=C0], messageTag=44, status=EMBER_SUCCESS, messageContents=]
2019-12-07 00:54:08.143 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=44 state=RX_ACK
2019-12-07 00:54:08.144 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=44, state=RX_ACK, outstanding=1
2019-12-07 00:54:08.144 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 44 -> RX_ACK == ACKED
2019-12-07 00:54:09.352 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspChildJoinHandler [index=0, joining=true, childId=58947, childEui64=00158D0001FF8F6A, childType=EMBER_SLEEPY_END_DEVICE]
2019-12-07 00:54:09.352 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: nodeStatusUpdate - node status is UNSECURED_JOIN, network address is 58947.
2019-12-07 00:54:09.353 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D0001FF8F6A: Device status updated. NWK=58947
2019-12-07 00:54:09.354 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D0001FF8F6A: NWK Discovery add node 58947
2019-12-07 00:54:09.354 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00158D0001FF8F6A: Node state updated from UNKNOWN to ONLINE
2019-12-07 00:54:09.355 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Updating node NWK=58947
2019-12-07 00:54:09.355 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Node 58947 update
2019-12-07 00:54:09.359 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Node 58947 is not updated
2019-12-07 00:54:09.849 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [newNodeId=58947, newNodeEui64=00158D0001FF8F6A, status=EMBER_STANDARD_SECURITY_UNSECURED_JOIN, policyDecision=EMBER_USE_PRECONFIGURED_KEY, parentOfNewNodeId=0]
2019-12-07 00:54:09.850 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: nodeStatusUpdate - node status is UNSECURED_JOIN, network address is 58947.
2019-12-07 00:54:09.850 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D0001FF8F6A: Device status updated. NWK=58947
2019-12-07 00:54:09.852 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D0001FF8F6A: NWK Discovery add node 58947
2019-12-07 00:54:09.852 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00158D0001FF8F6A: Node state updated from UNKNOWN to ONLINE
2019-12-07 00:54:09.853 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Updating node NWK=58947
2019-12-07 00:54:09.854 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Node 58947 update
2019-12-07 00:54:09.854 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Node 58947 is not updated
2019-12-07 00:54:13.726 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 7CB03EAA0A002E4F: ZigBee node property discovery using OTA cluster on endpoint 14815/3
2019-12-07 00:54:13.727 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 7CB03EAA0A002E4F: ZigBee node property discovery complete: {zigbee_logicaltype=ROUTER, zigbee_powerlevel=FULL, zigbee_manufacturercode=0xbbaa, modelId=Plug 01, zigbee_networkaddress=14815, zigbee_powersource=MAINS, zigbee_stkversion=2, zigbee_datecode=20140331DEOS****, zigbee_zclversion=1, vendor=OSRAM, zigbee_powermode=RECEIVER_ON_IDLE, zigbee_powersources=[RECHARGABLE_BATTERY, MAINS, DISPOSABLE_BATTERY], hardwareVersion=1, firmwareVersion=0x01020412, zigbee_applicationVersion=12}
2019-12-07 00:54:13.727 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 7CB03EAA0A002E4F: Update ZigBee device zigbee:device with bridge zigbee:coordinator_ember:cc9950e6, label 'OSRAM Plug 01'
2019-12-07 00:54:13.728 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 7CB03EAA0A002E4F: Data store: Deferring write for 250ms.
2019-12-07 00:54:13.736 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 7CB03EAA00B286AC: ZigBee node property discovery using OTA cluster on endpoint 37449/3
2019-12-07 00:54:13.737 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 7CB03EAA00B286AC: ZigBee node property discovery complete: {zigbee_logicaltype=ROUTER, zigbee_powerlevel=FULL, zigbee_manufacturercode=0xbbaa, modelId=Plug 01, zigbee_networkaddress=37449, zigbee_powersource=MAINS, zigbee_stkversion=2, zigbee_datecode=20140331DEOS****, zigbee_zclversion=1, vendor=OSRAM, zigbee_powermode=RECEIVER_ON_IDLE, zigbee_powersources=[RECHARGABLE_BATTERY, MAINS, DISPOSABLE_BATTERY], hardwareVersion=1, firmwareVersion=0x01020412, zigbee_applicationVersion=12}
2019-12-07 00:54:13.737 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 7CB03EAA00B286AC: Update ZigBee device zigbee:device with bridge zigbee:coordinator_ember:cc9950e6, label 'OSRAM Plug 01'
2019-12-07 00:54:13.738 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 7CB03EAA00B286AC: Data store: Deferring write for 250ms.
2019-12-07 00:54:13.980 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 7CB03EAA0A002E4F: Data store: Writing node.
2019-12-07 00:54:14.013 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 7CB03EAA0A002E4F: ZigBee saving network state complete.
2019-12-07 00:54:14.029 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 7CB03EAA00B286AC: Data store: Writing node.
2019-12-07 00:54:14.075 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 7CB03EAA00B286AC: ZigBee saving network state complete.
2019-12-07 00:54:18.032 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=10005, state=FAILED, sendCnt=1, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=44, nwkAddrOfInterest=58947]]
2019-12-07 00:54:18.032 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2019-12-07 00:54:18.033 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete FAILED 0
2019-12-07 00:54:18.033 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=10006, state=WAITING, sendCnt=1, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=44, nwkAddrOfInterest=58947]]
2019-12-07 00:54:20.033 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: ActiveEndpointsResponse returned CommandResult [TIMEOUT]
2019-12-07 00:54:20.033 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: request ACTIVE_ENDPOINTS failed. Retry 1, wait 2178ms before retry.
2019-12-07 00:54:22.213 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: running ACTIVE_ENDPOINTS
2019-12-07 00:54:22.213 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=--, nwkAddrOfInterest=58947]]
2019-12-07 00:54:22.214 [DEBUG] [transaction.ZigBeeTransactionManager] - 58947/0: Sending ZigBeeTransaction [queueTime=14187, state=WAITING, sendCnt=1, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=44, nwkAddrOfInterest=58947]]
2019-12-07 00:54:22.214 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2019-12-07 00:54:22.215 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=44, nwkAddrOfInterest=58947]
2019-12-07 00:54:22.215 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=58947/0, profile=0000, cluster=0005, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=45, payload=00 43 E6]
2019-12-07 00:54:22.228 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=C2]
2019-12-07 00:54:22.265 [DEBUG] [transaction.ZigBeeTransactionManager] - 58947/0: Sending ZigBeeTransaction [queueTime=52, state=WAITING, sendCnt=0, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=45, nwkAddrOfInterest=58947]]
2019-12-07 00:54:22.265 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2019-12-07 00:54:22.266 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=45, nwkAddrOfInterest=58947]
2019-12-07 00:54:22.266 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=58947/0, profile=0000, cluster=0005, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=46, payload=00 43 E6]
2019-12-07 00:54:22.278 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=C3]
2019-12-07 00:54:23.127 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspChildJoinHandler [index=0, joining=true, childId=58947, childEui64=00158D0001FF8F6A, childType=EMBER_SLEEPY_END_DEVICE]
2019-12-07 00:54:23.128 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: nodeStatusUpdate - node status is UNSECURED_JOIN, network address is 58947.
2019-12-07 00:54:23.128 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D0001FF8F6A: Device status updated. NWK=58947
2019-12-07 00:54:23.129 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D0001FF8F6A: NWK Discovery add node 58947
2019-12-07 00:54:23.130 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00158D0001FF8F6A: Node state updated from UNKNOWN to ONLINE
2019-12-07 00:54:23.130 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Updating node NWK=58947
2019-12-07 00:54:23.131 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Node 58947 update
2019-12-07 00:54:23.132 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Node 58947 is not updated
2019-12-07 00:54:23.628 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [newNodeId=58947, newNodeEui64=00158D0001FF8F6A, status=EMBER_STANDARD_SECURITY_UNSECURED_JOIN, policyDecision=EMBER_USE_PRECONFIGURED_KEY, parentOfNewNodeId=0]
2019-12-07 00:54:23.629 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: nodeStatusUpdate - node status is UNSECURED_JOIN, network address is 58947.
2019-12-07 00:54:23.629 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D0001FF8F6A: Device status updated. NWK=58947
2019-12-07 00:54:23.629 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D0001FF8F6A: NWK Discovery add node 58947
2019-12-07 00:54:23.630 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00158D0001FF8F6A: Node state updated from UNKNOWN to ONLINE
2019-12-07 00:54:23.630 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Updating node NWK=58947
2019-12-07 00:54:23.630 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Node 58947 update
2019-12-07 00:54:23.631 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Node 58947 is not updated
2019-12-07 00:54:23.876 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=58947, 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=C2], messageTag=44, status=EMBER_SUCCESS, messageContents=]
2019-12-07 00:54:23.894 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=44 state=RX_ACK
2019-12-07 00:54:23.896 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=44, state=RX_ACK, outstanding=2
2019-12-07 00:54:23.898 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 44 -> RX_ACK == ACKED
2019-12-07 00:54:24.073 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=58947, 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=C3], messageTag=45, status=EMBER_SUCCESS, messageContents=]
2019-12-07 00:54:24.074 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=45 state=RX_ACK
2019-12-07 00:54:24.075 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=45, state=RX_ACK, outstanding=2
2019-12-07 00:54:24.075 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 45 -> RX_ACK == ACKED
2019-12-07 00:54:26.676 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspChildJoinHandler [index=0, joining=true, childId=58947, childEui64=00158D0001FF8F6A, childType=EMBER_SLEEPY_END_DEVICE]
2019-12-07 00:54:26.677 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: nodeStatusUpdate - node status is UNSECURED_JOIN, network address is 58947.
2019-12-07 00:54:26.678 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D0001FF8F6A: Device status updated. NWK=58947
2019-12-07 00:54:26.678 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D0001FF8F6A: NWK Discovery add node 58947
2019-12-07 00:54:26.679 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00158D0001FF8F6A: Node state updated from UNKNOWN to ONLINE
2019-12-07 00:54:26.680 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Updating node NWK=58947
2019-12-07 00:54:26.681 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Node 58947 update
2019-12-07 00:54:26.681 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Node 58947 is not updated
2019-12-07 00:54:27.176 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [newNodeId=58947, newNodeEui64=00158D0001FF8F6A, status=EMBER_STANDARD_SECURITY_UNSECURED_JOIN, policyDecision=EMBER_USE_PRECONFIGURED_KEY, parentOfNewNodeId=0]
2019-12-07 00:54:27.176 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: nodeStatusUpdate - node status is UNSECURED_JOIN, network address is 58947.
2019-12-07 00:54:27.176 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D0001FF8F6A: Device status updated. NWK=58947
2019-12-07 00:54:27.177 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D0001FF8F6A: NWK Discovery add node 58947
2019-12-07 00:54:27.178 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00158D0001FF8F6A: Node state updated from UNKNOWN to ONLINE
2019-12-07 00:54:27.178 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Updating node NWK=58947
2019-12-07 00:54:27.179 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Node 58947 update
2019-12-07 00:54:27.180 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Node 58947 is not updated
2019-12-07 00:54:32.215 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=24188, state=FAILED, sendCnt=2, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=44, nwkAddrOfInterest=58947]]
2019-12-07 00:54:32.215 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2019-12-07 00:54:32.216 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete FAILED 1
2019-12-07 00:54:32.217 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete exceeded retries 2
2019-12-07 00:54:32.217 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=24190, state=FAILED, sendCnt=2, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=44, nwkAddrOfInterest=58947]]
2019-12-07 00:54:32.265 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=10052, state=FAILED, sendCnt=1, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=45, nwkAddrOfInterest=58947]]
2019-12-07 00:54:32.265 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2019-12-07 00:54:32.266 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete FAILED 0
2019-12-07 00:54:32.266 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=10053, state=WAITING, sendCnt=1, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=45, nwkAddrOfInterest=58947]]
2019-12-07 00:54:34.216 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: ActiveEndpointsResponse returned CommandResult [TIMEOUT]
2019-12-07 00:54:34.216 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: request ACTIVE_ENDPOINTS failed. Retry 2, wait 2178ms before retry.
2019-12-07 00:54:34.238 [INFO ] [pse.smarthome.model.script.AstroRule] - Calculated projected angle: -61.35685479669296
2019-12-07 00:54:34.239 [INFO ] [pse.smarthome.model.script.AstroRule] - Calculated projected angle: Less than 0
2019-12-07 00:54:34.240 [INFO ] [pse.smarthome.model.script.AstroRule] - Calculated projected angle for facade 1: -1.0E-4
2019-12-07 00:54:34.248 [INFO ] [e.smarthome.model.script.PowerInput4] - PowerInput4 set to 0
2019-12-07 00:54:34.251 [INFO ] [pse.smarthome.model.script.AstroRule] - Calculated projected angle: -89.39381069908008
2019-12-07 00:54:34.253 [INFO ] [pse.smarthome.model.script.AstroRule] - Calculated projected angle: Less than 0
2019-12-07 00:54:34.254 [INFO ] [pse.smarthome.model.script.AstroRule] - Calculated projected angle for facade 2: -1.0E-4
2019-12-07 00:54:34.262 [INFO ] [pse.smarthome.model.script.AstroRule] - Calculated projected angle: 61.35685479669296
2019-12-07 00:54:34.263 [INFO ] [e.smarthome.model.script.PowerInput1] - PowerInput1 set to 0
2019-12-07 00:54:34.264 [INFO ] [pse.smarthome.model.script.AstroRule] - Calculated projected angle for facade 3: 61.35685479669296
2019-12-07 00:54:34.269 [INFO ] [pse.smarthome.model.script.AstroRule] - Calculated projected angle: 89.39381069908008
2019-12-07 00:54:34.271 [INFO ] [e.smarthome.model.script.PowerInput2] - PowerInput2 set to 0
2019-12-07 00:54:34.271 [INFO ] [pse.smarthome.model.script.AstroRule] - Calculated projected angle for facade 4: 89.39381069908008
2019-12-07 00:54:34.278 [INFO ] [e.smarthome.model.script.PowerInput3] - PowerInput3 set to 0
2019-12-07 00:54:36.394 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: running ACTIVE_ENDPOINTS
2019-12-07 00:54:36.394 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=--, nwkAddrOfInterest=58947]]
2019-12-07 00:54:36.395 [DEBUG] [transaction.ZigBeeTransactionManager] - 58947/0: Sending ZigBeeTransaction [queueTime=14182, state=WAITING, sendCnt=1, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=45, nwkAddrOfInterest=58947]]
2019-12-07 00:54:36.395 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2019-12-07 00:54:36.396 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=45, nwkAddrOfInterest=58947]
2019-12-07 00:54:36.396 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=58947/0, profile=0000, cluster=0005, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=47, payload=00 43 E6]
2019-12-07 00:54:36.410 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=C6]
2019-12-07 00:54:36.446 [DEBUG] [transaction.ZigBeeTransactionManager] - 58947/0: Sending ZigBeeTransaction [queueTime=52, state=WAITING, sendCnt=0, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=46, nwkAddrOfInterest=58947]]
2019-12-07 00:54:36.446 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2019-12-07 00:54:36.447 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=46, nwkAddrOfInterest=58947]
2019-12-07 00:54:36.447 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=58947/0, profile=0000, cluster=0005, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=48, payload=00 43 E6]
2019-12-07 00:54:36.461 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=C7]
2019-12-07 00:54:40.452 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspChildJoinHandler [index=0, joining=true, childId=58947, childEui64=00158D0001FF8F6A, childType=EMBER_SLEEPY_END_DEVICE]
2019-12-07 00:54:40.452 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: nodeStatusUpdate - node status is UNSECURED_JOIN, network address is 58947.
2019-12-07 00:54:40.453 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D0001FF8F6A: Device status updated. NWK=58947
2019-12-07 00:54:40.454 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D0001FF8F6A: NWK Discovery add node 58947
2019-12-07 00:54:40.455 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00158D0001FF8F6A: Node state updated from UNKNOWN to ONLINE
2019-12-07 00:54:40.455 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Updating node NWK=58947
2019-12-07 00:54:40.455 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Node 58947 update
2019-12-07 00:54:40.456 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Node 58947 is not updated
2019-12-07 00:54:40.955 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [newNodeId=58947, newNodeEui64=00158D0001FF8F6A, status=EMBER_STANDARD_SECURITY_UNSECURED_JOIN, policyDecision=EMBER_USE_PRECONFIGURED_KEY, parentOfNewNodeId=0]
2019-12-07 00:54:40.956 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: nodeStatusUpdate - node status is UNSECURED_JOIN, network address is 58947.
2019-12-07 00:54:40.958 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D0001FF8F6A: Device status updated. NWK=58947
2019-12-07 00:54:40.959 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D0001FF8F6A: NWK Discovery add node 58947
2019-12-07 00:54:40.960 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00158D0001FF8F6A: Node state updated from UNKNOWN to ONLINE
2019-12-07 00:54:40.960 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Updating node NWK=58947
2019-12-07 00:54:40.961 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Node 58947 update
2019-12-07 00:54:40.961 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Node 58947 is not updated
2019-12-07 00:54:41.199 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=58947, 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=C6], messageTag=45, status=EMBER_SUCCESS, messageContents=]
2019-12-07 00:54:41.200 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=45 state=RX_ACK
2019-12-07 00:54:41.201 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=45, state=RX_ACK, outstanding=2
2019-12-07 00:54:41.202 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 45 -> RX_ACK == ACKED
2019-12-07 00:54:41.395 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=58947, 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=C7], messageTag=46, status=EMBER_SUCCESS, messageContents=]
2019-12-07 00:54:41.396 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=46 state=RX_ACK
2019-12-07 00:54:41.397 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=46, state=RX_ACK, outstanding=2
2019-12-07 00:54:41.398 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 46 -> RX_ACK == ACKED
2019-12-07 00:54:43.998 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspChildJoinHandler [index=0, joining=true, childId=58947, childEui64=00158D0001FF8F6A, childType=EMBER_SLEEPY_END_DEVICE]
2019-12-07 00:54:43.999 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: nodeStatusUpdate - node status is UNSECURED_JOIN, network address is 58947.
2019-12-07 00:54:43.999 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D0001FF8F6A: Device status updated. NWK=58947
2019-12-07 00:54:44.000 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D0001FF8F6A: NWK Discovery add node 58947
2019-12-07 00:54:44.001 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00158D0001FF8F6A: Node state updated from UNKNOWN to ONLINE
2019-12-07 00:54:44.002 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Updating node NWK=58947
2019-12-07 00:54:44.002 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Node 58947 update
2019-12-07 00:54:44.003 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Node 58947 is not updated
2019-12-07 00:54:44.497 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [newNodeId=58947, newNodeEui64=00158D0001FF8F6A, status=EMBER_STANDARD_SECURITY_UNSECURED_JOIN, policyDecision=EMBER_USE_PRECONFIGURED_KEY, parentOfNewNodeId=0]
2019-12-07 00:54:44.498 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: nodeStatusUpdate - node status is UNSECURED_JOIN, network address is 58947.
2019-12-07 00:54:44.499 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D0001FF8F6A: Device status updated. NWK=58947
2019-12-07 00:54:44.500 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D0001FF8F6A: NWK Discovery add node 58947
2019-12-07 00:54:44.501 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00158D0001FF8F6A: Node state updated from UNKNOWN to ONLINE
2019-12-07 00:54:44.501 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Updating node NWK=58947
2019-12-07 00:54:44.502 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Node 58947 update
2019-12-07 00:54:44.503 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Node 58947 is not updated
2019-12-07 00:54:46.448 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=10054, state=FAILED, sendCnt=1, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=46, nwkAddrOfInterest=58947]]
2019-12-07 00:54:46.448 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2019-12-07 00:54:46.449 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete FAILED 1
2019-12-07 00:54:46.449 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=10055, state=WAITING, sendCnt=1, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=46, nwkAddrOfInterest=58947]]
2019-12-07 00:54:46.397 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=24184, state=FAILED, sendCnt=2, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=45, nwkAddrOfInterest=58947]]
2019-12-07 00:54:46.513 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2019-12-07 00:54:46.514 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete FAILED 0
2019-12-07 00:54:46.514 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete exceeded retries 2
2019-12-07 00:54:46.515 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=24301, state=FAILED, sendCnt=2, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=45, nwkAddrOfInterest=58947]]
2019-12-07 00:54:48.398 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: ActiveEndpointsResponse returned CommandResult [TIMEOUT]
2019-12-07 00:54:48.398 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: request ACTIVE_ENDPOINTS failed. Retry 3, wait 6534ms before retry.
2019-12-07 00:54:54.296 [INFO ] [el.script.Temp_Outside_MinMaxAverage] - I_Geb_OutsideTemp24HMin set to -3.8000000000000003
2019-12-07 00:54:54.345 [INFO ] [el.script.Temp_Outside_MinMaxAverage] - I_Geb_OutsideTemp24HMax set to 5.9
2019-12-07 00:54:54.377 [INFO ] [el.script.Temp_Outside_MinMaxAverage] - I_Geb_OutsideTemp24HAvg set to 0.5323675479477700
2019-12-07 00:54:54.933 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: running ACTIVE_ENDPOINTS
2019-12-07 00:54:54.933 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=--, nwkAddrOfInterest=58947]]
2019-12-07 00:54:54.934 [DEBUG] [transaction.ZigBeeTransactionManager] - 58947/0: Sending ZigBeeTransaction [queueTime=18540, state=WAITING, sendCnt=1, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=46, nwkAddrOfInterest=58947]]
2019-12-07 00:54:54.934 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2019-12-07 00:54:54.934 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=46, nwkAddrOfInterest=58947]
2019-12-07 00:54:54.935 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=58947/0, profile=0000, cluster=0005, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=49, payload=00 43 E6]
2019-12-07 00:54:54.946 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=CA]
2019-12-07 00:54:54.985 [DEBUG] [transaction.ZigBeeTransactionManager] - 58947/0: Sending ZigBeeTransaction [queueTime=52, state=WAITING, sendCnt=0, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=47, nwkAddrOfInterest=58947]]
2019-12-07 00:54:54.985 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2019-12-07 00:54:54.986 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=47, nwkAddrOfInterest=58947]
2019-12-07 00:54:54.987 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=58947/0, profile=0000, cluster=0005, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=4A, payload=00 43 E6]
2019-12-07 00:54:55.000 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=CB]
2019-12-07 00:54:57.773 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspChildJoinHandler [index=0, joining=true, childId=58947, childEui64=00158D0001FF8F6A, childType=EMBER_SLEEPY_END_DEVICE]
2019-12-07 00:54:57.774 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: nodeStatusUpdate - node status is UNSECURED_JOIN, network address is 58947.
2019-12-07 00:54:57.774 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D0001FF8F6A: Device status updated. NWK=58947
2019-12-07 00:54:57.774 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D0001FF8F6A: NWK Discovery add node 58947
2019-12-07 00:54:57.775 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00158D0001FF8F6A: Node state updated from UNKNOWN to ONLINE
2019-12-07 00:54:57.775 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Updating node NWK=58947
2019-12-07 00:54:57.776 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Node 58947 update
2019-12-07 00:54:57.776 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Node 58947 is not updated
2019-12-07 00:54:58.272 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [newNodeId=58947, newNodeEui64=00158D0001FF8F6A, status=EMBER_STANDARD_SECURITY_UNSECURED_JOIN, policyDecision=EMBER_USE_PRECONFIGURED_KEY, parentOfNewNodeId=0]
2019-12-07 00:54:58.273 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: nodeStatusUpdate - node status is UNSECURED_JOIN, network address is 58947.
2019-12-07 00:54:58.274 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D0001FF8F6A: Device status updated. NWK=58947
2019-12-07 00:54:58.274 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D0001FF8F6A: NWK Discovery add node 58947
2019-12-07 00:54:58.275 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00158D0001FF8F6A: Node state updated from UNKNOWN to ONLINE
2019-12-07 00:54:58.276 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Updating node NWK=58947
2019-12-07 00:54:58.276 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Node 58947 update
2019-12-07 00:54:58.277 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Node 58947 is not updated
2019-12-07 00:54:58.520 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=58947, 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=CA], messageTag=46, status=EMBER_SUCCESS, messageContents=]
2019-12-07 00:54:58.521 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=46 state=RX_ACK
2019-12-07 00:54:58.522 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=46, state=RX_ACK, outstanding=2
2019-12-07 00:54:58.522 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 46 -> RX_ACK == ACKED
2019-12-07 00:54:58.717 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=58947, 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=CB], messageTag=47, status=EMBER_SUCCESS, messageContents=]
2019-12-07 00:54:58.718 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=47 state=RX_ACK
2019-12-07 00:54:58.718 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=47, state=RX_ACK, outstanding=2
2019-12-07 00:54:58.719 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 47 -> RX_ACK == ACKED
2019-12-07 00:55:01.320 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspChildJoinHandler [index=0, joining=true, childId=58947, childEui64=00158D0001FF8F6A, childType=EMBER_SLEEPY_END_DEVICE]
2019-12-07 00:55:01.321 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: nodeStatusUpdate - node status is UNSECURED_JOIN, network address is 58947.
2019-12-07 00:55:01.321 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D0001FF8F6A: Device status updated. NWK=58947
2019-12-07 00:55:01.322 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D0001FF8F6A: NWK Discovery add node 58947
2019-12-07 00:55:01.322 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00158D0001FF8F6A: Node state updated from UNKNOWN to ONLINE
2019-12-07 00:55:01.323 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Updating node NWK=58947
2019-12-07 00:55:01.323 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Node 58947 update
2019-12-07 00:55:01.324 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Node 58947 is not updated
2019-12-07 00:55:01.820 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [newNodeId=58947, newNodeEui64=00158D0001FF8F6A, status=EMBER_STANDARD_SECURITY_UNSECURED_JOIN, policyDecision=EMBER_USE_PRECONFIGURED_KEY, parentOfNewNodeId=0]
2019-12-07 00:55:01.820 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: nodeStatusUpdate - node status is UNSECURED_JOIN, network address is 58947.
2019-12-07 00:55:01.821 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D0001FF8F6A: Device status updated. NWK=58947
2019-12-07 00:55:01.822 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D0001FF8F6A: NWK Discovery add node 58947
2019-12-07 00:55:01.823 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00158D0001FF8F6A: Node state updated from UNKNOWN to ONLINE
2019-12-07 00:55:01.823 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Updating node NWK=58947
2019-12-07 00:55:01.824 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Node 58947 update
2019-12-07 00:55:01.825 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D0001FF8F6A: Node 58947 is not updated
2019-12-07 00:55:02.754 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_BROADCAST_LOOPBACK, apsFrame=EmberApsFrame [profileId=0, clusterId=1, sourceEndpoint=0, destinationEndpoint=0, options=[], groupId=0, sequence=CE], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=81 DF 39 00 00]
2019-12-07 00:55:02.755 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0001, addressMode=null, radius=0, apsSecurity=false, apsCounter=CE, payload=81 DF 39 00 00]
2019-12-07 00:55:02.755 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: IeeeAddressRequest [0/0 -> 0/0, cluster=0001, TID=--, nwkAddrOfInterest=14815, requestType=0, startIndex=0]
2019-12-07 00:55:02.756 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: IeeeAddressRequest [0/0 -> 0/0, cluster=0001, TID=--, nwkAddrOfInterest=14815, requestType=0, startIndex=0] 
2019-12-07 00:55:02.756 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: IeeeAddressRequest [0/0 -> 0/0, cluster=0001, TID=--, nwkAddrOfInterest=14815, requestType=0, startIndex=0] ZigBeeTransaction [queueTime=26362, state=ACKED, sendCnt=2, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=46, nwkAddrOfInterest=58947]]
2019-12-07 00:55:02.756 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: IeeeAddressRequest [0/0 -> 0/0, cluster=0001, TID=--, nwkAddrOfInterest=14815, requestType=0, startIndex=0] ZigBeeTransaction [queueTime=7823, state=ACKED, sendCnt=1, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=47, nwkAddrOfInterest=58947]]
2019-12-07 00:55:02.842 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteRecordHandler [source=14815, sourceEui=7CB03EAA0A002E4F, lastHopLqi=255, lastHopRssi=-67, relayList=5CEC]
2019-12-07 00:55:02.874 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=32769, sourceEndpoint=0, destinationEndpoint=0, options=[], groupId=0, sequence=5E], lastHopLqi=255, lastHopRssi=-68, sender=14815, bindingIndex=255, addressIndex=255, messageContents=81 00 4F 2E 00 0A AA 3E B0 7C DF 39]
2019-12-07 00:55:02.874 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=14815/0, destinationAddress=0/0, profile=0000, cluster=8001, addressMode=null, radius=0, apsSecurity=false, apsCounter=5E, payload=81 00 4F 2E 00 0A AA 3E B0 7C DF 39]
2019-12-07 00:55:02.875 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: IeeeAddressResponse [14815/0 -> 0/0, cluster=8001, TID=--, status=SUCCESS, ieeeAddrRemoteDev=7CB03EAA0A002E4F, nwkAddrRemoteDev=14815, startIndex=null, nwkAddrAssocDevList=[]]
2019-12-07 00:55:02.876 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: IeeeAddressResponse [14815/0 -> 0/0, cluster=8001, TID=--, status=SUCCESS, ieeeAddrRemoteDev=7CB03EAA0A002E4F, nwkAddrRemoteDev=14815, startIndex=null, nwkAddrAssocDevList=[]] 
2019-12-07 00:55:02.876 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: IeeeAddressResponse [14815/0 -> 0/0, cluster=8001, TID=--, status=SUCCESS, ieeeAddrRemoteDev=7CB03EAA0A002E4F, nwkAddrRemoteDev=14815, startIndex=null, nwkAddrAssocDevList=[]] ZigBeeTransaction [queueTime=26482, state=ACKED, sendCnt=2, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=46, nwkAddrOfInterest=58947]]
2019-12-07 00:55:02.877 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: IeeeAddressResponse [14815/0 -> 0/0, cluster=8001, TID=--, status=SUCCESS, ieeeAddrRemoteDev=7CB03EAA0A002E4F, nwkAddrRemoteDev=14815, startIndex=null, nwkAddrAssocDevList=[]] ZigBeeTransaction [queueTime=7944, state=ACKED, sendCnt=1, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=47, nwkAddrOfInterest=58947]]
2019-12-07 00:55:04.935 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=28541, state=FAILED, sendCnt=2, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=46, nwkAddrOfInterest=58947]]
2019-12-07 00:55:04.935 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2019-12-07 00:55:04.936 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete FAILED 1
2019-12-07 00:55:04.936 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete exceeded retries 2
2019-12-07 00:55:04.936 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=28542, state=FAILED, sendCnt=2, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=46, nwkAddrOfInterest=58947]]
2019-12-07 00:55:04.986 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=10053, state=FAILED, sendCnt=1, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=47, nwkAddrOfInterest=58947]]
2019-12-07 00:55:04.986 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2019-12-07 00:55:04.987 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete FAILED 0
2019-12-07 00:55:04.988 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=10054, state=WAITING, sendCnt=1, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=47, nwkAddrOfInterest=58947]]
2019-12-07 00:55:06.937 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: ActiveEndpointsResponse returned CommandResult [TIMEOUT]
2019-12-07 00:55:06.938 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: request ACTIVE_ENDPOINTS failed. Retry 4, wait 10890ms before retry.
2019-12-07 00:55:17.830 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: running ACTIVE_ENDPOINTS
2019-12-07 00:55:17.831 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=--, nwkAddrOfInterest=58947]]
2019-12-07 00:55:17.832 [DEBUG] [transaction.ZigBeeTransactionManager] - 58947/0: Sending ZigBeeTransaction [queueTime=22899, state=WAITING, sendCnt=1, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=47, nwkAddrOfInterest=58947]]
2019-12-07 00:55:17.839 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2019-12-07 00:55:17.840 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=47, nwkAddrOfInterest=58947]
2019-12-07 00:55:17.841 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=58947/0, profile=0000, cluster=0005, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=4B, payload=00 43 E6]
2019-12-07 00:55:17.852 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=CF]
2019-12-07 00:55:17.882 [DEBUG] [transaction.ZigBeeTransactionManager] - 58947/0: Sending ZigBeeTransaction [queueTime=51, state=WAITING, sendCnt=0, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=48, nwkAddrOfInterest=58947]]
2019-12-07 00:55:17.882 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2019-12-07 00:55:17.883 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=48, nwkAddrOfInterest=58947]
2019-12-07 00:55:17.883 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=58947/0, profile=0000, cluster=0005, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=4C, payload=00 43 E6]
2019-12-07 00:55:17.893 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=D0]
2019-12-07 00:55:25.360 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=58947]
2019-12-07 00:55:25.403 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=58947]
2019-12-07 00:55:27.841 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=32908, state=FAILED, sendCnt=2, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=47, nwkAddrOfInterest=58947]]
2019-12-07 00:55:27.842 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2019-12-07 00:55:27.842 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete FAILED 1
2019-12-07 00:55:27.843 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete exceeded retries 2
2019-12-07 00:55:27.843 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=32910, state=FAILED, sendCnt=2, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=47, nwkAddrOfInterest=58947]]
2019-12-07 00:55:27.883 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=10052, state=FAILED, sendCnt=1, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=48, nwkAddrOfInterest=58947]]
2019-12-07 00:55:27.884 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2019-12-07 00:55:27.884 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete FAILED 0
2019-12-07 00:55:27.885 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=10054, state=WAITING, sendCnt=1, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=48, nwkAddrOfInterest=58947]]
2019-12-07 00:55:29.842 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: ActiveEndpointsResponse returned CommandResult [TIMEOUT]
2019-12-07 00:55:29.842 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: request ACTIVE_ENDPOINTS failed. Retry 5, wait 8712ms before retry.
2019-12-07 00:55:34.433 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=58947]
2019-12-07 00:55:34.475 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=58947]
2019-12-07 00:55:38.557 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: running ACTIVE_ENDPOINTS
2019-12-07 00:55:38.557 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=--, nwkAddrOfInterest=58947]]
2019-12-07 00:55:38.558 [DEBUG] [transaction.ZigBeeTransactionManager] - 58947/0: Sending ZigBeeTransaction [queueTime=20727, state=WAITING, sendCnt=1, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=48, nwkAddrOfInterest=58947]]
2019-12-07 00:55:38.558 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2019-12-07 00:55:38.559 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=48, nwkAddrOfInterest=58947]
2019-12-07 00:55:38.559 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=58947/0, profile=0000, cluster=0005, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=4D, payload=00 43 E6]
2019-12-07 00:55:38.570 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=D1]
2019-12-07 00:55:38.609 [DEBUG] [transaction.ZigBeeTransactionManager] - 58947/0: Sending ZigBeeTransaction [queueTime=52, state=WAITING, sendCnt=0, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=49, nwkAddrOfInterest=58947]]
2019-12-07 00:55:38.610 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2019-12-07 00:55:38.611 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=49, nwkAddrOfInterest=58947]
2019-12-07 00:55:38.612 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=58947/0, profile=0000, cluster=0005, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=4E, payload=00 43 E6]
2019-12-07 00:55:38.623 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=D2]
2019-12-07 00:55:43.507 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=58947]
2019-12-07 00:55:43.547 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=58947]
2019-12-07 00:55:45.073 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=58947, 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=CF], messageTag=47, status=EMBER_DELIVERY_FAILED, messageContents=]
2019-12-07 00:55:45.073 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=47 state=RX_NAK
2019-12-07 00:55:45.074 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=47, state=RX_NAK, outstanding=2
2019-12-07 00:55:45.113 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=58947, 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=D0], messageTag=48, status=EMBER_DELIVERY_FAILED, messageContents=]
2019-12-07 00:55:45.113 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=48 state=RX_NAK
2019-12-07 00:55:45.114 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=48, state=RX_NAK, outstanding=2
2019-12-07 00:55:45.115 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=27284, state=FAILED, sendCnt=2, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=48, nwkAddrOfInterest=58947]]
2019-12-07 00:55:45.115 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2019-12-07 00:55:45.115 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete FAILED 1
2019-12-07 00:55:45.116 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete exceeded retries 2
2019-12-07 00:55:45.116 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=27285, state=FAILED, sendCnt=2, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=48, nwkAddrOfInterest=58947]]
2019-12-07 00:55:45.116 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 48 -> RX_NAK == FAILED
2019-12-07 00:55:46.080 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=58947]
2019-12-07 00:55:46.139 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=58947]
2019-12-07 00:55:46.641 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=32824, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=D3], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00 00 F8 FF 07 18 00 07 00 10 AB CE AA AA B3 AD AD A7 AC B1 A6 AD AB AD AC AC]
2019-12-07 00:55:46.641 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=8038, addressMode=null, radius=0, apsSecurity=false, apsCounter=D3, payload=00 00 00 F8 FF 07 18 00 07 00 10 AB CE AA AA B3 AD AD A7 AC B1 A6 AD AB AD AC AC]
2019-12-07 00:55:46.643 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementNetworkUpdateNotify [0/0 -> 0/0, cluster=8038, TID=--, status=SUCCESS, scannedChannels=134215680, totalTransmissions=24, transmissionFailures=7, energyValues=[171, 206, 170, 170, 179, 173, 173, 167, 172, 177, 166, 173, 171, 173, 172, 172]]
2019-12-07 00:55:46.643 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementNetworkUpdateNotify [0/0 -> 0/0, cluster=8038, TID=--, status=SUCCESS, scannedChannels=134215680, totalTransmissions=24, transmissionFailures=7, energyValues=[171, 206, 170, 170, 179, 173, 173, 167, 172, 177, 166, 173, 171, 173, 172, 172]] 
2019-12-07 00:55:46.644 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementNetworkUpdateNotify [0/0 -> 0/0, cluster=8038, TID=--, status=SUCCESS, scannedChannels=134215680, totalTransmissions=24, transmissionFailures=7, energyValues=[171, 206, 170, 170, 179, 173, 173, 167, 172, 177, 166, 173, 171, 173, 172, 172]] ZigBeeTransaction [queueTime=8086, state=DISPATCHED, sendCnt=1, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=49, nwkAddrOfInterest=58947]]
2019-12-07 00:55:48.611 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=10054, state=FAILED, sendCnt=1, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=49, nwkAddrOfInterest=58947]]
2019-12-07 00:55:48.611 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2019-12-07 00:55:48.612 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete FAILED 0
2019-12-07 00:55:48.612 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=10055, state=WAITING, sendCnt=1, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=49, nwkAddrOfInterest=58947]]
2019-12-07 00:55:50.559 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: ActiveEndpointsResponse returned CommandResult [TIMEOUT]
2019-12-07 00:55:50.560 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: request ACTIVE_ENDPOINTS failed. Retry 6, wait 10890ms before retry.
2019-12-07 00:55:54.261 [INFO ] [el.script.Temp_Outside_MinMaxAverage] - I_Geb_OutsideTemp24HMin set to -3.8000000000000003
2019-12-07 00:55:54.318 [INFO ] [el.script.Temp_Outside_MinMaxAverage] - I_Geb_OutsideTemp24HMax set to 5.9
2019-12-07 00:55:54.345 [INFO ] [el.script.Temp_Outside_MinMaxAverage] - I_Geb_OutsideTemp24HAvg set to 0.5385166783661550
2019-12-07 00:55:55.153 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=58947]
2019-12-07 00:55:55.204 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=58947]
2019-12-07 00:56:01.452 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0001FF8F6A: Node SVC Discovery: running ACTIVE_ENDPOINTS
2019-12-07 00:56:01.453 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=--, nwkAddrOfInterest=58947]]
2019-12-07 00:56:01.453 [DEBUG] [transaction.ZigBeeTransactionManager] - 58947/0: Sending ZigBeeTransaction [queueTime=22896, state=WAITING, sendCnt=1, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=49, nwkAddrOfInterest=58947]]
2019-12-07 00:56:01.454 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2019-12-07 00:56:01.455 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=49, nwkAddrOfInterest=58947]
2019-12-07 00:56:01.455 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=58947/0, profile=0000, cluster=0005, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=4F, payload=00 43 E6]
2019-12-07 00:56:01.468 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=D4]
2019-12-07 00:56:01.504 [DEBUG] [transaction.ZigBeeTransactionManager] - 58947/0: Sending ZigBeeTransaction [queueTime=51, state=WAITING, sendCnt=0, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=4A, nwkAddrOfInterest=58947]]
2019-12-07 00:56:01.504 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2019-12-07 00:56:01.505 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=4A, nwkAddrOfInterest=58947]
2019-12-07 00:56:01.505 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=58947/0, profile=0000, cluster=0005, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=50, payload=00 43 E6]
2019-12-07 00:56:01.518 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=D5]
2019-12-07 00:56:04.224 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=58947]
2019-12-07 00:56:04.278 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=58947]
2019-12-07 00:56:05.793 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=58947, 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=D1], messageTag=48, status=EMBER_DELIVERY_FAILED, messageContents=]
2019-12-07 00:56:05.794 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=48 state=RX_NAK
2019-12-07 00:56:05.795 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=48, state=RX_NAK, outstanding=2
2019-12-07 00:56:05.846 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=58947, 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=D2], messageTag=49, status=EMBER_DELIVERY_FAILED, messageContents=]
2019-12-07 00:56:05.846 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=49 state=RX_NAK
2019-12-07 00:56:05.847 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=49, state=RX_NAK, outstanding=2
2019-12-07 00:56:05.849 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=27291, state=FAILED, sendCnt=2, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=49, nwkAddrOfInterest=58947]]
2019-12-07 00:56:05.850 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2019-12-07 00:56:05.850 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete FAILED 1
2019-12-07 00:56:05.851 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete exceeded retries 2
2019-12-07 00:56:05.851 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=27294, state=FAILED, sendCnt=2, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=49, nwkAddrOfInterest=58947]]
2019-12-07 00:56:05.852 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 49 -> RX_NAK == FAILED
2019-12-07 00:56:08.975 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=58947]
2019-12-07 00:56:09.028 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=58947]
2019-12-07 00:56:11.516 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=10063, state=FAILED, sendCnt=1, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=4A, nwkAddrOfInterest=58947]]
2019-12-07 00:56:11.517 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2019-12-07 00:56:11.518 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: transactionComplete FAILED 0
2019-12-07 00:56:11.518 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=10065, state=WAITING, sendCnt=1, command=ActiveEndpointsRequest [0/0 -> 58947/0, cluster=0005, TID=4A, nwkAddrOfInterest=58947]]