feat: Refine the Atlantis Info Message Logging #5034

X-Guardian · 2024-10-23T22:09:01Z

what

Refine the Info logging messages that Atlantis produces in the following areas:

Add repo and pull annotations on all VCS logs.
Replace double quotes in log string with single quotes to avoid JSON escaping.
Remove superfluous repo and pull details in log messages where it is annotated.
Enhance command runner autoplan logging.
Enhance pre/post workflow hook start, end and error logging.
Change VCS check status debug messages to info messages
Fix 'Supported VCS Hosts' log entry
Change web server 'apply lock' entry from info to debug.

why

Improve the logging to help resolve future issues.

tests

Tested locally

Sample Logs

Current

{"level":"info","ts":"2024-11-08T17:32:07.197Z","caller":"vcs/gitlab_client.go:111","msg":"determined GitLab is running version 17.5.0","json":{}}
{"level":"info","ts":"2024-11-08T17:32:07.199Z","caller":"server/server.go:320","msg":"Supported VCS Hosts%!(EXTRA string=hosts, []models.VCSHostType=[Gitlab])","json":{}}
{"level":"info","ts":"2024-11-08T17:32:07.523Z","caller":"server/server.go:473","msg":"Utilizing BoltDB","json":{}}
{"level":"info","ts":"2024-11-08T17:32:07.538Z","caller":"policy/conftest_client.go:167","msg":"failed to get default conftest version. Will attempt request scoped lazy loads DEFAULT_CONFTEST_VERSION not set","json":{}}
{"level":"info","ts":"2024-11-08T17:32:07.538Z","caller":"server/server.go:1043","msg":"Atlantis started - listening on port 4141","json":{}}
{"level":"info","ts":"2024-11-08T17:32:07.539Z","caller":"scheduled/executor_service.go:51","msg":"Scheduled Executor Service started","json":{}}
{"level":"info","ts":"2024-11-08T17:32:26.208Z","caller":"events/events_controller.go:656","msg":"parsed comment as command=\"plan\", verbose=false, dir=\"\", workspace=\"\", project=\"\", policyset=\"\", auto-merge-disabled=false, auto-merge-method=, clear-policy-approval=false, flags=\"\"","json":{"repo":"sheather/test","pull":31}}
{"level":"info","ts":"2024-11-08T17:32:27.269Z","caller":"events/events_controller.go:699","msg":"Running comment command 'plan' on repo 'sheather/test', pull request: 31 for user 'sheather'.","json":{"repo":"sheather/test","pull":31}}
{"level":"info","ts":"2024-11-08T17:32:30.745Z","caller":"runtime/pre_workflow_hook_runner.go:80","msg":"successfully ran \"bash -ce echo \\\"Terraform Version: $ATLANTIS_TERRAFORM_VERSION\\\"\\n\" in \"/root/.atlantis/repos/sheather/test/31/default\"","json":{"repo":"sheather/test","pull":"31"}}
{"level":"warn","ts":"2024-11-08T17:32:33.186Z","caller":"events/plan_command_runner.go:192","msg":"unable to update commit status: POST https://gitlab.lan/api/v4/projects/sheather/test/statuses/a1e2908f540bd9e0b9beb57ace6ebbdecf57bc9b: 400 {message: Cannot transition status via :run from :running (Reason(s): Status cannot transition via \"run\")}","json":{"repo":"sheather/test","pull":"31"},"stacktrace":"github.com/runatlantis/atlantis/server/events.(*PlanCommandRunner).run\n\t/mnt/c/Users/Simon/Documents/GitHub/X-Guardian/atlantis/server/events/plan_command_runner.go:192\ngithub.com/runatlantis/atlantis/server/events.(*PlanCommandRunner).Run\n\t/mnt/c/Users/Simon/Documents/GitHub/X-Guardian/atlantis/server/events/plan_command_runner.go:307\ngithub.com/runatlantis/atlantis/server/events.(*DefaultCommandRunner).RunCommentCommand\n\t/mnt/c/Users/Simon/Documents/GitHub/X-Guardian/atlantis/server/events/command_runner.go:389"}
{"level":"info","ts":"2024-11-08T17:32:33.532Z","caller":"events/project_command_builder.go:496","msg":"found no atlantis.yaml file","json":{"repo":"sheather/test","pull":"31"}}
{"level":"info","ts":"2024-11-08T17:32:33.532Z","caller":"events/project_finder.go:147","msg":"filtered modified files to 1 file(s) in the autoplan file list: [live/aws/123456789012/develop/eu-west-2/stack11/main.tf]","json":{"repo":"sheather/test","pull":"31"}}
{"level":"info","ts":"2024-11-08T17:32:33.533Z","caller":"events/project_finder.go:176","msg":"there are 1 modified project(s) at path(s): live/aws/123456789012/develop/eu-west-2/stack11","json":{"repo":"sheather/test","pull":"31"}}
{"level":"info","ts":"2024-11-08T17:32:33.533Z","caller":"events/project_command_builder.go:518","msg":"automatically determined that there were 1 additional projects modified in this pull request: [repofullname=sheather/test path=live/aws/123456789012/develop/eu-west-2/stack11]","json":{"repo":"sheather/test","pull":"31"}}
{"level":"info","ts":"2024-11-08T17:32:33.533Z","caller":"events/project_finder.go:79","msg":"looking for Terraform Cloud workspace from configuration in \"/root/.atlantis/repos/sheather/test/31/default/live/aws/123456789012/develop/eu-west-2/stack11\"","json":{"repo":"sheather/test","pull":"31"}}
{"level":"info","ts":"2024-11-08T17:32:35.571Z","caller":"events/project_locker.go:86","msg":"acquired lock with id \"sheather/test/live/aws/123456789012/develop/eu-west-2/stack11/default\"","json":{"repo":"sheather/test","pull":"31"}}
{"level":"info","ts":"2024-11-08T17:32:42.478Z","caller":"models/shell_command_runner.go:181","msg":"successfully ran 'sh -c \"/root/.atlantis/bin/terraform1.9.8 init -input=false -upgrade\"' in '/root/.atlantis/repos/sheather/test/31/default/live/aws/123456789012/develop/eu-west-2/stack11'","json":{"repo":"sheather/test","pull":"31","duration":6.8940395}}
{"level":"info","ts":"2024-11-08T17:32:42.518Z","caller":"terraform/terraform_client.go:383","msg":"successfully ran \"/root/.atlantis/bin/terraform1.9.8 workspace show\" in \"/root/.atlantis/repos/sheather/test/31/default/live/aws/123456789012/develop/eu-west-2/stack11\"","json":{"repo":"sheather/test","pull":"31","duration":0.0394347}}
{"level":"info","ts":"2024-11-08T17:32:42.710Z","caller":"models/shell_command_runner.go:181","msg":"successfully ran 'sh -c \"/root/.atlantis/bin/terraform1.9.8 plan -input=false -refresh -out \\\"/root/.atlantis/repos/sheather/test/31/default/live/aws/123456789012/develop/eu-west-2/stack11/default.tfplan\\\"\"' in '/root/.atlantis/repos/sheather/test/31/default/live/aws/123456789012/develop/eu-west-2/stack11'","json":{"repo":"sheather/test","pull":"31","duration":0.1923274}}
{"level":"info","ts":"2024-11-08T17:32:43.259Z","caller":"events/instrumented_project_command_runner.go:88","msg":"plan success. output available at: https://gitlab.lan/sheather/test/-/merge_requests/31","json":{"repo":"sheather/test","pull":"31"}}
{"level":"info","ts":"2024-11-08T17:32:46.932Z","caller":"events/plan_command_runner.go:290","msg":"Running policy check for command=\"plan\", verbose=false, dir=\"\", workspace=\"\", project=\"\", policyset=\"\", auto-merge-disabled=false, auto-merge-method=, clear-policy-approval=false, flags=\"\"","json":{"repo":"sheather/test","pull":"31"}}
{"level":"info","ts":"2024-11-08T17:32:46.932Z","caller":"events/policy_check_command_runner.go:42","msg":"no projects to run policy_check in","json":{"repo":"sheather/test","pull":"31"}}
{"level":"info","ts":"2024-11-08T17:32:51.489Z","caller":"runtime/post_workflow_hook_runner.go:80","msg":"successfully ran \"bash -ce echo \\\"Terraform Version: $ATLANTIS_TERRAFORM_VERSION\\\"\\n\" in \"/root/.atlantis/repos/sheather/test/31/default\"","json":{"repo":"sheather/test","pull":"31"}}

New

{"level":"info","ts":"2024-11-08T17:02:27.858Z","caller":"vcs/gitlab_client.go:111","msg":"GitLab host 'gitlab.lan' is running version 17.5.0","json":{}}
{"level":"info","ts":"2024-11-08T17:02:27.859Z","caller":"server/server.go:325","msg":"Supported VCS Hosts: Gitlab","json":{}}
{"level":"info","ts":"2024-11-08T17:02:28.176Z","caller":"server/server.go:478","msg":"Utilizing BoltDB","json":{}}
{"level":"info","ts":"2024-11-08T17:02:28.192Z","caller":"policy/conftest_client.go:167","msg":"failed to get default conftest version. Will attempt request scoped lazy loads DEFAULT_CONFTEST_VERSION not set","json":{}}
{"level":"info","ts":"2024-11-08T17:02:28.193Z","caller":"server/server.go:1048","msg":"Atlantis started - listening on port 4141","json":{}}
{"level":"info","ts":"2024-11-08T17:02:28.193Z","caller":"scheduled/executor_service.go:51","msg":"Scheduled Executor Service started","json":{}}
{"level":"info","ts":"2024-11-08T17:02:41.173Z","caller":"events/events_controller.go:684","msg":"Handling 'plan' comment","json":{"repo":"sheather/test","pull":31}}
{"level":"info","ts":"2024-11-08T17:02:41.747Z","caller":"events/events_controller.go:728","msg":"Running comment command 'plan' for user 'sheather'.","json":{"repo":"sheather/test","pull":31}}
{"level":"info","ts":"2024-11-08T17:02:42.676Z","caller":"events/pre_workflow_hooks_command_runner.go:53","msg":"Pre-workflow hooks configured, running...","json":{"repo":"sheather/test","pull":"31"}}
{"level":"info","ts":"2024-11-08T17:02:42.683Z","caller":"vcs/gitlab_client.go:408","msg":"Updating GitLab commit status for 'atlantis/plan' to 'running'","json":{"repo":"sheather/test","pull":"31"}}
{"level":"info","ts":"2024-11-08T17:02:43.846Z","caller":"vcs/gitlab_client.go:408","msg":"Updating GitLab commit status for 'atlantis/pre_workflow_hook: Atlantis Setup' to 'running'","json":{"repo":"sheather/test","pull":"31"}}
{"level":"info","ts":"2024-11-08T17:02:45.322Z","caller":"runtime/pre_workflow_hook_runner.go:80","msg":"Successfully ran 'bash -ce echo \"Terraform Version: $ATLANTIS_TERRAFORM_VERSION\"\n' in '/root/.atlantis/repos/sheather/test/31/default'","json":{"repo":"sheather/test","pull":"31"}}
{"level":"info","ts":"2024-11-08T17:02:45.323Z","caller":"vcs/gitlab_client.go:408","msg":"Updating GitLab commit status for 'atlantis/pre_workflow_hook: Atlantis Setup' to 'success'","json":{"repo":"sheather/test","pull":"31"}}
{"level":"info","ts":"2024-11-08T17:02:46.822Z","caller":"events/pre_workflow_hooks_command_runner.go:103","msg":"Pre-workflow hooks completed successfully","json":{"repo":"sheather/test","pull":"31"}}
{"level":"info","ts":"2024-11-08T17:02:47.641Z","caller":"vcs/gitlab_client.go:408","msg":"Updating GitLab commit status for 'atlantis/plan' to 'running'","json":{"repo":"sheather/test","pull":"31"}}
{"level":"warn","ts":"2024-11-08T17:02:48.041Z","caller":"events/plan_command_runner.go:192","msg":"unable to update commit status: POST https://gitlab.lan/api/v4/projects/sheather/test/statuses/a1e2908f540bd9e0b9beb57ace6ebbdecf57bc9b: 400 {message: Cannot transition status via :run from :running (Reason(s): Status cannot transition via \"run\")}","json":{"repo":"sheather/test","pull":"31"},"stacktrace":"github.com/runatlantis/atlantis/server/events.(*PlanCommandRunner).run\n\t/mnt/c/Users/Simon/Documents/GitHub/X-Guardian/atlantis/server/events/plan_command_runner.go:192\ngithub.com/runatlantis/atlantis/server/events.(*PlanCommandRunner).Run\n\t/mnt/c/Users/Simon/Documents/GitHub/X-Guardian/atlantis/server/events/plan_command_runner.go:307\ngithub.com/runatlantis/atlantis/server/events.(*DefaultCommandRunner).RunCommentCommand\n\t/mnt/c/Users/Simon/Documents/GitHub/X-Guardian/atlantis/server/events/command_runner.go:383"}
{"level":"info","ts":"2024-11-08T17:02:48.363Z","caller":"events/project_command_builder.go:496","msg":"found no atlantis.yaml file","json":{"repo":"sheather/test","pull":"31"}}
{"level":"info","ts":"2024-11-08T17:02:48.364Z","caller":"events/project_finder.go:147","msg":"filtered modified files to 1 file(s) in the autoplan file list: [live/aws/123456789012/develop/eu-west-2/stack11/main.tf]","json":{"repo":"sheather/test","pull":"31"}}
{"level":"info","ts":"2024-11-08T17:02:48.364Z","caller":"events/project_finder.go:176","msg":"there are 1 modified project(s) at path(s): live/aws/123456789012/develop/eu-west-2/stack11","json":{"repo":"sheather/test","pull":"31"}}
{"level":"info","ts":"2024-11-08T17:02:48.364Z","caller":"events/project_command_builder.go:518","msg":"automatically determined that there were 1 additional projects modified in this pull request: [repofullname=sheather/test path=live/aws/123456789012/develop/eu-west-2/stack11]","json":{"repo":"sheather/test","pull":"31"}}
{"level":"info","ts":"2024-11-08T17:02:48.364Z","caller":"events/project_finder.go:79","msg":"Looking for Terraform Cloud workspace from configuration in '/root/.atlantis/repos/sheather/test/31/default/live/aws/123456789012/develop/eu-west-2/stack11'","json":{"repo":"sheather/test","pull":"31"}}
{"level":"info","ts":"2024-11-08T17:02:49.517Z","caller":"vcs/gitlab_client.go:408","msg":"Updating GitLab commit status for 'atlantis/plan: live/aws/123456789012/develop/eu-west-2/stack11/default' to 'running'","json":{"repo":"sheather/test","pull":"31"}}
{"level":"info","ts":"2024-11-08T17:02:49.982Z","caller":"events/project_locker.go:86","msg":"Acquired lock with id 'sheather/test/live/aws/123456789012/develop/eu-west-2/stack11/default'","json":{"repo":"sheather/test","pull":"31"}}
{"level":"info","ts":"2024-11-08T17:02:57.738Z","caller":"models/shell_command_runner.go:181","msg":"successfully ran 'sh -c /root/.atlantis/bin/terraform1.9.8 init -input=false -upgrade' in '/root/.atlantis/repos/sheather/test/31/default/live/aws/123456789012/develop/eu-west-2/stack11'","json":{"repo":"sheather/test","pull":"31","duration":7.7429596}}
{"level":"info","ts":"2024-11-08T17:02:57.782Z","caller":"terraform/terraform_client.go:383","msg":"Successfully ran '/root/.atlantis/bin/terraform1.9.8 workspace show' in '/root/.atlantis/repos/sheather/test/31/default/live/aws/123456789012/develop/eu-west-2/stack11'","json":{"repo":"sheather/test","pull":"31","duration":0.0430819}}
{"level":"info","ts":"2024-11-08T17:02:57.965Z","caller":"models/shell_command_runner.go:181","msg":"successfully ran 'sh -c /root/.atlantis/bin/terraform1.9.8 plan -input=false -refresh -out \"/root/.atlantis/repos/sheather/test/31/default/live/aws/123456789012/develop/eu-west-2/stack11/default.tfplan\"' in '/root/.atlantis/repos/sheather/test/31/default/live/aws/123456789012/develop/eu-west-2/stack11'","json":{"repo":"sheather/test","pull":"31","duration":0.1825007}}
{"level":"info","ts":"2024-11-08T17:02:57.965Z","caller":"vcs/gitlab_client.go:408","msg":"Updating GitLab commit status for 'atlantis/plan: live/aws/123456789012/develop/eu-west-2/stack11/default' to 'success'","json":{"repo":"sheather/test","pull":"31"}}
{"level":"info","ts":"2024-11-08T17:02:58.546Z","caller":"events/instrumented_project_command_runner.go:88","msg":"plan success. output available at: https://gitlab.lan/sheather/test/-/merge_requests/31","json":{"repo":"sheather/test","pull":"31"}}
{"level":"info","ts":"2024-11-08T17:03:01.504Z","caller":"vcs/gitlab_client.go:408","msg":"Updating GitLab commit status for 'atlantis/plan' to 'success'","json":{"repo":"sheather/test","pull":"31"}}
{"level":"info","ts":"2024-11-08T17:03:02.623Z","caller":"events/plan_command_runner.go:290","msg":"Running policy check for 'plan'","json":{"repo":"sheather/test","pull":"31"}}
{"level":"info","ts":"2024-11-08T17:03:02.623Z","caller":"events/policy_check_command_runner.go:42","msg":"no projects to run policy_check in","json":{"repo":"sheather/test","pull":"31"}}
{"level":"info","ts":"2024-11-08T17:03:02.623Z","caller":"vcs/gitlab_client.go:408","msg":"Updating GitLab commit status for 'atlantis/policy_check' to 'success'","json":{"repo":"sheather/test","pull":"31"}}
{"level":"info","ts":"2024-11-08T17:03:04.420Z","caller":"events/post_workflow_hooks_command_runner.go:53","msg":"Post-workflow hooks configured, running...","json":{"repo":"sheather/test","pull":"31"}}
{"level":"info","ts":"2024-11-08T17:03:04.434Z","caller":"vcs/gitlab_client.go:408","msg":"Updating GitLab commit status for 'atlantis/post_workflow_hook: Atlantis Cleanup' to 'running'","json":{"repo":"sheather/test","pull":"31"}}
{"level":"info","ts":"2024-11-08T17:03:06.549Z","caller":"runtime/post_workflow_hook_runner.go:80","msg":"Successfully ran 'bash -ce echo \"Terraform Version: $ATLANTIS_TERRAFORM_VERSION\"\n' in '/root/.atlantis/repos/sheather/test/31/default'","json":{"repo":"sheather/test","pull":"31"}}
{"level":"info","ts":"2024-11-08T17:03:06.549Z","caller":"vcs/gitlab_client.go:408","msg":"Updating GitLab commit status for 'atlantis/post_workflow_hook: Atlantis Cleanup' to 'success'","json":{"repo":"sheather/test","pull":"31"}}
{"level":"info","ts":"2024-11-08T17:03:07.997Z","caller":"events/post_workflow_hooks_command_runner.go:151","msg":"Post-workflow hooks completed","json":{"repo":"sheather/test","pull":"31"}}

Signed-off-by: X-Guardian <[email protected]>

Signed-off-by: Simon Heather <[email protected]>

lukemassa · 2024-11-08T04:05:18Z

server/controllers/api_controller.go

-		if err != nil {
-			ctx.Log.Err("Error running post-workflow hooks %s.", err)
-		}
+		a.PostWorkflowHooksCommandRunner.RunPostHooks(ctx, cc[i]) // nolint: errcheck


Not sure why I follow why these logs are being removed?

They have been moved into events/post_workflow_hooks_command_runner.go rather than being duplicated here.

Ah I see. Always a bit apprehensive when an err is being swallowed though; if we expect the body of RunPostHooks to "handle" the error (i.e. logging it), and we've now change all the call sites of this function to ignore the error, maybe it shouldn't return an error at all?

The tests use the return error, so we should leave it there.

lukemassa · 2024-11-08T04:10:08Z

server/core/terraform/terraform_client_internal_test.go

@@ -344,7 +344,7 @@ func TestDefaultClient_RunCommandAsync_ExitOne(t *testing.T) {
 	_, outCh := client.RunCommandAsync(ctx, tmp, []string{"dying", "&&", "exit", "1"}, map[string]string{}, nil, "workspace")

 	out, err := waitCh(outCh)
-	ErrEquals(t, fmt.Sprintf(`running 'sh -c "echo dying && exit 1"' in '%s': exit status 1`, tmp), err)
+	ErrEquals(t, fmt.Sprintf(`running 'sh -c echo dying && exit 1' in '%s': exit status 1`, tmp), err)


Removing the quotes here makes this harder to read. sh -c echo dying && exit 1 means a different thing than sh -c "echo dying && exit 1"

In the JSON logs, the msg property currently looks like this:

"msg":"successfully ran 'sh -c \"/root/.atlantis/bin/terraform1.9.8 init -input=false -upgrade\"' in '/root/.atlantis/repos/sheather/test/31/default/live/aws/stack11'"

which with the escaped double quotes is very confusing to read, so I removed them to give this:

"msg":"successfully ran 'sh -c /root/.atlantis/bin/terraform1.9.8 init -input=false -upgrade' in '/root/.atlantis/repos/sheather/test/31/default/live/aws/stack11'"

I can replace it with single quotes, or backticks instead:

Single Quotes

"msg":"successfully ran 'sh -c '/root/.atlantis/bin/terraform1.9.8 init -input=false -upgrade'' in '/root/.atlantis/repos/sheather/test/31/default/live/aws/stack11'"

backticks

"msg":"successfully ran 'sh -c `/root/.atlantis/bin/terraform1.9.8 init -input=false -upgrade`' in '/root/.atlantis/repos/sheather/test/31/default/live/aws/stack11'"

Thoughts?

Ah yeah, that's tough.

My personal view is that if you're logging to JSON you can expect \"s, and that it's still useful to be able to recover what command was actually ran.

But I could definitely see it going either way, and am fine with any of the above solutions

I've added single quotes.

Signed-off-by: X-Guardian <[email protected]>

Refine Logging

3ee7537

Signed-off-by: X-Guardian <[email protected]>

X-Guardian requested review from a team as code owners October 23, 2024 22:09

X-Guardian requested review from chenrui333, lukemassa and nitrocode and removed request for a team October 23, 2024 22:09

github-actions bot added provider/azuredevops go Pull requests that update Go code provider/bitbucket provider/github provider/gitlab labels Oct 23, 2024

dosubot bot added the feature New functionality/enhancement label Oct 23, 2024

X-Guardian and others added 9 commits October 24, 2024 21:28

Fix command name

5af375c

Signed-off-by: X-Guardian <[email protected]>

Fix linting issues

910a72d

Signed-off-by: X-Guardian <[email protected]>

Fix formatting

6b0f3c6

Signed-off-by: X-Guardian <[email protected]>

Updates

fd03bf0

Signed-off-by: X-Guardian <[email protected]>

Update handling comment

1e862f2

Signed-off-by: X-Guardian <[email protected]>

Merge branch 'main' into logging-refinement

a2bbe30

Merge branch 'main' into logging-refinement

3b34dc3

Merge branch 'main' into logging-refinement

12e6b23

Signed-off-by: Simon Heather <[email protected]>

Merge branch 'main' into logging-refinement

93d9d86

lukemassa reviewed Nov 8, 2024

View reviewed changes

jamengual and others added 2 commits November 8, 2024 10:42

Merge branch 'main' into logging-refinement

b674357

Refine quotes

f856703

Signed-off-by: X-Guardian <[email protected]>

X-Guardian requested a review from lukemassa November 11, 2024 21:37

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

feat: Refine the Atlantis Info Message Logging #5034

feat: Refine the Atlantis Info Message Logging #5034

X-Guardian commented Oct 23, 2024 •

edited

Loading

lukemassa Nov 8, 2024

X-Guardian Nov 8, 2024

lukemassa Nov 11, 2024

X-Guardian Nov 11, 2024

lukemassa Nov 8, 2024

X-Guardian Nov 8, 2024

lukemassa Nov 11, 2024

X-Guardian Nov 11, 2024

feat: Refine the Atlantis Info Message Logging #5034

Are you sure you want to change the base?

feat: Refine the Atlantis Info Message Logging #5034

Conversation

X-Guardian commented Oct 23, 2024 • edited Loading

what

why

tests

Sample Logs

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

X-Guardian commented Oct 23, 2024 •

edited

Loading