From 4843b49248d09c4d4963918212d8826a6fba42f9 Mon Sep 17 00:00:00 2001 From: Yuvaraj Kakaraparthi Date: Tue, 5 Jul 2022 15:19:03 -0700 Subject: [PATCH] runtime-sdk: add logs --- .../controllers/extensionconfig_controller.go | 10 ++++++- exp/runtime/internal/controllers/warmup.go | 8 ++++++ .../topology/cluster/cluster_controller.go | 6 ++++ .../topology/cluster/desired_state.go | 4 +++ internal/runtime/client/client.go | 28 ++++++++++++++++++- 5 files changed, 54 insertions(+), 2 deletions(-) diff --git a/exp/runtime/internal/controllers/extensionconfig_controller.go b/exp/runtime/internal/controllers/extensionconfig_controller.go index d6746b0e11c9..361a5c1c00bb 100644 --- a/exp/runtime/internal/controllers/extensionconfig_controller.go +++ b/exp/runtime/internal/controllers/extensionconfig_controller.go @@ -18,6 +18,7 @@ package controllers import ( "context" + "fmt" "strings" "github.com/pkg/errors" @@ -151,6 +152,7 @@ func (r *Reconciler) Reconcile(ctx context.Context, req ctrl.Request) (ctrl.Resu } // Register the ExtensionConfig if it was found and patched without error. + log.Info("Registering ExtensionConfig information into registry") if err = r.RuntimeClient.Register(discoveredExtensionConfig); err != nil { return ctrl.Result{}, errors.Wrapf(err, "failed to register ExtensionConfig %s/%s", extensionConfig.Namespace, extensionConfig.Name) } @@ -175,7 +177,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("Unregistering ExtensionConfig information from 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 +228,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 ExtensionConfig from secret %q", secretNameRaw)) + if secretName.Namespace == "" || secretName.Name == "" { return errors.Errorf("failed to reconcile caBundle: secret name %q must be in the form /", secretNameRaw) } diff --git a/exp/runtime/internal/controllers/warmup.go b/exp/runtime/internal/controllers/warmup.go index 1204ac6ec134..e120d3c81c0f 100644 --- a/exp/runtime/internal/controllers/warmup.go +++ b/exp/runtime/internal/controllers/warmup.go @@ -23,6 +23,7 @@ import ( "github.com/pkg/errors" kerrors "k8s.io/apimachinery/pkg/util/errors" "k8s.io/apimachinery/pkg/util/wait" + "k8s.io/klog/v2" ctrl "sigs.k8s.io/controller-runtime" "sigs.k8s.io/controller-runtime/pkg/client" "sigs.k8s.io/controller-runtime/pkg/manager" @@ -89,6 +90,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{} @@ -100,6 +103,9 @@ func warmupRegistry(ctx context.Context, client client.Client, reader client.Rea extensionConfig := &extensionConfigList.Items[i] original := extensionConfig.DeepCopy() + log := log.WithValues("extensionConfig", klog.KObj(extensionConfig), "name", extensionConfig.Name, "namespace", extensionConfig.Namespace) + ctx := ctrl.LoggerInto(ctx, log) + // Inject CABundle from secret if annotation is set. Otherwise https calls may fail. if err := reconcileCABundle(ctx, client, extensionConfig); err != nil { errs = append(errs, err) @@ -128,5 +134,7 @@ func warmupRegistry(ctx context.Context, client client.Client, reader client.Rea return err } + log.Info("The extension registry is warmed up") + return nil } diff --git a/internal/controllers/topology/cluster/cluster_controller.go b/internal/controllers/topology/cluster/cluster_controller.go index f6746e2f5320..e9d59949a63b 100644 --- a/internal/controllers/topology/cluster/cluster_controller.go +++ b/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 %q 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. diff --git a/internal/controllers/topology/cluster/desired_state.go b/internal/controllers/topology/cluster/desired_state.go index 1c607d6263fa..113d6fe9836b 100644 --- a/internal/controllers/topology/cluster/desired_state.go +++ b/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 %q are blocked by %q 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 %q is blocked by %q hook", desiredVersion, runtimecatalog.HookName(runtimehooksv1.BeforeClusterUpgrade)) return *currentVersion, nil } diff --git a/internal/runtime/client/client.go b/internal/runtime/client/client.go index a3d755a15f1e..73b0e7b9534c 100644 --- a/internal/runtime/client/client.go +++ b/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("Performing discovery for ExtensionConfig") + 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,9 +192,12 @@ 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 { + hookName := runtimecatalog.HookName(hook) + log := ctrl.LoggerFrom(ctx).WithValues("hook", hookName) + ctx = ctrl.LoggerInto(ctx, log) 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)) + return errors.Wrapf(err, "failed to call extension handlers for hook %q: failed to compute GroupVersionHook", hookName) } // Make sure the request is compatible with the hook. if err := c.catalog.ValidateRequest(gvh, request); err != nil { @@ -205,6 +213,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 %q", hookName)) responses := []runtimehooksv1.ResponseObject{} for _, registration := range registrations { // Creates a new instance of the response parameter. @@ -221,12 +230,14 @@ 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 extension handler %q as object '%s/%s' does not match selector %q of ExtensionConfig", registration.Name, forObject.GetNamespace(), forObject.GetName(), registration.NamespaceSelector)) continue } 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) @@ -289,6 +300,8 @@ 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).WithValues("extensionHandler", name, "hook", runtimecatalog.HookName(hook)) + ctx = ctrl.LoggerInto(ctx, log) 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 +333,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 handler %q", name)) var timeoutDuration time.Duration if registration.TimeoutSeconds != nil { timeoutDuration = time.Duration(*registration.TimeoutSeconds) * time.Second @@ -339,18 +353,27 @@ 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.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 handler returned blocking response with retryAfterSeconds of %q", retryResponse.GetRetryAfterSeconds())) + } else { + log.Info("extension handler returned success response") + } + // Received a successful response from the extension handler. The `response` object // has been populated with the result. Return no error. return nil @@ -366,6 +389,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 +413,7 @@ func httpCall(ctx context.Context, request, response runtime.Object, opts *httpC responseLocal := response if requireConversion { + log.V(5).Info(fmt.Sprintf("Hook version of supported request is %s. Converting request from %s", opts.registrationGVH, opts.hookGVH)) // The request and response objects need to be converted to match the version supported by // the ExtensionHandler. var err error @@ -485,6 +510,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 %s. Converting response to %s", opts.registrationGVH, 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)