Merge pull request #12753 from ptabor/20210306-integration-zap

Integration tests: Multiple improvements

.travis.yml

@@ -72,25 +72,25 @@ script:
       linux-amd64-fmt)
         docker run --rm \
           --volume=`pwd`:/go/src/go.etcd.io/etcd gcr.io/etcd-development/etcd-test:go${TRAVIS_GO_VERSION} \
-          /bin/bash -c "GOARCH=amd64 PASSES='fmt bom dep' ./test"
+          /bin/bash -c "GOARCH=amd64 PASSES='fmt bom dep' ./test.sh"
         ;;
       linux-amd64-integration-1-cpu)
         # TODO: Reenable 'race' when https://github.com/etcd-io/etcd/issues/12336 fixed.
         docker run --rm \
           --volume=`pwd`:/go/src/go.etcd.io/etcd gcr.io/etcd-development/etcd-test:go${TRAVIS_GO_VERSION} \
-          /bin/bash -c "GOARCH=amd64 CPU=1 PASSES='integration' RACE='false' ./test"
+          /bin/bash -c "GOARCH=amd64 CPU=1 PASSES='integration' RACE='false' ./test.sh"
         ;;
       linux-amd64-integration-2-cpu)
         # TODO: Reenable 'race' when https://github.com/etcd-io/etcd/issues/12336 fixed.
         docker run --rm \
           --volume=`pwd`:/go/src/go.etcd.io/etcd gcr.io/etcd-development/etcd-test:go${TRAVIS_GO_VERSION} \
-          /bin/bash -c "GOARCH=amd64 CPU=2 PASSES='integration' RACE='false' ./test"
+          /bin/bash -c "GOARCH=amd64 CPU=2 PASSES='integration' RACE='false' ./test.sh"
         ;;
       linux-amd64-integration-4-cpu)
         # TODO: Reenable 'race' when https://github.com/etcd-io/etcd/issues/12336 fixed.
         docker run --rm \
           --volume=`pwd`:/go/src/go.etcd.io/etcd gcr.io/etcd-development/etcd-test:go${TRAVIS_GO_VERSION} \
-          /bin/bash -c "GOARCH=amd64 CPU=4 PASSES='integration' RACE='false' ./test"
+          /bin/bash -c "GOARCH=amd64 CPU=4 PASSES='integration' RACE='false' ./test.sh"
         ;;
       linux-amd64-functional)
         docker run --rm \
@@ -100,29 +100,29 @@ script:
       linux-amd64-unit-4-cpu-race)
         docker run --rm \
           --volume=`pwd`:/go/src/go.etcd.io/etcd gcr.io/etcd-development/etcd-test:go${TRAVIS_GO_VERSION} \
-          /bin/bash -c "GOARCH=amd64 PASSES='unit' RACE='true' CPU='4' ./test -p=2"
+          /bin/bash -c "GOARCH=amd64 PASSES='unit' RACE='true' CPU='4' ./test.sh -p=2"
         ;;
       all-build)
         docker run --rm \
           --volume=`pwd`:/go/src/go.etcd.io/etcd gcr.io/etcd-development/etcd-test:go${TRAVIS_GO_VERSION} \
-          /bin/bash -c "GOARCH=amd64 PASSES='build' ./test \
-            && GOARCH=386 PASSES='build' ./test \
-            && GO_BUILD_FLAGS='-v -mod=readonly' GOOS=darwin GOARCH=amd64 ./build \
-            && GO_BUILD_FLAGS='-v -mod=readonly' GOOS=windows GOARCH=amd64 ./build \
-            && GO_BUILD_FLAGS='-v -mod=readonly' GOARCH=arm ./build \
-            && GO_BUILD_FLAGS='-v -mod=readonly' GOARCH=arm64 ./build \
-            && GO_BUILD_FLAGS='-v -mod=readonly' GOARCH=ppc64le ./build \
-            && GO_BUILD_FLAGS='-v -mod=readonly' GOARCH=s390x ./build"
+          /bin/bash -c "GOARCH=amd64 PASSES='build' ./test.sh \
+            && GOARCH=386 PASSES='build' ./test.sh \
+            && GO_BUILD_FLAGS='-v -mod=readonly' GOOS=darwin GOARCH=amd64 ./build.sh \
+            && GO_BUILD_FLAGS='-v -mod=readonly' GOOS=windows GOARCH=amd64 ./build.sh \
+            && GO_BUILD_FLAGS='-v -mod=readonly' GOARCH=arm ./build.sh \
+            && GO_BUILD_FLAGS='-v -mod=readonly' GOARCH=arm64 ./build.sh \
+            && GO_BUILD_FLAGS='-v -mod=readonly' GOARCH=ppc64le ./build.sh \
+            && GO_BUILD_FLAGS='-v -mod=readonly' GOARCH=s390x ./build.sh"
         ;;
       linux-amd64-grpcproxy)
         # TODO: Reenable race when https://github.com/etcd-io/etcd/issues/12336 fixed.
-        sudo HOST_TMP_DIR=/tmp TEST_OPTS="PASSES='build grpcproxy' VERBOSE='1' CPU='4' COVER='false' RACE='false'" make docker-test
+        sudo HOST_TMP_DIR=/tmp TEST_OPTS="PASSES='build grpcproxy'  CPU='4' COVER='false' RACE='false'" make docker-test
         ;;
       linux-amd64-coverage)
         sudo HOST_TMP_DIR=/tmp TEST_OPTS="VERBOSE='1'" make docker-test-coverage
         ;;
       linux-amd64-fmt-unit-go-tip-2-cpu)
-        GOARCH=amd64 PASSES='fmt unit' CPU='2' RACE='false' ./test -p=2
+        GOARCH=amd64 PASSES='fmt unit' CPU='2' RACE='false' ./test.sh -p=2
         ;;
       linux-386-unit-1-cpu)
         docker run --rm \

client/v3/client_test.go

@@ -28,7 +28,7 @@ import (
 )
 
 func TestDialCancel(t *testing.T) {
-	defer testutil.AfterTest(t)
+	testutil.BeforeTest(t)
 
 	// accept first connection so client is created with dial timeout
 	ln, err := net.Listen("unix", "dialcancel:12345")

client/v3/txn_test.go

@@ -22,7 +22,7 @@ import (
 )
 
 func TestTxnPanics(t *testing.T) {
-	defer testutil.AfterTest(t)
+	testutil.BeforeTest(t)
 
 	kv := &kv{}
 

pkg/testutil/leak.go

@@ -28,7 +28,7 @@ running(leaking) after all tests.
 	}
 
 	func TestSample(t *testing.T) {
-		defer testutil.AfterTest(t)
+		BeforeTest(t)
 		...
 	}
 
@@ -59,6 +59,7 @@ func CheckLeakedGoroutine() bool {
 func CheckAfterTest(d time.Duration) error {
 	http.DefaultTransport.(*http.Transport).CloseIdleConnections()
 	var bad string
+	// Presence of these goroutines causes immediate test failure.
 	badSubstring := map[string]string{
 		").writeLoop(": "a Transport",
 		"created by net/http/httptest.(*Server).Start": "an httptest.Server",
@@ -74,27 +75,42 @@ func CheckAfterTest(d time.Duration) error {
 	begin := time.Now()
 	for time.Since(begin) < d {
 		bad = ""
-		stacks = strings.Join(interestingGoroutines(), "\n\n")
+		goroutines := interestingGoroutines()
+		if len(goroutines) == 0 {
+			return nil
+		}
+		stacks = strings.Join(goroutines, "\n\n")
+
 		for substr, what := range badSubstring {
 			if strings.Contains(stacks, substr) {
 				bad = what
 			}
 		}
-		if bad == "" {
-			return nil
-		}
-		// Bad stuff found, but goroutines might just still be
+		// Undesired goroutines found, but goroutines might just still be
 		// shutting down, so give it some time.
+		runtime.Gosched()
 		time.Sleep(50 * time.Millisecond)
 	}
 	return fmt.Errorf("appears to have leaked %s:\n%s", bad, stacks)
 }
 
+// BeforeTest is a convenient way to register before-and-after code to a test.
+// If you execute BeforeTest, you don't need to explicitly register AfterTest.
+func BeforeTest(t TB) {
+	if err := CheckAfterTest(10 * time.Millisecond); err != nil {
+		t.Skip("Found leaked goroutined BEFORE test", err)
+		return
+	}
+	t.Cleanup(func() {
+		AfterTest(t)
+	})
+}
+
 // AfterTest is meant to run in a defer that executes after a test completes.
 // It will detect common goroutine leaks, retrying in case there are goroutines
 // not synchronously torn down, and fail the test if any goroutines are stuck.
-func AfterTest(t *testing.T) {
-	if err := CheckAfterTest(300 * time.Millisecond); err != nil {
+func AfterTest(t TB) {
+	if err := CheckAfterTest(1 * time.Second); err != nil {
 		t.Errorf("Test %v", err)
 	}
 }
@@ -126,7 +142,8 @@ func interestingGoroutines() (gs []string) {
 			strings.Contains(stack, "created by text/template/parse.lex") ||
 			strings.Contains(stack, "runtime.MHeap_Scavenger") ||
 			strings.Contains(stack, "rcrypto/internal/boring.(*PublicKeyRSA).finalize") ||
-			strings.Contains(stack, "net.(*netFD).Close(") {
+			strings.Contains(stack, "net.(*netFD).Close(") ||
+			strings.Contains(stack, "testing.(*T).Run") {
 			continue
 		}
 		gs = append(gs, stack)

pkg/testutil/testingtb.go

@@ -0,0 +1,130 @@
+// Copyright 2021 The etcd Authors
+//
+// 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 testutil
+
+import (
+	"io/ioutil"
+	"log"
+	"os"
+)
+
+// TB is a subset of methods of testing.TB interface.
+// We cannot implement testing.TB due to protection, so we expose this simplified interface.
+type TB interface {
+	Cleanup(func())
+	Error(args ...interface{})
+	Errorf(format string, args ...interface{})
+	Fail()
+	FailNow()
+	Failed() bool
+	Fatal(args ...interface{})
+	Fatalf(format string, args ...interface{})
+	Logf(format string, args ...interface{})
+	Name() string
+	TempDir() string
+	Helper()
+	Skip(args ...interface{})
+}
+
+// NewTestingTBProthesis creates a fake variant of testing.TB implementation.
+// It's supposed to be used in contexts were real testing.T is not provided,
+// e.g. in 'examples'.
+//
+// The `closef` goroutine should get executed when tb will not be needed any longer.
+//
+// The provided implementation is NOT thread safe (Cleanup() method).
+func NewTestingTBProthesis(name string) (tb TB, closef func()) {
+	testtb := &testingTBProthesis{name: name}
+	return testtb, testtb.close
+}
+
+type testingTBProthesis struct {
+	name     string
+	failed   bool
+	cleanups []func()
+}
+
+func (t *testingTBProthesis) Helper() {
+	// Ignored
+}
+
+func (t *testingTBProthesis) Skip(args ...interface{}) {
+	t.Log(append([]interface{}{"Skipping due to: "}, args...))
+}
+
+func (t *testingTBProthesis) Cleanup(f func()) {
+	t.cleanups = append(t.cleanups, f)
+}
+
+func (t *testingTBProthesis) Error(args ...interface{}) {
+	log.Println(args...)
+	t.Fail()
+}
+
+func (t *testingTBProthesis) Errorf(format string, args ...interface{}) {
+	log.Printf(format, args...)
+	t.Fail()
+}
+
+func (t *testingTBProthesis) Fail() {
+	t.failed = true
+}
+
+func (t *testingTBProthesis) FailNow() {
+	t.failed = true
+	panic("FailNow() called")
+}
+
+func (t *testingTBProthesis) Failed() bool {
+	return t.failed
+}
+
+func (t *testingTBProthesis) Fatal(args ...interface{}) {
+	log.Fatalln(args...)
+}
+
+func (t *testingTBProthesis) Fatalf(format string, args ...interface{}) {
+	log.Fatalf(format, args...)
+}
+
+func (t *testingTBProthesis) Logf(format string, args ...interface{}) {
+	log.Printf(format, args...)
+}
+
+func (t *testingTBProthesis) Log(args ...interface{}) {
+	log.Println(args...)
+}
+
+func (t *testingTBProthesis) Name() string {
+	return t.name
+}
+
+func (t *testingTBProthesis) TempDir() string {
+	dir, err := ioutil.TempDir("", t.name)
+	if err != nil {
+		t.Fatal(err)
+	}
+	t.cleanups = append([]func(){func() {
+		t.Logf("Cleaning UP: %v", dir)
+		os.RemoveAll(dir)
+	}}, t.cleanups...)
+	return dir
+}
+
+func (t *testingTBProthesis) close() {
+	for i := len(t.cleanups) - 1; i >= 0; i-- {
+		t.cleanups[i]()
+	}
+}

pkg/testutil/testutil.go

@@ -84,7 +84,7 @@ func Poll(interval time.Duration, timeout time.Duration, condition ConditionFunc
 	}
 }
 
-func SkipTestIfShortMode(t testing.TB, reason string) {
+func SkipTestIfShortMode(t TB, reason string) {
 	if t != nil {
 		t.Helper()
 		if testing.Short() {

raft/logger.go

@@ -48,6 +48,16 @@ func SetLogger(l Logger) {
 	raftLoggerMu.Unlock()
 }
 
+func ResetDefaultLogger() {
+	SetLogger(defaultLogger)
+}
+
+func getLogger() Logger {
+	raftLoggerMu.Lock()
+	defer raftLoggerMu.Unlock()
+	return raftLogger
+}
+
 var (
 	defaultLogger = &DefaultLogger{Logger: log.New(os.Stderr, "raft", log.LstdFlags)}
 	discardLogger = &DefaultLogger{Logger: log.New(ioutil.Discard, "", 0)}

raft/raft.go

@@ -230,7 +230,7 @@ func (c *Config) validate() error {
 	}
 
 	if c.Logger == nil {
-		c.Logger = raftLogger
+		c.Logger = getLogger()
 	}
 
 	if c.ReadOnlyOption == ReadOnlyLeaseBased && !c.CheckQuorum {

raft/status.go

@@ -100,7 +100,7 @@ func (s Status) MarshalJSON() ([]byte, error) {
 func (s Status) String() string {
 	b, err := s.MarshalJSON()
 	if err != nil {
-		raftLogger.Panicf("unexpected error: %v", err)
+		getLogger().Panicf("unexpected error: %v", err)
 	}
 	return string(b)
 }

raft/storage.go

@@ -115,7 +115,7 @@ func (ms *MemoryStorage) Entries(lo, hi, maxSize uint64) ([]pb.Entry, error) {
 		return nil, ErrCompacted
 	}
 	if hi > ms.lastIndex()+1 {
-		raftLogger.Panicf("entries' hi(%d) is out of bound lastindex(%d)", hi, ms.lastIndex())
+		getLogger().Panicf("entries' hi(%d) is out of bound lastindex(%d)", hi, ms.lastIndex())
 	}
 	// only contains dummy entries.
 	if len(ms.ents) == 1 {
@@ -200,7 +200,7 @@ func (ms *MemoryStorage) CreateSnapshot(i uint64, cs *pb.ConfState, data []byte)
 
 	offset := ms.ents[0].Index
 	if i > ms.lastIndex() {
-		raftLogger.Panicf("snapshot %d is out of bound lastindex(%d)", i, ms.lastIndex())
+		getLogger().Panicf("snapshot %d is out of bound lastindex(%d)", i, ms.lastIndex())
 	}
 
 	ms.snapshot.Metadata.Index = i
@@ -223,7 +223,7 @@ func (ms *MemoryStorage) Compact(compactIndex uint64) error {
 		return ErrCompacted
 	}
 	if compactIndex > ms.lastIndex() {
-		raftLogger.Panicf("compact %d is out of bound lastindex(%d)", compactIndex, ms.lastIndex())
+		getLogger().Panicf("compact %d is out of bound lastindex(%d)", compactIndex, ms.lastIndex())
 	}
 
 	i := compactIndex - offset
@@ -266,7 +266,7 @@ func (ms *MemoryStorage) Append(entries []pb.Entry) error {
 	case uint64(len(ms.ents)) == offset:
 		ms.ents = append(ms.ents, entries...)
 	default:
-		raftLogger.Panicf("missing log entry [last: %d, append at: %d]",
+		getLogger().Panicf("missing log entry [last: %d, append at: %d]",
 			ms.lastIndex(), entries[0].Index)
 	}
 	return nil

server/etcdserver/api/rafthttp/stream_test.go

@@ -187,7 +187,7 @@ func TestStreamReaderDialResult(t *testing.T) {
 
 // TestStreamReaderStopOnDial tests a stream reader closes the connection on stop.
 func TestStreamReaderStopOnDial(t *testing.T) {
-	defer testutil.AfterTest(t)
+	testutil.BeforeTest(t)
 	h := http.Header{}
 	h.Add("X-Server-Version", version.Version)
 	tr := &respWaitRoundTripper{rrt: &respRoundTripper{code: http.StatusOK, header: h}}

test.sh

@@ -110,7 +110,7 @@ function integration_extra {
 
 function integration_pass {
   local pkgs=${USERPKG:-"./integration/..."}
-  run_for_module "tests" go_test "${pkgs}" "parallel" : -timeout="${TIMEOUT:-15m}" "-v" "${COMMON_TEST_FLAGS[@]}" "${RUN_ARG[@]}" "$@" || return $?
+  run_for_module "tests" go_test "${pkgs}" "parallel" : -timeout="${TIMEOUT:-15m}" "${COMMON_TEST_FLAGS[@]}" "${RUN_ARG[@]}" "$@" || return $?
   integration_extra "$@"
 }