diff --git a/server/controllers/api_controller.go b/server/controllers/api_controller.go index f9b6aa809b..ff85371469 100644 --- a/server/controllers/api_controller.go +++ b/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 } diff --git a/server/controllers/events/events_controller.go b/server/controllers/events/events_controller.go index 8468e27d37..c838134132 100644 --- a/server/controllers/events/events_controller.go +++ b/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,7 +467,7 @@ 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) @@ -470,7 +475,14 @@ func (e *VCSEventsController) handleBitbucketCloudPullRequestEvent(w http.Respon } 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 diff --git a/server/core/runtime/models/shell_command_runner.go b/server/core/runtime/models/shell_command_runner.go index 7271f6789e..50b9f7760f 100644 --- a/server/core/runtime/models/shell_command_runner.go +++ b/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) } }() diff --git a/server/core/runtime/post_workflow_hook_runner.go b/server/core/runtime/post_workflow_hook_runner.go index d2e1f8cbb4..6bec732666 100644 --- a/server/core/runtime/post_workflow_hook_runner.go +++ b/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 } diff --git a/server/core/runtime/pre_workflow_hook_runner.go b/server/core/runtime/pre_workflow_hook_runner.go index 9e30e8eb27..737bd02e9f 100644 --- a/server/core/runtime/pre_workflow_hook_runner.go +++ b/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 } diff --git a/server/core/terraform/terraform_client.go b/server/core/terraform/terraform_client.go index cd2a0d8ad7..d01525704b 100644 --- a/server/core/terraform/terraform_client.go +++ b/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 } diff --git a/server/core/terraform/terraform_client_internal_test.go b/server/core/terraform/terraform_client_internal_test.go index 8c6be3ee43..f92a3fd2d2 100644 --- a/server/core/terraform/terraform_client_internal_test.go +++ b/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) diff --git a/server/events/command_runner.go b/server/events/command_runner.go index 301e9c27b5..fdd4b39153 100644 --- a/server/events/command_runner.go +++ b/server/events/command_runner.go @@ -159,13 +159,13 @@ func (c *DefaultCommandRunner) RunAutoplanCommand(baseRepo models.Repo, headRepo if c.TeamAllowlistChecker != nil && c.TeamAllowlistChecker.HasRules() { err := c.fetchUserTeams(baseRepo, &user) if err != nil { - c.Logger.Err("Unable to fetch user teams: %s", err) + log.Err("Unable to fetch user teams: %s", err) return } ok, err := c.checkUserPermissions(baseRepo, user, "plan") if err != nil { - c.Logger.Err("Unable to check user permissions: %s", err) + log.Err("Unable to check user permissions: %s", err) return } if !ok { @@ -191,32 +191,32 @@ func (c *DefaultCommandRunner) RunAutoplanCommand(baseRepo models.Repo, headRepo if len(c.DisableAutoplanLabel) > 0 { labels, err := c.VCSClient.GetPullLabels(ctx.Log, baseRepo, pull) if err != nil { - ctx.Log.Err("Unable to get pull labels. Proceeding with %s command.", err, command.Plan) + ctx.Log.Err("Unable to get VCS pull/merge request labels: %s. Proceeding with autoplan.", err) } else if utils.SlicesContains(labels, c.DisableAutoplanLabel) { + ctx.Log.Info("Pull/merge request has disable auto plan label '%s' so not running autoplan.", c.DisableAutoplanLabel) return } } + ctx.Log.Info("Running autoplan...") cmd := &CommentCommand{ Name: command.Autoplan, } err = c.PreWorkflowHooksCommandRunner.RunPreHooks(ctx, cmd) if err != nil { - ctx.Log.Err("Error running pre-workflow hooks %s.", err) - if c.FailOnPreWorkflowHookError { ctx.Log.Err("'fail-on-pre-workflow-hook-error' set, so not running %s command.", command.Plan) - // Update the plan or apply commit status to pending whilst the pre workflow hook is running so that the PR can't be merged. + // Update the plan or apply commit status to failed switch cmd.Name { case command.Plan: if err := c.CommitStatusUpdater.UpdateCombined(ctx.Log, ctx.Pull.BaseRepo, ctx.Pull, models.FailedCommitStatus, command.Plan); err != nil { - ctx.Log.Warn("unable to update plan commit status: %s", err) + ctx.Log.Warn("Unable to update plan commit status: %s", err) } case command.Apply: if err := c.CommitStatusUpdater.UpdateCombined(ctx.Log, ctx.Pull.BaseRepo, ctx.Pull, models.FailedCommitStatus, command.Apply); err != nil { - ctx.Log.Warn("unable to update apply commit status: %s", err) + ctx.Log.Warn("Unable to update apply commit status: %s", err) } } @@ -230,11 +230,7 @@ func (c *DefaultCommandRunner) RunAutoplanCommand(baseRepo models.Repo, headRepo autoPlanRunner.Run(ctx, nil) - err = c.PostWorkflowHooksCommandRunner.RunPostHooks(ctx, cmd) - - if err != nil { - ctx.Log.Err("Error running post-workflow hooks %s.", err) - } + c.PostWorkflowHooksCommandRunner.RunPostHooks(ctx, cmd) // nolint: errcheck } // commentUserDoesNotHavePermissions comments on the pull request that the user @@ -361,12 +357,10 @@ func (c *DefaultCommandRunner) RunCommentCommand(baseRepo models.Repo, maybeHead err = c.PreWorkflowHooksCommandRunner.RunPreHooks(ctx, cmd) if err != nil { - ctx.Log.Err("Error running pre-workflow hooks %s.", err) - if c.FailOnPreWorkflowHookError { ctx.Log.Err("'fail-on-pre-workflow-hook-error' set, so not running %s command.", cmd.Name.String()) - // Update the plan or apply commit status to pending whilst the pre workflow hook is running so that the PR can't be merged. + // Update the plan or apply commit status to failed switch cmd.Name { case command.Plan: if err := c.CommitStatusUpdater.UpdateCombined(ctx.Log, ctx.Pull.BaseRepo, ctx.Pull, models.FailedCommitStatus, command.Plan); err != nil { @@ -388,11 +382,7 @@ func (c *DefaultCommandRunner) RunCommentCommand(baseRepo models.Repo, maybeHead cmdRunner.Run(ctx, cmd) - err = c.PostWorkflowHooksCommandRunner.RunPostHooks(ctx, cmd) - - if err != nil { - ctx.Log.Err("Error running post-workflow hooks %s.", err) - } + c.PostWorkflowHooksCommandRunner.RunPostHooks(ctx, cmd) // nolint: errcheck } func (c *DefaultCommandRunner) getGithubData(logger logging.SimpleLogging, baseRepo models.Repo, pullNum int) (models.PullRequest, models.Repo, error) { diff --git a/server/events/plan_command_runner.go b/server/events/plan_command_runner.go index c2b6b7a107..c1cc3e81e0 100644 --- a/server/events/plan_command_runner.go +++ b/server/events/plan_command_runner.go @@ -287,7 +287,7 @@ func (p *PlanCommandRunner) run(ctx *command.Context, cmd *CommentCommand) { // This step does not approve any policies that require approval. if len(result.ProjectResults) > 0 && !(result.HasErrors() || result.PlansDeleted) { - ctx.Log.Info("Running policy check for %s", cmd.String()) + ctx.Log.Info("Running policy check for '%s'", cmd.CommandName()) p.policyCheckCommandRunner.Run(ctx, policyCheckCmds) } else if len(projectCmds) == 0 && !cmd.IsForSpecificProject() { // If there were no projects modified, we set successful commit statuses diff --git a/server/events/post_workflow_hooks_command_runner.go b/server/events/post_workflow_hooks_command_runner.go index f5fe0c5245..2466f042e8 100644 --- a/server/events/post_workflow_hooks_command_runner.go +++ b/server/events/post_workflow_hooks_command_runner.go @@ -50,7 +50,7 @@ func (w *DefaultPostWorkflowHooksCommandRunner) RunPostHooks(ctx *command.Contex return nil } - ctx.Log.Debug("post-hooks configured, running...") + ctx.Log.Info("Post-workflow hooks configured, running...") unlockFn, err := w.WorkingDirLocker.TryLock(ctx.Pull.BaseRepo.FullName, ctx.Pull.Num, DefaultWorkspace, DefaultRepoRelDir) if err != nil { @@ -84,6 +84,7 @@ func (w *DefaultPostWorkflowHooksCommandRunner) RunPostHooks(ctx *command.Contex postWorkflowHooks, repoDir) if err != nil { + ctx.Log.Err("Error running post-workflow hooks %s.", err) return err } @@ -146,5 +147,8 @@ func (w *DefaultPostWorkflowHooksCommandRunner) runHooks( ctx.Log.Warn("unable to update post workflow hook status: %s", err) } } + + ctx.Log.Info("Post-workflow hooks completed") + return nil } diff --git a/server/events/pre_workflow_hooks_command_runner.go b/server/events/pre_workflow_hooks_command_runner.go index 70462765a3..7d152c7328 100644 --- a/server/events/pre_workflow_hooks_command_runner.go +++ b/server/events/pre_workflow_hooks_command_runner.go @@ -50,7 +50,7 @@ func (w *DefaultPreWorkflowHooksCommandRunner) RunPreHooks(ctx *command.Context, return nil } - ctx.Log.Debug("pre-hooks configured, running...") + ctx.Log.Info("Pre-workflow hooks configured, running...") unlockFn, err := w.WorkingDirLocker.TryLock(ctx.Pull.BaseRepo.FullName, ctx.Pull.Num, DefaultWorkspace, DefaultRepoRelDir) if err != nil { @@ -96,9 +96,12 @@ func (w *DefaultPreWorkflowHooksCommandRunner) RunPreHooks(ctx *command.Context, preWorkflowHooks, repoDir) if err != nil { + ctx.Log.Err("Error running pre-workflow hooks %s.", err) return err } + ctx.Log.Info("Pre-workflow hooks completed successfully") + return nil } diff --git a/server/events/project_command_builder.go b/server/events/project_command_builder.go index 35e540a858..5870bf22e0 100644 --- a/server/events/project_command_builder.go +++ b/server/events/project_command_builder.go @@ -522,7 +522,7 @@ func (p *DefaultProjectCommandBuilder) buildAllCommandsByCfg(ctx *command.Contex absProjectDir := filepath.Join(repoDir, mp.Path) pWorkspace, err := p.ProjectFinder.DetermineWorkspaceFromHCL(ctx.Log, absProjectDir) if err != nil { - return nil, errors.Wrapf(err, "looking for Terraform Cloud workspace from configuration %s", absProjectDir) + return nil, errors.Wrapf(err, "Looking for Terraform Cloud workspace from configuration in '%s'", absProjectDir) } pCfg := p.GlobalCfg.DefaultProjCfg(ctx.Log, ctx.Pull.BaseRepo.ID(), mp.Path, pWorkspace) diff --git a/server/events/project_finder.go b/server/events/project_finder.go index 79c4a567f2..355e181d50 100644 --- a/server/events/project_finder.go +++ b/server/events/project_finder.go @@ -76,7 +76,7 @@ var cloudBlockSchema = &hcl.BodySchema{ } func (p *DefaultProjectFinder) DetermineWorkspaceFromHCL(log logging.SimpleLogging, absRepoDir string) (string, error) { - log.Info("looking for Terraform Cloud workspace from configuration in %q", absRepoDir) + log.Info("Looking for Terraform Cloud workspace from configuration in '%s'", absRepoDir) infos, err := os.ReadDir(absRepoDir) if err != nil { return "", err diff --git a/server/events/project_locker.go b/server/events/project_locker.go index 275b9e8c72..9620708db2 100644 --- a/server/events/project_locker.go +++ b/server/events/project_locker.go @@ -83,7 +83,7 @@ func (p *DefaultProjectLocker) TryLock(log logging.SimpleLogging, pull models.Pu LockFailureReason: failureMsg, }, nil } - log.Info("acquired lock with id %q", lockAttempt.LockKey) + log.Info("Acquired lock with id '%s'", lockAttempt.LockKey) return &TryLockResponse{ LockAcquired: true, UnlockFn: func() error { diff --git a/server/events/vcs/azuredevops_client.go b/server/events/vcs/azuredevops_client.go index 3bbc8925fb..316e5a038c 100644 --- a/server/events/vcs/azuredevops_client.go +++ b/server/events/vcs/azuredevops_client.go @@ -249,6 +249,8 @@ func (g *AzureDevopsClient) UpdateStatus(logger logging.SimpleLogging, repo mode adState = azuredevops.GitFailed.String() } + logger.Info("Updating Azure DevOps commit status for '%s' to '%s'", src, adState) + status := azuredevops.GitPullRequestStatus{} status.Context = GitStatusContextFromSrc(src) status.Description = &description diff --git a/server/events/vcs/bitbucketcloud/client.go b/server/events/vcs/bitbucketcloud/client.go index 19d2d7ea5f..4b2ad99577 100644 --- a/server/events/vcs/bitbucketcloud/client.go +++ b/server/events/vcs/bitbucketcloud/client.go @@ -181,6 +181,8 @@ func (b *Client) UpdateStatus(logger logging.SimpleLogging, repo models.Repo, pu bbState = "FAILED" } + logger.Info("Updating BitBucket commit status for '%s' to '%s'", src, bbState) + // URL is a required field for bitbucket statuses. We default to the // Atlantis server's URL. if url == "" { diff --git a/server/events/vcs/bitbucketserver/client.go b/server/events/vcs/bitbucketserver/client.go index 5d632efd58..15be8b792e 100644 --- a/server/events/vcs/bitbucketserver/client.go +++ b/server/events/vcs/bitbucketserver/client.go @@ -238,6 +238,8 @@ func (b *Client) UpdateStatus(logger logging.SimpleLogging, _ models.Repo, pull bbState = "FAILED" } + logger.Info("Updating BitBucket commit status for '%s' to '%s'", src, bbState) + // URL is a required field for bitbucket statuses. We default to the // Atlantis server's URL. if url == "" { diff --git a/server/events/vcs/gitea/client.go b/server/events/vcs/gitea/client.go index c32a7b3823..a1044f43ca 100644 --- a/server/events/vcs/gitea/client.go +++ b/server/events/vcs/gitea/client.go @@ -316,7 +316,7 @@ func (c *GiteaClient) UpdateStatus(logger logging.SimpleLogging, repo models.Rep giteaState = gitea.StatusFailure } - logger.Debug("Updating status on Gitea pull request %d for '%s' to '%s'", pull.Num, description, state) + logger.Info("Updating Gitea check status for '%s' to '%s'", src, state) newStatusOption := gitea.CreateStatusOption{ State: giteaState, diff --git a/server/events/vcs/github_client.go b/server/events/vcs/github_client.go index 7b1b80ba95..c8539890c2 100644 --- a/server/events/vcs/github_client.go +++ b/server/events/vcs/github_client.go @@ -909,7 +909,8 @@ func (g *GithubClient) UpdateStatus(logger logging.SimpleLogging, repo models.Re case models.FailedCommitStatus: ghState = "failure" } - logger.Debug("Updating status on GitHub pull request %d for '%s' to '%s'", pull.Num, description, ghState) + + logger.Info("Updating GitHub Check status for '%s' to '%s'", src, ghState) status := &github.RepoStatus{ State: github.String(ghState), diff --git a/server/events/vcs/gitlab_client.go b/server/events/vcs/gitlab_client.go index 7537676f6f..3adb51a974 100644 --- a/server/events/vcs/gitlab_client.go +++ b/server/events/vcs/gitlab_client.go @@ -108,7 +108,7 @@ func NewGitlabClient(hostname string, token string, logger logging.SimpleLogging if err != nil { return nil, err } - logger.Info("determined GitLab is running version %s", client.Version.String()) + logger.Info("GitLab host '%s' is running version %s", client.Client.BaseURL().Host, client.Version.String()) } return client, nil diff --git a/server/events/vcs/instrumented_client.go b/server/events/vcs/instrumented_client.go index 6e2f938771..adc0ca0abc 100644 --- a/server/events/vcs/instrumented_client.go +++ b/server/events/vcs/instrumented_client.go @@ -215,7 +215,6 @@ func (c *InstrumentedClient) UpdateStatus(logger logging.SimpleLogging, repo mod executionSuccess := scope.Counter(metrics.ExecutionSuccessMetric) executionError := scope.Counter(metrics.ExecutionErrorMetric) - logger.Info("updating vcs status") if err := c.Client.UpdateStatus(logger, repo, pull, state, src, description, url); err != nil { executionError.Inc(1) logger.Err("Unable to update status at url: %s, error: %s", url, err.Error()) diff --git a/server/server.go b/server/server.go index 14e368ddf9..001d666b71 100644 --- a/server/server.go +++ b/server/server.go @@ -317,7 +317,12 @@ func NewServer(userConfig UserConfig, config Config) (*Server, error) { } } - logger.Info("Supported VCS Hosts", "hosts", supportedVCSHosts) + var supportedVCSHostsStr []string + for _, host := range supportedVCSHosts { + supportedVCSHostsStr = append(supportedVCSHostsStr, host.String()) + } + + logger.Info("Supported VCS Hosts: %s", strings.Join(supportedVCSHostsStr, ", ")) home, err := homedir.Dir() if err != nil { @@ -1119,7 +1124,7 @@ func (s *Server) Index(w http.ResponseWriter, _ *http.Request) { } applyCmdLock, err := s.ApplyLocker.CheckApplyLock() - s.Logger.Info("Apply Lock: %v", applyCmdLock) + s.Logger.Debug("Apply Lock: %v", applyCmdLock) if err != nil { w.WriteHeader(http.StatusServiceUnavailable) fmt.Fprintf(w, "Could not retrieve global apply lock: %s", err)