diff --git a/config/default/kustomization.yaml b/config/default/kustomization.yaml index 7ad399c..7b9e61b 100644 --- a/config/default/kustomization.yaml +++ b/config/default/kustomization.yaml @@ -31,4 +31,4 @@ patches: - path: manager_webhook_patch.yaml # Uncomment below for local development -#- manager_config_dev_patch.yaml +#- path: manager_config_dev_patch.yaml diff --git a/internal/boost/manager.go b/internal/boost/manager.go index dbb461c..77d5c28 100644 --- a/internal/boost/manager.go +++ b/internal/boost/manager.go @@ -86,6 +86,7 @@ type managerImpl struct { startupCPUBoosts map[string]map[string]StartupCPUBoost timePolicyBoosts map[boostKey]StartupCPUBoost maxGoroutines int + log logr.Logger } type boostKey struct { @@ -105,6 +106,7 @@ func NewManagerWithTicker(client client.Client, ticker TimeTicker) Manager { startupCPUBoosts: make(map[string]map[string]StartupCPUBoost), timePolicyBoosts: make(map[boostKey]StartupCPUBoost), maxGoroutines: DefaultMaxGoroutines, + log: ctrl.Log.WithName("boost-manager"), } } @@ -116,10 +118,11 @@ func (m *managerImpl) AddStartupCPUBoost(ctx context.Context, boost StartupCPUBo if _, ok := m.getStartupCPUBoost(boost.Namespace(), boost.Name()); ok { return errStartupCPUBoostAlreadyExists } - log := m.loggerFromContext(ctx).WithValues("boost", boost.Name, "namespace", boost.Namespace) - log.V(5).Info("handling startup-cpu-boost create") + log := m.log.WithValues("boost", boost.Name(), "namespace", boost.Namespace()) + log.V(5).Info("handling boost registration") m.addStartupCPUBoost(boost) metrics.NewBoostConfiguration(boost.Namespace()) + log.Info("boost registered successfully") return nil } @@ -127,14 +130,15 @@ func (m *managerImpl) AddStartupCPUBoost(ctx context.Context, boost StartupCPUBo func (m *managerImpl) RemoveStartupCPUBoost(ctx context.Context, namespace, name string) { m.Lock() defer m.Unlock() - log := m.loggerFromContext(ctx).WithValues("boost", name, "namespace", namespace) - log.V(5).Info("handling startup-cpu-boost delete") + log := m.log.WithValues("boost", name, "namespace", namespace) + log.V(5).Info("handling boost deletion") if boosts, ok := m.startupCPUBoosts[namespace]; ok { delete(boosts, name) } key := boostKey{name: name, namespace: namespace} delete(m.timePolicyBoosts, key) metrics.DeleteBoostConfiguration(namespace) + log.Info("boost deleted successfully") } // StartupCPUBoost returns a startup-cpu-boost with a given name and namespace @@ -150,8 +154,7 @@ func (m *managerImpl) StartupCPUBoost(namespace string, name string) (StartupCPU func (m *managerImpl) StartupCPUBoostForPod(ctx context.Context, pod *corev1.Pod) (StartupCPUBoost, bool) { m.RLock() defer m.RUnlock() - log := m.loggerFromContext(ctx).WithValues("pod", pod.Name, "namespace", pod.Namespace) - log.V(5).Info("handling startup-cpu-boost pod lookup") + m.log.V(5).Info("handling boost pod lookup") nsBoosts, ok := m.startupCPUBoosts[pod.Namespace] if !ok { return nil, false @@ -169,13 +172,12 @@ func (m *managerImpl) SetStartupCPUBoostReconciler(reconciler reconcile.Reconcil } func (m *managerImpl) Start(ctx context.Context) error { - log := m.loggerFromContext(ctx) defer m.ticker.Stop() - log.V(2).Info("Starting") + m.log.Info("starting") for { select { case <-m.ticker.Tick(): - log.V(5).Info("tick...") + m.log.V(5).Info("tick...") m.validateTimePolicyBoosts(ctx) case <-ctx.Done(): return nil @@ -220,7 +222,6 @@ func (m *managerImpl) validateTimePolicyBoosts(ctx context.Context) { revertTasks := make(chan *podRevertTask, m.maxGoroutines) reconcileTasks := make(chan *reconcile.Request, m.maxGoroutines) errors := make(chan error, m.maxGoroutines) - log := m.loggerFromContext(ctx) go func() { for _, boost := range m.timePolicyBoosts { @@ -241,11 +242,12 @@ func (m *managerImpl) validateTimePolicyBoosts(ctx context.Context) { go func() { defer wg.Done() for task := range revertTasks { - log = log.WithValues("boost", task.boost.Name(), "namespace", task.boost.Namespace(), "pod", task.pod.Name) - log.V(5).Info("updating pod with initial resources") + log := m.log.WithValues("boost", task.boost.Name(), "namespace", task.boost.Namespace(), "pod", task.pod.Name) + log.V(5).Info("reverting pod resources") if err := task.boost.RevertResources(ctx, task.pod); err != nil { errors <- fmt.Errorf("pod %s/%s: %w", task.pod.Namespace, task.pod.Name, err) } else { + log.Info("pod resources reverted successfully") reconcileTasks <- &reconcile.Request{ NamespacedName: types.NamespacedName{ Name: task.boost.Name(), @@ -263,7 +265,7 @@ func (m *managerImpl) validateTimePolicyBoosts(ctx context.Context) { go func() { for err := range errors { - log.Error(err, "failed to revert resources") + m.log.Error(err, "pod resources reversion failed") } }() @@ -275,12 +277,6 @@ func (m *managerImpl) validateTimePolicyBoosts(ctx context.Context) { } } -// loggerFromContext returns a pre-configured logger from the given context -func (m *managerImpl) loggerFromContext(ctx context.Context) logr.Logger { - return ctrl.LoggerFrom(ctx). - WithName("boost-manager") -} - func dedupeReconcileRequests(reconcileTasks chan *reconcile.Request) []reconcile.Request { result := make([]reconcile.Request, 0, len(reconcileTasks)) requests := make(map[reconcile.Request]bool) diff --git a/internal/boost/startupcpuboost.go b/internal/boost/startupcpuboost.go index 6e0722c..26d43af 100644 --- a/internal/boost/startupcpuboost.go +++ b/internal/boost/startupcpuboost.go @@ -155,7 +155,7 @@ func (b *StartupCPUBoostImpl) UpsertPod(ctx context.Context, pod *corev1.Pod) er b.Lock() defer b.Unlock() log := b.loggerFromContext(ctx).WithValues("pod", pod.Name) - log.V(5).Info("upserting a pod") + log.V(5).Info("handling pod upsert") _, existing := b.pods[pod.Name] b.pods[pod.Name] = pod statsEvent := StartupCPUBoostStatsEvent{StartupCPUBoostStatsPodCreateEvent, pod} @@ -163,17 +163,18 @@ func (b *StartupCPUBoostImpl) UpsertPod(ctx context.Context, pod *corev1.Pod) er statsEvent.Type = StartupCPUBoostStatsPodUpdateEvent } b.updateStats(statsEvent) - + log.V(5).Info("pod upserted successfully") condPolicy, ok := b.durationPolicies[duration.PodConditionPolicyName] if !ok { - log.V(5).Info("skipping pod update as podCondition policy is missing") + log.V(5).Info("pod duration policy not found, skipping resource reversion") return nil } if valid := b.validatePolicyOnPod(ctx, condPolicy, pod); !valid { - log.V(2).Info("updating pod with initial resources") + log.V(5).Info("reverting pod resources") if err := b.revertResources(ctx, pod); err != nil { - return fmt.Errorf("failed to update pod: %s", err) + return fmt.Errorf("pod resources reversion failed: %s", err) } + log.Info("pod resources reverted successfully") } return nil } diff --git a/internal/controller/boost_controller.go b/internal/controller/boost_controller.go index 9b90208..8b1bacd 100644 --- a/internal/controller/boost_controller.go +++ b/internal/controller/boost_controller.go @@ -63,8 +63,7 @@ func (r *StartupCPUBoostReconciler) Reconcile(ctx context.Context, req ctrl.Requ if err = r.Client.Get(ctx, req.NamespacedName, &boostObj); err != nil { return ctrl.Result{}, client.IgnoreNotFound(err) } - log := r.Log.WithName("reconcile").WithValues("name", boostObj.Name, "namespace", boostObj.Namespace) - log.V(2).Info("reconciling") + log := r.Log.WithValues("name", boostObj.Name, "namespace", boostObj.Namespace) newBoostObj := boostObj.DeepCopy() activeCondition := metav1.Condition{ Type: "Active", @@ -84,15 +83,15 @@ func (r *StartupCPUBoostReconciler) Reconcile(ctx context.Context, req ctrl.Requ } meta.SetStatusCondition(&newBoostObj.Status.Conditions, activeCondition) if !equality.Semantic.DeepEqual(newBoostObj.Status, boostObj.Status) { - log.V(5).Info("updating status") + log.V(5).Info("updating boost status") err = r.Client.Status().Update(ctx, newBoostObj) } if err != nil { if apierrors.IsConflict(err) { - log.V(5).Info("status update conflict, requeueing") + log.V(5).Info("boost status update conflict, requeueing") return ctrl.Result{Requeue: true}, nil } - log.V(5).Error(err, "failed to update status") + log.Error(err, "boost status update error") return ctrl.Result{}, client.IgnoreNotFound(err) } return ctrl.Result{}, nil @@ -100,7 +99,7 @@ func (r *StartupCPUBoostReconciler) Reconcile(ctx context.Context, req ctrl.Requ // SetupWithManager sets up the controller with the Manager. func (r *StartupCPUBoostReconciler) SetupWithManager(mgr ctrl.Manager) error { - boostPodHandler := NewBoostPodHandler(r.Manager, r.Log.WithName("pod-handler")) + boostPodHandler := NewBoostPodHandler(r.Manager, ctrl.Log.WithName("pod-handler")) lsPredicate, err := predicate.LabelSelectorPredicate(*boostPodHandler.GetPodLabelSelector()) if err != nil { return err @@ -119,15 +118,15 @@ func (r *StartupCPUBoostReconciler) Create(e event.CreateEvent) bool { if !ok { return true } - log := r.Log.WithName("create").WithValues("name", boostObj.Name, "namespace", boostObj.Namespace) - log.V(2).Info("creating") + log := r.Log.WithValues("name", boostObj.Name, "namespace", boostObj.Namespace) + log.V(5).Info("handling boost create event") ctx := ctrl.LoggerInto(context.Background(), log) boost, err := boost.NewStartupCPUBoost(r.Client, boostObj) if err != nil { - log.Error(err, "failed to create startup-cpu-boost from spec") + log.Error(err, "boost creation error") } if err := r.Manager.AddStartupCPUBoost(ctx, boost); err != nil { - log.Error(err, "failed to register startup-cpu-boost in manager") + log.Error(err, "boost registration error") } return true } @@ -137,8 +136,8 @@ func (r *StartupCPUBoostReconciler) Delete(e event.DeleteEvent) bool { if !ok { return true } - log := r.Log.WithName("delete").WithValues("name", boostObj.Name, "namespace", boostObj.Namespace) - log.V(2).Info("deleting") + log := r.Log.WithValues("name", boostObj.Name, "namespace", boostObj.Namespace) + log.V(5).Info("handling boost delete event") ctx := ctrl.LoggerInto(context.Background(), log) r.Manager.RemoveStartupCPUBoost(ctx, boostObj.Namespace, boostObj.Name) return true @@ -149,13 +148,13 @@ func (r *StartupCPUBoostReconciler) Update(e event.UpdateEvent) bool { if !ok { return true } - log := r.Log.WithName("update").WithValues("name", boostObj.Name, "namespace", boostObj.Namespace) - log.V(2).Info("updating") + log := r.Log.WithValues("name", boostObj.Name, "namespace", boostObj.Namespace) + log.V(5).Info("handling boost update event") return true } func (r *StartupCPUBoostReconciler) Generic(e event.GenericEvent) bool { - log := r.Log.WithName("generic").WithValues("object", klog.KObj(e.Object)) - log.V(2).Info("handling generic event") + log := r.Log.WithValues("object", klog.KObj(e.Object)) + log.V(5).Info("handling generic event") return true } diff --git a/internal/controller/boost_pod_handler.go b/internal/controller/boost_pod_handler.go index 3416ce0..8d5140c 100644 --- a/internal/controller/boost_pod_handler.go +++ b/internal/controller/boost_pod_handler.go @@ -58,7 +58,7 @@ func (h *boostPodHandler) Create(ctx context.Context, e event.CreateEvent, wq wo log.V(5).Info("handling pod create") boost, ok := h.boostForPod(pod) if !ok { - log.V(5).Info("failed to get boost for pod") + log.V(5).Info("pod create skipped: no boost for pod") return } boostName := boost.Name() @@ -83,7 +83,7 @@ func (h *boostPodHandler) Delete(ctx context.Context, e event.DeleteEvent, wq wo log.V(5).Info("handling pod delete") boost, ok := h.boostForPod(pod) if !ok { - log.V(5).Info("failed to get boost for pod") + log.V(5).Info("pod delete skipped: no boost for pod") return } if err := boost.DeletePod(ctx, pod); err != nil { @@ -106,15 +106,16 @@ func (h *boostPodHandler) Update(ctx context.Context, e event.UpdateEvent, wq wo log := h.log.WithValues("pod", pod.Name, "namespace", pod.Namespace) log.V(5).Info("handling pod update") if equality.Semantic.DeepEqual(pod.Status.Conditions, oldPod.Status.Conditions) { + log.V(5).Info("pod update skipped: conditions did not change") return } boost, ok := h.boostForPod(pod) if !ok { - log.V(5).Info("failed to get boost for pod") + log.V(5).Info("pod update skipped: no boost for pod") return } if err := boost.UpsertPod(ctx, pod); err != nil { - log.Error(err, "failed to handle pod update") + log.Error(err, "pod update failed") } wq.Add(reconcile.Request{ NamespacedName: types.NamespacedName{ @@ -130,7 +131,7 @@ func (h *boostPodHandler) Generic(ctx context.Context, e event.GenericEvent, wq return } log := h.log.WithValues("pod", pod.Name, "namespace", pod.Namespace) - log.V(5).Info("got pod generic event") + log.V(5).Info("handling pod generic event") } func (h *boostPodHandler) GetPodLabelSelector() *metav1.LabelSelector { diff --git a/internal/webhook/podcpuboost_webhook.go b/internal/webhook/podcpuboost_webhook.go index 56314db..b2eda4f 100644 --- a/internal/webhook/podcpuboost_webhook.go +++ b/internal/webhook/podcpuboost_webhook.go @@ -51,13 +51,13 @@ func (h *podCPUBoostHandler) Handle(ctx context.Context, req admission.Request) if err != nil { return admission.Errored(http.StatusBadRequest, err) } - log := ctrl.LoggerFrom(ctx).WithName("cpuboost-webhook") - log.V(5).Info("handling Pod") + log := ctrl.LoggerFrom(ctx).WithName("boost-pod-webhook") + log.V(5).Info("handling pod") boostImpl, ok := h.manager.StartupCPUBoostForPod(ctx, pod) if !ok { - log.V(5).Info("no startupCPUBoost matched") - return admission.Allowed("no StartupCPUBoost matched") + log.V(5).Info("no boost matched") + return admission.Allowed("no boost matched") } log = log.WithValues("boost", boostImpl.Name()) h.boostContainerResources(ctx, boostImpl, pod, log) @@ -76,8 +76,8 @@ func (h *podCPUBoostHandler) boostContainerResources(ctx context.Context, b boos continue } log = log.WithValues("container", container.Name, - "CPURequests", container.Resources.Requests.Cpu().String(), - "CPULimits", container.Resources.Limits.Cpu().String(), + "cpuRequests", container.Resources.Requests.Cpu().String(), + "cpuLimits", container.Resources.Limits.Cpu().String(), ) if resizeRequiresRestart(container, corev1.ResourceCPU) { log.Info("skipping container due to restart policy") @@ -86,11 +86,11 @@ func (h *podCPUBoostHandler) boostContainerResources(ctx context.Context, b boos updateBoostAnnotation(annotation, container.Name, container.Resources) resources := policy.NewResources(ctx, &container) log = log.WithValues( - "newCPURequests", resources.Requests.Cpu().String(), - "newCPULimits", resources.Limits.Cpu().String(), + "newCpuRequests", resources.Requests.Cpu().String(), + "newCpuLimits", resources.Limits.Cpu().String(), ) - log.V(2).Info("increasing resources") pod.Spec.Containers[i].Resources = *resources + log.Info("pod resources increased") } if len(annotation.InitCPULimits) > 0 || len(annotation.InitCPURequests) > 0 { if pod.Annotations == nil { diff --git a/internal/webhook/startupcpuboost_webhook.go b/internal/webhook/startupcpuboost_webhook.go index aaa4966..ad0d001 100644 --- a/internal/webhook/startupcpuboost_webhook.go +++ b/internal/webhook/startupcpuboost_webhook.go @@ -45,16 +45,16 @@ func setupWebhookForStartupCPUBoost(mgr ctrl.Manager) error { // ValidateCreate implements webhook.CustomValidator so a webhook will be registered for the type func (w *StartupCPUBoostWebhook) ValidateCreate(ctx context.Context, obj runtime.Object) (admission.Warnings, error) { boost := obj.(*v1alpha1.StartupCPUBoost) - log := ctrl.LoggerFrom(ctx).WithName("startupcpuboost-webhook") - log.V(5).Info("validating create", "startupcpuboost", klog.KObj(boost)) + log := ctrl.LoggerFrom(ctx).WithName("boost-validate-webhook") + log.V(5).Info("handling create validation", "boos", klog.KObj(boost)) return nil, validate(boost) } // ValidateUpdate implements webhook.CustomValidator so a webhook will be registered for the type func (w *StartupCPUBoostWebhook) ValidateUpdate(ctx context.Context, oldObj, newObj runtime.Object) (admission.Warnings, error) { boost := newObj.(*v1alpha1.StartupCPUBoost) - log := ctrl.LoggerFrom(ctx).WithName("startupcpuboost-webhook") - log.V(5).Info("validating update", "startupcpuboost", klog.KObj(boost)) + log := ctrl.LoggerFrom(ctx).WithName("boost-validate-webhook") + log.V(5).Info("handling update validation", "startupcpuboost", klog.KObj(boost)) return nil, validate(boost) }