kubernetes/test/utils/ktesting/stepcontext_test.go

138 lines
3.9 KiB
Go
Raw Normal View History

/*
Copyright 2024 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 ktesting
import (
ktesting: abort entire test suite on SIGINT When aborting an integration test with CTRL-C while it runs, the current test fails and etcd exits. But additional tests were still being started and the failed slowly because they couldn't connect to etcd. It's better to fail additional tests in ktesting.Init when the test run has already been interrupted. While at it, also make it a bit more obvious that testing was interrupted by logging it and update one comment about this and clean up the naming of contexts in the code. Example: $ go test -v ./test/integration/quota ... I1106 11:42:48.857162 147325 etcd.go:416] "Not using watch cache" resource="events.events.k8s.io" I1106 11:42:48.857204 147325 handler.go:286] Adding GroupVersion events.k8s.io v1 to ResourceManager W1106 11:42:48.857209 147325 genericapiserver.go:765] Skipping API events.k8s.io/v1beta1 because it has no resources. ^C INFO: canceling test context: received interrupt signal {"level":"warn","ts":"2024-11-06T11:42:48.984676+0100","caller":"embed/serve.go:160","msg":"stopping insecure grpc server due to error","error":"accept tcp 127.0.0.1:44177: use of closed network connection"} ... I1106 11:42:50.042430 147325 handler.go:142] kube-apiserver: GET "/apis/rbac.authorization.k8s.io/v1/clusterroles" satisfied by gorestful with webservice /apis/rbac.authorization.k8s.io/v1 test_server.go:241: timed out waiting for the condition --- FAIL: TestQuota (11.45s) === RUN TestQuotaLimitedResourceDenial quota_test.go:292: testing has been interrupted: received interrupt signal --- FAIL: TestQuotaLimitedResourceDenial (0.00s) === RUN TestQuotaLimitService quota_test.go:418: testing has been interrupted: received interrupt signal --- FAIL: TestQuotaLimitService (0.00s) FAIL
2024-11-06 05:04:45 -05:00
"context"
"io"
"os"
"testing"
ktesting: abort entire test suite on SIGINT When aborting an integration test with CTRL-C while it runs, the current test fails and etcd exits. But additional tests were still being started and the failed slowly because they couldn't connect to etcd. It's better to fail additional tests in ktesting.Init when the test run has already been interrupted. While at it, also make it a bit more obvious that testing was interrupted by logging it and update one comment about this and clean up the naming of contexts in the code. Example: $ go test -v ./test/integration/quota ... I1106 11:42:48.857162 147325 etcd.go:416] "Not using watch cache" resource="events.events.k8s.io" I1106 11:42:48.857204 147325 handler.go:286] Adding GroupVersion events.k8s.io v1 to ResourceManager W1106 11:42:48.857209 147325 genericapiserver.go:765] Skipping API events.k8s.io/v1beta1 because it has no resources. ^C INFO: canceling test context: received interrupt signal {"level":"warn","ts":"2024-11-06T11:42:48.984676+0100","caller":"embed/serve.go:160","msg":"stopping insecure grpc server due to error","error":"accept tcp 127.0.0.1:44177: use of closed network connection"} ... I1106 11:42:50.042430 147325 handler.go:142] kube-apiserver: GET "/apis/rbac.authorization.k8s.io/v1/clusterroles" satisfied by gorestful with webservice /apis/rbac.authorization.k8s.io/v1 test_server.go:241: timed out waiting for the condition --- FAIL: TestQuota (11.45s) === RUN TestQuotaLimitedResourceDenial quota_test.go:292: testing has been interrupted: received interrupt signal --- FAIL: TestQuotaLimitedResourceDenial (0.00s) === RUN TestQuotaLimitService quota_test.go:418: testing has been interrupted: received interrupt signal --- FAIL: TestQuotaLimitService (0.00s) FAIL
2024-11-06 05:04:45 -05:00
"time"
"github.com/onsi/gomega"
"go.uber.org/goleak"
)
func TestStepContext(t *testing.T) {
for name, tc := range map[string]testcase{
"output": {
cb: func(tCtx TContext) {
tCtx = tCtx.WithStep("step")
tCtx.Log("Log", "a", "b", 42)
tCtx.Logf("Logf %s %s %d", "a", "b", 42)
tCtx.Error("Error", "a", "b", 42)
tCtx.Errorf("Errorf %s %s %d", "a", "b", 42)
},
expectTrace: `(LOG) <klog header>: step: Log a b 42
(LOG) <klog header>: step: Logf a b 42
ktesting: reimplement without interface The original implementation was inspired by how context.Context is handled via wrapping a parent context. That approach had several issues: - It is useful to let users call methods (e.g. tCtx.ExpectNoError) instead of ktesting functions with a tCtx parameters, but that only worked if all implementations of the interface implemented that set of methods. This made extending those methods cumbersome (see the commit which added Require+Assert) and could potentially break implementations of the interface elsewhere, defeating part of the motivation for having the interface in the first place. - It was hard to see how the different TContext wrappers cooperated with each other. - Layering injection of "ERROR" and "FATAL ERROR" on top of prefixing with the klog header caused post-processing of a failed unit test to remove that line because it looked like log output. Other log output lines where kept because they were not indented. - In Go <=1.25, the `go vet sprintf` check only works for functions and methods if they get called directly and themselves directly pass their parameters on to fmt.Sprint. The check does not work when calling methods through an interface. Support for that is coming in Go 1.26, but will depend on bumping the Go version also in go.mod and thus may not be immediately possible in Kubernetes. - Interface documentation in https://pkg.go.dev/k8s.io/kubernetes@v1.34.2/test/utils/ktesting#TContext is a monolithic text block. Documentation for methods is more readable and allows referencing those methods with [] (e.g. [TC.Errorf] works, [TContext.Errorf] didn't). The revised implementation is a single struct with (almost) no exported fields. The two exceptions (embedded context.Context and TB) are useful because it avoids having to write wrappers for several functions resp. necessary because Helper cannot be wrapped. Like a logr.LogSink, With* methods can make a shallow copy and then change some fields in the cloned instance. The former `ktesting.TContext` interface is now a type alias for `*ktesting.TC`. This ensures that existing code using ktesting doesn't need to be updated and because that code is a bit more compact (`tCtx ktesting.TContext` instead of `tCtx *ktesting.TContext` when not using such an alias). Hiding that it is a pointer might discourage accessing the exported fields because it looks like an interface. Output gets fixed and improved such that: - "FATAL ERROR" and "ERROR" are at the start of the line, followed by the klog header. - The failure message follows in the next line. - Continuation lines are always indented. The set of methods exposed via TB is now a bit more complete (Attr, Chdir). All former stand-alone With* functions are now also available as methods and should be used instead of the functions. Those will be removed. Linting of log calls now works and found some issues.
2025-12-08 02:19:51 -05:00
(ERROR) ERROR: <klog header>:
step: Error a b 42
(ERROR) ERROR: <klog header>:
step: Errorf a b 42
`,
},
"fatal": {
cb: func(tCtx TContext) {
tCtx = tCtx.WithStep("step")
tCtx.Fatal("Error", "a", "b", 42)
// not reached
tCtx.Log("Log")
},
ktesting: reimplement without interface The original implementation was inspired by how context.Context is handled via wrapping a parent context. That approach had several issues: - It is useful to let users call methods (e.g. tCtx.ExpectNoError) instead of ktesting functions with a tCtx parameters, but that only worked if all implementations of the interface implemented that set of methods. This made extending those methods cumbersome (see the commit which added Require+Assert) and could potentially break implementations of the interface elsewhere, defeating part of the motivation for having the interface in the first place. - It was hard to see how the different TContext wrappers cooperated with each other. - Layering injection of "ERROR" and "FATAL ERROR" on top of prefixing with the klog header caused post-processing of a failed unit test to remove that line because it looked like log output. Other log output lines where kept because they were not indented. - In Go <=1.25, the `go vet sprintf` check only works for functions and methods if they get called directly and themselves directly pass their parameters on to fmt.Sprint. The check does not work when calling methods through an interface. Support for that is coming in Go 1.26, but will depend on bumping the Go version also in go.mod and thus may not be immediately possible in Kubernetes. - Interface documentation in https://pkg.go.dev/k8s.io/kubernetes@v1.34.2/test/utils/ktesting#TContext is a monolithic text block. Documentation for methods is more readable and allows referencing those methods with [] (e.g. [TC.Errorf] works, [TContext.Errorf] didn't). The revised implementation is a single struct with (almost) no exported fields. The two exceptions (embedded context.Context and TB) are useful because it avoids having to write wrappers for several functions resp. necessary because Helper cannot be wrapped. Like a logr.LogSink, With* methods can make a shallow copy and then change some fields in the cloned instance. The former `ktesting.TContext` interface is now a type alias for `*ktesting.TC`. This ensures that existing code using ktesting doesn't need to be updated and because that code is a bit more compact (`tCtx ktesting.TContext` instead of `tCtx *ktesting.TContext` when not using such an alias). Hiding that it is a pointer might discourage accessing the exported fields because it looks like an interface. Output gets fixed and improved such that: - "FATAL ERROR" and "ERROR" are at the start of the line, followed by the klog header. - The failure message follows in the next line. - Continuation lines are always indented. The set of methods exposed via TB is now a bit more complete (Attr, Chdir). All former stand-alone With* functions are now also available as methods and should be used instead of the functions. Those will be removed. Linting of log calls now works and found some issues.
2025-12-08 02:19:51 -05:00
expectTrace: `(FATAL) FATAL ERROR: <klog header>:
step: Error a b 42
`,
},
"fatalf": {
cb: func(tCtx TContext) {
tCtx = tCtx.WithStep("step")
tCtx.Fatalf("Error %s %s %d", "a", "b", 42)
// not reached
tCtx.Log("Log")
},
ktesting: reimplement without interface The original implementation was inspired by how context.Context is handled via wrapping a parent context. That approach had several issues: - It is useful to let users call methods (e.g. tCtx.ExpectNoError) instead of ktesting functions with a tCtx parameters, but that only worked if all implementations of the interface implemented that set of methods. This made extending those methods cumbersome (see the commit which added Require+Assert) and could potentially break implementations of the interface elsewhere, defeating part of the motivation for having the interface in the first place. - It was hard to see how the different TContext wrappers cooperated with each other. - Layering injection of "ERROR" and "FATAL ERROR" on top of prefixing with the klog header caused post-processing of a failed unit test to remove that line because it looked like log output. Other log output lines where kept because they were not indented. - In Go <=1.25, the `go vet sprintf` check only works for functions and methods if they get called directly and themselves directly pass their parameters on to fmt.Sprint. The check does not work when calling methods through an interface. Support for that is coming in Go 1.26, but will depend on bumping the Go version also in go.mod and thus may not be immediately possible in Kubernetes. - Interface documentation in https://pkg.go.dev/k8s.io/kubernetes@v1.34.2/test/utils/ktesting#TContext is a monolithic text block. Documentation for methods is more readable and allows referencing those methods with [] (e.g. [TC.Errorf] works, [TContext.Errorf] didn't). The revised implementation is a single struct with (almost) no exported fields. The two exceptions (embedded context.Context and TB) are useful because it avoids having to write wrappers for several functions resp. necessary because Helper cannot be wrapped. Like a logr.LogSink, With* methods can make a shallow copy and then change some fields in the cloned instance. The former `ktesting.TContext` interface is now a type alias for `*ktesting.TC`. This ensures that existing code using ktesting doesn't need to be updated and because that code is a bit more compact (`tCtx ktesting.TContext` instead of `tCtx *ktesting.TContext` when not using such an alias). Hiding that it is a pointer might discourage accessing the exported fields because it looks like an interface. Output gets fixed and improved such that: - "FATAL ERROR" and "ERROR" are at the start of the line, followed by the klog header. - The failure message follows in the next line. - Continuation lines are always indented. The set of methods exposed via TB is now a bit more complete (Attr, Chdir). All former stand-alone With* functions are now also available as methods and should be used instead of the functions. Those will be removed. Linting of log calls now works and found some issues.
2025-12-08 02:19:51 -05:00
expectTrace: `(FATAL) FATAL ERROR: <klog header>:
step: Error a b 42
`,
},
} {
t.Run(name, func(t *testing.T) {
tc.run(t)
})
}
}
func TestProgressReport(t *testing.T) {
oldOut := defaultProgressReporter.out
ktesting: abort entire test suite on SIGINT When aborting an integration test with CTRL-C while it runs, the current test fails and etcd exits. But additional tests were still being started and the failed slowly because they couldn't connect to etcd. It's better to fail additional tests in ktesting.Init when the test run has already been interrupted. While at it, also make it a bit more obvious that testing was interrupted by logging it and update one comment about this and clean up the naming of contexts in the code. Example: $ go test -v ./test/integration/quota ... I1106 11:42:48.857162 147325 etcd.go:416] "Not using watch cache" resource="events.events.k8s.io" I1106 11:42:48.857204 147325 handler.go:286] Adding GroupVersion events.k8s.io v1 to ResourceManager W1106 11:42:48.857209 147325 genericapiserver.go:765] Skipping API events.k8s.io/v1beta1 because it has no resources. ^C INFO: canceling test context: received interrupt signal {"level":"warn","ts":"2024-11-06T11:42:48.984676+0100","caller":"embed/serve.go:160","msg":"stopping insecure grpc server due to error","error":"accept tcp 127.0.0.1:44177: use of closed network connection"} ... I1106 11:42:50.042430 147325 handler.go:142] kube-apiserver: GET "/apis/rbac.authorization.k8s.io/v1/clusterroles" satisfied by gorestful with webservice /apis/rbac.authorization.k8s.io/v1 test_server.go:241: timed out waiting for the condition --- FAIL: TestQuota (11.45s) === RUN TestQuotaLimitedResourceDenial quota_test.go:292: testing has been interrupted: received interrupt signal --- FAIL: TestQuotaLimitedResourceDenial (0.00s) === RUN TestQuotaLimitService quota_test.go:418: testing has been interrupted: received interrupt signal --- FAIL: TestQuotaLimitService (0.00s) FAIL
2024-11-06 05:04:45 -05:00
out := newOutputStream()
defaultProgressReporter.out = out
t.Cleanup(func() {
ktesting: abort entire test suite on SIGINT When aborting an integration test with CTRL-C while it runs, the current test fails and etcd exits. But additional tests were still being started and the failed slowly because they couldn't connect to etcd. It's better to fail additional tests in ktesting.Init when the test run has already been interrupted. While at it, also make it a bit more obvious that testing was interrupted by logging it and update one comment about this and clean up the naming of contexts in the code. Example: $ go test -v ./test/integration/quota ... I1106 11:42:48.857162 147325 etcd.go:416] "Not using watch cache" resource="events.events.k8s.io" I1106 11:42:48.857204 147325 handler.go:286] Adding GroupVersion events.k8s.io v1 to ResourceManager W1106 11:42:48.857209 147325 genericapiserver.go:765] Skipping API events.k8s.io/v1beta1 because it has no resources. ^C INFO: canceling test context: received interrupt signal {"level":"warn","ts":"2024-11-06T11:42:48.984676+0100","caller":"embed/serve.go:160","msg":"stopping insecure grpc server due to error","error":"accept tcp 127.0.0.1:44177: use of closed network connection"} ... I1106 11:42:50.042430 147325 handler.go:142] kube-apiserver: GET "/apis/rbac.authorization.k8s.io/v1/clusterroles" satisfied by gorestful with webservice /apis/rbac.authorization.k8s.io/v1 test_server.go:241: timed out waiting for the condition --- FAIL: TestQuota (11.45s) === RUN TestQuotaLimitedResourceDenial quota_test.go:292: testing has been interrupted: received interrupt signal --- FAIL: TestQuotaLimitedResourceDenial (0.00s) === RUN TestQuotaLimitService quota_test.go:418: testing has been interrupted: received interrupt signal --- FAIL: TestQuotaLimitService (0.00s) FAIL
2024-11-06 05:04:45 -05:00
goleak.VerifyNone(t)
defaultProgressReporter.out = oldOut
ktesting: abort entire test suite on SIGINT When aborting an integration test with CTRL-C while it runs, the current test fails and etcd exits. But additional tests were still being started and the failed slowly because they couldn't connect to etcd. It's better to fail additional tests in ktesting.Init when the test run has already been interrupted. While at it, also make it a bit more obvious that testing was interrupted by logging it and update one comment about this and clean up the naming of contexts in the code. Example: $ go test -v ./test/integration/quota ... I1106 11:42:48.857162 147325 etcd.go:416] "Not using watch cache" resource="events.events.k8s.io" I1106 11:42:48.857204 147325 handler.go:286] Adding GroupVersion events.k8s.io v1 to ResourceManager W1106 11:42:48.857209 147325 genericapiserver.go:765] Skipping API events.k8s.io/v1beta1 because it has no resources. ^C INFO: canceling test context: received interrupt signal {"level":"warn","ts":"2024-11-06T11:42:48.984676+0100","caller":"embed/serve.go:160","msg":"stopping insecure grpc server due to error","error":"accept tcp 127.0.0.1:44177: use of closed network connection"} ... I1106 11:42:50.042430 147325 handler.go:142] kube-apiserver: GET "/apis/rbac.authorization.k8s.io/v1/clusterroles" satisfied by gorestful with webservice /apis/rbac.authorization.k8s.io/v1 test_server.go:241: timed out waiting for the condition --- FAIL: TestQuota (11.45s) === RUN TestQuotaLimitedResourceDenial quota_test.go:292: testing has been interrupted: received interrupt signal --- FAIL: TestQuotaLimitedResourceDenial (0.00s) === RUN TestQuotaLimitService quota_test.go:418: testing has been interrupted: received interrupt signal --- FAIL: TestQuotaLimitService (0.00s) FAIL
2024-11-06 05:04:45 -05:00
// If we get here, the defaultProgressReporter is not active anymore,
// but the interrupt context should still be canceled.
gomega.NewGomegaWithT(t).Expect(defaultProgressReporter.usageCount).To(gomega.Equal(int64(0)), "usage count")
gomega.NewGomegaWithT(t).Expect(context.Cause(interruptCtx)).To(gomega.MatchError(gomega.Equal("received interrupt signal")), "interrupted persistently")
// Reset for next test.
interruptCtx, interrupted = context.WithCancelCause(context.Background())
})
// This must use a real testing.T, otherwise Init doesn't initialize signal handling.
tCtx := Init(t)
tCtx = tCtx.WithStep("step")
removeReporter := tCtx.Value("GINKGO_SPEC_CONTEXT").(ginkgoReporter).AttachProgressReporter(func() string { return "hello world" })
defer removeReporter()
tCtx.Expect(tCtx.Value("some other key")).To(gomega.BeNil(), "value for unknown context value key")
// Trigger report and wait for it.
defaultProgressReporter.progressChannel <- os.Interrupt
ktesting: abort entire test suite on SIGINT When aborting an integration test with CTRL-C while it runs, the current test fails and etcd exits. But additional tests were still being started and the failed slowly because they couldn't connect to etcd. It's better to fail additional tests in ktesting.Init when the test run has already been interrupted. While at it, also make it a bit more obvious that testing was interrupted by logging it and update one comment about this and clean up the naming of contexts in the code. Example: $ go test -v ./test/integration/quota ... I1106 11:42:48.857162 147325 etcd.go:416] "Not using watch cache" resource="events.events.k8s.io" I1106 11:42:48.857204 147325 handler.go:286] Adding GroupVersion events.k8s.io v1 to ResourceManager W1106 11:42:48.857209 147325 genericapiserver.go:765] Skipping API events.k8s.io/v1beta1 because it has no resources. ^C INFO: canceling test context: received interrupt signal {"level":"warn","ts":"2024-11-06T11:42:48.984676+0100","caller":"embed/serve.go:160","msg":"stopping insecure grpc server due to error","error":"accept tcp 127.0.0.1:44177: use of closed network connection"} ... I1106 11:42:50.042430 147325 handler.go:142] kube-apiserver: GET "/apis/rbac.authorization.k8s.io/v1/clusterroles" satisfied by gorestful with webservice /apis/rbac.authorization.k8s.io/v1 test_server.go:241: timed out waiting for the condition --- FAIL: TestQuota (11.45s) === RUN TestQuotaLimitedResourceDenial quota_test.go:292: testing has been interrupted: received interrupt signal --- FAIL: TestQuotaLimitedResourceDenial (0.00s) === RUN TestQuotaLimitService quota_test.go:418: testing has been interrupted: received interrupt signal --- FAIL: TestQuotaLimitService (0.00s) FAIL
2024-11-06 05:04:45 -05:00
report := <-out.stream
tCtx.Expect(report).To(gomega.Equal(`You requested a progress report.
step: hello world
`), "report")
ktesting: abort entire test suite on SIGINT When aborting an integration test with CTRL-C while it runs, the current test fails and etcd exits. But additional tests were still being started and the failed slowly because they couldn't connect to etcd. It's better to fail additional tests in ktesting.Init when the test run has already been interrupted. While at it, also make it a bit more obvious that testing was interrupted by logging it and update one comment about this and clean up the naming of contexts in the code. Example: $ go test -v ./test/integration/quota ... I1106 11:42:48.857162 147325 etcd.go:416] "Not using watch cache" resource="events.events.k8s.io" I1106 11:42:48.857204 147325 handler.go:286] Adding GroupVersion events.k8s.io v1 to ResourceManager W1106 11:42:48.857209 147325 genericapiserver.go:765] Skipping API events.k8s.io/v1beta1 because it has no resources. ^C INFO: canceling test context: received interrupt signal {"level":"warn","ts":"2024-11-06T11:42:48.984676+0100","caller":"embed/serve.go:160","msg":"stopping insecure grpc server due to error","error":"accept tcp 127.0.0.1:44177: use of closed network connection"} ... I1106 11:42:50.042430 147325 handler.go:142] kube-apiserver: GET "/apis/rbac.authorization.k8s.io/v1/clusterroles" satisfied by gorestful with webservice /apis/rbac.authorization.k8s.io/v1 test_server.go:241: timed out waiting for the condition --- FAIL: TestQuota (11.45s) === RUN TestQuotaLimitedResourceDenial quota_test.go:292: testing has been interrupted: received interrupt signal --- FAIL: TestQuotaLimitedResourceDenial (0.00s) === RUN TestQuotaLimitService quota_test.go:418: testing has been interrupted: received interrupt signal --- FAIL: TestQuotaLimitService (0.00s) FAIL
2024-11-06 05:04:45 -05:00
gomega.NewGomegaWithT(t).Expect(context.Cause(interruptCtx)).To(gomega.Succeed(), "not interrupted yet")
defaultProgressReporter.signalChannel <- os.Interrupt
message := <-out.stream
tCtx.Expect(message).To(gomega.Equal(`
INFO: canceling test context: received interrupt signal
`))
gomega.NewGomegaWithT(t).Eventually(func() error { return context.Cause(tCtx) }).WithTimeout(30*time.Second).To(gomega.MatchError(gomega.Equal("received interrupt signal")), "interrupted")
}
// outputStream forwards exactly one Write call to a stream.
// A second Write call is an error and will panic.
type outputStream struct {
stream chan string
}
var _ io.Writer = &outputStream{}
func newOutputStream() *outputStream {
return &outputStream{
stream: make(chan string),
}
}
func (s *outputStream) Write(buf []byte) (int, error) {
s.stream <- string(buf)
return len(buf), nil
}