From 09db9917242713b48075caa27e5e924dd44d4e06 Mon Sep 17 00:00:00 2001 From: RalfHammer <119853077+RalfHammer@users.noreply.github.com> Date: Thu, 18 Jul 2024 18:44:38 +0200 Subject: [PATCH] Improve log message (#56) * improve logging * cleanup makefile --- api/v1alpha1/clusterspace_webhook.go | 8 ++++---- api/v1alpha1/servicebinding_webhook.go | 8 ++++---- api/v1alpha1/serviceinstance_webhook.go | 8 ++++---- api/v1alpha1/space_webhook.go | 8 ++++---- .../controllers/servicebinding_controller.go | 18 +++++++++-------- .../controllers/serviceinstance_controller.go | 20 +++++++++++-------- internal/controllers/space_controller.go | 16 +++++++++------ main.go | 4 ++-- 8 files changed, 50 insertions(+), 40 deletions(-) diff --git a/api/v1alpha1/clusterspace_webhook.go b/api/v1alpha1/clusterspace_webhook.go index 1c53e7d..f3d4435 100644 --- a/api/v1alpha1/clusterspace_webhook.go +++ b/api/v1alpha1/clusterspace_webhook.go @@ -30,7 +30,7 @@ var _ webhook.Defaulter = &ClusterSpace{} // Default implements webhook.Defaulter so a webhook will be registered for the type func (r *ClusterSpace) Default() { - clusterspacelog.Info("default", "name", r.Name) + clusterspacelog.V(2).Info("Default", "name", r.Name) if r.Spec.Guid == "" && r.Spec.Name == "" { r.Spec.Name = r.Name @@ -43,7 +43,7 @@ var _ webhook.Validator = &ClusterSpace{} // ValidateCreate implements webhook.Validator so a webhook will be registered for the type func (r *ClusterSpace) ValidateCreate() (admission.Warnings, error) { - clusterspacelog.Info("validate create", "name", r.Name) + clusterspacelog.V(2).Info("Validate create", "name", r.Name) // Call the defaulting logic again (because defaulting might be incomplete in case of generateName usage) if r.Name == "" && r.GenerateName != "" { r.Name = r.GenerateName + "xxxxx" @@ -60,7 +60,7 @@ func (r *ClusterSpace) ValidateCreate() (admission.Warnings, error) { // ValidateUpdate implements webhook.Validator so a webhook will be registered for the type func (r *ClusterSpace) ValidateUpdate(old runtime.Object) (admission.Warnings, error) { - clusterspacelog.Info("validate update", "name", r.Name) + clusterspacelog.V(2).Info("Validate update", "name", r.Name) s := old.(*ClusterSpace) // Call the defaulting webhook logic for the old object (because defaulting through the webhook might be incomplete in case of generateName usage) s.Name = r.Name @@ -84,7 +84,7 @@ func (r *ClusterSpace) ValidateUpdate(old runtime.Object) (admission.Warnings, e // ValidateDelete implements webhook.Validator so a webhook will be registered for the type func (r *ClusterSpace) ValidateDelete() (admission.Warnings, error) { - clusterspacelog.Info("validate delete", "name", r.Name) + clusterspacelog.V(2).Info("Validate delete", "name", r.Name) return nil, nil } diff --git a/api/v1alpha1/servicebinding_webhook.go b/api/v1alpha1/servicebinding_webhook.go index 1a62988..cc0097e 100644 --- a/api/v1alpha1/servicebinding_webhook.go +++ b/api/v1alpha1/servicebinding_webhook.go @@ -30,7 +30,7 @@ var _ webhook.Defaulter = &ServiceBinding{} // Default implements webhook.Defaulter so a webhook will be registered for the type func (r *ServiceBinding) Default() { - servicebindinglog.Info("default", "name", r.Name) + servicebindinglog.V(2).Info("Default", "name", r.Name) if r.Labels == nil { r.Labels = make(map[string]string) @@ -51,14 +51,14 @@ var _ webhook.Validator = &ServiceBinding{} // ValidateCreate implements webhook.Validator so a webhook will be registered for the type func (r *ServiceBinding) ValidateCreate() (admission.Warnings, error) { - servicebindinglog.Info("validate create", "name", r.Name) + servicebindinglog.V(2).Info("Validate create", "name", r.Name) return nil, nil } // ValidateUpdate implements webhook.Validator so a webhook will be registered for the type func (r *ServiceBinding) ValidateUpdate(old runtime.Object) (admission.Warnings, error) { - servicebindinglog.Info("validate update", "name", r.Name) + servicebindinglog.V(2).Info("Validate update", "name", r.Name) s := old.(*ServiceBinding) // Call the defaulting webhook logic for the old object (because defaulting through the webhook might be incomplete in case of generateName usage) s.Name = r.Name @@ -78,7 +78,7 @@ func (r *ServiceBinding) ValidateUpdate(old runtime.Object) (admission.Warnings, // ValidateDelete implements webhook.Validator so a webhook will be registered for the type func (r *ServiceBinding) ValidateDelete() (admission.Warnings, error) { - servicebindinglog.Info("validate delete", "name", r.Name) + servicebindinglog.V(2).Info("Validate delete", "name", r.Name) return nil, nil } diff --git a/api/v1alpha1/serviceinstance_webhook.go b/api/v1alpha1/serviceinstance_webhook.go index 7669f76..37151df 100644 --- a/api/v1alpha1/serviceinstance_webhook.go +++ b/api/v1alpha1/serviceinstance_webhook.go @@ -30,7 +30,7 @@ var _ webhook.Defaulter = &ServiceInstance{} // Default implements webhook.Defaulter so a webhook will be registered for the type func (r *ServiceInstance) Default() { - serviceinstancelog.Info("default", "name", r.Name) + serviceinstancelog.V(2).Info("Default", "name", r.Name) if r.Labels == nil { r.Labels = make(map[string]string) @@ -53,7 +53,7 @@ var _ webhook.Validator = &ServiceInstance{} // ValidateCreate implements webhook.Validator so a webhook will be registered for the type func (r *ServiceInstance) ValidateCreate() (admission.Warnings, error) { - serviceinstancelog.Info("validate create", "name", r.Name) + serviceinstancelog.V(2).Info("Validate create", "name", r.Name) if !(r.Spec.SpaceName != "" && r.Spec.ClusterSpaceName == "" || r.Spec.SpaceName == "" && r.Spec.ClusterSpaceName != "") { @@ -70,7 +70,7 @@ func (r *ServiceInstance) ValidateCreate() (admission.Warnings, error) { // ValidateUpdate implements webhook.Validator so a webhook will be registered for the type func (r *ServiceInstance) ValidateUpdate(old runtime.Object) (admission.Warnings, error) { - serviceinstancelog.Info("validate update", "name", r.Name) + serviceinstancelog.V(2).Info("Validate update", "name", r.Name) s := old.(*ServiceInstance) // Call the defaulting webhook logic for the old object (because defaulting through the webhook might be incomplete in case of generateName usage) s.Name = r.Name @@ -106,7 +106,7 @@ func (r *ServiceInstance) ValidateUpdate(old runtime.Object) (admission.Warnings // ValidateDelete implements webhook.Validator so a webhook will be registered for the type func (r *ServiceInstance) ValidateDelete() (admission.Warnings, error) { - serviceinstancelog.Info("validate delete", "name", r.Name) + serviceinstancelog.V(2).Info("Validate delete", "name", r.Name) return nil, nil } diff --git a/api/v1alpha1/space_webhook.go b/api/v1alpha1/space_webhook.go index 40c4924..3e82cec 100644 --- a/api/v1alpha1/space_webhook.go +++ b/api/v1alpha1/space_webhook.go @@ -30,7 +30,7 @@ var _ webhook.Defaulter = &Space{} // Default implements webhook.Defaulter so a webhook will be registered for the type func (r *Space) Default() { - spacelog.Info("default", "name", r.Name) + spacelog.V(2).Info("Default", "name", r.Name) if r.Spec.Guid == "" && r.Spec.Name == "" { r.Spec.Name = r.Name @@ -43,7 +43,7 @@ var _ webhook.Validator = &Space{} // ValidateCreate implements webhook.Validator so a webhook will be registered for the type func (r *Space) ValidateCreate() (admission.Warnings, error) { - spacelog.Info("validate create", "name", r.Name) + spacelog.V(2).Info("Validate create", "name", r.Name) // Call the defaulting logic again (because defaulting might be incomplete in case of generateName usage) if r.Name == "" && r.GenerateName != "" { r.Name = r.GenerateName + "xxxxx" @@ -60,7 +60,7 @@ func (r *Space) ValidateCreate() (admission.Warnings, error) { // ValidateUpdate implements webhook.Validator so a webhook will be registered for the type func (r *Space) ValidateUpdate(old runtime.Object) (admission.Warnings, error) { - spacelog.Info("validate update", "name", r.Name) + spacelog.V(2).Info("Validate update", "name", r.Name) s := old.(*Space) // Call the defaulting webhook logic for the old object (because defaulting through the webhook might be incomplete in case of generateName usage) s.Name = r.Name @@ -84,7 +84,7 @@ func (r *Space) ValidateUpdate(old runtime.Object) (admission.Warnings, error) { // ValidateDelete implements webhook.Validator so a webhook will be registered for the type func (r *Space) ValidateDelete() (admission.Warnings, error) { - spacelog.Info("validate delete", "name", r.Name) + spacelog.V(2).Info("Validate delete", "name", r.Name) return nil, nil } diff --git a/internal/controllers/servicebinding_controller.go b/internal/controllers/servicebinding_controller.go index 170580c..12ff006 100644 --- a/internal/controllers/servicebinding_controller.go +++ b/internal/controllers/servicebinding_controller.go @@ -59,7 +59,7 @@ type ServiceBindingReconciler struct { func (r *ServiceBindingReconciler) Reconcile(ctx context.Context, req ctrl.Request) (result ctrl.Result, err error) { log := ctrl.LoggerFrom(ctx) - log.V(1).Info("running reconcile") + log.V(2).Info("Running reconcile") // Retrieve target service binding serviceBinding := &cfv1alpha1.ServiceBinding{} @@ -67,7 +67,7 @@ func (r *ServiceBindingReconciler) Reconcile(ctx context.Context, req ctrl.Reque if err := client.IgnoreNotFound(err); err != nil { return ctrl.Result{}, errors.Wrap(err, "unexpected get error") } - log.Info("not found; ignoring") + log.V(1).Info("Not found; ignoring") return ctrl.Result{}, nil } // Call the defaulting webhook logic also here (because defaulting through the webhook might be incomplete in case of generateName usage) @@ -178,6 +178,7 @@ func (r *ServiceBindingReconciler) Reconcile(ctx context.Context, req ctrl.Reque var cfbinding *facade.Binding bindingOpts := map[string]string{"name": "", "owner": string(serviceBinding.UID)} if client != nil { + log.V(1).Info("Retrieving binding by owner") cfbinding, err = client.GetBinding(ctx, bindingOpts) if err != nil { return ctrl.Result{}, err @@ -186,6 +187,7 @@ func (r *ServiceBindingReconciler) Reconcile(ctx context.Context, req ctrl.Reque if exists && cfbinding == nil && orphan == "adopt" { // find orphaned binding by name bindingOpts["name"] = serviceBinding.Name + log.V(1).Info("Retrieving binding by name") cfbinding, err = client.GetBinding(ctx, bindingOpts) if err != nil { return ctrl.Result{}, err @@ -202,7 +204,7 @@ func (r *ServiceBindingReconciler) Reconcile(ctx context.Context, req ctrl.Reque return ctrl.Result{}, errors.Wrap(err, "failed to unmarshal/merge parameters") } // update the orphaned cloud foundry service binding - log.V(1).Info("triggering update") + log.V(1).Info("Updating binding") if err := client.UpdateBinding( ctx, cfbinding.Guid, @@ -274,7 +276,7 @@ func (r *ServiceBindingReconciler) Reconcile(ctx context.Context, req ctrl.Reque inRecreation := false if cfbinding == nil { - log.V(1).Info("triggering creation") + log.V(1).Info("Creating binding") if err := client.CreateBinding( ctx, spec.Name, @@ -293,7 +295,7 @@ func (r *ServiceBindingReconciler) Reconcile(ctx context.Context, req ctrl.Reque (recreateOnInstanceChange && status.ServiceInstanceDigest != serviceInstance.Status.ServiceInstanceDigest) || cfbinding.State == facade.BindingStateCreatedFailed || cfbinding.State == facade.BindingStateDeleteFailed { // Re-create binding (unfortunately, cloud foundry does not support binding updates, other than metadata) - log.V(1).Info("triggering re-creation") + log.V(1).Info("Deleting binding for later re-creation") if err := client.DeleteBinding(ctx, cfbinding.Guid); err != nil { return ctrl.Result{}, err } @@ -303,8 +305,7 @@ func (r *ServiceBindingReconciler) Reconcile(ctx context.Context, req ctrl.Reque cfbinding = nil } else if cfbinding.Generation < serviceBinding.Generation { // metadata updates (such as updating the generation here) are possible with service bindings - log.V(1).Info("triggering update") - + log.V(1).Info("Updating binding") if err := client.UpdateBinding( ctx, cfbinding.Guid, @@ -323,6 +324,7 @@ func (r *ServiceBindingReconciler) Reconcile(ctx context.Context, req ctrl.Reque if cfbinding == nil { // Re-retrieve cloud foundry binding by UID; this happens exactly if the binding was created or updated above + log.V(1).Info("Retrieving binding") cfbinding, err = client.GetBinding(ctx, bindingOpts) if err != nil { return ctrl.Result{}, err @@ -399,7 +401,7 @@ func (r *ServiceBindingReconciler) Reconcile(ctx context.Context, req ctrl.Reque return ctrl.Result{}, nil } else { if cfbinding.State != facade.BindingStateDeleting { - log.V(1).Info("triggering deletion") + log.V(1).Info("Deleting binding") if err := client.DeleteBinding(ctx, cfbinding.Guid); err != nil { return ctrl.Result{}, err } diff --git a/internal/controllers/serviceinstance_controller.go b/internal/controllers/serviceinstance_controller.go index 23e6186..a4e51d2 100644 --- a/internal/controllers/serviceinstance_controller.go +++ b/internal/controllers/serviceinstance_controller.go @@ -69,7 +69,7 @@ var RetryError = errors.New("retry") func (r *ServiceInstanceReconciler) Reconcile(ctx context.Context, req ctrl.Request) (result ctrl.Result, err error) { log := ctrl.LoggerFrom(ctx) - log.V(1).Info("running reconcile") + log.V(2).Info("Running reconcile") // Retrieve target service instance serviceInstance := &cfv1alpha1.ServiceInstance{} @@ -77,7 +77,7 @@ func (r *ServiceInstanceReconciler) Reconcile(ctx context.Context, req ctrl.Requ if err := client.IgnoreNotFound(err); err != nil { return ctrl.Result{}, errors.Wrap(err, "unexpected get error") } - log.Info("not found; ignoring") + log.V(1).Info("Not found; ignoring") return ctrl.Result{}, nil } // Call the defaulting webhook logic also here (because defaulting through the webhook might be incomplete in case of generateName usage) @@ -192,6 +192,7 @@ func (r *ServiceInstanceReconciler) Reconcile(ctx context.Context, req ctrl.Requ var cfinstance *facade.Instance instanceOpts := map[string]string{"name": "", "owner": string(serviceInstance.UID)} if client != nil { + log.V(1).Info("Retrieving instance by owner") cfinstance, err = client.GetInstance(ctx, instanceOpts) if err != nil { return ctrl.Result{}, err @@ -200,6 +201,7 @@ func (r *ServiceInstanceReconciler) Reconcile(ctx context.Context, req ctrl.Requ if exists && cfinstance == nil && orphan == "adopt" { // find orphaned instance by name instanceOpts["name"] = serviceInstance.Name + log.V(1).Info("Retrieving instance by name") cfinstance, err = client.GetInstance(ctx, instanceOpts) if err != nil { return ctrl.Result{}, err @@ -216,7 +218,7 @@ func (r *ServiceInstanceReconciler) Reconcile(ctx context.Context, req ctrl.Requ return ctrl.Result{}, errors.Wrap(err, "failed to unmarshal/merge parameters") } // update the orphaned cloud foundry instance - log.V(1).Info("triggering update") + log.V(1).Info("Updating instance") if err := client.UpdateInstance( ctx, cfinstance.Guid, @@ -246,6 +248,7 @@ func (r *ServiceInstanceReconciler) Reconcile(ctx context.Context, req ctrl.Requ servicePlanGuid := spec.ServicePlanGuid if servicePlanGuid == "" { + log.V(1).Info("Searching service plan") servicePlanGuid, err = client.FindServicePlan(ctx, spec.ServiceOfferingName, spec.ServicePlanName, spaceGuid) if err != nil { return ctrl.Result{}, err @@ -291,7 +294,7 @@ func (r *ServiceInstanceReconciler) Reconcile(ctx context.Context, req ctrl.Requ inRecreation := false if cfinstance == nil { - log.V(1).Info("triggering creation") + log.V(1).Info("Creating instance") if err := client.CreateInstance( ctx, spec.Name, @@ -309,7 +312,7 @@ func (r *ServiceInstanceReconciler) Reconcile(ctx context.Context, req ctrl.Requ // This is the re-creation case; nothing to, we just wait until it is gone } else if recreateOnCreationFailure && (cfinstance.State == facade.InstanceStateCreatedFailed || cfinstance.State == facade.InstanceStateDeleteFailed) { // Re-create instance - log.V(1).Info("triggering re-creation") + log.V(1).Info("Deleting instance for later re-creation") if err := client.DeleteInstance(ctx, cfinstance.Guid); err != nil { return ctrl.Result{}, RetryError } @@ -319,7 +322,7 @@ func (r *ServiceInstanceReconciler) Reconcile(ctx context.Context, req ctrl.Requ cfinstance = nil } else if cfinstance.Generation < serviceInstance.Generation || cfinstance.ParameterHash != facade.ObjectHash(parameters) || cfinstance.State == facade.InstanceStateCreatedFailed || cfinstance.State == facade.InstanceStateUpdateFailed { - log.V(1).Info("triggering update") + log.V(1).Info("Updating instance") updateName := spec.Name if updateName == cfinstance.Name { updateName = "" @@ -362,6 +365,7 @@ func (r *ServiceInstanceReconciler) Reconcile(ctx context.Context, req ctrl.Requ if cfinstance == nil { // Re-retrieve cloud foundry instance by UID; this happens exactly if the instance was created or updated above + log.V(1).Info("Retrieving instance") cfinstance, err = client.GetInstance(ctx, instanceOpts) if err != nil { return ctrl.Result{}, err @@ -418,7 +422,7 @@ func (r *ServiceInstanceReconciler) Reconcile(ctx context.Context, req ctrl.Requ return ctrl.Result{}, nil } else { if cfinstance.State != facade.InstanceStateDeleting { - log.V(1).Info("triggering deletion") + log.V(1).Info("Deleting instance") if err := client.DeleteInstance(ctx, cfinstance.Guid); err != nil { return ctrl.Result{}, err } @@ -476,7 +480,7 @@ func (r *ServiceInstanceReconciler) HandleError(ctx context.Context, serviceInst requeueAfter = serviceInstanceDefaultMaxRetryInterval } - log.V(1).Info("***Retry after interval", "RequeueAfter", requeueAfter.String()) + log.V(1).Info("Scheduling next reconcile", "RequeueAfter", requeueAfter.String()) serviceInstance.SetReadyCondition(cfv1alpha1.ConditionUnknown, serviceInstanceReadyConditionReasonError, issue.Error()) return ctrl.Result{RequeueAfter: requeueAfter}, nil diff --git a/internal/controllers/space_controller.go b/internal/controllers/space_controller.go index a8e1c6f..161036b 100644 --- a/internal/controllers/space_controller.go +++ b/internal/controllers/space_controller.go @@ -59,7 +59,7 @@ type SpaceReconciler struct { func (r *SpaceReconciler) Reconcile(ctx context.Context, req ctrl.Request) (result ctrl.Result, err error) { log := ctrl.LoggerFrom(ctx) - log.V(1).Info("running reconcile") + log.V(2).Info("Running reconcile") // Retrieve target (cluster) space space, err := r.newSpace() @@ -71,7 +71,7 @@ func (r *SpaceReconciler) Reconcile(ctx context.Context, req ctrl.Request) (resu if err := client.IgnoreNotFound(err); err != nil { return ctrl.Result{}, errors.Wrap(err, "unexpected get error") } - log.Info("not found; ignoring") + log.V(1).Info("Not found; ignoring") return ctrl.Result{}, nil } // Call the defaulting webhook logic also here (because defaulting through the webhook might be incomplete in case of generateName usage) @@ -153,6 +153,7 @@ func (r *SpaceReconciler) Reconcile(ctx context.Context, req ctrl.Request) (resu } // Retrieve cloud foundry space + log.V(1).Info("Retrieving space") cfspace, err = client.GetSpace(ctx, string(space.GetUID())) if err != nil { return ctrl.Result{}, err @@ -175,7 +176,7 @@ func (r *SpaceReconciler) Reconcile(ctx context.Context, req ctrl.Request) (resu if spec.Guid == "" { if cfspace == nil { - log.V(1).Info("triggering creation") + log.V(1).Info("Creating space") if err := client.CreateSpace( ctx, spec.Name, @@ -187,7 +188,7 @@ func (r *SpaceReconciler) Reconcile(ctx context.Context, req ctrl.Request) (resu status.LastModifiedAt = &[]metav1.Time{metav1.Now()}[0] } else { if cfspace.Generation < space.GetGeneration() { - log.V(1).Info("triggering update") + log.V(1).Info("Updating space") updateName := spec.Name if updateName == cfspace.Name { updateName = "" @@ -207,6 +208,7 @@ func (r *SpaceReconciler) Reconcile(ctx context.Context, req ctrl.Request) (resu } if cfspace == nil { // Re-retrieve cloud foundry space; this happens exactly if the space was created or updated above + log.V(1).Info("Retrieving space") cfspace, err = client.GetSpace(ctx, string(space.GetUID())) if err != nil { return ctrl.Result{}, err @@ -217,6 +219,7 @@ func (r *SpaceReconciler) Reconcile(ctx context.Context, req ctrl.Request) (resu } // TODO: the following is not very clean; if the user referenced by the secret changes, we leave the previous one orphaned; // maybe we should clean it up somehow (but how ... what if that previous user has already been taken over by another manager, such as CAM?) + log.V(1).Info("Adding developer") if err := client.AddDeveloper(ctx, cfspace.Guid, string(secret.Data["username"])); err != nil { return ctrl.Result{}, err } @@ -234,11 +237,12 @@ func (r *SpaceReconciler) Reconcile(ctx context.Context, req ctrl.Request) (resu return ctrl.Result{}, errors.Wrapf(err, "failed to build the healthchecker from secret %s", secretName) } + log.V(1).Info("Checking space") if err := checker.Check(ctx); err != nil { return ctrl.Result{}, errors.Wrap(err, "healthcheck failed") } - log.V(1).Info("healthcheck successful") + log.V(1).Info("Healthcheck successful") space.SetReadyCondition(cfv1alpha1.ConditionTrue, spaceReadyConditionReasonSuccess, "Success") return getPollingInterval(space.GetAnnotations(), "60s", cfv1alpha1.AnnotationPollingIntervalReady), nil } else if len(serviceInstanceList.Items) > 0 { @@ -269,7 +273,7 @@ func (r *SpaceReconciler) Reconcile(ctx context.Context, req ctrl.Request) (resu skipStatusUpdate = true return ctrl.Result{}, nil } else { - log.V(1).Info("triggering deletion") + log.V(1).Info("Deleting space") if err := client.DeleteSpace(ctx, cfspace.Guid); err != nil { return ctrl.Result{}, err } diff --git a/main.go b/main.go index 88b542f..825f142 100644 --- a/main.go +++ b/main.go @@ -87,7 +87,7 @@ func main() { } setupLog.Info( - "starting", + "Starting", "enable-leader-election", enableLeaderElection, "metrics-addr", metricsAddr, "cluster-resource-namespace", clusterResourceNamespace, @@ -203,7 +203,7 @@ func main() { os.Exit(1) } - setupLog.Info("starting manager") + setupLog.Info("Starting manager") if err := mgr.Start(ctrl.SetupSignalHandler()); err != nil { setupLog.Error(err, "problem running manager") os.Exit(1)