Merge pull request #745 from dmage/precheck

Bug 2048186: Fix panic in finalizer handler

Author: openshift-merge-robot

.gitignore

@@ -4,7 +4,6 @@
 tmp/_output
 tmp/_test
 deploy/test
-cluster-image-registry-operator
 
 #idea dev tools
 .idea/

pkg/operator/controller.go

@@ -278,7 +278,7 @@ func (c *Controller) sync() error {
 	}
 	c.syncStatus(cr, deploy, routes, applyError)
 
-	metadataChanged := strategy.Metadata(&prevCR.ObjectMeta, &cr.ObjectMeta)
+	metadataChanged := strategy.Metadata(prevCR.ObjectMeta.DeepCopy(), &cr.ObjectMeta)
 	specChanged := !reflect.DeepEqual(prevCR.Spec, cr.Spec)
 	if metadataChanged || specChanged {
 		difference, err := object.DiffString(prevCR, cr)
@@ -299,7 +299,12 @@ func (c *Controller) sync() error {
 				updatedCR.ObjectMeta = cr.ObjectMeta
 			}
 			if specChanged {
+				// FIXME: Here be dragons. The operator can
+				// accidentally lose user-provided
+				// configuration.
+				managementState := updatedCR.Spec.ManagementState
 				updatedCR.Spec = cr.Spec
+				updatedCR.Spec.ManagementState = managementState
 			}
 
 			updatedCR, err = c.clients.RegOp.ImageregistryV1().Configs().Update(
@@ -313,6 +318,10 @@ func (c *Controller) sync() error {
 		// If we updated the Status field too, we'll make one more call and we
 		// want it to succeed.
 		cr.ResourceVersion = updatedCR.ResourceVersion
+
+		// Update prevCR to make diff accurate.
+		prevCR.ObjectMeta = updatedCR.ObjectMeta
+		prevCR.Spec = updatedCR.Spec
 	}
 
 	cr.Status.ObservedGeneration = cr.Generation

pkg/operator/finalizer.go

@@ -57,7 +57,7 @@ func (c *Controller) finalizeResources(o *imageregistryv1.Config) error {
 		if cr == nil {
 			// Skip using the cache here so we don't have as many
 			// retries due to slow cache updates
-			cr, err := client.Configs().Get(
+			cr, err = client.Configs().Get(
 				context.TODO(), o.Name, metav1.GetOptions{},
 			)
 			if err != nil {

test/e2e/aws_test.go

@@ -760,12 +760,6 @@ func TestAWSFinalizerDeleteS3Bucket(t *testing.T) {
 	if exists {
 		t.Errorf("s3 bucket should have been deleted, but it wasn't: %s", err)
 	}
-
-	// Once the config object is deleted, the operator will create a new one.
-	// The testing framework does not expect creation of a new config object
-	// when it is in the teardown stage, so let's wait until the operator
-	// stabilizes again.
-	framework.WaitUntilImageRegistryIsAvailable(te)
 }
 
 // createAWSConfigFile creates an AWS credentials config based on the contents of the Secret

test/framework/clusteroperators.go

@@ -34,7 +34,7 @@ func AreClusterOperatorsHealthy(cos []configv1.ClusterOperator) error {
 	return utilerrors.NewAggregate(errs)
 }
 
-func EnsureClusterOperatorsAreHealthy(te TestEnv, interval, timeout time.Duration) {
+func WaitUntilClusterOperatorsAreHealthy(te TestEnv, interval, timeout time.Duration) {
 	ctx := context.Background()
 	start := time.Now()
 	var lastErr error

test/framework/imageregistry.go

@@ -10,6 +10,7 @@ import (
 	appsv1 "k8s.io/api/apps/v1"
 	"k8s.io/apimachinery/pkg/api/errors"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
+	"k8s.io/apimachinery/pkg/labels"
 	"k8s.io/apimachinery/pkg/types"
 	"k8s.io/apimachinery/pkg/util/wait"
 	"k8s.io/client-go/util/retry"
@@ -88,36 +89,84 @@ func (c ImageRegistryConditions) String() string {
 	)
 }
 
-func ensureImageRegistryToBeRemoved(te TestEnv) {
+func removeImageRegistry(te TestEnv) {
+	te.Logf("uninstalling the image registry...")
+
+	operatorDeployment, err := te.Client().Deployments(OperatorDeploymentNamespace).Get(
+		context.Background(), OperatorDeploymentName, metav1.GetOptions{},
+	)
+	if err != nil {
+		te.Fatalf("unable to get the operator deployment: %s", err)
+	}
+
+	if !isDeploymentRolledOut(operatorDeployment) {
+		te.Errorf("unexepected state: the operator is not rolled out before removing the image registry")
+	}
+
+	if operatorDeployment.Spec.Replicas != nil && *operatorDeployment.Spec.Replicas == 0 {
+		config, err := te.Client().Configs().Get(
+			context.Background(), defaults.ImageRegistryResourceName, metav1.GetOptions{},
+		)
+		if errors.IsNotFound(err) {
+			return
+		} else if err != nil {
+			te.Fatalf("unable to get the image registry config: %s", err)
+		}
+		conds := GetImageRegistryConditions(config)
+		if !conds.Removed.IsTrue() {
+			te.Fatalf("unable to uninstall the image registry: the operator is shutted down, but the image registry is not removed: %s", config.Spec.ManagementState, conds)
+		}
+		return
+	}
+
+	err = wait.PollImmediate(2*time.Second, 30*time.Second, func() (stop bool, err error) {
+		cr, err := te.Client().Configs().Get(
+			context.Background(), defaults.ImageRegistryResourceName, metav1.GetOptions{},
+		)
+		if err != nil {
+			te.Logf("the image registry config is not found: %s", err)
+			return false, nil
+		}
+		if cr.DeletionTimestamp != nil {
+			te.Logf("the image registry config is being deleted: %s", cr.DeletionTimestamp)
+			return false, nil
+		}
+		return true, nil
+	})
+	if err != nil {
+		te.Fatalf("failed to wait until the operator creates the config object: %s", err)
+	}
+
 	if _, err := te.Client().Configs().Patch(
 		context.Background(),
 		defaults.ImageRegistryResourceName,
 		types.MergePatchType,
 		[]byte(`{"spec": {"managementState": "Removed"}}`),
 		metav1.PatchOptions{},
 	); err != nil {
-		if errors.IsNotFound(err) {
-			// That's not exactly what we are asked for. And few seconds later
-			// the operator may bootstrap it. However, if the operator is
-			// disabled, it means the registry is not installed and we're
-			// already in the desired state.
-			return
-		}
 		te.Fatalf("unable to uninstall the image registry: %s", err)
 	}
 
 	var cr *imageregistryapiv1.Config
-	err := wait.Poll(5*time.Second, AsyncOperationTimeout, func() (stop bool, err error) {
+	err = wait.Poll(5*time.Second, AsyncOperationTimeout, func() (stop bool, err error) {
 		cr, err = te.Client().Configs().Get(
 			context.Background(), defaults.ImageRegistryResourceName, metav1.GetOptions{},
 		)
 		if errors.IsNotFound(err) {
+			te.Logf("waiting for the registry to be removed: the config object does not exist?!")
 			cr = nil
 			return true, nil
 		} else if err != nil {
+			te.Logf("waiting for the registry to be removed: %s", err)
 			return false, err
 		}
 
+		if cr.Spec.ManagementState != "Removed" {
+			DumpYAML(te, "unexpected management state in the config object", cr)
+			DumpOperatorLogs(te)
+			te.Fatalf("unexpected management state: got %s, want Removed", cr.Spec.ManagementState)
+		}
+
 		conds := GetImageRegistryConditions(cr)
 		te.Logf("waiting for the registry to be removed: %s", conds)
 		return conds.Progressing.IsFalse() && conds.Removed.IsTrue(), nil
@@ -130,6 +179,7 @@ func ensureImageRegistryToBeRemoved(te TestEnv) {
 }
 
 func deleteImageRegistryConfig(te TestEnv) {
+	te.Logf("deleting the image registry config...")
 	// TODO(dmage): the finalizer should be removed by the operator
 	if err := retry.RetryOnConflict(retry.DefaultBackoff, func() error {
 		cr, err := te.Client().Configs().Get(
@@ -165,6 +215,19 @@ func deleteImageRegistryConfig(te TestEnv) {
 	}
 }
 
+func deleteLeaderElectionConfigMap(te TestEnv, name string) {
+	err := te.Client().ConfigMaps(OperatorDeploymentNamespace).Delete(
+		context.Background(),
+		name,
+		metav1.DeleteOptions{},
+	)
+	if err == nil {
+		te.Logf("leader election configmap %s deleted", name)
+	} else if !errors.IsNotFound(err) {
+		te.Errorf("unable to delete leader election configmap %s: %s", name, err)
+	}
+}
+
 func deleteNodeCADaemonSet(te TestEnv) {
 	ds, err := te.Client().DaemonSets(defaults.ImageRegistryOperatorNamespace).Get(
 		context.Background(),
@@ -224,18 +287,16 @@ func deleteImageRegistryCertificates(te TestEnv) {
 }
 
 func deleteImageRegistryAlwaysPresentResources(te TestEnv) {
+	te.Logf("deleting always-present resources...")
 	defer deleteImageRegistryCertificates(te)
 	defer deleteNodeCADaemonSet(te)
+	defer deleteLeaderElectionConfigMap(te, "openshift-master-controllers")
 }
 
 func RemoveImageRegistry(te TestEnv) {
-	te.Logf("uninstalling the image registry...")
-	ensureImageRegistryToBeRemoved(te)
-	te.Logf("stopping the operator...")
+	removeImageRegistry(te)
 	StopDeployment(te, OperatorDeploymentNamespace, OperatorDeploymentName)
-	te.Logf("deleting the image registry config...")
 	deleteImageRegistryConfig(te)
-	te.Logf("deleting always-present resources...")
 	deleteImageRegistryAlwaysPresentResources(te)
 }
 
@@ -255,7 +316,6 @@ func DeployImageRegistry(te TestEnv, spec *imageregistryapiv1.ImageRegistrySpec)
 		}
 	}
 
-	te.Logf("starting the operator...")
 	startOperator(te)
 }
 
@@ -505,10 +565,10 @@ func SetupAvailableImageRegistry(t *testing.T, spec *imageregistryapiv1.ImageReg
 }
 
 func TeardownImageRegistry(te TestEnv) {
-	defer func() {
-		RemoveImageRegistry(te)
-		EnsureClusterOperatorsAreHealthy(te, 10*time.Second, AsyncOperationTimeout)
-	}()
+	defer WaitUntilClusterOperatorsAreHealthy(te, 10*time.Second, AsyncOperationTimeout)
+	defer CheckAbsenceOfOperatorPods(te)
+	defer RemoveImageRegistry(te)
+	defer CheckPodsAreNotRestarted(te, labels.Everything())
 	if te.Failed() {
 		DumpImageRegistryResource(te)
 		DumpOperatorDeployment(te)

test/framework/logs.go

@@ -6,6 +6,7 @@ import (
 	"fmt"
 	"io"
 	"regexp"
+	"strings"
 
 	corev1 "k8s.io/api/core/v1"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
@@ -44,7 +45,7 @@ func (psl PodSetLogs) Contains(re *regexp.Regexp) bool {
 	return false
 }
 
-func GetLogsByLabelSelector(client *Clientset, namespace string, labelSelector *metav1.LabelSelector) (PodSetLogs, error) {
+func GetLogsByLabelSelector(client *Clientset, namespace string, labelSelector *metav1.LabelSelector, previous bool) (PodSetLogs, error) {
 	selector, err := metav1.LabelSelectorAsSelector(labelSelector)
 	if err != nil {
 		return nil, err
@@ -61,7 +62,7 @@ func GetLogsByLabelSelector(client *Clientset, namespace string, labelSelector *
 
 	podLogs := make(PodSetLogs)
 	for _, pod := range podList.Items {
-		podLog, err := readPodLogs(client, &pod)
+		podLog, err := readPodLogs(client, &pod, previous)
 		if err != nil {
 			return nil, err
 		}
@@ -76,7 +77,7 @@ func GetLogsForPod(client *Clientset, namespace string, podName string) (PodSetL
 	if err != nil {
 		return nil, err
 	}
-	podLogs, err := readPodLogs(client, pod)
+	podLogs, err := readPodLogs(client, pod, false)
 	if err != nil {
 		return nil, err
 	}
@@ -85,12 +86,13 @@ func GetLogsForPod(client *Clientset, namespace string, podName string) (PodSetL
 	return podSetLogs, nil
 }
 
-func readPodLogs(client *Clientset, pod *corev1.Pod) (PodLog, error) {
+func readPodLogs(client *Clientset, pod *corev1.Pod, previous bool) (PodLog, error) {
 	podLog := make(PodLog)
 	for _, container := range pod.Spec.Containers {
 		var containerLog ContainerLog
 		log, err := client.Pods(pod.Namespace).GetLogs(pod.Name, &corev1.PodLogOptions{
 			Container: container.Name,
+			Previous:  previous,
 		}).Stream(context.Background())
 		if err != nil {
 			return nil, fmt.Errorf("failed to get logs for pod %s: %s", pod.Name, err)
@@ -114,13 +116,16 @@ func readPodLogs(client *Clientset, pod *corev1.Pod) (PodLog, error) {
 
 func DumpPodLogs(logger Logger, podLogs PodSetLogs) {
 	if len(podLogs) > 0 {
-		for pod, logs := range podLogs {
-			logger.Logf("=== logs for pod/%s", pod)
-			for _, line := range logs {
-				logger.Logf("%s", line)
+		for pod, containers := range podLogs {
+			for container, logs := range containers {
+				var buf strings.Builder
+				fmt.Fprintf(&buf, "logs for pod/%s (container %s)\n", pod, container)
+				for _, line := range logs {
+					fmt.Fprintf(&buf, "%s", line)
+				}
+				logger.Logf("%s", buf.String())
 			}
 		}
-		logger.Logf("=== end of logs")
 	}
 }
 

test/framework/operator.go

@@ -2,6 +2,7 @@ package framework
 
 import (
 	"context"
+	"strings"
 	"time"
 
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
@@ -10,6 +11,7 @@ import (
 )
 
 func startOperator(te TestEnv) {
+	te.Logf("starting the operator...")
 	if _, err := te.Client().Deployments(OperatorDeploymentNamespace).Patch(
 		context.Background(),
 		OperatorDeploymentName,
@@ -32,7 +34,25 @@ func DumpOperatorDeployment(te TestEnv) {
 	DumpYAML(te, "the operator deployment", deployment)
 }
 
+func CheckAbsenceOfOperatorPods(te TestEnv) {
+	pods, err := te.Client().Pods(OperatorDeploymentNamespace).List(context.Background(), metav1.ListOptions{})
+	if err != nil {
+		te.Fatalf("failed to list the pods: %s", err)
+	}
+	i := 0
+	for _, pod := range pods.Items {
+		if strings.HasPrefix(pod.Name, OperatorDeploymentName+"-") {
+			te.Errorf("unexpected operator pod %s (%s old)", pod.Name, time.Since(pod.CreationTimestamp.Time))
+			i++
+		}
+	}
+	if i > 0 {
+		te.Fatalf("found %d unexpected operator pod(s)", i)
+	}
+}
+
 func StopDeployment(te TestEnv, namespace, name string) {
+	te.Logf("scaling down the deployment %s/%s...", namespace, name)
 	var realErr error
 	err := wait.Poll(1*time.Second, 30*time.Second, func() (bool, error) {
 		if _, realErr = te.Client().Deployments(namespace).Patch(
@@ -59,7 +79,7 @@ func GetOperatorLogs(client *Clientset) (PodSetLogs, error) {
 		MatchLabels: map[string]string{
 			"name": "cluster-image-registry-operator",
 		},
-	})
+	}, false)
 }
 
 func DumpOperatorLogs(te TestEnv) {