feat: Add Terraform command duration to log messages (#3484)

* Log duration of Terraform commands Closes #3413. Signed-off-by: Leandro López (inkel) <leandro.lopez@grafana.com> * Make log message casing consistent Signed-off-by: Leandro López (inkel) <leandro.lopez@grafana.com> * Add tests for passing duration to Terraform comamnds logs Signed-off-by: Leandro López (inkel) <leandro.lopez@grafana.com> * Add logging mocks for testing Terraform client Signed-off-by: Leandro López (inkel) <leandro.lopez@grafana.com> --------- Signed-off-by: Leandro López (inkel) <leandro.lopez@grafana.com>
2026-07-29 00:28:19 +00:00 · 2023-06-09 23:03:36 -03:00
parent 3d5786cbad
commit c709fd0cff
4 changed files with 48 additions and 11 deletions
--- a/server/core/runtime/models/shell_command_runner.go
+++ b/server/core/runtime/models/shell_command_runner.go
@@ -6,6 +6,7 @@ import (
 	"os/exec"
 	"strings"
 	"sync"
+	"time"

 	"github.com/pkg/errors"
 	"github.com/runatlantis/atlantis/server/events/command"
@@ -76,6 +77,7 @@ func (s *ShellCommandRunner) Run(ctx command.ProjectContext) (string, error) {
 func (s *ShellCommandRunner) RunCommandAsync(ctx command.ProjectContext) (chan<- string, <-chan Line) {
 	outCh := make(chan Line)
 	inCh := make(chan string)
+	start := time.Now()

 	// We start a goroutine to do our work asynchronously and then immediately
 	// return our channels.
@@ -147,13 +149,16 @@ func (s *ShellCommandRunner) RunCommandAsync(ctx command.ProjectContext) (chan<-
 		// Wait for the command to complete.
 		err = s.cmd.Wait()

+		dur := time.Since(start)
+		log := ctx.Log.With("duration", dur)
+
 		// We're done now. Send an error if there was one.
 		if err != nil {
 			err = errors.Wrapf(err, "running %q in %q", s.command, s.workingDir)
-			ctx.Log.Err(err.Error())
+			log.Err(err.Error())
 			outCh <- Line{Err: err}
 		} else {
-			ctx.Log.Info("successfully ran %q in %q", s.command, s.workingDir)
+			log.Info("successfully ran %q in %q", s.command, s.workingDir)
 		}
 	}()

--- a/server/core/runtime/models/shell_command_runner_test.go
+++ b/server/core/runtime/models/shell_command_runner_test.go
@@ -11,7 +11,7 @@ import (
 	"github.com/runatlantis/atlantis/server/core/runtime/models"
 	"github.com/runatlantis/atlantis/server/events/command"
 	"github.com/runatlantis/atlantis/server/jobs/mocks"
-	"github.com/runatlantis/atlantis/server/logging"
+	logmocks "github.com/runatlantis/atlantis/server/logging/mocks"
 	. "github.com/runatlantis/atlantis/testing"
 )

@@ -37,8 +37,10 @@ func TestShellCommandRunner_Run(t *testing.T) {
 	for _, c := range cases {
 		t.Run(c.Command, func(t *testing.T) {
 			RegisterMockTestingT(t)
+			log := logmocks.NewMockSimpleLogging()
+			When(log.With(AnyString(), AnyInterface())).ThenReturn(log)
 			ctx := command.ProjectContext{
-				Log:        logging.NewNoopLogger(t),
+				Log:        log,
 				Workspace:  "default",
 				RepoRelDir: ".",
 			}
@@ -61,6 +63,8 @@ func TestShellCommandRunner_Run(t *testing.T) {
 				projectCmdOutputHandler.VerifyWasCalledOnce().Send(ctx, line, false)
 			}

+			log.VerifyWasCalledOnce().With(EqString("duration"), AnyInterface())
+
 			// And again with streaming disabled. Everything should be the same except the
 			// command output handler should not have received anything

@@ -70,6 +74,8 @@ func TestShellCommandRunner_Run(t *testing.T) {
 			Ok(t, err)
 			Equals(t, expectedOutput, output)
 			projectCmdOutputHandler.VerifyWasCalled(Never()).Send(matchers.AnyCommandProjectContext(), AnyString(), EqBool(false))
+
+			log.VerifyWasCalled(Twice()).With(EqString("duration"), AnyInterface())
 		})
 	}
 }
--- a/server/core/terraform/terraform_client.go
+++ b/server/core/terraform/terraform_client.go
@@ -28,6 +28,7 @@ import (
 	"sort"
 	"strings"
 	"sync"
+	"time"

 	"github.com/hashicorp/go-getter/v2"
 	"github.com/hashicorp/go-version"
@@ -413,13 +414,16 @@ func (c *DefaultClient) RunCommandWithVersion(ctx command.ProjectContext, path s
 		envVars = append(envVars, fmt.Sprintf("%s=%s", key, val))
 	}
 	cmd.Env = envVars
+	start := time.Now()
 	out, err := cmd.CombinedOutput()
+	dur := time.Since(start)
+	log := ctx.Log.With("duration", dur)
 	if err != nil {
 		err = errors.Wrapf(err, "running %q in %q", tfCmd, path)
-		ctx.Log.Err(err.Error())
+		log.Err(err.Error())
 		return ansi.Strip(string(out)), err
 	}
-	ctx.Log.Info("Successfully ran %q in %q", tfCmd, path)
+	log.Info("successfully ran %q in %q", tfCmd, path)

 	return ansi.Strip(string(out)), nil
 }
--- a/server/core/terraform/terraform_client_internal_test.go
+++ b/server/core/terraform/terraform_client_internal_test.go
@@ -8,11 +8,13 @@ import (
 	"testing"

 	version "github.com/hashicorp/go-version"
+	. "github.com/petergtz/pegomock"
 	runtimemodels "github.com/runatlantis/atlantis/server/core/runtime/models"
 	"github.com/runatlantis/atlantis/server/events/command"
 	"github.com/runatlantis/atlantis/server/events/models"
 	jobmocks "github.com/runatlantis/atlantis/server/jobs/mocks"
 	"github.com/runatlantis/atlantis/server/logging"
+	logmocks "github.com/runatlantis/atlantis/server/logging/mocks"
 	. "github.com/runatlantis/atlantis/testing"
 )

@@ -168,10 +170,12 @@ func TestDefaultClient_RunCommandWithVersion_Error(t *testing.T) {
 }

 func TestDefaultClient_RunCommandAsync_Success(t *testing.T) {
+	RegisterMockTestingT(t)
 	v, err := version.NewVersion("0.11.11")
 	Ok(t, err)
 	tmp := t.TempDir()
-	logger := logging.NewNoopLogger(t)
+	logger := logmocks.NewMockSimpleLogging()
+	When(logger.With(AnyString(), AnyInterface())).ThenReturn(logger)
 	projectCmdOutputHandler := jobmocks.NewMockProjectCommandOutputHandler()

 	ctx := command.ProjectContext{
@@ -211,13 +215,17 @@ func TestDefaultClient_RunCommandAsync_Success(t *testing.T) {
 	Ok(t, err)
 	exp := fmt.Sprintf("TF_IN_AUTOMATION=true TF_PLUGIN_CACHE_DIR=%s WORKSPACE=workspace ATLANTIS_TERRAFORM_VERSION=0.11.11 DIR=%s", tmp, tmp)
 	Equals(t, exp, out)
+
+	logger.VerifyWasCalledOnce().With(EqString("duration"), AnyInterface())
 }

 func TestDefaultClient_RunCommandAsync_BigOutput(t *testing.T) {
+	RegisterMockTestingT(t)
 	v, err := version.NewVersion("0.11.11")
 	Ok(t, err)
 	tmp := t.TempDir()
-	logger := logging.NewNoopLogger(t)
+	logger := logmocks.NewMockSimpleLogging()
+	When(logger.With(AnyString(), AnyInterface())).ThenReturn(logger)
 	projectCmdOutputHandler := jobmocks.NewMockProjectCommandOutputHandler()

 	ctx := command.ProjectContext{
@@ -258,13 +266,17 @@ func TestDefaultClient_RunCommandAsync_BigOutput(t *testing.T) {
 	out, err := waitCh(outCh)
 	Ok(t, err)
 	Equals(t, strings.TrimRight(exp, "\n"), out)
+
+	logger.VerifyWasCalledOnce().With(EqString("duration"), AnyInterface())
 }

 func TestDefaultClient_RunCommandAsync_StderrOutput(t *testing.T) {
+	RegisterMockTestingT(t)
 	v, err := version.NewVersion("0.11.11")
 	Ok(t, err)
 	tmp := t.TempDir()
-	logger := logging.NewNoopLogger(t)
+	logger := logmocks.NewMockSimpleLogging()
+	When(logger.With(AnyString(), AnyInterface())).ThenReturn(logger)
 	projectCmdOutputHandler := jobmocks.NewMockProjectCommandOutputHandler()

 	ctx := command.ProjectContext{
@@ -294,13 +306,17 @@ func TestDefaultClient_RunCommandAsync_StderrOutput(t *testing.T) {
 	out, err := waitCh(outCh)
 	Ok(t, err)
 	Equals(t, "stderr", out)
+
+	logger.VerifyWasCalledOnce().With(EqString("duration"), AnyInterface())
 }

 func TestDefaultClient_RunCommandAsync_ExitOne(t *testing.T) {
+	RegisterMockTestingT(t)
 	v, err := version.NewVersion("0.11.11")
 	Ok(t, err)
 	tmp := t.TempDir()
-	logger := logging.NewNoopLogger(t)
+	logger := logmocks.NewMockSimpleLogging()
+	When(logger.With(AnyString(), AnyInterface())).ThenReturn(logger)
 	projectCmdOutputHandler := jobmocks.NewMockProjectCommandOutputHandler()

 	ctx := command.ProjectContext{
@@ -331,13 +347,17 @@ func TestDefaultClient_RunCommandAsync_ExitOne(t *testing.T) {
 	ErrEquals(t, fmt.Sprintf(`running "echo dying && exit 1" in %q: exit status 1`, tmp), err)
 	// Test that we still get our output.
 	Equals(t, "dying", out)
+
+	logger.VerifyWasCalledOnce().With(EqString("duration"), AnyInterface())
 }

 func TestDefaultClient_RunCommandAsync_Input(t *testing.T) {
+	RegisterMockTestingT(t)
 	v, err := version.NewVersion("0.11.11")
 	Ok(t, err)
 	tmp := t.TempDir()
-	logger := logging.NewNoopLogger(t)
+	logger := logmocks.NewMockSimpleLogging()
+	When(logger.With(AnyString(), AnyInterface())).ThenReturn(logger)
 	projectCmdOutputHandler := jobmocks.NewMockProjectCommandOutputHandler()

 	ctx := command.ProjectContext{
@@ -369,6 +389,8 @@ func TestDefaultClient_RunCommandAsync_Input(t *testing.T) {
 	out, err := waitCh(outCh)
 	Ok(t, err)
 	Equals(t, "echo me", out)
+
+	logger.VerifyWasCalledOnce().With(EqString("duration"), AnyInterface())
 }

 func waitCh(ch <-chan runtimemodels.Line) (string, error) {