From b1e4ad1daa94f49ed18e0f9e98c8bdc09f8252ea Mon Sep 17 00:00:00 2001 From: tstromberg Date: Wed, 6 Nov 2019 15:17:09 -0800 Subject: [PATCH 1/5] Add 500MB more memory, extend wait times --- test/integration/functional_test.go | 23 +++++++++++++---------- 1 file changed, 13 insertions(+), 10 deletions(-) diff --git a/test/integration/functional_test.go b/test/integration/functional_test.go index 00379f245b..fc1b2390aa 100644 --- a/test/integration/functional_test.go +++ b/test/integration/functional_test.go @@ -111,7 +111,9 @@ func validateStartWithProxy(ctx context.Context, t *testing.T, profile string) { if err != nil { t.Fatalf("Failed to set up the test proxy: %s", err) } - startArgs := append([]string{"start", "-p", profile, "--wait=false"}, StartArgs()...) + + // Use more memory so that we may reliably fit MySQL and nginx + startArgs := append([]string{"start", "-p", profile, "--wait=false", "--memory", "2500MB"}, StartArgs()...) c := exec.CommandContext(ctx, Target(), startArgs...) env := os.Environ() env = append(env, fmt.Sprintf("HTTP_PROXY=%s", srv.Addr)) @@ -159,8 +161,8 @@ func validateKubectlGetPods(ctx context.Context, t *testing.T, profile string) { // validateAddonManager asserts that the kube-addon-manager pod is deployed properly func validateAddonManager(ctx context.Context, t *testing.T, profile string) { // If --wait=false, this may take a couple of minutes - if _, err := PodWait(ctx, t, profile, "kube-system", "component=kube-addon-manager", 3*time.Minute); err != nil { - t.Errorf("wait: %v", err) + if _, err := PodWait(ctx, t, profile, "kube-system", "component=kube-addon-manager", 5*time.Minute); err != nil { + t.Fatalf("wait: %v", err) } } @@ -272,7 +274,7 @@ func validateDNS(ctx context.Context, t *testing.T, profile string) { t.Fatalf("%s failed: %v", rr.Args, err) } - names, err := PodWait(ctx, t, profile, "default", "integration-test=busybox", 3*time.Minute) + names, err := PodWait(ctx, t, profile, "default", "integration-test=busybox", 5*time.Minute) if err != nil { t.Fatalf("wait: %v", err) } @@ -407,7 +409,7 @@ func validateServiceCmd(ctx context.Context, t *testing.T, profile string) { t.Logf("%s failed: %v (may not be an error)", rr.Args, err) } - if _, err := PodWait(ctx, t, profile, "default", "app=hello-node", 4*time.Minute); err != nil { + if _, err := PodWait(ctx, t, profile, "default", "app=hello-node", 5*time.Minute); err != nil { t.Fatalf("wait: %v", err) } @@ -550,16 +552,17 @@ func validateMySQL(ctx context.Context, t *testing.T, profile string) { t.Fatalf("%s failed: %v", rr.Args, err) } + names, err := PodWait(ctx, t, profile, "default", "app=mysql", 5*time.Minute) + if err != nil { + t.Fatalf("podwait: %v", err) + } + // Retry, as mysqld first comes up without users configured. Scan for names in case of a reschedule. mysql := func() error { - names, err := PodWait(ctx, t, profile, "default", "app=mysql", 5*time.Second) - if err != nil { - return err - } rr, err = Run(t, exec.CommandContext(ctx, "kubectl", "--context", profile, "exec", names[0], "--", "mysql", "-ppassword", "-e", "show databases;")) return err } - if err = retry.Expo(mysql, 1*time.Second, 2*time.Minute); err != nil { + if err = retry.Expo(mysql, 10*time.Second, 60*time.Second); err != nil { t.Errorf("mysql failing: %v", err) } } From c9f99ece2cb2c4aa7e545e12435c2e3c184352c6 Mon Sep 17 00:00:00 2001 From: tstromberg Date: Wed, 6 Nov 2019 15:17:36 -0800 Subject: [PATCH 2/5] Add 'kubectl describe node' output, make error messages clearer --- test/integration/helpers.go | 37 ++++++++++++++++++++++++------------- 1 file changed, 24 insertions(+), 13 deletions(-) diff --git a/test/integration/helpers.go b/test/integration/helpers.go index 505d1aeea1..7e76cd245a 100644 --- a/test/integration/helpers.go +++ b/test/integration/helpers.go @@ -177,14 +177,17 @@ func Cleanup(t *testing.T, profile string, cancel context.CancelFunc) { // CleanupWithLogs cleans up after a test run, fetching logs and deleting the profile func CleanupWithLogs(t *testing.T, profile string, cancel context.CancelFunc) { t.Helper() - if t.Failed() && *postMortemLogs { - t.Logf("%s failed, collecting logs ...", t.Name()) - rr, err := Run(t, exec.Command(Target(), "-p", profile, "logs", "--problems")) - if err != nil { - t.Logf("failed logs error: %v", err) + if t.Failed() { + t.Logf("*** %s FAILED at %s", t.Name(), time.Now()) + if *postMortemLogs { + t.Logf(">>> %s FAILED: start of post-mortem logs >>>", t.Name()) + rr, err := Run(t, exec.Command(Target(), "-p", profile, "logs", "--problems")) + if err != nil { + t.Logf("failed logs error: %v", err) + } + t.Logf("%s logs: %s", t.Name(), rr.Stdout) + t.Logf("<<< %s FAILED: end of post-mortem logs <<<", t.Name()) } - t.Logf("%s logs: %s", t.Name(), rr.Stdout) - t.Logf("Sorry that %s failed :(", t.Name()) } Cleanup(t, profile, cancel) } @@ -225,11 +228,11 @@ func PodWait(ctx context.Context, t *testing.T, profile string, ns string, selec lastMsg := "" start := time.Now() - t.Logf("(dbg) waiting for pods with labels %q in namespace %q ...", selector, ns) + t.Logf("(dbg) %s: waiting %s for pods matching %q in namespace %q ...", t.Name(), timeout, selector, ns) f := func() (bool, error) { pods, err := client.CoreV1().Pods(ns).List(listOpts) if err != nil { - t.Logf("WARNING: pod list for %q %q returned: %v", ns, selector, err) + t.Logf("%s: WARNING: pod list for %q %q returned: %v", t.Name(), ns, selector, err) // Don't return the error upwards so that this is retried, in case the apiserver is rescheduled podStart = time.Time{} return false, nil @@ -254,7 +257,7 @@ func PodWait(ctx context.Context, t *testing.T, profile string, ns string, selec // Long-running process state if pod.Status.Phase != core.PodRunning { if !podStart.IsZero() { - t.Logf("WARNING: %s was running %s ago - may be unstable", selector, time.Since(podStart)) + t.Logf("%s: WARNING: %s was running %s ago - may be unstable", t.Name(), selector, time.Since(podStart)) } podStart = time.Time{} return false, nil @@ -271,24 +274,25 @@ func PodWait(ctx context.Context, t *testing.T, profile string, ns string, selec return false, nil } - err = wait.PollImmediate(500*time.Millisecond, timeout, f) + err = wait.PollImmediate(1*time.Second, timeout, f) names := []string{} for n := range foundNames { names = append(names, n) } if err == nil { - t.Logf("(dbg) pods %s up and healthy within %s", selector, time.Since(start)) + t.Logf("(dbg) %s: %s healthy within %s", t.Name(), selector, time.Since(start)) return names, nil } - t.Logf("pod %q failed to start: %v", selector, err) + t.Logf("***** %s: pod %q failed to start within %s: %v ****", t.Name(), selector, timeout, err) showPodLogs(ctx, t, profile, ns, names) return names, fmt.Errorf("%s: %v", fmt.Sprintf("%s within %s", selector, timeout), err) } // showPodLogs logs debug info for pods func showPodLogs(ctx context.Context, t *testing.T, profile string, ns string, names []string) { + t.Logf("%s: showing logs for failed pods as of %s", t.Name(), time.Now()) rr, rerr := Run(t, exec.CommandContext(ctx, "kubectl", "--context", profile, "get", "po", "-A", "--show-labels")) if rerr != nil { t.Logf("%s: %v", rr.Command(), rerr) @@ -312,6 +316,13 @@ func showPodLogs(ctx context.Context, t *testing.T, profile string, ns string, n t.Logf("(dbg) %s:\n%s", rr.Command(), rr.Stdout) } } + + rr, err := Run(t, exec.CommandContext(ctx, "kubectl", "--context", profile, "describe", "node")) + if err != nil { + t.Logf("%s: %v", rr.Command(), err) + } else { + t.Logf("(dbg) %s:\n%s", rr.Command(), rr.Stdout) + } } // Status returns the minikube cluster status as a string From fd27e16c187a72af4392fca2228c450506b24fd9 Mon Sep 17 00:00:00 2001 From: Thomas Stromberg Date: Thu, 7 Nov 2019 06:53:53 -0800 Subject: [PATCH 3/5] Reduce mysql retry time to 3s --- test/integration/functional_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/integration/functional_test.go b/test/integration/functional_test.go index fc1b2390aa..152f94309d 100644 --- a/test/integration/functional_test.go +++ b/test/integration/functional_test.go @@ -562,7 +562,7 @@ func validateMySQL(ctx context.Context, t *testing.T, profile string) { rr, err = Run(t, exec.CommandContext(ctx, "kubectl", "--context", profile, "exec", names[0], "--", "mysql", "-ppassword", "-e", "show databases;")) return err } - if err = retry.Expo(mysql, 10*time.Second, 60*time.Second); err != nil { + if err = retry.Expo(mysql, 3*time.Second, 60*time.Second); err != nil { t.Errorf("mysql failing: %v", err) } } From 885f4c265303fd52aac73c1e649a3c9e97f20f4c Mon Sep 17 00:00:00 2001 From: Thomas Stromberg Date: Mon, 11 Nov 2019 08:18:01 -0800 Subject: [PATCH 4/5] Pre-cache hello-node, wait longer for mysql password --- test/integration/functional_test.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/test/integration/functional_test.go b/test/integration/functional_test.go index 152f94309d..100017d42f 100644 --- a/test/integration/functional_test.go +++ b/test/integration/functional_test.go @@ -300,7 +300,7 @@ func validateCacheCmd(ctx context.Context, t *testing.T, profile string) { if NoneDriver() { t.Skipf("skipping: cache unsupported by none") } - for _, img := range []string{"busybox", "busybox:1.28.4-glibc", "mysql:5.6"} { + for _, img := range []string{"busybox", "busybox:1.28.4-glibc", "mysql:5.6", "gcr.io/hello-minikube-zero-install/hello-node"} { rr, err := Run(t, exec.CommandContext(ctx, Target(), "-p", profile, "cache", "add", img)) if err != nil { t.Errorf("%s failed: %v", rr.Args, err) @@ -562,7 +562,7 @@ func validateMySQL(ctx context.Context, t *testing.T, profile string) { rr, err = Run(t, exec.CommandContext(ctx, "kubectl", "--context", profile, "exec", names[0], "--", "mysql", "-ppassword", "-e", "show databases;")) return err } - if err = retry.Expo(mysql, 3*time.Second, 60*time.Second); err != nil { + if err = retry.Expo(mysql, 5*time.Second, 180*time.Second); err != nil { t.Errorf("mysql failing: %v", err) } } From 42e711df99f42e4c4c4911c1546687fd5137906c Mon Sep 17 00:00:00 2001 From: Thomas Stromberg Date: Mon, 11 Nov 2019 08:18:39 -0800 Subject: [PATCH 5/5] Move show-labels and get-node to post-mortem logs --- test/integration/helpers.go | 52 ++++++++++++++++++++----------------- 1 file changed, 28 insertions(+), 24 deletions(-) diff --git a/test/integration/helpers.go b/test/integration/helpers.go index 7e76cd245a..1539170f77 100644 --- a/test/integration/helpers.go +++ b/test/integration/helpers.go @@ -177,17 +177,35 @@ func Cleanup(t *testing.T, profile string, cancel context.CancelFunc) { // CleanupWithLogs cleans up after a test run, fetching logs and deleting the profile func CleanupWithLogs(t *testing.T, profile string, cancel context.CancelFunc) { t.Helper() - if t.Failed() { - t.Logf("*** %s FAILED at %s", t.Name(), time.Now()) - if *postMortemLogs { - t.Logf(">>> %s FAILED: start of post-mortem logs >>>", t.Name()) - rr, err := Run(t, exec.Command(Target(), "-p", profile, "logs", "--problems")) - if err != nil { - t.Logf("failed logs error: %v", err) - } - t.Logf("%s logs: %s", t.Name(), rr.Stdout) - t.Logf("<<< %s FAILED: end of post-mortem logs <<<", t.Name()) + if !t.Failed() { + Cleanup(t, profile, cancel) + return + } + + t.Logf("*** %s FAILED at %s", t.Name(), time.Now()) + + if *postMortemLogs { + t.Logf(">>> %s FAILED: start of post-mortem logs >>>", t.Name()) + + rr, rerr := Run(t, exec.Command("kubectl", "--context", profile, "get", "po", "-A", "--show-labels")) + if rerr != nil { + t.Logf("%s: %v", rr.Command(), rerr) } + t.Logf("(dbg) %s:\n%s", rr.Command(), rr.Stdout) + + rr, err := Run(t, exec.Command("kubectl", "--context", profile, "describe", "node")) + if err != nil { + t.Logf("%s: %v", rr.Command(), err) + } else { + t.Logf("(dbg) %s:\n%s", rr.Command(), rr.Stdout) + } + + rr, err = Run(t, exec.Command(Target(), "-p", profile, "logs", "--problems")) + if err != nil { + t.Logf("failed logs error: %v", err) + } + t.Logf("%s logs: %s", t.Name(), rr.Stdout) + t.Logf("<<< %s FAILED: end of post-mortem logs <<<", t.Name()) } Cleanup(t, profile, cancel) } @@ -293,13 +311,6 @@ func PodWait(ctx context.Context, t *testing.T, profile string, ns string, selec // showPodLogs logs debug info for pods func showPodLogs(ctx context.Context, t *testing.T, profile string, ns string, names []string) { t.Logf("%s: showing logs for failed pods as of %s", t.Name(), time.Now()) - rr, rerr := Run(t, exec.CommandContext(ctx, "kubectl", "--context", profile, "get", "po", "-A", "--show-labels")) - if rerr != nil { - t.Logf("%s: %v", rr.Command(), rerr) - // return now, because kubectl is hosed - return - } - t.Logf("(dbg) %s:\n%s", rr.Command(), rr.Stdout) for _, name := range names { rr, err := Run(t, exec.CommandContext(ctx, "kubectl", "--context", profile, "describe", "po", name, "-n", ns)) @@ -316,13 +327,6 @@ func showPodLogs(ctx context.Context, t *testing.T, profile string, ns string, n t.Logf("(dbg) %s:\n%s", rr.Command(), rr.Stdout) } } - - rr, err := Run(t, exec.CommandContext(ctx, "kubectl", "--context", profile, "describe", "node")) - if err != nil { - t.Logf("%s: %v", rr.Command(), err) - } else { - t.Logf("(dbg) %s:\n%s", rr.Command(), rr.Stdout) - } } // Status returns the minikube cluster status as a string