diag: TestTallLine flake (do not merge)

.github/workflows/ci.yml

@@ -19,14 +19,15 @@ jobs:
   # Rex runs only on macOS, so rexdiff is tested there.
   test:
     runs-on: macos-latest
-    timeout-minutes: 20
+    timeout-minutes: 60
     steps:
       - uses: actions/checkout@v7
       - uses: actions/setup-go@v7
         with:
           go-version-file: go.mod
       - run: go vet ./...
-      - run: go test -race -count=1 ./...
+      - run: go test -race -count=3 $(go list ./... | grep -v '/test$')
+      - run: go test -race -count=3 -timeout 40m ./test
       # A second run in a random order finds a test that depends on another.
       - run: go test -count=2 -shuffle=on ./diff/ ./vcs/ ./rex/ ./update/ ./internal/...
 

test/rexdiff_test.go

@@ -9,6 +9,7 @@ import (
 	"io"
 	"os"
 	"os/exec"
+	"runtime"
 	"path/filepath"
 	"slices"
 	"strconv"
@@ -87,6 +88,7 @@ type term struct {
 	// changed receives a value after each write to the screen. Its buffer
 	// holds one value, so a write before a wait is not lost.
 	changed chan struct{}
+	diag    func()
 	done    chan struct{}
 }
 
@@ -99,6 +101,12 @@ func start(t *testing.T, repo string, o opts) *term {
 	if bin == "" {
 		bin = binary(t)
 	}
+	diagLog := filepath.Join(t.TempDir(), "diag.log")
+	if i := slices.Index(o.args, "-log"); i >= 0 {
+		diagLog = o.args[i+1]
+	} else {
+		o.args = append([]string{"-log", diagLog}, o.args...)
+	}
 	cmd := exec.CommandContext(t.Context(), bin, append(o.args, repo)...)
 	cmd.Dir = repo
 	// SIGTERM, unlike a kill, lets rexdiff remove its files.
@@ -116,6 +124,10 @@ func start(t *testing.T, repo string, o opts) *term {
 			"REX_BIN_DIR="+o.rex.dir)
 	}
 	cmd.Env = append(cmd.Env, o.env...)
+	cmd.Env = append(cmd.Env, "GOTRACEBACK=all")
+	diagErr := filepath.Join(t.TempDir(), "stderr")
+	ef, _ := os.Create(diagErr)
+	cmd.Stderr = ef
 	f, err := pty.StartWithSize(cmd, &pty.Winsize{Cols: w, Rows: h})
 	if err != nil {
 		t.Fatal(err)
@@ -128,6 +140,27 @@ func start(t *testing.T, repo string, o opts) *term {
 		changed: make(chan struct{}, 1),
 		done:    make(chan struct{}),
 	}
+	tm.diag = func() {
+		ps, _ := exec.Command("ps", "-o", "pid,stat,wchan,time,command", "-p", strconv.Itoa(cmd.Process.Pid)).CombinedOutput()
+		t.Log("DIAG PS:\n" + string(ps))
+		buf := make([]byte, 1<<20)
+		buf = buf[:runtime.Stack(buf, true)]
+		var keep []string
+		for _, g := range strings.Split(string(buf), "\n\n") {
+			if strings.Contains(g, "rexdiff/test.") || strings.Contains(g, "io.Copy") || strings.Contains(g, "vt.") {
+				keep = append(keep, g)
+			}
+		}
+		t.Log("DIAG TEST STACKS:\n" + strings.Join(keep, "\n\n"))
+		_ = cmd.Process.Signal(syscall.SIGQUIT)
+		time.Sleep(3 * time.Second)
+		b, _ := os.ReadFile(diagLog)
+		ls := strings.Split(string(b), "\n")
+		t.Log("DIAG LOG TAIL:\n" + strings.Join(ls[max(len(ls)-40, 0):], "\n"))
+		st, _ := os.ReadFile(diagErr)
+		t.Log("DIAG STACKS:\n" + string(st))
+		t.Log("DIAG SCREEN AFTER:\n" + tm.screen())
+	}
 	go func() {
 		defer close(tm.done)
 		buf := make([]byte, 32<<10)
@@ -332,7 +365,9 @@ func (tm *term) waitUntil(ok func(string) bool, what string) string {
 			}
 			tm.t.Fatalf("rexdiff stops, and the screen does not %s. It shows:\n%s", what, s)
 		case <-timeout.C:
-			tm.t.Fatalf("the screen does not %s. It shows:\n%s", what, s)
+			tm.t.Logf("the screen does not %s. It shows:\n%s", what, s)
+			tm.diag()
+			tm.t.FailNow()
 		}
 	}
 }