Merge branch 'master' into marko/filter_logging

cmd/tendermint/commands/root.go

@@ -51,7 +51,8 @@ func RootCommand(conf *config.Config, logger log.Logger) *cobra.Command {
 			}
 			*conf = *pconf
 			config.EnsureRoot(conf.RootDir)
-			if err := log.OverrideWithNewLogger(logger, conf.LogFormat, conf.LogLevel); err != nil {
+			logger, err = cli.ParseLogLevel(conf.LogLevel, logger, config.DefaultPackageLogLevels())
+			if err != nil {
 				return err
 			}
 			if warning := pconf.DeprecatedFieldWarning(); warning != nil {

cmd/tendermint/commands/root_test.go

@@ -135,7 +135,7 @@ func TestRootConfig(t *testing.T) {
 	defer cancel()
 
 	// write non-default config
-	nonDefaultLogLvl := "debug"
+	nonDefaultLogLvl := "abc:debug"
 	cvals := map[string]string{
 		"log-level": nonDefaultLogLvl,
 	}
@@ -145,9 +145,9 @@ func TestRootConfig(t *testing.T) {
 		env    map[string]string
 		logLvl string
 	}{
-		{nil, nil, nonDefaultLogLvl},                             // should load config
-		{[]string{"--log-level=info"}, nil, "info"},              // flag over rides
-		{nil, map[string]string{"TM_LOG_LEVEL": "info"}, "info"}, // env over rides
+		{nil, nil, nonDefaultLogLvl},                                     // should load config
+		{[]string{"--log-level=abc:info"}, nil, "abc:info"},              // flag over rides
+		{nil, map[string]string{"TM_LOG_LEVEL": "abc:info"}, "abc:info"}, // env over rides
 	}
 
 	for i, tc := range cases {
@@ -172,6 +172,7 @@ func TestRootConfig(t *testing.T) {
 			tc.args = append([]string{cmd.Use}, tc.args...)
 			err = cli.RunWithArgs(ctx, cmd, tc.args, tc.env)
 			require.NoError(t, err)
+			fmt.Println(conf.LogLevel)
 
 			require.Equal(t, tc.logLvl, conf.LogLevel)
 		})

cmd/tendermint/main.go

@@ -20,7 +20,7 @@ func main() {
 		panic(err)
 	}
 
-	logger, err := log.NewDefaultLogger(conf.LogFormat, conf.LogLevel)
+	logger, err := log.NewDefaultLogger(conf.LogFormat, "debug") // todo incorrect
 	if err != nil {
 		panic(err)
 	}

config/config.go

@@ -22,9 +22,6 @@ const (
 	// FuzzModeDelay is a mode in which we randomly sleep
 	FuzzModeDelay
 
-	// DefaultLogLevel defines a default log level as INFO.
-	DefaultLogLevel = "info"
-
 	ModeFull      = "full"
 	ModeValidator = "validator"
 	ModeSeed      = "seed"
@@ -236,7 +233,7 @@ func DefaultBaseConfig() BaseConfig {
 		Moniker:     defaultMoniker,
 		ProxyApp:    "tcp://127.0.0.1:26658",
 		ABCI:        "socket",
-		LogLevel:    DefaultLogLevel,
+		LogLevel:    DefaultPackageLogLevels(),
 		LogFormat:   log.LogFormatPlain,
 		FilterPeers: false,
 		DBBackend:   "goleveldb",
@@ -308,6 +305,17 @@ func (cfg BaseConfig) DBDir() string {
 	return rootify(cfg.DBPath, cfg.RootDir)
 }
 
+// DefaultLogLevel returns a default log level of "error"
+func DefaultLogLevel() string {
+	return "error"
+}
+
+// DefaultPackageLogLevels returns a default log level setting so all packages
+// log at "error", while the `state` and `main` packages log at "info"
+func DefaultPackageLogLevels() string {
+	return fmt.Sprintf("main:info,state:info,*:%s", DefaultLogLevel())
+}
+
 // ValidateBasic performs basic validation (checking param bounds, etc.) and
 // returns an error if any check fails.
 func (cfg BaseConfig) ValidateBasic() error {

libs/cli/log_level.go

@@ -0,0 +1,91 @@
+package cli
+
+import (
+	"fmt"
+	"strings"
+
+	"github.com/pkg/errors"
+
+	"github.com/tendermint/tendermint/libs/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), "info")
+func ParseLogLevel(lvl string, logger log.Logger, defaultLogLevelValue string) (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)
+			}
+			fmt.Println(options)
+			options = append(options, option)
+
+		}
+	}
+
+	// if "*" is not provided, set default global level
+	if !isDefaultLogLevelSet {
+		option, err = log.AllowLevel(defaultLogLevelValue)
+		if err != nil {
+			return nil, err
+		}
+		options = append(options, option)
+	}
+
+	return log.NewFilter(logger, options...), nil
+}

libs/cli/log_level_test.go

@@ -0,0 +1,94 @@
+package cli_test
+
+import (
+	"bytes"
+	"strings"
+	"testing"
+
+	tmflags "github.com/tendermint/tendermint/libs/cli"
+	"github.com/tendermint/tendermint/libs/log"
+)
+
+const (
+	defaultLogLevelValue = "info"
+)
+
+func TestParseLogLevel(t *testing.T) {
+	var buf bytes.Buffer
+	jsonLogger := log.NewWriterLogger(&buf)
+
+	correctLogLevels := []struct {
+		lvl              string
+		expectedLogLines []string
+	}{
+		{"mempool:error", []string{
+			``, // if no default is given, assume info
+			``,
+			`{"level":"error","module":"mempool","message":"Mesmero"}`,
+			`{"level":"info","module":"state","message":"Mind"}`, // if no default is given, assume info
+			``}},
+
+		{"mempool:error,*:debug", []string{
+			`{"level":"debug","module":"mempool","module":"wire","message":"Kingpin"}`,
+			``,
+			`{"level":"error","module":"mempool","message":"Mesmero"}`,
+			`{"level":"info","module":"state","message":"Mind"}`,
+			`{"level":"debug","message":"Gideon"}`}},
+
+		{"*:debug,wire:none", []string{
+			``,
+			`{"level":"info","module":"mempool","message":"Kitty Pryde"}`,
+			`{"level":"error","module":"mempool","message":"Mesmero"}`,
+			`{"level":"info","module":"state","message":"Mind"}`,
+			`{"level":"debug","message":"Gideon"}`}},
+	}
+
+	for _, c := range correctLogLevels {
+		logger, err := tmflags.ParseLogLevel(c.lvl, jsonLogger, defaultLogLevelValue)
+		if err != nil {
+			t.Fatal(err)
+		}
+
+		buf.Reset()
+
+		logger.With("module", "mempool").With("module", "wire").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.With("module", "mempool").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.With("module", "mempool").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)
+		}
+
+		buf.Reset()
+
+		logger.With("module", "state").Info("Mind")
+		if have := strings.TrimSpace(buf.String()); c.expectedLogLines[3] != have {
+			t.Errorf("\nwant '%s'\nhave '%s'\nlevel '%s'", c.expectedLogLines[3], have, c.lvl)
+		}
+
+		buf.Reset()
+
+		logger.Debug("Gideon")
+		if have := strings.TrimSpace(buf.String()); c.expectedLogLines[4] != have {
+			t.Errorf("\nwant '%s'\nhave '%s'\nlevel '%s'", c.expectedLogLines[4], have, c.lvl)
+		}
+	}
+
+	incorrectLogLevel := []string{"some", "mempool:some", "*:some,mempool:error"}
+	for _, lvl := range incorrectLogLevel {
+		if _, err := tmflags.ParseLogLevel(lvl, jsonLogger, defaultLogLevelValue); err == nil {
+			t.Fatalf("Expected %s to produce error", lvl)
+		}
+	}
+}

libs/log/default.go

@@ -47,16 +47,16 @@ func NewDefaultLogger(format, level string) (Logger, error) {
 		return nil, fmt.Errorf("unsupported log format: %s", format)
 	}
 
-	logLevel, err := zerolog.ParseLevel(level)
-	if err != nil {
-		return nil, fmt.Errorf("failed to parse log level (%s): %w", level, err)
-	}
+	// logLevel, err := zerolog.ParseLevel(level)
+	// if err != nil {
+	// 	return nil, fmt.Errorf("failed to parse log level (%s): %w", level, err)
+	// }
 
 	// make the writer thread-safe
 	logWriter = newSyncWriter(logWriter)
 
 	return &defaultLogger{
-		Logger: zerolog.New(logWriter).Level(logLevel).With().Timestamp().Logger(),
+		Logger: zerolog.New(logWriter).With().Timestamp().Logger(),
 	}, nil
 }
 

libs/log/filter.go

@@ -0,0 +1,197 @@
+package log
+
+import (
+	"fmt"
+)
+
+type level byte
+
+const (
+	levelDebug level = 1 << iota
+	levelInfo
+	levelError
+)
+
+type filter struct {
+	next             Logger
+	allowed          level            // XOR'd levels for default case
+	initiallyAllowed level            // XOR'd levels for initial case
+	allowedKeyvals   map[keyval]level // When key-value match, use this level
+}
+
+type keyval struct {
+	key   interface{}
+	value interface{}
+}
+
+// NewFilter wraps next and implements filtering. See the commentary on the
+// Option functions for a detailed description of how to configure levels. If
+// no options are provided, all leveled log events created with Debug, Info or
+// Error helper methods are squelched.
+func NewFilter(next Logger, options ...Option) Logger {
+	l := &filter{
+		next:           next,
+		allowedKeyvals: make(map[keyval]level),
+	}
+	for _, option := range options {
+		option(l)
+	}
+	l.initiallyAllowed = l.allowed
+	return l
+}
+
+func (l *filter) Info(msg string, keyvals ...interface{}) {
+	levelAllowed := l.allowed&levelInfo != 0
+	if !levelAllowed {
+		return
+	}
+	l.next.Info(msg, keyvals...)
+}
+
+func (l *filter) Debug(msg string, keyvals ...interface{}) {
+	levelAllowed := l.allowed&levelDebug != 0
+	if !levelAllowed {
+		return
+	}
+	l.next.Debug(msg, keyvals...)
+}
+
+func (l *filter) Error(msg string, keyvals ...interface{}) {
+	levelAllowed := l.allowed&levelError != 0
+	if !levelAllowed {
+		return
+	}
+	l.next.Error(msg, keyvals...)
+}
+
+// With implements Logger by constructing a new filter with a keyvals appended
+// to the logger.
+//
+// If custom level was set for a keyval pair using one of the
+// Allow*With methods, it is used as the logger's level.
+//
+// Examples:
+//     logger = log.NewFilter(logger, log.AllowError(), log.AllowInfoWith("module", "crypto"))
+//		 logger.With("module", "crypto").Info("Hello") # produces "I... Hello module=crypto"
+//
+//     logger = log.NewFilter(logger, log.AllowError(),
+//				log.AllowInfoWith("module", "crypto"),
+// 				log.AllowNoneWith("user", "Sam"))
+//		 logger.With("module", "crypto", "user", "Sam").Info("Hello") # returns nil
+//
+//     logger = log.NewFilter(logger,
+// 				log.AllowError(),
+// 				log.AllowInfoWith("module", "crypto"), log.AllowNoneWith("user", "Sam"))
+//		 logger.With("user", "Sam").With("module", "crypto").Info("Hello") # produces "I... Hello module=crypto user=Sam"
+func (l *filter) With(keyvals ...interface{}) Logger {
+	keyInAllowedKeyvals := false
+
+	for i := len(keyvals) - 2; i >= 0; i -= 2 {
+		for kv, allowed := range l.allowedKeyvals {
+			if keyvals[i] == kv.key {
+				keyInAllowedKeyvals = true
+				// Example:
+				//		logger = log.NewFilter(logger, log.AllowError(), log.AllowInfoWith("module", "crypto"))
+				//		logger.With("module", "crypto")
+				if keyvals[i+1] == kv.value {
+					return &filter{
+						next:             l.next.With(keyvals...),
+						allowed:          allowed, // set the desired level
+						allowedKeyvals:   l.allowedKeyvals,
+						initiallyAllowed: l.initiallyAllowed,
+					}
+				}
+			}
+		}
+	}
+
+	// Example:
+	//		logger = log.NewFilter(logger, log.AllowError(), log.AllowInfoWith("module", "crypto"))
+	//		logger.With("module", "main")
+	if keyInAllowedKeyvals {
+		return &filter{
+			next:             l.next.With(keyvals...),
+			allowed:          l.initiallyAllowed, // return back to initially allowed
+			allowedKeyvals:   l.allowedKeyvals,
+			initiallyAllowed: l.initiallyAllowed,
+		}
+	}
+
+	return &filter{
+		next:             l.next.With(keyvals...),
+		allowed:          l.allowed, // simply continue with the current level
+		allowedKeyvals:   l.allowedKeyvals,
+		initiallyAllowed: l.initiallyAllowed,
+	}
+}
+
+//--------------------------------------------------------------------------------
+
+// Option sets a parameter for the filter.
+type Option func(*filter)
+
+// AllowLevel returns an option for the given level or error if no option exist
+// for such level.
+func AllowLevel(lvl string) (Option, error) {
+	switch lvl {
+	case "debug":
+		return AllowDebug(), nil
+	case "info":
+		return AllowInfo(), nil
+	case "error":
+		return AllowError(), nil
+	case "none":
+		return AllowNone(), nil
+	default:
+		return nil, fmt.Errorf("expected either \"info\", \"debug\", \"error\" or \"none\" level, given %s", lvl)
+	}
+}
+
+// AllowAll is an alias for AllowDebug.
+func AllowAll() Option {
+	return AllowDebug()
+}
+
+// AllowDebug allows error, info and debug level log events to pass.
+func AllowDebug() Option {
+	return allowed(levelError | levelInfo | levelDebug)
+}
+
+// AllowInfo allows error and info level log events to pass.
+func AllowInfo() Option {
+	return allowed(levelError | levelInfo)
+}
+
+// AllowError allows only error level log events to pass.
+func AllowError() Option {
+	return allowed(levelError)
+}
+
+// AllowNone allows no leveled log events to pass.
+func AllowNone() Option {
+	return allowed(0)
+}
+
+func allowed(allowed level) Option {
+	return func(l *filter) { l.allowed = allowed }
+}
+
+// AllowDebugWith allows error, info and debug level log events to pass for a specific key value pair.
+func AllowDebugWith(key interface{}, value interface{}) Option {
+	return func(l *filter) { l.allowedKeyvals[keyval{key, value}] = levelError | levelInfo | levelDebug }
+}
+
+// AllowInfoWith allows error and info level log events to pass for a specific key value pair.
+func AllowInfoWith(key interface{}, value interface{}) Option {
+	return func(l *filter) { l.allowedKeyvals[keyval{key, value}] = levelError | levelInfo }
+}
+
+// AllowErrorWith allows only error level log events to pass for a specific key value pair.
+func AllowErrorWith(key interface{}, value interface{}) Option {
+	return func(l *filter) { l.allowedKeyvals[keyval{key, value}] = levelError }
+}
+
+// AllowNoneWith allows no leveled log events to pass for a specific key value pair.
+func AllowNoneWith(key interface{}, value interface{}) Option {
+	return func(l *filter) { l.allowedKeyvals[keyval{key, value}] = 0 }
+}

libs/log/filter_test.go

@@ -0,0 +1,137 @@
+package log_test
+
+import (
+	"bytes"
+	"strings"
+	"testing"
+
+	"github.com/tendermint/tendermint/libs/log"
+)
+
+func TestVariousLevels(t *testing.T) {
+	testCases := []struct {
+		name    string
+		allowed log.Option
+		want    string
+	}{
+		{
+			"AllowAll",
+			log.AllowAll(),
+			strings.Join([]string{
+				`{"level":"debug","this is":"debug log","message":"here"}`,
+				`{"level":"info","this is":"info log","message":"here"}`,
+				`{"level":"error","this is":"error log","message":"here"}`,
+			}, "\n"),
+		},
+		{
+			"AllowDebug",
+			log.AllowDebug(),
+			strings.Join([]string{
+				`{"level":"debug","this is":"debug log","message":"here"}`,
+				`{"level":"info","this is":"info log","message":"here"}`,
+				`{"level":"error","this is":"error log","message":"here"}`,
+			}, "\n"),
+		},
+		{
+			"AllowInfo",
+			log.AllowInfo(),
+			strings.Join([]string{
+				`{"level":"info","this is":"info log","message":"here"}`,
+				`{"level":"error","this is":"error log","message":"here"}`,
+			}, "\n"),
+		},
+		{
+			"AllowError",
+			log.AllowError(),
+			strings.Join([]string{
+				`{"level":"error","this is":"error log","message":"here"}`,
+			}, "\n"),
+		},
+		{
+			"AllowNone",
+			log.AllowNone(),
+			``,
+		},
+	}
+
+	for _, tc := range testCases {
+		tc := tc
+		t.Run(tc.name, func(t *testing.T) {
+			var buf bytes.Buffer
+
+			logger := log.NewFilter(log.NewWriterLogger(&buf), tc.allowed)
+
+			logger.Debug("here", "this is", "debug log")
+			logger.Info("here", "this is", "info log")
+			logger.Error("here", "this is", "error log")
+
+			if want, have := tc.want, strings.TrimSpace(buf.String()); want != have {
+				t.Errorf("\nwant:\n%s\nhave:\n%s", want, have)
+			}
+		})
+	}
+}
+
+func TestLevelContext(t *testing.T) {
+	var buf bytes.Buffer
+	logger := log.NewFilter(log.NewWriterLogger(&buf), log.AllowError())
+
+	logger.Error("foo", "bar", "baz")
+
+	want := `{"level":"error","bar":"baz","message":"foo"}`
+	have := strings.TrimSpace(buf.String())
+	if want != have {
+		t.Errorf("\nwant '%s'\nhave '%s'", want, have)
+	}
+
+	buf.Reset()
+	logger.Info("foo", "bar", "baz")
+	if want, have := ``, strings.TrimSpace(buf.String()); want != have {
+		t.Errorf("\nwant '%s'\nhave '%s'", want, have)
+	}
+}
+func TestVariousAllowWith(t *testing.T) {
+	var buf bytes.Buffer
+
+	logger := log.NewWriterLogger(&buf)
+
+	logger1 := log.NewFilter(logger, log.AllowError(), log.AllowInfoWith("context", "value"))
+	logger1.With("context", "value").Info("foo", "bar", "baz")
+
+	want := `{"level":"info","context":"value","bar":"baz","message":"foo"}`
+	have := strings.TrimSpace(buf.String())
+	if want != have {
+		t.Errorf("\nwant '%s'\nhave '%s'", want, have)
+	}
+
+	buf.Reset()
+
+	logger2 := log.NewFilter(
+		logger,
+		log.AllowError(),
+		log.AllowInfoWith("context", "value"),
+		log.AllowNoneWith("user", "Sam"),
+	)
+
+	logger2.With("context", "value", "user", "Sam").Info("foo", "bar", "baz")
+	if want, have := ``, strings.TrimSpace(buf.String()); want != have {
+		t.Errorf("\nwant '%s'\nhave '%s'", want, have)
+	}
+
+	buf.Reset()
+
+	logger3 := log.NewFilter(
+		logger,
+		log.AllowError(),
+		log.AllowInfoWith("context", "value"),
+		log.AllowNoneWith("user", "Sam"),
+	)
+
+	logger3.With("user", "Sam").With("context", "value").Info("foo", "bar", "baz")
+
+	want = `{"level":"info","user":"Sam","context":"value","bar":"baz","message":"foo"}`
+	have = strings.TrimSpace(buf.String())
+	if want != have {
+		t.Errorf("\nwant '%s'\nhave '%s'", want, have)
+	}
+}

libs/log/testing.go

@@ -1,6 +1,7 @@
 package log
 
 import (
+	"io"
 	"testing"
 
 	"github.com/rs/zerolog"
@@ -49,3 +50,9 @@ func (tw testingWriter) Write(in []byte) (int, error) {
 	tw.t.Log(string(in))
 	return len(in), nil
 }
+
+func NewWriterLogger(writer io.Writer) Logger {
+	return defaultLogger{
+		Logger: zerolog.New(writer).With().Logger(),
+	}
+}

node/node.go

@@ -348,7 +348,7 @@ func makeNode(
 	}
 
 	if cfg.P2P.PexReactor {
-		node.services = append(node.services, pex.NewReactor(logger, peerManager, node.router.OpenChannel, peerManager.Subscribe))
+		node.services = append(node.services, pex.NewReactor(logger.With("module", "p2p"), peerManager, node.router.OpenChannel, peerManager.Subscribe))
 	}
 
 	// Set up state sync reactor, and schedule a sync if requested.