Tweak logging. Add timezone, use everywhere.

cmd/server.go

@@ -20,6 +20,8 @@ import (
 	"path/filepath"
 	"strings"
 
+	"github.com/runatlantis/atlantis/server/logging"
+
 	"github.com/mitchellh/go-homedir"
 	"github.com/pkg/errors"
 	"github.com/runatlantis/atlantis/server"
@@ -69,9 +71,6 @@ const (
 	DefaultPort             = 4141
 )
 
-const redTermStart = "\033[31m"
-const redTermEnd = "\033[39m"
-
 var stringFlags = []stringFlag{
 	{
 		name:        AtlantisURLFlag,
@@ -231,6 +230,7 @@ type ServerCmd struct {
 	// Useful for testing to keep the logs clean.
 	SilenceOutput   bool
 	AtlantisVersion string
+	Logger          *logging.SimpleLogger
 }
 
 // ServerCreator creates servers.
@@ -283,7 +283,7 @@ func (s *ServerCmd) Init() *cobra.Command {
 
 	// If a user passes in an invalid flag, tell them what the flag was.
 	c.SetFlagErrorFunc(func(c *cobra.Command, err error) error {
-		fmt.Fprintf(os.Stderr, "\033[31mError: %s\033[39m\n\n", err.Error())
+		s.printErr(err)
 		return err
 	})
 
@@ -334,6 +334,11 @@ func (s *ServerCmd) run() error {
 		return err
 	}
 	s.setDefaults(&userConfig)
+
+	// Now that we've parsed the config we can set our local logger to the
+	// right level.
+	s.Logger.SetLevel(userConfig.ToLogLevel())
+
 	if err := s.validate(userConfig); err != nil {
 		return err
 	}
@@ -471,26 +476,31 @@ func (s *ServerCmd) trimAtSymbolFromUsers(userConfig *server.UserConfig) {
 
 func (s *ServerCmd) securityWarnings(userConfig *server.UserConfig) {
 	if userConfig.GithubUser != "" && userConfig.GithubWebhookSecret == "" && !s.SilenceOutput {
-		fmt.Fprintf(os.Stderr, "%s[WARN] No GitHub webhook secret set. This could allow attackers to spoof requests from GitHub.%s\n", redTermStart, redTermEnd)
+		s.Logger.Warn("no GitHub webhook secret set. This could allow attackers to spoof requests from GitHub")
 	}
 	if userConfig.GitlabUser != "" && userConfig.GitlabWebhookSecret == "" && !s.SilenceOutput {
-		fmt.Fprintf(os.Stderr, "%s[WARN] No GitLab webhook secret set. This could allow attackers to spoof requests from GitLab.%s\n", redTermStart, redTermEnd)
+		s.Logger.Warn("no GitLab webhook secret set. This could allow attackers to spoof requests from GitLab")
 	}
 	if userConfig.BitbucketUser != "" && userConfig.BitbucketBaseURL != DefaultBitbucketBaseURL && userConfig.BitbucketWebhookSecret == "" && !s.SilenceOutput {
-		fmt.Fprintf(os.Stderr, "%s[WARN] No Bitbucket webhook secret set. This could allow attackers to spoof requests from Bitbucket.%s\n", redTermStart, redTermEnd)
+		s.Logger.Warn("no Bitbucket webhook secret set. This could allow attackers to spoof requests from Bitbucket")
 	}
 	if userConfig.BitbucketUser != "" && userConfig.BitbucketBaseURL == DefaultBitbucketBaseURL && !s.SilenceOutput {
-		fmt.Fprintf(os.Stderr, "%s[WARN] Bitbucket Cloud does not support webhook secrets. This could allow attackers to spoof requests from Bitbucket. Ensure you are whitelisting Bitbucket IPs.%s\n", redTermStart, redTermEnd)
+		s.Logger.Warn("Bitbucket Cloud does not support webhook secrets. This could allow attackers to spoof requests from Bitbucket. Ensure you are whitelisting Bitbucket IPs")
 	}
 }
 
-// withErrPrint prints out any errors to a terminal in red.
+// withErrPrint prints out any cmd errors to stderr.
 func (s *ServerCmd) withErrPrint(f func(*cobra.Command, []string) error) func(*cobra.Command, []string) error {
 	return func(cmd *cobra.Command, args []string) error {
 		err := f(cmd, args)
 		if err != nil && !s.SilenceOutput {
-			fmt.Fprintf(os.Stderr, "%s[ERROR] %s%s\n\n", redTermStart, err.Error(), redTermEnd)
+			s.printErr(err)
 		}
 		return err
 	}
 }
+
+// printErr prints err to stderr using a red terminal colour.
+func (s *ServerCmd) printErr(err error) {
+	fmt.Fprintf(os.Stderr, "%sError: %s%s\n", "\033[31m", err.Error(), "\033[39m")
+}

main.go

@@ -16,6 +16,7 @@ package main
 
 import (
 	"github.com/runatlantis/atlantis/cmd"
+	"github.com/runatlantis/atlantis/server/logging"
 	"github.com/spf13/viper"
 )
 
@@ -30,6 +31,7 @@ func main() {
 		ServerCreator:   &cmd.DefaultServerCreator{},
 		Viper:           v,
 		AtlantisVersion: atlantisVersion,
+		Logger:          logging.NewSimpleLogger("cmd", false, logging.Info),
 	}
 	version := &cmd.VersionCmd{AtlantisVersion: atlantisVersion}
 	testdrive := &cmd.TestdriveCmd{}

server/events/command_runner.go

@@ -74,14 +74,14 @@ type DefaultCommandRunner struct {
 // RunAutoplanCommand runs plan when a pull request is opened or updated.
 func (c *DefaultCommandRunner) RunAutoplanCommand(baseRepo models.Repo, headRepo models.Repo, pull models.PullRequest, user models.User) {
 	log := c.buildLogger(baseRepo.FullName, pull.Num)
+	defer c.logPanics(baseRepo, pull.Num, log)
 	ctx := &CommandContext{
 		User:     user,
 		Log:      log,
 		Pull:     pull,
 		HeadRepo: headRepo,
 		BaseRepo: baseRepo,
 	}
-	defer c.logPanics(ctx)
 	if !c.validateCtxAndComment(ctx) {
 		return
 	}
@@ -113,6 +113,8 @@ func (c *DefaultCommandRunner) RunAutoplanCommand(baseRepo models.Repo, headRepo
 // wasteful) call to get the necessary data.
 func (c *DefaultCommandRunner) RunCommentCommand(baseRepo models.Repo, maybeHeadRepo *models.Repo, maybePull *models.PullRequest, user models.User, pullNum int, cmd *CommentCommand) {
 	log := c.buildLogger(baseRepo.FullName, pullNum)
+	defer c.logPanics(baseRepo, pullNum, log)
+
 	var headRepo models.Repo
 	if maybeHeadRepo != nil {
 		headRepo = *maybeHeadRepo
@@ -147,7 +149,6 @@ func (c *DefaultCommandRunner) RunCommentCommand(baseRepo models.Repo, maybeHead
 		HeadRepo: headRepo,
 		BaseRepo: baseRepo,
 	}
-	defer c.logPanics(ctx)
 	if !c.validateCtxAndComment(ctx) {
 		return
 	}
@@ -221,7 +222,7 @@ func (c *DefaultCommandRunner) getGitlabData(baseRepo models.Repo, pullNum int)
 
 func (c *DefaultCommandRunner) buildLogger(repoFullName string, pullNum int) *logging.SimpleLogger {
 	src := fmt.Sprintf("%s#%d", repoFullName, pullNum)
-	return logging.NewSimpleLogger(src, c.Logger.Underlying(), true, c.Logger.GetLevel())
+	return c.Logger.NewLogger(src, true, c.Logger.GetLevel())
 }
 
 func (c *DefaultCommandRunner) validateCtxAndComment(ctx *CommandContext) bool {
@@ -262,11 +263,16 @@ func (c *DefaultCommandRunner) updatePull(ctx *CommandContext, command PullComma
 }
 
 // logPanics logs and creates a comment on the pull request for panics.
-func (c *DefaultCommandRunner) logPanics(ctx *CommandContext) {
+func (c *DefaultCommandRunner) logPanics(baseRepo models.Repo, pullNum int, logger logging.SimpleLogging) {
 	if err := recover(); err != nil {
 		stack := recovery.Stack(3)
-		c.VCSClient.CreateComment(ctx.BaseRepo, ctx.Pull.Num, // nolint: errcheck
-			fmt.Sprintf("**Error: goroutine panic. This is a bug.**\n```\n%s\n%s```", err, stack))
-		ctx.Log.Err("PANIC: %s\n%s", err, stack)
+		logger.Err("PANIC: %s\n%s", err, stack)
+		if commentErr := c.VCSClient.CreateComment(
+			baseRepo,
+			pullNum,
+			fmt.Sprintf("**Error: goroutine panic. This is a bug.**\n```\n%s\n%s```", err, stack),
+		); commentErr != nil {
+			logger.Err("unable to comment: %s", commentErr)
+		}
 	}
 }

server/events/command_runner_test.go

@@ -14,12 +14,13 @@
 package events_test
 
 import (
-	"bytes"
 	"errors"
-	"log"
+	"fmt"
 	"strings"
 	"testing"
 
+	"github.com/runatlantis/atlantis/server/logging"
+
 	"github.com/google/go-github/github"
 	. "github.com/petergtz/pegomock"
 	"github.com/runatlantis/atlantis/server/events"
@@ -38,7 +39,7 @@ var ghStatus *mocks.MockCommitStatusUpdater
 var githubGetter *mocks.MockGithubPullGetter
 var gitlabGetter *mocks.MockGitlabMergeRequestGetter
 var ch events.DefaultCommandRunner
-var logBytes *bytes.Buffer
+var pullLogger *logging.SimpleLogger
 
 func setup(t *testing.T) *vcsmocks.MockClientProxy {
 	RegisterMockTestingT(t)
@@ -49,9 +50,11 @@ func setup(t *testing.T) *vcsmocks.MockClientProxy {
 	githubGetter = mocks.NewMockGithubPullGetter()
 	gitlabGetter = mocks.NewMockGitlabMergeRequestGetter()
 	logger := logmocks.NewMockSimpleLogging()
-	logBytes = new(bytes.Buffer)
+	pullLogger = logging.NewSimpleLogger("runatlantis/atlantis#1", true, logging.Info)
 	projectCommandRunner := mocks.NewMockProjectCommandRunner()
-	When(logger.Underlying()).ThenReturn(log.New(logBytes, "", 0))
+	When(logger.GetLevel()).ThenReturn(logging.Info)
+	When(logger.NewLogger("runatlantis/atlantis#1", true, logging.Info)).
+		ThenReturn(pullLogger)
 	ch = events.DefaultCommandRunner{
 		VCSClient:                vcsClient,
 		CommitStatusUpdater:      ghStatus,
@@ -71,28 +74,26 @@ func setup(t *testing.T) *vcsmocks.MockClientProxy {
 func TestRunCommentCommand_LogPanics(t *testing.T) {
 	t.Log("if there is a panic it is commented back on the pull request")
 	vcsClient := setup(t)
-	ch.AllowForkPRs = true // Lets us get to the panic code.
-	defer func() { ch.AllowForkPRs = false }()
-	When(ghStatus.Update(fixtures.GithubRepo, fixtures.Pull, models.PendingCommitStatus, events.PlanCommand)).ThenPanic("panic")
-	ch.RunCommentCommand(fixtures.GithubRepo, &fixtures.GithubRepo, nil, fixtures.User, 1, nil)
+	When(githubGetter.GetPullRequest(fixtures.GithubRepo, fixtures.Pull.Num)).ThenPanic("OMG PANIC!!!")
+	ch.RunCommentCommand(fixtures.GithubRepo, &fixtures.GithubRepo, nil, fixtures.User, 1, &events.CommentCommand{Name: events.PlanCommand})
 	_, _, comment := vcsClient.VerifyWasCalledOnce().CreateComment(matchers.AnyModelsRepo(), AnyInt(), AnyString()).GetCapturedArguments()
-	Assert(t, strings.Contains(comment, "Error: goroutine panic"), "comment should be about a goroutine panic")
+	Assert(t, strings.Contains(comment, "Error: goroutine panic"), fmt.Sprintf("comment should be about a goroutine panic but was %q", comment))
 }
 
 func TestRunCommentCommand_NoGithubPullGetter(t *testing.T) {
 	t.Log("if DefaultCommandRunner was constructed with a nil GithubPullGetter an error should be logged")
 	setup(t)
 	ch.GithubPullGetter = nil
 	ch.RunCommentCommand(fixtures.GithubRepo, &fixtures.GithubRepo, nil, fixtures.User, 1, nil)
-	Equals(t, "[ERROR] runatlantis/atlantis#1: Atlantis not configured to support GitHub\n", logBytes.String())
+	Equals(t, "[EROR] Atlantis not configured to support GitHub\n", pullLogger.History.String())
 }
 
 func TestRunCommentCommand_NoGitlabMergeGetter(t *testing.T) {
 	t.Log("if DefaultCommandRunner was constructed with a nil GitlabMergeRequestGetter an error should be logged")
 	setup(t)
 	ch.GitlabMergeRequestGetter = nil
 	ch.RunCommentCommand(fixtures.GitlabRepo, &fixtures.GitlabRepo, nil, fixtures.User, 1, nil)
-	Equals(t, "[ERROR] runatlantis/atlantis#1: Atlantis not configured to support GitLab\n", logBytes.String())
+	Equals(t, "[EROR] Atlantis not configured to support GitLab\n", pullLogger.History.String())
 }
 
 func TestRunCommentCommand_GithubPullErr(t *testing.T) {

server/events_controller_e2e_test.go

@@ -260,7 +260,7 @@ func setupE2E(t *testing.T) (server.EventsController, *vcsmocks.MockClientProxy,
 	e2eGitlabGetter := mocks.NewMockGitlabMergeRequestGetter()
 
 	// Real dependencies.
-	logger := logging.NewSimpleLogger("server", nil, true, logging.Debug)
+	logger := logging.NewSimpleLogger("server", true, logging.Debug)
 	eventParser := &events.EventParser{
 		GithubUser:  "github-user",
 		GithubToken: "github-token",