From 400f9d7df0d9526a73b73caf0c30f41fbb68a7e6 Mon Sep 17 00:00:00 2001 From: Lorna Song Date: Mon, 9 May 2022 15:04:23 -0400 Subject: [PATCH 1/3] Update TestContext_sleepTimeoutExpired to check for canceling within timeframe Add a timeout to the test to ensure that the terraform apply cancels within a reasonable time of the 5s timeout. Currently, this test is not canceling the terraform apply as expected. In the logs you can see that the test takes 1 min rather than ~5s: ``` --- PASS: TestContext_sleepTimeoutExpired/sleep-0.12.31 (62.13s) ``` ``` === RUN TestContext_sleepTimeoutExpired/sleep-0.12.31 util_test.go:113: [INFO] running Terraform command: /var/folders/6y/gy9gggt14379c_k39vwb50lc0000gn/T/terraform_1378921380/terraform apply -no-color -auto-approve -input=false -lock=true -parallelism=10 -refresh=true util_test.go:103: CLI Output: // truncated ... time_sleep.sleep: Creating... time_sleep.sleep: Still creating... [10s elapsed] time_sleep.sleep: Still creating... [20s elapsed] time_sleep.sleep: Still creating... [30s elapsed] time_sleep.sleep: Still creating... [41s elapsed] time_sleep.sleep: Still creating... [51s elapsed] time_sleep.sleep: Creation complete after 1m0s [id=2022-05-06T17:40:20Z] Apply complete! Resources: 1 added, 0 changed, 0 destroyed. ``` --- tfexec/internal/e2etest/errors_test.go | 22 +++++++++++++++------- 1 file changed, 15 insertions(+), 7 deletions(-) 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") } }) } From b4e272e64fcc3cd429c152bb7cb7b58d85e0d3a4 Mon Sep 17 00:00:00 2001 From: Lorna Song Date: Mon, 9 May 2022 18:19:34 -0400 Subject: [PATCH 2/3] Remove runTerraformCmd check for cmd.ProcessState Processes were not being killed because cmd.ProcessState was nil. With this change, processes will be able to make the request to Kill(). Added a temporary log to printout cmd.ProcessState to demonstrate. Will be removed in next commit. Note: this will cause hanging `TestContext_sleepTimeoutExpired` due to a known Golang issue with killing a command when Stdout or Stderr are set to anything besides `nil` or `*os.File`. This is because the Kill does not notify the stdout/stderr subprocesses to stop. `cmd.Wait` (called by `cmd.Run`) waits indefinitely for those subprocesses to stop. --- tfexec/cmd_default.go | 3 ++- tfexec/cmd_linux.go | 3 ++- 2 files changed, 4 insertions(+), 2 deletions(-) diff --git a/tfexec/cmd_default.go b/tfexec/cmd_default.go index 08a65bcd..903bbe3e 100644 --- a/tfexec/cmd_default.go +++ b/tfexec/cmd_default.go @@ -18,7 +18,8 @@ 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 { + 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) diff --git a/tfexec/cmd_linux.go b/tfexec/cmd_linux.go index 7cbdcb96..8ac05a11 100644 --- a/tfexec/cmd_linux.go +++ b/tfexec/cmd_linux.go @@ -23,7 +23,8 @@ 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 { + 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 { From c3ccdc3086237f26fae47cece0c2b4e8aed538b4 Mon Sep 17 00:00:00 2001 From: Lorna Song Date: Tue, 10 May 2022 15:05:19 -0400 Subject: [PATCH 3/3] 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`. https://github.com/golang/go/issues/23019 Use workaround to read from StdoutPipe and StderrPipe rather than setting Stdout / Stderr --- tfexec/cmd.go | 21 +++++++++++++++++ tfexec/cmd_default.go | 55 ++++++++++++++++++++++++++++++++++++++----- tfexec/cmd_linux.go | 55 ++++++++++++++++++++++++++++++++++++++----- 3 files changed, 119 insertions(+), 12 deletions(-) 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 903bbe3e..b2c5f544 100644 --- a/tfexec/cmd_default.go +++ b/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,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() } @@ -43,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 8ac05a11..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, @@ -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,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() } @@ -51,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() + } + } }