diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 0d73ac2..6d16571 100644 --- a/.github/workflows/ci.yml +++ b/.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/... diff --git a/test/rexdiff_test.go b/test/rexdiff_test.go index fca31fe..0ff470f 100644 --- a/test/rexdiff_test.go +++ b/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() } } }