Merge pull request #883 from googs1025/logging

chore: add more contextual logging info for plugins

Author: k8s-ci-robot

pkg/capacityscheduling/capacity_scheduling.go

@@ -58,6 +58,7 @@ func init() {
 // CapacityScheduling is a plugin that implements the mechanism of capacity scheduling.
 type CapacityScheduling struct {
 	sync.RWMutex
+	logger            klog.Logger
 	fh                framework.Handle
 	podLister         corelisters.PodLister
 	pdbLister         policylisters.PodDisruptionBudgetLister
@@ -119,7 +120,9 @@ func (c *CapacityScheduling) Name() string {
 
 // New initializes a new plugin and returns it.
 func New(ctx context.Context, obj runtime.Object, handle framework.Handle) (framework.Plugin, error) {
+	lh := klog.FromContext(ctx).WithValues("plugin", Name)
 	c := &CapacityScheduling{
+		logger:            lh,
 		fh:                handle,
 		elasticQuotaInfos: NewElasticQuotaInfos(),
 		podLister:         handle.SharedInformerFactory().Core().V1().Pods().Lister(),
@@ -289,7 +292,7 @@ func (c *CapacityScheduling) PreFilterExtensions() framework.PreFilterExtensions
 
 // AddPod from pre-computed data in cycleState.
 func (c *CapacityScheduling) AddPod(ctx context.Context, cycleState *framework.CycleState, podToSchedule *v1.Pod, podToAdd *framework.PodInfo, nodeInfo *framework.NodeInfo) *framework.Status {
-	logger := klog.FromContext(ctx)
+	logger := klog.FromContext(klog.NewContext(ctx, c.logger))
 
 	elasticQuotaSnapshotState, err := getElasticQuotaSnapshotState(cycleState)
 	if err != nil {
@@ -310,7 +313,7 @@ func (c *CapacityScheduling) AddPod(ctx context.Context, cycleState *framework.C
 
 // RemovePod from pre-computed data in cycleState.
 func (c *CapacityScheduling) RemovePod(ctx context.Context, cycleState *framework.CycleState, podToSchedule *v1.Pod, podToRemove *framework.PodInfo, nodeInfo *framework.NodeInfo) *framework.Status {
-	logger := klog.FromContext(ctx)
+	logger := klog.FromContext(klog.NewContext(ctx, c.logger))
 
 	elasticQuotaSnapshotState, err := getElasticQuotaSnapshotState(cycleState)
 	if err != nil {
@@ -341,8 +344,9 @@ func (c *CapacityScheduling) PostFilter(ctx context.Context, state *framework.Cy
 		PdbLister:  c.pdbLister,
 		State:      state,
 		Interface: &preemptor{
-			fh:    c.fh,
-			state: state,
+			logger: c.logger,
+			fh:     c.fh,
+			state:  state,
 		},
 	}
 
@@ -352,8 +356,7 @@ func (c *CapacityScheduling) PostFilter(ctx context.Context, state *framework.Cy
 func (c *CapacityScheduling) Reserve(ctx context.Context, state *framework.CycleState, pod *v1.Pod, nodeName string) *framework.Status {
 	c.Lock()
 	defer c.Unlock()
-
-	logger := klog.FromContext(ctx)
+	logger := klog.FromContext(klog.NewContext(ctx, c.logger)).WithValues("ExtensionPoint", "Reserve")
 
 	elasticQuotaInfo := c.elasticQuotaInfos[pod.Namespace]
 	if elasticQuotaInfo != nil {
@@ -382,8 +385,9 @@ func (c *CapacityScheduling) Unreserve(ctx context.Context, state *framework.Cyc
 }
 
 type preemptor struct {
-	fh    framework.Handle
-	state *framework.CycleState
+	logger klog.Logger
+	fh     framework.Handle
+	state  *framework.CycleState
 }
 
 func (p *preemptor) OrderedScoreFuncs(ctx context.Context, nodesToVictims map[string]*extenderv1.Victims) []func(node string) int64 {
@@ -409,7 +413,7 @@ func (p *preemptor) CandidatesToVictimsMap(candidates []preemption.Candidate) ma
 // We look at the node that is nominated for this pod and as long as there are
 // terminating pods on the node, we don't consider this for preempting more pods.
 func (p *preemptor) PodEligibleToPreemptOthers(pod *v1.Pod, nominatedNodeStatus *framework.Status) (bool, string) {
-	logger := klog.FromContext(context.TODO())
+	logger := p.logger
 
 	if pod.Spec.PreemptionPolicy != nil && *pod.Spec.PreemptionPolicy == v1.PreemptNever {
 		logger.V(5).Info("Pod is not eligible for preemption because of its preemptionPolicy", "pod", klog.KObj(pod), "preemptionPolicy", v1.PreemptNever)
@@ -492,7 +496,7 @@ func (p *preemptor) SelectVictimsOnNode(
 	nodeInfo *framework.NodeInfo,
 	pdbs []*policy.PodDisruptionBudget) ([]*v1.Pod, int, *framework.Status) {
 
-	logger := klog.FromContext(ctx)
+	logger := p.logger
 
 	elasticQuotaSnapshotState, err := getElasticQuotaSnapshotState(state)
 	if err != nil {

pkg/coscheduling/coscheduling.go

@@ -40,6 +40,7 @@ import (
 
 // Coscheduling is a plugin that schedules pods in a group.
 type Coscheduling struct {
+	logger           klog.Logger
 	frameworkHandler framework.Handle
 	pgMgr            core.Manager
 	scheduleTimeout  *time.Duration
@@ -62,7 +63,7 @@ const (
 // New initializes and returns a new Coscheduling plugin.
 func New(ctx context.Context, obj runtime.Object, handle framework.Handle) (framework.Plugin, error) {
 
-	lh := klog.FromContext(ctx)
+	lh := klog.FromContext(ctx).WithValues("plugin", Name)
 	lh.V(5).Info("creating new coscheduling plugin")
 
 	args, ok := obj.(*config.CoschedulingArgs)
@@ -91,6 +92,7 @@ func New(ctx context.Context, obj runtime.Object, handle framework.Handle) (fram
 		handle.SharedInformerFactory().Core().V1().Pods(),
 	)
 	plugin := &Coscheduling{
+		logger:           lh,
 		frameworkHandler: handle,
 		pgMgr:            pgMgr,
 		scheduleTimeout:  &scheduleTimeDuration,
@@ -144,7 +146,7 @@ func (cs *Coscheduling) Less(podInfo1, podInfo2 *framework.QueuedPodInfo) bool {
 // 1. Whether the PodGroup that the Pod belongs to is on the deny list.
 // 2. Whether the total number of pods in a PodGroup is less than its `minMember`.
 func (cs *Coscheduling) PreFilter(ctx context.Context, state *framework.CycleState, pod *v1.Pod) (*framework.PreFilterResult, *framework.Status) {
-	lh := klog.FromContext(ctx)
+	lh := klog.FromContext(klog.NewContext(ctx, cs.logger)).WithValues("ExtensionPoint", "PreFilter")
 	// If PreFilter fails, return framework.UnschedulableAndUnresolvable to avoid
 	// any preemption attempts.
 	if err := cs.pgMgr.PreFilter(ctx, pod); err != nil {
@@ -157,7 +159,7 @@ func (cs *Coscheduling) PreFilter(ctx context.Context, state *framework.CycleSta
 // PostFilter is used to reject a group of pods if a pod does not pass PreFilter or Filter.
 func (cs *Coscheduling) PostFilter(ctx context.Context, state *framework.CycleState, pod *v1.Pod,
 	filteredNodeStatusMap framework.NodeToStatusMap) (*framework.PostFilterResult, *framework.Status) {
-	lh := klog.FromContext(ctx)
+	lh := klog.FromContext(klog.NewContext(ctx, cs.logger)).WithValues("ExtensionPoint", "PostFilter")
 	pgName, pg := cs.pgMgr.GetPodGroup(ctx, pod)
 	if pg == nil {
 		lh.V(4).Info("Pod does not belong to any group", "pod", klog.KObj(pod))
@@ -210,7 +212,7 @@ func (cs *Coscheduling) PreFilterExtensions() framework.PreFilterExtensions {
 
 // Permit is the functions invoked by the framework at "Permit" extension point.
 func (cs *Coscheduling) Permit(ctx context.Context, state *framework.CycleState, pod *v1.Pod, nodeName string) (*framework.Status, time.Duration) {
-	lh := klog.FromContext(ctx)
+	lh := klog.FromContext(klog.NewContext(ctx, cs.logger)).WithValues("ExtensionPoint", "Permit")
 	waitTime := *cs.scheduleTimeout
 	s := cs.pgMgr.Permit(ctx, state, pod)
 	var retStatus *framework.Status
@@ -251,7 +253,7 @@ func (cs *Coscheduling) Reserve(ctx context.Context, state *framework.CycleState
 
 // Unreserve rejects all other Pods in the PodGroup when one of the pods in the group times out.
 func (cs *Coscheduling) Unreserve(ctx context.Context, state *framework.CycleState, pod *v1.Pod, nodeName string) {
-	lh := klog.FromContext(ctx)
+	lh := klog.FromContext(klog.NewContext(ctx, cs.logger)).WithValues("ExtensionPoint", "Unreserve")
 	pgName, pg := cs.pgMgr.GetPodGroup(ctx, pod)
 	if pg == nil {
 		return

pkg/networkaware/networkoverhead/networkoverhead.go

@@ -73,7 +73,7 @@ func init() {
 // NetworkOverhead : Filter and Score nodes based on Pod's AppGroup requirements: MaxNetworkCosts requirements among Pods with dependencies
 type NetworkOverhead struct {
 	client.Client
-
+	logger      klog.Logger
 	podLister   corelisters.PodLister
 	handle      framework.Handle
 	namespaces  []string
@@ -140,7 +140,7 @@ func (no *NetworkOverhead) ScoreExtensions() framework.ScoreExtensions {
 
 // New : create an instance of a NetworkOverhead plugin
 func New(ctx context.Context, obj runtime.Object, handle framework.Handle) (framework.Plugin, error) {
-	logger := klog.FromContext(ctx)
+	logger := klog.FromContext(ctx).WithValues("plugin", Name)
 	logger.V(4).Info("Creating new instance of the NetworkOverhead plugin")
 
 	args, err := getArgs(obj)
@@ -155,8 +155,8 @@ func New(ctx context.Context, obj runtime.Object, handle framework.Handle) (fram
 	}
 
 	no := &NetworkOverhead{
-		Client: client,
-
+		Client:      client,
+		logger:      logger,
 		podLister:   handle.SharedInformerFactory().Core().V1().Pods().Lister(),
 		handle:      handle,
 		namespaces:  args.Namespaces,
@@ -178,7 +178,7 @@ func (no *NetworkOverhead) PreFilter(ctx context.Context, state *framework.Cycle
 	preFilterState := &PreFilterState{
 		scoreEqually: true,
 	}
-	logger := klog.FromContext(ctx)
+	logger := klog.FromContext(klog.NewContext(ctx, no.logger)).WithValues("ExtensionPoint", "PreFilter")
 
 	// Write initial status
 	state.Write(preFilterStateKey, preFilterState)
@@ -190,10 +190,10 @@ func (no *NetworkOverhead) PreFilter(ctx context.Context, state *framework.Cycle
 	}
 
 	// Get AppGroup CR
-	appGroup := no.findAppGroupNetworkOverhead(ctx, logger, agName)
+	appGroup := no.findAppGroupNetworkOverhead(ctx, agName)
 
 	// Get NetworkTopology CR
-	networkTopology := no.findNetworkTopologyNetworkOverhead(ctx, logger)
+	networkTopology := no.findNetworkTopologyNetworkOverhead(ctx)
 
 	// Sort Costs if manual weights were selected
 	no.sortNetworkTopologyCosts(networkTopology)
@@ -273,7 +273,7 @@ func (no *NetworkOverhead) PreFilter(ctx context.Context, state *framework.Cycle
 		logger.V(6).Info("Number of dependencies", "satisfied", satisfied, "violated", violated)
 
 		// Get accumulated cost based on pod dependencies
-		cost, ok := no.getAccumulatedCost(logger, scheduledList, dependencyList, nodeInfo.Node().Name, region, zone, costMap)
+		cost, ok := no.getAccumulatedCost(scheduledList, dependencyList, nodeInfo.Node().Name, region, zone, costMap)
 		if ok != nil {
 			return nil, framework.NewStatus(framework.Error, fmt.Sprintf("getting pod hostname from Snapshot: %v", ok))
 		}
@@ -332,7 +332,7 @@ func (no *NetworkOverhead) Filter(ctx context.Context,
 	if nodeInfo.Node() == nil {
 		return framework.NewStatus(framework.Error, "node not found")
 	}
-	logger := klog.FromContext(ctx)
+	logger := klog.FromContext(klog.NewContext(ctx, no.logger)).WithValues("ExtensionPoint", "Filter")
 
 	// Get PreFilterState
 	preFilterState, err := getPreFilterState(cycleState)
@@ -367,7 +367,7 @@ func (no *NetworkOverhead) Score(ctx context.Context,
 	nodeName string) (int64, *framework.Status) {
 	score := framework.MinNodeScore
 
-	logger := klog.FromContext(ctx)
+	logger := klog.FromContext(klog.NewContext(ctx, no.logger)).WithValues("ExtensionPoint", "Score")
 	// Get PreFilterState
 	preFilterState, err := getPreFilterState(cycleState)
 	if err != nil {
@@ -391,7 +391,7 @@ func (no *NetworkOverhead) NormalizeScore(ctx context.Context,
 	state *framework.CycleState,
 	pod *corev1.Pod,
 	scores framework.NodeScoreList) *framework.Status {
-	logger := klog.FromContext(ctx)
+	logger := klog.FromContext(klog.NewContext(ctx, no.logger)).WithValues("ExtensionPoint", "NormalizeScore")
 	logger.V(4).Info("before normalization: ", "scores", scores)
 
 	// Get Min and Max Scores to normalize between framework.MaxNodeScore and framework.MinNodeScore
@@ -575,7 +575,6 @@ func checkMaxNetworkCostRequirements(
 
 // getAccumulatedCost : calculate the accumulated cost based on the Pod's dependencies
 func (no *NetworkOverhead) getAccumulatedCost(
-	logger klog.Logger,
 	scheduledList networkawareutil.ScheduledList,
 	dependencyList []agv1alpha1.DependenciesInfo,
 	nodeName string,
@@ -599,7 +598,7 @@ func (no *NetworkOverhead) getAccumulatedCost(
 				// Get NodeInfo from pod Hostname
 				podNodeInfo, err := no.handle.SnapshotSharedLister().NodeInfos().Get(podAllocated.Hostname)
 				if err != nil {
-					logger.Error(err, "getting pod hostname from Snapshot", "nodeInfo", podNodeInfo)
+					no.logger.Error(err, "getting pod hostname from Snapshot", "nodeInfo", podNodeInfo)
 					return cost, err
 				}
 				// Get zone and region from Pod Hostname
@@ -653,18 +652,18 @@ func getPreFilterState(cycleState *framework.CycleState) (*PreFilterState, error
 	return state, nil
 }
 
-func (no *NetworkOverhead) findAppGroupNetworkOverhead(ctx context.Context, logger klog.Logger, agName string) *agv1alpha1.AppGroup {
-	logger.V(6).Info("Debugging namespaces", "namespaces", no.namespaces)
+func (no *NetworkOverhead) findAppGroupNetworkOverhead(ctx context.Context, agName string) *agv1alpha1.AppGroup {
+	no.logger.V(6).Info("Debugging namespaces", "namespaces", no.namespaces)
 	for _, namespace := range no.namespaces {
-		logger.V(6).Info("appGroup CR", "namespace", namespace, "name", agName)
+		no.logger.V(6).Info("appGroup CR", "namespace", namespace, "name", agName)
 		// AppGroup could not be placed in several namespaces simultaneously
 		appGroup := &agv1alpha1.AppGroup{}
 		err := no.Get(ctx, client.ObjectKey{
 			Namespace: namespace,
 			Name:      agName,
 		}, appGroup)
 		if err != nil {
-			logger.V(4).Error(err, "Cannot get AppGroup from AppGroupNamespaceLister:")
+			no.logger.V(4).Error(err, "Cannot get AppGroup from AppGroupNamespaceLister:")
 			continue
 		}
 		if appGroup != nil && appGroup.GetUID() != "" {
@@ -674,18 +673,18 @@ func (no *NetworkOverhead) findAppGroupNetworkOverhead(ctx context.Context, logg
 	return nil
 }
 
-func (no *NetworkOverhead) findNetworkTopologyNetworkOverhead(ctx context.Context, logger klog.Logger) *ntv1alpha1.NetworkTopology {
-	logger.V(6).Info("Debugging namespaces", "namespaces", no.namespaces)
+func (no *NetworkOverhead) findNetworkTopologyNetworkOverhead(ctx context.Context) *ntv1alpha1.NetworkTopology {
+	no.logger.V(6).Info("Debugging namespaces", "namespaces", no.namespaces)
 	for _, namespace := range no.namespaces {
-		logger.V(6).Info("networkTopology CR:", "namespace", namespace, "name", no.ntName)
+		no.logger.V(6).Info("networkTopology CR:", "namespace", namespace, "name", no.ntName)
 		// NetworkTopology could not be placed in several namespaces simultaneously
 		networkTopology := &ntv1alpha1.NetworkTopology{}
 		err := no.Get(ctx, client.ObjectKey{
 			Namespace: namespace,
 			Name:      no.ntName,
 		}, networkTopology)
 		if err != nil {
-			logger.V(4).Error(err, "Cannot get networkTopology from networkTopologyNamespaceLister:")
+			no.logger.V(4).Error(err, "Cannot get networkTopology from networkTopologyNamespaceLister:")
 			continue
 		}
 		if networkTopology != nil && networkTopology.GetUID() != "" {

pkg/networkaware/topologicalsort/topologicalsort.go

@@ -50,6 +50,7 @@ func init() {
 // TopologicalSort : Sort pods based on their AppGroup and corresponding microservice dependencies
 type TopologicalSort struct {
 	client.Client
+	logger     klog.Logger
 	handle     framework.Handle
 	namespaces []string
 }
@@ -73,7 +74,7 @@ func getArgs(obj runtime.Object) (*pluginconfig.TopologicalSortArgs, error) {
 
 // New : create an instance of a TopologicalSort plugin
 func New(ctx context.Context, obj runtime.Object, handle framework.Handle) (framework.Plugin, error) {
-	logger := klog.FromContext(ctx)
+	logger := klog.FromContext(ctx).WithValues("plugin", Name)
 	logger.V(4).Info("Creating new instance of the TopologicalSort plugin")
 
 	args, err := getArgs(obj)
@@ -90,6 +91,7 @@ func New(ctx context.Context, obj runtime.Object, handle framework.Handle) (fram
 
 	pl := &TopologicalSort{
 		Client:     client,
+		logger:     logger,
 		handle:     handle,
 		namespaces: args.Namespaces,
 	}
@@ -103,7 +105,7 @@ func (ts *TopologicalSort) Less(pInfo1, pInfo2 *framework.QueuedPodInfo) bool {
 	p1AppGroup := networkawareutil.GetPodAppGroupLabel(pInfo1.Pod)
 	p2AppGroup := networkawareutil.GetPodAppGroupLabel(pInfo2.Pod)
 	ctx := context.TODO()
-	logger := klog.FromContext(ctx)
+	logger := ts.logger.WithValues("ExtensionPoint", "Less")
 
 	// If pods do not belong to an AppGroup, or being to different AppGroups, follow vanilla QoS Sort
 	if p1AppGroup != p2AppGroup || len(p1AppGroup) == 0 {
@@ -115,7 +117,7 @@ func (ts *TopologicalSort) Less(pInfo1, pInfo2 *framework.QueuedPodInfo) bool {
 	// Pods belong to the same appGroup, get the CR
 	logger.V(6).Info("Pods belong to the same AppGroup CR", "p1 name", pInfo1.Pod.Name, "p2 name", pInfo2.Pod.Name, "appGroup", p1AppGroup)
 	agName := p1AppGroup
-	appGroup := ts.findAppGroupTopologicalSort(ctx, logger, agName)
+	appGroup := ts.findAppGroupTopologicalSort(ctx, agName)
 
 	// Get labels from both pods
 	labelsP1 := pInfo1.Pod.GetLabels()
@@ -131,7 +133,8 @@ func (ts *TopologicalSort) Less(pInfo1, pInfo2 *framework.QueuedPodInfo) bool {
 	return orderP1 <= orderP2
 }
 
-func (ts *TopologicalSort) findAppGroupTopologicalSort(ctx context.Context, logger klog.Logger, agName string) *agv1alpha.AppGroup {
+func (ts *TopologicalSort) findAppGroupTopologicalSort(ctx context.Context, agName string) *agv1alpha.AppGroup {
+	logger := ts.logger
 	for _, namespace := range ts.namespaces {
 		logger.V(6).Info("appGroup CR", "namespace", namespace, "name", agName)
 		// AppGroup couldn't be placed in several namespaces simultaneously

pkg/noderesources/allocatable.go

@@ -33,6 +33,7 @@ import (
 // Allocatable is a score plugin that favors nodes based on their allocatable
 // resources.
 type Allocatable struct {
+	logger klog.Logger
 	handle framework.Handle
 	resourceAllocationScorer
 }
@@ -59,7 +60,7 @@ func validateResources(resources []schedulerconfig.ResourceSpec) error {
 
 // Score invoked at the score extension point.
 func (alloc *Allocatable) Score(ctx context.Context, state *framework.CycleState, pod *v1.Pod, nodeName string) (int64, *framework.Status) {
-	logger := klog.FromContext(ctx)
+	logger := klog.FromContext(klog.NewContext(ctx, alloc.logger)).WithValues("ExtensionPoint", "Score")
 	nodeInfo, err := alloc.handle.SnapshotSharedLister().NodeInfos().Get(nodeName)
 	if err != nil {
 		return 0, framework.NewStatus(framework.Error, fmt.Sprintf("getting node %q from Snapshot: %v", nodeName, err))
@@ -79,7 +80,7 @@ func (alloc *Allocatable) ScoreExtensions() framework.ScoreExtensions {
 
 // NewAllocatable initializes a new plugin and returns it.
 func NewAllocatable(ctx context.Context, allocArgs runtime.Object, h framework.Handle) (framework.Plugin, error) {
-	logger := klog.FromContext(ctx)
+	logger := klog.FromContext(ctx).WithValues("plugin", AllocatableName)
 	// Start with default values.
 	mode := config.Least
 	resToWeightMap := defaultResourcesToWeightMap
@@ -110,6 +111,7 @@ func NewAllocatable(ctx context.Context, allocArgs runtime.Object, h framework.H
 	}
 
 	return &Allocatable{
+		logger: logger,
 		handle: h,
 		resourceAllocationScorer: resourceAllocationScorer{
 			Name:                AllocatableName,

pkg/noderesourcetopology/filter.go

@@ -191,7 +191,8 @@ func (tm *TopologyMatch) Filter(ctx context.Context, cycleState *framework.Cycle
 
 	nodeName := nodeInfo.Node().Name
 
-	lh := klog.FromContext(ctx).WithValues(logging.KeyPod, klog.KObj(pod), logging.KeyPodUID, logging.PodUID(pod), logging.KeyNode, nodeName)
+	lh := klog.FromContext(klog.NewContext(ctx, tm.logger)).WithValues("ExtensionPoint", "Filter").
+		WithValues(logging.KeyPod, klog.KObj(pod), logging.KeyPodUID, logging.PodUID(pod), logging.KeyNode, nodeName)
 
 	lh.V(4).Info(logging.FlowBegin)
 	defer lh.V(4).Info(logging.FlowEnd)