Handle panicking tests (FerretDB#3711)

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) {

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 {}
+}

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,48 +103,51 @@ 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
 
 		case "pause": // the test has been paused
 			// 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