Skip to content

✨ add logging to Enqueue_owner event handler #2427

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
wants to merge 1 commit into from
Closed

✨ add logging to Enqueue_owner event handler #2427

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
50 changes: 50 additions & 0 deletions pkg/handler/enqueue_owner.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -84,6 +84,7 @@ type enqueueRequestForOwner struct {

// Create implements EventHandler.
func (e *enqueueRequestForOwner) Create(ctx context.Context, evt event.CreateEvent, q workqueue.RateLimitingInterface) {
e.logEvent("Create", evt.Object, nil)
reqs := map[reconcile.Request]empty{}
e.getOwnerReconcileRequest(evt.Object, reqs)
for req := range reqs {
Expand All @@ -93,6 +94,7 @@ func (e *enqueueRequestForOwner) Create(ctx context.Context, evt event.CreateEve

// Update implements EventHandler.
func (e *enqueueRequestForOwner) Update(ctx context.Context, evt event.UpdateEvent, q workqueue.RateLimitingInterface) {
e.logEvent("Update", evt.ObjectOld, evt.ObjectNew)
reqs := map[reconcile.Request]empty{}
e.getOwnerReconcileRequest(evt.ObjectOld, reqs)
e.getOwnerReconcileRequest(evt.ObjectNew, reqs)
Expand All @@ -103,6 +105,7 @@ func (e *enqueueRequestForOwner) Update(ctx context.Context, evt event.UpdateEve

// Delete implements EventHandler.
func (e *enqueueRequestForOwner) Delete(ctx context.Context, evt event.DeleteEvent, q workqueue.RateLimitingInterface) {
e.logEvent("Delete", evt.Object, nil)
reqs := map[reconcile.Request]empty{}
e.getOwnerReconcileRequest(evt.Object, reqs)
for req := range reqs {
Expand All @@ -112,6 +115,7 @@ func (e *enqueueRequestForOwner) Delete(ctx context.Context, evt event.DeleteEve

// Generic implements EventHandler.
func (e *enqueueRequestForOwner) Generic(ctx context.Context, evt event.GenericEvent, q workqueue.RateLimitingInterface) {
e.logEvent("Generic", evt.Object, nil)
Copy link

@fgiloux fgiloux Jul 28, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It adds some amount of processing to a code path, which is frequently called. I am wondering whether it would not be possible to leverage what is already returned by getOwnerReconcileRequest a couple of lines below to get information on the owner instead of what is made in logEvent and extractTypedOwnerReference?
Also wouldn't we want to provide information on the object itself?

reqs := map[reconcile.Request]empty{}
e.getOwnerReconcileRequest(evt.Object, reqs)
for req := range reqs {
Expand Down Expand Up @@ -197,3 +201,49 @@ func (e *enqueueRequestForOwner) getOwnersReferences(object metav1.Object) []met
// No Controller OwnerReference found
return nil
}

// logEvent logs an event with the version, kind and name of the object and its owner.
func (e *enqueueRequestForOwner) logEvent(eventType string, object, newObject client.Object) {
Copy link
Member

@erikgb erikgb Jul 28, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I am personally not a big fan of func signatures like this one - with positional parameters. Could using the builder pattern be an option here?

Copy link
Member Author

@varshaprasad96 varshaprasad96 Jul 28, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Agreed. But a builder pattern just for logEvent could be an overkill just for one helper. I'll rework on this bit, to fetch the owner references from both the objects and then pass it to logevent so that its a bit more cleaner.

var ownerReference *metav1.OwnerReference
if e.ownerType != nil && object != nil {
ownerReference = extractTypedOwnerReference(e.ownerType.GetObjectKind().GroupVersionKind(), object.GetOwnerReferences())
if ownerReference == nil && newObject != nil {
ownerReference = extractTypedOwnerReference(e.ownerType.GetObjectKind().GroupVersionKind(), newObject.GetOwnerReferences())
}
}

// If no ownerReference was found then it's probably not an event we care about
if ownerReference != nil {
kvs := []interface{}{
"Event type", eventType,
"GroupVersionKind", object.GetObjectKind().GroupVersionKind().String(),
"Name", object.GetName(),
}
if objectNs := object.GetNamespace(); objectNs != "" {
kvs = append(kvs, "Namespace", objectNs)
}
kvs = append(kvs,
"Owner APIVersion", ownerReference.APIVersion,
"Owner Kind", ownerReference.Kind,
"Owner Name", ownerReference.Name,
)

log.Info("OwnerReference handler event", kvs...)
Copy link
Contributor

@everettraven everettraven Jul 28, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What "level" does this get logged at? Is there a way for me to specify that I only want this logged at a certain verbosity level?

Copy link
Member

@erikgb erikgb Jul 28, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
log.Info("OwnerReference handler event", kvs...)
log.V(1).Info("OwnerReference handler event", kvs...)

I don't think this should be logged at the normal Info level, as it will create too chatty logs. See https://github.com/kubernetes-sigs/controller-runtime/blob/main/TMP-LOGGING.md

Copy link
Member

@alvaroaleman alvaroaleman Jul 28, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah, this is defininitely debug level, it will cause a huge amount of logs for a controller that is even slightly busy

}
}

func extractTypedOwnerReference(ownerGVK schema.GroupVersionKind, ownerReferences []metav1.OwnerReference) *metav1.OwnerReference {
for _, ownerRef := range ownerReferences {
refGV, err := schema.ParseGroupVersion(ownerRef.APIVersion)
if err != nil {
log.Error(err, "Could not parse OwnerReference APIVersion",
"api version", ownerRef.APIVersion)
}

if ownerGVK.Group == refGV.Group &&
ownerGVK.Kind == ownerRef.Kind {
return &ownerRef
}
}
return nil
}
4 changes: 3 additions & 1 deletion pkg/handler/eventhandler_suite_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -17,6 +17,7 @@ limitations under the License.
package handler_test

import (
"bytes"
"testing"

. "github.com/onsi/ginkgo/v2"
Expand All @@ -34,9 +35,10 @@ func TestEventhandler(t *testing.T) {

var testenv *envtest.Environment
var cfg *rest.Config
var logBuffer bytes.Buffer
Copy link
Member

@erikgb erikgb Jul 28, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Could this global variable cause issues since it's mutated (Reset) in the test specs? How about unit testing the logging in enqueueRequestForOwner instead of in the e2e-tests?

Copy link
Member Author

@varshaprasad96 varshaprasad96 Jul 28, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

How about unit testing the logging in enqueueRequestForOwner instead of in the e2e-tests?

The logger is currently getting tested while unit testing for specific events in enqueueRequestForOwner. Could you point to the alternate option?

Could this global variable cause issues since it's mutated (Reset) in the test specs?

Would prefer to keep this at the beginning of test suite, because it needs to be set as the default logger before starting the tests. BeforeSuite anyways gets executed only once, though we are resetting the content quite a few times in the test spec for specific tests.


var _ = BeforeSuite(func() {
logf.SetLogger(zap.New(zap.WriteTo(GinkgoWriter), zap.UseDevMode(true)))
logf.SetLogger(zap.New(zap.WriteTo(&logBuffer), zap.UseDevMode(true)))

testenv = &envtest.Environment{}
var err error
Expand Down
36 changes: 30 additions & 6 deletions pkg/handler/eventhandler_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -26,6 +26,7 @@ import (
corev1 "k8s.io/api/core/v1"
"k8s.io/apimachinery/pkg/api/meta"
metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
"k8s.io/apimachinery/pkg/runtime/schema"
"k8s.io/apimachinery/pkg/types"
"k8s.io/client-go/kubernetes/scheme"
"k8s.io/client-go/rest"
Expand All @@ -50,6 +51,7 @@ var _ = Describe("Eventhandler", func() {
pod = &corev1.Pod{
ObjectMeta: metav1.ObjectMeta{Namespace: "biz", Name: "baz"},
}
pod.SetGroupVersionKind(schema.GroupVersionKind{Group: "", Version: "v1", Kind: "Pod"})
Expect(cfg).NotTo(BeNil())

httpClient, err := rest.HTTPClientFor(cfg)
Expand Down Expand Up @@ -307,8 +309,15 @@ var _ = Describe("Eventhandler", func() {
})

Describe("EnqueueRequestForOwner", func() {
var repl *appsv1.ReplicaSet

BeforeEach(func() {
repl = &appsv1.ReplicaSet{}
repl.SetGroupVersionKind(schema.GroupVersionKind{Group: "apps", Version: "v1", Kind: "ReplicaSet"})
})

It("should enqueue a Request with the Owner of the object in the CreateEvent.", func() {
instance := handler.EnqueueRequestForOwner(scheme.Scheme, mapper, &appsv1.ReplicaSet{})
instance := handler.EnqueueRequestForOwner(scheme.Scheme, mapper, repl)

pod.OwnerReferences = []metav1.OwnerReference{
{
Expand All @@ -320,17 +329,20 @@ var _ = Describe("Eventhandler", func() {
evt := event.CreateEvent{
Object: pod,
}
logBuffer.Reset()
instance.Create(ctx, evt, q)
Expect(q.Len()).To(Equal(1))

i, _ := q.Get()
Expect(i).To(Equal(reconcile.Request{
NamespacedName: types.NamespacedName{Namespace: pod.GetNamespace(), Name: "foo-parent"}}))
Expect(logBuffer.String()).To(MatchRegexp(
`controller-runtime.eventhandler.enqueueRequestForOwner.*OwnerReference.*handler.*event.*Create.*Owner.APIVersion.*Owner.Kind.*Owner.Name.*`,
))
})

It("should enqueue a Request with the Owner of the object in the DeleteEvent.", func() {
instance := handler.EnqueueRequestForOwner(scheme.Scheme, mapper, &appsv1.ReplicaSet{})

instance := handler.EnqueueRequestForOwner(scheme.Scheme, mapper, repl)
pod.OwnerReferences = []metav1.OwnerReference{
{
Name: "foo-parent",
Expand All @@ -341,20 +353,24 @@ var _ = Describe("Eventhandler", func() {
evt := event.DeleteEvent{
Object: pod,
}
logBuffer.Reset()
instance.Delete(ctx, evt, q)
Expect(q.Len()).To(Equal(1))

i, _ := q.Get()
Expect(i).To(Equal(reconcile.Request{
NamespacedName: types.NamespacedName{Namespace: pod.GetNamespace(), Name: "foo-parent"}}))
Expect(logBuffer.String()).To(MatchRegexp(
`controller-runtime.eventhandler.enqueueRequestForOwner.*OwnerReference.*handler.*event.*Delete.*Owner.APIVersion.*Owner.Kind.*Owner.Name.*`,
))
})

It("should enqueue a Request with the Owners of both objects in the UpdateEvent.", func() {
newPod := pod.DeepCopy()
newPod.Name = pod.Name + "2"
newPod.Namespace = pod.Namespace + "2"

instance := handler.EnqueueRequestForOwner(scheme.Scheme, mapper, &appsv1.ReplicaSet{})
instance := handler.EnqueueRequestForOwner(scheme.Scheme, mapper, repl)

pod.OwnerReferences = []metav1.OwnerReference{
{
Expand All @@ -370,6 +386,7 @@ var _ = Describe("Eventhandler", func() {
APIVersion: "apps/v1",
},
}
logBuffer.Reset()
evt := event.UpdateEvent{
ObjectOld: pod,
ObjectNew: newPod,
Expand All @@ -385,6 +402,9 @@ var _ = Describe("Eventhandler", func() {
reconcile.Request{
NamespacedName: types.NamespacedName{Namespace: newPod.GetNamespace(), Name: "foo2-parent"}},
))
Expect(logBuffer.String()).To(MatchRegexp(
`controller-runtime.eventhandler.enqueueRequestForOwner.*OwnerReference.*handler.*event.*Update.*Owner.APIVersion.*Owner.Kind.*Owner.Name.*`,
))
})

It("should enqueue a Request with the one duplicate Owner of both objects in the UpdateEvent.", func() {
Expand Down Expand Up @@ -420,7 +440,7 @@ var _ = Describe("Eventhandler", func() {
})

It("should enqueue a Request with the Owner of the object in the GenericEvent.", func() {
instance := handler.EnqueueRequestForOwner(scheme.Scheme, mapper, &appsv1.ReplicaSet{})
instance := handler.EnqueueRequestForOwner(scheme.Scheme, mapper, repl)
pod.OwnerReferences = []metav1.OwnerReference{
{
Name: "foo-parent",
Expand All @@ -431,12 +451,16 @@ var _ = Describe("Eventhandler", func() {
evt := event.GenericEvent{
Object: pod,
}
logBuffer.Reset()
instance.Generic(ctx, evt, q)
Expect(q.Len()).To(Equal(1))

i, _ := q.Get()
Expect(i).To(Equal(reconcile.Request{
NamespacedName: types.NamespacedName{Namespace: pod.GetNamespace(), Name: "foo-parent"}}))
Expect(logBuffer.String()).To(MatchRegexp(
`controller-runtime.eventhandler.enqueueRequestForOwner.*OwnerReference.*handler.*event.*Generic.*Owner.APIVersion.*Owner.Kind.*Owner.Name.*`,
))
})

It("should not enqueue a Request if there are no owners matching Group and Kind.", func() {
Expand Down Expand Up @@ -467,7 +491,7 @@ var _ = Describe("Eventhandler", func() {
{
Name: "foo-parent",
Kind: "HorizontalPodAutoscaler",
APIVersion: "autoscaling/v2beta1",
APIVersion: "autoscaling/v2",
Copy link
Member Author

@varshaprasad96 varshaprasad96 Jul 27, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Bumping this since v2beta1 was deprecated since k8s 1.22

},
}
evt := event.CreateEvent{
Expand Down