fix: [NPM] Reduce/Refactor Noisy NPM Logs (#3468)

* removed all logs from npm dataplane (except error/warning logs)

* removed all logs from npm controller (except error/warning logs)

* restored logs that are ununused by current npm (v2)

* removed test files

* resolved comments

* keep log related to reconciling chain placement when the chain is not in the right place

* added bootup logs back

* Removed two more noisy logs

* Add loglevel config option when printing application insight logs

* Updated all non-error/warning logs to commented out and with a vap TODO

* fixed typo

* small typo fix

* updated configmap with loglevel

* updated default value

* added a default value for loglevel

* fixed typo in json

* removed comma

* changed loglevel to info in configmap

* add a short sleep in TestNetPolInBackgroundSkipAddAfterRemove

* test remove dataplane changes to see if race condition fixes

* Revert "test remove dataplane changes to see if race condition fixes"

This reverts commit 08697eb.

* test

* Revert "test"

This reverts commit 449c2af.

* test

* update dataplane to test if changes are flagged in race

* added stop channels to unit tests to avoid race condtiions

* add non noisy logs back

* increased time

* revert time change after RunPeriodicTasks

* test with 1000 seconds

* 5000 milliseconds

* tweaked the delay

* update to 1500 for defer

* increased to 1500

* increase to 2000

* removed kubernetes

Author: rayaisaiah

npm/azure-npm.yaml

@@ -173,5 +173,6 @@ data:
             "PlaceAzureChainFirst":    false,
             "ApplyInBackground":       true,
             "NetPolInBackground":      true
-        }
+        },
+        "LogLevel": "info"
     }

npm/cmd/start.go

@@ -135,7 +135,11 @@ func start(config npmconfig.Config, flags npmconfig.Flags) error {
 		)
 	}
 
-	err = metrics.CreateTelemetryHandle(config.NPMVersion(), version, npm.GetAIMetadata())
+	logLevel := config.LogLevel
+	if logLevel == "" {
+		logLevel = npmconfig.DefaultConfig.LogLevel
+	}
+	err = metrics.CreateTelemetryHandle(config.NPMVersion(), version, npm.GetAIMetadata(), logLevel)
 	if err != nil {
 		klog.Infof("CreateTelemetryHandle failed with error %v. AITelemetry is not initialized.", err)
 	}

npm/cmd/start_daemon.go

@@ -94,7 +94,11 @@ func startDaemon(config npmconfig.Config) error {
 		return fmt.Errorf("failed to create dataplane: %w", err)
 	}
 
-	err = metrics.CreateTelemetryHandle(config.NPMVersion(), version, npm.GetAIMetadata())
+	logLevel := config.LogLevel
+	if logLevel == "" {
+		logLevel = npmconfig.DefaultConfig.LogLevel
+	}
+	err = metrics.CreateTelemetryHandle(config.NPMVersion(), version, npm.GetAIMetadata(), logLevel)
 	if err != nil {
 		klog.Infof("CreateTelemetryHandle failed with error %v. AITelemetry is not initialized.", err)
 	}

npm/cmd/start_server.go

@@ -113,7 +113,11 @@ func startControlplane(config npmconfig.Config, flags npmconfig.Flags) error {
 		return fmt.Errorf("failed to create NPM controlplane manager: %w", err)
 	}
 
-	err = metrics.CreateTelemetryHandle(config.NPMVersion(), version, npm.GetAIMetadata())
+	logLevel := config.LogLevel
+	if logLevel == "" {
+		logLevel = npmconfig.DefaultConfig.LogLevel
+	}
+	err = metrics.CreateTelemetryHandle(config.NPMVersion(), version, npm.GetAIMetadata(), logLevel)
 	if err != nil {
 		klog.Infof("CreateTelemetryHandle failed with error %v. AITelemetry is not initialized.", err)
 	}

npm/config/config.go

@@ -53,6 +53,9 @@ var DefaultConfig = Config{
 		NetPolInBackground: true,
 		EnableNPMLite:      false,
 	},
+
+	// Setting LogLevel to "info" by default. Set to "debug" to get application insight logs (creates a listener that outputs diagnosticMessageWriter logs).
+	LogLevel: "info",
 }
 
 type GrpcServerConfig struct {
@@ -82,6 +85,7 @@ type Config struct {
 	MaxPendingNetPols            int     `json:"MaxPendingNetPols,omitempty"`
 	NetPolInvervalInMilliseconds int     `json:"NetPolInvervalInMilliseconds,omitempty"`
 	Toggles                      Toggles `json:"Toggles,omitempty"`
+	LogLevel                     string  `json:"LogLevel,omitempty"`
 }
 
 type Toggles struct {

npm/metrics/ai-utils.go

@@ -3,6 +3,7 @@ package metrics
 import (
 	"fmt"
 	"strconv"
+	"strings"
 	"time"
 
 	"github.com/Azure/azure-container-networking/aitelemetry"
@@ -21,15 +22,18 @@ var (
 )
 
 // CreateTelemetryHandle creates a handler to initialize AI telemetry
-func CreateTelemetryHandle(npmVersionNum int, imageVersion, aiMetadata string) error {
+func CreateTelemetryHandle(npmVersionNum int, imageVersion, aiMetadata, logLevel string) error {
 	npmVersion = npmVersionNum
+	debugMode := strings.EqualFold(logLevel, "debug")
+	klog.Infof("LogLevel is %s. Debugmode is set to %v.", logLevel, debugMode)
+
 	aiConfig := aitelemetry.AIConfig{
 		AppName:                   util.AzureNpmFlag,
 		AppVersion:                imageVersion,
 		BatchSize:                 util.BatchSizeInBytes,
 		BatchInterval:             util.BatchIntervalInSecs,
 		RefreshTimeout:            util.RefreshTimeoutInSecs,
-		DebugMode:                 util.DebugMode,
+		DebugMode:                 debugMode,
 		GetEnvRetryCount:          util.GetEnvRetryCount,
 		GetEnvRetryWaitTimeInSecs: util.GetEnvRetryWaitTimeInSecs,
 	}

npm/pkg/controlplane/controllers/v2/namespaceController.go

@@ -164,14 +164,17 @@ func (nsc *NamespaceController) Run(stopCh <-chan struct{}) {
 	defer utilruntime.HandleCrash()
 	defer nsc.workqueue.ShutDown()
 
-	klog.Info("Starting Namespace controller\n")
-	klog.Info("Starting workers")
+	// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
+	// klog.Info("Starting Namespace controller\n")
+	// klog.Info("Starting workers")
 	// Launch workers to process namespace resources
 	go wait.Until(nsc.runWorker, time.Second, stopCh)
 
-	klog.Info("Started workers")
+	// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
+	// klog.Info("Started workers")
 	<-stopCh
-	klog.Info("Shutting down workers")
+	// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
+	// klog.Info("Shutting down workers")
 }
 
 func (nsc *NamespaceController) runWorker() {
@@ -209,7 +212,8 @@ func (nsc *NamespaceController) processNextWorkItem() bool {
 		// Finally, if no error occurs we Forget this item so it does not
 		// get queued again until another change happens.
 		nsc.workqueue.Forget(obj)
-		klog.Infof("Successfully synced '%s'", key)
+		// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
+		// klog.Infof("Successfully synced '%s'", key)
 		return nil
 	}(obj)
 	if err != nil {
@@ -321,7 +325,8 @@ func (nsc *NamespaceController) syncAddNamespace(nsObj *corev1.Namespace) error
 	// Add the namespace to its label's ipset list.
 	for nsLabelKey, nsLabelVal := range nsObj.ObjectMeta.Labels {
 		nsLabelKeyValue := util.GetIpSetFromLabelKV(nsLabelKey, nsLabelVal)
-		klog.Infof("Adding namespace %s to ipset list %s and %s", nsObj.ObjectMeta.Name, nsLabelKey, nsLabelKeyValue)
+		// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
+		// klog.Infof("Adding namespace %s to ipset list %s and %s", nsObj.ObjectMeta.Name, nsLabelKey, nsLabelKeyValue)
 		labelIPSets := []*ipsets.IPSetMetadata{
 			ipsets.NewIPSetMetadata(nsLabelKey, ipsets.KeyLabelOfNamespace),
 			ipsets.NewIPSetMetadata(nsLabelKeyValue, ipsets.KeyValueLabelOfNamespace),
@@ -344,7 +349,8 @@ func (nsc *NamespaceController) syncAddNamespace(nsObj *corev1.Namespace) error
 func (nsc *NamespaceController) syncUpdateNamespace(newNsObj *corev1.Namespace) (metrics.OperationKind, error) {
 	var err error
 	newNsName, newNsLabel := newNsObj.ObjectMeta.Name, newNsObj.ObjectMeta.Labels
-	klog.Infof("NAMESPACE UPDATING:\n namespace: [%s/%v]", newNsName, newNsLabel)
+	// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
+	// klog.Infof("NAMESPACE UPDATING:\n namespace: [%s/%v]", newNsName, newNsLabel)
 
 	// If previous syncAddNamespace failed for some reasons
 	// before caching npm namespace object or syncUpdateNamespace is called due to namespace creation event,
@@ -373,7 +379,8 @@ func (nsc *NamespaceController) syncUpdateNamespace(newNsObj *corev1.Namespace)
 		}
 		toBeRemoved := []*ipsets.IPSetMetadata{ipsets.NewIPSetMetadata(newNsName, ipsets.Namespace)}
 
-		klog.Infof("Deleting namespace %s from ipset list %s", newNsName, nsLabelVal)
+		// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
+		// klog.Infof("Deleting namespace %s from ipset list %s", newNsName, nsLabelVal)
 		if err = nsc.dp.RemoveFromList(labelSet, toBeRemoved); err != nil {
 			metrics.SendErrorLogAndMetric(util.NSID, "[UpdateNamespace] Error: failed to delete namespace %s from ipset list %s with err: %v", newNsName, nsLabelVal, err)
 			return metrics.UpdateOp, fmt.Errorf("failed to remove from list during sync update namespace with err %w", err)
@@ -389,7 +396,8 @@ func (nsc *NamespaceController) syncUpdateNamespace(newNsObj *corev1.Namespace)
 
 	// Add the namespace to its label's ipset list.
 	for _, nsLabelVal := range addToIPSets {
-		klog.Infof("Adding namespace %s to ipset list %s", newNsName, nsLabelVal)
+		// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
+		// klog.Infof("Adding namespace %s to ipset list %s", newNsName, nsLabelVal)
 
 		var labelSet []*ipsets.IPSetMetadata
 		if util.IsKeyValueLabelSetName(nsLabelVal) {
@@ -422,29 +430,32 @@ func (nsc *NamespaceController) syncUpdateNamespace(newNsObj *corev1.Namespace)
 
 // cleanDeletedNamespace handles deleting namespace from ipset.
 func (nsc *NamespaceController) cleanDeletedNamespace(cachedNsKey string) error {
-	klog.Infof("NAMESPACE DELETING: [%s]", cachedNsKey)
+	// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
+	// klog.Infof("NAMESPACE DELETING: [%s]", cachedNsKey)
 	cachedNsObj, exists := nsc.npmNamespaceCache.NsMap[cachedNsKey]
 	if !exists {
 		return nil
 	}
-
-	klog.Infof("NAMESPACE DELETING cached labels: [%s/%v]", cachedNsKey, cachedNsObj.LabelsMap)
+	// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
+	// klog.Infof("NAMESPACE DELETING cached labels: [%s/%v]", cachedNsKey, cachedNsObj.LabelsMap)
 
 	var err error
 	toBeDeletedNs := []*ipsets.IPSetMetadata{ipsets.NewIPSetMetadata(cachedNsKey, ipsets.Namespace)}
 	// Delete the namespace from its label's ipset list.
 	for nsLabelKey, nsLabelVal := range cachedNsObj.LabelsMap {
 
 		labelKey := ipsets.NewIPSetMetadata(nsLabelKey, ipsets.KeyLabelOfNamespace)
-		klog.Infof("Deleting namespace %s from ipset list %s", cachedNsKey, labelKey)
+		// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
+		// klog.Infof("Deleting namespace %s from ipset list %s", cachedNsKey, labelKey)
 		if err = nsc.dp.RemoveFromList(labelKey, toBeDeletedNs); err != nil {
 			metrics.SendErrorLogAndMetric(util.NSID, "[DeleteNamespace] Error: failed to delete namespace %s from ipset list %s with err: %v", cachedNsKey, labelKey, err)
 			return fmt.Errorf("failed to clean deleted namespace when deleting key with err %w", err)
 		}
 
 		labelIpsetName := util.GetIpSetFromLabelKV(nsLabelKey, nsLabelVal)
 		labelKeyValue := ipsets.NewIPSetMetadata(labelIpsetName, ipsets.KeyValueLabelOfNamespace)
-		klog.Infof("Deleting namespace %s from ipset list %s", cachedNsKey, labelIpsetName)
+		// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
+		// klog.Infof("Deleting namespace %s from ipset list %s", cachedNsKey, labelIpsetName)
 		if err = nsc.dp.RemoveFromList(labelKeyValue, toBeDeletedNs); err != nil {
 			metrics.SendErrorLogAndMetric(util.NSID, "[DeleteNamespace] Error: failed to delete namespace %s from ipset list %s with err: %v", cachedNsKey, labelIpsetName, err)
 			return fmt.Errorf("failed to clean deleted namespace when deleting key value with err %w", err)

npm/pkg/controlplane/controllers/v2/networkPolicyController.go

@@ -148,12 +148,15 @@ func (c *NetworkPolicyController) Run(stopCh <-chan struct{}) {
 	defer utilruntime.HandleCrash()
 	defer c.workqueue.ShutDown()
 
-	klog.Infof("Starting Network Policy worker")
+	// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
+	// klog.Infof("Starting Network Policy worker")
 	go wait.Until(c.runWorker, time.Second, stopCh)
 
-	klog.Infof("Started Network Policy worker")
+	// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
+	// klog.Infof("Started Network Policy worker")
 	<-stopCh
-	klog.Info("Shutting down Network Policy workers")
+	// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
+	// klog.Info("Shutting down Network Policy workers")
 }
 
 func (c *NetworkPolicyController) runWorker() {
@@ -190,7 +193,8 @@ func (c *NetworkPolicyController) processNextWorkItem() bool {
 		// Finally, if no error occurs we Forget this item so it does not
 		// get queued again until another change happens.
 		c.workqueue.Forget(obj)
-		klog.Infof("Successfully synced '%s'", key)
+		// TODO: Refactor non-error/warning klogs with Zap and set the following logs to "debug" level
+		// klog.Infof("Successfully synced '%s'", key)
 		return nil
 	}(obj)
 	if err != nil {