Read logs from Stderr/out Pipe to avoid hanging

`TestContext_sleepTimeoutExpired` can occasionally hang when killing a command
that has Stdout or Stderr set to anything besides `nil` or `*os.File`.
golang/go#23019

Use workaround to read from StdoutPipe and StderrPipe rather than setting
Stdout / Stderr

Author: lornasong

tfexec/cmd.go

@@ -1,9 +1,11 @@
 package tfexec
 
 import (
+	"bufio"
 	"bytes"
 	"context"
 	"encoding/json"
+	"errors"
 	"fmt"
 	"io"
 	"io/ioutil"
@@ -230,3 +232,22 @@ func mergeWriters(writers ...io.Writer) io.Writer {
 	}
 	return io.MultiWriter(compact...)
 }
+
+func writeOutput(r io.ReadCloser, w io.Writer) error {
+	buf := bufio.NewReader(r)
+	for {
+		line, err := buf.ReadBytes('\n')
+		if len(line) > 0 {
+			if _, err := w.Write(line); err != nil {
+				return err
+			}
+		}
+		if err != nil {
+			if errors.As(err, &io.EOF) {
+				return nil
+			}
+
+			return err
+		}
+	}
+}

tfexec/cmd_default.go

@@ -12,14 +12,10 @@ import (
 func (tf *Terraform) runTerraformCmd(ctx context.Context, cmd *exec.Cmd) error {
 	var errBuf strings.Builder
 
-	cmd.Stdout = mergeWriters(cmd.Stdout, tf.stdout)
-	cmd.Stderr = mergeWriters(cmd.Stderr, tf.stderr, &errBuf)
-
 	go func() {
 		<-ctx.Done()
 		if ctx.Err() == context.DeadlineExceeded || ctx.Err() == context.Canceled {
 			if cmd != nil && cmd.Process != nil {
-				tf.logger.Printf("killing process. cmd.ProcessState=%v", cmd.ProcessState)
 				err := cmd.Process.Kill()
 				if err != nil {
 					tf.logger.Printf("error from kill: %s", err)
@@ -35,13 +31,60 @@ func (tf *Terraform) runTerraformCmd(ctx context.Context, cmd *exec.Cmd) error {
 	default:
 	}
 
-	err := cmd.Run()
+	// Read stdout / stderr logs from pipe instead of setting cmd.Stdout and
+	// cmd.Stderr because it can cause hanging when killing the command
+	// https://github.com/golang/go/issues/23019
+	stdoutWriter := mergeWriters(cmd.Stdout, tf.stdout)
+	stderrWriter := mergeWriters(tf.stderr, &errBuf)
+
+	cmd.Stderr = nil
+	cmd.Stdout = nil
+
+	stdoutPipe, err := cmd.StdoutPipe()
+	if err != nil {
+		return err
+	}
+
+	stderrPipe, err := cmd.StderrPipe()
+	if err != nil {
+		return err
+	}
+
+	err = cmd.Start()
+	if err == nil && ctx.Err() != nil {
+		err = ctx.Err()
+	}
+	if err != nil {
+		return tf.wrapExitError(ctx, err, "")
+	}
+
+	exitChLen := 2
+	exitCh := make(chan error, exitChLen)
+	go func() {
+		exitCh <- writeOutput(stdoutPipe, stdoutWriter)
+	}()
+	go func() {
+		exitCh <- writeOutput(stderrPipe, stderrWriter)
+	}()
+
+	err = cmd.Wait()
 	if err == nil && ctx.Err() != nil {
 		err = ctx.Err()
 	}
 	if err != nil {
 		return tf.wrapExitError(ctx, err, errBuf.String())
 	}
 
-	return nil
+	// Wait for the logs to finish writing
+	counter := 0
+	for {
+		counter++
+		err := <-exitCh
+		if err != nil && err != context.Canceled {
+			return tf.wrapExitError(ctx, err, errBuf.String())
+		}
+		if counter >= exitChLen {
+			return ctx.Err()
+		}
+	}
 }

tfexec/cmd_linux.go

@@ -10,9 +10,6 @@ import (
 func (tf *Terraform) runTerraformCmd(ctx context.Context, cmd *exec.Cmd) error {
 	var errBuf strings.Builder
 
-	cmd.Stdout = mergeWriters(cmd.Stdout, tf.stdout)
-	cmd.Stderr = mergeWriters(cmd.Stderr, tf.stderr, &errBuf)
-
 	cmd.SysProcAttr = &syscall.SysProcAttr{
 		// kill children if parent is dead
 		Pdeathsig: syscall.SIGKILL,
@@ -24,7 +21,6 @@ func (tf *Terraform) runTerraformCmd(ctx context.Context, cmd *exec.Cmd) error {
 		<-ctx.Done()
 		if ctx.Err() == context.DeadlineExceeded || ctx.Err() == context.Canceled {
 			if cmd != nil && cmd.Process != nil {
-				tf.logger.Printf("killing process. cmd.ProcessState=%v", cmd.ProcessState)
 				// send SIGINT to process group
 				err := syscall.Kill(-cmd.Process.Pid, syscall.SIGINT)
 				if err != nil {
@@ -43,13 +39,60 @@ func (tf *Terraform) runTerraformCmd(ctx context.Context, cmd *exec.Cmd) error {
 	default:
 	}
 
-	err := cmd.Run()
+	// Read stdout / stderr logs from pipe instead of setting cmd.Stdout and
+	// cmd.Stderr because it can cause hanging when killing the command
+	// https://github.com/golang/go/issues/23019
+	stdoutWriter := mergeWriters(cmd.Stdout, tf.stdout)
+	stderrWriter := mergeWriters(tf.stderr, &errBuf)
+
+	cmd.Stderr = nil
+	cmd.Stdout = nil
+
+	stdoutPipe, err := cmd.StdoutPipe()
+	if err != nil {
+		return err
+	}
+
+	stderrPipe, err := cmd.StderrPipe()
+	if err != nil {
+		return err
+	}
+
+	err = cmd.Start()
+	if err == nil && ctx.Err() != nil {
+		err = ctx.Err()
+	}
+	if err != nil {
+		return tf.wrapExitError(ctx, err, "")
+	}
+
+	exitChLen := 2
+	exitCh := make(chan error, exitChLen)
+	go func() {
+		exitCh <- writeOutput(stdoutPipe, stdoutWriter)
+	}()
+	go func() {
+		exitCh <- writeOutput(stderrPipe, stderrWriter)
+	}()
+
+	err = cmd.Wait()
 	if err == nil && ctx.Err() != nil {
 		err = ctx.Err()
 	}
 	if err != nil {
 		return tf.wrapExitError(ctx, err, errBuf.String())
 	}
 
-	return nil
+	// Wait for the logs to finish writing
+	counter := 0
+	for {
+		counter++
+		err := <-exitCh
+		if err != nil && err != context.Canceled {
+			return tf.wrapExitError(ctx, err, errBuf.String())
+		}
+		if counter >= exitChLen {
+			return ctx.Err()
+		}
+	}
 }