From 3b316c07003125f8ff6fa76b4b22ab9dcd157446 Mon Sep 17 00:00:00 2001 From: Marin Date: Thu, 10 Aug 2017 15:35:58 +0200 Subject: [PATCH] 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 | 2 +- geth/api/backend.go | 2 +- geth/api/backend_jail_test.go | 2 +- geth/api/backend_test.go | 2 +- geth/api/backend_txqueue_test.go | 2 +- geth/common/logger.go | 95 -------------------------------- geth/common/logger_test.go | 83 ---------------------------- geth/common/utils.go | 2 +- geth/jail/jail.go | 2 +- geth/log/log.go | 75 +++++++++++++++++++++++++ geth/log/log_test.go | 18 ++++++ geth/node/manager.go | 2 +- geth/node/manager_test.go | 2 +- geth/node/node.go | 8 +-- geth/node/rpc.go | 4 +- geth/node/rpc_test.go | 2 +- geth/node/signals.go | 3 +- geth/node/utils.go | 2 +- geth/params/config.go | 2 +- 19 files changed, 110 insertions(+), 200 deletions(-) delete mode 100644 geth/common/logger.go delete mode 100644 geth/common/logger_test.go create mode 100644 geth/log/log.go create mode 100644 geth/log/log_test.go diff --git a/geth/api/api_test.go b/geth/api/api_test.go index 4524a959e..d64f15976 100644 --- a/geth/api/api_test.go +++ b/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" diff --git a/geth/api/backend.go b/geth/api/backend.go index 0586b2c4f..c6d16f09d 100644 --- a/geth/api/backend.go +++ b/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" ) diff --git a/geth/api/backend_jail_test.go b/geth/api/backend_jail_test.go index 0e096388d..cba3e8feb 100644 --- a/geth/api/backend_jail_test.go +++ b/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" diff --git a/geth/api/backend_test.go b/geth/api/backend_test.go index 1409c7564..20aabb7d6 100644 --- a/geth/api/backend_test.go +++ b/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" diff --git a/geth/api/backend_txqueue_test.go b/geth/api/backend_txqueue_test.go index 809ed10c0..7a9900e5b 100644 --- a/geth/api/backend_txqueue_test.go +++ b/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" diff --git a/geth/common/logger.go b/geth/common/logger.go deleted file mode 100644 index 069c3740a..000000000 --- a/geth/common/logger.go +++ /dev/null @@ -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 -} diff --git a/geth/common/logger_test.go b/geth/common/logger_test.go deleted file mode 100644 index eb6515f67..000000000 --- a/geth/common/logger_test.go +++ /dev/null @@ -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") -} diff --git a/geth/common/utils.go b/geth/common/utils.go index d4d5540b5..aa911ee87 100644 --- a/geth/common/utils.go +++ b/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" ) diff --git a/geth/jail/jail.go b/geth/jail/jail.go index d615f1486..fd3f6670f 100644 --- a/geth/jail/jail.go +++ b/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" diff --git a/geth/log/log.go b/geth/log/log.go new file mode 100644 index 000000000..da820408c --- /dev/null +++ b/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...) + + } +} diff --git a/geth/log/log_test.go b/geth/log/log_test.go new file mode 100644 index 000000000..86a314d00 --- /dev/null +++ b/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") +} diff --git a/geth/node/manager.go b/geth/node/manager.go index 8a4e7b740..eb97daa10 100644 --- a/geth/node/manager.go +++ b/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" ) diff --git a/geth/node/manager_test.go b/geth/node/manager_test.go index 5311c41ad..e415ff35a 100644 --- a/geth/node/manager_test.go +++ b/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" diff --git a/geth/node/node.go b/geth/node/node.go index 3848e6268..c17b4c8d3 100644 --- a/geth/node/node.go +++ b/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) diff --git a/geth/node/rpc.go b/geth/node/rpc.go index cdb0a12eb..308191397 100644 --- a/geth/node/rpc.go +++ b/geth/node/rpc.go @@ -10,12 +10,12 @@ 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 ( - jsonrpcVersion = "2.0" + jsonrpcVersion = "2.0" ) type jsonRequest struct { diff --git a/geth/node/rpc_test.go b/geth/node/rpc_test.go index c42515d45..33c2ec1c2 100644 --- a/geth/node/rpc_test.go +++ b/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" diff --git a/geth/node/signals.go b/geth/node/signals.go index 2905d0b82..f497e52d5 100644 --- a/geth/node/signals.go +++ b/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 ( diff --git a/geth/node/utils.go b/geth/node/utils.go index c1e5175f0..8e105bfe9 100644 --- a/geth/node/utils.go +++ b/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 diff --git a/geth/params/config.go b/geth/params/config.go index e4a49bdb0..36c20200a 100644 --- a/geth/params/config.go +++ b/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