feature: use contextal logging for plugins

Author: googs1025

pkg/framework/plugins/defaultevictor/defaultevictor.go

@@ -48,6 +48,7 @@ type constraint func(pod *v1.Pod) error
 // This plugin is only meant to customize other actions (extension points) of the evictor,
 // like filtering, sorting, and other ones that might be relevant in the future
 type DefaultEvictor struct {
+	logger      klog.Logger
 	args        *DefaultEvictorArgs
 	constraints []constraint
 	handle      frameworktypes.Handle
@@ -71,14 +72,16 @@ func New(args runtime.Object, handle frameworktypes.Handle) (frameworktypes.Plug
 	if !ok {
 		return nil, fmt.Errorf("want args to be of type defaultEvictorFilterArgs, got %T", args)
 	}
+	logger := klog.Background().WithValues("plugin", PluginName)
 
 	ev := &DefaultEvictor{
+		logger: logger,
 		handle: handle,
 		args:   defaultEvictorArgs,
 	}
 
 	if defaultEvictorArgs.EvictFailedBarePods {
-		klog.V(1).InfoS("Warning: EvictFailedBarePods is set to True. This could cause eviction of pods without ownerReferences.")
+		logger.V(1).Info("Warning: EvictFailedBarePods is set to True. This could cause eviction of pods without ownerReferences.")
 		ev.constraints = append(ev.constraints, func(pod *v1.Pod) error {
 			ownerRefList := podutil.OwnerRef(pod)
 			// Enable evictFailedBarePods to evict bare pods in failed phase
@@ -117,7 +120,7 @@ func New(args runtime.Object, handle frameworktypes.Handle) (frameworktypes.Plug
 			})
 		}
 	} else {
-		klog.V(1).InfoS("Warning: EvictSystemCriticalPods is set to True. This could cause eviction of Kubernetes system pods.")
+		logger.V(1).Info("Warning: EvictSystemCriticalPods is set to True. This could cause eviction of Kubernetes system pods.")
 	}
 	if !defaultEvictorArgs.EvictLocalStoragePods {
 		ev.constraints = append(ev.constraints, func(pod *v1.Pod) error {
@@ -169,7 +172,7 @@ func New(args runtime.Object, handle frameworktypes.Handle) (frameworktypes.Plug
 			}
 
 			if len(pod.OwnerReferences) > 1 {
-				klog.V(5).InfoS("pod has multiple owner references which is not supported for minReplicas check", "size", len(pod.OwnerReferences), "pod", klog.KObj(pod))
+				logger.V(5).Info("pod has multiple owner references which is not supported for minReplicas check", "size", len(pod.OwnerReferences), "pod", klog.KObj(pod))
 				return nil
 			}
 
@@ -218,14 +221,15 @@ func (d *DefaultEvictor) Name() string {
 }
 
 func (d *DefaultEvictor) PreEvictionFilter(pod *v1.Pod) bool {
+	logger := d.logger.WithValues("ExtensionPoint", frameworktypes.PreEvictionFilterExtensionPoint)
 	if d.args.NodeFit {
 		nodes, err := nodeutil.ReadyNodes(context.TODO(), d.handle.ClientSet(), d.handle.SharedInformerFactory().Core().V1().Nodes().Lister(), d.args.NodeSelector)
 		if err != nil {
-			klog.ErrorS(err, "unable to list ready nodes", "pod", klog.KObj(pod))
+			logger.Error(err, "unable to list ready nodes", "pod", klog.KObj(pod))
 			return false
 		}
 		if !nodeutil.PodFitsAnyOtherNode(d.handle.GetPodsAssignedToNodeFunc(), pod, nodes) {
-			klog.InfoS("pod does not fit on any other node because of nodeSelector(s), Taint(s), or nodes marked as unschedulable", "pod", klog.KObj(pod))
+			logger.Info("pod does not fit on any other node because of nodeSelector(s), Taint(s), or nodes marked as unschedulable", "pod", klog.KObj(pod))
 			return false
 		}
 		return true
@@ -234,6 +238,7 @@ func (d *DefaultEvictor) PreEvictionFilter(pod *v1.Pod) bool {
 }
 
 func (d *DefaultEvictor) Filter(pod *v1.Pod) bool {
+	logger := d.logger.WithValues("ExtensionPoint", frameworktypes.FilterExtensionPoint)
 	checkErrs := []error{}
 
 	if HaveEvictAnnotation(pod) {
@@ -259,7 +264,7 @@ func (d *DefaultEvictor) Filter(pod *v1.Pod) bool {
 	}
 
 	if len(checkErrs) > 0 {
-		klog.V(4).InfoS("Pod fails the following checks", "pod", klog.KObj(pod), "checks", utilerrors.NewAggregate(checkErrs).Error())
+		logger.V(4).Info("Pod fails the following checks", "pod", klog.KObj(pod), "checks", utilerrors.NewAggregate(checkErrs).Error())
 		return false
 	}
 

pkg/framework/plugins/example/example.go

@@ -46,6 +46,7 @@ var _ fwtypes.DeschedulePlugin = &Example{}
 // Example is our plugin (implementing the DeschedulePlugin interface). This
 // plugin will evict pods that match a regex and are older than a certain age.
 type Example struct {
+	logger    klog.Logger
 	handle    fwtypes.Handle
 	args      *ExampleArgs
 	podFilter podutil.FilterFunc
@@ -61,6 +62,7 @@ func New(args runtime.Object, handle fwtypes.Handle) (fwtypes.Plugin, error) {
 	if !ok {
 		return nil, fmt.Errorf("args must be of type ExampleArgs, got %T", args)
 	}
+	logger := klog.Background().WithValues("plugin", PluginName)
 
 	// we can use the included and excluded namespaces to filter the pods we want
 	// to evict.
@@ -90,6 +92,7 @@ func New(args runtime.Object, handle fwtypes.Handle) (fwtypes.Plugin, error) {
 	}
 
 	return &Example{
+		logger:    logger,
 		handle:    handle,
 		podFilter: podFilter,
 		args:      exampleArgs,
@@ -107,7 +110,7 @@ func (d *Example) Name() string {
 // of nodes we need to process.
 func (d *Example) Deschedule(ctx context.Context, nodes []*v1.Node) *fwtypes.Status {
 	var podsToEvict []*v1.Pod
-	logger := klog.FromContext(ctx)
+	logger := klog.FromContext(klog.NewContext(ctx, d.logger)).WithValues("ExtensionPoint", fwtypes.DescheduleExtensionPoint)
 	logger.Info("Example plugin starting descheduling")
 
 	re, err := regexp.Compile(d.args.Regex)

pkg/framework/plugins/nodeutilization/highnodeutilization.go

@@ -43,6 +43,7 @@ var _ frameworktypes.BalancePlugin = &HighNodeUtilization{}
 // can schedule according to its plugin. Note that CPU/Memory requests are used
 // to calculate nodes' utilization and not the actual resource usage.
 type HighNodeUtilization struct {
+	logger         klog.Logger
 	handle         frameworktypes.Handle
 	args           *HighNodeUtilizationArgs
 	podFilter      func(pod *v1.Pod) bool
@@ -63,6 +64,7 @@ func NewHighNodeUtilization(
 			genericArgs,
 		)
 	}
+	logger := klog.Background().WithValues("plugin", HighNodeUtilizationPluginName)
 
 	// this plugins worries only about thresholds but the nodeplugins
 	// package was made to take two thresholds into account, one for low
@@ -102,13 +104,15 @@ func NewHighNodeUtilization(
 	)
 
 	return &HighNodeUtilization{
+		logger:         logger,
 		handle:         handle,
 		args:           args,
 		resourceNames:  resourceNames,
 		highThresholds: highThresholds,
 		criteria:       criteria,
 		podFilter:      podFilter,
 		usageClient: newRequestedUsageClient(
+			logger.WithValues("client", "RequestedUsageClient"),
 			resourceNames,
 			handle.GetPodsAssignedToNodeFunc(),
 		),
@@ -124,6 +128,8 @@ func (h *HighNodeUtilization) Name() string {
 // utilized nodes. The goal here is to concentrate pods in fewer nodes so that
 // less nodes are used.
 func (h *HighNodeUtilization) Balance(ctx context.Context, nodes []*v1.Node) *frameworktypes.Status {
+	logger := klog.FromContext(klog.NewContext(ctx, h.logger)).WithValues("ExtensionPoint", frameworktypes.BalanceExtensionPoint)
+
 	if err := h.usageClient.sync(ctx, nodes); err != nil {
 		return &frameworktypes.Status{
 			Err: fmt.Errorf("error getting node usage: %v", err),
@@ -154,7 +160,7 @@ func (h *HighNodeUtilization) Balance(ctx context.Context, nodes []*v1.Node) *fr
 		// schedulable nodes.
 		func(nodeName string, usage, threshold api.ResourceThresholds) bool {
 			if nodeutil.IsNodeUnschedulable(nodesMap[nodeName]) {
-				klog.V(2).InfoS(
+				logger.V(2).Info(
 					"Node is unschedulable",
 					"node", klog.KObj(nodesMap[nodeName]),
 				)
@@ -173,7 +179,7 @@ func (h *HighNodeUtilization) Balance(ctx context.Context, nodes []*v1.Node) *fr
 	category := []string{"underutilized", "overutilized"}
 	for i := range nodeGroups {
 		for nodeName := range nodeGroups[i] {
-			klog.InfoS(
+			logger.Info(
 				"Node has been classified",
 				"category", category[i],
 				"node", klog.KObj(nodesMap[nodeName]),
@@ -197,18 +203,18 @@ func (h *HighNodeUtilization) Balance(ctx context.Context, nodes []*v1.Node) *fr
 
 	lowNodes, schedulableNodes := nodeInfos[0], nodeInfos[1]
 
-	klog.V(1).InfoS("Criteria for a node below target utilization", h.criteria...)
-	klog.V(1).InfoS("Number of underutilized nodes", "totalNumber", len(lowNodes))
+	logger.V(1).Info("Criteria for a node below target utilization", h.criteria...)
+	logger.V(1).Info("Number of underutilized nodes", "totalNumber", len(lowNodes))
 
 	if len(lowNodes) == 0 {
-		klog.V(1).InfoS(
+		logger.V(1).Info(
 			"No node is underutilized, nothing to do here, you might tune your thresholds further",
 		)
 		return nil
 	}
 
 	if len(lowNodes) <= h.args.NumberOfNodes {
-		klog.V(1).InfoS(
+		logger.V(1).Info(
 			"Number of nodes underutilized is less or equal than NumberOfNodes, nothing to do here",
 			"underutilizedNodes", len(lowNodes),
 			"numberOfNodes", h.args.NumberOfNodes,
@@ -217,12 +223,12 @@ func (h *HighNodeUtilization) Balance(ctx context.Context, nodes []*v1.Node) *fr
 	}
 
 	if len(lowNodes) == len(nodes) {
-		klog.V(1).InfoS("All nodes are underutilized, nothing to do here")
+		logger.V(1).Info("All nodes are underutilized, nothing to do here")
 		return nil
 	}
 
 	if len(schedulableNodes) == 0 {
-		klog.V(1).InfoS("No node is available to schedule the pods, nothing to do here")
+		logger.V(1).Info("No node is available to schedule the pods, nothing to do here")
 		return nil
 	}
 

pkg/framework/plugins/nodeutilization/lownodeutilization.go

@@ -43,6 +43,7 @@ var _ frameworktypes.BalancePlugin = &LowNodeUtilization{}
 // nodes. Note that CPU/Memory requests are used to calculate nodes'
 // utilization and not the actual resource usage.
 type LowNodeUtilization struct {
+	logger                klog.Logger
 	handle                frameworktypes.Handle
 	args                  *LowNodeUtilizationArgs
 	podFilter             func(pod *v1.Pod) bool
@@ -66,6 +67,7 @@ func NewLowNodeUtilization(
 			genericArgs,
 		)
 	}
+	logger := klog.Background().WithValues("plugin", LowNodeUtilizationPluginName)
 
 	// resourceNames holds a list of resources for which the user has
 	// provided thresholds for. extendedResourceNames holds those as well
@@ -115,16 +117,18 @@ func NewLowNodeUtilization(
 	// have the correct one or an error is triggered. XXX MetricsServer is
 	// deprecated, removed once dropped.
 	var usageClient usageClient = newRequestedUsageClient(
+		logger.WithValues("client", "RequestedUsageClient"),
 		extendedResourceNames, handle.GetPodsAssignedToNodeFunc(),
 	)
 	if metrics != nil {
-		usageClient, err = usageClientForMetrics(args, handle, extendedResourceNames)
+		usageClient, err = usageClientForMetrics(logger, args, handle, extendedResourceNames)
 		if err != nil {
 			return nil, err
 		}
 	}
 
 	return &LowNodeUtilization{
+		logger:                logger,
 		handle:                handle,
 		args:                  args,
 		underCriteria:         underCriteria,
@@ -145,6 +149,8 @@ func (l *LowNodeUtilization) Name() string {
 // utilized nodes to under utilized nodes. The goal here is to evenly
 // distribute pods across nodes.
 func (l *LowNodeUtilization) Balance(ctx context.Context, nodes []*v1.Node) *frameworktypes.Status {
+	logger := klog.FromContext(klog.NewContext(ctx, l.logger)).WithValues("ExtensionPoint", frameworktypes.BalanceExtensionPoint)
+
 	if err := l.usageClient.sync(ctx, nodes); err != nil {
 		return &frameworktypes.Status{
 			Err: fmt.Errorf("error getting node usage: %v", err),
@@ -192,7 +198,7 @@ func (l *LowNodeUtilization) Balance(ctx context.Context, nodes []*v1.Node) *fra
 		// underutilized but aren't schedulable are ignored.
 		func(nodeName string, usage, threshold api.ResourceThresholds) bool {
 			if nodeutil.IsNodeUnschedulable(nodesMap[nodeName]) {
-				klog.V(2).InfoS(
+				logger.V(2).Info(
 					"Node is unschedulable, thus not considered as underutilized",
 					"node", klog.KObj(nodesMap[nodeName]),
 				)
@@ -217,7 +223,7 @@ func (l *LowNodeUtilization) Balance(ctx context.Context, nodes []*v1.Node) *fra
 		for nodeName := range nodeGroups[i] {
 			classifiedNodes[nodeName] = true
 
-			klog.InfoS(
+			logger.Info(
 				"Node has been classified",
 				"category", categories[i],
 				"node", klog.KObj(nodesMap[nodeName]),
@@ -243,7 +249,7 @@ func (l *LowNodeUtilization) Balance(ctx context.Context, nodes []*v1.Node) *fra
 	// log nodes that are appropriately utilized.
 	for nodeName := range nodesMap {
 		if !classifiedNodes[nodeName] {
-			klog.InfoS(
+			logger.Info(
 				"Node is appropriately utilized",
 				"node", klog.KObj(nodesMap[nodeName]),
 				"usage", nodesUsageMap[nodeName],
@@ -255,20 +261,20 @@ func (l *LowNodeUtilization) Balance(ctx context.Context, nodes []*v1.Node) *fra
 	lowNodes, highNodes := nodeInfos[0], nodeInfos[1]
 
 	// log messages for nodes with low and high utilization
-	klog.V(1).InfoS("Criteria for a node under utilization", l.underCriteria...)
-	klog.V(1).InfoS("Number of underutilized nodes", "totalNumber", len(lowNodes))
-	klog.V(1).InfoS("Criteria for a node above target utilization", l.overCriteria...)
-	klog.V(1).InfoS("Number of overutilized nodes", "totalNumber", len(highNodes))
+	logger.V(1).Info("Criteria for a node under utilization", "underCriteria", klog.KObjSlice(l.underCriteria))
+	logger.V(1).Info("Number of underutilized nodes", "totalNumber", len(lowNodes))
+	logger.V(1).Info("Criteria for a node above target utilization", "overCriteria", klog.KObjSlice(l.overCriteria))
+	logger.V(1).Info("Number of overutilized nodes", "totalNumber", len(highNodes))
 
 	if len(lowNodes) == 0 {
-		klog.V(1).InfoS(
+		logger.V(1).Info(
 			"No node is underutilized, nothing to do here, you might tune your thresholds further",
 		)
 		return nil
 	}
 
 	if len(lowNodes) <= l.args.NumberOfNodes {
-		klog.V(1).InfoS(
+		logger.V(1).Info(
 			"Number of nodes underutilized is less or equal than NumberOfNodes, nothing to do here",
 			"underutilizedNodes", len(lowNodes),
 			"numberOfNodes", l.args.NumberOfNodes,
@@ -277,12 +283,12 @@ func (l *LowNodeUtilization) Balance(ctx context.Context, nodes []*v1.Node) *fra
 	}
 
 	if len(lowNodes) == len(nodes) {
-		klog.V(1).InfoS("All nodes are underutilized, nothing to do here")
+		logger.V(1).Info("All nodes are underutilized, nothing to do here")
 		return nil
 	}
 
 	if len(highNodes) == 0 {
-		klog.V(1).InfoS("All nodes are under target utilization, nothing to do here")
+		logger.V(1).Info("All nodes are under target utilization, nothing to do here")
 		return nil
 	}
 
@@ -359,6 +365,7 @@ func validatePrometheusMetricsUtilization(args *LowNodeUtilizationArgs) error {
 // usageClientForMetrics returns the correct usage client based on the
 // metrics source. XXX MetricsServer is deprecated, removed once dropped.
 func usageClientForMetrics(
+	logger klog.Logger,
 	args *LowNodeUtilizationArgs, handle frameworktypes.Handle, resources []v1.ResourceName,
 ) (usageClient, error) {
 	metrics := args.MetricsUtilization
@@ -368,6 +375,7 @@ func usageClientForMetrics(
 			return nil, fmt.Errorf("metrics client not initialized")
 		}
 		return newActualUsageClient(
+			logger.WithValues("client", "ActualUsageClient"),
 			resources,
 			handle.GetPodsAssignedToNodeFunc(),
 			handle.MetricsCollector(),
@@ -378,6 +386,7 @@ func usageClientForMetrics(
 			return nil, fmt.Errorf("prometheus client not initialized")
 		}
 		return newPrometheusUsageClient(
+			logger.WithValues("client", "PrometheusUsageClient"),
 			handle.GetPodsAssignedToNodeFunc(),
 			handle.PrometheusClient(),
 			metrics.Prometheus.Query,