pkg/utils: migrate KlogDump to structured logging

Drop the KlogDump helper in favor of klog.InfoS. However, that patch introduces a new DelayedDumper() helper to avoid processing (marshalling) of object unless really evaluated by the logging function.
kubernetes-sigs · May 30, 2023 · 418fff1 · 418fff1
1 parent 0a2c585
commit 418fff1
Show file tree

Hide file tree

Showing 17 changed files with 47 additions and 44 deletions.
diff --git a/pkg/apis/nfd/v1alpha1/rule.go b/pkg/apis/nfd/v1alpha1/rule.go
@@ -50,7 +50,7 @@ func (r *Rule) Execute(features *Features) (RuleOutput, error) {
 				return RuleOutput{}, err
 			} else if isMatch {
 				matched = true
-				utils.KlogDump(4, "matches for matchAny "+r.Name, "  ", matches)
+				klog.V(4).InfoS("matchAny matched", "ruleName", r.Name, "matchedFeatures", utils.DelayedDumper(matches))
 
 				if r.LabelsTemplate == "" && r.VarsTemplate == "" {
 					// there's no need to evaluate other matchers in MatchAny
@@ -80,7 +80,7 @@ func (r *Rule) Execute(features *Features) (RuleOutput, error) {
 			klog.V(2).InfoS("rule did not match", "ruleName", r.Name)
 			return RuleOutput{}, nil
 		} else {
-			utils.KlogDump(4, "matches for matchFeatures "+r.Name, "  ", matches)
+			klog.V(4).InfoS("matchFeatures matched", "ruleName", r.Name, "matchedFeatures", utils.DelayedDumper(matches))
 			if err := r.executeLabelsTemplate(matches, labels); err != nil {
 				return RuleOutput{}, err
 			}
@@ -102,7 +102,7 @@ func (r *Rule) Execute(features *Features) (RuleOutput, error) {
 	}
 
 	ret := RuleOutput{ExtendedResources: extendedResources, Labels: labels, Vars: vars, Taints: r.Taints}
-	utils.KlogDump(2, fmt.Sprintf("rule %q matched with: ", r.Name), "  ", ret)
+	klog.V(2).InfoS("rule matched", "ruleName", r.Name, "ruleOutput", utils.DelayedDumper(ret))
 	return ret, nil
 }
 

diff --git a/pkg/nfd-master/nfd-api-controller.go b/pkg/nfd-master/nfd-api-controller.go
@@ -57,7 +57,7 @@ func newNfdController(config *restclient.Config, nfdApiControllerOptions nfdApiC
 	}
 
 	nfdClient := nfdclientset.NewForConfigOrDie(config)
-	utils.KlogDump(2, "NFD API controller options:", "  ", nfdApiControllerOptions)
+	klog.V(2).InfoS("initializing new NFD API controller", "options", utils.DelayedDumper(nfdApiControllerOptions))
 
 	informerFactory := nfdinformers.NewSharedInformerFactory(nfdClient, nfdApiControllerOptions.ResyncPeriod)
 

diff --git a/pkg/nfd-master/nfd-master.go b/pkg/nfd-master/nfd-master.go
@@ -596,7 +596,7 @@ func (m *nfdMaster) SetLabels(c context.Context, r *pb.SetLabelsRequest) (*pb.Se
 
 	switch {
 	case klog.V(4).Enabled():
-		utils.KlogDump(3, "gRPC SetLabels request received", "  ", r)
+		klog.InfoS("gRPC SetLabels request received", "setLabelsRequest", utils.DelayedDumper(r))
 	case klog.V(1).Enabled():
 		klog.InfoS("gRPC SetLabels request received", "nodeName", r.NodeName, "nfdVersion", r.NfdVersion, "labels", r.Labels)
 	default:
@@ -685,7 +685,7 @@ func (m *nfdMaster) nfdAPIUpdateOneNode(nodeName string) error {
 			o.Spec.MergeInto(features)
 		}
 
-		utils.KlogDump(4, "Composite NodeFeatureSpec after merge:", "  ", features)
+		klog.V(4).InfoS("merged nodeFeatureSpecs", "newNodeFeatureSpec", utils.DelayedDumper(features))
 
 		if objs[0].Namespace == m.namespace && objs[0].Name == nodeName {
 			// This is the one created by nfd-worker
@@ -927,8 +927,7 @@ func (m *nfdMaster) processNodeFeatureRule(nodeName string, features *nfdv1alpha
 	for _, spec := range ruleSpecs {
 		switch {
 		case klog.V(3).Enabled():
-			h := fmt.Sprintf("executing NodeFeatureRule %q on node %q:", spec.Name, nodeName)
-			utils.KlogDump(3, h, "  ", spec.Spec)
+			klog.InfoS("executing NodeFeatureRule", "nodefeaturerule", klog.KObj(spec), "nodeName", nodeName, "nodeFeatureRuleSpec", utils.DelayedDumper(spec.Spec))
 		case klog.V(1).Enabled():
 			klog.InfoS("executing NodeFeatureRule", "nodefeaturerule", klog.KObj(spec), "nodeName", nodeName)
 		}
@@ -1169,8 +1168,7 @@ func (m *nfdMaster) configure(filepath string, overrides string) error {
 	m.deniedNs.normal["kubernetes.io"] = struct{}{}
 	m.deniedNs.wildcard[".kubernetes.io"] = struct{}{}
 
-	utils.KlogDump(1, "effective configuration:", "  ", m.config)
-	klog.InfoS("configuration successfully updated")
+	klog.InfoS("configuration successfully updated", "configuration", utils.DelayedDumper(m.config))
 
 	return nil
 }

diff --git a/pkg/nfd-topology-updater/nfd-topology-updater.go b/pkg/nfd-topology-updater/nfd-topology-updater.go
@@ -162,13 +162,13 @@ func (w *nfdTopologyUpdater) Run() error {
 		case info := <-w.eventSource:
 			klog.V(4).InfoS("event received, scanning...", "event", info.Event)
 			scanResponse, err := resScan.Scan()
-			utils.KlogDump(1, "podResources are", "  ", scanResponse.PodResources)
+			klog.V(1).InfoS("received updated pod resources", "podResources", utils.DelayedDumper(scanResponse.PodResources))
 			if err != nil {
 				klog.ErrorS(err, "scan failed")
 				continue
 			}
 			zones = resAggr.Aggregate(scanResponse.PodResources)
-			utils.KlogDump(1, "after aggregating resources identified zones are", "  ", zones)
+			klog.V(1).InfoS("aggregated resources identified", "resourceZones", utils.DelayedDumper(zones))
 			if !w.args.NoPublish {
 				if err = w.updateNodeResourceTopology(zones, scanResponse); err != nil {
 					return err
@@ -231,7 +231,7 @@ func (w *nfdTopologyUpdater) updateNodeResourceTopology(zoneInfo v1alpha2.ZoneLi
 	if err != nil {
 		return fmt.Errorf("failed to update NodeResourceTopology: %w", err)
 	}
-	utils.KlogDump(4, "CR instance updated resTopo:", "  ", nrtUpdated)
+	klog.V(4).InfoS("NodeResourceTopology object updated", "nodeResourceTopology", utils.DelayedDumper(nrtUpdated))
 	return nil
 }
 

diff --git a/pkg/nfd-worker/nfd-worker.go b/pkg/nfd-worker/nfd-worker.go
@@ -563,8 +563,11 @@ func createFeatureLabels(sources []source.LabelSource, labelWhiteList regexp.Reg
 			labels[name] = value
 		}
 	}
-	klog.InfoS("feature discovery completed")
-	utils.KlogDump(1, "labels discovered by feature sources:", "  ", labels)
+	if klogV := klog.V(1); klogV.Enabled() {
+		klogV.InfoS("feature discovery completed", "labels", utils.DelayedDumper(labels))
+	} else {
+		klog.InfoS("feature discovery completed")
+	}
 	return labels
 }
 
@@ -702,7 +705,7 @@ func (m *nfdWorker) updateNodeFeatureObject(labels Labels) error {
 			return fmt.Errorf("failed to create NodeFeature object %q: %w", nfr.Name, err)
 		}
 
-		utils.KlogDump(4, "NodeFeature object created:", "  ", nfrCreated)
+		klog.V(4).InfoS("NodeFeature object created", "nodeFeature", utils.DelayedDumper(nfrCreated))
 	} else if err != nil {
 		return fmt.Errorf("failed to get NodeFeature object: %w", err)
 	} else {
@@ -720,7 +723,7 @@ func (m *nfdWorker) updateNodeFeatureObject(labels Labels) error {
 			if err != nil {
 				return fmt.Errorf("failed to update NodeFeature object %q: %w", nfr.Name, err)
 			}
-			utils.KlogDump(4, "NodeFeature object updated:", "  ", nfrUpdated)
+			klog.V(4).InfoS("NodeFeature object updated", "nodeFeature", utils.DelayedDumper(nfrUpdated))
 		} else {
 			klog.V(1).InfoS("no changes in NodeFeature object, not updating", "nodefeature", klog.KObj(nfr))
 		}

diff --git a/pkg/utils/dump.go b/pkg/utils/dump.go
@@ -18,24 +18,24 @@ package utils
 
 import (
 	"fmt"
-	"strings"
 
-	"k8s.io/klog/v2"
 	"sigs.k8s.io/yaml"
 )
 
-func KlogDump(v klog.Level, heading, prefix string, obj interface{}) {
-	if klog.V(v).Enabled() {
-		if heading != "" {
-			klog.InfoDepth(1, heading)
-		}
-
-		d := strings.Split(Dump(obj), "\n")
-		// Print all but the last empty line
-		for i := 0; i < len(d)-1; i++ {
-			klog.InfoDepth(1, prefix+d[i])
-		}
-	}
+type dumper struct {
+	obj interface{}
+}
+
+// String implements the fmt.Stringer interface
+func (d *dumper) String() string {
+	return Dump(d.obj)
+}
+
+// DelayedDumper delays the dumping of an object. Useful in logging to delay
+// the processing (JSON marshalling) until (or if) the object is actually
+// evaluated.
+func DelayedDumper(obj interface{}) fmt.Stringer {
+	return &dumper{obj: obj}
 }
 
 // Dump dumps an object into YAML textual format

diff --git a/source/cpu/cpu.go b/source/cpu/cpu.go
@@ -270,7 +270,7 @@ func (s *cpuSource) Discover() error {
 	// Detect Coprocessor features
 	s.features.Attributes[CoprocessorFeature] = nfdv1alpha1.NewAttributeFeatures(discoverCoprocessor())
 
-	utils.KlogDump(3, "discovered cpu features:", "  ", s.features)
+	klog.V(3).InfoS("discovered features", "featureSource", s.Name(), "features", utils.DelayedDumper(s.features))
 
 	return nil
 }

diff --git a/source/custom/custom.go b/source/custom/custom.go
@@ -112,7 +112,7 @@ func (s *customSource) GetLabels() (source.FeatureLabels, error) {
 	labels := source.FeatureLabels{}
 	allFeatureConfig := append(getStaticFeatureConfig(), *s.config...)
 	allFeatureConfig = append(allFeatureConfig, getDirectoryFeatureConfig()...)
-	utils.KlogDump(2, "custom features configuration:", "  ", allFeatureConfig)
+	klog.V(2).InfoS("resolving custom features", "configuration", utils.DelayedDumper(allFeatureConfig))
 	// Iterate over features
 	for _, rule := range allFeatureConfig {
 		ruleOut, err := rule.execute(features)
@@ -128,6 +128,7 @@ func (s *customSource) GetLabels() (source.FeatureLabels, error) {
 		features.InsertAttributeFeatures(nfdv1alpha1.RuleBackrefDomain, nfdv1alpha1.RuleBackrefFeature, ruleOut.Labels)
 		features.InsertAttributeFeatures(nfdv1alpha1.RuleBackrefDomain, nfdv1alpha1.RuleBackrefFeature, ruleOut.Vars)
 	}
+
 	return labels, nil
 }
 

diff --git a/source/fake/fake.go b/source/fake/fake.go
@@ -19,6 +19,7 @@ package fake
 import (
 	"fmt"
 
+	"k8s.io/klog/v2"
 	nfdv1alpha1 "sigs.k8s.io/node-feature-discovery/pkg/apis/nfd/v1alpha1"
 	"sigs.k8s.io/node-feature-discovery/pkg/utils"
 	"sigs.k8s.io/node-feature-discovery/source"
@@ -127,7 +128,7 @@ func (s *fakeSource) Discover() error {
 	}
 	s.features.Instances[InstanceFeature] = nfdv1alpha1.NewInstanceFeatures(instances)
 
-	utils.KlogDump(3, "discovered fake features:", "  ", s.features)
+	klog.V(3).InfoS("discovered features", "featureSource", s.Name(), "features", utils.DelayedDumper(s.features))
 
 	return nil
 }

diff --git a/source/kernel/kernel.go b/source/kernel/kernel.go
@@ -159,7 +159,7 @@ func (s *kernelSource) Discover() error {
 		s.features.Attributes[SelinuxFeature].Elements["enabled"] = strconv.FormatBool(selinux)
 	}
 
-	utils.KlogDump(3, "discovered kernel features:", "  ", s.features)
+	klog.V(3).InfoS("discovered features", "featureSource", s.Name(), "features", utils.DelayedDumper(s.features))
 
 	return nil
 }

diff --git a/source/local/local.go b/source/local/local.go
@@ -130,7 +130,7 @@ func (s *localSource) Discover() error {
 
 	s.features.Attributes[LabelFeature] = nfdv1alpha1.NewAttributeFeatures(featuresFromFiles)
 
-	utils.KlogDump(3, "discovered local features:", "  ", s.features)
+	klog.V(3).InfoS("discovered features", "featureSource", s.Name(), "features", utils.DelayedDumper(s.features))
 
 	return nil
 }
@@ -191,7 +191,7 @@ func getFeaturesFromHooks() (map[string]string, error) {
 
 		// Append features
 		fileFeatures := parseFeatures(lines)
-		utils.KlogDump(4, fmt.Sprintf("features from hook %q:", fileName), "  ", fileFeatures)
+		klog.V(4).InfoS("hook executed", "fileName", fileName, "features", utils.DelayedDumper(fileFeatures))
 		for k, v := range fileFeatures {
 			if old, ok := features[k]; ok {
 				klog.InfoS("overriding label value from another hook", "labelKey", k, "oldValue", old, "newValue", v, "fileName", fileName)
@@ -267,7 +267,7 @@ func getFeaturesFromFiles() (map[string]string, error) {
 
 		// Append features
 		fileFeatures := parseFeatures(lines)
-		utils.KlogDump(4, fmt.Sprintf("features from feature file %q:", fileName), "  ", fileFeatures)
+		klog.V(4).InfoS("feature file read", "fileName", fileName, "features", utils.DelayedDumper(fileFeatures))
 		for k, v := range fileFeatures {
 			if old, ok := features[k]; ok {
 				klog.InfoS("overriding label value from another feature file", "labelKey", k, "oldValue", old, "newValue", v, "fileName", fileName)

diff --git a/source/memory/memory.go b/source/memory/memory.go
@@ -100,7 +100,7 @@ func (s *memorySource) Discover() error {
 		s.features.Instances[NvFeature] = nfdv1alpha1.InstanceFeatureSet{Elements: nv}
 	}
 
-	utils.KlogDump(3, "discovered memory features:", "  ", s.features)
+	klog.V(3).InfoS("discovered features", "featureSource", s.Name(), "features", utils.DelayedDumper(s.features))
 
 	return nil
 }

diff --git a/source/network/network.go b/source/network/network.go
@@ -99,7 +99,7 @@ func (s *networkSource) Discover() error {
 	}
 	s.features.Instances[DeviceFeature] = nfdv1alpha1.InstanceFeatureSet{Elements: devs}
 
-	utils.KlogDump(3, "discovered network features:", "  ", s.features)
+	klog.V(3).InfoS("discovered features", "featureSource", s.Name(), "features", utils.DelayedDumper(s.features))
 
 	return nil
 }

diff --git a/source/pci/pci.go b/source/pci/pci.go
@@ -148,7 +148,7 @@ func (s *pciSource) Discover() error {
 	}
 	s.features.Instances[DeviceFeature] = nfdv1alpha1.NewInstanceFeatures(devs)
 
-	utils.KlogDump(3, "discovered pci features:", "  ", s.features)
+	klog.V(3).InfoS("discovered features", "featureSource", s.Name(), "features", utils.DelayedDumper(s.features))
 
 	return nil
 }

diff --git a/source/storage/storage.go b/source/storage/storage.go
@@ -81,7 +81,7 @@ func (s *storageSource) Discover() error {
 	}
 	s.features.Instances[BlockFeature] = nfdv1alpha1.InstanceFeatureSet{Elements: devs}
 
-	utils.KlogDump(3, "discovered storage features:", "  ", s.features)
+	klog.V(3).InfoS("discovered features", "featureSource", s.Name(), "features", utils.DelayedDumper(s.features))
 
 	return nil
 }

diff --git a/source/system/system.go b/source/system/system.go
@@ -101,7 +101,7 @@ func (s *systemSource) Discover() error {
 		}
 	}
 
-	utils.KlogDump(3, "discovered system features:", "  ", s.features)
+	klog.V(3).InfoS("discovered features", "featureSource", s.Name(), "features", utils.DelayedDumper(s.features))
 
 	return nil
 }

diff --git a/source/usb/usb.go b/source/usb/usb.go
@@ -147,7 +147,7 @@ func (s *usbSource) Discover() error {
 	}
 	s.features.Instances[DeviceFeature] = nfdv1alpha1.NewInstanceFeatures(devs)
 
-	utils.KlogDump(3, "discovered usb features:", "  ", s.features)
+	klog.V(3).InfoS("discovered features", "featureSource", s.Name(), "features", utils.DelayedDumper(s.features))
 
 	return nil
 }
-Original file line number
+Diff line change
@@ Expand Up / @@ -101,7 +101,7 @@ func (s *systemSource) Discover() error { @@
     		}
     	}
-    	utils.KlogDump(3, "discovered system features:", "  ", s.features)
+    	klog.V(3).InfoS("discovered features", "featureSource", s.Name(), "features", utils.DelayedDumper(s.features))
     	return nil
     }
@@ Expand Down @@