From 05a82045089d99164aff92a9d2cac3c128a88f9c Mon Sep 17 00:00:00 2001 From: Anton Kaliaev Date: Mon, 15 May 2017 19:33:45 +0200 Subject: [PATCH 1/2] per module log levels (Refs #493) --- cmd/tendermint/commands/flags/log_level.go | 85 +++++++++++++++++++ .../commands/flags/log_level_test.go | 42 +++++++++ cmd/tendermint/commands/root.go | 20 ++++- cmd/tendermint/commands/run_node.go | 9 ++ glide.lock | 6 +- glide.yaml | 2 +- node/node.go | 13 +-- 7 files changed, 164 insertions(+), 13 deletions(-) create mode 100644 cmd/tendermint/commands/flags/log_level.go create mode 100644 cmd/tendermint/commands/flags/log_level_test.go diff --git a/cmd/tendermint/commands/flags/log_level.go b/cmd/tendermint/commands/flags/log_level.go new file mode 100644 index 000000000..361ec9d20 --- /dev/null +++ b/cmd/tendermint/commands/flags/log_level.go @@ -0,0 +1,85 @@ +package flags + +import ( + "fmt" + "strings" + + "github.com/pkg/errors" + + cfg "github.com/tendermint/tendermint/config" + "github.com/tendermint/tmlibs/log" +) + +const ( + defaultLogLevelKey = "*" +) + +// IsLogLevelSimple returns true if log level is a single word ("info", ...). +func IsLogLevelSimple(l string) bool { + return !strings.Contains(l, ":") +} + +// ParseComplexLogLevel parses complex log level - comma-separated +// list of module:level pairs with an optional *:level pair (* means +// all other modules). +// +// Example: +// ParseComplexLogLevel("consensus:debug,mempool:debug,*:error", log.NewTMLogger(os.Stdout)) +func ParseComplexLogLevel(l string, logger log.Logger) (log.Logger, error) { + if l == "" { + return nil, errors.New("Empty log level") + } + + options := make([]log.Option, 0) + + isDefaultLogLevelSet := false + var option log.Option + var err error + + list := strings.Split(l, ",") + for _, item := range list { + moduleAndLevel := strings.Split(item, ":") + + if len(moduleAndLevel) != 2 { + return nil, fmt.Errorf("Expected list in a form of \"module:level\" pairs, given pair %s, list %s", item, list) + } + + module := moduleAndLevel[0] + level := moduleAndLevel[1] + + if module == defaultLogLevelKey { + option, err = log.AllowLevel(level) + if err != nil { + return nil, errors.Wrap(err, fmt.Sprintf("Failed to parse default log level (pair %s, list %s)", item, l)) + } + options = append(options, option) + isDefaultLogLevelSet = true + } else { + switch level { + case "debug": + option = log.AllowDebugWith("module", module) + case "info": + option = log.AllowInfoWith("module", module) + case "error": + option = log.AllowErrorWith("module", module) + case "none": + option = log.AllowNoneWith("module", module) + default: + return nil, fmt.Errorf("Expected either \"info\", \"debug\", \"error\" or \"none\" log level, given %s (pair %s, list %s)", level, item, list) + } + options = append(options, option) + + } + } + + // if "*" is not provided, set default global level + if !isDefaultLogLevelSet { + option, err = log.AllowLevel(cfg.DefaultBaseConfig().LogLevel) + if err != nil { + return nil, err + } + options = append(options, option) + } + + return log.NewFilter(logger, options...), nil +} diff --git a/cmd/tendermint/commands/flags/log_level_test.go b/cmd/tendermint/commands/flags/log_level_test.go new file mode 100644 index 000000000..6ccd5c846 --- /dev/null +++ b/cmd/tendermint/commands/flags/log_level_test.go @@ -0,0 +1,42 @@ +package flags_test + +import ( + "testing" + + tmflags "github.com/tendermint/tendermint/cmd/tendermint/commands/flags" + "github.com/tendermint/tmlibs/log" +) + +func TestIsLogLevelSimple(t *testing.T) { + simpleFlags := []string{"info", "debug", "some"} + for _, f := range simpleFlags { + if !tmflags.IsLogLevelSimple(f) { + t.Fatalf("%s is a simple flag", f) + } + } + + complexFlags := []string{"mempool:error", "mempool:error,*:debug"} + for _, f := range complexFlags { + if tmflags.IsLogLevelSimple(f) { + t.Fatalf("%s is a complex flag", f) + } + } +} + +func TestParseComplexLogLevel(t *testing.T) { + logger := log.TestingLogger() + + correctLogLevels := []string{"mempool:error", "mempool:error,*:debug", "*:debug,wire:none"} + for _, lvl := range correctLogLevels { + if _, err := tmflags.ParseComplexLogLevel(lvl, logger); err != nil { + t.Fatal(err) + } + } + + incorrectLogLevel := []string{"some", "mempool:some", "*:some,mempool:error"} + for _, lvl := range incorrectLogLevel { + if _, err := tmflags.ParseComplexLogLevel(lvl, logger); err == nil { + t.Fatalf("Expected %s to produce error", lvl) + } + } +} diff --git a/cmd/tendermint/commands/root.go b/cmd/tendermint/commands/root.go index ffd013065..79448b987 100644 --- a/cmd/tendermint/commands/root.go +++ b/cmd/tendermint/commands/root.go @@ -1,11 +1,13 @@ package commands import ( + "fmt" "os" "github.com/spf13/cobra" "github.com/spf13/viper" + tmflags "github.com/tendermint/tendermint/cmd/tendermint/commands/flags" cfg "github.com/tendermint/tendermint/config" "github.com/tendermint/tmlibs/log" ) @@ -26,9 +28,21 @@ var RootCmd = &cobra.Command{ err := viper.Unmarshal(config) config.SetRoot(config.RootDir) cfg.EnsureRoot(config.RootDir) - logger, err = log.NewFilterByLevel(logger, config.LogLevel) - if err != nil { - return err + if tmflags.IsLogLevelSimple(config.LogLevel) { + var option log.Option + switch config.LogLevel { + case "info": + option = log.AllowInfo() + case "debug": + option = log.AllowDebug() + case "error": + option = log.AllowError() + case "none": + option = log.AllowNone() + default: + return fmt.Errorf("Expected log level to be either \"info\", \"debug\", \"error\" or \"none\", given %s", config.LogLevel) + } + logger = log.NewFilter(logger, option) } return err }, diff --git a/cmd/tendermint/commands/run_node.go b/cmd/tendermint/commands/run_node.go index 5e38f2b5f..5eb477f77 100644 --- a/cmd/tendermint/commands/run_node.go +++ b/cmd/tendermint/commands/run_node.go @@ -7,6 +7,7 @@ import ( "github.com/spf13/cobra" + tmflags "github.com/tendermint/tendermint/cmd/tendermint/commands/flags" "github.com/tendermint/tendermint/node" "github.com/tendermint/tendermint/types" cmn "github.com/tendermint/tmlibs/common" @@ -79,6 +80,14 @@ func runNode(cmd *cobra.Command, args []string) error { } } + if !tmflags.IsLogLevelSimple(config.LogLevel) { + var err error + logger, err = tmflags.ParseComplexLogLevel(config.LogLevel, logger) + if err != nil { + return err + } + } + // Create & start node n := node.NewNodeDefault(config, logger.With("module", "node")) if _, err := n.Start(); err != nil { diff --git a/glide.lock b/glide.lock index dcc1d6f17..da38ad3b2 100644 --- a/glide.lock +++ b/glide.lock @@ -1,5 +1,5 @@ -hash: 9caff08aa026986b239e4aeb9d876bdddfacadc64a660ee8109e77a211e53436 -updated: 2017-05-15T07:32:38.823266751Z +hash: aa1fd2f52c45db131460b9dedf558ce2d2119ae9f313424578c65cf8efbf38e3 +updated: 2017-05-16T10:38:37.077880616Z imports: - name: github.com/btcsuite/btcd version: 1ae306021e323ae11c71ffb8546fbd9019e6cb6f @@ -131,7 +131,7 @@ imports: - iavl - testutil - name: github.com/tendermint/tmlibs - version: 4fdeaa70afa2556360a396faaa82e640b9912b0c + version: d0cae7b6edb4896390fd5ff82aea1bac98994bd0 subpackages: - autofile - cli diff --git a/glide.yaml b/glide.yaml index dd4993f59..f0cbd00f6 100644 --- a/glide.yaml +++ b/glide.yaml @@ -27,7 +27,7 @@ import: subpackages: - data - package: github.com/tendermint/tmlibs - version: develop + version: feature/log-levels-per-key-in-filter subpackages: - autofile - cli diff --git a/node/node.go b/node/node.go index ecfdef45a..ac8908345 100644 --- a/node/node.go +++ b/node/node.go @@ -70,12 +70,13 @@ func NewNode(config *cfg.Config, privValidator *types.PrivValidator, clientCreat blockStoreDB := dbm.NewDB("blockstore", config.DBBackend, config.DBDir()) blockStore := bc.NewBlockStore(blockStoreDB) + consensusLogger := logger.With("module", "consensus") + stateLogger := logger.With("module", "state") + // Get State stateDB := dbm.NewDB("state", config.DBBackend, config.DBDir()) state := sm.GetState(stateDB, config.GenesisFile()) - state.SetLogger(logger.With("module", "state")) - - consensusLogger := logger.With("module", "consensus") + state.SetLogger(stateLogger) // Create the proxyApp, which manages connections (consensus, mempool, query) // and sync tendermint and the app by replaying any necessary blocks @@ -89,7 +90,7 @@ func NewNode(config *cfg.Config, privValidator *types.PrivValidator, clientCreat // reload the state (it may have been updated by the handshake) state = sm.LoadState(stateDB) - state.SetLogger(logger.With("module", "state")) + state.SetLogger(stateLogger) // Transaction indexing var txIndexer txindex.TxIndexer @@ -128,7 +129,7 @@ func NewNode(config *cfg.Config, privValidator *types.PrivValidator, clientCreat bcReactor.SetLogger(logger.With("module", "blockchain")) // Make MempoolReactor - mempoolLogger := logger.With("module", "consensus") + mempoolLogger := logger.With("module", "mempool") mempool := mempl.NewMempool(config.Mempool, proxyApp.Mempool()) mempool.SetLogger(mempoolLogger) mempoolReactor := mempl.NewMempoolReactor(config.Mempool, mempool) @@ -318,8 +319,8 @@ func (n *Node) startRPC() ([]net.Listener, error) { listeners := make([]net.Listener, len(listenAddrs)) for i, listenAddr := range listenAddrs { mux := http.NewServeMux() - rpcLogger := n.Logger.With("module", "rpcserver") wm := rpcserver.NewWebsocketManager(rpccore.Routes, n.evsw) + rpcLogger := n.Logger.With("module", "rpc-server") wm.SetLogger(rpcLogger) mux.HandleFunc("/websocket", wm.WebsocketHandler) rpcserver.RegisterRPCFuncs(mux, rpccore.Routes, rpcLogger) From fb0df75de097c2b92b4dfb5396db36e02e526bbe Mon Sep 17 00:00:00 2001 From: Anton Kaliaev Date: Tue, 16 May 2017 15:16:50 +0200 Subject: [PATCH 2/2] changes per Frey comments (Refs #493) --- cmd/tendermint/commands/flags/log_level.go | 20 ++++--- .../commands/flags/log_level_test.go | 60 +++++++++++++------ cmd/tendermint/commands/root.go | 24 +++----- cmd/tendermint/commands/run_node.go | 9 --- 4 files changed, 59 insertions(+), 54 deletions(-) diff --git a/cmd/tendermint/commands/flags/log_level.go b/cmd/tendermint/commands/flags/log_level.go index 361ec9d20..acdd24ec2 100644 --- a/cmd/tendermint/commands/flags/log_level.go +++ b/cmd/tendermint/commands/flags/log_level.go @@ -14,22 +14,24 @@ const ( defaultLogLevelKey = "*" ) -// IsLogLevelSimple returns true if log level is a single word ("info", ...). -func IsLogLevelSimple(l string) bool { - return !strings.Contains(l, ":") -} - -// ParseComplexLogLevel parses complex log level - comma-separated +// ParseLogLevel parses complex log level - comma-separated // list of module:level pairs with an optional *:level pair (* means // all other modules). // // Example: -// ParseComplexLogLevel("consensus:debug,mempool:debug,*:error", log.NewTMLogger(os.Stdout)) -func ParseComplexLogLevel(l string, logger log.Logger) (log.Logger, error) { - if l == "" { +// ParseLogLevel("consensus:debug,mempool:debug,*:error", log.NewTMLogger(os.Stdout)) +func ParseLogLevel(lvl string, logger log.Logger) (log.Logger, error) { + if lvl == "" { return nil, errors.New("Empty log level") } + l := lvl + + // prefix simple one word levels (e.g. "info") with "*" + if !strings.Contains(l, ":") { + l = defaultLogLevelKey + ":" + l + } + options := make([]log.Option, 0) isDefaultLogLevelSet := false diff --git a/cmd/tendermint/commands/flags/log_level_test.go b/cmd/tendermint/commands/flags/log_level_test.go index 6ccd5c846..c89f3f880 100644 --- a/cmd/tendermint/commands/flags/log_level_test.go +++ b/cmd/tendermint/commands/flags/log_level_test.go @@ -1,41 +1,63 @@ package flags_test import ( + "bytes" + "strings" "testing" tmflags "github.com/tendermint/tendermint/cmd/tendermint/commands/flags" "github.com/tendermint/tmlibs/log" ) -func TestIsLogLevelSimple(t *testing.T) { - simpleFlags := []string{"info", "debug", "some"} - for _, f := range simpleFlags { - if !tmflags.IsLogLevelSimple(f) { - t.Fatalf("%s is a simple flag", f) - } +func TestParseLogLevel(t *testing.T) { + var buf bytes.Buffer + jsonLogger := log.NewTMJSONLogger(&buf) + + correctLogLevels := []struct { + lvl string + expectedLogLines []string + }{ + {"mempool:error", []string{``, ``, `{"_msg":"Mesmero","level":"error","module":"mempool"}`}}, + {"mempool:error,*:debug", []string{``, ``, `{"_msg":"Mesmero","level":"error","module":"mempool"}`}}, + {"*:debug,wire:none", []string{ + `{"_msg":"Kingpin","level":"debug","module":"mempool"}`, + `{"_msg":"Kitty Pryde","level":"info","module":"mempool"}`, + `{"_msg":"Mesmero","level":"error","module":"mempool"}`}}, } - complexFlags := []string{"mempool:error", "mempool:error,*:debug"} - for _, f := range complexFlags { - if tmflags.IsLogLevelSimple(f) { - t.Fatalf("%s is a complex flag", f) + for _, c := range correctLogLevels { + logger, err := tmflags.ParseLogLevel(c.lvl, jsonLogger) + if err != nil { + t.Fatal(err) } - } -} -func TestParseComplexLogLevel(t *testing.T) { - logger := log.TestingLogger() + logger = logger.With("module", "mempool") - correctLogLevels := []string{"mempool:error", "mempool:error,*:debug", "*:debug,wire:none"} - for _, lvl := range correctLogLevels { - if _, err := tmflags.ParseComplexLogLevel(lvl, logger); err != nil { - t.Fatal(err) + buf.Reset() + + logger.Debug("Kingpin") + if have := strings.TrimSpace(buf.String()); c.expectedLogLines[0] != have { + t.Errorf("\nwant '%s'\nhave '%s'\nlevel '%s'", c.expectedLogLines[0], have, c.lvl) + } + + buf.Reset() + + logger.Info("Kitty Pryde") + if have := strings.TrimSpace(buf.String()); c.expectedLogLines[1] != have { + t.Errorf("\nwant '%s'\nhave '%s'\nlevel '%s'", c.expectedLogLines[1], have, c.lvl) + } + + buf.Reset() + + logger.Error("Mesmero") + if have := strings.TrimSpace(buf.String()); c.expectedLogLines[2] != have { + t.Errorf("\nwant '%s'\nhave '%s'\nlevel '%s'", c.expectedLogLines[2], have, c.lvl) } } incorrectLogLevel := []string{"some", "mempool:some", "*:some,mempool:error"} for _, lvl := range incorrectLogLevel { - if _, err := tmflags.ParseComplexLogLevel(lvl, logger); err == nil { + if _, err := tmflags.ParseLogLevel(lvl, jsonLogger); err == nil { t.Fatalf("Expected %s to produce error", lvl) } } diff --git a/cmd/tendermint/commands/root.go b/cmd/tendermint/commands/root.go index 79448b987..3565f3bb8 100644 --- a/cmd/tendermint/commands/root.go +++ b/cmd/tendermint/commands/root.go @@ -1,7 +1,6 @@ package commands import ( - "fmt" "os" "github.com/spf13/cobra" @@ -26,24 +25,15 @@ var RootCmd = &cobra.Command{ Short: "Tendermint Core (BFT Consensus) in Go", PersistentPreRunE: func(cmd *cobra.Command, args []string) error { err := viper.Unmarshal(config) + if err != nil { + return err + } config.SetRoot(config.RootDir) cfg.EnsureRoot(config.RootDir) - if tmflags.IsLogLevelSimple(config.LogLevel) { - var option log.Option - switch config.LogLevel { - case "info": - option = log.AllowInfo() - case "debug": - option = log.AllowDebug() - case "error": - option = log.AllowError() - case "none": - option = log.AllowNone() - default: - return fmt.Errorf("Expected log level to be either \"info\", \"debug\", \"error\" or \"none\", given %s", config.LogLevel) - } - logger = log.NewFilter(logger, option) + logger, err = tmflags.ParseLogLevel(config.LogLevel, logger) + if err != nil { + return err } - return err + return nil }, } diff --git a/cmd/tendermint/commands/run_node.go b/cmd/tendermint/commands/run_node.go index 5eb477f77..5e38f2b5f 100644 --- a/cmd/tendermint/commands/run_node.go +++ b/cmd/tendermint/commands/run_node.go @@ -7,7 +7,6 @@ import ( "github.com/spf13/cobra" - tmflags "github.com/tendermint/tendermint/cmd/tendermint/commands/flags" "github.com/tendermint/tendermint/node" "github.com/tendermint/tendermint/types" cmn "github.com/tendermint/tmlibs/common" @@ -80,14 +79,6 @@ func runNode(cmd *cobra.Command, args []string) error { } } - if !tmflags.IsLogLevelSimple(config.LogLevel) { - var err error - logger, err = tmflags.ParseComplexLogLevel(config.LogLevel, logger) - if err != nil { - return err - } - } - // Create & start node n := node.NewNodeDefault(config, logger.With("module", "node")) if _, err := n.Start(); err != nil {