chore(logging): update logging for nodeclass status controllers (#955)

* update logging for nodeclass status controllers

* update comments

* update image logging to add existing when updating

* remove cm being on nodeclass for mw

* Update pkg/controllers/nodeclass/status/images.go

Co-authored-by: Matthew Christopher <[email protected]>

* Update pkg/controllers/nodeclass/status/kubernetesversion.go

Co-authored-by: Matthew Christopher <[email protected]>

* Update pkg/controllers/nodeclass/status/kubernetesversion.go

Co-authored-by: Matthew Christopher <[email protected]>

* Update pkg/controllers/nodeclass/status/images.go

Co-authored-by: Matthew Christopher <[email protected]>

* update mw checking func

* update based on PR comments

* add comment on reasoning for ordering being important

* add copilot tests for HasChanged with minor modifications

---------

Co-authored-by: Matthew Christopher <[email protected]>

Author: charliedmcb

pkg/controllers/nodeclass/status/images.go

@@ -32,10 +32,12 @@ import (
 	"sigs.k8s.io/controller-runtime/pkg/log"
 
 	"github.com/awslabs/operatorpkg/reasonable"
+	"github.com/mitchellh/hashstructure/v2"
 	"github.com/samber/lo"
 
 	"github.com/Azure/karpenter-provider-azure/pkg/apis/v1beta1"
 	"github.com/Azure/karpenter-provider-azure/pkg/providers/imagefamily"
+	"github.com/Azure/karpenter-provider-azure/pkg/utils"
 
 	controllerruntime "sigs.k8s.io/controller-runtime"
 	"sigs.k8s.io/controller-runtime/pkg/manager"
@@ -109,7 +111,6 @@ func (r *NodeImageReconciler) Register(_ context.Context, m manager.Manager) err
 func (r *NodeImageReconciler) Reconcile(ctx context.Context, nodeClass *v1beta1.AKSNodeClass) (reconcile.Result, error) {
 	ctx = log.IntoContext(ctx, log.FromContext(ctx).WithName(nodeImageReconcilerName))
 	logger := log.FromContext(ctx)
-	logger.V(1).Info("starting reconcile")
 
 	nodeImages, err := r.nodeImageProvider.List(ctx, nodeClass)
 	if err != nil {
@@ -154,14 +155,16 @@ func (r *NodeImageReconciler) Reconcile(ctx context.Context, nodeClass *v1beta1.
 	if len(goalImages) == 0 {
 		nodeClass.Status.Images = nil
 		nodeClass.StatusConditions().SetFalse(v1beta1.ConditionTypeImagesReady, "ImagesNotFound", "ImageSelectors did not match any Images")
-		logger.Info("no node images")
+		logger.Info("no available node images")
 		return reconcile.Result{RequeueAfter: 5 * time.Minute}, nil
 	}
 
+	// We care about the ordering of the slices here, as it translates to priority during selection, so not treating them as sets
+	if utils.HasChanged(nodeClass.Status.Images, goalImages, &hashstructure.HashOptions{SlicesAsSets: false}) {
+		logger.WithValues("existingImages", nodeClass.Status.Images).WithValues("newImages", goalImages).Info("new available images updated for nodeclass")
+	}
 	nodeClass.Status.Images = goalImages
 	nodeClass.StatusConditions().SetTrue(v1beta1.ConditionTypeImagesReady)
-
-	logger.V(1).Info("success")
 	return reconcile.Result{RequeueAfter: 5 * time.Minute}, nil
 }
 
@@ -178,6 +181,7 @@ func imageVersionsUnready(nodeClass *v1beta1.AKSNodeClass) bool {
 // range from the ConfigMap into its own helper function using channel as a parameter.
 // nolint: gocyclo
 func (r *NodeImageReconciler) isMaintenanceWindowOpen(ctx context.Context) (bool, error) {
+	logger := log.FromContext(ctx)
 	if r.systemNamespace == "" {
 		// We fail open here, since the default case should be to upgrade
 		return true, nil
@@ -191,6 +195,16 @@ func (r *NodeImageReconciler) isMaintenanceWindowOpen(ctx context.Context) (bool
 		}
 		return false, fmt.Errorf("error getting maintenance window configmap, %w", err)
 	}
+	// Monitoring the entire ConfigMap's data might catch more data changes than we care about. However, I think it makes sense to monitor
+	//     here as it does catch the entire spread of cases we care about, and will give us direct insight on the raw data.
+	// Note: we don't need to add the nodeclass name into the monitoring here, as we actually want the entries to collide, since
+	//     maintenance windows are a cluster level concept, rather that a nodeclass level type, meaning we'd have repeat redundant info
+	//     if scoping to the nodeclass.
+	// TODO: In the longer run, the maintenance window handling should be factored out into a sharable provider, rather than being contained
+	//     within the image controller itself.
+	if r.cm.HasChanged("nodeclass-maintenancewindowdata", mwConfigMap.Data) {
+		logger.WithValues("maintenanceWindowData", mwConfigMap.Data).Info("new maintenance window data discovered")
+	}
 	if len(mwConfigMap.Data) == 0 {
 		// An empty configmap means there's no maintenance windows defined, and its up to us when to preform maintenance
 		return true, nil

pkg/controllers/nodeclass/status/kubernetesversion.go

@@ -71,8 +71,7 @@ func (r *KubernetesVersionReconciler) Register(_ context.Context, m manager.Mana
 //     - Note: We will indirectly trigger an upgrade to latest image version as well, by resetting the Images readiness.
 func (r *KubernetesVersionReconciler) Reconcile(ctx context.Context, nodeClass *v1beta1.AKSNodeClass) (reconcile.Result, error) {
 	ctx = log.IntoContext(ctx, log.FromContext(ctx).WithName(kubernetesVersionReconcilerName))
-	logger := log.FromContext(ctx)
-	logger.V(1).Info("starting reconcile")
+	logger := log.FromContext(ctx).WithValues("existingKubernetesVersion", nodeClass.Status.KubernetesVersion)
 
 	goalK8sVersion, err := r.kubernetesVersionProvider.KubeServerVersion(ctx)
 	if err != nil {
@@ -81,7 +80,7 @@ func (r *KubernetesVersionReconciler) Reconcile(ctx context.Context, nodeClass *
 
 	// Handles case 1: init, update kubernetes status to API server version found
 	if !nodeClass.StatusConditions().Get(v1beta1.ConditionTypeKubernetesVersionReady).IsTrue() || nodeClass.Status.KubernetesVersion == "" {
-		logger.Info(fmt.Sprintf("init kubernetes version: %s", goalK8sVersion))
+		logger.V(1).Info(fmt.Sprintf("init kubernetes version: %s", goalK8sVersion))
 	} else {
 		// Check if there is an upgrade
 		newK8sVersion, err := semver.Parse(goalK8sVersion)
@@ -94,16 +93,18 @@ func (r *KubernetesVersionReconciler) Reconcile(ctx context.Context, nodeClass *
 		}
 		// Handles case 2: Upgrade kubernetes version [Note: we set node image to not ready, since we upgrade node image when there is a kubernetes upgrade]
 		if newK8sVersion.GT(currentK8sVersion) {
-			logger.Info(fmt.Sprintf("kubernetes upgrade detected: from %s (current), to %s (discovered)", currentK8sVersion.String(), newK8sVersion.String()))
+			logger.V(1).Info(fmt.Sprintf("kubernetes upgrade detected: from %s (current), to %s (discovered)", currentK8sVersion.String(), newK8sVersion.String()))
 			nodeClass.StatusConditions().SetFalse(v1beta1.ConditionTypeImagesReady, "KubernetesUpgrade", "Performing kubernetes upgrade, need to get latest images")
 		} else if newK8sVersion.LT(currentK8sVersion) {
-			logger.Info(fmt.Sprintf("detected potential kubernetes downgrade: from %s (current), to %s (discovered)", currentK8sVersion.String(), newK8sVersion.String()))
+			logger.Info(fmt.Sprintf("WARN: detected potential kubernetes downgrade: from %s (current), to %s (discovered)", currentK8sVersion.String(), newK8sVersion.String()))
 			// We do not currently support downgrading, so keep the kubernetes version the same
 			goalK8sVersion = nodeClass.Status.KubernetesVersion
 		}
 	}
 	nodeClass.Status.KubernetesVersion = goalK8sVersion
 	nodeClass.StatusConditions().SetTrue(v1beta1.ConditionTypeKubernetesVersionReady)
-	logger.V(1).Info("successful reconcile")
+	if r.cm.HasChanged(fmt.Sprintf("nodeclass-%s-kubernetesversion", nodeClass.Name), nodeClass.Status.KubernetesVersion) {
+		logger.WithValues("newKubernetesVersion", nodeClass.Status.KubernetesVersion).Info("new kubernetes version updated for nodeclass")
+	}
 	return reconcile.Result{RequeueAfter: azurecache.KubernetesVersionTTL}, nil
 }

pkg/utils/utils.go

@@ -25,6 +25,7 @@ import (
 	"strings"
 
 	"github.com/Azure/azure-sdk-for-go/sdk/resourcemanager/compute/armcompute"
+	"github.com/mitchellh/hashstructure/v2"
 
 	"github.com/Azure/karpenter-provider-azure/pkg/apis/v1beta1"
 	"github.com/Azure/karpenter-provider-azure/pkg/consts"
@@ -178,3 +179,14 @@ func IsAKSManagedVNET(nodeResourceGroup string, subnetID string) (bool, error) {
 		strings.EqualFold(nodeResourceGroup, id.ResourceGroupName) &&
 		strings.EqualFold(id.SubnetName, managedSubnetName), nil
 }
+
+// HasChanged returns if the given value has changed, given the existing and new instance
+//
+// This option is accessible in place of using a ChangeMonitor, when there's access to both
+// the existing and new data.
+func HasChanged(existing, new any, options *hashstructure.HashOptions) bool {
+	// In the case of errors, the zero value from hashing will be compared, similar to ChangeMonitor
+	existingHV, _ := hashstructure.Hash(existing, hashstructure.FormatV2, options)
+	newHV, _ := hashstructure.Hash(new, hashstructure.FormatV2, options)
+	return existingHV != newHV
+}

pkg/utils/utils_test.go

@@ -20,6 +20,7 @@ import (
 	"testing"
 
 	"github.com/Azure/karpenter-provider-azure/pkg/utils"
+	"github.com/mitchellh/hashstructure/v2"
 	. "github.com/onsi/gomega"
 )
 
@@ -92,3 +93,32 @@ func TestIsAKSManagedVNET(t *testing.T) {
 		})
 	}
 }
+func TestHasChanged_SimpleCases(t *testing.T) {
+	g := NewWithT(t)
+
+	// Case: Has not changed (same int)
+	g.Expect(utils.HasChanged(42, 42, nil)).To(BeFalse())
+
+	// Case: Has changed (different int)
+	g.Expect(utils.HasChanged(42, 43, nil)).To(BeTrue())
+
+	// Case: Has not changed (same string)
+	g.Expect(utils.HasChanged("azure", "azure", nil)).To(BeFalse())
+
+	// Case: Has changed (different string)
+	g.Expect(utils.HasChanged("azure", "cloud", nil)).To(BeTrue())
+}
+
+func TestHasChanged_SliceOrderWithSlicesAsSets(t *testing.T) {
+	g := NewWithT(t)
+
+	a := []int{1, 2, 3}
+	b := []int{3, 2, 1}
+
+	// By default, order matters
+	g.Expect(utils.HasChanged(a, b, nil)).To(BeTrue())
+
+	// With SlicesAsSets, order does not matter
+	opts := &hashstructure.HashOptions{SlicesAsSets: true}
+	g.Expect(utils.HasChanged(a, b, opts)).To(BeFalse())
+}