Merge pull request #200 from commitdev/improved-debug-logging

Improved debug logging

cmd/init.go

@@ -6,6 +6,7 @@ import (
 	"github.com/commitdev/zero/internal/config/projectconfig"
 	initPrompts "github.com/commitdev/zero/internal/init"
 	"github.com/commitdev/zero/pkg/util/exit"
+	"github.com/commitdev/zero/pkg/util/flog"
 	"github.com/spf13/cobra"
 )
 
@@ -17,6 +18,7 @@ var initCmd = &cobra.Command{
 	Use:   "init",
 	Short: "Create new project with provided name and initialize configuration based on user input.",
 	Run: func(cmd *cobra.Command, args []string) {
+		flog.Debugf("Root directory is %s", projectconfig.RootDir)
 		projectContext := initPrompts.Init(projectconfig.RootDir)
 		projectConfigErr := projectconfig.CreateProjectConfigFile(projectconfig.RootDir, projectContext.Name, projectContext)
 

go.mod

@@ -20,6 +20,7 @@ require (
 	github.com/matryer/is v1.3.0 // indirect
 	github.com/mattn/go-colorable v0.1.2 // indirect
 	github.com/niemeyer/pretty v0.0.0-20200227124842-a10e7caefd8e // indirect
+	github.com/sirupsen/logrus v1.2.0
 	github.com/spf13/cobra v0.0.6
 	github.com/stretchr/testify v1.5.1
 	github.com/termie/go-shutil v0.0.0-20140729215957-bcacb06fecae

go.sum

@@ -331,6 +331,7 @@ github.com/satori/go.uuid v1.2.0/go.mod h1:dA0hQrYB0VpLJoorglMZABFdXlWrHn1NEOzdh
 github.com/sean-/seed v0.0.0-20170313163322-e2103e2c3529/go.mod h1:DxrIzT+xaE7yg65j358z/aeFdxmN0P9QXhEzd20vsDc=
 github.com/sergi/go-diff v1.0.0/go.mod h1:0CfEIISq7TuYL3j771MWULgwwjU+GofnZX9QAmXWZgo=
 github.com/shurcooL/sanitized_anchor_name v1.0.0/go.mod h1:1NzhyTcUVG4SuEtjjoZeVRXNmyL/1OwPU0+IJeTBvfc=
+github.com/sirupsen/logrus v1.2.0 h1:juTguoYk5qI21pwyTXY3B3Y5cOTH3ZUyZCg1v/mihuo=
 github.com/sirupsen/logrus v1.2.0/go.mod h1:LxeOpSwHxABJmUn/MG1IvRgCAasNZTLOkJPxbbu5VWo=
 github.com/smartystreets/assertions v0.0.0-20180927180507-b2de0cb4f26d/go.mod h1:OnSkiWE9lh6wB0YB77sQom3nweQdgAjqCqsofrRNTgc=
 github.com/smartystreets/goconvey v0.0.0-20180222194500-ef6db91d284a/go.mod h1:XDJAKZRPZ1CvBcN2aX5YOUTYGHki24fSF0Iv48Ibg0s=
@@ -392,6 +393,7 @@ golang.org/x/crypto v0.0.0-20190222235706-ffb98f73852f/go.mod h1:6SG95UA2DQfeDnf
 golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w=
 golang.org/x/crypto v0.0.0-20190426145343-a29dc8fdc734/go.mod h1:yigFU9vqHzYiE8UmvKecakEJjdnWj3jj499lnFckfCI=
 golang.org/x/crypto v0.0.0-20190605123033-f99c8df09eb5/go.mod h1:yigFU9vqHzYiE8UmvKecakEJjdnWj3jj499lnFckfCI=
+golang.org/x/crypto v0.0.0-20200510223506-06a226fb4e37 h1:cg5LA/zNPRzIXIWSCxQW10Rvpy94aQh3LT/ShoCpkHw=
 golang.org/x/crypto v0.0.0-20200510223506-06a226fb4e37/go.mod h1:LzIPMQfyMNhhGPhUkYOs5KpL4U8rLKemX1yGLhDgUto=
 golang.org/x/exp v0.0.0-20190121172915-509febef88a4/go.mod h1:CJ0aWSM057203Lf6IL+f9T1iT9GByDxfZKAQTCR3kQA=
 golang.org/x/exp v0.0.0-20190510132918-efd6b22b2522/go.mod h1:ZjyILWgesfNpC6sMxTJOJm9Kp84zZh5NQWvqDGG3Qr8=

internal/apply/apply.go

@@ -78,6 +78,7 @@ func applyAll(dir string, projectConfig projectconfig.ZeroProjectConfig, applyEn
 		if module.IsLocal(mod.Files.Source) && !filepath.IsAbs(modulePath) {
 			modulePath = filepath.Join(dir, modulePath)
 		}
+		flog.Debugf("Loaded module: %s from %s", name, modulePath)
 
 		// TODO: in the case user lost the `/tmp` (module source dir), this will fail
 		// and we should redownload the module for the user
@@ -91,6 +92,7 @@ func applyAll(dir string, projectConfig projectconfig.ZeroProjectConfig, applyEn
 		credentialEnvs := credentials.SelectedVendorsCredentialsAsEnv(modConfig.RequiredCredentials)
 		envList = util.AppendProjectEnvToCmdEnv(mod.Parameters, envList)
 		envList = util.AppendProjectEnvToCmdEnv(credentialEnvs, envList)
+		flog.Debugf("Env injected: %#v", envList)
 		util.ExecuteCommand(exec.Command("make"), modulePath, envList)
 		return nil
 	})
@@ -158,8 +160,10 @@ func summarizeAll(dir string, projectConfig projectconfig.ZeroProjectConfig, app
 		if module.IsLocal(mod.Files.Source) && !filepath.IsAbs(modulePath) {
 			modulePath = filepath.Join(dir, modulePath)
 		}
+		flog.Debugf("Loaded module: %s from %s", name, modulePath)
 
 		envList = util.AppendProjectEnvToCmdEnv(mod.Parameters, envList)
+		flog.Debugf("Env injected: %#v", envList)
 		util.ExecuteCommand(exec.Command("make", "summary"), modulePath, envList)
 		return nil
 	})

internal/config/globalconfig/global_config.go

@@ -13,6 +13,7 @@ import (
 	"github.com/commitdev/zero/internal/constants"
 	"github.com/commitdev/zero/internal/util"
 	"github.com/commitdev/zero/pkg/util/exit"
+	"github.com/commitdev/zero/pkg/util/flog"
 	yaml "gopkg.in/yaml.v2"
 )
 
@@ -140,12 +141,14 @@ func readOrCreateUserCredentialsFile() []byte {
 		if fileStateErr != nil {
 			exit.Fatal("Failed to create config file: %v", fileStateErr)
 		}
+		flog.Debugf("Created credentials file: %s", credPath)
 		defer file.Close()
 	}
 	data, err := ioutil.ReadFile(credPath)
 	if err != nil {
 		exit.Fatal("Failed to read credentials file: %v", err)
 	}
+	flog.Debugf("Loaded credentials file: %s", credPath)
 	return data
 }
 
@@ -166,6 +169,7 @@ func GetProjectCredentials(targetProjectName string) ProjectCredential {
 func Save(project ProjectCredential) {
 	projects := LoadUserCredentials()
 	projects[project.ProjectName] = project
+	flog.Debugf("Saved project credentials : %s", project.ProjectName)
 	writeCredentialsFile(projects)
 }
 

internal/config/projectconfig/init.go

@@ -9,6 +9,7 @@ import (
 
 	"github.com/commitdev/zero/internal/constants"
 	"github.com/commitdev/zero/internal/util"
+	"github.com/commitdev/zero/pkg/util/flog"
 	"gopkg.in/yaml.v2"
 )
 
@@ -35,7 +36,9 @@ func CreateProjectConfigFile(dir string, projectName string, projectContext *Zer
 		return err
 	}
 
-	writeErr := ioutil.WriteFile(path.Join(dir, projectName, constants.ZeroProjectYml), []byte(content), 0644)
+	filePath := path.Join(dir, projectName, constants.ZeroProjectYml)
+	flog.Debugf("Project file path: %s", filePath)
+	writeErr := ioutil.WriteFile(filePath, []byte(content), 0644)
 	if writeErr != nil {
 		return err
 	}

internal/config/projectconfig/project_config.go

@@ -4,6 +4,7 @@ import (
 	"io/ioutil"
 	"log"
 
+	"github.com/commitdev/zero/pkg/util/flog"
 	"github.com/hashicorp/terraform/dag"
 	"github.com/k0kubun/pp"
 	yaml "gopkg.in/yaml.v2"
@@ -45,7 +46,7 @@ func LoadConfig(filePath string) *ZeroProjectConfig {
 	if err != nil {
 		log.Panicf("failed to parse config: %v", err)
 	}
-
+	flog.Debugf("Loaded project config: %s from %s", config.Name, filePath)
 	return config
 }
 

internal/init/prompts.go

@@ -154,10 +154,11 @@ func executeCmd(command string, envVars map[string]string) string {
 	cmd := exec.Command("bash", "-c", command)
 	cmd.Env = util.AppendProjectEnvToCmdEnv(envVars, os.Environ())
 	out, err := cmd.Output()
-
+	flog.Debugf("Running command: %s", command)
 	if err != nil {
 		log.Fatalf("Failed to execute  %v\n", err)
 	}
+	flog.Debugf("Command result: %s", string(out))
 	return string(out)
 }
 

internal/module/module.go

@@ -13,6 +13,7 @@ import (
 	"github.com/commitdev/zero/internal/constants"
 	"github.com/commitdev/zero/internal/util"
 	"github.com/commitdev/zero/pkg/util/exit"
+	"github.com/commitdev/zero/pkg/util/flog"
 	"github.com/hashicorp/go-getter"
 )
 
@@ -22,6 +23,7 @@ func FetchModule(source string, wg *sync.WaitGroup) {
 
 	localPath := GetSourceDir(source)
 	if !IsLocal(source) {
+		flog.Debugf("Downloading module: %s to %s", source, localPath)
 		err := getter.Get(localPath, source)
 		if err != nil {
 			exit.Fatal("Failed to fetch remote module from %s: %v\n", source, err)

internal/vcs/create-git-repos.go

@@ -20,6 +20,7 @@ func InitializeRepository(repositoryUrl string, githubApiKey string) {
 		fmt.Printf("error creating repository: %s\n", err.Error())
 		return
 	}
+	flog.Debugf("Initialized repo: %s/%s", ownerName, repositoryName)
 
 	isOrgOwned, ownerId, err := isOrganizationOwned(ownerName, githubApiKey)
 	if err != nil {
@@ -190,6 +191,7 @@ func doInitialCommit(ownerName string, repositoryName string) error {
 
 		cmd := exec.Command(command.command, command.args...)
 		cmd.Dir = "./" + repositoryName
+		flog.Debugf("Running (%s) command in %s, %#v", command.command, cmd.Dir, command.args)
 		_, err := cmd.CombinedOutput()
 		if err != nil {
 			fmt.Printf("ERROR: failed to run %s: %s\n", command.description, err.Error())

pkg/util/flog/log.go

@@ -2,15 +2,46 @@ package flog
 
 import (
 	"fmt"
-	"log"
+	"os"
 
 	"github.com/kyokomi/emoji"
 	"github.com/logrusorgru/aurora"
+	"github.com/sirupsen/logrus"
 )
 
+const LogEnvVariable = "LOG_LEVEL"
+const defaultLogLevel = "info"
+
+var logger = getLogger()
+var infoFormatter = new(InfoFormatter)
+var debugFormatter = &logrus.TextFormatter{
+	DisableLevelTruncation:    true,
+	FullTimestamp:             true,
+	EnvironmentOverrideColors: true,
+}
+
+func getLogger() *logrus.Logger {
+	logger := logrus.New()
+
+	lvl, ok := os.LookupEnv(LogEnvVariable)
+	if !ok {
+		lvl = defaultLogLevel
+	}
+	logLevel, _ := logrus.ParseLevel(lvl)
+	logger.SetOutput(os.Stdout)
+	logger.SetLevel(logLevel)
+	return logger
+}
+
 // Warnf logs a formatted error message
 func Infof(format string, a ...interface{}) {
-	log.Println(aurora.Cyan(emoji.Sprintf(format, a...)))
+	logger.SetFormatter(infoFormatter)
+	logger.Info(aurora.Cyan(emoji.Sprintf(format, a...)))
+}
+
+func Debugf(format string, a ...interface{}) {
+	logger.SetFormatter(debugFormatter)
+	logger.Debug(aurora.Green(emoji.Sprintf(format, a...)))
 }
 
 // Infof prints out a timestamp as prefix, Guidef just prints the message
@@ -20,15 +51,24 @@ func Guidef(format string, a ...interface{}) {
 
 // Successf logs a formatted success message
 func Successf(format string, a ...interface{}) {
-	log.Println(aurora.Green(emoji.Sprintf(":white_check_mark: "+format, a...)))
+	logger.Info(aurora.Green(emoji.Sprintf(":white_check_mark: "+format, a...)))
 }
 
 // Warnf logs a formatted warning message
 func Warnf(format string, a ...interface{}) {
-	log.Println(aurora.Yellow(emoji.Sprintf(":exclamation: "+format, a...)))
+	logger.Warn(aurora.Yellow(emoji.Sprintf(":exclamation: "+format, a...)))
 }
 
 // Warnf logs a formatted error message
 func Errorf(format string, a ...interface{}) {
-	log.Println(aurora.Red(emoji.Sprintf(":exclamation: "+format, a...)))
+	logger.Error(aurora.Red(emoji.Sprintf(":exclamation: "+format, a...)))
+}
+
+// Info formatter is to not display the LOG_LEVEL in front of the command eg. INFO[2020-070-01T15:22:22] Hello World
+type InfoFormatter struct {
+}
+
+func (f *InfoFormatter) Format(entry *logrus.Entry) ([]byte, error) {
+	// extra line break stops the prompts from overtaking Existing line
+	return []byte(entry.Message + "\n"), nil
 }