Merge pull request #3186 from AryanSharma9917/aryan/issue-1314-capi-logging-pass-1

🌱 Improve logging

Author: k8s-ci-robot

controllers/openstackcluster_controller.go

@@ -32,6 +32,7 @@ import (
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	kerrors "k8s.io/apimachinery/pkg/util/errors"
 	"k8s.io/client-go/tools/events"
+	"k8s.io/klog/v2"
 	"k8s.io/utils/ptr"
 	clusterv1 "sigs.k8s.io/cluster-api/api/core/v1beta2"
 	"sigs.k8s.io/cluster-api/util"
@@ -98,11 +99,11 @@ func (r *OpenStackClusterReconciler) Reconcile(ctx context.Context, req ctrl.Req
 	}
 
 	if cluster == nil {
-		log.Info("Cluster Controller has not yet set OwnerRef")
+		log.Info("Cluster controller has not yet set owner reference")
 		return reconcile.Result{}, nil
 	}
 
-	log = log.WithValues("cluster", cluster.Name)
+	log = log.WithValues("Cluster", klog.KObj(cluster))
 
 	if annotations.IsPaused(cluster, openStackCluster) {
 		log.Info("OpenStackCluster or linked Cluster is marked as paused. Not reconciling")

controllers/openstackmachine_controller.go

@@ -29,6 +29,7 @@ import (
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	kerrors "k8s.io/apimachinery/pkg/util/errors"
 	"k8s.io/client-go/tools/events"
+	"k8s.io/klog/v2"
 	"k8s.io/utils/ptr"
 	clusterv1 "sigs.k8s.io/cluster-api/api/core/v1beta2"
 	ipamv1 "sigs.k8s.io/cluster-api/api/ipam/v1beta2"
@@ -95,7 +96,7 @@ func (r *OpenStackMachineReconciler) Reconcile(ctx context.Context, req ctrl.Req
 		return ctrl.Result{}, err
 	}
 
-	log = log.WithValues("openStackMachine", openStackMachine.Name)
+	log = log.WithValues("OpenStackMachine", klog.KObj(openStackMachine))
 	log.V(4).Info("Reconciling OpenStackMachine")
 
 	// Fetch the Machine.
@@ -104,20 +105,20 @@ func (r *OpenStackMachineReconciler) Reconcile(ctx context.Context, req ctrl.Req
 		return ctrl.Result{}, err
 	}
 	if machine == nil {
-		log.Info("Machine Controller has not yet set OwnerRef")
+		log.Info("Machine controller has not yet set owner reference")
 		return ctrl.Result{}, nil
 	}
 
-	log = log.WithValues("machine", machine.Name)
+	log = log.WithValues("Machine", klog.KObj(machine))
 
 	// Fetch the Cluster.
 	cluster, err := util.GetClusterFromMetadata(ctx, r.Client, machine.ObjectMeta)
 	if err != nil {
-		log.Info("Machine is missing cluster label or cluster does not exist")
+		log.Info("Machine is missing cluster label or Cluster does not exist")
 		return ctrl.Result{}, nil
 	}
 
-	log = log.WithValues("cluster", cluster.Name)
+	log = log.WithValues("Cluster", klog.KObj(cluster))
 
 	if annotations.IsPaused(cluster, openStackMachine) {
 		log.Info("OpenStackMachine or linked Cluster is marked as paused. Won't reconcile")
@@ -129,11 +130,11 @@ func (r *OpenStackMachineReconciler) Reconcile(ctx context.Context, req ctrl.Req
 		return ctrl.Result{}, errors.New("error getting infra provider cluster")
 	}
 	if infraCluster == nil {
-		log.Info("OpenStackCluster is not ready yet")
+		log.Info("OpenStackCluster is not ready yet", "OpenStackCluster", klog.KRef(cluster.Namespace, cluster.Spec.InfrastructureRef.Name))
 		return ctrl.Result{}, nil
 	}
 
-	log = log.WithValues("openStackCluster", infraCluster.Name)
+	log = log.WithValues("OpenStackCluster", klog.KObj(infraCluster))
 
 	// Initialize the patch helper
 	patchHelper, err := patch.NewHelper(openStackMachine, r.Client)
@@ -461,7 +462,7 @@ func (r *OpenStackMachineReconciler) reconcileNormal(ctx context.Context, scope
 		})
 	}
 
-	scope.Logger().Info("Reconciled Machine create successfully")
+	scope.Logger().Info("Reconciled OpenStackMachine create successfully")
 	return ctrl.Result{}, nil
 }
 
@@ -473,7 +474,7 @@ func (r *OpenStackMachineReconciler) reconcileMachineState(scope *scope.WithLogg
 	// This can happen when the server is still being created or when
 	// there was an error during resource resolution (e.g., image not found).
 	if openStackServer.Status.InstanceState == nil {
-		scope.Logger().Info("Waiting for OpenStackServer instance state", "name", openStackServer.Name)
+		scope.Logger().Info("Waiting for OpenStackServer instance state", "OpenStackServer", klog.KObj(openStackServer))
 
 		if condition := meta.FindStatusCondition(openStackServer.Status.Conditions, infrav1.InstanceReadyCondition); condition != nil && condition.Status == metav1.ConditionFalse {
 			conditions.Set(openStackMachine, metav1.Condition{

controllers/openstackmachinetemplate_controller.go

@@ -27,6 +27,7 @@ import (
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	kerrors "k8s.io/apimachinery/pkg/util/errors"
 	"k8s.io/client-go/tools/events"
+	"k8s.io/klog/v2"
 	clusterv1 "sigs.k8s.io/cluster-api/api/core/v1beta2"
 	"sigs.k8s.io/cluster-api/util"
 	"sigs.k8s.io/cluster-api/util/annotations"
@@ -90,8 +91,8 @@ func (r *OpenStackMachineTemplateReconciler) Reconcile(ctx context.Context, req
 		return ctrl.Result{}, err
 	}
 
-	log = log.WithValues("openStackMachineTemplate", openStackMachineTemplate.Name)
-	log.V(4).Info("Reconciling openStackMachineTemplate")
+	log = log.WithValues("OpenStackMachineTemplate", klog.KObj(openStackMachineTemplate))
+	log.V(4).Info("Reconciling OpenStackMachineTemplate")
 
 	// If OSMT is set for deletion, do nothing
 	if !openStackMachineTemplate.DeletionTimestamp.IsZero() {
@@ -105,11 +106,11 @@ func (r *OpenStackMachineTemplateReconciler) Reconcile(ctx context.Context, req
 	// are patched by the CC and thus not valid.
 	cluster, err := util.GetOwnerCluster(ctx, r.Client, openStackMachineTemplate.ObjectMeta)
 	if err != nil || cluster == nil {
-		log.Info("openStackMachineTemplate is missing owner cluster or cluster does not exist")
+		log.Info("OpenStackMachineTemplate is missing owner Cluster or Cluster does not exist")
 		return ctrl.Result{}, nil
 	}
 
-	log = log.WithValues("cluster", cluster.Name)
+	log = log.WithValues("Cluster", klog.KObj(cluster))
 
 	if annotations.IsPaused(cluster, openStackMachineTemplate) {
 		log.Info("OpenStackMachineTemplate or linked Cluster is marked as paused. Won't reconcile")
@@ -121,11 +122,11 @@ func (r *OpenStackMachineTemplateReconciler) Reconcile(ctx context.Context, req
 		return ctrl.Result{}, errors.New("error getting infra provider cluster")
 	}
 	if infraCluster == nil {
-		log.Info("OpenStackCluster not ready", "name", cluster.Spec.InfrastructureRef.Name)
+		log.Info("OpenStackCluster is not ready", "OpenStackCluster", klog.KRef(cluster.Namespace, cluster.Spec.InfrastructureRef.Name))
 		return ctrl.Result{}, nil
 	}
 
-	log = log.WithValues("openStackCluster", infraCluster.Name)
+	log = log.WithValues("OpenStackCluster", klog.KObj(infraCluster))
 
 	// Initialize the patch helper
 	patchHelper, err := patch.NewHelper(openStackMachineTemplate, r.Client)
@@ -356,10 +357,11 @@ func (r *OpenStackMachineTemplateReconciler) reconcileAllowedAddressPairs(ctx co
 					break
 				}
 				pairs := templatePorts[portIdx].AllowedAddressPairs
-				log.Info("Updating allowedAddressPairs on port", "portID", portStatus.ID,
-					"machine", osm.Name, "portIndex", portIdx)
+				log.Info("Updating spec.template.spec.ports[*].allowedAddressPairs on Neutron port",
+					"OpenStackMachine", klog.KObj(osm), "portID", portStatus.ID, "portIndex", portIdx)
 				if err := networkingService.UpdateAllowedAddressPairs(portStatus.ID, pairs); err != nil {
-					log.Error(err, "Failed to update allowedAddressPairs", "portID", portStatus.ID)
+					log.Error(err, "Failed to update spec.template.spec.ports[*].allowedAddressPairs",
+						"OpenStackMachine", klog.KObj(osm), "portID", portStatus.ID)
 					return err
 				}
 			}

controllers/openstackserver_controller.go

@@ -138,7 +138,8 @@ func (r *OpenStackServerReconciler) Reconcile(ctx context.Context, req ctrl.Requ
 	})
 	scope := scope.NewWithLogger(clientScope, log)
 
-	scope.Logger().Info("Reconciling OpenStackServer")
+	logger := scope.Logger().WithValues("OpenStackServer", klog.KObj(openStackServer))
+	logger.Info("Reconciling OpenStackServer")
 
 	cluster, err := getClusterFromMetadata(ctx, r.Client, openStackServer.ObjectMeta)
 	if err != nil {
@@ -241,7 +242,8 @@ func (r *OpenStackServerReconciler) SetupWithManager(ctx context.Context, mgr ct
 }
 
 func (r *OpenStackServerReconciler) reconcileDelete(scope *scope.WithLogger, openStackServer *infrav1alpha1.OpenStackServer) error {
-	scope.Logger().Info("Reconciling Server delete")
+	log := scope.Logger().WithValues("OpenStackServer", klog.KObj(openStackServer))
+	log.Info("Reconciling OpenStackServer delete")
 
 	computeService, err := compute.NewService(scope)
 	if err != nil {
@@ -300,7 +302,7 @@ func (r *OpenStackServerReconciler) reconcileDelete(scope *scope.WithLogger, ope
 	}
 
 	controllerutil.RemoveFinalizer(openStackServer, infrav1alpha1.OpenStackServerFinalizer)
-	scope.Logger().Info("Reconciled Server deleted successfully")
+	log.Info("Reconciled OpenStackServer deleted successfully")
 	return nil
 }
 
@@ -314,11 +316,13 @@ func IsServerTerminalError(server *infrav1alpha1.OpenStackServer) bool {
 func (r *OpenStackServerReconciler) reconcileNormal(ctx context.Context, scope *scope.WithLogger, openStackServer *infrav1alpha1.OpenStackServer) (_ ctrl.Result, reterr error) {
 	// If the OpenStackServer is in an error state, return early.
 	if IsServerTerminalError(openStackServer) {
-		scope.Logger().Info("Not reconciling server in error state. See openStackServer.status or previously logged error for details")
+		log := scope.Logger().WithValues("OpenStackServer", klog.KObj(openStackServer))
+		log.Info("Not reconciling OpenStackServer in error state. See openStackServer.status or previously logged error for details")
 		return ctrl.Result{}, nil
 	}
 
-	scope.Logger().Info("Reconciling Server create")
+	log := scope.Logger().WithValues("OpenStackServer", klog.KObj(openStackServer))
+	log.Info("Reconciling OpenStackServer")
 
 	labels := openStackServer.GetLabels()
 	if labels == nil {
@@ -363,7 +367,7 @@ func (r *OpenStackServerReconciler) reconcileNormal(ctx context.Context, scope *
 	// that in the delete path we can be sure that if there are no resolved
 	// resources then no resources were created.
 	if changed {
-		scope.Logger().V(5).Info("Server resources updated, requeuing")
+		log.V(5).Info("Server resources updated, requeuing")
 		return ctrl.Result{}, nil
 	}
 

pkg/cloud/services/loadbalancer/loadbalancer.go

@@ -87,7 +87,7 @@ func (s *Service) ReconcileLoadBalancer(openStackCluster *infrav1.OpenStackClust
 	}
 
 	loadBalancerName := getLoadBalancerName(clusterResourceName)
-	s.scope.Logger().Info("Reconciling load balancer", "name", loadBalancerName)
+	s.scope.Logger().V(3).Info("Reconciling load balancer", "name", loadBalancerName)
 
 	lbStatus := openStackCluster.Status.APIServerManagedLoadBalancer
 	if lbStatus == nil {
@@ -316,9 +316,9 @@ func (s *Service) getOrCreateAPILoadBalancer(openStackCluster *infrav1.OpenStack
 	if vipNetworkID == "" && vipSubnetID == "" {
 		// keep the default and create the VIP on the first cluster subnet
 		vipSubnetID = openStackCluster.Status.Network.Subnets[0].ID
-		s.scope.Logger().Info("No load balancer network specified, creating load balancer in the default subnet", "subnetID", vipSubnetID, "name", loadBalancerName)
+		s.scope.Logger().V(2).Info("No load balancer network specified, creating load balancer in the default subnet", "subnetID", vipSubnetID, "name", loadBalancerName)
 	} else {
-		s.scope.Logger().Info("Creating load balancer in subnet", "subnetID", vipSubnetID, "name", loadBalancerName)
+		s.scope.Logger().V(2).Info("Creating load balancer in subnet", "subnetID", vipSubnetID, "name", loadBalancerName)
 	}
 
 	providers, err := s.loadbalancerClient.ListLoadBalancerProviders()
@@ -444,7 +444,7 @@ func (s *Service) getOrCreateListener(openStackCluster *infrav1.OpenStackCluster
 		return listener, nil
 	}
 
-	s.scope.Logger().Info("Creating load balancer listener", "name", listenerName, "loadBalancerID", lbID)
+	s.scope.Logger().V(2).Info("Creating load balancer listener", "name", listenerName, "loadBalancerID", lbID)
 
 	listenerCreateOpts := listeners.CreateOpts{
 		Name:           listenerName,
@@ -480,7 +480,7 @@ func (s *Service) getOrUpdateAllowedCIDRs(openStackCluster *infrav1.OpenStackClu
 	listener.AllowedCIDRs = capostrings.Canonicalize(listener.AllowedCIDRs)
 
 	if !slices.Equal(allowedCIDRs, listener.AllowedCIDRs) {
-		s.scope.Logger().Info("CIDRs do not match, updating listener", "expectedCIDRs", allowedCIDRs, "currentCIDRs", listener.AllowedCIDRs)
+		s.scope.Logger().V(3).Info("CIDRs do not match, updating listener", "expectedCIDRs", allowedCIDRs, "currentCIDRs", listener.AllowedCIDRs)
 		listenerUpdateOpts := listeners.UpdateOpts{
 			AllowedCIDRs: &allowedCIDRs,
 		}
@@ -512,7 +512,7 @@ func (s *Service) getOrCreatePool(openStackCluster *infrav1.OpenStackCluster, po
 		return pool, nil
 	}
 
-	s.scope.Logger().Info("Creating load balancer pool for listener", "loadBalancerID", lbID, "listenerID", listenerID, "name", poolName)
+	s.scope.Logger().V(2).Info("Creating load balancer pool for listener", "loadBalancerID", lbID, "listenerID", listenerID, "name", poolName)
 
 	method := pools.LBMethodRoundRobin
 
@@ -564,31 +564,31 @@ func (s *Service) ensureMonitor(openStackCluster *infrav1.OpenStackCluster, moni
 		monitorUpdateOpts := monitors.UpdateOpts{}
 
 		if monitor.Delay != cfg.Delay {
-			s.scope.Logger().Info("Monitor delay needs update", "current", monitor.Delay, "desired", cfg.Delay)
+			s.scope.Logger().V(3).Info("Monitor delay needs update", "current", monitor.Delay, "desired", cfg.Delay)
 			monitorUpdateOpts.Delay = cfg.Delay
 			needsUpdate = true
 		}
 
 		if monitor.Timeout != cfg.Timeout {
-			s.scope.Logger().Info("Monitor timeout needs update", "current", monitor.Timeout, "desired", cfg.Timeout)
+			s.scope.Logger().V(3).Info("Monitor timeout needs update", "current", monitor.Timeout, "desired", cfg.Timeout)
 			monitorUpdateOpts.Timeout = cfg.Timeout
 			needsUpdate = true
 		}
 
 		if monitor.MaxRetries != cfg.MaxRetries {
-			s.scope.Logger().Info("Monitor maxRetries needs update", "current", monitor.MaxRetries, "desired", cfg.MaxRetries)
+			s.scope.Logger().V(3).Info("Monitor maxRetries needs update", "current", monitor.MaxRetries, "desired", cfg.MaxRetries)
 			monitorUpdateOpts.MaxRetries = cfg.MaxRetries
 			needsUpdate = true
 		}
 
 		if monitor.MaxRetriesDown != cfg.MaxRetriesDown {
-			s.scope.Logger().Info("Monitor maxRetriesDown needs update", "current", monitor.MaxRetriesDown, "desired", cfg.MaxRetriesDown)
+			s.scope.Logger().V(3).Info("Monitor maxRetriesDown needs update", "current", monitor.MaxRetriesDown, "desired", cfg.MaxRetriesDown)
 			monitorUpdateOpts.MaxRetriesDown = cfg.MaxRetriesDown
 			needsUpdate = true
 		}
 
 		if needsUpdate {
-			s.scope.Logger().Info("Updating load balancer monitor", "loadBalancerID", lbID, "name", monitorName, "monitorID", monitor.ID)
+			s.scope.Logger().V(2).Info("Updating load balancer monitor", "loadBalancerID", lbID, "name", monitorName, "monitorID", monitor.ID)
 
 			updatedMonitor, err := s.loadbalancerClient.UpdateMonitor(monitor.ID, monitorUpdateOpts)
 			if err != nil {
@@ -607,7 +607,7 @@ func (s *Service) ensureMonitor(openStackCluster *infrav1.OpenStackCluster, moni
 		return nil
 	}
 
-	s.scope.Logger().Info("Creating load balancer monitor for pool", "loadBalancerID", lbID, "name", monitorName, "poolID", poolID)
+	s.scope.Logger().V(2).Info("Creating load balancer monitor for pool", "loadBalancerID", lbID, "name", monitorName, "poolID", poolID)
 
 	monitor, err = s.loadbalancerClient.CreateMonitor(monitors.CreateOpts{
 		Name:           monitorName,
@@ -655,7 +655,7 @@ func (s *Service) ReconcileLoadBalancerMember(openStackCluster *infrav1.OpenStac
 	}
 
 	loadBalancerName := getLoadBalancerName(clusterResourceName)
-	s.scope.Logger().Info("Reconciling load balancer member", "loadBalancerName", loadBalancerName)
+	s.scope.Logger().V(3).Info("Reconciling load balancer member", "loadBalancerName", loadBalancerName)
 
 	lbID := openStackCluster.Status.APIServerManagedLoadBalancer.ID
 	var portList []int
@@ -689,7 +689,7 @@ func (s *Service) ReconcileLoadBalancerMember(openStackCluster *infrav1.OpenStac
 				continue
 			}
 
-			s.scope.Logger().Info("Deleting load balancer member because the IP of the machine changed", "name", name)
+			s.scope.Logger().V(2).Info("Deleting load balancer member because the IP of the machine changed", "name", name)
 
 			// lb member changed so let's delete it so we can create it again with the correct IP
 			_, err = s.waitForLoadBalancerActive(lbID)
@@ -705,7 +705,7 @@ func (s *Service) ReconcileLoadBalancerMember(openStackCluster *infrav1.OpenStac
 			}
 		}
 
-		s.scope.Logger().Info("Creating load balancer member", "name", name)
+		s.scope.Logger().V(2).Info("Creating load balancer member", "name", name)
 
 		// if we got to this point we should either create or re-create the lb member
 		lbMemberOpts := pools.CreateMemberOpts{
@@ -754,7 +754,7 @@ func (s *Service) DeleteLoadBalancer(openStackCluster *infrav1.OpenStackCluster,
 	// However we should still wait for the load balancer to be deleted which is why we
 	// request a new reconcile after a certain amount of time.
 	if lb.ProvisioningStatus == loadBalancerProvisioningStatusPendingDelete {
-		s.scope.Logger().Info("Load balancer is already in PENDING_DELETE state", "name", loadBalancerName)
+		s.scope.Logger().V(3).Info("Load balancer is already in PENDING_DELETE state", "name", loadBalancerName)
 		return &ctrl.Result{RequeueAfter: waitForOctaviaLBCleanup}, nil
 	}
 
@@ -775,15 +775,15 @@ func (s *Service) DeleteLoadBalancer(openStackCluster *infrav1.OpenStackCluster,
 					return nil, err
 				}
 			} else {
-				s.scope.Logger().Info("Skipping load balancer floating IP deletion as it's a user-provided resource", "name", loadBalancerName, "fip", fip.FloatingIP)
+				s.scope.Logger().V(3).Info("Skipping load balancer floating IP deletion as it's a user-provided resource", "name", loadBalancerName, "floatingIP", fip.FloatingIP)
 			}
 		}
 	}
 
 	deleteOpts := loadbalancers.DeleteOpts{
 		Cascade: true,
 	}
-	s.scope.Logger().Info("Deleting load balancer", "name", loadBalancerName, "cascade", deleteOpts.Cascade)
+	s.scope.Logger().V(2).Info("Deleting load balancer", "name", loadBalancerName, "cascade", deleteOpts.Cascade)
 	err = s.loadbalancerClient.DeleteLoadBalancer(lb.ID, deleteOpts)
 	if err != nil && !capoerrors.IsNotFound(err) {
 		record.Warnf(openStackCluster, "FailedDeleteLoadBalancer", "Failed to delete load balancer %s with id %s: %v", lb.Name, lb.ID, err)
@@ -830,7 +830,7 @@ func (s *Service) DeleteLoadBalancerMember(openStackCluster *infrav1.OpenStackCl
 			return err
 		}
 		if pool == nil {
-			s.scope.Logger().Info("Load balancer pool does not exist", "name", lbPortObjectsName)
+			s.scope.Logger().V(4).Info("Load balancer pool does not exist", "name", lbPortObjectsName)
 			continue
 		}
 
@@ -927,7 +927,7 @@ var backoff = wait.Backoff{
 func (s *Service) waitForLoadBalancerActive(id string) (*loadbalancers.LoadBalancer, error) {
 	var lb *loadbalancers.LoadBalancer
 
-	s.scope.Logger().Info("Waiting for load balancer", "id", id, "targetStatus", "ACTIVE")
+	s.scope.Logger().V(3).Info("Waiting for load balancer", "id", id, "targetStatus", "ACTIVE")
 	err := wait.ExponentialBackoff(backoff, func() (bool, error) {
 		var err error
 		lb, err = s.loadbalancerClient.GetLoadBalancer(id)
@@ -946,7 +946,7 @@ func (s *Service) waitForLoadBalancerActive(id string) (*loadbalancers.LoadBalan
 func (s *Service) waitForPoolMemberActive(poolID, memberID string) (*pools.Member, error) {
 	var member *pools.Member
 
-	s.scope.Logger().Info("Waiting for pool member", "pool_id", poolID, "member_id", memberID, "targetStatus", "ACTIVE")
+	s.scope.Logger().V(3).Info("Waiting for pool member", "poolID", poolID, "memberID", memberID, "targetStatus", "ACTIVE")
 	err := wait.ExponentialBackoff(backoff, func() (bool, error) {
 		var err error
 		member, err = s.loadbalancerClient.GetPoolMember(poolID, memberID)
@@ -962,7 +962,7 @@ func (s *Service) waitForPoolMemberActive(poolID, memberID string) (*pools.Membe
 }
 
 func (s *Service) waitForListener(id, target string) error {
-	s.scope.Logger().Info("Waiting for load balancer listener", "id", id, "targetStatus", target)
+	s.scope.Logger().V(3).Info("Waiting for load balancer listener", "id", id, "targetStatus", target)
 	return wait.ExponentialBackoff(backoff, func() (bool, error) {
 		_, err := s.loadbalancerClient.GetListener(id)
 		if err != nil {