Skip to content

Commit

Permalink
feat: Refine the Atlantis Info Message Logging (runatlantis#5034)
Browse files Browse the repository at this point in the history 
Signed-off-by: Simon Heather <32168619+X-Guardian@users.noreply.github.com>
  • Loading branch information
@X-Guardian
X-Guardian authored Nov 19, 2024
1 parent b975301 commit e468a23
Show file tree
Hide file tree
Showing 22 changed files with 119 additions and 85 deletions.
12 changes: 2 additions & 10 deletions server/controllers/api_controller.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
}
Expand All @@ -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
}
Expand All @@ -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
}
Expand All @@ -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
}
Expand Down
98 changes: 66 additions & 32 deletions server/controllers/events/events_controller.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -19,6 +19,7 @@ import (
"html"
"io"
"net/http"
"strconv"
"strings"

"github.com/google/go-github/v66/github"
Expand Down Expand Up @@ -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")
Expand Down Expand Up @@ -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")
Expand Down Expand Up @@ -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)
Expand All @@ -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)
Expand Down Expand Up @@ -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
Expand All @@ -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
Expand Down Expand Up @@ -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)
}

Expand All @@ -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(),
Expand Down Expand Up @@ -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(),
Expand All @@ -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",
}
Expand All @@ -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")
Expand Down Expand Up @@ -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.
Expand Down Expand Up @@ -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.
Expand All @@ -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
Expand Down
4 changes: 2 additions & 2 deletions server/core/runtime/models/shell_command_runner.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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)
}
}()
Expand Down
6 changes: 3 additions & 3 deletions server/core/runtime/post_workflow_hook_runner.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
}
Expand All @@ -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
}
2 changes: 1 addition & 1 deletion server/core/runtime/pre_workflow_hook_runner.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
}
4 changes: 2 additions & 2 deletions server/core/terraform/terraform_client.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
}
Expand Down
4 changes: 2 additions & 2 deletions server/core/terraform/terraform_client_internal_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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)
}
Expand Down Expand Up @@ -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)

Expand Down
Loading

0 comments on commit e468a23

Please sign in to comment.