From 93392fa05bbe5c91c200bc881f4d5038f1cd8c19 Mon Sep 17 00:00:00 2001 From: Cristian Magherusan-Stanciu Date: Fri, 16 Oct 2026 12:52:39 +0200 Subject: [PATCH 1/2] test(cli): drain captureAppOutput while the callback runs The helper read the pipe only after fn returned, so output above the pipe buffer deadlocked the writer. Drain concurrently, close both ends on every path including panics, and add a 1 MiB regression test with a 10s guard. Co-Authored-By: Claude Opus 5.5 --- cmd/multi_service_stats_test.go | 45 +++++++++++++++++++++++++++++---- 1 file changed, 40 insertions(+), 5 deletions(-) diff --git a/cmd/multi_service_stats_test.go b/cmd/multi_service_stats_test.go index 1bcb83d09..5ce253782 100644 --- a/cmd/multi_service_stats_test.go +++ b/cmd/multi_service_stats_test.go @@ -6,14 +6,17 @@ import ( "io" "log" "os" + "strings" "testing" + "time" "github.com/LeanerCloud/cloud-commitments-go/pkg/common" "github.com/stretchr/testify/assert" ) // captureAppOutput captures output from AppLogger and returns the captured string. -// Usage: output := captureAppOutput(t, func() { printSomething() }). +// The pipe is drained while fn runs so output beyond the pipe buffer cannot +// block the writer. Usage: output := captureAppOutput(t, func() { printSomething() }). func captureAppOutput(t *testing.T, fn func()) string { t.Helper() old := os.Stdout @@ -22,19 +25,29 @@ func captureAppOutput(t *testing.T, fn func()) string { if err != nil { t.Fatalf("os.Pipe failed: %v", err) } + var buf bytes.Buffer + drained := make(chan struct{}) + go func() { + defer close(drained) + _, _ = io.Copy(&buf, r) + }() os.Stdout = w AppLogger = log.New(w, "", 0) + // Runs on panic too: restore, close the writer to end the drain, then + // close the reader. defer func() { os.Stdout = old AppLogger = oldLogger + _ = w.Close() + <-drained + _ = r.Close() }() fn() - - w.Close() // Must close writer before reading to unblock io.Copy - var buf bytes.Buffer - _, _ = io.Copy(&buf, r) + // Close the writer before reading the buffer so the drain sees EOF. + _ = w.Close() + <-drained return buf.String() } @@ -558,3 +571,25 @@ func TestPrintFinalMessage(t *testing.T) { }) } } + +func TestCaptureAppOutputDrainsLargeOutput(t *testing.T) { + const lines, width = 1024, 1024 // 1 MiB, far above the pipe buffer + line := strings.Repeat("x", width-1) + // A deadlocked helper never restores these; do it so later tests run. + savedStdout, savedLogger := os.Stdout, AppLogger + t.Cleanup(func() { os.Stdout, AppLogger = savedStdout, savedLogger }) + done := make(chan string, 1) + go func() { + done <- captureAppOutput(t, func() { + for i := 0; i < lines; i++ { + AppLogger.Println(line) + } + }) + }() + select { + case out := <-done: + assert.Equal(t, lines*width, len(out)) + case <-time.After(10 * time.Second): + t.Fatal("captureAppOutput deadlocked on output larger than the pipe buffer") + } +} From a41104da96ef8a1e2c0a631a51ec1ffdb0fa678b Mon Sep 17 00:00:00 2001 From: Cristian Magherusan-Stanciu Date: Fri, 16 Oct 2026 12:53:45 +0200 Subject: [PATCH 2/2] test(cli): report child state when GCP signal markers time out Marker waits now fail with the child exit status (or still running) and its captured stderr. Child stdout is not read, preserving the blocked-stdout scenario. Timeouts are unchanged. Closes #2150 Co-Authored-By: Claude Opus 5.5 --- cmd/configure_gcp_signal_test.go | 62 ++++++++++++++++++++++++++++---- 1 file changed, 56 insertions(+), 6 deletions(-) diff --git a/cmd/configure_gcp_signal_test.go b/cmd/configure_gcp_signal_test.go index de3a9eec6..b0b43f0be 100644 --- a/cmd/configure_gcp_signal_test.go +++ b/cmd/configure_gcp_signal_test.go @@ -16,6 +16,7 @@ import ( "os/exec" "path/filepath" "strings" + "sync" "syscall" "testing" "time" @@ -36,7 +37,7 @@ func TestRunConfigureGCP_InterruptCleansMintedKey(t *testing.T) { child, dir, stdout, stderr := startGCPInterruptChild(t, "upload") defer stdout.Close() var keyFile string - require.Eventually(t, func() bool { + requireMarker(t, child, stderr, "minted key.json with fixture secret", func() bool { matches, err := filepath.Glob(filepath.Join(dir, "cudly-gcp-key-*", "key.json")) if err != nil || len(matches) != 1 { return false @@ -47,7 +48,7 @@ func TestRunConfigureGCP_InterruptCleansMintedKey(t *testing.T) { } keyFile = matches[0] return true - }, 10*time.Second, 10*time.Millisecond) + }) require.NoError(t, child.Process.Signal(sig)) err := child.Wait() require.NoFileExists(t, keyFile) @@ -63,10 +64,10 @@ func TestRunConfigureGCP_InterruptCleansMintedKey(t *testing.T) { func TestRunConfigureGCP_InterruptDuringMint(t *testing.T) { child, dir, stdout, stderr := startGCPInterruptChild(t, "mint") defer stdout.Close() - require.Eventually(t, func() bool { + requireMarker(t, child, stderr, "creating marker", func() bool { _, err := os.Stat(filepath.Join(dir, "creating")) return err == nil - }, 10*time.Second, 10*time.Millisecond) + }) require.NoError(t, child.Process.Signal(os.Interrupt)) require.NoError(t, child.Wait(), "child stderr: %s", stderr.String()) matches, err := filepath.Glob(filepath.Join(dir, "cudly-gcp-key-*")) @@ -94,7 +95,56 @@ func TestRunConfigureGCP_InterruptAtPromptExits(t *testing.T) { require.NoFileExists(t, filepath.Join(dir, "minted")) } -func startGCPInterruptChild(t *testing.T, phase string) (*exec.Cmd, string, io.ReadCloser, *bytes.Buffer) { +// syncBuffer lets the test read child stderr while exec is still copying it. +type syncBuffer struct { + mu sync.Mutex + buf bytes.Buffer +} + +func (b *syncBuffer) Write(p []byte) (int, error) { + b.mu.Lock() + defer b.mu.Unlock() + return b.buf.Write(p) +} + +func (b *syncBuffer) String() string { + b.mu.Lock() + defer b.mu.Unlock() + return b.buf.String() +} + +// requireMarker polls cond for 10s. On timeout it fails with the child's +// stderr and process state; child stdout is left untouched because one +// scenario keeps it deliberately full. +func requireMarker(t *testing.T, child *exec.Cmd, stderr *syncBuffer, what string, cond func() bool) { + t.Helper() + deadline := time.Now().Add(10 * time.Second) + for !cond() { + if time.Now().After(deadline) { + t.Fatalf("timed out after 10s waiting for %s\nchild state: %s\nchild stderr: %q", what, childState(child), stderr.String()) + } + time.Sleep(10 * time.Millisecond) + } +} + +// childState reaps the child if it already exited, so a later Wait would +// fail; it is only called on the failing path. +func childState(child *exec.Cmd) string { + var ws syscall.WaitStatus + pid, err := syscall.Wait4(child.Process.Pid, &ws, syscall.WNOHANG, nil) + switch { + case err != nil: + return fmt.Sprintf("wait4 failed: %v", err) + case pid == 0: + return fmt.Sprintf("still running (pid %d)", child.Process.Pid) + case ws.Signaled(): + return fmt.Sprintf("exited, killed by signal %v", ws.Signal()) + default: + return fmt.Sprintf("exited with code %d", ws.ExitStatus()) + } +} + +func startGCPInterruptChild(t *testing.T, phase string) (*exec.Cmd, string, io.ReadCloser, *syncBuffer) { t.Helper() dir := t.TempDir() adc := filepath.Join(dir, "adc.json") @@ -111,7 +161,7 @@ func startGCPInterruptChild(t *testing.T, phase string) (*exec.Cmd, string, io.R t.Cleanup(func() { _ = stdin.Close() }) stdout, err := child.StdoutPipe() require.NoError(t, err) - stderr := new(bytes.Buffer) + stderr := new(syncBuffer) child.Stderr = stderr require.NoError(t, child.Start()) t.Cleanup(func() { _ = child.Process.Kill() })