Improve reconcile exit logging (#3755)

* Fix issue where one path which should have logged on exit of the
   reconcile loop didn't.
 * Fix issue where one path which should have logged object after being
   committed to etcd didn't.

v2/internal/reconcilers/generic/generic_reconciler.go

@@ -76,11 +76,15 @@ func (gr *GenericReconciler) Reconcile(ctx context.Context, req ctrl.Request) (c
 	reconcilers.LogObj(log, Verbose, "Reconcile invoked", metaObj)
 
 	// Ensure the resource is tagged with the operator's namespace.
-	ownershipResult, err := gr.takeOwnership(ctx, metaObj)
+	ownershipResult, err := gr.takeOwnership(ctx, log, metaObj)
 	if err != nil {
-		return ctrl.Result{}, errors.Wrapf(err, "failed to take ownership of %s", metaObj.GetName())
+		err = errors.Wrapf(err, "failed to take ownership of %s", metaObj.GetName())
+		log.Error(err, "failed to take ownership of object")
+		return ctrl.Result{}, err
 	}
 	if ownershipResult != nil {
+		// Early return
+		log.V(Verbose).Info("Done with reconcile", "result", *ownershipResult)
 		return *ownershipResult, nil
 	}
 
@@ -121,7 +125,7 @@ func (gr *GenericReconciler) Reconcile(ctx context.Context, req ctrl.Request) (c
 	}
 
 	// Write the object
-	err = gr.CommitUpdate(ctx, log, originalObj, metaObj)
+	err = gr.CommitUpdate(ctx, log, originalObj, metaObj, kubeclient.SpecAndStatus)
 	if err != nil {
 		// NotFound is a superfluous error as per https://github.com/kubernetes-sigs/controller-runtime/issues/377
 		// The correct handling is just to ignore it and we will get an event shortly with the updated version to patch
@@ -205,7 +209,7 @@ func (gr *GenericReconciler) claimResource(ctx context.Context, log logr.Logger,
 	// Passing nil for original here as we know we've made a change and original is only used to determine if the obj
 	// has changed to avoid excess commits. In this case, we always need to commit at this stage as adding the finalizer
 	// must be persisted to etcd before proceeding.
-	err = gr.CommitUpdate(ctx, log, nil, metaObj)
+	err = gr.CommitUpdate(ctx, log, nil, metaObj, kubeclient.SpecOnly)
 	if err != nil {
 		log.Error(err, "Error adding finalizer")
 		return kubeclient.IgnoreNotFound(err)
@@ -297,7 +301,7 @@ func (gr *GenericReconciler) WriteReadyConditionError(ctx context.Context, log l
 		obj.GetGeneration(),
 		err.Reason,
 		err.Cause().Error())) // Don't use err.Error() here because it also includes details about Reason, Severity, which are getting displayed as part of the condition structure
-	commitErr := gr.CommitUpdate(ctx, log, nil, obj)
+	commitErr := gr.CommitUpdate(ctx, log, nil, obj, kubeclient.SpecAndStatus)
 	if commitErr != nil {
 		return errors.Wrap(commitErr, "updating resource error")
 	}
@@ -307,7 +311,7 @@ func (gr *GenericReconciler) WriteReadyConditionError(ctx context.Context, log l
 
 // takeOwnership marks this resource as owned by this operator. It returns a ctrl.Result ptr to indicate if the result
 // should be returned or not. If the result is nil, ownership does not need to be taken
-func (gr *GenericReconciler) takeOwnership(ctx context.Context, metaObj genruntime.MetaObject) (*ctrl.Result, error) {
+func (gr *GenericReconciler) takeOwnership(ctx context.Context, log logr.Logger, metaObj genruntime.MetaObject) (*ctrl.Result, error) {
 	// Ensure the resource is tagged with the operator's namespace.
 	annotations := metaObj.GetAnnotations()
 	reconcilerNamespace := annotations[NamespaceAnnotation]
@@ -322,26 +326,34 @@ func (gr *GenericReconciler) takeOwnership(ctx context.Context, metaObj genrunti
 		// be rare.
 		message := fmt.Sprintf("Operators in %q and %q are both configured to manage this resource", gr.Config.PodNamespace, reconcilerNamespace)
 		gr.Recorder.Event(metaObj, corev1.EventTypeWarning, "Overlap", message)
+		log.V(Info).Info(message)
+
 		return &ctrl.Result{}, nil
 	} else if reconcilerNamespace == "" && gr.Config.PodNamespace != "" {
 		genruntime.AddAnnotation(metaObj, NamespaceAnnotation, gr.Config.PodNamespace)
-		return &ctrl.Result{Requeue: true}, gr.KubeClient.Update(ctx, metaObj)
+		return &ctrl.Result{Requeue: true}, gr.CommitUpdate(ctx, log, nil, metaObj, kubeclient.SpecOnly)
 	}
 
 	return nil, nil
 }
 
-func (gr *GenericReconciler) CommitUpdate(ctx context.Context, log logr.Logger, original genruntime.MetaObject, obj genruntime.MetaObject) error {
+func (gr *GenericReconciler) CommitUpdate(
+	ctx context.Context,
+	log logr.Logger,
+	original genruntime.MetaObject,
+	obj genruntime.MetaObject,
+	commitType kubeclient.CommitType,
+) error {
 	if reflect.DeepEqual(original, obj) {
 		log.V(Debug).Info("Didn't commit obj as there was no change")
 		return nil
 	}
 
-	err := gr.KubeClient.CommitObject(ctx, obj)
+	err := gr.KubeClient.CommitObject(ctx, obj, commitType)
 	if err != nil {
 		return err
 	}
-	reconcilers.LogObj(log, Debug, "updated resource in etcd", obj)
+	reconcilers.LogObj(log, Verbose, "updated resource in etcd", obj)
 	return nil
 }
 

v2/internal/testcommon/kube_per_test_context.go

@@ -139,6 +139,9 @@ func ReadFromEnvironmentForTest() (config.Values, error) {
 
 	// Test configs never want SyncPeriod set as it introduces jitter
 	cfg.SyncPeriod = nil
+	// Simulate pod namespace being set, as we're not running in a pod context so we don't have this env varaible
+	// injected automatically
+	cfg.PodNamespace = "azureserviceoperator-system"
 
 	return cfg, err
 }

v2/internal/util/kubeclient/kube_client.go

@@ -17,14 +17,21 @@ import (
 	"sigs.k8s.io/controller-runtime/pkg/client"
 )
 
+type CommitType string
+
+const (
+	SpecOnly      = CommitType("SpecOnly")
+	SpecAndStatus = CommitType("SpecAndStatus")
+)
+
 type Client interface {
 	client.Client
 
 	// Additional helpers
 
 	GetObject(ctx context.Context, namespacedName types.NamespacedName, gvk schema.GroupVersionKind) (client.Object, error)
 	GetObjectOrDefault(ctx context.Context, namespacedName types.NamespacedName, gvk schema.GroupVersionKind) (client.Object, error)
-	CommitObject(ctx context.Context, obj client.Object) error
+	CommitObject(ctx context.Context, obj client.Object, commitType CommitType) error
 }
 
 type clientHelper struct {
@@ -124,7 +131,7 @@ func (c *clientHelper) GetObjectOrDefault(ctx context.Context, namespacedName ty
 // CommitObject persists the contents of obj to etcd by using the Kubernetes client.
 // Note that after this method has been called, obj contains the result of the update
 // from APIServer (including an updated resourceVersion). Both Spec and Status are written
-func (c *clientHelper) CommitObject(ctx context.Context, obj client.Object) error {
+func (c *clientHelper) CommitObject(ctx context.Context, obj client.Object, commitType CommitType) error {
 	// Order of updates (spec first or status first) matters here.
 	// If the status is updated first: clients that are waiting on status
 	// Condition Ready == true might see that quickly enough, and make a spec
@@ -145,11 +152,13 @@ func (c *clientHelper) CommitObject(ctx context.Context, obj client.Object) erro
 
 	obj.SetResourceVersion(clone.GetResourceVersion())
 
-	// Note that subsequent calls to GET can (if using a cached client) can miss the updates we've just done.
-	// See: https://github.com/kubernetes-sigs/controller-runtime/issues/1464.
-	err = c.Status().Update(ctx, obj)
-	if err != nil {
-		return errors.Wrapf(err, "updating %s/%s resource status", obj.GetNamespace(), obj.GetName())
+	if commitType == SpecAndStatus {
+		// Note that subsequent calls to GET can (if using a cached client) can miss the updates we've just done.
+		// See: https://github.com/kubernetes-sigs/controller-runtime/issues/1464.
+		err = c.Status().Update(ctx, obj)
+		if err != nil {
+			return errors.Wrapf(err, "updating %s/%s resource status", obj.GetNamespace(), obj.GetName())
+		}
 	}
 
 	return nil