2019-12-21 15:11:08.727 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Permit join to 65532/0 for 0 seconds. 2019-12-21 15:11:08.730 [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=0, tcSignificance=true]] 2019-12-21 15:11:08.731 [DEBUG] [transaction.ZigBeeTransactionManager] - 65532/0: Sending ZigBeeTransaction [queueTime=2, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=42, permitDuration=0, tcSignificance=true]] 2019-12-21 15:11:08.731 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding 2019-12-21 15:11:08.732 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=42, permitDuration=0, tcSignificance=true] 2019-12-21 15:11:08.733 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=65532/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=52, payload=00 00 01] 2019-12-21 15:11:08.734 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6F000DD025FE: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=0, tcSignificance=true]] 2019-12-21 15:11:08.735 [DEBUG] [transaction.ZigBeeTransactionManager] - 0/0: Sending ZigBeeTransaction [queueTime=1, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=43, permitDuration=0, tcSignificance=true]] 2019-12-21 15:11:08.735 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding 2019-12-21 15:11:08.736 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=43, permitDuration=0, tcSignificance=true] 2019-12-21 15:11:08.736 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=53, payload=00 00 01] 2019-12-21 15:11:08.736 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - EC1BBDFFFED57F2E: ZigBee leave command 2019-12-21 15:11:08.737 [DEBUG] [bee.handler.ZigBeeCoordinatorHandler] - EC1BBDFFFED57F2E: ZigBee leave command to 20156 2019-12-21 15:11:08.739 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - EC1BBDFFFED57F2E: Added transaction to queue, len=34, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ManagementLeaveRequest [0/0 -> 20156/0, cluster=0034, TID=--, deviceAddress=EC1BBDFFFED57F2E, removeChildrenRejoin=false]] 2019-12-21 15:11:08.749 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendBroadcastResponse [status=EMBER_SUCCESS, sequence=33] 2019-12-21 15:11:08.750 [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=33], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00 01] 2019-12-21 15:11:08.750 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0036, addressMode=null, radius=0, apsSecurity=false, apsCounter=33, payload=00 00 01] 2019-12-21 15:11:08.751 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=0, tcSignificance=true] 2019-12-21 15:11:08.751 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=0, tcSignificance=true] 2019-12-21 15:11:08.751 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=0, tcSignificance=true] ZigBeeTransaction [queueTime=17, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=43, permitDuration=0, tcSignificance=true]] 2019-12-21 15:11:08.752 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - EC1BBDFFFED57F2E: Handler dispose. 2019-12-21 15:11:08.752 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - EC1BBDFFFED57F2E: Polling stopped 2019-12-21 15:11:08.753 [DEBUG] [verter.ZigBeeConverterBatteryVoltage] - EC1BBDFFFED57F2E: Closing power configuration cluster 2019-12-21 15:11:08.753 [DEBUG] [onverter.ZigBeeConverterBatteryAlarm] - EC1BBDFFFED57F2E: Closing battery alarm converter 2019-12-21 15:11:08.753 [DEBUG] [verter.ZigBeeConverterBatteryPercent] - EC1BBDFFFED57F2E: Closing power configuration cluster 2019-12-21 15:11:08.753 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - Remove IsAlive Tracker for thingUID=zigbee:device:01190437:ec1bbdfffed57f2e 2019-12-21 15:11:08.754 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=0, tcSignificance=true] ZigBeeTransaction [queueTime=24, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=42, permitDuration=0, tcSignificance=true]] 2019-12-21 15:11:08.754 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - Canceling timeout task for thingUID=zigbee:device:01190437:ec1bbdfffed57f2e 2019-12-21 15:11:08.769 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=34] 2019-12-21 15:11:08.790 [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=34], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00 01] 2019-12-21 15:11:08.791 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0036, addressMode=null, radius=0, apsSecurity=false, apsCounter=34, payload=00 00 01] 2019-12-21 15:11:08.791 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=0, tcSignificance=true] 2019-12-21 15:11:08.791 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=0, tcSignificance=true] 2019-12-21 15:11:08.791 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=0, tcSignificance=true] ZigBeeTransaction [queueTime=57, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=43, permitDuration=0, tcSignificance=true]] 2019-12-21 15:11:08.791 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=0, tcSignificance=true] ZigBeeTransaction [queueTime=62, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=42, permitDuration=0, tcSignificance=true]] 2019-12-21 15:11:08.793 [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=35], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00] 2019-12-21 15:11:08.793 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=8036, addressMode=null, radius=0, apsSecurity=false, apsCounter=35, payload=00 00] 2019-12-21 15:11:08.794 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] 2019-12-21 15:11:08.794 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] 2019-12-21 15:11:08.794 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] ZigBeeTransaction [queueTime=60, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=43, permitDuration=0, tcSignificance=true]] 2019-12-21 15:11:08.795 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] ZigBeeTransaction [queueTime=66, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=42, permitDuration=0, tcSignificance=true]] 2019-12-21 15:11:08.796 [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=34], messageTag=43, status=EMBER_SUCCESS, messageContents=] 2019-12-21 15:11:08.796 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=43 state=RX_ACK 2019-12-21 15:11:08.797 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=43, state=RX_ACK, outstanding=2 2019-12-21 15:11:08.797 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=63, state=COMPLETE, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=43, permitDuration=0, tcSignificance=true]] 2019-12-21 15:11:08.797 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding 2019-12-21 15:11:08.797 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6F000DD025FE: transactionComplete COMPLETE 0 2019-12-21 15:11:08.798 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 43 -> RX_ACK == COMPLETE 2019-12-21 15:11:09.637 [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=33], messageTag=42, status=EMBER_SUCCESS, messageContents=] 2019-12-21 15:11:09.638 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=42 state=RX_ACK 2019-12-21 15:11:09.639 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=42, state=RX_ACK, outstanding=1 2019-12-21 15:11:09.644 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=915, state=COMPLETE, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=42, permitDuration=0, tcSignificance=true]] 2019-12-21 15:11:09.645 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding 2019-12-21 15:11:09.645 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete COMPLETE 0 2019-12-21 15:11:09.645 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 42 -> RX_ACK == COMPLETE 2019-12-21 15:11:20.744 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - EC1BBDFFFED57F2E: No successful response received to leave command (status code 65535) 2019-12-21 15:12:02.613 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspChildJoinHandler [index=0, joining=false, childId=20156, childEui64=EC1BBDFFFED57F2E, childType=EMBER_SLEEPY_END_DEVICE] 2019-12-21 15:12:02.614 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - EC1BBDFFFED57F2E: nodeStatusUpdate - node status is DEVICE_LEFT, network address is 20156. 2019-12-21 15:12:02.614 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - EC1BBDFFFED57F2E: Updating node NWK=20156 2019-12-21 15:12:02.615 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - EC1BBDFFFED57F2E: Node 20156 update 2019-12-21 15:12:02.616 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - EC1BBDFFFED57F2E: Node 20156 is not updated 2019-12-21 15:12:02.618 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [newNodeId=20156, newNodeEui64=EC1BBDFFFED57F2E, status=EMBER_DEVICE_LEFT, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=65535] 2019-12-21 15:12:02.619 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - EC1BBDFFFED57F2E: nodeStatusUpdate - node status is DEVICE_LEFT, network address is 20156. 2019-12-21 15:12:02.620 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - EC1BBDFFFED57F2E: Updating node NWK=20156 2019-12-21 15:12:02.620 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - EC1BBDFFFED57F2E: Node 20156 update 2019-12-21 15:12:02.621 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - EC1BBDFFFED57F2E: Node 20156 is not updated 2019-12-21 15:12:11.558 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - EC1BBDFFFED57F2E: Discovery: Starting discovery for existing device 2019-12-21 15:12:11.559 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - Starting ZigBee scan for zigbee:coordinator_ember:01190437 2019-12-21 15:12:11.560 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Permit join to 65532/0 for 60 seconds. 2019-12-21 15:12:11.562 [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-21 15:12:11.563 [DEBUG] [transaction.ZigBeeTransactionManager] - 65532/0: Sending ZigBeeTransaction [queueTime=1, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=44, permitDuration=60, tcSignificance=true]] 2019-12-21 15:12:11.564 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding 2019-12-21 15:12:11.565 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=44, permitDuration=60, tcSignificance=true] 2019-12-21 15:12:11.566 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=65532/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=54, payload=00 3C 01] 2019-12-21 15:12:11.567 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6F000DD025FE: 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-21 15:12:11.569 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - EC1BBDFFFED57F2E: Starting ZigBee device discovery 2019-12-21 15:12:11.570 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - EC1BBDFFFED57F2E: Creating ZigBee device zigbee:device with bridge zigbee:coordinator_ember:01190437 2019-12-21 15:12:11.570 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zigbee:device:01190437:ec1bbdfffed57f2e' to inbox. 2019-12-21 15:12:11.570 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - EC1BBDFFFED57F2E: ZigBee node property discovery start 2019-12-21 15:12:11.571 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - EC1BBDFFFED57F2E: ZigBee node property discovery using basic cluster on endpoint 20156/1 2019-12-21 15:12:11.569 [DEBUG] [transaction.ZigBeeTransactionManager] - 0/0: Sending ZigBeeTransaction [queueTime=2, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=45, permitDuration=60, tcSignificance=true]] 2019-12-21 15:12:11.572 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding 2019-12-21 15:12:11.573 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=45, permitDuration=60, tcSignificance=true] 2019-12-21 15:12:11.574 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=55, payload=00 3C 01] 2019-12-21 15:12:11.574 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - EC1BBDFFFED57F2E: Added transaction to queue, len=35, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Basic: 0/0 -> 20156/1, cluster=0000, TID=--, identifiers=[5, 4, 3, 2, 6, 0, 1]]] 2019-12-21 15:12:11.581 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendBroadcastResponse [status=EMBER_SUCCESS, sequence=36] 2019-12-21 15:12:11.582 [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=36], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 3C 01] 2019-12-21 15:12:11.582 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0036, addressMode=null, radius=0, apsSecurity=false, apsCounter=36, payload=00 3C 01] 2019-12-21 15:12:11.582 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] 2019-12-21 15:12:11.582 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] 2019-12-21 15:12:11.583 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] ZigBeeTransaction [queueTime=21, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=44, permitDuration=60, tcSignificance=true]] 2019-12-21 15:12:11.583 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] ZigBeeTransaction [queueTime=16, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=45, permitDuration=60, tcSignificance=true]] 2019-12-21 15:12:11.602 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=37] 2019-12-21 15:12:11.623 [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=37], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 3C 01] 2019-12-21 15:12:11.624 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0036, addressMode=null, radius=0, apsSecurity=false, apsCounter=37, payload=00 3C 01] 2019-12-21 15:12:11.624 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] 2019-12-21 15:12:11.625 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] 2019-12-21 15:12:11.625 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] ZigBeeTransaction [queueTime=63, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=44, permitDuration=60, tcSignificance=true]] 2019-12-21 15:12:11.625 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] ZigBeeTransaction [queueTime=58, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=45, permitDuration=60, tcSignificance=true]] 2019-12-21 15:12:11.626 [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=38], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00] 2019-12-21 15:12:11.627 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=8036, addressMode=null, radius=0, apsSecurity=false, apsCounter=38, payload=00 00] 2019-12-21 15:12:11.627 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] 2019-12-21 15:12:11.628 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] 2019-12-21 15:12:11.628 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] ZigBeeTransaction [queueTime=66, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=44, permitDuration=60, tcSignificance=true]] 2019-12-21 15:12:11.628 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] ZigBeeTransaction [queueTime=61, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=45, permitDuration=60, tcSignificance=true]] 2019-12-21 15:12:11.629 [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=37], messageTag=45, status=EMBER_SUCCESS, messageContents=] 2019-12-21 15:12:11.630 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=45 state=RX_ACK 2019-12-21 15:12:11.630 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=45, state=RX_ACK, outstanding=2 2019-12-21 15:12:11.631 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=64, state=COMPLETE, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=45, permitDuration=60, tcSignificance=true]] 2019-12-21 15:12:11.631 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding 2019-12-21 15:12:11.632 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6F000DD025FE: transactionComplete COMPLETE 0 2019-12-21 15:12:11.632 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 45 -> RX_ACK == COMPLETE 2019-12-21 15:12:12.550 [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=36], messageTag=44, status=EMBER_SUCCESS, messageContents=] 2019-12-21 15:12:12.552 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=44 state=RX_ACK 2019-12-21 15:12:12.553 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=44, state=RX_ACK, outstanding=1 2019-12-21 15:12:12.555 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=993, state=COMPLETE, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=44, permitDuration=60, tcSignificance=true]] 2019-12-21 15:12:12.556 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding 2019-12-21 15:12:12.557 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete COMPLETE 0 2019-12-21 15:12:12.557 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 44 -> RX_ACK == COMPLETE 2019-12-21 15:12:13.500 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspChildJoinHandler [index=0, joining=true, childId=54495, childEui64=EC1BBDFFFED57F2E, childType=EMBER_SLEEPY_END_DEVICE] 2019-12-21 15:12:13.501 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - EC1BBDFFFED57F2E: nodeStatusUpdate - node status is UNSECURED_JOIN, network address is 54495. 2019-12-21 15:12:13.503 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - EC1BBDFFFED57F2E: Device status updated. NWK=54495 2019-12-21 15:12:13.504 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - EC1BBDFFFED57F2E: NWK Discovery add node 54495 2019-12-21 15:12:13.506 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - EC1BBDFFFED57F2E: Node state updated from UNKNOWN to ONLINE 2019-12-21 15:12:13.507 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - EC1BBDFFFED57F2E: Updating node NWK=54495 2019-12-21 15:12:13.508 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - EC1BBDFFFED57F2E: Node 54495 update 2019-12-21 15:12:13.509 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - EC1BBDFFFED57F2E: Network address updated from 20156 to 54495 2019-12-21 15:12:13.511 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - EC1BBDFFFED57F2E: Set profile to ZigBeeTransactionProfile [maxOutstandingTransactions=1, interTransactionDelay=50, maxRetries=2] 2019-12-21 15:12:13.511 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - EC1BBDFFFED57F2E: Data store: Deferring write for 250ms. 2019-12-21 15:12:13.708 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [newNodeId=54495, newNodeEui64=EC1BBDFFFED57F2E, status=EMBER_STANDARD_SECURITY_UNSECURED_JOIN, policyDecision=EMBER_USE_PRECONFIGURED_KEY, parentOfNewNodeId=0] 2019-12-21 15:12:13.708 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - EC1BBDFFFED57F2E: nodeStatusUpdate - node status is UNSECURED_JOIN, network address is 54495. 2019-12-21 15:12:13.710 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - EC1BBDFFFED57F2E: Device status updated. NWK=54495 2019-12-21 15:12:13.711 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - EC1BBDFFFED57F2E: NWK Discovery add node 54495 2019-12-21 15:12:13.712 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - EC1BBDFFFED57F2E: Node state updated from UNKNOWN to ONLINE 2019-12-21 15:12:13.713 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - EC1BBDFFFED57F2E: Updating node NWK=54495 2019-12-21 15:12:13.714 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - EC1BBDFFFED57F2E: Node 54495 update 2019-12-21 15:12:13.715 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - EC1BBDFFFED57F2E: Node 54495 is not updated 2019-12-21 15:12:13.762 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - EC1BBDFFFED57F2E: Data store: Writing node. 2019-12-21 15:12:13.778 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - EC1BBDFFFED57F2E: ZigBee saving network state complete. 2019-12-21 15:12:15.717 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspChildJoinHandler [index=0, joining=true, childId=54495, childEui64=EC1BBDFFFED57F2E, childType=EMBER_SLEEPY_END_DEVICE] 2019-12-21 15:12:15.718 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - EC1BBDFFFED57F2E: nodeStatusUpdate - node status is UNSECURED_JOIN, network address is 54495. 2019-12-21 15:12:15.718 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - EC1BBDFFFED57F2E: Device status updated. NWK=54495 2019-12-21 15:12:15.720 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - EC1BBDFFFED57F2E: NWK Discovery add node 54495 2019-12-21 15:12:15.721 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - EC1BBDFFFED57F2E: Node state updated from UNKNOWN to ONLINE 2019-12-21 15:12:15.721 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - EC1BBDFFFED57F2E: Updating node NWK=54495 2019-12-21 15:12:15.722 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - EC1BBDFFFED57F2E: Node 54495 update 2019-12-21 15:12:15.723 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - EC1BBDFFFED57F2E: Node 54495 is not updated 2019-12-21 15:12:15.926 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [newNodeId=54495, newNodeEui64=EC1BBDFFFED57F2E, status=EMBER_STANDARD_SECURITY_UNSECURED_JOIN, policyDecision=EMBER_USE_PRECONFIGURED_KEY, parentOfNewNodeId=0] 2019-12-21 15:12:15.927 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - EC1BBDFFFED57F2E: nodeStatusUpdate - node status is UNSECURED_JOIN, network address is 54495. 2019-12-21 15:12:15.929 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - EC1BBDFFFED57F2E: Device status updated. NWK=54495 2019-12-21 15:12:15.930 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - EC1BBDFFFED57F2E: NWK Discovery add node 54495 2019-12-21 15:12:15.931 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - EC1BBDFFFED57F2E: Node state updated from UNKNOWN to ONLINE 2019-12-21 15:12:15.932 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - EC1BBDFFFED57F2E: Updating node NWK=54495 2019-12-21 15:12:15.932 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - EC1BBDFFFED57F2E: Node 54495 update 2019-12-21 15:12:15.933 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - EC1BBDFFFED57F2E: Node 54495 is not updated 2019-12-21 15:12:15.997 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingSenderEui64Handler [senderEui64=EC1BBDFFFED57F2E] 2019-12-21 15:12:15.998 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_BROADCAST, apsFrame=EmberApsFrame [profileId=0, clusterId=19, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_SOURCE_EUI64], groupId=0, sequence=05], lastHopLqi=255, lastHopRssi=-33, sender=54495, bindingIndex=255, addressIndex=255, messageContents=81 DF D4 2E 7F D5 FE FF BD 1B EC 80] 2019-12-21 15:12:15.999 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=54495/0, destinationAddress=0/0, profile=0000, cluster=0013, addressMode=null, radius=0, apsSecurity=false, apsCounter=05, payload=81 DF D4 2E 7F D5 FE FF BD 1B EC 80] 2019-12-21 15:12:15.999 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: DeviceAnnounce [54495/0 -> 0/0, cluster=0013, TID=--, nwkAddrOfInterest=54495, ieeeAddr=EC1BBDFFFED57F2E, capability=128] 2019-12-21 15:12:16.000 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: DeviceAnnounce [54495/0 -> 0/0, cluster=0013, TID=--, nwkAddrOfInterest=54495, ieeeAddr=EC1BBDFFFED57F2E, capability=128] 2019-12-21 15:12:16.000 [DEBUG] [p.discovery.ZigBeeDiscoveryExtension] - DISCOVERY Extension: Mesh related command received. Triggering mesh update. 2019-12-21 15:12:16.001 [DEBUG] [p.discovery.ZigBeeDiscoveryExtension] - DISCOVERY Extension: Start mesh update task with interval of 86400 seconds 2019-12-21 15:12:16.001 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - EC1BBDFFFED57F2E: Device announce received. NWK=54495 2019-12-21 15:12:16.002 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - EC1BBDFFFED57F2E: NWK Discovery add node 54495 2019-12-21 15:12:16.003 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - EC1BBDFFFED57F2E: Node state updated from UNKNOWN to ONLINE 2019-12-21 15:12:16.004 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - EC1BBDFFFED57F2E: Updating node NWK=54495 2019-12-21 15:12:16.005 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - EC1BBDFFFED57F2E: Node 54495 update 2019-12-21 15:12:16.005 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - EC1BBDFFFED57F2E: Node 54495 is not updated 2019-12-21 15:12:16.012 [DEBUG] [p.discovery.ZigBeeDiscoveryExtension] - DISCOVERY Extension: Starting mesh update 2019-12-21 15:12:16.012 [DEBUG] [p.discovery.ZigBeeDiscoveryExtension] - 000D6F000DD025FE: DISCOVERY Extension: Starting mesh update 2019-12-21 15:12:16.012 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000DD025FE: Node SVC Discovery: Update mesh 2019-12-21 15:12:16.013 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000DD025FE: Node SVC Discovery: starting new tasks [NEIGHBORS, ROUTES] 2019-12-21 15:12:16.013 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000DD025FE: Node SVC Discovery: scheduled [NEIGHBORS, ROUTES] 2019-12-21 15:12:16.803 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000DD025FE: Node SVC Discovery: running NEIGHBORS 2019-12-21 15:12:16.804 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6F000DD025FE: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ManagementLqiRequest [0/0 -> 0/0, cluster=0031, TID=--, startIndex=0]] 2019-12-21 15:12:16.805 [DEBUG] [transaction.ZigBeeTransactionManager] - 0/0: Sending ZigBeeTransaction [queueTime=1, state=WAITING, sendCnt=0, command=ManagementLqiRequest [0/0 -> 0/0, cluster=0031, TID=46, startIndex=0]] 2019-12-21 15:12:16.805 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding 2019-12-21 15:12:16.805 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementLqiRequest [0/0 -> 0/0, cluster=0031, TID=46, startIndex=0] 2019-12-21 15:12:16.806 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0031, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=56, payload=00 00] 2019-12-21 15:12:16.816 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=3B] 2019-12-21 15:12:16.838 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=49, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=3B], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00] 2019-12-21 15:12:16.838 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0031, addressMode=null, radius=0, apsSecurity=false, apsCounter=3B, payload=00 00] 2019-12-21 15:12:16.839 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementLqiRequest [0/0 -> 0/0, cluster=0031, TID=--, startIndex=0] 2019-12-21 15:12:16.839 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementLqiRequest [0/0 -> 0/0, cluster=0031, TID=--, startIndex=0] 2019-12-21 15:12:16.839 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementLqiRequest [0/0 -> 0/0, cluster=0031, TID=--, startIndex=0] ZigBeeTransaction [queueTime=35, state=DISPATCHED, sendCnt=1, command=ManagementLqiRequest [0/0 -> 0/0, cluster=0031, TID=46, startIndex=0]] 2019-12-21 15:12:16.840 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=32817, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=3C], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00 01 00 01 62 FB AC BC E9 88 6C 4C 2E 7F D5 FE FF BD 1B EC DF D4 12 00 01 FF] 2019-12-21 15:12:16.841 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=8031, addressMode=null, radius=0, apsSecurity=false, apsCounter=3C, payload=00 00 01 00 01 62 FB AC BC E9 88 6C 4C 2E 7F D5 FE FF BD 1B EC DF D4 12 00 01 FF] 2019-12-21 15:12:16.842 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementLqiResponse [0/0 -> 0/0, cluster=8031, TID=--, status=SUCCESS, neighborTableEntries=1, startIndex=0, neighborTableList=[NeighborTable [extendedPanId=4C6C88E9BCACFB62, extendedAddress=EC1BBDFFFED57F2E, networkAddress=54495, deviceType=END_DEVICE, rxOnWhenIdle=RX_OFF, relationship=CHILD, permitJoining=DISABLED, depth=1, lqi=255]]] 2019-12-21 15:12:16.842 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementLqiResponse [0/0 -> 0/0, cluster=8031, TID=--, status=SUCCESS, neighborTableEntries=1, startIndex=0, neighborTableList=[NeighborTable [extendedPanId=4C6C88E9BCACFB62, extendedAddress=EC1BBDFFFED57F2E, networkAddress=54495, deviceType=END_DEVICE, rxOnWhenIdle=RX_OFF, relationship=CHILD, permitJoining=DISABLED, depth=1, lqi=255]]] 2019-12-21 15:12:16.842 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementLqiResponse [0/0 -> 0/0, cluster=8031, TID=--, status=SUCCESS, neighborTableEntries=1, startIndex=0, neighborTableList=[NeighborTable [extendedPanId=4C6C88E9BCACFB62, extendedAddress=EC1BBDFFFED57F2E, networkAddress=54495, deviceType=END_DEVICE, rxOnWhenIdle=RX_OFF, relationship=CHILD, permitJoining=DISABLED, depth=1, lqi=255]]] ZigBeeTransaction [queueTime=38, state=DISPATCHED, sendCnt=1, command=ManagementLqiRequest [0/0 -> 0/0, cluster=0031, TID=46, startIndex=0]] 2019-12-21 15:12:16.844 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=40, state=COMPLETE, sendCnt=1, command=ManagementLqiRequest [0/0 -> 0/0, cluster=0031, TID=46, startIndex=0]] 2019-12-21 15:12:16.845 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=0, apsFrame=EmberApsFrame [profileId=0, clusterId=49, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=3B], messageTag=46, status=EMBER_SUCCESS, messageContents=] 2019-12-21 15:12:16.846 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding 2019-12-21 15:12:16.846 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=46 state=RX_ACK 2019-12-21 15:12:16.847 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=46, state=RX_ACK, outstanding=0 2019-12-21 15:12:16.847 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6F000DD025FE: transactionComplete COMPLETE 0 2019-12-21 15:12:16.847 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000DD025FE: Node SVC Discovery: ManagementLqiRequest response CommandResult [SUCCESS, ManagementLqiResponse [0/0 -> 0/0, cluster=8031, TID=--, status=SUCCESS, neighborTableEntries=1, startIndex=0, neighborTableList=[NeighborTable [extendedPanId=4C6C88E9BCACFB62, extendedAddress=EC1BBDFFFED57F2E, networkAddress=54495, deviceType=END_DEVICE, rxOnWhenIdle=RX_OFF, relationship=CHILD, permitJoining=DISABLED, depth=1, lqi=255]]]] 2019-12-21 15:12:16.848 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000DD025FE: Node SVC Discovery: ManagementLqiRequest complete [1 neighbors] 2019-12-21 15:12:16.849 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 000D6F000DD025FE: Neighbor table updated: [NeighborTable [extendedPanId=4C6C88E9BCACFB62, extendedAddress=EC1BBDFFFED57F2E, networkAddress=54495, deviceType=END_DEVICE, rxOnWhenIdle=RX_OFF, relationship=CHILD, permitJoining=DISABLED, depth=1, lqi=255]] 2019-12-21 15:12:16.849 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000DD025FE: Node SVC Discovery: request NEIGHBORS successful. Advancing to ROUTES. 2019-12-21 15:12:16.850 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000DD025FE: Node SVC Discovery: running ROUTES 2019-12-21 15:12:16.850 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6F000DD025FE: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=--, startIndex=0]] 2019-12-21 15:12:19.122 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspZigbeeKeyEstablishmentHandler [partner=EC1BBDFFFED57F2E, status=UNKNOWN] 2019-12-21 15:12:23.575 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - EC1BBDFFFED57F2E: ZigBee node property discovery using OTA cluster on endpoint 54495/1 2019-12-21 15:12:23.576 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - EC1BBDFFFED57F2E: ZigBee node property discovery complete: {zigbee_logicaltype=END_DEVICE, zigbee_powerlevel=FULL, zigbee_manufacturercode=0x117c, modelId=TRADFRI on/off switch, zigbee_networkaddress=20156, zigbee_powersource=MAINS, zigbee_stkversion=98, zigbee_datecode=20190723, zigbee_zclversion=3, vendor=IKEA of Sweden, zigbee_powermode=RECEIVER_ON_IDLE, zigbee_powersources=[MAINS], hardwareVersion=1, firmwareVersion=0x22010631, zigbee_applicationVersion=33} 2019-12-21 15:12:23.577 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - EC1BBDFFFED57F2E: Update ZigBee device zigbee:device with bridge zigbee:coordinator_ember:01190437, label 'IKEA of Sweden TRADFRI on/off switch' 2019-12-21 15:12:23.579 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - EC1BBDFFFED57F2E: Data store: Deferring write for 250ms. 2019-12-21 15:12:23.832 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - EC1BBDFFFED57F2E: Data store: Writing node. 2019-12-21 15:12:23.846 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - EC1BBDFFFED57F2E: ZigBee saving network state complete. 2019-12-21 15:12:28.851 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000DD025FE: Node SVC Discovery: ManagementRoutingRequest returned CommandResult [TIMEOUT] 2019-12-21 15:12:28.852 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000DD025FE: Node SVC Discovery: request ROUTES failed. Retry 1, wait 2195ms before retry. 2019-12-21 15:12:31.048 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000DD025FE: Node SVC Discovery: running ROUTES 2019-12-21 15:12:31.049 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6F000DD025FE: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=--, startIndex=0]] 2019-12-21 15:12:31.049 [DEBUG] [transaction.ZigBeeTransactionManager] - 0/0: Sending ZigBeeTransaction [queueTime=14199, state=WAITING, sendCnt=0, command=ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=47, startIndex=0]] 2019-12-21 15:12:31.050 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding 2019-12-21 15:12:31.050 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=47, startIndex=0] 2019-12-21 15:12:31.051 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0032, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=57, payload=00 00] 2019-12-21 15:12:31.062 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=3E] 2019-12-21 15:12:31.091 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=50, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=3E], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00] 2019-12-21 15:12:31.092 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0032, addressMode=null, radius=0, apsSecurity=false, apsCounter=3E, payload=00 00] 2019-12-21 15:12:31.094 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=--, startIndex=0] 2019-12-21 15:12:31.095 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=--, startIndex=0] 2019-12-21 15:12:31.096 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=--, startIndex=0] ZigBeeTransaction [queueTime=14246, state=DISPATCHED, sendCnt=1, command=ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=47, startIndex=0]] 2019-12-21 15:12:31.098 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=32818, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=3F], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00 10 00 0F 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00] 2019-12-21 15:12:31.100 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=8032, addressMode=null, radius=0, apsSecurity=false, apsCounter=3F, payload=00 00 10 00 0F 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00] 2019-12-21 15:12:31.101 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementRoutingResponse [0/0 -> 0/0, cluster=8032, TID=--, status=SUCCESS, routingTableEntries=16, startIndex=0, routingTableList=[RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0]]] 2019-12-21 15:12:31.101 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementRoutingResponse [0/0 -> 0/0, cluster=8032, TID=--, status=SUCCESS, routingTableEntries=16, startIndex=0, routingTableList=[RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0]]] 2019-12-21 15:12:31.102 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementRoutingResponse [0/0 -> 0/0, cluster=8032, TID=--, status=SUCCESS, routingTableEntries=16, startIndex=0, routingTableList=[RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0]]] ZigBeeTransaction [queueTime=14252, state=DISPATCHED, sendCnt=1, command=ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=47, startIndex=0]] 2019-12-21 15:12:31.103 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=14253, state=COMPLETE, sendCnt=1, command=ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=47, startIndex=0]] 2019-12-21 15:12:31.104 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=0, apsFrame=EmberApsFrame [profileId=0, clusterId=50, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=3E], messageTag=47, status=EMBER_SUCCESS, messageContents=] 2019-12-21 15:12:31.104 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding 2019-12-21 15:12:31.104 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6F000DD025FE: transactionComplete COMPLETE 0 2019-12-21 15:12:31.105 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=47 state=RX_ACK 2019-12-21 15:12:31.105 [DEBUG] [transaction.ZigBeeTransactionManager] - 0/0: Sending ZigBeeTransaction [queueTime=56, state=WAITING, sendCnt=0, command=ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=48, startIndex=0]] 2019-12-21 15:12:31.105 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding 2019-12-21 15:12:31.105 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=48, startIndex=0] 2019-12-21 15:12:31.105 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0032, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=58, payload=00 00] 2019-12-21 15:12:31.105 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=47, state=RX_ACK, outstanding=1 2019-12-21 15:12:31.116 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=40] 2019-12-21 15:12:31.146 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=50, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=40], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00] 2019-12-21 15:12:31.147 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0032, addressMode=null, radius=0, apsSecurity=false, apsCounter=40, payload=00 00] 2019-12-21 15:12:31.148 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=--, startIndex=0] 2019-12-21 15:12:31.149 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=--, startIndex=0] 2019-12-21 15:12:31.149 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=--, startIndex=0] ZigBeeTransaction [queueTime=100, state=DISPATCHED, sendCnt=1, command=ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=48, startIndex=0]] 2019-12-21 15:12:31.152 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=32818, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=41], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00 10 00 0F 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00] 2019-12-21 15:12:31.153 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=8032, addressMode=null, radius=0, apsSecurity=false, apsCounter=41, payload=00 00 10 00 0F 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00] 2019-12-21 15:12:31.154 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementRoutingResponse [0/0 -> 0/0, cluster=8032, TID=--, status=SUCCESS, routingTableEntries=16, startIndex=0, routingTableList=[RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0]]] 2019-12-21 15:12:31.155 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementRoutingResponse [0/0 -> 0/0, cluster=8032, TID=--, status=SUCCESS, routingTableEntries=16, startIndex=0, routingTableList=[RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0]]] 2019-12-21 15:12:31.156 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementRoutingResponse [0/0 -> 0/0, cluster=8032, TID=--, status=SUCCESS, routingTableEntries=16, startIndex=0, routingTableList=[RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0]]] ZigBeeTransaction [queueTime=107, state=DISPATCHED, sendCnt=1, command=ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=48, startIndex=0]] 2019-12-21 15:12:31.157 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=108, state=COMPLETE, sendCnt=1, command=ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=48, startIndex=0]] 2019-12-21 15:12:31.157 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000DD025FE: Node SVC Discovery: ManagementRoutingRequest returned CommandResult [SUCCESS, ManagementRoutingResponse [0/0 -> 0/0, cluster=8032, TID=--, status=SUCCESS, routingTableEntries=16, startIndex=0, routingTableList=[RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0]]]] 2019-12-21 15:12:31.158 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding 2019-12-21 15:12:31.158 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6F000DD025FE: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=--, startIndex=15]] 2019-12-21 15:12:31.158 [DEBUG] [transaction.ZigBeeTransactionManager] - 0/0: Sending ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=49, startIndex=15]] 2019-12-21 15:12:31.158 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding 2019-12-21 15:12:31.158 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=0, apsFrame=EmberApsFrame [profileId=0, clusterId=50, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=40], messageTag=48, status=EMBER_SUCCESS, messageContents=] 2019-12-21 15:12:31.159 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=48 state=RX_ACK 2019-12-21 15:12:31.159 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=49, startIndex=15] 2019-12-21 15:12:31.159 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=48, state=RX_ACK, outstanding=1 2019-12-21 15:12:31.159 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0032, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=59, payload=00 0F] 2019-12-21 15:12:31.160 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6F000DD025FE: transactionComplete COMPLETE 1 2019-12-21 15:12:31.169 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=42] 2019-12-21 15:12:31.190 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=50, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=42], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 0F] 2019-12-21 15:12:31.191 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0032, addressMode=null, radius=0, apsSecurity=false, apsCounter=42, payload=00 0F] 2019-12-21 15:12:31.191 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=--, startIndex=15] 2019-12-21 15:12:31.192 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=--, startIndex=15] 2019-12-21 15:12:31.192 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=--, startIndex=15] ZigBeeTransaction [queueTime=34, state=DISPATCHED, sendCnt=1, command=ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=49, startIndex=15]] 2019-12-21 15:12:31.195 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=32818, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=43], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00 10 0F 01 00 00 03 00 00] 2019-12-21 15:12:31.195 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=8032, addressMode=null, radius=0, apsSecurity=false, apsCounter=43, payload=00 00 10 0F 01 00 00 03 00 00] 2019-12-21 15:12:31.196 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementRoutingResponse [0/0 -> 0/0, cluster=8032, TID=--, status=SUCCESS, routingTableEntries=16, startIndex=15, routingTableList=[RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0]]] 2019-12-21 15:12:31.197 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementRoutingResponse [0/0 -> 0/0, cluster=8032, TID=--, status=SUCCESS, routingTableEntries=16, startIndex=15, routingTableList=[RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0]]] 2019-12-21 15:12:31.197 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementRoutingResponse [0/0 -> 0/0, cluster=8032, TID=--, status=SUCCESS, routingTableEntries=16, startIndex=15, routingTableList=[RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0]]] ZigBeeTransaction [queueTime=39, state=DISPATCHED, sendCnt=1, command=ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=49, startIndex=15]] 2019-12-21 15:12:31.198 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=40, state=COMPLETE, sendCnt=1, command=ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=49, startIndex=15]] 2019-12-21 15:12:31.198 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000DD025FE: Node SVC Discovery: ManagementRoutingRequest returned CommandResult [SUCCESS, ManagementRoutingResponse [0/0 -> 0/0, cluster=8032, TID=--, status=SUCCESS, routingTableEntries=16, startIndex=15, routingTableList=[RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0]]]] 2019-12-21 15:12:31.198 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000DD025FE: Node SVC Discovery: ManagementLqiRequest complete [1 routes] 2019-12-21 15:12:31.198 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding 2019-12-21 15:12:31.199 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6F000DD025FE: transactionComplete COMPLETE 0 2019-12-21 15:12:31.200 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=0, apsFrame=EmberApsFrame [profileId=0, clusterId=50, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=42], messageTag=49, status=EMBER_SUCCESS, messageContents=] 2019-12-21 15:12:31.199 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 000D6F000DD025FE: Routing table NEW: [RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0]] 2019-12-21 15:12:31.200 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=49 state=RX_ACK 2019-12-21 15:12:31.201 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 000D6F000DD025FE: Routing table OLD: [] 2019-12-21 15:12:31.201 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=49, state=RX_ACK, outstanding=0 2019-12-21 15:12:31.202 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 000D6F000DD025FE: Routing table updated: [RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0]] 2019-12-21 15:12:31.202 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000DD025FE: Node SVC Discovery: request ROUTES successful. Advancing to null. 2019-12-21 15:12:31.203 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000DD025FE: Node SVC Discovery: complete 2019-12-21 15:12:31.203 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 000D6F000DD025FE: Updating node NWK=0 2019-12-21 15:12:31.204 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 000D6F000DD025FE: Node 0 update 2019-12-21 15:12:31.204 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 000D6F000DD025FE: Neighbors updated 2019-12-21 15:12:31.205 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6F000DD025FE: Set profile to ZigBeeTransactionProfile [maxOutstandingTransactions=2, interTransactionDelay=50, maxRetries=2] 2019-12-21 15:12:31.205 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 000D6F000DD025FE: Data store: Deferring write for 250ms. 2019-12-21 15:12:31.456 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 000D6F000DD025FE: Data store: Writing node. 2019-12-21 15:12:31.461 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 000D6F000DD025FE: ZigBee saving network state complete. 2019-12-21 15:12:59.312 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - EC1BBDFFFED57F2E: Initializing ZigBee thing handler zigbee:device:01190437:ec1bbdfffed57f2e 2019-12-21 15:12:59.314 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - EC1BBDFFFED57F2E: Coordinator status changed to ONLINE. 2019-12-21 15:12:59.315 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - EC1BBDFFFED57F2E: Coordinator is ONLINE. Starting device initialisation. 2019-12-21 15:12:59.315 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - EC1BBDFFFED57F2E: NWK Discovery starting node rediscovery 2019-12-21 15:12:59.315 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=--, ieeeAddr=EC1BBDFFFED57F2E, requestType=0, startIndex=0]] 2019-12-21 15:12:59.316 [DEBUG] [transaction.ZigBeeTransactionManager] - 65533/0: Sending ZigBeeTransaction [queueTime=1, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=4A, ieeeAddr=EC1BBDFFFED57F2E, requestType=0, startIndex=0]] 2019-12-21 15:12:59.316 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding 2019-12-21 15:12:59.316 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=4A, ieeeAddr=EC1BBDFFFED57F2E, requestType=0, startIndex=0] 2019-12-21 15:12:59.316 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=65533/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=5A, payload=00 2E 7F D5 FE FF BD 1B EC 00 00] 2019-12-21 15:12:59.326 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - EC1BBDFFFED57F2E: Start initialising ZigBee Thing handler 2019-12-21 15:12:59.327 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - EC1BBDFFFED57F2E: ZigBee node property discovery start 2019-12-21 15:12:59.328 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - EC1BBDFFFED57F2E: ZigBee node property discovery using basic cluster on endpoint 54495/1 2019-12-21 15:12:59.328 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - EC1BBDFFFED57F2E: ZigBee node property discovery using OTA cluster on endpoint 54495/1 2019-12-21 15:12:59.328 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendBroadcastResponse [status=EMBER_SUCCESS, sequence=44] 2019-12-21 15:12:59.328 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - EC1BBDFFFED57F2E: ZigBee node property discovery complete: {zigbee_logicaltype=END_DEVICE, zigbee_powerlevel=FULL, zigbee_manufacturercode=0x117c, modelId=TRADFRI on/off switch, zigbee_networkaddress=54495, zigbee_powersource=MAINS, zigbee_stkversion=98, zigbee_datecode=20190723, zigbee_zclversion=3, vendor=IKEA of Sweden, zigbee_powermode=RECEIVER_ON_IDLE, zigbee_powersources=[MAINS], hardwareVersion=1, firmwareVersion=0x22010631, zigbee_applicationVersion=33} 2019-12-21 15:12:59.332 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - EC1BBDFFFED57F2E: Checking endpoint 1 channels 2019-12-21 15:12:59.336 [DEBUG] [er.ZigBeeChannelConverterFactoryImpl] - EC1BBDFFFED57F2E: Removing channel zigbee:switch_onoff in favor of zigbee:switch_level 2019-12-21 15:12:59.337 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - EC1BBDFFFED57F2E: Dynamically created 4 channels 2019-12-21 15:12:59.337 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - EC1BBDFFFED57F2E: Updating thing definition as channels have changed from [] to [zigbee:device:01190437:ec1bbdfffed57f2e:EC1BBDFFFED57F2E_1_batterylevel, zigbee:device:01190437:ec1bbdfffed57f2e:EC1BBDFFFED57F2E_1_dimmer, zigbee:device:01190437:ec1bbdfffed57f2e:EC1BBDFFFED57F2E_1_batteryalarm, zigbee:device:01190437:ec1bbdfffed57f2e:EC1BBDFFFED57F2E_1_batteryvoltage] 2019-12-21 15:12:59.338 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - EC1BBDFFFED57F2E: Initializing device 2019-12-21 15:12:59.339 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - EC1BBDFFFED57F2E: Initializing channel zigbee:device:01190437:ec1bbdfffed57f2e:EC1BBDFFFED57F2E_1_batterylevel with org.openhab.binding.zigbee.internal.converter.ZigBeeConverterBatteryPercent@36bb7d9f 2019-12-21 15:12:59.340 [DEBUG] [verter.ZigBeeConverterBatteryPercent] - EC1BBDFFFED57F2E: Initialising device battery percent converter 2019-12-21 15:12:59.341 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - EC1BBDFFFED57F2E: Added transaction to queue, len=36, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=BindRequest [0/0 -> 54495/0, cluster=0021, TID=--, srcAddress=EC1BBDFFFED57F2E, srcEndpoint=1, bindCluster=1, dstAddrMode=3, dstAddress=000D6F000DD025FE, dstEndpoint=1]] 2019-12-21 15:12:59.350 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_BROADCAST_LOOPBACK, apsFrame=EmberApsFrame [profileId=0, clusterId=0, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=44], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 2E 7F D5 FE FF BD 1B EC 00 00] 2019-12-21 15:12:59.350 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0000, addressMode=null, radius=0, apsSecurity=false, apsCounter=44, payload=00 2E 7F D5 FE FF BD 1B EC 00 00] 2019-12-21 15:12:59.353 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: NetworkAddressRequest [0/0 -> 0/0, cluster=0000, TID=--, ieeeAddr=EC1BBDFFFED57F2E, requestType=0, startIndex=0] 2019-12-21 15:12:59.354 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NetworkAddressRequest [0/0 -> 0/0, cluster=0000, TID=--, ieeeAddr=EC1BBDFFFED57F2E, requestType=0, startIndex=0] 2019-12-21 15:12:59.354 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NetworkAddressRequest [0/0 -> 0/0, cluster=0000, TID=--, ieeeAddr=EC1BBDFFFED57F2E, requestType=0, startIndex=0] ZigBeeTransaction [queueTime=39, state=DISPATCHED, sendCnt=1, command=NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=4A, ieeeAddr=EC1BBDFFFED57F2E, requestType=0, startIndex=0]] 2019-12-21 15:12:59.355 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=32768, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=45], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00 2E 7F D5 FE FF BD 1B EC DF D4] 2019-12-21 15:12:59.356 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=8000, addressMode=null, radius=0, apsSecurity=false, apsCounter=45, payload=00 00 2E 7F D5 FE FF BD 1B EC DF D4] 2019-12-21 15:12:59.357 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: NetworkAddressResponse [0/0 -> 0/0, cluster=8000, TID=--, status=SUCCESS, ieeeAddrRemoteDev=EC1BBDFFFED57F2E, nwkAddrRemoteDev=54495, startIndex=null, nwkAddrAssocDevList=[]] 2019-12-21 15:12:59.357 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NetworkAddressResponse [0/0 -> 0/0, cluster=8000, TID=--, status=SUCCESS, ieeeAddrRemoteDev=EC1BBDFFFED57F2E, nwkAddrRemoteDev=54495, startIndex=null, nwkAddrAssocDevList=[]] 2019-12-21 15:12:59.357 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NetworkAddressResponse [0/0 -> 0/0, cluster=8000, TID=--, status=SUCCESS, ieeeAddrRemoteDev=EC1BBDFFFED57F2E, nwkAddrRemoteDev=54495, startIndex=null, nwkAddrAssocDevList=[]] ZigBeeTransaction [queueTime=42, state=DISPATCHED, sendCnt=1, command=NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=4A, ieeeAddr=EC1BBDFFFED57F2E, requestType=0, startIndex=0]] 2019-12-21 15:12:59.359 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=43, state=COMPLETE, sendCnt=1, command=NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=4A, ieeeAddr=EC1BBDFFFED57F2E, requestType=0, startIndex=0]] 2019-12-21 15:12:59.359 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - EC1BBDFFFED57F2E: NWK Discovery add node 54495 2019-12-21 15:12:59.359 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - EC1BBDFFFED57F2E: Node state updated from UNKNOWN to ONLINE 2019-12-21 15:12:59.359 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - EC1BBDFFFED57F2E: Updating node NWK=54495 2019-12-21 15:12:59.359 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - EC1BBDFFFED57F2E: Node 54495 update 2019-12-21 15:12:59.359 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding 2019-12-21 15:12:59.359 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete COMPLETE 0 2019-12-21 15:12:59.360 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - EC1BBDFFFED57F2E: Node 54495 is not updated 2019-12-21 15:12:59.360 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 54495: NWK Discovery scheduling node discovery 2019-12-21 15:12:59.360 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - EC1BBDFFFED57F2E: NWK Discovery finishing node rediscovery after 0 attempts 2019-12-21 15:12:59.360 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 54495: NWK Discovery starting node discovery 2019-12-21 15:12:59.360 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - EC1BBDFFFED57F2E: Added transaction to queue, len=37, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=IeeeAddressRequest [0/0 -> 54495/0, cluster=0001, TID=--, nwkAddrOfInterest=54495, requestType=1, startIndex=0]] 2019-12-21 15:13:00.226 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_BROADCAST, indexOrDestination=65533, apsFrame=EmberApsFrame [profileId=0, clusterId=0, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=44], messageTag=4A, status=EMBER_SUCCESS, messageContents=] 2019-12-21 15:13:00.226 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=4A state=RX_ACK 2019-12-21 15:13:00.227 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=4A, state=RX_ACK, outstanding=0 2019-12-21 15:13:11.342 [ERROR] [verter.ZigBeeConverterBatteryPercent] - EC1BBDFFFED57F2E: Error 0xffff setting server binding 2019-12-21 15:13:11.343 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - EC1BBDFFFED57F2E: Initializing channel zigbee:device:01190437:ec1bbdfffed57f2e:EC1BBDFFFED57F2E_1_dimmer with org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchLevel@387c9538 2019-12-21 15:13:11.344 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - EC1BBDFFFED57F2E: Added transaction to queue, len=38, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=BindRequest [0/0 -> 54495/0, cluster=0021, TID=--, srcAddress=EC1BBDFFFED57F2E, srcEndpoint=1, bindCluster=8, dstAddrMode=3, dstAddress=000D6F000DD025FE, dstEndpoint=1]] 2019-12-21 15:13:12.862 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - EC1BBDFFFED57F2E: Added transaction to queue, len=39, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=IeeeAddressRequest [0/0 -> 54495/0, cluster=0001, TID=--, nwkAddrOfInterest=54495, requestType=1, startIndex=0]] 2019-12-21 15:13:23.345 [ERROR] [converter.ZigBeeConverterSwitchLevel] - EC1BBDFFFED57F2E: Error 0xffff setting client binding 2019-12-21 15:13:23.346 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - EC1BBDFFFED57F2E: Added transaction to queue, len=40, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=BindRequest [0/0 -> 54495/0, cluster=0021, TID=--, srcAddress=EC1BBDFFFED57F2E, srcEndpoint=1, bindCluster=6, dstAddrMode=3, dstAddress=000D6F000DD025FE, dstEndpoint=1]] 2019-12-21 15:13:26.364 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - EC1BBDFFFED57F2E: Added transaction to queue, len=41, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=IeeeAddressRequest [0/0 -> 54495/0, cluster=0001, TID=--, nwkAddrOfInterest=54495, requestType=1, startIndex=0]] 2019-12-21 15:13:35.348 [ERROR] [converter.ZigBeeConverterSwitchLevel] - EC1BBDFFFED57F2E: Error 0xffff setting client binding 2019-12-21 15:13:35.348 [DEBUG] [converter.ZigBeeConverterSwitchLevel] - EC1BBDFFFED57F2E: Level control device initialized as client 2019-12-21 15:13:35.349 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - EC1BBDFFFED57F2E: Initializing channel zigbee:device:01190437:ec1bbdfffed57f2e:EC1BBDFFFED57F2E_1_batteryalarm with org.openhab.binding.zigbee.internal.converter.ZigBeeConverterBatteryAlarm@3c4316ef 2019-12-21 15:13:35.350 [DEBUG] [onverter.ZigBeeConverterBatteryAlarm] - EC1BBDFFFED57F2E: Initialising device battery alarm converter 2019-12-21 15:13:35.351 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - EC1BBDFFFED57F2E: Added transaction to queue, len=42, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=BindRequest [0/0 -> 54495/0, cluster=0021, TID=--, srcAddress=EC1BBDFFFED57F2E, srcEndpoint=1, bindCluster=1, dstAddrMode=3, dstAddress=000D6F000DD025FE, dstEndpoint=1]] 2019-12-21 15:13:39.867 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - EC1BBDFFFED57F2E: Added transaction to queue, len=43, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=IeeeAddressRequest [0/0 -> 54495/0, cluster=0001, TID=--, nwkAddrOfInterest=54495, requestType=1, startIndex=0]] 2019-12-21 15:13:47.352 [DEBUG] [onverter.ZigBeeConverterBatteryAlarm] - Could not bind to the power configuration cluster; polling battery alarm state every 1800 seconds 2019-12-21 15:13:47.353 [INFO ] [ng.zigbee.handler.ZigBeeThingHandler] - EC1BBDFFFED57F2E: Channel zigbee:device:01190437:ec1bbdfffed57f2e:EC1BBDFFFED57F2E_1_batteryalarm failed to initialise device 2019-12-21 15:13:47.354 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - EC1BBDFFFED57F2E: Initializing channel zigbee:device:01190437:ec1bbdfffed57f2e:EC1BBDFFFED57F2E_1_batteryvoltage with org.openhab.binding.zigbee.internal.converter.ZigBeeConverterBatteryVoltage@79419f03 2019-12-21 15:13:47.354 [DEBUG] [verter.ZigBeeConverterBatteryVoltage] - EC1BBDFFFED57F2E: Initialising device battery voltage converter 2019-12-21 15:13:47.355 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - EC1BBDFFFED57F2E: Added transaction to queue, len=44, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=BindRequest [0/0 -> 54495/0, cluster=0021, TID=--, srcAddress=EC1BBDFFFED57F2E, srcEndpoint=1, bindCluster=1, dstAddrMode=3, dstAddress=000D6F000DD025FE, dstEndpoint=1]] 2019-12-21 15:13:51.868 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 54495: NWK Discovery ending node discovery. Success=false. 2019-12-21 15:13:59.357 [DEBUG] [.zsmartsystems.zigbee.zcl.ZclCluster] - readSync request: ZclAttribute [cluster=com.zsmartsystems.zigbee.zcl.clusters.ZclPowerConfigurationCluster@147b4231, id=33, name=Battery Percentage Remaining, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=87, lastReportTime=Sat Dec 21 14:03:32 CET 2019] 2019-12-21 15:13:59.358 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - EC1BBDFFFED57F2E: Added transaction to queue, len=45, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Power Configuration: 0/0 -> 54495/1, cluster=0001, TID=--, identifiers=[33]]] 2019-12-21 15:14:11.360 [DEBUG] [converter.ZigBeeConverterSwitchLevel] - EC1BBDFFFED57F2E: Level control initialized as client 2019-12-21 15:14:11.361 [DEBUG] [.zsmartsystems.zigbee.zcl.ZclCluster] - readSync request: ZclAttribute [cluster=com.zsmartsystems.zigbee.zcl.clusters.ZclPowerConfigurationCluster@147b4231, id=62, name=Battery Alarm State, dataType=BITMAP_32_BIT, lastValue=null] 2019-12-21 15:14:11.362 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - EC1BBDFFFED57F2E: Added transaction to queue, len=46, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Power Configuration: 0/0 -> 54495/1, cluster=0001, TID=--, identifiers=[62]]] 2019-12-21 15:14:23.363 [DEBUG] [.zsmartsystems.zigbee.zcl.ZclCluster] - readSync request: ZclAttribute [cluster=com.zsmartsystems.zigbee.zcl.clusters.ZclPowerConfigurationCluster@147b4231, id=32, name=Battery Voltage, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=30, lastReportTime=Sat Dec 21 14:33:49 CET 2019] 2019-12-21 15:14:23.364 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - EC1BBDFFFED57F2E: Added transaction to queue, len=47, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Power Configuration: 0/0 -> 54495/1, cluster=0001, TID=--, identifiers=[32]]] 2019-12-21 15:14:35.369 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - EC1BBDFFFED57F2E: Channel initialisation complete 2019-12-21 15:14:35.370 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - Setting ONLINE/OFFLINE timeout interval to: 14430 2019-12-21 15:14:35.370 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - Add IsAlive Tracker for thingUID=zigbee:device:01190437:ec1bbdfffed57f2e 2019-12-21 15:14:35.370 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - Reset timeout for handler with thingUID=zigbee:device:01190437:ec1bbdfffed57f2e 2019-12-21 15:14:35.371 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - Scheduling timeout task for thingUID=zigbee:device:01190437:ec1bbdfffed57f2e in 14430 seconds 2019-12-21 15:14:35.373 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - EC1BBDFFFED57F2E: Added transaction to queue, len=48, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ManagementBindRequest [0/0 -> 54495/0, cluster=0033, TID=--, startIndex=0]] 2019-12-21 15:14:47.375 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - EC1BBDFFFED57F2E: Error getting binding table 2019-12-21 15:14:47.376 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - EC1BBDFFFED57F2E: Polling initialised at 7519133ms 2019-12-21 15:14:47.377 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - EC1BBDFFFED57F2E: Done initialising ZigBee Thing handler 2019-12-21 15:14:47.378 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - EC1BBDFFFED57F2E: Data store: Deferring write for 250ms. 2019-12-21 15:14:47.629 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - EC1BBDFFFED57F2E: Data store: Writing node. 2019-12-21 15:14:47.642 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - EC1BBDFFFED57F2E: ZigBee saving network state complete. 2019-12-21 15:15:55.748 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_BROADCAST, apsFrame=EmberApsFrame [profileId=0, clusterId=6, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=0C], lastHopLqi=255, lastHopRssi=-33, sender=54495, bindingIndex=255, addressIndex=255, messageContents=02 FD FF 04 01 01 19 00 00] 2019-12-21 15:15:55.749 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=54495/0, destinationAddress=0/0, profile=0000, cluster=0006, addressMode=null, radius=0, apsSecurity=false, apsCounter=0C, payload=02 FD FF 04 01 01 19 00 00] 2019-12-21 15:15:55.750 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: MatchDescriptorRequest [54495/0 -> 0/0, cluster=0006, TID=--, nwkAddrOfInterest=65533, profileId=260, inClusterList=[25], outClusterList=[]] 2019-12-21 15:15:55.751 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: MatchDescriptorRequest [54495/0 -> 0/0, cluster=0006, TID=--, nwkAddrOfInterest=65533, profileId=260, inClusterList=[25], outClusterList=[]] 2019-12-21 15:15:55.753 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 4C6C88E9BCACFB62: ClusterMatcher received request MatchDescriptorRequest [54495/0 -> 0/0, cluster=0006, TID=--, nwkAddrOfInterest=65533, profileId=260, inClusterList=[25], outClusterList=[]] 2019-12-21 15:15:55.754 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 4C6C88E9BCACFB62: ClusterMatcher sending match MatchDescriptorResponse [null -> 54495/0, cluster=8006, TID=--, status=SUCCESS, nwkAddrOfInterest=0, matchList=[1]] 2019-12-21 15:15:55.754 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - EC1BBDFFFED57F2E: Added transaction to queue, len=49, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=MatchDescriptorResponse [0/0 -> 54495/0, cluster=8006, TID=--, status=SUCCESS, nwkAddrOfInterest=0, matchList=[1]]]