chore: improve logging

cmd/abcidump/cmd/rootcmd.go

@@ -20,15 +20,15 @@ func MakeRootCmd() *cobra.Command {
 		Use:   "abcidump",
 		Short: "Parse dump of protobuf communication between two nodes",
 		PersistentPreRunE: func(cmd *cobra.Command, args []string) (err error) {
-			logger, err = log.NewDefaultLogger(log.LogFormatPlain, logLevel)
+			logger, err = log.NewDefaultLogger(log.LogFormatPlain, log.Level(logLevel))
 			if err != nil {
 				return fmt.Errorf("cannot initialize logging: %w", err)
 			}
 			logger = logger.With("module", "abcidump")
 			return nil
 		},
 	}
-	cmd.PersistentFlags().StringVar(&logLevel, "log-level", log.LogLevelInfo, "log level")
+	cmd.PersistentFlags().StringVar(&logLevel, "log-level", log.LogLevelInfo.String(), "log level")
 
 	return cmd
 }

cmd/tenderdash/commands/light.go

@@ -215,7 +215,7 @@ for applications built w/ Cosmos SDK).
 		"max-open-connections",
 		900,
 		"maximum number of simultaneous connections (including WebSocket).")
-	cmd.Flags().StringVar(&logLevel, "log-level", log.LogLevelInfo, "The logging level (debug|info|warn|error|fatal)")
+	cmd.Flags().StringVar(&logLevel, "log-level", log.LogLevelInfo.String(), "The logging level (debug|info|warn|error|fatal)")
 	cmd.Flags().StringVar(&logFormat, "log-format", log.LogFormatPlain, "The logging format (text|json)")
 	cmd.Flags().StringVar(&dashCoreRPCHost, "dchost", "",
 		"host address of the Dash Core RPC node")

cmd/tenderdash/commands/root.go

@@ -51,7 +51,7 @@ 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 {
+			if err := log.OverrideWithNewLogger(logger, conf.LogFormat, log.Level(conf.LogLevel)); err != nil {
 				return err
 			}
 			if warning := pconf.DeprecatedFieldWarning(); warning != nil {

cmd/tenderdash/main.go

@@ -88,7 +88,7 @@ func newLoggerFromConfig(conf *config.Config) (log.Logger, func(), error) {
 	if err != nil {
 		return nil, nil, fmt.Errorf("failed to create log formatter: %w", err)
 	}
-	logger, err := log.NewLogger(conf.LogLevel, writer)
+	logger, err := log.NewLogger(log.Level(conf.LogLevel), writer)
 	if err != nil {
 		return nil, nil, err
 	}

internal/consensus/pbts_test.go

@@ -7,7 +7,6 @@ import (
 	"testing"
 	"time"
 
-	"github.com/rs/zerolog"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
 
@@ -102,7 +101,7 @@ func newPBTSTestHarness(ctx context.Context, t *testing.T, tc pbtsTestConfigurat
 		Time:       tc.genesisTime,
 		Validators: validators,
 	})
-	logger := log.NewTestingLoggerWithLevel(t, zerolog.LevelDebugValue)
+	logger := log.NewTestingLoggerWithLevel(t, log.LogLevelDebug)
 	kvApp, err := kvstore.NewMemoryApp(kvstore.WithLogger(logger))
 	require.NoError(t, err)
 

internal/consensus/peer_state.go

@@ -5,6 +5,7 @@ import (
 	"encoding/json"
 	"errors"
 	"fmt"
+	"math"
 	"time"
 
 	sync "github.com/sasha-s/go-deadlock"
@@ -173,7 +174,11 @@ func (ps *PeerState) InitProposalBlockParts(partSetHeader types.PartSetHeader) {
 func (ps *PeerState) SetHasProposalBlockPart(height int64, round int32, index int) {
 	prs := ps.GetRoundState()
 	if prs.Height != height || prs.Round != round {
-		ps.logger.Debug("SetHasProposalBlockPart height/round mismatch",
+		lvl := log.LogLevelTrace
+		if math.Abs(float64(prs.Height-height)) > 1 || math.Abs(float64(prs.Round-round)) > 1 {
+			lvl = log.LogLevelWarn
+		}
+		ps.logger.Log(lvl, "SetHasProposalBlockPart height/round mismatch",
 			"height", height, "round", round, "peer_height", prs.Height, "peer_round", prs.Round)
 		return
 	}

internal/consensus/state_add_prop_block.go

@@ -5,6 +5,7 @@ import (
 	"errors"
 	"fmt"
 	"io"
+	"math"
 
 	"github.com/gogo/protobuf/proto"
 
@@ -84,8 +85,14 @@ func (c *AddProposalBlockPartAction) addProposalBlockPart(
 	)
 
 	// Blocks might be reused, so round mismatch is OK
+	// Height mismatch > 1 might be a warning condition
 	if stateData.Height != height {
-		c.logger.Debug(
+		lvl := log.LogLevelTrace
+		if math.Abs(float64(stateData.Height-height)) > 1 {
+			lvl = log.LogLevelWarn
+		}
+
+		c.logger.Log(lvl,
 			"received block part from wrong height",
 			"height", stateData.Height,
 			"round", stateData.Round,

libs/log/default.go

@@ -24,7 +24,7 @@ type defaultLogger struct {
 // Since zerolog supports typed structured logging and it is difficult to reflect
 // that in a generic interface, all logging methods accept a series of key/value
 // pair tuples, where the key must be a string.
-func NewDefaultLogger(format, level string) (Logger, error) {
+func NewDefaultLogger(format string, level Level) (Logger, error) {
 	var logWriter io.Writer
 	switch strings.ToLower(format) {
 	case LogFormatPlain, LogFormatText:
@@ -50,8 +50,8 @@ func NewDefaultLogger(format, level string) (Logger, error) {
 	return NewLogger(level, logWriter)
 }
 
-func NewLogger(level string, logWriter io.Writer) (Logger, error) {
-	logLevel, err := zerolog.ParseLevel(level)
+func NewLogger(level Level, logWriter io.Writer) (Logger, error) {
+	logLevel, err := level.ToZerologLevel()
 	if err != nil {
 		return nil, fmt.Errorf("failed to parse log level (%s): %w", level, err)
 	}
@@ -66,6 +66,10 @@ func (l defaultLogger) Info(msg string, keyVals ...interface{}) {
 	l.Logger.Info().Fields(getLogFields(keyVals...)).Msg(msg)
 }
 
+func (l defaultLogger) Warn(msg string, keyVals ...interface{}) {
+	l.Logger.Warn().Fields(getLogFields(keyVals...)).Msg(msg)
+}
+
 func (l defaultLogger) Error(msg string, keyVals ...interface{}) {
 	l.Logger.Error().Fields(getLogFields(keyVals...)).Msg(msg)
 }
@@ -78,14 +82,23 @@ func (l defaultLogger) Trace(msg string, keyVals ...interface{}) {
 	l.Logger.Trace().Fields(getLogFields(keyVals...)).Msg(msg)
 }
 
+func (l defaultLogger) Log(level Level, msg string, keyVals ...interface{}) {
+	lvl, err := level.ToZerologLevel()
+	if err != nil {
+		panic("invalid log level " + string(level) + ": " + err.Error())
+	}
+
+	l.Logger.WithLevel(lvl).Fields(getLogFields(keyVals...)).Msg(msg)
+}
+
 func (l defaultLogger) With(keyVals ...interface{}) Logger {
 	return &defaultLogger{Logger: l.Logger.With().Fields(getLogFields(keyVals...)).Logger()}
 }
 
 // OverrideWithNewLogger replaces an existing logger's internal with
 // a new logger, and makes it possible to reconfigure an existing
 // logger that has already been propagated to callers.
-func OverrideWithNewLogger(logger Logger, format, level string) error {
+func OverrideWithNewLogger(logger Logger, format string, level Level) error {
 	ol, ok := logger.(*defaultLogger)
 	if !ok {
 		return fmt.Errorf("logger %T cannot be overridden", logger)

libs/log/default_test.go

@@ -11,7 +11,7 @@ import (
 func TestNewDefaultLogger(t *testing.T) {
 	testCases := map[string]struct {
 		format    string
-		level     string
+		level     log.Level
 		expectErr bool
 	}{
 		"invalid format": {

libs/log/logger.go

@@ -3,6 +3,7 @@ package log
 import (
 	"io"
 
+	"github.com/rs/zerolog"
 	sync "github.com/sasha-s/go-deadlock"
 )
 
@@ -23,17 +24,30 @@ const (
 	LogFormatJSON string = "json"
 
 	// Supported loging levels
-	LogLevelTrace = "trace"
-	LogLevelDebug = "debug"
-	LogLevelInfo  = "info"
-	LogLevelWarn  = "warn"
-	LogLevelError = "error"
+	LogLevelTrace Level = "trace"
+	LogLevelDebug Level = "debug"
+	LogLevelInfo  Level = "info"
+	LogLevelWarn  Level = "warn"
+	LogLevelError Level = "error"
 )
 
+type Level string
+
+func (l Level) ToZerologLevel() (zerolog.Level, error) {
+	return zerolog.ParseLevel(string(l))
+}
+
+func (l Level) String() string {
+	return string(l)
+}
+
 // Logger defines a generic logging interface compatible with Tendermint.
 type Logger interface {
+	Log(level Level, msg string, keyVals ...interface{})
+
 	Trace(msg string, keyVals ...interface{})
 	Debug(msg string, keyVals ...interface{})
+	Warn(msg string, keyVals ...interface{})
 	Info(msg string, keyVals ...interface{})
 	Error(msg string, keyVals ...interface{})
 

libs/log/testing.go

@@ -33,13 +33,13 @@ func NewTestingLogger(t testing.TB) *TestingLogger {
 
 // NewTestingLoggerWithLevel creates a testing logger instance at a
 // specific level that wraps the behavior of testing.T.Log().
-func NewTestingLoggerWithLevel(t testing.TB, level string) *TestingLogger {
+func NewTestingLoggerWithLevel(t testing.TB, level Level) *TestingLogger {
 	t.Helper()
 	t.Cleanup(func() {
 		// we need time to properly flush all logs, otherwise test can fail with race condition
 		time.Sleep(10 * time.Millisecond)
 	})
-	logLevel, err := zerolog.ParseLevel(level)
+	logLevel, err := zerolog.ParseLevel(string(level))
 	if err != nil {
 		t.Fatalf("failed to parse log level (%s): %v", level, err)
 	}

libs/log/testing_test.go

@@ -3,12 +3,10 @@ package log
 import (
 	"regexp"
 	"testing"
-
-	"github.com/rs/zerolog"
 )
 
 func TestTestingMatches(t *testing.T) {
-	logger := NewTestingLoggerWithLevel(t, zerolog.LevelDebugValue)
+	logger := NewTestingLoggerWithLevel(t, LogLevelDebug)
 	logger.AssertMatch(regexp.MustCompile("some text"))
 	logger.Debug("some initial text that is no match")
 	logger.Debug("this is some text to match")

test/e2e/node/main.go

@@ -362,7 +362,7 @@ func setupNode() (*config.Config, log.Logger, error) {
 		return nil, nil, fmt.Errorf("error in config file: %w", err)
 	}
 
-	nodeLogger, err := log.NewDefaultLogger(tmcfg.LogFormat, tmcfg.LogLevel)
+	nodeLogger, err := log.NewDefaultLogger(tmcfg.LogFormat, log.Level(tmcfg.LogLevel))
 	if err != nil {
 		return nil, nil, err
 	}