diff --git a/cmd/kwil-admin/nodecfg/toml.go b/cmd/kwil-admin/nodecfg/toml.go index d692e29d1..80544f33b 100644 --- a/cmd/kwil-admin/nodecfg/toml.go +++ b/cmd/kwil-admin/nodecfg/toml.go @@ -77,6 +77,15 @@ const defaultConfigTemplate = ` # Output level for logging, default is "info". Other options are "debug", "error", "warn", "trace" level = "{{ .Logging.Level }}" +# RPC systems' logging level. Must be higher than log.level. +rpc_level = "{{ .Logging.RPCLevel }}" + +# Consensus engine's logging level. Must be higher than log.level. +consensus_level = "{{ .Logging.ConsensusLevel }}" + +# DB driver's logging level. Must be higher than log.level. +db_level = "{{ .Logging.DBLevel }}" + # Output paths for the logger, can be stdout or a file path output_paths = {{arrayFormatter .Logging.OutputPaths }} diff --git a/cmd/kwild/config/config.go b/cmd/kwild/config/config.go index 24185d63b..e79667355 100644 --- a/cmd/kwild/config/config.go +++ b/cmd/kwild/config/config.go @@ -41,10 +41,13 @@ type KwildConfig struct { } type Logging struct { - Level string `mapstructure:"level"` - Format string `mapstructure:"format"` - TimeEncoding string `mapstructure:"time_format"` - OutputPaths []string `mapstructure:"output_paths"` + Level string `mapstructure:"level"` + RPCLevel string `mapstructure:"rpc_level"` + ConsensusLevel string `mapstructure:"consensus_level"` + DBLevel string `mapstructure:"db_level"` + Format string `mapstructure:"format"` + TimeEncoding string `mapstructure:"time_format"` + OutputPaths []string `mapstructure:"output_paths"` } type AppConfig struct { @@ -572,7 +575,7 @@ func DefaultConfig() *KwildConfig { Level: "info", Format: log.FormatJSON, TimeEncoding: log.TimeEncodingEpochFloat, - OutputPaths: []string{"stdout"}, + OutputPaths: []string{"stdout", "kwild.log"}, }, ChainCfg: &ChainConfig{ diff --git a/cmd/kwild/config/config_test.go b/cmd/kwild/config/config_test.go index b0febecf1..edb69ca02 100644 --- a/cmd/kwild/config/config_test.go +++ b/cmd/kwild/config/config_test.go @@ -16,6 +16,10 @@ func Test_Config_Toml(t *testing.T) { err = cfg.Merge(tomlCfg) assert.NoError(t, err) + assert.Equal(t, "debug", cfg.Logging.Level) + assert.Equal(t, "info", cfg.Logging.RPCLevel) + assert.Equal(t, "warn", cfg.Logging.ConsensusLevel) + assert.Equal(t, "192.168.1.1:8484", cfg.AppCfg.JSONRPCListenAddress) assert.Equal(t, "localhost:8080", cfg.AppCfg.HTTPListenAddress) diff --git a/cmd/kwild/config/default_config.toml b/cmd/kwild/config/default_config.toml index f5b4cbdb7..ef311d4d8 100644 --- a/cmd/kwild/config/default_config.toml +++ b/cmd/kwild/config/default_config.toml @@ -120,11 +120,21 @@ snapshot_dir = "snapshots" ### Logging Config Options ### ####################################################################### [log] + # Output level for logging, default is "info". Other options are "debug", "error", "warn", "trace" -level = "info" +level = "info" + +# RPC systems' logging level. Must be higher than log.level. +rpc_level = "info" + +# Consensus engine's logging level. Must be higher than log.level. +consensus_level = "warn" + +# DB driver's logging level. Must be higher than log.level. +db_level = "info" # Output paths for the logger, can be stdout or a file path -output_paths = ["stdout"] +output_paths = ["stdout","kwild.log"] # Output format: 'plain' or 'json' format = "plain" diff --git a/cmd/kwild/config/flags.go b/cmd/kwild/config/flags.go index dc6169406..55223f540 100644 --- a/cmd/kwild/config/flags.go +++ b/cmd/kwild/config/flags.go @@ -8,6 +8,9 @@ func AddConfigFlags(flagSet *pflag.FlagSet, cfg *KwildConfig) { // logging flagSet.StringVarP(&cfg.Logging.Level, "log.level", "l", cfg.Logging.Level, "kwild log level") + flagSet.StringVar(&cfg.Logging.RPCLevel, "log.rpc_level", cfg.Logging.RPCLevel, "user rpc server log level") + flagSet.StringVar(&cfg.Logging.ConsensusLevel, "log.consensus_level", cfg.Logging.ConsensusLevel, "consensus (cometbft) log level") + flagSet.StringVar(&cfg.Logging.DBLevel, "log.db_level", cfg.Logging.DBLevel, "database backend (postgres) log level") flagSet.StringVar(&cfg.Logging.Format, "log.format", cfg.Logging.Format, "kwild log format") flagSet.StringVar(&cfg.Logging.TimeEncoding, "log.time-format", cfg.Logging.TimeEncoding, "kwild time log format") flagSet.StringSliceVar(&cfg.Logging.OutputPaths, "log.output-paths", cfg.Logging.OutputPaths, "kwild log output paths") diff --git a/cmd/kwild/config/test_data/config.toml b/cmd/kwild/config/test_data/config.toml index 53e6345a0..089b4dc5a 100644 --- a/cmd/kwild/config/test_data/config.toml +++ b/cmd/kwild/config/test_data/config.toml @@ -117,7 +117,16 @@ snapshot_dir = "data/snapshots" ####################################################################### [log] # Output level for logging, default is "info". Other options are "debug", "error", "warn", "trace" -level = "info" +level = "debug" + +# RPC systems' logging level. Must be higher than log.level. +rpc_level = "info" + +# Consensus engine's logging level. Must be higher than log.level. +consensus_level = "warn" + +# DB driver's logging level. Must be higher than log.level. +db_level = "info" # Output paths for the logger, can be stdout or a file path output_paths = ["stdout"] diff --git a/cmd/kwild/server/build.go b/cmd/kwild/server/build.go index 8d0e95a42..9b1c34bf9 100644 --- a/cmd/kwild/server/build.go +++ b/cmd/kwild/server/build.go @@ -210,10 +210,13 @@ func buildServer(d *coreDependencies, closers *closeFuncs) *Server { listeners := buildListenerManager(d, ev, cometBftNode, txApp) // user service and server + rpcSvcLogger := increaseLogLevel("user-json-svc", &d.log, d.cfg.Logging.RPCLevel) + rpcServerLogger := increaseLogLevel("user-jsonrpc-server", &d.log, d.cfg.Logging.RPCLevel) + jsonRPCTxSvc := usersvc.NewService(db, e, wrappedCmtClient, txApp, - *d.log.Named("user-json-svc"), usersvc.WithReadTxTimeout(time.Duration(d.cfg.AppCfg.ReadTxTimeout))) + *rpcSvcLogger, usersvc.WithReadTxTimeout(time.Duration(d.cfg.AppCfg.ReadTxTimeout))) jsonRPCServer, err := rpcserver.NewServer(d.cfg.AppCfg.JSONRPCListenAddress, - *d.log.Named("user-jsonrpc-server"), rpcserver.WithTimeout(time.Duration(d.cfg.AppCfg.RPCTimeout)), + *rpcServerLogger, rpcserver.WithTimeout(time.Duration(d.cfg.AppCfg.RPCTimeout)), rpcserver.WithCORS()) if err != nil { failBuild(err, "unable to create json-rpc server") @@ -848,7 +851,7 @@ func buildCometNode(d *coreDependencies, closer *closeFuncs, abciApp abciTypes.A // I'm simply using this because we know it fsyncs the data to disk db, err := badger.NewBadgerDB(d.ctx, filepath.Join(d.cfg.RootDir, signingDirName), &badger.Options{ GuaranteeFSync: true, - Logger: *d.log.Named("private-validator-signature-store"), + Logger: *increaseLogLevel("private-validator-signature-store", &d.log, log.WarnLevel.String()), // badger is too noisy for an internal component }) if err != nil { failBuild(err, "failed to open comet node KV store") @@ -874,8 +877,9 @@ func buildCometNode(d *coreDependencies, closer *closeFuncs, abciApp abciTypes.A } } + nodeLogger := increaseLogLevel("cometbft", &d.log, d.cfg.Logging.ConsensusLevel) node, err := cometbft.NewCometBftNode(d.ctx, abciApp, nodeCfg, genDoc, d.privKey, - readWriter, &d.log) + readWriter, nodeLogger) if err != nil { failBuild(err, "failed to build comet node") } diff --git a/cmd/kwild/server/server.go b/cmd/kwild/server/server.go index 53c2d2b3a..a040fab32 100644 --- a/cmd/kwild/server/server.go +++ b/cmd/kwild/server/server.go @@ -95,7 +95,8 @@ func New(ctx context.Context, cfg *config.KwildConfig, genesisCfg *config.Genesi return nil, err } - pg.UseLogger(*logger.Named("pg")) + dbLogger := increaseLogLevel("pg", &logger, cfg.Logging.DBLevel) + pg.UseLogger(*dbLogger) host, port, user, pass := cfg.AppCfg.DBHost, cfg.AppCfg.DBPort, cfg.AppCfg.DBUser, cfg.AppCfg.DBPass diff --git a/cmd/kwild/server/utils.go b/cmd/kwild/server/utils.go index add078096..04ff05988 100644 --- a/cmd/kwild/server/utils.go +++ b/cmd/kwild/server/utils.go @@ -6,6 +6,7 @@ import ( "fmt" "strings" + "github.com/kwilteam/kwil-db/core/log" types "github.com/kwilteam/kwil-db/core/types/admin" "github.com/kwilteam/kwil-db/extensions/precompiles" "github.com/kwilteam/kwil-db/internal/abci" @@ -20,6 +21,27 @@ import ( cmttypes "github.com/cometbft/cometbft/types" ) +func increaseLogLevel(name string, logger *log.Logger, level string) *log.Logger { + logger = logger.Named(name) + if level == "" { + return logger + } + + lvl, err := log.ParseLevel(level) + if err != nil { + logger.Warnf("invalid log level %q for logger %q: %v", level, name, err) + return logger + } + + if parentLevel := logger.Level(); lvl < parentLevel { + logger.Warnf("cannot increase logger level for %q to %v from %v", name, level, parentLevel) + } else { // this would be a no-op + logger = logger.IncreasedLevel(lvl) + } + + return logger +} + // getExtensions returns both the local and remote extensions. Remote extensions are identified by // connecting to the specified extension URLs. func getExtensions(ctx context.Context, urls []string) (map[string]precompiles.Initializer, error) { diff --git a/core/log/logger.go b/core/log/logger.go index c149bafa9..12e238e1a 100644 --- a/core/log/logger.go +++ b/core/log/logger.go @@ -95,6 +95,12 @@ func (l *Logger) WithOptions(opts ...zap.Option) *Logger { return &Logger{l.L.WithOptions(opts...)} } +// IncreasedLevel creates a logger clone with a higher log level threshold, +// which is ignored if it is lower than the parent logger's level. +func (l *Logger) IncreasedLevel(lvl Level) *Logger { + return l.WithOptions(zap.IncreaseLevel(zap.NewAtomicLevelAt(lvl))) +} + func (l *Logger) Sync() error { return l.L.Sync() } @@ -201,6 +207,16 @@ const ( FatalLevel = zap.FatalLevel ) +// ParseLevel parses a log level string, which is useful for reading level +// settings from a config file or other text source. +func ParseLevel(lvl string) (Level, error) { + l, err := zapcore.ParseLevel(lvl) + if err != nil { + return zapcore.InvalidLevel, err + } + return l, nil +} + func NewStdOut(level Level) Logger { return New(Config{ Level: level.String(), diff --git a/internal/abci/cometbft/node.go b/internal/abci/cometbft/node.go index b3b812ad1..26cd5c1af 100644 --- a/internal/abci/cometbft/node.go +++ b/internal/abci/cometbft/node.go @@ -31,6 +31,7 @@ var demotedInfoMsgs = map[string]string{ "received proposal": "", "received complete proposal block": "", "executed block": "", + "Starting localClient service": "proxy", "Timed out": "consensus", // only the one from consensus.(*timeoutTicker).timeoutRoutine, which seems to be normal } @@ -164,7 +165,9 @@ WARNING: These files are overwritten on kwild startup.` } // NewCometBftNode creates a new CometBFT node. -func NewCometBftNode(ctx context.Context, app abciTypes.Application, conf *cometConfig.Config, genDoc *types.GenesisDoc, privateKey cometEd25519.PrivKey, atomicStore privval.AtomicReadWriter, log *log.Logger) (*CometBftNode, error) { +func NewCometBftNode(ctx context.Context, app abciTypes.Application, conf *cometConfig.Config, + genDoc *types.GenesisDoc, privateKey cometEd25519.PrivKey, atomicStore privval.AtomicReadWriter, + logger *log.Logger) (*CometBftNode, error) { if err := writeCometBFTConfigs(conf, genDoc); err != nil { return nil, fmt.Errorf("failed to write the effective cometbft config files: %w", err) } @@ -174,8 +177,6 @@ func NewCometBftNode(ctx context.Context, app abciTypes.Application, conf *comet return nil, fmt.Errorf("invalid node config: %w", err) } - logger := NewLogWrapper(log.Named("cometbft")) - privateValidator, err := privval.NewValidatorSigner(privateKey, atomicStore) if err != nil { return nil, fmt.Errorf("failed to create private validator: %v", err) @@ -192,7 +193,7 @@ func NewCometBftNode(ctx context.Context, app abciTypes.Application, conf *comet genesisDocProvider(genDoc), cometConfig.DefaultDBProvider, cometNodes.DefaultMetricsProvider(conf.Instrumentation), - logger, + NewLogWrapper(logger), ) if err != nil { if errors.Is(ctx.Err(), context.Canceled) {