*: FatalStack to stacktrace tests after timeout

Related to https://github.com/coreos/etcd/issues/4065.

pkg/testutil/testutil.go

@@ -17,6 +17,7 @@ package testutil
 
 import (
 	"net/url"
+	"runtime"
 	"testing"
 	"time"
 )
@@ -45,3 +46,11 @@ func MustNewURL(t *testing.T, s string) *url.URL {
 	}
 	return u
 }
+
+// FatalStack helps to fatal the test and print out the stacks of all running goroutines.
+func FatalStack(t *testing.T, s string) {
+	stackTrace := make([]byte, 8*1024)
+	n := runtime.Stack(stackTrace, true)
+	t.Error(string(stackTrace[:n]))
+	t.Fatalf(s)
+}

storage/kv_test.go

@@ -15,9 +15,9 @@
 package storage
 
 import (
+	"fmt"
 	"os"
 	"reflect"
-	"runtime"
 	"testing"
 	"time"
 
@@ -443,10 +443,7 @@ func TestKVTxnBlockNonTnxOperations(t *testing.T) {
 		select {
 		case <-done:
 		case <-time.After(10 * time.Second):
-			stack := make([]byte, 8*1024)
+			testutil.FatalStack(t, fmt.Sprintf("#%d: operation failed to be unblocked", i))
-			n := runtime.Stack(stack, true)
-			t.Error(string(stack[:n]))
-			t.Fatalf("#%d: operation failed to be unblocked", i)
 		}
 	}
 
@@ -773,8 +770,9 @@ func TestWatchableKVWatch(t *testing.T) {
 		if !reflect.DeepEqual(ev, wev) {
 			t.Errorf("watched event = %+v, want %+v", ev, wev)
 		}
-	case <-time.After(time.Second):
+	case <-time.After(5 * time.Second):
-		t.Fatalf("failed to watch the event")
+		// CPU might be too slow, and the routine is not able to switch around
+		testutil.FatalStack(t, "failed to watch the event")
 	}
 
 	s.Put([]byte("foo1"), []byte("bar1"), 2)
@@ -798,8 +796,8 @@ func TestWatchableKVWatch(t *testing.T) {
 		if !reflect.DeepEqual(ev, wev) {
 			t.Errorf("watched event = %+v, want %+v", ev, wev)
 		}
-	case <-time.After(time.Second):
+	case <-time.After(5 * time.Second):
-		t.Fatalf("failed to watch the event")
+		testutil.FatalStack(t, "failed to watch the event")
 	}
 
 	w = s.NewWatchStream()
@@ -825,8 +823,8 @@ func TestWatchableKVWatch(t *testing.T) {
 		if !reflect.DeepEqual(ev, wev) {
 			t.Errorf("watched event = %+v, want %+v", ev, wev)
 		}
-	case <-time.After(time.Second):
+	case <-time.After(5 * time.Second):
-		t.Fatalf("failed to watch the event")
+		testutil.FatalStack(t, "failed to watch the event")
 	}
 
 	s.Put([]byte("foo1"), []byte("bar11"), 3)
@@ -850,8 +848,8 @@ func TestWatchableKVWatch(t *testing.T) {
 		if !reflect.DeepEqual(ev, wev) {
 			t.Errorf("watched event = %+v, want %+v", ev, wev)
 		}
-	case <-time.After(time.Second):
+	case <-time.After(5 * time.Second):
-		t.Fatalf("failed to watch the event")
+		testutil.FatalStack(t, "failed to watch the event")
 	}
 }
 

storage/kvstore_test.go

@@ -20,7 +20,6 @@ import (
 	"math"
 	"os"
 	"reflect"
-	"runtime"
 	"testing"
 	"time"
 
@@ -457,11 +456,7 @@ func TestTxnBlockBackendForceCommit(t *testing.T) {
 	select {
 	case <-done:
 	case <-time.After(5 * time.Second): // wait 5 seconds for CI with slow IO
-		// print out stack traces of all routines if there is a failure
+		testutil.FatalStack(t, "failed to execute ForceCommit")
-		stackTrace := make([]byte, 8*1024)
-		n := runtime.Stack(stackTrace, true)
-		t.Error(string(stackTrace[:n]))
-		t.Fatalf("failed to execute ForceCommit")
 	}
 }