From 45bad39f1ba85391460db1ed7869b16f60bc64ed Mon Sep 17 00:00:00 2001 From: Redowan Delowar Date: Fri, 30 Oct 2026 14:19:32 +0100 Subject: [PATCH 1/8] diag: run TestTallLine 30 times --- .github/workflows/ci.yml | 3 ++- test/caps_test.go | 12 ++++++++++++ 2 files changed, 14 insertions(+), 1 deletion(-) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 0d73ac2..6d45c15 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -26,7 +26,8 @@ jobs: with: go-version-file: go.mod - run: go vet ./... - - run: go test -race -count=1 ./... + - run: go test -race -count=30 -failfast=false -run 'TestTallLine$' -v ./test 2>&1 | grep -E -- '--- FAIL|msg=key|^ok|^FAIL|caps_test' ; exit ${PIPESTATUS[0]} + shell: bash # 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/caps_test.go b/test/caps_test.go index ba685e5..f2bf7fd 100644 --- a/test/caps_test.go +++ b/test/caps_test.go @@ -9,6 +9,7 @@ import ( "strconv" "strings" "testing" + "time" "github.com/rednafi/rexdiff/internal/testgit" ) @@ -231,6 +232,17 @@ func TestTallLine(t *testing.T) { testgit.WriteFile(t, repo, "a.go", b.String()) log := filepath.Join(t.TempDir(), "log") tm := start(t, repo, opts{args: []string{"-log", log}}) + t.Cleanup(func() { + if t.Failed() { + b, _ := os.ReadFile(log) + for _, l := range strings.Split(string(b), "\n") { + if strings.Contains(l, "msg=key") { + t.Log(l) + } + } + _ = time.Now + } + }) // A partly drawn frame has no footer or a gap in the words. Or its last // line is blank because the terminal scrolled the old lines up. whole := func(s string) bool { From d14eb919efa1c144754d10a31d9bef48cd506ec7 Mon Sep 17 00:00:00 2001 From: Redowan Delowar Date: Fri, 30 Oct 2026 14:23:02 +0100 Subject: [PATCH 2/8] diag: full suite 3 times --- .github/workflows/ci.yml | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 6d45c15..8249706 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -19,14 +19,14 @@ jobs: # Rex runs only on macOS, so rexdiff is tested there. test: runs-on: macos-latest - timeout-minutes: 20 + timeout-minutes: 45 steps: - uses: actions/checkout@v7 - uses: actions/setup-go@v7 with: go-version-file: go.mod - run: go vet ./... - - run: go test -race -count=30 -failfast=false -run 'TestTallLine$' -v ./test 2>&1 | grep -E -- '--- FAIL|msg=key|^ok|^FAIL|caps_test' ; exit ${PIPESTATUS[0]} + - run: go test -race -count=3 -v ./... 2>&1 | grep -E -- '--- FAIL|msg=key|^ok|^FAIL|caps_test' ; exit ${PIPESTATUS[0]} shell: bash # 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/... From ef2084241f86046a9edf4059da65afac058b72f4 Mon Sep 17 00:00:00 2001 From: Redowan Delowar Date: Fri, 30 Oct 2026 14:35:02 +0100 Subject: [PATCH 3/8] diag: log keys on any failure --- .github/workflows/ci.yml | 3 +-- test/caps_test.go | 12 ------------ test/rexdiff_test.go | 14 ++++++++++++++ 3 files changed, 15 insertions(+), 14 deletions(-) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 8249706..e6a0701 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -26,8 +26,7 @@ jobs: with: go-version-file: go.mod - run: go vet ./... - - run: go test -race -count=3 -v ./... 2>&1 | grep -E -- '--- FAIL|msg=key|^ok|^FAIL|caps_test' ; exit ${PIPESTATUS[0]} - shell: bash + - run: go test -race -count=3 ./... # 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/caps_test.go b/test/caps_test.go index f2bf7fd..ba685e5 100644 --- a/test/caps_test.go +++ b/test/caps_test.go @@ -9,7 +9,6 @@ import ( "strconv" "strings" "testing" - "time" "github.com/rednafi/rexdiff/internal/testgit" ) @@ -232,17 +231,6 @@ func TestTallLine(t *testing.T) { testgit.WriteFile(t, repo, "a.go", b.String()) log := filepath.Join(t.TempDir(), "log") tm := start(t, repo, opts{args: []string{"-log", log}}) - t.Cleanup(func() { - if t.Failed() { - b, _ := os.ReadFile(log) - for _, l := range strings.Split(string(b), "\n") { - if strings.Contains(l, "msg=key") { - t.Log(l) - } - } - _ = time.Now - } - }) // A partly drawn frame has no footer or a gap in the words. Or its last // line is blank because the terminal scrolled the old lines up. whole := func(s string) bool { diff --git a/test/rexdiff_test.go b/test/rexdiff_test.go index fca31fe..a23c774 100644 --- a/test/rexdiff_test.go +++ b/test/rexdiff_test.go @@ -99,6 +99,20 @@ func start(t *testing.T, repo string, o opts) *term { if bin == "" { bin = binary(t) } + if !slices.Contains(o.args, "-log") { + diagLog := filepath.Join(t.TempDir(), "diag.log") + o.args = append([]string{"-log", diagLog}, o.args...) + t.Cleanup(func() { + if t.Failed() { + b, _ := os.ReadFile(diagLog) + for _, l := range strings.Split(string(b), "\n") { + if strings.Contains(l, "msg=key") { + t.Log("DIAG " + l) + } + } + } + }) + } cmd := exec.CommandContext(t.Context(), bin, append(o.args, repo)...) cmd.Dir = repo // SIGTERM, unlike a kill, lets rexdiff remove its files. From 8fd645e9a965e51bcdeab8574cc6889c78f856d9 Mon Sep 17 00:00:00 2001 From: Redowan Delowar Date: Fri, 30 Oct 2026 14:35:18 +0100 Subject: [PATCH 4/8] diag: also for tests with -log --- test/rexdiff_test.go | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/test/rexdiff_test.go b/test/rexdiff_test.go index a23c774..253bbe1 100644 --- a/test/rexdiff_test.go +++ b/test/rexdiff_test.go @@ -99,9 +99,13 @@ func start(t *testing.T, repo string, o opts) *term { if bin == "" { bin = binary(t) } - if !slices.Contains(o.args, "-log") { - diagLog := filepath.Join(t.TempDir(), "diag.log") + 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...) + } + { t.Cleanup(func() { if t.Failed() { b, _ := os.ReadFile(diagLog) From 672d400323ab65be7b43a61ed09032f61dfc073c Mon Sep 17 00:00:00 2001 From: Redowan Delowar Date: Fri, 30 Oct 2026 14:48:49 +0100 Subject: [PATCH 5/8] diag: longer timeout --- .github/workflows/ci.yml | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index e6a0701..f82cf05 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -19,14 +19,14 @@ jobs: # Rex runs only on macOS, so rexdiff is tested there. test: runs-on: macos-latest - timeout-minutes: 45 + 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=3 ./... + - run: go test -race -count=3 -timeout 40m ./... # 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/... From dcd450e97eeab1cba2e78740742922b293b76ebe Mon Sep 17 00:00:00 2001 From: Redowan Delowar Date: Fri, 30 Oct 2026 15:02:37 +0100 Subject: [PATCH 6/8] diag: goroutine dump on wait timeout --- test/rexdiff_test.go | 30 +++++++++++++++++------------- 1 file changed, 17 insertions(+), 13 deletions(-) diff --git a/test/rexdiff_test.go b/test/rexdiff_test.go index 253bbe1..b11771b 100644 --- a/test/rexdiff_test.go +++ b/test/rexdiff_test.go @@ -87,6 +87,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{} } @@ -105,18 +106,6 @@ func start(t *testing.T, repo string, o opts) *term { } else { o.args = append([]string{"-log", diagLog}, o.args...) } - { - t.Cleanup(func() { - if t.Failed() { - b, _ := os.ReadFile(diagLog) - for _, l := range strings.Split(string(b), "\n") { - if strings.Contains(l, "msg=key") { - t.Log("DIAG " + l) - } - } - } - }) - } cmd := exec.CommandContext(t.Context(), bin, append(o.args, repo)...) cmd.Dir = repo // SIGTERM, unlike a kill, lets rexdiff remove its files. @@ -134,6 +123,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) @@ -146,6 +139,15 @@ func start(t *testing.T, repo string, o opts) *term { changed: make(chan struct{}, 1), done: make(chan struct{}), } + tm.diag = func() { + _ = 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)) + } go func() { defer close(tm.done) buf := make([]byte, 32<<10) @@ -350,7 +352,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() } } } From 8d87edd66d2ef14e3d63b9979e074f6c928e50b8 Mon Sep 17 00:00:00 2001 From: Redowan Delowar Date: Fri, 30 Oct 2026 15:18:39 +0100 Subject: [PATCH 7/8] diag: ps state and test stacks --- test/rexdiff_test.go | 13 +++++++++++++ 1 file changed, 13 insertions(+) diff --git a/test/rexdiff_test.go b/test/rexdiff_test.go index b11771b..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" @@ -140,6 +141,17 @@ func start(t *testing.T, repo string, o opts) *term { 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) @@ -147,6 +159,7 @@ func start(t *testing.T, repo string, o opts) *term { 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) From 8b2ded155114fdd15ffb9f71f37328b75a3cf643 Mon Sep 17 00:00:00 2001 From: Redowan Delowar Date: Fri, 30 Oct 2026 15:32:34 +0100 Subject: [PATCH 8/8] diag: run ./test alone, 3 times --- .github/workflows/ci.yml | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index f82cf05..6d16571 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -26,7 +26,8 @@ jobs: with: go-version-file: go.mod - run: go vet ./... - - run: go test -race -count=3 -timeout 40m ./... + - 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/...