Merge pull request #1223 from marquiz/devel/logging

Migrate to structured logging

cmd/nfd-master/main.go

@@ -54,15 +54,15 @@ func main() {
 	flags.Visit(func(f *flag.Flag) {
 		switch f.Name {
 		case "featurerules-controller":
-			klog.Warningf("-featurerules-controller is deprecated, use '-crd-controller' flag instead")
+			klog.InfoS("-featurerules-controller is deprecated, use '-crd-controller' flag instead")
 		case "extra-label-ns":
 			args.Overrides.ExtraLabelNs = overrides.ExtraLabelNs
 		case "deny-label-ns":
 			args.Overrides.DenyLabelNs = overrides.DenyLabelNs
 		case "label-whitelist":
 			args.Overrides.LabelWhiteList = overrides.LabelWhiteList
 		case "resource-labels":
-			klog.Warningf("-resource-labels is deprecated, extended resources should be managed with NodeFeatureRule objects")
+			klog.InfoS("-resource-labels is deprecated, extended resources should be managed with NodeFeatureRule objects")
 			args.Overrides.ResourceLabels = overrides.ResourceLabels
 		case "enable-taints":
 			args.Overrides.EnableTaints = overrides.EnableTaints
@@ -80,7 +80,7 @@ func main() {
 
 	// Assert that the version is known
 	if version.Undefined() {
-		klog.Warningf("version not set! Set -ldflags \"-X sigs.k8s.io/node-feature-discovery/pkg/version.version=`git describe --tags --dirty --always`\" during build or run.")
+		klog.InfoS("version not set! Set -ldflags \"-X sigs.k8s.io/node-feature-discovery/pkg/version.version=`git describe --tags --dirty --always`\" during build or run.")
 	}
 
 	// Plug klog into grpc logging infrastructure
@@ -89,11 +89,13 @@ func main() {
 	// Get new NfdMaster instance
 	instance, err := master.NewNfdMaster(args)
 	if err != nil {
-		klog.Exitf("failed to initialize NfdMaster instance: %v", err)
+		klog.ErrorS(err, "failed to initialize NfdMaster instance")
+		os.Exit(1)
 	}
 
 	if err = instance.Run(); err != nil {
-		klog.Exit(err)
+		klog.ErrorS(err, "error while running")
+		os.Exit(1)
 	}
 }
 

cmd/nfd-topology-gc/main.go

@@ -47,17 +47,19 @@ func main() {
 
 	// Assert that the version is known
 	if version.Undefined() {
-		klog.Warningf("version not set! Set -ldflags \"-X sigs.k8s.io/node-feature-discovery/pkg/version.version=`git describe --tags --dirty --always`\" during build or run.")
+		klog.InfoS("version not set! Set -ldflags \"-X sigs.k8s.io/node-feature-discovery/pkg/version.version=`git describe --tags --dirty --always`\" during build or run.")
 	}
 
 	// Get new TopologyGC instance
 	gc, err := nfdtopologygarbagecollector.New(args)
 	if err != nil {
-		klog.Exit(err)
+		klog.ErrorS(err, "failed to initialize topology garbage collector instance")
+		os.Exit(1)
 	}
 
 	if err = gc.Run(); err != nil {
-		klog.Exit(err)
+		klog.ErrorS(err, "error while running")
+		os.Exit(1)
 	}
 }
 

cmd/nfd-topology-updater/main.go

@@ -57,47 +57,28 @@ func main() {
 
 	// Assert that the version is known
 	if version.Undefined() {
-		klog.Warningf("version not set! Set -ldflags \"-X sigs.k8s.io/node-feature-discovery/pkg/version.version=`git describe --tags --dirty --always`\" during build or run.")
+		klog.InfoS("version not set! Set -ldflags \"-X sigs.k8s.io/node-feature-discovery/pkg/version.version=`git describe --tags --dirty --always`\" during build or run.")
 	}
 
 	// Plug klog into grpc logging infrastructure
 	utils.ConfigureGrpcKlog()
 
-	u, err := url.ParseRequestURI(resourcemonitorArgs.KubeletConfigURI)
+	klConfig, err := getKubeletConfig(resourcemonitorArgs.KubeletConfigURI, resourcemonitorArgs.APIAuthTokenFile)
 	if err != nil {
-		klog.Exitf("failed to parse args for kubelet-config-uri: %v", err)
-	}
-
-	// init kubelet API client
-	var klConfig *kubeletconfigv1beta1.KubeletConfiguration
-	switch u.Scheme {
-	case "file":
-		klConfig, err = kubeconf.GetKubeletConfigFromLocalFile(u.Path)
-		if err != nil {
-			klog.Exitf("failed to read kubelet config: %v", err)
-		}
-	case "https":
-		restConfig, err := kubeconf.InsecureConfig(u.String(), resourcemonitorArgs.APIAuthTokenFile)
-		if err != nil {
-			klog.Exitf("failed to initialize rest config for kubelet config uri: %v", err)
-		}
-
-		klConfig, err = kubeconf.GetKubeletConfiguration(restConfig)
-		if err != nil {
-			klog.Exitf("failed to get kubelet config from configz endpoint: %v", err)
-		}
-	default:
-		klog.Exitf("unsupported URI scheme: %v", u.Scheme)
+		klog.ErrorS(err, "failed to get kubelet configuration")
+		os.Exit(1)
 	}
 
 	// Get new TopologyUpdater instance
 	instance, err := topology.NewTopologyUpdater(*args, *resourcemonitorArgs, klConfig.TopologyManagerPolicy, klConfig.TopologyManagerScope)
 	if err != nil {
-		klog.Exit(err)
+		klog.ErrorS(err, "failed to initialize topology updater instance")
+		os.Exit(1)
 	}
 
 	if err = instance.Run(); err != nil {
-		klog.Exit(err)
+		klog.ErrorS(err, "error while running")
+		os.Exit(1)
 	}
 }
 
@@ -153,3 +134,34 @@ func initFlags(flagset *flag.FlagSet) (*topology.Args, *resourcemonitor.Args) {
 
 	return args, resourcemonitorArgs
 }
+
+func getKubeletConfig(uri, apiAuthTokenFile string) (*kubeletconfigv1beta1.KubeletConfiguration, error) {
+	u, err := url.ParseRequestURI(uri)
+	if err != nil {
+		return nil, fmt.Errorf("failed to parse -kubelet-config-uri: %w", err)
+	}
+
+	// init kubelet API client
+	var klConfig *kubeletconfigv1beta1.KubeletConfiguration
+	switch u.Scheme {
+	case "file":
+		klConfig, err = kubeconf.GetKubeletConfigFromLocalFile(u.Path)
+		if err != nil {
+			return nil, fmt.Errorf("failed to read kubelet config: %w", err)
+		}
+		return klConfig, err
+	case "https":
+		restConfig, err := kubeconf.InsecureConfig(u.String(), apiAuthTokenFile)
+		if err != nil {
+			return nil, fmt.Errorf("failed to initialize rest config for kubelet config uri: %w", err)
+		}
+
+		klConfig, err = kubeconf.GetKubeletConfiguration(restConfig)
+		if err != nil {
+			return nil, fmt.Errorf("failed to get kubelet config from configz endpoint: %w", err)
+		}
+		return klConfig, nil
+	}
+
+	return nil, fmt.Errorf("unsupported URI scheme: %v", u.Scheme)
+}

cmd/nfd-worker/main.go

@@ -48,7 +48,7 @@ func main() {
 
 	// Assert that the version is known
 	if version.Undefined() {
-		klog.Warningf("version not set! Set -ldflags \"-X sigs.k8s.io/node-feature-discovery/pkg/version.version=`git describe --tags --dirty --always`\" during build or run.")
+		klog.InfoS("version not set! Set -ldflags \"-X sigs.k8s.io/node-feature-discovery/pkg/version.version=`git describe --tags --dirty --always`\" during build or run.")
 	}
 
 	// Plug klog into grpc logging infrastructure
@@ -57,11 +57,13 @@ func main() {
 	// Get new NfdWorker instance
 	instance, err := worker.NewNfdWorker(args)
 	if err != nil {
-		klog.Exitf("failed to initialize NfdWorker instance: %v", err)
+		klog.ErrorS(err, "failed to initialize NfdWorker instance")
+		os.Exit(1)
 	}
 
 	if err = instance.Run(); err != nil {
-		klog.Exit(err)
+		klog.ErrorS(err, "error while running")
+		os.Exit(1)
 	}
 }
 

pkg/apis/nfd/v1alpha1/expression.go

@@ -210,18 +210,15 @@ func (m *MatchExpression) MatchKeys(name string, keys map[string]Nil) (bool, err
 		return false, fmt.Errorf("invalid Op %q when matching keys", m.Op)
 	}
 
-	if klog.V(3).Enabled() {
-		mString := map[bool]string{false: "no match", true: "match found"}[matched]
+	if klogV := klog.V(3); klogV.Enabled() {
+		klogV.InfoS("matched keys", "matchResult", "matched", "matchKey", name, "matchOp", m.Op)
+	} else if klogV := klog.V(4); klogV.Enabled() {
 		k := make([]string, 0, len(keys))
 		for n := range keys {
 			k = append(k, n)
 		}
 		sort.Strings(k)
-		if len(keys) < 10 || klog.V(4).Enabled() {
-			klog.Infof("%s when matching %q %q against %s", mString, name, m.Op, strings.Join(k, " "))
-		} else {
-			klog.Infof("%s when matching %q %q against %s... (list truncated)", mString, name, m.Op, strings.Join(k[0:10], ", "))
-		}
+		klogV.InfoS("matched keys", "matchResult", "matched", "matchKey", name, "matchOp", m.Op, "inputKeys", k)
 	}
 	return matched, nil
 }
@@ -234,25 +231,10 @@ func (m *MatchExpression) MatchValues(name string, values map[string]string) (bo
 		return false, err
 	}
 
-	if klog.V(3).Enabled() {
-		mString := map[bool]string{false: "no match", true: "match found"}[matched]
-
-		keys := make([]string, 0, len(values))
-		for k := range values {
-			keys = append(keys, k)
-		}
-		sort.Strings(keys)
-
-		kv := make([]string, len(keys))
-		for i, k := range keys {
-			kv[i] = k + ":" + values[k]
-		}
-
-		if len(values) < 10 || klog.V(4).Enabled() {
-			klog.Infof("%s when matching %q %q %v against %s", mString, name, m.Op, m.Value, strings.Join(kv, " "))
-		} else {
-			klog.Infof("%s when matching %q %q %v against %s... (list truncated)", mString, name, m.Op, m.Value, strings.Join(kv[0:10], " "))
-		}
+	if klogV := klog.V(3); klogV.Enabled() {
+		klogV.InfoS("matched values", "matchResult", "matched", "matchKey", name, "matchOp", m.Op, "matchValue", m.Value)
+	} else if klogV := klog.V(4); klogV.Enabled() {
+		klogV.InfoS("matched values", "matchResult", "matched", "matchKey", name, "matchOp", m.Op, "matchValue", m.Value, "inputValues", values)
 	}
 
 	return matched, nil

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
@@ -68,7 +68,7 @@ func (r *Rule) Execute(features *Features) (RuleOutput, error) {
 			}
 		}
 		if !matched {
-			klog.V(2).Infof("rule %q did not match", r.Name)
+			klog.V(2).InfoS("rule did not match", "ruleName", r.Name)
 			return RuleOutput{}, nil
 		}
 	}
@@ -77,10 +77,10 @@ func (r *Rule) Execute(features *Features) (RuleOutput, error) {
 		if isMatch, matches, err := r.MatchFeatures.match(features); err != nil {
 			return RuleOutput{}, err
 		} else if !isMatch {
-			klog.V(2).Infof("rule %q did not match", r.Name)
+			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
 }
 
@@ -169,7 +169,7 @@ func (m *FeatureMatcher) match(features *Features) (bool, matchedFeatures, error
 
 		nameSplit := strings.SplitN(term.Feature, ".", 2)
 		if len(nameSplit) != 2 {
-			klog.Warning("feature %q not of format <domain>.<feature>, cannot be used for templating", term.Feature)
+			klog.InfoS("invalid feature name (not <domain>.<feature>), cannot be used for templating", "featureName", term.Feature)
 			nameSplit = []string{featureName, ""}
 		}
 

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)
 
@@ -67,17 +67,17 @@ func newNfdController(config *restclient.Config, nfdApiControllerOptions nfdApiC
 		if _, err := featureInformer.Informer().AddEventHandler(cache.ResourceEventHandlerFuncs{
 			AddFunc: func(obj interface{}) {
 				nfr := obj.(*nfdv1alpha1.NodeFeature)
-				klog.V(2).Infof("NodeFeature %s/%s added", nfr.Namespace, nfr.Name)
+				klog.V(2).InfoS("NodeFeature added", "nodefeature", klog.KObj(nfr))
 				c.updateOneNode("NodeFeature", nfr)
 			},
 			UpdateFunc: func(oldObj, newObj interface{}) {
 				nfr := newObj.(*nfdv1alpha1.NodeFeature)
-				klog.V(2).Infof("NodeFeature %s/%s updated", nfr.Namespace, nfr.Name)
+				klog.V(2).InfoS("NodeFeature updated", "nodefeature", klog.KObj(nfr))
 				c.updateOneNode("NodeFeature", nfr)
 			},
 			DeleteFunc: func(obj interface{}) {
 				nfr := obj.(*nfdv1alpha1.NodeFeature)
-				klog.V(2).Infof("NodeFeature %s/%s deleted", nfr.Namespace, nfr.Name)
+				klog.V(2).InfoS("NodeFeature deleted", "nodefeature", klog.KObj(nfr))
 				c.updateOneNode("NodeFeature", nfr)
 			},
 		}); err != nil {
@@ -90,24 +90,21 @@ func newNfdController(config *restclient.Config, nfdApiControllerOptions nfdApiC
 	ruleInformer := informerFactory.Nfd().V1alpha1().NodeFeatureRules()
 	if _, err := ruleInformer.Informer().AddEventHandler(cache.ResourceEventHandlerFuncs{
 		AddFunc: func(object interface{}) {
-			key, _ := cache.MetaNamespaceKeyFunc(object)
-			klog.V(2).Infof("NodeFeatureRule %v added", key)
+			klog.V(2).InfoS("NodeFeatureRule added", "nodefeaturerule", klog.KObj(object.(metav1.Object)))
 			if !nfdApiControllerOptions.DisableNodeFeature {
 				c.updateAllNodes()
 			}
 			// else: rules will be processed only when gRPC requests are received
 		},
 		UpdateFunc: func(oldObject, newObject interface{}) {
-			key, _ := cache.MetaNamespaceKeyFunc(newObject)
-			klog.V(2).Infof("NodeFeatureRule %v updated", key)
+			klog.V(2).InfoS("NodeFeatureRule updated", "nodefeaturerule", klog.KObj(newObject.(metav1.Object)))
 			if !nfdApiControllerOptions.DisableNodeFeature {
 				c.updateAllNodes()
 			}
 			// else: rules will be processed only when gRPC requests are received
 		},
 		DeleteFunc: func(object interface{}) {
-			key, _ := cache.MetaNamespaceKeyFunc(object)
-			klog.V(2).Infof("NodeFeatureRule %v deleted", key)
+			klog.V(2).InfoS("NodeFeatureRule deleted", "nodefeaturerule", klog.KObj(object.(metav1.Object)))
 			if !nfdApiControllerOptions.DisableNodeFeature {
 				c.updateAllNodes()
 			}
@@ -135,7 +132,7 @@ func (c *nfdController) stop() {
 func (c *nfdController) updateOneNode(typ string, obj metav1.Object) {
 	nodeName, err := getNodeNameForObj(obj)
 	if err != nil {
-		klog.Errorf("failed to determine node name for %s %s/%s: %v", typ, obj.GetNamespace(), obj.GetName(), err)
+		klog.ErrorS(err, "failed to determine node name for object", "type", typ, "object", klog.KObj(obj))
 		return
 	}
 	c.updateOneNodeChan <- nodeName