feat: [NPM] send more AI logs (#1230)

huntergregory · web-flow · commit c820189a2f75 · 2022-02-09T15:28:05.000-08:00
* send heartbeat log and send logs in v2

* address comment and add logs for ip validation and policy manager bootup
diff --git a/npm/cmd/start.go b/npm/cmd/start.go
@@ -160,6 +160,7 @@ func start(config npmconfig.Config, flags npmconfig.Flags) error {
 
 	go restserver.NPMRestServerListenAndServe(config, npMgr)
 
+	metrics.SendLog(util.NpmID, "starting NPM")
 	if err = npMgr.Start(config, stopChannel); err != nil {
 		metrics.SendErrorLogAndMetric(util.NpmID, "Failed to start NPM due to %+v", err)
 		return fmt.Errorf("failed to start with err: %w", err)
diff --git a/npm/iptm/iptm.go b/npm/iptm/iptm.go
@@ -330,6 +330,7 @@ func (iptMgr *IptablesManager) reconcileChains(stopCh <-chan struct{}) {
 			if err := iptMgr.checkAndAddForwardChain(); err != nil {
 				metrics.SendErrorLogAndMetric(util.NpmID, "Error: failed to reconcileChains Azure-NPM due to %s", err.Error())
 			}
+			metrics.SendHeartbeatLog()
 		}
 	}
 }
diff --git a/npm/metrics/ai-utils.go b/npm/metrics/ai-utils.go
@@ -62,29 +62,37 @@ func SendErrorLogAndMetric(operationID int, format string, args ...interface{})
 
 	// Send error logs
 	msg := fmt.Sprintf(format, args...)
-	report := aitelemetry.Report{
-		Message:          msg,
-		Context:          strconv.Itoa(operationID),
-		CustomDimensions: make(map[string]string),
-	}
 	log.Errorf(msg)
-	SendLog(report)
+	SendLog(operationID, msg)
 }
 
 // SendMetric sends metrics
 func SendMetric(metric aitelemetry.Metric) {
 	if th == nil {
-		log.Logf("AppInsights didn't initialized.")
+		log.Logf("AppInsights didn't initialize")
 		return
 	}
 	th.TrackMetric(metric)
 }
 
 // SendLog sends log
-func SendLog(report aitelemetry.Report) {
+func SendLog(operationID int, msg string) {
+	report := aitelemetry.Report{
+		Message:          msg,
+		Context:          strconv.Itoa(operationID),
+		CustomDimensions: make(map[string]string),
+	}
 	if th == nil {
 		log.Logf("AppInsights didn't initialized.")
 		return
 	}
 	th.TrackLog(report)
 }
+
+func SendHeartbeatLog() {
+	numPolicies, err := GetNumPolicies()
+	if err != nil {
+		message := fmt.Sprintf("Info: NPM currently has %d policies", numPolicies)
+		SendLog(util.NpmID, message)
+	}
+}
diff --git a/npm/pkg/dataplane/dataplane.go b/npm/pkg/dataplane/dataplane.go
@@ -9,6 +9,7 @@ import (
 	"github.com/Azure/azure-container-networking/npm/metrics"
 	"github.com/Azure/azure-container-networking/npm/pkg/dataplane/ipsets"
 	"github.com/Azure/azure-container-networking/npm/pkg/dataplane/policies"
+	"github.com/Azure/azure-container-networking/npm/util"
 	npmerrors "github.com/Azure/azure-container-networking/npm/util/errors"
 	"k8s.io/klog"
 )
@@ -111,9 +112,9 @@ func (dp *DataPlane) AddToSets(setNames []*ipsets.IPSetMetadata, podMetadata *Po
 		return fmt.Errorf("[DataPlane] error while adding to set: %w", err)
 	}
 	if dp.shouldUpdatePod() {
-		klog.Infof("[Dataplane] Updating Sets to Add for pod key %s", podMetadata.PodKey)
+		klog.Infof("[DataPlane] Updating Sets to Add for pod key %s", podMetadata.PodKey)
 		if _, ok := dp.updatePodCache[podMetadata.PodKey]; !ok {
-			klog.Infof("[Dataplane] {AddToSet} pod key %s not found creating a new obj", podMetadata.PodKey)
+			klog.Infof("[DataPlane] {AddToSet} pod key %s not found creating a new obj", podMetadata.PodKey)
 			dp.updatePodCache[podMetadata.PodKey] = newUpdateNPMPod(podMetadata)
 		}
 
@@ -132,9 +133,9 @@ func (dp *DataPlane) RemoveFromSets(setNames []*ipsets.IPSetMetadata, podMetadat
 	}
 
 	if dp.shouldUpdatePod() {
-		klog.Infof("[Dataplane] Updating Sets to Remove for pod key %s", podMetadata.PodKey)
+		klog.Infof("[DataPlane] Updating Sets to Remove for pod key %s", podMetadata.PodKey)
 		if _, ok := dp.updatePodCache[podMetadata.PodKey]; !ok {
-			klog.Infof("[Dataplane] {RemoveFromSet} pod key %s not found creating a new obj", podMetadata.PodKey)
+			klog.Infof("[DataPlane] {RemoveFromSet} pod key %s not found creating a new obj", podMetadata.PodKey)
 			dp.updatePodCache[podMetadata.PodKey] = newUpdateNPMPod(podMetadata)
 		}
 
@@ -179,6 +180,7 @@ func (dp *DataPlane) ApplyDataPlane() error {
 		for podKey, pod := range dp.updatePodCache {
 			err := dp.updatePod(pod)
 			if err != nil {
+				metrics.SendErrorLogAndMetric(util.DaemonDataplaneID, "error: failed to update pods: %s", err.Error())
 				return fmt.Errorf("[DataPlane] error while updating pod: %w", err)
 			}
 			delete(dp.updatePodCache, podKey)
@@ -292,7 +294,7 @@ func (dp *DataPlane) createIPSetsAndReferences(sets []*ipsets.TranslatedIPSet, n
 		dp.ipsetMgr.CreateIPSets([]*ipsets.IPSetMetadata{set.Metadata})
 		err := dp.ipsetMgr.AddReference(set.Metadata.GetPrefixName(), netpolName, referenceType)
 		if err != nil {
-			return npmerrors.Errorf(npmErrorString, false, fmt.Sprintf("[dataplane] failed to add reference with err: %s", err.Error()))
+			return npmerrors.Errorf(npmErrorString, false, fmt.Sprintf("[DataPlane] failed to add reference with err: %s", err.Error()))
 		}
 	}
 
@@ -308,19 +310,19 @@ func (dp *DataPlane) createIPSetsAndReferences(sets []*ipsets.TranslatedIPSet, n
 			for _, ipblock := range set.Members {
 				err := validateIPBlock(ipblock)
 				if err != nil {
-					return npmerrors.Errorf(npmErrorString, false, fmt.Sprintf("[dataplane] failed to parseCIDR in addIPSetReferences with err: %s", err.Error()))
+					return npmerrors.Errorf(npmErrorString, false, fmt.Sprintf("[DataPlane] failed to parseCIDR in addIPSetReferences with err: %s", err.Error()))
 				}
 				err = dp.ipsetMgr.AddToSets([]*ipsets.IPSetMetadata{set.Metadata}, ipblock, "")
 				if err != nil {
-					return npmerrors.Errorf(npmErrorString, false, fmt.Sprintf("[dataplane] failed to AddToSet in addIPSetReferences with err: %s", err.Error()))
+					return npmerrors.Errorf(npmErrorString, false, fmt.Sprintf("[DataPlane] failed to AddToSet in addIPSetReferences with err: %s", err.Error()))
 				}
 			}
 		} else if setType == ipsets.NestedLabelOfPod && len(set.Members) > 0 {
 			// Check if any 2nd level IPSets are generated by Controller with members
 			// Apply members to the list set
 			err := dp.ipsetMgr.AddToLists([]*ipsets.IPSetMetadata{set.Metadata}, getMembersOfTranslatedSets(set.Members))
 			if err != nil {
-				return npmerrors.Errorf(npmErrorString, false, fmt.Sprintf("[dataplane] failed to AddToList in addIPSetReferences with err: %s", err.Error()))
+				return npmerrors.Errorf(npmErrorString, false, fmt.Sprintf("[DataPlane] failed to AddToList in addIPSetReferences with err: %s", err.Error()))
 			}
 		}
 	}
@@ -338,7 +340,7 @@ func (dp *DataPlane) deleteIPSetsAndReferences(sets []*ipsets.TranslatedIPSet, n
 		// TODO add delete ipset after removing members
 		err := dp.ipsetMgr.DeleteReference(set.Metadata.GetPrefixName(), netpolName, referenceType)
 		if err != nil {
-			return npmerrors.Errorf(npmErrorString, false, fmt.Sprintf("[dataplane] failed to deleteIPSetReferences with err: %s", err.Error()))
+			return npmerrors.Errorf(npmErrorString, false, fmt.Sprintf("[DataPlane] failed to deleteIPSetReferences with err: %s", err.Error()))
 		}
 	}
 
@@ -356,18 +358,18 @@ func (dp *DataPlane) deleteIPSetsAndReferences(sets []*ipsets.TranslatedIPSet, n
 			for _, ipblock := range set.Members {
 				err := validateIPBlock(ipblock)
 				if err != nil {
-					return npmerrors.Errorf(npmErrorString, false, fmt.Sprintf("[dataplane] failed to parseCIDR in deleteIPSetReferences with err: %s", err.Error()))
+					return npmerrors.Errorf(npmErrorString, false, fmt.Sprintf("[DataPlane] failed to parseCIDR in deleteIPSetReferences with err: %s", err.Error()))
 				}
 				err = dp.ipsetMgr.RemoveFromSets([]*ipsets.IPSetMetadata{set.Metadata}, ipblock, "")
 				if err != nil {
-					return npmerrors.Errorf(npmErrorString, false, fmt.Sprintf("[dataplane] failed to RemoveFromSet in deleteIPSetReferences with err: %s", err.Error()))
+					return npmerrors.Errorf(npmErrorString, false, fmt.Sprintf("[DataPlane] failed to RemoveFromSet in deleteIPSetReferences with err: %s", err.Error()))
 				}
 			}
 		} else if set.Metadata.GetSetKind() == ipsets.ListSet && len(set.Members) > 0 {
 			// Delete if any 2nd level IPSets are generated by Controller with members
 			err := dp.ipsetMgr.RemoveFromList(set.Metadata, getMembersOfTranslatedSets(set.Members))
 			if err != nil {
-				return npmerrors.Errorf(npmErrorString, false, fmt.Sprintf("[dataplane] failed to RemoveFromList in deleteIPSetReferences with err: %s", err.Error()))
+				return npmerrors.Errorf(npmErrorString, false, fmt.Sprintf("[DataPlane] failed to RemoveFromList in deleteIPSetReferences with err: %s", err.Error()))
 			}
 
 		}
@@ -385,6 +387,7 @@ func validateIPBlock(ipblock string) error {
 	onlyCidr := strings.Split(ipblock, " ")[0]
 	_, _, err := net.ParseCIDR(onlyCidr)
 	if err != nil {
+		metrics.SendErrorLogAndMetric(util.IpsmID, "error: failed to parse CIDR: %s", err.Error())
 		return npmerrors.SimpleErrorWrapper("failed to parse CIDR", err)
 	}
 	return nil
diff --git a/npm/pkg/dataplane/ipsets/ipsetmanager.go b/npm/pkg/dataplane/ipsets/ipsetmanager.go
@@ -6,6 +6,7 @@ import (
 
 	"github.com/Azure/azure-container-networking/common"
 	"github.com/Azure/azure-container-networking/npm/metrics"
+	"github.com/Azure/azure-container-networking/npm/util"
 	npmerrors "github.com/Azure/azure-container-networking/npm/util/errors"
 	"k8s.io/klog"
 )
@@ -52,6 +53,7 @@ func (iMgr *IPSetManager) ResetIPSets() error {
 	defer iMgr.Unlock()
 	err := iMgr.resetIPSets()
 	if err != nil {
+		metrics.SendErrorLogAndMetric(util.IpsmID, "error: failed to reset ipsetmanager: %s", err.Error())
 		return fmt.Errorf("error while resetting ipsetmanager: %w", err)
 	}
 	// TODO update prometheus metrics here instead of in OS-specific functions (done in Linux right now)
@@ -122,12 +124,16 @@ func (iMgr *IPSetManager) AddReference(setName, referenceName string, referenceT
 		if referenceType == NetPolType {
 			npmErrorString = npmerrors.AddNetPolReference
 		}
-		return npmerrors.Errorf(npmErrorString, false, fmt.Sprintf("ipset %s does not exist", setName))
+		msg := fmt.Sprintf("ipset %s does not exist", setName)
+		metrics.SendErrorLogAndMetric(util.IpsmID, "error: failed to add reference: %s", msg)
+		return npmerrors.Errorf(npmErrorString, false, msg)
 	}
 
 	set := iMgr.setMap[setName]
 	if referenceType == SelectorType && !set.canSetBeSelectorIPSet() {
-		return npmerrors.Errorf(npmerrors.AddSelectorReference, false, fmt.Sprintf("ipset %s is not a selector ipset it is of type %s", setName, set.Type.String()))
+		msg := fmt.Sprintf("ipset %s is not a selector ipset it is of type %s", setName, set.Type.String())
+		metrics.SendErrorLogAndMetric(util.IpsmID, "error: failed to add reference: %s", msg)
+		return npmerrors.Errorf(npmerrors.AddSelectorReference, false, msg)
 	}
 	wasInKernel := iMgr.shouldBeInKernel(set)
 	set.addReference(referenceName, referenceType)
@@ -152,7 +158,9 @@ func (iMgr *IPSetManager) DeleteReference(setName, referenceName string, referen
 		if referenceType == NetPolType {
 			npmErrorString = npmerrors.DeleteNetPolReference
 		}
-		return npmerrors.Errorf(npmErrorString, false, fmt.Sprintf("ipset %s does not exist", setName))
+		msg := fmt.Sprintf("ipset %s does not exist", setName)
+		metrics.SendErrorLogAndMetric(util.IpsmID, "error: failed to delete reference: %s", msg)
+		return npmerrors.Errorf(npmErrorString, false, msg)
 	}
 
 	set := iMgr.setMap[setName]
@@ -188,7 +196,9 @@ func (iMgr *IPSetManager) AddToSets(addToSets []*IPSetMetadata, ip, podKey strin
 			set = iMgr.setMap[prefixedName]
 		}
 		if set.Kind != HashSet {
-			return npmerrors.Errorf(npmerrors.AppendIPSet, false, fmt.Sprintf("ipset %s is not a hash set", prefixedName))
+			msg := fmt.Sprintf("ipset %s is not a hash set", prefixedName)
+			metrics.SendErrorLogAndMetric(util.IpsmID, "error: failed to add to sets: %s", msg)
+			return npmerrors.Errorf(npmerrors.AppendIPSet, false, msg)
 		}
 
 		// 2. add ip to the set, and update the pod key
@@ -219,7 +229,9 @@ func (iMgr *IPSetManager) RemoveFromSets(removeFromSets []*IPSetMetadata, ip, po
 			continue
 		}
 		if set.Kind != HashSet {
-			return npmerrors.Errorf(npmerrors.DeleteIPSet, false, fmt.Sprintf("ipset %s is not a hash set", prefixedName))
+			msg := fmt.Sprintf("ipset %s is not a hash set", prefixedName)
+			metrics.SendErrorLogAndMetric(util.IpsmID, "error: failed to remove from sets: %s", msg)
+			return npmerrors.Errorf(npmerrors.DeleteIPSet, false, msg)
 		}
 
 		// 2. remove ip from the set
@@ -264,7 +276,9 @@ func (iMgr *IPSetManager) AddToLists(listMetadatas, setMetadatas []*IPSetMetadat
 		// Nested IPSets are only supported for windows
 		// Check if we want to actually use that support
 		if set.Kind != HashSet {
-			return npmerrors.Errorf(npmerrors.AppendIPSet, false, fmt.Sprintf("ipset %s is not a hash set and nested list sets are not supported", setName))
+			msg := fmt.Sprintf("ipset %s is not a hash set and nested list sets are not supported", setName)
+			metrics.SendErrorLogAndMetric(util.IpsmID, "error: failed to add to lists: %s", msg)
+			return npmerrors.Errorf(npmerrors.AppendIPSet, false, msg)
 		}
 	}
 
@@ -279,7 +293,9 @@ func (iMgr *IPSetManager) AddToLists(listMetadatas, setMetadatas []*IPSetMetadat
 		}
 
 		if list.Kind != ListSet {
-			return npmerrors.Errorf(npmerrors.AppendIPSet, false, fmt.Sprintf("ipset %s is not a list set", listName))
+			msg := fmt.Sprintf("ipset %s is not a list set", listName)
+			metrics.SendErrorLogAndMetric(util.IpsmID, "error: failed to add to lists: %s", msg)
+			return npmerrors.Errorf(npmerrors.AppendIPSet, false, msg)
 		}
 
 		modified := false
@@ -323,7 +339,9 @@ func (iMgr *IPSetManager) RemoveFromList(listMetadata *IPSetMetadata, setMetadat
 	}
 
 	if list.Kind != ListSet {
-		return npmerrors.Errorf(npmerrors.DeleteIPSet, false, fmt.Sprintf("ipset %s is not a list set", listName))
+		msg := fmt.Sprintf("ipset %s is not a list set", listName)
+		metrics.SendErrorLogAndMetric(util.IpsmID, "error: failed to remove from list: %s", msg)
+		return npmerrors.Errorf(npmerrors.DeleteIPSet, false, msg)
 	}
 
 	modified := false
@@ -340,7 +358,9 @@ func (iMgr *IPSetManager) RemoveFromList(listMetadata *IPSetMetadata, setMetadat
 			if modified {
 				iMgr.modifyCacheForKernelMemberUpdate(list)
 			}
-			return npmerrors.Errorf(npmerrors.DeleteIPSet, false, fmt.Sprintf("ipset %s is not a hash set and nested list sets are not supported", memberName))
+			msg := fmt.Sprintf("ipset %s is not a hash set and nested list sets are not supported", memberName)
+			metrics.SendErrorLogAndMetric(util.IpsmID, "error: failed to remove from list: %s", msg)
+			return npmerrors.Errorf(npmerrors.DeleteIPSet, false, msg)
 		}
 
 		// 2. remove member from the list
@@ -382,6 +402,7 @@ func (iMgr *IPSetManager) ApplyIPSets() error {
 	// Call the appropriate apply ipsets
 	err := iMgr.applyIPSets()
 	if err != nil {
+		metrics.SendErrorLogAndMetric(util.IpsmID, "error: failed to apply ipsets: %s", err.Error())
 		return err
 	}
 
@@ -494,12 +515,17 @@ func (iMgr *IPSetManager) modifyCacheForKernelMemberUpdate(set *IPSet) {
 // sanitizeDirtyCache will check if any set marked as delete is in toAddUpdate
 // if so will not delete it
 func (iMgr *IPSetManager) sanitizeDirtyCache() {
+	anyProblems := false
 	for setName := range iMgr.toDeleteCache {
 		_, ok := iMgr.toAddOrUpdateCache[setName]
 		if ok {
-			klog.Errorf("[IPSetManager] Unexpected state in dirty cache %s set is part of both update and delete caches \n ", setName)
+			klog.Errorf("[IPSetManager] Unexpected state in dirty cache %s set is part of both update and delete caches", setName)
+			anyProblems = true
 		}
 	}
+	if anyProblems {
+		metrics.SendErrorLogAndMetric(util.IpsmID, "error: some dirty cache sets are part of both update and delete caches")
+	}
 }
 
 func (iMgr *IPSetManager) clearDirtyCache() {
diff --git a/npm/pkg/dataplane/policies/chain-management_linux.go b/npm/pkg/dataplane/policies/chain-management_linux.go
@@ -194,7 +194,9 @@ func (pMgr *PolicyManager) bootup(_ []string) error {
 // - cleans up stale policy chains. It can be forced to stop this process if reconcileManager.forceLock() is called.
 func (pMgr *PolicyManager) reconcile() {
 	if err := pMgr.positionAzureChainJumpRule(); err != nil {
-		klog.Errorf("failed to reconcile jump rule to Azure-NPM due to %s", err.Error())
+		msg := fmt.Sprintf("failed to reconcile jump rule to Azure-NPM due to %s", err.Error())
+		metrics.SendErrorLogAndMetric(util.IptmID, "error: %s", msg)
+		klog.Error(msg)
 	}
 
 	pMgr.reconcileManager.Lock()
@@ -207,7 +209,9 @@ func (pMgr *PolicyManager) reconcile() {
 
 	klog.Infof("cleaning up these stale chains: %+v", staleChains)
 	if err := pMgr.cleanupChains(staleChains); err != nil {
-		klog.Errorf("failed to clean up old policy chains with the following error: %s", err.Error())
+		msg := fmt.Sprintf("failed to clean up old policy chains with the following error: %s", err.Error())
+		metrics.SendErrorLogAndMetric(util.IptmID, "error: %s", msg)
+		klog.Error(msg)
 	}
 }
 
diff --git a/npm/pkg/dataplane/policies/policymanager.go b/npm/pkg/dataplane/policies/policymanager.go
@@ -7,6 +7,7 @@ import (
 
 	"github.com/Azure/azure-container-networking/common"
 	"github.com/Azure/azure-container-networking/npm/metrics"
+	"github.com/Azure/azure-container-networking/npm/util"
 	npmerrors "github.com/Azure/azure-container-networking/npm/util/errors"
 	"k8s.io/klog"
 )
@@ -62,6 +63,7 @@ func NewPolicyManager(ioShim *common.IOShim, cfg *PolicyManagerCfg) *PolicyManag
 
 func (pMgr *PolicyManager) Bootup(epIDs []string) error {
 	if err := pMgr.bootup(epIDs); err != nil {
+		metrics.SendErrorLogAndMetric(util.IptmID, "error: failed to bootup policy manager: %s", err.Error())
 		return npmerrors.ErrorWrapper(npmerrors.BootupPolicyMgr, false, "failed to bootup policy manager", err)
 	}
 	return nil
@@ -78,6 +80,7 @@ func (pMgr *PolicyManager) Reconcile(stopChannel <-chan struct{}) {
 				return
 			case <-ticker.C:
 				pMgr.reconcile()
+				metrics.SendHeartbeatLog()
 			}
 		}
 	}()
@@ -102,13 +105,17 @@ func (pMgr *PolicyManager) AddPolicy(policy *NPMNetworkPolicy, endpointList map[
 	defer metrics.RecordACLRuleExecTime(prometheusTimer) // record execution time regardless of failure
 	normalizePolicy(policy)
 	if err := validatePolicy(policy); err != nil {
-		return npmerrors.Errorf(npmerrors.AddPolicy, false, fmt.Sprintf("couldn't add malformed policy: %s", err.Error()))
+		msg := fmt.Sprintf("failed to validate policy: %s", err.Error())
+		metrics.SendErrorLogAndMetric(util.IptmID, "error: %s", msg)
+		return npmerrors.Errorf(npmerrors.AddPolicy, false, msg)
 	}
 
 	// Call actual dataplane function to apply changes
 	err := pMgr.addPolicy(policy, endpointList)
 	if err != nil {
-		return npmerrors.Errorf(npmerrors.AddPolicy, false, fmt.Sprintf("failed to add policy: %v", err))
+		msg := fmt.Sprintf("failed to add policy: %s", err.Error())
+		metrics.SendErrorLogAndMetric(util.IptmID, "error: %s", msg)
+		return npmerrors.Errorf(npmerrors.AddPolicy, false, msg)
 	}
 
 	pMgr.policyMap.cache[policy.PolicyKey] = policy
@@ -133,7 +140,9 @@ func (pMgr *PolicyManager) RemovePolicy(policyKey string, endpointList map[strin
 	// Call actual dataplane function to apply changes
 	err := pMgr.removePolicy(policy, endpointList)
 	if err != nil {
-		return npmerrors.Errorf(npmerrors.RemovePolicy, false, fmt.Sprintf("failed to remove policy: %v", err))
+		msg := fmt.Sprintf("failed to remove policy: %s", err.Error())
+		metrics.SendErrorLogAndMetric(util.IptmID, "error: %s", msg)
+		return npmerrors.Errorf(npmerrors.RemovePolicy, false, msg)
 	}
 
 	delete(pMgr.policyMap.cache, policyKey)
diff --git a/npm/util/const.go b/npm/util/const.go
diff --git a/npm/util/ioutil/restore.go b/npm/util/ioutil/restore.go

Original file line number	Diff line number	Diff line change
`@@ -330,6 +330,7 @@ func (iptMgr *IptablesManager) reconcileChains(stopCh <-chan struct{}) {`
`330`	`330`	`if err := iptMgr.checkAndAddForwardChain(); err != nil {`
`331`	`331`	`metrics.SendErrorLogAndMetric(util.NpmID, "Error: failed to reconcileChains Azure-NPM due to %s", err.Error())`
`332`	`332`	`}`
	`333`	`+ metrics.SendHeartbeatLog()`
`333`	`334`	`}`
`334`	`335`	`}`
`335`	`336`	`}`
Original file line number	Diff line number	Diff line change
`@@ -9,6 +9,7 @@ import (`
`9`	`9`	`"github.com/Azure/azure-container-networking/npm/metrics"`
`10`	`10`	`"github.com/Azure/azure-container-networking/npm/pkg/dataplane/ipsets"`
`11`	`11`	`"github.com/Azure/azure-container-networking/npm/pkg/dataplane/policies"`
	`12`	`+ "github.com/Azure/azure-container-networking/npm/util"`
`12`	`13`	`npmerrors "github.com/Azure/azure-container-networking/npm/util/errors"`
`13`	`14`	`"k8s.io/klog"`
`14`	`15`	`)`
`@@ -111,9 +112,9 @@ func (dp DataPlane) AddToSets(setNames []ipsets.IPSetMetadata, podMetadata *Po`
`111`	`112`	`return fmt.Errorf("[DataPlane] error while adding to set: %w", err)`
`112`	`113`	`}`
`113`	`114`	`if dp.shouldUpdatePod() {`
`114`		`- klog.Infof("[Dataplane] Updating Sets to Add for pod key %s", podMetadata.PodKey)`
	`115`	`+ klog.Infof("[DataPlane] Updating Sets to Add for pod key %s", podMetadata.PodKey)`
`115`	`116`	`if _, ok := dp.updatePodCache[podMetadata.PodKey]; !ok {`
`116`		`- klog.Infof("[Dataplane] {AddToSet} pod key %s not found creating a new obj", podMetadata.PodKey)`
	`117`	`+ klog.Infof("[DataPlane] {AddToSet} pod key %s not found creating a new obj", podMetadata.PodKey)`
`117`	`118`	`dp.updatePodCache[podMetadata.PodKey] = newUpdateNPMPod(podMetadata)`
`118`	`119`	`}`
`119`	`120`
`@@ -132,9 +133,9 @@ func (dp DataPlane) RemoveFromSets(setNames []ipsets.IPSetMetadata, podMetadat`
`132`	`133`	`}`
`133`	`134`
`134`	`135`	`if dp.shouldUpdatePod() {`
`135`		`- klog.Infof("[Dataplane] Updating Sets to Remove for pod key %s", podMetadata.PodKey)`
	`136`	`+ klog.Infof("[DataPlane] Updating Sets to Remove for pod key %s", podMetadata.PodKey)`
`136`	`137`	`if _, ok := dp.updatePodCache[podMetadata.PodKey]; !ok {`
`137`		`- klog.Infof("[Dataplane] {RemoveFromSet} pod key %s not found creating a new obj", podMetadata.PodKey)`
	`138`	`+ klog.Infof("[DataPlane] {RemoveFromSet} pod key %s not found creating a new obj", podMetadata.PodKey)`
`138`	`139`	`dp.updatePodCache[podMetadata.PodKey] = newUpdateNPMPod(podMetadata)`
`139`	`140`	`}`
`140`	`141`
`@@ -179,6 +180,7 @@ func (dp *DataPlane) ApplyDataPlane() error {`
`179`	`180`	`for podKey, pod := range dp.updatePodCache {`
`180`	`181`	`err := dp.updatePod(pod)`
`181`	`182`	`if err != nil {`
	`183`	`+ metrics.SendErrorLogAndMetric(util.DaemonDataplaneID, "error: failed to update pods: %s", err.Error())`
`182`	`184`	`return fmt.Errorf("[DataPlane] error while updating pod: %w", err)`
`183`	`185`	`}`
`184`	`186`	`delete(dp.updatePodCache, podKey)`
`@@ -292,7 +294,7 @@ func (dp DataPlane) createIPSetsAndReferences(sets []ipsets.TranslatedIPSet, n`
`292`	`294`	`dp.ipsetMgr.CreateIPSets([]*ipsets.IPSetMetadata{set.Metadata})`
`293`	`295`	`err := dp.ipsetMgr.AddReference(set.Metadata.GetPrefixName(), netpolName, referenceType)`
`294`	`296`	`if err != nil {`
`295`		`- return npmerrors.Errorf(npmErrorString, false, fmt.Sprintf("[dataplane] failed to add reference with err: %s", err.Error()))`
	`297`	`+ return npmerrors.Errorf(npmErrorString, false, fmt.Sprintf("[DataPlane] failed to add reference with err: %s", err.Error()))`
`296`	`298`	`}`
`297`	`299`	`}`
`298`	`300`
`@@ -308,19 +310,19 @@ func (dp DataPlane) createIPSetsAndReferences(sets []ipsets.TranslatedIPSet, n`
`308`	`310`	`for _, ipblock := range set.Members {`
`309`	`311`	`err := validateIPBlock(ipblock)`
`310`	`312`	`if err != nil {`
`311`		`- return npmerrors.Errorf(npmErrorString, false, fmt.Sprintf("[dataplane] failed to parseCIDR in addIPSetReferences with err: %s", err.Error()))`
	`313`	`+ return npmerrors.Errorf(npmErrorString, false, fmt.Sprintf("[DataPlane] failed to parseCIDR in addIPSetReferences with err: %s", err.Error()))`
`312`	`314`	`}`
`313`	`315`	`err = dp.ipsetMgr.AddToSets([]*ipsets.IPSetMetadata{set.Metadata}, ipblock, "")`
`314`	`316`	`if err != nil {`
`315`		`- return npmerrors.Errorf(npmErrorString, false, fmt.Sprintf("[dataplane] failed to AddToSet in addIPSetReferences with err: %s", err.Error()))`
	`317`	`+ return npmerrors.Errorf(npmErrorString, false, fmt.Sprintf("[DataPlane] failed to AddToSet in addIPSetReferences with err: %s", err.Error()))`
`316`	`318`	`}`
`317`	`319`	`}`
`318`	`320`	`} else if setType == ipsets.NestedLabelOfPod && len(set.Members) > 0 {`
`319`	`321`	`// Check if any 2nd level IPSets are generated by Controller with members`
`320`	`322`	`// Apply members to the list set`
`321`	`323`	`err := dp.ipsetMgr.AddToLists([]*ipsets.IPSetMetadata{set.Metadata}, getMembersOfTranslatedSets(set.Members))`
`322`	`324`	`if err != nil {`
`323`		`- return npmerrors.Errorf(npmErrorString, false, fmt.Sprintf("[dataplane] failed to AddToList in addIPSetReferences with err: %s", err.Error()))`
	`325`	`+ return npmerrors.Errorf(npmErrorString, false, fmt.Sprintf("[DataPlane] failed to AddToList in addIPSetReferences with err: %s", err.Error()))`
`324`	`326`	`}`
`325`	`327`	`}`
`326`	`328`	`}`
`@@ -338,7 +340,7 @@ func (dp DataPlane) deleteIPSetsAndReferences(sets []ipsets.TranslatedIPSet, n`
`338`	`340`	`// TODO add delete ipset after removing members`
`339`	`341`	`err := dp.ipsetMgr.DeleteReference(set.Metadata.GetPrefixName(), netpolName, referenceType)`
`340`	`342`	`if err != nil {`
`341`		`- return npmerrors.Errorf(npmErrorString, false, fmt.Sprintf("[dataplane] failed to deleteIPSetReferences with err: %s", err.Error()))`
	`343`	`+ return npmerrors.Errorf(npmErrorString, false, fmt.Sprintf("[DataPlane] failed to deleteIPSetReferences with err: %s", err.Error()))`
`342`	`344`	`}`
`343`	`345`	`}`
`344`	`346`
`@@ -356,18 +358,18 @@ func (dp DataPlane) deleteIPSetsAndReferences(sets []ipsets.TranslatedIPSet, n`
`356`	`358`	`for _, ipblock := range set.Members {`
`357`	`359`	`err := validateIPBlock(ipblock)`
`358`	`360`	`if err != nil {`
`359`		`- return npmerrors.Errorf(npmErrorString, false, fmt.Sprintf("[dataplane] failed to parseCIDR in deleteIPSetReferences with err: %s", err.Error()))`
	`361`	`+ return npmerrors.Errorf(npmErrorString, false, fmt.Sprintf("[DataPlane] failed to parseCIDR in deleteIPSetReferences with err: %s", err.Error()))`
`360`	`362`	`}`
`361`	`363`	`err = dp.ipsetMgr.RemoveFromSets([]*ipsets.IPSetMetadata{set.Metadata}, ipblock, "")`
`362`	`364`	`if err != nil {`
`363`		`- return npmerrors.Errorf(npmErrorString, false, fmt.Sprintf("[dataplane] failed to RemoveFromSet in deleteIPSetReferences with err: %s", err.Error()))`
	`365`	`+ return npmerrors.Errorf(npmErrorString, false, fmt.Sprintf("[DataPlane] failed to RemoveFromSet in deleteIPSetReferences with err: %s", err.Error()))`
`364`	`366`	`}`
`365`	`367`	`}`
`366`	`368`	`} else if set.Metadata.GetSetKind() == ipsets.ListSet && len(set.Members) > 0 {`
`367`	`369`	`// Delete if any 2nd level IPSets are generated by Controller with members`
`368`	`370`	`err := dp.ipsetMgr.RemoveFromList(set.Metadata, getMembersOfTranslatedSets(set.Members))`
`369`	`371`	`if err != nil {`
`370`		`- return npmerrors.Errorf(npmErrorString, false, fmt.Sprintf("[dataplane] failed to RemoveFromList in deleteIPSetReferences with err: %s", err.Error()))`
	`372`	`+ return npmerrors.Errorf(npmErrorString, false, fmt.Sprintf("[DataPlane] failed to RemoveFromList in deleteIPSetReferences with err: %s", err.Error()))`
`371`	`373`	`}`
`372`	`374`
`373`	`375`	`}`
`@@ -385,6 +387,7 @@ func validateIPBlock(ipblock string) error {`
`385`	`387`	`onlyCidr := strings.Split(ipblock, " ")[0]`
`386`	`388`	`_, _, err := net.ParseCIDR(onlyCidr)`
`387`	`389`	`if err != nil {`
	`390`	`+ metrics.SendErrorLogAndMetric(util.IpsmID, "error: failed to parse CIDR: %s", err.Error())`
`388`	`391`	`return npmerrors.SimpleErrorWrapper("failed to parse CIDR", err)`
`389`	`392`	`}`
`390`	`393`	`return nil`
Original file line number	Diff line number	Diff line change
`@@ -6,6 +6,7 @@ import (`
`6`	`6`
`7`	`7`	`"github.com/Azure/azure-container-networking/common"`
`8`	`8`	`"github.com/Azure/azure-container-networking/npm/metrics"`
	`9`	`+ "github.com/Azure/azure-container-networking/npm/util"`
`9`	`10`	`npmerrors "github.com/Azure/azure-container-networking/npm/util/errors"`
`10`	`11`	`"k8s.io/klog"`
`11`	`12`	`)`
`@@ -52,6 +53,7 @@ func (iMgr *IPSetManager) ResetIPSets() error {`
`52`	`53`	`defer iMgr.Unlock()`
`53`	`54`	`err := iMgr.resetIPSets()`
`54`	`55`	`if err != nil {`
	`56`	`+ metrics.SendErrorLogAndMetric(util.IpsmID, "error: failed to reset ipsetmanager: %s", err.Error())`
`55`	`57`	`return fmt.Errorf("error while resetting ipsetmanager: %w", err)`
`56`	`58`	`}`
`57`	`59`	`// TODO update prometheus metrics here instead of in OS-specific functions (done in Linux right now)`
`@@ -122,12 +124,16 @@ func (iMgr *IPSetManager) AddReference(setName, referenceName string, referenceT`
`122`	`124`	`if referenceType == NetPolType {`
`123`	`125`	`npmErrorString = npmerrors.AddNetPolReference`
`124`	`126`	`}`
`125`		`- return npmerrors.Errorf(npmErrorString, false, fmt.Sprintf("ipset %s does not exist", setName))`
	`127`	`+ msg := fmt.Sprintf("ipset %s does not exist", setName)`
	`128`	`+ metrics.SendErrorLogAndMetric(util.IpsmID, "error: failed to add reference: %s", msg)`
	`129`	`+ return npmerrors.Errorf(npmErrorString, false, msg)`
`126`	`130`	`}`
`127`	`131`
`128`	`132`	`set := iMgr.setMap[setName]`
`129`	`133`	`if referenceType == SelectorType && !set.canSetBeSelectorIPSet() {`
`130`		`- return npmerrors.Errorf(npmerrors.AddSelectorReference, false, fmt.Sprintf("ipset %s is not a selector ipset it is of type %s", setName, set.Type.String()))`
	`134`	`+ msg := fmt.Sprintf("ipset %s is not a selector ipset it is of type %s", setName, set.Type.String())`
	`135`	`+ metrics.SendErrorLogAndMetric(util.IpsmID, "error: failed to add reference: %s", msg)`
	`136`	`+ return npmerrors.Errorf(npmerrors.AddSelectorReference, false, msg)`
`131`	`137`	`}`
`132`	`138`	`wasInKernel := iMgr.shouldBeInKernel(set)`
`133`	`139`	`set.addReference(referenceName, referenceType)`
`@@ -152,7 +158,9 @@ func (iMgr *IPSetManager) DeleteReference(setName, referenceName string, referen`
`152`	`158`	`if referenceType == NetPolType {`
`153`	`159`	`npmErrorString = npmerrors.DeleteNetPolReference`
`154`	`160`	`}`
`155`		`- return npmerrors.Errorf(npmErrorString, false, fmt.Sprintf("ipset %s does not exist", setName))`
	`161`	`+ msg := fmt.Sprintf("ipset %s does not exist", setName)`
	`162`	`+ metrics.SendErrorLogAndMetric(util.IpsmID, "error: failed to delete reference: %s", msg)`
	`163`	`+ return npmerrors.Errorf(npmErrorString, false, msg)`
`156`	`164`	`}`
`157`	`165`
`158`	`166`	`set := iMgr.setMap[setName]`
`@@ -188,7 +196,9 @@ func (iMgr IPSetManager) AddToSets(addToSets []IPSetMetadata, ip, podKey strin`
`188`	`196`	`set = iMgr.setMap[prefixedName]`
`189`	`197`	`}`
`190`	`198`	`if set.Kind != HashSet {`
`191`		`- return npmerrors.Errorf(npmerrors.AppendIPSet, false, fmt.Sprintf("ipset %s is not a hash set", prefixedName))`
	`199`	`+ msg := fmt.Sprintf("ipset %s is not a hash set", prefixedName)`
	`200`	`+ metrics.SendErrorLogAndMetric(util.IpsmID, "error: failed to add to sets: %s", msg)`
	`201`	`+ return npmerrors.Errorf(npmerrors.AppendIPSet, false, msg)`
`192`	`202`	`}`
`193`	`203`
`194`	`204`	`// 2. add ip to the set, and update the pod key`
`@@ -219,7 +229,9 @@ func (iMgr IPSetManager) RemoveFromSets(removeFromSets []IPSetMetadata, ip, po`
`219`	`229`	`continue`
`220`	`230`	`}`
`221`	`231`	`if set.Kind != HashSet {`
`222`		`- return npmerrors.Errorf(npmerrors.DeleteIPSet, false, fmt.Sprintf("ipset %s is not a hash set", prefixedName))`
	`232`	`+ msg := fmt.Sprintf("ipset %s is not a hash set", prefixedName)`
	`233`	`+ metrics.SendErrorLogAndMetric(util.IpsmID, "error: failed to remove from sets: %s", msg)`
	`234`	`+ return npmerrors.Errorf(npmerrors.DeleteIPSet, false, msg)`
`223`	`235`	`}`
`224`	`236`
`225`	`237`	`// 2. remove ip from the set`
`@@ -264,7 +276,9 @@ func (iMgr IPSetManager) AddToLists(listMetadatas, setMetadatas []IPSetMetadat`
`264`	`276`	`// Nested IPSets are only supported for windows`
`265`	`277`	`// Check if we want to actually use that support`
`266`	`278`	`if set.Kind != HashSet {`
`267`		`- return npmerrors.Errorf(npmerrors.AppendIPSet, false, fmt.Sprintf("ipset %s is not a hash set and nested list sets are not supported", setName))`
	`279`	`+ msg := fmt.Sprintf("ipset %s is not a hash set and nested list sets are not supported", setName)`
	`280`	`+ metrics.SendErrorLogAndMetric(util.IpsmID, "error: failed to add to lists: %s", msg)`
	`281`	`+ return npmerrors.Errorf(npmerrors.AppendIPSet, false, msg)`
`268`	`282`	`}`
`269`	`283`	`}`
`270`	`284`
`@@ -279,7 +293,9 @@ func (iMgr IPSetManager) AddToLists(listMetadatas, setMetadatas []IPSetMetadat`
`279`	`293`	`}`
`280`	`294`
`281`	`295`	`if list.Kind != ListSet {`
`282`		`- return npmerrors.Errorf(npmerrors.AppendIPSet, false, fmt.Sprintf("ipset %s is not a list set", listName))`
	`296`	`+ msg := fmt.Sprintf("ipset %s is not a list set", listName)`
	`297`	`+ metrics.SendErrorLogAndMetric(util.IpsmID, "error: failed to add to lists: %s", msg)`
	`298`	`+ return npmerrors.Errorf(npmerrors.AppendIPSet, false, msg)`
`283`	`299`	`}`
`284`	`300`
`285`	`301`	`modified := false`
`@@ -323,7 +339,9 @@ func (iMgr IPSetManager) RemoveFromList(listMetadata IPSetMetadata, setMetadat`
`323`	`339`	`}`
`324`	`340`
`325`	`341`	`if list.Kind != ListSet {`
`326`		`- return npmerrors.Errorf(npmerrors.DeleteIPSet, false, fmt.Sprintf("ipset %s is not a list set", listName))`
	`342`	`+ msg := fmt.Sprintf("ipset %s is not a list set", listName)`
	`343`	`+ metrics.SendErrorLogAndMetric(util.IpsmID, "error: failed to remove from list: %s", msg)`
	`344`	`+ return npmerrors.Errorf(npmerrors.DeleteIPSet, false, msg)`
`327`	`345`	`}`
`328`	`346`
`329`	`347`	`modified := false`
`@@ -340,7 +358,9 @@ func (iMgr IPSetManager) RemoveFromList(listMetadata IPSetMetadata, setMetadat`
`340`	`358`	`if modified {`
`341`	`359`	`iMgr.modifyCacheForKernelMemberUpdate(list)`
`342`	`360`	`}`
`343`		`- return npmerrors.Errorf(npmerrors.DeleteIPSet, false, fmt.Sprintf("ipset %s is not a hash set and nested list sets are not supported", memberName))`
	`361`	`+ msg := fmt.Sprintf("ipset %s is not a hash set and nested list sets are not supported", memberName)`
	`362`	`+ metrics.SendErrorLogAndMetric(util.IpsmID, "error: failed to remove from list: %s", msg)`
	`363`	`+ return npmerrors.Errorf(npmerrors.DeleteIPSet, false, msg)`
`344`	`364`	`}`
`345`	`365`
`346`	`366`	`// 2. remove member from the list`
`@@ -382,6 +402,7 @@ func (iMgr *IPSetManager) ApplyIPSets() error {`
`382`	`402`	`// Call the appropriate apply ipsets`
`383`	`403`	`err := iMgr.applyIPSets()`
`384`	`404`	`if err != nil {`
	`405`	`+ metrics.SendErrorLogAndMetric(util.IpsmID, "error: failed to apply ipsets: %s", err.Error())`
`385`	`406`	`return err`
`386`	`407`	`}`
`387`	`408`
`@@ -494,12 +515,17 @@ func (iMgr IPSetManager) modifyCacheForKernelMemberUpdate(set IPSet) {`
`494`	`515`	`// sanitizeDirtyCache will check if any set marked as delete is in toAddUpdate`
`495`	`516`	`// if so will not delete it`
`496`	`517`	`func (iMgr *IPSetManager) sanitizeDirtyCache() {`
	`518`	`+ anyProblems := false`
`497`	`519`	`for setName := range iMgr.toDeleteCache {`
`498`	`520`	`_, ok := iMgr.toAddOrUpdateCache[setName]`
`499`	`521`	`if ok {`
`500`		`- klog.Errorf("[IPSetManager] Unexpected state in dirty cache %s set is part of both update and delete caches \n ", setName)`
	`522`	`+ klog.Errorf("[IPSetManager] Unexpected state in dirty cache %s set is part of both update and delete caches", setName)`
	`523`	`+ anyProblems = true`
`501`	`524`	`}`
`502`	`525`	`}`
	`526`	`+ if anyProblems {`
	`527`	`+ metrics.SendErrorLogAndMetric(util.IpsmID, "error: some dirty cache sets are part of both update and delete caches")`
	`528`	`+ }`
`503`	`529`	`}`
`504`	`530`
`505`	`531`	`func (iMgr *IPSetManager) clearDirtyCache() {`
Original file line number	Diff line number	Diff line change
`@@ -194,7 +194,9 @@ func (pMgr *PolicyManager) bootup(_ []string) error {`
`194`	`194`	`// - cleans up stale policy chains. It can be forced to stop this process if reconcileManager.forceLock() is called.`
`195`	`195`	`func (pMgr *PolicyManager) reconcile() {`
`196`	`196`	`if err := pMgr.positionAzureChainJumpRule(); err != nil {`
`197`		`- klog.Errorf("failed to reconcile jump rule to Azure-NPM due to %s", err.Error())`
	`197`	`+ msg := fmt.Sprintf("failed to reconcile jump rule to Azure-NPM due to %s", err.Error())`
	`198`	`+ metrics.SendErrorLogAndMetric(util.IptmID, "error: %s", msg)`
	`199`	`+ klog.Error(msg)`
`198`	`200`	`}`
`199`	`201`
`200`	`202`	`pMgr.reconcileManager.Lock()`
`@@ -207,7 +209,9 @@ func (pMgr *PolicyManager) reconcile() {`
`207`	`209`
`208`	`210`	`klog.Infof("cleaning up these stale chains: %+v", staleChains)`
`209`	`211`	`if err := pMgr.cleanupChains(staleChains); err != nil {`
`210`		`- klog.Errorf("failed to clean up old policy chains with the following error: %s", err.Error())`
	`212`	`+ msg := fmt.Sprintf("failed to clean up old policy chains with the following error: %s", err.Error())`
	`213`	`+ metrics.SendErrorLogAndMetric(util.IptmID, "error: %s", msg)`
	`214`	`+ klog.Error(msg)`
`211`	`215`	`}`
`212`	`216`	`}`
`213`	`217`