08:02:49.324 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - Starting ZigBee scan for zigbee:coordinator_ember:013725D7
08:02:49.328 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - Permit join to FFFC/0 for 60 seconds.
08:02:49.331 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - Broadcast: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=null queueTime=0, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true]]
08:02:49.334 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
08:02:49.336 [DEBUG] [.transaction.ZigBeeTransactionManager] - FFFC/0: Sending ZigBeeTransaction [ieeeAddress=null queueTime=5, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=B9, permitDuration=60, tcSignificance=true]]
08:02:49.337 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
08:02:49.338 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=B9, permitDuration=60, tcSignificance=true]
08:02:49.339 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=FFFC/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=33, rssi=--, lqi=--, payload=B9 3C 01]
08:02:49.340 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 000D6F000DD1E41F: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=000D6F000DD1E41F queueTime=0, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true]]
08:02:49.341 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3
08:02:49.342 [DEBUG] [.transaction.ZigBeeTransactionManager] - 0000/0: Sending ZigBeeTransaction [ieeeAddress=000D6F000DD1E41F queueTime=2, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=BA, permitDuration=60, tcSignificance=true]]
08:02:49.343 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
08:02:49.344 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=BA, permitDuration=60, tcSignificance=true]
08:02:49.345 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=34, rssi=--, lqi=--, payload=BA 3C 01]
08:02:49.353 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendBroadcastResponse [networkId=0, status=EMBER_SUCCESS, sequence=B9]
08:02:49.354 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_BROADCAST_LOOPBACK, apsFrame=EmberApsFrame [profileId=0000, clusterId=0036, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=B9], lastHopLqi=255, lastHopRssi=0, sender=0000, bindingIndex=255, addressIndex=255, messageContents=B9 3C 01]
08:02:49.764 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=BA]
08:02:49.784 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=0036, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=BA], lastHopLqi=255, lastHopRssi=0, sender=0000, bindingIndex=255, addressIndex=255, messageContents=BA 3C 01]
08:02:49.787 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=BA, rssi=0, lqi=FF, payload=BA 3C 01]
08:02:49.789 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=BA, permitDuration=60, tcSignificance=true]
08:02:49.791 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=BA, permitDuration=60, tcSignificance=true]
08:02:49.794 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=8036, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=BB], lastHopLqi=255, lastHopRssi=0, sender=0000, bindingIndex=255, addressIndex=255, messageContents=BA 00]
08:02:49.797 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=8036, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=BB, rssi=0, lqi=FF, payload=BA 00]
08:02:49.798 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningResponse [0000/0 -> 0000/0, cluster=8036, TID=BA, status=SUCCESS]
08:02:49.799 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0000/0 -> 0000/0, cluster=8036, TID=BA, status=SUCCESS]
08:02:49.800 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=0000, apsFrame=EmberApsFrame [profileId=0000, clusterId=0036, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=BA], messageTag=BA, status=EMBER_SUCCESS, messageContents=]
08:02:49.801 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=BA state=RX_ACK
08:02:49.802 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=BA, state=RX_ACK, outstanding=2
08:02:49.803 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=000D6F000DD1E41F queueTime=463, state=COMPLETE, sendCnt=1, command=ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=BA, permitDuration=60, tcSignificance=true]]
08:02:49.803 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
08:02:49.804 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 000D6F000DD1E41F: transactionComplete, state=COMPLETE, outstanding=0
08:02:49.805 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=0, sleepy=0/3
08:02:49.805 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=0000, TID=BA, event=RX_ACK, state=COMPLETE
08:02:50.322 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_BROADCAST, indexOrDestination=FFFC, apsFrame=EmberApsFrame [profileId=0000, clusterId=0036, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=B9], messageTag=B9, status=EMBER_SUCCESS, messageContents=]
08:02:50.325 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=B9 state=RX_ACK
08:02:50.327 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=B9, state=RX_ACK, outstanding=1
08:02:50.331 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=null queueTime=1000, state=COMPLETE, sendCnt=1, command=ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=B9, permitDuration=60, tcSignificance=true]]
08:02:50.333 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
08:02:50.335 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete, state=COMPLETE, outstanding=0
08:02:50.336 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=0, sleepy=0/3
08:02:50.337 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=FFFC, TID=B9, event=RX_ACK, state=COMPLETE
08:02:51.267 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMacFilterMatchMessageHandler [networkId=0, filterIndexMatch=1, legacyPassthroughType=UNKNOWN, lastHopLqi=255, lastHopRssi=-46, messageContents=01 C8 C1 FF FF FF FF 32 56 DF 2F C3 FE FF E2 0A 68 0B 00 0B 00 10 5E C0 11 80 00 C6 21 5F 79 02 92]
08:02:51.541 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMacFilterMatchMessageHandler [networkId=0, filterIndexMatch=1, legacyPassthroughType=UNKNOWN, lastHopLqi=255, lastHopRssi=-46, messageContents=01 C8 C2 FF FF FF FF 32 56 DF 2F C3 FE FF E2 0A 68 0B 00 0B 00 10 5E C0 11 81 00 C6 21 5F 79 02 92]
08:02:52.573 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_BROADCAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0003, sourceEndpoint=1, destinationEndpoint=255, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=F4], lastHopLqi=255, lastHopRssi=-47, sender=511D, bindingIndex=255, addressIndex=255, messageContents=01 09 01]
08:02:52.576 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=511D/1, destinationAddress=0000/255, profile=0104, cluster=0003, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=F4, rssi=-47, lqi=FF, payload=01 09 01]
08:02:52.578 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - Incoming message from unknown node 511D: Notifying announce listeners
08:02:52.580 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=CLUSTER_SPECIFIC_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=9, commandId=1]
08:02:52.582 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - Unknown remote node 511D
08:02:52.583 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - Incoming message from node 511D did not translate to command
08:02:58.552 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspChildJoinHandler [networkId=0, index=0, joining=false, childId=511D, childEui64=680AE2FFFEC32FDF, childType=EMBER_SLEEPY_END_DEVICE]
08:02:58.555 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 680AE2FFFEC32FDF: nodeStatusUpdate - node status is DEVICE_LEFT, network address is 511D.
08:02:58.557 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 20765: Node has left, but wasn't found in the network.
08:02:58.559 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=511D, newNodeEui64=680AE2FFFEC32FDF, status=EMBER_DEVICE_LEFT, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=FFFF]
08:02:58.561 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 680AE2FFFEC32FDF: nodeStatusUpdate - node status is DEVICE_LEFT, network address is 511D.
08:02:58.563 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 20765: Node has left, but wasn't found in the network.
08:03:08.875 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspChildJoinHandler [networkId=0, index=0, joining=true, childId=8B4F, childEui64=680AE2FFFEC32FDF, childType=EMBER_SLEEPY_END_DEVICE]
08:03:08.878 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 680AE2FFFEC32FDF: nodeStatusUpdate - node status is UNSECURED_JOIN, network address is 8B4F.
08:03:08.879 [DEBUG] [app.discovery.ZigBeeNetworkDiscoverer] - 680AE2FFFEC32FDF: Device status updated. NWK=8B4F
08:03:08.881 [DEBUG] [app.discovery.ZigBeeNetworkDiscoverer] - 680AE2FFFEC32FDF: NWK Discovery add node 8B4F
08:03:08.883 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode  ] - 680AE2FFFEC32FDF: Node state updated from UNKNOWN to ONLINE
08:03:08.885 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 680AE2FFFEC32FDF: Updating node NWK=8B4F
08:03:08.887 [DEBUG] [pp.discovery.ZigBeeDiscoveryExtension] - 680AE2FFFEC32FDF: DISCOVERY Extension: Adding discoverer for node
08:03:08.887 [DEBUG] [database.ZigBeeNetworkDatabaseManager] - 680AE2FFFEC32FDF: Data store: Deferring write for 250ms.
08:03:08.888 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 680AE2FFFEC32FDF: Node SVC Discovery: created discoverer
08:03:08.889 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 680AE2FFFEC32FDF: Node SVC Discovery: start discovery
08:03:08.889 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 680AE2FFFEC32FDF: Node SVC Discovery: starting new tasks [POWER_DESCRIPTOR, NWK_ADDRESS, NODE_DESCRIPTOR, ACTIVE_ENDPOINTS]
08:03:08.891 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 680AE2FFFEC32FDF: Node SVC Discovery: scheduled [NWK_ADDRESS, POWER_DESCRIPTOR, NODE_DESCRIPTOR, ACTIVE_ENDPOINTS]
08:03:08.897 [INFO ] [gbee.discovery.ZigBeeDiscoveryService] - 680AE2FFFEC32FDF: Starting ZigBee device discovery
08:03:08.898 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - 680AE2FFFEC32FDF: Creating ZigBee device zigbee:device with bridge zigbee:coordinator_ember:013725D7
08:03:08.900 [INFO ] [ig.discovery.internal.PersistentInbox] - Added new thing 'zigbee:device:013725D7:680ae2fffec32fdf' to inbox.
08:03:08.900 [INFO ] [smarthome.event.InboxAddedEvent      ] - Discovery Result with UID 'zigbee:device:013725D7:680ae2fffec32fdf' has been added.
08:03:08.901 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - 680AE2FFFEC32FDF: Node discovery not complete
08:03:09.084 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=8B4F, newNodeEui64=680AE2FFFEC32FDF, status=EMBER_STANDARD_SECURITY_UNSECURED_JOIN, policyDecision=EMBER_USE_PRECONFIGURED_KEY, parentOfNewNodeId=0000]
08:03:09.086 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 680AE2FFFEC32FDF: nodeStatusUpdate - node status is UNSECURED_JOIN, network address is 8B4F.
08:03:09.088 [DEBUG] [app.discovery.ZigBeeNetworkDiscoverer] - 680AE2FFFEC32FDF: Device status updated. NWK=8B4F
08:03:09.089 [DEBUG] [app.discovery.ZigBeeNetworkDiscoverer] - 680AE2FFFEC32FDF: NWK Discovery add node 8B4F
08:03:09.090 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode  ] - 680AE2FFFEC32FDF: Node state updated from UNKNOWN to ONLINE
08:03:09.091 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 680AE2FFFEC32FDF: Updating node NWK=8B4F
08:03:09.092 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 680AE2FFFEC32FDF: Node update. NWK Address=8B4F
08:03:09.093 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 680AE2FFFEC32FDF: Node 8B4F is not updated
08:03:09.139 [DEBUG] [database.ZigBeeNetworkDatabaseManager] - 680AE2FFFEC32FDF: Data store: Writing node.
08:03:09.145 [DEBUG] [nding.zigbee.internal.ZigBeeDataStore] - 680AE2FFFEC32FDF: ZigBee saving network state complete.
08:03:10.203 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 680AE2FFFEC32FDF: Node SVC Discovery: running NWK_ADDRESS
08:03:10.205 [DEBUG] [.transaction.ZigBeeTransactionManager] - 680AE2FFFEC32FDF: Creating new Transaction Queue
08:03:10.208 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: Set profile to ZigBeeTransactionProfile [maxOutstandingTransactions=1, interTransactionDelay=50, maxRetries=2]
08:03:10.211 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=0, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> 8B4F/0, cluster=0000, TID=--, ieeeAddr=680AE2FFFEC32FDF, requestType=0, startIndex=0]]
08:03:10.212 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
08:03:10.213 [DEBUG] [.transaction.ZigBeeTransactionManager] - 8B4F/0: Sending ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=3, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> 8B4F/0, cluster=0000, TID=BB, ieeeAddr=680AE2FFFEC32FDF, requestType=0, startIndex=0]]
08:03:10.213 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
08:03:10.214 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0000/0 -> 8B4F/0, cluster=0000, TID=BB, ieeeAddr=680AE2FFFEC32FDF, requestType=0, startIndex=0]
08:03:10.215 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=8B4F/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=35, rssi=--, lqi=--, payload=BB DF 2F C3 FE FF E2 0A 68 00 00]
08:03:10.225 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=BD]
08:03:10.246 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=8B4F, apsFrame=EmberApsFrame [profileId=0000, clusterId=0000, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=BD], messageTag=BB, status=EMBER_SUCCESS, messageContents=]
08:03:10.247 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=BB state=RX_ACK
08:03:10.247 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=8000, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=BE], lastHopLqi=255, lastHopRssi=0, sender=0000, bindingIndex=255, addressIndex=255, messageContents=BB 00 DF 2F C3 FE FF E2 0A 68 4F 8B]
08:03:10.248 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=BB, state=RX_ACK, outstanding=1
08:03:10.249 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=8000, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=BE, rssi=0, lqi=FF, payload=BB 00 DF 2F C3 FE FF E2 0A 68 4F 8B]
08:03:10.250 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=8B4F, TID=BB, event=RX_ACK, state=ACKED
08:03:10.251 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: NetworkAddressResponse [0000/0 -> 0000/0, cluster=8000, TID=BB, status=SUCCESS, ieeeAddrRemoteDev=680AE2FFFEC32FDF, nwkAddrRemoteDev=8B4F, startIndex=null, nwkAddrAssocDevList=[]]
08:03:10.252 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NetworkAddressResponse [0000/0 -> 0000/0, cluster=8000, TID=BB, status=SUCCESS, ieeeAddrRemoteDev=680AE2FFFEC32FDF, nwkAddrRemoteDev=8B4F, startIndex=null, nwkAddrAssocDevList=[]]
08:03:10.254 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=44, state=COMPLETE, sendCnt=1, command=NetworkAddressRequest [0000/0 -> 8B4F/0, cluster=0000, TID=BB, ieeeAddr=680AE2FFFEC32FDF, requestType=0, startIndex=0]]
08:03:10.254 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 680AE2FFFEC32FDF: Node SVC Discovery: NetworkAddressRequest returned NetworkAddressResponse [0000/0 -> 0000/0, cluster=8000, TID=BB, status=SUCCESS, ieeeAddrRemoteDev=680AE2FFFEC32FDF, nwkAddrRemoteDev=8B4F, startIndex=null, nwkAddrAssocDevList=[]]
08:03:10.255 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
08:03:10.256 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 680AE2FFFEC32FDF: Node SVC Discovery: NetworkAddressRequest confirmed by unicast
08:03:10.257 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: transactionComplete, state=COMPLETE, outstanding=0
08:03:10.257 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 680AE2FFFEC32FDF: Node SVC Discovery: request NWK_ADDRESS successful. Advancing to NODE_DESCRIPTOR.
08:03:10.258 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=0, sleepy=0/3
08:03:10.258 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 680AE2FFFEC32FDF: Node SVC Discovery: running NODE_DESCRIPTOR
08:03:10.260 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=0, state=WAITING, sendCnt=0, command=NodeDescriptorRequest [0000/0 -> 8B4F/0, cluster=0002, TID=--, nwkAddrOfInterest=8B4F]]
08:03:10.261 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
08:03:10.263 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
08:03:10.264 [DEBUG] [.transaction.ZigBeeTransactionManager] - 8B4F/0: Sending ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=3, state=WAITING, sendCnt=0, command=NodeDescriptorRequest [0000/0 -> 8B4F/0, cluster=0002, TID=BC, nwkAddrOfInterest=8B4F]]
08:03:10.264 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
08:03:10.265 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NodeDescriptorRequest [0000/0 -> 8B4F/0, cluster=0002, TID=BC, nwkAddrOfInterest=8B4F]
08:03:10.266 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=8B4F/0, profile=0000, cluster=0002, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=36, rssi=--, lqi=--, payload=BC 4F 8B]
08:03:10.275 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=BF]
08:03:11.085 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspChildJoinHandler [networkId=0, index=0, joining=true, childId=8B4F, childEui64=680AE2FFFEC32FDF, childType=EMBER_SLEEPY_END_DEVICE]
08:03:11.089 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 680AE2FFFEC32FDF: nodeStatusUpdate - node status is UNSECURED_JOIN, network address is 8B4F.
08:03:11.091 [DEBUG] [app.discovery.ZigBeeNetworkDiscoverer] - 680AE2FFFEC32FDF: Device status updated. NWK=8B4F
08:03:11.093 [DEBUG] [app.discovery.ZigBeeNetworkDiscoverer] - 680AE2FFFEC32FDF: NWK Discovery add node 8B4F
08:03:11.095 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode  ] - 680AE2FFFEC32FDF: Node state updated from UNKNOWN to ONLINE
08:03:11.097 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 680AE2FFFEC32FDF: Updating node NWK=8B4F
08:03:11.098 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 680AE2FFFEC32FDF: Node update. NWK Address=8B4F
08:03:11.099 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 680AE2FFFEC32FDF: Node 8B4F is not updated
08:03:11.297 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=8B4F, newNodeEui64=680AE2FFFEC32FDF, status=EMBER_STANDARD_SECURITY_UNSECURED_JOIN, policyDecision=EMBER_USE_PRECONFIGURED_KEY, parentOfNewNodeId=0000]
08:03:11.299 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 680AE2FFFEC32FDF: nodeStatusUpdate - node status is UNSECURED_JOIN, network address is 8B4F.
08:03:11.301 [DEBUG] [app.discovery.ZigBeeNetworkDiscoverer] - 680AE2FFFEC32FDF: Device status updated. NWK=8B4F
08:03:11.303 [DEBUG] [app.discovery.ZigBeeNetworkDiscoverer] - 680AE2FFFEC32FDF: NWK Discovery add node 8B4F
08:03:11.305 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode  ] - 680AE2FFFEC32FDF: Node state updated from UNKNOWN to ONLINE
08:03:11.307 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 680AE2FFFEC32FDF: Updating node NWK=8B4F
08:03:11.309 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 680AE2FFFEC32FDF: Node update. NWK Address=8B4F
08:03:11.311 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 680AE2FFFEC32FDF: Node 8B4F is not updated
08:03:11.345 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingSenderEui64Handler [networkId=0, senderEui64=680AE2FFFEC32FDF]
08:03:11.347 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_BROADCAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=0013, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_SOURCE_EUI64], groupId=0, sequence=3C], lastHopLqi=255, lastHopRssi=-44, sender=8B4F, bindingIndex=255, addressIndex=255, messageContents=81 4F 8B DF 2F C3 FE FF E2 0A 68 80]
08:03:11.348 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=8B4F/0, destinationAddress=0000/0, profile=0000, cluster=0013, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=3C, rssi=-44, lqi=FF, payload=81 4F 8B DF 2F C3 FE FF E2 0A 68 80]
08:03:11.349 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: DeviceAnnounce [8B4F/0 -> 0000/0, cluster=0013, TID=81, nwkAddrOfInterest=8B4F, ieeeAddr=680AE2FFFEC32FDF, capability=80]
08:03:11.350 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionCommand: DeviceAnnounce [8B4F/0 -> 0000/0, cluster=0013, TID=81, nwkAddrOfInterest=8B4F, ieeeAddr=680AE2FFFEC32FDF, capability=80]
08:03:11.352 [DEBUG] [app.discovery.ZigBeeNetworkDiscoverer] - 680AE2FFFEC32FDF: Device announce received. From 8B4F, for 8B4F
08:03:11.353 [DEBUG] [app.discovery.ZigBeeNetworkDiscoverer] - 680AE2FFFEC32FDF: NWK Discovery add node 8B4F
08:03:11.354 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode  ] - 680AE2FFFEC32FDF: Node state updated from UNKNOWN to ONLINE
08:03:11.355 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 680AE2FFFEC32FDF: Updating node NWK=8B4F
08:03:11.356 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 680AE2FFFEC32FDF: Node update. NWK Address=8B4F
08:03:11.359 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 680AE2FFFEC32FDF: Node 8B4F is not updated
08:03:14.505 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspZigbeeKeyEstablishmentHandler [networkId=0, partner=680AE2FFFEC32FDF, status=EMBER_EEPROM_MFG_VERSION_MISMATCH]
08:03:16.656 [INFO ] [smarthome.event.InboxRemovedEvent    ] - Discovery Result with UID 'zigbee:device:013725D7:680ae2fffec32fdf' has been removed.
08:03:16.666 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zigbee:device:013725D7:680ae2fffec32fdf' changed from UNINITIALIZED to INITIALIZING
08:03:16.669 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 680AE2FFFEC32FDF: Initializing ZigBee thing handler zigbee:device:013725D7:680ae2fffec32fdf
08:03:16.670 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zigbee:device:013725D7:680ae2fffec32fdf' changed from INITIALIZING to UNKNOWN
08:03:16.670 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 680AE2FFFEC32FDF: Coordinator status changed to ONLINE.
08:03:16.672 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 680AE2FFFEC32FDF: Coordinator is ONLINE. Starting device initialisation.
08:03:16.672 [DEBUG] [app.discovery.ZigBeeNetworkDiscoverer] - 680AE2FFFEC32FDF: NWK Discovery starting node rediscovery
08:03:16.673 [DEBUG] [app.discovery.ZigBeeNetworkDiscoverer] - 680AE2FFFEC32FDF: NWK Discovery: Rediscovery using unicast to 8B4F
08:03:16.674 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=0, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> 8B4F/0, cluster=0000, TID=--, ieeeAddr=680AE2FFFEC32FDF, requestType=0, startIndex=0]]
08:03:16.675 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3
08:03:16.683 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 680AE2FFFEC32FDF: Node has not finished discovery
08:03:16.685 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zigbee:device:013725D7:680ae2fffec32fdf' changed from UNKNOWN to OFFLINE: Node has not completed discovery
08:03:16.689 [INFO ] [arthome.event.FirmwareStatusInfoEvent] - Firmware status of thing zigbee:device:013725D7:680ae2fffec32fdf changed to UNKNOWN.
08:03:19.588 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=8002, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=3F], lastHopLqi=255, lastHopRssi=-45, sender=8B4F, bindingIndex=255, addressIndex=255, messageContents=BC 00 4F 8B 02 40 80 7C 11 52 52 00 00 2C 52 00 00]
08:03:19.591 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=8B4F/0, destinationAddress=0000/0, profile=0000, cluster=8002, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=3F, rssi=-45, lqi=FF, payload=BC 00 4F 8B 02 40 80 7C 11 52 52 00 00 2C 52 00 00]
08:03:19.594 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: NodeDescriptorResponse [8B4F/0 -> 0000/0, cluster=8002, TID=BC, status=SUCCESS, nwkAddrOfInterest=8B4F, nodeDescriptor=NodeDescriptor [apsFlags=0, bufferSize=82, complexDescriptorAvailable=false, manufacturerCode=117C, logicalType=END_DEVICE, serverCapabilities=[], incomingTransferSize=82, outgoingTransferSize=82, userDescriptorAvailable=false, frequencyBands=[FREQ_2400_MHZ], macCapabilities=[REDUCED_FUNCTION_DEVICE], extendedEndpointListAvailable=false, extendedSimpleDescriptorListAvailable=false, stackCompliance=22]]
08:03:19.596 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NodeDescriptorResponse [8B4F/0 -> 0000/0, cluster=8002, TID=BC, status=SUCCESS, nwkAddrOfInterest=8B4F, nodeDescriptor=NodeDescriptor [apsFlags=0, bufferSize=82, complexDescriptorAvailable=false, manufacturerCode=117C, logicalType=END_DEVICE, serverCapabilities=[], incomingTransferSize=82, outgoingTransferSize=82, userDescriptorAvailable=false, frequencyBands=[FREQ_2400_MHZ], macCapabilities=[REDUCED_FUNCTION_DEVICE], extendedEndpointListAvailable=false, extendedSimpleDescriptorListAvailable=false, stackCompliance=22]]
08:03:19.599 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=9339, state=COMPLETE, sendCnt=1, command=NodeDescriptorRequest [0000/0 -> 8B4F/0, cluster=0002, TID=BC, nwkAddrOfInterest=8B4F]]
08:03:19.599 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 680AE2FFFEC32FDF: Node SVC Discovery: NodeDescriptorResponse returned NodeDescriptorResponse [8B4F/0 -> 0000/0, cluster=8002, TID=BC, status=SUCCESS, nwkAddrOfInterest=8B4F, nodeDescriptor=NodeDescriptor [apsFlags=0, bufferSize=82, complexDescriptorAvailable=false, manufacturerCode=117C, logicalType=END_DEVICE, serverCapabilities=[], incomingTransferSize=82, outgoingTransferSize=82, userDescriptorAvailable=false, frequencyBands=[FREQ_2400_MHZ], macCapabilities=[REDUCED_FUNCTION_DEVICE], extendedEndpointListAvailable=false, extendedSimpleDescriptorListAvailable=false, stackCompliance=22]]
08:03:19.600 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
08:03:19.601 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 680AE2FFFEC32FDF: Node SVC Discovery: request NODE_DESCRIPTOR successful. Advancing to POWER_DESCRIPTOR.
08:03:19.601 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: transactionComplete, state=COMPLETE, outstanding=0
08:03:19.602 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 680AE2FFFEC32FDF: Node SVC Discovery: running POWER_DESCRIPTOR
08:03:19.602 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
08:03:19.603 [DEBUG] [.transaction.ZigBeeTransactionManager] - 8B4F/0: Sending ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=2929, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> 8B4F/0, cluster=0000, TID=BD, ieeeAddr=680AE2FFFEC32FDF, requestType=0, startIndex=0]]
08:03:19.604 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
08:03:19.605 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0000/0 -> 8B4F/0, cluster=0000, TID=BD, ieeeAddr=680AE2FFFEC32FDF, requestType=0, startIndex=0]
08:03:19.605 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=8B4F/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=37, rssi=--, lqi=--, payload=BD DF 2F C3 FE FF E2 0A 68 00 00]
08:03:19.606 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=0, state=WAITING, sendCnt=0, command=PowerDescriptorRequest [0000/0 -> 8B4F/0, cluster=0003, TID=--, nwkAddrOfInterest=8B4F]]
08:03:19.607 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3
08:03:19.608 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=8B4F, apsFrame=EmberApsFrame [profileId=0000, clusterId=0002, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=BF], messageTag=BC, status=EMBER_SUCCESS, messageContents=]
08:03:19.628 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=C3]
08:03:19.628 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=BC state=RX_ACK
08:03:19.629 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=8B4F, apsFrame=EmberApsFrame [profileId=0000, clusterId=0000, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=C3], messageTag=BD, status=EMBER_SUCCESS, messageContents=]
08:03:19.629 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=BC, state=RX_ACK, outstanding=1
08:03:19.630 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=8000, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=C4], lastHopLqi=255, lastHopRssi=0, sender=0000, bindingIndex=255, addressIndex=255, messageContents=BD 00 DF 2F C3 FE FF E2 0A 68 4F 8B]
08:03:19.630 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=BD state=RX_ACK
08:03:19.631 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=8000, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=C4, rssi=0, lqi=FF, payload=BD 00 DF 2F C3 FE FF E2 0A 68 4F 8B]
08:03:19.632 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=BD, state=RX_ACK, outstanding=1
08:03:19.633 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: NetworkAddressResponse [0000/0 -> 0000/0, cluster=8000, TID=BD, status=SUCCESS, ieeeAddrRemoteDev=680AE2FFFEC32FDF, nwkAddrRemoteDev=8B4F, startIndex=null, nwkAddrAssocDevList=[]]
08:03:19.633 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=8B4F, TID=BD, event=RX_ACK, state=ACKED
08:03:19.634 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NetworkAddressResponse [0000/0 -> 0000/0, cluster=8000, TID=BD, status=SUCCESS, ieeeAddrRemoteDev=680AE2FFFEC32FDF, nwkAddrRemoteDev=8B4F, startIndex=null, nwkAddrAssocDevList=[]]
08:03:19.636 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=2962, state=COMPLETE, sendCnt=1, command=NetworkAddressRequest [0000/0 -> 8B4F/0, cluster=0000, TID=BD, ieeeAddr=680AE2FFFEC32FDF, requestType=0, startIndex=0]]
08:03:19.636 [DEBUG] [app.discovery.ZigBeeNetworkDiscoverer] - 680AE2FFFEC32FDF: NWK Discovery NetworkAddressRequest returned from NetworkAddressResponse [0000/0 -> 0000/0, cluster=8000, TID=BD, status=SUCCESS, ieeeAddrRemoteDev=680AE2FFFEC32FDF, nwkAddrRemoteDev=8B4F, startIndex=null, nwkAddrAssocDevList=[]]
08:03:19.637 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
08:03:19.638 [DEBUG] [app.discovery.ZigBeeNetworkDiscoverer] - 680AE2FFFEC32FDF: NWK Discovery: Rediscovery found network address to 8B4F
08:03:19.638 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: transactionComplete, state=COMPLETE, outstanding=0
08:03:19.639 [DEBUG] [app.discovery.ZigBeeNetworkDiscoverer] - 680AE2FFFEC32FDF: NWK Discovery add node 8B4F
08:03:19.640 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
08:03:19.641 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode  ] - 680AE2FFFEC32FDF: Node state updated from UNKNOWN to ONLINE
08:03:19.642 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 680AE2FFFEC32FDF: Updating node NWK=8B4F
08:03:19.643 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 680AE2FFFEC32FDF: Node update. NWK Address=8B4F
08:03:19.643 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 680AE2FFFEC32FDF: Node 8B4F is not updated
08:03:19.644 [DEBUG] [app.discovery.ZigBeeNetworkDiscoverer] - NWK Discovery for 8B4F scheduling node discovery
08:03:19.645 [DEBUG] [app.discovery.ZigBeeNetworkDiscoverer] - NWK Discovery for 8B4F starting node discovery
08:03:19.646 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: Added transaction to queue, len=2, transaction=ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=0, state=WAITING, sendCnt=0, command=IeeeAddressRequest [0000/0 -> 8B4F/0, cluster=0001, TID=--, nwkAddrOfInterest=8B4F, requestType=1, startIndex=0]]
08:03:19.647 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
08:03:19.653 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
08:03:19.654 [DEBUG] [.transaction.ZigBeeTransactionManager] - 8B4F/0: Sending ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=48, state=WAITING, sendCnt=0, command=PowerDescriptorRequest [0000/0 -> 8B4F/0, cluster=0003, TID=BE, nwkAddrOfInterest=8B4F]]
08:03:19.655 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
08:03:19.656 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: PowerDescriptorRequest [0000/0 -> 8B4F/0, cluster=0003, TID=BE, nwkAddrOfInterest=8B4F]
08:03:19.657 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=8B4F/0, profile=0000, cluster=0003, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=38, rssi=--, lqi=--, payload=BE 4F 8B]
08:03:19.666 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=C5]
08:03:19.704 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3
08:03:20.745 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=8003, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=40], lastHopLqi=255, lastHopRssi=-45, sender=8B4F, bindingIndex=255, addressIndex=255, messageContents=BE 00 4F 8B 10 C1]
08:03:20.748 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=8B4F/0, destinationAddress=0000/0, profile=0000, cluster=8003, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=40, rssi=-45, lqi=FF, payload=BE 00 4F 8B 10 C1]
08:03:20.751 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: PowerDescriptorResponse [8B4F/0 -> 0000/0, cluster=8003, TID=BE, status=SUCCESS, nwkAddrOfInterest=8B4F, powerDescriptor=PowerDescriptor [currentPowerMode=RECEIVER_ON_IDLE, availablePowerSources=[MAINS], currentPowerSource=MAINS, powerLevel=FULL]]
08:03:20.753 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionCommand: PowerDescriptorResponse [8B4F/0 -> 0000/0, cluster=8003, TID=BE, status=SUCCESS, nwkAddrOfInterest=8B4F, powerDescriptor=PowerDescriptor [currentPowerMode=RECEIVER_ON_IDLE, availablePowerSources=[MAINS], currentPowerSource=MAINS, powerLevel=FULL]]
08:03:20.755 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 680AE2FFFEC32FDF: Node SVC Discovery: PowerDescriptorResponse returned PowerDescriptorResponse [8B4F/0 -> 0000/0, cluster=8003, TID=BE, status=SUCCESS, nwkAddrOfInterest=8B4F, powerDescriptor=PowerDescriptor [currentPowerMode=RECEIVER_ON_IDLE, availablePowerSources=[MAINS], currentPowerSource=MAINS, powerLevel=FULL]]
08:03:20.756 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 680AE2FFFEC32FDF: Node SVC Discovery: request POWER_DESCRIPTOR successful. Advancing to ACTIVE_ENDPOINTS.
08:03:20.756 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=1150, state=COMPLETE, sendCnt=1, command=PowerDescriptorRequest [0000/0 -> 8B4F/0, cluster=0003, TID=BE, nwkAddrOfInterest=8B4F]]
08:03:20.756 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 680AE2FFFEC32FDF: Node SVC Discovery: running ACTIVE_ENDPOINTS
08:03:20.757 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
08:03:20.758 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: Added transaction to queue, len=2, transaction=ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=0, state=WAITING, sendCnt=0, command=ActiveEndpointsRequest [0000/0 -> 8B4F/0, cluster=0005, TID=--, nwkAddrOfInterest=8B4F]]
08:03:20.758 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
08:03:20.759 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: transactionComplete, state=COMPLETE, outstanding=0
08:03:20.760 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
08:03:20.760 [DEBUG] [.transaction.ZigBeeTransactionManager] - 8B4F/0: Sending ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=1114, state=WAITING, sendCnt=0, command=IeeeAddressRequest [0000/0 -> 8B4F/0, cluster=0001, TID=BF, nwkAddrOfInterest=8B4F, requestType=1, startIndex=0]]
08:03:20.761 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
08:03:20.761 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: IeeeAddressRequest [0000/0 -> 8B4F/0, cluster=0001, TID=BF, nwkAddrOfInterest=8B4F, requestType=1, startIndex=0]
08:03:20.762 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=8B4F/0, profile=0000, cluster=0001, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=39, rssi=--, lqi=--, payload=BF 4F 8B 01 00]
08:03:20.765 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=8B4F, apsFrame=EmberApsFrame [profileId=0000, clusterId=0003, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=C5], messageTag=BE, status=EMBER_SUCCESS, messageContents=]
08:03:20.785 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=C6]
08:03:20.785 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=BE state=RX_ACK
08:03:20.787 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=8B4F, apsFrame=EmberApsFrame [profileId=0000, clusterId=0001, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=C6], messageTag=BF, status=EMBER_SUCCESS, messageContents=]
08:03:20.787 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=BE, state=RX_ACK, outstanding=1
08:03:20.788 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=8001, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=C7], lastHopLqi=255, lastHopRssi=0, sender=0000, bindingIndex=255, addressIndex=255, messageContents=BF 00 DF 2F C3 FE FF E2 0A 68 4F 8B 00]
08:03:20.788 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=BF state=RX_ACK
08:03:20.789 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=8001, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=C7, rssi=0, lqi=FF, payload=BF 00 DF 2F C3 FE FF E2 0A 68 4F 8B 00]
08:03:20.790 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=BF, state=RX_ACK, outstanding=1
08:03:20.791 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: IeeeAddressResponse [0000/0 -> 0000/0, cluster=8001, TID=BF, status=SUCCESS, ieeeAddrRemoteDev=680AE2FFFEC32FDF, nwkAddrRemoteDev=8B4F, startIndex=null, nwkAddrAssocDevList=[]]
08:03:20.791 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=8B4F, TID=BF, event=RX_ACK, state=ACKED
08:03:20.792 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionCommand: IeeeAddressResponse [0000/0 -> 0000/0, cluster=8001, TID=BF, status=SUCCESS, ieeeAddrRemoteDev=680AE2FFFEC32FDF, nwkAddrRemoteDev=8B4F, startIndex=null, nwkAddrAssocDevList=[]]
08:03:20.794 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=1148, state=COMPLETE, sendCnt=1, command=IeeeAddressRequest [0000/0 -> 8B4F/0, cluster=0001, TID=BF, nwkAddrOfInterest=8B4F, requestType=1, startIndex=0]]
08:03:20.794 [DEBUG] [app.discovery.ZigBeeNetworkDiscoverer] - NWK Discovery for 8B4F IeeeAddressRequest returned IeeeAddressResponse [0000/0 -> 0000/0, cluster=8001, TID=BF, status=SUCCESS, ieeeAddrRemoteDev=680AE2FFFEC32FDF, nwkAddrRemoteDev=8B4F, startIndex=null, nwkAddrAssocDevList=[]]
08:03:20.795 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
08:03:20.796 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: transactionComplete, state=COMPLETE, outstanding=0
08:03:20.797 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
08:03:20.810 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
08:03:20.812 [DEBUG] [.transaction.ZigBeeTransactionManager] - 8B4F/0: Sending ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=55, state=WAITING, sendCnt=0, command=ActiveEndpointsRequest [0000/0 -> 8B4F/0, cluster=0005, TID=C0, nwkAddrOfInterest=8B4F]]
08:03:20.813 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
08:03:20.814 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ActiveEndpointsRequest [0000/0 -> 8B4F/0, cluster=0005, TID=C0, nwkAddrOfInterest=8B4F]
08:03:20.815 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=8B4F/0, profile=0000, cluster=0005, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=3A, rssi=--, lqi=--, payload=C0 4F 8B]
08:03:20.824 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=C8]
08:03:21.649 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=8005, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=41], lastHopLqi=255, lastHopRssi=-45, sender=8B4F, bindingIndex=255, addressIndex=255, messageContents=C0 00 4F 8B 01 01]
08:03:21.652 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=8B4F/0, destinationAddress=0000/0, profile=0000, cluster=8005, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=41, rssi=-45, lqi=FF, payload=C0 00 4F 8B 01 01]
08:03:21.654 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ActiveEndpointsResponse [8B4F/0 -> 0000/0, cluster=8005, TID=C0, status=SUCCESS, nwkAddrOfInterest=8B4F, activeEpList=[1]]
08:03:21.656 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ActiveEndpointsResponse [8B4F/0 -> 0000/0, cluster=8005, TID=C0, status=SUCCESS, nwkAddrOfInterest=8B4F, activeEpList=[1]]
08:03:21.658 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=901, state=COMPLETE, sendCnt=1, command=ActiveEndpointsRequest [0000/0 -> 8B4F/0, cluster=0005, TID=C0, nwkAddrOfInterest=8B4F]]
08:03:21.659 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 680AE2FFFEC32FDF: Node SVC Discovery: ActiveEndpointsResponse returned CommandResult [SUCCESS, ActiveEndpointsResponse [8B4F/0 -> 0000/0, cluster=8005, TID=C0, status=SUCCESS, nwkAddrOfInterest=8B4F, activeEpList=[1]]]
08:03:21.661 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
08:03:21.663 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=1, state=WAITING, sendCnt=0, command=SimpleDescriptorRequest [0000/0 -> 8B4F/0, cluster=0004, TID=--, nwkAddrOfInterest=8B4F, endpoint=1]]
08:03:21.664 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
08:03:21.665 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: transactionComplete, state=COMPLETE, outstanding=0
08:03:21.666 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
08:03:21.666 [DEBUG] [.transaction.ZigBeeTransactionManager] - 8B4F/0: Sending ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=4, state=WAITING, sendCnt=0, command=SimpleDescriptorRequest [0000/0 -> 8B4F/0, cluster=0004, TID=C1, nwkAddrOfInterest=8B4F, endpoint=1]]
08:03:21.667 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
08:03:21.667 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: SimpleDescriptorRequest [0000/0 -> 8B4F/0, cluster=0004, TID=C1, nwkAddrOfInterest=8B4F, endpoint=1]
08:03:21.668 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=8B4F/0, profile=0000, cluster=0004, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=3B, rssi=--, lqi=--, payload=C1 4F 8B 01]
08:03:21.669 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=8B4F, apsFrame=EmberApsFrame [profileId=0000, clusterId=0005, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=C8], messageTag=C0, status=EMBER_SUCCESS, messageContents=]
08:03:21.689 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=C9]
08:03:21.689 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=C0 state=RX_ACK
08:03:21.691 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=C0, state=RX_ACK, outstanding=1
08:03:22.832 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=8004, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=42], lastHopLqi=255, lastHopRssi=-45, sender=8B4F, bindingIndex=255, addressIndex=255, messageContents=C1 00 4F 8B 20 01 04 01 20 08 01 06 00 00 01 00 03 00 20 00 00 10 7C FC 06 03 00 04 00 06 00 08 00 19 00 00 10]
08:03:22.835 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=8B4F/0, destinationAddress=0000/0, profile=0000, cluster=8004, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=42, rssi=-45, lqi=FF, payload=C1 00 4F 8B 20 01 04 01 20 08 01 06 00 00 01 00 03 00 20 00 00 10 7C FC 06 03 00 04 00 06 00 08 00 19 00 00 10]
08:03:22.838 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: SimpleDescriptorResponse [8B4F/0 -> 0000/0, cluster=8004, TID=C1, status=SUCCESS, nwkAddrOfInterest=8B4F, length=32, simpleDescriptor=SimpleDescriptor [endpoint=1, profileId=0104, deviceId=0820, deviceVersion=1, inputClusterList=[0000, 0001, 0003, 0020, 1000, FC7C], outputClusterList=[0003, 0004, 0006, 0008, 0019, 1000]]]
08:03:22.855 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionCommand: SimpleDescriptorResponse [8B4F/0 -> 0000/0, cluster=8004, TID=C1, status=SUCCESS, nwkAddrOfInterest=8B4F, length=32, simpleDescriptor=SimpleDescriptor [endpoint=1, profileId=0104, deviceId=0820, deviceVersion=1, inputClusterList=[0000, 0001, 0003, 0020, 1000, FC7C], outputClusterList=[0003, 0004, 0006, 0008, 0019, 1000]]]
08:03:22.856 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=1194, state=COMPLETE, sendCnt=1, command=SimpleDescriptorRequest [0000/0 -> 8B4F/0, cluster=0004, TID=C1, nwkAddrOfInterest=8B4F, endpoint=1]]
08:03:22.856 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 680AE2FFFEC32FDF: Node SVC Discovery: SimpleDescriptorResponse returned SimpleDescriptorResponse [8B4F/0 -> 0000/0, cluster=8004, TID=C1, status=SUCCESS, nwkAddrOfInterest=8B4F, length=32, simpleDescriptor=SimpleDescriptor [endpoint=1, profileId=0104, deviceId=0820, deviceVersion=1, inputClusterList=[0000, 0001, 0003, 0020, 1000, FC7C], outputClusterList=[0003, 0004, 0006, 0008, 0019, 1000]]]
08:03:22.857 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=8B4F, apsFrame=EmberApsFrame [profileId=0000, clusterId=0004, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=C9], messageTag=C1, status=EMBER_SUCCESS, messageContents=]
08:03:22.856 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
08:03:22.863 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=C1 state=RX_ACK
08:03:22.862 [DEBUG] [m.zsmartsystems.zigbee.ZigBeeEndpoint] - 8B4F/1: Setting input clusters [0000, 0001, 0003, 0020, 1000, FC7C]
08:03:22.863 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=C1, state=RX_ACK, outstanding=0
08:03:22.863 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: transactionComplete, state=COMPLETE, outstanding=0
08:03:22.864 [DEBUG] [m.zsmartsystems.zigbee.ZigBeeEndpoint] - 680AE2FFFEC32FDF: Endpoint 1. Setting server cluster 0000 Basic
08:03:22.865 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=0, sleepy=0/3
08:03:22.865 [DEBUG] [m.zsmartsystems.zigbee.ZigBeeEndpoint] - 680AE2FFFEC32FDF: Endpoint 1. Setting server cluster 0001 Power Configuration
08:03:22.866 [DEBUG] [m.zsmartsystems.zigbee.ZigBeeEndpoint] - 680AE2FFFEC32FDF: Endpoint 1. Setting server cluster 0003 Identify
08:03:22.867 [DEBUG] [m.zsmartsystems.zigbee.ZigBeeEndpoint] - 680AE2FFFEC32FDF: Endpoint 1. Setting server cluster 0020 Poll Control
08:03:22.868 [DEBUG] [m.zsmartsystems.zigbee.ZigBeeEndpoint] - 680AE2FFFEC32FDF: Endpoint 1. Unsupported cluster 1000 - using ZclCustomCluster
08:03:22.868 [DEBUG] [m.zsmartsystems.zigbee.ZigBeeEndpoint] - 680AE2FFFEC32FDF: Endpoint 1. Setting server cluster 1000
08:03:22.869 [DEBUG] [m.zsmartsystems.zigbee.ZigBeeEndpoint] - 680AE2FFFEC32FDF: Endpoint 1. Unsupported cluster FC7C - using ZclCustomCluster
08:03:22.869 [DEBUG] [m.zsmartsystems.zigbee.ZigBeeEndpoint] - 680AE2FFFEC32FDF: Endpoint 1. Setting server cluster FC7C
08:03:22.870 [DEBUG] [m.zsmartsystems.zigbee.ZigBeeEndpoint] - 8B4F/1: Setting output clusters [0003, 0004, 0006, 0008, 0019, 1000]
08:03:22.870 [DEBUG] [m.zsmartsystems.zigbee.ZigBeeEndpoint] - 680AE2FFFEC32FDF: Endpoint 1. Setting client cluster 0003 Identify
08:03:22.871 [DEBUG] [m.zsmartsystems.zigbee.ZigBeeEndpoint] - 680AE2FFFEC32FDF: Endpoint 1. Setting client cluster 0004 Groups
08:03:22.872 [DEBUG] [m.zsmartsystems.zigbee.ZigBeeEndpoint] - 680AE2FFFEC32FDF: Endpoint 1. Setting client cluster 0006 On/Off
08:03:22.872 [DEBUG] [m.zsmartsystems.zigbee.ZigBeeEndpoint] - 680AE2FFFEC32FDF: Endpoint 1. Setting client cluster 0008 Level Control
08:03:22.873 [DEBUG] [m.zsmartsystems.zigbee.ZigBeeEndpoint] - 680AE2FFFEC32FDF: Endpoint 1. Setting client cluster 0019 Ota Upgrade
08:03:22.874 [DEBUG] [m.zsmartsystems.zigbee.ZigBeeEndpoint] - 680AE2FFFEC32FDF: Endpoint 1. Unsupported cluster 1000 - using ZclCustomCluster
08:03:22.874 [DEBUG] [m.zsmartsystems.zigbee.ZigBeeEndpoint] - 680AE2FFFEC32FDF: Endpoint 1. Setting client cluster 1000
08:03:22.875 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 680AE2FFFEC32FDF: Node SVC Discovery: request ACTIVE_ENDPOINTS successful. Advancing to null.
08:03:22.876 [DEBUG] [discovery.ZigBeeNodeServiceDiscoverer] - 680AE2FFFEC32FDF: Node SVC Discovery: complete
08:03:22.876 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 680AE2FFFEC32FDF: Updating node NWK=8B4F
08:03:22.877 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - 680AE2FFFEC32FDF: Node update. NWK Address=8B4F
08:03:22.877 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode  ] - 680AE2FFFEC32FDF: Node descriptor updated
08:03:22.878 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode  ] - 680AE2FFFEC32FDF: Power descriptor updated
08:03:22.879 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode  ] - 680AE2FFFEC32FDF: Endpoint 1 added
08:03:22.879 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: Set profile to ZigBeeTransactionProfile [maxOutstandingTransactions=1, interTransactionDelay=50, maxRetries=2]
08:03:22.880 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 680AE2FFFEC32FDF: Node updated - ZigBeeNode [state=ONLINE, IEEE=680AE2FFFEC32FDF, NWK=8B4F, Type=END_DEVICE, endpoints=[1]]
08:03:22.879 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - 680AE2FFFEC32FDF: NodeDescriptor passed to Ember NCP NodeDescriptor [apsFlags=0, bufferSize=82, complexDescriptorAvailable=false, manufacturerCode=117C, logicalType=END_DEVICE, serverCapabilities=[], incomingTransferSize=82, outgoingTransferSize=82, userDescriptorAvailable=false, frequencyBands=[FREQ_2400_MHZ], macCapabilities=[REDUCED_FUNCTION_DEVICE], extendedEndpointListAvailable=false, extendedSimpleDescriptorListAvailable=false, stackCompliance=22]
08:03:22.879 [DEBUG] [database.ZigBeeNetworkDatabaseManager] - 680AE2FFFEC32FDF: Data store: Deferring write for 250ms.
08:03:22.881 [INFO ] [smarthome.event.ThingUpdatedEvent    ] - Thing 'zigbee:device:013725D7:680ae2fffec32fdf' has been updated.
08:03:22.880 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: Updated sleepy state from false to true
08:03:22.882 [DEBUG] [.transaction.ZigBeeTransactionManager] - Sleepy transaction count resynchronised: was 0, now 0
08:03:22.887 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSetExtendedTimeoutResponse [networkId=0]
08:03:22.890 [INFO ] [gbee.discovery.ZigBeeDiscoveryService] - 680AE2FFFEC32FDF: Starting ZigBee device discovery
08:03:22.890 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - 680AE2FFFEC32FDF: Creating ZigBee device zigbee:device with bridge zigbee:coordinator_ember:013725D7
08:03:22.891 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 680AE2FFFEC32FDF: Start initialising ZigBee Thing handler
08:03:22.892 [DEBUG] [iscovery.ZigBeeNodePropertyDiscoverer] - 680AE2FFFEC32FDF: ZigBee node property discovery start
08:03:22.892 [DEBUG] [iscovery.ZigBeeNodePropertyDiscoverer] - 680AE2FFFEC32FDF: ZigBee node property discovery start
08:03:22.893 [DEBUG] [iscovery.ZigBeeNodePropertyDiscoverer] - 680AE2FFFEC32FDF: ZigBee node property discovery using basic cluster on endpoint 8B4F/1
08:03:22.893 [DEBUG] [iscovery.ZigBeeNodePropertyDiscoverer] - 680AE2FFFEC32FDF: ZigBee node property discovery using basic cluster on endpoint 8B4F/1
08:03:22.894 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Basic: 0000/0 -> 8B4F/1, cluster=0000, TID=--, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
08:03:22.895 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
08:03:22.896 [DEBUG] [.transaction.ZigBeeTransactionManager] - 8B4F/1: Sending ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=2, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Basic: 0000/0 -> 8B4F/1, cluster=0000, TID=C2, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
08:03:22.897 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
08:03:22.898 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Basic: 0000/0 -> 8B4F/1, cluster=0000, TID=C2, identifiers=[5, 4, 3, 2, 6, 0, 1]]
08:03:22.899 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=194, commandId=0]
08:03:22.900 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=8B4F/1, profile=0104, cluster=0000, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=3C, rssi=--, lqi=--, payload=00 C2 00 05 00 04 00 03 00 02 00 06 00 00 00 01 00]
08:03:22.901 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Basic: 0000/0 -> 8B4F/1, cluster=0000, TID=--, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
08:03:22.903 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=1/3
08:03:22.912 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=CA]
08:03:22.946 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=1/3
08:03:23.132 [DEBUG] [database.ZigBeeNetworkDatabaseManager] - 680AE2FFFEC32FDF: Data store: Writing node.
08:03:23.144 [DEBUG] [nding.zigbee.internal.ZigBeeDataStore] - 680AE2FFFEC32FDF: ZigBee saving network state complete.
08:03:23.734 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0000, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=43], lastHopLqi=255, lastHopRssi=-45, sender=8B4F, bindingIndex=255, addressIndex=255, messageContents=18 C2 01 05 00 00 42 16 54 52 41 44 46 52 49 20 72 65 6D 6F 74 65 20 63 6F 6E 74 72 6F 6C 04 00 00 42 0E 49 4B 45 41 20 6F 66 20 53 77 65 64 65 6E 03 00 00 20 01 02 00 00 20 62 06 00 00 42 08 32 30 31 39 30 34 30 31 00 00 00 20 03 01 00 00 20]
08:03:23.737 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=8B4F/1, destinationAddress=0000/1, profile=0104, cluster=0000, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=43, rssi=-45, lqi=FF, payload=18 C2 01 05 00 00 42 16 54 52 41 44 46 52 49 20 72 65 6D 6F 74 65 20 63 6F 6E 74 72 6F 6C 04 00 00 42 0E 49 4B 45 41 20 6F 66 20 53 77 65 64 65 6E 03 00 00 20 01 02 00 00 20 62 06 00 00 42 08 32 30 31 39 30 34 30 31 00 00 00 20 03 01 00 00 20]
08:03:23.739 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=194, commandId=1]
08:03:23.740 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReadAttributesResponse [Basic: 8B4F/1 -> 0000/1, cluster=0000, TID=C2, records=[ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=5, attributeDataType=CHARACTER_STRING, attributeValue=TRADFRI remote control], ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=4, attributeDataType=CHARACTER_STRING, attributeValue=IKEA of Sweden], ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=3, attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeValue=1], ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=2, attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeValue=98], ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=6, attributeDataType=CHARACTER_STRING, attributeValue=20190401], ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=0, attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeValue=3], ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=1, attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeValue=null]]]
08:03:23.741 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [Basic: 8B4F/1 -> 0000/1, cluster=0000, TID=C2, records=[ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=5, attributeDataType=CHARACTER_STRING, attributeValue=TRADFRI remote control], ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=4, attributeDataType=CHARACTER_STRING, attributeValue=IKEA of Sweden], ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=3, attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeValue=1], ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=2, attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeValue=98], ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=6, attributeDataType=CHARACTER_STRING, attributeValue=20190401], ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=0, attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeValue=3], ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=1, attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeValue=null]]]
08:03:23.743 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=8B4F, apsFrame=EmberApsFrame [profileId=0104, clusterId=0000, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=CA], messageTag=C2, status=EMBER_SUCCESS, messageContents=]
08:03:23.744 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=C2 state=RX_ACK
08:03:23.745 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=C2, state=RX_ACK, outstanding=1
08:03:23.745 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=851, state=COMPLETE, sendCnt=1, command=ReadAttributesCommand [Basic: 0000/0 -> 8B4F/1, cluster=0000, TID=C2, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
08:03:23.748 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
08:03:23.747 [DEBUG] [iscovery.ZigBeeNodePropertyDiscoverer] - 680AE2FFFEC32FDF: Application version failed
08:03:23.750 [DEBUG] [iscovery.ZigBeeNodePropertyDiscoverer] - 680AE2FFFEC32FDF: ZigBee node property discovery using OTA cluster on endpoint 8B4F/1
08:03:23.751 [DEBUG] [m.zsmartsystems.zigbee.zcl.ZclCluster] - readSync request: 2
08:03:23.752 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: Added transaction to queue, len=2, transaction=ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Ota Upgrade: 0000/0 -> 8B4F/1, cluster=0019, TID=--, identifiers=[2]]]
08:03:23.753 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=1/3
08:03:23.754 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: transactionComplete, state=COMPLETE, outstanding=0
08:03:23.755 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
08:03:23.756 [DEBUG] [.transaction.ZigBeeTransactionManager] - 8B4F/1: Sending ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=855, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Basic: 0000/0 -> 8B4F/1, cluster=0000, TID=C3, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
08:03:23.756 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
08:03:23.757 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Basic: 0000/0 -> 8B4F/1, cluster=0000, TID=C3, identifiers=[5, 4, 3, 2, 6, 0, 1]]
08:03:23.758 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=195, commandId=0]
08:03:23.758 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=8B4F/1, profile=0104, cluster=0000, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=3D, rssi=--, lqi=--, payload=00 C3 00 05 00 04 00 03 00 02 00 06 00 00 00 01 00]
08:03:23.759 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=8B4F, TID=C2, event=RX_ACK, state=ACKED
08:03:23.769 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=CB]
08:03:23.806 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=1/3
08:03:23.848 [INFO ] [smarthome.event.ItemCommandEvent     ] - Item 'settings_global_light_automation' received command ON
08:03:23.849 [INFO ] [smarthome.event.ItemCommandEvent     ] - Item 'settings_livingroom_kodi_automation' received command ON
08:03:24.758 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0000, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=44], lastHopLqi=255, lastHopRssi=-45, sender=8B4F, bindingIndex=255, addressIndex=255, messageContents=18 C3 01 05 00 00 42 16 54 52 41 44 46 52 49 20 72 65 6D 6F 74 65 20 63 6F 6E 74 72 6F 6C 04 00 00 42 0E 49 4B 45 41 20 6F 66 20 53 77 65 64 65 6E 03 00 00 20 01 02 00 00 20 62 06 00 00 42 08 32 30 31 39 30 34 30 31 00 00 00 20 03 01 00 00 20]
08:03:24.762 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=8B4F/1, destinationAddress=0000/1, profile=0104, cluster=0000, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=44, rssi=-45, lqi=FF, payload=18 C3 01 05 00 00 42 16 54 52 41 44 46 52 49 20 72 65 6D 6F 74 65 20 63 6F 6E 74 72 6F 6C 04 00 00 42 0E 49 4B 45 41 20 6F 66 20 53 77 65 64 65 6E 03 00 00 20 01 02 00 00 20 62 06 00 00 42 08 32 30 31 39 30 34 30 31 00 00 00 20 03 01 00 00 20]
08:03:24.764 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=195, commandId=1]
08:03:24.764 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReadAttributesResponse [Basic: 8B4F/1 -> 0000/1, cluster=0000, TID=C3, records=[ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=5, attributeDataType=CHARACTER_STRING, attributeValue=TRADFRI remote control], ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=4, attributeDataType=CHARACTER_STRING, attributeValue=IKEA of Sweden], ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=3, attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeValue=1], ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=2, attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeValue=98], ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=6, attributeDataType=CHARACTER_STRING, attributeValue=20190401], ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=0, attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeValue=3], ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=1, attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeValue=null]]]
08:03:24.765 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [Basic: 8B4F/1 -> 0000/1, cluster=0000, TID=C3, records=[ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=5, attributeDataType=CHARACTER_STRING, attributeValue=TRADFRI remote control], ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=4, attributeDataType=CHARACTER_STRING, attributeValue=IKEA of Sweden], ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=3, attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeValue=1], ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=2, attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeValue=98], ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=6, attributeDataType=CHARACTER_STRING, attributeValue=20190401], ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=0, attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeValue=3], ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=1, attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeValue=null]]]
08:03:24.766 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=1865, state=COMPLETE, sendCnt=1, command=ReadAttributesCommand [Basic: 0000/0 -> 8B4F/1, cluster=0000, TID=C3, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
08:03:24.766 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=8B4F, apsFrame=EmberApsFrame [profileId=0104, clusterId=0000, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=CB], messageTag=C3, status=EMBER_SUCCESS, messageContents=]
08:03:24.766 [DEBUG] [iscovery.ZigBeeNodePropertyDiscoverer] - 680AE2FFFEC32FDF: Application version failed
08:03:24.767 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=C3 state=RX_ACK
08:03:24.767 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
08:03:24.768 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=C3, state=RX_ACK, outstanding=0
08:03:24.768 [DEBUG] [iscovery.ZigBeeNodePropertyDiscoverer] - 680AE2FFFEC32FDF: ZigBee node property discovery using OTA cluster on endpoint 8B4F/1
08:03:24.769 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: transactionComplete, state=COMPLETE, outstanding=0
08:03:24.770 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
08:03:24.771 [DEBUG] [.transaction.ZigBeeTransactionManager] - 8B4F/1: Sending ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=1019, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Ota Upgrade: 0000/0 -> 8B4F/1, cluster=0019, TID=C4, identifiers=[2]]]
08:03:24.771 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
08:03:24.772 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Ota Upgrade: 0000/0 -> 8B4F/1, cluster=0019, TID=C4, identifiers=[2]]
08:03:24.772 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=196, commandId=0]
08:03:24.773 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=8B4F/1, profile=0104, cluster=0019, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=3E, rssi=--, lqi=--, payload=08 C4 00 02 00]
08:03:24.774 [DEBUG] [m.zsmartsystems.zigbee.zcl.ZclCluster] - readSync request: 2
08:03:24.775 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Ota Upgrade: 0000/0 -> 8B4F/1, cluster=0019, TID=--, identifiers=[2]]]
08:03:24.775 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=1/3
08:03:24.782 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=CC]
08:03:24.821 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=1/3
08:03:25.286 [INFO ] [smarthome.event.ThingUpdatedEvent    ] - Thing 'yamahareceiver:zone:946ab0b3f65e:ZoneID1' has been updated.
08:03:25.405 [INFO ] [smarthome.event.ThingUpdatedEvent    ] - Thing 'yamahareceiver:zone:946ab0b3f65e:ZoneID2' has been updated.
08:03:25.776 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=45], lastHopLqi=255, lastHopRssi=-45, sender=8B4F, bindingIndex=255, addressIndex=255, messageContents=10 C4 01 02 00 00 23 31 46 01 23]
08:03:25.778 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=8B4F/1, destinationAddress=0000/1, profile=0104, cluster=0019, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=45, rssi=-45, lqi=FF, payload=10 C4 01 02 00 00 23 31 46 01 23]
08:03:25.780 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=196, commandId=1]
08:03:25.782 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReadAttributesResponse [Ota Upgrade: 8B4F/1 -> 0000/1, cluster=0019, TID=C4, records=[ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=2, attributeDataType=UNSIGNED_32_BIT_INTEGER, attributeValue=587286065]]]
08:03:25.784 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [Ota Upgrade: 8B4F/1 -> 0000/1, cluster=0019, TID=C4, records=[ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=2, attributeDataType=UNSIGNED_32_BIT_INTEGER, attributeValue=587286065]]]
08:03:25.787 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=2035, state=COMPLETE, sendCnt=1, command=ReadAttributesCommand [Ota Upgrade: 0000/0 -> 8B4F/1, cluster=0019, TID=C4, identifiers=[2]]]
08:03:25.787 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=8B4F, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=CC], messageTag=C4, status=EMBER_SUCCESS, messageContents=]
08:03:25.789 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=C4 state=RX_ACK
08:03:25.790 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=C4, state=RX_ACK, outstanding=0
08:03:25.787 [DEBUG] [iscovery.ZigBeeNodePropertyDiscoverer] - 680AE2FFFEC32FDF: ZigBee node property discovery complete: {zigbee_logicaltype=END_DEVICE, zigbee_powerlevel=FULL, zigbee_manufacturercode=0x117c, modelId=TRADFRI remote control, zigbee_networkaddress=35663, zigbee_powersource=MAINS, zigbee_stkversion=98, zigbee_datecode=20190401, zigbee_zclversion=3, zigbee_routes=[], zigbee_lastupdate=, zigbee_stkcompliance=22, vendor=IKEA of Sweden, zigbee_powermode=RECEIVER_ON_IDLE, zigbee_powersources=[MAINS], hardwareVersion=1, zigbee_neighbors=[], firmwareVersion=0x23014631, zigbee_devices=[]}
08:03:25.788 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
08:03:25.794 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 680AE2FFFEC32FDF: Checking endpoint 1 channels
08:03:25.794 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: transactionComplete, state=COMPLETE, outstanding=0
08:03:25.796 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: Added transaction to queue, len=2, transaction=ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=0, state=WAITING, sendCnt=0, command=DiscoverAttributesCommand [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=--, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]]
08:03:25.797 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
08:03:25.797 [DEBUG] [.transaction.ZigBeeTransactionManager] - 8B4F/1: Sending ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=1022, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Ota Upgrade: 0000/0 -> 8B4F/1, cluster=0019, TID=C5, identifiers=[2]]]
08:03:25.798 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
08:03:25.799 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Ota Upgrade: 0000/0 -> 8B4F/1, cluster=0019, TID=C5, identifiers=[2]]
08:03:25.800 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=197, commandId=0]
08:03:25.800 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=8B4F/1, profile=0104, cluster=0019, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=3F, rssi=--, lqi=--, payload=08 C5 00 02 00]
08:03:25.795 [INFO ] [smarthome.event.ThingUpdatedEvent    ] - Thing 'zigbee:device:013725D7:680ae2fffec32fdf' has been updated.
08:03:25.801 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=1/3
08:03:25.809 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=CD]
08:03:25.847 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=1/3
08:03:26.835 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=46], lastHopLqi=255, lastHopRssi=-45, sender=8B4F, bindingIndex=255, addressIndex=255, messageContents=10 C5 01 02 00 00 23 31 46 01 23]
08:03:26.838 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=8B4F/1, destinationAddress=0000/1, profile=0104, cluster=0019, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=46, rssi=-45, lqi=FF, payload=10 C5 01 02 00 00 23 31 46 01 23]
08:03:26.840 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=197, commandId=1]
08:03:26.842 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReadAttributesResponse [Ota Upgrade: 8B4F/1 -> 0000/1, cluster=0019, TID=C5, records=[ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=2, attributeDataType=UNSIGNED_32_BIT_INTEGER, attributeValue=587286065]]]
08:03:26.844 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [Ota Upgrade: 8B4F/1 -> 0000/1, cluster=0019, TID=C5, records=[ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=2, attributeDataType=UNSIGNED_32_BIT_INTEGER, attributeValue=587286065]]]
08:03:26.846 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=2071, state=COMPLETE, sendCnt=1, command=ReadAttributesCommand [Ota Upgrade: 0000/0 -> 8B4F/1, cluster=0019, TID=C5, identifiers=[2]]]
08:03:26.846 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=8B4F, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=CD], messageTag=C5, status=EMBER_SUCCESS, messageContents=]
08:03:26.846 [DEBUG] [iscovery.ZigBeeNodePropertyDiscoverer] - 680AE2FFFEC32FDF: ZigBee node property discovery complete: {zigbee_logicaltype=END_DEVICE, zigbee_powerlevel=FULL, zigbee_manufacturercode=0x117c, modelId=TRADFRI remote control, zigbee_networkaddress=35663, zigbee_powersource=MAINS, zigbee_stkversion=98, zigbee_datecode=20190401, zigbee_zclversion=3, vendor=IKEA of Sweden, zigbee_powermode=RECEIVER_ON_IDLE, zigbee_powersources=[MAINS], hardwareVersion=1, firmwareVersion=0x23014631}
08:03:26.848 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=C5 state=RX_ACK
08:03:26.847 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
08:03:26.849 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=C5, state=RX_ACK, outstanding=0
08:03:26.848 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - 680AE2FFFEC32FDF: Update ZigBee device zigbee:device with bridge zigbee:coordinator_ember:013725D7, label 'IKEA of Sweden TRADFRI remote control'
08:03:26.849 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: transactionComplete, state=COMPLETE, outstanding=0
08:03:26.851 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
08:03:26.851 [DEBUG] [database.ZigBeeNetworkDatabaseManager] - 680AE2FFFEC32FDF: Data store: Deferring write for 250ms.
08:03:26.851 [DEBUG] [.transaction.ZigBeeTransactionManager] - 8B4F/1: Sending ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=1056, state=WAITING, sendCnt=0, command=DiscoverAttributesCommand [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=C6, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]]
08:03:26.852 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
08:03:26.853 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: DiscoverAttributesCommand [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=C6, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]
08:03:26.854 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=198, commandId=12]
08:03:26.854 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=8B4F/1, profile=0104, cluster=0001, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=40, rssi=--, lqi=--, payload=00 C6 0C 00 00 0A]
08:03:26.863 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=CE]
08:03:27.102 [DEBUG] [database.ZigBeeNetworkDatabaseManager] - 680AE2FFFEC32FDF: Data store: Writing node.
08:03:27.118 [DEBUG] [nding.zigbee.internal.ZigBeeDataStore] - 680AE2FFFEC32FDF: ZigBee saving network state complete.
08:03:27.932 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0001, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=47], lastHopLqi=255, lastHopRssi=-45, sender=8B4F, bindingIndex=255, addressIndex=255, messageContents=18 C6 0D 01 20 00 20 21 00 20 FD FF 21]
08:03:27.934 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=8B4F/1, destinationAddress=0000/1, profile=0104, cluster=0001, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=47, rssi=-45, lqi=FF, payload=18 C6 0D 01 20 00 20 21 00 20 FD FF 21]
08:03:27.936 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=198, commandId=13]
08:03:27.938 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: DiscoverAttributesResponse [Power Configuration: 8B4F/1 -> 0000/1, cluster=0001, TID=C6, discoveryComplete=true, attributeInformation=[AttributeInformation [dataType=UNSIGNED_8_BIT_INTEGER, identifier=32], AttributeInformation [dataType=UNSIGNED_8_BIT_INTEGER, identifier=33], AttributeInformation [dataType=UNSIGNED_16_BIT_INTEGER, identifier=65533]]]
08:03:27.940 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionCommand: DiscoverAttributesResponse [Power Configuration: 8B4F/1 -> 0000/1, cluster=0001, TID=C6, discoveryComplete=true, attributeInformation=[AttributeInformation [dataType=UNSIGNED_8_BIT_INTEGER, identifier=32], AttributeInformation [dataType=UNSIGNED_8_BIT_INTEGER, identifier=33], AttributeInformation [dataType=UNSIGNED_16_BIT_INTEGER, identifier=65533]]]
08:03:27.943 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=2147, state=COMPLETE, sendCnt=1, command=DiscoverAttributesCommand [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=C6, startAttributeIdentifier=0, maximumAttributeIdentifiers=10]]
08:03:27.943 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=8B4F, apsFrame=EmberApsFrame [profileId=0104, clusterId=0001, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=CE], messageTag=C6, status=EMBER_SUCCESS, messageContents=]
08:03:27.944 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
08:03:27.944 [DEBUG] [m.zsmartsystems.zigbee.zcl.ZclCluster] - readSync request: ZclAttribute [cluster=Power Configuration, id=33, name=Battery Percentage Remaining, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=null, implemented=true]
08:03:27.946 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: transactionComplete, state=COMPLETE, outstanding=0
08:03:27.945 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=C6 state=RX_ACK
08:03:27.947 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=0, sleepy=0/3
08:03:27.947 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=C6, state=RX_ACK, outstanding=0
08:03:27.948 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=--, identifiers=[33]]]
08:03:27.949 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
08:03:27.949 [DEBUG] [.transaction.ZigBeeTransactionManager] - 8B4F/1: Sending ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=1, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=C7, identifiers=[33]]]
08:03:27.950 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
08:03:27.951 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=C7, identifiers=[33]]
08:03:27.951 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=199, commandId=0]
08:03:27.952 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=8B4F/1, profile=0104, cluster=0001, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=41, rssi=--, lqi=--, payload=00 C7 00 21 00]
08:03:27.961 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=CF]
08:03:28.865 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0001, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=48], lastHopLqi=255, lastHopRssi=-45, sender=8B4F, bindingIndex=255, addressIndex=255, messageContents=18 C7 01 21 00 00 20 64]
08:03:28.867 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=8B4F/1, destinationAddress=0000/1, profile=0104, cluster=0001, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=48, rssi=-45, lqi=FF, payload=18 C7 01 21 00 00 20 64]
08:03:28.869 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=199, commandId=1]
08:03:28.870 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReadAttributesResponse [Power Configuration: 8B4F/1 -> 0000/1, cluster=0001, TID=C7, records=[ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=33, attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeValue=100]]]
08:03:28.872 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [Power Configuration: 8B4F/1 -> 0000/1, cluster=0001, TID=C7, records=[ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=33, attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeValue=100]]]
08:03:28.873 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=925, state=COMPLETE, sendCnt=1, command=ReadAttributesCommand [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=C7, identifiers=[33]]]
08:03:28.873 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=8B4F, apsFrame=EmberApsFrame [profileId=0104, clusterId=0001, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=CF], messageTag=C7, status=EMBER_SUCCESS, messageContents=]
08:03:28.874 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
08:03:28.874 [DEBUG] [m.zsmartsystems.zigbee.zcl.ZclCluster] - readSync request: ZclAttribute [cluster=Power Configuration, id=32, name=Battery Voltage, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=null, implemented=true]
08:03:28.874 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=C7 state=RX_ACK
08:03:28.875 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: transactionComplete, state=COMPLETE, outstanding=0
08:03:28.876 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=C7, state=RX_ACK, outstanding=0
08:03:28.877 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=--, identifiers=[32]]]
08:03:28.878 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
08:03:28.878 [DEBUG] [.transaction.ZigBeeTransactionManager] - 8B4F/1: Sending ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=1, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=C8, identifiers=[32]]]
08:03:28.879 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
08:03:28.880 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=C8, identifiers=[32]]
08:03:28.881 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=200, commandId=0]
08:03:28.882 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=8B4F/1, profile=0104, cluster=0001, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=42, rssi=--, lqi=--, payload=00 C8 00 20 00]
08:03:28.882 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=0, sleepy=1/3
08:03:28.891 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=D0]
08:03:30.007 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0001, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=49], lastHopLqi=255, lastHopRssi=-45, sender=8B4F, bindingIndex=255, addressIndex=255, messageContents=18 C8 01 20 00 00 20 00]
08:03:30.010 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=8B4F/1, destinationAddress=0000/1, profile=0104, cluster=0001, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=49, rssi=-45, lqi=FF, payload=18 C8 01 20 00 00 20 00]
08:03:30.012 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=200, commandId=1]
08:03:30.014 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReadAttributesResponse [Power Configuration: 8B4F/1 -> 0000/1, cluster=0001, TID=C8, records=[ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=32, attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeValue=0]]]
08:03:30.016 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [Power Configuration: 8B4F/1 -> 0000/1, cluster=0001, TID=C8, records=[ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=32, attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeValue=0]]]
08:03:30.016 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=1139, state=COMPLETE, sendCnt=1, command=ReadAttributesCommand [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=C8, identifiers=[32]]]
08:03:30.016 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=8B4F, apsFrame=EmberApsFrame [profileId=0104, clusterId=0001, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=D0], messageTag=C8, status=EMBER_SUCCESS, messageContents=]
08:03:30.017 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
08:03:30.017 [DEBUG] [ter.ZigBeeChannelConverterFactoryImpl] - 680AE2FFFEC32FDF: Removing channel zigbee:switch_onoff in favor of zigbee:switch_level
08:03:30.017 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=C8 state=RX_ACK
08:03:30.018 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 680AE2FFFEC32FDF: Dynamically created 4 channels
08:03:30.018 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: transactionComplete, state=COMPLETE, outstanding=0
08:03:30.020 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 680AE2FFFEC32FDF: Updating thing definition as channels have changed from [] to [zigbee:device:013725D7:680ae2fffec32fdf:680AE2FFFEC32FDF_1_batterylevel, zigbee:device:013725D7:680ae2fffec32fdf:680AE2FFFEC32FDF_1_dimmer, zigbee:device:013725D7:680ae2fffec32fdf:680AE2FFFEC32FDF_1_batteryalarm, zigbee:device:013725D7:680ae2fffec32fdf:680AE2FFFEC32FDF_1_batteryvoltage]
08:03:30.019 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=C8, state=RX_ACK, outstanding=0
08:03:30.020 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=0, sleepy=0/3
08:03:30.022 [INFO ] [smarthome.event.ThingUpdatedEvent    ] - Thing 'zigbee:device:013725D7:680ae2fffec32fdf' has been updated.
08:03:30.022 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 680AE2FFFEC32FDF: Initializing device
08:03:30.023 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 680AE2FFFEC32FDF: Initializing channel zigbee:device:013725D7:680ae2fffec32fdf:680AE2FFFEC32FDF_1_batterylevel with org.openhab.binding.zigbee.internal.converter.ZigBeeConverterBatteryPercent@8ca0dfe
08:03:30.023 [DEBUG] [nverter.ZigBeeConverterBatteryPercent] - 680AE2FFFEC32FDF: Initialising device battery percent converter
08:03:30.024 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=0, state=WAITING, sendCnt=0, command=BindRequest [0000/0 -> 8B4F/0, cluster=0021, TID=--, srcAddress=680AE2FFFEC32FDF, srcEndpoint=1, bindCluster=1, dstAddrMode=3, dstAddress=000D6F000DD1E41F, dstEndpoint=1]]
08:03:30.025 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
08:03:30.025 [DEBUG] [.transaction.ZigBeeTransactionManager] - 8B4F/0: Sending ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=1, state=WAITING, sendCnt=0, command=BindRequest [0000/0 -> 8B4F/0, cluster=0021, TID=C9, srcAddress=680AE2FFFEC32FDF, srcEndpoint=1, bindCluster=1, dstAddrMode=3, dstAddress=000D6F000DD1E41F, dstEndpoint=1]]
08:03:30.026 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
08:03:30.027 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: BindRequest [0000/0 -> 8B4F/0, cluster=0021, TID=C9, srcAddress=680AE2FFFEC32FDF, srcEndpoint=1, bindCluster=1, dstAddrMode=3, dstAddress=000D6F000DD1E41F, dstEndpoint=1]
08:03:30.027 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=8B4F/0, profile=0000, cluster=0021, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=43, rssi=--, lqi=--, payload=C9 DF 2F C3 FE FF E2 0A 68 01 01 00 03 1F E4 D1 0D 00 6F 0D 00 01]
08:03:30.039 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=D1]
08:03:30.925 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=8021, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=4A], lastHopLqi=255, lastHopRssi=-45, sender=8B4F, bindingIndex=255, addressIndex=255, messageContents=C9 00]
08:03:30.927 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=8B4F/0, destinationAddress=0000/0, profile=0000, cluster=8021, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=4A, rssi=-45, lqi=FF, payload=C9 00]
08:03:30.929 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: BindResponse [8B4F/0 -> 0000/0, cluster=8021, TID=C9, status=SUCCESS]
08:03:30.931 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionCommand: BindResponse [8B4F/0 -> 0000/0, cluster=8021, TID=C9, status=SUCCESS]
08:03:30.932 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=8B4F, apsFrame=EmberApsFrame [profileId=0000, clusterId=0021, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=D1], messageTag=C9, status=EMBER_SUCCESS, messageContents=]
08:03:30.933 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=0, state=WAITING, sendCnt=0, command=ConfigureReportingCommand [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=--, records=[AttributeReportingConfigurationRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=33, direction=0, minimumReportingInterval=600, maximumReportingInterval=7200, reportableChange=1]]]]
08:03:30.934 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=1/3
08:03:30.932 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=908, state=COMPLETE, sendCnt=1, command=BindRequest [0000/0 -> 8B4F/0, cluster=0021, TID=C9, srcAddress=680AE2FFFEC32FDF, srcEndpoint=1, bindCluster=1, dstAddrMode=3, dstAddress=000D6F000DD1E41F, dstEndpoint=1]]
08:03:30.936 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
08:03:30.936 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: transactionComplete, state=COMPLETE, outstanding=0
08:03:30.937 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
08:03:30.933 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=C9 state=RX_ACK
08:03:30.938 [DEBUG] [.transaction.ZigBeeTransactionManager] - 8B4F/1: Sending ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=6, state=WAITING, sendCnt=0, command=ConfigureReportingCommand [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=CA, records=[AttributeReportingConfigurationRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=33, direction=0, minimumReportingInterval=600, maximumReportingInterval=7200, reportableChange=1]]]]
08:03:30.939 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=C9, state=RX_ACK, outstanding=0
08:03:30.939 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
08:03:30.940 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ConfigureReportingCommand [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=CA, records=[AttributeReportingConfigurationRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=33, direction=0, minimumReportingInterval=600, maximumReportingInterval=7200, reportableChange=1]]]
08:03:30.941 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=202, commandId=6]
08:03:30.942 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=8B4F/1, profile=0104, cluster=0001, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=44, rssi=--, lqi=--, payload=00 CA 06 00 21 00 20 58 02 20 1C 01]
08:03:30.952 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=D2]
08:03:31.959 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0001, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=4B], lastHopLqi=255, lastHopRssi=-45, sender=8B4F, bindingIndex=255, addressIndex=255, messageContents=08 CA 07 00]
08:03:31.964 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=8B4F/1, destinationAddress=0000/1, profile=0104, cluster=0001, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=4B, rssi=-45, lqi=FF, payload=08 CA 07 00]
08:03:31.966 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=202, commandId=7]
08:03:31.968 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ConfigureReportingResponse [Power Configuration: 8B4F/1 -> 0000/1, cluster=0001, TID=CA, status=SUCCESS, records=null]
08:03:31.970 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ConfigureReportingResponse [Power Configuration: 8B4F/1 -> 0000/1, cluster=0001, TID=CA, status=SUCCESS, records=null]
08:03:31.972 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=8B4F, apsFrame=EmberApsFrame [profileId=0104, clusterId=0001, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=D2], messageTag=CA, status=EMBER_SUCCESS, messageContents=]
08:03:31.973 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 680AE2FFFEC32FDF: Initializing channel zigbee:device:013725D7:680ae2fffec32fdf:680AE2FFFEC32FDF_1_dimmer with org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchLevel@c0405b8
08:03:31.973 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=1041, state=COMPLETE, sendCnt=1, command=ConfigureReportingCommand [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=CA, records=[AttributeReportingConfigurationRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=33, direction=0, minimumReportingInterval=600, maximumReportingInterval=7200, reportableChange=1]]]]
08:03:31.972 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=1, state=WAITING, sendCnt=0, command=DefaultResponse [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=CA, commandIdentifier=7, statusCode=SUCCESS]]
08:03:31.974 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
08:03:31.974 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=CA state=RX_ACK
08:03:31.975 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=1/3
08:03:31.976 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=CA, state=RX_ACK, outstanding=0
08:03:31.976 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: transactionComplete, state=COMPLETE, outstanding=0
08:03:31.977 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
08:03:31.978 [DEBUG] [.transaction.ZigBeeTransactionManager] - 8B4F/1: Sending ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=7, state=WAITING, sendCnt=0, command=DefaultResponse [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=CA, commandIdentifier=7, statusCode=SUCCESS]]
08:03:31.978 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
08:03:31.979 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: DefaultResponse [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=CA, commandIdentifier=7, statusCode=SUCCESS]
08:03:31.979 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=202, commandId=11]
08:03:31.980 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=8B4F/1, profile=0104, cluster=0001, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=45, rssi=--, lqi=--, payload=10 CA 0B 07 00]
08:03:31.981 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=0, state=WAITING, sendCnt=0, command=BindRequest [0000/0 -> 8B4F/0, cluster=0021, TID=--, srcAddress=680AE2FFFEC32FDF, srcEndpoint=1, bindCluster=8, dstAddrMode=3, dstAddress=000D6F000DD1E41F, dstEndpoint=1]]
08:03:31.982 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=1/3
08:03:31.989 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=D3]
08:03:32.028 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=1/3
08:03:32.978 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=8B4F, apsFrame=EmberApsFrame [profileId=0104, clusterId=0001, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=D3], messageTag=CA, status=EMBER_SUCCESS, messageContents=]
08:03:32.980 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=CA state=RX_ACK
08:03:32.982 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=CA, state=RX_ACK, outstanding=1
08:03:32.984 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=1013, state=COMPLETE, sendCnt=1, command=DefaultResponse [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=CA, commandIdentifier=7, statusCode=SUCCESS]]
08:03:32.986 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
08:03:32.988 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: transactionComplete, state=COMPLETE, outstanding=0
08:03:32.988 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
08:03:32.989 [DEBUG] [.transaction.ZigBeeTransactionManager] - 8B4F/0: Sending ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=1008, state=WAITING, sendCnt=0, command=BindRequest [0000/0 -> 8B4F/0, cluster=0021, TID=CB, srcAddress=680AE2FFFEC32FDF, srcEndpoint=1, bindCluster=8, dstAddrMode=3, dstAddress=000D6F000DD1E41F, dstEndpoint=1]]
08:03:32.990 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
08:03:32.991 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: BindRequest [0000/0 -> 8B4F/0, cluster=0021, TID=CB, srcAddress=680AE2FFFEC32FDF, srcEndpoint=1, bindCluster=8, dstAddrMode=3, dstAddress=000D6F000DD1E41F, dstEndpoint=1]
08:03:32.992 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=8B4F/0, profile=0000, cluster=0021, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=46, rssi=--, lqi=--, payload=CB DF 2F C3 FE FF E2 0A 68 01 08 00 03 1F E4 D1 0D 00 6F 0D 00 01]
08:03:32.992 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=8B4F, TID=CA, event=RX_ACK, state=COMPLETE
08:03:33.004 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=D4]
08:03:34.002 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=8021, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=4C], lastHopLqi=255, lastHopRssi=-45, sender=8B4F, bindingIndex=255, addressIndex=255, messageContents=CB 00]
08:03:34.004 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=8B4F/0, destinationAddress=0000/0, profile=0000, cluster=8021, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=4C, rssi=-45, lqi=FF, payload=CB 00]
08:03:34.006 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: BindResponse [8B4F/0 -> 0000/0, cluster=8021, TID=CB, status=SUCCESS]
08:03:34.008 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionCommand: BindResponse [8B4F/0 -> 0000/0, cluster=8021, TID=CB, status=SUCCESS]
08:03:34.010 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=2029, state=COMPLETE, sendCnt=1, command=BindRequest [0000/0 -> 8B4F/0, cluster=0021, TID=CB, srcAddress=680AE2FFFEC32FDF, srcEndpoint=1, bindCluster=8, dstAddrMode=3, dstAddress=000D6F000DD1E41F, dstEndpoint=1]]
08:03:34.010 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=0, state=WAITING, sendCnt=0, command=BindRequest [0000/0 -> 8B4F/0, cluster=0021, TID=--, srcAddress=680AE2FFFEC32FDF, srcEndpoint=1, bindCluster=6, dstAddrMode=3, dstAddress=000D6F000DD1E41F, dstEndpoint=1]]
08:03:34.010 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=8B4F, apsFrame=EmberApsFrame [profileId=0000, clusterId=0021, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=D4], messageTag=CB, status=EMBER_SUCCESS, messageContents=]
08:03:34.013 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=1/3
08:03:34.012 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
08:03:34.014 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=CB state=RX_ACK
08:03:34.015 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: transactionComplete, state=COMPLETE, outstanding=0
08:03:34.015 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=CB, state=RX_ACK, outstanding=0
08:03:34.016 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
08:03:34.017 [DEBUG] [.transaction.ZigBeeTransactionManager] - 8B4F/0: Sending ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=7, state=WAITING, sendCnt=0, command=BindRequest [0000/0 -> 8B4F/0, cluster=0021, TID=CC, srcAddress=680AE2FFFEC32FDF, srcEndpoint=1, bindCluster=6, dstAddrMode=3, dstAddress=000D6F000DD1E41F, dstEndpoint=1]]
08:03:34.017 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
08:03:34.018 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: BindRequest [0000/0 -> 8B4F/0, cluster=0021, TID=CC, srcAddress=680AE2FFFEC32FDF, srcEndpoint=1, bindCluster=6, dstAddrMode=3, dstAddress=000D6F000DD1E41F, dstEndpoint=1]
08:03:34.019 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=8B4F/0, profile=0000, cluster=0021, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=47, rssi=--, lqi=--, payload=CC DF 2F C3 FE FF E2 0A 68 01 06 00 03 1F E4 D1 0D 00 6F 0D 00 01]
08:03:34.031 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=D5]
08:03:35.035 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=8021, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=4D], lastHopLqi=255, lastHopRssi=-45, sender=8B4F, bindingIndex=255, addressIndex=255, messageContents=CC 00]
08:03:35.037 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=8B4F/0, destinationAddress=0000/0, profile=0000, cluster=8021, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=4D, rssi=-45, lqi=FF, payload=CC 00]
08:03:35.039 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: BindResponse [8B4F/0 -> 0000/0, cluster=8021, TID=CC, status=SUCCESS]
08:03:35.041 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionCommand: BindResponse [8B4F/0 -> 0000/0, cluster=8021, TID=CC, status=SUCCESS]
08:03:35.043 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=1033, state=COMPLETE, sendCnt=1, command=BindRequest [0000/0 -> 8B4F/0, cluster=0021, TID=CC, srcAddress=680AE2FFFEC32FDF, srcEndpoint=1, bindCluster=6, dstAddrMode=3, dstAddress=000D6F000DD1E41F, dstEndpoint=1]]
08:03:35.043 [DEBUG] [.converter.ZigBeeConverterSwitchLevel] - 680AE2FFFEC32FDF: Level control device initialized as client
08:03:35.045 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
08:03:35.047 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 680AE2FFFEC32FDF: Initializing channel zigbee:device:013725D7:680ae2fffec32fdf:680AE2FFFEC32FDF_1_batteryalarm with org.openhab.binding.zigbee.internal.converter.ZigBeeConverterBatteryAlarm@4b834c8e
08:03:35.047 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: transactionComplete, state=COMPLETE, outstanding=0
08:03:35.048 [DEBUG] [converter.ZigBeeConverterBatteryAlarm] - 680AE2FFFEC32FDF: Initialising device battery alarm converter
08:03:35.048 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=0, sleepy=0/3
08:03:35.049 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=0, state=WAITING, sendCnt=0, command=BindRequest [0000/0 -> 8B4F/0, cluster=0021, TID=--, srcAddress=680AE2FFFEC32FDF, srcEndpoint=1, bindCluster=1, dstAddrMode=3, dstAddress=000D6F000DD1E41F, dstEndpoint=1]]
08:03:35.050 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
08:03:35.051 [DEBUG] [.transaction.ZigBeeTransactionManager] - 8B4F/0: Sending ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=2, state=WAITING, sendCnt=0, command=BindRequest [0000/0 -> 8B4F/0, cluster=0021, TID=CD, srcAddress=680AE2FFFEC32FDF, srcEndpoint=1, bindCluster=1, dstAddrMode=3, dstAddress=000D6F000DD1E41F, dstEndpoint=1]]
08:03:35.051 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
08:03:35.052 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: BindRequest [0000/0 -> 8B4F/0, cluster=0021, TID=CD, srcAddress=680AE2FFFEC32FDF, srcEndpoint=1, bindCluster=1, dstAddrMode=3, dstAddress=000D6F000DD1E41F, dstEndpoint=1]
08:03:35.053 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=8B4F/0, profile=0000, cluster=0021, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=48, rssi=--, lqi=--, payload=CD DF 2F C3 FE FF E2 0A 68 01 01 00 03 1F E4 D1 0D 00 6F 0D 00 01]
08:03:35.055 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=8B4F, apsFrame=EmberApsFrame [profileId=0000, clusterId=0021, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=D5], messageTag=CC, status=EMBER_SUCCESS, messageContents=]
08:03:35.075 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=D6]
08:03:35.075 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=CC state=RX_ACK
08:03:35.076 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=CC, state=RX_ACK, outstanding=1
08:03:36.093 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=8021, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=4E], lastHopLqi=255, lastHopRssi=-45, sender=8B4F, bindingIndex=255, addressIndex=255, messageContents=CD 00]
08:03:36.095 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=8B4F/0, destinationAddress=0000/0, profile=0000, cluster=8021, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=4E, rssi=-45, lqi=FF, payload=CD 00]
08:03:36.097 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: BindResponse [8B4F/0 -> 0000/0, cluster=8021, TID=CD, status=SUCCESS]
08:03:36.099 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionCommand: BindResponse [8B4F/0 -> 0000/0, cluster=8021, TID=CD, status=SUCCESS]
08:03:36.102 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=1052, state=COMPLETE, sendCnt=1, command=BindRequest [0000/0 -> 8B4F/0, cluster=0021, TID=CD, srcAddress=680AE2FFFEC32FDF, srcEndpoint=1, bindCluster=1, dstAddrMode=3, dstAddress=000D6F000DD1E41F, dstEndpoint=1]]
08:03:36.102 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=0, state=WAITING, sendCnt=0, command=ConfigureReportingCommand [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=--, records=[AttributeReportingConfigurationRecord [attributeDataType=BITMAP_32_BIT, attributeIdentifier=62, direction=0, minimumReportingInterval=600, maximumReportingInterval=7200]]]]
08:03:36.104 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
08:03:36.106 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=1/3
08:03:36.107 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: transactionComplete, state=COMPLETE, outstanding=0
08:03:36.108 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
08:03:36.108 [DEBUG] [.transaction.ZigBeeTransactionManager] - 8B4F/1: Sending ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=6, state=WAITING, sendCnt=0, command=ConfigureReportingCommand [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=CE, records=[AttributeReportingConfigurationRecord [attributeDataType=BITMAP_32_BIT, attributeIdentifier=62, direction=0, minimumReportingInterval=600, maximumReportingInterval=7200]]]]
08:03:36.109 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
08:03:36.110 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ConfigureReportingCommand [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=CE, records=[AttributeReportingConfigurationRecord [attributeDataType=BITMAP_32_BIT, attributeIdentifier=62, direction=0, minimumReportingInterval=600, maximumReportingInterval=7200]]]
08:03:36.110 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=206, commandId=6]
08:03:36.111 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=8B4F/1, profile=0104, cluster=0001, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=49, rssi=--, lqi=--, payload=00 CE 06 00 3E 00 1B 58 02 20 1C]
08:03:36.113 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=8B4F, apsFrame=EmberApsFrame [profileId=0000, clusterId=0021, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=D6], messageTag=CD, status=EMBER_SUCCESS, messageContents=]
08:03:36.133 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=D7]
08:03:36.133 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=CD state=RX_ACK
08:03:36.135 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=CD, state=RX_ACK, outstanding=1
08:03:37.210 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0001, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=4F], lastHopLqi=255, lastHopRssi=-45, sender=8B4F, bindingIndex=255, addressIndex=255, messageContents=08 CE 07 86 00 3E 00]
08:03:37.215 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=8B4F/1, destinationAddress=0000/1, profile=0104, cluster=0001, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=4F, rssi=-45, lqi=FF, payload=08 CE 07 86 00 3E 00]
08:03:37.217 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=206, commandId=7]
08:03:37.219 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ConfigureReportingResponse [Power Configuration: 8B4F/1 -> 0000/1, cluster=0001, TID=CE, status=null, records=[Attribute Status Record [status=UNSUPPORTED_ATTRIBUTE, direction=false, attributeIdentifier=62]]]
08:03:37.220 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ConfigureReportingResponse [Power Configuration: 8B4F/1 -> 0000/1, cluster=0001, TID=CE, status=null, records=[Attribute Status Record [status=UNSUPPORTED_ATTRIBUTE, direction=false, attributeIdentifier=62]]]
08:03:37.231 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=8B4F, apsFrame=EmberApsFrame [profileId=0104, clusterId=0001, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=D7], messageTag=CE, status=EMBER_SUCCESS, messageContents=]
08:03:37.231 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=0, state=WAITING, sendCnt=0, command=DefaultResponse [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=CE, commandIdentifier=7, statusCode=SUCCESS]]
08:03:37.231 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 680AE2FFFEC32FDF: Initializing channel zigbee:device:013725D7:680ae2fffec32fdf:680AE2FFFEC32FDF_1_batteryvoltage with org.openhab.binding.zigbee.internal.converter.ZigBeeConverterBatteryVoltage@778b3622
08:03:37.231 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=1119, state=COMPLETE, sendCnt=1, command=ConfigureReportingCommand [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=CE, records=[AttributeReportingConfigurationRecord [attributeDataType=BITMAP_32_BIT, attributeIdentifier=62, direction=0, minimumReportingInterval=600, maximumReportingInterval=7200]]]]
08:03:37.233 [DEBUG] [nverter.ZigBeeConverterBatteryVoltage] - 680AE2FFFEC32FDF: Initialising device battery voltage converter
08:03:37.232 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=1/3
08:03:37.232 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=CE state=RX_ACK
08:03:37.234 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
08:03:37.236 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=CE, state=RX_ACK, outstanding=0
08:03:37.236 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: Added transaction to queue, len=2, transaction=ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=0, state=WAITING, sendCnt=0, command=BindRequest [0000/0 -> 8B4F/0, cluster=0021, TID=--, srcAddress=680AE2FFFEC32FDF, srcEndpoint=1, bindCluster=1, dstAddrMode=3, dstAddress=000D6F000DD1E41F, dstEndpoint=1]]
08:03:37.237 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=1/3
08:03:37.238 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: transactionComplete, state=COMPLETE, outstanding=0
08:03:37.239 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
08:03:37.239 [DEBUG] [.transaction.ZigBeeTransactionManager] - 8B4F/1: Sending ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=8, state=WAITING, sendCnt=0, command=DefaultResponse [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=CE, commandIdentifier=7, statusCode=SUCCESS]]
08:03:37.240 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
08:03:37.240 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: DefaultResponse [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=CE, commandIdentifier=7, statusCode=SUCCESS]
08:03:37.241 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=206, commandId=11]
08:03:37.242 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=8B4F/1, profile=0104, cluster=0001, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=4A, rssi=--, lqi=--, payload=10 CE 0B 07 00]
08:03:37.251 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=D8]
08:03:37.290 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=1/3
08:03:38.126 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=8B4F, apsFrame=EmberApsFrame [profileId=0104, clusterId=0001, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=D8], messageTag=CE, status=EMBER_SUCCESS, messageContents=]
08:03:38.129 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=CE state=RX_ACK
08:03:38.131 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=CE, state=RX_ACK, outstanding=1
08:03:38.133 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=902, state=COMPLETE, sendCnt=1, command=DefaultResponse [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=CE, commandIdentifier=7, statusCode=SUCCESS]]
08:03:38.135 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
08:03:38.136 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: transactionComplete, state=COMPLETE, outstanding=0
08:03:38.137 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
08:03:38.139 [DEBUG] [.transaction.ZigBeeTransactionManager] - 8B4F/0: Sending ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=903, state=WAITING, sendCnt=0, command=BindRequest [0000/0 -> 8B4F/0, cluster=0021, TID=CF, srcAddress=680AE2FFFEC32FDF, srcEndpoint=1, bindCluster=1, dstAddrMode=3, dstAddress=000D6F000DD1E41F, dstEndpoint=1]]
08:03:38.140 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
08:03:38.141 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: BindRequest [0000/0 -> 8B4F/0, cluster=0021, TID=CF, srcAddress=680AE2FFFEC32FDF, srcEndpoint=1, bindCluster=1, dstAddrMode=3, dstAddress=000D6F000DD1E41F, dstEndpoint=1]
08:03:38.142 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=8B4F/0, profile=0000, cluster=0021, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=4B, rssi=--, lqi=--, payload=CF DF 2F C3 FE FF E2 0A 68 01 01 00 03 1F E4 D1 0D 00 6F 0D 00 01]
08:03:38.143 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=8B4F, TID=CE, event=RX_ACK, state=COMPLETE
08:03:38.154 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=D9]
08:03:39.141 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=8021, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=50], lastHopLqi=255, lastHopRssi=-45, sender=8B4F, bindingIndex=255, addressIndex=255, messageContents=CF 00]
08:03:39.144 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=8B4F/0, destinationAddress=0000/0, profile=0000, cluster=8021, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=50, rssi=-45, lqi=FF, payload=CF 00]
08:03:39.146 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: BindResponse [8B4F/0 -> 0000/0, cluster=8021, TID=CF, status=SUCCESS]
08:03:39.148 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionCommand: BindResponse [8B4F/0 -> 0000/0, cluster=8021, TID=CF, status=SUCCESS]
08:03:39.150 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=1914, state=COMPLETE, sendCnt=1, command=BindRequest [0000/0 -> 8B4F/0, cluster=0021, TID=CF, srcAddress=680AE2FFFEC32FDF, srcEndpoint=1, bindCluster=1, dstAddrMode=3, dstAddress=000D6F000DD1E41F, dstEndpoint=1]]
08:03:39.150 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=0, state=WAITING, sendCnt=0, command=ConfigureReportingCommand [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=--, records=[AttributeReportingConfigurationRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=32, direction=0, minimumReportingInterval=600, maximumReportingInterval=7200, reportableChange=1]]]]
08:03:39.152 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
08:03:39.153 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=1/3
08:03:39.155 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: transactionComplete, state=COMPLETE, outstanding=0
08:03:39.155 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
08:03:39.156 [DEBUG] [.transaction.ZigBeeTransactionManager] - 8B4F/1: Sending ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=6, state=WAITING, sendCnt=0, command=ConfigureReportingCommand [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=D0, records=[AttributeReportingConfigurationRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=32, direction=0, minimumReportingInterval=600, maximumReportingInterval=7200, reportableChange=1]]]]
08:03:39.157 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
08:03:39.157 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ConfigureReportingCommand [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=D0, records=[AttributeReportingConfigurationRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=32, direction=0, minimumReportingInterval=600, maximumReportingInterval=7200, reportableChange=1]]]
08:03:39.158 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=208, commandId=6]
08:03:39.158 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=8B4F/1, profile=0104, cluster=0001, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=4C, rssi=--, lqi=--, payload=00 D0 06 00 20 00 20 58 02 20 1C 01]
08:03:39.161 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=8B4F, apsFrame=EmberApsFrame [profileId=0000, clusterId=0021, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=D9], messageTag=CF, status=EMBER_SUCCESS, messageContents=]
08:03:39.182 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=DA]
08:03:39.182 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=CF state=RX_ACK
08:03:39.183 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=CF, state=RX_ACK, outstanding=1
08:03:41.216 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0001, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=51], lastHopLqi=255, lastHopRssi=-43, sender=8B4F, bindingIndex=255, addressIndex=255, messageContents=08 D0 07 00]
08:03:41.219 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=8B4F/1, destinationAddress=0000/1, profile=0104, cluster=0001, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=51, rssi=-43, lqi=FF, payload=08 D0 07 00]
08:03:41.220 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=208, commandId=7]
08:03:41.222 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ConfigureReportingResponse [Power Configuration: 8B4F/1 -> 0000/1, cluster=0001, TID=D0, status=SUCCESS, records=null]
08:03:41.224 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ConfigureReportingResponse [Power Configuration: 8B4F/1 -> 0000/1, cluster=0001, TID=D0, status=SUCCESS, records=null]
08:03:41.226 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=0, state=WAITING, sendCnt=0, command=DefaultResponse [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=D0, commandIdentifier=7, statusCode=SUCCESS]]
08:03:41.226 [DEBUG] [m.zsmartsystems.zigbee.zcl.ZclCluster] - readSync request: ZclAttribute [cluster=Power Configuration, id=33, name=Battery Percentage Remaining, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=100, lastReportTime=Tue Oct 06 08:03:28 CEST 2020, implemented=true]
08:03:41.226 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=8B4F, apsFrame=EmberApsFrame [profileId=0104, clusterId=0001, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=DA], messageTag=D0, status=EMBER_SUCCESS, messageContents=]
08:03:41.226 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=2076, state=COMPLETE, sendCnt=1, command=ConfigureReportingCommand [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=D0, records=[AttributeReportingConfigurationRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=32, direction=0, minimumReportingInterval=600, maximumReportingInterval=7200, reportableChange=1]]]]
08:03:41.231 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=D0 state=RX_ACK
08:03:41.228 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=1/3
08:03:41.232 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=D0, state=RX_ACK, outstanding=0
08:03:41.231 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
08:03:41.232 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: Added transaction to queue, len=2, transaction=ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=--, identifiers=[33]]]
08:03:41.233 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=1/3
08:03:41.234 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: transactionComplete, state=COMPLETE, outstanding=0
08:03:41.235 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
08:03:41.235 [DEBUG] [.transaction.ZigBeeTransactionManager] - 8B4F/1: Sending ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=9, state=WAITING, sendCnt=0, command=DefaultResponse [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=D0, commandIdentifier=7, statusCode=SUCCESS]]
08:03:41.236 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
08:03:41.236 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: DefaultResponse [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=D0, commandIdentifier=7, statusCode=SUCCESS]
08:03:41.237 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=208, commandId=11]
08:03:41.237 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=8B4F/1, profile=0104, cluster=0001, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=4D, rssi=--, lqi=--, payload=10 D0 0B 07 00]
08:03:41.246 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=DB]
08:03:41.285 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=1/3
08:03:43.258 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=8B4F, apsFrame=EmberApsFrame [profileId=0104, clusterId=0001, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=DB], messageTag=D0, status=EMBER_SUCCESS, messageContents=]
08:03:43.261 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=D0 state=RX_ACK
08:03:43.263 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=D0, state=RX_ACK, outstanding=1
08:03:43.265 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=2039, state=COMPLETE, sendCnt=1, command=DefaultResponse [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=D0, commandIdentifier=7, statusCode=SUCCESS]]
08:03:43.267 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
08:03:43.268 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: transactionComplete, state=COMPLETE, outstanding=0
08:03:43.270 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
08:03:43.272 [DEBUG] [.transaction.ZigBeeTransactionManager] - 8B4F/1: Sending ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=2040, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=D1, identifiers=[33]]]
08:03:43.273 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
08:03:43.273 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=D1, identifiers=[33]]
08:03:43.274 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=209, commandId=0]
08:03:43.275 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=8B4F/1, profile=0104, cluster=0001, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=4E, rssi=--, lqi=--, payload=00 D1 00 21 00]
08:03:43.276 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=8B4F, TID=D0, event=RX_ACK, state=COMPLETE
08:03:43.284 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=DC]
08:03:44.294 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0001, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=52], lastHopLqi=255, lastHopRssi=-44, sender=8B4F, bindingIndex=255, addressIndex=255, messageContents=18 D1 01 21 00 00 20 64]
08:03:44.297 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=8B4F/1, destinationAddress=0000/1, profile=0104, cluster=0001, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=52, rssi=-44, lqi=FF, payload=18 D1 01 21 00 00 20 64]
08:03:44.299 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=209, commandId=1]
08:03:44.301 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReadAttributesResponse [Power Configuration: 8B4F/1 -> 0000/1, cluster=0001, TID=D1, records=[ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=33, attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeValue=100]]]
08:03:44.302 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [Power Configuration: 8B4F/1 -> 0000/1, cluster=0001, TID=D1, records=[ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=33, attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeValue=100]]]
08:03:44.304 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=3072, state=COMPLETE, sendCnt=1, command=ReadAttributesCommand [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=D1, identifiers=[33]]]
08:03:44.306 [DEBUG] [.converter.ZigBeeConverterSwitchLevel] - 680AE2FFFEC32FDF: Level control initialized as client
08:03:44.305 [DEBUG] [nverter.ZigBeeConverterBatteryPercent] - 680AE2FFFEC32FDF: ZigBee attribute reports ZclAttribute [cluster=Power Configuration, id=33, name=Battery Percentage Remaining, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=100, lastReportTime=Tue Oct 06 08:03:44 CEST 2020, implemented=true]
08:03:44.305 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=8B4F, apsFrame=EmberApsFrame [profileId=0104, clusterId=0001, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=DC], messageTag=D1, status=EMBER_SUCCESS, messageContents=]
08:03:44.307 [DEBUG] [.converter.ZigBeeBaseChannelConverter] - 680AE2FFFEC32FDF: Channel zigbee:device:013725D7:680ae2fffec32fdf:680AE2FFFEC32FDF_1_batterylevel updated to 50
08:03:44.307 [DEBUG] [m.zsmartsystems.zigbee.zcl.ZclCluster] - readSync request: ZclAttribute [cluster=Power Configuration, id=62, name=Battery Alarm State, dataType=BITMAP_32_BIT, lastValue=null, implemented=false]
08:03:44.306 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
08:03:44.309 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=--, identifiers=[62]]]
08:03:44.308 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 680AE2FFFEC32FDF: Updating ZigBee channel state zigbee:device:013725D7:680ae2fffec32fdf:680AE2FFFEC32FDF_1_batterylevel to 50
08:03:44.308 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=D1 state=RX_ACK
08:03:44.310 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=1/3
08:03:44.311 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=D1, state=RX_ACK, outstanding=0
08:03:44.311 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: transactionComplete, state=COMPLETE, outstanding=0
08:03:44.312 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
08:03:44.312 [DEBUG] [.transaction.ZigBeeTransactionManager] - 8B4F/1: Sending ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=3, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=D2, identifiers=[62]]]
08:03:44.313 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
08:03:44.313 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=D2, identifiers=[62]]
08:03:44.314 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=210, commandId=0]
08:03:44.315 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=8B4F/1, profile=0104, cluster=0001, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=4F, rssi=--, lqi=--, payload=00 D2 00 3E 00]
08:03:44.323 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=DD]
08:03:46.349 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0001, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=53], lastHopLqi=255, lastHopRssi=-43, sender=8B4F, bindingIndex=255, addressIndex=255, messageContents=18 D2 01 3E 00 86]
08:03:46.352 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=8B4F/1, destinationAddress=0000/1, profile=0104, cluster=0001, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=53, rssi=-43, lqi=FF, payload=18 D2 01 3E 00 86]
08:03:46.354 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=210, commandId=1]
08:03:46.356 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReadAttributesResponse [Power Configuration: 8B4F/1 -> 0000/1, cluster=0001, TID=D2, records=[ReadAttributeStatusRecord [status=UNSUPPORTED_ATTRIBUTE, attributeIdentifier=62]]]
08:03:46.357 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [Power Configuration: 8B4F/1 -> 0000/1, cluster=0001, TID=D2, records=[ReadAttributeStatusRecord [status=UNSUPPORTED_ATTRIBUTE, attributeIdentifier=62]]]
08:03:46.359 [DEBUG] [m.zsmartsystems.zigbee.zcl.ZclCluster] - 8B4F/1: Error reading server attribute 62 in cluster 1 - UNSUPPORTED_ATTRIBUTE
08:03:46.360 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=8B4F, apsFrame=EmberApsFrame [profileId=0104, clusterId=0001, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=DD], messageTag=D2, status=EMBER_SUCCESS, messageContents=]
08:03:46.360 [DEBUG] [m.zsmartsystems.zigbee.zcl.ZclCluster] - readSync request: ZclAttribute [cluster=Power Configuration, id=32, name=Battery Voltage, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=0, lastReportTime=Tue Oct 06 08:03:30 CEST 2020, implemented=true]
08:03:46.359 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=2050, state=COMPLETE, sendCnt=1, command=ReadAttributesCommand [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=D2, identifiers=[62]]]
08:03:46.363 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=--, identifiers=[32]]]
08:03:46.363 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=D2 state=RX_ACK
08:03:46.364 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
08:03:46.364 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=1/3
08:03:46.366 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: transactionComplete, state=COMPLETE, outstanding=0
08:03:46.365 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=D2, state=RX_ACK, outstanding=0
08:03:46.368 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
08:03:46.369 [DEBUG] [.transaction.ZigBeeTransactionManager] - 8B4F/1: Sending ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=6, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=D3, identifiers=[32]]]
08:03:46.370 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
08:03:46.371 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=D3, identifiers=[32]]
08:03:46.372 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=211, commandId=0]
08:03:46.373 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=8B4F/1, profile=0104, cluster=0001, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=50, rssi=--, lqi=--, payload=00 D3 00 20 00]
08:03:46.382 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=DE]
08:03:47.384 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0001, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=54], lastHopLqi=255, lastHopRssi=-42, sender=8B4F, bindingIndex=255, addressIndex=255, messageContents=18 D3 01 20 00 00 20 00]
08:03:47.386 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=8B4F/1, destinationAddress=0000/1, profile=0104, cluster=0001, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=54, rssi=-42, lqi=FF, payload=18 D3 01 20 00 00 20 00]
08:03:47.388 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=211, commandId=1]
08:03:47.390 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReadAttributesResponse [Power Configuration: 8B4F/1 -> 0000/1, cluster=0001, TID=D3, records=[ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=32, attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeValue=0]]]
08:03:47.392 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [Power Configuration: 8B4F/1 -> 0000/1, cluster=0001, TID=D3, records=[ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=32, attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeValue=0]]]
08:03:47.394 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 680AE2FFFEC32FDF: Channel initialisation complete
08:03:47.394 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=1030, state=COMPLETE, sendCnt=1, command=ReadAttributesCommand [Power Configuration: 0000/0 -> 8B4F/1, cluster=0001, TID=D3, identifiers=[32]]]
08:03:47.394 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=8B4F, apsFrame=EmberApsFrame [profileId=0104, clusterId=0001, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=DE], messageTag=D3, status=EMBER_SUCCESS, messageContents=]
08:03:47.394 [DEBUG] [nverter.ZigBeeConverterBatteryPercent] - 680AE2FFFEC32FDF: ZigBee attribute reports ZclAttribute [cluster=Power Configuration, id=32, name=Battery Voltage, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=0, lastReportTime=Tue Oct 06 08:03:47 CEST 2020, implemented=true]
08:03:47.394 [DEBUG] [nverter.ZigBeeConverterBatteryVoltage] - 680AE2FFFEC32FDF: ZigBee attribute reports ZclAttribute [cluster=Power Configuration, id=32, name=Battery Voltage, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=0, lastReportTime=Tue Oct 06 08:03:47 CEST 2020, implemented=true]
08:03:47.395 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=D3 state=RX_ACK
08:03:47.397 [DEBUG] [.converter.ZigBeeBaseChannelConverter] - 680AE2FFFEC32FDF: Channel zigbee:device:013725D7:680ae2fffec32fdf:680AE2FFFEC32FDF_1_batteryvoltage updated to 0.0 V
08:03:47.395 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
08:03:47.394 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 680AE2FFFEC32FDF: Thing is RFD, using long poll period of 1800sec
08:03:47.398 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: transactionComplete, state=COMPLETE, outstanding=0
08:03:47.397 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 680AE2FFFEC32FDF: Updating ZigBee channel state zigbee:device:013725D7:680ae2fffec32fdf:680AE2FFFEC32FDF_1_batteryvoltage to 0.0 V
08:03:47.397 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=D3, state=RX_ACK, outstanding=0
08:03:47.399 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=0, sleepy=0/3
08:03:47.398 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 680AE2FFFEC32FDF: Setting ONLINE/OFFLINE timeout interval to: 14430
08:03:47.400 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker added for thingUID=zigbee:device:013725D7:680ae2fffec32fdf
08:03:47.401 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker reset for handler with thingUID=zigbee:device:013725D7:680ae2fffec32fdf
08:03:47.401 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:013725D7:680ae2fffec32fdf in 14430 seconds
08:03:47.403 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=1, state=WAITING, sendCnt=0, command=ManagementBindRequest [0000/0 -> 8B4F/0, cluster=0033, TID=--, startIndex=0]]
08:03:47.403 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
08:03:47.404 [DEBUG] [.transaction.ZigBeeTransactionManager] - 8B4F/0: Sending ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=2, state=WAITING, sendCnt=0, command=ManagementBindRequest [0000/0 -> 8B4F/0, cluster=0033, TID=D4, startIndex=0]]
08:03:47.405 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
08:03:47.405 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementBindRequest [0000/0 -> 8B4F/0, cluster=0033, TID=D4, startIndex=0]
08:03:47.406 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=8B4F/0, profile=0000, cluster=0033, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=51, rssi=--, lqi=--, payload=D4 00]
08:03:47.414 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=DF]
08:03:49.449 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=8033, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=55], lastHopLqi=255, lastHopRssi=-42, sender=8B4F, bindingIndex=255, addressIndex=255, messageContents=D4 00 03 00 03 DF 2F C3 FE FF E2 0A 68 01 01 00 03 1F E4 D1 0D 00 6F 0D 00 01 DF 2F C3 FE FF E2 0A 68 01 08 00 03 1F E4 D1 0D 00 6F 0D 00 01 DF 2F C3 FE FF E2 0A 68 01 06 00 03 1F E4 D1 0D 00 6F 0D 00 01]
08:03:49.452 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=8B4F/0, destinationAddress=0000/0, profile=0000, cluster=8033, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=55, rssi=-42, lqi=FF, payload=D4 00 03 00 03 DF 2F C3 FE FF E2 0A 68 01 01 00 03 1F E4 D1 0D 00 6F 0D 00 01 DF 2F C3 FE FF E2 0A 68 01 08 00 03 1F E4 D1 0D 00 6F 0D 00 01 DF 2F C3 FE FF E2 0A 68 01 06 00 03 1F E4 D1 0D 00 6F 0D 00 01]
08:03:49.454 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementBindResponse [8B4F/0 -> 0000/0, cluster=8033, TID=D4, status=SUCCESS, bindingTableEntries=3, startIndex=0, bindingTableList=[BindingTable [srcAddr=680AE2FFFEC32FDF/1, dstAddr=000D6F000DD1E41F/1, clusterId=0001], BindingTable [srcAddr=680AE2FFFEC32FDF/1, dstAddr=000D6F000DD1E41F/1, clusterId=0008], BindingTable [srcAddr=680AE2FFFEC32FDF/1, dstAddr=000D6F000DD1E41F/1, clusterId=0006]]]
08:03:49.456 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementBindResponse [8B4F/0 -> 0000/0, cluster=8033, TID=D4, status=SUCCESS, bindingTableEntries=3, startIndex=0, bindingTableList=[BindingTable [srcAddr=680AE2FFFEC32FDF/1, dstAddr=000D6F000DD1E41F/1, clusterId=0001], BindingTable [srcAddr=680AE2FFFEC32FDF/1, dstAddr=000D6F000DD1E41F/1, clusterId=0008], BindingTable [srcAddr=680AE2FFFEC32FDF/1, dstAddr=000D6F000DD1E41F/1, clusterId=0006]]]
08:03:49.458 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=2055, state=COMPLETE, sendCnt=1, command=ManagementBindRequest [0000/0 -> 8B4F/0, cluster=0033, TID=D4, startIndex=0]]
08:03:49.458 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode  ] - 680AE2FFFEC32FDF: Binding table updated: [BindingTable [srcAddr=680AE2FFFEC32FDF/1, dstAddr=000D6F000DD1E41F/1, clusterId=0001], BindingTable [srcAddr=680AE2FFFEC32FDF/1, dstAddr=000D6F000DD1E41F/1, clusterId=0008], BindingTable [srcAddr=680AE2FFFEC32FDF/1, dstAddr=000D6F000DD1E41F/1, clusterId=0006]]
08:03:49.458 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=8B4F, apsFrame=EmberApsFrame [profileId=0000, clusterId=0033, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=DF], messageTag=D4, status=EMBER_SUCCESS, messageContents=]
08:03:49.459 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
08:03:49.461 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 680AE2FFFEC32FDF: Polling initialised at 1881958ms
08:03:49.462 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=D4 state=RX_ACK
08:03:49.462 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: transactionComplete, state=COMPLETE, outstanding=0
08:03:49.462 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zigbee:device:013725D7:680ae2fffec32fdf' changed from OFFLINE: Node has not completed discovery to ONLINE
08:03:49.477 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=0, sleepy=0/3
08:03:49.476 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=D4, state=RX_ACK, outstanding=0
08:03:49.475 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - 680AE2FFFEC32FDF: Done initialising ZigBee Thing handler
08:03:49.478 [DEBUG] [database.ZigBeeNetworkDatabaseManager] - 680AE2FFFEC32FDF: Data store: Deferring write for 250ms.
08:03:49.479 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker reset for handler with thingUID=zigbee:device:013725D7:680ae2fffec32fdf
08:03:49.480 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker cancelled task for thingUID=zigbee:device:013725D7:680ae2fffec32fdf
08:03:49.480 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:013725D7:680ae2fffec32fdf in 14430 seconds
08:03:49.481 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker reset for handler with thingUID=zigbee:device:013725D7:680ae2fffec32fdf
08:03:49.482 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker cancelled task for thingUID=zigbee:device:013725D7:680ae2fffec32fdf
08:03:49.482 [DEBUG] [g.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:013725D7:680ae2fffec32fdf in 14430 seconds
08:03:49.729 [DEBUG] [database.ZigBeeNetworkDatabaseManager] - 680AE2FFFEC32FDF: Data store: Writing node.
08:03:49.747 [DEBUG] [nding.zigbee.internal.ZigBeeDataStore] - 680AE2FFFEC32FDF: ZigBee saving network state complete.
08:03:56.433 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_BROADCAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=0006, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=56], lastHopLqi=255, lastHopRssi=-49, sender=8B4F, bindingIndex=255, addressIndex=255, messageContents=02 FD FF 04 01 01 19 00 00]
08:03:56.435 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=8B4F/0, destinationAddress=0000/0, profile=0000, cluster=0006, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=56, rssi=-49, lqi=FF, payload=02 FD FF 04 01 01 19 00 00]
08:03:56.437 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: MatchDescriptorRequest [8B4F/0 -> 0000/0, cluster=0006, TID=02, nwkAddrOfInterest=FFFD, profileId=0104, inClusterList=[25], outClusterList=[]]
08:03:56.439 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionCommand: MatchDescriptorRequest [8B4F/0 -> 0000/0, cluster=0006, TID=02, nwkAddrOfInterest=FFFD, profileId=0104, inClusterList=[25], outClusterList=[]]
08:03:56.441 [DEBUG] [ystems.zigbee.internal.ClusterMatcher] - 711D6B937B1552AB: ClusterMatcher received request MatchDescriptorRequest [8B4F/0 -> 0000/0, cluster=0006, TID=02, nwkAddrOfInterest=FFFD, profileId=0104, inClusterList=[25], outClusterList=[]]
08:03:56.444 [DEBUG] [ystems.zigbee.internal.ClusterMatcher] - 711D6B937B1552AB: ClusterMatcher sending match MatchDescriptorResponse [null -> 8B4F/0, cluster=8006, TID=02, status=SUCCESS, nwkAddrOfInterest=0000, matchList=[1]]
08:03:56.446 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=0, state=WAITING, sendCnt=0, command=MatchDescriptorResponse [0000/0 -> 8B4F/0, cluster=8006, TID=02, status=SUCCESS, nwkAddrOfInterest=0000, matchList=[1]]]
08:03:56.447 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
08:03:56.448 [DEBUG] [.transaction.ZigBeeTransactionManager] - 8B4F/0: Sending ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=3, state=WAITING, sendCnt=0, command=MatchDescriptorResponse [0000/0 -> 8B4F/0, cluster=8006, TID=02, status=SUCCESS, nwkAddrOfInterest=0000, matchList=[1]]]
08:03:56.449 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
08:03:56.450 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: MatchDescriptorResponse [0000/0 -> 8B4F/0, cluster=8006, TID=02, status=SUCCESS, nwkAddrOfInterest=0000, matchList=[1]]
08:03:56.450 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=8B4F/0, profile=0000, cluster=8006, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=52, rssi=--, lqi=--, payload=02 00 00 00 01 01]
08:03:56.460 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=E0]
08:03:57.466 [DEBUG] [.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=8B4F, apsFrame=EmberApsFrame [profileId=0000, clusterId=8006, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=E0], messageTag=02, status=EMBER_SUCCESS, messageContents=]
08:03:57.468 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=02 state=RX_ACK
08:03:57.470 [DEBUG] [.transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=02, state=RX_ACK, outstanding=1
08:03:57.472 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=680AE2FFFEC32FDF queueTime=1027, state=COMPLETE, sendCnt=1, command=MatchDescriptorResponse [0000/0 -> 8B4F/0, cluster=8006, TID=02, status=SUCCESS, nwkAddrOfInterest=0000, matchList=[1]]]
08:03:57.474 [DEBUG] [.transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
08:03:57.475 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - 680AE2FFFEC32FDF: transactionComplete, state=COMPLETE, outstanding=0
08:03:57.477 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=0, sleepy=0/3
08:03:57.479 [DEBUG] [.zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=8B4F, TID=02, event=RX_ACK, state=COMPLETE