diff --git a/tfexec/cmd.go b/tfexec/cmd.go index 83abd22d..32cc23a5 100644 --- a/tfexec/cmd.go +++ b/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 + } + } +} diff --git a/tfexec/cmd_default.go b/tfexec/cmd_default.go index 08a65bcd..b2c5f544 100644 --- a/tfexec/cmd_default.go +++ b/tfexec/cmd_default.go @@ -12,13 +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 && cmd.ProcessState != nil { + if cmd != nil && cmd.Process != nil { err := cmd.Process.Kill() if err != nil { tf.logger.Printf("error from kill: %s", err) @@ -34,7 +31,43 @@ 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() } @@ -42,5 +75,16 @@ func (tf *Terraform) runTerraformCmd(ctx context.Context, cmd *exec.Cmd) error { 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() + } + } } diff --git a/tfexec/cmd_linux.go b/tfexec/cmd_linux.go index 7cbdcb96..75754f83 100644 --- a/tfexec/cmd_linux.go +++ b/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, @@ -23,7 +20,7 @@ func (tf *Terraform) runTerraformCmd(ctx context.Context, cmd *exec.Cmd) error { go func() { <-ctx.Done() if ctx.Err() == context.DeadlineExceeded || ctx.Err() == context.Canceled { - if cmd != nil && cmd.Process != nil && cmd.ProcessState != nil { + if cmd != nil && cmd.Process != nil { // send SIGINT to process group err := syscall.Kill(-cmd.Process.Pid, syscall.SIGINT) if err != nil { @@ -42,7 +39,43 @@ 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() } @@ -50,5 +83,16 @@ func (tf *Terraform) runTerraformCmd(ctx context.Context, cmd *exec.Cmd) error { 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() + } + } } diff --git a/tfexec/internal/e2etest/errors_test.go b/tfexec/internal/e2etest/errors_test.go index 804024ea..95775557 100644 --- a/tfexec/internal/e2etest/errors_test.go +++ b/tfexec/internal/e2etest/errors_test.go @@ -205,13 +205,21 @@ func TestContext_sleepTimeoutExpired(t *testing.T) { ctx, cancel := context.WithTimeout(ctx, 5*time.Second) defer cancel() - err = tf.Apply(ctx) - if err == nil { - t.Fatal("expected error, but didn't find one") - } - - if !errors.Is(err, context.DeadlineExceeded) { - t.Fatalf("expected context.DeadlineExceeded, got %T %s", err, err) + errCh := make(chan error) + go func() { + err = tf.Apply(ctx) + if err != nil { + errCh <- err + } + }() + + select { + case err := <-errCh: + if !errors.Is(err, context.DeadlineExceeded) { + t.Fatalf("expected context.DeadlineExceeded, got %T %s", err, err) + } + case <-time.After(time.Second * 10): + t.Fatal("terraform apply should have canceled and returned in ~5s") } }) }