From aa2bde5e857f3b615bdea8948e036d0b768111af Mon Sep 17 00:00:00 2001 From: Matthew Christopher Date: Thu, 1 Feb 2024 11:57:36 -0800 Subject: [PATCH] Improve reconcile exit logging * 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. --- .../reconcilers/generic/generic_reconciler.go | 32 +++++++++++++------ .../testcommon/kube_per_test_context.go | 3 ++ v2/internal/util/kubeclient/kube_client.go | 23 +++++++++---- 3 files changed, 41 insertions(+), 17 deletions(-) diff --git a/v2/internal/reconcilers/generic/generic_reconciler.go b/v2/internal/reconcilers/generic/generic_reconciler.go index 9c7235270b8..c79f9cb1621 100644 --- a/v2/internal/reconcilers/generic/generic_reconciler.go +++ b/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 } diff --git a/v2/internal/testcommon/kube_per_test_context.go b/v2/internal/testcommon/kube_per_test_context.go index a388fcaf6ed..d043523fec9 100644 --- a/v2/internal/testcommon/kube_per_test_context.go +++ b/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 } diff --git a/v2/internal/util/kubeclient/kube_client.go b/v2/internal/util/kubeclient/kube_client.go index 717f7cd088e..b6a3342320f 100644 --- a/v2/internal/util/kubeclient/kube_client.go +++ b/v2/internal/util/kubeclient/kube_client.go @@ -17,6 +17,13 @@ import ( "sigs.k8s.io/controller-runtime/pkg/client" ) +type CommitType string + +const ( + SpecOnly = CommitType("SpecOnly") + SpecAndStatus = CommitType("SpecAndStatus") +) + type Client interface { client.Client @@ -24,7 +31,7 @@ type Client interface { 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