@@ -21,6 +21,7 @@ import (
2121 "bytes"
2222 "context"
2323 "encoding/json"
24+ "fmt"
2425 "io"
2526 "net"
2627 "net/http"
@@ -40,6 +41,7 @@ import (
4041 "k8s.io/apimachinery/pkg/util/validation"
4142 "k8s.io/client-go/transport"
4243 "k8s.io/utils/pointer"
44+ ctrl "sigs.k8s.io/controller-runtime"
4345 ctrlclient "sigs.k8s.io/controller-runtime/pkg/client"
4446
4547 runtimev1 "sigs.k8s.io/cluster-api/exp/runtime/api/v1alpha1"
@@ -117,6 +119,9 @@ func (c *client) IsReady() bool {
117119}
118120
119121func (c * client ) Discover (ctx context.Context , extensionConfig * runtimev1.ExtensionConfig ) (* runtimev1.ExtensionConfig , error ) {
122+ log := ctrl .LoggerFrom (ctx )
123+ log .Info ("Performing discovery for ExtensionConfig" )
124+
120125 hookGVH , err := c .catalog .GroupVersionHook (runtimehooksv1 .Discovery )
121126 if err != nil {
122127 return nil , errors .Wrapf (err , "failed to discover extension %q: failed to compute GVH of hook" , extensionConfig .Name )
@@ -187,9 +192,12 @@ func (c *client) Unregister(extensionConfig *runtimev1.ExtensionConfig) error {
187192// See CallExtension for more details on when an ExtensionHandler returns an error.
188193// The aggregated result of the ExtensionHandlers is updated into the response object passed to the function.
189194func (c * client ) CallAllExtensions (ctx context.Context , hook runtimecatalog.Hook , forObject metav1.Object , request runtime.Object , response runtimehooksv1.ResponseObject ) error {
195+ hookName := runtimecatalog .HookName (hook )
196+ log := ctrl .LoggerFrom (ctx ).WithValues ("hook" , hookName )
197+ ctx = ctrl .LoggerInto (ctx , log )
190198 gvh , err := c .catalog .GroupVersionHook (hook )
191199 if err != nil {
192- return errors .Wrapf (err , "failed to call extension handlers for hook %q: failed to compute GroupVersionHook" , runtimecatalog . HookName ( hook ) )
200+ return errors .Wrapf (err , "failed to call extension handlers for hook %q: failed to compute GroupVersionHook" , hookName )
193201 }
194202 // Make sure the request is compatible with the hook.
195203 if err := c .catalog .ValidateRequest (gvh , request ); err != nil {
@@ -205,6 +213,7 @@ func (c *client) CallAllExtensions(ctx context.Context, hook runtimecatalog.Hook
205213 return errors .Wrapf (err , "failed to call extension handlers for hook %q" , gvh .GroupHook ())
206214 }
207215
216+ log .Info (fmt .Sprintf ("Calling all extensions of hook %q" , hookName ))
208217 responses := []runtimehooksv1.ResponseObject {}
209218 for _ , registration := range registrations {
210219 // Creates a new instance of the response parameter.
@@ -221,12 +230,14 @@ func (c *client) CallAllExtensions(ctx context.Context, hook runtimecatalog.Hook
221230 }
222231 // If the object namespace isn't matched by the registration NamespaceSelector skip the call.
223232 if ! namespaceMatches {
233+ log .V (5 ).Info (fmt .Sprintf ("skipping extension handler %q as object '%s/%s' does not match selector %q of ExtensionConfig" , registration .Name , forObject .GetNamespace (), forObject .GetName (), registration .NamespaceSelector ))
224234 continue
225235 }
226236
227237 err = c .CallExtension (ctx , hook , forObject , registration .Name , request , tmpResponse )
228238 // If one of the extension handlers fails lets short-circuit here and return early.
229239 if err != nil {
240+ log .Error (err , "failed to call extension handlers" )
230241 return errors .Wrapf (err , "failed to call extension handlers for hook %q" , gvh .GroupHook ())
231242 }
232243 responses = append (responses , tmpResponse )
@@ -289,6 +300,8 @@ func lowestNonZeroRetryAfterSeconds(i, j int32) int32 {
289300// - Internal errors. Examples: hooks is incompatible with ExtensionHandler, ExtensionHandler information is missing.
290301// - Error when ExtensionHandler returns a response with `Status` set to `Failure`.
291302func (c * client ) CallExtension (ctx context.Context , hook runtimecatalog.Hook , forObject metav1.Object , name string , request runtime.Object , response runtimehooksv1.ResponseObject ) error {
303+ log := ctrl .LoggerFrom (ctx ).WithValues ("extensionHandler" , name , "hook" , runtimecatalog .HookName (hook ))
304+ ctx = ctrl .LoggerInto (ctx , log )
292305 hookGVH , err := c .catalog .GroupVersionHook (hook )
293306 if err != nil {
294307 return errors .Wrapf (err , "failed to call extension handler %q: failed to compute GroupVersionHook" , name )
@@ -320,6 +333,7 @@ func (c *client) CallExtension(ctx context.Context, hook runtimecatalog.Hook, fo
320333 return errors .Errorf ("failed to call extension handler %q: namespaceSelector did not match object %s" , name , util .ObjectKey (forObject ))
321334 }
322335
336+ log .Info (fmt .Sprintf ("Calling extension handler %q" , name ))
323337 var timeoutDuration time.Duration
324338 if registration .TimeoutSeconds != nil {
325339 timeoutDuration = time .Duration (* registration .TimeoutSeconds ) * time .Second
@@ -339,18 +353,27 @@ func (c *client) CallExtension(ctx context.Context, hook runtimecatalog.Hook, fo
339353 ignore := * registration .FailurePolicy == runtimev1 .FailurePolicyIgnore
340354 if _ , ok := err .(errCallingExtensionHandler ); ok && ignore {
341355 // Update the response to a default success response and return.
356+ log .Info (fmt .Sprintf ("ignoring error calling extension handler because of FailurePolicy %q" , * registration .FailurePolicy ))
342357 response .SetStatus (runtimehooksv1 .ResponseStatusSuccess )
343358 response .SetMessage ("" )
344359 return nil
345360 }
361+ log .Error (err , "failed to call extension handler" )
346362 return errors .Wrapf (err , "failed to call extension handler %q" , name )
347363 }
348364
349365 // If the received response is a failure then return an error.
350366 if response .GetStatus () == runtimehooksv1 .ResponseStatusFailure {
367+ log .Error (err , "extension handler returned a failure response" )
351368 return errors .Errorf ("failed to call extension handler %q: got failure response with message %q" , name , response .GetMessage ())
352369 }
353370
371+ if retryResponse , ok := response .(runtimehooksv1.RetryResponseObject ); ok && retryResponse .GetRetryAfterSeconds () != 0 {
372+ log .Info (fmt .Sprintf ("extension handler returned blocking response with retryAfterSeconds of %q" , retryResponse .GetRetryAfterSeconds ()))
373+ } else {
374+ log .Info ("extension handler returned success response" )
375+ }
376+
354377 // Received a successful response from the extension handler. The `response` object
355378 // has been populated with the result. Return no error.
356379 return nil
@@ -366,6 +389,7 @@ type httpCallOptions struct {
366389}
367390
368391func httpCall (ctx context.Context , request , response runtime.Object , opts * httpCallOptions ) error {
392+ log := ctrl .LoggerFrom (ctx )
369393 if opts == nil || request == nil || response == nil {
370394 return errors .New ("http call failed: opts, request and response cannot be nil" )
371395 }
@@ -389,6 +413,7 @@ func httpCall(ctx context.Context, request, response runtime.Object, opts *httpC
389413 responseLocal := response
390414
391415 if requireConversion {
416+ log .V (5 ).Info (fmt .Sprintf ("Hook version of supported request is %s. Converting request from %s" , opts .registrationGVH , opts .hookGVH ))
392417 // The request and response objects need to be converted to match the version supported by
393418 // the ExtensionHandler.
394419 var err error
@@ -485,6 +510,7 @@ func httpCall(ctx context.Context, request, response runtime.Object, opts *httpC
485510 }
486511
487512 if requireConversion {
513+ log .V (5 ).Info (fmt .Sprintf ("Hook version of received response is %s. Converting response to %s" , opts .registrationGVH , opts .hookGVH ))
488514 // Convert the received response to the original version of the response object.
489515 if err := opts .catalog .Convert (responseLocal , response , ctx ); err != nil {
490516 return errors .Wrapf (err , "http call failed: failed to convert response from %T to %T" , requestLocal , response )
0 commit comments