Skip to content

Commit

Permalink
writing-good-e2e-tests.md: polling, contexts and failure messages
Browse files Browse the repository at this point in the history 
This reflects the recent changes that came with Ginkgo v2.
  • Loading branch information
@pohly
pohly committed Mar 1, 2023
1 parent 0380da7 commit bf8b4d5
Showing 1 changed file with 316 additions and 4 deletions.
320 changes: 316 additions & 4 deletions contributors/devel/sig-testing/writing-good-e2e-tests.md
View file
Original file line number Diff line number Diff line change
Expand Up @@ -25,8 +25,22 @@ time, and delayed merges.

#### Debuggability ####

If your test fails, it should provide as detailed as possible reasons
for the failure in its output. "Timeout" is not a useful error
If your test fails, it should provide as detailed as possible reasons for the
failure in its failure message. The failure message is the string that gets
passed (directly or indirectly) to `ginkgo.Fail(f)`. That text is what gets
shown in the overview of failed tests for a Prow job and what gets aggregated
by https://go.k8s.io/triage.

A good failure message:
- identifies the test failure
- has enough details to provide some initial understanding of what went wrong

It's okay for it to contain information that changes during each test
run. Aggregation [simplifies the failure message with regular
expressions](https://github.com/kubernetes/test-infra/blob/d56bc333ae8acf176887a3249f750e7a8e0377f0/triage/summarize/text.go#L39-L69)
before looking for similar failures.

"Timeout" is not a useful error
message. "Timed out after 60 seconds waiting for pod xxx to enter
running state, still in pending state" is much more useful to someone
trying to figure out why your test failed and what to do about it.
Expand All @@ -38,17 +52,315 @@ like the following generates rather useless errors:
Expect(err).NotTo(HaveOccurred())
```

Rather
Errors returned by client-go can be very detailed. A better way to test for
errors is with `framework.ExpectNoError` because it logs the full error and
then includes only the shorter `err.Error()` in the failure message. To make
that failure message more informative,
[annotate](https://onsi.github.io/gomega/#annotating-assertions) your assertion with something like this:

```
Expect(err).NotTo(HaveOccurred(), "Failed to create %d foobars, only created %d", foobarsReqd, foobarsCreated)
framework.ExpectNoError(err, "tried creating %d foobars, only created %d", foobarsReqd, foobarsCreated)
```

On the other hand, overly verbose logging, particularly of non-error conditions, can make
it unnecessarily difficult to figure out whether a test failed and if
so why? So don't log lots of irrelevant stuff either.

Except for this special case, using Gomega assertions directly is
encouraged. They are more versatile than the (few) wrappers that were added to
the E2E framework. Use assertions that match the check in the test. Using Go
code to evaluate some condition and then checking the result often isn't
informative. For example this check should be avoided:

```
gomega.Expect(strings.Contains(actualStr, expectedSubStr)).To(gomega.Equal(true))
```

Better pass both values to Gomega, which will automatically include them in the
failure message. Add an annotation that explains what the assertion is about:

```
gomega.Expect(actualStr).To(gomega.ContainSubstring("xyz"), "checking log output")
```

This produces the following failure message:
```
[FAILED] checking log output
Expected
<string>: hello world
to contain substring
<string>: xyz
```

If there is no suitable Gomega assertion, call `ginkgo.Failf` directly:
```
import "github.com/onsi/gomega/format"
ok := someCustomCheck(abc)
if !ok {
ginkgo.Failf("check xyz failed for object:\n%s", format.Object(abc))
}
```

[Comparing a boolean](https://github.com/kubernetes/kubernetes/issues/105678)
like this against `true` or `false` with `gomega.Equal` or
`framework.ExpectEqual` is not useful because dumping the actual and expected
value just distracts from the underlying failure reason.

Dumping structs with `format.Object` is recommended. Starting with Kubernetes
1.26, `format.Object` will pretty-print Kubernetes API objects or structs [as
YAML and omit unset
fields](https://github.com/kubernetes/kubernetes/pull/113384), which is more
readable than other alternatives like `fmt.Sprintf("%+v")`.

import (
"fmt"
"k8s.io/api/core/v1"
"k8s.io/kubernetes/test/utils/format"
)

var pod v1.Pod
fmt.Printf("Printf: %+v\n\n", pod)
fmt.Printf("format.Object:\n%s", format.Object(pod, 1 /* indent one level */))

=>

Printf: {TypeMeta:{Kind: APIVersion:} ObjectMeta:{Name: GenerateName: Namespace: SelfLink: UID: ResourceVersion: Generation:0 CreationTimestamp:0001-01-01 00:00:00 +0000 UTC DeletionTimestamp:<nil> DeletionGracePeriodSeconds:<nil> Labels:map[] Annotations:map[] OwnerReferences:[] Finalizers:[] ManagedFields:[]} Spec:{Volumes:[] InitContainers:[] Containers:[] EphemeralContainers:[] RestartPolicy: TerminationGracePeriodSeconds:<nil> ActiveDeadlineSeconds:<nil> DNSPolicy: NodeSelector:map[] ServiceAccountName: DeprecatedServiceAccount: AutomountServiceAccountToken:<nil> NodeName: HostNetwork:false HostPID:false HostIPC:false ShareProcessNamespace:<nil> SecurityContext:nil ImagePullSecrets:[] Hostname: Subdomain: Affinity:nil SchedulerName: Tolerations:[] HostAliases:[] PriorityClassName: Priority:<nil> DNSConfig:nil ReadinessGates:[] RuntimeClassName:<nil> EnableServiceLinks:<nil> PreemptionPolicy:<nil> Overhead:map[] TopologySpreadConstraints:[] SetHostnameAsFQDN:<nil> OS:nil HostUsers:<nil> SchedulingGates:[] ResourceClaims:[]} Status:{Phase: Conditions:[] Message: Reason: NominatedNodeName: HostIP: PodIP: PodIPs:[] StartTime:<nil> InitContainerStatuses:[] ContainerStatuses:[] QOSClass: EphemeralContainerStatuses:[] Resize:}}

format.Object:
<v1.Pod>:
metadata:
creationTimestamp: null
spec:
containers: null
status: {}

Consider writing a [Gomega
matcher](https://onsi.github.io/gomega/#adding-your-own-matchers). It combines
the custom check and generating the failure messages and can make tests more
readable.

It is good practice to include details like the object that failed some
assertion in the failure message because then a) the information is available
when analyzing a failure that occurred in the CI and b) it only gets logged
when some assertion fails. Always dumping objects via log messages can make the
test output very large and may distract from the relevant information.

#### Recovering from test failures ####

All tests should ensure that a cluster is restored to the state that it was in
before the test ran. [`ginkgo.DeferCleanup`
](https://pkg.go.dev/github.com/onsi/ginkgo/v2#DeferCleanup) is recommended for
this because it can be called similar to `defer` directly after setting up
something. It is better than `defer` because Ginkgo will show additional
details about which cleanup code is running and (if possible) handle timeouts
for that code (see next section). Is is better than `ginkgo.AfterEach` because
it is not necessary to define additional variables and because
`ginkgo.DeferCleanup` executes code in the more useful last-in-first-out order,
i.e. things that get set up first get removed last.

Objects created in the test namespace do not need to be deleted because
deleting the namespace will also delete them. However, if deleting an object
may fail, then explicitly cleaning it up is better because then failures or
timeouts related to it will be more obvious.

In cases where the test may have removed the object, `framework.IgnoreNotFound`
can be used to ignore the "not found" error:
```
podClient := f.ClientSet.CoreV1().Pods(f.Namespace.Name)
pod, err := podClient.Create(ctx, testPod, metav1.CreateOptions{})
framework.ExpectNoError(err, "create test pod")
ginkgo.DeferCleanup(framework.IgnoreNotFound(podClient.Delete), pod.Name, metav1.DeleteOptions{})
```

#### Interrupting tests ####

When aborting a manual `gingko ./test/e2e` invocation with CTRL-C or a signal,
the currently running test(s) should stop immediately. This gets achieved by
accepting a `ctx context.Context` as first parameter in the Ginkgo callback
function and then passing that context through to all code that might
block. When Ginkgo notices that it needs to shut down, it will cancel that
context and all code trying to use it will immediately return with a `context
canceled` error. Cleanup callbacks get a new context which will time out
eventually to ensure that tests don't get stuck. For a detailed description,
see https://onsi.github.io/ginkgo/#interrupting-aborting-and-timing-out-suites.
Most of the E2E tests [were update to use the Ginkgo
context](https://github.com/kubernetes/kubernetes/pull/112923) at the start of
the 1.27 development cycle.

There are some gotchas:

- Don't use the `ctx` passed into `ginkgo.It` in a `ginkgo.DeferCleanup`
callback because the context will be canceled when the cleanup code
runs. This is wrong:

ginkgo.It("something", func(ctx context.Context) {
...
ginkgo.DeferCleanup(func() {
// do something with ctx
})
})

Instead, register a function which accepts a new context:

ginkgo.DeferCleanup(func(ctx context.Context) {
// do something with the new ctx
})

Anonymous functions can be avoided by passing some existing function and its
parameters directly to `ginkgo.DeferCleanup`. Again, beware to *not* pass the
wrong `ctx`. This is wrong:

ginkgo.It("something", func(ctx context.Context) {
...
ginkgo.DeferCleanup(myDeleteFunc, ctx, objName)
})

Instead, just pass the other parameters and let `ginkgo.DeferCleanup`
add a new context:

ginkgo.DeferCleanup(myDeleteFunc, objName)

- When starting some background goroutine in a `ginkgo.BeforeEach` callback,
use `context.WithCancel(context.Background())`. The context passed into the
callback will get canceled when the callback returns, which would cause the
background goroutine to stop before the test runs. This works:

backgroundCtx, cancel := context.WithCancel(context.Background())
ginkgo.DeferCleanup(cancel)
_, controller = cache.NewInformer( ... )
go controller.Run(backgroundCtx.Done())

- When adding a timeout to the context for one particular operation,
beware of overwriting the `ctx` variable. This code here applies
the timeout to the next call and everything else that follows:

ctx, cancel := context.WithTimeout(ctx, 5 * time.Second)
defer cancel()
someOperation(ctx)
...
anotherOperation(ctx)

Better use some other variable name:

timeoutCtx, cancel := context.WithTimeout(ctx, 5 * time.Second)
defer cancel()
someOperation(timeoutCtx)

When the intention is to set a timeout for the entire callback, use
[`ginkgo.NodeTimeout`](https://pkg.go.dev/github.com/onsi/ginkgo/v2#NodeTimeout):

ginkgo.It("something", ginkgo.NodeTimeout(30 * time.Second), func(ctx context.Context) {
})

There is also a `ginkgo.SpecTimeout`, but that then also includes the time
taken for `BeforeEach`, `AfterEach` and `DeferCleanup` callbacks.

#### Polling and timeouts ####

When waiting for something to happen, use a reasonable timeout. Without it, a
test might keep running until the entire test suite gets killed by the
CI. Beware that the CI under load may take a lot longer to complete some
operation compared to running the same test locally. On the other hand, a too
long timeout can be annoying when trying to debug tests locally.

The framework provides some [common
timeouts](https://github.com/kubernetes/kubernetes/blob/eba98af1d8b19b120e39f3/test/e2e/framework/timeouts.go#L44-L109)
through the [framework
instance](https://github.com/kubernetes/kubernetes/blob/1e84987baccbccf929eba98af1d8b19b120e39f3/test/e2e/framework/framework.go#L122-L123).
When writing a test, check whether one of those fits before defining a custom
timeout in the test.

Good code that waits for something to happen meets the following criteria:
- accepts a context for test timeouts
- informative during interactive use (i.e. intermediate reports, either
periodically or on demand)
- little to no output during a CI run except when it fails
- full explanation when it fails: when it observes some state and then
encounters errors reading the state, then dumping both the latest
observed state and the latest error is useful
- extension mechanism for writing custom checks
- early abort when condition cannot be reached anymore

[`gomega.Eventually`](https://pkg.go.dev/github.com/onsi/gomega#Eventually)
satisfies all of these criteria and therefore is recommended, but not required.
In https://github.com/kubernetes/kubernetes/pull/113298,
[test/e2e/framework/pods/wait.go](https://github.com/kubernetes/kubernetes/blob/222f65506252354da012c2e9d5457a6944a4e681/test/e2e/framework/pod/wait.go)
and the framework were modified to use gomega. Typically, `Eventually` is
passed a function which gets an object or lists several of them, then `Should`
checks against the expected result. Errors and retries specific to Kubernetes
are handled by [wrapping client-go
functions](https://github.com/kubernetes/kubernetes/blob/master/test/e2e/framework/get.go).

Using gomega assertions in helper packages is problematic for two reasons:
- The stacktrace associated with the failure starts with the helper unless
extra care is take to pass in a stack offset.
- Additional explanations for a potential failure must be prepared beforehand
and passed in.

The E2E framework therefore uses a different approach:
- [`framework.Gomega()`](https://github.com/kubernetes/kubernetes/blob/222f65506252354da012c2e9d5457a6944a4e681/test/e2e/framework/expect.go#L80-L101)
offers similar functions as the `gomega` package, except that they return a
normal error instead of failing the test.
- That error gets wrapped with `fmt.Errorf("<explanation>: %w)` to
add additional information, just as in normal Go code.
- Wrapping the error (`%w` instead of `%v`) is important because then
`framework.ExpectNoError` directly uses the error message as failure without
additional boiler plate text. It also is able to log the stacktrace where
the error occurred and not just where it was finally treated as a test
failure.

Some tips for writing and debugging long-running tests:

- Use `ginkgo.By` to record individual steps. Ginkgo will use that information
when describing where a test timed out.

- Invoke the `ginkgo` CLI with `--poll-progress-after=30s` or some other
suitable duration to [be informed
early](https://onsi.github.io/ginkgo/#getting-visibility-into-long-running-specs)
why a test doesn't complete and where it is stuck. A SIGINFO or SIGUSR1
signal can be sent to the CLI and/or e2e.test processes to trigger an
immediate progress report.

- Use [`gomega.Eventually`](https://pkg.go.dev/github.com/onsi/gomega#Eventually)
to wait for some condition. When it times out or
gets stuck, the last failed assertion will be included in the report
automatically. A good way to invoke it is:

gomega.Eventually(ctx, func(ctx context.Context) (book Book, err error) {
// Retrieve book from API server and return it.
...
}).WithPolling(5 * time.Second).WithTimeout(30 * time.Second).
Should(gomega.HaveField("Author.DOB.Year()", BeNumerically("<", 1900)))

Avoid testing for some condition inside the callback and returning a boolean
because then failure messages are not informative (see above). See
https://github.com/kubernetes/kubernetes/pull/114640 for an example where
[gomega/gcustom](https://pkg.go.dev/github.com/onsi/gomega@v1.27.2/gcustom)
was used to write assertions.

Some of the E2E framework sub-packages have helper functions that wait for
certain domain-specific conditions. Currently most of these functions don't
follow best practices (not using gomega.Eventually, error messages not very
informative). [Work is
planned](https://github.com/kubernetes/kubernetes/issues/106575) in that
area, so beware that these APIs may
change at some point.

- Use `gomega.Consistently` to ensure that some condition is true
for a while. As with `gomega.Eventually`, make assertions about the
value instead of checking the value with Go code and then asserting
that the code returns true.

- Both `gomega.Consistently` and `gomega.Eventually` can be aborted early via
[`gomega.StopPolling`](https://onsi.github.io/gomega/#bailing-out-early---polling-functions).

- Avoid polling with functions that don't take a context (`wait.Poll`,
`wait.PollImmediate`, `wait.Until`, ...) and replace with their counterparts
that do (`wait.PollWithContext`, `wait.PollImmediateWithContext`,
`wait.UntilWithContext`, ...) or even better, with `gomega.Eventually`.


#### Ability to run in non-dedicated test clusters ####

To reduce end-to-end delay and improve resource utilization when
Expand Down

0 comments on commit bf8b4d5

Please sign in to comment.