This continues the work in
https://github.com/kubernetes/kubernetes/pull/81426 by also moving the
logger_test.go, moving the log helper code from util.go to log.go (a
more logical place, as it is only used there) and updating comments.
After merging
259bb3bef5 (diff-eb7b79470992813ea1905e96c298b47b)
ExpectEqual and some of the other wrappers logged the failure twice,
once inside the wrapper itself and once in the failure handler.
Logging the stack backtrace is useful because many assertions still
don't contain an explanation and therefore knowing where they occur is
crucial. Now all failures are logged with a "Full Stack Trace", not
just those with a wrapper. The stack is pruned to skip over wrapper
functions and removes Ginkgo internal functions to keep the stack
trace smaller.
Failures occuring in the wrappers were recorded as occuring in those
wrappers. Now the wrappers are skipped and the caller is recorded
instead.
The full stack trace recorded by Ginkgo 1.10.0 is currently off by one
entry. This needs to be fixed in Ginkgo, then the test can be updated.
Ginkgo 1.10.0 includes the relevant fix for dumping the full stack
(https://github.com/onsi/ginkgo/pull/590), so when using that release
we can simplify the logging unit test.
By changing the skipping, we can avoid the rather volatile util.go
entries. However, that gomega is part of the stack trace still needs
to be fixed in Gingko.
it turns out that the framework.TestContext.IPFamily variable is
not available for the DNS tests if they don't run in the initial
Ginkgo node when running in parallel.
We add a function to the framework to allow us to run command
only once per each Ginkgo node parallel execution.
It also adds a method to detect if the cluster is IPv6.
The use of the framework.TestContext.IPFamily variable guarantees
consistency all over the testing because this variable is only
assigned at the beginning of the testing.
Source code paths during //test/e2e/framework/log:go_default_test in
the Kubernetes CI start with relative paths. To avoid too broad
matching of the regex, those paths that occur in practice are named
explicitly as alternatives to the leading slash.
All failures are worth logging immediately, not just unexpected
errors. That helps understand tests that have long-running cleanup
operations with their own logging, because the failure will be visible
inside the test output.
The logging in framework.ExpectNoError also was rather poor, because
it only showed the error, but not the additional information about it.
Tests suites now should use log.Fail as Gomega failure handler instead
of ginkgowrapper.Fail. log.Fail will handle the logging for all
failures before proceeding to record the failure in Ginkgo.
Because logging is always done also after a test failure, additional
failures during cleanup are now visible. Ginkgo itself just ignores
them.
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
We tried to separate logger functionality as subpackage of e2e test
framework, but we've recognized that should be core functionality
and we should keep it as core of e2e test framework after facing
circular dependency issues.
So this adds log.go back to core of e2e test framework. In addition,
this makes volume sub package use the core logger as a sample.
