http2: fix flakiness from t.Log when GOOS=js

The http2 package uses a precursor to the experimental
testing/synctest package, parsing runtime.Stack output
to determine when goroutines are idle.

When GOOS=js, some tests which use t.Log are flaky.
t.Log blocks in the syscall package writing to stdout.
The GOOS=js implementation of the syscall leaves the goroutine
blocked on a channel operation, which synctest interprets
as the goroutine being "durably blocked".

Fix the http2 synctest to treat any goroutine blocked in the
syscall package as not being durably blocked.

Making this fix reveals another bug when GOOS=js: Looping
while calling runtime.Gosched does not appear to permit
syscalls to make progress. Add a few time.Sleep(1) calls
while waiting for idleness to work around the problem.

While changing things in here, change http2's synctest
to not treat goroutines blocked on mutex operations as
durably blocked. This matches the behavior of testing/synctest.

(This would all be simpler if we just used testing/synctest,
but we don't want to make the http2 package depend on an
experimental API.)

Fixes golang/go#67693

Change-Id: I889834e97e4a33f4ef232278b1a78af00d52d261
Reviewed-on: https://go-review.googlesource.com/c/net/+/653696
Reviewed-by: Jonathan Amsterdam <jba@google.com>
LUCI-TryBot-Result: Go LUCI <golang-scoped@luci-project-accounts.iam.gserviceaccount.com>
Auto-Submit: Damien Neil <dneil@google.com>

Author: neild

http2/sync_test.go

@@ -24,9 +24,10 @@ type synctestGroup struct {
 }
 
 type goroutine struct {
-	id     int
-	parent int
-	state  string
+	id      int
+	parent  int
+	state   string
+	syscall bool
 }
 
 // newSynctest creates a new group with the synthetic clock set the provided time.
@@ -76,6 +77,14 @@ func (g *synctestGroup) Wait() {
 			return
 		}
 		runtime.Gosched()
+		if runtime.GOOS == "js" {
+			// When GOOS=js, we appear to need to time.Sleep to make progress
+			// on some syscalls. In particular, without this sleep
+			// writing to stdout (including via t.Log) can block forever.
+			for range 10 {
+				time.Sleep(1)
+			}
+		}
 	}
 }
 
@@ -87,6 +96,9 @@ func (g *synctestGroup) idle() bool {
 		if !g.gids[gr.id] && !g.gids[gr.parent] {
 			continue
 		}
+		if gr.syscall {
+			return false
+		}
 		// From runtime/runtime2.go.
 		switch gr.state {
 		case "IO wait":
@@ -97,9 +109,6 @@ func (g *synctestGroup) idle() bool {
 		case "chan receive":
 		case "chan send":
 		case "sync.Cond.Wait":
-		case "sync.Mutex.Lock":
-		case "sync.RWMutex.RLock":
-		case "sync.RWMutex.Lock":
 		default:
 			return false
 		}
@@ -138,6 +147,10 @@ func stacks(all bool) []goroutine {
 			panic(fmt.Errorf("3 unparsable goroutine stack:\n%s", gs))
 		}
 		state, rest, ok := strings.Cut(rest, "]")
+		isSyscall := false
+		if strings.Contains(rest, "\nsyscall.") {
+			isSyscall = true
+		}
 		var parent int
 		_, rest, ok = strings.Cut(rest, "\ncreated by ")
 		if ok && strings.Contains(rest, " in goroutine ") {
@@ -155,9 +168,10 @@ func stacks(all bool) []goroutine {
 			}
 		}
 		goroutines = append(goroutines, goroutine{
-			id:     id,
-			parent: parent,
-			state:  state,
+			id:      id,
+			parent:  parent,
+			state:   state,
+			syscall: isSyscall,
 		})
 	}
 	return goroutines
@@ -291,3 +305,25 @@ func (tm *fakeTimer) Stop() bool {
 	delete(tm.g.timers, tm)
 	return stopped
 }
+
+// TestSynctestLogs verifies that t.Log works,
+// in particular that the GOOS=js workaround in synctestGroup.Wait is working.
+// (When GOOS=js, writing to stdout can hang indefinitely if some goroutine loops
+// calling runtime.Gosched; see Wait for the workaround.)
+func TestSynctestLogs(t *testing.T) {
+	g := newSynctest(time.Now())
+	donec := make(chan struct{})
+	go func() {
+		g.Join()
+		for range 100 {
+			t.Logf("logging a long line")
+		}
+		close(donec)
+	}()
+	g.Wait()
+	select {
+	case <-donec:
+	default:
+		panic("done")
+	}
+}