Beta/refactor logging#221 (#244)

Added a lightweight logger wrapper around go-ethereum/log which adds StatusIM prefix to all messages and allows to clearly distinguish between status-go and go-ethereum logs.

Logs under vendor/go-ethereum left unchanged because those pieces of code might undergo huge refactoring in the near term.

geth/api/api_test.go

@@ -8,8 +8,8 @@ import (
 	"testing"
 	"time"
 
-	"github.com/ethereum/go-ethereum/log"
 	"github.com/status-im/status-go/geth/api"
+	"github.com/status-im/status-go/geth/log"
 	"github.com/status-im/status-go/geth/params"
 	. "github.com/status-im/status-go/geth/testing"
 	"github.com/stretchr/testify/suite"

geth/api/backend.go

@@ -5,9 +5,9 @@ import (
 
 	gethcommon "github.com/ethereum/go-ethereum/common"
 	"github.com/ethereum/go-ethereum/les"
-	"github.com/ethereum/go-ethereum/log"
 	"github.com/status-im/status-go/geth/common"
 	"github.com/status-im/status-go/geth/jail"
+	"github.com/status-im/status-go/geth/log"
 	"github.com/status-im/status-go/geth/node"
 	"github.com/status-im/status-go/geth/params"
 )

geth/api/backend_jail_test.go

@@ -11,10 +11,10 @@ import (
 
 	gethcommon "github.com/ethereum/go-ethereum/common"
 	"github.com/ethereum/go-ethereum/crypto"
-	"github.com/ethereum/go-ethereum/log"
 	whisper "github.com/ethereum/go-ethereum/whisper/whisperv5"
 	"github.com/status-im/status-go/geth/common"
 	"github.com/status-im/status-go/geth/jail"
+	"github.com/status-im/status-go/geth/log"
 	"github.com/status-im/status-go/geth/node"
 	"github.com/status-im/status-go/geth/params"
 	. "github.com/status-im/status-go/geth/testing"

geth/api/backend_test.go

@@ -6,11 +6,11 @@ import (
 	"time"
 
 	"github.com/ethereum/go-ethereum/les"
-	"github.com/ethereum/go-ethereum/log"
 	whisper "github.com/ethereum/go-ethereum/whisper/whisperv5"
 	"github.com/status-im/status-go/geth/api"
 	"github.com/status-im/status-go/geth/common"
 	"github.com/status-im/status-go/geth/jail"
+	"github.com/status-im/status-go/geth/log"
 	"github.com/status-im/status-go/geth/node"
 	"github.com/status-im/status-go/geth/params"
 	. "github.com/status-im/status-go/geth/testing"

geth/api/backend_txqueue_test.go

@@ -11,8 +11,8 @@ import (
 	gethcommon "github.com/ethereum/go-ethereum/common"
 	"github.com/ethereum/go-ethereum/common/hexutil"
 	"github.com/ethereum/go-ethereum/les/status"
-	"github.com/ethereum/go-ethereum/log"
 	"github.com/status-im/status-go/geth/common"
+	"github.com/status-im/status-go/geth/log"
 	"github.com/status-im/status-go/geth/node"
 	"github.com/status-im/status-go/geth/params"
 	. "github.com/status-im/status-go/geth/testing"

geth/common/logger.go

@@ -1,95 +0,0 @@
-package common
-
-import (
-	"os"
-	"path/filepath"
-	"sync"
-
-	"github.com/ethereum/go-ethereum/log"
-	"github.com/status-im/status-go/geth/params"
-)
-
-// Logger is wrapper for custom logging
-type Logger struct {
-	origHandler log.Handler
-	handler     log.Handler
-	config      *params.NodeConfig
-}
-
-var (
-	onceInitNodeLogger sync.Once
-	nodeLoggerInstance *Logger
-)
-
-// SetupLogger configs logger using parameters in config
-func SetupLogger(config *params.NodeConfig) (*Logger, error) {
-	if !config.LogEnabled {
-		return nil, nil
-	}
-
-	onceInitNodeLogger.Do(func() {
-		nodeLoggerInstance = &Logger{
-			config:      config,
-			origHandler: log.Root().GetHandler(),
-		}
-		nodeLoggerInstance.handler = nodeLoggerInstance.makeLogHandler(parseLogLevel(config.LogLevel))
-	})
-
-	if err := nodeLoggerInstance.Start(); err != nil {
-		return nil, err
-	}
-
-	return nodeLoggerInstance, nil
-}
-
-// SetV allows to dynamically change log level of messages being written
-func (l *Logger) SetV(logLevel string) {
-	log.Root().SetHandler(l.makeLogHandler(parseLogLevel(logLevel)))
-}
-
-// Start installs logger handler
-func (l *Logger) Start() error {
-	log.Root().SetHandler(l.handler)
-	return nil
-}
-
-// Stop replaces our handler back to the original log handler
-func (l *Logger) Stop() error {
-	log.Root().SetHandler(l.origHandler)
-	return nil
-}
-
-// makeLogHandler creates a log handler for a given level and node configuration
-func (l *Logger) makeLogHandler(lvl log.Lvl) log.Handler {
-	var handler log.Handler
-	logFilePath := filepath.Join(l.config.DataDir, l.config.LogFile)
-	fileHandler := log.Must.FileHandler(logFilePath, log.LogfmtFormat())
-	stderrHandler := log.StreamHandler(os.Stderr, log.TerminalFormat(true))
-	if l.config.LogToStderr {
-		handler = log.MultiHandler(
-			log.LvlFilterHandler(lvl, log.CallerFileHandler(log.CallerFuncHandler(stderrHandler))),
-			log.LvlFilterHandler(lvl, fileHandler))
-	} else {
-		handler = log.LvlFilterHandler(lvl, fileHandler)
-	}
-
-	return handler
-}
-
-// parseLogLevel parses string and returns logger.* constant
-func parseLogLevel(logLevel string) log.Lvl {
-	switch logLevel {
-	case "ERROR":
-		return log.LvlError
-	case "WARNING":
-		return log.LvlWarn
-	case "INFO":
-		return log.LvlInfo
-	case "DEBUG":
-		return log.LvlDebug
-	case "TRACE":
-		return log.LvlTrace
-	}
-
-	return log.LvlInfo
-}

geth/common/logger_test.go

@@ -1,83 +0,0 @@
-package common_test
-
-import (
-	"io/ioutil"
-	"os"
-	"path/filepath"
-	"strings"
-	"testing"
-
-	"github.com/ethereum/go-ethereum/log"
-	"github.com/status-im/status-go/geth/common"
-	"github.com/status-im/status-go/geth/params"
-)
-
-func TestLogger(t *testing.T) {
-	tmpDir, err := ioutil.TempDir(os.TempDir(), "geth-logger-tests")
-	if err != nil {
-		t.Fatal(err)
-	}
-	//defer os.RemoveAll(tmpDir)
-
-	nodeConfig, err := params.NewNodeConfig(tmpDir, params.RopstenNetworkID, true)
-	if err != nil {
-		t.Fatal("cannot create config object")
-	}
-	nodeLogger, err := common.SetupLogger(nodeConfig)
-	if err != nil {
-		t.Fatal("cannot create logger object")
-	}
-	if nodeLogger != nil {
-		t.Fatalf("logger is not empty (while logs are disabled): %v", nodeLogger)
-	}
-
-	nodeConfig.LogEnabled = true
-	nodeConfig.LogToStderr = false // just capture logs to file
-	nodeLogger, err = common.SetupLogger(nodeConfig)
-	if err != nil {
-		t.Fatal("cannot create logger object")
-	}
-	if nodeLogger == nil {
-		t.Fatal("logger is empty (while logs are enabled)")
-	}
-
-	validateLogText := func(expectedLogText string) {
-		logFilePath := filepath.Join(nodeConfig.DataDir, nodeConfig.LogFile)
-		logBytes, err := ioutil.ReadFile(logFilePath)
-		if err != nil {
-			panic(err)
-		}
-		logText := string(logBytes)
-		logText = strings.Trim(logText, "\n")
-		logText = logText[len(logText)-len(expectedLogText):] // as logs can be prepended with log info
-
-		if expectedLogText != logText {
-			t.Fatalf("invalid log, expected: [%s], got: [%s]", expectedLogText, string(logText))
-		} else {
-			t.Logf("log match found, expected: [%s], got: [%s]", expectedLogText, string(logText))
-		}
-	}
-
-	// sample log message
-	log.Info("use log package")
-	validateLogText(`msg="use log package"`)
-
-	// log using DEBUG log level (with appropriate level set)
-	nodeLogger.SetV("DEBUG")
-	log.Info("logged DEBUG log level message")
-	validateLogText(`msg="logged DEBUG log level message"`)
-
-	// log using DEBUG log level (with appropriate level set)
-	nodeLogger.SetV("INFO")
-	log.Info("logged INFO log level message")
-	validateLogText(`msg="logged INFO log level message"`)
-	log.Debug("logged DEBUG log level message")
-	validateLogText(`msg="logged INFO log level message"`) // debug level message is NOT logged
-
-	// stop logger and see if os.Stderr and gethlog continue functioning
-	if err = nodeLogger.Stop(); err != nil {
-		t.Fatal(err)
-	}
-
-	log.Info("logging message: this message happens after custom logger has been stopped")
-}

geth/common/utils.go

@@ -16,7 +16,7 @@ import (
 
 	"github.com/ethereum/go-ethereum/accounts"
 	"github.com/ethereum/go-ethereum/common"
-	"github.com/ethereum/go-ethereum/log"
+	"github.com/status-im/status-go/geth/log"
 	"github.com/status-im/status-go/static"
 )
 

geth/jail/jail.go

@@ -6,10 +6,10 @@ import (
 	"fmt"
 	"sync"
 
-	"github.com/ethereum/go-ethereum/log"
 	"github.com/ethereum/go-ethereum/rpc"
 	"github.com/robertkrimen/otto"
 	"github.com/status-im/status-go/geth/common"
+	"github.com/status-im/status-go/geth/log"
 	"github.com/status-im/status-go/static"
 
 	"fknsrs.biz/p/ottoext/loop"

geth/log/log.go

@@ -0,0 +1,75 @@
+package log
+
+import (
+	"github.com/ethereum/go-ethereum/log"
+)
+
+// Logger is wrapper for go-ethereum log
+type Logger struct {
+	output log.Logger
+}
+
+// Instance to a logger struct
+var logger *Logger
+
+// Trace is a convenient alias for Root().Trace
+func Trace(msg string, ctx ...interface{}) {
+	printLog(log.LvlTrace, msg, ctx...)
+}
+
+// Debug is a convenient alias for Root().Debug
+func Debug(msg string, ctx ...interface{}) {
+	printLog(log.LvlDebug, msg, ctx...)
+}
+
+// Info is a convenient alias for Root().Info
+func Info(msg string, ctx ...interface{}) {
+	printLog(log.LvlInfo, msg, ctx...)
+}
+
+// Warn is a convenient alias for Root().Warn
+func Warn(msg string, ctx ...interface{}) {
+	printLog(log.LvlWarn, msg, ctx...)
+}
+
+// Error is a convenient alias for Root().Error
+func Error(msg string, ctx ...interface{}) {
+	printLog(log.LvlError, msg, ctx...)
+}
+
+// Crit is a convenient alias for Root().Crit
+func Crit(msg string, ctx ...interface{}) {
+	printLog(log.LvlCrit, msg, ctx...)
+}
+
+// outputs the log to a given log config level
+func printLog(lvl log.Lvl, msg string, ctx ...interface{}) {
+	if logger == nil {
+		logger = &Logger{
+			output: log.New("geth", "StatusIM"),
+		}
+		logger.output.SetHandler(log.StdoutHandler)
+	}
+
+	switch lvl {
+
+	case log.LvlError:
+		logger.output.Error(msg, ctx...)
+
+	case log.LvlWarn:
+		logger.output.Warn(msg, ctx...)
+
+	case log.LvlInfo:
+		logger.output.Info(msg, ctx...)
+
+	case log.LvlDebug:
+		logger.output.Debug(msg, ctx...)
+
+	case log.LvlTrace:
+		logger.output.Trace(msg, ctx...)
+
+	default:
+		logger.output.Info(msg, ctx...)
+
+	}
+}

geth/log/log_test.go

@@ -0,0 +1,18 @@
+// log_test
+package log
+
+import (
+	"testing"
+)
+
+func TestLogger(t *testing.T) {
+
+	t.Log("Testing log package..")
+
+	Trace("Trace Message")
+	Debug("Debug Message")
+	Info("Info Message")
+	Warn("Warn Message")
+	Error("Error Message")
+	Crit("Crit Message")
+}

geth/node/manager.go

@@ -10,11 +10,11 @@ import (
 	"github.com/ethereum/go-ethereum/accounts"
 	"github.com/ethereum/go-ethereum/accounts/keystore"
 	"github.com/ethereum/go-ethereum/les"
-	"github.com/ethereum/go-ethereum/log"
 	"github.com/ethereum/go-ethereum/node"
 	"github.com/ethereum/go-ethereum/p2p/discover"
 	"github.com/ethereum/go-ethereum/rpc"
 	whisper "github.com/ethereum/go-ethereum/whisper/whisperv5"
+	"github.com/status-im/status-go/geth/log"
 	"github.com/status-im/status-go/geth/params"
 )
 

geth/node/manager_test.go

@@ -10,10 +10,10 @@ import (
 	"github.com/ethereum/go-ethereum/accounts"
 	"github.com/ethereum/go-ethereum/accounts/keystore"
 	"github.com/ethereum/go-ethereum/les"
-	"github.com/ethereum/go-ethereum/log"
 	gethnode "github.com/ethereum/go-ethereum/node"
 	"github.com/ethereum/go-ethereum/rpc"
 	whisper "github.com/ethereum/go-ethereum/whisper/whisperv5"
+	"github.com/status-im/status-go/geth/log"
 	"github.com/status-im/status-go/geth/node"
 	"github.com/status-im/status-go/geth/params"
 	. "github.com/status-im/status-go/geth/testing"

geth/node/node.go

@@ -16,7 +16,6 @@ import (
 	"github.com/ethereum/go-ethereum/eth/downloader"
 	"github.com/ethereum/go-ethereum/les"
 	"github.com/ethereum/go-ethereum/light"
-	"github.com/ethereum/go-ethereum/log"
 	"github.com/ethereum/go-ethereum/node"
 	"github.com/ethereum/go-ethereum/p2p"
 	"github.com/ethereum/go-ethereum/p2p/discover"
@@ -26,7 +25,7 @@ import (
 	"github.com/ethereum/go-ethereum/whisper/mailserver"
 	"github.com/ethereum/go-ethereum/whisper/notifications"
 	whisper "github.com/ethereum/go-ethereum/whisper/whisperv5"
-	"github.com/status-im/status-go/geth/common"
+	"github.com/status-im/status-go/geth/log"
 	"github.com/status-im/status-go/geth/params"
 )
 
@@ -52,11 +51,6 @@ func MakeNode(config *params.NodeConfig) (*node.Node, error) {
 		return nil, err
 	}
 
-	// setup logging
-	if _, err := common.SetupLogger(config); err != nil {
-		return nil, err
-	}
-
 	// configure required node (should you need to update node's config, e.g. add bootstrap nodes, see node.Config)
 	stackConfig := defaultEmbeddedNodeConfig(config)
 

geth/node/rpc.go

@@ -10,8 +10,8 @@ import (
 	"time"
 
 	"github.com/ethereum/go-ethereum/les/status"
-	"github.com/ethereum/go-ethereum/log"
 	"github.com/status-im/status-go/geth/common"
+	"github.com/status-im/status-go/geth/log"
 )
 
 const (

geth/node/rpc_test.go

@@ -3,7 +3,7 @@ package node_test
 import (
 	"testing"
 
-	"github.com/ethereum/go-ethereum/log"
+	"github.com/status-im/status-go/geth/log"
 	"github.com/status-im/status-go/geth/node"
 	"github.com/status-im/status-go/geth/params"
 	. "github.com/status-im/status-go/geth/testing"

geth/node/signals.go

@@ -8,7 +8,8 @@ extern bool StatusServiceSignalEvent(const char *jsonEvent);
 import "C"
 import (
 	"encoding/json"
-	"github.com/ethereum/go-ethereum/log"
+
+	"github.com/status-im/status-go/geth/log"
 )
 
 const (

geth/node/utils.go

@@ -5,8 +5,8 @@ import (
 	"os"
 	"os/signal"
 
-	"github.com/ethereum/go-ethereum/log"
 	"github.com/status-im/status-go/geth/common"
+	"github.com/status-im/status-go/geth/log"
 )
 
 // HaltOnPanic recovers from panic, logs issue, sends upward notification, and exits

geth/params/config.go

@@ -16,7 +16,7 @@ import (
 
 	"github.com/ethereum/go-ethereum/core"
 	"github.com/ethereum/go-ethereum/crypto"
-	"github.com/ethereum/go-ethereum/log"
+	"github.com/status-im/status-go/geth/log"
 )
 
 // default node configuration options