From 261e558b36f01001ef591ed1d2c9019f1516f358 Mon Sep 17 00:00:00 2001 From: Alexey Palazhchenko Date: Wed, 15 Nov 2023 09:03:41 +0400 Subject: [PATCH] Handle panicking tests (#3711) --- cmd/envtool/envtool.go | 2 +- cmd/envtool/testdata/panic_test.go | 29 ++++++ cmd/envtool/tests.go | 125 +++++++++++++++++++------- cmd/envtool/tests_test.go | 136 ++++++++++++++++++++--------- 4 files changed, 216 insertions(+), 76 deletions(-) create mode 100644 cmd/envtool/testdata/panic_test.go diff --git a/cmd/envtool/envtool.go b/cmd/envtool/envtool.go index 73a7432d34b6..d4589338c57d 100644 --- a/cmd/envtool/envtool.go +++ b/cmd/envtool/envtool.go @@ -390,7 +390,7 @@ func makeLogger(level zapcore.Level, output []string) (*zap.Logger, error) { NameKey: "N", CallerKey: zapcore.OmitKey, FunctionKey: zapcore.OmitKey, - StacktraceKey: "S", + StacktraceKey: zapcore.OmitKey, LineEnding: zapcore.DefaultLineEnding, EncodeLevel: zapcore.CapitalLevelEncoder, EncodeTime: func(t time.Time, enc zapcore.PrimitiveArrayEncoder) { diff --git a/cmd/envtool/testdata/panic_test.go b/cmd/envtool/testdata/panic_test.go new file mode 100644 index 000000000000..52245e9ad122 --- /dev/null +++ b/cmd/envtool/testdata/panic_test.go @@ -0,0 +1,29 @@ +// Copyright 2021 FerretDB Inc. +// +// 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 testdata + +import ( + "runtime" + "testing" +) + +func TestPanic1(t *testing.T) { + go func() { + runtime.Gosched() + panic("Panic 1") + }() + + select {} +} diff --git a/cmd/envtool/tests.go b/cmd/envtool/tests.go index 491d70058bee..64006ed23184 100644 --- a/cmd/envtool/tests.go +++ b/cmd/envtool/tests.go @@ -24,6 +24,7 @@ import ( "io" "os" "os/exec" + "slices" "sort" "strconv" "strings" @@ -33,6 +34,7 @@ import ( "golang.org/x/exp/maps" "github.com/FerretDB/FerretDB/internal/util/lazyerrors" + "github.com/FerretDB/FerretDB/internal/util/must" ) // testEvent represents a single even emitted by `go test -json`. @@ -54,18 +56,10 @@ func (te testEvent) Elapsed() time.Duration { // testResult represents the outcome of a single test. type testResult struct { - run time.Time - cont time.Time - outputs []string -} - -// levelTest returns test level (starting from 0) for the given (sub)test name. -func levelTest(testName string) int { - if testName == "" { - panic("empty test name") - } - - return strings.Count(testName, "/") + run time.Time + cont time.Time + outputs []string + lastAction string } // parentTest returns parent test name for the given subtest, or empty string. @@ -109,37 +103,31 @@ func runGoTest(ctx context.Context, args []string, total int, times bool, logger for { var event testEvent if err = d.Decode(&event); err != nil { - if errors.Is(err, io.EOF) { - return cmd.Wait() + if !errors.Is(err, io.EOF) { + return lazyerrors.Error(err) } - return lazyerrors.Error(err) + break } - // logger.Desugar().Debug("decoded event", zap.Any("event", event)) + // logger.Desugar().Info("decoded event", zap.Any("event", event)) - for t := event.Test; t != ""; t = parentTest(t) { - res := results[t] - if res == nil { - res = &testResult{ + if event.Test != "" { + if results[event.Test] == nil { + results[event.Test] = &testResult{ outputs: make([]string, 0, 2), } - results[t] = res } - if out := strings.TrimSpace(event.Output); out != "" { - res.outputs = append(res.outputs, strings.Repeat(" ", levelTest(t)+1)+out) - } + results[event.Test].lastAction = event.Action } - // We should also handle the output without a test name (for example, for panics); - // see https://github.com/golang/go/issues/38382. - switch event.Action { case "start": // the test binary is about to be executed // nothing case "run": // the test has started running + must.NotBeZero(event.Test) results[event.Test].run = event.Time results[event.Test].cont = event.Time @@ -147,10 +135,19 @@ func runGoTest(ctx context.Context, args []string, total int, times bool, logger // nothing case "cont": // the test has continued running + must.NotBeZero(event.Test) results[event.Test].cont = event.Time case "output": // the test printed output - // nothing + out := strings.TrimSuffix(event.Output, "\n") + + // initial setup output or early panic + if event.Test == "" { + logger.Info(out) + continue + } + + results[event.Test].outputs = append(results[event.Test].outputs, out) case "bench": // the benchmark printed log output but did not fail // nothing @@ -167,7 +164,7 @@ func runGoTest(ctx context.Context, args []string, total int, times bool, logger continue } - top := levelTest(event.Test) == 0 + top := parentTest(event.Test) == "" if !top && event.Action == "pass" { continue } @@ -201,18 +198,80 @@ func runGoTest(ctx context.Context, args []string, total int, times bool, logger } msg += ":" - logger.Info(msg) + logger.Warn(msg) - for _, l := range results[event.Test].outputs { - logger.Info(l) + for _, l := range res.outputs { + logger.Warn(l) } - logger.Info("") + logger.Warn("") default: return lazyerrors.Errorf("unknown action %q", event.Action) } } + + var unfinished []string + + for t, res := range results { + switch res.lastAction { + case "pass", "fail", "skip": + continue + } + + unfinished = append(unfinished, t) + } + + if unfinished == nil { + return cmd.Wait() + } + + slices.Sort(unfinished) + + logger.Error("") + + logger.Error("Some tests did not finish:") + + for _, t := range unfinished { + logger.Errorf(" %s", t) + } + + logger.Error("") + + // On panic, the last event will not be "fail"; see https://github.com/golang/go/issues/38382. + // Try to provide the best possible output in that case. + + var panicked string + + for _, t := range unfinished { + if !slices.ContainsFunc(results[t].outputs, func(s string) bool { + return strings.Contains(s, "panic: ") + }) { + continue + } + + if panicked != "" { + break + } + + panicked = t + } + + for _, t := range unfinished { + if panicked != "" && t != panicked { + continue + } + + logger.Errorf("%s:", t) + + for _, l := range results[t].outputs { + logger.Error(l) + } + + logger.Error("") + } + + return cmd.Wait() } // testsRun runs tests specified by the shard index and total or by the run regex diff --git a/cmd/envtool/tests_test.go b/cmd/envtool/tests_test.go index 5a2a67c5883b..564cd1625827 100644 --- a/cmd/envtool/tests_test.go +++ b/cmd/envtool/tests_test.go @@ -43,12 +43,39 @@ func makeTestLogger(messages *[]string) (*zap.Logger, error) { return logger, nil } +var ( + cleanupTimingRe = regexp.MustCompile(`(\d+\.\d+)s`) // duration are different + cleanupGoroutineRe = regexp.MustCompile(`goroutine (\d+)`) // goroutine IDs are different + cleanupPathRe = regexp.MustCompile(`^\t(.+)/cmd/envtool/testdata/`) // absolute file paths are different + cleanupAddrRe = regexp.MustCompile(` (\+0x[0-9a-f]+)$`) // addresses are different +) + +// cleanup removes variable parts of the output. +func cleanup(lines []string) { + for i, line := range lines { + if loc := cleanupTimingRe.FindStringSubmatchIndex(line); loc != nil { + line = line[:loc[2]] + "" + line[loc[3]:] + } + + if loc := cleanupGoroutineRe.FindStringSubmatchIndex(line); loc != nil { + line = line[:loc[2]] + "" + line[loc[3]:] + } + + if loc := cleanupPathRe.FindStringSubmatchIndex(line); loc != nil { + line = line[:loc[2]] + "" + line[loc[3]:] + } + + if loc := cleanupAddrRe.FindStringSubmatchIndex(line); loc != nil { + line = line[:loc[2]] + "" + line[loc[3]:] + } + + lines[i] = line + } +} + func TestRunGoTest(t *testing.T) { t.Parallel() - // sometimes it is "(0.01s)" on CI - timingRe := regexp.MustCompile(` \(\d+\.\d+s\)$`) - t.Run("Normal", func(t *testing.T) { t.Parallel() @@ -56,14 +83,18 @@ func TestRunGoTest(t *testing.T) { logger, err := makeTestLogger(&actual) require.NoError(t, err) - err = runGoTest(context.TODO(), []string{"./testdata", "-run=TestNormal"}, 2, false, logger.Sugar()) + err = runGoTest(context.TODO(), []string{"./testdata", "-count=1", "-run=TestNormal"}, 2, false, logger.Sugar()) require.NoError(t, err) expected := []string{ "PASS TestNormal1 1/2", "PASS TestNormal2 2/2", + "PASS", + "ok github.com/FerretDB/FerretDB/cmd/envtool/testdata s", "PASS github.com/FerretDB/FerretDB/cmd/envtool/testdata", } + + cleanup(actual) assert.Equal(t, expected, actual, "actual:\n%s", strings.Join(actual, "\n")) }) @@ -74,7 +105,7 @@ func TestRunGoTest(t *testing.T) { logger, err := makeTestLogger(&actual) require.NoError(t, err) - err = runGoTest(context.TODO(), []string{"./testdata", "-run=TestError"}, 2, false, logger.Sugar()) + err = runGoTest(context.TODO(), []string{"./testdata", "-count=1", "-run=TestError"}, 2, false, logger.Sugar()) var exitErr *exec.ExitError require.ErrorAs(t, err, &exitErr) @@ -82,48 +113,36 @@ func TestRunGoTest(t *testing.T) { expected := []string{ "FAIL TestError1 1/2:", - " === RUN TestError1", - " error_test.go:20: not hidden 1", - " error_test.go:22: Error 1", - " error_test.go:24: not hidden 2", - " --- FAIL: TestError1", + "=== RUN TestError1", + " error_test.go:20: not hidden 1", + " error_test.go:22: Error 1", + " error_test.go:24: not hidden 2", + "--- FAIL: TestError1 (s)", "", "FAIL TestError2/Parallel:", - " === RUN TestError2/Parallel", + "=== RUN TestError2/Parallel", " error_test.go:35: not hidden 5", - " === PAUSE TestError2/Parallel", - " === CONT TestError2/Parallel", + "=== PAUSE TestError2/Parallel", + "=== CONT TestError2/Parallel", " error_test.go:39: not hidden 6", " error_test.go:41: Error 2", " error_test.go:43: not hidden 7", - " --- FAIL: TestError2/Parallel", + "--- FAIL: TestError2/Parallel (s)", "", "FAIL TestError2 2/2:", - " === RUN TestError2", - " error_test.go:28: not hidden 3", - " === PAUSE TestError2", - " === CONT TestError2", - " error_test.go:32: not hidden 4", - " === RUN TestError2/Parallel", - " error_test.go:35: not hidden 5", - " === PAUSE TestError2/Parallel", - " === RUN TestError2/NotParallel", - " error_test.go:47: not hidden for parent", - " --- PASS: TestError2/NotParallel", - " === CONT TestError2/Parallel", - " error_test.go:39: not hidden 6", - " error_test.go:41: Error 2", - " error_test.go:43: not hidden 7", - " --- FAIL: TestError2/Parallel", - " --- FAIL: TestError2", + "=== RUN TestError2", + " error_test.go:28: not hidden 3", + "=== PAUSE TestError2", + "=== CONT TestError2", + " error_test.go:32: not hidden 4", + "--- FAIL: TestError2 (s)", "", + "FAIL", + "FAIL github.com/FerretDB/FerretDB/cmd/envtool/testdata s", "FAIL github.com/FerretDB/FerretDB/cmd/envtool/testdata", } - for i, line := range expected { - actual[i] = timingRe.ReplaceAllString(line, "") - } - + cleanup(actual) assert.Equal(t, expected, actual, "actual:\n%s", strings.Join(actual, "\n")) }) @@ -134,23 +153,55 @@ func TestRunGoTest(t *testing.T) { logger, err := makeTestLogger(&actual) require.NoError(t, err) - err = runGoTest(context.TODO(), []string{"./testdata", "-run=TestSkip"}, 1, false, logger.Sugar()) + err = runGoTest(context.TODO(), []string{"./testdata", "-count=1", "-run=TestSkip"}, 1, false, logger.Sugar()) require.NoError(t, err) expected := []string{ "SKIP TestSkip1 1/1:", - " === RUN TestSkip1", - " skip_test.go:20: not hidden 1", - " skip_test.go:22: Skip 1", - " --- SKIP: TestSkip1", + "=== RUN TestSkip1", + " skip_test.go:20: not hidden 1", + " skip_test.go:22: Skip 1", + "--- SKIP: TestSkip1 (s)", "", + "PASS", + "ok github.com/FerretDB/FerretDB/cmd/envtool/testdata s", "PASS github.com/FerretDB/FerretDB/cmd/envtool/testdata", } - for i, line := range expected { - actual[i] = timingRe.ReplaceAllString(line, "") + cleanup(actual) + assert.Equal(t, expected, actual, "actual:\n%s", strings.Join(actual, "\n")) + }) + + t.Run("Panic", func(t *testing.T) { + t.Parallel() + + var actual []string + logger, err := makeTestLogger(&actual) + require.NoError(t, err) + + err = runGoTest(context.TODO(), []string{"./testdata", "-count=1", "-run=TestPanic"}, 1, false, logger.Sugar()) + require.Error(t, err) + + expected := []string{ + "FAIL github.com/FerretDB/FerretDB/cmd/envtool/testdata s", + "FAIL github.com/FerretDB/FerretDB/cmd/envtool/testdata", + "", + "Some tests did not finish:", + " TestPanic1", + "", + "TestPanic1:", + "=== RUN TestPanic1", + "panic: Panic 1", + "", + "goroutine [running]:", + "github.com/FerretDB/FerretDB/cmd/envtool/testdata.TestPanic1.func1()", + " /cmd/envtool/testdata/panic_test.go:25 ", + "created by github.com/FerretDB/FerretDB/cmd/envtool/testdata.TestPanic1 in goroutine ", + " /cmd/envtool/testdata/panic_test.go:23 ", + "", } + cleanup(actual) assert.Equal(t, expected, actual, "actual:\n%s", strings.Join(actual, "\n")) }) } @@ -165,6 +216,7 @@ func TestListTestFuncs(t *testing.T) { "TestError2", "TestNormal1", "TestNormal2", + "TestPanic1", "TestSkip1", } assert.Equal(t, expected, actual)