Add logs that allow users to see what events the controller is receiving

changelog/fragments/ansible_log_events.yaml

@@ -0,0 +1,10 @@
+# entries is a list of entries to include in
+# release notes and/or the migration guide
+entries:
+  - description: >
+      For Ansible-based operators, adds log messages for each event that is received.
+      This will make debugging excessive reconciliations much more straightforward.
+
+    kind: "addition"
+
+    breaking: false

go.mod

@@ -15,6 +15,7 @@ require (
 	github.com/operator-framework/operator-lib v0.4.0
 	github.com/operator-framework/operator-registry v1.15.3
 	github.com/prometheus/client_golang v1.7.1
+	github.com/prometheus/client_model v0.2.0
 	github.com/sergi/go-diff v1.1.0
 	github.com/sirupsen/logrus v1.7.0
 	github.com/spf13/afero v1.2.2

internal/ansible/controller/controller.go

@@ -20,7 +20,6 @@ import (
 	"strings"
 	"time"
 
-	"github.com/operator-framework/operator-lib/handler"
 	libpredicate "github.com/operator-framework/operator-lib/predicate"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	"k8s.io/apimachinery/pkg/apis/meta/v1/unstructured"
@@ -33,6 +32,7 @@ import (
 	"sigs.k8s.io/controller-runtime/pkg/source"
 
 	"github.com/operator-framework/operator-sdk/internal/ansible/events"
+	"github.com/operator-framework/operator-sdk/internal/ansible/handler"
 	"github.com/operator-framework/operator-sdk/internal/ansible/predicate"
 	"github.com/operator-framework/operator-sdk/internal/ansible/runner"
 )
@@ -112,7 +112,7 @@ func Add(mgr manager.Manager, options Options) *controller.Controller {
 
 	u := &unstructured.Unstructured{}
 	u.SetGroupVersionKind(options.GVK)
-	err = c.Watch(&source.Kind{Type: u}, &handler.InstrumentedEnqueueRequestForObject{}, predicates...)
+	err = c.Watch(&source.Kind{Type: u}, &handler.LoggingEnqueueRequestForObject{}, predicates...)
 	if err != nil {
 		log.Error(err, "")
 		os.Exit(1)

internal/ansible/handler/handler_suite_test.go

@@ -0,0 +1,36 @@
+// Copyright 2021 The Operator-SDK Authors
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+package handler
+
+import (
+	"bytes"
+	"testing"
+
+	. "github.com/onsi/ginkgo"
+	. "github.com/onsi/gomega"
+	logf "sigs.k8s.io/controller-runtime/pkg/log"
+	"sigs.k8s.io/controller-runtime/pkg/log/zap"
+)
+
+var logBuffer bytes.Buffer
+
+func TestEventhandler(t *testing.T) {
+	RegisterFailHandler(Fail)
+	RunSpecs(t, "Handler Suite")
+}
+
+var _ = BeforeSuite(func() {
+	logf.SetLogger(zap.New(zap.WriteTo(&logBuffer), zap.UseDevMode(true)))
+})

internal/ansible/handler/logging_enqueue_annotation.go

@@ -0,0 +1,112 @@
+// Copyright 2021 The Operator-SDK Authors
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+package handler
+
+import (
+	"fmt"
+	"strings"
+
+	"github.com/operator-framework/operator-lib/handler"
+
+	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
+	"k8s.io/apimachinery/pkg/runtime/schema"
+	"k8s.io/apimachinery/pkg/types"
+	"k8s.io/client-go/util/workqueue"
+	"sigs.k8s.io/controller-runtime/pkg/client"
+	"sigs.k8s.io/controller-runtime/pkg/event"
+)
+
+const (
+	nilString = "<nil>"
+)
+
+// LoggingEnqueueRequestForAnnotation wraps operator-lib handler for
+// "InstrumentedEnqueueRequestForObject", and logs the events as they occur
+//		&handler.LoggingEnqueueRequestForAnnotation{}
+type LoggingEnqueueRequestForAnnotation struct {
+	handler.EnqueueRequestForAnnotation
+}
+
+// Create implements EventHandler, and emits a log message.
+func (h LoggingEnqueueRequestForAnnotation) Create(e event.CreateEvent, q workqueue.RateLimitingInterface) {
+	h.logEvent("Create", e.Object, nil)
+	h.EnqueueRequestForAnnotation.Create(e, q)
+}
+
+// Update implements EventHandler, and emits a log message.
+func (h LoggingEnqueueRequestForAnnotation) Update(e event.UpdateEvent, q workqueue.RateLimitingInterface) {
+	h.logEvent("Update", e.ObjectOld, e.ObjectNew)
+	h.EnqueueRequestForAnnotation.Update(e, q)
+}
+
+// Delete implements EventHandler, and emits a log message.
+func (h LoggingEnqueueRequestForAnnotation) Delete(e event.DeleteEvent, q workqueue.RateLimitingInterface) {
+	h.logEvent("Delete", e.Object, nil)
+	h.EnqueueRequestForAnnotation.Delete(e, q)
+}
+
+// Generic implements EventHandler, and emits a log message.
+func (h LoggingEnqueueRequestForAnnotation) Generic(e event.GenericEvent, q workqueue.RateLimitingInterface) {
+	h.logEvent("Generic", e.Object, nil)
+	h.EnqueueRequestForAnnotation.Generic(e, q)
+}
+
+func (h LoggingEnqueueRequestForAnnotation) logEvent(eventType string, object, newObject client.Object) {
+	typeString, name, namespace := extractTypedOwnerAnnotations(h.EnqueueRequestForAnnotation.Type, object)
+	if newObject != nil && typeString == "" {
+		typeString, name, namespace = extractTypedOwnerAnnotations(h.EnqueueRequestForAnnotation.Type, newObject)
+	}
+	if namespace == "" {
+		namespace = nilString
+	}
+
+	objectNs := object.GetNamespace()
+	if objectNs == "" {
+		objectNs = nilString
+	}
+
+	if name != "" && typeString != "" {
+		log.Info(fmt.Sprintf("Received %s event for dependent resource with GVK %s with name %s in namespace %s, mapped to owner GK %s with name %s in namespace %s",
+			eventType,
+			object.GetObjectKind().GroupVersionKind().String(),
+			object.GetName(),
+			objectNs,
+			typeString,
+			name,
+			namespace))
+	}
+}
+
+func extractTypedOwnerAnnotations(ownerGK schema.GroupKind, object metav1.Object) (string, string, string) {
+	if typeString, ok := object.GetAnnotations()[handler.TypeAnnotation]; ok && typeString == ownerGK.String() {
+		if namespacedNameString, ok := object.GetAnnotations()[handler.NamespacedNameAnnotation]; ok {
+			parsed := parseNamespacedName(namespacedNameString)
+			return typeString, parsed.Name, parsed.Namespace
+		}
+	}
+	return "", "", ""
+}
+
+// parseNamespacedName parses the provided string to extract the namespace and name into a
+// types.NamespacedName. The edge case of empty string is handled prior to calling this function.
+func parseNamespacedName(namespacedNameString string) types.NamespacedName {
+	values := strings.SplitN(namespacedNameString, "/", 2)
+
+	switch len(values) {
+	case 1:
+		return types.NamespacedName{Name: values[0]}
+	default:
+		return types.NamespacedName{Namespace: values[0], Name: values[1]}
+	}
+}