Merge pull request #12997 from fabriziopandini/add-more-info-to-rollout-planner-logs

🌱 Add more info to logs for rollout changes

Author: k8s-ci-robot

internal/controllers/machinedeployment/machinedeployment_controller.go

@@ -19,6 +19,7 @@ package machinedeployment
 import (
 	"context"
 	"fmt"
+	"sort"
 	"strings"
 
 	"github.com/pkg/errors"
@@ -332,24 +333,53 @@ func (r *Reconciler) reconcile(ctx context.Context, s *scope) error {
 // Note: When the newMS has been created by the rollout planner, also wait for the cache to be up to date.
 func (r *Reconciler) createOrUpdateMachineSetsAndSyncMachineDeploymentRevision(ctx context.Context, p *rolloutPlanner) error {
 	log := ctrl.LoggerFrom(ctx)
-	allMSs := append(p.oldMSs, p.newMS)
 
-	for _, ms := range allMSs {
-		log = log.WithValues("MachineSet", klog.KObj(ms))
-		ctx = ctrl.LoggerInto(ctx, log)
+	// Note: newMS goes first so in the logs we will have first create/scale up newMS, then scale down oldMSs
+	allMSs := append([]*clusterv1.MachineSet{p.newMS}, p.oldMSs...)
 
+	// Get all the diff introduced by the rollout planner.
+	// Note: collect all the diff first, so for each change we can add an overview of all the MachineSets
+	// in the MachineDeployment, because those info are required to understand why a change happened.
+	machineSetsDiff := map[string]machineSetDiff{}
+	machineSetsSummary := map[string]string{}
+	for _, ms := range allMSs {
+		// Update spec.Replicas in the MachineSet.
 		if scaleIntent, ok := p.scaleIntents[ms.Name]; ok {
-			ms.Spec.Replicas = &scaleIntent
+			ms.Spec.Replicas = ptr.To(scaleIntent)
 		}
 
-		if ms.GetUID() == "" {
+		diff := p.getMachineSetDiff(ms)
+		machineSetsDiff[ms.Name] = diff
+		machineSetsSummary[ms.Name] = diff.Summary
+	}
+
+	// Apply changes to MachineSets.
+	for _, ms := range allMSs {
+		log := log.WithValues("MachineSet", klog.KObj(ms))
+		ctx := ctrl.LoggerInto(ctx, log)
+
+		// Retrieve the diff for the MachineSet.
+		// Note: no need to check for diff doesn't exist, all the diff have been computed right above.
+		diff := machineSetsDiff[ms.Name]
+
+		// Add to the log kv pairs providing the overview of all the MachineSets computed above.
+		// Note: This value should not be added to the context to prevent propagation to other func.
+		log = log.WithValues("machineSets", machineSetsSummary)
+
+		if diff.OriginalMS == nil {
 			// Create the MachineSet.
 			if err := ssa.Patch(ctx, r.Client, machineDeploymentManagerName, ms); err != nil {
 				r.recorder.Eventf(p.md, corev1.EventTypeWarning, "FailedCreate", "Failed to create MachineSet %s: %v", klog.KObj(ms), err)
 				return errors.Wrapf(err, "failed to create MachineSet %s", klog.KObj(ms))
 			}
-			log.Info(fmt.Sprintf("MachineSet created (%s)", p.createReason))
-			r.recorder.Eventf(p.md, corev1.EventTypeNormal, "SuccessfulCreate", "Created MachineSet %s with %d replicas", klog.KObj(ms), ptr.Deref(ms.Spec.Replicas, 0))
+			if len(p.oldMSs) > 0 {
+				log.Info(fmt.Sprintf("MachineSets need rollout: %s", strings.Join(machineSetNames(p.oldMSs), ", ")), "reason", p.createReason)
+			}
+			log.Info(fmt.Sprintf("MachineSet %s created, it is now the current MachineSet", ms.Name))
+			if diff.DesiredReplicas > 0 {
+				log.Info(fmt.Sprintf("Scaled up current MachineSet %s from 0 to %d replicas (+%[2]d)", ms.Name, diff.DesiredReplicas))
+			}
+			r.recorder.Eventf(p.md, corev1.EventTypeNormal, "SuccessfulCreate", "Created MachineSet %s with %d replicas", klog.KObj(ms), diff.DesiredReplicas)
 
 			// Keep trying to get the MachineSet. This will force the cache to update and prevent any future reconciliation of
 			// the MachineDeployment to reconcile with an outdated list of MachineSets which could lead to unwanted creation of
@@ -361,14 +391,21 @@ func (r *Reconciler) createOrUpdateMachineSetsAndSyncMachineDeploymentRevision(c
 			continue
 		}
 
-		// Update the MachineSet to propagate in-place mutable fields from the MachineDeployment and/or changes applied by the rollout planner.
-		originalMS, ok := p.originalMS[ms.Name]
-		if !ok {
-			return errors.Errorf("failed to update MachineSet %s, original MS is missing", klog.KObj(ms))
+		// Add to the log kv pairs providing context and details about changes in this MachineSet (reason, diff)
+		// Note: Those values should not be added to the context to prevent propagation to other func.
+		statusToLogKeyAndValues := []any{
+			"reason", diff.Reason,
+			"diff", diff.OtherChanges,
 		}
-		originalReplicas := ptr.Deref(originalMS.Spec.Replicas, 0)
+		if len(p.acknowledgedMachineNames) > 0 {
+			statusToLogKeyAndValues = append(statusToLogKeyAndValues, "acknowledgedMachines", sortAndJoin(p.acknowledgedMachineNames))
+		}
+		if len(p.updatingMachineNames) > 0 {
+			statusToLogKeyAndValues = append(statusToLogKeyAndValues, "updatingMachines", sortAndJoin(p.updatingMachineNames))
+		}
+		log = log.WithValues(statusToLogKeyAndValues...)
 
-		err := ssa.Patch(ctx, r.Client, machineDeploymentManagerName, ms, ssa.WithCachingProxy{Cache: r.ssaCache, Original: originalMS})
+		err := ssa.Patch(ctx, r.Client, machineDeploymentManagerName, ms, ssa.WithCachingProxy{Cache: r.ssaCache, Original: diff.OriginalMS})
 		if err != nil {
 			// Note: If we are Applying a MachineSet with UID set and the MachineSet does not exist anymore, the
 			// kube-apiserver returns a conflict error.
@@ -379,25 +416,20 @@ func (r *Reconciler) createOrUpdateMachineSetsAndSyncMachineDeploymentRevision(c
 			return errors.Wrapf(err, "failed to update MachineSet %s", klog.KObj(ms))
 		}
 
-		changes := getAnnotationChanges(originalMS, ms)
-
-		newReplicas := ptr.Deref(ms.Spec.Replicas, 0)
-		if newReplicas < originalReplicas {
-			changes = append(changes, fmt.Sprintf("replicas %d", newReplicas))
-			log.Info(fmt.Sprintf("Scaled down MachineSet %s to %d replicas (-%d)", ms.Name, newReplicas, originalReplicas-newReplicas), "diff", strings.Join(changes, ","))
-			r.recorder.Eventf(p.md, corev1.EventTypeNormal, "SuccessfulScale", "Scaled down MachineSet %v: %d -> %d", ms.Name, originalReplicas, newReplicas)
+		if diff.DesiredReplicas < diff.OriginalReplicas {
+			log.Info(fmt.Sprintf("Scaled down %s MachineSet %s from %d to %d replicas (-%d)", diff.Type, ms.Name, diff.OriginalReplicas, diff.DesiredReplicas, diff.OriginalReplicas-diff.DesiredReplicas))
+			r.recorder.Eventf(p.md, corev1.EventTypeNormal, "SuccessfulScale", "Scaled down MachineSet %v: %d -> %d", ms.Name, diff.OriginalReplicas, diff.DesiredReplicas)
 		}
-		if newReplicas > originalReplicas {
-			changes = append(changes, fmt.Sprintf("replicas %d", newReplicas))
-			log.Info(fmt.Sprintf("Scaled up MachineSet %s to %d replicas (+%d)", ms.Name, newReplicas, newReplicas-originalReplicas), "diff", strings.Join(changes, ","))
-			r.recorder.Eventf(p.md, corev1.EventTypeNormal, "SuccessfulScale", "Scaled up MachineSet %v: %d -> %d", ms.Name, originalReplicas, newReplicas)
+		if diff.DesiredReplicas > diff.OriginalReplicas {
+			log.Info(fmt.Sprintf("Scaled up %s MachineSet %s from %d to %d replicas (+%d)", diff.Type, ms.Name, diff.OriginalReplicas, diff.DesiredReplicas, diff.DesiredReplicas-diff.OriginalReplicas))
+			r.recorder.Eventf(p.md, corev1.EventTypeNormal, "SuccessfulScale", "Scaled up MachineSet %v: %d -> %d", ms.Name, diff.OriginalReplicas, diff.DesiredReplicas)
 		}
-		if newReplicas == originalReplicas && len(changes) > 0 {
-			log.Info(fmt.Sprintf("Updated MachineSet %s", ms.Name), "diff", strings.Join(changes, ","))
+		if diff.DesiredReplicas == diff.OriginalReplicas && diff.OtherChanges != "" {
+			log.Info(fmt.Sprintf("Updated %s MachineSet %s", diff.Type, ms.Name))
 		}
 
 		// Only wait for cache if the object was changed.
-		if originalMS.ResourceVersion != ms.ResourceVersion {
+		if diff.OriginalMS.ResourceVersion != ms.ResourceVersion {
 			if err := clientutil.WaitForCacheToBeUpToDate(ctx, r.Client, "MachineSet update", ms); err != nil {
 				return err
 			}
@@ -415,40 +447,13 @@ func (r *Reconciler) createOrUpdateMachineSetsAndSyncMachineDeploymentRevision(c
 	return nil
 }
 
-func getAnnotationChanges(originalMS *clusterv1.MachineSet, ms *clusterv1.MachineSet) []string {
-	changes := []string{}
-	if originalMS.Annotations[clusterv1.MachineSetMoveMachinesToMachineSetAnnotation] != ms.Annotations[clusterv1.MachineSetMoveMachinesToMachineSetAnnotation] {
-		if value, ok := ms.Annotations[clusterv1.MachineSetMoveMachinesToMachineSetAnnotation]; ok {
-			changes = append(changes, fmt.Sprintf("%s: %s", clusterv1.MachineSetMoveMachinesToMachineSetAnnotation, value))
-		} else {
-			changes = append(changes, fmt.Sprintf("%s removed", clusterv1.MachineSetMoveMachinesToMachineSetAnnotation))
-		}
-	}
-
-	if originalMS.Annotations[clusterv1.MachineSetReceiveMachinesFromMachineSetsAnnotation] != ms.Annotations[clusterv1.MachineSetReceiveMachinesFromMachineSetsAnnotation] {
-		if value, ok := ms.Annotations[clusterv1.MachineSetReceiveMachinesFromMachineSetsAnnotation]; ok {
-			changes = append(changes, fmt.Sprintf("%s: %s", clusterv1.MachineSetReceiveMachinesFromMachineSetsAnnotation, value))
-		} else {
-			changes = append(changes, fmt.Sprintf("%s removed", clusterv1.MachineSetReceiveMachinesFromMachineSetsAnnotation))
-		}
-	}
-
-	if originalMS.Annotations[clusterv1.AcknowledgedMoveAnnotation] != ms.Annotations[clusterv1.AcknowledgedMoveAnnotation] {
-		if value, ok := ms.Annotations[clusterv1.AcknowledgedMoveAnnotation]; ok {
-			changes = append(changes, fmt.Sprintf("%s: %s", clusterv1.AcknowledgedMoveAnnotation, value))
-		} else {
-			changes = append(changes, fmt.Sprintf("%s removed", clusterv1.AcknowledgedMoveAnnotation))
-		}
-	}
-
-	if originalMS.Annotations[clusterv1.DisableMachineCreateAnnotation] != ms.Annotations[clusterv1.DisableMachineCreateAnnotation] {
-		if value, ok := ms.Annotations[clusterv1.DisableMachineCreateAnnotation]; ok {
-			changes = append(changes, fmt.Sprintf("%s: %s", clusterv1.DisableMachineCreateAnnotation, value))
-		} else {
-			changes = append(changes, fmt.Sprintf("%s removed", clusterv1.DisableMachineCreateAnnotation))
-		}
+func machineSetNames(machineSets []*clusterv1.MachineSet) []string {
+	names := []string{}
+	for _, ms := range machineSets {
+		names = append(names, ms.Name)
 	}
-	return changes
+	sort.Strings(names)
+	return names
 }
 
 func (r *Reconciler) reconcileDelete(ctx context.Context, s *scope) error {

internal/controllers/machinedeployment/machinedeployment_rollout_ondelete.go

@@ -111,6 +111,7 @@ func (p *rolloutPlanner) reconcileOldMachineSetsOnDelete(ctx context.Context) {
 		scaleDownCount := max(ptr.Deref(oldMS.Spec.Replicas, 0)-ptr.Deref(oldMS.Status.Replicas, 0), 0)
 		if scaleDownCount > 0 {
 			newScaleIntent := max(ptr.Deref(oldMS.Spec.Replicas, 0)-scaleDownCount, 0)
+			p.addNote(oldMS, "scale down to align to existing Machines")
 			log.V(5).Info(fmt.Sprintf("Setting scale down intent for MachineSet %s to %d replicas (-%d)", oldMS.Name, newScaleIntent, scaleDownCount), "MachineSet", klog.KObj(oldMS))
 			p.scaleIntents[oldMS.Name] = newScaleIntent
 
@@ -138,6 +139,7 @@ func (p *rolloutPlanner) reconcileOldMachineSetsOnDelete(ctx context.Context) {
 		scaleDownCount := min(scaleIntent, totalScaleDownCount)
 		if scaleDownCount > 0 {
 			newScaleIntent := max(ptr.Deref(oldMS.Spec.Replicas, 0)-scaleDownCount, 0)
+			p.addNote(oldMS, "scale down to align MachineSet spec.replicas to MachineDeployment spec.replicas")
 			log.V(5).Info(fmt.Sprintf("Setting scale down intent for MachineSet %s to %d replicas (-%d)", oldMS.Name, newScaleIntent, scaleDownCount), "MachineSet", klog.KObj(oldMS))
 			p.scaleIntents[oldMS.Name] = newScaleIntent
 

internal/controllers/machinedeployment/machinedeployment_rollout_ondelete_test.go

@@ -20,7 +20,6 @@ import (
 	"context"
 	"fmt"
 	"math/rand"
-	"os"
 	"strings"
 	"testing"
 	"time"
@@ -29,7 +28,6 @@ import (
 	. "github.com/onsi/gomega"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	"k8s.io/klog/v2"
-	"k8s.io/klog/v2/textlogger"
 	"k8s.io/utils/ptr"
 	ctrl "sigs.k8s.io/controller-runtime"
 
@@ -45,6 +43,7 @@ func TestReconcileOldMachineSetsOnDelete(t *testing.T) {
 		newMachineSet     *clusterv1.MachineSet
 		oldMachineSets    []*clusterv1.MachineSet
 		expectScaleIntent map[string]int32
+		expectedNotes     map[string][]string
 		error             error
 	}{
 		{
@@ -98,6 +97,7 @@ func TestReconcileOldMachineSetsOnDelete(t *testing.T) {
 			expectScaleIntent: map[string]int32{
 				// no new intent for old MS
 			},
+			expectedNotes: map[string][]string{},
 		},
 		{
 			name: "OnDelete strategy: scale down oldMSs when machines have been deleted",
@@ -152,6 +152,10 @@ func TestReconcileOldMachineSetsOnDelete(t *testing.T) {
 				"ms1": 2, // scale down by one, one machines has been deleted
 				"ms2": 0, // scale down by one, one machines has been deleted
 			},
+			expectedNotes: map[string][]string{
+				"ms1": {"scale down to align to existing Machines"},
+				"ms2": {"scale down to align to existing Machines"},
+			},
 		},
 		{
 			name: "OnDelete strategy: scale down oldMSs when md has been scaled down",
@@ -206,6 +210,10 @@ func TestReconcileOldMachineSetsOnDelete(t *testing.T) {
 				"ms1": 0, // scale down by one, 1 exceeding machine removed from ms1
 				"ms2": 1, // scale down by one, 1 exceeding machine removed from ms2
 			},
+			expectedNotes: map[string][]string{
+				"ms1": {"scale down to align MachineSet spec.replicas to MachineDeployment spec.replicas"},
+				"ms2": {"scale down to align MachineSet spec.replicas to MachineDeployment spec.replicas"},
+			},
 		},
 		{
 			name: "OnDelete strategy: scale down oldMSs when md has been scaled down, keeps into account newMS scale intent",
@@ -263,6 +271,10 @@ func TestReconcileOldMachineSetsOnDelete(t *testing.T) {
 				"ms1": 0, // scale down by one, 1 exceeding machine removed from ms1
 				"ms2": 1, // scale down by one, 1 exceeding machine removed from ms2
 			},
+			expectedNotes: map[string][]string{
+				"ms1": {"scale down to align MachineSet spec.replicas to MachineDeployment spec.replicas"},
+				"ms2": {"scale down to align MachineSet spec.replicas to MachineDeployment spec.replicas"},
+			},
 		},
 		{
 			name: "OnDelete strategy: scale down oldMSs when md has been scaled down keeps into account deleted machines",
@@ -317,6 +329,10 @@ func TestReconcileOldMachineSetsOnDelete(t *testing.T) {
 				"ms1": 0, // scale down by one, one machines has been deleted
 				"ms2": 1, // scale down by one, 1 exceeding machine removed from ms1
 			},
+			expectedNotes: map[string][]string{
+				"ms1": {"scale down to align to existing Machines"},
+				"ms2": {"scale down to align MachineSet spec.replicas to MachineDeployment spec.replicas"},
+			},
 		},
 	}
 	for _, tt := range testCases {
@@ -330,6 +346,7 @@ func TestReconcileOldMachineSetsOnDelete(t *testing.T) {
 
 			planner.reconcileOldMachineSetsOnDelete(ctx)
 			g.Expect(planner.scaleIntents).To(Equal(tt.expectScaleIntent), "unexpected scaleIntents")
+			g.Expect(planner.notes).To(Equal(tt.expectedNotes), "unexpected notes")
 		})
 	}
 }
@@ -390,9 +407,6 @@ type onDeleteSequenceTestCase struct {
 }
 
 func Test_OnDeleteSequences(t *testing.T) {
-	ctx := context.Background()
-	ctx = ctrl.LoggerInto(ctx, textlogger.NewLogger(textlogger.NewConfig(textlogger.Verbosity(5), textlogger.Output(os.Stdout))))
-
 	tests := []onDeleteSequenceTestCase{
 		{ // delete 1
 			name:                "3 replicas, maxUserUnavailable 1",
@@ -553,7 +567,7 @@ func runOnDeleteTestCase(ctx context.Context, t *testing.T, tt onDeleteSequenceT
 	desired := computeDesiredRolloutScope(current, tt.desiredMachineNames)
 
 	// Log initial state
-	fLogger.Logf("[Test] Initial state\n%s", current)
+	fLogger.Logf("[Test] Initial state\n%s", current.summary())
 	random := ""
 	if tt.randomControllerOrder {
 		random = fmt.Sprintf(", random(%d)", tt.seed)
@@ -577,7 +591,6 @@ func runOnDeleteTestCase(ctx context.Context, t *testing.T, tt onDeleteSequenceT
 			task := taskList[taskID]
 			if task == "md" {
 				fLogger.Logf("[MD controller] Iteration %d, Reconcile md", i)
-				fLogger.Logf("[MD controller] - Input to rollout planner\n%s", current)
 
 				// Running a small subset of MD reconcile (the rollout logic and a bit of setReplicas)
 				p := newRolloutPlanner(nil, nil)
@@ -618,7 +631,7 @@ func runOnDeleteTestCase(ctx context.Context, t *testing.T, tt onDeleteSequenceT
 				current.machineDeployment.Status.AvailableReplicas = mdutil.GetAvailableReplicaCountForMachineSets(current.machineSets)
 
 				// Log state after this reconcile
-				fLogger.Logf("[MD controller] - Result of rollout planner\n%s", current)
+				fLogger.Logf("[MD controller] - Result of rollout planner\n%s", current.rolloutPlannerResultSummary(p))
 			}
 
 			// Simulate the user deleting machines not upToDate; in order to make this realistic deletion will be performed
@@ -666,7 +679,7 @@ func runOnDeleteTestCase(ctx context.Context, t *testing.T, tt onDeleteSequenceT
 			// Run mutators faking MS controllers
 			for _, ms := range current.machineSets {
 				if ms.Name == task {
-					fLogger.Logf("[MS controller] Iteration %d, Reconcile %s, %s", i, ms.Name, msLog(ms, current.machineSetMachines[ms.Name]))
+					fLogger.Logf("[MS controller] Iteration %d, Reconcile %s", i, current.machineSetSummary(ms))
 					err := machineSetControllerMutator(fLogger, ms, current)
 					g.Expect(err).ToNot(HaveOccurred())
 					break
@@ -686,7 +699,7 @@ func runOnDeleteTestCase(ctx context.Context, t *testing.T, tt onDeleteSequenceT
 
 		// Check if we are at the desired state
 		if current.Equal(desired) {
-			fLogger.Logf("[Test] Final state\n%s", current)
+			fLogger.Logf("[Test] Final state\n%s", current.summary())
 			break
 		}
 
@@ -696,7 +709,7 @@ func runOnDeleteTestCase(ctx context.Context, t *testing.T, tt onDeleteSequenceT
 			// NOTE: the following can be used to set a breakpoint for debugging why the system is not reaching desired state after maxIterations (to check what is not yet equal)
 			current.Equal(desired)
 			// Log desired state we never reached
-			fLogger.Logf("[Test] Desired state\n%s", desired)
+			fLogger.Logf("[Test] Desired state\n%s", desired.summary())
 			g.Fail(fmt.Sprintf("Failed to reach desired state in %d iterations", maxIterations))
 		}
 	}