From bfbbec158f13f65795868fecc2c50ebb540c337b Mon Sep 17 00:00:00 2001 From: Mario Manno Date: Tue, 2 Mar 2021 11:47:35 +0100 Subject: [PATCH] Improve error messages * indicate waiting loop * remove stack trace from log message when waiting * better indicate timeout vs error --- go.sum | 3 +++ .../quarks_statefulset_active_passive_test.go | 16 ++++++++-------- .../active_passive_reconciler.go | 2 +- .../quarksstatefulset_reconciler.go | 7 ++++++- .../statefulset_rollout_reconciler.go | 4 ++-- 5 files changed, 20 insertions(+), 12 deletions(-) diff --git a/go.sum b/go.sum index 44e669de..3d0d0e61 100644 --- a/go.sum +++ b/go.sum @@ -784,17 +784,20 @@ honnef.co/go/tools v0.0.1-2020.1.3/go.mod h1:X/FiERA/W4tHapMX5mGpAtMSVEeEUOyHaw9 k8s.io/api v0.20.1/go.mod h1:KqwcCVogGxQY3nBlRpwt+wpAMF/KjaCc7RpywacvqUo= k8s.io/api v0.20.2 h1:y/HR22XDZY3pniu9hIFDLpUCPq2w5eQ6aV/VFQ7uJMw= k8s.io/api v0.20.2/go.mod h1:d7n6Ehyzx+S+cE3VhTGfVNNqtGc/oL9DCdYYahlurV8= +k8s.io/api v0.20.4 h1:xZjKidCirayzX6tHONRQyTNDVIR55TYVqgATqo6ZULY= k8s.io/api v0.20.4/go.mod h1:++lNL1AJMkDymriNniQsWRkMDzRaX2Y/POTUi8yvqYQ= k8s.io/apiextensions-apiserver v0.20.1 h1:ZrXQeslal+6zKM/HjDXLzThlz/vPSxrfK3OqL8txgVQ= k8s.io/apiextensions-apiserver v0.20.1/go.mod h1:ntnrZV+6a3dB504qwC5PN/Yg9PBiDNt1EVqbW2kORVk= k8s.io/apimachinery v0.20.1/go.mod h1:WlLqWAHZGg07AeltaI0MV5uk1Omp8xaN0JGLY6gkRpU= k8s.io/apimachinery v0.20.2 h1:hFx6Sbt1oG0n6DZ+g4bFt5f6BoMkOjKWsQFu077M3Vg= k8s.io/apimachinery v0.20.2/go.mod h1:WlLqWAHZGg07AeltaI0MV5uk1Omp8xaN0JGLY6gkRpU= +k8s.io/apimachinery v0.20.4 h1:vhxQ0PPUUU2Ns1b9r4/UFp13UPs8cw2iOoTjnY9faa0= k8s.io/apimachinery v0.20.4/go.mod h1:WlLqWAHZGg07AeltaI0MV5uk1Omp8xaN0JGLY6gkRpU= k8s.io/apiserver v0.20.1/go.mod h1:ro5QHeQkgMS7ZGpvf4tSMx6bBOgPfE+f52KwvXfScaU= k8s.io/client-go v0.20.1/go.mod h1:/zcHdt1TeWSd5HoUe6elJmHSQ6uLLgp4bIJHVEuy+/Y= k8s.io/client-go v0.20.2 h1:uuf+iIAbfnCSw8IGAv/Rg0giM+2bOzHLOsbbrwrdhNQ= k8s.io/client-go v0.20.2/go.mod h1:kH5brqWqp7HDxUFKoEgiI4v8G1xzbe9giaCenUWJzgE= +k8s.io/client-go v0.20.4 h1:85crgh1IotNkLpKYKZHVNI1JT86nr/iDCvq2iWKsql4= k8s.io/client-go v0.20.4/go.mod h1:LiMv25ND1gLUdBeYxBIwKpkSC5IsozMMmOOeSJboP+k= k8s.io/code-generator v0.20.1 h1:kre3GNich5gbO3d1FyTT8fHI4ZJezZV217yFdWlQaRQ= k8s.io/code-generator v0.20.1/go.mod h1:UsqdF+VX4PU2g46NC2JRs4gc+IfrctnwHb76RNbWHJg= diff --git a/integration/quarks_statefulset_active_passive_test.go b/integration/quarks_statefulset_active_passive_test.go index ae0efe80..65376722 100644 --- a/integration/quarks_statefulset_active_passive_test.go +++ b/integration/quarks_statefulset_active_passive_test.go @@ -41,7 +41,7 @@ var _ = Describe("QuarksStatefulSetActivePassive", func() { // Expect(env.WaitForPVCsDelete(env.Namespace)).To(Succeed()) }) - Context("when pod-active label is not present and probe passes", func() { + When("pod-active label is not present and probe passes", func() { sleepCMD := []string{"/bin/sh", "-c", "sleep 2"} It("should label a single pod out of one", func() { By("Creating a QuarksStatefulSet with a valid CRD probe cmd") @@ -65,7 +65,7 @@ var _ = Describe("QuarksStatefulSetActivePassive", func() { }) }) - Context("when pod-active label is present in one pod and probe fails", func() { + When("pod-active label is present in one pod and probe fails", func() { cmdSleepTypo := []string{"/bin/sh", "-c", "sleeps 2"} @@ -98,7 +98,7 @@ var _ = Describe("QuarksStatefulSetActivePassive", func() { }) }) - Context("when pod-active label is present in multiple pods and only one probe pass", func() { + When("pod-active label is present in multiple pods and only one probe pass", func() { // two set of cmds, one that runs as the CRD probe // the second one, runs as a patch, so that the next CRD probe executiong will pass cmdCatScript := []string{"/bin/sh", "-c", "cat /tmp/busybox-script.sh"} @@ -160,7 +160,7 @@ var _ = Describe("QuarksStatefulSetActivePassive", func() { }) }) - Context("when active passive pod fails a new one becomes active", func() { + When("active passive pod fails a new one becomes active", func() { cmdCatScript := []string{"/bin/sh", "-c", "cat /tmp/busybox-script.sh"} cmdTouchScript := []string{"/bin/sh", "-c", "touch /tmp/busybox-script.sh"} containerName := "busybox" @@ -242,7 +242,7 @@ var _ = Describe("QuarksStatefulSetActivePassive", func() { }) }) - Context("when multiple pods pass the probe multiple remain active", func() { + When("multiple pods pass the probe multiple remain active", func() { cmdCatScript := []string{"/bin/sh", "-c", "cat /tmp/busybox-script.sh"} cmdTouchScript := []string{"/bin/sh", "-c", "touch /tmp/busybox-script.sh"} containerName := "busybox" @@ -306,7 +306,7 @@ var _ = Describe("QuarksStatefulSetActivePassive", func() { }) }) - Context("when CRD does not specify a probe periodSeconds", func() { + When("CRD does not specify a probe periodSeconds", func() { cmdDate := []string{"/bin/sh", "-c", "date"} It("should ensure the proper event takes place", func() { By("Creating a QuarksStatefulSet with pods that contain a probe that will initially fail") @@ -326,14 +326,14 @@ var _ = Describe("QuarksStatefulSetActivePassive", func() { objectName, objectUID, eventReason, - "periodSeconds probe was not specified, going to default to 30 secs", + fmt.Sprintf("Requeue probe for '%s/%s' in 30s", env.Namespace, qStsName), ) }) Expect(err).NotTo(HaveOccurred()) }) }) - Context("when QuarksStatefulSet cross AZs", func() { + When("QuarksStatefulSet cross AZs", func() { sleepCMD := []string{"/bin/sh", "-c", "sleep 2"} zones := []string{"z0", "z1"} It("should validate all pods cross AZs", func() { diff --git a/pkg/kube/controllers/quarksstatefulset/active_passive_reconciler.go b/pkg/kube/controllers/quarksstatefulset/active_passive_reconciler.go index 2fe7b83b..a69720e8 100644 --- a/pkg/kube/controllers/quarksstatefulset/active_passive_reconciler.go +++ b/pkg/kube/controllers/quarksstatefulset/active_passive_reconciler.go @@ -107,11 +107,11 @@ func (r *ReconcileStatefulSetActivePassive) Reconcile(_ context.Context, request ps := time.Second * time.Duration(qSts.Spec.ActivePassiveProbes[containerName].PeriodSeconds) if ps == (time.Second * time.Duration(0)) { - ctxlog.WithEvent(qSts, "active-passive").Debugf(ctx, "periodSeconds probe was not specified, going to default to 30 secs") ps = time.Second * 30 } // Reconcile for any reason than error after the ActivePassiveProbe PeriodSeconds + ctxlog.WithEvent(qSts, "active-passive").Debugf(ctx, "Requeue probe for '%s' in %s", request.NamespacedName, ps) return reconcile.Result{RequeueAfter: ps}, nil } diff --git a/pkg/kube/controllers/quarksstatefulset/quarksstatefulset_reconciler.go b/pkg/kube/controllers/quarksstatefulset/quarksstatefulset_reconciler.go index 052dccef..0403abc7 100644 --- a/pkg/kube/controllers/quarksstatefulset/quarksstatefulset_reconciler.go +++ b/pkg/kube/controllers/quarksstatefulset/quarksstatefulset_reconciler.go @@ -106,7 +106,12 @@ func (r *ReconcileQuarksStatefulSet) Reconcile(_ context.Context, request reconc // Update labels of versioned secrets in quarksStatefulSet spec err = r.UpdateVersions(ctx, qStatefulSet) if err != nil { - return reconcile.Result{}, ctxlog.WithEvent(qStatefulSet, "IncrementVersionError").Error(ctx, "Could not update labels of versioned secrets in QuarksStatefulSet '", request.NamespacedName, "': ", err) + if apierrors.IsNotFound(err) { + ctxlog.Infof(ctx, "Requeue, waiting for secret: '%s'", err) + return reconcile.Result{RequeueAfter: ReconcileSkipDuration}, nil + } + _ = ctxlog.WithEvent(qStatefulSet, "IncrementVersionError").Error(ctx, "Could not update labels of versioned secrets in QuarksStatefulSet '", request.NamespacedName, "': ", err) + return reconcile.Result{}, err } if qStatefulSet.Status.LastReconcile == nil { diff --git a/pkg/kube/controllers/statefulset/statefulset_rollout_reconciler.go b/pkg/kube/controllers/statefulset/statefulset_rollout_reconciler.go index 573a9533..404a0101 100644 --- a/pkg/kube/controllers/statefulset/statefulset_rollout_reconciler.go +++ b/pkg/kube/controllers/statefulset/statefulset_rollout_reconciler.go @@ -100,7 +100,7 @@ func (r *ReconcileStatefulSetRollout) Reconcile(_ context.Context, request recon } if timedOut, err := r.failIfTimedOut(ctx, statefulSet, AnnotationUpdateWatchTime); timedOut || err != nil { - ctxlog.Errorf(ctx, "Error updating StatefulSet '%s' after timeout: %s", request.NamespacedName, err) + ctxlog.Errorf(ctx, "Error updating StatefulSet '%s' after timeout, err: %v", request.NamespacedName, err) return reconcile.Result{}, err } @@ -162,7 +162,7 @@ func (r *ReconcileStatefulSetRollout) Reconcile(_ context.Context, request recon } } statusChanged := newStatus != statefulSet.Annotations[AnnotationCanaryRollout] - ctxlog.Debugf(ctx, "Statefulset rollout for '%s/%s' is in status %s", statefulSet.Namespace, statefulSet.Name, newStatus) + ctxlog.Infof(ctx, "Statefulset rollout for '%s/%s' is in status %s", statefulSet.Namespace, statefulSet.Name, newStatus) if statusChanged { statefulSet.Annotations[AnnotationCanaryRollout] = newStatus dirty = true