diff --git a/cmd/abcidump/cmd/rootcmd.go b/cmd/abcidump/cmd/rootcmd.go index 872400a0cd..37c599594b 100644 --- a/cmd/abcidump/cmd/rootcmd.go +++ b/cmd/abcidump/cmd/rootcmd.go @@ -20,7 +20,7 @@ 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) } @@ -28,7 +28,7 @@ func MakeRootCmd() *cobra.Command { 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 } diff --git a/cmd/tenderdash/commands/light.go b/cmd/tenderdash/commands/light.go index acbe7ac21b..3dd149a6fc 100644 --- a/cmd/tenderdash/commands/light.go +++ b/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") diff --git a/cmd/tenderdash/commands/root.go b/cmd/tenderdash/commands/root.go index 2c2b2bff84..b9c4dcab38 100644 --- a/cmd/tenderdash/commands/root.go +++ b/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 { diff --git a/cmd/tenderdash/main.go b/cmd/tenderdash/main.go index 6ab26dc628..3b12f44e72 100644 --- a/cmd/tenderdash/main.go +++ b/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 } diff --git a/internal/consensus/pbts_test.go b/internal/consensus/pbts_test.go index 203fc32f46..ae3e668ed6 100644 --- a/internal/consensus/pbts_test.go +++ b/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) diff --git a/internal/consensus/peer_state.go b/internal/consensus/peer_state.go index 607fc3be86..a3b0cd4907 100644 --- a/internal/consensus/peer_state.go +++ b/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 } diff --git a/internal/consensus/state_add_prop_block.go b/internal/consensus/state_add_prop_block.go index bf2b5d4376..56bb5b7dfb 100644 --- a/internal/consensus/state_add_prop_block.go +++ b/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, diff --git a/libs/log/default.go b/libs/log/default.go index 64d2095e63..9e8f3ef6fb 100644 --- a/libs/log/default.go +++ b/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,6 +82,15 @@ 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()} } @@ -85,7 +98,7 @@ func (l defaultLogger) With(keyVals ...interface{}) 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) diff --git a/libs/log/default_test.go b/libs/log/default_test.go index 5d828a5444..ed9992987d 100644 --- a/libs/log/default_test.go +++ b/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": { diff --git a/libs/log/logger.go b/libs/log/logger.go index 3d41660aec..60f8a6061f 100644 --- a/libs/log/logger.go +++ b/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{}) diff --git a/libs/log/testing.go b/libs/log/testing.go index e356163255..44851122e6 100644 --- a/libs/log/testing.go +++ b/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) } diff --git a/libs/log/testing_test.go b/libs/log/testing_test.go index 9582d11a91..4241e5631a 100644 --- a/libs/log/testing_test.go +++ b/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") diff --git a/test/e2e/node/main.go b/test/e2e/node/main.go index caf90c2ac4..703cb42cc8 100644 --- a/test/e2e/node/main.go +++ b/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 }