Add more logging around catalog source sync

Signed-off-by: Per Goncalves da Silva <[email protected]>

Author: Per Goncalves da Silva

pkg/controller/operators/catalog/operator.go

@@ -897,6 +897,7 @@ func (o *Operator) handleCatSrcDeletion(obj interface{}) {
 }
 
 func validateSourceType(logger *logrus.Entry, in *v1alpha1.CatalogSource) (out *v1alpha1.CatalogSource, continueSync bool, _ error) {
+	logger.Info("validating catalog source type")
 	out = in
 	var err error
 	switch sourceType := out.Spec.SourceType; sourceType {
@@ -912,41 +913,46 @@ func validateSourceType(logger *logrus.Entry, in *v1alpha1.CatalogSource) (out *
 		err = fmt.Errorf("unknown sourcetype: %s", sourceType)
 	}
 	if err != nil {
+		logger.WithError(err).Error("error validating catalog source type")
 		out.SetError(v1alpha1.CatalogSourceSpecInvalidError, err)
 		return
 	}
 
 	// The sourceType is valid, clear all status (other than status conditions array) if there's existing invalid spec reason
 	if out.Status.Reason == v1alpha1.CatalogSourceSpecInvalidError {
+		logger.Info("catalog source has invalid spec")
 		out.Status = v1alpha1.CatalogSourceStatus{
 			Conditions: out.Status.Conditions,
 		}
 	}
 	continueSync = true
 
+	logger.Info("catalog source type validated")
 	return
 }
 
 func (o *Operator) syncConfigMap(logger *logrus.Entry, in *v1alpha1.CatalogSource) (out *v1alpha1.CatalogSource, continueSync bool, syncError error) {
+	logger = logger.WithFields(logrus.Fields{
+		"configmap.namespace": in.Namespace,
+		"configmap.name":      in.Spec.ConfigMap,
+	})
+	logger.Info("checking catsrc configmap state")
+
 	out = in
 	if !(in.Spec.SourceType == v1alpha1.SourceTypeInternal || in.Spec.SourceType == v1alpha1.SourceTypeConfigmap) {
 		continueSync = true
+		logger.Info("catalog type is neither internal not configmap - bailing without error")
 		return
 	}
 
 	out = in.DeepCopy()
 
-	logger = logger.WithFields(logrus.Fields{
-		"configmap.namespace": in.Namespace,
-		"configmap.name":      in.Spec.ConfigMap,
-	})
-	logger.Info("checking catsrc configmap state")
-
 	var updateLabel bool
 	// Get the catalog source's config map
 	configMap, err := o.lister.CoreV1().ConfigMapLister().ConfigMaps(in.GetNamespace()).Get(in.Spec.ConfigMap)
 	// Attempt to look up the CM via api call if there is a cache miss
 	if apierrors.IsNotFound(err) {
+		logger.Info("configmap not found in cache - attempting with live client")
 		configMap, err = o.opClient.KubernetesInterface().CoreV1().ConfigMaps(in.GetNamespace()).Get(context.TODO(), in.Spec.ConfigMap, metav1.GetOptions{})
 		// Found cm in the cluster, add managed label to configmap
 		if err == nil {
@@ -961,6 +967,7 @@ func (o *Operator) syncConfigMap(logger *logrus.Entry, in *v1alpha1.CatalogSourc
 		}
 	}
 	if err != nil {
+		logger.WithError(err).Error("error getting configmap")
 		syncError = fmt.Errorf("failed to get catalog config map %s: %s", in.Spec.ConfigMap, err)
 		out.SetError(v1alpha1.CatalogSourceConfigMapError, syncError)
 		return
@@ -969,11 +976,11 @@ func (o *Operator) syncConfigMap(logger *logrus.Entry, in *v1alpha1.CatalogSourc
 	if wasOwned := ownerutil.EnsureOwner(configMap, in); !wasOwned || updateLabel {
 		configMap, err = o.opClient.KubernetesInterface().CoreV1().ConfigMaps(configMap.GetNamespace()).Update(context.TODO(), configMap, metav1.UpdateOptions{})
 		if err != nil {
+			logger.WithError(err).Error("error updating configmap")
 			syncError = fmt.Errorf("unable to write owner onto catalog source configmap - %v", err)
 			out.SetError(v1alpha1.CatalogSourceConfigMapError, syncError)
 			return
 		}
-
 		logger.Info("adopted configmap")
 	}
 
@@ -992,22 +999,30 @@ func (o *Operator) syncConfigMap(logger *logrus.Entry, in *v1alpha1.CatalogSourc
 	}
 
 	continueSync = true
+	logger.Info("configmap catalog source sync'ed successfully")
 	return
 }
 
 func (o *Operator) syncRegistryServer(logger *logrus.Entry, in *v1alpha1.CatalogSource) (out *v1alpha1.CatalogSource, continueSync bool, syncError error) {
 	out = in.DeepCopy()
 
 	logger.Info("synchronizing registry server")
+	defer func() {
+		logger.WithError(syncError).WithField("continueSync", continueSync).Info("finished synchronizing registry server")
+	}()
 	sourceKey := registry.CatalogKey{Name: in.GetName(), Namespace: in.GetNamespace()}
+
+	logger.Info("getting reconciler for catalog source")
 	srcReconciler := o.reconciler.ReconcilerForSource(in)
 	if srcReconciler == nil {
-		// TODO: Add failure status on catalogsource and remove from sources
+		// TODO: Add failure status on catalogsource and remove from sources )
 		syncError = fmt.Errorf("no reconciler for source type %s", in.Spec.SourceType)
 		out.SetError(v1alpha1.CatalogSourceRegistryServerError, syncError)
+		logger.WithError(syncError).Info("not reconciler for source")
 		return
 	}
 
+	logger.Info("checking registry server health")
 	healthy, err := srcReconciler.CheckRegistryServer(logger, in)
 	if err != nil {
 		syncError = err
@@ -1048,11 +1063,14 @@ func (o *Operator) syncRegistryServer(logger *logrus.Entry, in *v1alpha1.Catalog
 	if out.Spec.UpdateStrategy != nil && out.Spec.UpdateStrategy.RegistryPoll != nil {
 		if out.Spec.UpdateStrategy.Interval == nil {
 			syncError = fmt.Errorf("empty polling interval; cannot requeue registry server sync without a provided polling interval")
+			logger.WithError(syncError).Info("failed to sync registry server")
 			out.SetError(v1alpha1.CatalogSourceIntervalInvalidError, syncError)
 			return
 		}
 		if out.Spec.UpdateStrategy.RegistryPoll.ParsingError != "" && out.Status.Reason != v1alpha1.CatalogSourceIntervalInvalidError {
-			out.SetError(v1alpha1.CatalogSourceIntervalInvalidError, errors.New(out.Spec.UpdateStrategy.RegistryPoll.ParsingError))
+			err := errors.New(out.Spec.UpdateStrategy.RegistryPoll.ParsingError)
+			logger.WithError(err).Info("failed to parse registry poll interval")
+			out.SetError(v1alpha1.CatalogSourceIntervalInvalidError, err)
 		}
 		logger.Infof("requeuing registry server sync based on polling interval %s", out.Spec.UpdateStrategy.Interval.Duration.String())
 		resyncPeriod := reconciler.SyncRegistryUpdateInterval(out, time.Now())
@@ -1061,13 +1079,14 @@ func (o *Operator) syncRegistryServer(logger *logrus.Entry, in *v1alpha1.Catalog
 	}
 
 	if err := o.sources.Remove(sourceKey); err != nil {
-		o.logger.WithError(err).Debug("error closing client connection")
+		o.logger.WithError(err).Info("error closing client connection")
 	}
 
 	return
 }
 
 func (o *Operator) syncConnection(logger *logrus.Entry, in *v1alpha1.CatalogSource) (out *v1alpha1.CatalogSource, continueSync bool, syncError error) {
+	logger.Info("syncing connection")
 	out = in.DeepCopy()
 
 	sourceKey := registry.CatalogKey{Name: in.GetName(), Namespace: in.GetNamespace()}
@@ -1079,11 +1098,13 @@ func (o *Operator) syncConnection(logger *logrus.Entry, in *v1alpha1.CatalogSour
 		newSource, err := o.sources.Add(sourceKey, address)
 		if err != nil {
 			connErr = fmt.Errorf("couldn't connect to registry - %v", err)
+			logger.WithError(err).Info("couldn't connect to registry")
 			return
 		}
 
 		if newSource == nil {
 			connErr = errors.New("couldn't connect to registry")
+			logger.Info("couldn't connect to registry: new source is nil")
 			return
 		}
 
@@ -1101,6 +1122,7 @@ func (o *Operator) syncConnection(logger *logrus.Entry, in *v1alpha1.CatalogSour
 
 	source := o.sources.GetMeta(sourceKey)
 	if source == nil {
+		logger.Info("source not found - attempting to establish connection")
 		source, syncError = connectFunc()
 		if syncError != nil {
 			out.SetError(v1alpha1.CatalogSourceRegistryServerError, syncError)
@@ -1109,10 +1131,15 @@ func (o *Operator) syncConnection(logger *logrus.Entry, in *v1alpha1.CatalogSour
 
 		// Set connection status and return.
 		updateConnectionStateFunc(out, source)
+		logger.Info("successfully created source and updated connection state")
 		return
 	}
 
 	if source.Address != address {
+		logger.WithFields(logrus.Fields{
+			"source.address":        source.Address,
+			"catalogsource.address": address,
+		}).Info("source and catalog source addresses differ - creating a new source")
 		source, syncError = connectFunc()
 		if syncError != nil {
 			out.SetError(v1alpha1.CatalogSourceRegistryServerError, syncError)
@@ -1125,17 +1152,20 @@ func (o *Operator) syncConnection(logger *logrus.Entry, in *v1alpha1.CatalogSour
 
 	// GRPCConnectionState update must fail before
 	if out.Status.GRPCConnectionState == nil {
+		logger.Info("connection state is nil - attempting to update connection state")
 		updateConnectionStateFunc(out, source)
 	}
 
 	// connection is already good, but we need to update the sync time
 	if o.sourcesLastUpdate.After(out.Status.GRPCConnectionState.LastConnectTime.Time) {
+		logger.Info("updating sync time")
 		// Set connection status and return.
 		out.Status.GRPCConnectionState.LastConnectTime = now
 		out.Status.GRPCConnectionState.LastObservedState = source.ConnectionState.String()
 		out.Status.GRPCConnectionState.Address = source.Address
 	}
 
+	logger.Info("successfully sync'ed connection")
 	return
 }
 
@@ -1153,6 +1183,13 @@ func (o *Operator) syncCatalogSources(obj interface{}) (syncError error) {
 		"id":                      queueinformer.NewLoopID(),
 	})
 	logger.Info("syncing catalog source")
+	defer func() {
+		if syncError != nil {
+			logger.WithError(syncError).Info("failed to sync catalog source")
+		} else {
+			logger.Info("successfully synced catalog source")
+		}
+	}()
 
 	syncFunc := func(in *v1alpha1.CatalogSource, chain []CatalogSourceSyncFunc) (out *v1alpha1.CatalogSource, syncErr error) {
 		out = in

pkg/controller/registry/reconciler/grpc.go

@@ -252,6 +252,7 @@ func (c *GrpcRegistryReconciler) EnsureRegistryServer(logger *logrus.Entry, cata
 	// if service status is nil, we force create every object to ensure they're created the first time
 	valid, err := isRegistryServiceStatusValid(&source)
 	if err != nil {
+		logger.WithError(err).Info("couldn't validate registry service status")
 		return err
 	}
 	overwrite := !valid
@@ -262,22 +263,26 @@ func (c *GrpcRegistryReconciler) EnsureRegistryServer(logger *logrus.Entry, cata
 	//TODO: if any of these error out, we should write a status back (possibly set RegistryServiceStatus to nil so they get recreated)
 	sa, err := c.ensureSA(source)
 	if err != nil && !apierrors.IsAlreadyExists(err) {
+		logger.WithError(err).Error("couldn't ensure registry service account")
 		return pkgerrors.Wrapf(err, "error ensuring service account: %s", source.GetName())
 	}
 
 	sa, err = c.OpClient.GetServiceAccount(sa.GetNamespace(), sa.GetName())
 	if err != nil {
+		logger.WithError(err).Error("couldn't get registry service account")
 		return err
 	}
 
 	defaultPodSecurityConfig, err := getDefaultPodContextConfig(c.OpClient, catalogSource.GetNamespace())
 	if err != nil {
+		logger.WithError(err).Error("couldn't get default pod security config")
 		return err
 	}
 
 	// recreate the pod if no existing pod is serving the latest image or correct spec
 	current, err := c.currentPodsWithCorrectImageAndSpec(logger, source, sa, defaultPodSecurityConfig)
 	if err != nil {
+		logger.WithError(err).Error("couldn't get current pods with correct image and spec")
 		return err
 	}
 	overwritePod := overwrite || len(current) == 0
@@ -287,29 +292,36 @@ func (c *GrpcRegistryReconciler) EnsureRegistryServer(logger *logrus.Entry, cata
 
 	pod, err := source.Pod(sa, defaultPodSecurityConfig)
 	if err != nil {
+		logger.WithError(err).Error("couldn't create registry pod")
 		return err
 	}
 	if err := c.ensurePod(logger, source, sa, defaultPodSecurityConfig, overwritePod); err != nil {
+		logger.WithError(err).Error("couldn't ensure registry pod")
 		return pkgerrors.Wrapf(err, "error ensuring pod: %s", pod.GetName())
 	}
 	if err := c.ensureUpdatePod(logger, sa, defaultPodSecurityConfig, source); err != nil {
 		if _, ok := err.(UpdateNotReadyErr); ok {
+			logger.WithError(err).Error("ensure update pod error is not of type UpdateNotReadyErr")
 			return err
 		}
 		return pkgerrors.Wrapf(err, "error ensuring updated catalog source pod: %s", pod.GetName())
 	}
 	service, err := source.Service()
 	if err != nil {
+		logger.WithError(err).Error("couldn't get service")
 		return err
 	}
 	if err := c.ensureService(source, overwrite); err != nil {
+		logger.WithError(err).Error("couldn't ensure service")
 		return pkgerrors.Wrapf(err, "error ensuring service: %s", service.GetName())
 	}
 
 	if overwritePod {
+		logger.Info("overwriting pod registry service status")
 		now := c.now()
 		service, err := source.Service()
 		if err != nil {
+			logger.WithError(err).Error("couldn't get service")
 			return err
 		}
 		catalogSource.Status.RegistryServiceStatus = &v1alpha1.RegistryServiceStatus{
@@ -320,6 +332,8 @@ func (c *GrpcRegistryReconciler) EnsureRegistryServer(logger *logrus.Entry, cata
 			Port:             getPort(service),
 		}
 	}
+
+	logger.Info("registry service ensured successfully")
 	return nil
 }
 
@@ -581,6 +595,7 @@ func (c *GrpcRegistryReconciler) removePods(pods []*corev1.Pod, namespace string
 
 // CheckRegistryServer returns true if the given CatalogSource is considered healthy; false otherwise.
 func (c *GrpcRegistryReconciler) CheckRegistryServer(logger *logrus.Entry, catalogSource *v1alpha1.CatalogSource) (bool, error) {
+	logger.Info("checking registry server")
 	source := grpcCatalogSourceDecorator{CatalogSource: catalogSource, createPodAsUser: c.createPodAsUser, opmImage: c.opmImage, utilImage: c.utilImage}
 
 	// The CheckRegistryServer function is called by the CatalogSoruce controller before the registry resources are created,
@@ -589,6 +604,7 @@ func (c *GrpcRegistryReconciler) CheckRegistryServer(logger *logrus.Entry, catal
 	serviceAccount := source.ServiceAccount()
 	serviceAccount, err := c.OpClient.GetServiceAccount(serviceAccount.GetNamespace(), serviceAccount.GetName())
 	if err != nil {
+		logger.WithError(err).Infof("registry service not healthy: could not get service account")
 		if !apierrors.IsNotFound(err) {
 			return false, err
 		}
@@ -597,27 +613,40 @@ func (c *GrpcRegistryReconciler) CheckRegistryServer(logger *logrus.Entry, catal
 
 	registryPodSecurityConfig, err := getDefaultPodContextConfig(c.OpClient, catalogSource.GetNamespace())
 	if err != nil {
+		logger.WithError(err).Info("registry service not healthy: could not get registry pod security config")
 		return false, err
 	}
 
 	// Check on registry resources
 	// TODO: add gRPC health check
 	service, err := c.currentService(source)
 	if err != nil {
+		logger.WithError(err).Info("catalog registry service not healthy: could not get current service")
 		return false, err
 	}
 	currentPods, err := c.currentPodsWithCorrectImageAndSpec(logger, source, serviceAccount, registryPodSecurityConfig)
 	if err != nil {
+		logger.WithError(err).Info("catalog registry service not healthy: could not get current pods")
 		return false, err
 	}
+
+	currentServiceAccount := c.currentServiceAccount(source)
 	if len(currentPods) < 1 ||
-		service == nil || c.currentServiceAccount(source) == nil {
+		service == nil || currentServiceAccount == nil {
+		logger.WithFields(logrus.Fields{
+			"numCurrentPods":      len(currentPods),
+			"isServiceNil":        service == nil,
+			"isServiceAccountNil": serviceAccount == nil,
+		}).Info("catalog registry service not healthy: one or more required resources are missing")
 		return false, nil
 	}
 	podsAreLive, e := detectAndDeleteDeadPods(logger, c.OpClient, currentPods, source.GetNamespace())
 	if e != nil {
+		logger.WithError(e).Info("catalog registry service not healthy: could not detect and delete dead pods")
 		return false, fmt.Errorf("error deleting dead pods: %v", e)
 	}
+
+	logger.WithField("podsAreAlive", podsAreLive).Info("registry server is healthy")
 	return podsAreLive, nil
 }