Merge pull request #11712 from k8s-infra-cherrypick-robot/cherry-pick-11693-to-release-1.9

[release-1.9] 🌱 Improve Machine create and delete logs

Author: k8s-ci-robot

controlplane/kubeadm/internal/control_plane.go

@@ -18,6 +18,9 @@ package internal
 
 import (
 	"context"
+	"fmt"
+	"sort"
+	"strings"
 
 	"github.com/pkg/errors"
 	apierrors "k8s.io/apimachinery/pkg/api/errors"
@@ -32,6 +35,7 @@ import (
 	controlplanev1 "sigs.k8s.io/cluster-api/controlplane/kubeadm/api/v1beta1"
 	"sigs.k8s.io/cluster-api/controlplane/kubeadm/internal/etcd"
 	"sigs.k8s.io/cluster-api/util/collections"
+	"sigs.k8s.io/cluster-api/util/conditions"
 	"sigs.k8s.io/cluster-api/util/failuredomains"
 	"sigs.k8s.io/cluster-api/util/patch"
 )
@@ -385,3 +389,81 @@ func (c *ControlPlane) InjectTestManagementCluster(managementCluster ManagementC
 	c.managementCluster = managementCluster
 	c.workloadCluster = nil
 }
+
+// StatusToLogKeyAndValues returns the following key/value pairs describing the overall status of the control plane:
+// - machines is the list of KCP machines; each machine might have additional notes surfacing
+//   - if the machine has been created in the current reconcile
+//   - if machines node ref is not yet set
+//   - if the machine has been marked for remediation
+//   - if there are unhealthy control plane component on the machine
+//   - if the machine has a deletion timestamp/has been deleted in the current reconcile
+//   - if the machine is not up to date with the KCP spec
+//
+// - etcdMembers list as reported by etcd.
+func (c *ControlPlane) StatusToLogKeyAndValues(newMachine, deletedMachine *clusterv1.Machine) []any {
+	controlPlaneMachineHealthConditions := []clusterv1.ConditionType{
+		controlplanev1.MachineAPIServerPodHealthyCondition,
+		controlplanev1.MachineControllerManagerPodHealthyCondition,
+		controlplanev1.MachineSchedulerPodHealthyCondition,
+	}
+	if c.IsEtcdManaged() {
+		controlPlaneMachineHealthConditions = append(controlPlaneMachineHealthConditions,
+			controlplanev1.MachineEtcdPodHealthyCondition,
+			controlplanev1.MachineEtcdMemberHealthyCondition,
+		)
+	}
+
+	machines := []string{}
+	for _, m := range c.Machines {
+		notes := []string{}
+
+		if m.Status.NodeRef == nil {
+			notes = append(notes, "status.nodeRef not set")
+		}
+
+		if c.MachinesToBeRemediatedByKCP().Has(m) {
+			notes = append(notes, "marked for remediation")
+		}
+
+		for _, condition := range controlPlaneMachineHealthConditions {
+			if conditions.IsUnknown(m, condition) {
+				notes = append(notes, strings.Replace(string(condition), "Healthy", " health unknown", -1))
+			}
+			if conditions.IsFalse(m, condition) {
+				notes = append(notes, strings.Replace(string(condition), "Healthy", " not healthy", -1))
+			}
+		}
+
+		if !c.UpToDateMachines().Has(m) {
+			notes = append(notes, "not up-to-date")
+		}
+
+		if deletedMachine != nil && m.Name == deletedMachine.Name {
+			notes = append(notes, "just deleted")
+		} else if !m.DeletionTimestamp.IsZero() {
+			notes = append(notes, "deleting")
+		}
+
+		name := m.Name
+		if len(notes) > 0 {
+			name = fmt.Sprintf("%s (%s)", name, strings.Join(notes, ", "))
+		}
+		machines = append(machines, name)
+	}
+
+	if newMachine != nil {
+		machines = append(machines, fmt.Sprintf("%s (just created)", newMachine.Name))
+	}
+	sort.Strings(machines)
+
+	etcdMembers := []string{}
+	for _, m := range c.EtcdMembers {
+		etcdMembers = append(etcdMembers, m.Name)
+	}
+	sort.Strings(etcdMembers)
+
+	return []any{
+		"machines", strings.Join(machines, ", "),
+		"etcdMembers", strings.Join(etcdMembers, ", "),
+	}
+}

controlplane/kubeadm/internal/control_plane_test.go

@@ -17,15 +17,18 @@ limitations under the License.
 package internal
 
 import (
+	"strings"
 	"testing"
 
+	"github.com/google/go-cmp/cmp"
 	. "github.com/onsi/gomega"
 	corev1 "k8s.io/api/core/v1"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	"k8s.io/utils/ptr"
 
 	clusterv1 "sigs.k8s.io/cluster-api/api/v1beta1"
 	controlplanev1 "sigs.k8s.io/cluster-api/controlplane/kubeadm/api/v1beta1"
+	"sigs.k8s.io/cluster-api/controlplane/kubeadm/internal/etcd"
 	"sigs.k8s.io/cluster-api/util/collections"
 	"sigs.k8s.io/cluster-api/util/conditions"
 )
@@ -252,6 +255,75 @@ func TestHasHealthyMachineStillProvisioning(t *testing.T) {
 	})
 }
 
+func TestStatusToLogKeyAndValues(t *testing.T) {
+	healthyMachine := &clusterv1.Machine{
+		ObjectMeta: metav1.ObjectMeta{Name: "healthy"},
+		Status: clusterv1.MachineStatus{
+			NodeRef: &corev1.ObjectReference{Name: "healthy-node"},
+			Conditions: []clusterv1.Condition{
+				{Type: controlplanev1.MachineAPIServerPodHealthyCondition, Status: corev1.ConditionTrue},
+				{Type: controlplanev1.MachineControllerManagerPodHealthyCondition, Status: corev1.ConditionTrue},
+				{Type: controlplanev1.MachineSchedulerPodHealthyCondition, Status: corev1.ConditionTrue},
+				{Type: controlplanev1.MachineEtcdPodHealthyCondition, Status: corev1.ConditionTrue},
+				{Type: controlplanev1.MachineEtcdMemberHealthyCondition, Status: corev1.ConditionTrue},
+			},
+		},
+	}
+
+	machineWithoutNode := &clusterv1.Machine{
+		ObjectMeta: metav1.ObjectMeta{Name: "without-node"},
+		Status: clusterv1.MachineStatus{
+			NodeRef: nil,
+			Conditions: []clusterv1.Condition{
+				{Type: controlplanev1.MachineAPIServerPodHealthyCondition, Status: corev1.ConditionUnknown},
+				{Type: controlplanev1.MachineControllerManagerPodHealthyCondition, Status: corev1.ConditionUnknown},
+				{Type: controlplanev1.MachineSchedulerPodHealthyCondition, Status: corev1.ConditionUnknown},
+				{Type: controlplanev1.MachineEtcdPodHealthyCondition, Status: corev1.ConditionUnknown},
+				{Type: controlplanev1.MachineEtcdMemberHealthyCondition, Status: corev1.ConditionFalse}, // not a real use case, but used to test a code branch.
+			},
+		},
+	}
+
+	machineJustCreated := &clusterv1.Machine{ObjectMeta: metav1.ObjectMeta{Name: "just-created"}}
+
+	machineJustDeleted := healthyMachine.DeepCopy()
+	machineJustDeleted.Name = "just-deleted"
+
+	machineNotUpToDate := healthyMachine.DeepCopy()
+	machineNotUpToDate.Name = "not-up-to-date"
+
+	machineMarkedForRemediation := healthyMachine.DeepCopy()
+	machineMarkedForRemediation.Name = "marked-for-remediation"
+	machineMarkedForRemediation.Status.Conditions = append(machineMarkedForRemediation.Status.Conditions,
+		clusterv1.Condition{Type: clusterv1.MachineHealthCheckSucceededCondition, Status: corev1.ConditionFalse},
+		clusterv1.Condition{Type: clusterv1.MachineOwnerRemediatedCondition, Status: corev1.ConditionFalse},
+	)
+
+	g := NewWithT(t)
+	c := &ControlPlane{
+		KCP:                 &controlplanev1.KubeadmControlPlane{},
+		Machines:            collections.FromMachines(healthyMachine, machineWithoutNode, machineJustDeleted, machineNotUpToDate, machineMarkedForRemediation),
+		machinesNotUptoDate: collections.FromMachines(machineNotUpToDate),
+		EtcdMembers:         []*etcd.Member{{Name: "m1"}, {Name: "m2"}, {Name: "m3"}},
+	}
+
+	got := c.StatusToLogKeyAndValues(machineJustCreated, machineJustDeleted)
+
+	g.Expect(got).To(HaveLen(4))
+	g.Expect(got[0]).To(Equal("machines"))
+	machines := strings.Join([]string{
+		"healthy",
+		"just-created (just created)",
+		"just-deleted (just deleted)",
+		"marked-for-remediation (marked for remediation)",
+		"not-up-to-date (not up-to-date)",
+		"without-node (status.nodeRef not set, APIServerPod health unknown, ControllerManagerPod health unknown, SchedulerPod health unknown, EtcdPod health unknown, EtcdMember not healthy)",
+	}, ", ")
+	g.Expect(got[1]).To(Equal(machines), cmp.Diff(got[1], machines))
+	g.Expect(got[2]).To(Equal("etcdMembers"))
+	g.Expect(got[3]).To(Equal("m1, m2, m3"))
+}
+
 type machineOpt func(*clusterv1.Machine)
 
 func failureDomain(controlPlane bool) clusterv1.FailureDomainSpec {

controlplane/kubeadm/internal/controllers/controller.go

@@ -672,10 +672,13 @@ func (r *KubeadmControlPlaneReconciler) reconcileDelete(ctx context.Context, con
 			continue
 		}
 
-		log.Info("Deleting control plane Machine")
 		if err := r.Client.Delete(ctx, machineToDelete); err != nil && !apierrors.IsNotFound(err) {
 			errs = append(errs, errors.Wrapf(err, "failed to delete control plane Machine %s", klog.KObj(machineToDelete)))
 		}
+		// Note: We intentionally log after Delete because we want this log line to show up only after DeletionTimestamp has been set.
+		// Also, setting DeletionTimestamp doesn't mean the Machine is actually deleted (deletion takes some time).
+		log.WithValues(controlPlane.StatusToLogKeyAndValues(nil, machineToDelete)...).
+			Info("Deleting Machine (KubeadmControlPlane deleted)")
 	}
 	if len(errs) > 0 {
 		err := kerrors.NewAggregate(errs)

controlplane/kubeadm/internal/controllers/helpers.go

@@ -182,13 +182,13 @@ func (r *KubeadmControlPlaneReconciler) reconcileExternalReference(ctx context.C
 	return patchHelper.Patch(ctx, obj)
 }
 
-func (r *KubeadmControlPlaneReconciler) cloneConfigsAndGenerateMachine(ctx context.Context, cluster *clusterv1.Cluster, kcp *controlplanev1.KubeadmControlPlane, bootstrapSpec *bootstrapv1.KubeadmConfigSpec, failureDomain *string) error {
+func (r *KubeadmControlPlaneReconciler) cloneConfigsAndGenerateMachine(ctx context.Context, cluster *clusterv1.Cluster, kcp *controlplanev1.KubeadmControlPlane, bootstrapSpec *bootstrapv1.KubeadmConfigSpec, failureDomain *string) (*clusterv1.Machine, error) {
 	var errs []error
 
 	// Compute desired Machine
 	machine, err := r.computeDesiredMachine(kcp, cluster, failureDomain, nil)
 	if err != nil {
-		return errors.Wrap(err, "failed to create Machine: failed to compute desired Machine")
+		return nil, errors.Wrap(err, "failed to create Machine: failed to compute desired Machine")
 	}
 
 	// Since the cloned resource should eventually have a controller ref for the Machine, we create an
@@ -220,7 +220,7 @@ func (r *KubeadmControlPlaneReconciler) cloneConfigsAndGenerateMachine(ctx conte
 		// Safe to return early here since no resources have been created yet.
 		conditions.MarkFalse(kcp, controlplanev1.MachinesCreatedCondition, controlplanev1.InfrastructureTemplateCloningFailedReason,
 			clusterv1.ConditionSeverityError, err.Error())
-		return errors.Wrap(err, "failed to clone infrastructure template")
+		return nil, errors.Wrap(err, "failed to clone infrastructure template")
 	}
 	machine.Spec.InfrastructureRef = *infraRef
 
@@ -248,11 +248,10 @@ func (r *KubeadmControlPlaneReconciler) cloneConfigsAndGenerateMachine(ctx conte
 		if err := r.cleanupFromGeneration(ctx, infraRef, bootstrapRef); err != nil {
 			errs = append(errs, errors.Wrap(err, "failed to cleanup generated resources"))
 		}
-
-		return kerrors.NewAggregate(errs)
+		return nil, kerrors.NewAggregate(errs)
 	}
 
-	return nil
+	return machine, nil
 }
 
 func (r *KubeadmControlPlaneReconciler) cleanupFromGeneration(ctx context.Context, remoteRefs ...*corev1.ObjectReference) error {

controlplane/kubeadm/internal/controllers/helpers_test.go

@@ -374,7 +374,8 @@ func TestCloneConfigsAndGenerateMachine(t *testing.T) {
 	bootstrapSpec := &bootstrapv1.KubeadmConfigSpec{
 		JoinConfiguration: &bootstrapv1.JoinConfiguration{},
 	}
-	g.Expect(r.cloneConfigsAndGenerateMachine(ctx, cluster, kcp, bootstrapSpec, nil)).To(Succeed())
+	_, err := r.cloneConfigsAndGenerateMachine(ctx, cluster, kcp, bootstrapSpec, nil)
+	g.Expect(err).To(Succeed())
 
 	machineList := &clusterv1.MachineList{}
 	g.Expect(env.GetAPIReader().List(ctx, machineList, client.InNamespace(cluster.Namespace))).To(Succeed())
@@ -463,7 +464,8 @@ func TestCloneConfigsAndGenerateMachineFail(t *testing.T) {
 
 	// Try to break Infra Cloning
 	kcp.Spec.MachineTemplate.InfrastructureRef.Name = "something_invalid"
-	g.Expect(r.cloneConfigsAndGenerateMachine(ctx, cluster, kcp, bootstrapSpec, nil)).To(HaveOccurred())
+	_, err := r.cloneConfigsAndGenerateMachine(ctx, cluster, kcp, bootstrapSpec, nil)
+	g.Expect(err).To(HaveOccurred())
 	g.Expect(&kcp.GetConditions()[0]).Should(conditions.HaveSameStateOf(&clusterv1.Condition{
 		Type:     controlplanev1.MachinesCreatedCondition,
 		Status:   corev1.ConditionFalse,

controlplane/kubeadm/internal/controllers/remediation.go

@@ -311,7 +311,10 @@ func (r *KubeadmControlPlaneReconciler) reconcileUnhealthyMachines(ctx context.C
 	}
 
 	// Surface the operation is in progress.
-	log.Info("Remediating unhealthy machine")
+	// Note: We intentionally log after Delete because we want this log line to show up only after DeletionTimestamp has been set.
+	// Also, setting DeletionTimestamp doesn't mean the Machine is actually deleted (deletion takes some time).
+	log.WithValues(controlPlane.StatusToLogKeyAndValues(nil, machineToBeRemediated)...).
+		Info("Deleting Machine (remediating unhealthy Machine)")
 	conditions.MarkFalse(machineToBeRemediated, clusterv1.MachineOwnerRemediatedCondition, clusterv1.RemediationInProgressReason, clusterv1.ConditionSeverityWarning, "")
 
 	v1beta2conditions.Set(machineToBeRemediated, metav1.Condition{

controlplane/kubeadm/internal/controllers/scale.go

@@ -53,12 +53,19 @@ func (r *KubeadmControlPlaneReconciler) initializeControlPlane(ctx context.Conte
 		return ctrl.Result{}, err
 	}
 
-	if err := r.cloneConfigsAndGenerateMachine(ctx, controlPlane.Cluster, controlPlane.KCP, bootstrapSpec, fd); err != nil {
+	newMachine, err := r.cloneConfigsAndGenerateMachine(ctx, controlPlane.Cluster, controlPlane.KCP, bootstrapSpec, fd)
+	if err != nil {
 		logger.Error(err, "Failed to create initial control plane Machine")
 		r.recorder.Eventf(controlPlane.KCP, corev1.EventTypeWarning, "FailedInitialization", "Failed to create initial control plane Machine for cluster %s control plane: %v", klog.KObj(controlPlane.Cluster), err)
 		return ctrl.Result{}, err
 	}
 
+	logger.WithValues(controlPlane.StatusToLogKeyAndValues(newMachine, nil)...).
+		Info("Machine created (scale up)",
+			"Machine", klog.KObj(newMachine),
+			newMachine.Spec.InfrastructureRef.Kind, klog.KRef(newMachine.Spec.InfrastructureRef.Namespace, newMachine.Spec.InfrastructureRef.Name),
+			newMachine.Spec.Bootstrap.ConfigRef.Kind, klog.KRef(newMachine.Spec.Bootstrap.ConfigRef.Namespace, newMachine.Spec.Bootstrap.ConfigRef.Name))
+
 	// Requeue the control plane, in case there are additional operations to perform
 	return ctrl.Result{Requeue: true}, nil
 }
@@ -87,12 +94,19 @@ func (r *KubeadmControlPlaneReconciler) scaleUpControlPlane(ctx context.Context,
 		return ctrl.Result{}, err
 	}
 
-	if err := r.cloneConfigsAndGenerateMachine(ctx, controlPlane.Cluster, controlPlane.KCP, bootstrapSpec, fd); err != nil {
+	newMachine, err := r.cloneConfigsAndGenerateMachine(ctx, controlPlane.Cluster, controlPlane.KCP, bootstrapSpec, fd)
+	if err != nil {
 		logger.Error(err, "Failed to create additional control plane Machine")
 		r.recorder.Eventf(controlPlane.KCP, corev1.EventTypeWarning, "FailedScaleUp", "Failed to create additional control plane Machine for cluster % control plane: %v", klog.KObj(controlPlane.Cluster), err)
 		return ctrl.Result{}, err
 	}
 
+	logger.WithValues(controlPlane.StatusToLogKeyAndValues(newMachine, nil)...).
+		Info("Machine created (scale up)",
+			"Machine", klog.KObj(newMachine),
+			newMachine.Spec.InfrastructureRef.Kind, klog.KRef(newMachine.Spec.InfrastructureRef.Namespace, newMachine.Spec.InfrastructureRef.Name),
+			newMachine.Spec.Bootstrap.ConfigRef.Kind, klog.KRef(newMachine.Spec.Bootstrap.ConfigRef.Namespace, newMachine.Spec.Bootstrap.ConfigRef.Name))
+
 	// Requeue the control plane, in case there are other operations to perform
 	return ctrl.Result{Requeue: true}, nil
 }
@@ -138,13 +152,16 @@ func (r *KubeadmControlPlaneReconciler) scaleDownControlPlane(
 		// NOTE: etcd member removal will be performed by the kcp-cleanup hook after machine completes drain & all volumes are detached.
 	}
 
-	logger = logger.WithValues("Machine", klog.KObj(machineToDelete))
 	if err := r.Client.Delete(ctx, machineToDelete); err != nil && !apierrors.IsNotFound(err) {
 		logger.Error(err, "Failed to delete control plane machine")
 		r.recorder.Eventf(controlPlane.KCP, corev1.EventTypeWarning, "FailedScaleDown",
 			"Failed to delete control plane Machine %s for cluster %s control plane: %v", machineToDelete.Name, klog.KObj(controlPlane.Cluster), err)
 		return ctrl.Result{}, err
 	}
+	// Note: We intentionally log after Delete because we want this log line to show up only after DeletionTimestamp has been set.
+	// Also, setting DeletionTimestamp doesn't mean the Machine is actually deleted (deletion takes some time).
+	logger.WithValues(controlPlane.StatusToLogKeyAndValues(nil, machineToDelete)...).
+		Info("Deleting Machine (scale down)", "Machine", klog.KObj(machineToDelete))
 
 	// Requeue the control plane, in case there are additional operations to perform
 	return ctrl.Result{Requeue: true}, nil

internal/controllers/machineset/machineset_controller.go

@@ -427,10 +427,12 @@ func (r *Reconciler) reconcileDelete(ctx context.Context, s *scope) (ctrl.Result
 	// else delete owned machines.
 	for _, machine := range machineList {
 		if machine.DeletionTimestamp.IsZero() {
-			log.Info("Deleting Machine", "Machine", klog.KObj(machine))
 			if err := r.Client.Delete(ctx, machine); err != nil && !apierrors.IsNotFound(err) {
 				return ctrl.Result{}, errors.Wrapf(err, "failed to delete Machine %s", klog.KObj(machine))
 			}
+			// Note: We intentionally log after Delete because we want this log line to show up only after DeletionTimestamp has been set.
+			// Also, setting DeletionTimestamp doesn't mean the Machine is actually deleted (deletion takes some time).
+			log.Info("Deleting Machine (MachineSet deleted)", "Machine", klog.KObj(machine))
 		}
 	}
 
@@ -794,7 +796,7 @@ func (r *Reconciler) syncReplicas(ctx context.Context, s *scope) (ctrl.Result, e
 				continue
 			}
 
-			log.Info(fmt.Sprintf("Created machine %d of %d", i+1, diff), "Machine", klog.KObj(machine))
+			log.Info(fmt.Sprintf("Machine created (scale up, creating %d of %d)", i+1, diff), "Machine", klog.KObj(machine))
 			r.recorder.Eventf(ms, corev1.EventTypeNormal, "SuccessfulCreate", "Created machine %q", machine.Name)
 			machineList = append(machineList, machine)
 		}
@@ -816,16 +818,18 @@ func (r *Reconciler) syncReplicas(ctx context.Context, s *scope) (ctrl.Result, e
 		for i, machine := range machinesToDelete {
 			log := log.WithValues("Machine", klog.KObj(machine))
 			if machine.GetDeletionTimestamp().IsZero() {
-				log.Info(fmt.Sprintf("Deleting machine %d of %d", i+1, diff))
 				if err := r.Client.Delete(ctx, machine); err != nil {
 					log.Error(err, "Unable to delete Machine")
 					r.recorder.Eventf(ms, corev1.EventTypeWarning, "FailedDelete", "Failed to delete machine %q: %v", machine.Name, err)
 					errs = append(errs, err)
 					continue
 				}
+				// Note: We intentionally log after Delete because we want this log line to show up only after DeletionTimestamp has been set.
+				// Also, setting DeletionTimestamp doesn't mean the Machine is actually deleted (deletion takes some time).
+				log.Info(fmt.Sprintf("Deleting Machine (scale down, deleting %d of %d)", i+1, diff))
 				r.recorder.Eventf(ms, corev1.EventTypeNormal, "SuccessfulDelete", "Deleted machine %q", machine.Name)
 			} else {
-				log.Info(fmt.Sprintf("Waiting for machine %d of %d to be deleted", i+1, diff))
+				log.Info(fmt.Sprintf("Waiting for Machine to be deleted (scale down, deleting %d of %d)", i+1, diff))
 			}
 		}
 
@@ -1492,10 +1496,12 @@ func (r *Reconciler) reconcileUnhealthyMachines(ctx context.Context, s *scope) (
 	}
 	var errs []error
 	for _, m := range machinesToRemediate {
-		log.Info("Deleting unhealthy Machine", "Machine", klog.KObj(m))
 		if err := r.Client.Delete(ctx, m); err != nil && !apierrors.IsNotFound(err) {
 			errs = append(errs, errors.Wrapf(err, "failed to delete Machine %s", klog.KObj(m)))
 		}
+		// Note: We intentionally log after Delete because we want this log line to show up only after DeletionTimestamp has been set.
+		// Also, setting DeletionTimestamp doesn't mean the Machine is actually deleted (deletion takes some time).
+		log.Info("Deleting Machine (remediating unhealthy Machine)", "Machine", klog.KObj(m))
 	}
 	if len(errs) > 0 {
 		return ctrl.Result{}, errors.Wrapf(kerrors.NewAggregate(errs), "failed to delete unhealthy Machines")