Repository: Azure/ARO-RP
Pull request #2615 (2023-01-05 10:53:11)

Adds missing debug logs to the operator
### What this PR does / why we need it:

Every other controller has debug logs like this, but these two controllers were missing logs.




Patch:
diff --git a/docs/monitoring.md b/docs/monitoring.md
index 861c45d24..0aad1e4a4 100644
--- a/docs/monitoring.md
+++ b/docs/monitoring.md
@@ -31,6 +31,12 @@ monitoring from inside the cluster as well as a complementary near-term goal.
   locally (like k8s list/watch).  At startup, the cosmos DB change feed returns
   the current state of all of the OpenShiftClusterDocuments; subsequently as
   OpenShiftClusterDocuments it returns the updated documents.
+* At the moment of writing, the change feed does not log record deletions. It logs
+  only changes. Deallocated clusters are deleted from the monitoring list only if
+  they were seen in the `DeletingProvisioningState` by the monitor.
+  The monitor reads the change feed every 10 seconds, so we should avoid
+  cases when `OpenShiftClusterDocuments` have the `DeletingProvisioningState` for 
+  less than 10 seconds.
 * Each monitor aims to check each cluster it "owns" every 5 minutes; it walks
   the local database map and distributes checking over lots of local goroutine
   workers.
diff --git a/pkg/backend/openshiftcluster.go b/pkg/backend/openshiftcluster.go
index 97be54c69..275189108 100644
--- a/pkg/backend/openshiftcluster.go
+++ b/pkg/backend/openshiftcluster.go
@@ -172,6 +172,7 @@ func (ocb *openShiftClusterBackend) handle(ctx context.Context, log *logrus.Entr
 
 	case api.ProvisioningStateDeleting:
 		log.Print("deleting")
+		t := time.Now()
 
 		err = m.Delete(ctx)
 		if err != nil {
@@ -185,6 +186,11 @@ func (ocb *openShiftClusterBackend) handle(ctx context.Context, log *logrus.Entr
 
 		stop()
 
+		// This Sleep ensures that the monitor has enough time
+		// to capture the deletion (by reading from the changefeed)
+		// and stop monitoring the cluster.
+		// TODO: Provide better communication between RP and Monitor
+		time.Sleep(time.Until(t.Add(time.Second * 20)))
 		return ocb.dbOpenShiftClusters.Delete(ctx, doc)
 	}
 
diff --git a/pkg/frontend/clustermanager_putorpatch.go b/pkg/frontend/clustermanager_putorpatch.go
index b43c25e16..97873261c 100644
--- a/pkg/frontend/clustermanager_putorpatch.go
+++ b/pkg/frontend/clustermanager_putorpatch.go
@@ -371,6 +371,9 @@ func enrichSyncSetSystemData(doc *api.ClusterManagerConfigurationDocument, syste
 	if systemData == nil {
 		return
 	}
+	if doc.SyncSet.SystemData == nil {
+		doc.SyncSet.SystemData = &api.SystemData{}
+	}
 	if systemData.CreatedAt != nil {
 		doc.SyncSet.SystemData.CreatedAt = systemData.CreatedAt
 	}
@@ -395,6 +398,9 @@ func enrichMachinePoolSystemData(doc *api.ClusterManagerConfigurationDocument, s
 	if systemData == nil {
 		return
 	}
+	if doc.MachinePool.SystemData == nil {
+		doc.MachinePool.SystemData = &api.SystemData{}
+	}
 	if systemData.CreatedAt != nil {
 		doc.MachinePool.SystemData.CreatedAt = systemData.CreatedAt
 	}
@@ -419,6 +425,9 @@ func enrichSyncIdentityProviderSystemData(doc *api.ClusterManagerConfigurationDo
 	if systemData == nil {
 		return
 	}
+	if doc.SyncIdentityProvider.SystemData == nil {
+		doc.SyncIdentityProvider.SystemData = &api.SystemData{}
+	}
 	if systemData.CreatedAt != nil {
 		doc.SyncIdentityProvider.SystemData.CreatedAt = systemData.CreatedAt
 	}
@@ -443,6 +452,9 @@ func enrichSecretSystemData(doc *api.ClusterManagerConfigurationDocument, system
 	if systemData == nil {
 		return
 	}
+	if doc.Secret.SystemData == nil {
+		doc.Secret.SystemData = &api.SystemData{}
+	}
 	if systemData.CreatedAt != nil {
 		doc.Secret.SystemData.CreatedAt = systemData.CreatedAt
 	}
diff --git a/pkg/monitor/worker.go b/pkg/monitor/worker.go
index 941db769a..feb632edf 100644
--- a/pkg/monitor/worker.go
+++ b/pkg/monitor/worker.go
@@ -76,6 +76,8 @@ func (mon *monitor) changefeed(ctx context.Context, baseLog *logrus.Entry, stop
 	clustersIterator := mon.dbOpenShiftClusters.ChangeFeed()
 	subscriptionsIterator := mon.dbSubscriptions.ChangeFeed()
 
+	// Align this time with the deletion mechanism.
+	// Go to docs/monitoring.md for the details.
 	t := time.NewTicker(10 * time.Second)
 	defer t.Stop()
 
diff --git a/pkg/operator/controllers/clusteroperatoraro/clusteroperatoraro_controller.go b/pkg/operator/controllers/clusteroperatoraro/clusteroperatoraro_controller.go
index e7d19030c..c27707533 100644
--- a/pkg/operator/controllers/clusteroperatoraro/clusteroperatoraro_controller.go
+++ b/pkg/operator/controllers/clusteroperatoraro/clusteroperatoraro_controller.go
@@ -69,6 +69,7 @@ func (r *Reconciler) SetupWithManager(mgr ctrl.Manager) error {
 }
 
 func (r *Reconciler) Reconcile(ctx context.Context, request ctrl.Request) (ctrl.Result, error) {
+	r.log.Debug("running")
 	cluster, err := r.arocli.AroV1alpha1().Clusters().Get(ctx, arov1alpha1.SingletonClusterName, metav1.GetOptions{})
 	if err != nil {
 		return reconcile.Result{}, err
diff --git a/pkg/operator/controllers/previewfeature/previewfeature_controller.go b/pkg/operator/controllers/previewfeature/previewfeature_controller.go
index 8d8f3acab..02571ca56 100644
--- a/pkg/operator/controllers/previewfeature/previewfeature_controller.go
+++ b/pkg/operator/controllers/previewfeature/previewfeature_controller.go
@@ -56,6 +56,7 @@ func NewReconciler(log *logrus.Entry, arocli aroclient.Interface, kubernetescli
 
 // Reconcile reconciles ARO preview features
 func (r *Reconciler) Reconcile(ctx context.Context, request ctrl.Request) (ctrl.Result, error) {
+	r.log.Debug("running")
 	instance, err := r.arocli.PreviewV1alpha1().PreviewFeatures().Get(ctx, aropreviewv1alpha1.SingletonPreviewFeatureName, metav1.GetOptions{})
 	if err != nil {
 		return reconcile.Result{}, err


Test patch:
diff --git a/pkg/frontend/clustermanager_putorpatch_test.go b/pkg/frontend/clustermanager_putorpatch_test.go
index 374e04ef1..2c9aada47 100644
--- a/pkg/frontend/clustermanager_putorpatch_test.go
+++ b/pkg/frontend/clustermanager_putorpatch_test.go
@@ -6,6 +6,7 @@ import (
 	"net/http"
 	"strings"
 	"testing"
+	"time"
 
 	"github.com/Azure/ARO-RP/pkg/api"
 	v20220904 "github.com/Azure/ARO-RP/pkg/api/v20220904"
@@ -226,3 +227,82 @@ func TestPutOrPatchClusterManagerConfiguration(t *testing.T) {
 		})
 	}
 }
+
+var populatedSystemData = api.SystemData{
+	LastModifiedAt:     &time.Time{},
+	LastModifiedBy:     "test-user",
+	LastModifiedByType: api.CreatedByTypeUser,
+	CreatedAt:          &time.Time{},
+	CreatedBy:          "test-user",
+	CreatedByType:      api.CreatedByTypeUser,
+}
+
+func TestEnrichSyncSetSystemData(t *testing.T) {
+	doc := api.ClusterManagerConfigurationDocument{
+		SyncSet: &api.SyncSet{},
+	}
+
+	enrichSyncSetSystemData(&doc, &populatedSystemData)
+
+	if err := compareSystemData(*doc.SyncSet.SystemData, populatedSystemData); err != nil {
+		t.Fatal(err)
+	}
+}
+
+func TestEnrichSyncIdentityProviderSystemData(t *testing.T) {
+	doc := api.ClusterManagerConfigurationDocument{
+		SyncIdentityProvider: &api.SyncIdentityProvider{},
+	}
+
+	enrichSyncIdentityProviderSystemData(&doc, &populatedSystemData)
+
+	if err := compareSystemData(*doc.SyncIdentityProvider.SystemData, populatedSystemData); err != nil {
+		t.Fatal(err)
+	}
+}
+
+func TestEnrichMachinePoolSystemData(t *testing.T) {
+	doc := api.ClusterManagerConfigurationDocument{
+		MachinePool: &api.MachinePool{},
+	}
+
+	enrichMachinePoolSystemData(&doc, &populatedSystemData)
+
+	if err := compareSystemData(*doc.MachinePool.SystemData, populatedSystemData); err != nil {
+		t.Fatal(err)
+	}
+}
+
+func TestEnrichSecretSystemData(t *testing.T) {
+	doc := api.ClusterManagerConfigurationDocument{
+		Secret: &api.Secret{},
+	}
+
+	enrichSecretSystemData(&doc, &populatedSystemData)
+
+	if err := compareSystemData(*doc.Secret.SystemData, populatedSystemData); err != nil {
+		t.Fatal(err)
+	}
+}
+
+func compareSystemData(docSystemData, expectedSystemData api.SystemData) error {
+	if docSystemData.CreatedAt == nil || docSystemData.CreatedAt != expectedSystemData.CreatedAt {
+		return fmt.Errorf("CreatedAt was %q expected %q", docSystemData.CreatedAt, expectedSystemData.CreatedAt)
+	}
+	if docSystemData.CreatedBy == "" || docSystemData.CreatedBy != expectedSystemData.CreatedBy {
+		return fmt.Errorf("CreatedBy was %q expected %q", docSystemData.CreatedBy, expectedSystemData.CreatedBy)
+	}
+	if docSystemData.CreatedByType == "" || docSystemData.CreatedByType != expectedSystemData.CreatedByType {
+		return fmt.Errorf("CreatedByType was %q expected %q", docSystemData.CreatedByType, expectedSystemData.CreatedByType)
+	}
+	if docSystemData.LastModifiedAt == nil || docSystemData.LastModifiedAt != expectedSystemData.LastModifiedAt {
+		return fmt.Errorf("LastModifiedAt was %q expected %q", docSystemData.LastModifiedAt, expectedSystemData.LastModifiedAt)
+	}
+	if docSystemData.LastModifiedBy == "" || docSystemData.LastModifiedBy != expectedSystemData.LastModifiedBy {
+		return fmt.Errorf("LastModifiedBy was %q expected %q", docSystemData.LastModifiedBy, expectedSystemData.LastModifiedBy)
+	}
+	if docSystemData.LastModifiedByType == "" || docSystemData.LastModifiedByType != expectedSystemData.LastModifiedByType {
+		return fmt.Errorf("LastModifiedByType was %q expected %q", docSystemData.LastModifiedByType, expectedSystemData.LastModifiedByType)
+	}
+	return nil
+}