Repository: runatlantis/atlantis (language: go)

Issue:
Add plan and apply durations to atlantis log messages
<!--- Please keep this note for the community --->

### Community Note

- Please vote on this issue by adding a 👍 [reaction](https://blog.github.com/2016-03-10-add-reactions-to-pull-requests-issues-and-comments/) to the original issue to help the community and maintainers prioritize this request. Searching for pre-existing feature requests helps us consolidate datapoints for identical requirements into a single place, thank you!
- Please do not leave "+1" or other comments that do not add relevant new information or questions, they generate extra noise for issue followers and do not help prioritize the request.
- If you are interested in working on this issue or have submitted a pull request, please leave a comment.

<!--- Thank you for keeping this note for the community --->

---

- [ ] I'd be willing to implement this feature ([contributing guide](https://github.com/runatlantis/atlantis/blob/main/CONTRIBUTING.md))

**Describe the user story**
As an engineer who has many repos that use atlantis, I would like to know how long my plans and applies are taking and have these durations available in my SIEM or other tool so I can monitor and review trends over time.

**Describe the solution you'd like**
I want duration added to the log message, for example
```
{
  "message": {
    "level": "info",
    "ts": "2023-05-17T22:30:28.885Z",
    "caller": "terraform/terraform_client.go:422",
    "msg": "Successfully ran \"/home/atlantis/.atlantis/bin/terraform1.3.2 plan -input=false -refresh -out \\\"/home/atlantis/.atlantis/repos/myorg/myrepo/blah/blah/blah/default.tfplan\\\"\" in \"/home/atlantis/.atlantis/repos/myorg/myrepo/blah/blah/blah\"",
    "json": {
      "repo": "myorg/myrepo",
      "pull": "1142"
    },
    "duration": 123.   <------- this gets added!!
}
```

**Describe the drawbacks of your solution**
Atlantis needs to keep track of when commands were started and when they were completed and add that to the log message

**Describe alternatives you've considered**
I have tried using my SIEM to look for the message for the start of the plan and tie that to the message that reports the successful plan and then subtract the two timeframes. It is gross.

Add plan and apply durations to atlantis log messages
<!--- Please keep this note for the community --->

### Community Note

- Please vote on this issue by adding a 👍 [reaction](https://blog.github.com/2016-03-10-add-reactions-to-pull-requests-issues-and-comments/) to the original issue to help the community and maintainers prioritize this request. Searching for pre-existing feature requests helps us consolidate datapoints for identical requirements into a single place, thank you!
- Please do not leave "+1" or other comments that do not add relevant new information or questions, they generate extra noise for issue followers and do not help prioritize the request.
- If you are interested in working on this issue or have submitted a pull request, please leave a comment.

<!--- Thank you for keeping this note for the community --->

---

- [ ] I'd be willing to implement this feature ([contributing guide](https://github.com/runatlantis/atlantis/blob/main/CONTRIBUTING.md))

**Describe the user story**
As an engineer who has many repos that use atlantis, I would like to know how long my plans and applies are taking and have these durations available in my SIEM or other tool so I can monitor and review trends over time.

**Describe the solution you'd like**
I want duration added to the log message, for example
```
{
  "message": {
    "level": "info",
    "ts": "2023-05-17T22:30:28.885Z",
    "caller": "terraform/terraform_client.go:422",
    "msg": "Successfully ran \"/home/atlantis/.atlantis/bin/terraform1.3.2 plan -input=false -refresh -out \\\"/home/atlantis/.atlantis/repos/myorg/myrepo/blah/blah/blah/default.tfplan\\\"\" in \"/home/atlantis/.atlantis/repos/myorg/myrepo/blah/blah/blah\"",
    "json": {
      "repo": "myorg/myrepo",
      "pull": "1142"
    },
    "duration": 123.   <------- this gets added!!
}
```

**Describe the drawbacks of your solution**
Atlantis needs to keep track of when commands were started and when they were completed and add that to the log message

**Describe alternatives you've considered**
I have tried using my SIEM to look for the message for the start of the plan and tie that to the message that reports the successful plan and then subtract the two timeframes. It is gross.



Discussion / hints:
This would be handy. If we're going to log it, might as well expose them as metrics in Prometheus too
It would also a great addition to the templates data.
Maybe this could be helpful as a workaround 'til the feature is implemented:

https://github.com/datarootsio/tf-profile

As cool as `tf-profile` looks I don't think adding a dependency on a 3rd-party tool should be an Atlantis concern. It does look like a cool post-workflow tool to have in the docs, tho.

I've been looking at the code and it looks fairly simple (not easy) to add it to the logs, not so much to make it available to the templates data and/or Prometheus metrics.
This would be handy. If we're going to log it, might as well expose them as metrics in Prometheus too
It would also a great addition to the templates data.
Maybe this could be helpful as a workaround 'til the feature is implemented:

https://github.com/datarootsio/tf-profile

As cool as `tf-profile` looks I don't think adding a dependency on a 3rd-party tool should be an Atlantis concern. It does look like a cool post-workflow tool to have in the docs, tho.

I've been looking at the code and it looks fairly simple (not easy) to add it to the logs, not so much to make it available to the templates data and/or Prometheus metrics.

Fix patch:
diff --git a/server/core/runtime/models/shell_command_runner.go b/server/core/runtime/models/shell_command_runner.go
index c30f97378d..3dcd56dd8a 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/terraform/terraform_client.go b/server/core/terraform/terraform_client.go
index 7da9781ebc..2f57d08cdb 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
 }


Test patch:
diff --git a/server/core/runtime/models/shell_command_runner_test.go b/server/core/runtime/models/shell_command_runner_test.go
index 2bb5f0a28b..9683ac88fc 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_internal_test.go b/server/core/terraform/terraform_client_internal_test.go
index dc9f0b9956..d497d74e77 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) {