diff --git a/pkg/scheduler/eventhandlers.go b/pkg/scheduler/eventhandlers.go index 95ed57114b5..15944ceb163 100644 --- a/pkg/scheduler/eventhandlers.go +++ b/pkg/scheduler/eventhandlers.go @@ -43,9 +43,10 @@ import ( ) func (sched *Scheduler) onStorageClassAdd(obj interface{}) { + logger := sched.logger sc, ok := obj.(*storagev1.StorageClass) if !ok { - klog.ErrorS(nil, "Cannot convert to *storagev1.StorageClass", "obj", obj) + logger.Error(nil, "Cannot convert to *storagev1.StorageClass", "obj", obj) return } @@ -56,42 +57,45 @@ func (sched *Scheduler) onStorageClassAdd(obj interface{}) { // We don't need to invalidate cached results because results will not be // cached for pod that has unbound immediate PVCs. if sc.VolumeBindingMode != nil && *sc.VolumeBindingMode == storagev1.VolumeBindingWaitForFirstConsumer { - sched.SchedulingQueue.MoveAllToActiveOrBackoffQueue(queue.StorageClassAdd, nil) + sched.SchedulingQueue.MoveAllToActiveOrBackoffQueue(logger, queue.StorageClassAdd, nil) } } func (sched *Scheduler) addNodeToCache(obj interface{}) { + logger := sched.logger node, ok := obj.(*v1.Node) if !ok { - klog.ErrorS(nil, "Cannot convert to *v1.Node", "obj", obj) + logger.Error(nil, "Cannot convert to *v1.Node", "obj", obj) return } - nodeInfo := sched.Cache.AddNode(node) - klog.V(3).InfoS("Add event for node", "node", klog.KObj(node)) - sched.SchedulingQueue.MoveAllToActiveOrBackoffQueue(queue.NodeAdd, preCheckForNode(nodeInfo)) + nodeInfo := sched.Cache.AddNode(logger, node) + logger.V(3).Info("Add event for node", "node", klog.KObj(node)) + sched.SchedulingQueue.MoveAllToActiveOrBackoffQueue(logger, queue.NodeAdd, preCheckForNode(nodeInfo)) } func (sched *Scheduler) updateNodeInCache(oldObj, newObj interface{}) { + logger := sched.logger oldNode, ok := oldObj.(*v1.Node) if !ok { - klog.ErrorS(nil, "Cannot convert oldObj to *v1.Node", "oldObj", oldObj) + logger.Error(nil, "Cannot convert oldObj to *v1.Node", "oldObj", oldObj) return } newNode, ok := newObj.(*v1.Node) if !ok { - klog.ErrorS(nil, "Cannot convert newObj to *v1.Node", "newObj", newObj) + logger.Error(nil, "Cannot convert newObj to *v1.Node", "newObj", newObj) return } - nodeInfo := sched.Cache.UpdateNode(oldNode, newNode) + nodeInfo := sched.Cache.UpdateNode(logger, oldNode, newNode) // Only requeue unschedulable pods if the node became more schedulable. if event := nodeSchedulingPropertiesChange(newNode, oldNode); event != nil { - sched.SchedulingQueue.MoveAllToActiveOrBackoffQueue(*event, preCheckForNode(nodeInfo)) + sched.SchedulingQueue.MoveAllToActiveOrBackoffQueue(logger, *event, preCheckForNode(nodeInfo)) } } func (sched *Scheduler) deleteNodeFromCache(obj interface{}) { + logger := sched.logger var node *v1.Node switch t := obj.(type) { case *v1.Node: @@ -100,28 +104,30 @@ func (sched *Scheduler) deleteNodeFromCache(obj interface{}) { var ok bool node, ok = t.Obj.(*v1.Node) if !ok { - klog.ErrorS(nil, "Cannot convert to *v1.Node", "obj", t.Obj) + logger.Error(nil, "Cannot convert to *v1.Node", "obj", t.Obj) return } default: - klog.ErrorS(nil, "Cannot convert to *v1.Node", "obj", t) + logger.Error(nil, "Cannot convert to *v1.Node", "obj", t) return } - klog.V(3).InfoS("Delete event for node", "node", klog.KObj(node)) - if err := sched.Cache.RemoveNode(node); err != nil { - klog.ErrorS(err, "Scheduler cache RemoveNode failed") + logger.V(3).Info("Delete event for node", "node", klog.KObj(node)) + if err := sched.Cache.RemoveNode(logger, node); err != nil { + logger.Error(err, "Scheduler cache RemoveNode failed") } } func (sched *Scheduler) addPodToSchedulingQueue(obj interface{}) { + logger := sched.logger pod := obj.(*v1.Pod) - klog.V(3).InfoS("Add event for unscheduled pod", "pod", klog.KObj(pod)) - if err := sched.SchedulingQueue.Add(pod); err != nil { + logger.V(3).Info("Add event for unscheduled pod", "pod", klog.KObj(pod)) + if err := sched.SchedulingQueue.Add(logger, pod); err != nil { utilruntime.HandleError(fmt.Errorf("unable to queue %T: %v", obj, err)) } } func (sched *Scheduler) updatePodInSchedulingQueue(oldObj, newObj interface{}) { + logger := sched.logger oldPod, newPod := oldObj.(*v1.Pod), newObj.(*v1.Pod) // Bypass update event that carries identical objects; otherwise, a duplicated // Pod may go through scheduling and cause unexpected behavior (see #96071). @@ -137,12 +143,13 @@ func (sched *Scheduler) updatePodInSchedulingQueue(oldObj, newObj interface{}) { return } - if err := sched.SchedulingQueue.Update(oldPod, newPod); err != nil { + if err := sched.SchedulingQueue.Update(logger, oldPod, newPod); err != nil { utilruntime.HandleError(fmt.Errorf("unable to update %T: %v", newObj, err)) } } func (sched *Scheduler) deletePodFromSchedulingQueue(obj interface{}) { + logger := sched.logger var pod *v1.Pod switch t := obj.(type) { case *v1.Pod: @@ -158,7 +165,7 @@ func (sched *Scheduler) deletePodFromSchedulingQueue(obj interface{}) { utilruntime.HandleError(fmt.Errorf("unable to handle object in %T: %T", sched, obj)) return } - klog.V(3).InfoS("Delete event for unscheduled pod", "pod", klog.KObj(pod)) + logger.V(3).Info("Delete event for unscheduled pod", "pod", klog.KObj(pod)) if err := sched.SchedulingQueue.Delete(pod); err != nil { utilruntime.HandleError(fmt.Errorf("unable to dequeue %T: %v", obj, err)) } @@ -166,53 +173,56 @@ func (sched *Scheduler) deletePodFromSchedulingQueue(obj interface{}) { if err != nil { // This shouldn't happen, because we only accept for scheduling the pods // which specify a scheduler name that matches one of the profiles. - klog.ErrorS(err, "Unable to get profile", "pod", klog.KObj(pod)) + logger.Error(err, "Unable to get profile", "pod", klog.KObj(pod)) return } // If a waiting pod is rejected, it indicates it's previously assumed and we're // removing it from the scheduler cache. In this case, signal a AssignedPodDelete // event to immediately retry some unscheduled Pods. if fwk.RejectWaitingPod(pod.UID) { - sched.SchedulingQueue.MoveAllToActiveOrBackoffQueue(queue.AssignedPodDelete, nil) + sched.SchedulingQueue.MoveAllToActiveOrBackoffQueue(logger, queue.AssignedPodDelete, nil) } } func (sched *Scheduler) addPodToCache(obj interface{}) { + logger := sched.logger pod, ok := obj.(*v1.Pod) if !ok { - klog.ErrorS(nil, "Cannot convert to *v1.Pod", "obj", obj) + logger.Error(nil, "Cannot convert to *v1.Pod", "obj", obj) return } - klog.V(3).InfoS("Add event for scheduled pod", "pod", klog.KObj(pod)) + logger.V(3).Info("Add event for scheduled pod", "pod", klog.KObj(pod)) - if err := sched.Cache.AddPod(pod); err != nil { - klog.ErrorS(err, "Scheduler cache AddPod failed", "pod", klog.KObj(pod)) + if err := sched.Cache.AddPod(logger, pod); err != nil { + logger.Error(err, "Scheduler cache AddPod failed", "pod", klog.KObj(pod)) } - sched.SchedulingQueue.AssignedPodAdded(pod) + sched.SchedulingQueue.AssignedPodAdded(logger, pod) } func (sched *Scheduler) updatePodInCache(oldObj, newObj interface{}) { + logger := sched.logger oldPod, ok := oldObj.(*v1.Pod) if !ok { - klog.ErrorS(nil, "Cannot convert oldObj to *v1.Pod", "oldObj", oldObj) + logger.Error(nil, "Cannot convert oldObj to *v1.Pod", "oldObj", oldObj) return } newPod, ok := newObj.(*v1.Pod) if !ok { - klog.ErrorS(nil, "Cannot convert newObj to *v1.Pod", "newObj", newObj) + logger.Error(nil, "Cannot convert newObj to *v1.Pod", "newObj", newObj) return } - klog.V(4).InfoS("Update event for scheduled pod", "pod", klog.KObj(oldPod)) + logger.V(4).Info("Update event for scheduled pod", "pod", klog.KObj(oldPod)) - if err := sched.Cache.UpdatePod(oldPod, newPod); err != nil { - klog.ErrorS(err, "Scheduler cache UpdatePod failed", "pod", klog.KObj(oldPod)) + if err := sched.Cache.UpdatePod(logger, oldPod, newPod); err != nil { + logger.Error(err, "Scheduler cache UpdatePod failed", "pod", klog.KObj(oldPod)) } - sched.SchedulingQueue.AssignedPodUpdated(newPod) + sched.SchedulingQueue.AssignedPodUpdated(logger, newPod) } func (sched *Scheduler) deletePodFromCache(obj interface{}) { + logger := sched.logger var pod *v1.Pod switch t := obj.(type) { case *v1.Pod: @@ -221,19 +231,19 @@ func (sched *Scheduler) deletePodFromCache(obj interface{}) { var ok bool pod, ok = t.Obj.(*v1.Pod) if !ok { - klog.ErrorS(nil, "Cannot convert to *v1.Pod", "obj", t.Obj) + logger.Error(nil, "Cannot convert to *v1.Pod", "obj", t.Obj) return } default: - klog.ErrorS(nil, "Cannot convert to *v1.Pod", "obj", t) + logger.Error(nil, "Cannot convert to *v1.Pod", "obj", t) return } - klog.V(3).InfoS("Delete event for scheduled pod", "pod", klog.KObj(pod)) - if err := sched.Cache.RemovePod(pod); err != nil { - klog.ErrorS(err, "Scheduler cache RemovePod failed", "pod", klog.KObj(pod)) + logger.V(3).Info("Delete event for scheduled pod", "pod", klog.KObj(pod)) + if err := sched.Cache.RemovePod(logger, pod); err != nil { + logger.Error(err, "Scheduler cache RemovePod failed", "pod", klog.KObj(pod)) } - sched.SchedulingQueue.MoveAllToActiveOrBackoffQueue(queue.AssignedPodDelete, nil) + sched.SchedulingQueue.MoveAllToActiveOrBackoffQueue(logger, queue.AssignedPodDelete, nil) } // assignedPod selects pods that are assigned (scheduled and running). @@ -317,24 +327,25 @@ func addAllEventHandlers( }, ) + logger := sched.logger buildEvtResHandler := func(at framework.ActionType, gvk framework.GVK, shortGVK string) cache.ResourceEventHandlerFuncs { funcs := cache.ResourceEventHandlerFuncs{} if at&framework.Add != 0 { evt := framework.ClusterEvent{Resource: gvk, ActionType: framework.Add, Label: fmt.Sprintf("%vAdd", shortGVK)} funcs.AddFunc = func(_ interface{}) { - sched.SchedulingQueue.MoveAllToActiveOrBackoffQueue(evt, nil) + sched.SchedulingQueue.MoveAllToActiveOrBackoffQueue(logger, evt, nil) } } if at&framework.Update != 0 { evt := framework.ClusterEvent{Resource: gvk, ActionType: framework.Update, Label: fmt.Sprintf("%vUpdate", shortGVK)} funcs.UpdateFunc = func(_, _ interface{}) { - sched.SchedulingQueue.MoveAllToActiveOrBackoffQueue(evt, nil) + sched.SchedulingQueue.MoveAllToActiveOrBackoffQueue(logger, evt, nil) } } if at&framework.Delete != 0 { evt := framework.ClusterEvent{Resource: gvk, ActionType: framework.Delete, Label: fmt.Sprintf("%vDelete", shortGVK)} funcs.DeleteFunc = func(_ interface{}) { - sched.SchedulingQueue.MoveAllToActiveOrBackoffQueue(evt, nil) + sched.SchedulingQueue.MoveAllToActiveOrBackoffQueue(logger, evt, nil) } } return funcs @@ -402,7 +413,7 @@ func addAllEventHandlers( informerFactory.Storage().V1().StorageClasses().Informer().AddEventHandler( cache.ResourceEventHandlerFuncs{ UpdateFunc: func(_, _ interface{}) { - sched.SchedulingQueue.MoveAllToActiveOrBackoffQueue(queue.StorageClassUpdate, nil) + sched.SchedulingQueue.MoveAllToActiveOrBackoffQueue(logger, queue.StorageClassUpdate, nil) }, }, ) @@ -421,7 +432,7 @@ func addAllEventHandlers( // - foos.v1 (2 sections) // - foo.v1.example.com (the first section should be plural) if strings.Count(string(gvk), ".") < 2 { - klog.ErrorS(nil, "incorrect event registration", "gvk", gvk) + logger.Error(nil, "incorrect event registration", "gvk", gvk) continue } // Fall back to try dynamic informers. diff --git a/pkg/scheduler/eventhandlers_test.go b/pkg/scheduler/eventhandlers_test.go index 856d2302652..2dbef1fc961 100644 --- a/pkg/scheduler/eventhandlers_test.go +++ b/pkg/scheduler/eventhandlers_test.go @@ -29,6 +29,7 @@ import ( storagev1 "k8s.io/api/storage/v1" "k8s.io/apimachinery/pkg/api/resource" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" + "k8s.io/klog/v2/ktesting" "k8s.io/apimachinery/pkg/runtime" "k8s.io/apimachinery/pkg/runtime/schema" @@ -220,11 +221,13 @@ func TestUpdatePodInCache(t *testing.T) { } for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { - ctx, cancel := context.WithCancel(context.Background()) + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) defer cancel() sched := &Scheduler{ - Cache: cache.New(ttl, ctx.Done()), + Cache: cache.New(ctx, ttl), SchedulingQueue: queue.NewTestQueue(ctx, nil), + logger: logger, } sched.addPodToCache(tt.oldObj) sched.updatePodInCache(tt.oldObj, tt.newObj) @@ -430,7 +433,8 @@ func TestAddAllEventHandlers(t *testing.T) { for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { - ctx, cancel := context.WithCancel(context.Background()) + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) defer cancel() informerFactory := informers.NewSharedInformerFactory(fake.NewSimpleClientset(), 0) @@ -438,6 +442,7 @@ func TestAddAllEventHandlers(t *testing.T) { testSched := Scheduler{ StopEverything: ctx.Done(), SchedulingQueue: schedulingQueue, + logger: logger, } dynclient := dyfake.NewSimpleDynamicClient(scheme) diff --git a/pkg/scheduler/extender_test.go b/pkg/scheduler/extender_test.go index ff70e348d1d..fc398a48cab 100644 --- a/pkg/scheduler/extender_test.go +++ b/pkg/scheduler/extender_test.go @@ -283,9 +283,9 @@ func TestSchedulerWithExtenders(t *testing.T) { ctx, cancel := context.WithCancel(ctx) defer cancel() - cache := internalcache.New(time.Duration(0), ctx.Done()) + cache := internalcache.New(ctx, time.Duration(0)) for _, name := range test.nodes { - cache.AddNode(createNode(name)) + cache.AddNode(logger, createNode(name)) } fwk, err := st.NewFramework( ctx, @@ -304,6 +304,7 @@ func TestSchedulerWithExtenders(t *testing.T) { nodeInfoSnapshot: emptySnapshot, percentageOfNodesToScore: schedulerapi.DefaultPercentageOfNodesToScore, Extenders: extenders, + logger: logger, } sched.applyDefaultHandlers() diff --git a/pkg/scheduler/framework/interface.go b/pkg/scheduler/framework/interface.go index bb6cbaacc2e..43ba3567482 100644 --- a/pkg/scheduler/framework/interface.go +++ b/pkg/scheduler/framework/interface.go @@ -35,6 +35,7 @@ import ( clientset "k8s.io/client-go/kubernetes" restclient "k8s.io/client-go/rest" "k8s.io/client-go/tools/events" + "k8s.io/klog/v2" "k8s.io/kubernetes/pkg/scheduler/apis/config" "k8s.io/kubernetes/pkg/scheduler/framework/parallelize" ) @@ -704,11 +705,11 @@ func (ni *NominatingInfo) Mode() NominatingMode { type PodNominator interface { // AddNominatedPod adds the given pod to the nominator or // updates it if it already exists. - AddNominatedPod(pod *PodInfo, nominatingInfo *NominatingInfo) + AddNominatedPod(logger klog.Logger, pod *PodInfo, nominatingInfo *NominatingInfo) // DeleteNominatedPodIfExists deletes nominatedPod from internal cache. It's a no-op if it doesn't exist. DeleteNominatedPodIfExists(pod *v1.Pod) // UpdateNominatedPod updates the with . - UpdateNominatedPod(oldPod *v1.Pod, newPodInfo *PodInfo) + UpdateNominatedPod(logger klog.Logger, oldPod *v1.Pod, newPodInfo *PodInfo) // NominatedPodsForNode returns nominatedPods on the given node. NominatedPodsForNode(nodeName string) []*PodInfo } diff --git a/pkg/scheduler/framework/plugins/defaultpreemption/default_preemption_test.go b/pkg/scheduler/framework/plugins/defaultpreemption/default_preemption_test.go index aa746c30673..16d17280adc 100644 --- a/pkg/scheduler/framework/plugins/defaultpreemption/default_preemption_test.go +++ b/pkg/scheduler/framework/plugins/defaultpreemption/default_preemption_test.go @@ -1701,9 +1701,9 @@ func TestPreempt(t *testing.T) { ctx, cancel := context.WithCancel(ctx) defer cancel() - cache := internalcache.New(time.Duration(0), ctx.Done()) + cache := internalcache.New(ctx, time.Duration(0)) for _, pod := range test.pods { - cache.AddPod(pod) + cache.AddPod(logger, pod) } cachedNodeInfoMap := map[string]*framework.NodeInfo{} nodes := make([]*v1.Node, len(test.nodeNames)) @@ -1716,7 +1716,7 @@ func TestPreempt(t *testing.T) { node.ObjectMeta.Labels[labelKeys[i]] = label } node.Name = node.ObjectMeta.Labels["hostname"] - cache.AddNode(node) + cache.AddNode(logger, node) nodes[i] = node // Set nodeInfo to extenders to mock extenders' cache for preemption. diff --git a/pkg/scheduler/framework/runtime/framework_test.go b/pkg/scheduler/framework/runtime/framework_test.go index e611ac77d36..9713250a70b 100644 --- a/pkg/scheduler/framework/runtime/framework_test.go +++ b/pkg/scheduler/framework/runtime/framework_test.go @@ -2342,6 +2342,7 @@ func TestFilterPluginsWithNominatedPods(t *testing.T) { for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { + logger, _ := ktesting.NewTestContext(t) registry := Registry{} cfgPls := &config.Plugins{} @@ -2373,6 +2374,7 @@ func TestFilterPluginsWithNominatedPods(t *testing.T) { podNominator := internalqueue.NewPodNominator(nil) if tt.nominatedPod != nil { podNominator.AddNominatedPod( + logger, mustNewPodInfo(t, tt.nominatedPod), &framework.NominatingInfo{NominatingMode: framework.ModeOverride, NominatedNodeName: nodeName}) } diff --git a/pkg/scheduler/internal/cache/cache.go b/pkg/scheduler/internal/cache/cache.go index 18cc953ee09..4e94b4b3baa 100644 --- a/pkg/scheduler/internal/cache/cache.go +++ b/pkg/scheduler/internal/cache/cache.go @@ -17,6 +17,7 @@ limitations under the License. package cache import ( + "context" "fmt" "sync" "time" @@ -35,11 +36,12 @@ var ( // New returns a Cache implementation. // It automatically starts a go routine that manages expiration of assumed pods. -// "ttl" is how long the assumed pod will get expired, "0" means pod will never expire. -// "stop" is the channel that would close the background goroutine. -func New(ttl time.Duration, stop <-chan struct{}) Cache { - cache := newCache(ttl, cleanAssumedPeriod, stop) - cache.run() +// "ttl" is how long the assumed pod will get expired. +// "ctx" is the context that would close the background goroutine. +func New(ctx context.Context, ttl time.Duration) Cache { + logger := klog.FromContext(ctx) + cache := newCache(ctx, ttl, cleanAssumedPeriod) + cache.run(logger) return cache } @@ -97,14 +99,15 @@ func (cache *cacheImpl) createImageStateSummary(state *imageState) *framework.Im } } -func newCache(ttl, period time.Duration, stop <-chan struct{}) *cacheImpl { +func newCache(ctx context.Context, ttl, period time.Duration) *cacheImpl { + logger := klog.FromContext(ctx) return &cacheImpl{ ttl: ttl, period: period, - stop: stop, + stop: ctx.Done(), nodes: make(map[string]*nodeInfoListItem), - nodeTree: newNodeTree(nil), + nodeTree: newNodeTree(logger, nil), assumedPods: sets.New[string](), podStates: make(map[string]*podState), imageStates: make(map[string]*imageState), @@ -121,10 +124,10 @@ func newNodeInfoListItem(ni *framework.NodeInfo) *nodeInfoListItem { // moveNodeInfoToHead moves a NodeInfo to the head of "cache.nodes" doubly // linked list. The head is the most recently updated NodeInfo. // We assume cache lock is already acquired. -func (cache *cacheImpl) moveNodeInfoToHead(name string) { +func (cache *cacheImpl) moveNodeInfoToHead(logger klog.Logger, name string) { ni, ok := cache.nodes[name] if !ok { - klog.ErrorS(nil, "No node info with given name found in the cache", "node", klog.KRef("", name)) + logger.Error(nil, "No node info with given name found in the cache", "node", klog.KRef("", name)) return } // if the node info list item is already at the head, we are done. @@ -149,10 +152,10 @@ func (cache *cacheImpl) moveNodeInfoToHead(name string) { // removeNodeInfoFromList removes a NodeInfo from the "cache.nodes" doubly // linked list. // We assume cache lock is already acquired. -func (cache *cacheImpl) removeNodeInfoFromList(name string) { +func (cache *cacheImpl) removeNodeInfoFromList(logger klog.Logger, name string) { ni, ok := cache.nodes[name] if !ok { - klog.ErrorS(nil, "No node info with given name found in the cache", "node", klog.KRef("", name)) + logger.Error(nil, "No node info with given name found in the cache", "node", klog.KRef("", name)) return } @@ -194,7 +197,7 @@ func (cache *cacheImpl) Dump() *Dump { // nodeInfo.Node() is guaranteed to be not nil for all the nodes in the snapshot. // This function tracks generation number of NodeInfo and updates only the // entries of an existing snapshot that have changed after the snapshot was taken. -func (cache *cacheImpl) UpdateSnapshot(nodeSnapshot *Snapshot) error { +func (cache *cacheImpl) UpdateSnapshot(logger klog.Logger, nodeSnapshot *Snapshot) error { cache.mu.Lock() defer cache.mu.Unlock() @@ -271,7 +274,7 @@ func (cache *cacheImpl) UpdateSnapshot(nodeSnapshot *Snapshot) error { } if updateAllLists || updateNodesHavePodsWithAffinity || updateNodesHavePodsWithRequiredAntiAffinity || updateUsedPVCSet { - cache.updateNodeInfoSnapshotList(nodeSnapshot, updateAllLists) + cache.updateNodeInfoSnapshotList(logger, nodeSnapshot, updateAllLists) } if len(nodeSnapshot.nodeInfoList) != cache.nodeTree.numNodes { @@ -280,17 +283,17 @@ func (cache *cacheImpl) UpdateSnapshot(nodeSnapshot *Snapshot) error { ", trying to recover", len(nodeSnapshot.nodeInfoList), cache.nodeTree.numNodes, len(nodeSnapshot.nodeInfoMap), len(cache.nodes)) - klog.ErrorS(nil, errMsg) + logger.Error(nil, errMsg) // We will try to recover by re-creating the lists for the next scheduling cycle, but still return an // error to surface the problem, the error will likely cause a failure to the current scheduling cycle. - cache.updateNodeInfoSnapshotList(nodeSnapshot, true) + cache.updateNodeInfoSnapshotList(logger, nodeSnapshot, true) return fmt.Errorf(errMsg) } return nil } -func (cache *cacheImpl) updateNodeInfoSnapshotList(snapshot *Snapshot, updateAll bool) { +func (cache *cacheImpl) updateNodeInfoSnapshotList(logger klog.Logger, snapshot *Snapshot, updateAll bool) { snapshot.havePodsWithAffinityNodeInfoList = make([]*framework.NodeInfo, 0, cache.nodeTree.numNodes) snapshot.havePodsWithRequiredAntiAffinityNodeInfoList = make([]*framework.NodeInfo, 0, cache.nodeTree.numNodes) snapshot.usedPVCSet = sets.New[string]() @@ -299,7 +302,7 @@ func (cache *cacheImpl) updateNodeInfoSnapshotList(snapshot *Snapshot, updateAll snapshot.nodeInfoList = make([]*framework.NodeInfo, 0, cache.nodeTree.numNodes) nodesList, err := cache.nodeTree.list() if err != nil { - klog.ErrorS(err, "Error occurred while retrieving the list of names of the nodes from node tree") + logger.Error(err, "Error occurred while retrieving the list of names of the nodes from node tree") } for _, nodeName := range nodesList { if nodeInfo := snapshot.nodeInfoMap[nodeName]; nodeInfo != nil { @@ -314,7 +317,7 @@ func (cache *cacheImpl) updateNodeInfoSnapshotList(snapshot *Snapshot, updateAll snapshot.usedPVCSet.Insert(key) } } else { - klog.ErrorS(nil, "Node exists in nodeTree but not in NodeInfoMap, this should not happen", "node", klog.KRef("", nodeName)) + logger.Error(nil, "Node exists in nodeTree but not in NodeInfoMap, this should not happen", "node", klog.KRef("", nodeName)) } } } else { @@ -369,7 +372,7 @@ func (cache *cacheImpl) PodCount() (int, error) { return count, nil } -func (cache *cacheImpl) AssumePod(pod *v1.Pod) error { +func (cache *cacheImpl) AssumePod(logger klog.Logger, pod *v1.Pod) error { key, err := framework.GetPodKey(pod) if err != nil { return err @@ -381,15 +384,15 @@ func (cache *cacheImpl) AssumePod(pod *v1.Pod) error { return fmt.Errorf("pod %v(%v) is in the cache, so can't be assumed", key, klog.KObj(pod)) } - return cache.addPod(pod, true) + return cache.addPod(logger, pod, true) } -func (cache *cacheImpl) FinishBinding(pod *v1.Pod) error { - return cache.finishBinding(pod, time.Now()) +func (cache *cacheImpl) FinishBinding(logger klog.Logger, pod *v1.Pod) error { + return cache.finishBinding(logger, pod, time.Now()) } // finishBinding exists to make tests deterministic by injecting now as an argument -func (cache *cacheImpl) finishBinding(pod *v1.Pod, now time.Time) error { +func (cache *cacheImpl) finishBinding(logger klog.Logger, pod *v1.Pod, now time.Time) error { key, err := framework.GetPodKey(pod) if err != nil { return err @@ -398,7 +401,7 @@ func (cache *cacheImpl) finishBinding(pod *v1.Pod, now time.Time) error { cache.mu.RLock() defer cache.mu.RUnlock() - klog.V(5).InfoS("Finished binding for pod, can be expired", "podKey", key, "pod", klog.KObj(pod)) + logger.V(5).Info("Finished binding for pod, can be expired", "podKey", key, "pod", klog.KObj(pod)) currState, ok := cache.podStates[key] if ok && cache.assumedPods.Has(key) { if cache.ttl == time.Duration(0) { @@ -412,7 +415,7 @@ func (cache *cacheImpl) finishBinding(pod *v1.Pod, now time.Time) error { return nil } -func (cache *cacheImpl) ForgetPod(pod *v1.Pod) error { +func (cache *cacheImpl) ForgetPod(logger klog.Logger, pod *v1.Pod) error { key, err := framework.GetPodKey(pod) if err != nil { return err @@ -428,13 +431,13 @@ func (cache *cacheImpl) ForgetPod(pod *v1.Pod) error { // Only assumed pod can be forgotten. if ok && cache.assumedPods.Has(key) { - return cache.removePod(pod) + return cache.removePod(logger, pod) } return fmt.Errorf("pod %v(%v) wasn't assumed so cannot be forgotten", key, klog.KObj(pod)) } // Assumes that lock is already acquired. -func (cache *cacheImpl) addPod(pod *v1.Pod, assumePod bool) error { +func (cache *cacheImpl) addPod(logger klog.Logger, pod *v1.Pod, assumePod bool) error { key, err := framework.GetPodKey(pod) if err != nil { return err @@ -445,7 +448,7 @@ func (cache *cacheImpl) addPod(pod *v1.Pod, assumePod bool) error { cache.nodes[pod.Spec.NodeName] = n } n.info.AddPod(pod) - cache.moveNodeInfoToHead(pod.Spec.NodeName) + cache.moveNodeInfoToHead(logger, pod.Spec.NodeName) ps := &podState{ pod: pod, } @@ -457,18 +460,18 @@ func (cache *cacheImpl) addPod(pod *v1.Pod, assumePod bool) error { } // Assumes that lock is already acquired. -func (cache *cacheImpl) updatePod(oldPod, newPod *v1.Pod) error { - if err := cache.removePod(oldPod); err != nil { +func (cache *cacheImpl) updatePod(logger klog.Logger, oldPod, newPod *v1.Pod) error { + if err := cache.removePod(logger, oldPod); err != nil { return err } - return cache.addPod(newPod, false) + return cache.addPod(logger, newPod, false) } // Assumes that lock is already acquired. // Removes a pod from the cached node info. If the node information was already // removed and there are no more pods left in the node, cleans up the node from // the cache. -func (cache *cacheImpl) removePod(pod *v1.Pod) error { +func (cache *cacheImpl) removePod(logger klog.Logger, pod *v1.Pod) error { key, err := framework.GetPodKey(pod) if err != nil { return err @@ -476,16 +479,15 @@ func (cache *cacheImpl) removePod(pod *v1.Pod) error { n, ok := cache.nodes[pod.Spec.NodeName] if !ok { - klog.ErrorS(nil, "Node not found when trying to remove pod", "node", klog.KRef("", pod.Spec.NodeName), "podKey", key, "pod", klog.KObj(pod)) - + logger.Error(nil, "Node not found when trying to remove pod", "node", klog.KRef("", pod.Spec.NodeName), "podKey", key, "pod", klog.KObj(pod)) } else { if err := n.info.RemovePod(pod); err != nil { return err } if len(n.info.Pods) == 0 && n.info.Node() == nil { - cache.removeNodeInfoFromList(pod.Spec.NodeName) + cache.removeNodeInfoFromList(logger, pod.Spec.NodeName) } else { - cache.moveNodeInfoToHead(pod.Spec.NodeName) + cache.moveNodeInfoToHead(logger, pod.Spec.NodeName) } } @@ -494,7 +496,7 @@ func (cache *cacheImpl) removePod(pod *v1.Pod) error { return nil } -func (cache *cacheImpl) AddPod(pod *v1.Pod) error { +func (cache *cacheImpl) AddPod(logger klog.Logger, pod *v1.Pod) error { key, err := framework.GetPodKey(pod) if err != nil { return err @@ -508,18 +510,18 @@ func (cache *cacheImpl) AddPod(pod *v1.Pod) error { case ok && cache.assumedPods.Has(key): // When assuming, we've already added the Pod to cache, // Just update here to make sure the Pod's status is up-to-date. - if err = cache.updatePod(currState.pod, pod); err != nil { - klog.ErrorS(err, "Error occurred while updating pod") + if err = cache.updatePod(logger, currState.pod, pod); err != nil { + logger.Error(err, "Error occurred while updating pod") } if currState.pod.Spec.NodeName != pod.Spec.NodeName { // The pod was added to a different node than it was assumed to. - klog.InfoS("Pod was added to a different node than it was assumed", "podKey", key, "pod", klog.KObj(pod), "assumedNode", klog.KRef("", pod.Spec.NodeName), "currentNode", klog.KRef("", currState.pod.Spec.NodeName)) + logger.Info("Pod was added to a different node than it was assumed", "podKey", key, "pod", klog.KObj(pod), "assumedNode", klog.KRef("", pod.Spec.NodeName), "currentNode", klog.KRef("", currState.pod.Spec.NodeName)) return nil } case !ok: // Pod was expired. We should add it back. - if err = cache.addPod(pod, false); err != nil { - klog.ErrorS(err, "Error occurred while adding pod") + if err = cache.addPod(logger, pod, false); err != nil { + logger.Error(err, "Error occurred while adding pod") } default: return fmt.Errorf("pod %v(%v) was already in added state", key, klog.KObj(pod)) @@ -527,7 +529,7 @@ func (cache *cacheImpl) AddPod(pod *v1.Pod) error { return nil } -func (cache *cacheImpl) UpdatePod(oldPod, newPod *v1.Pod) error { +func (cache *cacheImpl) UpdatePod(logger klog.Logger, oldPod, newPod *v1.Pod) error { key, err := framework.GetPodKey(oldPod) if err != nil { return err @@ -548,14 +550,14 @@ func (cache *cacheImpl) UpdatePod(oldPod, newPod *v1.Pod) error { } if currState.pod.Spec.NodeName != newPod.Spec.NodeName { - klog.ErrorS(nil, "Pod updated on a different node than previously added to", "podKey", key, "pod", klog.KObj(oldPod)) - klog.ErrorS(nil, "scheduler cache is corrupted and can badly affect scheduling decisions") + logger.Error(nil, "Pod updated on a different node than previously added to", "podKey", key, "pod", klog.KObj(oldPod)) + logger.Error(nil, "scheduler cache is corrupted and can badly affect scheduling decisions") klog.FlushAndExit(klog.ExitFlushTimeout, 1) } - return cache.updatePod(oldPod, newPod) + return cache.updatePod(logger, oldPod, newPod) } -func (cache *cacheImpl) RemovePod(pod *v1.Pod) error { +func (cache *cacheImpl) RemovePod(logger klog.Logger, pod *v1.Pod) error { key, err := framework.GetPodKey(pod) if err != nil { return err @@ -569,15 +571,15 @@ func (cache *cacheImpl) RemovePod(pod *v1.Pod) error { return fmt.Errorf("pod %v(%v) is not found in scheduler cache, so cannot be removed from it", key, klog.KObj(pod)) } if currState.pod.Spec.NodeName != pod.Spec.NodeName { - klog.ErrorS(nil, "Pod was added to a different node than it was assumed", "podKey", key, "pod", klog.KObj(pod), "assumedNode", klog.KRef("", pod.Spec.NodeName), "currentNode", klog.KRef("", currState.pod.Spec.NodeName)) + logger.Error(nil, "Pod was added to a different node than it was assumed", "podKey", key, "pod", klog.KObj(pod), "assumedNode", klog.KRef("", pod.Spec.NodeName), "currentNode", klog.KRef("", currState.pod.Spec.NodeName)) if pod.Spec.NodeName != "" { // An empty NodeName is possible when the scheduler misses a Delete // event and it gets the last known state from the informer cache. - klog.ErrorS(nil, "scheduler cache is corrupted and can badly affect scheduling decisions") + logger.Error(nil, "scheduler cache is corrupted and can badly affect scheduling decisions") klog.FlushAndExit(klog.ExitFlushTimeout, 1) } } - return cache.removePod(currState.pod) + return cache.removePod(logger, currState.pod) } func (cache *cacheImpl) IsAssumedPod(pod *v1.Pod) (bool, error) { @@ -611,7 +613,7 @@ func (cache *cacheImpl) GetPod(pod *v1.Pod) (*v1.Pod, error) { return podState.pod, nil } -func (cache *cacheImpl) AddNode(node *v1.Node) *framework.NodeInfo { +func (cache *cacheImpl) AddNode(logger klog.Logger, node *v1.Node) *framework.NodeInfo { cache.mu.Lock() defer cache.mu.Unlock() @@ -622,15 +624,15 @@ func (cache *cacheImpl) AddNode(node *v1.Node) *framework.NodeInfo { } else { cache.removeNodeImageStates(n.info.Node()) } - cache.moveNodeInfoToHead(node.Name) + cache.moveNodeInfoToHead(logger, node.Name) - cache.nodeTree.addNode(node) + cache.nodeTree.addNode(logger, node) cache.addNodeImageStates(node, n.info) n.info.SetNode(node) return n.info.Clone() } -func (cache *cacheImpl) UpdateNode(oldNode, newNode *v1.Node) *framework.NodeInfo { +func (cache *cacheImpl) UpdateNode(logger klog.Logger, oldNode, newNode *v1.Node) *framework.NodeInfo { cache.mu.Lock() defer cache.mu.Unlock() @@ -638,13 +640,13 @@ func (cache *cacheImpl) UpdateNode(oldNode, newNode *v1.Node) *framework.NodeInf if !ok { n = newNodeInfoListItem(framework.NewNodeInfo()) cache.nodes[newNode.Name] = n - cache.nodeTree.addNode(newNode) + cache.nodeTree.addNode(logger, newNode) } else { cache.removeNodeImageStates(n.info.Node()) } - cache.moveNodeInfoToHead(newNode.Name) + cache.moveNodeInfoToHead(logger, newNode.Name) - cache.nodeTree.updateNode(oldNode, newNode) + cache.nodeTree.updateNode(logger, oldNode, newNode) cache.addNodeImageStates(newNode, n.info) n.info.SetNode(newNode) return n.info.Clone() @@ -656,7 +658,7 @@ func (cache *cacheImpl) UpdateNode(oldNode, newNode *v1.Node) *framework.NodeInf // the source of truth. // However, we keep a ghost node with the list of pods until all pod deletion // events have arrived. A ghost node is skipped from snapshots. -func (cache *cacheImpl) RemoveNode(node *v1.Node) error { +func (cache *cacheImpl) RemoveNode(logger klog.Logger, node *v1.Node) error { cache.mu.Lock() defer cache.mu.Unlock() @@ -670,11 +672,11 @@ func (cache *cacheImpl) RemoveNode(node *v1.Node) error { // in a different watch, and thus can potentially be observed later, even though // they happened before node removal. if len(n.info.Pods) == 0 { - cache.removeNodeInfoFromList(node.Name) + cache.removeNodeInfoFromList(logger, node.Name) } else { - cache.moveNodeInfoToHead(node.Name) + cache.moveNodeInfoToHead(logger, node.Name) } - if err := cache.nodeTree.removeNode(node); err != nil { + if err := cache.nodeTree.removeNode(logger, node); err != nil { return err } cache.removeNodeImageStates(node) @@ -732,17 +734,15 @@ func (cache *cacheImpl) removeNodeImageStates(node *v1.Node) { } } -func (cache *cacheImpl) run() { - go wait.Until(cache.cleanupExpiredAssumedPods, cache.period, cache.stop) -} - -func (cache *cacheImpl) cleanupExpiredAssumedPods() { - cache.cleanupAssumedPods(time.Now()) +func (cache *cacheImpl) run(logger klog.Logger) { + go wait.Until(func() { + cache.cleanupAssumedPods(logger, time.Now()) + }, cache.period, cache.stop) } // cleanupAssumedPods exists for making test deterministic by taking time as input argument. // It also reports metrics on the cache size for nodes, pods, and assumed pods. -func (cache *cacheImpl) cleanupAssumedPods(now time.Time) { +func (cache *cacheImpl) cleanupAssumedPods(logger klog.Logger, now time.Time) { cache.mu.Lock() defer cache.mu.Unlock() defer cache.updateMetrics() @@ -751,17 +751,17 @@ func (cache *cacheImpl) cleanupAssumedPods(now time.Time) { for key := range cache.assumedPods { ps, ok := cache.podStates[key] if !ok { - klog.ErrorS(nil, "Key found in assumed set but not in podStates, potentially a logical error") + logger.Error(nil, "Key found in assumed set but not in podStates, potentially a logical error") klog.FlushAndExit(klog.ExitFlushTimeout, 1) } if !ps.bindingFinished { - klog.V(5).InfoS("Could not expire cache for pod as binding is still in progress", "podKey", key, "pod", klog.KObj(ps.pod)) + logger.V(5).Info("Could not expire cache for pod as binding is still in progress", "podKey", key, "pod", klog.KObj(ps.pod)) continue } if cache.ttl != 0 && now.After(*ps.deadline) { - klog.InfoS("Pod expired", "podKey", key, "pod", klog.KObj(ps.pod)) - if err := cache.removePod(ps.pod); err != nil { - klog.ErrorS(err, "ExpirePod failed", "podKey", key, "pod", klog.KObj(ps.pod)) + logger.Info("Pod expired", "podKey", key, "pod", klog.KObj(ps.pod)) + if err := cache.removePod(logger, ps.pod); err != nil { + logger.Error(err, "ExpirePod failed", "podKey", key, "pod", klog.KObj(ps.pod)) } } } diff --git a/pkg/scheduler/internal/cache/cache_test.go b/pkg/scheduler/internal/cache/cache_test.go index 7d6e71127e1..426f05161f3 100644 --- a/pkg/scheduler/internal/cache/cache_test.go +++ b/pkg/scheduler/internal/cache/cache_test.go @@ -17,6 +17,7 @@ limitations under the License. package cache import ( + "context" "errors" "fmt" "reflect" @@ -30,6 +31,8 @@ import ( metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" "k8s.io/apimachinery/pkg/types" "k8s.io/apimachinery/pkg/util/sets" + "k8s.io/klog/v2" + "k8s.io/klog/v2/ktesting" "k8s.io/kubernetes/pkg/scheduler/framework" st "k8s.io/kubernetes/pkg/scheduler/testing" schedutil "k8s.io/kubernetes/pkg/scheduler/util" @@ -207,13 +210,16 @@ func TestAssumePodScheduled(t *testing.T) { for i, tt := range tests { t.Run(fmt.Sprintf("case_%d", i), func(t *testing.T) { - cache := newCache(time.Second, time.Second, nil) + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) + defer cancel() + cache := newCache(ctx, time.Second, time.Second) for _, pod := range tt.pods { - if err := cache.AssumePod(pod); err != nil { + if err := cache.AssumePod(logger, pod); err != nil { t.Fatalf("AssumePod failed: %v", err) } // pod already in cache so can't be assumed - if err := cache.AssumePod(pod); err == nil { + if err := cache.AssumePod(logger, pod); err == nil { t.Error("expected error, no error found") } } @@ -223,7 +229,7 @@ func TestAssumePodScheduled(t *testing.T) { } for _, pod := range tt.pods { - if err := cache.ForgetPod(pod); err != nil { + if err := cache.ForgetPod(logger, pod); err != nil { t.Fatalf("ForgetPod failed: %v", err) } if err := isForgottenFromCache(pod, cache); err != nil { @@ -240,11 +246,11 @@ type testExpirePodStruct struct { assumedTime time.Time } -func assumeAndFinishBinding(cache *cacheImpl, pod *v1.Pod, assumedTime time.Time) error { - if err := cache.AssumePod(pod); err != nil { +func assumeAndFinishBinding(logger klog.Logger, cache *cacheImpl, pod *v1.Pod, assumedTime time.Time) error { + if err := cache.AssumePod(logger, pod); err != nil { return err } - return cache.finishBinding(pod, assumedTime) + return cache.finishBinding(logger, pod, assumedTime) } // TestExpirePod tests that assumed pods will be removed if expired. @@ -323,22 +329,25 @@ func TestExpirePod(t *testing.T) { for _, tc := range tests { t.Run(tc.name, func(t *testing.T) { - cache := newCache(tc.ttl, time.Second, nil) + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) + defer cancel() + cache := newCache(ctx, tc.ttl, time.Second) for _, pod := range tc.pods { - if err := cache.AssumePod(pod.pod); err != nil { + if err := cache.AssumePod(logger, pod.pod); err != nil { t.Fatal(err) } if !pod.finishBind { continue } - if err := cache.finishBinding(pod.pod, pod.assumedTime); err != nil { + if err := cache.finishBinding(logger, pod.pod, pod.assumedTime); err != nil { t.Fatal(err) } } // pods that got bound and have assumedTime + ttl < cleanupTime will get // expired and removed - cache.cleanupAssumedPods(tc.cleanupTime) + cache.cleanupAssumedPods(logger, tc.cleanupTime) n := cache.nodes[nodeName] if err := deepEqualWithoutGeneration(n, tc.wNodeInfo); err != nil { t.Error(err) @@ -383,22 +392,25 @@ func TestAddPodWillConfirm(t *testing.T) { for i, tt := range tests { t.Run(fmt.Sprintf("case_%d", i), func(t *testing.T) { - cache := newCache(ttl, time.Second, nil) + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) + defer cancel() + cache := newCache(ctx, ttl, time.Second) for _, podToAssume := range tt.podsToAssume { - if err := assumeAndFinishBinding(cache, podToAssume, now); err != nil { + if err := assumeAndFinishBinding(logger, cache, podToAssume, now); err != nil { t.Fatalf("assumePod failed: %v", err) } } for _, podToAdd := range tt.podsToAdd { - if err := cache.AddPod(podToAdd); err != nil { + if err := cache.AddPod(logger, podToAdd); err != nil { t.Fatalf("AddPod failed: %v", err) } // pod already in added state - if err := cache.AddPod(podToAdd); err == nil { + if err := cache.AddPod(logger, podToAdd); err == nil { t.Error("expected error, no error found") } } - cache.cleanupAssumedPods(now.Add(2 * ttl)) + cache.cleanupAssumedPods(logger, now.Add(2*ttl)) // check after expiration. confirmed pods shouldn't be expired. n := cache.nodes[nodeName] if err := deepEqualWithoutGeneration(n, tt.wNodeInfo); err != nil { @@ -427,14 +439,17 @@ func TestDump(t *testing.T) { for i, tt := range tests { t.Run(fmt.Sprintf("case_%d", i), func(t *testing.T) { - cache := newCache(ttl, time.Second, nil) + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) + defer cancel() + cache := newCache(ctx, ttl, time.Second) for _, podToAssume := range tt.podsToAssume { - if err := assumeAndFinishBinding(cache, podToAssume, now); err != nil { + if err := assumeAndFinishBinding(logger, cache, podToAssume, now); err != nil { t.Errorf("assumePod failed: %v", err) } } for _, podToAdd := range tt.podsToAdd { - if err := cache.AddPod(podToAdd); err != nil { + if err := cache.AddPod(logger, podToAdd); err != nil { t.Errorf("AddPod failed: %v", err) } } @@ -460,6 +475,9 @@ func TestDump(t *testing.T) { // even when the Pod is assumed one. func TestAddPodAlwaysUpdatesPodInfoInNodeInfo(t *testing.T) { ttl := 10 * time.Second + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) + defer cancel() now := time.Now() p1 := makeBasePod(t, "node1", "test-1", "100m", "500", "", []v1.ContainerPort{{HostPort: 80}}) @@ -497,14 +515,14 @@ func TestAddPodAlwaysUpdatesPodInfoInNodeInfo(t *testing.T) { for i, tt := range tests { t.Run(fmt.Sprintf("case_%d", i), func(t *testing.T) { - cache := newCache(ttl, time.Second, nil) + cache := newCache(ctx, ttl, time.Second) for _, podToAssume := range tt.podsToAssume { - if err := assumeAndFinishBinding(cache, podToAssume, now); err != nil { + if err := assumeAndFinishBinding(logger, cache, podToAssume, now); err != nil { t.Fatalf("assumePod failed: %v", err) } } for _, podToAdd := range tt.podsToAddAfterAssume { - if err := cache.AddPod(podToAdd); err != nil { + if err := cache.AddPod(logger, podToAdd); err != nil { t.Fatalf("AddPod failed: %v", err) } } @@ -557,19 +575,22 @@ func TestAddPodWillReplaceAssumed(t *testing.T) { for i, tt := range tests { t.Run(fmt.Sprintf("case_%d", i), func(t *testing.T) { - cache := newCache(ttl, time.Second, nil) + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) + defer cancel() + cache := newCache(ctx, ttl, time.Second) for _, podToAssume := range tt.podsToAssume { - if err := assumeAndFinishBinding(cache, podToAssume, now); err != nil { + if err := assumeAndFinishBinding(logger, cache, podToAssume, now); err != nil { t.Fatalf("assumePod failed: %v", err) } } for _, podToAdd := range tt.podsToAdd { - if err := cache.AddPod(podToAdd); err != nil { + if err := cache.AddPod(logger, podToAdd); err != nil { t.Fatalf("AddPod failed: %v", err) } } for _, podToUpdate := range tt.podsToUpdate { - if err := cache.UpdatePod(podToUpdate[0], podToUpdate[1]); err != nil { + if err := cache.UpdatePod(logger, podToUpdate[0], podToUpdate[1]); err != nil { t.Fatalf("UpdatePod failed: %v", err) } } @@ -611,17 +632,20 @@ func TestAddPodAfterExpiration(t *testing.T) { for i, tt := range tests { t.Run(fmt.Sprintf("case_%d", i), func(t *testing.T) { + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) + defer cancel() now := time.Now() - cache := newCache(ttl, time.Second, nil) - if err := assumeAndFinishBinding(cache, tt.pod, now); err != nil { + cache := newCache(ctx, ttl, time.Second) + if err := assumeAndFinishBinding(logger, cache, tt.pod, now); err != nil { t.Fatalf("assumePod failed: %v", err) } - cache.cleanupAssumedPods(now.Add(2 * ttl)) + cache.cleanupAssumedPods(logger, now.Add(2*ttl)) // It should be expired and removed. if err := isForgottenFromCache(tt.pod, cache); err != nil { t.Error(err) } - if err := cache.AddPod(tt.pod); err != nil { + if err := cache.AddPod(logger, tt.pod); err != nil { t.Fatalf("AddPod failed: %v", err) } // check after expiration. confirmed pods shouldn't be expired. @@ -678,9 +702,12 @@ func TestUpdatePod(t *testing.T) { for i, tt := range tests { t.Run(fmt.Sprintf("case_%d", i), func(t *testing.T) { - cache := newCache(ttl, time.Second, nil) + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) + defer cancel() + cache := newCache(ctx, ttl, time.Second) for _, podToAdd := range tt.podsToAdd { - if err := cache.AddPod(podToAdd); err != nil { + if err := cache.AddPod(logger, podToAdd); err != nil { t.Fatalf("AddPod failed: %v", err) } } @@ -689,7 +716,7 @@ func TestUpdatePod(t *testing.T) { if j == 0 { continue } - if err := cache.UpdatePod(tt.podsToUpdate[j-1], tt.podsToUpdate[j]); err != nil { + if err := cache.UpdatePod(logger, tt.podsToUpdate[j-1], tt.podsToUpdate[j]); err != nil { t.Fatalf("UpdatePod failed: %v", err) } // check after expiration. confirmed pods shouldn't be expired. @@ -714,7 +741,7 @@ func TestUpdatePodAndGet(t *testing.T) { pod *v1.Pod podToUpdate *v1.Pod - handler func(cache Cache, pod *v1.Pod) error + handler func(logger klog.Logger, cache Cache, pod *v1.Pod) error assumePod bool }{ @@ -722,8 +749,8 @@ func TestUpdatePodAndGet(t *testing.T) { pod: testPods[0], podToUpdate: testPods[0], - handler: func(cache Cache, pod *v1.Pod) error { - return cache.AssumePod(pod) + handler: func(logger klog.Logger, cache Cache, pod *v1.Pod) error { + return cache.AssumePod(logger, pod) }, assumePod: true, }, @@ -731,8 +758,8 @@ func TestUpdatePodAndGet(t *testing.T) { pod: testPods[0], podToUpdate: testPods[1], - handler: func(cache Cache, pod *v1.Pod) error { - return cache.AddPod(pod) + handler: func(logger klog.Logger, cache Cache, pod *v1.Pod) error { + return cache.AddPod(logger, pod) }, assumePod: false, }, @@ -740,7 +767,10 @@ func TestUpdatePodAndGet(t *testing.T) { for i, tt := range tests { t.Run(fmt.Sprintf("case_%d", i), func(t *testing.T) { - cache := newCache(ttl, time.Second, nil) + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) + defer cancel() + cache := newCache(ctx, ttl, time.Second) // trying to get an unknown pod should return an error // podToUpdate has not been added yet if _, err := cache.GetPod(tt.podToUpdate); err == nil { @@ -749,16 +779,16 @@ func TestUpdatePodAndGet(t *testing.T) { // trying to update an unknown pod should return an error // pod has not been added yet - if err := cache.UpdatePod(tt.pod, tt.podToUpdate); err == nil { + if err := cache.UpdatePod(logger, tt.pod, tt.podToUpdate); err == nil { t.Error("expected error, no error found") } - if err := tt.handler(cache, tt.pod); err != nil { + if err := tt.handler(logger, cache, tt.pod); err != nil { t.Fatalf("unexpected err: %v", err) } if !tt.assumePod { - if err := cache.UpdatePod(tt.pod, tt.podToUpdate); err != nil { + if err := cache.UpdatePod(logger, tt.pod, tt.podToUpdate); err != nil { t.Fatalf("UpdatePod failed: %v", err) } } @@ -821,17 +851,20 @@ func TestExpireAddUpdatePod(t *testing.T) { for i, tt := range tests { t.Run(fmt.Sprintf("case_%d", i), func(t *testing.T) { + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) + defer cancel() now := time.Now() - cache := newCache(ttl, time.Second, nil) + cache := newCache(ctx, ttl, time.Second) for _, podToAssume := range tt.podsToAssume { - if err := assumeAndFinishBinding(cache, podToAssume, now); err != nil { + if err := assumeAndFinishBinding(logger, cache, podToAssume, now); err != nil { t.Fatalf("assumePod failed: %v", err) } } - cache.cleanupAssumedPods(now.Add(2 * ttl)) + cache.cleanupAssumedPods(logger, now.Add(2*ttl)) for _, podToAdd := range tt.podsToAdd { - if err := cache.AddPod(podToAdd); err != nil { + if err := cache.AddPod(logger, podToAdd); err != nil { t.Fatalf("AddPod failed: %v", err) } } @@ -840,7 +873,7 @@ func TestExpireAddUpdatePod(t *testing.T) { if j == 0 { continue } - if err := cache.UpdatePod(tt.podsToUpdate[j-1], tt.podsToUpdate[j]); err != nil { + if err := cache.UpdatePod(logger, tt.podsToUpdate[j-1], tt.podsToUpdate[j]); err != nil { t.Fatalf("UpdatePod failed: %v", err) } // check after expiration. confirmed pods shouldn't be expired. @@ -886,8 +919,11 @@ func TestEphemeralStorageResource(t *testing.T) { } for i, tt := range tests { t.Run(fmt.Sprintf("case_%d", i), func(t *testing.T) { - cache := newCache(time.Second, time.Second, nil) - if err := cache.AddPod(tt.pod); err != nil { + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) + defer cancel() + cache := newCache(ctx, time.Second, time.Second) + if err := cache.AddPod(logger, tt.pod); err != nil { t.Fatalf("AddPod failed: %v", err) } n := cache.nodes[nodeName] @@ -895,7 +931,7 @@ func TestEphemeralStorageResource(t *testing.T) { t.Error(err) } - if err := cache.RemovePod(tt.pod); err != nil { + if err := cache.RemovePod(logger, tt.pod); err != nil { t.Fatalf("RemovePod failed: %v", err) } if _, err := cache.GetPod(tt.pod); err == nil { @@ -938,15 +974,18 @@ func TestRemovePod(t *testing.T) { for name, tt := range tests { t.Run(name, func(t *testing.T) { + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) + defer cancel() nodeName := pod.Spec.NodeName - cache := newCache(time.Second, time.Second, nil) + cache := newCache(ctx, time.Second, time.Second) // Add/Assume pod succeeds even before adding the nodes. if tt.assume { - if err := cache.AddPod(pod); err != nil { + if err := cache.AddPod(logger, pod); err != nil { t.Fatalf("AddPod failed: %v", err) } } else { - if err := cache.AssumePod(pod); err != nil { + if err := cache.AssumePod(logger, pod); err != nil { t.Fatalf("AssumePod failed: %v", err) } } @@ -955,10 +994,10 @@ func TestRemovePod(t *testing.T) { t.Error(err) } for _, n := range nodes { - cache.AddNode(n) + cache.AddNode(logger, n) } - if err := cache.RemovePod(pod); err != nil { + if err := cache.RemovePod(logger, pod); err != nil { t.Fatalf("RemovePod failed: %v", err) } @@ -967,7 +1006,7 @@ func TestRemovePod(t *testing.T) { } // trying to remove a pod already removed should return an error - if err := cache.RemovePod(pod); err == nil { + if err := cache.RemovePod(logger, pod); err == nil { t.Error("expected error, no error found") } @@ -985,10 +1024,13 @@ func TestForgetPod(t *testing.T) { pods := []*v1.Pod{basePod} now := time.Now() ttl := 10 * time.Second + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) + defer cancel() - cache := newCache(ttl, time.Second, nil) + cache := newCache(ctx, ttl, time.Second) for _, pod := range pods { - if err := assumeAndFinishBinding(cache, pod, now); err != nil { + if err := assumeAndFinishBinding(logger, cache, pod, now); err != nil { t.Fatalf("assumePod failed: %v", err) } isAssumed, err := cache.IsAssumedPod(pod) @@ -1010,14 +1052,14 @@ func TestForgetPod(t *testing.T) { } } for _, pod := range pods { - if err := cache.ForgetPod(pod); err != nil { + if err := cache.ForgetPod(logger, pod); err != nil { t.Fatalf("ForgetPod failed: %v", err) } if err := isForgottenFromCache(pod, cache); err != nil { t.Errorf("pod %q: %v", pod.Name, err) } // trying to forget a pod already forgotten should return an error - if err := cache.ForgetPod(pod); err == nil { + if err := cache.ForgetPod(logger, pod); err == nil { t.Error("expected error, no error found") } } @@ -1169,13 +1211,16 @@ func TestNodeOperators(t *testing.T) { for i, test := range tests { t.Run(fmt.Sprintf("case_%d", i), func(t *testing.T) { + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) + defer cancel() expected := buildNodeInfo(test.node, test.pods) node := test.node - cache := newCache(time.Second, time.Second, nil) - cache.AddNode(node) + cache := newCache(ctx, time.Second, time.Second) + cache.AddNode(logger, node) for _, pod := range test.pods { - if err := cache.AddPod(pod); err != nil { + if err := cache.AddPod(logger, pod); err != nil { t.Fatal(err) } } @@ -1201,7 +1246,7 @@ func TestNodeOperators(t *testing.T) { // Step 2: dump cached nodes successfully. cachedNodes := NewEmptySnapshot() - if err := cache.UpdateSnapshot(cachedNodes); err != nil { + if err := cache.UpdateSnapshot(logger, cachedNodes); err != nil { t.Error(err) } newNode, found := cachedNodes.nodeInfoMap[node.Name] @@ -1217,7 +1262,7 @@ func TestNodeOperators(t *testing.T) { node.Status.Allocatable[v1.ResourceMemory] = mem50m expected.Allocatable.Memory = mem50m.Value() - cache.UpdateNode(nil, node) + cache.UpdateNode(logger, nil, node) got, found = cache.nodes[node.Name] if !found { t.Errorf("Failed to find node %v in schedulertypes after UpdateNode.", node.Name) @@ -1240,7 +1285,7 @@ func TestNodeOperators(t *testing.T) { } // Step 4: the node can be removed even if it still has pods. - if err := cache.RemoveNode(node); err != nil { + if err := cache.RemoveNode(logger, node); err != nil { t.Error(err) } if n, err := cache.getNodeInfo(node.Name); err != nil { @@ -1250,7 +1295,7 @@ func TestNodeOperators(t *testing.T) { } // trying to remove a node already removed should return an error - if err := cache.RemoveNode(node); err == nil { + if err := cache.RemoveNode(logger, node); err == nil { t.Error("expected error, no error found") } @@ -1271,7 +1316,7 @@ func TestNodeOperators(t *testing.T) { // Step 5: removing pods for the removed node still succeeds. for _, p := range test.pods { - if err := cache.RemovePod(p); err != nil { + if err := cache.RemovePod(logger, p); err != nil { t.Error(err) } if _, err := cache.GetPod(p); err == nil { @@ -1283,6 +1328,8 @@ func TestNodeOperators(t *testing.T) { } func TestSchedulerCache_UpdateSnapshot(t *testing.T) { + logger, _ := ktesting.NewTestContext(t) + // Create a few nodes to be used in tests. var nodes []*v1.Node for i := 0; i < 10; i++ { @@ -1349,73 +1396,73 @@ func TestSchedulerCache_UpdateSnapshot(t *testing.T) { addNode := func(i int) operation { return func(t *testing.T) { - cache.AddNode(nodes[i]) + cache.AddNode(logger, nodes[i]) } } removeNode := func(i int) operation { return func(t *testing.T) { - if err := cache.RemoveNode(nodes[i]); err != nil { + if err := cache.RemoveNode(logger, nodes[i]); err != nil { t.Error(err) } } } updateNode := func(i int) operation { return func(t *testing.T) { - cache.UpdateNode(nodes[i], updatedNodes[i]) + cache.UpdateNode(logger, nodes[i], updatedNodes[i]) } } addPod := func(i int) operation { return func(t *testing.T) { - if err := cache.AddPod(pods[i]); err != nil { + if err := cache.AddPod(logger, pods[i]); err != nil { t.Error(err) } } } addPodWithAffinity := func(i int) operation { return func(t *testing.T) { - if err := cache.AddPod(podsWithAffinity[i]); err != nil { + if err := cache.AddPod(logger, podsWithAffinity[i]); err != nil { t.Error(err) } } } addPodWithPVC := func(i int) operation { return func(t *testing.T) { - if err := cache.AddPod(podsWithPVC[i]); err != nil { + if err := cache.AddPod(logger, podsWithPVC[i]); err != nil { t.Error(err) } } } removePod := func(i int) operation { return func(t *testing.T) { - if err := cache.RemovePod(pods[i]); err != nil { + if err := cache.RemovePod(logger, pods[i]); err != nil { t.Error(err) } } } removePodWithAffinity := func(i int) operation { return func(t *testing.T) { - if err := cache.RemovePod(podsWithAffinity[i]); err != nil { + if err := cache.RemovePod(logger, podsWithAffinity[i]); err != nil { t.Error(err) } } } removePodWithPVC := func(i int) operation { return func(t *testing.T) { - if err := cache.RemovePod(podsWithPVC[i]); err != nil { + if err := cache.RemovePod(logger, podsWithPVC[i]); err != nil { t.Error(err) } } } updatePod := func(i int) operation { return func(t *testing.T) { - if err := cache.UpdatePod(pods[i], updatedPods[i]); err != nil { + if err := cache.UpdatePod(logger, pods[i], updatedPods[i]); err != nil { t.Error(err) } } } updateSnapshot := func() operation { return func(t *testing.T) { - cache.UpdateSnapshot(snapshot) + cache.UpdateSnapshot(logger, snapshot) if err := compareCacheWithNodeInfoSnapshot(t, cache, snapshot); err != nil { t.Error(err) } @@ -1637,7 +1684,10 @@ func TestSchedulerCache_UpdateSnapshot(t *testing.T) { for _, test := range tests { t.Run(test.name, func(t *testing.T) { - cache = newCache(time.Second, time.Second, nil) + _, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) + defer cancel() + cache = newCache(ctx, time.Second, time.Second) snapshot = NewEmptySnapshot() for _, op := range test.operations { @@ -1671,7 +1721,7 @@ func TestSchedulerCache_UpdateSnapshot(t *testing.T) { } // Always update the snapshot at the end of operations and compare it. - if err := cache.UpdateSnapshot(snapshot); err != nil { + if err := cache.UpdateSnapshot(logger, snapshot); err != nil { t.Error(err) } if err := compareCacheWithNodeInfoSnapshot(t, cache, snapshot); err != nil { @@ -1746,6 +1796,8 @@ func compareCacheWithNodeInfoSnapshot(t *testing.T, cache *cacheImpl, snapshot * } func TestSchedulerCache_updateNodeInfoSnapshotList(t *testing.T) { + logger, _ := ktesting.NewTestContext(t) + // Create a few nodes to be used in tests. var nodes []*v1.Node i := 0 @@ -1769,7 +1821,7 @@ func TestSchedulerCache_updateNodeInfoSnapshotList(t *testing.T) { var snapshot *Snapshot addNode := func(t *testing.T, i int) { - cache.AddNode(nodes[i]) + cache.AddNode(logger, nodes[i]) _, ok := snapshot.nodeInfoMap[nodes[i].Name] if !ok { snapshot.nodeInfoMap[nodes[i].Name] = cache.nodes[nodes[i].Name].info @@ -1777,7 +1829,7 @@ func TestSchedulerCache_updateNodeInfoSnapshotList(t *testing.T) { } updateSnapshot := func(t *testing.T) { - cache.updateNodeInfoSnapshotList(snapshot, true) + cache.updateNodeInfoSnapshotList(logger, snapshot, true) if err := compareCacheWithNodeInfoSnapshot(t, cache, snapshot); err != nil { t.Error(err) } @@ -1867,13 +1919,16 @@ func TestSchedulerCache_updateNodeInfoSnapshotList(t *testing.T) { for _, test := range tests { t.Run(test.name, func(t *testing.T) { - cache = newCache(time.Second, time.Second, nil) + _, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) + defer cancel() + cache = newCache(ctx, time.Second, time.Second) snapshot = NewEmptySnapshot() test.operations(t) // Always update the snapshot at the end of operations and compare it. - cache.updateNodeInfoSnapshotList(snapshot, true) + cache.updateNodeInfoSnapshotList(logger, snapshot, true) if err := compareCacheWithNodeInfoSnapshot(t, cache, snapshot); err != nil { t.Error(err) } @@ -1889,11 +1944,12 @@ func TestSchedulerCache_updateNodeInfoSnapshotList(t *testing.T) { } func BenchmarkUpdate1kNodes30kPods(b *testing.B) { + logger, _ := ktesting.NewTestContext(b) cache := setupCacheOf1kNodes30kPods(b) b.ResetTimer() for n := 0; n < b.N; n++ { cachedNodes := NewEmptySnapshot() - cache.UpdateSnapshot(cachedNodes) + cache.UpdateSnapshot(logger, cachedNodes) } } @@ -1912,12 +1968,13 @@ func BenchmarkExpirePods(b *testing.B) { } func benchmarkExpire(b *testing.B, podNum int) { + logger, _ := ktesting.NewTestContext(b) now := time.Now() for n := 0; n < b.N; n++ { b.StopTimer() cache := setupCacheWithAssumedPods(b, podNum, now) b.StartTimer() - cache.cleanupAssumedPods(now.Add(2 * time.Second)) + cache.cleanupAssumedPods(logger, now.Add(2*time.Second)) } } @@ -1946,14 +2003,17 @@ func makeBasePod(t testingMode, nodeName, objName, cpu, mem, extended string, po } func setupCacheOf1kNodes30kPods(b *testing.B) Cache { - cache := newCache(time.Second, time.Second, nil) + logger, ctx := ktesting.NewTestContext(b) + ctx, cancel := context.WithCancel(ctx) + defer cancel() + cache := newCache(ctx, time.Second, time.Second) for i := 0; i < 1000; i++ { nodeName := fmt.Sprintf("node-%d", i) for j := 0; j < 30; j++ { objName := fmt.Sprintf("%s-pod-%d", nodeName, j) pod := makeBasePod(b, nodeName, objName, "0", "0", "", nil) - if err := cache.AddPod(pod); err != nil { + if err := cache.AddPod(logger, pod); err != nil { b.Fatalf("AddPod failed: %v", err) } } @@ -1962,13 +2022,16 @@ func setupCacheOf1kNodes30kPods(b *testing.B) Cache { } func setupCacheWithAssumedPods(b *testing.B, podNum int, assumedTime time.Time) *cacheImpl { - cache := newCache(time.Second, time.Second, nil) + logger, ctx := ktesting.NewTestContext(b) + ctx, cancel := context.WithCancel(ctx) + defer cancel() + cache := newCache(ctx, time.Second, time.Second) for i := 0; i < podNum; i++ { nodeName := fmt.Sprintf("node-%d", i/10) objName := fmt.Sprintf("%s-pod-%d", nodeName, i%10) pod := makeBasePod(b, nodeName, objName, "0", "0", "", nil) - err := assumeAndFinishBinding(cache, pod, assumedTime) + err := assumeAndFinishBinding(logger, cache, pod, assumedTime) if err != nil { b.Fatalf("assumePod failed: %v", err) } diff --git a/pkg/scheduler/internal/cache/debugger/comparer.go b/pkg/scheduler/internal/cache/debugger/comparer.go index bf8cafb7844..bc7648dce6b 100644 --- a/pkg/scheduler/internal/cache/debugger/comparer.go +++ b/pkg/scheduler/internal/cache/debugger/comparer.go @@ -38,9 +38,9 @@ type CacheComparer struct { } // Compare compares the nodes and pods of NodeLister with Cache.Snapshot. -func (c *CacheComparer) Compare() error { - klog.V(3).InfoS("Cache comparer started") - defer klog.V(3).InfoS("Cache comparer finished") +func (c *CacheComparer) Compare(logger klog.Logger) error { + logger.V(3).Info("Cache comparer started") + defer logger.V(3).Info("Cache comparer finished") nodes, err := c.NodeLister.List(labels.Everything()) if err != nil { @@ -57,11 +57,11 @@ func (c *CacheComparer) Compare() error { pendingPods, _ := c.PodQueue.PendingPods() if missed, redundant := c.CompareNodes(nodes, dump.Nodes); len(missed)+len(redundant) != 0 { - klog.InfoS("Cache mismatch", "missedNodes", missed, "redundantNodes", redundant) + logger.Info("Cache mismatch", "missedNodes", missed, "redundantNodes", redundant) } if missed, redundant := c.ComparePods(pods, pendingPods, dump.Nodes); len(missed)+len(redundant) != 0 { - klog.InfoS("Cache mismatch", "missedPods", missed, "redundantPods", redundant) + logger.Info("Cache mismatch", "missedPods", missed, "redundantPods", redundant) } return nil diff --git a/pkg/scheduler/internal/cache/debugger/debugger.go b/pkg/scheduler/internal/cache/debugger/debugger.go index d8839ec67e8..8a1f80c88b4 100644 --- a/pkg/scheduler/internal/cache/debugger/debugger.go +++ b/pkg/scheduler/internal/cache/debugger/debugger.go @@ -17,10 +17,12 @@ limitations under the License. package debugger import ( + "context" "os" "os/signal" corelisters "k8s.io/client-go/listers/core/v1" + "k8s.io/klog/v2" internalcache "k8s.io/kubernetes/pkg/scheduler/internal/cache" internalqueue "k8s.io/kubernetes/pkg/scheduler/internal/queue" ) @@ -54,7 +56,9 @@ func New( // ListenForSignal starts a goroutine that will trigger the CacheDebugger's // behavior when the process receives SIGINT (Windows) or SIGUSER2 (non-Windows). -func (d *CacheDebugger) ListenForSignal(stopCh <-chan struct{}) { +func (d *CacheDebugger) ListenForSignal(ctx context.Context) { + logger := klog.FromContext(ctx) + stopCh := ctx.Done() ch := make(chan os.Signal, 1) signal.Notify(ch, compareSignal) @@ -64,8 +68,8 @@ func (d *CacheDebugger) ListenForSignal(stopCh <-chan struct{}) { case <-stopCh: return case <-ch: - d.Comparer.Compare() - d.Dumper.DumpAll() + d.Comparer.Compare(logger) + d.Dumper.DumpAll(logger) } } }() diff --git a/pkg/scheduler/internal/cache/debugger/dumper.go b/pkg/scheduler/internal/cache/debugger/dumper.go index d95c234eed7..618be63d989 100644 --- a/pkg/scheduler/internal/cache/debugger/dumper.go +++ b/pkg/scheduler/internal/cache/debugger/dumper.go @@ -36,30 +36,30 @@ type CacheDumper struct { } // DumpAll writes cached nodes and scheduling queue information to the scheduler logs. -func (d *CacheDumper) DumpAll() { - d.dumpNodes() - d.dumpSchedulingQueue() +func (d *CacheDumper) DumpAll(logger klog.Logger) { + d.dumpNodes(logger) + d.dumpSchedulingQueue(logger) } // dumpNodes writes NodeInfo to the scheduler logs. -func (d *CacheDumper) dumpNodes() { +func (d *CacheDumper) dumpNodes(logger klog.Logger) { dump := d.cache.Dump() nodeInfos := make([]string, 0, len(dump.Nodes)) for name, nodeInfo := range dump.Nodes { nodeInfos = append(nodeInfos, d.printNodeInfo(name, nodeInfo)) } // Extra blank line added between node entries for readability. - klog.InfoS("Dump of cached NodeInfo", "nodes", strings.Join(nodeInfos, "\n\n")) + logger.Info("Dump of cached NodeInfo", "nodes", strings.Join(nodeInfos, "\n\n")) } // dumpSchedulingQueue writes pods in the scheduling queue to the scheduler logs. -func (d *CacheDumper) dumpSchedulingQueue() { +func (d *CacheDumper) dumpSchedulingQueue(logger klog.Logger) { pendingPods, s := d.podQueue.PendingPods() var podData strings.Builder for _, p := range pendingPods { podData.WriteString(printPod(p)) } - klog.InfoS("Dump of scheduling queue", "summary", s, "pods", podData.String()) + logger.Info("Dump of scheduling queue", "summary", s, "pods", podData.String()) } // printNodeInfo writes parts of NodeInfo to a string. diff --git a/pkg/scheduler/internal/cache/fake/fake_cache.go b/pkg/scheduler/internal/cache/fake/fake_cache.go index 0bcf7e13ae6..1a39f9cef51 100644 --- a/pkg/scheduler/internal/cache/fake/fake_cache.go +++ b/pkg/scheduler/internal/cache/fake/fake_cache.go @@ -18,6 +18,7 @@ package fake import ( v1 "k8s.io/api/core/v1" + "k8s.io/klog/v2" "k8s.io/kubernetes/pkg/scheduler/framework" internalcache "k8s.io/kubernetes/pkg/scheduler/internal/cache" ) @@ -31,28 +32,28 @@ type Cache struct { } // AssumePod is a fake method for testing. -func (c *Cache) AssumePod(pod *v1.Pod) error { +func (c *Cache) AssumePod(logger klog.Logger, pod *v1.Pod) error { c.AssumeFunc(pod) return nil } // FinishBinding is a fake method for testing. -func (c *Cache) FinishBinding(pod *v1.Pod) error { return nil } +func (c *Cache) FinishBinding(logger klog.Logger, pod *v1.Pod) error { return nil } // ForgetPod is a fake method for testing. -func (c *Cache) ForgetPod(pod *v1.Pod) error { +func (c *Cache) ForgetPod(logger klog.Logger, pod *v1.Pod) error { c.ForgetFunc(pod) return nil } // AddPod is a fake method for testing. -func (c *Cache) AddPod(pod *v1.Pod) error { return nil } +func (c *Cache) AddPod(logger klog.Logger, pod *v1.Pod) error { return nil } // UpdatePod is a fake method for testing. -func (c *Cache) UpdatePod(oldPod, newPod *v1.Pod) error { return nil } +func (c *Cache) UpdatePod(logger klog.Logger, oldPod, newPod *v1.Pod) error { return nil } // RemovePod is a fake method for testing. -func (c *Cache) RemovePod(pod *v1.Pod) error { return nil } +func (c *Cache) RemovePod(logger klog.Logger, pod *v1.Pod) error { return nil } // IsAssumedPod is a fake method for testing. func (c *Cache) IsAssumedPod(pod *v1.Pod) (bool, error) { @@ -65,16 +66,18 @@ func (c *Cache) GetPod(pod *v1.Pod) (*v1.Pod, error) { } // AddNode is a fake method for testing. -func (c *Cache) AddNode(node *v1.Node) *framework.NodeInfo { return nil } +func (c *Cache) AddNode(logger klog.Logger, node *v1.Node) *framework.NodeInfo { return nil } // UpdateNode is a fake method for testing. -func (c *Cache) UpdateNode(oldNode, newNode *v1.Node) *framework.NodeInfo { return nil } +func (c *Cache) UpdateNode(logger klog.Logger, oldNode, newNode *v1.Node) *framework.NodeInfo { + return nil +} // RemoveNode is a fake method for testing. -func (c *Cache) RemoveNode(node *v1.Node) error { return nil } +func (c *Cache) RemoveNode(logger klog.Logger, node *v1.Node) error { return nil } // UpdateSnapshot is a fake method for testing. -func (c *Cache) UpdateSnapshot(snapshot *internalcache.Snapshot) error { +func (c *Cache) UpdateSnapshot(logger klog.Logger, snapshot *internalcache.Snapshot) error { return nil } diff --git a/pkg/scheduler/internal/cache/interface.go b/pkg/scheduler/internal/cache/interface.go index 644c1e92fec..24b7fd49066 100644 --- a/pkg/scheduler/internal/cache/interface.go +++ b/pkg/scheduler/internal/cache/interface.go @@ -19,6 +19,7 @@ package cache import ( v1 "k8s.io/api/core/v1" "k8s.io/apimachinery/pkg/util/sets" + "k8s.io/klog/v2" "k8s.io/kubernetes/pkg/scheduler/framework" ) @@ -68,23 +69,23 @@ type Cache interface { // AssumePod assumes a pod scheduled and aggregates the pod's information into its node. // The implementation also decides the policy to expire pod before being confirmed (receiving Add event). // After expiration, its information would be subtracted. - AssumePod(pod *v1.Pod) error + AssumePod(logger klog.Logger, pod *v1.Pod) error // FinishBinding signals that cache for assumed pod can be expired - FinishBinding(pod *v1.Pod) error + FinishBinding(logger klog.Logger, pod *v1.Pod) error // ForgetPod removes an assumed pod from cache. - ForgetPod(pod *v1.Pod) error + ForgetPod(logger klog.Logger, pod *v1.Pod) error // AddPod either confirms a pod if it's assumed, or adds it back if it's expired. // If added back, the pod's information would be added again. - AddPod(pod *v1.Pod) error + AddPod(logger klog.Logger, pod *v1.Pod) error // UpdatePod removes oldPod's information and adds newPod's information. - UpdatePod(oldPod, newPod *v1.Pod) error + UpdatePod(logger klog.Logger, oldPod, newPod *v1.Pod) error // RemovePod removes a pod. The pod's information would be subtracted from assigned node. - RemovePod(pod *v1.Pod) error + RemovePod(logger klog.Logger, pod *v1.Pod) error // GetPod returns the pod from the cache with the same namespace and the // same name of the specified pod. @@ -95,21 +96,21 @@ type Cache interface { // AddNode adds overall information about node. // It returns a clone of added NodeInfo object. - AddNode(node *v1.Node) *framework.NodeInfo + AddNode(logger klog.Logger, node *v1.Node) *framework.NodeInfo // UpdateNode updates overall information about node. // It returns a clone of updated NodeInfo object. - UpdateNode(oldNode, newNode *v1.Node) *framework.NodeInfo + UpdateNode(logger klog.Logger, oldNode, newNode *v1.Node) *framework.NodeInfo // RemoveNode removes overall information about node. - RemoveNode(node *v1.Node) error + RemoveNode(logger klog.Logger, node *v1.Node) error // UpdateSnapshot updates the passed infoSnapshot to the current contents of Cache. // The node info contains aggregated information of pods scheduled (including assumed to be) // on this node. // The snapshot only includes Nodes that are not deleted at the time this function is called. // nodeinfo.Node() is guaranteed to be not nil for all the nodes in the snapshot. - UpdateSnapshot(nodeSnapshot *Snapshot) error + UpdateSnapshot(logger klog.Logger, nodeSnapshot *Snapshot) error // Dump produces a dump of the current cache. Dump() *Dump diff --git a/pkg/scheduler/internal/cache/node_tree.go b/pkg/scheduler/internal/cache/node_tree.go index 2463e3a95bd..f344f8494fd 100644 --- a/pkg/scheduler/internal/cache/node_tree.go +++ b/pkg/scheduler/internal/cache/node_tree.go @@ -36,24 +36,24 @@ type nodeTree struct { } // newNodeTree creates a NodeTree from nodes. -func newNodeTree(nodes []*v1.Node) *nodeTree { +func newNodeTree(logger klog.Logger, nodes []*v1.Node) *nodeTree { nt := &nodeTree{ tree: make(map[string][]string, len(nodes)), } for _, n := range nodes { - nt.addNode(n) + nt.addNode(logger, n) } return nt } // addNode adds a node and its corresponding zone to the tree. If the zone already exists, the node // is added to the array of nodes in that zone. -func (nt *nodeTree) addNode(n *v1.Node) { +func (nt *nodeTree) addNode(logger klog.Logger, n *v1.Node) { zone := utilnode.GetZoneKey(n) if na, ok := nt.tree[zone]; ok { for _, nodeName := range na { if nodeName == n.Name { - klog.InfoS("Node already exists in the NodeTree", "node", klog.KObj(n)) + logger.Info("Did not add to the NodeTree because it already exists", "node", klog.KObj(n)) return } } @@ -62,12 +62,12 @@ func (nt *nodeTree) addNode(n *v1.Node) { nt.zones = append(nt.zones, zone) nt.tree[zone] = []string{n.Name} } - klog.V(2).InfoS("Added node in listed group to NodeTree", "node", klog.KObj(n), "zone", zone) + logger.V(2).Info("Added node in listed group to NodeTree", "node", klog.KObj(n), "zone", zone) nt.numNodes++ } // removeNode removes a node from the NodeTree. -func (nt *nodeTree) removeNode(n *v1.Node) error { +func (nt *nodeTree) removeNode(logger klog.Logger, n *v1.Node) error { zone := utilnode.GetZoneKey(n) if na, ok := nt.tree[zone]; ok { for i, nodeName := range na { @@ -76,13 +76,13 @@ func (nt *nodeTree) removeNode(n *v1.Node) error { if len(nt.tree[zone]) == 0 { nt.removeZone(zone) } - klog.V(2).InfoS("Removed node in listed group from NodeTree", "node", klog.KObj(n), "zone", zone) + logger.V(2).Info("Removed node in listed group from NodeTree", "node", klog.KObj(n), "zone", zone) nt.numNodes-- return nil } } } - klog.ErrorS(nil, "Node in listed group was not found", "node", klog.KObj(n), "zone", zone) + logger.Error(nil, "Did not remove Node in NodeTree because it was not found", "node", klog.KObj(n), "zone", zone) return fmt.Errorf("node %q in group %q was not found", n.Name, zone) } @@ -99,7 +99,7 @@ func (nt *nodeTree) removeZone(zone string) { } // updateNode updates a node in the NodeTree. -func (nt *nodeTree) updateNode(old, new *v1.Node) { +func (nt *nodeTree) updateNode(logger klog.Logger, old, new *v1.Node) { var oldZone string if old != nil { oldZone = utilnode.GetZoneKey(old) @@ -110,8 +110,8 @@ func (nt *nodeTree) updateNode(old, new *v1.Node) { if oldZone == newZone { return } - nt.removeNode(old) // No error checking. We ignore whether the old node exists or not. - nt.addNode(new) + nt.removeNode(logger, old) // No error checking. We ignore whether the old node exists or not. + nt.addNode(logger, new) } // list returns the list of names of the node. NodeTree iterates over zones and in each zone iterates diff --git a/pkg/scheduler/internal/cache/node_tree_test.go b/pkg/scheduler/internal/cache/node_tree_test.go index ba497066cf7..12f09a6db0b 100644 --- a/pkg/scheduler/internal/cache/node_tree_test.go +++ b/pkg/scheduler/internal/cache/node_tree_test.go @@ -22,6 +22,7 @@ import ( v1 "k8s.io/api/core/v1" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" + "k8s.io/klog/v2/ktesting" ) var allNodes = []*v1.Node{ @@ -204,9 +205,10 @@ func TestNodeTree_AddNode(t *testing.T) { for _, test := range tests { t.Run(test.name, func(t *testing.T) { - nt := newNodeTree(nil) + logger, _ := ktesting.NewTestContext(t) + nt := newNodeTree(logger, nil) for _, n := range test.nodesToAdd { - nt.addNode(n) + nt.addNode(logger, n) } verifyNodeTree(t, nt, test.expectedTree) }) @@ -261,9 +263,10 @@ func TestNodeTree_RemoveNode(t *testing.T) { for _, test := range tests { t.Run(test.name, func(t *testing.T) { - nt := newNodeTree(test.existingNodes) + logger, _ := ktesting.NewTestContext(t) + nt := newNodeTree(logger, test.existingNodes) for _, n := range test.nodesToRemove { - err := nt.removeNode(n) + err := nt.removeNode(logger, n) if test.expectError == (err == nil) { t.Errorf("unexpected returned error value: %v", err) } @@ -337,7 +340,8 @@ func TestNodeTree_UpdateNode(t *testing.T) { for _, test := range tests { t.Run(test.name, func(t *testing.T) { - nt := newNodeTree(test.existingNodes) + logger, _ := ktesting.NewTestContext(t) + nt := newNodeTree(logger, test.existingNodes) var oldNode *v1.Node for _, n := range allNodes { if n.Name == test.nodeToUpdate.Name { @@ -348,7 +352,7 @@ func TestNodeTree_UpdateNode(t *testing.T) { if oldNode == nil { oldNode = &v1.Node{ObjectMeta: metav1.ObjectMeta{Name: "nonexisting-node"}} } - nt.updateNode(oldNode, test.nodeToUpdate) + nt.updateNode(logger, oldNode, test.nodeToUpdate) verifyNodeTree(t, nt, test.expectedTree) }) } @@ -384,7 +388,8 @@ func TestNodeTree_List(t *testing.T) { for _, test := range tests { t.Run(test.name, func(t *testing.T) { - nt := newNodeTree(test.nodesToAdd) + logger, _ := ktesting.NewTestContext(t) + nt := newNodeTree(logger, test.nodesToAdd) output, err := nt.list() if err != nil { @@ -398,7 +403,8 @@ func TestNodeTree_List(t *testing.T) { } func TestNodeTree_List_Exhausted(t *testing.T) { - nt := newNodeTree(allNodes[:9]) + logger, _ := ktesting.NewTestContext(t) + nt := newNodeTree(logger, allNodes[:9]) nt.numNodes++ _, err := nt.list() if err == nil { @@ -453,7 +459,8 @@ func TestNodeTreeMultiOperations(t *testing.T) { for _, test := range tests { t.Run(test.name, func(t *testing.T) { - nt := newNodeTree(nil) + logger, _ := ktesting.NewTestContext(t) + nt := newNodeTree(logger, nil) addIndex := 0 removeIndex := 0 for _, op := range test.operations { @@ -462,14 +469,14 @@ func TestNodeTreeMultiOperations(t *testing.T) { if addIndex >= len(test.nodesToAdd) { t.Error("more add operations than nodesToAdd") } else { - nt.addNode(test.nodesToAdd[addIndex]) + nt.addNode(logger, test.nodesToAdd[addIndex]) addIndex++ } case "remove": if removeIndex >= len(test.nodesToRemove) { t.Error("more remove operations than nodesToRemove") } else { - nt.removeNode(test.nodesToRemove[removeIndex]) + nt.removeNode(logger, test.nodesToRemove[removeIndex]) removeIndex++ } default: diff --git a/pkg/scheduler/internal/queue/scheduling_queue.go b/pkg/scheduler/internal/queue/scheduling_queue.go index 37f8642d01d..dd1df58c128 100644 --- a/pkg/scheduler/internal/queue/scheduling_queue.go +++ b/pkg/scheduler/internal/queue/scheduling_queue.go @@ -91,15 +91,15 @@ type PreEnqueueCheck func(pod *v1.Pod) bool // makes it easy to use those data structures as a SchedulingQueue. type SchedulingQueue interface { framework.PodNominator - Add(pod *v1.Pod) error + Add(logger klog.Logger, pod *v1.Pod) error // Activate moves the given pods to activeQ iff they're in unschedulablePods or backoffQ. // The passed-in pods are originally compiled from plugins that want to activate Pods, // by injecting the pods through a reserved CycleState struct (PodsToActivate). - Activate(pods map[string]*v1.Pod) + Activate(logger klog.Logger, pods map[string]*v1.Pod) // AddUnschedulableIfNotPresent adds an unschedulable pod back to scheduling queue. // The podSchedulingCycle represents the current scheduling cycle number which can be // returned by calling SchedulingCycle(). - AddUnschedulableIfNotPresent(pod *framework.QueuedPodInfo, podSchedulingCycle int64) error + AddUnschedulableIfNotPresent(logger klog.Logger, pod *framework.QueuedPodInfo, podSchedulingCycle int64) error // SchedulingCycle returns the current number of scheduling cycle which is // cached by scheduling queue. Normally, incrementing this number whenever // a pod is popped (e.g. called Pop()) is enough. @@ -107,17 +107,17 @@ type SchedulingQueue interface { // Pop removes the head of the queue and returns it. It blocks if the // queue is empty and waits until a new item is added to the queue. Pop() (*framework.QueuedPodInfo, error) - Update(oldPod, newPod *v1.Pod) error + Update(logger klog.Logger, oldPod, newPod *v1.Pod) error Delete(pod *v1.Pod) error - MoveAllToActiveOrBackoffQueue(event framework.ClusterEvent, preCheck PreEnqueueCheck) - AssignedPodAdded(pod *v1.Pod) - AssignedPodUpdated(pod *v1.Pod) + MoveAllToActiveOrBackoffQueue(logger klog.Logger, event framework.ClusterEvent, preCheck PreEnqueueCheck) + AssignedPodAdded(logger klog.Logger, pod *v1.Pod) + AssignedPodUpdated(logger klog.Logger, pod *v1.Pod) PendingPods() ([]*v1.Pod, string) // Close closes the SchedulingQueue so that the goroutine which is // waiting to pop items can exit gracefully. Close() // Run starts the goroutines managing the queue. - Run() + Run(logger klog.Logger) } // NewSchedulingQueue initializes a priority queue as a new scheduling queue. @@ -330,9 +330,13 @@ func NewPriorityQueue( } // Run starts the goroutine to pump from podBackoffQ to activeQ -func (p *PriorityQueue) Run() { - go wait.Until(p.flushBackoffQCompleted, 1.0*time.Second, p.stop) - go wait.Until(p.flushUnschedulablePodsLeftover, 30*time.Second, p.stop) +func (p *PriorityQueue) Run(logger klog.Logger) { + go wait.Until(func() { + p.flushBackoffQCompleted(logger) + }, 1.0*time.Second, p.stop) + go wait.Until(func() { + p.flushUnschedulablePodsLeftover(logger) + }, 30*time.Second, p.stop) } // runPreEnqueuePlugins iterates PreEnqueue function in each registered PreEnqueuePlugin. @@ -341,6 +345,7 @@ func (p *PriorityQueue) Run() { // Note: we need to associate the failed plugin to `pInfo`, so that the pod can be moved back // to activeQ by related cluster event. func (p *PriorityQueue) runPreEnqueuePlugins(ctx context.Context, pInfo *framework.QueuedPodInfo) bool { + logger := klog.FromContext(ctx) var s *framework.Status pod := pInfo.Pod startTime := time.Now() @@ -357,9 +362,9 @@ func (p *PriorityQueue) runPreEnqueuePlugins(ctx context.Context, pInfo *framewo pInfo.UnschedulablePlugins.Insert(pl.Name()) metrics.UnschedulableReason(pl.Name(), pod.Spec.SchedulerName).Inc() if s.Code() == framework.Error { - klog.ErrorS(s.AsError(), "Unexpected error running PreEnqueue plugin", "pod", klog.KObj(pod), "plugin", pl.Name()) + logger.Error(s.AsError(), "Unexpected error running PreEnqueue plugin", "pod", klog.KObj(pod), "plugin", pl.Name()) } else { - klog.V(5).InfoS("Status after running PreEnqueue plugin", "pod", klog.KObj(pod), "plugin", pl.Name(), "status", s) + logger.Info("Status after running PreEnqueue plugin", "pod", klog.KObj(pod), "plugin", pl.Name(), "status", s) } return false } @@ -379,7 +384,7 @@ func (p *PriorityQueue) runPreEnqueuePlugin(ctx context.Context, pl framework.Pr // addToActiveQ tries to add pod to active queue. It returns 2 parameters: // 1. a boolean flag to indicate whether the pod is added successfully. // 2. an error for the caller to act on. -func (p *PriorityQueue) addToActiveQ(pInfo *framework.QueuedPodInfo) (bool, error) { +func (p *PriorityQueue) addToActiveQ(logger klog.Logger, pInfo *framework.QueuedPodInfo) (bool, error) { pInfo.Gated = !p.runPreEnqueuePlugins(context.Background(), pInfo) if pInfo.Gated { // Add the Pod to unschedulablePods if it's not passing PreEnqueuePlugins. @@ -387,7 +392,7 @@ func (p *PriorityQueue) addToActiveQ(pInfo *framework.QueuedPodInfo) (bool, erro return false, nil } if err := p.activeQ.Add(pInfo); err != nil { - klog.ErrorS(err, "Error adding pod to the active queue", "pod", klog.KObj(pInfo.Pod)) + logger.Error(err, "Error adding pod to the active queue", "pod", klog.KObj(pInfo.Pod)) return false, err } return true, nil @@ -395,39 +400,39 @@ func (p *PriorityQueue) addToActiveQ(pInfo *framework.QueuedPodInfo) (bool, erro // Add adds a pod to the active queue. It should be called only when a new pod // is added so there is no chance the pod is already in active/unschedulable/backoff queues -func (p *PriorityQueue) Add(pod *v1.Pod) error { +func (p *PriorityQueue) Add(logger klog.Logger, pod *v1.Pod) error { p.lock.Lock() defer p.lock.Unlock() pInfo := p.newQueuedPodInfo(pod) gated := pInfo.Gated - if added, err := p.addToActiveQ(pInfo); !added { + if added, err := p.addToActiveQ(logger, pInfo); !added { return err } if p.unschedulablePods.get(pod) != nil { - klog.ErrorS(nil, "Error: pod is already in the unschedulable queue", "pod", klog.KObj(pod)) + logger.Error(nil, "Error: pod is already in the unschedulable queue", "pod", klog.KObj(pod)) p.unschedulablePods.delete(pod, gated) } // Delete pod from backoffQ if it is backing off if err := p.podBackoffQ.Delete(pInfo); err == nil { - klog.ErrorS(nil, "Error: pod is already in the podBackoff queue", "pod", klog.KObj(pod)) + logger.Error(nil, "Error: pod is already in the podBackoff queue", "pod", klog.KObj(pod)) } - klog.V(5).InfoS("Pod moved to an internal scheduling queue", "pod", klog.KObj(pod), "event", PodAdd, "queue", activeQName) + logger.V(5).Info("Pod moved to an internal scheduling queue", "pod", klog.KObj(pod), "event", PodAdd, "queue", activeQName) metrics.SchedulerQueueIncomingPods.WithLabelValues("active", PodAdd).Inc() - p.addNominatedPodUnlocked(pInfo.PodInfo, nil) + p.addNominatedPodUnlocked(logger, pInfo.PodInfo, nil) p.cond.Broadcast() return nil } // Activate moves the given pods to activeQ iff they're in unschedulablePods or backoffQ. -func (p *PriorityQueue) Activate(pods map[string]*v1.Pod) { +func (p *PriorityQueue) Activate(logger klog.Logger, pods map[string]*v1.Pod) { p.lock.Lock() defer p.lock.Unlock() activated := false for _, pod := range pods { - if p.activate(pod) { + if p.activate(logger, pod) { activated = true } } @@ -437,7 +442,7 @@ func (p *PriorityQueue) Activate(pods map[string]*v1.Pod) { } } -func (p *PriorityQueue) activate(pod *v1.Pod) bool { +func (p *PriorityQueue) activate(logger klog.Logger, pod *v1.Pod) bool { // Verify if the pod is present in activeQ. if _, exists, _ := p.activeQ.Get(newQueuedPodInfoForLookup(pod)); exists { // No need to activate if it's already present in activeQ. @@ -448,7 +453,7 @@ func (p *PriorityQueue) activate(pod *v1.Pod) bool { if pInfo = p.unschedulablePods.get(pod); pInfo == nil { // If the pod doesn't belong to unschedulablePods or backoffQ, don't activate it. if obj, exists, _ := p.podBackoffQ.Get(newQueuedPodInfoForLookup(pod)); !exists { - klog.ErrorS(nil, "To-activate pod does not exist in unschedulablePods or backoffQ", "pod", klog.KObj(pod)) + logger.Error(nil, "To-activate pod does not exist in unschedulablePods or backoffQ", "pod", klog.KObj(pod)) return false } else { pInfo = obj.(*framework.QueuedPodInfo) @@ -457,18 +462,18 @@ func (p *PriorityQueue) activate(pod *v1.Pod) bool { if pInfo == nil { // Redundant safe check. We shouldn't reach here. - klog.ErrorS(nil, "Internal error: cannot obtain pInfo") + logger.Error(nil, "Internal error: cannot obtain pInfo") return false } gated := pInfo.Gated - if added, _ := p.addToActiveQ(pInfo); !added { + if added, _ := p.addToActiveQ(logger, pInfo); !added { return false } p.unschedulablePods.delete(pInfo.Pod, gated) p.podBackoffQ.Delete(pInfo) metrics.SchedulerQueueIncomingPods.WithLabelValues("active", ForceActivate).Inc() - p.addNominatedPodUnlocked(pInfo.PodInfo, nil) + p.addNominatedPodUnlocked(logger, pInfo.PodInfo, nil) return true } @@ -493,7 +498,7 @@ func (p *PriorityQueue) SchedulingCycle() int64 { // the queue, unless it is already in the queue. Normally, PriorityQueue puts // unschedulable pods in `unschedulablePods`. But if there has been a recent move // request, then the pod is put in `podBackoffQ`. -func (p *PriorityQueue) AddUnschedulableIfNotPresent(pInfo *framework.QueuedPodInfo, podSchedulingCycle int64) error { +func (p *PriorityQueue) AddUnschedulableIfNotPresent(logger klog.Logger, pInfo *framework.QueuedPodInfo, podSchedulingCycle int64) error { p.lock.Lock() defer p.lock.Unlock() pod := pInfo.Pod @@ -520,21 +525,21 @@ func (p *PriorityQueue) AddUnschedulableIfNotPresent(pInfo *framework.QueuedPodI if err := p.podBackoffQ.Add(pInfo); err != nil { return fmt.Errorf("error adding pod %v to the backoff queue: %v", klog.KObj(pod), err) } - klog.V(5).InfoS("Pod moved to an internal scheduling queue", "pod", klog.KObj(pod), "event", ScheduleAttemptFailure, "queue", backoffQName) + logger.V(5).Info("Pod moved to an internal scheduling queue", "pod", klog.KObj(pod), "event", ScheduleAttemptFailure, "queue", backoffQName) metrics.SchedulerQueueIncomingPods.WithLabelValues("backoff", ScheduleAttemptFailure).Inc() } else { p.unschedulablePods.addOrUpdate(pInfo) - klog.V(5).InfoS("Pod moved to an internal scheduling queue", "pod", klog.KObj(pod), "event", ScheduleAttemptFailure, "queue", unschedulablePods) + logger.V(5).Info("Pod moved to an internal scheduling queue", "pod", klog.KObj(pod), "event", ScheduleAttemptFailure, "queue", unschedulablePods) metrics.SchedulerQueueIncomingPods.WithLabelValues("unschedulable", ScheduleAttemptFailure).Inc() } - p.addNominatedPodUnlocked(pInfo.PodInfo, nil) + p.addNominatedPodUnlocked(logger, pInfo.PodInfo, nil) return nil } // flushBackoffQCompleted Moves all pods from backoffQ which have completed backoff in to activeQ -func (p *PriorityQueue) flushBackoffQCompleted() { +func (p *PriorityQueue) flushBackoffQCompleted(logger klog.Logger) { p.lock.Lock() defer p.lock.Unlock() activated := false @@ -550,11 +555,11 @@ func (p *PriorityQueue) flushBackoffQCompleted() { } _, err := p.podBackoffQ.Pop() if err != nil { - klog.ErrorS(err, "Unable to pop pod from backoff queue despite backoff completion", "pod", klog.KObj(pod)) + logger.Error(err, "Unable to pop pod from backoff queue despite backoff completion", "pod", klog.KObj(pod)) break } - if added, _ := p.addToActiveQ(pInfo); added { - klog.V(5).InfoS("Pod moved to an internal scheduling queue", "pod", klog.KObj(pod), "event", BackoffComplete, "queue", activeQName) + if added, _ := p.addToActiveQ(logger, pInfo); added { + logger.V(5).Info("Pod moved to an internal scheduling queue", "pod", klog.KObj(pod), "event", BackoffComplete, "queue", activeQName) metrics.SchedulerQueueIncomingPods.WithLabelValues("active", BackoffComplete).Inc() activated = true } @@ -567,7 +572,7 @@ func (p *PriorityQueue) flushBackoffQCompleted() { // flushUnschedulablePodsLeftover moves pods which stay in unschedulablePods // longer than podMaxInUnschedulablePodsDuration to backoffQ or activeQ. -func (p *PriorityQueue) flushUnschedulablePodsLeftover() { +func (p *PriorityQueue) flushUnschedulablePodsLeftover(logger klog.Logger) { p.lock.Lock() defer p.lock.Unlock() @@ -581,7 +586,7 @@ func (p *PriorityQueue) flushUnschedulablePodsLeftover() { } if len(podsToMove) > 0 { - p.movePodsToActiveOrBackoffQueue(podsToMove, UnschedulableTimeout) + p.movePodsToActiveOrBackoffQueue(logger, podsToMove, UnschedulableTimeout) } } @@ -629,7 +634,7 @@ func isPodUpdated(oldPod, newPod *v1.Pod) bool { // the item from the unschedulable queue if pod is updated in a way that it may // become schedulable and adds the updated one to the active queue. // If pod is not present in any of the queues, it is added to the active queue. -func (p *PriorityQueue) Update(oldPod, newPod *v1.Pod) error { +func (p *PriorityQueue) Update(logger klog.Logger, oldPod, newPod *v1.Pod) error { p.lock.Lock() defer p.lock.Unlock() @@ -638,14 +643,14 @@ func (p *PriorityQueue) Update(oldPod, newPod *v1.Pod) error { // If the pod is already in the active queue, just update it there. if oldPodInfo, exists, _ := p.activeQ.Get(oldPodInfo); exists { pInfo := updatePod(oldPodInfo, newPod) - p.updateNominatedPodUnlocked(oldPod, pInfo.PodInfo) + p.updateNominatedPodUnlocked(logger, oldPod, pInfo.PodInfo) return p.activeQ.Update(pInfo) } // If the pod is in the backoff queue, update it there. if oldPodInfo, exists, _ := p.podBackoffQ.Get(oldPodInfo); exists { pInfo := updatePod(oldPodInfo, newPod) - p.updateNominatedPodUnlocked(oldPod, pInfo.PodInfo) + p.updateNominatedPodUnlocked(logger, oldPod, pInfo.PodInfo) return p.podBackoffQ.Update(pInfo) } } @@ -653,7 +658,7 @@ func (p *PriorityQueue) Update(oldPod, newPod *v1.Pod) error { // If the pod is in the unschedulable queue, updating it may make it schedulable. if usPodInfo := p.unschedulablePods.get(newPod); usPodInfo != nil { pInfo := updatePod(usPodInfo, newPod) - p.updateNominatedPodUnlocked(oldPod, pInfo.PodInfo) + p.updateNominatedPodUnlocked(logger, oldPod, pInfo.PodInfo) if isPodUpdated(oldPod, newPod) { gated := usPodInfo.Gated if p.isPodBackingoff(usPodInfo) { @@ -661,13 +666,13 @@ func (p *PriorityQueue) Update(oldPod, newPod *v1.Pod) error { return err } p.unschedulablePods.delete(usPodInfo.Pod, gated) - klog.V(5).InfoS("Pod moved to an internal scheduling queue", "pod", klog.KObj(pInfo.Pod), "event", PodUpdate, "queue", backoffQName) + logger.V(5).Info("Pod moved to an internal scheduling queue", "pod", klog.KObj(pInfo.Pod), "event", PodUpdate, "queue", backoffQName) } else { - if added, err := p.addToActiveQ(pInfo); !added { + if added, err := p.addToActiveQ(logger, pInfo); !added { return err } p.unschedulablePods.delete(usPodInfo.Pod, gated) - klog.V(5).InfoS("Pod moved to an internal scheduling queue", "pod", klog.KObj(pInfo.Pod), "event", BackoffComplete, "queue", activeQName) + logger.V(5).Info("Pod moved to an internal scheduling queue", "pod", klog.KObj(pInfo.Pod), "event", BackoffComplete, "queue", activeQName) p.cond.Broadcast() } } else { @@ -679,11 +684,11 @@ func (p *PriorityQueue) Update(oldPod, newPod *v1.Pod) error { } // If pod is not in any of the queues, we put it in the active queue. pInfo := p.newQueuedPodInfo(newPod) - if added, err := p.addToActiveQ(pInfo); !added { + if added, err := p.addToActiveQ(logger, pInfo); !added { return err } - p.addNominatedPodUnlocked(pInfo.PodInfo, nil) - klog.V(5).InfoS("Pod moved to an internal scheduling queue", "pod", klog.KObj(pInfo.Pod), "event", PodUpdate, "queue", activeQName) + p.addNominatedPodUnlocked(logger, pInfo.PodInfo, nil) + logger.V(5).Info("Pod moved to an internal scheduling queue", "pod", klog.KObj(pInfo.Pod), "event", PodUpdate, "queue", activeQName) p.cond.Broadcast() return nil } @@ -707,9 +712,9 @@ func (p *PriorityQueue) Delete(pod *v1.Pod) error { // AssignedPodAdded is called when a bound pod is added. Creation of this pod // may make pending pods with matching affinity terms schedulable. -func (p *PriorityQueue) AssignedPodAdded(pod *v1.Pod) { +func (p *PriorityQueue) AssignedPodAdded(logger klog.Logger, pod *v1.Pod) { p.lock.Lock() - p.movePodsToActiveOrBackoffQueue(p.getUnschedulablePodsWithMatchingAffinityTerm(pod), AssignedPodAdd) + p.movePodsToActiveOrBackoffQueue(logger, p.getUnschedulablePodsWithMatchingAffinityTerm(pod), AssignedPodAdd) p.lock.Unlock() } @@ -729,12 +734,12 @@ func isPodResourcesResizedDown(pod *v1.Pod) bool { // AssignedPodUpdated is called when a bound pod is updated. Change of labels // may make pending pods with matching affinity terms schedulable. -func (p *PriorityQueue) AssignedPodUpdated(pod *v1.Pod) { +func (p *PriorityQueue) AssignedPodUpdated(logger klog.Logger, pod *v1.Pod) { p.lock.Lock() if isPodResourcesResizedDown(pod) { - p.moveAllToActiveOrBackoffQueue(AssignedPodUpdate, nil) + p.moveAllToActiveOrBackoffQueue(logger, AssignedPodUpdate, nil) } else { - p.movePodsToActiveOrBackoffQueue(p.getUnschedulablePodsWithMatchingAffinityTerm(pod), AssignedPodUpdate) + p.movePodsToActiveOrBackoffQueue(logger, p.getUnschedulablePodsWithMatchingAffinityTerm(pod), AssignedPodUpdate) } p.lock.Unlock() } @@ -744,28 +749,28 @@ func (p *PriorityQueue) AssignedPodUpdated(pod *v1.Pod) { // This function adds all pods and then signals the condition variable to ensure that // if Pop() is waiting for an item, it receives the signal after all the pods are in the // queue and the head is the highest priority pod. -func (p *PriorityQueue) moveAllToActiveOrBackoffQueue(event framework.ClusterEvent, preCheck PreEnqueueCheck) { +func (p *PriorityQueue) moveAllToActiveOrBackoffQueue(logger klog.Logger, event framework.ClusterEvent, preCheck PreEnqueueCheck) { unschedulablePods := make([]*framework.QueuedPodInfo, 0, len(p.unschedulablePods.podInfoMap)) for _, pInfo := range p.unschedulablePods.podInfoMap { if preCheck == nil || preCheck(pInfo.Pod) { unschedulablePods = append(unschedulablePods, pInfo) } } - p.movePodsToActiveOrBackoffQueue(unschedulablePods, event) + p.movePodsToActiveOrBackoffQueue(logger, unschedulablePods, event) } // MoveAllToActiveOrBackoffQueue moves all pods from unschedulablePods to activeQ or backoffQ. // This function adds all pods and then signals the condition variable to ensure that // if Pop() is waiting for an item, it receives the signal after all the pods are in the // queue and the head is the highest priority pod. -func (p *PriorityQueue) MoveAllToActiveOrBackoffQueue(event framework.ClusterEvent, preCheck PreEnqueueCheck) { +func (p *PriorityQueue) MoveAllToActiveOrBackoffQueue(logger klog.Logger, event framework.ClusterEvent, preCheck PreEnqueueCheck) { p.lock.Lock() defer p.lock.Unlock() - p.moveAllToActiveOrBackoffQueue(event, preCheck) + p.moveAllToActiveOrBackoffQueue(logger, event, preCheck) } // NOTE: this function assumes lock has been acquired in caller -func (p *PriorityQueue) movePodsToActiveOrBackoffQueue(podInfoList []*framework.QueuedPodInfo, event framework.ClusterEvent) { +func (p *PriorityQueue) movePodsToActiveOrBackoffQueue(logger klog.Logger, podInfoList []*framework.QueuedPodInfo, event framework.ClusterEvent) { activated := false for _, pInfo := range podInfoList { // If the event doesn't help making the Pod schedulable, continue. @@ -778,16 +783,16 @@ func (p *PriorityQueue) movePodsToActiveOrBackoffQueue(podInfoList []*framework. pod := pInfo.Pod if p.isPodBackingoff(pInfo) { if err := p.podBackoffQ.Add(pInfo); err != nil { - klog.ErrorS(err, "Error adding pod to the backoff queue", "pod", klog.KObj(pod)) + logger.Error(err, "Error adding pod to the backoff queue", "pod", klog.KObj(pod)) } else { - klog.V(5).InfoS("Pod moved to an internal scheduling queue", "pod", klog.KObj(pInfo.Pod), "event", event, "queue", backoffQName) + logger.V(5).Info("Pod moved to an internal scheduling queue", "pod", klog.KObj(pInfo.Pod), "event", event, "queue", backoffQName) metrics.SchedulerQueueIncomingPods.WithLabelValues("backoff", event.Label).Inc() p.unschedulablePods.delete(pod, pInfo.Gated) } } else { gated := pInfo.Gated - if added, _ := p.addToActiveQ(pInfo); added { - klog.V(5).InfoS("Pod moved to an internal scheduling queue", "pod", klog.KObj(pInfo.Pod), "event", event, "queue", activeQName) + if added, _ := p.addToActiveQ(logger, pInfo); added { + logger.V(5).Info("Pod moved to an internal scheduling queue", "pod", klog.KObj(pInfo.Pod), "event", event, "queue", activeQName) activated = true metrics.SchedulerQueueIncomingPods.WithLabelValues("active", event.Label).Inc() p.unschedulablePods.delete(pod, gated) @@ -864,9 +869,9 @@ func (npm *nominator) deleteNominatedPodIfExistsUnlocked(pod *v1.Pod) { // This is called during the preemption process after a node is nominated to run // the pod. We update the structure before sending a request to update the pod // object to avoid races with the following scheduling cycles. -func (npm *nominator) AddNominatedPod(pi *framework.PodInfo, nominatingInfo *framework.NominatingInfo) { +func (npm *nominator) AddNominatedPod(logger klog.Logger, pi *framework.PodInfo, nominatingInfo *framework.NominatingInfo) { npm.lock.Lock() - npm.addNominatedPodUnlocked(pi, nominatingInfo) + npm.addNominatedPodUnlocked(logger, pi, nominatingInfo) npm.lock.Unlock() } @@ -1019,7 +1024,7 @@ type nominator struct { lock sync.RWMutex } -func (npm *nominator) addNominatedPodUnlocked(pi *framework.PodInfo, nominatingInfo *framework.NominatingInfo) { +func (npm *nominator) addNominatedPodUnlocked(logger klog.Logger, pi *framework.PodInfo, nominatingInfo *framework.NominatingInfo) { // Always delete the pod if it already exists, to ensure we never store more than // one instance of the pod. npm.delete(pi.Pod) @@ -1038,11 +1043,11 @@ func (npm *nominator) addNominatedPodUnlocked(pi *framework.PodInfo, nominatingI // If the pod was removed or if it was already scheduled, don't nominate it. updatedPod, err := npm.podLister.Pods(pi.Pod.Namespace).Get(pi.Pod.Name) if err != nil { - klog.V(4).InfoS("Pod doesn't exist in podLister, aborted adding it to the nominator", "pod", klog.KObj(pi.Pod)) + logger.V(4).Info("Pod doesn't exist in podLister, aborted adding it to the nominator", "pod", klog.KObj(pi.Pod)) return } if updatedPod.Spec.NodeName != "" { - klog.V(4).InfoS("Pod is already scheduled to a node, aborted adding it to the nominator", "pod", klog.KObj(pi.Pod), "node", updatedPod.Spec.NodeName) + logger.V(4).Info("Pod is already scheduled to a node, aborted adding it to the nominator", "pod", klog.KObj(pi.Pod), "node", updatedPod.Spec.NodeName) return } } @@ -1050,7 +1055,7 @@ func (npm *nominator) addNominatedPodUnlocked(pi *framework.PodInfo, nominatingI npm.nominatedPodToNode[pi.Pod.UID] = nodeName for _, npi := range npm.nominatedPods[nodeName] { if npi.Pod.UID == pi.Pod.UID { - klog.V(4).InfoS("Pod already exists in the nominator", "pod", klog.KObj(npi.Pod)) + logger.V(4).Info("Pod already exists in the nominator", "pod", klog.KObj(npi.Pod)) return } } @@ -1075,13 +1080,13 @@ func (npm *nominator) delete(p *v1.Pod) { } // UpdateNominatedPod updates the with . -func (npm *nominator) UpdateNominatedPod(oldPod *v1.Pod, newPodInfo *framework.PodInfo) { +func (npm *nominator) UpdateNominatedPod(logger klog.Logger, oldPod *v1.Pod, newPodInfo *framework.PodInfo) { npm.lock.Lock() defer npm.lock.Unlock() - npm.updateNominatedPodUnlocked(oldPod, newPodInfo) + npm.updateNominatedPodUnlocked(logger, oldPod, newPodInfo) } -func (npm *nominator) updateNominatedPodUnlocked(oldPod *v1.Pod, newPodInfo *framework.PodInfo) { +func (npm *nominator) updateNominatedPodUnlocked(logger klog.Logger, oldPod *v1.Pod, newPodInfo *framework.PodInfo) { // In some cases, an Update event with no "NominatedNode" present is received right // after a node("NominatedNode") is reserved for this pod in memory. // In this case, we need to keep reserving the NominatedNode when updating the pod pointer. @@ -1102,7 +1107,7 @@ func (npm *nominator) updateNominatedPodUnlocked(oldPod *v1.Pod, newPodInfo *fra // We update irrespective of the nominatedNodeName changed or not, to ensure // that pod pointer is updated. npm.delete(oldPod) - npm.addNominatedPodUnlocked(newPodInfo, nominatingInfo) + npm.addNominatedPodUnlocked(logger, newPodInfo, nominatingInfo) } // NewPodNominator creates a nominator as a backing of framework.PodNominator. @@ -1122,17 +1127,17 @@ func newPodNominator(podLister listersv1.PodLister) *nominator { // MakeNextPodFunc returns a function to retrieve the next pod from a given // scheduling queue -func MakeNextPodFunc(queue SchedulingQueue) func() *framework.QueuedPodInfo { +func MakeNextPodFunc(logger klog.Logger, queue SchedulingQueue) func() *framework.QueuedPodInfo { return func() *framework.QueuedPodInfo { podInfo, err := queue.Pop() if err == nil { - klog.V(4).InfoS("About to try and schedule pod", "pod", klog.KObj(podInfo.Pod)) + logger.V(4).Info("About to try and schedule pod", "pod", klog.KObj(podInfo.Pod)) for plugin := range podInfo.UnschedulablePlugins { metrics.UnschedulableReason(plugin, podInfo.Pod.Spec.SchedulerName).Dec() } return podInfo } - klog.ErrorS(err, "Error while retrieving next pod from scheduling queue") + logger.Error(err, "Error while retrieving next pod from scheduling queue") return nil } } diff --git a/pkg/scheduler/internal/queue/scheduling_queue_test.go b/pkg/scheduler/internal/queue/scheduling_queue_test.go index 40c3a5f9225..da78a8a2410 100644 --- a/pkg/scheduler/internal/queue/scheduling_queue_test.go +++ b/pkg/scheduler/internal/queue/scheduling_queue_test.go @@ -36,6 +36,8 @@ import ( "k8s.io/client-go/informers" "k8s.io/client-go/kubernetes/fake" "k8s.io/component-base/metrics/testutil" + "k8s.io/klog/v2" + "k8s.io/klog/v2/ktesting" podutil "k8s.io/kubernetes/pkg/api/v1/pod" "k8s.io/kubernetes/pkg/scheduler/framework" "k8s.io/kubernetes/pkg/scheduler/framework/plugins/queuesort" @@ -93,16 +95,17 @@ func getUnschedulablePod(p *PriorityQueue, pod *v1.Pod) *v1.Pod { func TestPriorityQueue_Add(t *testing.T) { objs := []runtime.Object{medPriorityPodInfo.Pod, unschedulablePodInfo.Pod, highPriorityPodInfo.Pod} - ctx, cancel := context.WithCancel(context.Background()) + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) defer cancel() q := NewTestQueueWithObjects(ctx, newDefaultQueueSort(), objs) - if err := q.Add(medPriorityPodInfo.Pod); err != nil { + if err := q.Add(logger, medPriorityPodInfo.Pod); err != nil { t.Errorf("add failed: %v", err) } - if err := q.Add(unschedulablePodInfo.Pod); err != nil { + if err := q.Add(logger, unschedulablePodInfo.Pod); err != nil { t.Errorf("add failed: %v", err) } - if err := q.Add(highPriorityPodInfo.Pod); err != nil { + if err := q.Add(logger, highPriorityPodInfo.Pod); err != nil { t.Errorf("add failed: %v", err) } expectedNominatedPods := &nominator{ @@ -138,13 +141,14 @@ func newDefaultQueueSort() framework.LessFunc { func TestPriorityQueue_AddWithReversePriorityLessFunc(t *testing.T) { objs := []runtime.Object{medPriorityPodInfo.Pod, highPriorityPodInfo.Pod} - ctx, cancel := context.WithCancel(context.Background()) + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) defer cancel() q := NewTestQueueWithObjects(ctx, newDefaultQueueSort(), objs) - if err := q.Add(medPriorityPodInfo.Pod); err != nil { + if err := q.Add(logger, medPriorityPodInfo.Pod); err != nil { t.Errorf("add failed: %v", err) } - if err := q.Add(highPriorityPodInfo.Pod); err != nil { + if err := q.Add(logger, highPriorityPodInfo.Pod); err != nil { t.Errorf("add failed: %v", err) } if p, err := q.Pop(); err != nil || p.Pod != highPriorityPodInfo.Pod { @@ -157,12 +161,13 @@ func TestPriorityQueue_AddWithReversePriorityLessFunc(t *testing.T) { func TestPriorityQueue_AddUnschedulableIfNotPresent(t *testing.T) { objs := []runtime.Object{highPriNominatedPodInfo.Pod, unschedulablePodInfo.Pod} - ctx, cancel := context.WithCancel(context.Background()) + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) defer cancel() q := NewTestQueueWithObjects(ctx, newDefaultQueueSort(), objs) - q.Add(highPriNominatedPodInfo.Pod) - q.AddUnschedulableIfNotPresent(newQueuedPodInfoForLookup(highPriNominatedPodInfo.Pod), q.SchedulingCycle()) // Must not add anything. - q.AddUnschedulableIfNotPresent(newQueuedPodInfoForLookup(unschedulablePodInfo.Pod), q.SchedulingCycle()) + q.Add(logger, highPriNominatedPodInfo.Pod) + q.AddUnschedulableIfNotPresent(logger, newQueuedPodInfoForLookup(highPriNominatedPodInfo.Pod), q.SchedulingCycle()) // Must not add anything. + q.AddUnschedulableIfNotPresent(logger, newQueuedPodInfoForLookup(unschedulablePodInfo.Pod), q.SchedulingCycle()) expectedNominatedPods := &nominator{ nominatedPodToNode: map[types.UID]string{ unschedulablePodInfo.Pod.UID: "node1", @@ -191,7 +196,8 @@ func TestPriorityQueue_AddUnschedulableIfNotPresent(t *testing.T) { // Pods in and before current scheduling cycle will be put back to activeQueue // if we were trying to schedule them when we received move request. func TestPriorityQueue_AddUnschedulableIfNotPresent_Backoff(t *testing.T) { - ctx, cancel := context.WithCancel(context.Background()) + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) defer cancel() q := NewTestQueue(ctx, newDefaultQueueSort(), WithClock(testingclock.NewFakeClock(time.Now()))) totalNum := 10 @@ -201,7 +207,7 @@ func TestPriorityQueue_AddUnschedulableIfNotPresent_Backoff(t *testing.T) { p := st.MakePod().Name(fmt.Sprintf("pod%d", i)).Namespace(fmt.Sprintf("ns%d", i)).UID(fmt.Sprintf("upns%d", i)).Priority(priority).Obj() expectedPods = append(expectedPods, *p) // priority is to make pods ordered in the PriorityQueue - q.Add(p) + q.Add(logger, p) } // Pop all pods except for the first one @@ -213,7 +219,7 @@ func TestPriorityQueue_AddUnschedulableIfNotPresent_Backoff(t *testing.T) { } // move all pods to active queue when we were trying to schedule them - q.MoveAllToActiveOrBackoffQueue(TestEvent, nil) + q.MoveAllToActiveOrBackoffQueue(logger, TestEvent, nil) oldCycle := q.SchedulingCycle() firstPod, _ := q.Pop() @@ -234,7 +240,7 @@ func TestPriorityQueue_AddUnschedulableIfNotPresent_Backoff(t *testing.T) { }, } - if err := q.AddUnschedulableIfNotPresent(newQueuedPodInfoForLookup(unschedulablePod), oldCycle); err != nil { + if err := q.AddUnschedulableIfNotPresent(logger, newQueuedPodInfoForLookup(unschedulablePod), oldCycle); err != nil { t.Errorf("Failed to call AddUnschedulableIfNotPresent(%v): %v", unschedulablePod.Name, err) } } @@ -250,7 +256,8 @@ func TestPriorityQueue_AddUnschedulableIfNotPresent_Backoff(t *testing.T) { func TestPriorityQueue_Pop(t *testing.T) { objs := []runtime.Object{medPriorityPodInfo.Pod} - ctx, cancel := context.WithCancel(context.Background()) + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) defer cancel() q := NewTestQueueWithObjects(ctx, newDefaultQueueSort(), objs) wg := sync.WaitGroup{} @@ -264,17 +271,18 @@ func TestPriorityQueue_Pop(t *testing.T) { t.Errorf("Expected medPriorityPodInfo to be present in nomindatePods: %v", q.nominator.nominatedPods["node1"]) } }() - q.Add(medPriorityPodInfo.Pod) + q.Add(logger, medPriorityPodInfo.Pod) wg.Wait() } func TestPriorityQueue_Update(t *testing.T) { objs := []runtime.Object{highPriorityPodInfo.Pod, unschedulablePodInfo.Pod, medPriorityPodInfo.Pod} c := testingclock.NewFakeClock(time.Now()) - ctx, cancel := context.WithCancel(context.Background()) + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) defer cancel() q := NewTestQueueWithObjects(ctx, newDefaultQueueSort(), objs, WithClock(c)) - q.Update(nil, highPriorityPodInfo.Pod) + q.Update(logger, nil, highPriorityPodInfo.Pod) if _, exists, _ := q.activeQ.Get(newQueuedPodInfoForLookup(highPriorityPodInfo.Pod)); !exists { t.Errorf("Expected %v to be added to activeQ.", highPriorityPodInfo.Pod.Name) } @@ -282,7 +290,7 @@ func TestPriorityQueue_Update(t *testing.T) { t.Errorf("Expected nomindatePods to be empty: %v", q.nominator) } // Update highPriorityPodInfo and add a nominatedNodeName to it. - q.Update(highPriorityPodInfo.Pod, highPriNominatedPodInfo.Pod) + q.Update(logger, highPriorityPodInfo.Pod, highPriNominatedPodInfo.Pod) if q.activeQ.Len() != 1 { t.Error("Expected only one item in activeQ.") } @@ -291,12 +299,12 @@ func TestPriorityQueue_Update(t *testing.T) { } // Updating an unschedulable pod which is not in any of the two queues, should // add the pod to activeQ. - q.Update(unschedulablePodInfo.Pod, unschedulablePodInfo.Pod) + q.Update(logger, unschedulablePodInfo.Pod, unschedulablePodInfo.Pod) if _, exists, _ := q.activeQ.Get(newQueuedPodInfoForLookup(unschedulablePodInfo.Pod)); !exists { t.Errorf("Expected %v to be added to activeQ.", unschedulablePodInfo.Pod.Name) } // Updating a pod that is already in activeQ, should not change it. - q.Update(unschedulablePodInfo.Pod, unschedulablePodInfo.Pod) + q.Update(logger, unschedulablePodInfo.Pod, unschedulablePodInfo.Pod) if len(q.unschedulablePods.podInfoMap) != 0 { t.Error("Expected unschedulablePods to be empty.") } @@ -313,7 +321,7 @@ func TestPriorityQueue_Update(t *testing.T) { if err := q.podBackoffQ.Add(podInfo); err != nil { t.Errorf("adding pod to backoff queue error: %v", err) } - q.Update(podInfo.Pod, podInfo.Pod) + q.Update(logger, podInfo.Pod, podInfo.Pod) rawPodInfo, err := q.podBackoffQ.Pop() podGotFromBackoffQ := rawPodInfo.(*framework.QueuedPodInfo).Pod if err != nil || podGotFromBackoffQ != medPriorityPodInfo.Pod { @@ -322,13 +330,13 @@ func TestPriorityQueue_Update(t *testing.T) { // updating a pod which is in unschedulable queue, and it is still backing off, // we will move it to backoff queue - q.AddUnschedulableIfNotPresent(q.newQueuedPodInfo(medPriorityPodInfo.Pod), q.SchedulingCycle()) + q.AddUnschedulableIfNotPresent(logger, q.newQueuedPodInfo(medPriorityPodInfo.Pod), q.SchedulingCycle()) if len(q.unschedulablePods.podInfoMap) != 1 { t.Error("Expected unschedulablePods to be 1.") } updatedPod := medPriorityPodInfo.Pod.DeepCopy() updatedPod.Annotations["foo"] = "test" - q.Update(medPriorityPodInfo.Pod, updatedPod) + q.Update(logger, medPriorityPodInfo.Pod, updatedPod) rawPodInfo, err = q.podBackoffQ.Pop() podGotFromBackoffQ = rawPodInfo.(*framework.QueuedPodInfo).Pod if err != nil || podGotFromBackoffQ != updatedPod { @@ -337,7 +345,7 @@ func TestPriorityQueue_Update(t *testing.T) { // updating a pod which is in unschedulable queue, and it is not backing off, // we will move it to active queue - q.AddUnschedulableIfNotPresent(q.newQueuedPodInfo(medPriorityPodInfo.Pod), q.SchedulingCycle()) + q.AddUnschedulableIfNotPresent(logger, q.newQueuedPodInfo(medPriorityPodInfo.Pod), q.SchedulingCycle()) if len(q.unschedulablePods.podInfoMap) != 1 { t.Error("Expected unschedulablePods to be 1.") } @@ -346,7 +354,7 @@ func TestPriorityQueue_Update(t *testing.T) { // Move clock by podInitialBackoffDuration, so that pods in the unschedulablePods would pass the backing off, // and the pods will be moved into activeQ. c.Step(q.podInitialBackoffDuration) - q.Update(medPriorityPodInfo.Pod, updatedPod) + q.Update(logger, medPriorityPodInfo.Pod, updatedPod) if p, err := q.Pop(); err != nil || p.Pod != updatedPod { t.Errorf("Expected: %v after Pop, but got: %v", updatedPod.Name, p.Pod.Name) } @@ -354,11 +362,12 @@ func TestPriorityQueue_Update(t *testing.T) { func TestPriorityQueue_Delete(t *testing.T) { objs := []runtime.Object{highPriorityPodInfo.Pod, unschedulablePodInfo.Pod} - ctx, cancel := context.WithCancel(context.Background()) + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) defer cancel() q := NewTestQueueWithObjects(ctx, newDefaultQueueSort(), objs) - q.Update(highPriorityPodInfo.Pod, highPriNominatedPodInfo.Pod) - q.Add(unschedulablePodInfo.Pod) + q.Update(logger, highPriorityPodInfo.Pod, highPriNominatedPodInfo.Pod) + q.Add(logger, unschedulablePodInfo.Pod) if err := q.Delete(highPriNominatedPodInfo.Pod); err != nil { t.Errorf("delete failed: %v", err) } @@ -416,7 +425,8 @@ func TestPriorityQueue_Activate(t *testing.T) { for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { var objs []runtime.Object - ctx, cancel := context.WithCancel(context.Background()) + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) defer cancel() q := NewTestQueueWithObjects(ctx, newDefaultQueueSort(), objs) @@ -434,7 +444,7 @@ func TestPriorityQueue_Activate(t *testing.T) { } // Activate specific pod according to the table - q.Activate(map[string]*v1.Pod{"test_pod": tt.qPodInfoToActivate.PodInfo.Pod}) + q.Activate(logger, map[string]*v1.Pod{"test_pod": tt.qPodInfoToActivate.PodInfo.Pod}) // Check the result after activation by the length of activeQ if wantLen := len(tt.want); q.activeQ.Len() != wantLen { @@ -516,12 +526,13 @@ func TestPriorityQueue_addToActiveQ(t *testing.T) { for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { ctx, cancel := context.WithCancel(context.Background()) + logger := klog.FromContext(ctx) defer cancel() m := map[string][]framework.PreEnqueuePlugin{"": tt.plugins} q := NewTestQueueWithObjects(ctx, newDefaultQueueSort(), []runtime.Object{tt.pod}, WithPreEnqueuePluginMap(m), WithPodInitialBackoffDuration(time.Second*30), WithPodMaxBackoffDuration(time.Second*60)) - got, _ := q.addToActiveQ(q.newQueuedPodInfo(tt.pod)) + got, _ := q.addToActiveQ(logger, q.newQueuedPodInfo(tt.pod)) if got != tt.wantSuccess { t.Errorf("Unexpected result: want %v, but got %v", tt.wantSuccess, got) } @@ -532,7 +543,7 @@ func TestPriorityQueue_addToActiveQ(t *testing.T) { // Simulate an update event. clone := tt.pod.DeepCopy() metav1.SetMetaDataAnnotation(&clone.ObjectMeta, "foo", "") - q.Update(tt.pod, clone) + q.Update(logger, tt.pod, clone) // Ensure the pod is still located in unschedulablePods. if tt.wantUnschedulablePods != len(q.unschedulablePods.podInfoMap) { t.Errorf("Unexpected unschedulablePods: want %v, but got %v", tt.wantUnschedulablePods, len(q.unschedulablePods.podInfoMap)) @@ -595,6 +606,7 @@ func BenchmarkMoveAllToActiveOrBackoffQueue(b *testing.B) { for _, tt := range tests { for _, podsInUnschedulablePods := range []int{1000, 5000} { b.Run(fmt.Sprintf("%v-%v", tt.name, podsInUnschedulablePods), func(b *testing.B) { + logger, _ := ktesting.NewTestContext(b) for i := 0; i < b.N; i++ { b.StopTimer() c := testingclock.NewFakeClock(time.Now()) @@ -640,15 +652,15 @@ func BenchmarkMoveAllToActiveOrBackoffQueue(b *testing.B) { // Random case. podInfo = q.newQueuedPodInfo(p, plugins[j%len(plugins)]) } - q.AddUnschedulableIfNotPresent(podInfo, q.SchedulingCycle()) + q.AddUnschedulableIfNotPresent(logger, podInfo, q.SchedulingCycle()) } b.StartTimer() if tt.moveEvent.Resource != "" { - q.MoveAllToActiveOrBackoffQueue(tt.moveEvent, nil) + q.MoveAllToActiveOrBackoffQueue(logger, tt.moveEvent, nil) } else { // Random case. - q.MoveAllToActiveOrBackoffQueue(events[i%len(events)], nil) + q.MoveAllToActiveOrBackoffQueue(logger, events[i%len(events)], nil) } } }) @@ -661,22 +673,23 @@ func TestPriorityQueue_MoveAllToActiveOrBackoffQueue(t *testing.T) { m := map[framework.ClusterEvent]sets.Set[string]{ {Resource: framework.Node, ActionType: framework.Add}: sets.New("fooPlugin"), } - ctx, cancel := context.WithCancel(context.Background()) + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) defer cancel() q := NewTestQueue(ctx, newDefaultQueueSort(), WithClock(c), WithClusterEventMap(m)) - q.Add(medPriorityPodInfo.Pod) - q.AddUnschedulableIfNotPresent(q.newQueuedPodInfo(unschedulablePodInfo.Pod, "fooPlugin"), q.SchedulingCycle()) - q.AddUnschedulableIfNotPresent(q.newQueuedPodInfo(highPriorityPodInfo.Pod, "fooPlugin"), q.SchedulingCycle()) + q.Add(logger, medPriorityPodInfo.Pod) + q.AddUnschedulableIfNotPresent(logger, q.newQueuedPodInfo(unschedulablePodInfo.Pod, "fooPlugin"), q.SchedulingCycle()) + q.AddUnschedulableIfNotPresent(logger, q.newQueuedPodInfo(highPriorityPodInfo.Pod, "fooPlugin"), q.SchedulingCycle()) // Construct a Pod, but don't associate its scheduler failure to any plugin hpp1 := highPriorityPodInfo.Pod.DeepCopy() hpp1.Name = "hpp1" - q.AddUnschedulableIfNotPresent(q.newQueuedPodInfo(hpp1), q.SchedulingCycle()) + q.AddUnschedulableIfNotPresent(logger, q.newQueuedPodInfo(hpp1), q.SchedulingCycle()) // Construct another Pod, and associate its scheduler failure to plugin "barPlugin". hpp2 := highPriorityPodInfo.Pod.DeepCopy() hpp2.Name = "hpp2" - q.AddUnschedulableIfNotPresent(q.newQueuedPodInfo(hpp2, "barPlugin"), q.SchedulingCycle()) + q.AddUnschedulableIfNotPresent(logger, q.newQueuedPodInfo(hpp2, "barPlugin"), q.SchedulingCycle()) // Pods is still backing off, move the pod into backoffQ. - q.MoveAllToActiveOrBackoffQueue(NodeAdd, nil) + q.MoveAllToActiveOrBackoffQueue(logger, NodeAdd, nil) if q.activeQ.Len() != 1 { t.Errorf("Expected 1 item to be in activeQ, but got: %v", q.activeQ.Len()) } @@ -691,9 +704,9 @@ func TestPriorityQueue_MoveAllToActiveOrBackoffQueue(t *testing.T) { } q.schedulingCycle++ - q.AddUnschedulableIfNotPresent(q.newQueuedPodInfo(unschedulablePodInfo.Pod, "fooPlugin"), q.SchedulingCycle()) - q.AddUnschedulableIfNotPresent(q.newQueuedPodInfo(highPriorityPodInfo.Pod, "fooPlugin"), q.SchedulingCycle()) - q.AddUnschedulableIfNotPresent(q.newQueuedPodInfo(hpp1), q.SchedulingCycle()) + q.AddUnschedulableIfNotPresent(logger, q.newQueuedPodInfo(unschedulablePodInfo.Pod, "fooPlugin"), q.SchedulingCycle()) + q.AddUnschedulableIfNotPresent(logger, q.newQueuedPodInfo(highPriorityPodInfo.Pod, "fooPlugin"), q.SchedulingCycle()) + q.AddUnschedulableIfNotPresent(logger, q.newQueuedPodInfo(hpp1), q.SchedulingCycle()) for _, pod := range []*v1.Pod{unschedulablePodInfo.Pod, highPriorityPodInfo.Pod, hpp1, hpp2} { if q.unschedulablePods.get(pod) == nil { t.Errorf("Expected %v in the unschedulablePods", pod.Name) @@ -702,7 +715,7 @@ func TestPriorityQueue_MoveAllToActiveOrBackoffQueue(t *testing.T) { // Move clock by podInitialBackoffDuration, so that pods in the unschedulablePods would pass the backing off, // and the pods will be moved into activeQ. c.Step(q.podInitialBackoffDuration) - q.MoveAllToActiveOrBackoffQueue(NodeAdd, nil) + q.MoveAllToActiveOrBackoffQueue(logger, NodeAdd, nil) // hpp2 won't be moved regardless of its backoff timer. if q.activeQ.Len() != 4 { t.Errorf("Expected 4 items to be in activeQ, but got: %v", q.activeQ.Len()) @@ -716,24 +729,26 @@ func TestPriorityQueue_MoveAllToActiveOrBackoffQueue(t *testing.T) { // when a pod with pod affinity is in unschedulablePods and another pod with a // matching label is added, the unschedulable pod is moved to activeQ. func TestPriorityQueue_AssignedPodAdded(t *testing.T) { + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) + defer cancel() + affinityPod := st.MakePod().Name("afp").Namespace("ns1").UID("upns1").Annotation("annot2", "val2").Priority(mediumPriority).NominatedNodeName("node1").PodAffinityExists("service", "region", st.PodAffinityWithRequiredReq).Obj() labelPod := st.MakePod().Name("lbp").Namespace(affinityPod.Namespace).Label("service", "securityscan").Node("node1").Obj() c := testingclock.NewFakeClock(time.Now()) m := map[framework.ClusterEvent]sets.Set[string]{AssignedPodAdd: sets.New("fakePlugin")} - ctx, cancel := context.WithCancel(context.Background()) - defer cancel() q := NewTestQueue(ctx, newDefaultQueueSort(), WithClock(c), WithClusterEventMap(m)) - q.Add(medPriorityPodInfo.Pod) + q.Add(logger, medPriorityPodInfo.Pod) // Add a couple of pods to the unschedulablePods. - q.AddUnschedulableIfNotPresent(q.newQueuedPodInfo(unschedulablePodInfo.Pod, "fakePlugin"), q.SchedulingCycle()) - q.AddUnschedulableIfNotPresent(q.newQueuedPodInfo(affinityPod, "fakePlugin"), q.SchedulingCycle()) + q.AddUnschedulableIfNotPresent(logger, q.newQueuedPodInfo(unschedulablePodInfo.Pod, "fakePlugin"), q.SchedulingCycle()) + q.AddUnschedulableIfNotPresent(logger, q.newQueuedPodInfo(affinityPod, "fakePlugin"), q.SchedulingCycle()) // Move clock to make the unschedulable pods complete backoff. c.Step(DefaultPodInitialBackoffDuration + time.Second) // Simulate addition of an assigned pod. The pod has matching labels for // affinityPod. So, affinityPod should go to activeQ. - q.AssignedPodAdded(labelPod) + q.AssignedPodAdded(logger, labelPod) if getUnschedulablePod(q, affinityPod) != nil { t.Error("affinityPod is still in the unschedulablePods.") } @@ -748,12 +763,13 @@ func TestPriorityQueue_AssignedPodAdded(t *testing.T) { func TestPriorityQueue_NominatedPodsForNode(t *testing.T) { objs := []runtime.Object{medPriorityPodInfo.Pod, unschedulablePodInfo.Pod, highPriorityPodInfo.Pod} - ctx, cancel := context.WithCancel(context.Background()) + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) defer cancel() q := NewTestQueueWithObjects(ctx, newDefaultQueueSort(), objs) - q.Add(medPriorityPodInfo.Pod) - q.Add(unschedulablePodInfo.Pod) - q.Add(highPriorityPodInfo.Pod) + q.Add(logger, medPriorityPodInfo.Pod) + q.Add(logger, unschedulablePodInfo.Pod) + q.Add(logger, highPriorityPodInfo.Pod) if p, err := q.Pop(); err != nil || p.Pod != highPriorityPodInfo.Pod { t.Errorf("Expected: %v after Pop, but got: %v", highPriorityPodInfo.Pod.Name, p.Pod.Name) } @@ -798,6 +814,7 @@ func TestPriorityQueue_NominatedPodDeleted(t *testing.T) { for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { + logger, _ := ktesting.NewTestContext(t) cs := fake.NewSimpleClientset(tt.podInfo.Pod) informerFactory := informers.NewSharedInformerFactory(cs, 0) podLister := informerFactory.Core().V1().Pods().Lister() @@ -814,7 +831,7 @@ func TestPriorityQueue_NominatedPodDeleted(t *testing.T) { informerFactory.Core().V1().Pods().Informer().GetStore().Delete(tt.podInfo.Pod) } - q.AddNominatedPod(tt.podInfo, nil) + q.AddNominatedPod(logger, tt.podInfo, nil) if got := len(q.NominatedPodsForNode(tt.podInfo.Pod.Status.NominatedNodeName)) == 1; got != tt.want { t.Errorf("Want %v, but got %v", tt.want, got) @@ -832,12 +849,13 @@ func TestPriorityQueue_PendingPods(t *testing.T) { return pendingSet } - ctx, cancel := context.WithCancel(context.Background()) + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) defer cancel() q := NewTestQueue(ctx, newDefaultQueueSort()) - q.Add(medPriorityPodInfo.Pod) - q.AddUnschedulableIfNotPresent(q.newQueuedPodInfo(unschedulablePodInfo.Pod), q.SchedulingCycle()) - q.AddUnschedulableIfNotPresent(q.newQueuedPodInfo(highPriorityPodInfo.Pod), q.SchedulingCycle()) + q.Add(logger, medPriorityPodInfo.Pod) + q.AddUnschedulableIfNotPresent(logger, q.newQueuedPodInfo(unschedulablePodInfo.Pod), q.SchedulingCycle()) + q.AddUnschedulableIfNotPresent(logger, q.newQueuedPodInfo(highPriorityPodInfo.Pod), q.SchedulingCycle()) expectedSet := makeSet([]*v1.Pod{medPriorityPodInfo.Pod, unschedulablePodInfo.Pod, highPriorityPodInfo.Pod}) gotPods, gotSummary := q.PendingPods() @@ -848,7 +866,7 @@ func TestPriorityQueue_PendingPods(t *testing.T) { t.Errorf("Unexpected pending pods summary: want %v, but got %v.", wantSummary, gotSummary) } // Move all to active queue. We should still see the same set of pods. - q.MoveAllToActiveOrBackoffQueue(TestEvent, nil) + q.MoveAllToActiveOrBackoffQueue(logger, TestEvent, nil) gotPods, gotSummary = q.PendingPods() if !reflect.DeepEqual(expectedSet, makeSet(gotPods)) { t.Error("Unexpected list of pending Pods.") @@ -859,19 +877,20 @@ func TestPriorityQueue_PendingPods(t *testing.T) { } func TestPriorityQueue_UpdateNominatedPodForNode(t *testing.T) { - objs := []runtime.Object{medPriorityPodInfo.Pod, unschedulablePodInfo.Pod, highPriorityPodInfo.Pod, scheduledPodInfo.Pod} - ctx, cancel := context.WithCancel(context.Background()) + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) defer cancel() + objs := []runtime.Object{medPriorityPodInfo.Pod, unschedulablePodInfo.Pod, highPriorityPodInfo.Pod, scheduledPodInfo.Pod} q := NewTestQueueWithObjects(ctx, newDefaultQueueSort(), objs) - if err := q.Add(medPriorityPodInfo.Pod); err != nil { + if err := q.Add(logger, medPriorityPodInfo.Pod); err != nil { t.Errorf("add failed: %v", err) } // Update unschedulablePodInfo on a different node than specified in the pod. - q.AddNominatedPod(mustNewTestPodInfo(t, unschedulablePodInfo.Pod), + q.AddNominatedPod(logger, mustNewTestPodInfo(t, unschedulablePodInfo.Pod), &framework.NominatingInfo{NominatingMode: framework.ModeOverride, NominatedNodeName: "node5"}) // Update nominated node name of a pod on a node that is not specified in the pod object. - q.AddNominatedPod(mustNewTestPodInfo(t, highPriorityPodInfo.Pod), + q.AddNominatedPod(logger, mustNewTestPodInfo(t, highPriorityPodInfo.Pod), &framework.NominatingInfo{NominatingMode: framework.ModeOverride, NominatedNodeName: "node2"}) expectedNominatedPods := &nominator{ nominatedPodToNode: map[types.UID]string{ @@ -897,7 +916,7 @@ func TestPriorityQueue_UpdateNominatedPodForNode(t *testing.T) { } // Update one of the nominated pods that doesn't have nominatedNodeName in the // pod object. It should be updated correctly. - q.AddNominatedPod(highPriorityPodInfo, &framework.NominatingInfo{NominatingMode: framework.ModeOverride, NominatedNodeName: "node4"}) + q.AddNominatedPod(logger, highPriorityPodInfo, &framework.NominatingInfo{NominatingMode: framework.ModeOverride, NominatedNodeName: "node4"}) expectedNominatedPods = &nominator{ nominatedPodToNode: map[types.UID]string{ medPriorityPodInfo.Pod.UID: "node1", @@ -916,7 +935,7 @@ func TestPriorityQueue_UpdateNominatedPodForNode(t *testing.T) { // Attempt to nominate a pod that was deleted from the informer cache. // Nothing should change. - q.AddNominatedPod(nonExistentPodInfo, &framework.NominatingInfo{NominatingMode: framework.ModeOverride, NominatedNodeName: "node1"}) + q.AddNominatedPod(logger, nonExistentPodInfo, &framework.NominatingInfo{NominatingMode: framework.ModeOverride, NominatedNodeName: "node1"}) if diff := cmp.Diff(q.nominator, expectedNominatedPods, nominatorCmpOpts...); diff != "" { t.Errorf("Unexpected diff after nominating a deleted pod (-want, +got):\n%s", diff) } @@ -924,7 +943,7 @@ func TestPriorityQueue_UpdateNominatedPodForNode(t *testing.T) { // Nothing should change. scheduledPodCopy := scheduledPodInfo.Pod.DeepCopy() scheduledPodInfo.Pod.Spec.NodeName = "" - q.AddNominatedPod(mustNewTestPodInfo(t, scheduledPodCopy), &framework.NominatingInfo{NominatingMode: framework.ModeOverride, NominatedNodeName: "node1"}) + q.AddNominatedPod(logger, mustNewTestPodInfo(t, scheduledPodCopy), &framework.NominatingInfo{NominatingMode: framework.ModeOverride, NominatedNodeName: "node1"}) if diff := cmp.Diff(q.nominator, expectedNominatedPods, nominatorCmpOpts...); diff != "" { t.Errorf("Unexpected diff after nominating a scheduled pod (-want, +got):\n%s", diff) } @@ -1104,13 +1123,14 @@ func TestSchedulingQueue_Close(t *testing.T) { // are frequent events that move pods to the active queue. func TestRecentlyTriedPodsGoBack(t *testing.T) { c := testingclock.NewFakeClock(time.Now()) - ctx, cancel := context.WithCancel(context.Background()) + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) defer cancel() q := NewTestQueue(ctx, newDefaultQueueSort(), WithClock(c)) // Add a few pods to priority queue. for i := 0; i < 5; i++ { p := st.MakePod().Name(fmt.Sprintf("test-pod-%v", i)).Namespace("ns1").UID(fmt.Sprintf("tp00%v", i)).Priority(highPriority).Node("node1").NominatedNodeName("node1").Obj() - q.Add(p) + q.Add(logger, p) } c.Step(time.Microsecond) // Simulate a pod being popped by the scheduler, determined unschedulable, and @@ -1128,10 +1148,10 @@ func TestRecentlyTriedPodsGoBack(t *testing.T) { LastProbeTime: metav1.Now(), }) // Put in the unschedulable queue. - q.AddUnschedulableIfNotPresent(p1, q.SchedulingCycle()) + q.AddUnschedulableIfNotPresent(logger, p1, q.SchedulingCycle()) c.Step(DefaultPodInitialBackoffDuration) // Move all unschedulable pods to the active queue. - q.MoveAllToActiveOrBackoffQueue(UnschedulableTimeout, nil) + q.MoveAllToActiveOrBackoffQueue(logger, UnschedulableTimeout, nil) // Simulation is over. Now let's pop all pods. The pod popped first should be // the last one we pop here. for i := 0; i < 5; i++ { @@ -1151,7 +1171,8 @@ func TestRecentlyTriedPodsGoBack(t *testing.T) { // are frequent events that move pods to the active queue. func TestPodFailedSchedulingMultipleTimesDoesNotBlockNewerPod(t *testing.T) { c := testingclock.NewFakeClock(time.Now()) - ctx, cancel := context.WithCancel(context.Background()) + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) defer cancel() q := NewTestQueue(ctx, newDefaultQueueSort(), WithClock(c)) @@ -1169,11 +1190,11 @@ func TestPodFailedSchedulingMultipleTimesDoesNotBlockNewerPod(t *testing.T) { }) // Put in the unschedulable queue - q.AddUnschedulableIfNotPresent(newQueuedPodInfoForLookup(unschedulablePod), q.SchedulingCycle()) + q.AddUnschedulableIfNotPresent(logger, newQueuedPodInfoForLookup(unschedulablePod), q.SchedulingCycle()) // Move clock to make the unschedulable pods complete backoff. c.Step(DefaultPodInitialBackoffDuration + time.Second) // Move all unschedulable pods to the active queue. - q.MoveAllToActiveOrBackoffQueue(UnschedulableTimeout, nil) + q.MoveAllToActiveOrBackoffQueue(logger, UnschedulableTimeout, nil) // Simulate a pod being popped by the scheduler, // At this time, unschedulable pod should be popped. @@ -1188,7 +1209,7 @@ func TestPodFailedSchedulingMultipleTimesDoesNotBlockNewerPod(t *testing.T) { // Assume newer pod was added just after unschedulable pod // being popped and before being pushed back to the queue. newerPod := st.MakePod().Name("test-newer-pod").Namespace("ns1").UID("tp002").CreationTimestamp(metav1.Now()).Priority(highPriority).NominatedNodeName("node1").Obj() - q.Add(newerPod) + q.Add(logger, newerPod) // And then unschedulablePodInfo was determined as unschedulable AGAIN. podutil.UpdatePodCondition(&unschedulablePod.Status, &v1.PodCondition{ @@ -1199,11 +1220,11 @@ func TestPodFailedSchedulingMultipleTimesDoesNotBlockNewerPod(t *testing.T) { }) // And then, put unschedulable pod to the unschedulable queue - q.AddUnschedulableIfNotPresent(newQueuedPodInfoForLookup(unschedulablePod), q.SchedulingCycle()) + q.AddUnschedulableIfNotPresent(logger, newQueuedPodInfoForLookup(unschedulablePod), q.SchedulingCycle()) // Move clock to make the unschedulable pods complete backoff. c.Step(DefaultPodInitialBackoffDuration + time.Second) // Move all unschedulable pods to the active queue. - q.MoveAllToActiveOrBackoffQueue(UnschedulableTimeout, nil) + q.MoveAllToActiveOrBackoffQueue(logger, UnschedulableTimeout, nil) // At this time, newerPod should be popped // because it is the oldest tried pod. @@ -1219,14 +1240,15 @@ func TestPodFailedSchedulingMultipleTimesDoesNotBlockNewerPod(t *testing.T) { // TestHighPriorityBackoff tests that a high priority pod does not block // other pods if it is unschedulable func TestHighPriorityBackoff(t *testing.T) { - ctx, cancel := context.WithCancel(context.Background()) + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) defer cancel() q := NewTestQueue(ctx, newDefaultQueueSort()) midPod := st.MakePod().Name("test-midpod").Namespace("ns1").UID("tp-mid").Priority(midPriority).NominatedNodeName("node1").Obj() highPod := st.MakePod().Name("test-highpod").Namespace("ns1").UID("tp-high").Priority(highPriority).NominatedNodeName("node1").Obj() - q.Add(midPod) - q.Add(highPod) + q.Add(logger, midPod) + q.Add(logger, highPod) // Simulate a pod being popped by the scheduler, determined unschedulable, and // then moved back to the active queue. p, err := q.Pop() @@ -1244,9 +1266,9 @@ func TestHighPriorityBackoff(t *testing.T) { Message: "fake scheduling failure", }) // Put in the unschedulable queue. - q.AddUnschedulableIfNotPresent(p, q.SchedulingCycle()) + q.AddUnschedulableIfNotPresent(logger, p, q.SchedulingCycle()) // Move all unschedulable pods to the active queue. - q.MoveAllToActiveOrBackoffQueue(TestEvent, nil) + q.MoveAllToActiveOrBackoffQueue(logger, TestEvent, nil) p, err = q.Pop() if err != nil { @@ -1264,7 +1286,8 @@ func TestHighPriorityFlushUnschedulablePodsLeftover(t *testing.T) { m := map[framework.ClusterEvent]sets.Set[string]{ NodeAdd: sets.New("fakePlugin"), } - ctx, cancel := context.WithCancel(context.Background()) + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) defer cancel() q := NewTestQueue(ctx, newDefaultQueueSort(), WithClock(c), WithClusterEventMap(m)) midPod := st.MakePod().Name("test-midpod").Namespace("ns1").UID("tp-mid").Priority(midPriority).NominatedNodeName("node1").Obj() @@ -1286,10 +1309,10 @@ func TestHighPriorityFlushUnschedulablePodsLeftover(t *testing.T) { Message: "fake scheduling failure", }) - q.AddUnschedulableIfNotPresent(q.newQueuedPodInfo(highPod, "fakePlugin"), q.SchedulingCycle()) - q.AddUnschedulableIfNotPresent(q.newQueuedPodInfo(midPod, "fakePlugin"), q.SchedulingCycle()) + q.AddUnschedulableIfNotPresent(logger, q.newQueuedPodInfo(highPod, "fakePlugin"), q.SchedulingCycle()) + q.AddUnschedulableIfNotPresent(logger, q.newQueuedPodInfo(midPod, "fakePlugin"), q.SchedulingCycle()) c.Step(DefaultPodMaxInUnschedulablePodsDuration + time.Second) - q.flushUnschedulablePodsLeftover() + q.flushUnschedulablePodsLeftover(logger) if p, err := q.Pop(); err != nil || p.Pod != highPod { t.Errorf("Expected: %v after Pop, but got: %v", highPriorityPodInfo.Pod.Name, p.Pod.Name) @@ -1345,7 +1368,8 @@ func TestPriorityQueue_initPodMaxInUnschedulablePodsDuration(t *testing.T) { for _, test := range tests { t.Run(test.name, func(t *testing.T) { - ctx, cancel := context.WithCancel(context.Background()) + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) defer cancel() var queue *PriorityQueue if test.podMaxInUnschedulablePodsDuration > 0 { @@ -1360,7 +1384,7 @@ func TestPriorityQueue_initPodMaxInUnschedulablePodsDuration(t *testing.T) { var podInfoList []*framework.QueuedPodInfo for i, op := range test.operations { - op(queue, test.operands[i]) + op(logger, queue, test.operands[i]) } expectedLen := len(test.expected) @@ -1383,25 +1407,25 @@ func TestPriorityQueue_initPodMaxInUnschedulablePodsDuration(t *testing.T) { } } -type operation func(queue *PriorityQueue, pInfo *framework.QueuedPodInfo) +type operation func(logger klog.Logger, queue *PriorityQueue, pInfo *framework.QueuedPodInfo) var ( - add = func(queue *PriorityQueue, pInfo *framework.QueuedPodInfo) { - queue.Add(pInfo.Pod) + add = func(logger klog.Logger, queue *PriorityQueue, pInfo *framework.QueuedPodInfo) { + queue.Add(logger, pInfo.Pod) } - addUnschedulablePodBackToUnschedulablePods = func(queue *PriorityQueue, pInfo *framework.QueuedPodInfo) { - queue.AddUnschedulableIfNotPresent(pInfo, 0) + addUnschedulablePodBackToUnschedulablePods = func(logger klog.Logger, queue *PriorityQueue, pInfo *framework.QueuedPodInfo) { + queue.AddUnschedulableIfNotPresent(logger, pInfo, 0) } - addUnschedulablePodBackToBackoffQ = func(queue *PriorityQueue, pInfo *framework.QueuedPodInfo) { - queue.AddUnschedulableIfNotPresent(pInfo, -1) + addUnschedulablePodBackToBackoffQ = func(logger klog.Logger, queue *PriorityQueue, pInfo *framework.QueuedPodInfo) { + queue.AddUnschedulableIfNotPresent(logger, pInfo, -1) } - addPodActiveQ = func(queue *PriorityQueue, pInfo *framework.QueuedPodInfo) { + addPodActiveQ = func(logger klog.Logger, queue *PriorityQueue, pInfo *framework.QueuedPodInfo) { queue.activeQ.Add(pInfo) } - updatePodActiveQ = func(queue *PriorityQueue, pInfo *framework.QueuedPodInfo) { + updatePodActiveQ = func(logger klog.Logger, queue *PriorityQueue, pInfo *framework.QueuedPodInfo) { queue.activeQ.Update(pInfo) } - addPodUnschedulablePods = func(queue *PriorityQueue, pInfo *framework.QueuedPodInfo) { + addPodUnschedulablePods = func(logger klog.Logger, queue *PriorityQueue, pInfo *framework.QueuedPodInfo) { if !pInfo.Gated { // Update pod condition to unschedulable. podutil.UpdatePodCondition(&pInfo.Pod.Status, &v1.PodCondition{ @@ -1413,30 +1437,30 @@ var ( } queue.unschedulablePods.addOrUpdate(pInfo) } - deletePod = func(queue *PriorityQueue, pInfo *framework.QueuedPodInfo) { + deletePod = func(_ klog.Logger, queue *PriorityQueue, pInfo *framework.QueuedPodInfo) { queue.Delete(pInfo.Pod) } - updatePodQueueable = func(queue *PriorityQueue, pInfo *framework.QueuedPodInfo) { + updatePodQueueable = func(logger klog.Logger, queue *PriorityQueue, pInfo *framework.QueuedPodInfo) { newPod := pInfo.Pod.DeepCopy() newPod.Labels = map[string]string{"queueable": ""} - queue.Update(pInfo.Pod, newPod) + queue.Update(logger, pInfo.Pod, newPod) } - addPodBackoffQ = func(queue *PriorityQueue, pInfo *framework.QueuedPodInfo) { + addPodBackoffQ = func(logger klog.Logger, queue *PriorityQueue, pInfo *framework.QueuedPodInfo) { queue.podBackoffQ.Add(pInfo) } - moveAllToActiveOrBackoffQ = func(queue *PriorityQueue, _ *framework.QueuedPodInfo) { - queue.MoveAllToActiveOrBackoffQueue(UnschedulableTimeout, nil) + moveAllToActiveOrBackoffQ = func(logger klog.Logger, queue *PriorityQueue, _ *framework.QueuedPodInfo) { + queue.MoveAllToActiveOrBackoffQueue(logger, UnschedulableTimeout, nil) } - flushBackoffQ = func(queue *PriorityQueue, _ *framework.QueuedPodInfo) { + flushBackoffQ = func(logger klog.Logger, queue *PriorityQueue, _ *framework.QueuedPodInfo) { queue.clock.(*testingclock.FakeClock).Step(2 * time.Second) - queue.flushBackoffQCompleted() + queue.flushBackoffQCompleted(logger) } - moveClockForward = func(queue *PriorityQueue, _ *framework.QueuedPodInfo) { + moveClockForward = func(logger klog.Logger, queue *PriorityQueue, _ *framework.QueuedPodInfo) { queue.clock.(*testingclock.FakeClock).Step(2 * time.Second) } - flushUnschedulerQ = func(queue *PriorityQueue, _ *framework.QueuedPodInfo) { + flushUnschedulerQ = func(logger klog.Logger, queue *PriorityQueue, _ *framework.QueuedPodInfo) { queue.clock.(*testingclock.FakeClock).Step(queue.podMaxInUnschedulablePodsDuration) - queue.flushUnschedulablePodsLeftover() + queue.flushUnschedulablePodsLeftover(logger) } ) @@ -1505,13 +1529,14 @@ func TestPodTimestamp(t *testing.T) { for _, test := range tests { t.Run(test.name, func(t *testing.T) { - ctx, cancel := context.WithCancel(context.Background()) + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) defer cancel() queue := NewTestQueue(ctx, newDefaultQueueSort(), WithClock(testingclock.NewFakeClock(timestamp))) var podInfoList []*framework.QueuedPodInfo for i, op := range test.operations { - op(queue, test.operands[i]) + op(logger, queue, test.operands[i]) } expectedLen := len(test.expected) @@ -1788,7 +1813,8 @@ scheduler_plugin_execution_duration_seconds_count{extension_point="PreEnqueue",p for _, test := range tests { t.Run(test.name, func(t *testing.T) { resetMetrics() - ctx, cancel := context.WithCancel(context.Background()) + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) defer cancel() m := map[string][]framework.PreEnqueuePlugin{"": {&preEnqueuePlugin{allowlists: []string{queueable}}}} @@ -1796,7 +1822,7 @@ scheduler_plugin_execution_duration_seconds_count{extension_point="PreEnqueue",p queue := NewTestQueue(ctx, newDefaultQueueSort(), WithClock(testingclock.NewFakeClock(timestamp)), WithPreEnqueuePluginMap(m), WithPluginMetricsSamplePercent(test.pluginMetricsSamplePercent), WithMetricsRecorder(*recorder)) for i, op := range test.operations { for _, pInfo := range test.operands[i] { - op(queue, pInfo) + op(logger, queue, pInfo) } } @@ -1818,10 +1844,11 @@ func TestPerPodSchedulingMetrics(t *testing.T) { // Case 1: A pod is created and scheduled after 1 attempt. The queue operations are // Add -> Pop. c := testingclock.NewFakeClock(timestamp) - ctx, cancel := context.WithCancel(context.Background()) + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) defer cancel() queue := NewTestQueue(ctx, newDefaultQueueSort(), WithClock(c)) - queue.Add(pod) + queue.Add(logger, pod) pInfo, err := queue.Pop() if err != nil { t.Fatalf("Failed to pop a pod %v", err) @@ -1832,16 +1859,16 @@ func TestPerPodSchedulingMetrics(t *testing.T) { // Add -> Pop -> AddUnschedulableIfNotPresent -> flushUnschedulablePodsLeftover -> Pop. c = testingclock.NewFakeClock(timestamp) queue = NewTestQueue(ctx, newDefaultQueueSort(), WithClock(c)) - queue.Add(pod) + queue.Add(logger, pod) pInfo, err = queue.Pop() if err != nil { t.Fatalf("Failed to pop a pod %v", err) } - queue.AddUnschedulableIfNotPresent(pInfo, 1) + queue.AddUnschedulableIfNotPresent(logger, pInfo, 1) // Override clock to exceed the DefaultPodMaxInUnschedulablePodsDuration so that unschedulable pods // will be moved to activeQ c.SetTime(timestamp.Add(DefaultPodMaxInUnschedulablePodsDuration + 1)) - queue.flushUnschedulablePodsLeftover() + queue.flushUnschedulablePodsLeftover(logger) pInfo, err = queue.Pop() if err != nil { t.Fatalf("Failed to pop a pod %v", err) @@ -1852,19 +1879,19 @@ func TestPerPodSchedulingMetrics(t *testing.T) { // Add -> Pop -> AddUnschedulableIfNotPresent -> flushUnschedulablePodsLeftover -> Update -> Pop. c = testingclock.NewFakeClock(timestamp) queue = NewTestQueue(ctx, newDefaultQueueSort(), WithClock(c)) - queue.Add(pod) + queue.Add(logger, pod) pInfo, err = queue.Pop() if err != nil { t.Fatalf("Failed to pop a pod %v", err) } - queue.AddUnschedulableIfNotPresent(pInfo, 1) + queue.AddUnschedulableIfNotPresent(logger, pInfo, 1) // Override clock to exceed the DefaultPodMaxInUnschedulablePodsDuration so that unschedulable pods // will be moved to activeQ c.SetTime(timestamp.Add(DefaultPodMaxInUnschedulablePodsDuration + 1)) - queue.flushUnschedulablePodsLeftover() + queue.flushUnschedulablePodsLeftover(logger) newPod := pod.DeepCopy() newPod.Generation = 1 - queue.Update(pod, newPod) + queue.Update(logger, pod, newPod) pInfo, err = queue.Pop() if err != nil { t.Fatalf("Failed to pop a pod %v", err) @@ -1944,12 +1971,13 @@ func TestIncomingPodsMetrics(t *testing.T) { for _, test := range tests { t.Run(test.name, func(t *testing.T) { metrics.SchedulerQueueIncomingPods.Reset() - ctx, cancel := context.WithCancel(context.Background()) + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) defer cancel() queue := NewTestQueue(ctx, newDefaultQueueSort(), WithClock(testingclock.NewFakeClock(timestamp))) for _, op := range test.operations { for _, pInfo := range pInfos { - op(queue, pInfo) + op(logger, queue, pInfo) } } metricName := metrics.SchedulerSubsystem + "_" + metrics.SchedulerQueueIncomingPods.Name @@ -1972,7 +2000,8 @@ func checkPerPodSchedulingMetrics(name string, t *testing.T, pInfo *framework.Qu func TestBackOffFlow(t *testing.T) { cl := testingclock.NewFakeClock(time.Now()) - ctx, cancel := context.WithCancel(context.Background()) + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) defer cancel() q := NewTestQueue(ctx, newDefaultQueueSort(), WithClock(cl)) steps := []struct { @@ -1992,7 +2021,7 @@ func TestBackOffFlow(t *testing.T) { Namespace: pod.Namespace, Name: pod.Name, } - if err := q.Add(pod); err != nil { + if err := q.Add(logger, pod); err != nil { t.Fatal(err) } @@ -2007,12 +2036,12 @@ func TestBackOffFlow(t *testing.T) { if podInfo.Attempts != i+1 { t.Errorf("got attempts %d, want %d", podInfo.Attempts, i+1) } - if err := q.AddUnschedulableIfNotPresent(podInfo, int64(i)); err != nil { + if err := q.AddUnschedulableIfNotPresent(logger, podInfo, int64(i)); err != nil { t.Fatal(err) } // An event happens. - q.MoveAllToActiveOrBackoffQueue(UnschedulableTimeout, nil) + q.MoveAllToActiveOrBackoffQueue(logger, UnschedulableTimeout, nil) if _, ok, _ := q.podBackoffQ.Get(podInfo); !ok { t.Errorf("pod %v is not in the backoff queue", podID) @@ -2027,14 +2056,14 @@ func TestBackOffFlow(t *testing.T) { // Simulate routine that continuously flushes the backoff queue. cl.Step(time.Millisecond) - q.flushBackoffQCompleted() + q.flushBackoffQCompleted(logger) // Still in backoff queue after an early flush. if _, ok, _ := q.podBackoffQ.Get(podInfo); !ok { t.Errorf("pod %v is not in the backoff queue", podID) } // Moved out of the backoff queue after timeout. cl.Step(backoff) - q.flushBackoffQCompleted() + q.flushBackoffQCompleted(logger) if _, ok, _ := q.podBackoffQ.Get(podInfo); ok { t.Errorf("pod %v is still in the backoff queue", podID) } @@ -2183,11 +2212,12 @@ func TestMoveAllToActiveOrBackoffQueue_PreEnqueueChecks(t *testing.T) { for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { - ctx, cancel := context.WithCancel(context.Background()) + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) defer cancel() q := NewTestQueue(ctx, newDefaultQueueSort()) for i, podInfo := range tt.podInfos { - q.AddUnschedulableIfNotPresent(podInfo, q.schedulingCycle) + q.AddUnschedulableIfNotPresent(logger, podInfo, q.schedulingCycle) // NOTE: On Windows, time.Now() is not as precise, 2 consecutive calls may return the same timestamp, // resulting in 0 time delta / latency. This will cause the pods to be backed off in a random // order, which would cause this test to fail, since the expectation is for them to be backed off @@ -2195,7 +2225,7 @@ func TestMoveAllToActiveOrBackoffQueue_PreEnqueueChecks(t *testing.T) { // See: https://github.com/golang/go/issues/8687 podInfo.Timestamp = podInfo.Timestamp.Add(time.Duration((i - len(tt.podInfos))) * time.Millisecond) } - q.MoveAllToActiveOrBackoffQueue(TestEvent, tt.preEnqueueCheck) + q.MoveAllToActiveOrBackoffQueue(logger, TestEvent, tt.preEnqueueCheck) var got []string for q.podBackoffQ.Len() != 0 { obj, err := q.podBackoffQ.Pop() diff --git a/pkg/scheduler/schedule_one.go b/pkg/scheduler/schedule_one.go index 842c0636d7d..aa4f19bbf9a 100644 --- a/pkg/scheduler/schedule_one.go +++ b/pkg/scheduler/schedule_one.go @@ -60,6 +60,7 @@ const ( // scheduleOne does the entire scheduling workflow for a single pod. It is serialized on the scheduling algorithm's host fitting. func (sched *Scheduler) scheduleOne(ctx context.Context) { + logger := klog.FromContext(ctx) podInfo := sched.NextPod() // pod could be nil when schedulerQueue is closed if podInfo == nil || podInfo.Pod == nil { @@ -70,14 +71,14 @@ func (sched *Scheduler) scheduleOne(ctx context.Context) { if err != nil { // This shouldn't happen, because we only accept for scheduling the pods // which specify a scheduler name that matches one of the profiles. - klog.ErrorS(err, "Error occurred") + logger.Error(err, "Error occurred") return } - if sched.skipPodSchedule(fwk, pod) { + if sched.skipPodSchedule(ctx, fwk, pod) { return } - klog.V(3).InfoS("Attempting to schedule pod", "pod", klog.KObj(pod)) + logger.V(3).Info("Attempting to schedule pod", "pod", klog.KObj(pod)) // Synchronously attempt to find a fit for the pod. start := time.Now() @@ -123,6 +124,7 @@ func (sched *Scheduler) schedulingCycle( start time.Time, podsToActivate *framework.PodsToActivate, ) (ScheduleResult, *framework.QueuedPodInfo, *framework.Status) { + logger := klog.FromContext(ctx) pod := podInfo.Pod scheduleResult, err := sched.SchedulePod(ctx, fwk, state, pod) if err != nil { @@ -133,7 +135,7 @@ func (sched *Scheduler) schedulingCycle( fitError, ok := err.(*framework.FitError) if !ok { - klog.ErrorS(err, "Error selecting node for pod", "pod", klog.KObj(pod)) + logger.Error(err, "Error selecting node for pod", "pod", klog.KObj(pod)) return ScheduleResult{nominatingInfo: clearNominatedNode}, podInfo, framework.AsStatus(err) } @@ -143,7 +145,7 @@ func (sched *Scheduler) schedulingCycle( // into the resources that were preempted, but this is harmless. if !fwk.HasPostFilterPlugins() { - klog.V(3).InfoS("No PostFilter plugins are registered, so no preemption will be performed") + logger.V(3).Info("No PostFilter plugins are registered, so no preemption will be performed") return ScheduleResult{}, podInfo, framework.NewStatus(framework.Unschedulable).WithError(err) } @@ -152,9 +154,9 @@ func (sched *Scheduler) schedulingCycle( msg := status.Message() fitError.Diagnosis.PostFilterMsg = msg if status.Code() == framework.Error { - klog.ErrorS(nil, "Status after running PostFilter plugins for pod", "pod", klog.KObj(pod), "status", msg) + logger.Error(nil, "Status after running PostFilter plugins for pod", "pod", klog.KObj(pod), "status", msg) } else { - klog.V(5).InfoS("Status after running PostFilter plugins for pod", "pod", klog.KObj(pod), "status", msg) + logger.V(5).Info("Status after running PostFilter plugins for pod", "pod", klog.KObj(pod), "status", msg) } var nominatingInfo *framework.NominatingInfo @@ -170,7 +172,7 @@ func (sched *Scheduler) schedulingCycle( assumedPodInfo := podInfo.DeepCopy() assumedPod := assumedPodInfo.Pod // assume modifies `assumedPod` by setting NodeName=scheduleResult.SuggestedHost - err = sched.assume(assumedPod, scheduleResult.SuggestedHost) + err = sched.assume(logger, assumedPod, scheduleResult.SuggestedHost) if err != nil { // This is most probably result of a BUG in retrying logic. // We report an error here so that pod scheduling can be retried. @@ -186,8 +188,8 @@ func (sched *Scheduler) schedulingCycle( if sts := fwk.RunReservePluginsReserve(ctx, state, assumedPod, scheduleResult.SuggestedHost); !sts.IsSuccess() { // trigger un-reserve to clean up state associated with the reserved Pod fwk.RunReservePluginsUnreserve(ctx, state, assumedPod, scheduleResult.SuggestedHost) - if forgetErr := sched.Cache.ForgetPod(assumedPod); forgetErr != nil { - klog.ErrorS(forgetErr, "Scheduler cache ForgetPod failed") + if forgetErr := sched.Cache.ForgetPod(logger, assumedPod); forgetErr != nil { + logger.Error(forgetErr, "Scheduler cache ForgetPod failed") } return ScheduleResult{nominatingInfo: clearNominatedNode}, @@ -200,8 +202,8 @@ func (sched *Scheduler) schedulingCycle( if !runPermitStatus.IsWait() && !runPermitStatus.IsSuccess() { // trigger un-reserve to clean up state associated with the reserved Pod fwk.RunReservePluginsUnreserve(ctx, state, assumedPod, scheduleResult.SuggestedHost) - if forgetErr := sched.Cache.ForgetPod(assumedPod); forgetErr != nil { - klog.ErrorS(forgetErr, "Scheduler cache ForgetPod failed") + if forgetErr := sched.Cache.ForgetPod(logger, assumedPod); forgetErr != nil { + logger.Error(forgetErr, "Scheduler cache ForgetPod failed") } return ScheduleResult{nominatingInfo: clearNominatedNode}, @@ -211,7 +213,7 @@ func (sched *Scheduler) schedulingCycle( // At the end of a successful scheduling cycle, pop and move up Pods if needed. if len(podsToActivate.Map) != 0 { - sched.SchedulingQueue.Activate(podsToActivate.Map) + sched.SchedulingQueue.Activate(logger, podsToActivate.Map) // Clear the entries after activation. podsToActivate.Map = make(map[string]*v1.Pod) } @@ -228,6 +230,7 @@ func (sched *Scheduler) bindingCycle( assumedPodInfo *framework.QueuedPodInfo, start time.Time, podsToActivate *framework.PodsToActivate) *framework.Status { + logger := klog.FromContext(ctx) assumedPod := assumedPodInfo.Pod @@ -247,7 +250,7 @@ func (sched *Scheduler) bindingCycle( } // Calculating nodeResourceString can be heavy. Avoid it if klog verbosity is below 2. - klog.V(2).InfoS("Successfully bound pod to node", "pod", klog.KObj(assumedPod), "node", scheduleResult.SuggestedHost, "evaluatedNodes", scheduleResult.EvaluatedNodes, "feasibleNodes", scheduleResult.FeasibleNodes) + logger.V(2).Info("Successfully bound pod to node", "pod", klog.KObj(assumedPod), "node", scheduleResult.SuggestedHost, "evaluatedNodes", scheduleResult.EvaluatedNodes, "feasibleNodes", scheduleResult.FeasibleNodes) metrics.PodScheduled(fwk.ProfileName(), metrics.SinceInSeconds(start)) metrics.PodSchedulingAttempts.Observe(float64(assumedPodInfo.Attempts)) metrics.PodSchedulingDuration.WithLabelValues(getAttemptsLabel(assumedPodInfo)).Observe(metrics.SinceInSeconds(assumedPodInfo.InitialAttemptTimestamp)) @@ -257,7 +260,7 @@ func (sched *Scheduler) bindingCycle( // At the end of a successful binding cycle, move up Pods if needed. if len(podsToActivate.Map) != 0 { - sched.SchedulingQueue.Activate(podsToActivate.Map) + sched.SchedulingQueue.Activate(logger, podsToActivate.Map) // Unlike the logic in schedulingCycle(), we don't bother deleting the entries // as `podsToActivate.Map` is no longer consumed. } @@ -273,12 +276,13 @@ func (sched *Scheduler) handleBindingCycleError( start time.Time, scheduleResult ScheduleResult, status *framework.Status) { + logger := klog.FromContext(ctx) assumedPod := podInfo.Pod // trigger un-reserve plugins to clean up state associated with the reserved Pod fwk.RunReservePluginsUnreserve(ctx, state, assumedPod, scheduleResult.SuggestedHost) - if forgetErr := sched.Cache.ForgetPod(assumedPod); forgetErr != nil { - klog.ErrorS(forgetErr, "scheduler cache ForgetPod failed") + if forgetErr := sched.Cache.ForgetPod(logger, assumedPod); forgetErr != nil { + logger.Error(forgetErr, "scheduler cache ForgetPod failed") } else { // "Forget"ing an assumed Pod in binding cycle should be treated as a PodDelete event, // as the assumed Pod had occupied a certain amount of resources in scheduler cache. @@ -287,11 +291,11 @@ func (sched *Scheduler) handleBindingCycleError( // It's intentional to "defer" this operation; otherwise MoveAllToActiveOrBackoffQueue() would // update `q.moveRequest` and thus move the assumed pod to backoffQ anyways. if status.IsUnschedulable() { - defer sched.SchedulingQueue.MoveAllToActiveOrBackoffQueue(internalqueue.AssignedPodDelete, func(pod *v1.Pod) bool { + defer sched.SchedulingQueue.MoveAllToActiveOrBackoffQueue(logger, internalqueue.AssignedPodDelete, func(pod *v1.Pod) bool { return assumedPod.UID != pod.UID }) } else { - sched.SchedulingQueue.MoveAllToActiveOrBackoffQueue(internalqueue.AssignedPodDelete, nil) + sched.SchedulingQueue.MoveAllToActiveOrBackoffQueue(logger, internalqueue.AssignedPodDelete, nil) } } @@ -307,11 +311,11 @@ func (sched *Scheduler) frameworkForPod(pod *v1.Pod) (framework.Framework, error } // skipPodSchedule returns true if we could skip scheduling the pod for specified cases. -func (sched *Scheduler) skipPodSchedule(fwk framework.Framework, pod *v1.Pod) bool { +func (sched *Scheduler) skipPodSchedule(ctx context.Context, fwk framework.Framework, pod *v1.Pod) bool { // Case 1: pod is being deleted. if pod.DeletionTimestamp != nil { fwk.EventRecorder().Eventf(pod, nil, v1.EventTypeWarning, "FailedScheduling", "Scheduling", "skip schedule deleting pod: %v/%v", pod.Namespace, pod.Name) - klog.V(3).InfoS("Skip schedule deleting pod", "pod", klog.KObj(pod)) + klog.FromContext(ctx).V(3).Info("Skip schedule deleting pod", "pod", klog.KObj(pod)) return true } @@ -320,6 +324,7 @@ func (sched *Scheduler) skipPodSchedule(fwk framework.Framework, pod *v1.Pod) bo // during its previous scheduling cycle but before getting assumed. isAssumed, err := sched.Cache.IsAssumedPod(pod) if err != nil { + // TODO(91633): pass ctx into a revised HandleError utilruntime.HandleError(fmt.Errorf("failed to check whether pod %s/%s is assumed: %v", pod.Namespace, pod.Name, err)) return false } @@ -332,8 +337,7 @@ func (sched *Scheduler) skipPodSchedule(fwk framework.Framework, pod *v1.Pod) bo func (sched *Scheduler) schedulePod(ctx context.Context, fwk framework.Framework, state *framework.CycleState, pod *v1.Pod) (result ScheduleResult, err error) { trace := utiltrace.New("Scheduling", utiltrace.Field{Key: "namespace", Value: pod.Namespace}, utiltrace.Field{Key: "name", Value: pod.Name}) defer trace.LogIfLong(100 * time.Millisecond) - - if err := sched.Cache.UpdateSnapshot(sched.nodeInfoSnapshot); err != nil { + if err := sched.Cache.UpdateSnapshot(klog.FromContext(ctx), sched.nodeInfoSnapshot); err != nil { return result, err } trace.Step("Snapshotting scheduler cache and node infos done") @@ -383,6 +387,7 @@ func (sched *Scheduler) schedulePod(ctx context.Context, fwk framework.Framework // Filters the nodes to find the ones that fit the pod based on the framework // filter plugins and filter extenders. func (sched *Scheduler) findNodesThatFitPod(ctx context.Context, fwk framework.Framework, state *framework.CycleState, pod *v1.Pod) ([]*v1.Node, framework.Diagnosis, error) { + logger := klog.FromContext(ctx) diagnosis := framework.Diagnosis{ NodeToStatusMap: make(framework.NodeToStatusMap), UnschedulablePlugins: sets.New[string](), @@ -401,7 +406,7 @@ func (sched *Scheduler) findNodesThatFitPod(ctx context.Context, fwk framework.F // Record the messages from PreFilter in Diagnosis.PreFilterMsg. msg := s.Message() diagnosis.PreFilterMsg = msg - klog.V(5).InfoS("Status after running PreFilter plugins for pod", "pod", klog.KObj(pod), "status", msg) + logger.V(5).Info("Status after running PreFilter plugins for pod", "pod", klog.KObj(pod), "status", msg) // Status satisfying IsUnschedulable() gets injected into diagnosis.UnschedulablePlugins. if s.FailedPlugin() != "" { diagnosis.UnschedulablePlugins.Insert(s.FailedPlugin()) @@ -414,7 +419,7 @@ func (sched *Scheduler) findNodesThatFitPod(ctx context.Context, fwk framework.F if len(pod.Status.NominatedNodeName) > 0 { feasibleNodes, err := sched.evaluateNominatedNode(ctx, pod, fwk, state, diagnosis) if err != nil { - klog.ErrorS(err, "Evaluation failed on nominated node", "pod", klog.KObj(pod), "node", pod.Status.NominatedNodeName) + logger.Error(err, "Evaluation failed on nominated node", "pod", klog.KObj(pod), "node", pod.Status.NominatedNodeName) } // Nominated node passes all the filters, scheduler is good to assign this node to the pod. if len(feasibleNodes) != 0 { @@ -442,7 +447,7 @@ func (sched *Scheduler) findNodesThatFitPod(ctx context.Context, fwk framework.F return nil, diagnosis, err } - feasibleNodes, err = findNodesThatPassExtenders(sched.Extenders, pod, feasibleNodes, diagnosis.NodeToStatusMap) + feasibleNodes, err = findNodesThatPassExtenders(ctx, sched.Extenders, pod, feasibleNodes, diagnosis.NodeToStatusMap) if err != nil { return nil, diagnosis, err } @@ -461,7 +466,7 @@ func (sched *Scheduler) evaluateNominatedNode(ctx context.Context, pod *v1.Pod, return nil, err } - feasibleNodes, err = findNodesThatPassExtenders(sched.Extenders, pod, feasibleNodes, diagnosis.NodeToStatusMap) + feasibleNodes, err = findNodesThatPassExtenders(ctx, sched.Extenders, pod, feasibleNodes, diagnosis.NodeToStatusMap) if err != nil { return nil, err } @@ -571,7 +576,8 @@ func (sched *Scheduler) numFeasibleNodesToFind(percentageOfNodesToScore *int32, return numNodes } -func findNodesThatPassExtenders(extenders []framework.Extender, pod *v1.Pod, feasibleNodes []*v1.Node, statuses framework.NodeToStatusMap) ([]*v1.Node, error) { +func findNodesThatPassExtenders(ctx context.Context, extenders []framework.Extender, pod *v1.Pod, feasibleNodes []*v1.Node, statuses framework.NodeToStatusMap) ([]*v1.Node, error) { + logger := klog.FromContext(ctx) // Extenders are called sequentially. // Nodes in original feasibleNodes can be excluded in one extender, and pass on to the next // extender in a decreasing manner. @@ -591,7 +597,7 @@ func findNodesThatPassExtenders(extenders []framework.Extender, pod *v1.Pod, fea feasibleList, failedMap, failedAndUnresolvableMap, err := extender.Filter(pod, feasibleNodes) if err != nil { if extender.IsIgnorable() { - klog.InfoS("Skipping extender as it returned error and has ignorable flag set", "extender", extender, "err", err) + logger.Info("Skipping extender as it returned error and has ignorable flag set", "extender", extender, "err", err) continue } return nil, err @@ -637,6 +643,7 @@ func prioritizeNodes( pod *v1.Pod, nodes []*v1.Node, ) ([]framework.NodePluginScores, error) { + logger := klog.FromContext(ctx) // If no priority configs are provided, then all nodes will have a score of one. // This is required to generate the priority list in the required format if len(extenders) == 0 && !fwk.HasScorePlugins() { @@ -663,11 +670,11 @@ func prioritizeNodes( } // Additional details logged at level 10 if enabled. - klogV := klog.V(10) - if klogV.Enabled() { + loggerVTen := logger.V(10) + if loggerVTen.Enabled() { for _, nodeScore := range nodesScores { for _, pluginScore := range nodeScore.Scores { - klogV.InfoS("Plugin scored node for pod", "pod", klog.KObj(pod), "plugin", pluginScore.Name, "node", nodeScore.Name, "score", pluginScore.Score) + loggerVTen.Info("Plugin scored node for pod", "pod", klog.KObj(pod), "plugin", pluginScore.Name, "node", nodeScore.Name, "score", pluginScore.Score) } } } @@ -692,7 +699,7 @@ func prioritizeNodes( prioritizedList, weight, err := extenders[extIndex].Prioritize(pod, nodes) if err != nil { // Prioritization errors from extender can be ignored, let k8s/other extenders determine the priorities - klog.V(5).InfoS("Failed to run extender's priority function. No score given by this extender.", "error", err, "pod", klog.KObj(pod), "extender", extenders[extIndex].Name()) + logger.V(5).Info("Failed to run extender's priority function. No score given by this extender.", "error", err, "pod", klog.KObj(pod), "extender", extenders[extIndex].Name()) return } mu.Lock() @@ -700,8 +707,8 @@ func prioritizeNodes( for i := range *prioritizedList { nodename := (*prioritizedList)[i].Host score := (*prioritizedList)[i].Score - if klogV.Enabled() { - klogV.InfoS("Extender scored node for pod", "pod", klog.KObj(pod), "extender", extenders[extIndex].Name(), "node", nodename, "score", score) + if loggerVTen.Enabled() { + loggerVTen.Info("Extender scored node for pod", "pod", klog.KObj(pod), "extender", extenders[extIndex].Name(), "node", nodename, "score", score) } // MaxExtenderPriority may diverge from the max priority used in the scheduler and defined by MaxNodeScore, @@ -732,9 +739,9 @@ func prioritizeNodes( } } - if klogV.Enabled() { + if loggerVTen.Enabled() { for i := range nodesScores { - klogV.InfoS("Calculated node's final score for pod", "pod", klog.KObj(pod), "node", nodesScores[i].Name, "score", nodesScores[i].TotalScore) + loggerVTen.Info("Calculated node's final score for pod", "pod", klog.KObj(pod), "node", nodesScores[i].Name, "score", nodesScores[i].TotalScore) } } return nodesScores, nil @@ -767,15 +774,15 @@ func selectHost(nodeScores []framework.NodePluginScores) (string, error) { // assume signals to the cache that a pod is already in the cache, so that binding can be asynchronous. // assume modifies `assumed`. -func (sched *Scheduler) assume(assumed *v1.Pod, host string) error { +func (sched *Scheduler) assume(logger klog.Logger, assumed *v1.Pod, host string) error { // Optimistically assume that the binding will succeed and send it to apiserver // in the background. // If the binding fails, scheduler will release resources allocated to assumed pod // immediately. assumed.Spec.NodeName = host - if err := sched.Cache.AssumePod(assumed); err != nil { - klog.ErrorS(err, "Scheduler cache AssumePod failed") + if err := sched.Cache.AssumePod(logger, assumed); err != nil { + logger.Error(err, "Scheduler cache AssumePod failed") return err } // if "assumed" is a nominated pod, we should remove it from internal cache @@ -790,8 +797,9 @@ func (sched *Scheduler) assume(assumed *v1.Pod, host string) error { // The precedence for binding is: (1) extenders and (2) framework plugins. // We expect this to run asynchronously, so we handle binding metrics internally. func (sched *Scheduler) bind(ctx context.Context, fwk framework.Framework, assumed *v1.Pod, targetNode string, state *framework.CycleState) (status *framework.Status) { + logger := klog.FromContext(ctx) defer func() { - sched.finishBinding(fwk, assumed, targetNode, status) + sched.finishBinding(logger, fwk, assumed, targetNode, status) }() bound, err := sched.extendersBinding(assumed, targetNode) @@ -815,12 +823,12 @@ func (sched *Scheduler) extendersBinding(pod *v1.Pod, node string) (bool, error) return false, nil } -func (sched *Scheduler) finishBinding(fwk framework.Framework, assumed *v1.Pod, targetNode string, status *framework.Status) { - if finErr := sched.Cache.FinishBinding(assumed); finErr != nil { - klog.ErrorS(finErr, "Scheduler cache FinishBinding failed") +func (sched *Scheduler) finishBinding(logger klog.Logger, fwk framework.Framework, assumed *v1.Pod, targetNode string, status *framework.Status) { + if finErr := sched.Cache.FinishBinding(logger, assumed); finErr != nil { + logger.Error(finErr, "Scheduler cache FinishBinding failed") } if !status.IsSuccess() { - klog.V(1).InfoS("Failed to bind pod", "pod", klog.KObj(assumed)) + logger.V(1).Info("Failed to bind pod", "pod", klog.KObj(assumed)) return } @@ -839,6 +847,7 @@ func getAttemptsLabel(p *framework.QueuedPodInfo) string { // handleSchedulingFailure records an event for the pod that indicates the // pod has failed to schedule. Also, update the pod condition and nominated node name if set. func (sched *Scheduler) handleSchedulingFailure(ctx context.Context, fwk framework.Framework, podInfo *framework.QueuedPodInfo, status *framework.Status, nominatingInfo *framework.NominatingInfo, start time.Time) { + logger := klog.FromContext(ctx) reason := v1.PodReasonSchedulerError if status.IsUnschedulable() { reason = v1.PodReasonUnschedulable @@ -856,13 +865,13 @@ func (sched *Scheduler) handleSchedulingFailure(ctx context.Context, fwk framewo errMsg := status.Message() if err == ErrNoNodesAvailable { - klog.V(2).InfoS("Unable to schedule pod; no nodes are registered to the cluster; waiting", "pod", klog.KObj(pod), "err", err) - } else if fitError, ok := err.(*framework.FitError); ok { - // Inject UnschedulablePlugins to PodInfo, which will be used later for moving Pods between queues efficiently. + + logger.V(2).Info("Unable to schedule pod; no nodes are registered to the cluster; waiting", "pod", klog.KObj(pod)) + } else if fitError, ok := err.(*framework.FitError); ok { // Inject UnschedulablePlugins to PodInfo, which will be used later for moving Pods between queues efficiently. podInfo.UnschedulablePlugins = fitError.Diagnosis.UnschedulablePlugins - klog.V(2).InfoS("Unable to schedule pod; no fit; waiting", "pod", klog.KObj(pod), "err", errMsg) + logger.V(2).Info("Unable to schedule pod; no fit; waiting", "pod", klog.KObj(pod), "err", errMsg) } else if apierrors.IsNotFound(err) { - klog.V(2).InfoS("Unable to schedule pod, possibly due to node not found; waiting", "pod", klog.KObj(pod), "err", errMsg) + logger.V(2).Info("Unable to schedule pod, possibly due to node not found; waiting", "pod", klog.KObj(pod), "err", errMsg) if errStatus, ok := err.(apierrors.APIStatus); ok && errStatus.Status().Details.Kind == "node" { nodeName := errStatus.Status().Details.Name // when node is not found, We do not remove the node right away. Trying again to get @@ -870,32 +879,32 @@ func (sched *Scheduler) handleSchedulingFailure(ctx context.Context, fwk framewo _, err := fwk.ClientSet().CoreV1().Nodes().Get(context.TODO(), nodeName, metav1.GetOptions{}) if err != nil && apierrors.IsNotFound(err) { node := v1.Node{ObjectMeta: metav1.ObjectMeta{Name: nodeName}} - if err := sched.Cache.RemoveNode(&node); err != nil { - klog.V(4).InfoS("Node is not found; failed to remove it from the cache", "node", node.Name) + if err := sched.Cache.RemoveNode(logger, &node); err != nil { + logger.V(4).Info("Node is not found; failed to remove it from the cache", "node", node.Name) } } } } else { - klog.ErrorS(err, "Error scheduling pod; retrying", "pod", klog.KObj(pod)) + logger.Error(err, "Error scheduling pod; retrying", "pod", klog.KObj(pod)) } // Check if the Pod exists in informer cache. podLister := fwk.SharedInformerFactory().Core().V1().Pods().Lister() cachedPod, e := podLister.Pods(pod.Namespace).Get(pod.Name) if e != nil { - klog.InfoS("Pod doesn't exist in informer cache", "pod", klog.KObj(pod), "err", e) + logger.Info("Pod doesn't exist in informer cache", "pod", klog.KObj(pod), "err", e) } else { // In the case of extender, the pod may have been bound successfully, but timed out returning its response to the scheduler. // It could result in the live version to carry .spec.nodeName, and that's inconsistent with the internal-queued version. if len(cachedPod.Spec.NodeName) != 0 { - klog.InfoS("Pod has been assigned to node. Abort adding it back to queue.", "pod", klog.KObj(pod), "node", cachedPod.Spec.NodeName) + logger.Info("Pod has been assigned to node. Abort adding it back to queue.", "pod", klog.KObj(pod), "node", cachedPod.Spec.NodeName) } else { // As is from SharedInformer, we need to do a DeepCopy() here. // ignore this err since apiserver doesn't properly validate affinity terms // and we can't fix the validation for backwards compatibility. podInfo.PodInfo, _ = framework.NewPodInfo(cachedPod.DeepCopy()) - if err := sched.SchedulingQueue.AddUnschedulableIfNotPresent(podInfo, sched.SchedulingQueue.SchedulingCycle()); err != nil { - klog.ErrorS(err, "Error occurred") + if err := sched.SchedulingQueue.AddUnschedulableIfNotPresent(logger, podInfo, sched.SchedulingQueue.SchedulingCycle()); err != nil { + logger.Error(err, "Error occurred") } } } @@ -905,7 +914,8 @@ func (sched *Scheduler) handleSchedulingFailure(ctx context.Context, fwk framewo // and the time the scheduler receives a Pod Update for the nominated pod. // Here we check for nil only for tests. if sched.SchedulingQueue != nil { - sched.SchedulingQueue.AddNominatedPod(podInfo.PodInfo, nominatingInfo) + logger := klog.FromContext(ctx) + sched.SchedulingQueue.AddNominatedPod(logger, podInfo.PodInfo, nominatingInfo) } if err == nil { @@ -921,7 +931,7 @@ func (sched *Scheduler) handleSchedulingFailure(ctx context.Context, fwk framewo Reason: reason, Message: errMsg, }, nominatingInfo); err != nil { - klog.ErrorS(err, "Error updating pod", "pod", klog.KObj(pod)) + klog.FromContext(ctx).Error(err, "Error updating pod", "pod", klog.KObj(pod)) } } @@ -936,7 +946,8 @@ func truncateMessage(message string) string { } func updatePod(ctx context.Context, client clientset.Interface, pod *v1.Pod, condition *v1.PodCondition, nominatingInfo *framework.NominatingInfo) error { - klog.V(3).InfoS("Updating pod condition", "pod", klog.KObj(pod), "conditionType", condition.Type, "conditionStatus", condition.Status, "conditionReason", condition.Reason) + logger := klog.FromContext(ctx) + logger.V(3).Info("Updating pod condition", "pod", klog.KObj(pod), "conditionType", condition.Type, "conditionStatus", condition.Status, "conditionReason", condition.Reason) podStatusCopy := pod.Status.DeepCopy() // NominatedNodeName is updated only if we are trying to set it, and the value is // different from the existing one. diff --git a/pkg/scheduler/schedule_one_test.go b/pkg/scheduler/schedule_one_test.go index 098731e9206..47311e5bb5b 100644 --- a/pkg/scheduler/schedule_one_test.go +++ b/pkg/scheduler/schedule_one_test.go @@ -46,6 +46,8 @@ import ( clientcache "k8s.io/client-go/tools/cache" "k8s.io/client-go/tools/events" "k8s.io/component-helpers/storage/volume" + "k8s.io/klog/v2" + "k8s.io/klog/v2/ktesting" extenderv1 "k8s.io/kube-scheduler/extender/v1" schedulerapi "k8s.io/kubernetes/pkg/scheduler/apis/config" "k8s.io/kubernetes/pkg/scheduler/framework" @@ -811,13 +813,14 @@ func TestSchedulerScheduleOne(t *testing.T) { } func TestSchedulerNoPhantomPodAfterExpire(t *testing.T) { - ctx, cancel := context.WithCancel(context.Background()) + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) defer cancel() queuedPodStore := clientcache.NewFIFO(clientcache.MetaNamespaceKeyFunc) - scache := internalcache.New(100*time.Millisecond, ctx.Done()) + scache := internalcache.New(ctx, 100*time.Millisecond) pod := podWithPort("pod.Name", "", 8080) node := v1.Node{ObjectMeta: metav1.ObjectMeta{Name: "node1", UID: types.UID("node1")}} - scache.AddNode(&node) + scache.AddNode(logger, &node) fns := []st.RegisterPluginFunc{ st.RegisterQueueSortPlugin(queuesort.Name, queuesort.New), @@ -876,13 +879,14 @@ func TestSchedulerNoPhantomPodAfterExpire(t *testing.T) { } func TestSchedulerNoPhantomPodAfterDelete(t *testing.T) { - ctx, cancel := context.WithCancel(context.Background()) + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) defer cancel() queuedPodStore := clientcache.NewFIFO(clientcache.MetaNamespaceKeyFunc) - scache := internalcache.New(10*time.Minute, ctx.Done()) + scache := internalcache.New(ctx, 10*time.Minute) firstPod := podWithPort("pod.Name", "", 8080) node := v1.Node{ObjectMeta: metav1.ObjectMeta{Name: "node1", UID: types.UID("node1")}} - scache.AddNode(&node) + scache.AddNode(logger, &node) fns := []st.RegisterPluginFunc{ st.RegisterQueueSortPlugin(queuesort.Name, queuesort.New), st.RegisterBindPlugin(defaultbinder.Name, defaultbinder.New), @@ -921,10 +925,10 @@ func TestSchedulerNoPhantomPodAfterDelete(t *testing.T) { // and would be removed itself (without any explicit actions on schedulernodeinfo). Even in that case, // explicitly AddPod will as well correct the behavior. firstPod.Spec.NodeName = node.Name - if err := scache.AddPod(firstPod); err != nil { + if err := scache.AddPod(logger, firstPod); err != nil { t.Fatalf("err: %v", err) } - if err := scache.RemovePod(firstPod); err != nil { + if err := scache.RemovePod(logger, firstPod); err != nil { t.Fatalf("err: %v", err) } @@ -945,10 +949,11 @@ func TestSchedulerNoPhantomPodAfterDelete(t *testing.T) { } func TestSchedulerFailedSchedulingReasons(t *testing.T) { - ctx, cancel := context.WithCancel(context.Background()) + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) defer cancel() queuedPodStore := clientcache.NewFIFO(clientcache.MetaNamespaceKeyFunc) - scache := internalcache.New(10*time.Minute, ctx.Done()) + scache := internalcache.New(ctx, 10*time.Minute) // Design the baseline for the pods, and we will make nodes that don't fit it later. var cpu = int64(4) @@ -980,7 +985,7 @@ func TestSchedulerFailedSchedulingReasons(t *testing.T) { v1.ResourcePods: *(resource.NewQuantity(10, resource.DecimalSI)), }}, } - scache.AddNode(&node) + scache.AddNode(logger, &node) nodes = append(nodes, &node) objects = append(objects, &node) } @@ -1221,7 +1226,8 @@ func TestSchedulerBinding(t *testing.T) { } return false, nil, nil }) - ctx, cancel := context.WithCancel(context.Background()) + _, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) defer cancel() fwk, err := st.NewFramework(ctx, []st.RegisterPluginFunc{ @@ -1233,7 +1239,7 @@ func TestSchedulerBinding(t *testing.T) { } sched := &Scheduler{ Extenders: test.extenders, - Cache: internalcache.New(100*time.Millisecond, ctx.Done()), + Cache: internalcache.New(ctx, 100*time.Millisecond), nodeInfoSnapshot: nil, percentageOfNodesToScore: 0, } @@ -1660,13 +1666,14 @@ func TestFindNodesThatPassExtenders(t *testing.T) { for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { + _, ctx := ktesting.NewTestContext(t) var extenders []framework.Extender for ii := range tt.extenders { extenders = append(extenders, &tt.extenders[ii]) } pod := st.MakePod().Name("1").UID("1").Obj() - got, err := findNodesThatPassExtenders(extenders, pod, tt.nodes, tt.filteredNodesStatuses) + got, err := findNodesThatPassExtenders(ctx, extenders, pod, tt.nodes, tt.filteredNodesStatuses) if tt.expectsErr { if err == nil { t.Error("Unexpected non-error") @@ -2204,18 +2211,19 @@ func TestSchedulerSchedulePod(t *testing.T) { } for _, test := range tests { t.Run(test.name, func(t *testing.T) { - ctx, cancel := context.WithCancel(context.Background()) + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) defer cancel() - cache := internalcache.New(time.Duration(0), ctx.Done()) + cache := internalcache.New(ctx, time.Duration(0)) for _, pod := range test.pods { - cache.AddPod(pod) + cache.AddPod(logger, pod) } var nodes []*v1.Node for _, name := range test.nodes { node := &v1.Node{ObjectMeta: metav1.ObjectMeta{Name: name, Labels: map[string]string{"hostname": name}}} nodes = append(nodes, node) - cache.AddNode(node) + cache.AddNode(logger, node) } cs := clientsetfake.NewSimpleClientset() @@ -2403,7 +2411,8 @@ func TestFindFitPredicateCallCounts(t *testing.T) { registerFakeFilterFunc, st.RegisterBindPlugin(defaultbinder.Name, defaultbinder.New), } - ctx, cancel := context.WithCancel(context.Background()) + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) defer cancel() fwk, err := st.NewFramework( ctx, @@ -2415,11 +2424,14 @@ func TestFindFitPredicateCallCounts(t *testing.T) { } scheduler := makeScheduler(ctx, nodes) - if err := scheduler.Cache.UpdateSnapshot(scheduler.nodeInfoSnapshot); err != nil { + if err := scheduler.Cache.UpdateSnapshot(logger, scheduler.nodeInfoSnapshot); err != nil { t.Fatal(err) } - fwk.AddNominatedPod(mustNewPodInfo(t, st.MakePod().UID("nominated").Priority(midPriority).Obj()), - &framework.NominatingInfo{NominatingMode: framework.ModeOverride, NominatedNodeName: "1"}) + podinfo, err := framework.NewPodInfo(st.MakePod().UID("nominated").Priority(midPriority).Obj()) + if err != nil { + t.Fatal(err) + } + fwk.AddNominatedPod(logger, podinfo, &framework.NominatingInfo{NominatingMode: framework.ModeOverride, NominatedNodeName: "1"}) _, _, err = scheduler.findNodesThatFitPod(ctx, fwk, framework.NewCycleState(), test.pod) if err != nil { @@ -2952,16 +2964,17 @@ func TestPreferNominatedNodeFilterCallCounts(t *testing.T) { for _, test := range tests { t.Run(test.name, func(t *testing.T) { - ctx, cancel := context.WithCancel(context.Background()) + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) defer cancel() // create three nodes in the cluster. nodes := makeNodeList([]string{"node1", "node2", "node3"}) client := clientsetfake.NewSimpleClientset(test.pod) informerFactory := informers.NewSharedInformerFactory(client, 0) - cache := internalcache.New(time.Duration(0), ctx.Done()) + cache := internalcache.New(ctx, time.Duration(0)) for _, n := range nodes { - cache.AddNode(n) + cache.AddNode(logger, n) } plugin := st.FakeFilterPlugin{FailedNodeReturnCodeMap: test.nodeReturnCodeMap} registerFakeFilterFunc := st.RegisterFilterPlugin( @@ -3038,9 +3051,10 @@ func makeNodeList(nodeNames []string) []*v1.Node { // makeScheduler makes a simple Scheduler for testing. func makeScheduler(ctx context.Context, nodes []*v1.Node) *Scheduler { - cache := internalcache.New(time.Duration(0), ctx.Done()) + logger := klog.FromContext(ctx) + cache := internalcache.New(ctx, time.Duration(0)) for _, n := range nodes { - cache.AddNode(n) + cache.AddNode(logger, n) } sched := &Scheduler{ @@ -3049,7 +3063,7 @@ func makeScheduler(ctx context.Context, nodes []*v1.Node) *Scheduler { percentageOfNodesToScore: schedulerapi.DefaultPercentageOfNodesToScore, } sched.applyDefaultHandlers() - cache.UpdateSnapshot(sched.nodeInfoSnapshot) + cache.UpdateSnapshot(logger, sched.nodeInfoSnapshot) return sched } @@ -3162,6 +3176,7 @@ func setupTestScheduler(ctx context.Context, t *testing.T, queuedPodStore *clien } func setupTestSchedulerWithVolumeBinding(ctx context.Context, t *testing.T, volumeBinder volumebinding.SchedulerVolumeBinder, broadcaster events.EventBroadcaster) (*Scheduler, chan *v1.Binding, chan error) { + logger := klog.FromContext(ctx) testNode := v1.Node{ObjectMeta: metav1.ObjectMeta{Name: "node1", UID: types.UID("node1")}} queuedPodStore := clientcache.NewFIFO(clientcache.MetaNamespaceKeyFunc) pod := podWithID("foo", "") @@ -3169,8 +3184,8 @@ func setupTestSchedulerWithVolumeBinding(ctx context.Context, t *testing.T, volu pod.Spec.Volumes = append(pod.Spec.Volumes, v1.Volume{Name: "testVol", VolumeSource: v1.VolumeSource{PersistentVolumeClaim: &v1.PersistentVolumeClaimVolumeSource{ClaimName: "testPVC"}}}) queuedPodStore.Add(pod) - scache := internalcache.New(10*time.Minute, ctx.Done()) - scache.AddNode(&testNode) + scache := internalcache.New(ctx, 10*time.Minute) + scache.AddNode(logger, &testNode) testPVC := v1.PersistentVolumeClaim{ObjectMeta: metav1.ObjectMeta{Name: "testPVC", Namespace: pod.Namespace, UID: types.UID("testPVC")}} client := clientsetfake.NewSimpleClientset(&testNode, &testPVC) informerFactory := informers.NewSharedInformerFactory(client, 0) diff --git a/pkg/scheduler/scheduler.go b/pkg/scheduler/scheduler.go index 43d8b3c974e..910f4091cde 100644 --- a/pkg/scheduler/scheduler.go +++ b/pkg/scheduler/scheduler.go @@ -96,6 +96,11 @@ type Scheduler struct { percentageOfNodesToScore int32 nextStartNodeIndex int + + // logger *must* be initialized when creating a Scheduler, + // otherwise logging functions will access a nil sink and + // panic. + logger klog.Logger } func (s *Scheduler) applyDefaultHandlers() { @@ -246,6 +251,7 @@ func New(ctx context.Context, recorderFactory profile.RecorderFactory, opts ...Option) (*Scheduler, error) { + logger := klog.FromContext(ctx) stopEverything := ctx.Done() options := defaultSchedulerOptions @@ -270,7 +276,7 @@ func New(ctx context.Context, metrics.Register() - extenders, err := buildExtenders(options.extenders, options.profiles) + extenders, err := buildExtenders(logger, options.extenders, options.profiles) if err != nil { return nil, fmt.Errorf("couldn't build extenders: %w", err) } @@ -323,11 +329,11 @@ func New(ctx context.Context, fwk.SetPodNominator(podQueue) } - schedulerCache := internalcache.New(durationToExpireAssumedPod, stopEverything) + schedulerCache := internalcache.New(ctx, durationToExpireAssumedPod) // Setup cache debugger. debugger := cachedebugger.New(nodeLister, podLister, schedulerCache, podQueue) - debugger.ListenForSignal(stopEverything) + debugger.ListenForSignal(ctx) sched := &Scheduler{ Cache: schedulerCache, @@ -335,10 +341,11 @@ func New(ctx context.Context, nodeInfoSnapshot: snapshot, percentageOfNodesToScore: options.percentageOfNodesToScore, Extenders: extenders, - NextPod: internalqueue.MakeNextPodFunc(podQueue), + NextPod: internalqueue.MakeNextPodFunc(logger, podQueue), StopEverything: stopEverything, SchedulingQueue: podQueue, Profiles: profiles, + logger: logger, } sched.applyDefaultHandlers() @@ -349,7 +356,8 @@ func New(ctx context.Context, // Run begins watching and scheduling. It starts scheduling and blocked until the context is done. func (sched *Scheduler) Run(ctx context.Context) { - sched.SchedulingQueue.Run() + logger := klog.FromContext(ctx) + sched.SchedulingQueue.Run(logger) // We need to start scheduleOne loop in a dedicated goroutine, // because scheduleOne function hangs on getting the next item @@ -371,7 +379,7 @@ func NewInformerFactory(cs clientset.Interface, resyncPeriod time.Duration) info return informerFactory } -func buildExtenders(extenders []schedulerapi.Extender, profiles []schedulerapi.KubeSchedulerProfile) ([]framework.Extender, error) { +func buildExtenders(logger klog.Logger, extenders []schedulerapi.Extender, profiles []schedulerapi.KubeSchedulerProfile) ([]framework.Extender, error) { var fExtenders []framework.Extender if len(extenders) == 0 { return nil, nil @@ -380,7 +388,7 @@ func buildExtenders(extenders []schedulerapi.Extender, profiles []schedulerapi.K var ignoredExtendedResources []string var ignorableExtenders []framework.Extender for i := range extenders { - klog.V(2).InfoS("Creating extender", "extender", extenders[i]) + logger.V(2).Info("Creating extender", "extender", extenders[i]) extender, err := NewHTTPExtender(&extenders[i]) if err != nil { return nil, err diff --git a/pkg/scheduler/scheduler_test.go b/pkg/scheduler/scheduler_test.go index dc9b2153ba9..71f301aa94b 100644 --- a/pkg/scheduler/scheduler_test.go +++ b/pkg/scheduler/scheduler_test.go @@ -36,6 +36,7 @@ import ( "k8s.io/client-go/kubernetes/scheme" "k8s.io/client-go/tools/cache" "k8s.io/client-go/tools/events" + "k8s.io/klog/v2" "k8s.io/klog/v2/ktesting" schedulerapi "k8s.io/kubernetes/pkg/scheduler/apis/config" "k8s.io/kubernetes/pkg/scheduler/framework" @@ -262,7 +263,8 @@ func TestFailureHandler(t *testing.T) { for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { - ctx, cancel := context.WithCancel(context.Background()) + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) defer cancel() client := fake.NewSimpleClientset(&v1.PodList{Items: []v1.Pod{*testPod}}) @@ -272,14 +274,14 @@ func TestFailureHandler(t *testing.T) { podInformer.Informer().GetStore().Add(testPod) queue := internalqueue.NewPriorityQueue(nil, informerFactory, internalqueue.WithClock(testingclock.NewFakeClock(time.Now()))) - schedulerCache := internalcache.New(30*time.Second, ctx.Done()) + schedulerCache := internalcache.New(ctx, 30*time.Second) - queue.Add(testPod) + queue.Add(logger, testPod) queue.Pop() if tt.podUpdatedDuringScheduling { podInformer.Informer().GetStore().Update(testPodUpdated) - queue.Update(testPod, testPodUpdated) + queue.Update(logger, testPod, testPodUpdated) } if tt.podDeletedDuringScheduling { podInformer.Informer().GetStore().Delete(testPod) @@ -340,7 +342,8 @@ func TestFailureHandler_NodeNotFound(t *testing.T) { for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { - ctx, cancel := context.WithCancel(context.Background()) + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) defer cancel() client := fake.NewSimpleClientset(&v1.PodList{Items: []v1.Pod{*testPod}}, &v1.NodeList{Items: tt.nodes}) @@ -350,12 +353,12 @@ func TestFailureHandler_NodeNotFound(t *testing.T) { podInformer.Informer().GetStore().Add(testPod) queue := internalqueue.NewPriorityQueue(nil, informerFactory, internalqueue.WithClock(testingclock.NewFakeClock(time.Now()))) - schedulerCache := internalcache.New(30*time.Second, ctx.Done()) + schedulerCache := internalcache.New(ctx, 30*time.Second) for i := range tt.nodes { node := tt.nodes[i] // Add node to schedulerCache no matter it's deleted in API server or not. - schedulerCache.AddNode(&node) + schedulerCache.AddNode(logger, &node) if node.Name == tt.nodeNameToDelete { client.CoreV1().Nodes().Delete(ctx, node.Name, metav1.DeleteOptions{}) } @@ -382,7 +385,8 @@ func TestFailureHandler_NodeNotFound(t *testing.T) { } func TestFailureHandler_PodAlreadyBound(t *testing.T) { - ctx, cancel := context.WithCancel(context.Background()) + logger, ctx := ktesting.NewTestContext(t) + ctx, cancel := context.WithCancel(ctx) defer cancel() nodeFoo := v1.Node{ObjectMeta: metav1.ObjectMeta{Name: "foo"}} @@ -395,10 +399,10 @@ func TestFailureHandler_PodAlreadyBound(t *testing.T) { podInformer.Informer().GetStore().Add(testPod) queue := internalqueue.NewPriorityQueue(nil, informerFactory, internalqueue.WithClock(testingclock.NewFakeClock(time.Now()))) - schedulerCache := internalcache.New(30*time.Second, ctx.Done()) + schedulerCache := internalcache.New(ctx, 30*time.Second) // Add node to schedulerCache no matter it's deleted in API server or not. - schedulerCache.AddNode(&nodeFoo) + schedulerCache.AddNode(logger, &nodeFoo) s, fwk, err := initScheduler(ctx, schedulerCache, queue, client, informerFactory) if err != nil { @@ -488,6 +492,7 @@ func getPodFromPriorityQueue(queue *internalqueue.PriorityQueue, pod *v1.Pod) *v func initScheduler(ctx context.Context, cache internalcache.Cache, queue internalqueue.SchedulingQueue, client kubernetes.Interface, informerFactory informers.SharedInformerFactory) (*Scheduler, framework.Framework, error) { + logger := klog.FromContext(ctx) registerPluginFuncs := []st.RegisterPluginFunc{ st.RegisterQueueSortPlugin(queuesort.Name, queuesort.New), st.RegisterBindPlugin(defaultbinder.Name, defaultbinder.New), @@ -510,6 +515,7 @@ func initScheduler(ctx context.Context, cache internalcache.Cache, queue interna StopEverything: ctx.Done(), SchedulingQueue: queue, Profiles: profile.Map{testSchedulerName: fwk}, + logger: logger, } s.applyDefaultHandlers() diff --git a/test/integration/scheduler/queue_test.go b/test/integration/scheduler/queue_test.go index 3261452f6a3..a816a8e4fa9 100644 --- a/test/integration/scheduler/queue_test.go +++ b/test/integration/scheduler/queue_test.go @@ -37,6 +37,7 @@ import ( "k8s.io/client-go/dynamic" "k8s.io/client-go/kubernetes" featuregatetesting "k8s.io/component-base/featuregate/testing" + "k8s.io/klog/v2" configv1 "k8s.io/kube-scheduler/config/v1" apiservertesting "k8s.io/kubernetes/cmd/kube-apiserver/app/testing" "k8s.io/kubernetes/pkg/features" @@ -378,6 +379,7 @@ func TestCustomResourceEnqueue(t *testing.T) { defer testutils.CleanupTest(t, testCtx) cs, ns, ctx := testCtx.ClientSet, testCtx.NS.Name, testCtx.Ctx + logger := klog.FromContext(ctx) // Create one Node. node := st.MakeNode().Name("fake-node").Obj() if _, err := cs.CoreV1().Nodes().Create(ctx, node, metav1.CreateOptions{}); err != nil { @@ -415,7 +417,7 @@ func TestCustomResourceEnqueue(t *testing.T) { // Scheduling cycle is incremented from 0 to 1 after NextPod() is called, so // pass a number larger than 1 to move Pod to unschedulablePods. - testCtx.Scheduler.SchedulingQueue.AddUnschedulableIfNotPresent(podInfo, 10) + testCtx.Scheduler.SchedulingQueue.AddUnschedulableIfNotPresent(logger, podInfo, 10) // Trigger a Custom Resource event. // We expect this event to trigger moving the test Pod from unschedulablePods to activeQ.