From c4ec2ae557b4ab94ce6e4163f703db6ed9482140 Mon Sep 17 00:00:00 2001
From: Yuvaraj Kakaraparthi <kakaraparthy@vmware.com>
Date: Thu, 7 Jul 2022 17:13:53 -0700
Subject: [PATCH] address review comments

---
 internal/runtime/client/client.go | 16 ++++++++++------
 1 file changed, 10 insertions(+), 6 deletions(-)

diff --git a/internal/runtime/client/client.go b/internal/runtime/client/client.go
index e3e427cd2efc..6108d8122c41 100644
--- a/internal/runtime/client/client.go
+++ b/internal/runtime/client/client.go
@@ -192,8 +192,8 @@ func (c *client) Unregister(extensionConfig *runtimev1.ExtensionConfig) error {
 // See CallExtension for more details on when an ExtensionHandler returns an error.
 // The aggregated result of the ExtensionHandlers is updated into the response object passed to the function.
 func (c *client) CallAllExtensions(ctx context.Context, hook runtimecatalog.Hook, forObject metav1.Object, request runtime.Object, response runtimehooksv1.ResponseObject) error {
-	log := ctrl.LoggerFrom(ctx)
 	hookName := runtimecatalog.HookName(hook)
+	log := ctrl.LoggerFrom(ctx).WithValues("hook", hookName)
 	gvh, err := c.catalog.GroupVersionHook(hook)
 	if err != nil {
 		return errors.Wrapf(err, "failed to call extension handlers for hook %q: failed to compute GroupVersionHook", hookName)
@@ -229,12 +229,15 @@ func (c *client) CallAllExtensions(ctx context.Context, hook runtimecatalog.Hook
 		}
 		// If the object namespace isn't matched by the registration NamespaceSelector skip the call.
 		if !namespaceMatches {
+			log.V(5).Info(fmt.Sprintf("skipping object %s/%s as it does not match selector %q of ExtensionConfig", forObject.GetNamespace(), forObject.GetName(), registration.NamespaceSelector))
 			continue
 		}
 
+		ctx := ctrl.LoggerInto(ctx, log)
 		err = c.CallExtension(ctx, hook, forObject, registration.Name, request, tmpResponse)
 		// If one of the extension handlers fails lets short-circuit here and return early.
 		if err != nil {
+			log.Error(err, "failed to call extension handlers")
 			return errors.Wrapf(err, "failed to call extension handlers for hook %q", gvh.GroupHook())
 		}
 		responses = append(responses, tmpResponse)
@@ -297,8 +300,7 @@ func lowestNonZeroRetryAfterSeconds(i, j int32) int32 {
 // - Internal errors. Examples: hooks is incompatible with ExtensionHandler, ExtensionHandler information is missing.
 // - Error when ExtensionHandler returns a response with `Status` set to `Failure`.
 func (c *client) CallExtension(ctx context.Context, hook runtimecatalog.Hook, forObject metav1.Object, name string, request runtime.Object, response runtimehooksv1.ResponseObject) error {
-	log := ctrl.LoggerFrom(ctx)
-	hookName := runtimecatalog.HookName(hook)
+	log := ctrl.LoggerFrom(ctx).WithValues("extensionHandler", name, "hook", runtimecatalog.HookName(hook))
 	hookGVH, err := c.catalog.GroupVersionHook(hook)
 	if err != nil {
 		return errors.Wrapf(err, "failed to call extension handler %q: failed to compute GroupVersionHook", name)
@@ -330,7 +332,7 @@ func (c *client) CallExtension(ctx context.Context, hook runtimecatalog.Hook, fo
 		return errors.Errorf("failed to call extension handler %q: namespaceSelector did not match object %s", name, util.ObjectKey(forObject))
 	}
 
-	log.Info(fmt.Sprintf("Calling extension %q of hook %q", name, hookName))
+	log.Info(fmt.Sprintf("Calling extension handler %q", name))
 	var timeoutDuration time.Duration
 	if registration.TimeoutSeconds != nil {
 		timeoutDuration = time.Duration(*registration.TimeoutSeconds) * time.Second
@@ -350,21 +352,23 @@ func (c *client) CallExtension(ctx context.Context, hook runtimecatalog.Hook, fo
 		ignore := *registration.FailurePolicy == runtimev1.FailurePolicyIgnore
 		if _, ok := err.(errCallingExtensionHandler); ok && ignore {
 			// Update the response to a default success response and return.
-			log.V(5).Info(fmt.Sprintf("error calling extension %q of hook %q ignored because of FailurePolicy %q", name, hookName, *registration.FailurePolicy))
+			log.V(5).Info(fmt.Sprintf("ignoring error calling extension handler because of FailurePolicy %q", *registration.FailurePolicy))
 			response.SetStatus(runtimehooksv1.ResponseStatusSuccess)
 			response.SetMessage("")
 			return nil
 		}
+		log.Error(err, "failed to call extension handler")
 		return errors.Wrapf(err, "failed to call extension handler %q", name)
 	}
 
 	// If the received response is a failure then return an error.
 	if response.GetStatus() == runtimehooksv1.ResponseStatusFailure {
+		log.Error(err, "extension handler returned a failure response")
 		return errors.Errorf("failed to call extension handler %q: got failure response with message %q", name, response.GetMessage())
 	}
 
 	if retryResponse, ok := response.(runtimehooksv1.RetryResponseObject); ok && retryResponse.GetRetryAfterSeconds() != 0 {
-		log.Info(fmt.Sprintf("extension %q of hook %q returned blocking response with retryAfterSeconds of %q", name, hookName, retryResponse.GetRetryAfterSeconds()))
+		log.Info(fmt.Sprintf("extension handler returned blocking response with retryAfterSeconds of %q", retryResponse.GetRetryAfterSeconds()))
 	}
 
 	// Received a successful response from the extension handler. The `response` object