log the JSON patch document when updating resource (#95)

This patch updates the `resourceReconciler.patchResourceMetadataAndSpec` and
`resourceReconciler.patchResourceStatus` methods in a couple ways.
First, I ensure that the desired and latest resource parameters are
*never* modified by either method by ensuring that only copies of
desired and latest are used when calling Patch against the API server.
Second, I added some debug-level logging of the exact JSON patch
document that is sent over the wire to the Kubernetes API server when
patching either the metadata/spec *or* the status.

Here is what this looks like in the debug logging output:

metadata+spec:

```
1.65540769296847e+09	DEBUG	ackrt	>>>> kc.Patch (metadata + spec)	{"account": "750630568209", "role": "", "region": "us-west-2", "kind": "Repository", "namespace": "default", "name": "ecr-repository-u8loelgfy", "is_adopted": false, "generation": 1}
1.6554076929743059e+09	DEBUG	ackrt	patched resource metadata + spec	{"account": "750630568209", "role": "", "region": "us-west-2", "kind": "Repository", "namespace": "default", "name": "ecr-repository-u8loelgfy", "is_adopted": false, "generation": 1, "json": "{\"metadata\":{\"generation\":2,\"resourceVersion\":\"1049\"},\"spec\":{\"encryptionConfiguration\":{\"encryptionType\":\"AES256\"},\"imageScanningConfiguration\":{\"scanOnPush\":false},\"imageTagMutability\":\"MUTABLE\",\"registryID\":\"750630568209\",\"tags\":null},\"status\":{\"conditions\":null}}"}
1.6554076929743316e+09	DEBUG	ackrt	<<<< kc.Patch (metadata + spec)	{"account": "750630568209", "role": "", "region": "us-west-2", "kind": "Repository", "namespace": "default", "name": "ecr-repository-u8loelgfy", "is_adopted": false, "generation": 1}
```

status:

```
1.6554077304127564e+09	DEBUG	ackrt	>> kc.Patch (status)	{"account": "750630568209", "role": "", "region": "us-west-2", "kind": "Repository", "namespace": "default", "name": "ecr-repository-yq327yxdo", "is_adopted": false, "generation": 5}
1.6554077304208796e+09	DEBUG	ackrt	patched resource status	{"account": "750630568209", "role": "", "region": "us-west-2", "kind": "Repository", "namespace": "default", "name": "ecr-repository-yq327yxdo", "is_adopted": false, "generation": 5, "json": "{\"metadata\":{\"resourceVersion\":\"1129\"},\"spec\":{\"tags\":[{\"key\":\"k1\",\"value\":\"v1\"}]},\"status\":{\"conditions\":[{\"lastTransitionTime\":\"2022-06-16T19:28:50Z\",\"message\":\"Late initialization successful\",\"reason\":\"Late initialization successful\",\"status\":\"True\",\"type\":\"ACK.LateInitialized\"},{\"lastTransitionTime\":\"2022-06-16T19:28:50Z\",\"message\":\"Resource synced successfully\",\"reason\":\"\",\"status\":\"True\",\"type\":\"ACK.ResourceSynced\"}]}}"}
1.6554077304209113e+09	DEBUG	ackrt	<< kc.Patch (status)	{"account": "750630568209", "role": "", "region": "us-west-2", "kind": "Repository", "namespace": "default", "name": "ecr-repository-yq327yxdo", "is_adopted": false, "generation": 5}
1.655407730420916e+09	DEBUG	ackrt	< r.patchResourceStatus	{"account": "750630568209", "role": "", "region": "us-west-2", "kind": "Repository", "namespace": "default", "name": "ecr-repository-yq327yxdo", "is_adopted": false, "generation": 5}
```

I specifically strip out all of the Kubernetes server-side apply
annotations out of the patch document because they are super verbose and
are not helpful since we don't use server-side apply.

I'm hoping this extra bit of logging information will be useful when
attempting to diagnose exactly when and what changes are being applied
to resources in the Kubernetes API.

Signed-off-by: Jay Pipes <[email protected]>

By submitting this pull request, I confirm that my contribution is made
under the terms of the Apache 2.0 license.

Author: jaypipes

mocks/pkg/types/logger.go

@@ -26,6 +26,7 @@ var (
 // testing and mocking...
 type voidLogger struct{}
 
+func (l *voidLogger) IsDebugEnabled() bool         { return false }
 func (l *voidLogger) WithValues(...interface{})    {}
 func (l *voidLogger) Info(string, ...interface{})  {}
 func (l *voidLogger) Debug(string, ...interface{}) {}

pkg/runtime/log/noop.go

@@ -31,6 +31,12 @@ type ResourceLogger struct {
 	blockDepth int
 }
 
+// IsDebugEnabled returns true when the underlying logger is configured to
+// write debug messages, false otherwise.
+func (rl *ResourceLogger) IsDebugEnabled() bool {
+	return rl.log.V(1).Enabled()
+}
+
 // WithValues adapts the internal logger with a set of additional values
 func (rl *ResourceLogger) WithValues(
 	values ...interface{},

pkg/runtime/log/resource.go

@@ -15,6 +15,7 @@ package runtime
 
 import (
 	"context"
+	"encoding/json"
 	"fmt"
 	"time"
 
@@ -584,8 +585,46 @@ func (r *resourceReconciler) lateInitializeResource(
 	return lateInitializedLatest, err
 }
 
-// patchResourceMetadataAndSpec patches the custom resource in the Kubernetes API to match the
-// supplied latest resource's metadata and spec.
+// getPatchDocument returns a JSON string containing the object that will be
+// patched in the Kubernetes API server.
+//
+// NOTE(jaypipes): Because the Kubernetes API server's server-side apply
+// functionality introduces an enormous amount of verbose annotations in the
+// resource metadata, and because those annotations are pretty unhelpful to
+// ACK, we strip all that stuff out of the returned patch document.
+func getPatchDocument(
+	patch client.Patch,
+	obj client.Object, // the diff of this will be represented in the patch
+) string {
+	js, _ := patch.Data(obj)
+	var m map[string]interface{}
+	_ = json.Unmarshal(js, &m)
+	if md, ok := m["metadata"]; ok {
+		// Strip out managedFields stuff, since it's super verbose and
+		// doesn't offer any value to us (since we don't use server-side
+		// apply
+		if mv, ok := md.(map[string]interface{}); ok {
+			if _, ok := mv["managedFields"]; ok {
+				delete(mv, "managedFields")
+			}
+		}
+	}
+	js, _ = json.Marshal(m)
+	return string(js)
+}
+
+// patchResourceMetadataAndSpec patches the custom resource in the Kubernetes
+// API to match the supplied latest resource's metadata and spec.
+//
+// NOTE(jaypipes): The latest parameter is *mutated* by this method: the
+// resource's metadata.resourceVersion is incremented in the process of calling
+// Patch. This is intentional, because without updating the resource's
+// metadata.resourceVersion, the resource cannot be passed to Patch again later
+// in the reconciliation loop if Patch is called with the Optimistic Locking
+// option.
+//
+// See https://github.com/kubernetes-sigs/controller-runtime/blob/165a8c869c4388b861c7c91cb1e5330f6e07ee16/pkg/client/patch.go#L81-L84
+// for more information.
 func (r *resourceReconciler) patchResourceMetadataAndSpec(
 	ctx context.Context,
 	desired acktypes.AWSResource,
@@ -608,27 +647,29 @@ func (r *resourceReconciler) patchResourceMetadataAndSpec(
 	}
 
 	rlog.Enter("kc.Patch (metadata + spec)")
-	// Save a copy of the latest object, to reset 'Status' after performing
-	// the kc.Patch() operation
-	latestCopy := latest.DeepCopy()
-	err = r.kc.Patch(
-		ctx,
-		latest.RuntimeObject(),
-		client.MergeFrom(desired.DeepCopy().RuntimeObject()),
-	)
-	// Reset the status of latest object after patching.
-	latest.SetStatus(latestCopy)
-	rlog.Exit("kc.Patch (metadata + spec)", err)
-
-	if err != nil {
-		return err
+	dobj := desired.DeepCopy().RuntimeObject()
+	lorig := latest.DeepCopy()
+	patch := client.MergeFrom(dobj)
+	err = r.kc.Patch(ctx, latest.RuntimeObject(), patch)
+	if err == nil {
+		if rlog.IsDebugEnabled() {
+			js := getPatchDocument(patch, lorig.RuntimeObject())
+			rlog.Debug("patched resource metadata + spec", "json", js)
+		}
 	}
-	rlog.Debug("patched resource metadata and spec", "latest", latest)
-	return nil
+	// The call to Patch() above ends up setting the latest variable's Status
+	// to the value of the desired variable's Status. We do not want this
+	// behaviour; instead, we want to keep latest's original Status value.
+	latest.SetStatus(lorig)
+	rlog.Exit("kc.Patch (metadata + spec)", err)
+	return err
 }
 
-// patchResourceStatus patches the custom resource in the Kubernetes API to match the
-// supplied latest resource.
+// patchResourceStatus patches the custom resource in the Kubernetes API to
+// match the supplied latest resource.
+//
+// NOTE(jaypipes): We make a copy of both desired and latest parameters to
+// avoid mutating either
 func (r *resourceReconciler) patchResourceStatus(
 	ctx context.Context,
 	desired acktypes.AWSResource,
@@ -642,13 +683,15 @@ func (r *resourceReconciler) patchResourceStatus(
 	}()
 
 	rlog.Enter("kc.Patch (status)")
-	err = r.kc.Status().Patch(
-		ctx,
-		latest.RuntimeObject(),
-		client.MergeFrom(desired.DeepCopy().RuntimeObject()),
-	)
+	dobj := desired.DeepCopy().RuntimeObject()
+	lobj := latest.DeepCopy().RuntimeObject()
+	patch := client.MergeFrom(dobj)
+	err = r.kc.Status().Patch(ctx, lobj, patch)
 	if err == nil {
-		rlog.Debug("patched resource status")
+		if rlog.IsDebugEnabled() {
+			js := getPatchDocument(patch, lobj)
+			rlog.Debug("patched resource status", "json", js)
+		}
 	} else if apierrors.IsNotFound(err) {
 		// reset the NotFound error so it is not printed in controller logs
 		// providing false positive error

pkg/runtime/reconciler.go

@@ -16,6 +16,9 @@ package types
 // Logger is responsible for writing log messages
 type Logger interface {
 	Tracer
+	// IsDebugEnabled returns true when the underlying logger is configured to
+	// write debug messages, false otherwise.
+	IsDebugEnabled() bool
 	// WithValues adapts the internal logger with a set of additional key/value
 	// data
 	WithValues(...interface{})