Add new logs and improve structure

Signed-off-by: alexander-demicev <alexandr.demicev@suse.com>

Author: alexander-demicev

cmd/plugin/cmd/delete.go

@@ -299,16 +299,16 @@ func deleteProviders(ctx context.Context, client ctrlclient.Client, providerList
 	if err := client.List(ctx, providerList, selector); meta.IsNoMatchError(err) || apierrors.IsNotFound(err) {
 		return true, nil
 	} else if err != nil {
-		log.Error(err, fmt.Sprintf("Unable to list providers to delete, %#v", err))
+		log.Error(err, "Unable to list providers to delete")
 		return false, err
 	}
 
 	for _, provider := range providerList.GetItems() {
-		log.Info(fmt.Sprintf("Deleting %s %s/%s", provider.GetType(), provider.GetName(), provider.GetNamespace()))
+		log.Info("Deleting provider", "type", provider.GetType(), "name", provider.GetName(), "namespace", provider.GetNamespace())
 
 		provider, ok := provider.(genericProvider)
 		if !ok {
-			log.Info(fmt.Sprintf("Expected to get GenericProvider for %s", gvk))
+			log.Info("Expected to get GenericProvider", "gvk", gvk)
 			continue
 		}
 
@@ -318,7 +318,7 @@ func deleteProviders(ctx context.Context, client ctrlclient.Client, providerList
 
 		if deleteOpts.includeNamespace {
 			if strings.HasPrefix(provider.GetNamespace(), "kube-") || provider.GetNamespace() == "default" {
-				log.Info(fmt.Sprintf("Skipping system namespace %s", provider.GetNamespace()))
+				log.Info("Skipping system namespace", "namespace", provider.GetNamespace())
 				continue
 			}
 
@@ -330,7 +330,7 @@ func deleteProviders(ctx context.Context, client ctrlclient.Client, providerList
 	}
 
 	if len(providerList.GetItems()) > 0 {
-		log.Info(fmt.Sprintf("%d items remaning...", len(providerList.GetItems())))
+		log.Info("Items remaining", "count", len(providerList.GetItems()))
 		return false, nil
 	}
 

internal/controller/client_proxy.go

@@ -27,11 +27,11 @@ import (
 
 	"k8s.io/apimachinery/pkg/apis/meta/v1/unstructured"
 	"k8s.io/client-go/rest"
-	"k8s.io/klog/v2"
 
 	clusterctlv1 "sigs.k8s.io/cluster-api/cmd/clusterctl/api/v1alpha3"
 	"sigs.k8s.io/cluster-api/cmd/clusterctl/client/cluster"
 	"sigs.k8s.io/cluster-api/cmd/clusterctl/client/repository"
+	ctrl "sigs.k8s.io/controller-runtime"
 	"sigs.k8s.io/controller-runtime/pkg/client"
 )
 
@@ -107,6 +107,7 @@ func (k *controllerProxy) GetResourceNames(ctx context.Context, groupVersion, ki
 
 // ListResources lists namespaced and cluster-wide resources for a component matching the labels.
 func (k *controllerProxy) ListResources(ctx context.Context, labels map[string]string, namespaces ...string) ([]unstructured.Unstructured, error) {
+	log := ctrl.LoggerFrom(ctx)
 	resourceList := []*metav1.APIResourceList{
 		{
 			GroupVersion: "v1",
@@ -160,7 +161,7 @@ func (k *controllerProxy) ListResources(ctx context.Context, labels map[string]s
 						return nil, err
 					}
 
-					klog.V(3).InfoS("listed", "kind", resourceKind.Kind, "count", len(objList.Items))
+					log.V(2).Info("Listed resources", "kind", resourceKind.Kind, "count", len(objList.Items))
 
 					ret = append(ret, objList.Items...)
 				}
@@ -170,7 +171,7 @@ func (k *controllerProxy) ListResources(ctx context.Context, labels map[string]s
 					return nil, err
 				}
 
-				klog.V(3).InfoS("listed", "kind", resourceKind.Kind, "count", len(objList.Items))
+				log.V(2).Info("Listed resources", "kind", resourceKind.Kind, "count", len(objList.Items))
 
 				ret = append(ret, objList.Items...)
 			}

internal/controller/configmaps_to_providers.go

@@ -64,7 +64,7 @@ func newConfigMapToProviderFuncMapForProviderList(k8sClient client.Client, provi
 			}
 
 			if selector.Matches(configMapLabels) {
-				log.V(1).Info("ConfigMap matches provider selector, enqueueing reconcile request")
+				log.Info("ConfigMap matches provider selector, enqueueing reconcile request")
 
 				requests = append(requests, reconcile.Request{NamespacedName: client.ObjectKeyFromObject(provider)})
 			}

internal/controller/genericprovider_controller.go

@@ -140,6 +140,8 @@ func (r *GenericProviderReconciler) Reconcile(ctx context.Context, req reconcile
 		if apierrors.IsNotFound(err) {
 			// Object not found, return. Created objects are automatically garbage collected.
 			// For additional cleanup logic use finalizers.
+			log.Info("Provider not found, skipping reconciliation")
+
 			return ctrl.Result{}, nil
 		}
 		// Error reading the object - requeue the request.
@@ -167,12 +169,16 @@ func (r *GenericProviderReconciler) Reconcile(ctx context.Context, req reconcile
 
 	// Add finalizer first if not exist to avoid the race condition between init and delete
 	if !controllerutil.ContainsFinalizer(r.Provider, operatorv1.ProviderFinalizer) {
+		log.Info("Adding finalizer, requeueing")
 		controllerutil.AddFinalizer(r.Provider, operatorv1.ProviderFinalizer)
+
 		return ctrl.Result{}, nil
 	}
 
 	// Handle deletion reconciliation loop.
 	if !r.Provider.GetDeletionTimestamp().IsZero() {
+		log.Info("Provider marked for deletion, entering delete reconciliation")
+
 		res, err := r.reconcileDelete(ctx, r.Provider)
 		if err != nil {
 			return reconcile.Result{}, err
@@ -381,25 +387,17 @@ func addObjectToHash(hash hash.Hash, object interface{}) error {
 
 // providerHash calculates hash for provider and referenced objects.
 func providerHash(ctx context.Context, client client.Client, hash hash.Hash, provider genericprovider.GenericProvider) error {
-	log := log.FromContext(ctx)
-
 	err := addObjectToHash(hash, provider.GetSpec())
 	if err != nil {
-		log.Error(err, "failed to calculate provider hash")
-
-		return err
+		return fmt.Errorf("failed to calculate provider hash: %w", err)
 	}
 
 	if err := addConfigSecretToHash(ctx, client, hash, provider); err != nil {
-		log.Error(err, "failed to calculate secret hash")
-
-		return err
+		return fmt.Errorf("failed to calculate secret hash: %w", err)
 	}
 
 	if err := addConfigMapToHash(ctx, client, hash, provider); err != nil {
-		log.Error(err, "failed to calculate configmap hash")
-
-		return err
+		return fmt.Errorf("failed to calculate configmap hash: %w", err)
 	}
 
 	return nil
@@ -444,23 +442,17 @@ func (p *PhaseReconciler) ApplyFromCache(ctx context.Context) (*Result, error) {
 		// secret does not exist, nothing to apply
 		return &Result{}, nil
 	} else if err != nil {
-		log.Error(err, "failed to get provider cache")
-
 		return &Result{}, fmt.Errorf("failed to get provider cache: %w", err)
 	}
 
 	// calculate combined hash for provider and config map cache
 	hash := sha256.New()
 	if err := providerHash(ctx, p.ctrlClient, hash, p.provider); err != nil {
-		log.Error(err, "failed to calculate provider hash")
-
 		return &Result{}, err
 	}
 
 	if err := addObjectToHash(hash, secret.Data); err != nil {
-		log.Error(err, "failed to calculate config map hash")
-
-		return &Result{}, err
+		return &Result{}, fmt.Errorf("failed to calculate config map hash: %w", err)
 	}
 
 	data, err := os.ReadFile(configPath)
@@ -471,9 +463,7 @@ func (p *PhaseReconciler) ApplyFromCache(ctx context.Context) (*Result, error) {
 	}
 
 	if err := addObjectToHash(hash, data); err != nil {
-		log.Error(err, "failed to calculate clusterctl.yaml file hash")
-
-		return &Result{}, nil
+		return &Result{}, err
 	}
 
 	cacheHash := fmt.Sprintf("%x", hash.Sum(nil))
@@ -499,8 +489,6 @@ func (p *PhaseReconciler) ApplyFromCache(ctx context.Context) (*Result, error) {
 	compressed := secret.GetAnnotations()[operatorv1.CompressedAnnotation] == operatorv1.TrueValue
 
 	if err := p.applyManifestsFromData(ctx, secret.Data, compressed); err != nil {
-		log.Error(err, "failed to apply objects from cache")
-
 		return &Result{}, err
 	}
 
@@ -514,6 +502,8 @@ func (p *PhaseReconciler) ApplyFromCache(ctx context.Context) (*Result, error) {
 func (p *PhaseReconciler) applyManifestsFromData(ctx context.Context, data map[string][]byte, compressed bool) error {
 	log := log.FromContext(ctx)
 
+	log.V(2).Info("Applying manifests from cache", "entries", len(data), "compressed", compressed)
+
 	var errs []error
 
 	for _, raw := range data {
@@ -524,18 +514,14 @@ func (p *PhaseReconciler) applyManifestsFromData(ctx context.Context, data map[s
 
 			manifest, err = decompressData(raw)
 			if err != nil {
-				log.Error(err, "failed to decompress yaml")
-
-				return err
+				return fmt.Errorf("failed to decompress yaml: %w", err)
 			}
 		}
 
 		var manifests []unstructured.Unstructured
 
 		if err := json.Unmarshal(manifest, &manifests); err != nil {
-			log.Error(err, "failed to convert yaml to unstructured")
-
-			return err
+			return fmt.Errorf("failed to convert yaml to unstructured: %w", err)
 		}
 
 		for i := range manifests {
@@ -550,6 +536,8 @@ func (p *PhaseReconciler) applyManifestsFromData(ctx context.Context, data map[s
 
 // setCacheHash calculates current provider and secret hash, and updates it on the secret.
 func setCacheHash(ctx context.Context, cl client.Client, provider genericprovider.GenericProvider) error {
+	log := log.FromContext(ctx)
+
 	secret := &corev1.Secret{}
 	if err := cl.Get(ctx, client.ObjectKey{Name: ProviderCacheName(provider), Namespace: provider.GetNamespace()}, secret); err != nil {
 		return fmt.Errorf("failed to get cache secret: %w", err)
@@ -583,6 +571,8 @@ func setCacheHash(ctx context.Context, cl client.Client, provider genericprovide
 
 	cacheHash := fmt.Sprintf("%x", hash.Sum(nil))
 
+	log.V(2).Info("Setting cache hash", "hash", cacheHash, "provider", provider.GetName())
+
 	annotations := secret.GetAnnotations()
 	if annotations == nil {
 		annotations = map[string]string{}

internal/controller/healthcheck/healthcheck_controller.go

@@ -148,12 +148,16 @@ func (r *GenericProviderHealthCheckReconciler) Reconcile(ctx context.Context, re
 
 	// Stop earlier if this provider is not fully installed yet.
 	if !conditions.IsTrue(typedProvider, operatorv1.ProviderInstalledCondition) {
+		log.V(2).Info("Provider not fully installed yet, requeueing")
+
 		return ctrl.Result{RequeueAfter: 5 * time.Second}, nil
 	}
 
 	// Compare provider's Ready condition with the deployment's Available condition and stop if they already match.
 	currentReadyCondition := conditions.Get(typedProvider, clusterv1.ReadyCondition)
 	if currentReadyCondition != nil && deploymentAvailableCondition != nil && currentReadyCondition.Status == metav1.ConditionStatus(deploymentAvailableCondition.Status) {
+		log.V(5).Info("Health check conditions already in sync, skipping")
+
 		return result, nil
 	}
 
@@ -169,6 +173,8 @@ func (r *GenericProviderHealthCheckReconciler) Reconcile(ctx context.Context, re
 			reason = operatorv1.DeploymentAvailableReason
 		}
 
+		log.Info("Updating provider health status", "available", deploymentAvailableCondition.Status)
+
 		conditions.Set(typedProvider, metav1.Condition{
 			Type:   clusterv1.ReadyCondition,
 			Status: metav1.ConditionStatus(deploymentAvailableCondition.Status),

internal/controller/manifests_downloader.go

@@ -73,7 +73,7 @@ func (p *PhaseReconciler) DownloadManifests(ctx context.Context) (*Result, error
 		return &Result{}, nil
 	}
 
-	log.Info("Downloading provider manifests")
+	log.Info("Downloading provider manifests", "version", p.provider.GetSpec().Version)
 
 	if p.providerConfig.URL() != fakeURL {
 		p.repo, err = util.RepositoryFactory(ctx, p.providerConfig, p.configClient.Variables())
@@ -90,6 +90,8 @@ func (p *PhaseReconciler) DownloadManifests(ctx context.Context) (*Result, error
 		// User didn't set the version, try to get repository default.
 		spec.Version = p.repo.DefaultVersion()
 
+		log.Info("Using repository default version", "version", spec.Version)
+
 		// Add version to the provider spec.
 		p.provider.SetSpec(spec)
 	}
@@ -98,11 +100,15 @@ func (p *PhaseReconciler) DownloadManifests(ctx context.Context) (*Result, error
 
 	// Fetch the provider metadata and components yaml files from the provided repository GitHub/GitLab or OCI source
 	if p.provider.GetSpec().FetchConfig != nil && p.provider.GetSpec().FetchConfig.OCI != "" {
+		log.Info("Downloading manifests from OCI source", "oci", p.provider.GetSpec().FetchConfig.OCI)
+
 		configMap, err = OCIConfigMap(ctx, p.provider, OCIAuthentication(p.configClient.Variables()))
 		if err != nil {
 			return &Result{}, wrapPhaseError(err, operatorv1.ComponentsFetchErrorReason, operatorv1.ProviderInstalledCondition)
 		}
 	} else {
+		log.Info("Downloading manifests from repository", "url", p.providerConfig.URL())
+
 		configMap, err = RepositoryConfigMap(ctx, p.provider, p.repo)
 		if err != nil {
 			err = fmt.Errorf("failed to create config map for provider %q: %w", p.provider.GetName(), err)
@@ -141,9 +147,13 @@ func (p *PhaseReconciler) checkConfigMapExists(ctx context.Context, labelSelecto
 
 // Finalize applies combined hash to a configMap, in order to mark provider provisioning completed.
 func (p *PhaseReconciler) Finalize(ctx context.Context) (*Result, error) {
+	log := ctrl.LoggerFrom(ctx)
+
 	err := setCacheHash(ctx, p.ctrlClient, p.provider)
 	if err != nil {
-		ctrl.LoggerFrom(ctx).V(5).Error(err, "Failed to update providers hash")
+		log.V(5).Error(err, "Failed to update providers hash")
+	} else {
+		log.Info("Provider reconciliation finalized successfully")
 	}
 
 	return &Result{}, wrapPhaseError(err, "FailedToUpdateProvidersHash", operatorv1.ProviderInstalledCondition)

internal/controller/oci_source.go

@@ -215,15 +215,11 @@ func parseOCISource(url string, version string) (string, string, bool) {
 
 // CopyOCIStore collects artifacts from the provider OCI url and creates a map of file contents.
 func CopyOCIStore(ctx context.Context, url string, version string, store *mapStore, credential *auth.Credential) error {
-	log := log.FromContext(ctx)
-
 	url, version, plainHTTP := parseOCISource(url, version)
 
 	repo, err := remote.NewRepository(url)
 	if err != nil {
-		log.Error(err, "Invalid registry URL specified")
-
-		return err
+		return fmt.Errorf("invalid registry URL specified: %w", err)
 	}
 
 	if credential != nil {
@@ -245,9 +241,7 @@ func CopyOCIStore(ctx context.Context, url string, version string, store *mapSto
 		},
 	})
 	if err != nil {
-		log.Error(err, "Unable to copy OCI content to store")
-
-		return err
+		return fmt.Errorf("unable to copy OCI content to store: %w", err)
 	}
 
 	return nil
@@ -276,16 +270,14 @@ func OCIAuthentication(c configclient.VariablesClient) *auth.Credential {
 func FetchOCI(ctx context.Context, provider operatorv1.GenericProvider, cred *auth.Credential) (*mapStore, error) {
 	log := log.FromContext(ctx)
 
-	log.Info("Custom fetch configuration OCI url was provided")
+	log.V(2).Info("Custom fetch configuration OCI url was provided")
 
 	// Prepare components store for the provider type.
 	store := NewMapStore(provider)
 
 	err := CopyOCIStore(ctx, provider.GetSpec().FetchConfig.OCI, provider.GetSpec().Version, &store, cred)
 	if err != nil {
-		log.Error(err, "Unable to copy OCI content")
-
-		return nil, err
+		return nil, fmt.Errorf("unable to copy OCI content: %w", err)
 	}
 
 	return &store, nil

internal/controller/phase_fetch.go

@@ -49,6 +49,8 @@ func (p *PhaseReconciler) Fetch(ctx context.Context) (*Result, error) {
 	// Check if components exceed the resource size.
 	p.needsCompression = needToCompress(componentsFile)
 
+	log.V(2).Info("Fetched components file", "size", len(componentsFile), "needsCompression", p.needsCompression)
+
 	// Generate a set of new objects using the clusterctl library. NewComponents() will do the yaml processing,
 	// like ensure all the provider components are in proper namespace, replace variables, etc. See the clusterctl
 	// documentation for more details.
@@ -95,7 +97,6 @@ func (p *PhaseReconciler) Store(ctx context.Context) (*Result, error) {
 
 	kinds, _, err := scheme.Scheme.ObjectKinds(&corev1.Secret{})
 	if err != nil || len(kinds) == 0 {
-		log.Error(err, "cannot fetch kind of the Secret resource")
 		err = fmt.Errorf("cannot fetch kind of the Secret resource: %w", err)
 
 		return &Result{}, wrapPhaseError(err, operatorv1.ComponentsCustomizationErrorReason, operatorv1.ProviderInstalledCondition)
@@ -147,8 +148,6 @@ func (p *PhaseReconciler) Store(ctx context.Context) (*Result, error) {
 	}
 
 	if err := p.ctrlClient.Patch(ctx, secret, client.Apply, client.ForceOwnership, client.FieldOwner(cacheOwner)); err != nil {
-		log.Error(err, "failed to apply cache config map")
-
 		return &Result{}, wrapPhaseError(err, operatorv1.ComponentsCustomizationErrorReason, operatorv1.ProviderInstalledCondition)
 	}
 
@@ -182,12 +181,16 @@ func addNamespaceIfMissing(objs []unstructured.Unstructured, targetNamespace str
 	return objs
 }
 
-func (p *PhaseReconciler) ReportStatus(_ context.Context) (*Result, error) {
+func (p *PhaseReconciler) ReportStatus(ctx context.Context) (*Result, error) {
+	log := ctrl.LoggerFrom(ctx)
+
 	status := p.provider.GetStatus()
 	status.Contract = &p.contract
 	installedVersion := p.components.Version()
 	status.InstalledVersion = &installedVersion
 	p.provider.SetStatus(status)
 
+	log.V(2).Info("Reported provider status", "contract", p.contract, "installedVersion", installedVersion)
+
 	return &Result{}, nil
 }