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 (trace|debug|info|warn|error)")
 	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, conf.LogFilePath); err != nil {
+			if err := log.OverrideWithNewLogger(logger, conf.LogFormat, log.Level(conf.LogLevel), conf.LogFilePath); err != nil {
 				return err
 			}
 			if warning := pconf.DeprecatedFieldWarning(); warning != nil {
@@ -63,7 +63,7 @@ func RootCommand(conf *config.Config, logger log.Logger) *cobra.Command {
 	}
 	cmd.PersistentFlags().StringP(cli.HomeFlag, "", os.ExpandEnv(filepath.Join("$HOME", config.DefaultTendermintDir)), "directory for config and data")
 	cmd.PersistentFlags().Bool(cli.TraceFlag, false, "print out full stack trace on errors")
-	cmd.PersistentFlags().String("log-level", conf.LogLevel, "log level")
+	cmd.PersistentFlags().String("log-level", conf.LogLevel, "log level (trace|debug|info|warn|error)")
 	cobra.OnInitialize(func() { cli.InitEnv("TM") })
 	return cmd
 }

cmd/tenderdash/main.go

@@ -21,7 +21,7 @@ func main() {
 		panic(err)
 	}
 
-	logger, err := log.NewMultiLogger(conf.LogFormat, conf.LogLevel, conf.LogFilePath)
+	logger, err := log.NewMultiLogger(conf.LogFormat, log.Level(conf.LogLevel), conf.LogFilePath)
 	if err != nil {
 		panic(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,

internal/consensus/state_enter_propose.go

@@ -87,8 +87,6 @@ func (c *EnterProposeAction) Execute(ctx context.Context, stateEvent StateEvent)
 		logger.Info("propose step; not our turn to propose",
 			"proposer_proTxHash", stateData.Validators.GetProposer().ProTxHash,
 			"node_proTxHash", proTxHash.String(),
-			"height", stateData.Height,
-			"round", stateData.Round,
 			"step", stateData.Step)
 		return nil
 	}
@@ -100,8 +98,6 @@ func (c *EnterProposeAction) Execute(ctx context.Context, stateEvent StateEvent)
 
 	logger.Info("propose step; our turn to propose",
 		"proposer_proTxHash", proTxHash.ShortString(),
-		"height", stateData.Height,
-		"round", stateData.Round,
 		"step", stateData.Step,
 	)
 	// Flush the WAL. Otherwise, we may not recompute the same proposal to sign,

internal/state/execution.go

@@ -395,10 +395,10 @@ func (blockExec *BlockExecutor) ValidateBlockWithRoundState(
 	// Validate app info
 	if uncommittedState.AppHash != nil && !bytes.Equal(block.AppHash, uncommittedState.AppHash) {
 		return fmt.Errorf(
-			"wrong Block.Header.AppHash at state height %d, block %d. Expected %X, got %X",
+			"Block.Header.AppHash mismatch; state (or ABCI App) at height %d expects App Hash %X, block at height %d expects App Hash %X",
 			uncommittedState.GetHeight(),
-			block.Height,
 			uncommittedState.AppHash,
+			block.Height,
 			block.AppHash,
 		)
 	}

libs/log/default.go

@@ -26,7 +26,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) {
 	return NewMultiLogger(format, level, "")
 }
 
@@ -39,7 +39,7 @@ func NewDefaultLogger(format, level string) (Logger, error) {
 // The function returns a Logger interface and an error if any.
 //
 // See NewDefaultLogger for more details.
-func NewMultiLogger(format, level, additionalLogPath string) (Logger, error) {
+func NewMultiLogger(format string, level Level, additionalLogPath string) (Logger, error) {
 	var (
 		writer    io.Writer = os.Stderr
 		closeFunc           = func() error { return nil }
@@ -70,24 +70,26 @@ func NewMultiLogger(format, level, additionalLogPath string) (Logger, error) {
 	return logger, nil
 }
 
-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)
 	}
 
 	// make the writer thread-safe
 	logWriter = newSyncWriter(logWriter)
 
-	return &defaultLogger{
-		Logger: zerolog.New(logWriter).Level(logLevel).With().Timestamp().Logger(),
-	}, nil
+	return &defaultLogger{Logger: zerolog.New(logWriter).Level(logLevel).With().Timestamp().Logger()}, nil
 }
 
 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)
 }
@@ -100,9 +102,19 @@ 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()}
 }
+
 func (l *defaultLogger) Close() (err error) {
 	if l == nil {
 		return nil
@@ -122,7 +134,7 @@ func (l *defaultLogger) Close() (err error) {
 // 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, additionalLogFilePath string) error {
+func OverrideWithNewLogger(logger Logger, format string, level Level, additionalLogFilePath string) 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,19 +24,32 @@ 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 {
 	io.Closer
 
+	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
 	}