Skip to content

Commit

Permalink
[OpinionatedReconciler] Add debug logging and tracing, change some lo…
Browse files Browse the repository at this point in the history 
…gic to avoid retry loops on deletes (#560)

Related to #559, added
debug logging and tracing similar to what `OpinionatedWatcher` already
has. While testing, changed the logic in the `OpinionatedReconciler` to
resolve two issues:
1. Previously, when an update added the `deletionTimestamp`, the
`OpinionatedReconciler` would remove the finalizer and return, and then
rely on the subsequent delete event to be propagated down to the
downstream reconciler for delete behavior. This introduces an edge case
that is addressed in `OpinionatedWatcher` but missed here, where, if the
downstream's processing of the delete fails, the object is still deleted
in the API server, possibly leaving a bad state (in
`OpinionatedWatcher`, the finalizer is not removed until the downstream
delete is successfully processed). The logic has now been changed to
mimic that of the `OpinionatedWatcher`, sending the "add
`deletionTimestamp`" event to the downstream reconciler as a delete
event, and only removing the finalizer once this is successful. As a
side effect, _actual_ delete events are no long propagated to the
downstream.
2. After the final finalizer is removed from an object with a non-nil
`deletionTimestamp`, a delete event is emitted in the watch stream which
_still contains_ the last finalizer to be removed (if there were
multiple finalizers, only the last one is present in the list, i.e. the
last state the object was in before the finalizers list became empty),
rather than an empty finalizers list. To combat having this make us
attempt to then remove the finalizer _again_ (because the object is
actually deleted now and this will result in an error which will be
retried by default), the swallowing of delete events has been moved to
_before_ any of the other deletionTimestamp checks.

Example of deletion finalizers list behavior from (2):
```
% kubectl get --raw '/apis/issuetrackerproject.ext.grafana.com/v1/namespaces/default/issues?watch=1'
{"type":"ADDED","object":{"apiVersion":"issuetrackerproject.ext.grafana.com/v1","kind":"Issue","metadata":{"creationTimestamp":"2025-01-02T17:46:29Z","generation":1,...trimmed...}}}
{"type":"MODIFIED","object":{"apiVersion":"issuetrackerproject.ext.grafana.com/v1","kind":"Issue","metadata":{"creationTimestamp":"2025-01-02T17:46:29Z","finalizers":["issue-tracker-project-issues-finalizer"],"generation":1,...trimmed...}}}
{"type":"MODIFIED","object":{"apiVersion":"issuetrackerproject.ext.grafana.com/v1","kind":"Issue","metadata":{"creationTimestamp":"2025-01-02T17:46:29Z","finalizers":["issue-tracker-project-issues-finalizer","foo"],"generation":1,...trimmed...}}}
{"type":"MODIFIED","object":{"apiVersion":"issuetrackerproject.ext.grafana.com/v1","kind":"Issue","metadata":{"creationTimestamp":"2025-01-02T17:46:29Z","deletionGracePeriodSeconds":0,"deletionTimestamp":"2025-01-02T17:47:14Z","finalizers":["issue-tracker-project-issues-finalizer","foo"],"generation":2,...trimmed...}}}
{"type":"MODIFIED","object":{"apiVersion":"issuetrackerproject.ext.grafana.com/v1","kind":"Issue","metadata":{"creationTimestamp":"2025-01-02T17:46:29Z","deletionGracePeriodSeconds":0,"deletionTimestamp":"2025-01-02T17:47:14Z","finalizers":["foo"],"generation":2,...trimmed...}}}
{"type":"DELETED","object":{"apiVersion":"issuetrackerproject.ext.grafana.com/v1","kind":"Issue","metadata":{"creationTimestamp":"2025-01-02T17:46:29Z","deletionGracePeriodSeconds":0,"deletionTimestamp":"2025-01-02T17:47:14Z","finalizers":["foo"],"generation":2,...trimmed...}}}
```
Here a new `issue` is created (from the tutorial project), the
reconciler adds its finalizer, then an extra `foo` finalizer is added.
The object is deleted, and the reconciler automatically removes its
finalizer. The `foo` finalizer is removed, but the state of the object
doesn't change and the delete happens with that state.
  • Loading branch information
@IfSentient
IfSentient authored Jan 7, 2025
1 parent 10d4364 commit 8e340a2
Show file tree
Hide file tree
Showing 2 changed files with 192 additions and 31 deletions.
69 changes: 64 additions & 5 deletions operator/reconciler.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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"
)

Expand Down Expand Up @@ -141,31 +144,47 @@ 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
// - If the action is a Create, and the OpinionatedReconciler's finalizer is missing, add the finalizer after the delegated Reconcile request returns successfully
// - 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,
Expand All @@ -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,
Expand Down
Loading

0 comments on commit 8e340a2

Please sign in to comment.