|
| 1 | +/* |
| 2 | +Copyright 2019 The Kubernetes Authors. |
| 3 | +
|
| 4 | +Licensed under the Apache License, Version 2.0 (the "License"); |
| 5 | +you may not use this file except in compliance with the License. |
| 6 | +You may obtain a copy of the License at |
| 7 | +
|
| 8 | + http://www.apache.org/licenses/LICENSE-2.0 |
| 9 | +
|
| 10 | +Unless required by applicable law or agreed to in writing, software |
| 11 | +distributed under the License is distributed on an "AS IS" BASIS, |
| 12 | +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. |
| 13 | +See the License for the specific language governing permissions and |
| 14 | +limitations under the License. |
| 15 | +*/ |
| 16 | + |
| 17 | +package log_test |
| 18 | + |
| 19 | +import ( |
| 20 | + "errors" |
| 21 | + "regexp" |
| 22 | + "sort" |
| 23 | + "strings" |
| 24 | + "testing" |
| 25 | + |
| 26 | + "github.com/onsi/ginkgo" |
| 27 | + "github.com/onsi/ginkgo/config" |
| 28 | + "github.com/onsi/ginkgo/reporters" |
| 29 | + "github.com/onsi/gomega" |
| 30 | + |
| 31 | + "k8s.io/kubernetes/test/e2e/framework" |
| 32 | + "k8s.io/kubernetes/test/e2e/framework/log" |
| 33 | +) |
| 34 | + |
| 35 | +var _ = ginkgo.Describe("log", func() { |
| 36 | + ginkgo.BeforeEach(func() { |
| 37 | + log.Logf("before") |
| 38 | + }) |
| 39 | + ginkgo.It("fails", func() { |
| 40 | + func() { |
| 41 | + log.Failf("I'm failing.") |
| 42 | + }() |
| 43 | + }) |
| 44 | + ginkgo.It("asserts", func() { |
| 45 | + gomega.Expect(false).To(gomega.Equal(true), "false is never true") |
| 46 | + }) |
| 47 | + ginkgo.It("error", func() { |
| 48 | + err := errors.New("an error with a long, useless description") |
| 49 | + framework.ExpectNoError(err, "hard-coded error") |
| 50 | + }) |
| 51 | + ginkgo.AfterEach(func() { |
| 52 | + log.Logf("after") |
| 53 | + gomega.Expect(true).To(gomega.Equal(false), "true is never false either") |
| 54 | + }) |
| 55 | +}) |
| 56 | + |
| 57 | +func TestFailureOutput(t *testing.T) { |
| 58 | + // Run the Ginkgo suite with output collected by a custom |
| 59 | + // reporter in adddition to the default one. To see what the full |
| 60 | + // Ginkgo report looks like, run this test with "go test -v". |
| 61 | + config.DefaultReporterConfig.FullTrace = true |
| 62 | + gomega.RegisterFailHandler(log.Fail) |
| 63 | + fakeT := &testing.T{} |
| 64 | + reporter := reporters.NewFakeReporter() |
| 65 | + ginkgo.RunSpecsWithDefaultAndCustomReporters(fakeT, "Logging Suite", []ginkgo.Reporter{reporter}) |
| 66 | + |
| 67 | + // Now check the output. |
| 68 | + // TODO: all of the stacks are currently broken because Ginkgo doesn't properly skip |
| 69 | + // over the initial entries returned by runtime.Stack. Fix is pending in |
| 70 | + // https://github.com/onsi/ginkgo/pull/590, "stack" texts need to be updated |
| 71 | + // when updating to a fixed Ginkgo. |
| 72 | + g := gomega.NewGomegaWithT(t) |
| 73 | + actual := normalizeReport(*reporter) |
| 74 | + expected := suiteResults{ |
| 75 | + testResult{ |
| 76 | + name: "[Top Level] log asserts", |
| 77 | + output: "INFO: before\nFAIL: false is never true\nExpected\n <bool>: false\nto equal\n <bool>: true\nINFO: after\nFAIL: true is never false either\nExpected\n <bool>: true\nto equal\n <bool>: false\n", |
| 78 | + failure: "false is never true\nExpected\n <bool>: false\nto equal\n <bool>: true", |
| 79 | + // TODO: should start with k8s.io/kubernetes/test/e2e/framework/log_test.glob..func1.3() |
| 80 | + stack: "\tassertion.go:75\nk8s.io/kubernetes/vendor/github.com/onsi/gomega/internal/assertion.(*Assertion).To()\n\tassertion.go:38\nk8s.io/kubernetes/test/e2e/framework/log_test.glob..func1.3()\n\tlogger_test.go:45\nk8s.io/kubernetes/vendor/github.com/onsi/ginkgo/internal/leafnodes.(*runner).runSync()\n\tlogger_test.go:65\n", |
| 81 | + }, |
| 82 | + testResult{ |
| 83 | + name: "[Top Level] log error", |
| 84 | + output: "INFO: before\nFAIL: hard-coded error\nUnexpected error:\n <*errors.errorString>: {\n s: \"an error with a long, useless description\",\n }\n an error with a long, useless description\noccurred\nINFO: after\nFAIL: true is never false either\nExpected\n <bool>: true\nto equal\n <bool>: false\n", |
| 85 | + failure: "hard-coded error\nUnexpected error:\n <*errors.errorString>: {\n s: \"an error with a long, useless description\",\n }\n an error with a long, useless description\noccurred", |
| 86 | + // TODO: should start with k8s.io/kubernetes/test/e2e/framework/log_test.glob..func1.4() |
| 87 | + stack: "\tutil.go:1362\nk8s.io/kubernetes/test/e2e/framework.ExpectNoError()\n\tutil.go:1356\nk8s.io/kubernetes/test/e2e/framework/log_test.glob..func1.4()\n\tlogger_test.go:49\nk8s.io/kubernetes/vendor/github.com/onsi/ginkgo/internal/leafnodes.(*runner).runSync()\n\tlogger_test.go:65\n", |
| 88 | + }, |
| 89 | + testResult{ |
| 90 | + name: "[Top Level] log fails", |
| 91 | + output: "INFO: before\nFAIL: I'm failing.\nINFO: after\nFAIL: true is never false either\nExpected\n <bool>: true\nto equal\n <bool>: false\n", |
| 92 | + failure: "I'm failing.", |
| 93 | + // TODO: should start with k8s.io/kubernetes/test/e2e/framework/log_test.glob..func1.2.1(...) |
| 94 | + stack: "\tlogger.go:52\nk8s.io/kubernetes/test/e2e/framework/log.Failf()\n\tlogger.go:44\nk8s.io/kubernetes/test/e2e/framework/log_test.glob..func1.2.1(...)\n\tlogger_test.go:41\nk8s.io/kubernetes/test/e2e/framework/log_test.glob..func1.2()\n\tlogger_test.go:42\nk8s.io/kubernetes/vendor/github.com/onsi/ginkgo/internal/leafnodes.(*runner).runSync()\n\tlogger_test.go:65\n", |
| 95 | + }, |
| 96 | + } |
| 97 | + // Compare individual fields. Comparing the slices leads to unreadable error output when there is any mismatch. |
| 98 | + g.Expect(len(actual)).To(gomega.Equal(len(expected)), "%d entries in %v", len(expected), actual) |
| 99 | + for i, a := range actual { |
| 100 | + b := expected[i] |
| 101 | + g.Expect(a.name).To(gomega.Equal(b.name), "name in %d", i) |
| 102 | + g.Expect(a.output).To(gomega.Equal(b.output), "output in %d", i) |
| 103 | + g.Expect(a.failure).To(gomega.Equal(b.failure), "failure in %d", i) |
| 104 | + g.Expect(a.stack).To(gomega.Equal(b.stack), "stack in %d", i) |
| 105 | + } |
| 106 | +} |
| 107 | + |
| 108 | +type testResult struct { |
| 109 | + name string |
| 110 | + // output written to GinkgoWriter during test. |
| 111 | + output string |
| 112 | + // failure is SpecSummary.Failure.Message with varying parts stripped. |
| 113 | + failure string |
| 114 | + // stack is a normalized version (just file names, function parametes stripped) of |
| 115 | + // Ginkgo's FullStackTrace of a failure. Empty if no failure. |
| 116 | + stack string |
| 117 | +} |
| 118 | + |
| 119 | +type suiteResults []testResult |
| 120 | + |
| 121 | +func normalizeReport(report reporters.FakeReporter) suiteResults { |
| 122 | + var results suiteResults |
| 123 | + for _, spec := range report.SpecSummaries { |
| 124 | + results = append(results, testResult{ |
| 125 | + name: strings.Join(spec.ComponentTexts, " "), |
| 126 | + output: stripAddresses(stripTimes(spec.CapturedOutput)), |
| 127 | + failure: stripAddresses(stripTimes(spec.Failure.Message)), |
| 128 | + stack: normalizeLocation(spec.Failure.Location.FullStackTrace), |
| 129 | + }) |
| 130 | + } |
| 131 | + sort.Slice(results, func(i, j int) bool { |
| 132 | + return strings.Compare(results[i].name, results[j].name) < 0 |
| 133 | + }) |
| 134 | + return results |
| 135 | +} |
| 136 | + |
| 137 | +// timePrefix matches "Jul 17 08:08:25.950: " at the beginning of each line. |
| 138 | +var timePrefix = regexp.MustCompile(`(?m)^[[:alpha:]]{3} [[:digit:]]{1,2} [[:digit:]]{2}:[[:digit:]]{2}:[[:digit:]]{2}.[[:digit:]]{3}: `) |
| 139 | + |
| 140 | +func stripTimes(in string) string { |
| 141 | + return timePrefix.ReplaceAllString(in, "") |
| 142 | +} |
| 143 | + |
| 144 | +// instanceAddr matches " | 0xc0003dec60>" |
| 145 | +var instanceAddr = regexp.MustCompile(` \| 0x[0-9a-fA-F]+>`) |
| 146 | + |
| 147 | +func stripAddresses(in string) string { |
| 148 | + return instanceAddr.ReplaceAllString(in, ">") |
| 149 | +} |
| 150 | + |
| 151 | +// stackLocation matches "<some path>/<file>.go:75 +0x1f1" after a slash (built |
| 152 | +// locally) or one of a few relative paths (built in the Kubernetes CI). |
| 153 | +var stackLocation = regexp.MustCompile(`(?:/|vendor/|test/|GOROOT/).*/([[:^space:]]+.go:[[:digit:]]+)( \+0x[0-9a-fA-F]+)?`) |
| 154 | + |
| 155 | +// functionArgs matches "<function name>(...)". |
| 156 | +var functionArgs = regexp.MustCompile(`([[:alpha:]]+)\(.*\)`) |
| 157 | + |
| 158 | +// testingStackEntries matches "testing.tRunner" and "created by" entries. |
| 159 | +var testingStackEntries = regexp.MustCompile(`(?m)(?:testing\.|created by).*\n\t.*\n`) |
| 160 | + |
| 161 | +// normalizeLocation removes path prefix and function parameters and certain stack entries |
| 162 | +// that we don't care about. |
| 163 | +func normalizeLocation(in string) string { |
| 164 | + out := in |
| 165 | + out = stackLocation.ReplaceAllString(out, "$1") |
| 166 | + out = functionArgs.ReplaceAllString(out, "$1()") |
| 167 | + out = testingStackEntries.ReplaceAllString(out, "") |
| 168 | + return out |
| 169 | +} |
0 commit comments