From 6661c8c081c6681cb4e3482f2488fee418edc75f Mon Sep 17 00:00:00 2001 From: Austin Pond Date: Thu, 2 Jan 2025 12:49:10 -0500 Subject: [PATCH] [OpinionatedReconciler] Add debug logging and tracing, change some logic to avoid retry loops on deletes. --- operator/reconciler.go | 69 ++++++++++++++-- operator/reconciler_test.go | 154 ++++++++++++++++++++++++++++++------ 2 files changed, 192 insertions(+), 31 deletions(-) diff --git a/operator/reconciler.go b/operator/reconciler.go index abbebc03..fce53d1a 100644 --- a/operator/reconciler.go +++ b/operator/reconciler.go @@ -5,8 +5,11 @@ import ( "fmt" "time" + "go.opentelemetry.io/otel/attribute" + "go.opentelemetry.io/otel/codes" "k8s.io/utils/strings/slices" + "github.com/grafana/grafana-app-sdk/logging" "github.com/grafana/grafana-app-sdk/resource" ) @@ -141,7 +144,10 @@ type OpinionatedReconciler struct { client PatchClient } -const opinionatedReconcilerPatchStateKey = "grafana-app-sdk-opinionated-reconciler-create-patch-status" +const ( + opinionatedReconcilerPatchAddStateKey = "grafana-app-sdk-opinionated-reconciler-create-patch-status" + opinionatedReconcilerPatchRemoveStateKey = "grafana-app-sdk-opinionated-reconciler-delete-patch-status" +) // Reconcile consumes a ReconcileRequest and passes it off to the underlying ReconcileFunc, using the following criteria to modify or drop the request if needed: // - If the action is a Create, and the OpinionatedReconciler's finalizer is in the finalizer list, update the action to a Resync @@ -149,23 +155,36 @@ const opinionatedReconcilerPatchStateKey = "grafana-app-sdk-opinionated-reconcil // - If the action is an Update, and the DeletionTimestamp is non-nil, remove the OpinionatedReconciler's finalizer, and do not delegate (the subsequent Delete will be delegated) // - If the action is an Update, and the OpinionatedReconciler's finalizer is missing (and DeletionTimestamp is nil), add the finalizer, and do not delegate (the subsequent update action will delegate) func (o *OpinionatedReconciler) Reconcile(ctx context.Context, request ReconcileRequest) (ReconcileResult, error) { + ctx, span := GetTracer().Start(ctx, "OpinionatedReconciler-reconcile") + defer span.End() + logger := logging.FromContext(ctx).With("action", ResourceActionFromReconcileAction(request.Action), "component", "OpinionatedReconciler", "kind", request.Object.GroupVersionKind().Kind, "namespace", request.Object.GetNamespace(), "name", request.Object.GetName()) + logger.Debug("Reconcile request received") + // Check if this action is a create, and the resource already has a finalizer. If so, make it a sync. if request.Action == ReconcileActionCreated && slices.Contains(request.Object.GetFinalizers(), o.finalizer) { + logger.Debug("Object already has the correct finalizer, converting to a Resync event and propagating", "finalizer", o.finalizer) request.Action = ReconcileActionResynced return o.wrappedReconcile(ctx, request) } if request.Action == ReconcileActionCreated { resp := ReconcileResult{} - if request.State == nil || request.State[opinionatedReconcilerPatchStateKey] == nil { + if request.State == nil || request.State[opinionatedReconcilerPatchAddStateKey] == nil { // Delegate var err error resp, err = o.wrappedReconcile(ctx, request) if err != nil || resp.RequeueAfter != nil { + if resp.RequeueAfter != nil { + span.SetAttributes(attribute.String("reconcile.requeafter", resp.RequeueAfter.String())) + } + if err != nil { + span.SetStatus(codes.Error, fmt.Sprintf("watcher add error: %s", err.Error())) + } return resp, err } } // Attach the finalizer on success + logger.Debug("Downstream reconcile succeeded, adding finalizer", "finalizer", o.finalizer) patchErr := o.client.PatchInto(ctx, request.Object.GetStaticMetadata().Identifier(), resource.PatchRequest{ Operations: []resource.PatchOperation{{ Operation: resource.PatchOpAdd, @@ -174,24 +193,64 @@ func (o *OpinionatedReconciler) Reconcile(ctx context.Context, request Reconcile }}, }, resource.PatchOptions{}, request.Object) if patchErr != nil { + span.SetStatus(codes.Error, fmt.Sprintf("error adding finalizer: %s", patchErr.Error())) if resp.State == nil { resp.State = make(map[string]any) } - resp.State[opinionatedReconcilerPatchStateKey] = patchErr + resp.State[opinionatedReconcilerPatchAddStateKey] = patchErr } return resp, patchErr } - if request.Action == ReconcileActionUpdated && request.Object.GetDeletionTimestamp() != nil && slices.Contains(request.Object.GetFinalizers(), o.finalizer) { + // Ignore deleted actions, as we send them on updates where we need to remove our finalizer + // This needs to be checked before the "is deletionTimestamp non-nil and still has our finalizer", + // because after we remove the finalizer, a delete event comes through that still has the final finalizer to be removed from the list + if request.Action == ReconcileActionDeleted { + logger.Debug("Not propagating delete event, as this is handled when deletionTimestamp is set to a non-nil value") + return ReconcileResult{}, nil + } + if request.Object.GetDeletionTimestamp() != nil && slices.Contains(request.Object.GetFinalizers(), o.finalizer) { + res := ReconcileResult{} + if request.State == nil || request.State[opinionatedReconcilerPatchRemoveStateKey] == nil { + logger.Debug("Update added a deletionTimestamp, propagate this event as a delete", "deletionTimestamp", request.Object.GetDeletionTimestamp()) + // Propagate as a delete, if the delete succeeds, remove the finalizer + request.Action = ReconcileActionDeleted + var err error + res, err = o.wrappedReconcile(ctx, request) + if err != nil || res.RequeueAfter != nil { + if res.RequeueAfter != nil { + span.SetAttributes(attribute.String("reconcile.requeafter", res.RequeueAfter.String())) + } + if err != nil { + span.SetStatus(codes.Error, fmt.Sprintf("watcher add error: %s", err.Error())) + } + return res, err + } + } else { + logger.Debug("Retry of an update which added a deletionTimestamp, downstream reconciler already successfully processed delete, need to retry removing the finalizer", "patchError", request.State[opinionatedReconcilerPatchRemoveStateKey]) + } + logger.Debug("Removing finalizer from object", "finalizer", o.finalizer) patchErr := o.client.PatchInto(ctx, request.Object.GetStaticMetadata().Identifier(), resource.PatchRequest{ Operations: []resource.PatchOperation{{ Operation: resource.PatchOpRemove, Path: fmt.Sprintf("/metadata/finalizers/%d", slices.Index(request.Object.GetFinalizers(), o.finalizer)), }}, }, resource.PatchOptions{}, request.Object) - return ReconcileResult{}, patchErr + if patchErr != nil { + span.SetStatus(codes.Error, fmt.Sprintf("error adding finalizer: %s", patchErr.Error())) + if res.State == nil { + res.State = make(map[string]any) + } + res.State[opinionatedReconcilerPatchRemoveStateKey] = patchErr + } + return res, patchErr + } + if request.Object.GetDeletionTimestamp() != nil { + logger.Debug("Object has a deletionTimestamp but does not contain our finalizer, ignoring event as object delete has already been processed", "finalizer", o.finalizer, "deletionTimestamp", request.Object.GetDeletionTimestamp()) + return ReconcileResult{}, nil } if request.Action == ReconcileActionUpdated && !slices.Contains(request.Object.GetFinalizers(), o.finalizer) { // Add the finalizer, don't delegate, let the reconcile action for adding the finalizer propagate down to avoid confusing extra reconciliations + logger.Debug("Missing finalizer in object, adding (this will trigger a new reconcile event)", "finalizer", o.finalizer) patchErr := o.client.PatchInto(ctx, request.Object.GetStaticMetadata().Identifier(), resource.PatchRequest{ Operations: []resource.PatchOperation{{ Operation: resource.PatchOpAdd, diff --git a/operator/reconciler_test.go b/operator/reconciler_test.go index ae14642d..e6c1944c 100644 --- a/operator/reconciler_test.go +++ b/operator/reconciler_test.go @@ -60,7 +60,6 @@ func TestOpinionatedReconciler_Reconcile(t *testing.T) { ctx := context.Background() op, err := NewOpinionatedReconciler(&mockPatchClient{ PatchIntoFunc: func(c context.Context, identifier resource.Identifier, request resource.PatchRequest, options resource.PatchOptions, object resource.Object) error { - assert.Equal(t, ctx, c) assert.Equal(t, req.Object.GetStaticMetadata().Identifier(), identifier) assert.Equal(t, resource.PatchRequest{ Operations: []resource.PatchOperation{{ @@ -83,7 +82,6 @@ func TestOpinionatedReconciler_Reconcile(t *testing.T) { } op.Reconciler = &SimpleReconciler{ ReconcileFunc: func(c context.Context, request ReconcileRequest) (ReconcileResult, error) { - assert.Equal(t, ctx, c) assert.Equal(t, req, request) return result, nil }, @@ -117,7 +115,6 @@ func TestOpinionatedReconciler_Reconcile(t *testing.T) { resErr := errors.New("I AM ERROR") op.Reconciler = &SimpleReconciler{ ReconcileFunc: func(c context.Context, request ReconcileRequest) (ReconcileResult, error) { - assert.Equal(t, ctx, c) assert.Equal(t, req, request) return result, resErr }, @@ -140,7 +137,6 @@ func TestOpinionatedReconciler_Reconcile(t *testing.T) { patchErr := errors.New("I AM ERROR") op, err := NewOpinionatedReconciler(&mockPatchClient{ PatchIntoFunc: func(c context.Context, identifier resource.Identifier, request resource.PatchRequest, options resource.PatchOptions, object resource.Object) error { - assert.Equal(t, ctx, c) assert.Equal(t, req.Object.GetStaticMetadata().Identifier(), identifier) assert.Equal(t, resource.PatchRequest{ Operations: []resource.PatchOperation{{ @@ -163,7 +159,6 @@ func TestOpinionatedReconciler_Reconcile(t *testing.T) { } op.Reconciler = &SimpleReconciler{ ReconcileFunc: func(c context.Context, request ReconcileRequest) (ReconcileResult, error) { - assert.Equal(t, ctx, c) assert.Equal(t, req, request) return result, nil }, @@ -172,7 +167,7 @@ func TestOpinionatedReconciler_Reconcile(t *testing.T) { assert.Equal(t, patchErr, err) assert.True(t, patchCalled) assert.Equal(t, "bar", res.State["foo"]) - assert.Equal(t, patchErr, res.State[opinionatedReconcilerPatchStateKey]) + assert.Equal(t, patchErr, res.State[opinionatedReconcilerPatchAddStateKey]) }) t.Run("retried add from client error", func(t *testing.T) { @@ -181,13 +176,12 @@ func TestOpinionatedReconciler_Reconcile(t *testing.T) { Action: ReconcileActionCreated, Object: &resource.TypedSpecObject[int]{}, State: map[string]any{ - opinionatedReconcilerPatchStateKey: errors.New("I AM ERROR"), + opinionatedReconcilerPatchAddStateKey: errors.New("I AM ERROR"), }, } ctx := context.Background() op, err := NewOpinionatedReconciler(&mockPatchClient{ PatchIntoFunc: func(c context.Context, identifier resource.Identifier, request resource.PatchRequest, options resource.PatchOptions, object resource.Object) error { - assert.Equal(t, ctx, c) assert.Equal(t, req.Object.GetStaticMetadata().Identifier(), identifier) assert.Equal(t, resource.PatchRequest{ Operations: []resource.PatchOperation{{ @@ -240,7 +234,6 @@ func TestOpinionatedReconciler_Reconcile(t *testing.T) { resErr := errors.New("I AM ERROR") op.Reconciler = &SimpleReconciler{ ReconcileFunc: func(c context.Context, request ReconcileRequest) (ReconcileResult, error) { - assert.Equal(t, ctx, c) assert.Equal(t, ReconcileActionResynced, request.Action) assert.Equal(t, req.Object, request.Object) assert.Equal(t, req.State, request.State) @@ -279,7 +272,6 @@ func TestOpinionatedReconciler_Reconcile(t *testing.T) { resErr := errors.New("I AM ERROR") op.Reconciler = &SimpleReconciler{ ReconcileFunc: func(c context.Context, request ReconcileRequest) (ReconcileResult, error) { - assert.Equal(t, ctx, c) assert.Equal(t, req, request) return result, resErr }, @@ -301,7 +293,6 @@ func TestOpinionatedReconciler_Reconcile(t *testing.T) { ctx := context.Background() op, err := NewOpinionatedReconciler(&mockPatchClient{ PatchIntoFunc: func(c context.Context, identifier resource.Identifier, request resource.PatchRequest, options resource.PatchOptions, object resource.Object) error { - assert.Equal(t, ctx, c) assert.Equal(t, req.Object.GetStaticMetadata().Identifier(), identifier) assert.Equal(t, resource.PatchRequest{ Operations: []resource.PatchOperation{{ @@ -345,7 +336,6 @@ func TestOpinionatedReconciler_Reconcile(t *testing.T) { ctx := context.Background() op, err := NewOpinionatedReconciler(&mockPatchClient{ PatchIntoFunc: func(c context.Context, identifier resource.Identifier, request resource.PatchRequest, options resource.PatchOptions, object resource.Object) error { - assert.Equal(t, ctx, c) assert.Equal(t, req.Object.GetStaticMetadata().Identifier(), identifier) assert.Equal(t, resource.PatchRequest{ Operations: []resource.PatchOperation{{ @@ -359,16 +349,135 @@ func TestOpinionatedReconciler_Reconcile(t *testing.T) { }, }, finalizer) require.Nil(t, err) + expRes := ReconcileResult{ + State: map[string]any{ + "bar": "foo", + }, + } + op.Reconciler = &SimpleReconciler{ + ReconcileFunc: func(c context.Context, request ReconcileRequest) (ReconcileResult, error) { + // Request should have the Deleted action instead of Updated, but otherwise be the same + assert.Equal(t, ReconcileActionDeleted, request.Action) + assert.Equal(t, req.Object, request.Object) + assert.Equal(t, req.State, request.State) + return expRes, nil + }, + } + res, err := op.Reconcile(ctx, req) + assert.Equal(t, expRes, res) + assert.Nil(t, err) + assert.True(t, patchCalled) + }) + + t.Run("update with non-nil deletionTimestamp, reconcile error", func(t *testing.T) { + deleted := metav1.NewTime(time.Now()) + req := ReconcileRequest{ + Action: ReconcileActionUpdated, + Object: &resource.TypedSpecObject[int]{ + ObjectMeta: metav1.ObjectMeta{ + Finalizers: []string{finalizer}, + DeletionTimestamp: &deleted, + }, + }, + State: map[string]any{ + "foo": "bar", + }, + } + ctx := context.Background() + op, err := NewOpinionatedReconciler(&mockPatchClient{ + PatchIntoFunc: func(c context.Context, identifier resource.Identifier, request resource.PatchRequest, options resource.PatchOptions, object resource.Object) error { + // No patch to remove finalizer if reconcile fails + require.Fail(t, "patch should not be called") + return nil + }, + }, finalizer) + require.Nil(t, err) + reconcileErr := errors.New("I AM ERROR") + op.Reconciler = &SimpleReconciler{ + ReconcileFunc: func(c context.Context, request ReconcileRequest) (ReconcileResult, error) { + return ReconcileResult{}, reconcileErr + }, + } + res, err := op.Reconcile(ctx, req) + assert.Equal(t, ReconcileResult{}, res) + assert.Equal(t, reconcileErr, err) + }) + + t.Run("update with non-nil deletionTimestamp, patch error", func(t *testing.T) { + deleted := metav1.NewTime(time.Now()) + req := ReconcileRequest{ + Action: ReconcileActionUpdated, + Object: &resource.TypedSpecObject[int]{ + ObjectMeta: metav1.ObjectMeta{ + Finalizers: []string{finalizer}, + DeletionTimestamp: &deleted, + }, + }, + State: map[string]any{ + "foo": "bar", + }, + } + patchErr := errors.New("I AM ERROR") + ctx := context.Background() + op, err := NewOpinionatedReconciler(&mockPatchClient{ + PatchIntoFunc: func(c context.Context, identifier resource.Identifier, request resource.PatchRequest, options resource.PatchOptions, object resource.Object) error { + assert.Equal(t, req.Object.GetStaticMetadata().Identifier(), identifier) + assert.Equal(t, resource.PatchRequest{ + Operations: []resource.PatchOperation{{ + Path: "/metadata/finalizers/0", + Operation: resource.PatchOpRemove, + Value: nil, + }}, + }, request) + return patchErr + }, + }, finalizer) + require.Nil(t, err) op.Reconciler = &SimpleReconciler{ ReconcileFunc: func(c context.Context, request ReconcileRequest) (ReconcileResult, error) { - assert.Fail(t, "Reconcile shouldn't be called") + return ReconcileResult{}, nil + }, + } + res, err := op.Reconcile(ctx, req) + assert.Equal(t, ReconcileResult{ + State: map[string]any{ + opinionatedReconcilerPatchRemoveStateKey: patchErr, + }, + }, res) + assert.Equal(t, patchErr, err) + }) + + t.Run("update with non-nil deletionTimestamp, missing finalizer", func(t *testing.T) { + deleted := metav1.NewTime(time.Now()) + req := ReconcileRequest{ + Action: ReconcileActionUpdated, + Object: &resource.TypedSpecObject[int]{ + ObjectMeta: metav1.ObjectMeta{ + Finalizers: []string{finalizer + "no"}, + DeletionTimestamp: &deleted, + }, + }, + State: map[string]any{ + "foo": "bar", + }, + } + ctx := context.Background() + op, err := NewOpinionatedReconciler(&mockPatchClient{ + PatchIntoFunc: func(c context.Context, identifier resource.Identifier, request resource.PatchRequest, options resource.PatchOptions, object resource.Object) error { + require.Fail(t, "patch should not be called") + return nil + }, + }, finalizer) + require.Nil(t, err) + op.Reconciler = &SimpleReconciler{ + ReconcileFunc: func(c context.Context, request ReconcileRequest) (ReconcileResult, error) { + require.Fail(t, "reconcile should not be called") return ReconcileResult{}, nil }, } res, err := op.Reconcile(ctx, req) assert.Equal(t, ReconcileResult{}, res) assert.Nil(t, err) - assert.True(t, patchCalled) }) t.Run("normal delete", func(t *testing.T) { @@ -382,26 +491,20 @@ func TestOpinionatedReconciler_Reconcile(t *testing.T) { ctx := context.Background() op, err := NewOpinionatedReconciler(&mockPatchClient{ PatchIntoFunc: func(c context.Context, identifier resource.Identifier, request resource.PatchRequest, options resource.PatchOptions, object resource.Object) error { - assert.Fail(t, "patch should not be called") + require.Fail(t, "patch should not be called") return nil }, }, finalizer) require.Nil(t, err) - after := time.Second - result := ReconcileResult{ - RequeueAfter: &after, - } - resErr := errors.New("I AM ERROR") op.Reconciler = &SimpleReconciler{ ReconcileFunc: func(c context.Context, request ReconcileRequest) (ReconcileResult, error) { - assert.Equal(t, ctx, c) - assert.Equal(t, req, request) - return result, resErr + require.Fail(t, "reconcile should not be called") + return ReconcileResult{}, nil }, } res, err := op.Reconcile(ctx, req) - assert.Equal(t, result, res) - assert.Equal(t, resErr, err) + assert.Equal(t, ReconcileResult{}, res) + assert.Nil(t, err) }) } @@ -418,7 +521,6 @@ func TestOpinionatedReconciler_Wrap(t *testing.T) { ctx := context.Background() myRec := &SimpleReconciler{ ReconcileFunc: func(c context.Context, request ReconcileRequest) (ReconcileResult, error) { - assert.Equal(t, ctx, c) assert.Equal(t, rreq, request) return rr, nil },