weiguoqiang/cert-manager
1
0
Fork 0
Code Issues Pull Requests Actions 3 Packages Projects Releases Wiki Activity

make/e2e.sh: add a backoff to the log.Logf when waiting for something

Browse Source 
Signed-off-by: Maël Valais <mael@vls.dev>
This commit is contained in:
Maël Valais 2022-03-23 11:43:30 +01:00
parent f70baa8d3c
commit d6ebdda49c
11 changed files with 116 additions and 35 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

6
test/e2e/framework/helper/certificaterequests.go
View File

@ -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

29
test/e2e/framework/helper/certificates.go
View File

@ -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,

4
test/e2e/framework/helper/certificatesigningrequests.go
View File

@ -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)

8
test/e2e/framework/helper/pod_start.go
View File

@ -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
}

6
test/e2e/framework/helper/secret.go
View File

@ -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
},

5
test/e2e/framework/log/BUILD.bazel
View File

@ -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(

45
test/e2e/framework/log/log.go
View File

@ -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
}

12
test/e2e/suite/issuers/acme/certificate/http01.go
View File

@ -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

18
test/e2e/suite/issuers/acme/certificate/webhook.go
View File

@ -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
}
}

6
test/e2e/suite/issuers/acme/certificaterequest/http01.go
View File

@ -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

12
test/e2e/util/util.go
View File

@ -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