Merge pull request #501 from tendermint/feature/493-per-module-log-levels

Feature/493 per module log levels

cmd/tendermint/commands/flags/log_level.go

@@ -0,0 +1,87 @@
+package flags
+
+import (
+	"fmt"
+	"strings"
+
+	"github.com/pkg/errors"
+
+	cfg "github.com/tendermint/tendermint/config"
+	"github.com/tendermint/tmlibs/log"
+)
+
+const (
+	defaultLogLevelKey = "*"
+)
+
+// ParseLogLevel parses complex log level - comma-separated
+// list of module:level pairs with an optional *:level pair (* means
+// all other modules).
+//
+// Example:
+//		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
+	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
+}

cmd/tendermint/commands/flags/log_level_test.go

@@ -0,0 +1,64 @@
+package flags_test
+
+import (
+	"bytes"
+	"strings"
+	"testing"
+
+	tmflags "github.com/tendermint/tendermint/cmd/tendermint/commands/flags"
+	"github.com/tendermint/tmlibs/log"
+)
+
+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"}`}},
+	}
+
+	for _, c := range correctLogLevels {
+		logger, err := tmflags.ParseLogLevel(c.lvl, jsonLogger)
+		if err != nil {
+			t.Fatal(err)
+		}
+
+		logger = logger.With("module", "mempool")
+
+		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.ParseLogLevel(lvl, jsonLogger); err == nil {
+			t.Fatalf("Expected %s to produce error", lvl)
+		}
+	}
+}

cmd/tendermint/commands/root.go

@@ -6,6 +6,7 @@ import (
 	"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"
 )
@@ -24,12 +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)
-		config.SetRoot(config.RootDir)
-		cfg.EnsureRoot(config.RootDir)
-		logger, err = log.NewFilterByLevel(logger, config.LogLevel)
 		if err != nil {
 			return err
 		}
-		return err
+		config.SetRoot(config.RootDir)
+		cfg.EnsureRoot(config.RootDir)
+		logger, err = tmflags.ParseLogLevel(config.LogLevel, logger)
+		if err != nil {
+			return err
+		}
+		return nil
 	},
 }

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

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

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
@@ -135,7 +136,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)
@@ -325,8 +326,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)