From be955efe25b71cbab31fe891e3013a90fad339fc Mon Sep 17 00:00:00 2001 From: Aaron Craelius Date: Tue, 13 May 2025 16:48:30 -0400 Subject: [PATCH] feat: verbose logging during upgrades (#24720) Co-authored-by: Alex | Interchain Labs --- CHANGELOG.md | 3 + client/flags/flags.go | 7 +- go.mod | 4 +- go.sum | 2 - log/CHANGELOG.md | 2 + log/level_test.go | 129 ++++++++++++++++++++++++++++++ log/logger.go | 63 ++++++++++++--- log/options.go | 21 ++++- log/with_test.go | 46 +++++++++++ log/writer.go | 9 ++- server/cmd/execute.go | 1 + server/util.go | 17 ++++ server/verbose_level_test.go | 32 ++++++++ simapp/go.mod | 3 +- simapp/go.sum | 2 - simapp/upgrades.go | 2 + systemtests/go.mod | 1 + systemtests/go.sum | 2 - systemtests/system.go | 24 +++++- tests/go.mod | 1 + tests/go.sum | 2 - tests/systemtests/go.mod | 1 + tests/systemtests/go.sum | 2 - tests/systemtests/upgrade_test.go | 5 ++ types/module/module.go | 1 + x/upgrade/CHANGELOG.md | 2 + x/upgrade/keeper/keeper.go | 14 ++++ 27 files changed, 364 insertions(+), 34 deletions(-) create mode 100644 log/with_test.go create mode 100644 server/verbose_level_test.go diff --git a/CHANGELOG.md b/CHANGELOG.md index e77f4cca6b..93e1f0dfce 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -38,6 +38,9 @@ Ref: https://keepachangelog.com/en/1.0.0/ ## [Unreleased] +### Features +* (server) [#24720](https://github.com/cosmos/cosmos-sdk/pull/24720) add `verbose_log_level` flag for configuring the log level when switching to verbose logging mode during sensitive operations (such as chain upgrades). + ### Improvements * (baseapp) [#24655](https://github.com/cosmos/cosmos-sdk/pull/24655) Add mutex locks for `state` and make `lastCommitInfo` atomic to prevent race conditions between `Commit` and `CreateQueryContext`. diff --git a/client/flags/flags.go b/client/flags/flags.go index c7f8ebf674..fd6d25e04f 100644 --- a/client/flags/flags.go +++ b/client/flags/flags.go @@ -87,9 +87,10 @@ const ( // This differs from FlagOutputDocument that is used to set the output file. FlagOutput = "output" // Logging flags - FlagLogLevel = "log_level" - FlagLogFormat = "log_format" - FlagLogNoColor = "log_no_color" + FlagLogLevel = "log_level" + FlagVerboseLogLevel = "verbose_log_level" + FlagLogFormat = "log_format" + FlagLogNoColor = "log_no_color" ) // List of supported output formats diff --git a/go.mod b/go.mod index dec49f4bf4..b1c3272e83 100644 --- a/go.mod +++ b/go.mod @@ -216,9 +216,7 @@ require ( // Here are the short-lived replace from the Cosmos SDK // Replace here are pending PRs, or version to be tagged -// replace ( -// -// ) +replace cosmossdk.io/log => ./log // Replace all unreleased direct deps upgraded to comet v1 replace ( diff --git a/go.sum b/go.sum index 4f05b0e9ff..dd0340c307 100644 --- a/go.sum +++ b/go.sum @@ -620,8 +620,6 @@ cosmossdk.io/depinject v1.2.0 h1:6NW/FSK1IkWTrX7XxUpBmX1QMBozpEI9SsWkKTBc5zw= cosmossdk.io/depinject v1.2.0/go.mod h1:pvitjtUxZZZTQESKNS9KhGjWVslJZxtO9VooRJYyPjk= cosmossdk.io/errors v1.0.2 h1:wcYiJz08HThbWxd/L4jObeLaLySopyyuUFB5w4AGpCo= cosmossdk.io/errors v1.0.2/go.mod h1:0rjgiHkftRYPj//3DrD6y8hcm40HcPv/dR4R/4efr0k= -cosmossdk.io/log v1.5.1 h1:wLwiYXmfrort/O+j6EkjF+HvbdrRQd+4cYCPKFSm+zM= -cosmossdk.io/log v1.5.1/go.mod h1:5cXXBvfBkR2/BcXmosdCSLXllvgSjphrrDVdfVRmBGM= cosmossdk.io/math v1.5.3 h1:WH6tu6Z3AUCeHbeOSHg2mt9rnoiUWVWaQ2t6Gkll96U= cosmossdk.io/math v1.5.3/go.mod h1:uqcZv7vexnhMFJF+6zh9EWdm/+Ylyln34IvPnBauPCQ= cosmossdk.io/schema v1.1.0 h1:mmpuz3dzouCoyjjcMcA/xHBEmMChN+EHh8EHxHRHhzE= diff --git a/log/CHANGELOG.md b/log/CHANGELOG.md index 70c661e724..ae450d54f8 100644 --- a/log/CHANGELOG.md +++ b/log/CHANGELOG.md @@ -22,6 +22,8 @@ Each entry must include the Github issue reference in the following format: ## [Unreleased] +* [#24720](https://github.com/cosmos/cosmos-sdk/pull/24720) add `VerboseModeLogger` extension interface and `VerboseLevel` configuration option for increasing log verbosity during sensitive operations such as upgrades. + ## [v1.5.1](https://github.com/cosmos/cosmos-sdk/releases/tag/log/v1.5.1) - 2025-03-07 * [#23928](https://github.com/cosmos/cosmos-sdk/pull/23928) Bump sonic json library to [v1.3.1](https://github.com/bytedance/sonic/releases/tag/v1.13.1) for Go 1.24 compatibility. diff --git a/log/level_test.go b/log/level_test.go index 9b7e2a5ac1..cde9e53a6e 100644 --- a/log/level_test.go +++ b/log/level_test.go @@ -1,8 +1,12 @@ package log_test import ( + "bytes" + "fmt" "testing" + "github.com/rs/zerolog" + "cosmossdk.io/log" ) @@ -88,3 +92,128 @@ func TestParseLogLevel(t *testing.T) { t.Errorf("expected filter to return true for state:debug") } } + +func TestVerboseMode(t *testing.T) { + logMessages := []struct { + level zerolog.Level + module string + message string + }{ + { + zerolog.InfoLevel, + "foo", + "msg 1", + }, + { + zerolog.WarnLevel, + "foo", + "msg 2", + }, + { + zerolog.ErrorLevel, + "bar", + "msg 3", + }, + { + zerolog.DebugLevel, + "foo", + "msg 4", + }, + } + tt := []struct { + name string + level zerolog.Level + verboseLevel zerolog.Level + filter string + expected string + }{ + { + name: "verbose mode simple case", + level: zerolog.WarnLevel, + verboseLevel: zerolog.DebugLevel, + expected: `* WRN msg 2 module=foo +* ERR msg 3 module=bar +* ERR Start Verbose Mode +* INF msg 1 module=foo +* WRN msg 2 module=foo +* ERR msg 3 module=bar +* DBG msg 4 module=foo +`, + }, + { + name: "verbose mode with filter", + level: zerolog.WarnLevel, + verboseLevel: zerolog.InfoLevel, + filter: "foo:error", + expected: `* ERR msg 3 module=bar +* ERR Start Verbose Mode +* INF msg 1 module=foo +* WRN msg 2 module=foo +* ERR msg 3 module=bar +`, + }, + { + name: "no verbose mode", + level: zerolog.WarnLevel, + verboseLevel: zerolog.NoLevel, + expected: `* WRN msg 2 module=foo +* ERR msg 3 module=bar +* ERR Start Verbose Mode +* WRN msg 2 module=foo +* ERR msg 3 module=bar +`, + }, + { + name: "no verbose mode with filter", + level: zerolog.WarnLevel, + verboseLevel: zerolog.NoLevel, + filter: "foo:error", + expected: `* ERR msg 3 module=bar +* ERR Start Verbose Mode +* ERR msg 3 module=bar +`, + }, + } + for i, tc := range tt { + t.Run(fmt.Sprintf("%d: %s", i, tc.name), func(t *testing.T) { + out := new(bytes.Buffer) + opts := []log.Option{ + log.LevelOption(tc.level), + log.VerboseLevelOption(tc.verboseLevel), + log.ColorOption(false), + log.TimeFormatOption("*"), // disable non-deterministic time format + } + if tc.filter != "" { + filter, err := log.ParseLogLevel(tc.filter) + if err != nil { + t.Fatalf("failed to parse log level: %v", err) + } + opts = append(opts, log.FilterOption(filter)) + } + logger := log.NewLogger(out, opts...) + writeMsgs := func() { + for _, msg := range logMessages { + switch msg.level { + case zerolog.InfoLevel: + logger.Info(msg.message, log.ModuleKey, msg.module) + case zerolog.WarnLevel: + logger.Warn(msg.message, log.ModuleKey, msg.module) + case zerolog.DebugLevel: + logger.Debug(msg.message, log.ModuleKey, msg.module) + case zerolog.ErrorLevel: + logger.Error(msg.message, log.ModuleKey, msg.module) + default: + t.Fatalf("unexpected level: %v", msg.level) + } + } + } + writeMsgs() + logger.Error("Start Verbose Mode") + logger.(log.VerboseModeLogger).SetVerboseMode(true) + writeMsgs() + if tc.expected != out.String() { + t.Fatalf("expected:\n%s\ngot:\n%s", tc.expected, out.String()) + } + }) + } +} diff --git a/log/logger.go b/log/logger.go index d8f5a314c0..ea7cb58201 100644 --- a/log/logger.go +++ b/log/logger.go @@ -62,6 +62,15 @@ type Logger interface { Impl() any } +// VerboseModeLogger is an extension interface of Logger which allows verbosity to be configured. +type VerboseModeLogger interface { + Logger + // SetVerboseMode configures whether the logger enters verbose mode or not for + // special operations where increased observability of log messages is desired + // (such as chain upgrades). + SetVerboseMode(bool) +} + // WithJSONMarshal configures zerolog global json encoding. func WithJSONMarshal(marshaler func(v any) ([]byte, error)) { zerolog.InterfaceMarshalFunc = func(i any) ([]byte, error) { @@ -80,6 +89,11 @@ func WithJSONMarshal(marshaler func(v any) ([]byte, error)) { type zeroLogWrapper struct { *zerolog.Logger + regularLevel zerolog.Level + verboseLevel zerolog.Level + // this field is used to disable filtering during verbose logging + // and will only be non-nil when we have a filterWriter + filterWriter *filterWriter } // NewLogger returns a new logger that writes to the given destination. @@ -105,8 +119,13 @@ func NewLogger(dst io.Writer, options ...Option) Logger { } } + var fltWtr *filterWriter if logCfg.Filter != nil { - output = NewFilterWriter(output, logCfg.Filter) + fltWtr = &filterWriter{ + parent: output, + filter: logCfg.Filter, + } + output = fltWtr } logger := zerolog.New(output) @@ -123,18 +142,25 @@ func NewLogger(dst io.Writer, options ...Option) Logger { logger = logger.With().Timestamp().Logger() } - if logCfg.Level != zerolog.NoLevel { - logger = logger.Level(logCfg.Level) - } - + logger = logger.Level(logCfg.Level) logger = logger.Hook(logCfg.Hooks...) - return zeroLogWrapper{&logger} + return zeroLogWrapper{ + Logger: &logger, + regularLevel: logCfg.Level, + verboseLevel: logCfg.VerboseLevel, + filterWriter: fltWtr, + } } // NewCustomLogger returns a new logger with the given zerolog logger. func NewCustomLogger(logger zerolog.Logger) Logger { - return zeroLogWrapper{&logger} + return zeroLogWrapper{ + Logger: &logger, + regularLevel: logger.GetLevel(), + verboseLevel: zerolog.NoLevel, + filterWriter: nil, + } } // Info takes a message and a set of key/value pairs and logs with level INFO. @@ -164,13 +190,15 @@ func (l zeroLogWrapper) Debug(msg string, keyVals ...interface{}) { // With returns a new wrapped logger with additional context provided by a set. func (l zeroLogWrapper) With(keyVals ...interface{}) Logger { logger := l.Logger.With().Fields(keyVals).Logger() - return zeroLogWrapper{&logger} + l.Logger = &logger + return l } // WithContext returns a new wrapped logger with additional context provided by a set. func (l zeroLogWrapper) WithContext(keyVals ...interface{}) any { logger := l.Logger.With().Fields(keyVals).Logger() - return zeroLogWrapper{&logger} + l.Logger = &logger + return l } // Impl returns the underlying zerolog logger. @@ -179,6 +207,23 @@ func (l zeroLogWrapper) Impl() interface{} { return l.Logger } +// SetVerboseMode implements VerboseModeLogger interface. +func (l zeroLogWrapper) SetVerboseMode(enable bool) { + if enable && l.verboseLevel != zerolog.NoLevel { + *l.Logger = l.Level(l.verboseLevel) + if l.filterWriter != nil { + l.filterWriter.disableFilter = true + } + } else { + *l.Logger = l.Level(l.regularLevel) + if l.filterWriter != nil { + l.filterWriter.disableFilter = false + } + } +} + +var _ VerboseModeLogger = zeroLogWrapper{} + // NewNopLogger returns a new logger that does nothing. func NewNopLogger() Logger { // The custom nopLogger is about 3x faster than a zeroLogWrapper with zerolog.Nop(). diff --git a/log/options.go b/log/options.go index 28cfefee2e..94a4ca4564 100644 --- a/log/options.go +++ b/log/options.go @@ -8,7 +8,7 @@ import ( // defaultConfig has all the options disabled, except Color and TimeFormat var defaultConfig = Config{ - Level: zerolog.NoLevel, + Level: zerolog.TraceLevel, // this is the default level that zerolog initializes new Logger's with Filter: nil, OutputJSON: false, Color: true, @@ -19,7 +19,16 @@ var defaultConfig = Config{ // Config defines configuration for the logger. type Config struct { - Level zerolog.Level + // Level is the default logging level. + Level zerolog.Level + // VerboseLevel is the logging level to use when verbose mode is enabled. + // If there is a filter enabled, it will be disabled when verbose mode is enabled + // and all log messages will be emitted at the VerboseLevel. + // If this is set to NoLevel, then no changes to the logging level or filter will be made + // when verbose mode is enabled. + VerboseLevel zerolog.Level + // Filter is the filter function to use that allows for filtering by key and level. + // When verbose mode is enabled, the filter will be disabled unless VerboseLevel is set to NoLevel. Filter FilterFunc OutputJSON bool Color bool @@ -45,6 +54,14 @@ func LevelOption(level zerolog.Level) Option { } } +// VerboseLevelOption sets the verbose level for the Logger. +// When verbose mode is enabled, the logger will be switched to this level. +func VerboseLevelOption(level zerolog.Level) Option { + return func(cfg *Config) { + cfg.VerboseLevel = level + } +} + // OutputJSONOption sets the output of the logger to JSON. // By default, the logger outputs to a human-readable format. func OutputJSONOption() Option { diff --git a/log/with_test.go b/log/with_test.go new file mode 100644 index 0000000000..4c89ad836b --- /dev/null +++ b/log/with_test.go @@ -0,0 +1,46 @@ +package log + +import ( + "bytes" + "testing" + + "github.com/rs/zerolog" +) + +// this test ensures that when the With and WithContext methods are called, +// that the log wrapper is properly copied with all of its associated options +// otherwise, verbose mode will fail +func TestLoggerWith(t *testing.T) { + logger := zerolog.New(&bytes.Buffer{}) + regularLevel := zerolog.WarnLevel + verboseLevel := zerolog.InfoLevel + filterWriter := &filterWriter{} + wrapper := zeroLogWrapper{ + Logger: &logger, + regularLevel: regularLevel, + verboseLevel: verboseLevel, + filterWriter: filterWriter, + } + + wrapper2 := wrapper.With("x", "y").(zeroLogWrapper) + if wrapper2.filterWriter != filterWriter { + t.Fatalf("expected filterWriter to be copied, but it was not") + } + if wrapper2.regularLevel != regularLevel { + t.Fatalf("expected regularLevel to be copied, but it was not") + } + if wrapper2.verboseLevel != verboseLevel { + t.Fatalf("expected verboseLevel to be copied, but it was not") + } + + wrapper3 := wrapper.WithContext("a", "b").(zeroLogWrapper) + if wrapper3.filterWriter != filterWriter { + t.Fatalf("expected filterWriter to be copied, but it was not") + } + if wrapper3.regularLevel != regularLevel { + t.Fatalf("expected regularLevel to be copied, but it was not") + } + if wrapper3.verboseLevel != verboseLevel { + t.Fatalf("expected verboseLevel to be copied, but it was not") + } +} diff --git a/log/writer.go b/log/writer.go index d6f0dc2381..7e225e2677 100644 --- a/log/writer.go +++ b/log/writer.go @@ -11,16 +11,17 @@ import ( // If the filter is nil, the writer will pass all events through. // The filter function is called with the module and level of the event. func NewFilterWriter(parent io.Writer, filter FilterFunc) io.Writer { - return &filterWriter{parent, filter} + return &filterWriter{parent: parent, filter: filter} } type filterWriter struct { - parent io.Writer - filter FilterFunc + parent io.Writer + filter FilterFunc + disableFilter bool } func (fw *filterWriter) Write(p []byte) (n int, err error) { - if fw.filter == nil { + if fw.filter == nil || fw.disableFilter { return fw.parent.Write(p) } diff --git a/server/cmd/execute.go b/server/cmd/execute.go index cf8e7c009f..fb69303252 100644 --- a/server/cmd/execute.go +++ b/server/cmd/execute.go @@ -29,6 +29,7 @@ func Execute(rootCmd *cobra.Command, envPrefix, defaultHome string) error { // NOTE: The default logger is only checking for the "json" value, any other value will default to plain text. rootCmd.PersistentFlags().String(flags.FlagLogFormat, "plain", "The logging format (json|plain)") rootCmd.PersistentFlags().Bool(flags.FlagLogNoColor, false, "Disable colored logs") + rootCmd.PersistentFlags().String(flags.FlagVerboseLogLevel, zerolog.DebugLevel.String(), "The logging level (trace|debug|info|warn|error|fatal|panic|disabled|none) to use when performing operations which require extra verbosity (such as upgrades). When enabled, verbose mode disables any custom log filters. Set this to none to make verbose mode equivalent to normal logging.") executor := cmtcli.PrepareBaseCmd(rootCmd, envPrefix, defaultHome) return executor.ExecuteContext(ctx) diff --git a/server/util.go b/server/util.go index dcdc321203..1622af08a7 100644 --- a/server/util.go +++ b/server/util.go @@ -177,6 +177,15 @@ func CreateSDKLogger(ctx *Context, out io.Writer) (log.Logger, error) { // We use CometBFT flag (cmtcli.TraceFlag) for trace logging. log.TraceOption(ctx.Viper.GetBool(FlagTrace))) + verboseLogLevelStr := ctx.Viper.GetString(flags.FlagVerboseLogLevel) + if verboseLogLevelStr != "" { + verboseLogLvl, err := parseVerboseLogLevel(verboseLogLevelStr) + if err != nil { + return nil, fmt.Errorf("invalid verbose log level: %s: %w", verboseLogLevelStr, err) + } + opts = append(opts, log.VerboseLevelOption(verboseLogLvl)) + } + // check and set filter level or keys for the logger if any logLvlStr := ctx.Viper.GetString(flags.FlagLogLevel) if logLvlStr == "" { @@ -200,6 +209,14 @@ func CreateSDKLogger(ctx *Context, out io.Writer) (log.Logger, error) { return log.NewLogger(out, opts...), nil } +// parseVerboseLogLevel parses the string "none" as zerolog.NoLevel and all other level strings using zerolog.ParseLevel. +func parseVerboseLogLevel(verboseLogLevelStr string) (zerolog.Level, error) { + if verboseLogLevelStr == "none" { + return zerolog.NoLevel, nil + } + return zerolog.ParseLevel(verboseLogLevelStr) +} + // GetServerContextFromCmd returns a Context from a command or an empty Context // if it has not been set. func GetServerContextFromCmd(cmd *cobra.Command) *Context { diff --git a/server/verbose_level_test.go b/server/verbose_level_test.go new file mode 100644 index 0000000000..5476900f3e --- /dev/null +++ b/server/verbose_level_test.go @@ -0,0 +1,32 @@ +package server + +import ( + "testing" + + "github.com/rs/zerolog" + "github.com/stretchr/testify/require" +) + +func TestParseVerboseLogLevel(t *testing.T) { + tt := []struct { + input string + expected zerolog.Level + }{ + // mainly testing that none maps to NoLevel, but checking other cases too for sanity + {"none", zerolog.NoLevel}, + {"debug", zerolog.DebugLevel}, + {"info", zerolog.InfoLevel}, + {"warn", zerolog.WarnLevel}, + {"error", zerolog.ErrorLevel}, + {"fatal", zerolog.FatalLevel}, + {"panic", zerolog.PanicLevel}, + {"trace", zerolog.TraceLevel}, + {"disabled", zerolog.Disabled}, + } + + for _, tc := range tt { + lvl, err := parseVerboseLogLevel(tc.input) + require.NoError(t, err) + require.Equal(t, tc.expected, lvl) + } +} diff --git a/simapp/go.mod b/simapp/go.mod index 1f8514907d..8b1e95ed34 100644 --- a/simapp/go.mod +++ b/simapp/go.mod @@ -218,9 +218,8 @@ require ( // Here are the short-lived replace from the SimApp // Replace here are pending PRs, or version to be tagged -// replace ( // -// ) +replace cosmossdk.io/log => ../log // Replace all unreleased direct deps upgraded to comet v1 replace ( diff --git a/simapp/go.sum b/simapp/go.sum index 9ff41ea314..04f8913822 100644 --- a/simapp/go.sum +++ b/simapp/go.sum @@ -620,8 +620,6 @@ cosmossdk.io/depinject v1.2.0 h1:6NW/FSK1IkWTrX7XxUpBmX1QMBozpEI9SsWkKTBc5zw= cosmossdk.io/depinject v1.2.0/go.mod h1:pvitjtUxZZZTQESKNS9KhGjWVslJZxtO9VooRJYyPjk= cosmossdk.io/errors v1.0.2 h1:wcYiJz08HThbWxd/L4jObeLaLySopyyuUFB5w4AGpCo= cosmossdk.io/errors v1.0.2/go.mod h1:0rjgiHkftRYPj//3DrD6y8hcm40HcPv/dR4R/4efr0k= -cosmossdk.io/log v1.5.1 h1:wLwiYXmfrort/O+j6EkjF+HvbdrRQd+4cYCPKFSm+zM= -cosmossdk.io/log v1.5.1/go.mod h1:5cXXBvfBkR2/BcXmosdCSLXllvgSjphrrDVdfVRmBGM= cosmossdk.io/math v1.5.3 h1:WH6tu6Z3AUCeHbeOSHg2mt9rnoiUWVWaQ2t6Gkll96U= cosmossdk.io/math v1.5.3/go.mod h1:uqcZv7vexnhMFJF+6zh9EWdm/+Ylyln34IvPnBauPCQ= cosmossdk.io/schema v1.1.0 h1:mmpuz3dzouCoyjjcMcA/xHBEmMChN+EHh8EHxHRHhzE= diff --git a/simapp/upgrades.go b/simapp/upgrades.go index 6dbcaf4f4c..d8e1011bc7 100644 --- a/simapp/upgrades.go +++ b/simapp/upgrades.go @@ -5,6 +5,7 @@ import ( storetypes "cosmossdk.io/store/types" + sdk "github.com/cosmos/cosmos-sdk/types" "github.com/cosmos/cosmos-sdk/types/module" epochstypes "github.com/cosmos/cosmos-sdk/x/epochs/types" protocolpooltypes "github.com/cosmos/cosmos-sdk/x/protocolpool/types" @@ -23,6 +24,7 @@ func (app SimApp) RegisterUpgradeHandlers() { app.UpgradeKeeper.SetUpgradeHandler( UpgradeName, func(ctx context.Context, _ upgradetypes.Plan, fromVM module.VersionMap) (module.VersionMap, error) { + sdk.UnwrapSDKContext(ctx).Logger().Debug("this is a debug level message to test that verbose logging mode has properly been enabled during a chain upgrade") return app.ModuleManager.RunMigrations(ctx, app.Configurator(), fromVM) }, ) diff --git a/systemtests/go.mod b/systemtests/go.mod index 08cc92dd7e..041861a4d9 100644 --- a/systemtests/go.mod +++ b/systemtests/go.mod @@ -170,6 +170,7 @@ replace github.com/cosmos/cosmos-sdk => ../. replace ( cosmossdk.io/api => ../api cosmossdk.io/core => ../core + cosmossdk.io/log => ../log cosmossdk.io/store => ../store cosmossdk.io/x/tx => ../x/tx ) diff --git a/systemtests/go.sum b/systemtests/go.sum index ba04e40b64..1df597c78e 100644 --- a/systemtests/go.sum +++ b/systemtests/go.sum @@ -6,8 +6,6 @@ cosmossdk.io/depinject v1.2.0 h1:6NW/FSK1IkWTrX7XxUpBmX1QMBozpEI9SsWkKTBc5zw= cosmossdk.io/depinject v1.2.0/go.mod h1:pvitjtUxZZZTQESKNS9KhGjWVslJZxtO9VooRJYyPjk= cosmossdk.io/errors v1.0.2 h1:wcYiJz08HThbWxd/L4jObeLaLySopyyuUFB5w4AGpCo= cosmossdk.io/errors v1.0.2/go.mod h1:0rjgiHkftRYPj//3DrD6y8hcm40HcPv/dR4R/4efr0k= -cosmossdk.io/log v1.5.1 h1:wLwiYXmfrort/O+j6EkjF+HvbdrRQd+4cYCPKFSm+zM= -cosmossdk.io/log v1.5.1/go.mod h1:5cXXBvfBkR2/BcXmosdCSLXllvgSjphrrDVdfVRmBGM= cosmossdk.io/math v1.5.3 h1:WH6tu6Z3AUCeHbeOSHg2mt9rnoiUWVWaQ2t6Gkll96U= cosmossdk.io/math v1.5.3/go.mod h1:uqcZv7vexnhMFJF+6zh9EWdm/+Ylyln34IvPnBauPCQ= cosmossdk.io/schema v1.1.0 h1:mmpuz3dzouCoyjjcMcA/xHBEmMChN+EHh8EHxHRHhzE= diff --git a/systemtests/system.go b/systemtests/system.go index aef713728e..c5e45e607b 100644 --- a/systemtests/system.go +++ b/systemtests/system.go @@ -207,7 +207,7 @@ func (s *SystemUnderTest) IsDirty() bool { // watchLogs stores stdout/stderr in a file and in a ring buffer to output the last n lines on test error func (s *SystemUnderTest) watchLogs(node int, cmd *exec.Cmd) { - logfile, err := os.Create(filepath.Join(WorkDir, s.outputDir, fmt.Sprintf("node%d.out", node))) + logfile, err := os.Create(s.logfileName(node)) if err != nil { panic(fmt.Sprintf("open logfile error %#+v", err)) } @@ -230,6 +230,10 @@ func (s *SystemUnderTest) watchLogs(node int, cmd *exec.Cmd) { }) } +func (s *SystemUnderTest) logfileName(node int) string { + return filepath.Join(WorkDir, s.outputDir, fmt.Sprintf("node%d.out", node)) +} + func appendToBuf(r io.Reader, b *ring.Ring, stop <-chan struct{}) { scanner := bufio.NewScanner(r) for scanner.Scan() { @@ -791,6 +795,24 @@ func (s *SystemUnderTest) BlockTime() time.Duration { return s.blockTime } +// FindLogMessage searches the logs of each node and returns a count of the number of +// nodes that had a match for the provided regular expression. +func (s *SystemUnderTest) FindLogMessage(regex *regexp.Regexp) int { + found := 0 + for i := 0; i < s.nodesCount; i++ { + logfile := s.logfileName(i) + content, err := os.ReadFile(logfile) + if err != nil { + continue // skip if file cannot be read + } + if regex.Match(content) { + found++ + } + + } + return found +} + type Node struct { ID string IP string diff --git a/tests/go.mod b/tests/go.mod index 47dfeb1c45..2f7a1ad324 100644 --- a/tests/go.mod +++ b/tests/go.mod @@ -221,6 +221,7 @@ require ( replace ( cosmossdk.io/api => ../api cosmossdk.io/core => ../core + cosmossdk.io/log => ../log cosmossdk.io/store => ../store cosmossdk.io/x/tx => ../x/tx ) diff --git a/tests/go.sum b/tests/go.sum index 7194b637ec..9992bd9127 100644 --- a/tests/go.sum +++ b/tests/go.sum @@ -622,8 +622,6 @@ cosmossdk.io/depinject v1.2.0 h1:6NW/FSK1IkWTrX7XxUpBmX1QMBozpEI9SsWkKTBc5zw= cosmossdk.io/depinject v1.2.0/go.mod h1:pvitjtUxZZZTQESKNS9KhGjWVslJZxtO9VooRJYyPjk= cosmossdk.io/errors v1.0.2 h1:wcYiJz08HThbWxd/L4jObeLaLySopyyuUFB5w4AGpCo= cosmossdk.io/errors v1.0.2/go.mod h1:0rjgiHkftRYPj//3DrD6y8hcm40HcPv/dR4R/4efr0k= -cosmossdk.io/log v1.5.1 h1:wLwiYXmfrort/O+j6EkjF+HvbdrRQd+4cYCPKFSm+zM= -cosmossdk.io/log v1.5.1/go.mod h1:5cXXBvfBkR2/BcXmosdCSLXllvgSjphrrDVdfVRmBGM= cosmossdk.io/math v1.5.3 h1:WH6tu6Z3AUCeHbeOSHg2mt9rnoiUWVWaQ2t6Gkll96U= cosmossdk.io/math v1.5.3/go.mod h1:uqcZv7vexnhMFJF+6zh9EWdm/+Ylyln34IvPnBauPCQ= cosmossdk.io/schema v1.1.0 h1:mmpuz3dzouCoyjjcMcA/xHBEmMChN+EHh8EHxHRHhzE= diff --git a/tests/systemtests/go.mod b/tests/systemtests/go.mod index d00d01da57..ea871f0c88 100644 --- a/tests/systemtests/go.mod +++ b/tests/systemtests/go.mod @@ -3,6 +3,7 @@ module cosmossdk.io/tests/systemtests go 1.23.5 replace ( + cosmossdk.io/log => ../../log // always use latest versions in tests cosmossdk.io/systemtests => ../../systemtests github.com/cosmos/cosmos-sdk => ../.. diff --git a/tests/systemtests/go.sum b/tests/systemtests/go.sum index d569199e8b..7f416fd89d 100644 --- a/tests/systemtests/go.sum +++ b/tests/systemtests/go.sum @@ -6,8 +6,6 @@ cosmossdk.io/depinject v1.2.0 h1:6NW/FSK1IkWTrX7XxUpBmX1QMBozpEI9SsWkKTBc5zw= cosmossdk.io/depinject v1.2.0/go.mod h1:pvitjtUxZZZTQESKNS9KhGjWVslJZxtO9VooRJYyPjk= cosmossdk.io/errors v1.0.2 h1:wcYiJz08HThbWxd/L4jObeLaLySopyyuUFB5w4AGpCo= cosmossdk.io/errors v1.0.2/go.mod h1:0rjgiHkftRYPj//3DrD6y8hcm40HcPv/dR4R/4efr0k= -cosmossdk.io/log v1.5.1 h1:wLwiYXmfrort/O+j6EkjF+HvbdrRQd+4cYCPKFSm+zM= -cosmossdk.io/log v1.5.1/go.mod h1:5cXXBvfBkR2/BcXmosdCSLXllvgSjphrrDVdfVRmBGM= cosmossdk.io/math v1.5.3 h1:WH6tu6Z3AUCeHbeOSHg2mt9rnoiUWVWaQ2t6Gkll96U= cosmossdk.io/math v1.5.3/go.mod h1:uqcZv7vexnhMFJF+6zh9EWdm/+Ylyln34IvPnBauPCQ= cosmossdk.io/schema v1.1.0 h1:mmpuz3dzouCoyjjcMcA/xHBEmMChN+EHh8EHxHRHhzE= diff --git a/tests/systemtests/upgrade_test.go b/tests/systemtests/upgrade_test.go index bb2a98e4fd..59d47e271e 100644 --- a/tests/systemtests/upgrade_test.go +++ b/tests/systemtests/upgrade_test.go @@ -4,6 +4,7 @@ package systemtests import ( "fmt" + "regexp" "testing" "time" @@ -125,6 +126,10 @@ func TestChainUpgrade(t *testing.T) { require.Equal(t, upgradeHeight+1, systest.Sut.CurrentHeight()) + regex, err := regexp.Compile("DBG this is a debug level message to test that verbose logging mode has properly been enabled during a chain upgrade") + require.NoError(t, err) + require.Equal(t, systest.Sut.NodesCount(), systest.Sut.FindLogMessage(regex)) + // smoke test that new version runs cli = systest.NewCLIWrapper(t, systest.Sut, systest.Verbose) got := cli.Run("tx", "protocolpool", "fund-community-pool", "100stake", "--from=node0") diff --git a/types/module/module.go b/types/module/module.go index aba997de1a..b2ebca09e7 100644 --- a/types/module/module.go +++ b/types/module/module.go @@ -722,6 +722,7 @@ func (m Manager) RunMigrations(ctx context.Context, cfg Configurator, fromVM Ver // 2. An existing chain is upgrading from version < 0.43 to v0.43+ for the first time. // In this case, all modules have yet to be added to x/upgrade's VersionMap store. if exists { + sdkCtx.Logger().Info(fmt.Sprintf("running migrations for module: %s", moduleName)) err := c.runModuleMigrations(sdkCtx, moduleName, fromVersion, toVersion) if err != nil { return nil, err diff --git a/x/upgrade/CHANGELOG.md b/x/upgrade/CHANGELOG.md index 7689c1e9e7..094f8cd2b5 100644 --- a/x/upgrade/CHANGELOG.md +++ b/x/upgrade/CHANGELOG.md @@ -28,6 +28,8 @@ Ref: https://keepachangelog.com/en/1.0.0/ ### Improvements * [#24543](https://github.com/cosmos/cosmos-sdk/issues/24543) Use `telemetry.MetricKeyPreBlocker` metric key instead of `telemetry.MetricKeyBeginBlocker` in `PreBlocker`. +* [#24720](https://github.com/cosmos/cosmos-sdk/pull/24720) switch to verbose mode logging when calling upgrading handlers. + ## [v0.2.0](https://github.com/cosmos/cosmos-sdk/releases/tag/x/upgrade/v0.2.0) - 2025-04-24 diff --git a/x/upgrade/keeper/keeper.go b/x/upgrade/keeper/keeper.go index a7a65fcf59..1b996c1a18 100644 --- a/x/upgrade/keeper/keeper.go +++ b/x/upgrade/keeper/keeper.go @@ -463,11 +463,25 @@ func (k Keeper) ApplyUpgrade(ctx context.Context, plan types.Plan) error { return err } + // Enable verbose mode logging, if possible + sdkCtx := sdk.UnwrapSDKContext(ctx) + logger := sdkCtx.Logger() + if verboseLogger, ok := logger.(log.VerboseModeLogger); ok { + verboseLogger.SetVerboseMode(true) + } + + logger.Info("Starting upgrade", "name", plan.Name, "height", plan.Height) + updatedVM, err := handler(ctx, plan, vm) if err != nil { return err } + // Disable verbose mode logging + if verboseLogger, ok := logger.(log.VerboseModeLogger); ok { + verboseLogger.SetVerboseMode(false) + } + err = k.SetModuleVersionMap(ctx, updatedVM) if err != nil { return err