From 30c09d9a03f5c26d2b29d0a322b830249cb29736 Mon Sep 17 00:00:00 2001 From: Samra Belachew Date: Fri, 13 May 2022 11:31:59 -0700 Subject: [PATCH] Pass context through logs/use field parameter to offer details (#252) * draft * pass context/fields thru * fix tests --- .../controllers/events/events_controller.go | 24 ++++++--- .../events/events_controller_e2e_test.go | 5 +- .../events/events_controller_test.go | 13 +++-- .../mocks/matchers/locking_trylockresponse.go | 3 +- .../map_of_string_to_models_projectlock.go | 3 +- .../locking/mocks/matchers/models_project.go | 3 +- .../mocks/matchers/models_pullrequest.go | 3 +- .../locking/mocks/matchers/models_user.go | 3 +- .../matchers/ptr_to_models_projectlock.go | 3 +- .../matchers/slice_of_models_projectlock.go | 3 +- server/core/locking/mocks/mock_locker.go | 5 +- server/core/runtime/apply_step_runner.go | 10 ++-- server/core/runtime/apply_step_runner_test.go | 6 +++ server/core/runtime/env_step_runner_test.go | 1 + server/core/runtime/init_step_runner.go | 6 +-- server/core/runtime/init_step_runner_test.go | 5 ++ server/core/runtime/plan_step_runner.go | 2 +- server/core/runtime/policy/conftest_client.go | 4 +- .../runtime/policy/conftest_client_test.go | 1 + server/core/runtime/run_step_runner.go | 6 +-- server/core/runtime/run_step_runner_test.go | 1 + server/core/runtime/steps_runner_test.go | 3 +- server/core/terraform/async_client.go | 10 ++-- server/core/terraform/async_client_test.go | 15 ++++-- server/core/terraform/terraform_client.go | 5 +- .../terraform_client_internal_test.go | 6 ++- .../core/terraform/terraform_client_test.go | 2 + server/events/apply_command_runner.go | 22 ++++---- server/events/apply_command_runner_test.go | 14 +++--- .../events/approve_policies_command_runner.go | 12 ++--- server/events/command/context.go | 2 + server/events/command/plan/runner.go | 2 +- server/events/command/policies/runner.go | 2 +- server/events/command/project_context.go | 4 ++ server/events/command_runner.go | 22 ++++---- server/events/delete_lock_command.go | 14 ++++-- server/events/github_app_working_dir.go | 6 ++- .../instrumented_project_command_builder.go | 6 +-- .../instrumented_project_command_runner.go | 6 +-- server/events/mocks/mock_project_lock.go | 37 ++++++++------ server/events/plan_command_runner.go | 36 ++++++------- server/events/policy_check_command_runner.go | 12 ++--- server/events/project_command_builder.go | 12 ++--- .../project_command_builder_internal_test.go | 19 ++++++- server/events/project_command_builder_test.go | 50 +++++++++++-------- .../events/project_command_context_builder.go | 8 +-- .../project_command_context_builder_test.go | 2 + .../events/project_command_output_wrapper.go | 6 +-- server/events/project_command_runner_test.go | 4 +- server/events/project_finder.go | 9 ++-- server/events/project_finder_test.go | 3 +- server/events/project_locker.go | 7 +-- server/events/project_locker_test.go | 7 +-- server/events/pull_closed_executor.go | 8 ++- server/events/pull_updater.go | 8 +-- server/events/unlock_command_runner.go | 4 +- server/events/version_command_runner.go | 6 +-- server/events/working_dir.go | 26 ++++++++-- server/lyft/aws/sqs/worker.go | 12 ++--- server/lyft/command/feature_runner.go | 2 +- .../audit_project_commands_wrapper.go | 4 +- server/lyft/gateway/autoplan_builder.go | 37 +++++++------- server/sync/project.go | 2 +- server/vcs/provider/github/request/handler.go | 3 +- 64 files changed, 348 insertions(+), 239 deletions(-) diff --git a/server/controllers/events/events_controller.go b/server/controllers/events/events_controller.go index 97eb6d99db..29e10f245a 100644 --- a/server/controllers/events/events_controller.go +++ b/server/controllers/events/events_controller.go @@ -154,6 +154,7 @@ func NewVCSEventsController( return &VCSEventsController{ RequestRouter: router, + Logger: logger, Scope: scope, Parser: eventParser, CommentParser: commentParser, @@ -253,7 +254,7 @@ func (p *RequestRouter) Route(w http.ResponseWriter, r *http.Request) { // VCS host, ex. GitHub. // TODO: migrate all provider specific request handling into packaged resolver similar to github type VCSEventsController struct { - Logger logging.SimpleLogging + Logger logging.Logger Scope tally.Scope CommentParser events.CommentParsing Parser events.EventParsing @@ -483,7 +484,7 @@ func (e *VCSEventsController) handleBitbucketCloudPullRequestEvent(w http.Respon return } pullEventType := e.Parser.GetBitbucketCloudPullEventType(eventType) - e.Logger.Infof("identified event as type %q", pullEventType.String()) + e.Logger.Info(fmt.Sprintf("identified event as type %q", pullEventType.String())) eventTimestamp := time.Now() //TODO: move this to the outer most function similar to github lvl := logging.Debug @@ -515,7 +516,7 @@ func (e *VCSEventsController) handleBitbucketServerPullRequestEvent(w http.Respo return } pullEventType := e.Parser.GetBitbucketServerPullEventType(eventType) - e.Logger.Infof("identified event as type %q", pullEventType.String()) + e.Logger.Info(fmt.Sprintf("identified event as type %q", pullEventType.String())) eventTimestamp := time.Now() lvl := logging.Debug cloneableRequest, err := httputils.NewBufferedRequest(request) @@ -607,7 +608,7 @@ func (e *VCSEventsController) HandleGitlabMergeRequestEvent(w http.ResponseWrite e.respond(w, logging.Error, http.StatusBadRequest, "Error parsing webhook: %s", err) return } - e.Logger.Infof("identified event as type %q", pullEventType.String()) + e.Logger.Info(fmt.Sprintf("identified event as type %q", pullEventType.String())) eventTimestamp := time.Now() lvl := logging.Debug @@ -717,7 +718,7 @@ func (e *VCSEventsController) HandleAzureDevopsPullRequestEvent(w http.ResponseW e.respond(w, logging.Error, http.StatusBadRequest, "Error parsing pull data: %s %s", err, azuredevopsReqID) return } - e.Logger.Infof("identified event as type %q", pullEventType.String()) + e.Logger.Info(fmt.Sprintf("identified event as type %q", pullEventType.String())) eventTimestamp := time.Now() lvl := logging.Debug cloneableRequest, err := httputils.NewBufferedRequest(request) @@ -751,7 +752,18 @@ func (e *VCSEventsController) supportsHost(h models.VCSHostType) bool { func (e *VCSEventsController) respond(w http.ResponseWriter, lvl logging.LogLevel, code int, format string, args ...interface{}) { response := fmt.Sprintf(format, args...) - e.Logger.Log(lvl, response) + switch lvl { + case logging.Error: + e.Logger.Error(response) + case logging.Info: + e.Logger.Info(response) + case logging.Warn: + e.Logger.Warn(response) + case logging.Debug: + e.Logger.Debug(response) + default: + e.Logger.Error(response) + } w.WriteHeader(code) fmt.Fprintln(w, response) } diff --git a/server/controllers/events/events_controller_e2e_test.go b/server/controllers/events/events_controller_e2e_test.go index f65012c522..ce05a0a4fc 100644 --- a/server/controllers/events/events_controller_e2e_test.go +++ b/server/controllers/events/events_controller_e2e_test.go @@ -650,10 +650,9 @@ func setupE2E(t *testing.T, repoFixtureDir string, userConfig *server.UserConfig // TODO: we should compare this output against what we post on github projectCmdOutputHandler := &jobs.NoopProjectOutputHandler{} - logger := logging.NewNoopLogger(t) ctxLogger := logging.NewNoopCtxLogger(t) featureAllocator, _ := feature.NewStringSourcedAllocator(ctxLogger) - terraformClient, err := terraform.NewE2ETestClient(logger, binDir, cacheDir, "", "", "", "default-tf-version", "https://releases.hashicorp.com", downloader, false, projectCmdOutputHandler, featureAllocator) + terraformClient, err := terraform.NewE2ETestClient(binDir, cacheDir, "", "", "", "default-tf-version", "https://releases.hashicorp.com", downloader, false, projectCmdOutputHandler, featureAllocator) Ok(t, err) // Set real dependencies here. @@ -990,7 +989,7 @@ func setupE2E(t *testing.T, repoFixtureDir string, userConfig *server.UserConfig ctrl := events_controllers.VCSEventsController{ RequestRouter: requestRouter, - Logger: logger, + Logger: ctxLogger, Scope: statsScope, Parser: eventParser, CommentParser: commentParser, diff --git a/server/controllers/events/events_controller_test.go b/server/controllers/events/events_controller_test.go index 97f574f0fd..152e6485e6 100644 --- a/server/controllers/events/events_controller_test.go +++ b/server/controllers/events/events_controller_test.go @@ -210,8 +210,8 @@ func TestPost_BBServerPullClosed(t *testing.T) { RegisterMockTestingT(t) allowlist, err := events.NewRepoAllowlistChecker("*") Ok(t, err) - logger := logging.NewNoopLogger(t) - scope, _, _ := metrics.NewLoggingScope(logging.NewNoopCtxLogger(t), "null") + ctxLogger := logging.NewNoopCtxLogger(t) + scope, _, _ := metrics.NewLoggingScope(ctxLogger, "null") ec := &events_controllers.VCSEventsController{ Parser: &events.EventParser{ BitbucketUser: "bb-user", @@ -223,7 +223,7 @@ func TestPost_BBServerPullClosed(t *testing.T) { RepoAllowlistChecker: allowlist, SupportedVCSHosts: []models.VCSHostType{models.BitbucketServer}, VCSClient: nil, - Logger: logger, + Logger: ctxLogger, Scope: scope, } @@ -302,11 +302,10 @@ func setup(t *testing.T) (events_controllers.VCSEventsController, *mocks.MockGit vcsmock := vcsmocks.NewMockClient() repoAllowlistChecker, err := events.NewRepoAllowlistChecker("*") Ok(t, err) - logger := logging.NewNoopLogger(t) - scope, _, _ := metrics.NewLoggingScope(logging.NewNoopCtxLogger(t), "null") + ctxLogger := logging.NewNoopCtxLogger(t) + scope, _, _ := metrics.NewLoggingScope(ctxLogger, "null") e := events_controllers.VCSEventsController{ - - Logger: logger, + Logger: ctxLogger, Scope: scope, Parser: p, CommentEventHandler: noopCommentHandler{}, diff --git a/server/core/locking/mocks/matchers/locking_trylockresponse.go b/server/core/locking/mocks/matchers/locking_trylockresponse.go index 02aaa00983..53e9bb19d5 100644 --- a/server/core/locking/mocks/matchers/locking_trylockresponse.go +++ b/server/core/locking/mocks/matchers/locking_trylockresponse.go @@ -2,9 +2,8 @@ package matchers import ( - "reflect" - "github.com/petergtz/pegomock" + "reflect" locking "github.com/runatlantis/atlantis/server/core/locking" ) diff --git a/server/core/locking/mocks/matchers/map_of_string_to_models_projectlock.go b/server/core/locking/mocks/matchers/map_of_string_to_models_projectlock.go index e541f2b227..eb1b54416e 100644 --- a/server/core/locking/mocks/matchers/map_of_string_to_models_projectlock.go +++ b/server/core/locking/mocks/matchers/map_of_string_to_models_projectlock.go @@ -2,9 +2,8 @@ package matchers import ( - "reflect" - "github.com/petergtz/pegomock" + "reflect" models "github.com/runatlantis/atlantis/server/events/models" ) diff --git a/server/core/locking/mocks/matchers/models_project.go b/server/core/locking/mocks/matchers/models_project.go index 0cc4104e5a..a5a87e6f0d 100644 --- a/server/core/locking/mocks/matchers/models_project.go +++ b/server/core/locking/mocks/matchers/models_project.go @@ -2,9 +2,8 @@ package matchers import ( - "reflect" - "github.com/petergtz/pegomock" + "reflect" models "github.com/runatlantis/atlantis/server/events/models" ) diff --git a/server/core/locking/mocks/matchers/models_pullrequest.go b/server/core/locking/mocks/matchers/models_pullrequest.go index db2666f02f..9ae2a7e920 100644 --- a/server/core/locking/mocks/matchers/models_pullrequest.go +++ b/server/core/locking/mocks/matchers/models_pullrequest.go @@ -2,9 +2,8 @@ package matchers import ( - "reflect" - "github.com/petergtz/pegomock" + "reflect" models "github.com/runatlantis/atlantis/server/events/models" ) diff --git a/server/core/locking/mocks/matchers/models_user.go b/server/core/locking/mocks/matchers/models_user.go index e9bf1384ba..0aa92b5d88 100644 --- a/server/core/locking/mocks/matchers/models_user.go +++ b/server/core/locking/mocks/matchers/models_user.go @@ -2,9 +2,8 @@ package matchers import ( - "reflect" - "github.com/petergtz/pegomock" + "reflect" models "github.com/runatlantis/atlantis/server/events/models" ) diff --git a/server/core/locking/mocks/matchers/ptr_to_models_projectlock.go b/server/core/locking/mocks/matchers/ptr_to_models_projectlock.go index c33537f97d..7b0b6f1084 100644 --- a/server/core/locking/mocks/matchers/ptr_to_models_projectlock.go +++ b/server/core/locking/mocks/matchers/ptr_to_models_projectlock.go @@ -2,9 +2,8 @@ package matchers import ( - "reflect" - "github.com/petergtz/pegomock" + "reflect" models "github.com/runatlantis/atlantis/server/events/models" ) diff --git a/server/core/locking/mocks/matchers/slice_of_models_projectlock.go b/server/core/locking/mocks/matchers/slice_of_models_projectlock.go index 16932f9a11..f510db6e8e 100644 --- a/server/core/locking/mocks/matchers/slice_of_models_projectlock.go +++ b/server/core/locking/mocks/matchers/slice_of_models_projectlock.go @@ -2,9 +2,8 @@ package matchers import ( - "reflect" - "github.com/petergtz/pegomock" + "reflect" models "github.com/runatlantis/atlantis/server/events/models" ) diff --git a/server/core/locking/mocks/mock_locker.go b/server/core/locking/mocks/mock_locker.go index 2346124d32..645ca45528 100644 --- a/server/core/locking/mocks/mock_locker.go +++ b/server/core/locking/mocks/mock_locker.go @@ -4,12 +4,11 @@ package mocks import ( - "reflect" - "time" - pegomock "github.com/petergtz/pegomock" locking "github.com/runatlantis/atlantis/server/core/locking" models "github.com/runatlantis/atlantis/server/events/models" + "reflect" + "time" ) type MockLocker struct { diff --git a/server/core/runtime/apply_step_runner.go b/server/core/runtime/apply_step_runner.go index 6f814736c0..f0bfd23f84 100644 --- a/server/core/runtime/apply_step_runner.go +++ b/server/core/runtime/apply_step_runner.go @@ -37,7 +37,7 @@ func (a *ApplyStepRunner) Run(ctx context.Context, prjCtx command.ProjectContext return "", errors.Wrap(err, "unable to read planfile") } - prjCtx.Log.Info("starting apply") + prjCtx.Log.InfoContext(prjCtx.RequestCtx, "starting apply") var out string // TODO: Leverage PlanTypeStepRunnerDelegate here @@ -56,9 +56,9 @@ func (a *ApplyStepRunner) Run(ctx context.Context, prjCtx command.ProjectContext // If the apply was successful, delete the plan. if err == nil { - prjCtx.Log.Info("apply successful, deleting planfile") + prjCtx.Log.InfoContext(prjCtx.RequestCtx, "apply successful, deleting planfile") if removeErr := os.Remove(planPath); removeErr != nil { - prjCtx.Log.Warn(fmt.Sprintf("failed to delete planfile after successful apply: %s", removeErr)) + prjCtx.Log.WarnContext(prjCtx.RequestCtx, fmt.Sprintf("failed to delete planfile after successful apply: %s", removeErr)) } } return out, err @@ -129,7 +129,7 @@ func (a *ApplyStepRunner) runRemoteApply( // updateStatusF will update the commit status and log any error. updateStatusF := func(status models.CommitStatus, url string) { if err := a.CommitStatusUpdater.UpdateProject(ctx, prjCtx, command.Apply, status, url); err != nil { - prjCtx.Log.Error(fmt.Sprintf("unable to update status: %s", err)) + prjCtx.Log.ErrorContext(prjCtx.RequestCtx, fmt.Sprintf("unable to update status: %s", err)) } } @@ -165,7 +165,7 @@ func (a *ApplyStepRunner) runRemoteApply( // Check if the plan is as expected. planChangedErr = a.remotePlanChanged(string(planfileBytes), strings.Join(lines, "\n"), tfVersion) if planChangedErr != nil { - prjCtx.Log.Error(fmt.Sprintf("plan generated during apply does not match expected plan, aborting")) + prjCtx.Log.ErrorContext(prjCtx.RequestCtx, fmt.Sprintf("plan generated during apply does not match expected plan, aborting")) inCh <- "no\n" // Need to continue so we read all the lines, otherwise channel // sender (in TerraformClient) will block indefinitely waiting diff --git a/server/core/runtime/apply_step_runner_test.go b/server/core/runtime/apply_step_runner_test.go index 77a9977807..1707324cac 100644 --- a/server/core/runtime/apply_step_runner_test.go +++ b/server/core/runtime/apply_step_runner_test.go @@ -64,6 +64,7 @@ func TestRun_Success(t *testing.T) { Workspace: "workspace", RepoRelDir: ".", EscapedCommentArgs: []string{"comment", "args"}, + RequestCtx: context.TODO(), } Ok(t, err) @@ -98,6 +99,7 @@ func TestRun_AppliesCorrectProjectPlan(t *testing.T) { RepoRelDir: ".", ProjectName: "projectname", EscapedCommentArgs: []string{"comment", "args"}, + RequestCtx: context.TODO(), } Ok(t, err) @@ -133,6 +135,7 @@ func TestRun_UsesConfiguredTFVersion(t *testing.T) { EscapedCommentArgs: []string{"comment", "args"}, TerraformVersion: tfVersion, Log: logger, + RequestCtx: context.TODO(), } RegisterMockTestingT(t) @@ -222,6 +225,7 @@ func TestRun_UsingTarget(t *testing.T) { Workspace: "workspace", RepoRelDir: ".", EscapedCommentArgs: c.commentFlags, + RequestCtx: context.TODO(), }, c.extraArgs, tmpDir, map[string]string(nil)) Equals(t, "", output) if c.expErr { @@ -268,6 +272,7 @@ Plan: 0 to add, 0 to change, 1 to destroy.` RepoRelDir: ".", EscapedCommentArgs: []string{"comment", "args"}, TerraformVersion: tfVersion, + RequestCtx: context.TODO(), } output, err := o.Run(ctx, prjCtx, []string{"extra", "args"}, tmpDir, map[string]string(nil)) <-tfExec.DoneCh @@ -331,6 +336,7 @@ Plan: 0 to add, 0 to change, 1 to destroy.` RepoRelDir: ".", EscapedCommentArgs: []string{"comment", "args"}, TerraformVersion: tfVersion, + RequestCtx: context.TODO(), }, []string{"extra", "args"}, tmpDir, map[string]string(nil)) <-tfExec.DoneCh ErrEquals(t, `Plan generated during apply phase did not match plan generated during plan phase. diff --git a/server/core/runtime/env_step_runner_test.go b/server/core/runtime/env_step_runner_test.go index 5337333f75..d6ba011226 100644 --- a/server/core/runtime/env_step_runner_test.go +++ b/server/core/runtime/env_step_runner_test.go @@ -76,6 +76,7 @@ func TestEnvStepRunner_Run(t *testing.T) { RepoRelDir: "mydir", TerraformVersion: tfVersion, ProjectName: c.ProjectName, + RequestCtx: context.TODO(), } value, err := envRunner.Run(ctx, prjCtx, c.Command, c.Value, tmpDir, map[string]string(nil)) if c.ExpErr != "" { diff --git a/server/core/runtime/init_step_runner.go b/server/core/runtime/init_step_runner.go index 2527854b11..78406fe21a 100644 --- a/server/core/runtime/init_step_runner.go +++ b/server/core/runtime/init_step_runner.go @@ -22,7 +22,7 @@ func (i *InitStepRunner) Run(ctx context.Context, prjCtx command.ProjectContext, terraformLockfilePath := filepath.Join(path, lockFileName) terraformLockFileTracked, err := common.IsFileTracked(path, lockFileName) if err != nil { - prjCtx.Log.Warn(fmt.Sprintf("Error checking if %s is tracked in %s", lockFileName, path)) + prjCtx.Log.WarnContext(prjCtx.RequestCtx, fmt.Sprintf("Error checking if %s is tracked in %s", lockFileName, path)) } // If .terraform.lock.hcl is not tracked in git and it exists prior to init @@ -31,7 +31,7 @@ func (i *InitStepRunner) Run(ctx context.Context, prjCtx command.ProjectContext, if common.FileExists(terraformLockfilePath) && !terraformLockFileTracked { delErr := os.Remove(terraformLockfilePath) if delErr != nil { - prjCtx.Log.Info(fmt.Sprintf("Error Deleting `%s`", lockFileName)) + prjCtx.Log.InfoContext(prjCtx.RequestCtx, fmt.Sprintf("Error Deleting `%s`", lockFileName)) } } @@ -45,7 +45,7 @@ func (i *InitStepRunner) Run(ctx context.Context, prjCtx command.ProjectContext, // If we're running < 0.9 we have to use `terraform get` instead of `init`. if MustConstraint("< 0.9.0").Check(tfVersion) { - prjCtx.Log.Info(fmt.Sprintf("running terraform version %s so will use `get` instead of `init`", tfVersion)) + prjCtx.Log.InfoContext(prjCtx.RequestCtx, fmt.Sprintf("running terraform version %s so will use `get` instead of `init`", tfVersion)) terraformInitVerb = []string{"get"} terraformInitArgs = []string{} } diff --git a/server/core/runtime/init_step_runner_test.go b/server/core/runtime/init_step_runner_test.go index c573e3e367..cedc87a15c 100644 --- a/server/core/runtime/init_step_runner_test.go +++ b/server/core/runtime/init_step_runner_test.go @@ -55,6 +55,7 @@ func TestRun_UsesGetOrInitForRightVersion(t *testing.T) { Workspace: "workspace", RepoRelDir: ".", Log: logger, + RequestCtx: context.TODO(), } tfVersion, _ := version.NewVersion(c.version) @@ -99,6 +100,7 @@ func TestRun_ShowInitOutputOnError(t *testing.T) { Workspace: "workspace", RepoRelDir: ".", Log: logger, + RequestCtx: context.TODO(), }, nil, "/path", map[string]string(nil)) ErrEquals(t, "error", err) Equals(t, "output", output) @@ -160,6 +162,7 @@ func TestRun_InitKeepsUpgradeFlagIfLockFileNotPresent(t *testing.T) { Workspace: "workspace", RepoRelDir: ".", Log: logger, + RequestCtx: context.TODO(), } tfVersion, _ := version.NewVersion("0.14.0") @@ -195,6 +198,7 @@ func TestRun_InitKeepUpgradeFlagIfLockFilePresentAndTFLessThanPoint14(t *testing Workspace: "workspace", RepoRelDir: ".", Log: logger, + RequestCtx: context.TODO(), } tfVersion, _ := version.NewVersion("0.13.0") @@ -263,6 +267,7 @@ func TestRun_InitExtraArgsDeDupe(t *testing.T) { Workspace: "workspace", RepoRelDir: ".", Log: logger, + RequestCtx: context.TODO(), } tfVersion, _ := version.NewVersion("0.10.0") diff --git a/server/core/runtime/plan_step_runner.go b/server/core/runtime/plan_step_runner.go index 63d3822da0..982d5d2dc0 100644 --- a/server/core/runtime/plan_step_runner.go +++ b/server/core/runtime/plan_step_runner.go @@ -249,7 +249,7 @@ func (p *PlanStepRunner) runRemotePlan( // updateStatusF will update the commit status and log any error. updateStatusF := func(status models.CommitStatus, url string) { if err := p.CommitStatusUpdater.UpdateProject(ctx, prjCtx, command.Plan, status, url); err != nil { - prjCtx.Log.Error(fmt.Sprintf("unable to update status: %s", err)) + prjCtx.Log.ErrorContext(prjCtx.RequestCtx, fmt.Sprintf("unable to update status: %s", err)) } } diff --git a/server/core/runtime/policy/conftest_client.go b/server/core/runtime/policy/conftest_client.go index cf4ac73d4d..63e587179e 100644 --- a/server/core/runtime/policy/conftest_client.go +++ b/server/core/runtime/policy/conftest_client.go @@ -168,7 +168,7 @@ func (c *ConfTestExecutorWorkflow) Run(ctx context.Context, prjCtx command.Proje // Let's not fail the whole step because of a single failure. Log and fail silently if err != nil { - prjCtx.Log.Error(fmt.Sprintf("Error resolving policyset %s. err: %s", policySet.Name, err.Error())) + prjCtx.Log.ErrorContext(prjCtx.RequestCtx, fmt.Sprintf("Error resolving policyset %s. err: %s", policySet.Name, err.Error())) continue } @@ -190,7 +190,7 @@ func (c *ConfTestExecutorWorkflow) Run(ctx context.Context, prjCtx command.Proje serializedArgs, err := args.build() if err != nil { - prjCtx.Log.Warn("No policies have been configured") + prjCtx.Log.WarnContext(prjCtx.RequestCtx, "No policies have been configured") return "", nil // TODO: enable when we can pass policies in otherwise e2e tests with policy checks fail // return "", errors.Wrap(err, "building args") diff --git a/server/core/runtime/policy/conftest_client_test.go b/server/core/runtime/policy/conftest_client_test.go index 384b5c3a3e..3b0152b221 100644 --- a/server/core/runtime/policy/conftest_client_test.go +++ b/server/core/runtime/policy/conftest_client_test.go @@ -171,6 +171,7 @@ func TestRun(t *testing.T) { ProjectName: "testproj", Workspace: "default", Log: log, + RequestCtx: context.TODO(), } t.Run("success", func(t *testing.T) { diff --git a/server/core/runtime/run_step_runner.go b/server/core/runtime/run_step_runner.go index 036eed2311..b9bc6fc38c 100644 --- a/server/core/runtime/run_step_runner.go +++ b/server/core/runtime/run_step_runner.go @@ -29,7 +29,7 @@ func (r *RunStepRunner) Run(ctx context.Context, prjCtx command.ProjectContext, err := r.TerraformExecutor.EnsureVersion(prjCtx.Log, tfVersion) if err != nil { err = fmt.Errorf("%s: Downloading terraform Version %s", err, tfVersion.String()) - prjCtx.Log.Error(fmt.Sprintf("error: %s", err)) + prjCtx.Log.ErrorContext(prjCtx.RequestCtx, fmt.Sprintf("error: %s", err)) return "", err } @@ -71,9 +71,9 @@ func (r *RunStepRunner) Run(ctx context.Context, prjCtx command.ProjectContext, if err != nil { err = fmt.Errorf("%s: running %q in %q: \n%s", err, command, path, out) - prjCtx.Log.Error(fmt.Sprintf("error: %s", err)) + prjCtx.Log.ErrorContext(prjCtx.RequestCtx, fmt.Sprintf("error: %s", err)) return "", err } - prjCtx.Log.Info(fmt.Sprintf("successfully ran %q in %q", command, path)) + prjCtx.Log.InfoContext(prjCtx.RequestCtx, fmt.Sprintf("successfully ran %q in %q", command, path)) return string(out), nil } diff --git a/server/core/runtime/run_step_runner_test.go b/server/core/runtime/run_step_runner_test.go index e189f166af..d3f99a9de2 100644 --- a/server/core/runtime/run_step_runner_test.go +++ b/server/core/runtime/run_step_runner_test.go @@ -135,6 +135,7 @@ func TestRunStepRunner_Run(t *testing.T) { Username: "acme-user", }, Log: logger, + RequestCtx: context.TODO(), Workspace: "myworkspace", RepoRelDir: "mydir", TerraformVersion: projVersion, diff --git a/server/core/runtime/steps_runner_test.go b/server/core/runtime/steps_runner_test.go index 627702f43f..b6d6be3eff 100644 --- a/server/core/runtime/steps_runner_test.go +++ b/server/core/runtime/steps_runner_test.go @@ -162,7 +162,8 @@ func TestStepsRuinner_RunEnvSteps(t *testing.T) { ctx := context.Background() prjCtx := command.ProjectContext{ - Log: logging.NewNoopCtxLogger(t), + Log: logging.NewNoopCtxLogger(t), + RequestCtx: context.TODO(), Steps: []valid.Step{ { StepName: "run", diff --git a/server/core/terraform/async_client.go b/server/core/terraform/async_client.go index b368137f48..c9e3da72b7 100644 --- a/server/core/terraform/async_client.go +++ b/server/core/terraform/async_client.go @@ -57,7 +57,7 @@ func (c *AsyncClient) RunCommandAsyncWithInput(ctx context.Context, prjCtx comma cmd, err := c.commandBuilder.Build(v, workspace, path, args) if err != nil { - prjCtx.Log.Error(err.Error()) + prjCtx.Log.ErrorContext(prjCtx.RequestCtx, err.Error()) outCh <- helpers.Line{Err: err} return } @@ -73,7 +73,7 @@ func (c *AsyncClient) RunCommandAsyncWithInput(ctx context.Context, prjCtx comma err = cmd.Start() if err != nil { err = errors.Wrapf(err, "running %q in %q", cmd.String(), path) - prjCtx.Log.Error(err.Error()) + prjCtx.Log.ErrorContext(prjCtx.RequestCtx, err.Error()) outCh <- helpers.Line{Err: err} return } @@ -84,7 +84,7 @@ func (c *AsyncClient) RunCommandAsyncWithInput(ctx context.Context, prjCtx comma for line := range input { _, err := io.WriteString(stdin, line) if err != nil { - prjCtx.Log.Error(errors.Wrapf(err, "writing %q to process", line).Error()) + prjCtx.Log.ErrorContext(prjCtx.RequestCtx, errors.Wrapf(err, "writing %q to process", line).Error()) } } }() @@ -125,10 +125,10 @@ func (c *AsyncClient) RunCommandAsyncWithInput(ctx context.Context, prjCtx comma // We're done now. Send an error if there was one. if err != nil { err = errors.Wrapf(err, "running %q in %q", cmd.String(), path) - prjCtx.Log.Error(err.Error()) + prjCtx.Log.ErrorContext(prjCtx.RequestCtx, err.Error()) outCh <- helpers.Line{Err: err} } else { - prjCtx.Log.Info(fmt.Sprintf("successfully ran %q in %q", cmd.String(), path)) + prjCtx.Log.InfoContext(prjCtx.RequestCtx, fmt.Sprintf("successfully ran %q in %q", cmd.String(), path)) } }() diff --git a/server/core/terraform/async_client_test.go b/server/core/terraform/async_client_test.go index c99a2634b4..0d3411f575 100644 --- a/server/core/terraform/async_client_test.go +++ b/server/core/terraform/async_client_test.go @@ -30,7 +30,8 @@ func TestDefaultClient_RunCommandAsync_Success(t *testing.T) { ctx := context.Background() prjCtx := command.ProjectContext{ - Log: logger, + Log: logger, + RequestCtx: context.TODO(), } mockBuilder := mocks.NewMockcommandBuilder() @@ -59,7 +60,8 @@ func TestDefaultClient_RunCommandAsync_BigOutput(t *testing.T) { ctx := context.Background() prjCtx := command.ProjectContext{ - Log: logger, + Log: logger, + RequestCtx: context.TODO(), } mockBuilder := mocks.NewMockcommandBuilder() projectCmdOutputHandler := jobmocks.NewMockProjectCommandOutputHandler() @@ -107,7 +109,8 @@ func TestDefaultClient_RunCommandAsync_StderrOutput(t *testing.T) { ctx := context.Background() prjCtx := command.ProjectContext{ - Log: logger, + Log: logger, + RequestCtx: context.TODO(), } mockBuilder := mocks.NewMockcommandBuilder() projectCmdOutputHandler := jobmocks.NewMockProjectCommandOutputHandler() @@ -134,7 +137,8 @@ func TestDefaultClient_RunCommandAsync_ExitOne(t *testing.T) { ctx := context.Background() prjCtx := command.ProjectContext{ - Log: logger, + Log: logger, + RequestCtx: context.TODO(), } mockBuilder := mocks.NewMockcommandBuilder() projectCmdOutputHandler := jobmocks.NewMockProjectCommandOutputHandler() @@ -162,7 +166,8 @@ func TestDefaultClient_RunCommandAsync_Input(t *testing.T) { ctx := context.Background() prjCtx := command.ProjectContext{ - Log: logger, + Log: logger, + RequestCtx: context.TODO(), } mockBuilder := mocks.NewMockcommandBuilder() projectCmdOutputHandler := jobmocks.NewMockProjectCommandOutputHandler() diff --git a/server/core/terraform/terraform_client.go b/server/core/terraform/terraform_client.go index d124251ba6..d6938ebbd4 100644 --- a/server/core/terraform/terraform_client.go +++ b/server/core/terraform/terraform_client.go @@ -136,7 +136,6 @@ func NewClientWithVersionCache( } func NewE2ETestClient( - log logging.SimpleLogging, binDir string, cacheDir string, tfeToken string, @@ -259,10 +258,10 @@ func (c *DefaultClient) RunCommandWithVersion(ctx context.Context, prjCtx comman out, err := cmd.CombinedOutput() if err != nil { err = errors.Wrapf(err, "running %q in %q", cmd.String(), path) - prjCtx.Log.Error(err.Error()) + prjCtx.Log.ErrorContext(prjCtx.RequestCtx, err.Error()) return ansi.Strip(string(out)), err } - prjCtx.Log.Info(fmt.Sprintf("successfully ran %q in %q", cmd.String(), path)) + prjCtx.Log.InfoContext(prjCtx.RequestCtx, fmt.Sprintf("successfully ran %q in %q", cmd.String(), 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 8605f50fd3..09e0e57ea5 100644 --- a/server/core/terraform/terraform_client_internal_test.go +++ b/server/core/terraform/terraform_client_internal_test.go @@ -31,7 +31,8 @@ func TestDefaultClient_Synchronous_RunCommandWithVersion(t *testing.T) { ctx := context.Background() prjCtx := command.ProjectContext{ - Log: logger, + RequestCtx: context.TODO(), + Log: logger, BaseRepo: models.Repo{ FullName: "owner/repo", Owner: "owner", @@ -106,7 +107,8 @@ func TestDefaultClient_Synchronous_RunCommandWithVersion_Error(t *testing.T) { ctx := context.Background() prjCtx := command.ProjectContext{ - Log: logger, + RequestCtx: context.TODO(), + Log: logger, BaseRepo: models.Repo{ FullName: "owner/repo", Owner: "owner", diff --git a/server/core/terraform/terraform_client_test.go b/server/core/terraform/terraform_client_test.go index 0480744269..0cfd06725f 100644 --- a/server/core/terraform/terraform_client_test.go +++ b/server/core/terraform/terraform_client_test.go @@ -54,6 +54,7 @@ func TestNewClient_DefaultTFFlagInPath(t *testing.T) { projectCmdOutputHandler := jobmocks.NewMockProjectCommandOutputHandler() ctx := context.Background() prjCtx := command.ProjectContext{ + RequestCtx: context.TODO(), Log: logging.NewNoopCtxLogger(t), Workspace: "default", RepoRelDir: ".", @@ -88,6 +89,7 @@ func TestNewClient_DefaultTFFlagInBinDir(t *testing.T) { projectCmdOutputHandler := jobmocks.NewMockProjectCommandOutputHandler() ctx := context.Background() prjCtx := command.ProjectContext{ + RequestCtx: context.TODO(), Log: logging.NewNoopCtxLogger(t), Workspace: "default", RepoRelDir: ".", diff --git a/server/events/apply_command_runner.go b/server/events/apply_command_runner.go index f19c315d68..2c4f61b42a 100644 --- a/server/events/apply_command_runner.go +++ b/server/events/apply_command_runner.go @@ -59,29 +59,29 @@ func (a *ApplyCommandRunner) Run(ctx *command.Context, cmd *command.Comment) { // raises an error // We will log failure as warning if err != nil { - ctx.Log.Warn(fmt.Sprintf("checking global apply lock: %s", err)) + ctx.Log.WarnContext(ctx.RequestCtx, fmt.Sprintf("checking global apply lock: %s", err)) } if locked { - ctx.Log.Info("ignoring apply command since apply disabled globally") + ctx.Log.InfoContext(ctx.RequestCtx, "ignoring apply command since apply disabled globally") if err := a.vcsClient.CreateComment(baseRepo, pull.Num, applyDisabledComment, command.Apply.String()); err != nil { - ctx.Log.Error(fmt.Sprintf("unable to comment on pull request: %s", err)) + ctx.Log.ErrorContext(ctx.RequestCtx, fmt.Sprintf("unable to comment on pull request: %s", err)) } return } if a.DisableApplyAll && !cmd.IsForSpecificProject() { - ctx.Log.Info("ignoring apply command without flags since apply all is disabled") + ctx.Log.InfoContext(ctx.RequestCtx, "ignoring apply command without flags since apply all is disabled") if err := a.vcsClient.CreateComment(baseRepo, pull.Num, applyAllDisabledComment, command.Apply.String()); err != nil { - ctx.Log.Error(fmt.Sprintf("unable to comment on pull request: %s", err)) + ctx.Log.ErrorContext(ctx.RequestCtx, fmt.Sprintf("unable to comment on pull request: %s", err)) } return } if err = a.commitStatusUpdater.UpdateCombined(context.TODO(), baseRepo, pull, models.PendingCommitStatus, cmd.CommandName()); err != nil { - ctx.Log.Warn(fmt.Sprintf("unable to update commit status: %s", err)) + ctx.Log.WarnContext(ctx.RequestCtx, fmt.Sprintf("unable to update commit status: %s", err)) } // Get the mergeable status before we set any build statuses of our own. @@ -95,7 +95,7 @@ func (a *ApplyCommandRunner) Run(ctx *command.Context, cmd *command.Comment) { // We want to continue because not all apply's will need this status, // only if they rely on the mergeability requirement. // All PullRequestStatus fields are set to false by default when error. - ctx.Log.Warn(fmt.Sprintf("unable to get pull request status: %s. Continuing with mergeable and approved assumed false", err)) + ctx.Log.WarnContext(ctx.RequestCtx, fmt.Sprintf("unable to get pull request status: %s. Continuing with mergeable and approved assumed false", err)) } var projectCmds []command.ProjectContext @@ -103,7 +103,7 @@ func (a *ApplyCommandRunner) Run(ctx *command.Context, cmd *command.Comment) { if err != nil { if statusErr := a.commitStatusUpdater.UpdateCombined(context.TODO(), ctx.Pull.BaseRepo, ctx.Pull, models.FailedCommitStatus, cmd.CommandName()); statusErr != nil { - ctx.Log.Warn(fmt.Sprintf("unable to update commit status: %s", statusErr)) + ctx.Log.WarnContext(ctx.RequestCtx, fmt.Sprintf("unable to update commit status: %s", statusErr)) } a.pullUpdater.UpdatePull(ctx, cmd, command.Result{Error: err}) return @@ -112,7 +112,7 @@ func (a *ApplyCommandRunner) Run(ctx *command.Context, cmd *command.Comment) { // Only run commands in parallel if enabled var result command.Result if a.isParallelEnabled(projectCmds) { - ctx.Log.Info(fmt.Sprintf("Running applies in parallel")) + ctx.Log.InfoContext(ctx.RequestCtx, fmt.Sprintf("Running applies in parallel")) result = runProjectCmdsParallel(projectCmds, a.prjCmdRunner.Apply, a.parallelPoolSize) } else { result = runProjectCmds(projectCmds, a.prjCmdRunner.Apply) @@ -125,7 +125,7 @@ func (a *ApplyCommandRunner) Run(ctx *command.Context, cmd *command.Comment) { pullStatus, err := a.dbUpdater.updateDB(ctx, pull, result.ProjectResults) if err != nil { - ctx.Log.Error(fmt.Sprintf("writing results: %s", err)) + ctx.Log.ErrorContext(ctx.RequestCtx, fmt.Sprintf("writing results: %s", err)) return } @@ -167,7 +167,7 @@ func (a *ApplyCommandRunner) updateCommitStatus(ctx *command.Context, pullStatus numSuccess, len(pullStatus.Projects), ); err != nil { - ctx.Log.Warn(fmt.Sprintf("unable to update commit status: %s", err)) + ctx.Log.WarnContext(ctx.RequestCtx, fmt.Sprintf("unable to update commit status: %s", err)) } } diff --git a/server/events/apply_command_runner_test.go b/server/events/apply_command_runner_test.go index c59efed1e5..087e7b0c57 100644 --- a/server/events/apply_command_runner_test.go +++ b/server/events/apply_command_runner_test.go @@ -1,6 +1,7 @@ package events_test import ( + "context" "errors" "testing" @@ -50,12 +51,13 @@ func TestApplyCommandRunner_IsLocked(t *testing.T) { scopeNull, _, _ := metrics.NewLoggingScope(logger, "atlantis") modelPull := models.PullRequest{BaseRepo: fixtures.GithubRepo, State: models.OpenPullState, Num: fixtures.Pull.Num} ctx := &command.Context{ - User: fixtures.User, - Log: logger, - Pull: modelPull, - HeadRepo: fixtures.GithubRepo, - Trigger: command.CommentTrigger, - Scope: scopeNull, + User: fixtures.User, + Log: logger, + Pull: modelPull, + HeadRepo: fixtures.GithubRepo, + Trigger: command.CommentTrigger, + Scope: scopeNull, + RequestCtx: context.TODO(), } When(applyLockChecker.CheckApplyLock()).ThenReturn(locking.ApplyCommandLock{Locked: c.ApplyLocked}, c.ApplyLockError) diff --git a/server/events/approve_policies_command_runner.go b/server/events/approve_policies_command_runner.go index df6dee94eb..316eab65ca 100644 --- a/server/events/approve_policies_command_runner.go +++ b/server/events/approve_policies_command_runner.go @@ -37,25 +37,25 @@ func (a *ApprovePoliciesCommandRunner) Run(ctx *command.Context, cmd *command.Co pull := ctx.Pull if err := a.commitStatusUpdater.UpdateCombined(context.TODO(), baseRepo, pull, models.PendingCommitStatus, command.PolicyCheck); err != nil { - ctx.Log.Warn(fmt.Sprintf("unable to update commit status: %s", err)) + ctx.Log.WarnContext(ctx.RequestCtx, fmt.Sprintf("unable to update commit status: %s", err)) } projectCmds, err := a.prjCmdBuilder.BuildApprovePoliciesCommands(ctx, cmd) if err != nil { if statusErr := a.commitStatusUpdater.UpdateCombined(context.TODO(), ctx.Pull.BaseRepo, ctx.Pull, models.FailedCommitStatus, command.PolicyCheck); statusErr != nil { - ctx.Log.Warn(fmt.Sprintf("unable to update commit status: %s", statusErr)) + ctx.Log.WarnContext(ctx.RequestCtx, fmt.Sprintf("unable to update commit status: %s", statusErr)) } a.pullUpdater.UpdatePull(ctx, cmd, command.Result{Error: err}) return } if len(projectCmds) == 0 { - ctx.Log.Info(fmt.Sprintf("determined there was no project to run approve_policies in")) + ctx.Log.InfoContext(ctx.RequestCtx, fmt.Sprintf("determined there was no project to run approve_policies in")) // If there were no projects modified, we set successful commit statuses // with 0/0 projects approve_policies successfully because some users require // the Atlantis status to be passing for all pull requests. if err := a.commitStatusUpdater.UpdateCombinedCount(context.TODO(), ctx.Pull.BaseRepo, ctx.Pull, models.SuccessCommitStatus, command.PolicyCheck, 0, 0); err != nil { - ctx.Log.Warn(fmt.Sprintf("unable to update commit status: %s", err)) + ctx.Log.WarnContext(ctx.RequestCtx, fmt.Sprintf("unable to update commit status: %s", err)) } return } @@ -70,7 +70,7 @@ func (a *ApprovePoliciesCommandRunner) Run(ctx *command.Context, cmd *command.Co pullStatus, err := a.dbUpdater.updateDB(ctx, pull, result.ProjectResults) if err != nil { - ctx.Log.Error(fmt.Sprintf("writing results: %s", err)) + ctx.Log.ErrorContext(ctx.RequestCtx, fmt.Sprintf("writing results: %s", err)) return } @@ -109,6 +109,6 @@ func (a *ApprovePoliciesCommandRunner) updateCommitStatus(ctx *command.Context, } if err := a.commitStatusUpdater.UpdateCombinedCount(context.TODO(), ctx.Pull.BaseRepo, ctx.Pull, status, command.PolicyCheck, numSuccess, len(pullStatus.Projects)); err != nil { - ctx.Log.Warn(fmt.Sprintf("unable to update commit status: %s", err)) + ctx.Log.WarnContext(ctx.RequestCtx, fmt.Sprintf("unable to update commit status: %s", err)) } } diff --git a/server/events/command/context.go b/server/events/command/context.go index 1defb80930..7c140d80a0 100644 --- a/server/events/command/context.go +++ b/server/events/command/context.go @@ -1,6 +1,7 @@ package command import ( + "context" "time" "github.com/runatlantis/atlantis/server/events/models" @@ -42,4 +43,5 @@ type Context struct { // Time Atlantis received VCS event, triggering command to be executed TriggerTimestamp time.Time + RequestCtx context.Context } diff --git a/server/events/command/plan/runner.go b/server/events/command/plan/runner.go index 29fb9c6d85..be5b26c23d 100644 --- a/server/events/command/plan/runner.go +++ b/server/events/command/plan/runner.go @@ -18,6 +18,6 @@ type Runner struct { func (r *Runner) Run(ctx *command.Context, cmd *command.Comment) { if err := r.vcsClient.CreateComment(ctx.Pull.BaseRepo, ctx.Pull.Num, "I'm a platform mode plan runner", command.Plan.String()); err != nil { - ctx.Log.Error(fmt.Sprintf("unable to comment: %s", err)) + ctx.Log.ErrorContext(ctx.RequestCtx, fmt.Sprintf("unable to comment: %s", err)) } } diff --git a/server/events/command/policies/runner.go b/server/events/command/policies/runner.go index 43bf09a6e8..328bfd10f0 100644 --- a/server/events/command/policies/runner.go +++ b/server/events/command/policies/runner.go @@ -18,6 +18,6 @@ type Runner struct { func (r *Runner) Run(ctx *command.Context, cmd *command.Comment) { if err := r.vcsClient.CreateComment(ctx.Pull.BaseRepo, ctx.Pull.Num, "I'm a platform mode approve_policies runner", command.ApprovePolicies.String()); err != nil { - ctx.Log.Error(fmt.Sprintf("unable to comment: %s", err)) + ctx.Log.ErrorContext(ctx.RequestCtx, fmt.Sprintf("unable to comment: %s", err)) } } diff --git a/server/events/command/project_context.go b/server/events/command/project_context.go index 0f658c896f..a32a05a251 100644 --- a/server/events/command/project_context.go +++ b/server/events/command/project_context.go @@ -1,6 +1,7 @@ package command import ( + "context" "fmt" "path/filepath" "strings" @@ -74,6 +75,7 @@ func NewProjectContext( Tags: projCfg.Tags, PullReqStatus: pullStatus, JobID: uuid.New().String(), + RequestCtx: ctx.RequestCtx, } } @@ -148,6 +150,8 @@ type ProjectContext struct { PolicySets valid.PolicySets // UUID for atlantis logs JobID string + // RequestCtx is the context generated when request is first received from VCS + RequestCtx context.Context } // ProjectCloneDir creates relative path to clone the repo to. If we are running diff --git a/server/events/command_runner.go b/server/events/command_runner.go index 32791dc4db..2c4cbf6a56 100644 --- a/server/events/command_runner.go +++ b/server/events/command_runner.go @@ -103,7 +103,7 @@ func (c *DefaultCommandRunner) RunAutoplanCommand(ctx context.Context, baseRepo } defer c.Drainer.OpDone() - ctx = newCtx(ctx, baseRepo.FullName, pull.Num) + //ctx = newCtx(ctx, baseRepo.FullName, pull.Num) defer c.logPanics(ctx) status, err := c.PullStatusFetcher.GetPullStatus(pull) @@ -124,8 +124,9 @@ func (c *DefaultCommandRunner) RunAutoplanCommand(ctx context.Context, baseRepo PullStatus: status, Trigger: command.AutoTrigger, TriggerTimestamp: timestamp, + RequestCtx: ctx, } - if !c.validateCtxAndComment(ctx, cmdCtx) { + if !c.validateCtxAndComment(cmdCtx) { return } if c.DisableAutoplan { @@ -161,7 +162,7 @@ func (c *DefaultCommandRunner) RunCommentCommand(ctx context.Context, baseRepo m } defer c.Drainer.OpDone() - ctx = newCtx(ctx, baseRepo.FullName, pullNum) + //ctx = newCtx(ctx, baseRepo.FullName, pullNum) defer c.logPanics(ctx) scope := c.StatsScope.SubScope("comment") @@ -187,9 +188,10 @@ func (c *DefaultCommandRunner) RunCommentCommand(ctx context.Context, baseRepo m Trigger: command.CommentTrigger, Scope: scope, TriggerTimestamp: timestamp, + RequestCtx: ctx, } - if !c.validateCtxAndComment(ctx, cmdCtx) { + if !c.validateCtxAndComment(cmdCtx) { return } @@ -214,26 +216,26 @@ func newCtx(ctx context.Context, repoFullName string, pullNum int) context.Conte return context.WithValue(ctx, logging.PullNumKey, strconv.Itoa(pullNum)) } -func (c *DefaultCommandRunner) validateCtxAndComment(ctx context.Context, cmdCtx *command.Context) bool { +func (c *DefaultCommandRunner) validateCtxAndComment(cmdCtx *command.Context) bool { if cmdCtx.HeadRepo.Owner != cmdCtx.Pull.BaseRepo.Owner { - c.Logger.InfoContext(ctx, "command was run on a fork pull request which is disallowed") + c.Logger.InfoContext(cmdCtx.RequestCtx, "command was run on a fork pull request which is disallowed") if err := c.VCSClient.CreateComment(cmdCtx.Pull.BaseRepo, cmdCtx.Pull.Num, "Atlantis commands can't be run on fork pull requests.", ""); err != nil { - c.Logger.ErrorContext(ctx, err.Error()) + c.Logger.ErrorContext(cmdCtx.RequestCtx, err.Error()) } return false } if cmdCtx.Pull.State != models.OpenPullState { - c.Logger.InfoContext(ctx, "command was run on closed pull request") + c.Logger.InfoContext(cmdCtx.RequestCtx, "command was run on closed pull request") if err := c.VCSClient.CreateComment(cmdCtx.Pull.BaseRepo, cmdCtx.Pull.Num, "Atlantis commands can't be run on closed pull requests", ""); err != nil { - c.Logger.ErrorContext(ctx, err.Error()) + c.Logger.ErrorContext(cmdCtx.RequestCtx, err.Error()) } return false } repo := c.GlobalCfg.MatchingRepo(cmdCtx.Pull.BaseRepo.ID()) if !repo.BranchMatches(cmdCtx.Pull.BaseBranch) { - c.Logger.InfoContext(ctx, "command was run on a pull request which doesn't match base branches") + c.Logger.InfoContext(cmdCtx.RequestCtx, "command was run on a pull request which doesn't match base branches") // just ignore it to allow us to use any git workflows without malicious intentions. return false } diff --git a/server/events/delete_lock_command.go b/server/events/delete_lock_command.go index 5c276d7cc8..dbc166df1c 100644 --- a/server/events/delete_lock_command.go +++ b/server/events/delete_lock_command.go @@ -66,16 +66,24 @@ func (l *DefaultDeleteLockCommand) deleteWorkingDir(lock models.ProjectLock) { return } unlock, err := l.WorkingDirLocker.TryLock(lock.Pull.BaseRepo.FullName, lock.Pull.Num, lock.Workspace) + logFields := map[string]interface{}{ + "repository": lock.Pull.BaseRepo.FullName, + "pull-num": lock.Pull.Num, + "workspace": lock.Workspace, + } if err != nil { - l.Logger.Error(fmt.Sprintf("unable to obtain working dir lock when trying to delete old plans: %s", err)) + l.Logger.Error( + fmt.Sprintf("unable to obtain working dir lock when trying to delete old plans: %s", err), + logFields, + ) } else { defer unlock() // nolint: vetshadow if err := l.WorkingDir.DeleteForWorkspace(lock.Pull.BaseRepo, lock.Pull, lock.Workspace); err != nil { - l.Logger.Error(fmt.Sprintf("unable to delete workspace: %s", err)) + l.Logger.Error(fmt.Sprintf("unable to delete workspace: %s", err), logFields) } } if err := l.DB.UpdateProjectStatus(lock.Pull, lock.Workspace, lock.Project.Path, models.DiscardedPlanStatus); err != nil { - l.Logger.Error(fmt.Sprintf("unable to delete project status: %s", err)) + l.Logger.Error(fmt.Sprintf("unable to delete project status: %s", err), logFields) } } diff --git a/server/events/github_app_working_dir.go b/server/events/github_app_working_dir.go index 3cb3a19790..72b3b7e7b9 100644 --- a/server/events/github_app_working_dir.go +++ b/server/events/github_app_working_dir.go @@ -23,7 +23,11 @@ type GithubAppWorkingDir struct { // Clone writes a fresh token for Github App authentication func (g *GithubAppWorkingDir) Clone(log logging.Logger, headRepo models.Repo, p models.PullRequest, workspace string) (string, bool, error) { - log.Info("Refreshing git tokens for Github App") + log.Info("Refreshing git tokens for Github App", map[string]interface{}{ + "repository": headRepo.FullName, + "pull-num": p.Num, + "workspace": workspace, + }) token, err := g.Credentials.GetToken() if err != nil { diff --git a/server/events/instrumented_project_command_builder.go b/server/events/instrumented_project_command_builder.go index 09e6eee292..9ccaebbbd1 100644 --- a/server/events/instrumented_project_command_builder.go +++ b/server/events/instrumented_project_command_builder.go @@ -25,7 +25,7 @@ func (b *InstrumentedProjectCommandBuilder) BuildApplyCommands(ctx *command.Cont if err != nil { executionError.Inc(1) - b.Logger.Error(fmt.Sprintf("Error building apply commands: %s", err)) + b.Logger.ErrorContext(ctx.RequestCtx, fmt.Sprintf("Error building apply commands: %s", err)) } else { executionSuccess.Inc(1) } @@ -46,7 +46,7 @@ func (b *InstrumentedProjectCommandBuilder) BuildAutoplanCommands(ctx *command.C if err != nil { executionError.Inc(1) - b.Logger.Error(fmt.Sprintf("Error building auto plan commands: %s", err)) + b.Logger.ErrorContext(ctx.RequestCtx, fmt.Sprintf("Error building auto plan commands: %s", err)) } else { executionSuccess.Inc(1) } @@ -67,7 +67,7 @@ func (b *InstrumentedProjectCommandBuilder) BuildPlanCommands(ctx *command.Conte if err != nil { executionError.Inc(1) - b.Logger.Error(fmt.Sprintf("Error building plan commands: %s", err)) + b.Logger.ErrorContext(ctx.RequestCtx, fmt.Sprintf("Error building plan commands: %s", err)) } else { executionSuccess.Inc(1) } diff --git a/server/events/instrumented_project_command_runner.go b/server/events/instrumented_project_command_runner.go index 8664b70c0a..cfdcac4334 100644 --- a/server/events/instrumented_project_command_runner.go +++ b/server/events/instrumented_project_command_runner.go @@ -41,17 +41,17 @@ func RunAndEmitStats(commandName string, ctx command.ProjectContext, execute fun if result.Error != nil { executionError.Inc(1) - logger.Error(fmt.Sprintf("Error running %s operation: %s", commandName, result.Error.Error()), map[string]interface{}{"project": ctx.ProjectName}) + logger.ErrorContext(ctx.RequestCtx, fmt.Sprintf("Error running %s operation: %s", commandName, result.Error.Error()), map[string]interface{}{"project": ctx.ProjectName}) return result } if result.Failure != "" { executionFailure.Inc(1) - logger.Error(fmt.Sprintf("Failure running %s operation: %s", commandName, result.Failure), map[string]interface{}{"project": ctx.ProjectName}) + logger.ErrorContext(ctx.RequestCtx, fmt.Sprintf("Failure running %s operation: %s", commandName, result.Failure), map[string]interface{}{"project": ctx.ProjectName}) return result } - logger.Info(fmt.Sprintf("%s success. output available at: %s", commandName, ctx.Pull.URL), map[string]interface{}{"project": ctx.ProjectName}) + logger.InfoContext(ctx.RequestCtx, fmt.Sprintf("%s success. output available at: %s", commandName, ctx.Pull.URL), map[string]interface{}{"project": ctx.ProjectName}) executionSuccess.Inc(1) return result diff --git a/server/events/mocks/mock_project_lock.go b/server/events/mocks/mock_project_lock.go index 4cadfc9f34..12b64c4290 100644 --- a/server/events/mocks/mock_project_lock.go +++ b/server/events/mocks/mock_project_lock.go @@ -4,6 +4,7 @@ package mocks import ( + context "context" pegomock "github.com/petergtz/pegomock" events "github.com/runatlantis/atlantis/server/events" models "github.com/runatlantis/atlantis/server/events/models" @@ -27,11 +28,11 @@ func NewMockProjectLocker(options ...pegomock.Option) *MockProjectLocker { func (mock *MockProjectLocker) SetFailHandler(fh pegomock.FailHandler) { mock.fail = fh } func (mock *MockProjectLocker) FailHandler() pegomock.FailHandler { return mock.fail } -func (mock *MockProjectLocker) TryLock(log logging.Logger, pull models.PullRequest, user models.User, workspace string, project models.Project) (*events.TryLockResponse, error) { +func (mock *MockProjectLocker) TryLock(log logging.Logger, requestCtx context.Context, pull models.PullRequest, user models.User, workspace string, project models.Project) (*events.TryLockResponse, error) { if mock == nil { panic("mock must not be nil. Use myMock := NewMockProjectLocker().") } - params := []pegomock.Param{log, pull, user, workspace, project} + params := []pegomock.Param{log, requestCtx, pull, user, workspace, project} result := pegomock.GetGenericMockFrom(mock).Invoke("TryLock", params, []reflect.Type{reflect.TypeOf((**events.TryLockResponse)(nil)).Elem(), reflect.TypeOf((*error)(nil)).Elem()}) var ret0 *events.TryLockResponse var ret1 error @@ -83,8 +84,8 @@ type VerifierMockProjectLocker struct { timeout time.Duration } -func (verifier *VerifierMockProjectLocker) TryLock(log logging.Logger, pull models.PullRequest, user models.User, workspace string, project models.Project) *MockProjectLocker_TryLock_OngoingVerification { - params := []pegomock.Param{log, pull, user, workspace, project} +func (verifier *VerifierMockProjectLocker) TryLock(log logging.Logger, requestCtx context.Context, pull models.PullRequest, user models.User, workspace string, project models.Project) *MockProjectLocker_TryLock_OngoingVerification { + params := []pegomock.Param{log, requestCtx, pull, user, workspace, project} methodInvocations := pegomock.GetGenericMockFrom(verifier.mock).Verify(verifier.inOrderContext, verifier.invocationCountMatcher, "TryLock", params, verifier.timeout) return &MockProjectLocker_TryLock_OngoingVerification{mock: verifier.mock, methodInvocations: methodInvocations} } @@ -94,33 +95,37 @@ type MockProjectLocker_TryLock_OngoingVerification struct { methodInvocations []pegomock.MethodInvocation } -func (c *MockProjectLocker_TryLock_OngoingVerification) GetCapturedArguments() (logging.Logger, models.PullRequest, models.User, string, models.Project) { - log, pull, user, workspace, project := c.GetAllCapturedArguments() - return log[len(log)-1], pull[len(pull)-1], user[len(user)-1], workspace[len(workspace)-1], project[len(project)-1] +func (c *MockProjectLocker_TryLock_OngoingVerification) GetCapturedArguments() (logging.Logger, context.Context, models.PullRequest, models.User, string, models.Project) { + log, requestCtx, pull, user, workspace, project := c.GetAllCapturedArguments() + return log[len(log)-1], requestCtx[len(requestCtx)-1], pull[len(pull)-1], user[len(user)-1], workspace[len(workspace)-1], project[len(project)-1] } -func (c *MockProjectLocker_TryLock_OngoingVerification) GetAllCapturedArguments() (_param0 []logging.Logger, _param1 []models.PullRequest, _param2 []models.User, _param3 []string, _param4 []models.Project) { +func (c *MockProjectLocker_TryLock_OngoingVerification) GetAllCapturedArguments() (_param0 []logging.Logger, _param1 []context.Context, _param2 []models.PullRequest, _param3 []models.User, _param4 []string, _param5 []models.Project) { params := pegomock.GetGenericMockFrom(c.mock).GetInvocationParams(c.methodInvocations) if len(params) > 0 { _param0 = make([]logging.Logger, len(c.methodInvocations)) for u, param := range params[0] { _param0[u] = param.(logging.Logger) } - _param1 = make([]models.PullRequest, len(c.methodInvocations)) + _param1 = make([]context.Context, len(c.methodInvocations)) for u, param := range params[1] { - _param1[u] = param.(models.PullRequest) + _param1[u] = param.(context.Context) } - _param2 = make([]models.User, len(c.methodInvocations)) + _param2 = make([]models.PullRequest, len(c.methodInvocations)) for u, param := range params[2] { - _param2[u] = param.(models.User) + _param2[u] = param.(models.PullRequest) } - _param3 = make([]string, len(c.methodInvocations)) + _param3 = make([]models.User, len(c.methodInvocations)) for u, param := range params[3] { - _param3[u] = param.(string) + _param3[u] = param.(models.User) } - _param4 = make([]models.Project, len(c.methodInvocations)) + _param4 = make([]string, len(c.methodInvocations)) for u, param := range params[4] { - _param4[u] = param.(models.Project) + _param4[u] = param.(string) + } + _param5 = make([]models.Project, len(c.methodInvocations)) + for u, param := range params[5] { + _param5[u] = param.(models.Project) } } return diff --git a/server/events/plan_command_runner.go b/server/events/plan_command_runner.go index 5259e67021..b687008869 100644 --- a/server/events/plan_command_runner.go +++ b/server/events/plan_command_runner.go @@ -55,7 +55,7 @@ func (p *PlanCommandRunner) runAutoplan(ctx *command.Context) { projectCmds, err := p.prjCmdBuilder.BuildAutoplanCommands(ctx) if err != nil { if statusErr := p.commitStatusUpdater.UpdateCombined(context.TODO(), baseRepo, pull, models.FailedCommitStatus, command.Plan); statusErr != nil { - ctx.Log.Warn(fmt.Sprintf("unable to update commit status: %s", statusErr)) + ctx.Log.WarnContext(ctx.RequestCtx, fmt.Sprintf("unable to update commit status: %s", statusErr)) } p.pullUpdater.UpdatePull(ctx, AutoplanCommand{}, command.Result{Error: err}) return @@ -64,31 +64,31 @@ func (p *PlanCommandRunner) runAutoplan(ctx *command.Context) { projectCmds, policyCheckCmds := p.partitionProjectCmds(ctx, projectCmds) if len(projectCmds) == 0 { - ctx.Log.Info("determined there was no project to run plan in") + ctx.Log.InfoContext(ctx.RequestCtx, "determined there was no project to run plan in") // If there were no projects modified, we set successful commit statuses // with 0/0 projects planned/policy_checked/applied successfully because some users require // the Atlantis status to be passing for all pull requests. if err := p.commitStatusUpdater.UpdateCombinedCount(context.TODO(), baseRepo, pull, models.SuccessCommitStatus, command.Plan, 0, 0); err != nil { - ctx.Log.Warn(fmt.Sprintf("unable to update commit status: %s", err)) + ctx.Log.WarnContext(ctx.RequestCtx, fmt.Sprintf("unable to update commit status: %s", err)) } if err := p.commitStatusUpdater.UpdateCombinedCount(context.TODO(), baseRepo, pull, models.SuccessCommitStatus, command.PolicyCheck, 0, 0); err != nil { - ctx.Log.Warn(fmt.Sprintf("unable to update commit status: %s", err)) + ctx.Log.WarnContext(ctx.RequestCtx, fmt.Sprintf("unable to update commit status: %s", err)) } if err := p.commitStatusUpdater.UpdateCombinedCount(context.TODO(), baseRepo, pull, models.SuccessCommitStatus, command.Apply, 0, 0); err != nil { - ctx.Log.Warn(fmt.Sprintf("unable to update commit status: %s", err)) + ctx.Log.WarnContext(ctx.RequestCtx, fmt.Sprintf("unable to update commit status: %s", err)) } return } // At this point we are sure Atlantis has work to do, so set commit status to pending if err := p.commitStatusUpdater.UpdateCombined(context.TODO(), ctx.Pull.BaseRepo, ctx.Pull, models.PendingCommitStatus, command.Plan); err != nil { - ctx.Log.Warn(fmt.Sprintf("unable to update commit status: %s", err)) + ctx.Log.WarnContext(ctx.RequestCtx, fmt.Sprintf("unable to update commit status: %s", err)) } // Only run commands in parallel if enabled var result command.Result if p.isParallelEnabled(projectCmds) { - ctx.Log.Info("Running plans in parallel") + ctx.Log.InfoContext(ctx.RequestCtx, "Running plans in parallel") result = runProjectCmdsParallel(projectCmds, p.prjCmdRunner.Plan, p.parallelPoolSize) } else { result = runProjectCmds(projectCmds, p.prjCmdRunner.Plan) @@ -98,7 +98,7 @@ func (p *PlanCommandRunner) runAutoplan(ctx *command.Context) { pullStatus, err := p.dbUpdater.updateDB(ctx, ctx.Pull, result.ProjectResults) if err != nil { - ctx.Log.Error(fmt.Sprintf("writing results: %s", err)) + ctx.Log.ErrorContext(ctx.RequestCtx, fmt.Sprintf("writing results: %s", err)) } p.updateCommitStatus(ctx, pullStatus) @@ -106,7 +106,7 @@ func (p *PlanCommandRunner) runAutoplan(ctx *command.Context) { // Check if there are any planned projects and if there are any errors or if plans are being deleted if len(policyCheckCmds) > 0 && !result.HasErrors() { // Run policy_check command - ctx.Log.Info("Running policy_checks for all plans") + ctx.Log.InfoContext(ctx.RequestCtx, "Running policy_checks for all plans") // refresh ctx's view of pull status since we just wrote to it. // realistically each command should refresh this at the start, @@ -124,13 +124,13 @@ func (p *PlanCommandRunner) run(ctx *command.Context, cmd *command.Comment) { pull := ctx.Pull if err = p.commitStatusUpdater.UpdateCombined(context.TODO(), baseRepo, pull, models.PendingCommitStatus, command.Plan); err != nil { - ctx.Log.Warn(fmt.Sprintf("unable to update commit status: %s", err)) + ctx.Log.WarnContext(ctx.RequestCtx, fmt.Sprintf("unable to update commit status: %s", err)) } projectCmds, err := p.prjCmdBuilder.BuildPlanCommands(ctx, cmd) if err != nil { if statusErr := p.commitStatusUpdater.UpdateCombined(context.TODO(), ctx.Pull.BaseRepo, ctx.Pull, models.FailedCommitStatus, command.Plan); statusErr != nil { - ctx.Log.Warn(fmt.Sprintf("unable to update commit status: %s", statusErr)) + ctx.Log.WarnContext(ctx.RequestCtx, fmt.Sprintf("unable to update commit status: %s", statusErr)) } p.pullUpdater.UpdatePull(ctx, cmd, command.Result{Error: err}) return @@ -141,7 +141,7 @@ func (p *PlanCommandRunner) run(ctx *command.Context, cmd *command.Comment) { // Only run commands in parallel if enabled var result command.Result if p.isParallelEnabled(projectCmds) { - ctx.Log.Info(fmt.Sprintf("Running applies in parallel")) + ctx.Log.InfoContext(ctx.RequestCtx, fmt.Sprintf("Running applies in parallel")) result = runProjectCmdsParallel(projectCmds, p.prjCmdRunner.Plan, p.parallelPoolSize) } else { result = runProjectCmds(projectCmds, p.prjCmdRunner.Plan) @@ -154,7 +154,7 @@ func (p *PlanCommandRunner) run(ctx *command.Context, cmd *command.Comment) { pullStatus, err := p.dbUpdater.updateDB(ctx, pull, result.ProjectResults) if err != nil { - ctx.Log.Error(fmt.Sprintf("writing results: %s", err)) + ctx.Log.ErrorContext(ctx.RequestCtx, fmt.Sprintf("writing results: %s", err)) return } @@ -163,7 +163,7 @@ func (p *PlanCommandRunner) run(ctx *command.Context, cmd *command.Comment) { // Runs policy checks step after all plans are successful. // This step does not approve any policies that require approval. if len(result.ProjectResults) > 0 && !result.HasErrors() { - ctx.Log.Info(fmt.Sprintf("Running policy check for %s", cmd.String())) + ctx.Log.InfoContext(ctx.RequestCtx, fmt.Sprintf("Running policy check for %s", cmd.String())) p.policyCheckCommandRunner.Run(ctx, policyCheckCmds) } } @@ -200,7 +200,7 @@ func (p *PlanCommandRunner) updateCommitStatus(ctx *command.Context, pullStatus numSuccess, len(pullStatus.Projects), ); err != nil { - ctx.Log.Warn(fmt.Sprintf("unable to update commit status: %s", err)) + ctx.Log.WarnContext(ctx.RequestCtx, fmt.Sprintf("unable to update commit status: %s", err)) } } @@ -208,10 +208,10 @@ func (p *PlanCommandRunner) updateCommitStatus(ctx *command.Context, pullStatus func (p *PlanCommandRunner) deletePlans(ctx *command.Context) { pullDir, err := p.workingDir.GetPullDir(ctx.Pull.BaseRepo, ctx.Pull) if err != nil { - ctx.Log.Error(fmt.Sprintf("getting pull dir: %s", err)) + ctx.Log.ErrorContext(ctx.RequestCtx, fmt.Sprintf("getting pull dir: %s", err)) } if err := p.pendingPlanFinder.DeletePlans(pullDir); err != nil { - ctx.Log.Error(fmt.Sprintf("deleting pending plans: %s", err)) + ctx.Log.ErrorContext(ctx.RequestCtx, fmt.Sprintf("deleting pending plans: %s", err)) } } @@ -229,7 +229,7 @@ func (p *PlanCommandRunner) partitionProjectCmds( case command.PolicyCheck: policyCheckCmds = append(policyCheckCmds, cmd) default: - ctx.Log.Error(fmt.Sprintf("%s is not supported", cmd.CommandName)) + ctx.Log.ErrorContext(ctx.RequestCtx, fmt.Sprintf("%s is not supported", cmd.CommandName)) } } return diff --git a/server/events/policy_check_command_runner.go b/server/events/policy_check_command_runner.go index 218717fed5..e36597567a 100644 --- a/server/events/policy_check_command_runner.go +++ b/server/events/policy_check_command_runner.go @@ -34,24 +34,24 @@ type PolicyCheckCommandRunner struct { func (p *PolicyCheckCommandRunner) Run(ctx *command.Context, cmds []command.ProjectContext) { if len(cmds) == 0 { - ctx.Log.Info("no projects to run policy_check in") + ctx.Log.InfoContext(ctx.RequestCtx, "no projects to run policy_check in") // If there were no projects modified, we set successful commit statuses // with 0/0 projects policy_checked successfully because some users require // the Atlantis status to be passing for all pull requests. if err := p.commitStatusUpdater.UpdateCombinedCount(context.TODO(), ctx.Pull.BaseRepo, ctx.Pull, models.SuccessCommitStatus, command.PolicyCheck, 0, 0); err != nil { - ctx.Log.Warn(fmt.Sprintf("unable to update commit status: %s", err)) + ctx.Log.WarnContext(ctx.RequestCtx, fmt.Sprintf("unable to update commit status: %s", err)) } return } // So set policy_check commit status to pending if err := p.commitStatusUpdater.UpdateCombined(context.TODO(), ctx.Pull.BaseRepo, ctx.Pull, models.PendingCommitStatus, command.PolicyCheck); err != nil { - ctx.Log.Warn(fmt.Sprintf("unable to update commit status: %s", err)) + ctx.Log.WarnContext(ctx.RequestCtx, fmt.Sprintf("unable to update commit status: %s", err)) } var result command.Result if p.isParallelEnabled(cmds) { - ctx.Log.Info("Running policy_checks in parallel") + ctx.Log.InfoContext(ctx.RequestCtx, "Running policy_checks in parallel") result = runProjectCmdsParallel(cmds, p.prjCmdRunner.PolicyCheck, p.parallelPoolSize) } else { result = runProjectCmds(cmds, p.prjCmdRunner.PolicyCheck) @@ -61,7 +61,7 @@ func (p *PolicyCheckCommandRunner) Run(ctx *command.Context, cmds []command.Proj pullStatus, err := p.dbUpdater.updateDB(ctx, ctx.Pull, result.ProjectResults) if err != nil { - ctx.Log.Error(fmt.Sprintf("writing results: %s", err)) + ctx.Log.ErrorContext(ctx.RequestCtx, fmt.Sprintf("writing results: %s", err)) } p.updateCommitStatus(ctx, pullStatus) @@ -80,7 +80,7 @@ func (p *PolicyCheckCommandRunner) updateCommitStatus(ctx *command.Context, pull } if err := p.commitStatusUpdater.UpdateCombinedCount(context.TODO(), ctx.Pull.BaseRepo, ctx.Pull, status, command.PolicyCheck, numSuccess, len(pullStatus.Projects)); err != nil { - ctx.Log.Warn(fmt.Sprintf("unable to update commit status: %s", err)) + ctx.Log.WarnContext(ctx.RequestCtx, fmt.Sprintf("unable to update commit status: %s", err)) } } diff --git a/server/events/project_command_builder.go b/server/events/project_command_builder.go index 8fc93dd600..020dd1a6bc 100644 --- a/server/events/project_command_builder.go +++ b/server/events/project_command_builder.go @@ -183,7 +183,7 @@ func (p *DefaultProjectCommandBuilder) buildPlanAllCommands(ctx *command.Context unlockFn, err := p.WorkingDirLocker.TryLock(ctx.Pull.BaseRepo.FullName, ctx.Pull.Num, workspace) if err != nil { - ctx.Log.Warn("workspace was locked") + ctx.Log.WarnContext(ctx.RequestCtx, "workspace was locked") return nil, err } defer unlockFn() @@ -207,12 +207,12 @@ func (p *DefaultProjectCommandBuilder) buildPlanAllCommands(ctx *command.Context if err != nil { return nil, errors.Wrapf(err, "parsing %s", config.AtlantisYAMLFilename) } - ctx.Log.Info(fmt.Sprintf("successfully parsed %s file", config.AtlantisYAMLFilename)) + ctx.Log.InfoContext(ctx.RequestCtx, fmt.Sprintf("successfully parsed %s file", config.AtlantisYAMLFilename)) matchingProjects, err := p.ProjectFinder.DetermineProjectsViaConfig(ctx.Log, modifiedFiles, repoCfg, repoDir) if err != nil { return nil, err } - ctx.Log.Info(fmt.Sprintf("%d projects are to be planned based on their when_modified config", len(matchingProjects))) + ctx.Log.InfoContext(ctx.RequestCtx, fmt.Sprintf("%d projects are to be planned based on their when_modified config", len(matchingProjects))) for _, mp := range matchingProjects { mergedCfg := p.GlobalCfg.MergeProjectCfg(ctx.Log, ctx.Pull.BaseRepo.ID(), mp, repoCfg) @@ -234,12 +234,12 @@ func (p *DefaultProjectCommandBuilder) buildPlanAllCommands(ctx *command.Context } else { // If there is no config file, then we'll plan each project that // our algorithm determines was modified. - ctx.Log.Info(fmt.Sprintf("found no %s file", config.AtlantisYAMLFilename)) - modifiedProjects := p.ProjectFinder.DetermineProjects(ctx.Log, modifiedFiles, ctx.Pull.BaseRepo.FullName, repoDir, p.AutoplanFileList) + ctx.Log.InfoContext(ctx.RequestCtx, fmt.Sprintf("found no %s file", config.AtlantisYAMLFilename)) + modifiedProjects := p.ProjectFinder.DetermineProjects(ctx.Log, ctx.RequestCtx, modifiedFiles, ctx.Pull.BaseRepo.FullName, repoDir, p.AutoplanFileList) if err != nil { return nil, errors.Wrapf(err, "finding modified projects: %s", modifiedFiles) } - ctx.Log.Info(fmt.Sprintf("automatically determined that there were %d projects modified in this pull request: %s", len(modifiedProjects), modifiedProjects)) + ctx.Log.InfoContext(ctx.RequestCtx, fmt.Sprintf("automatically determined that there were %d projects modified in this pull request: %s", len(modifiedProjects), modifiedProjects)) for _, mp := range modifiedProjects { pCfg := p.GlobalCfg.DefaultProjCfg(ctx.Log, ctx.Pull.BaseRepo.ID(), mp.Path, DefaultWorkspace) diff --git a/server/events/project_command_builder_internal_test.go b/server/events/project_command_builder_internal_test.go index 2fcc8aed82..2cb43fc9f9 100644 --- a/server/events/project_command_builder_internal_test.go +++ b/server/events/project_command_builder_internal_test.go @@ -1,6 +1,7 @@ package events import ( + "context" "io/ioutil" "os" "path/filepath" @@ -77,6 +78,7 @@ workflows: User: models.User{}, Workspace: "myworkspace", PolicySets: emptyPolicySets, + RequestCtx: context.TODO(), }, expPlanSteps: []string{"init", "plan"}, expApplySteps: []string{"apply"}, @@ -128,6 +130,7 @@ projects: User: models.User{}, Workspace: "myworkspace", PolicySets: emptyPolicySets, + RequestCtx: context.TODO(), }, expPlanSteps: []string{"init", "plan"}, expApplySteps: []string{"apply"}, @@ -179,6 +182,7 @@ projects: User: models.User{}, Workspace: "myworkspace", PolicySets: emptyPolicySets, + RequestCtx: context.TODO(), }, expPlanSteps: []string{"init", "plan"}, expApplySteps: []string{"apply"}, @@ -238,6 +242,7 @@ projects: User: models.User{}, Workspace: "myworkspace", PolicySets: emptyPolicySets, + RequestCtx: context.TODO(), }, expPlanSteps: []string{"plan"}, expApplySteps: []string{}, @@ -381,6 +386,7 @@ workflows: User: models.User{}, Workspace: "myworkspace", PolicySets: emptyPolicySets, + RequestCtx: context.TODO(), }, expPlanSteps: []string{"plan"}, expApplySteps: []string{"apply"}, @@ -436,6 +442,7 @@ projects: User: models.User{}, Workspace: "myworkspace", PolicySets: emptyPolicySets, + RequestCtx: context.TODO(), }, expPlanSteps: []string{"plan"}, expApplySteps: []string{"apply"}, @@ -494,6 +501,7 @@ workflows: User: models.User{}, Workspace: "myworkspace", PolicySets: emptyPolicySets, + RequestCtx: context.TODO(), }, expPlanSteps: []string{}, expApplySteps: []string{}, @@ -536,6 +544,7 @@ projects: User: models.User{}, Workspace: "myworkspace", PolicySets: emptyPolicySets, + RequestCtx: context.TODO(), }, expPlanSteps: []string{"plan"}, expApplySteps: []string{"apply"}, @@ -591,7 +600,8 @@ projects: for _, cmd := range []command.Name{command.Plan, command.Apply} { t.Run(cmd.String(), func(t *testing.T) { ctxs, err := builder.buildProjectCommandCtx(&command.Context{ - Log: logger, + RequestCtx: context.TODO(), + Log: logger, Pull: models.PullRequest{ BaseRepo: baseRepo, }, @@ -727,6 +737,7 @@ projects: User: models.User{}, Workspace: "myworkspace", PolicySets: emptyPolicySets, + RequestCtx: context.TODO(), }, expPlanSteps: []string{"init", "plan"}, expApplySteps: []string{"apply"}, @@ -789,6 +800,7 @@ projects: PullRequestStatus: models.PullReqStatus{ Mergeable: true, }, + RequestCtx: context.TODO(), }, cmd, "myproject_[1-2]", []string{"flag"}, tmp, "project1", "myworkspace", false) if c.expErr != "" { @@ -883,6 +895,7 @@ repos: User: models.User{}, Workspace: "myworkspace", PolicySets: emptyPolicySets, + RequestCtx: context.TODO(), }, expPolicyCheckSteps: []string{"show", "policy_check"}, }, @@ -939,6 +952,7 @@ workflows: User: models.User{}, Workspace: "myworkspace", PolicySets: emptyPolicySets, + RequestCtx: context.TODO(), }, expPolicyCheckSteps: []string{"policy_check"}, }, @@ -993,7 +1007,8 @@ workflows: cmd := command.PolicyCheck t.Run(cmd.String(), func(t *testing.T) { ctxs, err := builder.buildProjectCommandCtx(&command.Context{ - Log: logger, + RequestCtx: context.TODO(), + Log: logger, Pull: models.PullRequest{ BaseRepo: baseRepo, }, diff --git a/server/events/project_command_builder_test.go b/server/events/project_command_builder_test.go index ef19476e7a..fd27a92061 100644 --- a/server/events/project_command_builder_test.go +++ b/server/events/project_command_builder_test.go @@ -1,6 +1,7 @@ package events_test import ( + "context" "fmt" "os" "path/filepath" @@ -157,6 +158,7 @@ projects: ) ctxs, err := builder.BuildAutoplanCommands(&command.Context{ + RequestCtx: context.TODO(), PullRequestStatus: models.PullReqStatus{ Mergeable: true, }, @@ -422,11 +424,12 @@ projects: var err error if cmdName == command.Plan { actCtxs, err = builder.BuildPlanCommands(&command.Context{ - Log: logger, - Scope: scope, + RequestCtx: context.TODO(), + Log: logger, + Scope: scope, }, &c.Cmd) } else { - actCtxs, err = builder.BuildApplyCommands(&command.Context{Log: logger, Scope: scope}, &c.Cmd) + actCtxs, err = builder.BuildApplyCommands(&command.Context{Log: logger, Scope: scope, RequestCtx: context.TODO()}, &c.Cmd) } if c.ExpErr != "" { @@ -566,8 +569,9 @@ projects: ctxs, err := builder.BuildPlanCommands( &command.Context{ - Log: logger, - Scope: scope, + Log: logger, + Scope: scope, + RequestCtx: context.TODO(), }, &command.Comment{ RepoRelDir: "", @@ -648,8 +652,9 @@ func TestDefaultProjectCommandBuilder_BuildMultiApply(t *testing.T) { ctxs, err := builder.BuildApplyCommands( &command.Context{ - Log: logger, - Scope: scope, + Log: logger, + Scope: scope, + RequestCtx: context.TODO(), }, &command.Comment{ RepoRelDir: "", @@ -723,11 +728,12 @@ projects: ) ctx := &command.Context{ - HeadRepo: models.Repo{}, - Pull: models.PullRequest{}, - User: models.User{}, - Log: logging.NewNoopCtxLogger(t), - Scope: scope, + RequestCtx: context.TODO(), + HeadRepo: models.Repo{}, + Pull: models.PullRequest{}, + User: models.User{}, + Log: logging.NewNoopCtxLogger(t), + Scope: scope, } _, err = builder.BuildPlanCommands(ctx, &command.Comment{ RepoRelDir: ".", @@ -794,8 +800,9 @@ func TestDefaultProjectCommandBuilder_EscapeArgs(t *testing.T) { var actCtxs []command.ProjectContext var err error actCtxs, err = builder.BuildPlanCommands(&command.Context{ - Log: logger, - Scope: scope, + RequestCtx: context.TODO(), + Log: logger, + Scope: scope, }, &command.Comment{ RepoRelDir: ".", Flags: c.ExtraArgs, @@ -966,8 +973,9 @@ projects: actCtxs, err := builder.BuildPlanCommands( &command.Context{ - Log: logger, - Scope: scope, + RequestCtx: context.TODO(), + Log: logger, + Scope: scope, }, &command.Comment{ RepoRelDir: "", @@ -1029,8 +1037,9 @@ func TestDefaultProjectCommandBuilder_WithPolicyCheckEnabled_BuildAutoplanComman PullRequestStatus: models.PullReqStatus{ Mergeable: true, }, - Log: logger, - Scope: scope, + RequestCtx: context.TODO(), + Log: logger, + Scope: scope, }) Ok(t, err) @@ -1100,8 +1109,9 @@ func TestDefaultProjectCommandBuilder_BuildVersionCommand(t *testing.T) { ctxs, err := builder.BuildVersionCommands( &command.Context{ - Log: logger, - Scope: scope, + RequestCtx: context.TODO(), + Log: logger, + Scope: scope, }, &command.Comment{ RepoRelDir: "", diff --git a/server/events/project_command_context_builder.go b/server/events/project_command_context_builder.go index 5ee1346152..9c97520c0a 100644 --- a/server/events/project_command_context_builder.go +++ b/server/events/project_command_context_builder.go @@ -129,11 +129,11 @@ func escapeArgs(args []string) []string { func getTfVersion(ctx *command.Context, absProjDir string) *version.Version { module, diags := tfconfig.LoadModule(absProjDir) if diags.HasErrors() { - ctx.Log.Error(fmt.Sprintf("trying to detect required version: %s", diags.Error())) + ctx.Log.ErrorContext(ctx.RequestCtx, fmt.Sprintf("trying to detect required version: %s", diags.Error())) return nil } if len(module.RequiredCore) != 1 { - ctx.Log.Info(fmt.Sprintf("cannot determine which version to use from terraform configuration, detected %d possibilities.", len(module.RequiredCore))) + ctx.Log.InfoContext(ctx.RequestCtx, fmt.Sprintf("cannot determine which version to use from terraform configuration, detected %d possibilities.", len(module.RequiredCore))) return nil } requiredVersionSetting := module.RequiredCore[0] @@ -146,10 +146,10 @@ func getTfVersion(ctx *command.Context, absProjDir string) *version.Version { } version, err := version.NewVersion(matched[1]) if err != nil { - ctx.Log.Error(err.Error()) + ctx.Log.ErrorContext(ctx.RequestCtx, err.Error()) return nil } - ctx.Log.Info(fmt.Sprintf("detected module requires version: %q", version.String())) + ctx.Log.InfoContext(ctx.RequestCtx, fmt.Sprintf("detected module requires version: %q", version.String())) return version } diff --git a/server/events/project_command_context_builder_test.go b/server/events/project_command_context_builder_test.go index 3d5ff68ef1..7b75b7417d 100644 --- a/server/events/project_command_context_builder_test.go +++ b/server/events/project_command_context_builder_test.go @@ -1,6 +1,7 @@ package events_test import ( + "context" "testing" . "github.com/petergtz/pegomock" @@ -42,6 +43,7 @@ func TestProjectCommandContextBuilder_PullStatus(t *testing.T) { Log: logging.NewNoopCtxLogger(t), PullStatus: pullStatus, Scope: scope, + RequestCtx: context.TODO(), } expectedApplyCmt := "Apply Comment" diff --git a/server/events/project_command_output_wrapper.go b/server/events/project_command_output_wrapper.go index 24336cef50..d69d48fa53 100644 --- a/server/events/project_command_output_wrapper.go +++ b/server/events/project_command_output_wrapper.go @@ -31,7 +31,7 @@ func (p *ProjectOutputWrapper) updateProjectPRStatus(commandName command.Name, c // include a link to view the progress of atlantis plan command in real // time if err := p.JobURLSetter.SetJobURLWithStatus(ctx, commandName, models.PendingCommitStatus); err != nil { - ctx.Log.Error(fmt.Sprintf("updating project PR status %v", err)) + ctx.Log.ErrorContext(ctx.RequestCtx, fmt.Sprintf("updating project PR status %v", err)) } // ensures we are differentiating between project level command and overall command @@ -39,14 +39,14 @@ func (p *ProjectOutputWrapper) updateProjectPRStatus(commandName command.Name, c if result.Error != nil || result.Failure != "" { if err := p.JobURLSetter.SetJobURLWithStatus(ctx, commandName, models.FailedCommitStatus); err != nil { - ctx.Log.Error(fmt.Sprintf("updating project PR status %v", err)) + ctx.Log.ErrorContext(ctx.RequestCtx, fmt.Sprintf("updating project PR status %v", err)) } return result } if err := p.JobURLSetter.SetJobURLWithStatus(ctx, commandName, models.SuccessCommitStatus); err != nil { - ctx.Log.Error(fmt.Sprintf("updating project PR status %v", err)) + ctx.Log.ErrorContext(ctx.RequestCtx, fmt.Sprintf("updating project PR status %v", err)) } return result diff --git a/server/events/project_command_runner_test.go b/server/events/project_command_runner_test.go index 736453fd27..e58b6b341d 100644 --- a/server/events/project_command_runner_test.go +++ b/server/events/project_command_runner_test.go @@ -60,6 +60,7 @@ func TestDefaultProjectCommandRunner_Plan(t *testing.T) { When(mockLocker.TryLock( matchers.AnyLoggingLogger(), + matchers.AnyContextContext(), matchers.AnyModelsPullRequest(), matchers.AnyModelsUser(), AnyString(), @@ -116,7 +117,8 @@ func TestDefaultProjectCommandRunner_Plan(t *testing.T) { func TestDefaultProjectCommandRunner_PlanWithSync(t *testing.T) { RegisterMockTestingT(t) prjCtx := command.ProjectContext{ - Log: logging.NewNoopCtxLogger(t), + RequestCtx: context.TODO(), + Log: logging.NewNoopCtxLogger(t), Pull: models.PullRequest{ BaseRepo: models.Repo{ FullName: "test", diff --git a/server/events/project_finder.go b/server/events/project_finder.go index 24753b5a30..44af1baeff 100644 --- a/server/events/project_finder.go +++ b/server/events/project_finder.go @@ -14,6 +14,7 @@ package events import ( + "context" "fmt" "os" "path" @@ -34,7 +35,7 @@ type ProjectFinder interface { // DetermineProjects returns the list of projects that were modified based on // the modifiedFiles. The list will be de-duplicated. // absRepoDir is the path to the cloned repo on disk. - DetermineProjects(log logging.Logger, modifiedFiles []string, repoFullName string, absRepoDir string, autoplanFileList string) []models.Project + DetermineProjects(log logging.Logger, requestCtx context.Context, modifiedFiles []string, repoFullName string, absRepoDir string, autoplanFileList string) []models.Project // DetermineProjectsViaConfig returns the list of projects that were modified // based on modifiedFiles and the repo's config. // absRepoDir is the path to the cloned repo on disk. @@ -48,14 +49,14 @@ var ignoredFilenameFragments = []string{"terraform.tfstate", "terraform.tfstate. type DefaultProjectFinder struct{} // See ProjectFinder.DetermineProjects. -func (p *DefaultProjectFinder) DetermineProjects(log logging.Logger, modifiedFiles []string, repoFullName string, absRepoDir string, autoplanFileList string) []models.Project { +func (p *DefaultProjectFinder) DetermineProjects(log logging.Logger, requestCtx context.Context, modifiedFiles []string, repoFullName string, absRepoDir string, autoplanFileList string) []models.Project { var projects []models.Project modifiedTerraformFiles := p.filterToFileList(log, modifiedFiles, autoplanFileList) if len(modifiedTerraformFiles) == 0 { return projects } - log.Info(fmt.Sprintf("filtered modified files to %d .tf or terragrunt.hcl files: %v", + log.InfoContext(requestCtx, fmt.Sprintf("filtered modified files to %d .tf or terragrunt.hcl files: %v", len(modifiedTerraformFiles), modifiedTerraformFiles)) var dirs []string @@ -76,7 +77,7 @@ func (p *DefaultProjectFinder) DetermineProjects(log logging.Logger, modifiedFil for _, p := range exists { projects = append(projects, models.NewProject(repoFullName, p)) } - log.Info(fmt.Sprintf("there are %d modified project(s) at path(s): %v", + log.InfoContext(requestCtx, fmt.Sprintf("there are %d modified project(s) at path(s): %v", len(projects), strings.Join(exists, ", "))) return projects } diff --git a/server/events/project_finder_test.go b/server/events/project_finder_test.go index b0d8ad8f01..fa179d8612 100644 --- a/server/events/project_finder_test.go +++ b/server/events/project_finder_test.go @@ -14,6 +14,7 @@ package events_test import ( + "context" "io/ioutil" "os" "path/filepath" @@ -252,7 +253,7 @@ func TestDetermineProjects(t *testing.T) { } for _, c := range cases { t.Run(c.description, func(t *testing.T) { - projects := m.DetermineProjects(noopLogger, c.files, modifiedRepo, c.repoDir, c.autoplanFileList) + projects := m.DetermineProjects(noopLogger, context.TODO(), c.files, modifiedRepo, c.repoDir, c.autoplanFileList) // Extract the paths from the projects. We use a slice here instead of a // map so we can test whether there are duplicates returned. diff --git a/server/events/project_locker.go b/server/events/project_locker.go index 6ed80272be..c1d3eb5480 100644 --- a/server/events/project_locker.go +++ b/server/events/project_locker.go @@ -14,6 +14,7 @@ package events import ( + "context" "fmt" "github.com/runatlantis/atlantis/server/core/locking" @@ -33,7 +34,7 @@ type ProjectLocker interface { // The third return value is a function that can be called to unlock the // lock. It will only be set if the lock was acquired. Any errors will set // error. - TryLock(log logging.Logger, pull models.PullRequest, user models.User, workspace string, project models.Project) (*TryLockResponse, error) + TryLock(log logging.Logger, requestCtx context.Context, pull models.PullRequest, user models.User, workspace string, project models.Project) (*TryLockResponse, error) } // DefaultProjectLocker implements ProjectLocker. @@ -58,7 +59,7 @@ type TryLockResponse struct { } // TryLock implements ProjectLocker.TryLock. -func (p *DefaultProjectLocker) TryLock(log logging.Logger, pull models.PullRequest, user models.User, workspace string, project models.Project) (*TryLockResponse, error) { +func (p *DefaultProjectLocker) TryLock(log logging.Logger, requestCtx context.Context, pull models.PullRequest, user models.User, workspace string, project models.Project) (*TryLockResponse, error) { lockAttempt, err := p.Locker.TryLock(project, workspace, pull, user) if err != nil { return nil, err @@ -77,7 +78,7 @@ func (p *DefaultProjectLocker) TryLock(log logging.Logger, pull models.PullReque LockFailureReason: failureMsg, }, nil } - log.Info(fmt.Sprintf("acquired lock with id %q", lockAttempt.LockKey)) + log.InfoContext(requestCtx, fmt.Sprintf("acquired lock with id %q", lockAttempt.LockKey)) return &TryLockResponse{ LockAcquired: true, UnlockFn: func() error { diff --git a/server/events/project_locker_test.go b/server/events/project_locker_test.go index 9bf30a7e13..ac26584336 100644 --- a/server/events/project_locker_test.go +++ b/server/events/project_locker_test.go @@ -14,6 +14,7 @@ package events_test import ( + "context" "fmt" "testing" @@ -53,7 +54,7 @@ func TestDefaultProjectLocker_TryLockWhenLocked(t *testing.T) { }, nil, ) - res, err := locker.TryLock(logging.NewNoopCtxLogger(t), expPull, expUser, expWorkspace, expProject) + res, err := locker.TryLock(logging.NewNoopCtxLogger(t), context.TODO(), expPull, expUser, expWorkspace, expProject) link, _ := mockClient.MarkdownPullLink(lockingPull) Ok(t, err) Equals(t, &events.TryLockResponse{ @@ -90,7 +91,7 @@ func TestDefaultProjectLocker_TryLockWhenLockedSamePull(t *testing.T) { }, nil, ) - res, err := locker.TryLock(logging.NewNoopCtxLogger(t), expPull, expUser, expWorkspace, expProject) + res, err := locker.TryLock(logging.NewNoopCtxLogger(t), context.TODO(), expPull, expUser, expWorkspace, expProject) Ok(t, err) Equals(t, true, res.LockAcquired) @@ -129,7 +130,7 @@ func TestDefaultProjectLocker_TryLockUnlocked(t *testing.T) { }, nil, ) - res, err := locker.TryLock(logging.NewNoopCtxLogger(t), expPull, expUser, expWorkspace, expProject) + res, err := locker.TryLock(logging.NewNoopCtxLogger(t), context.TODO(), expPull, expUser, expWorkspace, expProject) Ok(t, err) Equals(t, true, res.LockAcquired) diff --git a/server/events/pull_closed_executor.go b/server/events/pull_closed_executor.go index b5dd735701..73814c13c1 100644 --- a/server/events/pull_closed_executor.go +++ b/server/events/pull_closed_executor.go @@ -81,10 +81,14 @@ var pullClosedTemplate = template.Must(template.New("").Parse( // CleanUpPull cleans up after a closed pull request. func (p *PullClosedExecutor) CleanUpPull(repo models.Repo, pull models.PullRequest) error { + logFields := map[string]interface{}{ + "repository": repo.FullName, + "pull-num": pull.Num, + } pullStatus, err := p.DB.GetPullStatus(pull) if err != nil { // Log and continue to clean up other resources. - p.Logger.Error(fmt.Sprintf("retrieving pull status: %s", err)) + p.Logger.Error(fmt.Sprintf("retrieving pull status: %s", err), logFields) } if pullStatus != nil { @@ -113,7 +117,7 @@ func (p *PullClosedExecutor) CleanUpPull(repo models.Repo, pull models.PullReque // Delete pull from DB. if err := p.DB.DeletePullStatus(pull); err != nil { - p.Logger.Error(fmt.Sprintf("deleting pull from db: %s", err)) + p.Logger.Error(fmt.Sprintf("deleting pull from db: %s", err), logFields) } // If there are no locks then there's no need to comment. diff --git a/server/events/pull_updater.go b/server/events/pull_updater.go index 780bd538aa..881ed5c53d 100644 --- a/server/events/pull_updater.go +++ b/server/events/pull_updater.go @@ -17,9 +17,9 @@ type PullUpdater struct { func (c *PullUpdater) UpdatePull(ctx *command.Context, cmd PullCommand, res command.Result) { // Log if we got any errors or failures. if res.Error != nil { - ctx.Log.Error(res.Error.Error()) + ctx.Log.ErrorContext(ctx.RequestCtx, res.Error.Error()) } else if res.Failure != "" { - ctx.Log.Warn(res.Failure) + ctx.Log.WarnContext(ctx.RequestCtx, res.Failure) } // HidePrevCommandComments will hide old comments left from previous runs to reduce @@ -27,7 +27,7 @@ func (c *PullUpdater) UpdatePull(ctx *command.Context, cmd PullCommand, res comm // comment trail may be useful in auditing or backtracing problems. if c.HidePrevPlanComments { if err := c.VCSClient.HidePrevCommandComments(ctx.Pull.BaseRepo, ctx.Pull.Num, cmd.CommandName().TitleString()); err != nil { - ctx.Log.Error(fmt.Sprintf("unable to hide old comments: %s", err)) + ctx.Log.ErrorContext(ctx.RequestCtx, fmt.Sprintf("unable to hide old comments: %s", err)) } } @@ -39,6 +39,6 @@ func (c *PullUpdater) UpdatePull(ctx *command.Context, cmd PullCommand, res comm comment := c.MarkdownRenderer.Render(res, cmd.CommandName(), ctx.Pull.BaseRepo.VCSHost.Type, templateOverrides) if err := c.VCSClient.CreateComment(ctx.Pull.BaseRepo, ctx.Pull.Num, comment, cmd.CommandName().String()); err != nil { - ctx.Log.Error(fmt.Sprintf("unable to comment: %s", err)) + ctx.Log.ErrorContext(ctx.RequestCtx, fmt.Sprintf("unable to comment: %s", err)) } } diff --git a/server/events/unlock_command_runner.go b/server/events/unlock_command_runner.go index fcda8535b2..33c311777f 100644 --- a/server/events/unlock_command_runner.go +++ b/server/events/unlock_command_runner.go @@ -32,10 +32,10 @@ func (u *UnlockCommandRunner) Run( _, err := u.deleteLockCommand.DeleteLocksByPull(baseRepo.FullName, pullNum) if err != nil { vcsMessage = "Failed to delete PR locks" - ctx.Log.Error(fmt.Sprintf("failed to delete locks by pull %s", err.Error())) + ctx.Log.ErrorContext(ctx.RequestCtx, fmt.Sprintf("failed to delete locks by pull %s", err.Error())) } if commentErr := u.vcsClient.CreateComment(baseRepo, pullNum, vcsMessage, command.Unlock.String()); commentErr != nil { - ctx.Log.Error(fmt.Sprintf("unable to comment: %s", commentErr)) + ctx.Log.ErrorContext(ctx.RequestCtx, fmt.Sprintf("unable to comment: %s", commentErr)) } } diff --git a/server/events/version_command_runner.go b/server/events/version_command_runner.go index 23d379471e..2a6091eeb0 100644 --- a/server/events/version_command_runner.go +++ b/server/events/version_command_runner.go @@ -31,18 +31,18 @@ func (v *VersionCommandRunner) Run(ctx *command.Context, cmd *command.Comment) { var projectCmds []command.ProjectContext projectCmds, err = v.prjCmdBuilder.BuildVersionCommands(ctx, cmd) if err != nil { - ctx.Log.Warn(fmt.Sprintf("Error %s", err)) + ctx.Log.WarnContext(ctx.RequestCtx, fmt.Sprintf("Error %s", err)) } if len(projectCmds) == 0 { - ctx.Log.Info("no projects to run version in") + ctx.Log.InfoContext(ctx.RequestCtx, "no projects to run version in") return } // Only run commands in parallel if enabled var result command.Result if v.isParallelEnabled(projectCmds) { - ctx.Log.Info("Running version in parallel") + ctx.Log.InfoContext(ctx.RequestCtx, "Running version in parallel") result = runProjectCmdsParallel(projectCmds, v.prjCmdRunner.Version, v.parallelPoolSize) } else { result = runProjectCmds(projectCmds, v.prjCmdRunner.Version) diff --git a/server/events/working_dir.go b/server/events/working_dir.go index bff173f8b6..8a9a82d12b 100644 --- a/server/events/working_dir.go +++ b/server/events/working_dir.go @@ -97,8 +97,15 @@ func (w *FileWorkspace) Clone( revParseCmd := exec.Command("git", "rev-parse", pullHead) // #nosec revParseCmd.Dir = cloneDir outputRevParseCmd, err := revParseCmd.CombinedOutput() + logFields := map[string]interface{}{ + "repository": headRepo.FullName, + "pull-num": p.Num, + "workspace": projectCloneDir, + } if err != nil { - log.Warn(fmt.Sprintf("will re-clone repo, could not determine if was at correct commit: %s: %s: %s", strings.Join(revParseCmd.Args, " "), err, string(outputRevParseCmd))) + log.Warn( + fmt.Sprintf("will re-clone repo, could not determine if was at correct commit: %s: %s: %s", strings.Join(revParseCmd.Args, " "), err, string(outputRevParseCmd)), + logFields) return cloneDir, false, w.forceClone(log, cloneDir, headRepo, p) } currCommit := strings.Trim(string(outputRevParseCmd), "\n") @@ -148,6 +155,12 @@ func (w *FileWorkspace) warnDiverged(log logging.Logger, p models.PullRequest, h }, } + logFields := map[string]interface{}{ + "repository": headRepo.FullName, + "pull-num": p.Num, + "workspace": cloneDir, + } + for _, args := range cmds { cmd := exec.Command(args[0], args[1:]...) // nolint: gosec cmd.Dir = cloneDir @@ -155,14 +168,14 @@ func (w *FileWorkspace) warnDiverged(log logging.Logger, p models.PullRequest, h output, err := cmd.CombinedOutput() if err != nil { - log.Warn(fmt.Sprintf("getting remote update failed: %s", string(output))) + log.Warn(fmt.Sprintf("getting remote update failed: %s", string(output)), logFields) return false } } hasDiverged := w.HasDiverged(log, cloneDir) if hasDiverged { - log.Info("remote master branch is ahead and thereby has new commits, it is recommended to pull new commits") + log.Info("remote master branch is ahead and thereby has new commits, it is recommended to pull new commits", logFields) } return hasDiverged } @@ -189,6 +202,11 @@ func (w *FileWorkspace) forceClone(log logging.Logger, cloneDir string, headRepo models.Repo, p models.PullRequest) error { + logFields := map[string]interface{}{ + "repository": headRepo.FullName, + "pull-num": p.Num, + "workspace": cloneDir, + } err := os.RemoveAll(cloneDir) if err != nil { @@ -196,7 +214,7 @@ func (w *FileWorkspace) forceClone(log logging.Logger, } // Create the directory and parents if necessary. - log.Info(fmt.Sprintf("creating dir %q", cloneDir)) + log.Info(fmt.Sprintf("creating dir %q", cloneDir), logFields) if err := os.MkdirAll(cloneDir, 0700); err != nil { return errors.Wrap(err, "creating new workspace") } diff --git a/server/lyft/aws/sqs/worker.go b/server/lyft/aws/sqs/worker.go index b3f088def7..96df6b051f 100644 --- a/server/lyft/aws/sqs/worker.go +++ b/server/lyft/aws/sqs/worker.go @@ -63,7 +63,7 @@ func (w *Worker) Work(ctx context.Context) { wg.Add(1) go func() { defer wg.Done() - w.Logger.Info("start processing sqs messages") + w.Logger.InfoContext(ctx, "start processing sqs messages") w.processMessage(ctx, messages) }() request := &sqs.ReceiveMessageInput{ @@ -71,7 +71,7 @@ func (w *Worker) Work(ctx context.Context) { MaxNumberOfMessages: 10, //max number of batch-able messages WaitTimeSeconds: 20, //max duration long polling } - w.Logger.Info("start receiving sqs messages") + w.Logger.InfoContext(ctx, "start receiving sqs messages") w.receiveMessages(ctx, messages, request) wg.Wait() } @@ -81,12 +81,12 @@ func (w *Worker) receiveMessages(ctx context.Context, messages chan types.Messag select { case <-ctx.Done(): close(messages) - w.Logger.Info("closed sqs messages channel") + w.Logger.InfoContext(ctx, "closed sqs messages channel") return default: response, err := w.Queue.ReceiveMessage(ctx, request) if err != nil { - w.Logger.Warn("unable to receive sqs message", map[string]interface{}{"err": err}) + w.Logger.WarnContext(ctx, "unable to receive sqs message", map[string]interface{}{"err": err}) continue } for _, message := range response.Messages { @@ -101,7 +101,7 @@ func (w *Worker) processMessage(ctx context.Context, messages chan types.Message for message := range messages { err := w.MessageProcessor.ProcessMessage(message) if err != nil { - w.Logger.Error("unable to process sqs message", map[string]interface{}{"err": err}) + w.Logger.ErrorContext(ctx, "unable to process sqs message", map[string]interface{}{"err": err}) continue } @@ -111,7 +111,7 @@ func (w *Worker) processMessage(ctx context.Context, messages chan types.Message ReceiptHandle: message.ReceiptHandle, }) if err != nil { - w.Logger.Warn("unable to delete processed sqs message", map[string]interface{}{"err": err}) + w.Logger.WarnContext(ctx, "unable to delete processed sqs message", map[string]interface{}{"err": err}) } } } diff --git a/server/lyft/command/feature_runner.go b/server/lyft/command/feature_runner.go index 0dfe8f50b2..ae67c2aa8c 100644 --- a/server/lyft/command/feature_runner.go +++ b/server/lyft/command/feature_runner.go @@ -46,7 +46,7 @@ func (r *PlatformModeFeatureRunner) Run(ctx *command.Context, cmd *command.Comme shouldAllocate, err := r.featureAllocator.ShouldAllocate(feature.PlatformMode, ctx.HeadRepo.FullName) if err != nil { - r.logger.Error(fmt.Sprintf("unable to allocate for feature: %s, error: %s", feature.PlatformMode, err)) + r.logger.ErrorContext(ctx.RequestCtx, fmt.Sprintf("unable to allocate for feature: %s, error: %s", feature.PlatformMode, err)) } if !shouldAllocate { diff --git a/server/lyft/decorators/audit_project_commands_wrapper.go b/server/lyft/decorators/audit_project_commands_wrapper.go index d8d2ee2007..13773dcd75 100644 --- a/server/lyft/decorators/audit_project_commands_wrapper.go +++ b/server/lyft/decorators/audit_project_commands_wrapper.go @@ -68,14 +68,14 @@ func (p *AuditProjectCommandWrapper) Apply(ctx command.ProjectContext) command.P if result.Error != nil || result.Failure != "" { if err := p.emit(ctx, AtlantisJobStateFailure, atlantisJobEvent); err != nil { - ctx.Log.Error(fmt.Sprintf("failed to emit atlantis job event %v", err)) + ctx.Log.ErrorContext(ctx.RequestCtx, fmt.Sprintf("failed to emit atlantis job event %v", err)) } return result } if err := p.emit(ctx, AtlantisJobStateSuccess, atlantisJobEvent); err != nil { - ctx.Log.Error(fmt.Sprintf("failed to emit atlantis job event %v", err)) + ctx.Log.ErrorContext(ctx.RequestCtx, fmt.Sprintf("failed to emit atlantis job event %v", err)) } return result diff --git a/server/lyft/gateway/autoplan_builder.go b/server/lyft/gateway/autoplan_builder.go index 2a94db0ede..f0cacc436a 100644 --- a/server/lyft/gateway/autoplan_builder.go +++ b/server/lyft/gateway/autoplan_builder.go @@ -39,42 +39,43 @@ func (r *AutoplanValidator) isValid(ctx context.Context, logger logging.Logger, defer r.logPanics(ctx, logger) cmdCtx := &command.Context{ - User: user, - Log: logger, - Scope: r.Scope, - Pull: pull, - HeadRepo: headRepo, - Trigger: command.AutoTrigger, + User: user, + Log: logger, + Scope: r.Scope, + Pull: pull, + HeadRepo: headRepo, + Trigger: command.AutoTrigger, + RequestCtx: ctx, } - if !r.validateCtxAndComment(cmdCtx, ctx) { + if !r.validateCtxAndComment(cmdCtx) { return false, errors.New("invalid command context") } err := r.PreWorkflowHooksCommandRunner.RunPreHooks(context.TODO(), cmdCtx) if err != nil { - cmdCtx.Log.ErrorContext(ctx, fmt.Sprintf("Error running pre-workflow hooks %s. Proceeding with %s command.", err, command.Plan)) + cmdCtx.Log.ErrorContext(cmdCtx.RequestCtx, fmt.Sprintf("Error running pre-workflow hooks %s. Proceeding with %s command.", err, command.Plan)) } projectCmds, err := r.PrjCmdBuilder.BuildAutoplanCommands(cmdCtx) if err != nil { if statusErr := r.CommitStatusUpdater.UpdateCombined(context.TODO(), baseRepo, pull, models.FailedCommitStatus, command.Plan); statusErr != nil { - cmdCtx.Log.WarnContext(ctx, fmt.Sprintf("unable to update commit status: %v", statusErr)) + cmdCtx.Log.WarnContext(cmdCtx.RequestCtx, fmt.Sprintf("unable to update commit status: %v", statusErr)) } // If error happened after clone was made, we should clean it up here too unlockFn, lockErr := r.WorkingDirLocker.TryLock(baseRepo.FullName, pull.Num, DefaultWorkspace) if lockErr != nil { - cmdCtx.Log.WarnContext(ctx, "workspace was locked") + cmdCtx.Log.WarnContext(cmdCtx.RequestCtx, "workspace was locked") return false, errors.Wrap(err, lockErr.Error()) } defer unlockFn() if cloneErr := r.WorkingDir.Delete(baseRepo, pull); cloneErr != nil { - cmdCtx.Log.WarnContext(ctx, "unable to delete clone after autoplan failed", map[string]interface{}{"err": cloneErr}) + cmdCtx.Log.WarnContext(cmdCtx.RequestCtx, "unable to delete clone after autoplan failed", map[string]interface{}{"err": cloneErr}) } r.PullUpdater.UpdatePull(cmdCtx, events.AutoplanCommand{}, command.Result{Error: err}) return false, errors.Wrap(err, "Failed building autoplan commands") } unlockFn, err := r.WorkingDirLocker.TryLock(baseRepo.FullName, pull.Num, DefaultWorkspace) if err != nil { - cmdCtx.Log.WarnContext(ctx, "workspace was locked") + cmdCtx.Log.WarnContext(cmdCtx.RequestCtx, "workspace was locked") return false, err } defer unlockFn() @@ -83,10 +84,10 @@ func (r *AutoplanValidator) isValid(ctx context.Context, logger logging.Logger, return false, errors.Wrap(err, "Failed deleting cloned repo") } if len(projectCmds) == 0 { - cmdCtx.Log.InfoContext(ctx, "no modified projects have been found") + cmdCtx.Log.InfoContext(cmdCtx.RequestCtx, "no modified projects have been found") for _, cmd := range []command.Name{command.Plan, command.Apply, command.PolicyCheck} { if err := r.CommitStatusUpdater.UpdateCombinedCount(context.TODO(), baseRepo, pull, models.SuccessCommitStatus, cmd, 0, 0); err != nil { - cmdCtx.Log.WarnContext(ctx, fmt.Sprintf("unable to update commit status: %s", err)) + cmdCtx.Log.WarnContext(cmdCtx.RequestCtx, fmt.Sprintf("unable to update commit status: %s", err)) } } return false, nil @@ -119,20 +120,20 @@ func (r *AutoplanValidator) logPanics(ctx context.Context, logger logging.Logger } } -func (r *AutoplanValidator) validateCtxAndComment(cmdCtx *command.Context, ctx context.Context) bool { +func (r *AutoplanValidator) validateCtxAndComment(cmdCtx *command.Context) bool { if cmdCtx.HeadRepo.Owner != cmdCtx.Pull.BaseRepo.Owner { - cmdCtx.Log.InfoContext(ctx, "command was run on a fork pull request which is disallowed") + cmdCtx.Log.InfoContext(cmdCtx.RequestCtx, "command was run on a fork pull request which is disallowed") return false } if cmdCtx.Pull.State != models.OpenPullState { - cmdCtx.Log.InfoContext(ctx, "command was run on closed pull request") + cmdCtx.Log.InfoContext(cmdCtx.RequestCtx, "command was run on closed pull request") return false } repo := r.GlobalCfg.MatchingRepo(cmdCtx.Pull.BaseRepo.ID()) if !repo.BranchMatches(cmdCtx.Pull.BaseBranch) { - cmdCtx.Log.InfoContext(ctx, "command was run on a pull request which doesn't match base branches") + cmdCtx.Log.InfoContext(cmdCtx.RequestCtx, "command was run on a pull request which doesn't match base branches") // just ignore it to allow us to use any git workflows without malicious intentions. return false } diff --git a/server/sync/project.go b/server/sync/project.go index 525242cb94..7f39398cdb 100644 --- a/server/sync/project.go +++ b/server/sync/project.go @@ -59,7 +59,7 @@ func (p *ProjectSyncer) sync( } // Acquire Atlantis lock for this repo/dir/workspace. - lockResponse, err := p.Locker.TryLock(ctx.Log, ctx.Pull, ctx.User, ctx.Workspace, models.NewProject(ctx.Pull.BaseRepo.FullName, ctx.RepoRelDir)) + lockResponse, err := p.Locker.TryLock(ctx.Log, ctx.RequestCtx, ctx.Pull, ctx.User, ctx.Workspace, models.NewProject(ctx.Pull.BaseRepo.FullName, ctx.RepoRelDir)) if err != nil { result.Error = errors.Wrap(err, "acquiring lock") return diff --git a/server/vcs/provider/github/request/handler.go b/server/vcs/provider/github/request/handler.go index 001442f2b8..30b0c5df52 100644 --- a/server/vcs/provider/github/request/handler.go +++ b/server/vcs/provider/github/request/handler.go @@ -148,8 +148,9 @@ func (h *Handler) handleGithubCommentEvent(ctx context.Context, event *github.Is } ctxWithRepo := context.WithValue(ctx, logging.RepositoryKey, commentEvent.BaseRepo.FullName) ctxWithPull := context.WithValue(ctxWithRepo, logging.PullNumKey, commentEvent.PullNum) + ctxWithSha := context.WithValue(ctxWithPull, logging.SHAKey, commentEvent.Pull.HeadCommit) - return h.commentHandler.Handle(ctxWithPull, request, commentEvent) + return h.commentHandler.Handle(ctxWithSha, request, commentEvent) } func (h *Handler) handleGithubPullRequestEvent(ctx context.Context, event *github.PullRequestEvent, request *http.BufferedRequest) error {