feat: Refine the Atlantis Info Message Logging

server/controllers/api_controller.go

@@ -154,7 +154,6 @@ func (a *APIController) apiPlan(request *APIRequest, ctx *command.Context) (*com
 	for i, cmd := range cmds {
 		err = a.PreWorkflowHooksCommandRunner.RunPreHooks(ctx, cc[i])
 		if err != nil {
-			ctx.Log.Err("Error running pre-workflow hooks %s.", err)
 			if a.FailOnPreWorkflowHookError {
 				return nil, err
 			}
@@ -163,10 +162,7 @@ func (a *APIController) apiPlan(request *APIRequest, ctx *command.Context) (*com
 		res := a.ProjectPlanCommandRunner.Plan(cmd)
 		projectResults = append(projectResults, res)
 
-		err = a.PostWorkflowHooksCommandRunner.RunPostHooks(ctx, cc[i])
-		if err != nil {
-			ctx.Log.Err("Error running post-workflow hooks %s.", err)
-		}
+		a.PostWorkflowHooksCommandRunner.RunPostHooks(ctx, cc[i]) // nolint: errcheck
 	}
 	return &command.Result{ProjectResults: projectResults}, nil
 }
@@ -181,7 +177,6 @@ func (a *APIController) apiApply(request *APIRequest, ctx *command.Context) (*co
 	for i, cmd := range cmds {
 		err = a.PreWorkflowHooksCommandRunner.RunPreHooks(ctx, cc[i])
 		if err != nil {
-			ctx.Log.Err("Error running pre-workflow hooks %s.", err)
 			if a.FailOnPreWorkflowHookError {
 				return nil, err
 			}
@@ -190,10 +185,7 @@ func (a *APIController) apiApply(request *APIRequest, ctx *command.Context) (*co
 		res := a.ProjectApplyCommandRunner.Apply(cmd)
 		projectResults = append(projectResults, res)
 
-		err = a.PostWorkflowHooksCommandRunner.RunPostHooks(ctx, cc[i])
-		if err != nil {
-			ctx.Log.Err("Error running post-workflow hooks %s.", err)
-		}
+		a.PostWorkflowHooksCommandRunner.RunPostHooks(ctx, cc[i]) // nolint: errcheck
 	}
 	return &command.Result{ProjectResults: projectResults}, nil
 }

server/controllers/events/events_controller.go

@@ -19,6 +19,7 @@ import (
 	"html"
 	"io"
 	"net/http"
+	"strconv"
 	"strings"
 
 	"github.com/google/go-github/v66/github"
@@ -231,7 +232,7 @@ func (e *VCSEventsController) handleBitbucketCloudPost(w http.ResponseWriter, r
 	switch eventType {
 	case bitbucketcloud.PullCreatedHeader, bitbucketcloud.PullUpdatedHeader, bitbucketcloud.PullFulfilledHeader, bitbucketcloud.PullRejectedHeader:
 		e.Logger.Debug("handling as pull request state changed event")
-		e.handleBitbucketCloudPullRequestEvent(w, eventType, body, reqID)
+		e.handleBitbucketCloudPullRequestEvent(e.Logger, w, eventType, body, reqID)
 		return
 	case bitbucketcloud.PullCommentCreatedHeader:
 		e.Logger.Debug("handling as comment created event")
@@ -267,7 +268,7 @@ func (e *VCSEventsController) handleBitbucketServerPost(w http.ResponseWriter, r
 	switch eventType {
 	case bitbucketserver.PullCreatedHeader, bitbucketserver.PullFromRefUpdatedHeader, bitbucketserver.PullMergedHeader, bitbucketserver.PullDeclinedHeader, bitbucketserver.PullDeletedHeader:
 		e.Logger.Debug("handling as pull request state changed event")
-		e.handleBitbucketServerPullRequestEvent(w, eventType, body, reqID)
+		e.handleBitbucketServerPullRequestEvent(e.Logger, w, eventType, body, reqID)
 		return
 	case bitbucketserver.PullCommentCreatedHeader:
 		e.Logger.Debug("handling as comment created event")
@@ -325,33 +326,35 @@ func (e *VCSEventsController) handleGiteaPost(w http.ResponseWriter, r *http.Req
 		}
 	}
 
+	logger := e.Logger.With("gitea-request-id", reqID)
+
 	// Log the event type for debugging purposes
-	e.Logger.Debug("Received Gitea event %s with ID %s", eventType, reqID)
+	logger.Debug("Received Gitea event %s with ID %s", eventType, reqID)
 
 	// Depending on the event type, handle the event appropriately
 	switch eventType {
 	case "pull_request_comment":
 		e.HandleGiteaPullRequestCommentEvent(w, body, reqID)
 	case "pull_request":
-		e.Logger.Debug("Handling as pull_request")
-		e.handleGiteaPullRequestEvent(w, body, reqID)
+		logger.Debug("Handling as pull_request")
+		e.handleGiteaPullRequestEvent(logger, w, body, reqID)
 	// Add other case handlers as necessary
 	default:
 		e.respond(w, logging.Debug, http.StatusOK, "Ignoring unsupported Gitea event type: %s %s=%s", eventType, "X-Gitea-Delivery", reqID)
 	}
 }
 
-func (e *VCSEventsController) handleGiteaPullRequestEvent(w http.ResponseWriter, body []byte, reqID string) {
-	e.Logger.Debug("Entering handleGiteaPullRequestEvent")
+func (e *VCSEventsController) handleGiteaPullRequestEvent(logger logging.SimpleLogging, w http.ResponseWriter, body []byte, reqID string) {
+	logger.Debug("Entering handleGiteaPullRequestEvent")
 	// Attempt to unmarshal the incoming body into the Gitea PullRequest struct
 	var payload gitea.GiteaWebhookPayload
 	if err := json.Unmarshal(body, &payload); err != nil {
 		e.Logger.Err("Failed to unmarshal Gitea webhook payload: %v", err)
-		e.respond(w, logging.Error, http.StatusBadRequest, "Failed to parse request body")
+		e.respond(w, logging.Error, http.StatusBadRequest, "Failed to parse request body: %s %s=%s", err, giteaRequestIDHeader, reqID)
 		return
 	}
 
-	e.Logger.Debug("Successfully unmarshaled Gitea event")
+	logger.Debug("Successfully unmarshaled Gitea event")
 
 	// Use the parser function to convert into Atlantis models
 	pull, pullEventType, baseRepo, headRepo, user, err := e.Parser.ParseGiteaPullRequestEvent(payload.PullRequest)
@@ -361,12 +364,14 @@ func (e *VCSEventsController) handleGiteaPullRequestEvent(w http.ResponseWriter,
 		return
 	}
 
-	e.Logger.Debug("Parsed Gitea event into Atlantis models successfully")
+	logger.Debug("Parsed Gitea event into Atlantis models successfully")
 
-	logger := e.Logger.With("gitea-request-id", reqID)
-	logger.Debug("Identified Gitea event as type", "type", pullEventType)
-
-	// Call a generic handler for pull request events
+	// Annotate logger with repo and pull/merge request number.
+	logger = logger.With(
+		"repo", baseRepo.FullName,
+		"pull", strconv.Itoa(pull.Num),
+	)
+	logger.Info("Handling Gitea Pull Request '%s' event", pullEventType.String())
 	response := e.handlePullRequestEvent(logger, baseRepo, headRepo, pull, user, pullEventType)
 
 	e.respond(w, logging.Debug, http.StatusOK, "%s", response.body)
@@ -462,15 +467,22 @@ func (e *VCSEventsController) HandleBitbucketServerCommentEvent(w http.ResponseW
 	e.respond(w, lvl, code, "%s", msg)
 }
 
-func (e *VCSEventsController) handleBitbucketCloudPullRequestEvent(w http.ResponseWriter, eventType string, body []byte, reqID string) {
+func (e *VCSEventsController) handleBitbucketCloudPullRequestEvent(logger logging.SimpleLogging, w http.ResponseWriter, eventType string, body []byte, reqID string) {
 	pull, baseRepo, headRepo, user, err := e.Parser.ParseBitbucketCloudPullEvent(body)
 	if err != nil {
 		e.respond(w, logging.Error, http.StatusBadRequest, "Error parsing pull data: %s %s=%s", err, bitbucketCloudRequestIDHeader, reqID)
 		return
 	}
 	e.Logger.Debug("SHA is %q", pull.HeadCommit)
 	pullEventType := e.Parser.GetBitbucketCloudPullEventType(eventType, pull.HeadCommit, pull.URL)
-	e.Logger.Info("identified event as type %q", pullEventType.String())
+
+	// Annotate logger with repo and pull/merge request number.
+	logger = logger.With(
+		"repo", baseRepo.FullName,
+		"pull", strconv.Itoa(pull.Num),
+	)
+
+	logger.Info("Handling Bitbucket Cloud Pull Request '%s' event", pullEventType.String())
 	resp := e.handlePullRequestEvent(e.Logger, baseRepo, headRepo, pull, user, pullEventType)
 
 	//TODO: move this to the outer most function similar to github
@@ -485,14 +497,21 @@ func (e *VCSEventsController) handleBitbucketCloudPullRequestEvent(w http.Respon
 	e.respond(w, lvl, code, "%s", msg)
 }
 
-func (e *VCSEventsController) handleBitbucketServerPullRequestEvent(w http.ResponseWriter, eventType string, body []byte, reqID string) {
+func (e *VCSEventsController) handleBitbucketServerPullRequestEvent(logger logging.SimpleLogging, w http.ResponseWriter, eventType string, body []byte, reqID string) {
 	pull, baseRepo, headRepo, user, err := e.Parser.ParseBitbucketServerPullEvent(body)
 	if err != nil {
 		e.respond(w, logging.Error, http.StatusBadRequest, "Error parsing pull data: %s %s=%s", err, bitbucketServerRequestIDHeader, reqID)
 		return
 	}
 	pullEventType := e.Parser.GetBitbucketServerPullEventType(eventType)
-	e.Logger.Info("identified event as type %q", pullEventType.String())
+
+	// Annotate logger with repo and pull/merge request number.
+	logger = logger.With(
+		"repo", baseRepo.FullName,
+		"pull", strconv.Itoa(pull.Num),
+	)
+
+	logger.Info("Handling Bitbucket Server Pull Request '%s' event", pullEventType.String())
 	resp := e.handlePullRequestEvent(e.Logger, baseRepo, headRepo, pull, user, pullEventType)
 
 	//TODO: move this to the outer most function similar to github
@@ -523,7 +542,14 @@ func (e *VCSEventsController) HandleGithubPullRequestEvent(logger logging.Simple
 			},
 		}
 	}
-	logger.Debug("identified event as type %q", pullEventType.String())
+
+	// Annotate logger with repo and pull/merge request number.
+	logger = logger.With(
+		"repo", baseRepo.FullName,
+		"pull", strconv.Itoa(pull.Num),
+	)
+
+	logger.Info("Handling GitHub Pull Request '%s' event", pullEventType.String())
 	return e.handlePullRequestEvent(logger, baseRepo, headRepo, pull, user, pullEventType)
 }
 
@@ -537,7 +563,7 @@ func (e *VCSEventsController) handlePullRequestEvent(logger logging.SimpleLoggin
 			e.commentNotAllowlisted(baseRepo, pull.Num)
 		}
 
-		err := errors.Errorf("Pull request event from non-allowlisted repo \"%s/%s\"", baseRepo.VCSHost.Hostname, baseRepo.FullName)
+		err := errors.Errorf("Pull request event from non-allowlisted repo '%s/%s'", baseRepo.VCSHost.Hostname, baseRepo.FullName)
 
 		return HTTPResponse{
 			body: err.Error(),
@@ -567,6 +593,7 @@ func (e *VCSEventsController) handlePullRequestEvent(logger logging.SimpleLoggin
 		}
 	case models.ClosedPullEvent:
 		// If the pull request was closed, we delete locks.
+		logger.Info("Pull request closed, cleaning up...")
 		if err := e.PullCleaner.CleanUpPull(logger, baseRepo, pull); err != nil {
 			return HTTPResponse{
 				body: err.Error(),
@@ -577,7 +604,7 @@ func (e *VCSEventsController) handlePullRequestEvent(logger logging.SimpleLoggin
 				},
 			}
 		}
-		logger.Info("deleted locks and workspace for repo %s, pull %d", baseRepo.FullName, pull.Num)
+		logger.Info("Locks and workspace successfully deleted")
 		return HTTPResponse{
 			body: "Pull request cleaned successfully",
 		}
@@ -603,8 +630,7 @@ func (e *VCSEventsController) handleGitlabPost(w http.ResponseWriter, r *http.Re
 		e.Logger.Debug("handling as comment event")
 		e.HandleGitlabCommentEvent(w, event)
 	case gitlab.MergeEvent:
-		e.Logger.Debug("handling as pull request event")
-		e.HandleGitlabMergeRequestEvent(w, event)
+		e.HandleGitlabMergeRequestEvent(e.Logger, w, event)
 	case gitlab.CommitCommentEvent:
 		e.Logger.Debug("comments on commits are not supported, only comments on merge requests")
 		e.respond(w, logging.Debug, http.StatusOK, "Ignoring comment on commit event")
@@ -650,11 +676,14 @@ func (e *VCSEventsController) handleCommentEvent(logger logging.SimpleLogging, b
 		if len(truncated) > truncateLen {
 			truncated = comment[:truncateLen] + "..."
 		}
+		logger.Debug("Ignoring non-command comment: '%s'", truncated)
 		return HTTPResponse{
 			body: fmt.Sprintf("Ignoring non-command comment: %q", truncated),
 		}
 	}
-	logger.Info("parsed comment as %s", parseResult.Command)
+	if parseResult.Command != nil {
+		logger.Info("Handling '%s' comment", parseResult.Command.Name)
+	}
 
 	// At this point we know it's a command we're not supposed to ignore, so now
 	// we check if this repo is allowed to run commands in the first place.
@@ -687,18 +716,17 @@ func (e *VCSEventsController) handleCommentEvent(logger logging.SimpleLogging, b
 	// variable to comment back on the pull request.
 	if parseResult.CommentResponse != "" {
 		if err := e.VCSClient.CreateComment(logger, baseRepo, pullNum, parseResult.CommentResponse, ""); err != nil {
-			logger.Err("unable to comment on pull request: %s", err)
+			logger.Err("Unable to comment on pull request: %s", err)
 		}
 		return HTTPResponse{
 			body: "Commenting back on pull request",
 		}
 	}
 	if parseResult.Command.RepoRelDir != "" {
-		logger.Info("Running comment command '%v' on dir '%v' on repo '%v', pull request: %v for user '%v'.",
-			parseResult.Command.Name, parseResult.Command.RepoRelDir, baseRepo.FullName, pullNum, user.Username)
+		logger.Info("Running comment command '%v' on dir '%v' for user '%v'.",
+			parseResult.Command.Name, parseResult.Command.RepoRelDir, user.Username)
 	} else {
-		logger.Info("Running comment command '%v' on repo '%v', pull request: %v for user '%v'.",
-			parseResult.Command.Name, baseRepo.FullName, pullNum, user.Username)
+		logger.Info("Running comment command '%v' for user '%v'.", parseResult.Command.Name, user.Username)
 	}
 	if !e.TestingMode {
 		// Respond with success and then actually execute the command asynchronously.
@@ -718,14 +746,20 @@ func (e *VCSEventsController) handleCommentEvent(logger logging.SimpleLogging, b
 // HandleGitlabMergeRequestEvent will delete any locks associated with the pull
 // request if the event is a merge request closed event. It's exported to make
 // testing easier.
-func (e *VCSEventsController) HandleGitlabMergeRequestEvent(w http.ResponseWriter, event gitlab.MergeEvent) {
+func (e *VCSEventsController) HandleGitlabMergeRequestEvent(logger logging.SimpleLogging, w http.ResponseWriter, event gitlab.MergeEvent) {
 	pull, pullEventType, baseRepo, headRepo, user, err := e.Parser.ParseGitlabMergeRequestEvent(event)
 	if err != nil {
 		e.respond(w, logging.Error, http.StatusBadRequest, "Error parsing webhook: %s", err)
 		return
 	}
-	e.Logger.Info("identified event as type %q", pullEventType.String())
-	resp := e.handlePullRequestEvent(e.Logger, baseRepo, headRepo, pull, user, pullEventType)
+
+	// Annotate logger with repo and pull/merge request number.
+	logger = logger.With(
+		"repo", baseRepo.FullName,
+		"pull", strconv.Itoa(pull.Num),
+	)
+	logger.Info("Processing Gitlab merge request '%s' event", pullEventType.String())
+	resp := e.handlePullRequestEvent(logger, baseRepo, headRepo, pull, user, pullEventType)
 
 	//TODO: move this to the outer most function similar to github
 	lvl := logging.Debug

server/core/runtime/models/shell_command_runner.go

@@ -173,12 +173,12 @@ func (s *ShellCommandRunner) RunCommandAsync(ctx command.ProjectContext) (chan<-
 
 		// We're done now. Send an error if there was one.
 		if err != nil {
-			err = errors.Wrapf(err, "running '%s %q' in '%s'",
+			err = errors.Wrapf(err, "running '%s' '%s' in '%s'",
 				s.shell.String(), s.command, s.workingDir)
 			log.Err(err.Error())
 			outCh <- Line{Err: err}
 		} else {
-			log.Info("successfully ran '%s %q' in '%s'",
+			log.Info("successfully ran '%s' '%s' in '%s'",
 				s.shell.String(), s.command, s.workingDir)
 		}
 	}()

server/core/runtime/post_workflow_hook_runner.go

@@ -59,7 +59,7 @@ func (wh DefaultPostWorkflowHookRunner) Run(ctx models.WorkflowHookCommandContex
 	wh.OutputHandler.SendWorkflowHook(ctx, "\n", true)
 
 	if err != nil {
-		err = fmt.Errorf("%s: running %q in %q: \n%s", err, shell+" "+shellArgs+" "+command, path, out)
+		err = fmt.Errorf("%s: running '%s' in '%s': \n%s", err, shell+" "+shellArgs+" "+command, path, out)
 		ctx.Log.Debug("error: %s", err)
 		return string(out), "", err
 	}
@@ -71,12 +71,12 @@ func (wh DefaultPostWorkflowHookRunner) Run(ctx models.WorkflowHookCommandContex
 		var customStatusErr error
 		customStatusOut, customStatusErr = os.ReadFile(outputFilePath)
 		if customStatusErr != nil {
-			err = fmt.Errorf("%s: running %q in %q: \n%s", err, shell+" "+shellArgs+" "+command, path, out)
+			err = fmt.Errorf("%s: running '%s' in '%s': \n%s", err, shell+" "+shellArgs+" "+command, path, out)
 			ctx.Log.Debug("error: %s", err)
 			return string(out), "", err
 		}
 	}
 
-	ctx.Log.Info("successfully ran %q in %q", shell+" "+shellArgs+" "+command, path)
+	ctx.Log.Info("Successfully ran '%s' in '%s'", shell+" "+shellArgs+" "+command, path)
 	return string(out), strings.Trim(string(customStatusOut), "\n"), nil
 }

server/core/runtime/pre_workflow_hook_runner.go

@@ -77,6 +77,6 @@ func (wh DefaultPreWorkflowHookRunner) Run(ctx models.WorkflowHookCommandContext
 		}
 	}
 
-	ctx.Log.Info("successfully ran %q in %q", shell+" "+shellArgs+" "+command, path)
+	ctx.Log.Info("Successfully ran '%s' in '%s'", shell+" "+shellArgs+" "+command, path)
 	return string(out), strings.Trim(string(customStatusOut), "\n"), nil
 }

server/core/terraform/terraform_client.go

@@ -376,11 +376,11 @@ func (c *DefaultClient) RunCommandWithVersion(ctx command.ProjectContext, path s
 	dur := time.Since(start)
 	log := ctx.Log.With("duration", dur)
 	if err != nil {
-		err = errors.Wrapf(err, "running %q in %q", tfCmd, path)
+		err = errors.Wrapf(err, "running '%s' in '%s'", tfCmd, path)
 		log.Err(err.Error())
 		return ansi.Strip(string(out)), err
 	}
-	log.Info("successfully ran %q in %q", tfCmd, path)
+	log.Info("Successfully ran '%s' in '%s'", tfCmd, path)
 
 	return ansi.Strip(string(out)), nil
 }

server/core/terraform/terraform_client_internal_test.go

@@ -164,7 +164,7 @@ func TestDefaultClient_RunCommandWithVersion_Error(t *testing.T) {
 		"1",
 	}
 	out, err := client.RunCommandWithVersion(ctx, tmp, args, map[string]string{}, nil, "workspace")
-	ErrEquals(t, fmt.Sprintf(`running "echo dying && exit 1" in %q: exit status 1`, tmp), err)
+	ErrEquals(t, fmt.Sprintf(`running 'echo dying && exit 1' in '%s': exit status 1`, tmp), err)
 	// Test that we still get our output.
 	Equals(t, "dying\n", out)
 }
@@ -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)
 	// Test that we still get our output.
 	Equals(t, "dying", out)