mirror of
https://github.com/k3s-io/kubernetes.git
synced 2025-07-20 02:11:09 +00:00
e2e: unit test for logger.go and ginkgowrapper.go
This test runs a fake Ginkgo suite with various errors and checks how
logger.go respectively ginkgowrapper.go handle this. Right now, the
outcome is sub-optimal:
- some test failures (those that use framework.Failf or
framework.ExpectNoError) are logged immediately, Gomega failures
are not
- framework.ExpectNoError logs just the error, which is often useless
without the additional explanation
- failures that occur after some others are not reported at all;
this can happen in cleanup code and while that code should better
be written so that it contines instead of failing on an assertion,
in practice quite a lot of code fails and when it does, the output
would be useful to have
- the full stack trace is odd and doesn't start with the expected
function name
Example output:
• Failure [0.002 seconds]
log
/nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/logger_test.go:35
fails [It]
/nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/logger_test.go:39
Jul 17 12:00:52.545: I'm failing.
/nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/logger_test.go:41
Full Stack Trace
/nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/logger.go:51 +0x143
k8s.io/kubernetes/test/e2e/framework/log.Failf(...)
/nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/logger.go:43
k8s.io/kubernetes/test/e2e/framework/log_test.glob..func1.2.1(...)
/nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/logger_test.go:41
k8s.io/kubernetes/test/e2e/framework/log_test.glob..func1.2()
/nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/logger_test.go:42 +0x52
k8s.io/kubernetes/vendor/github.com/onsi/ginkgo/internal/leafnodes.(*runner).runSync(0xc00029b020, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
/nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/logger_test.go:65 +0x1c8
testing.tRunner(0xc000358600, 0x19818c0)
/nvme/gopath/go/src/testing/testing.go:865 +0xc0
created by testing.(*T).Run
/nvme/gopath/go/src/testing/testing.go:916 +0x35a
------------------------------
Jul 17 12:00:52.545: INFO: before
Jul 17 12:00:52.545: INFO: I'm failing.
Jul 17 12:00:52.547: INFO: after
• Failure [0.002 seconds]
log
/nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/logger_test.go:35
asserts [It]
/nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/logger_test.go:44
false is never true
Expected
<bool>: false
to equal
<bool>: true
/nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/logger_test.go:45
Full Stack Trace
/nvme/gopath/src/k8s.io/kubernetes/vendor/github.com/onsi/gomega/internal/assertion/assertion.go:75 +0x1f1
k8s.io/kubernetes/vendor/github.com/onsi/gomega/internal/assertion.(*Assertion).To(0xc00035f6c0, 0x1b42140, 0xc000350dd0, 0xc000350de0, 0x1, 0x1, 0x42e35f)
/nvme/gopath/src/k8s.io/kubernetes/vendor/github.com/onsi/gomega/internal/assertion/assertion.go:38 +0xc7
k8s.io/kubernetes/test/e2e/framework/log_test.glob..func1.3()
/nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/logger_test.go:45 +0x17e
k8s.io/kubernetes/vendor/github.com/onsi/ginkgo/internal/leafnodes.(*runner).runSync(0xc00029b0e0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
/nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/logger_test.go:65 +0x1c8
testing.tRunner(0xc000358600, 0x19818c0)
/nvme/gopath/go/src/testing/testing.go:865 +0xc0
created by testing.(*T).Run
/nvme/gopath/go/src/testing/testing.go:916 +0x35a
------------------------------
Jul 17 12:00:52.548: INFO: before
Jul 17 12:00:52.549: INFO: after
• Failure [0.002 seconds]
log
/nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/logger_test.go:35
error [It]
/nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/logger_test.go:47
hard-coded error
Unexpected error:
<*errors.errorString | 0xc000351930>: {
s: "I'm an error, nice to meet to.",
}
I'm an error, nice to meet to.
occurred
/nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/logger_test.go:49
Full Stack Trace
/nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/util.go:1376 +0x191
k8s.io/kubernetes/test/e2e/framework.ExpectNoError(...)
/nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/util.go:1367
k8s.io/kubernetes/test/e2e/framework/log_test.glob..func1.4()
/nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/logger_test.go:49 +0xc9
k8s.io/kubernetes/vendor/github.com/onsi/ginkgo/internal/leafnodes.(*runner).runSync(0xc00029b200, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
/nvme/gopath/src/k8s.io/kubernetes/test/e2e/framework/log/logger_test.go:65 +0x1c8
testing.tRunner(0xc000358600, 0x19818c0)
/nvme/gopath/go/src/testing/testing.go:865 +0xc0
created by testing.(*T).Run
/nvme/gopath/go/src/testing/testing.go:916 +0x35a
------------------------------
Jul 17 12:00:52.550: INFO: before
Jul 17 12:00:52.550: INFO: Unexpected error occurred: I'm an error, nice to meet to.
Jul 17 12:00:52.551: INFO: after
This commit is contained in:
Patrick Ohly
parent
8a2def5b51
commit
311b66ada1
158
test/e2e/framework/log/logger_test.go
Normal file
158
test/e2e/framework/log/logger_test.go
Normal file
@ -0,0 +1,158 @@
|
|||||||
|
/*
|
||||||
|
Copyright 2019 The Kubernetes Authors.
|
||||||
|
|
||||||
|
Licensed under the Apache License, Version 2.0 (the "License");
|
||||||
|
you may not use this file except in compliance with the License.
|
||||||
|
You may obtain a copy of the License at
|
||||||
|
|
||||||
|
http://www.apache.org/licenses/LICENSE-2.0
|
||||||
|
|
||||||
|
Unless required by applicable law or agreed to in writing, software
|
||||||
|
distributed under the License is distributed on an "AS IS" BASIS,
|
||||||
|
WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
|
||||||
|
See the License for the specific language governing permissions and
|
||||||
|
limitations under the License.
|
||||||
|
*/
|
||||||
|
|
||||||
|
package log_test
|
||||||
|
|
||||||
|
import (
|
||||||
|
"errors"
|
||||||
|
"regexp"
|
||||||
|
"sort"
|
||||||
|
"strings"
|
||||||
|
"testing"
|
||||||
|
|
||||||
|
"github.com/onsi/ginkgo"
|
||||||
|
"github.com/onsi/ginkgo/config"
|
||||||
|
"github.com/onsi/ginkgo/reporters"
|
||||||
|
"github.com/onsi/gomega"
|
||||||
|
|
||||||
|
"k8s.io/kubernetes/test/e2e/framework"
|
||||||
|
"k8s.io/kubernetes/test/e2e/framework/ginkgowrapper"
|
||||||
|
"k8s.io/kubernetes/test/e2e/framework/log"
|
||||||
|
)
|
||||||
|
|
||||||
|
var _ = ginkgo.Describe("log", func() {
|
||||||
|
ginkgo.BeforeEach(func() {
|
||||||
|
log.Logf("before")
|
||||||
|
})
|
||||||
|
ginkgo.It("fails", func() {
|
||||||
|
func() {
|
||||||
|
log.Failf("I'm failing.")
|
||||||
|
}()
|
||||||
|
})
|
||||||
|
ginkgo.It("asserts", func() {
|
||||||
|
gomega.Expect(false).To(gomega.Equal(true), "false is never true")
|
||||||
|
})
|
||||||
|
ginkgo.It("error", func() {
|
||||||
|
err := errors.New("I'm an error, nice to meet to.")
|
||||||
|
framework.ExpectNoError(err, "hard-coded error")
|
||||||
|
})
|
||||||
|
ginkgo.AfterEach(func() {
|
||||||
|
log.Logf("after")
|
||||||
|
gomega.Expect(true).To(gomega.Equal(false), "true is never false either")
|
||||||
|
})
|
||||||
|
})
|
||||||
|
|
||||||
|
func TestFailureOutput(t *testing.T) {
|
||||||
|
// Run the Ginkgo suite with output collected by a custom
|
||||||
|
// reporter in adddition to the default one. To see what the full
|
||||||
|
// Ginkgo report looks like, run this test with "go test -v".
|
||||||
|
config.DefaultReporterConfig.FullTrace = true
|
||||||
|
gomega.RegisterFailHandler(ginkgowrapper.Fail)
|
||||||
|
fakeT := &testing.T{}
|
||||||
|
reporter := reporters.NewFakeReporter()
|
||||||
|
ginkgo.RunSpecsWithDefaultAndCustomReporters(fakeT, "Logging Suite", []ginkgo.Reporter{reporter})
|
||||||
|
|
||||||
|
// Now check the output.
|
||||||
|
g := gomega.NewGomegaWithT(t)
|
||||||
|
g.Expect(normalizeReport(*reporter)).To(gomega.Equal(suiteResults{
|
||||||
|
testResult{
|
||||||
|
name: "[Top Level] log asserts",
|
||||||
|
// TODO: also log the failed assertion as it happens
|
||||||
|
output: "INFO: before\nINFO: after\n",
|
||||||
|
failure: "false is never true\nExpected\n <bool>: false\nto equal\n <bool>: true",
|
||||||
|
// TODO: ginkowrapper.Fail should also prune this stack.
|
||||||
|
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:46\nk8s.io/kubernetes/vendor/github.com/onsi/ginkgo/internal/leafnodes.(*runner).runSync()\n\tlogger_test.go:66\n",
|
||||||
|
},
|
||||||
|
testResult{
|
||||||
|
name: "[Top Level] log error",
|
||||||
|
// TODO: the additional information about the error should be logged
|
||||||
|
output: "INFO: before\nINFO: Unexpected error occurred: I'm an error, nice to meet to.\nINFO: after\n",
|
||||||
|
failure: "hard-coded error\nUnexpected error:\n <*errors.errorString>: {\n s: \"I'm an error, nice to meet to.\",\n }\n I'm an error, nice to meet to.\noccurred",
|
||||||
|
// TODO: ginkowrapper.Fail should also prune this stack.
|
||||||
|
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",
|
||||||
|
},
|
||||||
|
testResult{
|
||||||
|
name: "[Top Level] log fails",
|
||||||
|
// TODO: why is the failure log as "INFO"?
|
||||||
|
output: "INFO: before\nINFO: I'm failing.\nINFO: after\n",
|
||||||
|
failure: "I'm failing.",
|
||||||
|
// TODO: ginkowrapper.Fail should also prune this stack.
|
||||||
|
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",
|
||||||
|
},
|
||||||
|
}))
|
||||||
|
}
|
||||||
|
|
||||||
|
type testResult struct {
|
||||||
|
name string
|
||||||
|
// output written to GinkgoWriter during test.
|
||||||
|
output string
|
||||||
|
// failure is SpecSummary.Failure.Message with varying parts stripped.
|
||||||
|
failure string
|
||||||
|
// stack is a normalized version (just file names, function parametes stripped) of
|
||||||
|
// Ginkgo's FullStackTrace of a failure. Empty if no failure.
|
||||||
|
stack string
|
||||||
|
}
|
||||||
|
|
||||||
|
type suiteResults []testResult
|
||||||
|
|
||||||
|
func normalizeReport(report reporters.FakeReporter) suiteResults {
|
||||||
|
var results suiteResults
|
||||||
|
for _, spec := range report.SpecSummaries {
|
||||||
|
results = append(results, testResult{
|
||||||
|
name: strings.Join(spec.ComponentTexts, " "),
|
||||||
|
output: stripAddresses(stripTimes(spec.CapturedOutput)),
|
||||||
|
failure: stripAddresses(stripTimes(spec.Failure.Message)),
|
||||||
|
stack: normalizeLocation(spec.Failure.Location.FullStackTrace),
|
||||||
|
})
|
||||||
|
}
|
||||||
|
sort.Slice(results, func(i, j int) bool {
|
||||||
|
return strings.Compare(results[i].name, results[j].name) < 0
|
||||||
|
})
|
||||||
|
return results
|
||||||
|
}
|
||||||
|
|
||||||
|
// timePrefix matches "Jul 17 08:08:25.950: " at the beginning of each line.
|
||||||
|
var timePrefix = regexp.MustCompile(`(?m)^[[:alpha:]]{3} [[:digit:]]{1,2} [[:digit:]]{2}:[[:digit:]]{2}:[[:digit:]]{2}.[[:digit:]]{3}: `)
|
||||||
|
|
||||||
|
func stripTimes(in string) string {
|
||||||
|
return timePrefix.ReplaceAllString(in, "")
|
||||||
|
}
|
||||||
|
|
||||||
|
// instanceAddr matches " | 0xc0003dec60>"
|
||||||
|
var instanceAddr = regexp.MustCompile(` \| 0x[0-9a-fA-F]+>`)
|
||||||
|
|
||||||
|
func stripAddresses(in string) string {
|
||||||
|
return instanceAddr.ReplaceAllString(in, ">")
|
||||||
|
}
|
||||||
|
|
||||||
|
// stackLocation matches "\t/<some path>/<file>.go:75 +0x1f1".
|
||||||
|
var stackLocation = regexp.MustCompile(`/.*/([[:^space:]]+.go:[[:digit:]]+)( \+0x[0-9a-fA-F]+)?`)
|
||||||
|
|
||||||
|
// functionArgs matches "<function name>(...)".
|
||||||
|
var functionArgs = regexp.MustCompile(`([[:alpha:]]+)\(.*\)`)
|
||||||
|
|
||||||
|
// testingStackEntries matches "testing.tRunner" and "created by" entries.
|
||||||
|
var testingStackEntries = regexp.MustCompile(`(?m)(?:testing\.|created by).*\n\t.*\n`)
|
||||||
|
|
||||||
|
// normalizeLocation removes path prefix and function parameters and certain stack entries
|
||||||
|
// that we don't care about.
|
||||||
|
func normalizeLocation(in string) string {
|
||||||
|
out := in
|
||||||
|
out = stackLocation.ReplaceAllString(out, "$1")
|
||||||
|
out = functionArgs.ReplaceAllString(out, "$1()")
|
||||||
|
out = testingStackEntries.ReplaceAllString(out, "")
|
||||||
|
return out
|
||||||
|
}
|
||||||
Loading…
Reference in New Issue
Block a user