Hotfix add extra debug logs

internal/helm-locker/controllers/release/controller.go

@@ -96,9 +96,13 @@ func Register(
 }
 
 func (h *handler) OnObjectSetChange(setID string, obj runtime.Object) (runtime.Object, error) {
+	logrus.Debugf("Handling ObjectSet %s", setID)
+
 	helmReleases, err := h.helmReleaseCache.GetByIndex(HelmReleaseByReleaseKey, setID)
 	if err != nil {
-		return nil, fmt.Errorf("unable to find HelmReleases for objectset %s to trigger event", setID)
+		err = fmt.Errorf("unable to find HelmReleases for objectset %s to trigger event", setID)
+		logrus.Warnf("%v", err)
+		return nil, err
 	}
 	for _, helmRelease := range helmReleases {
 		if helmRelease == nil {
@@ -179,6 +183,7 @@ func (h *handler) OnHelmReleaseRemove(_ string, helmRelease *v1alpha1.HelmReleas
 	}
 	if helmRelease.Status.State == v1alpha1.SecretNotFoundState || helmRelease.Status.State == v1alpha1.UninstalledState {
 		// HelmRelease was not tracking any underlying objectSet
+		logrus.Warnf("HelmRelease %s was removed. It was not tracking an objectset. State was: %s.", helmRelease.GetName(), helmRelease.Status.State)
 		return helmRelease, nil
 	}
 	// HelmRelease CRs are only pointers to Helm releases... if the HelmRelease CR is removed, we should do nothing, but should warn the user
@@ -191,6 +196,7 @@ func (h *handler) OnHelmReleaseRemove(_ string, helmRelease *v1alpha1.HelmReleas
 }
 
 func (h *handler) OnHelmRelease(_ string, helmRelease *v1alpha1.HelmRelease) (*v1alpha1.HelmRelease, error) {
+
 	if shouldManage, err := h.shouldManage(helmRelease); err != nil {
 		return helmRelease, err
 	} else if !shouldManage {
@@ -211,7 +217,9 @@ func (h *handler) OnHelmRelease(_ string, helmRelease *v1alpha1.HelmRelease) (*v
 			helmRelease.Status.Notes = ""
 			return h.helmReleases.UpdateStatus(helmRelease)
 		}
-		return helmRelease, fmt.Errorf("unable to find latest Helm Release Secret tied to Helm Release %s: %s", helmRelease.GetName(), err)
+		err = fmt.Errorf("unable to find latest Helm Release Secret tied to Helm Release %s: %s", helmRelease.GetName(), err)
+		logrus.Warnf("%v", err)
+		return helmRelease, err
 	}
 	logrus.Infof("loading latest release version %d of HelmRelease %s", latestRelease.Version, helmRelease.GetName())
 	releaseInfo := newReleaseInfo(latestRelease)

internal/helm-locker/objectset/cache.go

@@ -175,6 +175,9 @@ func (c *lockableObjectSetRegisterAndCache) Lock(key relatedresource.Key) {
 		// nothing to lock
 		return
 	}
+
+	s.mutateMu.RLock()
+	defer s.mutateMu.RUnlock()
 	if s.ObjectSet == nil {
 		// nothing to lock
 		return
@@ -285,7 +288,9 @@ func (c *lockableObjectSetRegisterAndCache) deleteState(key relatedresource.Key)
 	delete(c.stateByKey, key)
 	c.stateMapLock.Unlock()
 
+	s.mutateMu.Lock()
 	s.ObjectSet = nil
+	s.mutateMu.Unlock()
 	s.Locked = false
 	c.stateChanges <- watch.Event{Type: watch.Deleted, Object: s}
 }

internal/helm-locker/objectset/state.go

@@ -1,6 +1,8 @@
 package objectset
 
 import (
+	"sync"
+
 	"time"
 
 	"github.com/google/uuid"
@@ -38,6 +40,7 @@ func newObjectSetState(namespace, name string, obj objectSetState) *objectSetSta
 	obj.UID = types.UID(uuid.New().String())
 	obj.CreationTimestamp = metav1.NewTime(time.Now())
 	obj.ResourceVersion = "0"
+	obj.mutateMu = &sync.RWMutex{}
 	return &obj
 }
 
@@ -50,6 +53,8 @@ type objectSetState struct {
 	// ObjectSet is a pointer to the underlying ObjectSet whose state is being tracked
 	ObjectSet *objectset.ObjectSet `json:"objectSet,omitempty"`
 
+	mutateMu *sync.RWMutex
+
 	// Locked represents whether the ObjectSet should be locked in the cluster or not
 	Locked bool `json:"locked"`
 }

internal/helm-project-operator/controllers/controllers.go

@@ -145,6 +145,7 @@ func Register(ctx context.Context, systemNamespace string, cfg clientcmd.ClientC
 	if err != nil {
 		return err
 	}
+	logrus.Infof("Registering Project Controller...")
 	project.Register(ctx,
 		systemNamespace,
 		opts,

internal/helm-project-operator/controllers/project/controller.go

@@ -71,6 +71,7 @@ func Register(
 	projectGetter namespace.ProjectGetter,
 ) {
 
+	logrus.Debugf("running apply inside Project Controller register")
 	apply = apply.
 		// Why do we need the release name?
 		// To ensure that we don't override the set created by another instance of the Project Operator
@@ -105,8 +106,10 @@ func Register(
 		projectGetter:           projectGetter,
 	}
 
+	logrus.Debugf("Initializing indexers inside Project Controller register")
 	h.initIndexers()
 
+	logrus.Debugf("Initializing resolvers inside Project Controller register")
 	h.initResolvers(ctx)
 
 	// Why do we need to add the managedBy string to the generatingHandlerName?
@@ -158,36 +161,44 @@ func (h *handler) shouldManage(projectHelmChart *v1alpha2.ProjectHelmChart) bool
 		//
 		// Note: we know that this error would only happen if the namespace is not found since the only valid error returned from this
 		// call is errors.NewNotFound(c.resource, name)
+		logrus.Warnf("ProjectHelmChart %s/%s has invalid namespace. It will not be managed by this controller.", projectHelmChart.Name, projectHelmChart.Namespace)
 		return false
 	}
 	isProjectRegistrationNamespace := h.projectGetter.IsProjectRegistrationNamespace(namespace)
 	if !isProjectRegistrationNamespace {
 		// only watching resources in registered namespaces
+		logrus.Warnf("ProjectHelmChart %s/%s does not live in a project registration namespace. It will not be managed by this controller.", projectHelmChart.Name, projectHelmChart.Namespace)
 		return false
 	}
 	if projectHelmChart.Spec.HelmAPIVersion != h.opts.HelmAPIVersion {
 		// only watch resources with the HelmAPIVersion this controller was configured with
+		logrus.Debugf("ProjectHelmChart %s/%s has HelmAPIVersion %s. This controller will only manager resources with helmAPIVersion %s.", projectHelmChart.Name, projectHelmChart.Namespace, projectHelmChart.Spec.HelmAPIVersion, h.opts.HelmAPIVersion)
 		return false
 	}
 	return true
 }
 
 func (h *handler) OnChange(projectHelmChart *v1alpha2.ProjectHelmChart, projectHelmChartStatus v1alpha2.ProjectHelmChartStatus) ([]runtime.Object, v1alpha2.ProjectHelmChartStatus, error) {
+	logrus.Debugf("Handling ProjectHelmChart %s/%s.", projectHelmChart.Name, projectHelmChart.Namespace)
+
 	var objs []runtime.Object
 
 	// initial checks to see if we should handle this
 	shouldManage := h.shouldManage(projectHelmChart)
 	if !shouldManage {
+		logrus.Debugf("Cancelled handling of ProjectHelmChart %s/%s. shouldManage returned 'false'.", projectHelmChart.Name, projectHelmChart.Namespace)
 		return nil, projectHelmChartStatus, nil
 	}
 	if projectHelmChart.DeletionTimestamp != nil {
+		logrus.Debugf("Cancelled handling of ProjectHelmChart %s/%s. CR has been deleted.", projectHelmChart.Name, projectHelmChart.Namespace)
 		return nil, projectHelmChartStatus, nil
 	}
 
 	// handle charts with cleanup label
 	if common2.HasCleanupLabel(projectHelmChart) {
 		projectHelmChartStatus = h.getCleanupStatus(projectHelmChart, projectHelmChartStatus)
-		logrus.Infof("Cleaning up HelmChart and HelmRelease for ProjectHelmChart %s/%s", projectHelmChart.Namespace, projectHelmChart.Name)
+		logrus.Debugf("ProjectHelmChart %s/%s has cleanup label set to 'true'. %s", projectHelmChart.Name, projectHelmChart.Namespace, projectHelmChartStatus.StatusMessage)
+		logrus.Debugf("Cleaning up HelmChart and HelmRelease for ProjectHelmChart %s/%s.", projectHelmChart.Namespace, projectHelmChart.Name)
 		return nil, projectHelmChartStatus, nil
 	}
 
@@ -197,11 +208,14 @@ func (h *handler) OnChange(projectHelmChart *v1alpha2.ProjectHelmChart, projectH
 		return nil, projectHelmChartStatus, err
 	}
 	releaseNamespace, releaseName := h.getReleaseNamespaceAndName(projectHelmChart)
+	logrus.Debugf("ProjectHelmChart %s/%s has project release namespace set to %s and HelmRelease named %s.", projectHelmChart.Name, projectHelmChart.Namespace, releaseNamespace, releaseName)
 
 	// check if the releaseName is already tracked by another ProjectHelmChart
 	projectHelmCharts, err := h.projectHelmChartCache.GetByIndex(ProjectHelmChartByReleaseName, releaseName)
 	if err != nil {
-		return nil, projectHelmChartStatus, fmt.Errorf("unable to get ProjectHelmCharts to verify if release is already tracked: %s", err)
+		err = fmt.Errorf("unable to get ProjectHelmCharts to verify if release is already tracked: %s", err)
+		logrus.Warnf("%v", err)
+		return nil, projectHelmChartStatus, err
 	}
 	for _, conflictingProjectHelmChart := range projectHelmCharts {
 		if conflictingProjectHelmChart == nil {
@@ -221,10 +235,12 @@ func (h *handler) OnChange(projectHelmChart *v1alpha2.ProjectHelmChart, projectH
 		}
 		// we have found another ProjectHelmChart that already exists and is tracking this release with some non-conflicting status
 		err = fmt.Errorf(
-			"ProjectHelmChart %s/%s already tracks release %s/%s",
-			conflictingProjectHelmChart.Namespace, conflictingProjectHelmChart.Name,
+			"unable to create HelmRelease for ProjectHelmChart %s/%s. ProjectHelmChart %s/%s already tracks release %s/%s",
+			projectHelmChart.Name, projectHelmChart.Namespace,
+			conflictingProjectHelmChart.Name, conflictingProjectHelmChart.Namespace,
 			releaseName, releaseNamespace,
 		)
+		logrus.Warnf("%v", err)
 		projectHelmChartStatus = h.getUnableToCreateHelmReleaseStatus(projectHelmChart, projectHelmChartStatus, err)
 		return nil, projectHelmChartStatus, nil
 	}
@@ -237,14 +253,17 @@ func (h *handler) OnChange(projectHelmChart *v1alpha2.ProjectHelmChart, projectH
 	// gather target project namespaces
 	targetProjectNamespaces, err := h.projectGetter.GetTargetProjectNamespaces(projectHelmChart)
 	if err != nil {
-		return nil, projectHelmChartStatus, fmt.Errorf("unable to find project namespaces to deploy ProjectHelmChart: %s", err)
+		err = fmt.Errorf("Unable to find target project namespaces to deploy ProjectHelmChart %s/%s: %s", projectHelmChart.Name, projectHelmChart.Namespace, err)
+		logrus.Warnf("%v", err)
+		return nil, projectHelmChartStatus, err
 	}
 	if len(targetProjectNamespaces) == 0 {
 		projectReleaseNamespace := h.getProjectReleaseNamespace(projectID, true, projectHelmChart)
 		if projectReleaseNamespace != nil {
 			objs = append(objs, projectReleaseNamespace)
 		}
 		projectHelmChartStatus = h.getNoTargetNamespacesStatus(projectHelmChart, projectHelmChartStatus)
+		logrus.Debugf("ProjectHelmChart %s/%s has no target project namespaces. Setting its status to %s.", projectHelmChart.Name, projectHelmChart.Namespace, projectHelmChartStatus.Status)
 		return objs, projectHelmChartStatus, nil
 	}
 
@@ -254,6 +273,7 @@ func (h *handler) OnChange(projectHelmChart *v1alpha2.ProjectHelmChart, projectH
 		objs = append(objs, projectReleaseNamespace)
 		// need to add auto-generated release namespace to target namespaces
 		targetProjectNamespaces = append(targetProjectNamespaces, releaseNamespace)
+		logrus.Debugf("Adding auto-generated release namespace %s to list of target namespaces for ProjectHelmChart %s/%s.", releaseNamespace, projectHelmChart.Name, projectHelmChart.Namespace)
 	}
 	projectHelmChartStatus.TargetNamespaces = targetProjectNamespaces
 
@@ -262,6 +282,7 @@ func (h *handler) OnChange(projectHelmChart *v1alpha2.ProjectHelmChart, projectH
 	valuesContentBytes, err := values.ToYAML()
 	if err != nil {
 		err = fmt.Errorf("unable to marshall spec.values: %s", err)
+		logrus.Warnf("%v", err)
 		projectHelmChartStatus = h.getValuesParseErrorStatus(projectHelmChart, projectHelmChartStatus, err)
 		return nil, projectHelmChartStatus, nil
 	}
@@ -277,6 +298,7 @@ func (h *handler) OnChange(projectHelmChart *v1alpha2.ProjectHelmChart, projectH
 		// the newly created namespace. Without this, a deleted release namespace will always have ProjectHelmCharts stuck in
 		// WaitingForDashboardValues since the underlying helm release will never be recreated
 		err = fmt.Errorf("cannot find release namespace %s to deploy release", releaseNamespace)
+		logrus.Warnf("%v", err)
 		projectHelmChartStatus = h.getUnableToCreateHelmReleaseStatus(projectHelmChart, projectHelmChartStatus, err)
 		return objs, projectHelmChartStatus, nil
 	} else if err != nil {
@@ -286,11 +308,15 @@ func (h *handler) OnChange(projectHelmChart *v1alpha2.ProjectHelmChart, projectH
 	// get rolebindings that need to be created in release namespace
 	k8sRolesToRoleRefs, err := h.getSubjectRoleToRoleRefsFromRoles(projectHelmChart)
 	if err != nil {
-		return nil, projectHelmChartStatus, fmt.Errorf("unable to get release roles from project release namespace %s for %s/%s: %s", releaseNamespace, projectHelmChart.Namespace, projectHelmChart.Name, err)
+		err = fmt.Errorf("unable to get release roles from project release namespace %s for %s/%s: %s", releaseNamespace, projectHelmChart.Name, projectHelmChart.Namespace, err)
+		logrus.Warnf("%v", err)
+		return nil, projectHelmChartStatus, err
 	}
 	k8sRolesToSubjects, err := h.getSubjectRoleToSubjectsFromBindings(projectHelmChart)
 	if err != nil {
-		return nil, projectHelmChartStatus, fmt.Errorf("unable to get rolebindings to default project operator roles from project registration namespace %s for %s/%s: %s", projectHelmChart.Namespace, projectHelmChart.Namespace, projectHelmChart.Name, err)
+		err = fmt.Errorf("unable to get rolebindings to default project operator roles from project registration namespace %s for %s/%s: %s", projectHelmChart.Namespace, projectHelmChart.Name, projectHelmChart.Namespace, err)
+		logrus.Warnf("%v", err)
+		return nil, projectHelmChartStatus, err
 	}
 	objs = append(objs,
 		h.getRoleBindings(projectID, k8sRolesToRoleRefs, k8sRolesToSubjects, projectHelmChart)...,
@@ -305,10 +331,13 @@ func (h *handler) OnChange(projectHelmChart *v1alpha2.ProjectHelmChart, projectH
 	// get dashboard values if available
 	dashboardValues, err := h.getDashboardValuesFromConfigmaps(projectHelmChart)
 	if err != nil {
-		return nil, projectHelmChartStatus, fmt.Errorf("unable to get dashboard values from status ConfigMaps: %s", err)
+		err = fmt.Errorf("unable to get dashboard values from status ConfigMaps: %s", err)
+		logrus.Warnf("%v", err)
+		return nil, projectHelmChartStatus, err
 	}
 	if len(dashboardValues) == 0 {
 		projectHelmChartStatus = h.getWaitingForDashboardValuesStatus(projectHelmChart, projectHelmChartStatus)
+		logrus.Debugf("Dashboard values returned with length 0. Setting %s/%s to have status %s", projectHelmChart.Name, projectHelmChart.Namespace, projectHelmChartStatus.Status)
 	} else {
 		projectHelmChartStatus.DashboardValues = dashboardValues
 		projectHelmChartStatus = h.getDeployedStatus(projectHelmChart, projectHelmChartStatus)
@@ -317,13 +346,17 @@ func (h *handler) OnChange(projectHelmChart *v1alpha2.ProjectHelmChart, projectH
 }
 
 func (h *handler) OnRemove(_ string, projectHelmChart *v1alpha2.ProjectHelmChart) (*v1alpha2.ProjectHelmChart, error) {
+	logrus.Debugf("Handling ProjectHelmChart %s/%s removal.", projectHelmChart.Name, projectHelmChart.Namespace)
+
 	if projectHelmChart == nil {
+		logrus.Debugf("ProjectHelmChart %s/%s is nil. Canceling removal.", projectHelmChart.Name, projectHelmChart.Namespace)
 		return nil, nil
 	}
 
 	// get information about the projectHelmChart
 	projectID, err := h.getProjectID(projectHelmChart)
 	if err != nil {
+		logrus.Warnf("Error getting projectID for projectHelmChart %s/%s: %v", projectHelmChart.Name, projectHelmChart.Namespace, err)
 		return projectHelmChart, err
 	}
 
@@ -341,7 +374,9 @@ func (h *handler) OnRemove(_ string, projectHelmChart *v1alpha2.ProjectHelmChart
 	// that will delete this projectReleaseNamespace on seeing it
 	err = h.apply.ApplyObjects(projectReleaseNamespace)
 	if err != nil {
-		return projectHelmChart, fmt.Errorf("unable to add orphaned annotation to project release namespace %s", projectReleaseNamespace.Name)
+		err = fmt.Errorf("unable to add orphaned annotation to project release namespace %s", projectReleaseNamespace.Name)
+		logrus.Warnf("%v", err)
+		return projectHelmChart, err
 	}
 	return projectHelmChart, nil
 }