Modified binary search for the correct delay. (#2584)

* Binary search for the correct delay.

* Removes an unnecessary log line.

* Fixes.

* Switches back to linear search.

* Replaces cancel with a timeout.

test/context_canceled_test.go

@@ -41,38 +41,71 @@ func (s) TestContextCanceled(t *testing.T) {
 	}
 	defer ss.Stop()
 
-	var i, cntCanceled uint
-	cntPermDenied := func() uint {
-		return i - cntCanceled
-	}
-	for i, cntCanceled = 0, 0; i < 500 && (cntCanceled < 5 || cntPermDenied() < 5); i++ {
-		ctx, cancel := context.WithCancel(context.Background())
-		defer cancel()
+	// Runs 10 rounds of tests with the given delay and returns counts of status codes.
+	// Fails in case of trailer/status code inconsistency.
+	const cntRetry uint = 10
+	runTest := func(delay time.Duration) (cntCanceled, cntPermDenied uint) {
+		for i := uint(0); i < cntRetry; i++ {
+			ctx, cancel := context.WithTimeout(context.Background(), delay)
+			defer cancel()
 
-		str, err := ss.client.FullDuplexCall(ctx)
-		if err != nil {
-			t.Fatalf("%v.FullDuplexCall(_) = _, %v, want <nil>", ss.client, err)
+			str, err := ss.client.FullDuplexCall(ctx)
+			if err != nil {
+				continue
+			}
+
+			_, err = str.Recv()
+			if err == nil {
+				t.Fatalf("non-nil error expected from Recv()")
+			}
+
+			_, trlOk := str.Trailer()["a"]
+			switch status.Code(err) {
+			case codes.PermissionDenied:
+				if !trlOk {
+					t.Fatalf(`status err: %v; wanted key "a" in trailer but didn't get it`, err)
+				}
+				cntPermDenied++
+			case codes.DeadlineExceeded:
+				if trlOk {
+					t.Fatalf(`status err: %v; didn't want key "a" in trailer but got it`, err)
+				}
+				cntCanceled++
+			default:
+				t.Fatalf(`unexpected status err: %v`, err)
+			}
 		}
-		// As this duration goes up chances of Recv returning Cancelled will decrease.
-		time.Sleep(time.Duration(i) * time.Microsecond)
-		cancel()
-		_, err = str.Recv()
-		if err == nil {
-			t.Fatalf("non-nil error expected from Recv()")
+		return cntCanceled, cntPermDenied
+	}
+
+	// Tries to find the delay that causes canceled/perm denied race.
+	canceledOk, permDeniedOk := false, false
+	for lower, upper := time.Duration(0), 2*time.Millisecond; lower <= upper; {
+		delay := lower + (upper-lower)/2
+		cntCanceled, cntPermDenied := runTest(delay)
+		if cntPermDenied > 0 && cntCanceled > 0 {
+			// Delay that causes the race is found.
+			return
 		}
-		code := status.Code(err)
-		if code == codes.Canceled {
-			cntCanceled++
+
+		// Set OK flags.
+		if cntCanceled > 0 {
+			canceledOk = true
 		}
-		_, ok := str.Trailer()["a"]
-		if code == codes.PermissionDenied && !ok {
-			t.Fatalf(`status err: %v; wanted key "a" in trailer but didn't get it`, err)
+		if cntPermDenied > 0 {
+			permDeniedOk = true
 		}
-		if code == codes.Canceled && ok {
-			t.Fatalf(`status err: %v; didn't want key "a" in trailer but got it`, err)
+
+		if cntPermDenied == 0 {
+			// No perm denied, increase the delay.
+			lower += (upper-lower)/10 + 1
+		} else {
+			// All perm denied, decrease the delay.
+			upper -= (upper-lower)/10 + 1
 		}
 	}
-	if cntCanceled < 5 || cntPermDenied() < 5 {
-		t.Fatalf("got Canceled status %v times and PermissionDenied status %v times but wanted both of them at least 5 times", cntCanceled, cntPermDenied())
+
+	if !canceledOk || !permDeniedOk {
+		t.Fatalf(`couldn't find the delay that causes canceled/perm denied race.`)
 	}
 }