From d6ebdda49c5346bef5d7d2206f2e28fcf7be793b Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ma=C3=ABl=20Valais?= Date: Wed, 23 Mar 2022 11:43:30 +0100 Subject: [PATCH] make/e2e.sh: add a backoff to the log.Logf when waiting for something MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Signed-off-by: Maël Valais --- .../framework/helper/certificaterequests.go | 6 ++- test/e2e/framework/helper/certificates.go | 29 +++++++----- .../helper/certificatesigningrequests.go | 4 +- test/e2e/framework/helper/pod_start.go | 8 ++-- test/e2e/framework/helper/secret.go | 6 ++- test/e2e/framework/log/BUILD.bazel | 5 ++- test/e2e/framework/log/log.go | 45 +++++++++++++++++++ .../suite/issuers/acme/certificate/http01.go | 12 +++-- .../suite/issuers/acme/certificate/webhook.go | 18 +++++--- .../issuers/acme/certificaterequest/http01.go | 6 ++- test/e2e/util/util.go | 12 +++-- 11 files changed, 116 insertions(+), 35 deletions(-) diff --git a/test/e2e/framework/helper/certificaterequests.go b/test/e2e/framework/helper/certificaterequests.go index 6774a0011..36b69fbc0 100644 --- a/test/e2e/framework/helper/certificaterequests.go +++ b/test/e2e/framework/helper/certificaterequests.go @@ -41,10 +41,12 @@ import ( // enter a Ready state. func (h *Helper) WaitForCertificateRequestReady(ns, name string, timeout time.Duration) (*cmapi.CertificateRequest, error) { var cr *cmapi.CertificateRequest + logf, done := log.LogBackoff() + defer done() err := wait.PollImmediate(time.Second, timeout, func() (bool, error) { var err error - log.Logf("Waiting for CertificateRequest %s to be ready", name) + logf("Waiting for CertificateRequest %s to be ready", name) cr, err = h.CMClient.CertmanagerV1().CertificateRequests(ns).Get(context.TODO(), name, metav1.GetOptions{}) if err != nil { return false, fmt.Errorf("error getting CertificateRequest %s: %v", name, err) @@ -54,7 +56,7 @@ func (h *Helper) WaitForCertificateRequestReady(ns, name string, timeout time.Du Status: cmmeta.ConditionTrue, }) if !isReady { - log.Logf("Expected CertificateRequest to have Ready condition 'true' but it has: %v", cr.Status.Conditions) + logf("Expected CertificateRequest to have Ready condition 'true' but it has: %v", cr.Status.Conditions) return false, nil } return true, nil diff --git a/test/e2e/framework/helper/certificates.go b/test/e2e/framework/helper/certificates.go index addd31ed6..9f69506be 100644 --- a/test/e2e/framework/helper/certificates.go +++ b/test/e2e/framework/helper/certificates.go @@ -39,8 +39,10 @@ import ( func (h *Helper) WaitForCertificateToExist(namespace string, name string, timeout time.Duration) (*cmapi.Certificate, error) { client := h.CMClient.CertmanagerV1().Certificates(namespace) var certificate *v1.Certificate + logf, done := log.LogBackoff() + defer done() pollErr := wait.PollImmediate(500*time.Millisecond, timeout, func() (bool, error) { - log.Logf("Waiting for Certificate %v to exist", name) + logf("Waiting for Certificate %v to exist", name) var err error certificate, err = client.Get(context.TODO(), name, metav1.GetOptions{}) if errors.IsNotFound(err) { @@ -100,9 +102,11 @@ func (h *Helper) WaitForCertificateReadyAndDoneIssuing(cert *cmapi.Certificate, Type: cmapi.CertificateConditionIssuing, Status: cmmeta.ConditionTrue, } + logf, done := log.LogBackoff() + defer done() return h.waitForCertificateCondition(h.CMClient.CertmanagerV1().Certificates(cert.Namespace), cert.Name, func(certificate *v1.Certificate) bool { if !apiutil.CertificateHasConditionWithObservedGeneration(certificate, ready_true_condition) { - log.Logf( + logf( "Expected Certificate %v condition %v=%v (generation >= %v) but it has: %v", certificate.Name, ready_true_condition.Type, @@ -114,12 +118,12 @@ func (h *Helper) WaitForCertificateReadyAndDoneIssuing(cert *cmapi.Certificate, } if apiutil.CertificateHasCondition(certificate, issuing_true_condition) { - log.Logf("Expected Certificate %v condition %v to be missing but it has: %v", certificate.Name, issuing_true_condition.Type, certificate.Status.Conditions) + logf("Expected Certificate %v condition %v to be missing but it has: %v", certificate.Name, issuing_true_condition.Type, certificate.Status.Conditions) return false } if certificate.Status.NextPrivateKeySecretName != nil { - log.Logf("Expected Certificate %v 'next-private-key-secret-name' attribute to be empty but has: %v", certificate.Name, *certificate.Status.NextPrivateKeySecretName) + logf("Expected Certificate %v 'next-private-key-secret-name' attribute to be empty but has: %v", certificate.Name, *certificate.Status.NextPrivateKeySecretName) return false } @@ -139,9 +143,11 @@ func (h *Helper) WaitForCertificateNotReadyAndDoneIssuing(cert *cmapi.Certificat Type: cmapi.CertificateConditionIssuing, Status: cmmeta.ConditionTrue, } + logf, done := log.LogBackoff() + defer done() return h.waitForCertificateCondition(h.CMClient.CertmanagerV1().Certificates(cert.Namespace), cert.Name, func(certificate *v1.Certificate) bool { if !apiutil.CertificateHasConditionWithObservedGeneration(certificate, ready_false_condition) { - log.Logf( + logf( "Expected Certificate %v condition %v=%v (generation >= %v) but it has: %v", certificate.Name, ready_false_condition.Type, @@ -153,12 +159,12 @@ func (h *Helper) WaitForCertificateNotReadyAndDoneIssuing(cert *cmapi.Certificat } if apiutil.CertificateHasCondition(certificate, issuing_true_condition) { - log.Logf("Expected Certificate %v condition %v to be missing but it has: %v", certificate.Name, issuing_true_condition.Type, certificate.Status.Conditions) + logf("Expected Certificate %v condition %v to be missing but it has: %v", certificate.Name, issuing_true_condition.Type, certificate.Status.Conditions) return false } if certificate.Status.NextPrivateKeySecretName != nil { - log.Logf("Expected Certificate %v 'next-private-key-secret-name' attribute to be empty but has: %v", certificate.Name, *certificate.Status.NextPrivateKeySecretName) + logf("Expected Certificate %v 'next-private-key-secret-name' attribute to be empty but has: %v", certificate.Name, *certificate.Status.NextPrivateKeySecretName) return false } @@ -196,9 +202,11 @@ func (h *Helper) WaitIssuerReady(issuer *cmapi.Issuer, timeout time.Duration) (* Status: cmmeta.ConditionTrue, } + logf, done := log.LogBackoff() + defer done() return h.waitForIssuerCondition(h.CMClient.CertmanagerV1().Issuers(issuer.Namespace), issuer.Name, func(issuer *v1.Issuer) bool { if !apiutil.IssuerHasCondition(issuer, ready_true_condition) { - log.Logf( + logf( "Expected Issuer %v condition %v=%v but it has: %v", issuer.Name, ready_true_condition.Type, @@ -240,10 +248,11 @@ func (h *Helper) WaitClusterIssuerReady(issuer *cmapi.ClusterIssuer, timeout tim Type: cmapi.IssuerConditionReady, Status: cmmeta.ConditionTrue, } - + logf, done := log.LogBackoff() + defer done() return h.waitForClusterIssuerCondition(h.CMClient.CertmanagerV1().ClusterIssuers(), issuer.Name, func(issuer *v1.ClusterIssuer) bool { if !apiutil.IssuerHasCondition(issuer, ready_true_condition) { - log.Logf( + logf( "Expected Cluster Issuer %v condition %v=%v but it has: %v", issuer.Name, ready_true_condition.Type, diff --git a/test/e2e/framework/helper/certificatesigningrequests.go b/test/e2e/framework/helper/certificatesigningrequests.go index 9da862e12..17f67fd4f 100644 --- a/test/e2e/framework/helper/certificatesigningrequests.go +++ b/test/e2e/framework/helper/certificatesigningrequests.go @@ -33,10 +33,12 @@ import ( // CertificateSigningRequest resource to be signed. func (h *Helper) WaitForCertificateSigningRequestSigned(name string, timeout time.Duration) (*certificatesv1.CertificateSigningRequest, error) { var csr *certificatesv1.CertificateSigningRequest + logf, done := log.LogBackoff() + defer done() err := wait.PollImmediate(time.Second, timeout, func() (bool, error) { var err error - log.Logf("Waiting for CertificateSigningRequest %s to be ready", name) + logf("Waiting for CertificateSigningRequest %s to be ready", name) csr, err = h.KubeClient.CertificatesV1().CertificateSigningRequests().Get(context.TODO(), name, metav1.GetOptions{}) if err != nil { return false, fmt.Errorf("error getting CertificateSigningRequest %s: %v", name, err) diff --git a/test/e2e/framework/helper/pod_start.go b/test/e2e/framework/helper/pod_start.go index 203d5579e..78cd49316 100644 --- a/test/e2e/framework/helper/pod_start.go +++ b/test/e2e/framework/helper/pod_start.go @@ -45,6 +45,8 @@ func (h *Helper) WaitForAllPodsRunningInNamespace(ns string) error { func (h *Helper) WaitForAllPodsRunningInNamespaceTimeout(ns string, timeout time.Duration) error { ginkgo.By("Waiting " + timeout.String() + " for all pods in namespace '" + ns + "' to be Ready") + logf, done := log.LogBackoff() + defer done() return wait.PollImmediate(Poll, timeout, func() (bool, error) { pods, err := h.KubeClient.CoreV1().Pods(ns).List(context.TODO(), metav1.ListOptions{}) if err != nil { @@ -52,7 +54,7 @@ func (h *Helper) WaitForAllPodsRunningInNamespaceTimeout(ns string, timeout time } if len(pods.Items) == 0 { - log.Logf("No pods found in namespace %s - checking again...") + logf("No pods found in namespace %s - checking again...") return false, nil } @@ -64,7 +66,7 @@ func (h *Helper) WaitForAllPodsRunningInNamespaceTimeout(ns string, timeout time continue } if c.Reason == "PodCompleted" { - log.Logf("Pod %q has Completed, assuming it is ready/expected", p.Name) + logf("Pod %q has Completed, assuming it is ready/expected", p.Name) continue } // This pod does not have the ready condition set to True @@ -75,7 +77,7 @@ func (h *Helper) WaitForAllPodsRunningInNamespaceTimeout(ns string, timeout time if len(errs) > 0 { for _, err := range errs { - log.Logf(err) + logf(err) } return false, nil } diff --git a/test/e2e/framework/helper/secret.go b/test/e2e/framework/helper/secret.go index 2989b1459..9bc327edd 100644 --- a/test/e2e/framework/helper/secret.go +++ b/test/e2e/framework/helper/secret.go @@ -32,10 +32,12 @@ import ( // inside a Secret created by cert-manager. func (h *Helper) WaitForSecretCertificateData(ns, name string, timeout time.Duration) (*corev1.Secret, error) { var secret *corev1.Secret + logf, done := log.LogBackoff() + defer done() err := wait.PollImmediate(time.Second, timeout, func() (bool, error) { var err error - log.Logf("Waiting for Secret %s:%s to contain a certificate", ns, name) + logf("Waiting for Secret %s:%s to contain a certificate", ns, name) secret, err = h.KubeClient.CoreV1().Secrets(ns).Get(context.TODO(), name, metav1.GetOptions{}) if err != nil { return false, fmt.Errorf("error getting secret %s: %s", name, err) @@ -45,7 +47,7 @@ func (h *Helper) WaitForSecretCertificateData(ns, name string, timeout time.Dura return true, nil } - log.Logf("Secret still does not contain certificate data %s/%s", + logf("Secret still does not contain certificate data %s/%s", secret.Namespace, secret.Name) return false, nil }, diff --git a/test/e2e/framework/log/BUILD.bazel b/test/e2e/framework/log/BUILD.bazel index 7e80cfff1..27f7af161 100644 --- a/test/e2e/framework/log/BUILD.bazel +++ b/test/e2e/framework/log/BUILD.bazel @@ -6,7 +6,10 @@ go_library( importpath = "github.com/cert-manager/cert-manager/test/e2e/framework/log", tags = ["manual"], visibility = ["//visibility:public"], - deps = ["@com_github_onsi_ginkgo//:go_default_library"], + deps = [ + "@com_github_onsi_ginkgo//:go_default_library", + "@io_k8s_apimachinery//pkg/util/wait:go_default_library", + ], ) filegroup( diff --git a/test/e2e/framework/log/log.go b/test/e2e/framework/log/log.go index 0fc522a33..317e9de0c 100644 --- a/test/e2e/framework/log/log.go +++ b/test/e2e/framework/log/log.go @@ -18,9 +18,11 @@ package log import ( "fmt" + "sync" "time" "github.com/onsi/ginkgo" + "k8s.io/apimachinery/pkg/util/wait" ) var Writer = ginkgo.GinkgoWriter @@ -36,3 +38,46 @@ func log(level string, format string, args ...interface{}) { func Logf(format string, args ...interface{}) { log("INFO", format, args...) } + +// LogBackoff gives you a logger with an exponential backoff. If the +// returned 'logf' func is called too often, the logf calls get ignored +// until the backoff expires. +// +// The reason we use this backoff mechanism is that we have many "waiting +// loops" that poll every 0.5 seconds. We don't want to use a higher +// polling interval since it would slow the test. +// +// The first log line is immediately printed, and the last message is +// always printed even if the backoff isn't done. That's because the first +// and last messages are often helpful to understand how things went. +func LogBackoff() (logf func(format string, args ...interface{}), done func()) { + backoff := wait.Backoff{ + Duration: 5 * time.Second, + Factor: 1.2, + Steps: 10, + Cap: 1 * time.Minute, + } + + start := time.Now() + var msg string + done = func() { + Logf(msg + fmt.Sprintf(" (took %v)", time.Since(start).Truncate(time.Second))) + } + + once := sync.Once{} + step := time.Now() + return func(format string, args ...interface{}) { + msg = fmt.Sprintf(format, args...) + once.Do(func() { + Logf(msg) + }) + + if time.Since(step) < backoff.Duration { + return + } + + step = time.Now() + _ = backoff.Step() + Logf(msg) + }, done +} diff --git a/test/e2e/suite/issuers/acme/certificate/http01.go b/test/e2e/suite/issuers/acme/certificate/http01.go index af7f55dfe..67aa1d4e9 100644 --- a/test/e2e/suite/issuers/acme/certificate/http01.go +++ b/test/e2e/suite/issuers/acme/certificate/http01.go @@ -151,19 +151,21 @@ var _ = framework.CertManagerDescribe("ACME Certificate (HTTP01)", func() { By("Making sure the Order failed with a 400 since google.com is invalid") order := &cmacme.Order{} + logf, done := log.LogBackoff() + defer done() err = wait.PollImmediate(1*time.Second, 1*time.Minute, func() (done bool, err error) { orders, err := listOwnedOrders(f.CertManagerClientSet, cert) Expect(err).NotTo(HaveOccurred()) if len(orders) == 0 || len(orders) > 1 { - log.Logf("Waiting as one Order should exist, but we found %d", len(orders)) + logf("Waiting as one Order should exist, but we found %d", len(orders)) return false, nil } order = orders[0] expected := `400 urn:ietf:params:acme:error:rejectedIdentifier` if !strings.Contains(order.Status.Reason, expected) { - log.Logf("Waiting for Order's reason, current: %s, should contain: %s", order.Status.Reason, expected) + logf("Waiting for Order's reason, current: %s, should contain: %s", order.Status.Reason, expected) return false, nil } @@ -436,16 +438,18 @@ var _ = framework.CertManagerDescribe("ACME Certificate (HTTP01)", func() { By("killing the solver pod") podClient := f.KubeClientSet.CoreV1().Pods(f.Namespace.Name) var pod corev1.Pod + logf, done := log.LogBackoff() + defer done() err = wait.PollImmediate(1*time.Second, time.Minute, func() (bool, error) { - log.Logf("Waiting for solver pod to exist") + logf("Waiting for solver pod to exist") podlist, err := podClient.List(context.TODO(), metav1.ListOptions{}) if err != nil { return false, err } for _, p := range podlist.Items { - log.Logf("solver pod %s", p.Name) + logf("solver pod %s", p.Name) // TODO(dmo): make this cleaner instead of just going by name if strings.Contains(p.Name, "http-solver") { pod = p diff --git a/test/e2e/suite/issuers/acme/certificate/webhook.go b/test/e2e/suite/issuers/acme/certificate/webhook.go index 814791639..660cfbc04 100644 --- a/test/e2e/suite/issuers/acme/certificate/webhook.go +++ b/test/e2e/suite/issuers/acme/certificate/webhook.go @@ -126,41 +126,45 @@ var _ = framework.CertManagerDescribe("ACME webhook DNS provider", func() { Expect(err).NotTo(HaveOccurred()) var order *cmacme.Order + logf, done := log.LogBackoff() + defer done() pollErr := wait.PollImmediate(2*time.Second, time.Second*30, func() (bool, error) { orders, err := listOwnedOrders(f.CertManagerClientSet, cert) Expect(err).NotTo(HaveOccurred()) - log.Logf("Found %d orders for certificate", len(orders)) + logf("Found %d orders for certificate", len(orders)) if len(orders) == 1 { order = orders[0] - log.Logf("Found order named %q", order.Name) + logf("Found order named %q", order.Name) return true, nil } - log.Logf("Waiting as one Order should exist, but we found %d", len(orders)) + logf("Waiting as one Order should exist, but we found %d", len(orders)) return false, nil }, ) Expect(pollErr).NotTo(HaveOccurred()) + logf, done = log.LogBackoff() + defer done() pollErr = wait.PollImmediate(2*time.Second, time.Second*90, func() (bool, error) { l, err := listOwnedChallenges(f.CertManagerClientSet, order) Expect(err).NotTo(HaveOccurred()) - log.Logf("Found %d challenges", len(l)) + logf("Found %d challenges", len(l)) if len(l) == 0 { - log.Logf("Waiting for at least one challenge to exist") + logf("Waiting for at least one challenge to exist") return false, nil } allPresented := true for _, ch := range l { - log.Logf("Found challenge named %q", ch.Name) + logf("Found challenge named %q", ch.Name) if ch.Status.Presented == false { - log.Logf("Challenge %q has not been 'Presented'", ch.Name) + logf("Challenge %q has not been 'Presented'", ch.Name) allPresented = false } } diff --git a/test/e2e/suite/issuers/acme/certificaterequest/http01.go b/test/e2e/suite/issuers/acme/certificaterequest/http01.go index 3e3a9007a..747d7f0d9 100644 --- a/test/e2e/suite/issuers/acme/certificaterequest/http01.go +++ b/test/e2e/suite/issuers/acme/certificaterequest/http01.go @@ -218,16 +218,18 @@ var _ = framework.CertManagerDescribe("ACME CertificateRequest (HTTP01)", func() By("killing the solver pod") podClient := f.KubeClientSet.CoreV1().Pods(f.Namespace.Name) var pod corev1.Pod + logf, done := log.LogBackoff() + defer done() err = wait.PollImmediate(1*time.Second, time.Minute, func() (bool, error) { - log.Logf("Waiting for solver pod to exist") + logf("Waiting for solver pod to exist") podlist, err := podClient.List(context.TODO(), metav1.ListOptions{}) if err != nil { return false, err } for _, p := range podlist.Items { - log.Logf("solver pod %s", p.Name) + logf("solver pod %s", p.Name) // TODO(dmo): make this cleaner instead of just going by name if strings.Contains(p.Name, "http-solver") { pod = p diff --git a/test/e2e/util/util.go b/test/e2e/util/util.go index 58d670301..1addd9545 100644 --- a/test/e2e/util/util.go +++ b/test/e2e/util/util.go @@ -70,9 +70,11 @@ func WaitForIssuerStatusFunc(client clientset.IssuerInterface, name string, fn f // WaitForIssuerCondition waits for the status of the named issuer to contain // a condition whose type and status matches the supplied one. func WaitForIssuerCondition(client clientset.IssuerInterface, name string, condition v1.IssuerCondition) error { + logf, done := log.LogBackoff() + defer done() pollErr := wait.PollImmediate(500*time.Millisecond, time.Minute, func() (bool, error) { - log.Logf("Waiting for issuer %v condition %#v", name, condition) + logf("Waiting for issuer %v condition %#v", name, condition) issuer, err := client.Get(context.TODO(), name, metav1.GetOptions{}) if nil != err { return false, fmt.Errorf("error getting Issuer %q: %v", name, err) @@ -108,9 +110,11 @@ func wrapErrorWithIssuerStatusCondition(client clientset.IssuerInterface, pollEr // WaitForClusterIssuerCondition waits for the status of the named issuer to contain // a condition whose type and status matches the supplied one. func WaitForClusterIssuerCondition(client clientset.ClusterIssuerInterface, name string, condition v1.IssuerCondition) error { + logf, done := log.LogBackoff() + defer done() pollErr := wait.PollImmediate(500*time.Millisecond, time.Minute, func() (bool, error) { - log.Logf("Waiting for clusterissuer %v condition %#v", name, condition) + logf("Waiting for clusterissuer %v condition %#v", name, condition) issuer, err := client.Get(context.TODO(), name, metav1.GetOptions{}) if nil != err { return false, fmt.Errorf("error getting ClusterIssuer %v: %v", name, err) @@ -146,9 +150,11 @@ func wrapErrorWithClusterIssuerStatusCondition(client clientset.ClusterIssuerInt // WaitForCRDToNotExist waits for the CRD with the given name to no // longer exist. func WaitForCRDToNotExist(client apiextensionsv1.CustomResourceDefinitionInterface, name string) error { + logf, done := log.LogBackoff() + defer done() return wait.PollImmediate(500*time.Millisecond, time.Minute, func() (bool, error) { - log.Logf("Waiting for CRD %v to not exist", name) + logf("Waiting for CRD %v to not exist", name) _, err := client.Get(context.TODO(), name, metav1.GetOptions{}) if nil == err { return false, nil