Merge #1362

1362: [Admin] add log level customization command r=smnzhu a=smnzhu

Add log level admin command, to allow dynamically changing the log level without restarting a node.

Tested and it works on localnet.

To change the log level to debug, for example:

```
curl -d '{"commandName": "set-log-level", "data": {"level": "debug"}}' -H 'Content-Type: application/json' localhost:5873/admin/run_command
```

where `localhost:5873` is the address of the admin server.

Co-authored-by: Simon Zhu <simon.zsiyan@gmail.com>

admin/command_runner.go

@@ -22,10 +22,15 @@ import (
 
 const CommandRunnerShutdownTimeout = 5 * time.Second
 
-type CommandHandler func(ctx context.Context, data map[string]interface{}) error
-type CommandValidator func(data map[string]interface{}) error
+type CommandHandler func(ctx context.Context, request *CommandRequest) error
+type CommandValidator func(request *CommandRequest) error
 type CommandRunnerOption func(*CommandRunner)
 
+type CommandRequest struct {
+	Data          map[string]interface{}
+	ValidatorData interface{}
+}
+
 func WithTLS(config *tls.Config) CommandRunnerOption {
 	return func(r *CommandRunner) {
 		r.tlsConfig = config
@@ -242,14 +247,15 @@ func (r *CommandRunner) runAdminServer(ctx context.Context) error {
 func (r *CommandRunner) runCommand(ctx context.Context, command string, data map[string]interface{}) error {
 	r.logger.Info().Str("command", command).Msg("received new command")
 
+	req := &CommandRequest{Data: data}
 	if validator := r.getValidator(command); validator != nil {
-		if validationErr := validator(data); validationErr != nil {
+		if validationErr := validator(req); validationErr != nil {
 			return status.Error(codes.InvalidArgument, validationErr.Error())
 		}
 	}
 
 	if handler := r.getHandler(command); handler != nil {
-		if handleErr := handler(ctx, data); handleErr != nil {
+		if handleErr := handler(ctx, req); handleErr != nil {
 			if errors.Is(handleErr, context.Canceled) {
 				return status.Error(codes.Canceled, "client canceled")
 			} else if errors.Is(handleErr, context.DeadlineExceeded) {

admin/command_runner_test.go

@@ -86,15 +86,15 @@ func (suite *CommandRunnerSuite) SetupCommandRunner(opts ...CommandRunnerOption)
 func (suite *CommandRunnerSuite) TestHandler() {
 	called := false
 
-	suite.bootstrapper.RegisterHandler("foo", func(ctx context.Context, data map[string]interface{}) error {
+	suite.bootstrapper.RegisterHandler("foo", func(ctx context.Context, req *CommandRequest) error {
 		select {
 		case <-ctx.Done():
 			return ctx.Err()
 		default:
 		}
 
-		suite.EqualValues(data["string"], "foo")
-		suite.EqualValues(data["number"], 123)
+		suite.EqualValues(req.Data["string"], "foo")
+		suite.EqualValues(req.Data["number"], 123)
 		called = true
 
 		return nil
@@ -142,7 +142,7 @@ func (suite *CommandRunnerSuite) TestUnimplementedHandler() {
 func (suite *CommandRunnerSuite) TestValidator() {
 	calls := 0
 
-	suite.bootstrapper.RegisterHandler("foo", func(ctx context.Context, data map[string]interface{}) error {
+	suite.bootstrapper.RegisterHandler("foo", func(ctx context.Context, req *CommandRequest) error {
 		select {
 		case <-ctx.Done():
 			return ctx.Err()
@@ -155,8 +155,8 @@ func (suite *CommandRunnerSuite) TestValidator() {
 	})
 
 	validatorErr := errors.New("unexpected value")
-	suite.bootstrapper.RegisterValidator("foo", func(data map[string]interface{}) error {
-		if data["key"] != "value" {
+	suite.bootstrapper.RegisterValidator("foo", func(req *CommandRequest) error {
+		if req.Data["key"] != "value" {
 			return validatorErr
 		}
 		return nil
@@ -192,7 +192,7 @@ func (suite *CommandRunnerSuite) TestValidator() {
 
 func (suite *CommandRunnerSuite) TestHandlerError() {
 	handlerErr := errors.New("handler error")
-	suite.bootstrapper.RegisterHandler("foo", func(ctx context.Context, data map[string]interface{}) error {
+	suite.bootstrapper.RegisterHandler("foo", func(ctx context.Context, req *CommandRequest) error {
 		select {
 		case <-ctx.Done():
 			return ctx.Err()
@@ -222,7 +222,7 @@ func (suite *CommandRunnerSuite) TestHandlerError() {
 }
 
 func (suite *CommandRunnerSuite) TestTimeout() {
-	suite.bootstrapper.RegisterHandler("foo", func(ctx context.Context, data map[string]interface{}) error {
+	suite.bootstrapper.RegisterHandler("foo", func(ctx context.Context, req *CommandRequest) error {
 		<-ctx.Done()
 		return ctx.Err()
 	})
@@ -248,14 +248,14 @@ func (suite *CommandRunnerSuite) TestTimeout() {
 func (suite *CommandRunnerSuite) TestHTTPServer() {
 	called := false
 
-	suite.bootstrapper.RegisterHandler("foo", func(ctx context.Context, data map[string]interface{}) error {
+	suite.bootstrapper.RegisterHandler("foo", func(ctx context.Context, req *CommandRequest) error {
 		select {
 		case <-ctx.Done():
 			return ctx.Err()
 		default:
 		}
 
-		suite.EqualValues(data["key"], "value")
+		suite.EqualValues(req.Data["key"], "value")
 		called = true
 
 		return nil
@@ -387,14 +387,14 @@ func generateCerts(t *testing.T) (tls.Certificate, *x509.CertPool, tls.Certifica
 func (suite *CommandRunnerSuite) TestTLS() {
 	called := false
 
-	suite.bootstrapper.RegisterHandler("foo", func(ctx context.Context, data map[string]interface{}) error {
+	suite.bootstrapper.RegisterHandler("foo", func(ctx context.Context, req *CommandRequest) error {
 		select {
 		case <-ctx.Done():
 			return ctx.Err()
 		default:
 		}
 
-		suite.EqualValues(data["key"], "value")
+		suite.EqualValues(req.Data["key"], "value")
 		called = true
 
 		return nil

admin/commands/command.go

@@ -0,0 +1,8 @@
+package commands
+
+import "github.com/onflow/flow-go/admin"
+
+type AdminCommand struct {
+	Handler   admin.CommandHandler
+	Validator admin.CommandValidator
+}

admin/commands/common/set_log_level.go

@@ -0,0 +1,36 @@
+package common
+
+import (
+	"context"
+	"errors"
+	"fmt"
+
+	"github.com/rs/zerolog"
+
+	"github.com/onflow/flow-go/admin"
+	"github.com/onflow/flow-go/admin/commands"
+)
+
+var SetLogLevelCommand commands.AdminCommand = commands.AdminCommand{
+	Handler: func(ctx context.Context, req *admin.CommandRequest) error {
+		level := req.ValidatorData.(zerolog.Level)
+		zerolog.SetGlobalLevel(level)
+		return nil
+	},
+	Validator: func(req *admin.CommandRequest) error {
+		level, ok := req.Data["level"]
+		if !ok {
+			return errors.New("the \"level\" field must be provided")
+		}
+		levelStr, ok := level.(string)
+		if !ok {
+			return errors.New("\"level\" must be a string")
+		}
+		logLevel, err := zerolog.ParseLevel(levelStr)
+		if err != nil {
+			return fmt.Errorf("failed to parse level: %w", err)
+		}
+		req.ValidatorData = logLevel
+		return nil
+	},
+}

cmd/access/node_builder/staked_access_node_builder.go

@@ -90,6 +90,8 @@ func (builder *StakedAccessNodeBuilder) Initialize() error {
 		return err
 	}
 
+	builder.EnqueueAdminServerInit(ctx)
+
 	builder.EnqueueTracer()
 
 	return nil

cmd/node_builder.go

@@ -104,10 +104,10 @@ type NodeBuilder interface {
 // while for a node running as a library, the config fields are expected to be initialized by the caller.
 type BaseConfig struct {
 	nodeIDHex             string
-	adminAddr             string
-	adminCert             string
-	adminKey              string
-	adminClientCAs        string
+	AdminAddr             string
+	AdminCert             string
+	AdminKey              string
+	AdminClientCAs        string
 	BindAddr              string
 	NodeRole              string
 	datadir               string
@@ -176,10 +176,10 @@ func DefaultBaseConfig() *BaseConfig {
 
 	return &BaseConfig{
 		nodeIDHex:             NotSet,
-		adminAddr:             NotSet,
-		adminCert:             NotSet,
-		adminKey:              NotSet,
-		adminClientCAs:        NotSet,
+		AdminAddr:             NotSet,
+		AdminCert:             NotSet,
+		AdminKey:              NotSet,
+		AdminClientCAs:        NotSet,
 		BindAddr:              NotSet,
 		BootstrapDir:          "bootstrap",
 		datadir:               datadir,

cmd/scaffold.go

@@ -22,6 +22,7 @@ import (
 	"github.com/spf13/pflag"
 
 	"github.com/onflow/flow-go/admin"
+	"github.com/onflow/flow-go/admin/commands/common"
 	"github.com/onflow/flow-go/cmd/build"
 	"github.com/onflow/flow-go/consensus/hotstuff/persister"
 	"github.com/onflow/flow-go/fvm"
@@ -139,10 +140,10 @@ func (fnb *FlowNodeBuilder) BaseFlags() {
 	fnb.flags.UintVar(&fnb.BaseConfig.tracerSensitivity, "tracer-sensitivity", defaultConfig.tracerSensitivity,
 		"adjusts the level of sampling when tracing is enabled. 0 means capture everything, higher value results in less samples")
 
-	fnb.flags.StringVar(&fnb.BaseConfig.adminAddr, "admin-addr", defaultConfig.adminAddr, "address to bind on for admin HTTP server")
-	fnb.flags.StringVar(&fnb.BaseConfig.adminCert, "admin-cert", defaultConfig.adminCert, "admin cert file (for TLS)")
-	fnb.flags.StringVar(&fnb.BaseConfig.adminKey, "admin-key", defaultConfig.adminKey, "admin key file (for TLS)")
-	fnb.flags.StringVar(&fnb.BaseConfig.adminClientCAs, "admin-client-certs", defaultConfig.adminClientCAs, "admin client certs (for mutual TLS)")
+	fnb.flags.StringVar(&fnb.BaseConfig.AdminAddr, "admin-addr", defaultConfig.AdminAddr, "address to bind on for admin HTTP server")
+	fnb.flags.StringVar(&fnb.BaseConfig.AdminCert, "admin-cert", defaultConfig.AdminCert, "admin cert file (for TLS)")
+	fnb.flags.StringVar(&fnb.BaseConfig.AdminKey, "admin-key", defaultConfig.AdminKey, "admin key file (for TLS)")
+	fnb.flags.StringVar(&fnb.BaseConfig.AdminClientCAs, "admin-client-certs", defaultConfig.AdminClientCAs, "admin client certs (for mutual TLS)")
 
 	fnb.flags.DurationVar(&fnb.BaseConfig.DNSCacheTTL, "dns-cache-ttl", dns.DefaultTimeToLive, "time-to-live for dns cache")
 	fnb.flags.UintVar(&fnb.BaseConfig.guaranteesCacheSize, "guarantees-cache-size", bstorage.DefaultCacheSize, "collection guarantees cache size")
@@ -277,37 +278,44 @@ func (fnb *FlowNodeBuilder) EnqueueMetricsServerInit() {
 }
 
 func (fnb *FlowNodeBuilder) EnqueueAdminServerInit(ctx context.Context) {
-	fnb.Component("admin server", func(builder NodeBuilder, node *NodeConfig) (module.ReadyDoneAware, error) {
-		var opts []admin.CommandRunnerOption
+	if fnb.AdminAddr != NotSet {
+		if (fnb.AdminCert != NotSet || fnb.AdminKey != NotSet || fnb.AdminClientCAs != NotSet) &&
+			!(fnb.AdminCert != NotSet && fnb.AdminKey != NotSet && fnb.AdminClientCAs != NotSet) {
+			fnb.Logger.Fatal().Msg("admin cert / key and client certs must all be provided to enable mutual TLS")
+		}
+		fnb.RegisterDefaultAdminCommands()
+		fnb.Component("admin server", func(builder NodeBuilder, node *NodeConfig) (module.ReadyDoneAware, error) {
+			var opts []admin.CommandRunnerOption
 
-		if node.adminCert != NotSet {
-			serverCert, err := tls.LoadX509KeyPair(node.adminCert, node.adminKey)
-			if err != nil {
-				return nil, err
+			if node.AdminCert != NotSet {
+				serverCert, err := tls.LoadX509KeyPair(node.AdminCert, node.AdminKey)
+				if err != nil {
+					return nil, err
+				}
+				clientCAs, err := ioutil.ReadFile(node.AdminClientCAs)
+				if err != nil {
+					return nil, err
+				}
+				certPool := x509.NewCertPool()
+				certPool.AppendCertsFromPEM(clientCAs)
+				config := &tls.Config{
+					MinVersion:   tls.VersionTLS13,
+					Certificates: []tls.Certificate{serverCert},
+					ClientAuth:   tls.RequireAndVerifyClientCert,
+					ClientCAs:    certPool,
+				}
+
+				opts = append(opts, admin.WithTLS(config))
 			}
-			clientCAs, err := ioutil.ReadFile(node.adminClientCAs)
-			if err != nil {
+
+			command_runner := fnb.adminCommandBootstrapper.Bootstrap(fnb.Logger, fnb.AdminAddr, opts...)
+			if err := command_runner.Start(ctx); err != nil {
 				return nil, err
 			}
-			certPool := x509.NewCertPool()
-			certPool.AppendCertsFromPEM(clientCAs)
-			config := &tls.Config{
-				MinVersion:   tls.VersionTLS13,
-				Certificates: []tls.Certificate{serverCert},
-				ClientAuth:   tls.RequireAndVerifyClientCert,
-				ClientCAs:    certPool,
-			}
 
-			opts = append(opts, admin.WithTLS(config))
-		}
-
-		command_runner := fnb.adminCommandBootstrapper.Bootstrap(fnb.Logger, fnb.adminAddr, opts...)
-		if err := command_runner.Start(ctx); err != nil {
-			return nil, err
-		}
-
-		return command_runner, nil
-	})
+			return command_runner, nil
+		})
+	}
 }
 
 func (fnb *FlowNodeBuilder) RegisterBadgerMetrics() error {
@@ -379,7 +387,8 @@ func (fnb *FlowNodeBuilder) initLogger() {
 	if err != nil {
 		log.Fatal().Err(err).Msg("invalid log level")
 	}
-	log = log.Level(lvl)
+	log = log.Level(zerolog.DebugLevel)
+	zerolog.SetGlobalLevel(lvl)
 
 	fnb.Logger = log
 }
@@ -931,19 +940,17 @@ func (fnb *FlowNodeBuilder) Initialize() error {
 		}
 	}
 
-	if fnb.adminAddr != NotSet {
-		if (fnb.adminCert != NotSet || fnb.adminKey != NotSet || fnb.adminClientCAs != NotSet) &&
-			!(fnb.adminCert != NotSet && fnb.adminKey != NotSet && fnb.adminClientCAs != NotSet) {
-			fnb.Logger.Fatal().Msg("admin cert / key and client certs must all be provided to enable mutual TLS")
-		}
-		fnb.EnqueueAdminServerInit(ctx)
-	}
+	fnb.EnqueueAdminServerInit(ctx)
 
 	fnb.EnqueueTracer()
 
 	return nil
 }
 
+func (fnb *FlowNodeBuilder) RegisterDefaultAdminCommands() {
+	fnb.AdminCommand("set-log-level", common.SetLogLevelCommand.Handler, common.SetLogLevelCommand.Validator)
+}
+
 // Run calls Ready() to start all the node modules and components. It also sets up a channel to gracefully shut
 // down each component if a SIGINT is received. Until a SIGINT is received, Run will block.
 // Since, Run is a blocking call it should only be used when running a node as it's own independent process.

engine/common/synchronization/engine.go

@@ -380,7 +380,7 @@ func (e *Engine) sendRequests(participants flow.IdentifierList, ranges []flow.Ra
 			errs = multierror.Append(errs, fmt.Errorf("could not submit range request: %w", err))
 			continue
 		}
-		e.log.Debug().
+		e.log.Info().
 			Uint64("range_from", req.FromHeight).
 			Uint64("range_to", req.ToHeight).
 			Uint64("range_nonce", req.Nonce).