Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

feat: Add Terraform command duration to log messages #3484

Merged
merged 4 commits into from
Jun 10, 2023
Merged

feat: Add Terraform command duration to log messages #3484

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
4600a34
Log duration of Terraform commands
inkel Jun 4, 2023
ecd8c19
Make log message casing consistent
inkel Jun 4, 2023
5896844
Add tests for passing duration to Terraform comamnds logs
inkel Jun 8, 2023
19efc41
Add logging mocks for testing Terraform client
inkel Jun 9, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
9 changes: 7 additions & 2 deletions server/core/runtime/models/shell_command_runner.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -6,6 +6,7 @@ import (
"os/exec"
"strings"
"sync"
"time"

"github.com/pkg/errors"
"github.com/runatlantis/atlantis/server/events/command"
Expand Down Expand Up @@ -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.
Expand Down Expand Up @@ -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)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Please add a unit test for this in shell_command_runner_test.go. if this doesn't exist, please create one to ensure this functionality works as expected and doesn't break in the future.

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)
}
}()

Expand Down
10 changes: 8 additions & 2 deletions server/core/runtime/models/shell_command_runner_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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"
)

Expand All @@ -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: ".",
}
Expand All @@ -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

Expand All @@ -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())
})
}
}
8 changes: 6 additions & 2 deletions server/core/terraform/terraform_client.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -28,6 +28,7 @@ import (
"sort"
"strings"
"sync"
"time"

"github.com/hashicorp/go-getter/v2"
"github.com/hashicorp/go-version"
Expand Down Expand Up @@ -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)
Copy link
Member

@nitrocode nitrocode Jun 5, 2023 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Same test request here (prev comment) please but for terraform_client_test.go

https://github.com/runatlantis/atlantis/blob/main/server/core/terraform/terraform_client_test.go

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
}
Expand Down
32 changes: 27 additions & 5 deletions server/core/terraform/terraform_client_internal_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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"
)

Expand Down Expand Up @@ -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{
Expand Down Expand Up @@ -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{
Expand Down Expand Up @@ -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{
Expand Down Expand Up @@ -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{
Expand Down Expand Up @@ -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{
Expand Down Expand Up @@ -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) {
Expand Down