Added tool name to printed logs. (#5988)

toolkit/tools/go.mod

@@ -12,7 +12,7 @@ require (
 	github.com/klauspost/pgzip v1.2.5
 	github.com/muesli/crunchy v0.4.0
 	github.com/rivo/tview v0.0.0-20200219135020-0ba8301b415c
-	github.com/sirupsen/logrus v1.8.1
+	github.com/sirupsen/logrus v1.9.3
 	github.com/stretchr/testify v1.7.1
 	github.com/ulikunitz/xz v0.5.10
 	golang.org/x/sys v0.0.0-20220722155257-8c9f86f7a55f

toolkit/tools/go.sum

@@ -51,11 +51,11 @@ github.com/rivo/tview v0.0.0-20200219135020-0ba8301b415c h1:Q1oRqcTvxE0hjV0Gw4bE
 github.com/rivo/tview v0.0.0-20200219135020-0ba8301b415c/go.mod h1:/rBeY22VG2QprWnEqG57IBC8biVu3i0DOIjRLc9I8H0=
 github.com/rivo/uniseg v0.1.0 h1:+2KBaVoUmb9XzDsrx/Ct0W/EYOSFf/nWTauy++DprtY=
 github.com/rivo/uniseg v0.1.0/go.mod h1:J6wj4VEh+S6ZtnVlnTBMWIodfgj8LQOQFoIToxlJtxc=
-github.com/sirupsen/logrus v1.8.1 h1:dJKuHgqk1NNQlqoA6BTlM1Wf9DOH3NBjQyu0h9+AZZE=
-github.com/sirupsen/logrus v1.8.1/go.mod h1:yWOB1SBYBC5VeMP7gHvWumXLIWorT60ONWic61uBYv0=
+github.com/sirupsen/logrus v1.9.3 h1:dueUQJ1C2q9oE3F7wvmSGAaVtTmUizReu6fjN8uqzbQ=
+github.com/sirupsen/logrus v1.9.3/go.mod h1:naHLuLoDiP4jHNo9R0sCBMtWGeIprob74mVsIT4qYEQ=
 github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
-github.com/stretchr/testify v1.2.2/go.mod h1:a8OnRcib4nhh0OaRAV+Yts87kKdq0PP7pXfy6kDkUVs=
 github.com/stretchr/testify v1.4.0/go.mod h1:j7eGeouHqKxXV5pUuKE4zz7dFj8WfuZ+81PSLYec5m4=
+github.com/stretchr/testify v1.7.0/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg=
 github.com/stretchr/testify v1.7.1 h1:5TQK59W5E3v0r2duFAb7P95B6hEeOyEnHRa8MjYSMTY=
 github.com/stretchr/testify v1.7.1/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg=
 github.com/ulikunitz/xz v0.5.10 h1:t92gobL9l3HE202wg3rlk19F6X+JOxl9BBrCCMYEYd8=
@@ -79,7 +79,7 @@ golang.org/x/sys v0.0.0-20190312061237-fead79001313/go.mod h1:h1NjWce9XRLGQEsW7w
 golang.org/x/sys v0.0.0-20190412213103-97732733099d/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/sys v0.0.0-20190626150813-e07cf5db2756/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/sys v0.0.0-20191018095205-727590c5006e/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
-golang.org/x/sys v0.0.0-20191026070338-33540a1f6037/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
+golang.org/x/sys v0.0.0-20220715151400-c0bba94af5f8/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.0.0-20220722155257-8c9f86f7a55f h1:v4INt8xihDGvnrfjMDVXGxw9wrfxYyCjk0KbXjhR55s=
 golang.org/x/sys v0.0.0-20220722155257-8c9f86f7a55f/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ=

toolkit/tools/internal/logger/log.go

@@ -8,22 +8,22 @@ package logger
 import (
 	"bufio"
 	"io"
-	"io/ioutil"
+	"log"
 	"os"
 	"path/filepath"
+	"runtime"
+	"strings"
 	"sync"
 
-	log "github.com/sirupsen/logrus"
-
-	"github.com/microsoft/CBL-Mariner/toolkit/tools/internal/logger/hooks/writerhook"
+	"github.com/sirupsen/logrus"
 )
 
 var (
 	// Log contains the shared Logger
-	Log *log.Logger
+	Log *logrus.Logger
 
-	stderrHook *writerhook.WriterHook
-	fileHook   *writerhook.WriterHook
+	stderrHook *writerHook
+	fileHook   *writerHook
 
 	// Valid log levels
 	levelsArray = []string{"panic", "fatal", "error", "warn", "info", "debug", "trace"}
@@ -45,13 +45,17 @@ const (
 	// FileFlagHelp is the suggested help message for the logfile flag
 	FileFlagHelp = "Path to the image's log file."
 
-	defaultLogFileLevel   = log.DebugLevel
-	defaultStderrLogLevel = log.InfoLevel
+	defaultLogFileLevel   = logrus.DebugLevel
+	defaultStderrLogLevel = logrus.InfoLevel
+	parentCallerLevel     = 1
 )
 
-// InitLogFile initializes the common logger with a file
-func InitLogFile(filePath string) (err error) {
-	const useColors = false
+// initLogFile initializes the common logger with a file
+func initLogFile(filePath string) (err error) {
+	const (
+		noToolName = ""
+		useColors  = false
+	)
 
 	err = os.MkdirAll(filepath.Dir(filePath), os.ModePerm)
 	if err != nil {
@@ -63,7 +67,7 @@ func InitLogFile(filePath string) (err error) {
 		return
 	}
 
-	fileHook = writerhook.NewWriterHook(file, defaultLogFileLevel, useColors)
+	fileHook = newWriterHook(file, defaultLogFileLevel, useColors, noToolName)
 	Log.Hooks.Add(fileHook)
 	Log.SetLevel(defaultLogFileLevel)
 
@@ -72,15 +76,12 @@ func InitLogFile(filePath string) (err error) {
 
 // InitStderrLog initializes the logger to print to stderr
 func InitStderrLog() {
-	const useColors = true
+	_, callerFilePath, _, ok := runtime.Caller(parentCallerLevel)
+	if !ok {
+		log.Panic("Failed to get caller info.")
+	}
 
-	Log = log.New()
-
-	// By default send all log messages through stderrHook
-	stderrHook = writerhook.NewWriterHook(os.Stderr, defaultStderrLogLevel, useColors)
-	Log.AddHook(stderrHook)
-	Log.SetLevel(defaultStderrLogLevel)
-	Log.SetOutput(ioutil.Discard)
+	initStderrLogInternal(callerFilePath)
 }
 
 // SetFileLogLevel sets the lowest log level for file output
@@ -99,10 +100,15 @@ func InitBestEffort(path string, level string) {
 		level = defaultStderrLogLevel.String()
 	}
 
-	InitStderrLog()
+	_, callerFilePath, _, ok := runtime.Caller(parentCallerLevel)
+	if !ok {
+		log.Panic("Failed to get caller info.")
+	}
+
+	initStderrLogInternal(callerFilePath)
 
 	if path != "" {
-		PanicOnError(InitLogFile(path), "Failed while setting log file (%s).", path)
+		PanicOnError(initLogFile(path), "Failed while setting log file (%s).", path)
 	}
 
 	PanicOnError(SetStderrLogLevel(level), "Failed while setting log level.")
@@ -169,12 +175,27 @@ func ReplaceStderrWriter(newOut io.Writer) (oldOut io.Writer) {
 }
 
 // ReplaceStderrFormatter replaces the stderr formatter and returns the old formatter
-func ReplaceStderrFormatter(newFormatter log.Formatter) (oldFormatter log.Formatter) {
+func ReplaceStderrFormatter(newFormatter logrus.Formatter) (oldFormatter logrus.Formatter) {
 	return stderrHook.ReplaceFormatter(newFormatter)
 }
 
-func setHookLogLevel(hook *writerhook.WriterHook, level string) (err error) {
-	logLevel, err := log.ParseLevel(level)
+func initStderrLogInternal(callerFilePath string) {
+	const useColors = true
+
+	Log = logrus.New()
+	Log.ReportCaller = true
+
+	toolName := strings.TrimSuffix(filepath.Base(callerFilePath), ".go")
+
+	// By default send all log messages through stderrHook
+	stderrHook = newWriterHook(os.Stderr, defaultStderrLogLevel, useColors, toolName)
+	Log.AddHook(stderrHook)
+	Log.SetLevel(defaultStderrLogLevel)
+	Log.SetOutput(io.Discard)
+}
+
+func setHookLogLevel(hook *writerHook, level string) (err error) {
+	logLevel, err := logrus.ParseLevel(level)
 	if err != nil {
 		return
 	}

toolkit/tools/internal/logger/writerhook.go

@@ -1,31 +1,48 @@
 // Copyright (c) Microsoft Corporation.
 // Licensed under the MIT License.
 
-package writerhook
+package logger
 
 import (
 	"fmt"
 	"io"
+	"runtime"
 	"sync"
 
 	"github.com/sirupsen/logrus"
 )
 
-// WriterHook is a hook to handle writing to a writer at a custom log level
-type WriterHook struct {
+// writerHook is a hook to handle writing to a writer at a custom log level
+type writerHook struct {
 	lock      sync.Mutex
 	level     logrus.Level
 	writer    io.Writer
 	formatter logrus.Formatter
 }
 
-// NewWriterHook returns new WriterHook
-func NewWriterHook(writer io.Writer, level logrus.Level, useColors bool) *WriterHook {
+// newWriterHook returns new writerHook
+func newWriterHook(writer io.Writer, level logrus.Level, useColors bool, toolName string) *writerHook {
 	formatter := &logrus.TextFormatter{
 		ForceColors: useColors,
+		CallerPrettyfier: func(frame *runtime.Frame) (function string, file string) {
+			return
+		},
 	}
 
-	return &WriterHook{
+	if toolName != "" {
+		formatter.CallerPrettyfier = func(frame *runtime.Frame) (function string, file string) {
+			const gray = 90
+
+			toolNameField := fmt.Sprintf("[%s]", toolName)
+			if useColors {
+				toolNameField = fmt.Sprintf("[\x1b[%dm%s\x1b[0m]", gray, toolName)
+			}
+
+			return "", toolNameField
+		}
+	}
+
+	return &writerHook{
 		level:     level,
 		writer:    writer,
 		formatter: formatter,
@@ -33,7 +50,7 @@ func NewWriterHook(writer io.Writer, level logrus.Level, useColors bool) *Writer
 }
 
 // Fire writes the log entry to the writer
-func (h *WriterHook) Fire(entry *logrus.Entry) (err error) {
+func (h *writerHook) Fire(entry *logrus.Entry) (err error) {
 	// Filter out entries that are at a higher level (more verbose) than the current filter
 	if entry.Level > h.level {
 		return
@@ -52,17 +69,17 @@ func (h *WriterHook) Fire(entry *logrus.Entry) (err error) {
 }
 
 // SetLevel sets the lowest log level
-func (h *WriterHook) SetLevel(level logrus.Level) {
+func (h *writerHook) SetLevel(level logrus.Level) {
 	h.level = level
 }
 
 // Levels returns configured log levels
-func (h *WriterHook) Levels() []logrus.Level {
+func (h *writerHook) Levels() []logrus.Level {
 	return logrus.AllLevels
 }
 
 // ReplaceWriter replaces the writer and returns the old one
-func (h *WriterHook) ReplaceWriter(newWriter io.Writer) (oldWriter io.Writer) {
+func (h *writerHook) ReplaceWriter(newWriter io.Writer) (oldWriter io.Writer) {
 	h.lock.Lock()
 	defer h.lock.Unlock()
 
@@ -73,7 +90,7 @@ func (h *WriterHook) ReplaceWriter(newWriter io.Writer) (oldWriter io.Writer) {
 }
 
 // ReplaceFormatter replaces the formatter used by the hook and returns the old formatter
-func (h *WriterHook) ReplaceFormatter(newFormatter logrus.Formatter) (oldFormatter logrus.Formatter) {
+func (h *writerHook) ReplaceFormatter(newFormatter logrus.Formatter) (oldFormatter logrus.Formatter) {
 	h.lock.Lock()
 	defer h.lock.Unlock()
 
@@ -84,6 +101,6 @@ func (h *WriterHook) ReplaceFormatter(newFormatter logrus.Formatter) (oldFormatt
 }
 
 // CurrentLevel returns the current log level for the hook
-func (h *WriterHook) CurrentLevel() logrus.Level {
+func (h *writerHook) CurrentLevel() logrus.Level {
 	return h.level
 }