diff --git a/test/e2e/e2e_test.go b/test/e2e/e2e_test.go index a850945..ac736b0 100644 --- a/test/e2e/e2e_test.go +++ b/test/e2e/e2e_test.go @@ -19,7 +19,9 @@ package e2e import ( "archive/zip" + "bytes" "encoding/json" + "errors" "fmt" "io" "net/http" @@ -27,6 +29,7 @@ import ( "os/exec" "path/filepath" "runtime" + "strconv" "strings" "testing" "time" @@ -170,23 +173,7 @@ func run(t *testing.T, timeout time.Duration, name string, args ...string) (stri // bypasses that package by design: it drives the real binaries the way a // user does. cmd.Env = append(os.Environ(), "WSL_UTF8=1") - done := make(chan struct{}) - var out []byte - var err error - go func() { - out, err = cmd.CombinedOutput() - close(done) - }() - select { - case <-done: - return strings.TrimSpace(string(out)), err - case <-time.After(timeout): - if cmd.Process != nil { - cmd.Process.Kill() - } - <-done - return strings.TrimSpace(string(out)), fmt.Errorf("%s timed out after %s", name, timeout) - } + return runBounded(cmd, timeout, name) } // runEnv is run() with an explicit environment, for subprocesses that shell @@ -197,19 +184,52 @@ func runEnv(t *testing.T, env []string, timeout time.Duration, name string, args t.Helper() cmd := exec.Command(name, args...) cmd.Env = env - done := make(chan struct{}) - var out []byte - var err error - go func() { out, err = cmd.CombinedOutput(); close(done) }() + return runBounded(cmd, timeout, name) +} + +// errTimedOut marks a runBounded timeout, for callers that add a hint to it. +var errTimedOut = errors.New("timed out") + +// killGrace is how long runBounded still waits for output after killing a +// timed-out command's process tree. +const killGrace = 5 * time.Second + +// runBounded runs cmd and returns its trimmed combined output, giving up after +// timeout with " timed out after ". Every command the suite +// runs with a timeout goes through here. +// +// On timeout it kills the whole process tree, not only cmd's own process. +// Killing only the direct child is not enough (#554): a grandchild that +// inherited the output pipe keeps it open, and the wait for output then lasts +// until that grandchild exits on its own -- a 2s timeout took 29s. A process +// whose parent has already exited is outside the tree taskkill walks, so if +// the pipe is still held killGrace after the kill, it stops waiting and +// returns without the output. +func runBounded(cmd *exec.Cmd, timeout time.Duration, what string) (string, error) { + var buf bytes.Buffer + cmd.Stdout = &buf + cmd.Stderr = &buf + if err := cmd.Start(); err != nil { + return "", err + } + done := make(chan error, 1) + go func() { done <- cmd.Wait() }() select { - case <-done: - return strings.TrimSpace(string(out)), err + case err := <-done: + return strings.TrimSpace(buf.String()), err case <-time.After(timeout): - if cmd.Process != nil { - cmd.Process.Kill() - } - <-done - return strings.TrimSpace(string(out)), fmt.Errorf("%s timed out after %s", name, timeout) + } + // taskkill /T needs the process alive to find its descendants, so it goes + // first; Kill covers taskkill itself failing. + exec.Command("taskkill", "/T", "/F", "/PID", strconv.Itoa(cmd.Process.Pid)).Run() + cmd.Process.Kill() + select { + case <-done: + return strings.TrimSpace(buf.String()), fmt.Errorf("%s %w after %s", what, errTimedOut, timeout) + case <-time.After(killGrace): + // Wait is still copying into buf, so it cannot be read here. + return "", fmt.Errorf("%s %w after %s; output lost: something outside its process tree still held the pipe %s after the kill", + what, errTimedOut, timeout, killGrace) } } @@ -226,24 +246,7 @@ func dockerE(t *testing.T, s *state, timeout time.Duration, args ...string) (str t.Helper() cmd := exec.Command(s.docker, args...) cmd.Env = s.dockerEnv() - done := make(chan struct{}) - var out []byte - var err error - go func() { - out, err = cmd.CombinedOutput() - close(done) - }() - select { - case <-done: - return strings.TrimSpace(string(out)), err - case <-time.After(timeout): - if cmd.Process != nil { - cmd.Process.Kill() - } - <-done - return strings.TrimSpace(string(out)), fmt.Errorf("docker %s timed out after %s", - strings.Join(args, " "), timeout) - } + return runBounded(cmd, timeout, "docker "+strings.Join(args, " ")) } func wslProcCount(t *testing.T) int { @@ -1630,21 +1633,11 @@ func dockerStdin(t *testing.T, s *state, stdin string, timeout time.Duration, ar cmd := exec.Command(s.docker, args...) cmd.Env = s.dockerEnv() cmd.Stdin = strings.NewReader(stdin) - done := make(chan struct{}) - var out []byte - var err error - go func() { out, err = cmd.CombinedOutput(); close(done) }() - select { - case <-done: - return strings.TrimSpace(string(out)), err - case <-time.After(timeout): - if cmd.Process != nil { - cmd.Process.Kill() - } - <-done - return strings.TrimSpace(string(out)), fmt.Errorf("docker %s timed out after %s (stdin EOF likely not propagating)", - strings.Join(args, " "), timeout) + out, err := runBounded(cmd, timeout, "docker "+strings.Join(args, " ")) + if errors.Is(err, errTimedOut) { + err = fmt.Errorf("%w (stdin EOF likely not propagating)", err) } + return out, err } func stageLogsFollow(t *testing.T, s *state) { @@ -1729,20 +1722,7 @@ services: cmd := exec.Command(s.docker, append([]string{"compose"}, args...)...) cmd.Dir = dir cmd.Env = s.dockerEnv() - done := make(chan struct{}) - var out []byte - var err error - go func() { out, err = cmd.CombinedOutput(); close(done) }() - select { - case <-done: - return strings.TrimSpace(string(out)), err - case <-time.After(timeout): - if cmd.Process != nil { - cmd.Process.Kill() - } - <-done - return strings.TrimSpace(string(out)), fmt.Errorf("compose timed out after %s", timeout) - } + return runBounded(cmd, timeout, "compose") } defer composeCmd(3*time.Minute, "down", "--timeout", "5") @@ -2192,20 +2172,7 @@ func (s *state) runDocker(t *testing.T, timeout time.Duration, args ...string) ( t.Helper() cmd := exec.Command(s.docker, args...) cmd.Env = s.hostEnv() - done := make(chan struct{}) - var out []byte - var err error - go func() { out, err = cmd.CombinedOutput(); close(done) }() - select { - case <-done: - return strings.TrimSpace(string(out)), err - case <-time.After(timeout): - if cmd.Process != nil { - cmd.Process.Kill() - } - <-done - return strings.TrimSpace(string(out)), fmt.Errorf("docker timed out after %s", timeout) - } + return runBounded(cmd, timeout, "docker") } // stageAuditToggle is the regression test for #202: the audit setting has to diff --git a/test/e2e/harness_test.go b/test/e2e/harness_test.go new file mode 100644 index 0000000..7c93e43 --- /dev/null +++ b/test/e2e/harness_test.go @@ -0,0 +1,64 @@ +//go:build e2e + +package e2e + +import ( + "os" + "runtime" + "strings" + "testing" + "time" +) + +// A timeout has to end the wait even when the command started something that +// inherited its output pipe. Killing only the direct child leaves that +// process holding the pipe, and the old harness then waited out its whole +// run: a 2s timeout that took 11s (#554). +func TestTimeoutEndsTheWait(t *testing.T) { + if runtime.GOOS != "windows" { + t.Skip("the harness's process-tree kill is Windows-specific") + } + const timeout = 2 * time.Second + cases := []struct { + name string + args []string + lostOK bool // whether the helper may give up on the output + }{ + // cmd.exe waits on ping, its child, which inherited the pipe: the + // tree is intact when the timeout fires, so the tree kill closes the + // pipe and the output is kept. + {"grandchild", []string{"/c", "ping -n 30 127.0.0.1"}, false}, + // cmd.exe exits at once and leaves ping running with the pipe: there + // is no live parent left to walk a tree from, so only the grace + // period ends the wait. + {"orphan", []string{"/c", "start /b ping -n 30 127.0.0.1"}, true}, + } + helpers := []struct { + name string + run func(args []string) error + }{ + {"run", func(a []string) error { _, err := run(t, timeout, "cmd", a...); return err }}, + {"runEnv", func(a []string) error { _, err := runEnv(t, os.Environ(), timeout, "cmd", a...); return err }}, + {"dockerE", func(a []string) error { _, err := dockerE(t, &state{docker: "cmd"}, timeout, a...); return err }}, + } + for _, c := range cases { + for _, h := range helpers { + t.Run(c.name+"/"+h.name, func(t *testing.T) { + start := time.Now() + err := h.run(c.args) + took := time.Since(start) + if err == nil || !strings.Contains(err.Error(), "timed out") { + t.Errorf("err = %v, want a timeout", err) + } + if !c.lostOK && err != nil && strings.Contains(err.Error(), "output lost") { + t.Errorf("the tree kill did not close the pipe: %v", err) + } + // ping -n 30 runs ~29s; the bound leaves room for the kill + // and the grace period, and none for waiting ping out. + if took > 12*time.Second { + t.Errorf("a %s timeout returned after %s", timeout, took.Round(100*time.Millisecond)) + } + }) + } + } +}