Removes logrus package and refactors logging messages (#5293)

This fix removes logrus package dependency and refactors the console
logging as the only logging mechanism by removing file logging support.
It rearranges the log message format and adds stack trace information
whenever trace information is not available in the error structure.
It also adds `--json` flag support for server logging.
When minio server is started with `--json` flag, all log messages are
displayed in json format, with no start-up and informational log
messages.
Fixes #5265 #5220 #5197

cmd/config-migrate.go

@@ -1147,14 +1147,6 @@ func migrateV15ToV16() error {
 	// Load browser config from existing config in the file.
 	srvConfig.Browser = cv15.Browser
 
-	// Migrate console and file fields
-	if cv15.Logger.Console.Enable {
-		srvConfig.Logger.Console = NewConsoleLogger()
-	}
-	if cv15.Logger.File.Enable {
-		srvConfig.Logger.File = NewFileLogger(cv15.Logger.File.Filename)
-	}
-
 	if err = quick.Save(configFile, srvConfig); err != nil {
 		return fmt.Errorf("Failed to migrate config from ‘%s’ to ‘%s’. %v", cv15.Version, srvConfig.Version, err)
 	}

cmd/config-versions.go

@@ -418,6 +418,21 @@ type serverConfigV15 struct {
 	Notify *notifier `json:"notify"`
 }
 
+// FileLogger is introduced to workaround the dependency about logrus
+type FileLogger struct {
+	Enable   bool   `json:"enable"`
+	Filename string `json:"filename"`
+}
+
+// ConsoleLogger is introduced to workaround the dependency about logrus
+type ConsoleLogger struct {
+	Enable bool `json:"enable"`
+}
+
+// Loggers struct is defined with FileLogger and ConsoleLogger
+// although they are removed from logging logic. They are
+// kept here just to workaround the dependency migration
+// code/logic has on them.
 type loggers struct {
 	sync.RWMutex
 	Console ConsoleLogger `json:"console"`

cmd/console-logger.go

@@ -1,74 +0,0 @@
-/*
- * Minio Cloud Storage, (C) 2017 Minio, Inc.
- *
- * Licensed under the Apache License, Version 2.0 (the "License");
- * you may not use this file except in compliance with the License.
- * You may obtain a copy of the License at
- *
- *     http://www.apache.org/licenses/LICENSE-2.0
- *
- * Unless required by applicable law or agreed to in writing, software
- * distributed under the License is distributed on an "AS IS" BASIS,
- * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
- * See the License for the specific language governing permissions and
- * limitations under the License.
- */
-
-package cmd
-
-import (
-	"fmt"
-	"os"
-
-	"github.com/Sirupsen/logrus"
-)
-
-// ConsoleLogger - console logger which logs into stderr.
-type ConsoleLogger struct {
-	BaseLogTarget
-}
-
-// Fire - log entry handler.
-func (logger ConsoleLogger) Fire(entry *logrus.Entry) error {
-	if !logger.Enable {
-		return nil
-	}
-
-	msgBytes, err := logger.formatter.Format(entry)
-	if err == nil {
-		fmt.Fprintf(os.Stderr, string(msgBytes))
-	}
-
-	return err
-}
-
-// String - represents ConsoleLogger as string.
-func (logger ConsoleLogger) String() string {
-	enableStr := "disabled"
-	if logger.Enable {
-		enableStr = "enabled"
-	}
-
-	return fmt.Sprintf("console:%s", enableStr)
-}
-
-// NewConsoleLogger - return new console logger object.
-func NewConsoleLogger() (logger ConsoleLogger) {
-	logger.Enable = true
-	logger.formatter = new(logrus.TextFormatter)
-
-	return logger
-}
-
-// InitConsoleLogger - initializes console logger.
-func InitConsoleLogger(logger *ConsoleLogger) {
-	if !logger.Enable {
-		return
-	}
-
-	if logger.formatter == nil {
-		logger.formatter = new(logrus.TextFormatter)
-	}
-
-	return
-}

cmd/file-logger.go

@@ -1,86 +0,0 @@
-/*
- * Minio Cloud Storage, (C) 2017 Minio, Inc.
- *
- * Licensed under the Apache License, Version 2.0 (the "License");
- * you may not use this file except in compliance with the License.
- * You may obtain a copy of the License at
- *
- *     http://www.apache.org/licenses/LICENSE-2.0
- *
- * Unless required by applicable law or agreed to in writing, software
- * distributed under the License is distributed on an "AS IS" BASIS,
- * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
- * See the License for the specific language governing permissions and
- * limitations under the License.
- */
-
-package cmd
-
-import (
-	"fmt"
-	"os"
-
-	"github.com/Sirupsen/logrus"
-)
-
-// FileLogger - file logger which logs to a file.
-type FileLogger struct {
-	BaseLogTarget
-	Filename string `json:"filename"`
-	file     *os.File
-}
-
-// Fire - log entry handler.
-func (logger FileLogger) Fire(entry *logrus.Entry) (err error) {
-	if !logger.Enable {
-		return nil
-	}
-
-	msgBytes, err := logger.formatter.Format(entry)
-	if err != nil {
-		return err
-	}
-
-	if _, err = logger.file.Write(msgBytes); err != nil {
-		return err
-	}
-
-	err = logger.file.Sync()
-	return err
-}
-
-// String - represents ConsoleLogger as string.
-func (logger FileLogger) String() string {
-	enableStr := "disabled"
-	if logger.Enable {
-		enableStr = "enabled"
-	}
-
-	return fmt.Sprintf("file:%s:%s", enableStr, logger.Filename)
-}
-
-// NewFileLogger - creates new file logger object.
-func NewFileLogger(filename string) (logger FileLogger) {
-	logger.Enable = true
-	logger.formatter = new(logrus.JSONFormatter)
-	logger.Filename = filename
-
-	return logger
-}
-
-// InitFileLogger - initializes file logger.
-func InitFileLogger(logger *FileLogger) (err error) {
-	if !logger.Enable {
-		return err
-	}
-
-	if logger.formatter == nil {
-		logger.formatter = new(logrus.JSONFormatter)
-	}
-
-	if logger.file == nil {
-		logger.file, err = os.OpenFile(logger.Filename, os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0664)
-	}
-
-	return err
-}

cmd/gateway-main.go

@@ -112,6 +112,13 @@ func StartGateway(ctx *cli.Context, gw Gateway) {
 		cli.ShowCommandHelpAndExit(ctx, gatewayName, 1)
 	}
 
+	// Get "json" flag from command line argument and
+	// enable json and quite modes if jason flag is turned on.
+	jsonFlag := ctx.Bool("json") || ctx.GlobalBool("json")
+	if jsonFlag {
+		log.EnableJSON()
+	}
+
 	// Get quiet flag from command line argument.
 	quietFlag := ctx.Bool("quiet") || ctx.GlobalBool("quiet")
 	if quietFlag {

cmd/globals.go

@@ -174,6 +174,7 @@ var (
 	colorBold   = color.New(color.Bold).SprintFunc()
 	colorBlue   = color.New(color.FgBlue).SprintfFunc()
 	colorYellow = color.New(color.FgYellow).SprintfFunc()
+	colorRed    = color.New(color.FgRed).SprintfFunc()
 )
 
 // Returns minio global information, as a key value map.

cmd/logger.go

@@ -17,78 +17,68 @@
 package cmd
 
 import (
+	"encoding/json"
 	"fmt"
-	"io/ioutil"
+	"os"
-	"path"
+	"path/filepath"
 	"runtime"
 	"strings"
+	"time"
 
-	"github.com/Sirupsen/logrus"
 	"github.com/minio/mc/pkg/console"
 	"github.com/minio/minio/pkg/errors"
 )
 
 var log = NewLogger()
+var trimStrings []string
 
-// LogTarget - interface for log target.
+// Level type
-type LogTarget interface {
+type Level int8
-	Fire(entry *logrus.Entry) error
-	String() string
-}
 
-// BaseLogTarget - base log target.
+// Enumerated level types
-type BaseLogTarget struct {
+const (
-	Enable    bool `json:"enable"`
+	Error Level = iota + 1
-	formatter logrus.Formatter
+	Fatal
-}
+)
 
-// Logger - higher level logger.
+func (level Level) String() string {
-type Logger struct {
+	var lvlStr string
-	logger        *logrus.Logger
+	switch level {
-	consoleTarget ConsoleLogger
+	case Error:
-	targets       []LogTarget
+		lvlStr = "ERROR"
-	quiet         bool
+	case Fatal:
+		lvlStr = "FATAL"
+	}
+	return lvlStr
 }
 
-// AddTarget - add logger to this hook.
+type logEntry struct {
-func (log *Logger) AddTarget(logTarget LogTarget) {
+	Level   string   `json:"level"`
-	log.targets = append(log.targets, logTarget)
+	Message string   `json:"message"`
+	Time    string   `json:"time"`
+	Cause   string   `json:"cause"`
+	Trace   []string `json:"trace"`
 }
 
-// SetConsoleTarget - sets console target to this hook.
+// Logger - for console messages
-func (log *Logger) SetConsoleTarget(consoleTarget ConsoleLogger) {
+type Logger struct {
-	log.consoleTarget = consoleTarget
+	quiet bool
+	json  bool
 }
 
-// Fire - log entry handler to save logs.
+// NewLogger - to create a new Logger object
-func (log *Logger) Fire(entry *logrus.Entry) (err error) {
+func NewLogger() *Logger {
-	if err = log.consoleTarget.Fire(entry); err != nil {
+	return &Logger{}
-		log.Printf("Unable to log to console target. %s\n", err)
-	}
-
-	for _, logTarget := range log.targets {
-		if err = logTarget.Fire(entry); err != nil {
-			log.Printf("Unable to log to target %s. %s\n", logTarget, err)
-		}
-	}
-
-	return err
 }
 
-// Levels - returns list of log levels support.
+// EnableQuiet - turns quiet option on.
-func (log *Logger) Levels() []logrus.Level {
+func (log *Logger) EnableQuiet() {
-	return []logrus.Level{
+	log.quiet = true
-		logrus.PanicLevel,
-		logrus.FatalLevel,
-		logrus.ErrorLevel,
-		logrus.WarnLevel,
-		logrus.InfoLevel,
-		logrus.DebugLevel,
-	}
 }
 
-// EnableQuiet - sets quiet option.
+// EnableJSON - outputs logs in json format.
-func (log *Logger) EnableQuiet() {
+func (log *Logger) EnableJSON() {
+	log.json = true
 	log.quiet = true
 }
 
@@ -106,38 +96,66 @@ func (log *Logger) Printf(format string, args ...interface{}) {
 	}
 }
 
-// NewLogger - returns a new initialized logger.
+func init() {
-func NewLogger() *Logger {
+	var goPathList []string
-	logger := logrus.New()
+	// Add all possible GOPATH paths into trimStrings
-	logger.Out = ioutil.Discard
+	// Split GOPATH depending on the OS type
-	logger.Level = logrus.DebugLevel
+	if runtime.GOOS == "windows" {
-
+		goPathList = strings.Split(GOPATH, ";")
-	l := &Logger{
+	} else {
-		logger:        logger,
+		// All other types of OSs
-		consoleTarget: NewConsoleLogger(),
+		goPathList = strings.Split(GOPATH, ":")
 	}
 
-	// Adds a console logger.
+	// Add trim string "{GOROOT}/src/" into trimStrings
-	logger.Hooks.Add(l)
+	trimStrings = []string{filepath.Join(runtime.GOROOT(), "src") + string(filepath.Separator)}
 
-	return l
+	// Add all possible path from GOPATH=path1:path2...:pathN
+	// as "{path#}/src/" into trimStrings
+	for _, goPathString := range goPathList {
+		trimStrings = append(trimStrings, filepath.Join(goPathString, "src")+string(filepath.Separator))
+	}
+	// Add "github.com/minio/minio" as the last to cover
+	// paths like "{GOROOT}/src/github.com/minio/minio"
+	// and "{GOPATH}/src/github.com/minio/minio"
+	trimStrings = append(trimStrings, filepath.Join("github.com", "minio", "minio")+string(filepath.Separator))
 }
 
-func getSource() string {
+func trimTrace(f string) string {
-	var funcName string
+	for _, trimString := range trimStrings {
-	pc, filename, lineNum, ok := runtime.Caller(2)
+		f = strings.TrimPrefix(filepath.ToSlash(f), filepath.ToSlash(trimString))
-	if ok {
-		filename = path.Base(filename)
-		funcName = strings.TrimPrefix(runtime.FuncForPC(pc).Name(), "github.com/minio/minio/cmd.")
-	} else {
-		filename = "<unknown>"
-		lineNum = 0
 	}
+	return filepath.FromSlash(f)
+}
 
-	return fmt.Sprintf("[%s:%d:%s()]", filename, lineNum, funcName)
+// getTrace method - creates and returns stack trace
+func getTrace(traceLevel int) []string {
+	var trace []string
+	pc, file, lineNumber, ok := runtime.Caller(traceLevel)
+
+	for ok {
+		// Clean up the common prefixes
+		file = trimTrace(file)
+		// Get the function name
+		_, funcName := filepath.Split(runtime.FuncForPC(pc).Name())
+		// Skip duplicate traces that start with file name, "<autogenerated>"
+		// and also skip traces with function name that starts with "runtime."
+		if !strings.HasPrefix(file, "<autogenerated>") &&
+			!strings.HasPrefix(funcName, "runtime.") {
+			// Form and append a line of stack trace into a
+			// collection, 'trace', to build full stack trace
+			trace = append(trace, fmt.Sprintf("%v:%v:%v()", file, lineNumber, funcName))
+		}
+		traceLevel++
+		// Read stack trace information from PC
+		pc, file, lineNumber, ok = runtime.Caller(traceLevel)
+	}
+	return trace
 }
 
-func logIf(level logrus.Level, source string, err error, msg string, data ...interface{}) {
+func logIf(level Level, err error, msg string,
+	data ...interface{}) {
+
 	isErrIgnored := func(err error) (ok bool) {
 		err = errors.Cause(err)
 		switch err.(type) {
@@ -154,36 +172,51 @@ func logIf(level logrus.Level, source string, err error, msg string, data ...int
 	if err == nil || isErrIgnored(err) {
 		return
 	}
+	cause := strings.Title(err.Error())
+	// Get full stack trace
+	trace := getTrace(3)
+	// Get time
+	timeOfError := UTCNow().Format(time.RFC3339Nano)
+	// Output the formatted log message at console
+	var output string
+	message := fmt.Sprintf(msg, data...)
+	if log.json {
+		logJSON, err := json.Marshal(&logEntry{
+			Level:   level.String(),
+			Message: message,
+			Time:    timeOfError,
+			Cause:   cause,
+			Trace:   trace,
+		})
+		if err != nil {
+			panic("json marshal of logEntry failed: " + err.Error())
+		}
+		output = string(logJSON)
+	} else {
+		// Add a sequence number and formatting for each stack trace
+		// No formatting is required for the first entry
+		trace[0] = "1: " + trace[0]
+		for i, element := range trace[1:] {
+			trace[i+1] = fmt.Sprintf("%8v: %s", i+2, element)
+		}
+		errMsg := fmt.Sprintf("[%s] [%s] %s (%s)",
+			timeOfError, level.String(), message, cause)
 
-	fields := logrus.Fields{
+		output = fmt.Sprintf("\nTrace: %s\n%s",
-		"source": source,
+			strings.Join(trace, "\n"),
-		"cause":  err.Error(),
+			colorRed(colorBold(errMsg)))
-	}
-
-	if terr, ok := err.(*errors.Error); ok {
-		fields["stack"] = strings.Join(terr.Stack(), " ")
 	}
+	fmt.Println(output)
 
-	switch level {
+	if level == Fatal {
-	case logrus.PanicLevel:
+		os.Exit(1)
-		log.logger.WithFields(fields).Panicf(msg, data...)
-	case logrus.FatalLevel:
-		log.logger.WithFields(fields).Fatalf(msg, data...)
-	case logrus.ErrorLevel:
-		log.logger.WithFields(fields).Errorf(msg, data...)
-	case logrus.WarnLevel:
-		log.logger.WithFields(fields).Warnf(msg, data...)
-	case logrus.InfoLevel:
-		log.logger.WithFields(fields).Infof(msg, data...)
-	default:
-		log.logger.WithFields(fields).Debugf(msg, data...)
 	}
 }
 
 func errorIf(err error, msg string, data ...interface{}) {
-	logIf(logrus.ErrorLevel, getSource(), err, msg, data...)
+	logIf(Error, err, msg, data...)
 }
 
 func fatalIf(err error, msg string, data ...interface{}) {
-	logIf(logrus.FatalLevel, getSource(), err, msg, data...)
+	logIf(Fatal, err, msg, data...)
 }

cmd/logger_test.go

@@ -1,31 +0,0 @@
-/*
- * Minio Cloud Storage (C) 2015, 2016, 2017 Minio, Inc.
- *
- * Licensed under the Apache License, Version 2.0 (the "License");
- * you may not use this file except in compliance with the License.
- * You may obtain a copy of the License at
- *
- *     http://www.apache.org/licenses/LICENSE-2.0
- *
- * Unless required by applicable law or agreed to in writing, software
- * distributed under the License is distributed on an "AS IS" BASIS,
- * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
- * See the License for the specific language governing permissions and
- * limitations under the License.
- */
-
-package cmd
-
-import (
-	"testing"
-)
-
-// Tests getSource().
-func TestGetSource(t *testing.T) {
-	currentSource := func() string { return getSource() }
-	gotSource := currentSource()
-	expectedSource := "[logger_test.go:26:TestGetSource()]"
-	if gotSource != expectedSource {
-		t.Errorf("expected : %s, got : %s", expectedSource, gotSource)
-	}
-}

cmd/main.go

@@ -38,6 +38,10 @@ var globalFlags = []cli.Flag{
 		Name:  "quiet",
 		Usage: "Disable startup information.",
 	},
+	cli.BoolFlag{
+		Name:  "json",
+		Usage: "Output server logs and startup information in json format.",
+	},
 }
 
 // Help template for minio.

cmd/namespace-lock.go

@@ -19,6 +19,8 @@ package cmd
 import (
 	"errors"
 	pathutil "path"
+	"runtime"
+	"strings"
 	"sync"
 
 	"fmt"
@@ -366,3 +368,18 @@ func (li *lockInstance) RUnlock() {
 	readLock := true
 	li.ns.unlock(li.volume, li.path, li.opsID, readLock)
 }
+
+func getSource() string {
+	var funcName string
+	pc, filename, lineNum, ok := runtime.Caller(2)
+	if ok {
+		filename = pathutil.Base(filename)
+		funcName = strings.TrimPrefix(runtime.FuncForPC(pc).Name(),
+			"github.com/minio/minio/cmd.")
+	} else {
+		filename = "<unknown>"
+		lineNum = 0
+	}
+
+	return fmt.Sprintf("[%s:%d:%s()]", filename, lineNum, funcName)
+}

cmd/namespace-lock_test.go

@@ -21,6 +21,22 @@ import (
 	"time"
 )
 
+// WARNING:
+//
+// Expected source line number is hard coded, 32, in the
+// following test. Adding new code before this test or changing its
+// position will cause the line number to change and the test to FAIL
+// Tests getSource().
+func TestGetSource(t *testing.T) {
+	currentSource := func() string { return getSource() }
+	gotSource := currentSource()
+	// Hard coded line number, 32, in the "expectedSource" value
+	expectedSource := "[namespace-lock_test.go:32:TestGetSource()]"
+	if gotSource != expectedSource {
+		t.Errorf("expected : %s, got : %s", expectedSource, gotSource)
+	}
+}
+
 // Tests functionality provided by namespace lock.
 func TestNamespaceLockTest(t *testing.T) {
 	// List of test cases.

cmd/prepare-storage-msg.go

@@ -21,7 +21,6 @@ import (
 	"sync"
 
 	humanize "github.com/dustin/go-humanize"
-	"github.com/minio/mc/pkg/console"
 )
 
 // Helper to generate integer sequences into a friendlier user consumable format.
@@ -44,7 +43,7 @@ func printOnceFn() printOnceFunc {
 	var once sync.Once
 	return func(msg string) {
 		once.Do(func() {
-			console.Println(msg)
+			log.Println(msg)
 		})
 	}
 }
@@ -91,7 +90,7 @@ func getHealMsg(endpoints EndpointList, storageDisks []StorageAPI) string {
 
 // Prints regular message when we have sufficient disks to start the cluster.
 func printRegularMsg(endpoints EndpointList, storageDisks []StorageAPI, fn printOnceFunc) {
-	msg := getStorageInitMsg("\nInitializing data volume.", endpoints, storageDisks)
+	msg := getStorageInitMsg("Initializing data volume.", endpoints, storageDisks)
 	fn(msg)
 }
 
@@ -121,7 +120,7 @@ func getStorageInitMsg(titleMsg string, endpoints EndpointList, storageDisks []S
 
 // Prints initialization message when cluster is being initialized for the first time.
 func printFormatMsg(endpoints EndpointList, storageDisks []StorageAPI, fn printOnceFunc) {
-	msg := getStorageInitMsg("\nInitializing data volume for the first time.", endpoints, storageDisks)
+	msg := getStorageInitMsg("Initializing data volume for the first time.", endpoints, storageDisks)
 	fn(msg)
 }
 

cmd/prepare-storage.go

@@ -20,7 +20,6 @@ import (
 	"fmt"
 	"time"
 
-	"github.com/minio/mc/pkg/console"
 	"github.com/minio/minio/pkg/errors"
 )
 
@@ -289,11 +288,9 @@ func retryFormattingXLDisks(firstDisk bool, endpoints EndpointList, storageDisks
 			case Abort:
 				return reduceInitXLErrs(storageDisks, sErrs)
 			case FormatDisks:
-				console.Eraseline()
 				printFormatMsg(endpoints, storageDisks, printOnceFn())
 				return initFormatXL(storageDisks)
 			case InitObjectLayer:
-				console.Eraseline()
 				// Validate formats loaded before proceeding forward.
 				err := genericFormatCheckXL(formatConfigs, sErrs)
 				if err == nil {
@@ -308,7 +305,7 @@ func retryFormattingXLDisks(firstDisk bool, endpoints EndpointList, storageDisks
 				}
 				return err
 			case WaitForQuorum:
-				console.Printf(
+				log.Printf(
 					"Initializing data volume. Waiting for minimum %d servers to come online. (elapsed %s)\n",
 					len(storageDisks)/2+1, getElapsedTime(),
 				)
@@ -316,9 +313,9 @@ func retryFormattingXLDisks(firstDisk bool, endpoints EndpointList, storageDisks
 				// Print configuration errors.
 				return reduceInitXLErrs(storageDisks, sErrs)
 			case WaitForAll:
-				console.Printf("Initializing data volume for first time. Waiting for other servers to come online (elapsed %s)\n", getElapsedTime())
+				log.Printf("Initializing data volume for first time. Waiting for other servers to come online (elapsed %s)\n", getElapsedTime())
 			case WaitForFormatting:
-				console.Printf("Initializing data volume for first time. Waiting for first server to come online (elapsed %s)\n", getElapsedTime())
+				log.Printf("Initializing data volume for first time. Waiting for first server to come online (elapsed %s)\n", getElapsedTime())
 			}
 		case <-globalServiceDoneCh:
 			return fmt.Errorf("Initializing data volumes gracefully stopped")

cmd/server-main.go

@@ -132,6 +132,13 @@ func serverMain(ctx *cli.Context) {
 		cli.ShowCommandHelpAndExit(ctx, "server", 1)
 	}
 
+	// Get "json" flag from command line argument and
+	// enable json and quite modes if jason flag is turned on.
+	jsonFlag := ctx.Bool("json") || ctx.GlobalBool("json")
+	if jsonFlag {
+		log.EnableJSON()
+	}
+
 	// Get quiet flag from command line argument.
 	quietFlag := ctx.Bool("quiet") || ctx.GlobalBool("quiet")
 	if quietFlag {

cmd/test-utils_test.go

@@ -71,9 +71,6 @@ func init() {
 
 	// Set system resources to maximum.
 	setMaxResources()
-
-	// Quiet logging.
-	log.logger.Hooks = nil
 }
 
 // concurreny level for certain parallel tests.