From de5b22ffba731382f550bec18c0449e4723b99ff Mon Sep 17 00:00:00 2001 From: Alejandro Pedraza Date: Tue, 26 May 2020 16:41:31 -0500 Subject: [PATCH] Flaky tests: when installation test fails, fetch logs and events (#4410) * When installation test fails, fetch logs and events Re #4371 When a test fails in `./test/install_test.go`, trigger the `TestLogs` and `TestEvents` tests in a separate process in order to output any unexpected logs/events that might have caused the initial test failure. For instance, currently we're sporadically experiencing pod restarts. Instead of ignoring them, this might help provide us with the real underlying cause. --- bin/test-run | 5 +- test/install_test.go | 138 +++++++++++++++++++++++++++---------------- 2 files changed, 91 insertions(+), 52 deletions(-) diff --git a/bin/test-run b/bin/test-run index 7e8b2810c..367d0862f 100755 --- a/bin/test-run +++ b/bin/test-run @@ -4,8 +4,9 @@ # 1. upgrade_integration_tests # 2. helm_integration_tests # 3. helm_upgrade_integration_tests -# 4. deep_integration_tests -# 5. external_issuer_integration_tests +# 4. uninstall_integration_tests +# 5. deep_integration_tests +# 6. external_issuer_integration_tests bindir=$( cd "${BASH_SOURCE[0]%/*}" && pwd ) diff --git a/test/install_test.go b/test/install_test.go index 094285c9c..a642ba199 100644 --- a/test/install_test.go +++ b/test/install_test.go @@ -1,6 +1,7 @@ package test import ( + "errors" "fmt" "os" "regexp" @@ -19,11 +20,32 @@ import ( /// TEST SETUP /// ////////////////////// -var TestHelper *testutil.TestHelper +var ( + TestHelper *testutil.TestHelper + + // controlPlaneInstalled becomes true as soon as there's a CP available to + // retrieve logs from + controlPlaneInstalled = false +) func TestMain(m *testing.M) { TestHelper = testutil.NewTestHelper() - os.Exit(m.Run()) + code := m.Run() + // if the test failed, show logs and events that can potentially explain cause + if code != 0 && controlPlaneInstalled { + _, errs1 := fetchAndCheckLogs() + for _, err := range errs1 { + fmt.Println(err) + } + errs2 := fetchAndCheckEvents() + for _, err := range errs2 { + fmt.Println(err) + } + if len(errs1) == 0 && len(errs2) == 0 { + fmt.Println("No unexpected log entries or events found") + } + } + os.Exit(code) } var ( @@ -195,6 +217,7 @@ func TestInstallOrUpgradeCli(t *testing.T) { if TestHelper.GetHelmReleaseName() != "" { return } + controlPlaneInstalled = true var ( cmd = "install" @@ -358,6 +381,7 @@ func TestInstallHelm(t *testing.T) { if TestHelper.GetHelmReleaseName() == "" { return } + controlPlaneInstalled = true cn := fmt.Sprintf("identity.%s.cluster.local", TestHelper.GetLinkerdNamespace()) var err error @@ -396,7 +420,7 @@ func TestResourcesPostInstall(t *testing.T) { for _, svc := range linkerdSvcs { if err := TestHelper.CheckService(TestHelper.GetLinkerdNamespace(), svc); err != nil { testutil.AnnotatedErrorf(t, fmt.Sprintf("error validating service [%s]", svc), - "rrror validating service [%s]:\n%s", svc, err) + "error validating service [%s]:\n%s", svc, err) } } @@ -721,7 +745,10 @@ func TestCheckProxy(t *testing.T) { } } -func TestLogs(t *testing.T) { +func fetchAndCheckLogs() ([]string, []error) { + okMessages := []string{} + errs := []error{} + controllerRegex := regexp.MustCompile("level=(panic|fatal|error|warn)") proxyRegex := regexp.MustCompile(fmt.Sprintf("%s (ERR|WARN)", k8s.ProxyContainerName)) clientGoRegex := regexp.MustCompile("client-go@") @@ -744,85 +771,96 @@ func TestLogs(t *testing.T) { knownErrorsRegex = knownProxyErrorsRegex } - t.Run(name, func(t *testing.T) { - outputStream, err := TestHelper.LinkerdRunStream( - "logs", "--no-color", - "--control-plane-component", deploy, - "--container", container, - ) - if err != nil { - testutil.AnnotatedErrorf(t, "error running command", - "error running command:\n%s", err) - } - defer outputStream.Stop() - // Ignore the error returned, since ReadUntil will return an error if it - // does not return 10,000 after 2 seconds. We don't need 10,000 log lines. - outputLines, _ := outputStream.ReadUntil(10000, 2*time.Second) + outputStream, err := TestHelper.LinkerdRunStream( + "logs", "--no-color", + "--control-plane-component", deploy, + "--container", container, + ) + if err != nil { + errs = append(errs, fmt.Errorf("error running command:\n%s", err)) + continue + } + defer outputStream.Stop() + // Ignore the error returned, since ReadUntil will return an error if it + // does not return 10,000 after 2 seconds. We don't need 10,000 log lines. + outputLines, _ := outputStream.ReadUntil(10000, 2*time.Second) + if len(outputLines) == 0 { + // Retry one time for 30 more seconds, in case the cluster is slow to + // produce log lines. + outputLines, _ = outputStream.ReadUntil(10000, 30*time.Second) if len(outputLines) == 0 { - // Retry one time for 30 more seconds, in case the cluster is slow to - // produce log lines. - outputLines, _ = outputStream.ReadUntil(10000, 30*time.Second) - if len(outputLines) == 0 { - testutil.AnnotatedErrorf(t, "no logs found for %s", name) - } + errs = append(errs, fmt.Errorf("no logs found for %s", name)) } + } - for _, line := range outputLines { - if errRegex.MatchString(line) { - if knownErrorsRegex.MatchString(line) { - // report all known logging errors in the output - t.Logf("Found known error in %s log: %s", name, line) + for _, line := range outputLines { + if errRegex.MatchString(line) { + if knownErrorsRegex.MatchString(line) { + // report all known logging errors in the output + okMessages = append(okMessages, fmt.Sprintf("found known error in %s log: %s", name, line)) + } else { + if proxy { + okMessages = append(okMessages, fmt.Sprintf("found unexpected proxy error in %s log: %s", name, line)) } else { - if proxy { - t.Logf("Found unexpected proxy error in %s log: %s", name, line) - } else { - testutil.AnnotatedErrorf(t, - "Found unexpected controller error in %s log: %s", name, line) - } + errs = append(errs, fmt.Errorf("found unexpected controller error in %s log: %s", name, line)) } } - if clientGoRegex.MatchString((line)) { - hasClientGoLogs = true - } } - }) + if clientGoRegex.MatchString((line)) { + hasClientGoLogs = true + } + } } } if !hasClientGoLogs { - testutil.AnnotatedError(t, "didn't find any client-go entries") + errs = append(errs, errors.New("didn't find any client-go entries")) + } + + return okMessages, errs +} + +func TestLogs(t *testing.T) { + okMessages, errs := fetchAndCheckLogs() + for msg := range okMessages { + t.Log(msg) + } + for err := range errs { + testutil.AnnotatedError(t, "Error checking logs", err) } } -func TestEvents(t *testing.T) { +func fetchAndCheckEvents() []error { out, err := TestHelper.Kubectl("", "--namespace", TestHelper.GetLinkerdNamespace(), "get", "events", "-ojson", ) if err != nil { - testutil.AnnotatedErrorf(t, "'kubectl get events' command failed", - "'kubectl get events' command failed with %s\n%s", err, out) + return []error{fmt.Errorf("'kubectl get events' command failed with %s\n%s", err, out)} } events, err := testutil.ParseEvents(out) if err != nil { - testutil.AnnotatedError(t, "error parsing events", err) + return []error{err} } - var unknownEvents []string + errs := []error{} for _, e := range events { if e.Type == corev1.EventTypeNormal { continue } - evtStr := fmt.Sprintf("Reason: [%s] Object: [%s] Message: [%s]", e.Reason, e.InvolvedObject.Name, e.Message) + evtStr := fmt.Errorf("found unexpected warning event: reason: [%s] Object: [%s] Message: [%s]", e.Reason, e.InvolvedObject.Name, e.Message) if !knownEventWarningsRegex.MatchString(e.Message) { - unknownEvents = append(unknownEvents, evtStr) + errs = append(errs, evtStr) } } - if len(unknownEvents) > 0 { - testutil.AnnotatedErrorf(t, "found unexpected warning events", - "found unexpected warning events:\n%s", strings.Join(unknownEvents, "\n")) + return errs +} + +func TestEvents(t *testing.T) { + for err := range fetchAndCheckEvents() { + testutil.AnnotatedError(t, "Error checking events", err) } }