Add tracing to envtool tests run (#3695)

Closes #3665. Co-authored-by: Alexey Palazhchenko <alexey.palazhchenko@ferretdb.io>
FerretDB · Dec 6, 2023 · f814189 · f814189
1 parent 504c567
commit f814189
Show file tree

Hide file tree

Showing 16 changed files with 231 additions and 124 deletions.
diff --git a/.golangci.yml b/.golangci.yml
@@ -129,6 +129,18 @@ linters-settings:
         alias: sqlite3
       - pkg: modernc.org/sqlite/lib
         alias: sqlite3lib
+      - pkg: go.opentelemetry.io/otel/attribute
+        alias: otelattribute
+      - pkg: go.opentelemetry.io/otel/codes
+        alias: otelcodes
+      - pkg: go.opentelemetry.io/otel/trace
+        alias: oteltrace
+      - pkg: go.opentelemetry.io/otel/sdk/resource
+        alias: otelsdkresource
+      - pkg: go.opentelemetry.io/otel/sdk/trace
+        alias: otelsdktrace
+      - pkg: go.opentelemetry.io/otel/semconv/v1.21.0
+        alias: otelsemconv
   # ineffassign
   lll:
     line-length: 130

diff --git a/cmd/envtool/envtool.go b/cmd/envtool/envtool.go
@@ -457,16 +457,16 @@ func main() {
 
 	logger := zap.S()
 
-	ctx, cancel := context.WithTimeout(context.Background(), time.Minute)
-	defer cancel()
-
 	cmd := kongCtx.Command()
 	logger.Debugf("Command: %q", cmd)
 
 	var err error
 
 	switch cmd {
 	case "setup":
+		ctx, cancel := context.WithTimeout(context.Background(), time.Minute)
+		defer cancel()
+
 		err = setup(ctx, logger)
 
 	case "package-version":
@@ -480,8 +480,13 @@ func main() {
 		err = shellRead(os.Stdout, cli.Shell.Read.Paths...)
 
 	case "tests run <args>":
+		ctx, stop := ctxutil.SigTerm(context.Background())
+		defer stop()
+
 		err = testsRun(
-			cli.Tests.Run.ShardIndex, cli.Tests.Run.ShardTotal, cli.Tests.Run.Run, cli.Tests.Run.Args,
+			ctx,
+			cli.Tests.Run.ShardIndex, cli.Tests.Run.ShardTotal,
+			cli.Tests.Run.Run, cli.Tests.Run.Args,
 			logger,
 		)
 

diff --git a/cmd/envtool/tests.go b/cmd/envtool/tests.go
@@ -30,11 +30,16 @@ import (
 	"strings"
 	"time"
 
+	"go.opentelemetry.io/otel"
+	otelattribute "go.opentelemetry.io/otel/attribute"
+	otelcodes "go.opentelemetry.io/otel/codes"
+	oteltrace "go.opentelemetry.io/otel/trace"
 	"go.uber.org/zap"
 	"golang.org/x/exp/maps"
 
 	"github.com/FerretDB/FerretDB/internal/util/lazyerrors"
 	"github.com/FerretDB/FerretDB/internal/util/must"
+	"github.com/FerretDB/FerretDB/internal/util/observability"
 )
 
 // testEvent represents a single even emitted by `go test -json`.
@@ -56,10 +61,11 @@ func (te testEvent) Elapsed() time.Duration {
 
 // testResult represents the outcome of a single test.
 type testResult struct {
+	ctx        context.Context
 	run        time.Time
 	cont       time.Time
-	outputs    []string
 	lastAction string
+	outputs    []string
 }
 
 // parentTest returns parent test name for the given subtest, or empty string.
@@ -71,8 +77,30 @@ func parentTest(testName string) string {
 	return ""
 }
 
+// resultKey returns a key for the given package and test name.
+func resultKey(packageName, testName string) string {
+	must.NotBeZero(packageName)
+
+	if testName == "" {
+		return packageName
+	}
+
+	return packageName + "." + testName
+}
+
 // runGoTest runs `go test` with given extra args.
 func runGoTest(ctx context.Context, args []string, total int, times bool, logger *zap.SugaredLogger) error {
+	shutdownOtel := observability.SetupOtel("envtool tests")
+
+	defer func() {
+		shutdownCtx, shutdownCancel := context.WithTimeout(context.Background(), 5*time.Second)
+		defer shutdownCancel()
+
+		if err := shutdownOtel(shutdownCtx); err != nil {
+			logger.Error(err)
+		}
+	}()
+
 	cmd := exec.CommandContext(ctx, "go", append([]string{"test", "-json"}, args...)...)
 	logger.Debugf("Running %s", strings.Join(cmd.Args, " "))
 
@@ -89,9 +117,16 @@ func runGoTest(ctx context.Context, args []string, total int, times bool, logger
 
 	defer cmd.Cancel() //nolint:errcheck // safe to ignore
 
-	var done int
+	// Keys are:
+	// - "package/name"
+	// - "package/name.TestName"
+	// - "package/name.TestName/subtest"
+	//
+	// See [resultKey].
 	results := make(map[string]*testResult, 300)
 
+	var done int
+
 	d := json.NewDecoder(p)
 	d.DisallowUnknownFields()
 
@@ -100,6 +135,11 @@ func runGoTest(ctx context.Context, args []string, total int, times bool, logger
 		totalTests = strconv.Itoa(total)
 	}
 
+	var root oteltrace.Span
+	ctx, root = otel.Tracer("").Start(ctx, "run")
+
+	defer root.End()
+
 	for {
 		var event testEvent
 		if err = d.Decode(&event); err != nil {
@@ -112,33 +152,63 @@ func runGoTest(ctx context.Context, args []string, total int, times bool, logger
 
 		// logger.Desugar().Info("decoded event", zap.Any("event", event))
 
-		if event.Test != "" {
-			if results[event.Test] == nil {
-				results[event.Test] = &testResult{
-					outputs: make([]string, 0, 2),
-				}
+		must.NotBeZero(event.Package)
+
+		res := results[resultKey(event.Package, event.Test)]
+		if res == nil {
+			res = new(testResult)
+			results[resultKey(event.Package, event.Test)] = res
+
+			attributes := []otelattribute.KeyValue{
+				otelattribute.String("package", event.Package),
+				otelattribute.String("test", event.Test),
 			}
 
-			results[event.Test].lastAction = event.Action
+			var parentCtx context.Context
+			var spanName string
+
+			if event.Test == "" {
+				parentCtx = ctx
+				spanName = event.Package
+			} else {
+				parentCtx = results[resultKey(event.Package, parentTest(event.Test))].ctx
+				spanName = event.Test
+			}
+
+			must.NotBeZero(parentCtx)
+			must.NotBeZero(spanName)
+
+			res.ctx, _ = otel.Tracer("").Start(parentCtx, spanName, oteltrace.WithAttributes(attributes...))
+			res.outputs = make([]string, 0, 2)
 		}
 
+		res.lastAction = event.Action
+
 		switch event.Action {
 		case "start": // the test binary is about to be executed
-			// nothing
+			oteltrace.SpanFromContext(res.ctx).AddEvent(event.Action)
 
 		case "run": // the test has started running
 			must.NotBeZero(event.Test)
-			results[event.Test].run = event.Time
-			results[event.Test].cont = event.Time
+
+			oteltrace.SpanFromContext(res.ctx).AddEvent(event.Action)
+
+			res.run = event.Time
+			res.cont = event.Time
 
 		case "pause": // the test has been paused
-			// nothing
+			oteltrace.SpanFromContext(res.ctx).AddEvent(event.Action)
 
 		case "cont": // the test has continued running
 			must.NotBeZero(event.Test)
-			results[event.Test].cont = event.Time
+
+			oteltrace.SpanFromContext(res.ctx).AddEvent(event.Action)
+
+			res.cont = event.Time
 
 		case "output": // the test printed output
+			// do not add span event
+
 			out := strings.TrimSuffix(event.Output, "\n")
 
 			// initial setup output or early panic
@@ -147,10 +217,10 @@ func runGoTest(ctx context.Context, args []string, total int, times bool, logger
 				continue
 			}
 
-			results[event.Test].outputs = append(results[event.Test].outputs, out)
+			res.outputs = append(res.outputs, out)
 
 		case "bench": // the benchmark printed log output but did not fail
-			// nothing
+			// do not add span event
 
 		case "pass": // the test passed
 			fallthrough
@@ -159,6 +229,16 @@ func runGoTest(ctx context.Context, args []string, total int, times bool, logger
 			fallthrough
 
 		case "skip": // the test was skipped or the package contained no tests
+			code := otelcodes.Ok
+			if event.Action == "fail" {
+				code = otelcodes.Error
+			}
+
+			testSpan := oteltrace.SpanFromContext(res.ctx)
+			testSpan.AddEvent(event.Action)
+			testSpan.SetStatus(code, event.Action)
+			testSpan.End()
+
 			if event.Test == "" {
 				logger.Info(strings.ToTitle(event.Action) + " " + event.Package)
 				continue
@@ -169,8 +249,6 @@ func runGoTest(ctx context.Context, args []string, total int, times bool, logger
 				continue
 			}
 
-			res := results[event.Test]
-
 			msg := strings.ToTitle(event.Action) + " " + event.Test
 
 			if times {
@@ -276,7 +354,7 @@ func runGoTest(ctx context.Context, args []string, total int, times bool, logger
 
 // testsRun runs tests specified by the shard index and total or by the run regex
 // using `go test` with given extra args.
-func testsRun(index, total uint, run string, args []string, logger *zap.SugaredLogger) error {
+func testsRun(ctx context.Context, index, total uint, run string, args []string, logger *zap.SugaredLogger) error {
 	logger.Debugf("testsRun: index=%d, total=%d, run=%q, args=%q", index, total, run, args)
 
 	var totalTest int
@@ -308,7 +386,7 @@ func testsRun(index, total uint, run string, args []string, logger *zap.SugaredL
 		run += ")$"
 	}
 
-	return runGoTest(context.TODO(), append([]string{"-run=" + run}, args...), totalTest, true, logger)
+	return runGoTest(ctx, append([]string{"-run=" + run}, args...), totalTest, true, logger)
 }
 
 // listTestFuncs returns a sorted slice of all top-level test functions (tests, benchmarks, examples, fuzz functions)
@@ -345,6 +423,7 @@ func listTestFuncs(dir string) ([]string, error) {
 		}
 
 		if _, dup := testFuncs[l]; dup {
+			// testutil.DatabaseName and other helpers depend on test names being unique across packages
 			return nil, fmt.Errorf("duplicate test function name %q", l)
 		}
 

diff --git a/cmd/envtool/tests_test.go b/cmd/envtool/tests_test.go
@@ -187,9 +187,9 @@ func TestRunGoTest(t *testing.T) {
 			"FAIL github.com/FerretDB/FerretDB/cmd/envtool/testdata",
 			"",
 			"Some tests did not finish:",
-			"  TestPanic1",
+			"  github.com/FerretDB/FerretDB/cmd/envtool/testdata.TestPanic1",
 			"",
-			"TestPanic1:",
+			"github.com/FerretDB/FerretDB/cmd/envtool/testdata.TestPanic1:",
 			"=== RUN   TestPanic1",
 			"panic: Panic 1",
 			"",

diff --git a/cmd/ferretdb/main.go b/cmd/ferretdb/main.go
@@ -38,6 +38,7 @@ import (
 	"github.com/FerretDB/FerretDB/internal/clientconn"
 	"github.com/FerretDB/FerretDB/internal/clientconn/connmetrics"
 	"github.com/FerretDB/FerretDB/internal/handler/registry"
+	"github.com/FerretDB/FerretDB/internal/util/ctxutil"
 	"github.com/FerretDB/FerretDB/internal/util/debug"
 	"github.com/FerretDB/FerretDB/internal/util/debugbuild"
 	"github.com/FerretDB/FerretDB/internal/util/logging"
@@ -339,7 +340,7 @@ func run() {
 		logger.Sugar().Warnf("Failed to set GOMAXPROCS: %s.", err)
 	}
 
-	ctx, stop := notifyAppTermination(context.Background())
+	ctx, stop := ctxutil.SigTerm(context.Background())
 
 	go func() {
 		<-ctx.Done()

diff --git a/go.mod b/go.mod
@@ -19,6 +19,9 @@ require (
 	github.com/stretchr/testify v1.8.4
 	go.mongodb.org/mongo-driver v1.13.0
 	go.opentelemetry.io/otel v1.21.0
+	go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp v1.21.0
+	go.opentelemetry.io/otel/sdk v1.21.0
+	go.opentelemetry.io/otel/trace v1.21.0
 	go.uber.org/automaxprocs v1.5.3
 	go.uber.org/zap v1.26.0
 	golang.org/x/crypto v0.16.0 // indirect; always use @latest
@@ -30,13 +33,16 @@ require (
 
 require (
 	github.com/beorn7/perks v1.0.1 // indirect
+	github.com/cenkalti/backoff/v4 v4.2.1 // indirect
 	github.com/cespare/xxhash/v2 v2.2.0 // indirect
 	github.com/davecgh/go-spew v1.1.1 // indirect
 	github.com/dustin/go-humanize v1.0.1 // indirect
 	github.com/go-logr/logr v1.3.0 // indirect
 	github.com/go-logr/stdr v1.2.2 // indirect
+	github.com/golang/protobuf v1.5.3 // indirect
 	github.com/golang/snappy v0.0.1 // indirect
 	github.com/gorilla/websocket v1.5.0 // indirect
+	github.com/grpc-ecosystem/grpc-gateway/v2 v2.16.0 // indirect
 	github.com/jackc/pgpassfile v1.0.0 // indirect
 	github.com/jackc/pgservicefile v0.0.0-20221227161230-091c0ba34f0a // indirect
 	github.com/jackc/puddle/v2 v2.2.1 // indirect
@@ -51,13 +57,18 @@ require (
 	github.com/xdg-go/scram v1.1.2 // indirect
 	github.com/xdg-go/stringprep v1.0.4 // indirect
 	github.com/youmark/pkcs8 v0.0.0-20181117223130-1be2e3e5546d // indirect
+	go.opentelemetry.io/otel/exporters/otlp/otlptrace v1.21.0 // indirect
 	go.opentelemetry.io/otel/metric v1.21.0 // indirect
-	go.opentelemetry.io/otel/trace v1.21.0 // indirect
+	go.opentelemetry.io/proto/otlp v1.0.0 // indirect
 	go.uber.org/multierr v1.10.0 // indirect
 	golang.org/x/mod v0.14.0 // indirect
+	golang.org/x/net v0.19.0 // indirect
 	golang.org/x/sync v0.5.0 // indirect
 	golang.org/x/text v0.14.0 // indirect
 	golang.org/x/tools v0.16.0 // indirect
+	google.golang.org/genproto/googleapis/api v0.0.0-20230822172742-b8732ec3820d // indirect
+	google.golang.org/genproto/googleapis/rpc v0.0.0-20230822172742-b8732ec3820d // indirect
+	google.golang.org/grpc v1.59.0 // indirect
 	google.golang.org/protobuf v1.31.0 // indirect
 	gopkg.in/yaml.v3 v3.0.1 // indirect
 	lukechampine.com/uint128 v1.2.0 // indirect