Pass context through logs/use field parameter to offer details (#252)

* draft

* pass context/fields thru

* fix tests

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)
 }

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,

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{},

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

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.

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 != "" {

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{}
 	}

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")

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))
 		}
 	}