runtime-sdk: add logs

exp/runtime/internal/controllers/extensionconfig_controller.go

@@ -18,6 +18,7 @@ package controllers
 
 import (
 	"context"
+	"fmt"
 	"strings"
 
 	"github.com/pkg/errors"
@@ -175,7 +176,9 @@ func patchExtensionConfig(ctx context.Context, client client.Client, original, m
 
 // reconcileDelete will remove the ExtensionConfig from the registry on deletion of the object. Note this is a best
 // effort deletion that may not catch all cases.
-func (r *Reconciler) reconcileDelete(_ context.Context, extensionConfig *runtimev1.ExtensionConfig) (ctrl.Result, error) {
+func (r *Reconciler) reconcileDelete(ctx context.Context, extensionConfig *runtimev1.ExtensionConfig) (ctrl.Result, error) {
+	log := ctrl.LoggerFrom(ctx)
+	log.Info("Un-registering extension information from extension registry")
 	if err := r.RuntimeClient.Unregister(extensionConfig); err != nil {
 		return ctrl.Result{}, errors.Wrapf(err, "failed to unregister %s", tlog.KObj{Obj: extensionConfig})
 	}
@@ -224,12 +227,16 @@ func discoverExtensionConfig(ctx context.Context, runtimeClient runtimeclient.Cl
 // Note: This was implemented to behave similar to the cert-manager cainjector.
 // We couldn't use the cert-manager cainjector because it doesn't work with CustomResources.
 func reconcileCABundle(ctx context.Context, client client.Client, config *runtimev1.ExtensionConfig) error {
+	log := ctrl.LoggerFrom(ctx)
+
 	secretNameRaw, ok := config.Annotations[runtimev1.InjectCAFromSecretAnnotation]
 	if !ok {
 		return nil
 	}
 	secretName := splitNamespacedName(secretNameRaw)
 
+	log.Info(fmt.Sprintf("Injecting CA Bundle into extension '%s/%s' from secret '%s'", config.Namespace, config.Name, secretName))
+
 	if secretName.Namespace == "" || secretName.Name == "" {
 		return errors.Errorf("failed to reconcile caBundle: secret name %q must be in the form <namespace>/<name>", secretNameRaw)
 	}

exp/runtime/internal/controllers/warmup.go

@@ -89,6 +89,8 @@ func (r *warmupRunnable) Start(ctx context.Context) error {
 // warmupRegistry attempts to discover all existing ExtensionConfigs and patch their status with discovered Handlers.
 // It warms up the registry by passing it the up-to-date list of ExtensionConfigs.
 func warmupRegistry(ctx context.Context, client client.Client, reader client.Reader, runtimeClient runtimeclient.Client) error {
+	log := ctrl.LoggerFrom(ctx)
+
 	var errs []error
 
 	extensionConfigList := runtimev1.ExtensionConfigList{}
@@ -128,5 +130,7 @@ func warmupRegistry(ctx context.Context, client client.Client, reader client.Rea
 		return err
 	}
 
+	log.Info("The extension registry is warmed up")
+
 	return nil
 }

internal/controllers/topology/cluster/cluster_controller.go

@@ -37,12 +37,14 @@ import (
 	clusterv1 "sigs.k8s.io/cluster-api/api/v1beta1"
 	"sigs.k8s.io/cluster-api/api/v1beta1/index"
 	"sigs.k8s.io/cluster-api/controllers/external"
+	runtimecatalog "sigs.k8s.io/cluster-api/exp/runtime/catalog"
 	runtimehooksv1 "sigs.k8s.io/cluster-api/exp/runtime/hooks/api/v1alpha1"
 	"sigs.k8s.io/cluster-api/feature"
 	"sigs.k8s.io/cluster-api/internal/controllers/topology/cluster/patches"
 	"sigs.k8s.io/cluster-api/internal/controllers/topology/cluster/scope"
 	"sigs.k8s.io/cluster-api/internal/controllers/topology/cluster/structuredmerge"
 	"sigs.k8s.io/cluster-api/internal/hooks"
+	tlog "sigs.k8s.io/cluster-api/internal/log"
 	runtimeclient "sigs.k8s.io/cluster-api/internal/runtime/client"
 	"sigs.k8s.io/cluster-api/util"
 	"sigs.k8s.io/cluster-api/util/annotations"
@@ -273,6 +275,7 @@ func (r *Reconciler) setupDynamicWatches(ctx context.Context, s *scope.Scope) er
 func (r *Reconciler) callBeforeClusterCreateHook(ctx context.Context, s *scope.Scope) (reconcile.Result, error) {
 	// If the cluster objects (InfraCluster, ControlPlane, etc) are not yet created we are in the creation phase.
 	// Call the BeforeClusterCreate hook before proceeding.
+	log := tlog.LoggerFrom(ctx)
 	if s.Current.Cluster.Spec.InfrastructureRef == nil && s.Current.Cluster.Spec.ControlPlaneRef == nil {
 		hookRequest := &runtimehooksv1.BeforeClusterCreateRequest{
 			Cluster: *s.Current.Cluster,
@@ -283,6 +286,7 @@ func (r *Reconciler) callBeforeClusterCreateHook(ctx context.Context, s *scope.S
 		}
 		s.HookResponseTracker.Add(runtimehooksv1.BeforeClusterCreate, hookResponse)
 		if hookResponse.RetryAfterSeconds != 0 {
+			log.Infof("Creation of Cluster topology is blocked by %s hook", runtimecatalog.HookName(runtimehooksv1.BeforeClusterCreate))
 			return ctrl.Result{RequeueAfter: time.Duration(hookResponse.RetryAfterSeconds) * time.Second}, nil
 		}
 	}
@@ -338,6 +342,7 @@ func (r *Reconciler) machineDeploymentToCluster(o client.Object) []ctrl.Request
 func (r *Reconciler) reconcileDelete(ctx context.Context, cluster *clusterv1.Cluster) (ctrl.Result, error) {
 	// Call the BeforeClusterDelete hook if the 'ok-to-delete' annotation is not set
 	// and add the annotation to the cluster after receiving a successful non-blocking response.
+	log := tlog.LoggerFrom(ctx)
 	if feature.Gates.Enabled(feature.RuntimeSDK) {
 		if !hooks.IsOkToDelete(cluster) {
 			hookRequest := &runtimehooksv1.BeforeClusterDeleteRequest{
@@ -348,6 +353,7 @@ func (r *Reconciler) reconcileDelete(ctx context.Context, cluster *clusterv1.Clu
 				return ctrl.Result{}, err
 			}
 			if hookResponse.RetryAfterSeconds != 0 {
+				log.Infof("Cluster deletion is blocked by %s hook", runtimecatalog.HookName(runtimehooksv1.BeforeClusterDelete))
 				return ctrl.Result{RequeueAfter: time.Duration(hookResponse.RetryAfterSeconds) * time.Second}, nil
 			}
 			// The BeforeClusterDelete hook returned a non-blocking response. Now the cluster is ready to be deleted.

internal/controllers/topology/cluster/desired_state.go

@@ -31,6 +31,7 @@ import (
 
 	clusterv1 "sigs.k8s.io/cluster-api/api/v1beta1"
 	"sigs.k8s.io/cluster-api/controllers/external"
+	runtimecatalog "sigs.k8s.io/cluster-api/exp/runtime/catalog"
 	runtimehooksv1 "sigs.k8s.io/cluster-api/exp/runtime/hooks/api/v1alpha1"
 	"sigs.k8s.io/cluster-api/feature"
 	"sigs.k8s.io/cluster-api/internal/contract"
@@ -257,6 +258,7 @@ func (r *Reconciler) computeControlPlane(ctx context.Context, s *scope.Scope, in
 // The version is calculated using the state of the current machine deployments, the current control plane
 // and the version defined in the topology.
 func (r *Reconciler) computeControlPlaneVersion(ctx context.Context, s *scope.Scope) (string, error) {
+	log := tlog.LoggerFrom(ctx)
 	desiredVersion := s.Blueprint.Topology.Version
 	// If we are creating the control plane object (current control plane is nil), use version from topology.
 	if s.Current.ControlPlane == nil || s.Current.ControlPlane.Object == nil {
@@ -334,6 +336,7 @@ func (r *Reconciler) computeControlPlaneVersion(ctx context.Context, s *scope.Sc
 				// change the UpgradeTracker accordingly, otherwise the hook call is completed and we
 				// can remove this hook from the list of pending-hooks.
 				if hookResponse.RetryAfterSeconds != 0 {
+					log.Infof("MachineDeployments upgrade to version '%s' are blocked by %s hook", desiredVersion, runtimecatalog.HookName(runtimehooksv1.AfterControlPlaneUpgrade))
 					s.UpgradeTracker.MachineDeployments.HoldUpgrades(true)
 				} else {
 					if err := hooks.MarkAsDone(ctx, r.Client, s.Current.Cluster, runtimehooksv1.AfterControlPlaneUpgrade); err != nil {
@@ -383,6 +386,7 @@ func (r *Reconciler) computeControlPlaneVersion(ctx context.Context, s *scope.Sc
 		s.HookResponseTracker.Add(runtimehooksv1.BeforeClusterUpgrade, hookResponse)
 		if hookResponse.RetryAfterSeconds != 0 {
 			// Cannot pickup the new version right now. Need to try again later.
+			log.Infof("Cluster upgrade to version '%s' is blocked by %s hook", desiredVersion, runtimecatalog.HookName(runtimehooksv1.BeforeClusterUpgrade))
 			return *currentVersion, nil
 		}
 

internal/runtime/client/client.go

@@ -21,6 +21,7 @@ import (
 	"bytes"
 	"context"
 	"encoding/json"
+	"fmt"
 	"io"
 	"net"
 	"net/http"
@@ -40,6 +41,7 @@ import (
 	"k8s.io/apimachinery/pkg/util/validation"
 	"k8s.io/client-go/transport"
 	"k8s.io/utils/pointer"
+	ctrl "sigs.k8s.io/controller-runtime"
 	ctrlclient "sigs.k8s.io/controller-runtime/pkg/client"
 
 	runtimev1 "sigs.k8s.io/cluster-api/exp/runtime/api/v1alpha1"
@@ -117,6 +119,9 @@ func (c *client) IsReady() bool {
 }
 
 func (c *client) Discover(ctx context.Context, extensionConfig *runtimev1.ExtensionConfig) (*runtimev1.ExtensionConfig, error) {
+	log := ctrl.LoggerFrom(ctx)
+	log.Info(fmt.Sprintf("Performing discovery for Extension %s/%s", extensionConfig.Namespace, extensionConfig.Name))
+
 	hookGVH, err := c.catalog.GroupVersionHook(runtimehooksv1.Discovery)
 	if err != nil {
 		return nil, errors.Wrapf(err, "failed to discover extension %q: failed to compute GVH of hook", extensionConfig.Name)
@@ -187,6 +192,7 @@ 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)
 	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", runtimecatalog.HookName(hook))
@@ -205,6 +211,7 @@ func (c *client) CallAllExtensions(ctx context.Context, hook runtimecatalog.Hook
 		return errors.Wrapf(err, "failed to call extension handlers for hook %q", gvh.GroupHook())
 	}
 
+	log.Info(fmt.Sprintf("Calling all extensions of hook '%s'", runtimecatalog.HookName(hook)))
 	responses := []runtimehooksv1.ResponseObject{}
 	for _, registration := range registrations {
 		// Creates a new instance of the response parameter.
@@ -289,6 +296,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)
 	hookGVH, err := c.catalog.GroupVersionHook(hook)
 	if err != nil {
 		return errors.Wrapf(err, "failed to call extension handler %q: failed to compute GroupVersionHook", name)
@@ -320,6 +328,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 '%s' of hook '%s'", name, runtimecatalog.HookName(hook)))
 	var timeoutDuration time.Duration
 	if registration.TimeoutSeconds != nil {
 		timeoutDuration = time.Duration(*registration.TimeoutSeconds) * time.Second
@@ -366,6 +375,7 @@ type httpCallOptions struct {
 }
 
 func httpCall(ctx context.Context, request, response runtime.Object, opts *httpCallOptions) error {
+	log := ctrl.LoggerFrom(ctx)
 	if opts == nil || request == nil || response == nil {
 		return errors.New("http call failed: opts, request and response cannot be nil")
 	}
@@ -389,6 +399,7 @@ func httpCall(ctx context.Context, request, response runtime.Object, opts *httpC
 	responseLocal := response
 
 	if requireConversion {
+		log.V(5).Info(fmt.Sprintf("Supported hook version of extension is different. Converting request to %s", opts.registrationGVH))
 		// The request and response objects need to be converted to match the version supported by
 		// the ExtensionHandler.
 		var err error
@@ -485,6 +496,7 @@ func httpCall(ctx context.Context, request, response runtime.Object, opts *httpC
 	}
 
 	if requireConversion {
+		log.V(5).Info(fmt.Sprintf("Hook version of received response is different. Converting response back to %s", opts.hookGVH))
 		// Convert the received response to the original version of the response object.
 		if err := opts.catalog.Convert(responseLocal, response, ctx); err != nil {
 			return errors.Wrapf(err, "http call failed: failed to convert response from %T to %T", requestLocal, response)