✨ add logging to Enqueue_owner event handler #2427

varshaprasad96 · 2023-07-27T21:21:21Z

This PR adds logging to Enqueue owner event handler, that is helpful in logging the GVK of the owner that
caused reconciliation.

Fixes: #1186

In Operator SDK we have a LoggingEnqueueRequestForOwnerHandler (ref) that used to add logging to the existing EnqueueRequestForOwnerHandler. In C-R 0.15.0 this was made internal, making it difficult to create a wrapper around it. However, adding logging to the existing handler available in c-r would be useful to other consumers also in identifying the cause of reconcile.

This PR adds logging to Enqueue owner event handler, that is helpful in logging the GVK of the owner that caused reconcilation. Signed-off-by: Varsha Prasad Narsing <varshaprasad96@gmail.com>

k8s-ci-robot · 2023-07-27T21:21:32Z

[APPROVALNOTIFIER] This PR is NOT APPROVED

This pull-request has been approved by: varshaprasad96
Once this PR has been reviewed and has the lgtm label, please assign sbueringer for approval. For more information see the Kubernetes Code Review Process.

The full list of commands accepted by this bot can be found here.

Needs approval from an approver in each of these files:

OWNERS

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

varshaprasad96 · 2023-07-27T21:22:32Z

pkg/handler/eventhandler_test.go

@@ -467,7 +491,7 @@ var _ = Describe("Eventhandler", func() {
 				{
 					Name:       "foo-parent",
 					Kind:       "HorizontalPodAutoscaler",
-					APIVersion: "autoscaling/v2beta1",
+					APIVersion: "autoscaling/v2",


Bumping this since v2beta1 was deprecated since k8s 1.22

everettraven · 2023-07-28T14:50:42Z

pkg/handler/enqueue_owner.go

+			"Owner Name", ownerReference.Name,
+		)
+
+		log.Info("OwnerReference handler event", kvs...)


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?

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

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

erikgb · 2023-07-28T15:03:12Z

pkg/handler/enqueue_owner.go

+			"Owner Name", ownerReference.Name,
+		)
+
+		log.Info("OwnerReference handler event", kvs...)


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

erikgb · 2023-07-28T15:05:44Z

pkg/handler/enqueue_owner.go

@@ -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) {


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?

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.

erikgb · 2023-07-28T15:23:32Z

pkg/handler/eventhandler_suite_test.go

@@ -34,9 +35,10 @@ func TestEventhandler(t *testing.T) {

 var testenv *envtest.Environment
 var cfg *rest.Config
+var logBuffer bytes.Buffer


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?

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.

fgiloux · 2023-07-28T15:57:36Z

pkg/handler/enqueue_owner.go

@@ -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)


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?

alvaroaleman · 2023-07-28T17:11:37Z

@varshaprasad96 sorry, I don't understand the problem you are solving. How does the implementation being internal prevent you from adding logging? Your wrapper can and should wrap the handler.Handler interface, not the concrete implementation.

I am not a huge fan of this because it opens a can of worms:

Maybe the next person wants some additional information to be logged, like what requests actually came out of the handler
Maybe the next person wants that for some other handler
Maybe the third person would also like to have metrics for this

I'd prefer it if we made it easy to wrap a handler, possibly even provide a generic logging implementation but not adjust all the handlers.

erikgb · 2023-07-28T21:40:30Z

I agree with @alvaroaleman, and to get a bit more familiar with the c-r codebase, I drafted something that might allow users to wrap event handlers. Feel free to use it in a new PR if you like the idea: 2f01213

varshaprasad96 · 2023-08-04T15:20:50Z

Your wrapper can and should wrap the handler.Handler interface, not the concrete implementation.

@alvaroaleman Agreed that we need to implement the handler interface. However, enqueueRequestForOwner is a commonly used handler, which is what we are looking to re-use, just with additional logging on who the owner was that caused reconcile.

How does the implementation being internal prevent you from adding logging?
Based on the current state, if we want to customize and reuse a particular implementation of handler we would have to re-write the same piece of code that implements the interface.

I would like to explore the options before closing the PR here:

Agreed on @erikgb's implementation, implementing a logging handler and providing an option to wrap it with existing one's is useful.
Injecting a logger into the handler implementation (similar to how it was done in previous implementations with inject pkg), where if provided we would log the details on the events. Or have the current implementation and allow users to enable/disable it using Options. (Con: we cannot control the log message for each event).
Provide an option to enable passing of multiple event handlers. Each event handler would create a listener (https://github.com/kubernetes/kubernetes/blob/2c6c4566eff972d6c1320b5f8ad795f88c822d09/staging/src/k8s.io/client-go/tools/cache/shared_informer.go#L556), which would then be enabled here.

I'm not super familiar with the client-go side of code, but the question which I have with (1) and (3) is while wrapping or enabling multiple handlers, there is no guarantee on the order in which listeners will be distributed. Which is something we would want to maintain at least while logging for a particular event?

alvaroaleman · 2023-08-14T18:35:36Z

Agreed that we need to implement the handler interface. However, enqueueRequestForOwner is a commonly used handler, which is what we are looking to re-use, just with additional logging on who the owner was that caused reconcile.

Yeah, you can do that as a wraper.

Injecting a logger into the handler implementation (similar to how it was done in previous implementations with inject pkg), where if provided we would log the details on the events. Or have the current implementation and allow users to enable/disable it using Options. (Con: we cannot control the log message for each event).

The approach of injecting things is deprecated. You can get a logger from the manager or anywhere else.

Provide an option to enable passing of multiple event handlers. Each event handler would create a listener [..]

I don't understand this part. The source registers the eventhandler in the cache and then passed the event onto the predicate.predicate and finally handler.Handler (the package here). Why do you want multiple handlers?

sbueringer · 2024-01-03T16:11:43Z

I'm inclined to close this PR given no recent activity and the alternative suggested by @alvaroaleman. @varshaprasad96 WDYT?

k8s-triage-robot · 2024-04-02T16:46:06Z

The Kubernetes project currently lacks enough contributors to adequately respond to all PRs.

This bot triages PRs according to the following rules:

After 90d of inactivity, lifecycle/stale is applied
After 30d of inactivity since lifecycle/stale was applied, lifecycle/rotten is applied
After 30d of inactivity since lifecycle/rotten was applied, the PR is closed

You can:

Mark this PR as fresh with /remove-lifecycle stale
Close this PR with /close
Offer to help out with Issue Triage

Please send feedback to sig-contributor-experience at kubernetes/community.

/lifecycle stale

vincepri · 2024-04-02T20:25:58Z

/close

per comment above

k8s-ci-robot · 2024-04-02T20:26:03Z

@vincepri: Closed this PR.

In response to this:

/close

per comment above

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

✨ add logging to Enqueue_owner event handler

0edc5c2

This PR adds logging to Enqueue owner event handler, that is helpful in logging the GVK of the owner that caused reconcilation. Signed-off-by: Varsha Prasad Narsing <varshaprasad96@gmail.com>

k8s-ci-robot added the cncf-cla: yes Indicates the PR's author has signed the CNCF CLA. label Jul 27, 2023

k8s-ci-robot requested review from FillZpp and inteon July 27, 2023 21:21

k8s-ci-robot added the size/M Denotes a PR that changes 30-99 lines, ignoring generated files. label Jul 27, 2023

varshaprasad96 commented Jul 27, 2023

View reviewed changes

varshaprasad96 mentioned this pull request Jul 27, 2023

wip: work on bumping KB operator-framework/operator-sdk#6514

Closed

6 tasks

everettraven reviewed Jul 28, 2023

View reviewed changes

erikgb reviewed Jul 28, 2023

View reviewed changes

fgiloux reviewed Jul 28, 2023

View reviewed changes

oceanc80 mentioned this pull request Oct 18, 2023

Bump golang, k8s operator-framework/ansible-operator-plugins#37

Merged

k8s-ci-robot added the lifecycle/stale Denotes an issue or PR has remained open with no activity and has become stale. label Apr 2, 2024

k8s-ci-robot closed this Apr 2, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

✨ add logging to Enqueue_owner event handler #2427

✨ add logging to Enqueue_owner event handler #2427

varshaprasad96 commented Jul 27, 2023

k8s-ci-robot commented Jul 27, 2023

varshaprasad96 Jul 27, 2023

everettraven Jul 28, 2023

erikgb Jul 28, 2023

alvaroaleman Jul 28, 2023

erikgb Jul 28, 2023

erikgb Jul 28, 2023

varshaprasad96 Jul 28, 2023

erikgb Jul 28, 2023

varshaprasad96 Jul 28, 2023

fgiloux Jul 28, 2023

alvaroaleman commented Jul 28, 2023 •

edited

erikgb commented Jul 28, 2023

varshaprasad96 commented Aug 4, 2023

alvaroaleman commented Aug 14, 2023

sbueringer commented Jan 3, 2024

k8s-triage-robot commented Apr 2, 2024

vincepri commented Apr 2, 2024

k8s-ci-robot commented Apr 2, 2024

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

✨ add logging to Enqueue_owner event handler #2427

✨ add logging to Enqueue_owner event handler #2427

Conversation

varshaprasad96 commented Jul 27, 2023

k8s-ci-robot commented Jul 27, 2023

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

alvaroaleman commented Jul 28, 2023 • edited

erikgb commented Jul 28, 2023

varshaprasad96 commented Aug 4, 2023

alvaroaleman commented Aug 14, 2023

sbueringer commented Jan 3, 2024

k8s-triage-robot commented Apr 2, 2024

vincepri commented Apr 2, 2024

k8s-ci-robot commented Apr 2, 2024

alvaroaleman commented Jul 28, 2023 •

edited