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() }) 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") + } +}