Fix panic in finalizer handler

Author: dmage

.gitignore

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

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/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,7 +89,8 @@ func (c ImageRegistryConditions) String() string {
 	)
 }
 
-func ensureImageRegistryToBeRemoved(te TestEnv) {
+func removeImageRegistry(te TestEnv) {
+	te.Logf("uninstalling the image registry...")
 	if _, err := te.Client().Configs().Patch(
 		context.Background(),
 		defaults.ImageRegistryResourceName,
@@ -130,6 +132,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 +168,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 +240,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 +269,6 @@ func DeployImageRegistry(te TestEnv, spec *imageregistryapiv1.ImageRegistrySpec)
 		}
 	}
 
-	te.Logf("starting the operator...")
 	startOperator(te)
 }
 
@@ -505,10 +518,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) {

test/framework/pods.go

@@ -0,0 +1,32 @@
+package framework
+
+import (
+	"context"
+
+	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
+	"k8s.io/apimachinery/pkg/labels"
+)
+
+func CheckPodsAreNotRestarted(te TestEnv, labels labels.Selector) {
+	pods, err := te.Client().Pods(OperatorDeploymentNamespace).List(
+		context.Background(),
+		metav1.ListOptions{
+			LabelSelector: labels.String(),
+		},
+	)
+	if err != nil {
+		te.Fatalf("failed to list pods: %s", err)
+	}
+	for _, pod := range pods.Items {
+		for _, container := range pod.Status.InitContainerStatuses {
+			if container.RestartCount > 0 {
+				te.Errorf("pod %s/%s: init container %s: restarted %d time(s)", pod.Namespace, pod.Name, container.Name, container.RestartCount)
+			}
+		}
+		for _, container := range pod.Status.ContainerStatuses {
+			if container.RestartCount > 0 {
+				te.Errorf("pod %s/%s: container %s: restarted %d time(s)", pod.Namespace, pod.Name, container.Name, container.RestartCount)
+			}
+		}
+	}
+}

test/framework/testenv.go

@@ -1,6 +1,9 @@
 package framework
 
-import "testing"
+import (
+	"testing"
+	"time"
+)
 
 type TestEnv interface {
 	Client() *Clientset
@@ -24,12 +27,30 @@ func Setup(t *testing.T) TestEnv {
 		t.Fatal(err)
 	}
 
-	return &testEnv{
+	te := &testEnv{
 		T:      t,
 		client: client,
 	}
+	CheckAbsenceOfOperatorPods(te)
+	return te
+}
+
+func (te *testEnv) timestamp() string {
+	return time.Now().UTC().Format("15:04:05.000")
 }
 
 func (te *testEnv) Client() *Clientset {
 	return te.client
 }
+
+func (te *testEnv) Log(a ...interface{}) {
+	te.T.Helper()
+	args := append([]interface{}{te.timestamp()}, a...)
+	te.T.Log(args...)
+}
+
+func (te *testEnv) Logf(format string, a ...interface{}) {
+	te.T.Helper()
+	args := append([]interface{}{te.timestamp()}, a...)
+	te.T.Logf("%s "+format, args...)
+}