diff --git a/server/core/runtime/models/shell_command_runner.go b/server/core/runtime/models/shell_command_runner.go index c30f97378..3dcd56dd8 100644 --- 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) } }() diff --git a/server/core/runtime/models/shell_command_runner_test.go b/server/core/runtime/models/shell_command_runner_test.go index 2bb5f0a28..9683ac88f 100644 --- 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()) }) } } diff --git a/server/core/terraform/terraform_client.go b/server/core/terraform/terraform_client.go index 7da9781eb..2f57d08cd 100644 --- 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 } diff --git a/server/core/terraform/terraform_client_internal_test.go b/server/core/terraform/terraform_client_internal_test.go index dc9f0b995..d497d74e7 100644 --- 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) {