Start/Wait on exec.Cmd when using pipes (#611)

This might've been the cause for the flaky test we saw, because the docs
say that `cmd.Run()` in combination with `StdoutPipe`/`StderrPipe` is
wrong:

> `Wait` will close the pipe after seeing the command exit, so most callers
> need not close the pipe themselves. It is thus incorrect to call `Wait`
> before all reads from the pipe have completed. For the same reason, it
> is incorrect to call `Run` when using `StdoutPipe`. See the example for
> idiomatic usage.

See: https://pkg.go.dev/os/exec#example-Cmd.StdoutPipe

Author: mrnugget

internal/batches/executor/run_steps.go

@@ -313,8 +313,6 @@ func executeSingleStep(
 		cmd.Dir = *dir
 	}
 
-	var stdoutBuffer, stderrBuffer bytes.Buffer
-
 	writerCtx, writerCancel := context.WithCancel(ctx)
 	defer writerCancel()
 	uiStdoutWriter := opts.ui.StepStdoutWriter(writerCtx, opts.task, i)
@@ -324,33 +322,47 @@ func executeSingleStep(
 		uiStderrWriter.Close()
 	}()
 
+	var stdoutBuffer, stderrBuffer bytes.Buffer
 	stdout := io.MultiWriter(&stdoutBuffer, uiStdoutWriter, opts.logger.PrefixWriter("stdout"))
 	stderr := io.MultiWriter(&stderrBuffer, uiStderrWriter, opts.logger.PrefixWriter("stderr"))
 
+	// Setup readers that pipe the output into the given buffers
 	wg, err := process.PipeOutput(cmd, stdout, stderr)
 	if err != nil {
 		return bytes.Buffer{}, bytes.Buffer{}, errors.Wrap(err, "piping process output")
 	}
 
+	newStepFailedErr := func(wrappedErr error) stepFailedErr {
+		return stepFailedErr{
+			Err:         wrappedErr,
+			Args:        cmd.Args,
+			Run:         runScript,
+			Container:   step.Container,
+			TmpFilename: containerTemp,
+			Stdout:      strings.TrimSpace(stdoutBuffer.String()),
+			Stderr:      strings.TrimSpace(stderrBuffer.String()),
+		}
+	}
+
 	opts.logger.Logf("[Step %d] run: %q, container: %q", i+1, step.Run, step.Container)
 	opts.logger.Logf("[Step %d] full command: %q", i+1, strings.Join(cmd.Args, " "))
 
+	// Start the command
 	t0 := time.Now()
-	err = cmd.Run()
+	if err := cmd.Start(); err != nil {
+		opts.logger.Logf("[Step %d] error starting Docker container: %+v", i+1, err)
+		return stdoutBuffer, stderrBuffer, newStepFailedErr(err)
+	}
+
+	// Wait for the readers, because the pipes used by PipeOutput under the
+	// hood are closed when the command exits
 	wg.Wait()
+	// Now wait for the command
+	err = cmd.Wait()
 	elapsed := time.Since(t0).Round(time.Millisecond)
 	if err != nil {
 		opts.logger.Logf("[Step %d] took %s; error running Docker container: %+v", i+1, elapsed, err)
-
-		return stdoutBuffer, stderrBuffer, stepFailedErr{
-			Err:         err,
-			Args:        cmd.Args,
-			Run:         runScript,
-			Container:   step.Container,
-			TmpFilename: containerTemp,
-			Stdout:      strings.TrimSpace(stdoutBuffer.String()),
-			Stderr:      strings.TrimSpace(stderrBuffer.String()),
-		}
+		return stdoutBuffer, stderrBuffer, newStepFailedErr(err)
 	}
 
 	opts.logger.Logf("[Step %d] complete in %s", i+1, elapsed)