test remove dataplane changes to see if race condition fixes

Author: rayaisaiah

npm/pkg/dataplane/dataplane.go

@@ -81,8 +81,7 @@ type DataPlane struct {
 func NewDataPlane(nodeName string, ioShim *common.IOShim, cfg *Config, stopChannel <-chan struct{}) (*DataPlane, error) {
 	metrics.InitializeAll()
 	if util.IsWindowsDP() {
-		// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
-		// klog.Infof("[DataPlane] enabling AddEmptySetToLists for Windows")
+		klog.Infof("[DataPlane] enabling AddEmptySetToLists for Windows")
 		cfg.IPSetManagerCfg.AddEmptySetToLists = true
 	}
 
@@ -113,8 +112,7 @@ func NewDataPlane(nodeName string, ioShim *common.IOShim, cfg *Config, stopChann
 			return nil, ErrInvalidApplyConfig
 		}
 	} else {
-		// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
-		// klog.Info("[DataPlane] dataplane configured to NOT apply in background")
+		klog.Info("[DataPlane] dataplane configured to NOT apply in background")
 		dp.updatePodCache = newUpdatePodCache(1)
 	}
 
@@ -152,8 +150,7 @@ func (dp *DataPlane) FinishBootupPhase() {
 	dp.applyInfo.Lock()
 	defer dp.applyInfo.Unlock()
 
-	// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
-	// klog.Infof("[DataPlane] finished bootup phase")
+	klog.Infof("[DataPlane] finished bootup phase")
 	dp.applyInfo.inBootupPhase = false
 }
 
@@ -260,8 +257,7 @@ func (dp *DataPlane) AddToSets(setNames []*ipsets.IPSetMetadata, podMetadata *Po
 	}
 
 	if dp.shouldUpdatePod() && podMetadata.NodeName == dp.nodeName {
-		// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
-		// 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)
 
 		// lock updatePodCache while reading/modifying or setting the updatePod in the cache
 		dp.updatePodCache.Lock()
@@ -283,8 +279,7 @@ func (dp *DataPlane) RemoveFromSets(setNames []*ipsets.IPSetMetadata, podMetadat
 	}
 
 	if dp.shouldUpdatePod() && podMetadata.NodeName == dp.nodeName {
-		// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
-		// 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)
 
 		// lock updatePodCache while reading/modifying or setting the updatePod in the cache
 		dp.updatePodCache.Lock()
@@ -333,27 +328,23 @@ func (dp *DataPlane) ApplyDataPlane() error {
 	newCount := dp.applyInfo.numBatches
 	dp.applyInfo.Unlock()
 
-	// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
-	// klog.Infof("[DataPlane] [%s] new batch count: %d", contextApplyDP, newCount)
+	klog.Infof("[DataPlane] [%s] new batch count: %d", contextApplyDP, newCount)
 
 	if newCount >= dp.ApplyMaxBatches {
-		// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
-		// klog.Infof("[DataPlane] [%s] applying now since reached maximum batch count: %d", contextApplyDP, newCount)
+		klog.Infof("[DataPlane] [%s] applying now since reached maximum batch count: %d", contextApplyDP, newCount)
 		return dp.applyDataPlaneNow(contextApplyDP)
 	}
 
 	return nil
 }
 
 func (dp *DataPlane) applyDataPlaneNow(context string) error {
-	// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
-	// klog.Infof("[DataPlane] [ApplyDataPlane] [%s] starting to apply ipsets", context)
+	klog.Infof("[DataPlane] [ApplyDataPlane] [%s] starting to apply ipsets", context)
 	err := dp.ipsetMgr.ApplyIPSets()
 	if err != nil {
 		return fmt.Errorf("[DataPlane] [%s] error while applying IPSets: %w", context, err)
 	}
-	// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
-	// klog.Infof("[DataPlane] [ApplyDataPlane] [%s] finished applying ipsets", context)
+	klog.Infof("[DataPlane] [ApplyDataPlane] [%s] finished applying ipsets", context)
 
 	// see comment in RemovePolicy() for why this is here
 	dp.setRemovePolicyFailure(false)
@@ -374,8 +365,7 @@ func (dp *DataPlane) applyDataPlaneNow(context string) error {
 		}
 		dp.updatePodCache.Unlock()
 
-		// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
-		// klog.Infof("[DataPlane] [ApplyDataPlane] [%s] refreshing endpoints before updating pods", context)
+		klog.Infof("[DataPlane] [ApplyDataPlane] [%s] refreshing endpoints before updating pods", context)
 
 		err := dp.refreshPodEndpoints()
 		if err != nil {
@@ -384,16 +374,14 @@ func (dp *DataPlane) applyDataPlaneNow(context string) error {
 			return nil
 		}
 
-		// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
-		// klog.Infof("[DataPlane] [ApplyDataPlane] [%s] refreshed endpoints", context)
+		klog.Infof("[DataPlane] [ApplyDataPlane] [%s] refreshed endpoints", context)
 
 		// lock updatePodCache while driving goal state to kernel
 		// prevents another ApplyDataplane call from updating the same pods
 		dp.updatePodCache.Lock()
 		defer dp.updatePodCache.Unlock()
 
-		// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
-		// klog.Infof("[DataPlane] [ApplyDataPlane] [%s] starting to update pods", context)
+		klog.Infof("[DataPlane] [ApplyDataPlane] [%s] starting to update pods", context)
 		for !dp.updatePodCache.isEmpty() {
 			pod := dp.updatePodCache.dequeue()
 			if pod == nil {
@@ -411,16 +399,14 @@ func (dp *DataPlane) applyDataPlaneNow(context string) error {
 			}
 		}
 
-		// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
-		// klog.Infof("[DataPlane] [ApplyDataPlane] [%s] finished updating pods", context)
+		klog.Infof("[DataPlane] [ApplyDataPlane] [%s] finished updating pods", context)
 	}
 	return nil
 }
 
 // AddPolicy takes in a translated NPMNetworkPolicy object and applies on dataplane
 func (dp *DataPlane) AddPolicy(policy *policies.NPMNetworkPolicy) error {
-	// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
-	// klog.Infof("[DataPlane] Add Policy called for %s", policy.PolicyKey)
+	klog.Infof("[DataPlane] Add Policy called for %s", policy.PolicyKey)
 
 	if !dp.netPolInBackground {
 		return dp.addPolicies([]*policies.NPMNetworkPolicy{policy})
@@ -434,12 +420,10 @@ func (dp *DataPlane) AddPolicy(policy *policies.NPMNetworkPolicy) error {
 	dp.netPolQueue.enqueue(policy)
 	newCount := dp.netPolQueue.len()
 
-	// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
-	// klog.Infof("[DataPlane] [%s] new pending netpol count: %d", contextAddNetPol, newCount)
+	klog.Infof("[DataPlane] [%s] new pending netpol count: %d", contextAddNetPol, newCount)
 
 	if newCount >= dp.MaxPendingNetPols {
-		// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
-		// klog.Infof("[DataPlane] [%s] applying now since reached maximum batch count: %d", contextAddNetPol, newCount)
+		klog.Infof("[DataPlane] [%s] applying now since reached maximum batch count: %d", contextAddNetPol, newCount)
 		dp.addPoliciesWithRetry(contextAddNetPol)
 	}
 	return nil
@@ -449,14 +433,12 @@ func (dp *DataPlane) AddPolicy(policy *policies.NPMNetworkPolicy) error {
 // The caller must lock netPolQueue.
 func (dp *DataPlane) addPoliciesWithRetry(context string) {
 	netPols := dp.netPolQueue.dump()
-	// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
-	// klog.Infof("[DataPlane] adding policies %+v", netPols)
+	klog.Infof("[DataPlane] adding policies %+v", netPols)
 
 	err := dp.addPolicies(netPols)
 	if err == nil {
 		// clear queue and return on success
-		// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
-		// klog.Infof("[DataPlane] [%s] added policies successfully", context)
+		klog.Infof("[DataPlane] [%s] added policies successfully", context)
 		dp.netPolQueue.clear()
 		return
 	}
@@ -469,8 +451,7 @@ func (dp *DataPlane) addPoliciesWithRetry(context string) {
 		err = dp.addPolicies([]*policies.NPMNetworkPolicy{netPol})
 		if err == nil {
 			// remove from queue on success
-			// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
-			// klog.Infof("[DataPlane] [%s] added policy successfully one at a time. policyKey: %s", context, netPol.PolicyKey)
+			klog.Infof("[DataPlane] [%s] added policy successfully one at a time. policyKey: %s", context, netPol.PolicyKey)
 			dp.netPolQueue.delete(netPol.PolicyKey)
 		} else {
 			// keep in queue on failure
@@ -488,8 +469,7 @@ func (dp *DataPlane) addPolicies(netPols []*policies.NPMNetworkPolicy) error {
 	}
 
 	if len(netPols) == 0 {
-		// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
-		// klog.Infof("[DataPlane] expected to have at least one NetPol in dp.addPolicies()")
+		klog.Infof("[DataPlane] expected to have at least one NetPol in dp.addPolicies()")
 		return nil
 	}
 
@@ -533,8 +513,7 @@ func (dp *DataPlane) addPolicies(netPols []*policies.NPMNetworkPolicy) error {
 		// Create and add references for Rule IPSets
 		err = dp.createIPSetsAndReferences(netPol.RuleIPSets, netPol.PolicyKey, ipsets.NetPolType)
 		if err != nil {
-			// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
-			// klog.Infof("[DataPlane] error while adding Rule IPSet references: %s", err.Error())
+			klog.Infof("[DataPlane] error while adding Rule IPSet references: %s", err.Error())
 			return fmt.Errorf("[DataPlane] error while adding Rule IPSet references: %w", err)
 		}
 
@@ -547,18 +526,15 @@ func (dp *DataPlane) addPolicies(netPols []*policies.NPMNetworkPolicy) error {
 			// increment batch and apply IPSets if needed
 			dp.applyInfo.numBatches++
 			newCount := dp.applyInfo.numBatches
-			// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
-			// klog.Infof("[DataPlane] [%s] new batch count: %d", contextAddNetPolBootup, newCount)
+			klog.Infof("[DataPlane] [%s] new batch count: %d", contextAddNetPolBootup, newCount)
 			if newCount >= dp.ApplyMaxBatches {
-				// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
-				// klog.Infof("[DataPlane] [%s] applying now since reached maximum batch count: %d", contextAddNetPolBootup, newCount)
-				// klog.Infof("[DataPlane] [%s] starting to apply ipsets", contextAddNetPolBootup)
+				klog.Infof("[DataPlane] [%s] applying now since reached maximum batch count: %d", contextAddNetPolBootup, newCount)
+				klog.Infof("[DataPlane] [%s] starting to apply ipsets", contextAddNetPolBootup)
 				err = dp.ipsetMgr.ApplyIPSets()
 				if err != nil {
 					return fmt.Errorf("[DataPlane] [%s] error while applying IPSets: %w", contextAddNetPolBootup, err)
 				}
-				// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
-				// klog.Infof("[DataPlane] [%s] finished applying ipsets", contextAddNetPolBootup)
+				klog.Infof("[DataPlane] [%s] finished applying ipsets", contextAddNetPolBootup)
 
 				// see comment in RemovePolicy() for why this is here
 				dp.setRemovePolicyFailure(false)
@@ -598,8 +574,7 @@ func (dp *DataPlane) addPolicies(netPols []*policies.NPMNetworkPolicy) error {
 
 // RemovePolicy takes in network policyKey (namespace/name of network policy) and removes it from dataplane and cache
 func (dp *DataPlane) RemovePolicy(policyKey string) error {
-	// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
-	// klog.Infof("[DataPlane] Remove Policy called for %s", policyKey)
+	klog.Infof("[DataPlane] Remove Policy called for %s", policyKey)
 
 	if dp.netPolInBackground {
 		// make sure to not add this NetPol if we're deleting it
@@ -675,12 +650,10 @@ func (dp *DataPlane) RemovePolicy(policyKey string) error {
 // UpdatePolicy takes in updated policy object, calculates the delta and applies changes
 // onto dataplane accordingly
 func (dp *DataPlane) UpdatePolicy(policy *policies.NPMNetworkPolicy) error {
-	// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
-	// klog.Infof("[DataPlane] Update Policy called for %s", policy.PolicyKey)
+	klog.Infof("[DataPlane] Update Policy called for %s", policy.PolicyKey)
 	ok := dp.policyMgr.PolicyExists(policy.PolicyKey)
 	if !ok {
-		// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
-		// klog.Infof("[DataPlane] Policy %s is not found.", policy.PolicyKey)
+		klog.Infof("[DataPlane] Policy %s is not found.", policy.PolicyKey)
 		return dp.AddPolicy(policy)
 	}
 

npm/pkg/dataplane/dataplane_linux_test.go

@@ -94,8 +94,6 @@ func TestNetPolInBackgroundUpdatePolicy(t *testing.T) {
 }
 
 func TestNetPolInBackgroundSkipAddAfterRemove(t *testing.T) {
-	// Sleep for a bit to let IncNumACLRulesBy be resolved to avoid race condition
-	time.Sleep(100 * time.Millisecond)
 	metrics.ReinitializeAll()
 
 	calls := getBootupTestCalls()

npm/pkg/dataplane/ipsets/ipsetmanager.go

@@ -93,8 +93,7 @@ func (iMgr *IPSetManager) Reconcile() {
 	}
 	numRemovedSets := originalNumSets - len(iMgr.setMap)
 	if numRemovedSets > 0 {
-		// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
-		// klog.Infof("[IPSetManager] removed %d empty/unreferenced ipsets, updating toDeleteCache to: %+v", numRemovedSets, iMgr.dirtyCache.printDeleteCache())
+		klog.Infof("[IPSetManager] removed %d empty/unreferenced ipsets, updating toDeleteCache to: %+v", numRemovedSets, iMgr.dirtyCache.printDeleteCache())
 	}
 }
 
@@ -309,11 +308,10 @@ func (iMgr *IPSetManager) RemoveFromSets(removeFromSets []*IPSetMetadata, ip, po
 		}
 		// in case the IP belongs to a new Pod, then ignore this Delete call as this might be stale
 		if cachedPodKey != podKey {
-			// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
-			// klog.Infof(
-			// 	"[IPSetManager] DeleteFromSet: PodOwner has changed for Ip: %s, setName:%s, Old podKey: %s, new podKey: %s. Ignore the delete as this is stale update",
-			// 	ip, prefixedName, cachedPodKey, podKey,
-			// )
+			klog.Infof(
+				"[IPSetManager] DeleteFromSet: PodOwner has changed for Ip: %s, setName:%s, Old podKey: %s, new podKey: %s. Ignore the delete as this is stale update",
+				ip, prefixedName, cachedPodKey, podKey,
+			)
 			continue
 		}
 
@@ -455,16 +453,14 @@ func (iMgr *IPSetManager) ApplyIPSets() error {
 	defer iMgr.Unlock()
 
 	if iMgr.dirtyCache.numSetsToAddOrUpdate() == 0 && iMgr.dirtyCache.numSetsToDelete() == 0 {
-		// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
-		// klog.Info("[IPSetManager] No IPSets to apply")
+		klog.Info("[IPSetManager] No IPSets to apply")
 		return nil
 	}
 
-	// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
-	// klog.Infof(
-	// 	"[IPSetManager] dirty caches. toAddUpdateCache: %s, toDeleteCache: %s",
-	// 	iMgr.dirtyCache.printAddOrUpdateCache(), iMgr.dirtyCache.printDeleteCache(),
-	// )
+	klog.Infof(
+		"[IPSetManager] dirty caches. toAddUpdateCache: %s, toDeleteCache: %s",
+		iMgr.dirtyCache.printAddOrUpdateCache(), iMgr.dirtyCache.printDeleteCache(),
+	)
 	iMgr.sanitizeDirtyCache()
 
 	// Call the appropriate apply ipsets