🌱 Improve logging for VSphereMachine

controllers/vspheremachine_controller.go

@@ -31,6 +31,7 @@
 	apitypes "k8s.io/apimachinery/pkg/types"
 	kerrors "k8s.io/apimachinery/pkg/util/errors"
 	"k8s.io/apimachinery/pkg/util/validation"
+	"k8s.io/klog/v2"
 	clusterv1 "sigs.k8s.io/cluster-api/api/v1beta1"
 	clusterutilv1 "sigs.k8s.io/cluster-api/util"
 	"sigs.k8s.io/cluster-api/util/annotations"
@@ -61,7 +62,11 @@
 	"sigs.k8s.io/cluster-api-provider-vsphere/pkg/util"
 )
 
-const hostInfoErrStr = "host info cannot be used as a label value"
+const (
+	hostInfoErrStr = "host info cannot be used as a label value"
+	// VSphereMachineControllerName is the name of the vSphere machine controller.
+	VSphereMachineControllerName = "vspheremachine-controller"
+)
 
 // +kubebuilder:rbac:groups=infrastructure.cluster.x-k8s.io,resources=vspheremachines,verbs=get;list;watch;create;update;patch;delete
 // +kubebuilder:rbac:groups=infrastructure.cluster.x-k8s.io,resources=vspheremachines/status,verbs=get;update;patch
@@ -97,15 +102,8 @@
 		controllerNameLong = fmt.Sprintf("%s/%s/%s", controllerManagerContext.Namespace, controllerManagerContext.Name, controllerNameShort)
 	}
 
-	// Build the controller context.
-	controllerContext := &capvcontext.ControllerContext{
-		ControllerManagerContext: controllerManagerContext,
-		Name:                     controllerNameShort,
-		Recorder:                 record.New(mgr.GetEventRecorderFor(controllerNameLong)),
-		Logger:                   controllerManagerContext.Logger.WithName(controllerNameShort),
-	}
-
 	builder := ctrl.NewControllerManagedBy(mgr).
+		Named(VSphereMachineControllerName).
 		// Watch the controlled, infrastructure resource.
 		For(controlledType).
 		WithOptions(options).
@@ -126,15 +124,16 @@
 		WithEventFilter(predicates.ResourceNotPausedAndHasFilterLabel(ctrl.LoggerFrom(ctx), controllerManagerContext.WatchFilterValue))
 
 	r := &machineReconciler{
-		ControllerContext: controllerContext,
-		VMService:         &services.VimMachineService{},
-		supervisorBased:   supervisorBased,
+		Client:          controllerManagerContext.Client,
+		Recorder:        record.New(mgr.GetEventRecorderFor(controllerNameLong)),
+		VMService:       &services.VimMachineService{Client: controllerManagerContext.Client},
+		supervisorBased: supervisorBased,
 	}
 
 	if supervisorBased {
 		// Watch any VirtualMachine resources owned by this VSphereMachine
 		builder.Owns(&vmoprv1.VirtualMachine{})
-		r.VMService = &vmoperator.VmopMachineService{}
+		r.VMService = &vmoperator.VmopMachineService{Client: controllerManagerContext.Client}
 		networkProvider, err := inframanager.GetNetworkProvider(ctx, controllerManagerContext.Client, controllerManagerContext.NetworkProvider)
 		if err != nil {
 			return errors.Wrap(err, "failed to create a network provider")
@@ -160,7 +159,7 @@
 			&clusterv1.Cluster{},
 			handler.EnqueueRequestsFromMapFunc(r.clusterToVSphereMachines),
 			ctrlbldr.WithPredicates(
-				predicates.ClusterUnpausedAndInfrastructureReady(r.Logger),
+				predicates.ClusterUnpausedAndInfrastructureReady(ctrl.LoggerFrom(ctx)),
 			),
 		)
 	}
@@ -169,7 +168,8 @@
 }
 
 type machineReconciler struct {
-	*capvcontext.ControllerContext
+	Client          client.Client
+	Recorder        record.Recorder
 	VMService       services.VSphereMachineService
 	networkProvider services.NetworkProvider
 	supervisorBased bool
@@ -178,11 +178,11 @@
 // Reconcile ensures the back-end state reflects the Kubernetes resource state intent.
 func (r *machineReconciler) Reconcile(ctx context.Context, req ctrl.Request) (_ ctrl.Result, reterr error) {
 	var machineContext capvcontext.MachineContext
-	logger := ctrl.LoggerFrom(ctx)
-	logger.V(4).Info("Starting Reconcile")
+	log := ctrl.LoggerFrom(ctx)
+	log.V(4).Info("Starting Reconcile")
 
 	// Fetch VSphereMachine object and populate the machine context
-	machineContext, err := r.VMService.FetchVSphereMachine(r.Client, req.NamespacedName)
+	machineContext, err := r.VMService.FetchVSphereMachine(ctx, req.NamespacedName)
 	if err != nil {
 		if apierrors.IsNotFound(err) {
 			return reconcile.Result{}, nil
@@ -191,15 +191,17 @@
 	}
 
 	// Fetch the CAPI Machine and CAPI Cluster.
-	machine, err := clusterutilv1.GetOwnerMachine(r, r.Client, machineContext.GetObjectMeta())
+	machine, err := clusterutilv1.GetOwnerMachine(ctx, r.Client, machineContext.GetObjectMeta())
 	if err != nil {
 		return reconcile.Result{}, err
 	}
 	if machine == nil {
-		logger.V(2).Info("waiting on Machine controller to set OwnerRef on infra machine")
+		log.Info("Waiting on Machine controller to set OwnerRef on VSphereMachine")
 		return reconcile.Result{}, nil
 	}
 
+	log = log.WithValues("Machine", klog.KObj(machine))
+	ctx = ctrl.LoggerInto(ctx, log)
 	cluster := r.fetchCAPICluster(ctx, machine, machineContext.GetVSphereMachine())
 
 	// Create the patch helper.
@@ -212,11 +214,9 @@
 			machineContext.GetObjectMeta().Name)
 	}
 	machineContext.SetBaseMachineContext(&capvcontext.BaseMachineContext{
-		ControllerContext: r.ControllerContext,
-		Cluster:           cluster,
-		Machine:           machine,
-		Logger:            logger,
-		PatchHelper:       patchHelper,
+		Cluster:     cluster,
+		Machine:     machine,
+		PatchHelper: patchHelper,
 	})
 	// always patch the VSphereMachine object
 	defer func() {
@@ -228,7 +228,7 @@
 		)
 
 		// Patch the VSphereMachine resource.
-		if err := machineContext.Patch(); err != nil {
+		if err := machineContext.Patch(ctx); err != nil {
 			reterr = kerrors.NewAggregate([]error{reterr, err})
 		}
 	}()
@@ -243,9 +243,9 @@
 	}
 
 	// Fetch the VSphereCluster and update the machine context
-	machineContext, err = r.VMService.FetchVSphereCluster(r.Client, cluster, machineContext)
+	machineContext, err = r.VMService.FetchVSphereCluster(ctx, cluster, machineContext)
 	if err != nil {
-		logger.Info("unable to retrieve VSphereCluster", "error", err)
+		log.Error(err, "unable to retrieve VSphereCluster")
 		return reconcile.Result{}, nil
 	}
 
@@ -261,10 +261,11 @@
 
 func (r *machineReconciler) reconcileDelete(ctx context.Context, machineCtx capvcontext.MachineContext) (reconcile.Result, error) {
 	log := ctrl.LoggerFrom(ctx)
+
 	log.Info("Handling deleted VSphereMachine")
 	conditions.MarkFalse(machineCtx.GetVSphereMachine(), infrav1.VMProvisionedCondition, clusterv1.DeletingReason, clusterv1.ConditionSeverityInfo, "")
 
-	if err := r.VMService.ReconcileDelete(machineCtx); err != nil {
+	if err := r.VMService.ReconcileDelete(ctx, machineCtx); err != nil {
 		if apierrors.IsNotFound(err) {
 			// The VM is deleted so remove the finalizer.
 			ctrlutil.RemoveFinalizer(machineCtx.GetVSphereMachine(), infrav1.MachineFinalizer)
@@ -280,14 +281,15 @@
 
 func (r *machineReconciler) reconcileNormal(ctx context.Context, machineCtx capvcontext.MachineContext) (reconcile.Result, error) {
 	log := ctrl.LoggerFrom(ctx)
-	machineFailed, err := r.VMService.SyncFailureReason(machineCtx)
+
+	machineFailed, err := r.VMService.SyncFailureReason(ctx, machineCtx)
 	if err != nil && !apierrors.IsNotFound(err) {
 		return reconcile.Result{}, err
 	}
 
 	// If the VSphereMachine is in an error state, return early.
 	if machineFailed {
-		log.Info("Error state detected, skipping reconciliation")
+		log.Error(err, "Error state detected, skipping reconciliation")
 		return reconcile.Result{}, nil
 	}
 
@@ -318,7 +320,7 @@
 		return reconcile.Result{}, nil
 	}
 
-	requeue, err := r.VMService.ReconcileNormal(machineCtx)
+	requeue, err := r.VMService.ReconcileNormal(ctx, machineCtx)
 	if err != nil {
 		return reconcile.Result{}, err
 	} else if requeue {
@@ -343,7 +345,8 @@
 // which would be added onto the node by the CAPI controllers.
 func (r *machineReconciler) patchMachineLabelsWithHostInfo(ctx context.Context, machineCtx capvcontext.MachineContext) error {
 	log := ctrl.LoggerFrom(ctx)
-	hostInfo, err := r.VMService.GetHostInfo(machineCtx)
+
+	hostInfo, err := r.VMService.GetHostInfo(ctx, machineCtx)
 	if err != nil {
 		return err
 	}
@@ -366,7 +369,7 @@
 	labels[constants.ESXiHostInfoLabel] = info
 	machine.Labels = labels
 
-	return patchHelper.Patch(r, machine)
+	return patchHelper.Patch(ctx, machine)
 }
 
 func (r *machineReconciler) clusterToVSphereMachines(ctx context.Context, a client.Object) []reconcile.Request {
@@ -389,13 +392,14 @@
 
 func (r *machineReconciler) fetchCAPICluster(ctx context.Context, machine *clusterv1.Machine, vsphereMachine metav1.Object) *clusterv1.Cluster {
 	log := ctrl.LoggerFrom(ctx)
-	cluster, err := clusterutilv1.GetClusterFromMetadata(r, r.Client, machine.ObjectMeta)
+	cluster, err := clusterutilv1.GetClusterFromMetadata(ctx, r.Client, machine.ObjectMeta)
 	if err != nil {
 		log.Info("Machine is missing cluster label or cluster does not exist")
 		return nil
 	}
+	log = log.WithValues("Cluster", klog.KObj(cluster))
 	if annotations.IsPaused(cluster, vsphereMachine) {
-		log.V(4).Info("VSphereMachine %s/%s linked to a cluster that is paused", vsphereMachine.GetNamespace(), vsphereMachine.GetName())
+		log.V(4).Info("VSphereMachine is linked to a cluster that is paused")
 		return nil
 	}
 

pkg/context/fake/fake_machine_context.go

@@ -46,7 +46,6 @@ func NewMachineContext(clusterCtx *capvcontext.ClusterContext, controllerCtx *ca
 			ControllerContext: controllerCtx,
 			Cluster:           clusterCtx.Cluster,
 			Machine:           &machine,
-			Logger:            controllerCtx.Logger.WithName(vsphereMachine.Name),
 		},
 		VSphereCluster: clusterCtx.VSphereCluster,
 		VSphereMachine: &vsphereMachine,

pkg/context/interfaces.go

@@ -17,7 +17,8 @@ limitations under the License.
 package context
 
 import (
-	"github.com/go-logr/logr"
+	"context"
+
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	clusterv1 "sigs.k8s.io/cluster-api/api/v1beta1"
 	"sigs.k8s.io/cluster-api/util/conditions"
@@ -27,8 +28,7 @@ import (
 // MachineContext is the context used in VSphereMachine reconciliation.
 type MachineContext interface {
 	String() string
-	Patch() error
-	GetLogger() logr.Logger
+	Patch(ctx context.Context) error
 	GetVSphereMachine() VSphereMachine
 	GetObjectMeta() metav1.ObjectMeta
 	GetCluster() *clusterv1.Cluster

pkg/context/machine_context.go

@@ -17,9 +17,9 @@ limitations under the License.
 package context
 
 import (
+	"context"
 	"fmt"
 
-	"github.com/go-logr/logr"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	clusterv1 "sigs.k8s.io/cluster-api/api/v1beta1"
 	"sigs.k8s.io/cluster-api/util/patch"
@@ -29,11 +29,10 @@ import (
 
 // BaseMachineContext contains information about a CAPI Machine for VSphereMachine reconciliation.
 type BaseMachineContext struct {
-	*ControllerContext
-	Logger      logr.Logger
-	Cluster     *clusterv1.Cluster
-	Machine     *clusterv1.Machine
-	PatchHelper *patch.Helper
+	ControllerContext *ControllerContext
+	Cluster           *clusterv1.Cluster
+	Machine           *clusterv1.Machine
+	PatchHelper       *patch.Helper
 }
 
 // GetCluster returns the cluster for the BaseMachineContext.
@@ -46,11 +45,6 @@ func (c *BaseMachineContext) GetMachine() *clusterv1.Machine {
 	return c.Machine
 }
 
-// GetLogger returns this context's logger.
-func (c *BaseMachineContext) GetLogger() logr.Logger {
-	return c.Logger
-}
-
 // VIMMachineContext is a Go context used with a VSphereMachine.
 type VIMMachineContext struct {
 	*BaseMachineContext
@@ -64,8 +58,8 @@ func (c *VIMMachineContext) String() string {
 }
 
 // Patch updates the object and its status on the API server.
-func (c *VIMMachineContext) Patch() error {
-	return c.PatchHelper.Patch(c, c.VSphereMachine)
+func (c *VIMMachineContext) Patch(ctx context.Context) error {
+	return c.PatchHelper.Patch(ctx, c.VSphereMachine)
 }
 
 // GetVSphereMachine sets the VSphereMachine for the VIMMachineContext.

pkg/context/vmware/machine_context.go

@@ -17,22 +17,23 @@ limitations under the License.
 package vmware
 
 import (
+	"context"
 	"fmt"
 
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	"k8s.io/apimachinery/pkg/runtime"
 
 	vmwarev1 "sigs.k8s.io/cluster-api-provider-vsphere/apis/vmware/v1beta1"
-	"sigs.k8s.io/cluster-api-provider-vsphere/pkg/context"
+	capvcontext "sigs.k8s.io/cluster-api-provider-vsphere/pkg/context"
 )
 
 // VMModifier allows a function to be passed to VM creation to modify its spec
 // The hook is loosely typed so as to allow for different VirtualMachine backends.
 type VMModifier func(runtime.Object) (runtime.Object, error)
 
-// SupervisorMachineContext is a Go context used with a VSphereMachine.
+// SupervisorMachineContext is a Go capvcontext used with a VSphereMachine.
 type SupervisorMachineContext struct {
-	*context.BaseMachineContext
+	*capvcontext.BaseMachineContext
 	VSphereCluster *vmwarev1.VSphereCluster
 	VSphereMachine *vmwarev1.VSphereMachine
 	VMModifiers    []VMModifier
@@ -44,12 +45,12 @@ func (c *SupervisorMachineContext) String() string {
 }
 
 // Patch updates the object and its status on the API server.
-func (c *SupervisorMachineContext) Patch() error {
-	return c.PatchHelper.Patch(c, c.VSphereMachine)
+func (c *SupervisorMachineContext) Patch(ctx context.Context) error {
+	return c.PatchHelper.Patch(ctx, c.VSphereMachine)
 }
 
 // GetVSphereMachine returns the VSphereMachine from the SupervisorMachineContext.
-func (c *SupervisorMachineContext) GetVSphereMachine() context.VSphereMachine {
+func (c *SupervisorMachineContext) GetVSphereMachine() capvcontext.VSphereMachine {
 	return c.VSphereMachine
 }
 
@@ -67,6 +68,6 @@ func (c *SupervisorMachineContext) GetClusterContext() *ClusterContext {
 }
 
 // SetBaseMachineContext sets the BaseMachineContext for the SupervisorMachineContext.
-func (c *SupervisorMachineContext) SetBaseMachineContext(base *context.BaseMachineContext) {
+func (c *SupervisorMachineContext) SetBaseMachineContext(base *capvcontext.BaseMachineContext) {
 	c.BaseMachineContext = base
 }

pkg/services/interfaces.go

@@ -23,7 +23,6 @@ import (
 	"k8s.io/apimachinery/pkg/runtime"
 	"k8s.io/apimachinery/pkg/types"
 	clusterv1 "sigs.k8s.io/cluster-api/api/v1beta1"
-	"sigs.k8s.io/controller-runtime/pkg/client"
 	"sigs.k8s.io/controller-runtime/pkg/reconcile"
 
 	infrav1 "sigs.k8s.io/cluster-api-provider-vsphere/apis/v1beta1"
@@ -33,12 +32,12 @@ import (
 
 // VSphereMachineService is used for vsphere VM lifecycle and syncing with VSphereMachine types.
 type VSphereMachineService interface {
-	FetchVSphereMachine(client client.Client, name types.NamespacedName) (capvcontext.MachineContext, error)
-	FetchVSphereCluster(client client.Client, cluster *clusterv1.Cluster, machineContext capvcontext.MachineContext) (capvcontext.MachineContext, error)
-	ReconcileDelete(machineCtx capvcontext.MachineContext) error
-	SyncFailureReason(machineCtx capvcontext.MachineContext) (bool, error)
-	ReconcileNormal(machineCtx capvcontext.MachineContext) (bool, error)
-	GetHostInfo(machineCtx capvcontext.MachineContext) (string, error)
+	FetchVSphereMachine(ctx context.Context, name types.NamespacedName) (capvcontext.MachineContext, error)
+	FetchVSphereCluster(ctx context.Context, cluster *clusterv1.Cluster, machineContext capvcontext.MachineContext) (capvcontext.MachineContext, error)
+	ReconcileDelete(ctx context.Context, machineCtx capvcontext.MachineContext) error
+	SyncFailureReason(ctx context.Context, machineCtx capvcontext.MachineContext) (bool, error)
+	ReconcileNormal(ctx context.Context, machineCtx capvcontext.MachineContext) (bool, error)
+	GetHostInfo(ctx context.Context, machineCtx capvcontext.MachineContext) (string, error)
 }
 
 // VirtualMachineService is a service for creating/updating/deleting virtual

pkg/services/services_suite_test.go

@@ -21,8 +21,11 @@ import (
 
 	. "github.com/onsi/ginkgo/v2"
 	. "github.com/onsi/gomega"
+	ctrl "sigs.k8s.io/controller-runtime"
 )
 
+var ctx = ctrl.SetupSignalHandler()
+
 func TestCAPVServices(t *testing.T) {
 	RegisterFailHandler(Fail)
 	RunSpecs(t, "CAPV services tests")