feat: Add Terraform command duration to log messages

[inkel]

what

This PR adds the wall clock duration of executing any Terraform command to the logs.

why

This information is useful for observability purposes.

tests

Tested the changes running Atlantis locally. Because it relies on time.Now adding tests that are not flaky is difficult.

references

• closes Add plan and apply durations to atlantis log messages #3413.

[nitrocode]

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.

[nitrocode]

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

[inkel]

Hey @nitrocode thanks for the review. I definitely agree with that it would be nice to have unit tests for this, although I'm failing to come up with "simple" ones. There are a couple things that are getting in the way:

1. usage of time.Now; this is a known issue when trying to test things that rely on time differences. One thing that sometimes work is defining a top level var now func() time.Time = time.Now that then can be overloaded at test time just to make it return specific times and thus make any computations, however, this also uses time.Since which relies on the stdlib time.Now function, which cannot be overloaded. I suppose one option would be to not use time.Since and simply use Time.Sub, however, in that case we would be losing the checks time.Since has implemented internally.
2. the logging infrastructure (logging.SimpleLogging) lacks an easy way to indicate where the logs should be written to. There is SimpleLogging.GetHistory, however, that is marked for removal in a TODO comment. Even if that won't be the case, the only possible check would be to try and match over the whole logs history and not particular entries. And also the returned history is only for the passed down log messages, not any contextual values.
3. related to the one above, there is a MockSimpleLogging which should help with checking that certain calls and their arguments are being invoked, however, in that case we would end up testing implementation and not functionality. And even in this case we go back to the first point in where we can test that we are calling SimpleLogging.With with a "duration" key but then we cannot really test that the time.Duration passed is right.

I'll continue to investigate what it's possible to do, tho, because I believe having tests is really useful.

[inkel]

Hey @nitrocode I've added a test in shell_command_runner_test.go, let me know what you think and I can port it to the other file!

[nitrocode]

Nice job @inkel . Yes, please add a test for the terraform client too. These tests will help preserve the feature you're adding.

[inkel]

@nitrocode done!

[nitrocode]

Thank you!

[ndavies-om1]

this does exactly what I want! Thank you!!