diff --git a/README.md b/README.md index 504cf2e..f2fdc51 100644 --- a/README.md +++ b/README.md @@ -10,7 +10,7 @@ their `go.mod`; each fails CI with a specific finding and says how to resolve it | tool | what it catches | |---|---| | [`mutate`](https://spin-stack.github.io/go-tools/mutate/) | code your change touched that no test checks, even at 100% coverage: it breaks the code one small edit at a time and fails when the tests still pass | -| [`testquality`](https://spin-stack.github.io/go-tools/testquality/) | tests that cannot fail, and tests skipped unconditionally | +| [`testquality`](https://spin-stack.github.io/go-tools/testquality/) | tests that cannot fail, tests skipped unconditionally, and tests that sleep a second or more where a condition should be waited for | | [`ctxlife`](https://spin-stack.github.io/go-tools/ctxlife/) | goroutines that use their caller's context and outlive the call | | [`refs`](https://spin-stack.github.io/go-tools/refs/) | paths, tasks and packages that AGENTS.md or CLAUDE.md names and the tree no longer has | | [`vulngate`](https://spin-stack.github.io/go-tools/vulngate/) | vulnerabilities the code calls and that have a fix | diff --git a/internal/testquality/testdata/src/waits/waits_test.go b/internal/testquality/testdata/src/waits/waits_test.go new file mode 100644 index 0000000..619561a --- /dev/null +++ b/internal/testquality/testdata/src/waits/waits_test.go @@ -0,0 +1,86 @@ +// Package waits holds tests that sleep for a second or more where a condition should be waited +// for, and the sleeps that are not that. +package waits + +import ( + "testing" + "time" +) + +const settle = 3 * time.Second + +func TestSleepsASecond(t *testing.T) { + time.Sleep(time.Second) // want `TestSleepsASecond sleeps 1s` + if t.Name() == "" { + t.Fatal("named") + } +} + +func TestSleepsInASubtestAndAGoroutine(t *testing.T) { + t.Run("sub", func(t *testing.T) { + time.Sleep(2 * time.Second) // want `TestSleepsInASubtestAndAGoroutine sleeps 2s` + if t.Name() == "" { + t.Fatal("named") + } + }) + go func() { + time.Sleep(settle) // want `TestSleepsInASubtestAndAGoroutine sleeps 3s` + }() + time.Sleep(time.Minute + 500*time.Millisecond) // want `TestSleepsInASubtestAndAGoroutine sleeps 1m0.5s` + if t.Name() == "" { + t.Fatal("named") + } +} + +// Under a second paces a loop, and a duration the test computes is not a number to judge here. A +// loop that sleeps looks again, which is a wait for a condition with the loop's own bound. +func TestPacesAndComputes(t *testing.T) { + time.Sleep(20 * time.Millisecond) + time.Sleep(999 * time.Millisecond) + for deadline := time.Now().Add(time.Minute); time.Now().Before(deadline); time.Sleep(2 * time.Second) { + if t.Name() != "" { + break + } + } + for !ready() { + time.Sleep(5 * time.Second) + } + for range 3 { + func() { time.Sleep(time.Second) }() + } + d := time.Duration(t.Name()[0]) * time.Second + time.Sleep(d) + time.Sleep(backoff(3)) + waitABit(t) + // Not time.Sleep: another package's Sleep, and a duration handed to something else. + clock{}.Sleep(5 * time.Second) + <-time.After(2 * time.Second) + if t.Name() == "" { + t.Fatal("named") + } +} + +// A sleep after a loop is not the loop's. +func TestSleepsAfterALoop(t *testing.T) { + for !ready() { + time.Sleep(time.Second) + } + time.Sleep(4 * time.Second) // want `TestSleepsAfterALoop sleeps 4s` + if t.Name() == "" { + t.Fatal("named") + } +} + +// A helper's sleep is the helper's: a helper named by many tests is one line to fix. +func waitABit(t *testing.T) { + t.Helper() + time.Sleep(5 * time.Second) +} + +func backoff(n int) time.Duration { return time.Duration(n) * time.Second } + +func ready() bool { return true } + +type clock struct{} + +func (clock) Sleep(time.Duration) {} diff --git a/internal/testquality/testquality.go b/internal/testquality/testquality.go index bfd90de..c9281a2 100644 --- a/internal/testquality/testquality.go +++ b/internal/testquality/testquality.go @@ -5,8 +5,11 @@ package testquality import ( "errors" "go/ast" + "go/constant" + "go/token" "go/types" "strings" + "time" "golang.org/x/tools/go/analysis" "golang.org/x/tools/go/analysis/passes/inspect" @@ -62,6 +65,13 @@ func run(pass *analysis.Pass) (any, error) { "t.Skip or an assertion, and no helper is handed the test. A test that asserts "+ "nothing passes forever and reports this package as covered", fn.Name.Name) } + + for _, sleep := range longSleeps(pass, fn) { + pass.Reportf(sleep.call.Pos(), "%s sleeps %s for nothing it can see: a wait on the clock "+ + "passes on a quiet machine and fails on a loaded one, which is what a flake is. Wait for "+ + "the condition - a channel, a log line, Eventually - or say in the allowlist why the "+ + "clock is the only signal there is", fn.Name.Name, sleep.d) + } }) return nil, nil @@ -196,3 +206,58 @@ func isFromPackage(pass *analysis.Pass, call *ast.CallExpr, pkgs map[string]bool } return pkgs[fn.Pkg().Path()] } + +// longSleep is one time.Sleep in a test's body, closures included, of a second or more. +type longSleep struct { + call *ast.CallExpr + d time.Duration +} + +// longSleeps is every time.Sleep in fn whose duration is a constant of a second or more and that +// is not inside a loop: a loop that sleeps looks again, which is a wait for a condition, with the +// loop's own bound. Under a second paces anything, and a duration the test computes is not a +// number to judge here. A helper's sleep is the helper's, not every caller's. +func longSleeps(pass *analysis.Pass, fn *ast.FuncDecl) []longSleep { + var loops []ast.Node + ast.Inspect(fn.Body, func(n ast.Node) bool { + switch n.(type) { + case *ast.ForStmt, *ast.RangeStmt: + loops = append(loops, n) + } + return true + }) + inLoop := func(pos token.Pos) bool { + for _, l := range loops { + if l.Pos() <= pos && pos < l.End() { + return true + } + } + return false + } + var found []longSleep + ast.Inspect(fn.Body, func(n ast.Node) bool { + call, ok := n.(*ast.CallExpr) + if !ok || len(call.Args) != 1 || inLoop(call.Pos()) { + return true + } + sel, ok := call.Fun.(*ast.SelectorExpr) + if !ok || sel.Sel.Name != "Sleep" || !isFromPackage(pass, call, map[string]bool{"time": true}) { + return true + } + // A duration that is not a constant has no value here (the zero TypeAndValue's is nil). + value := pass.TypesInfo.Types[call.Args[0]].Value + if value == nil { + return true + } + ns, exact := constant.Int64Val(constant.ToInt(value)) + if !exact { + return true + } + if ns < int64(time.Second) { + return true + } + found = append(found, longSleep{call: call, d: time.Duration(ns)}) + return true + }) + return found +} diff --git a/internal/testquality/testquality_test.go b/internal/testquality/testquality_test.go index 54f2325..1693850 100644 --- a/internal/testquality/testquality_test.go +++ b/internal/testquality/testquality_test.go @@ -19,6 +19,12 @@ func TestTestsThatCanFailAreNotFlagged(t *testing.T) { analysistest.Run(t, analysistest.TestData(), testquality.Analyzer, "canfail") } +// A sleep of a second or more in a test's body, closures included, is a wait on the clock; under a +// second, a computed duration and a helper's sleep are not flagged. +func TestLongSleepsInATestAreFlagged(t *testing.T) { + analysistest.Run(t, analysistest.TestData(), testquality.Analyzer, "waits") +} + func TestTestsThatNeverRunAreFlagged(t *testing.T) { analysistest.Run(t, analysistest.TestData(), testquality.Analyzer, "skipped") } diff --git a/site/src/content/docs/testquality.md b/site/src/content/docs/testquality.md index b18df39..9315139 100644 --- a/site/src/content/docs/testquality.md +++ b/site/src/content/docs/testquality.md @@ -1,6 +1,6 @@ --- title: testquality -description: Fails on a test that cannot fail, or one skipped unconditionally. Such a test counts as covered, passes forever, and proves nothing. +description: Fails on a test that cannot fail, one skipped unconditionally, or one that sleeps a second or more where a condition should be waited for. The first two count as covered, pass forever and prove nothing; the third passes on a quiet machine and fails on a loaded one. --- A test that cannot fail is worse than no test: it shows up green, it counts toward coverage, and @@ -33,11 +33,27 @@ func TestSkippedOutright(t *testing.T) { t.Skip("comes back when the feature is written") t.Fatal("never reached") } + +func TestWaitsOnTheClock(t *testing.T) { + start(t) + time.Sleep(5 * time.Second) // for the server to be up, presumably + assertUp(t) +} ``` -The first two are reported as `cannot fail` and the third as `is skipped unconditionally`. A test -that hands `t` to a helper counts as one that can fail, and so does one where a closure captures -`t` and calls an assertion package. Subtests are inspected with the rest of the body. +The first two are reported as `cannot fail`, the third as `is skipped unconditionally`, and the +fourth as `sleeps 5s for nothing it can see`. A test that hands `t` to a helper counts as one that +can fail, and so does one where a closure captures `t` and calls an assertion package. Subtests +are inspected with the rest of the body. + +A sleep of a second or more in a test's body - a subtest's or a goroutine's included - is a wait +on the clock: it passes on a quiet machine and fails on a loaded one, which is what a flake is. +Of 45 failed fleet gates in two days of one repository, the real flakes were each a wait with a +bound that the machine's load outran. Wait for the condition - a channel, a log line, an +`Eventually` - or say in the allowlist why the clock is the only signal there is. A sleep inside a +loop looks again, which is a wait for a condition with the loop's own bound, and is not flagged; +nor is one under a second, which paces; nor a duration the test computes, which is not a number to +judge; a helper's sleep is the helper's, one line to fix however many tests call it. Tests behind the `integration` and `e2e` build tags are analyzed too: a test in another lane is held like any other.