refactor logger & add json log format (ava-labs#198)

* refactor logger & add json log format

* add fallback comment

plugin/evm/admin.go

@@ -63,11 +63,9 @@ type SetLogLevelArgs struct {
 
 func (p *Admin) SetLogLevel(r *http.Request, args *SetLogLevelArgs, reply *api.EmptyReply) error {
 	log.Info("EVM: SetLogLevel called", "logLevel", args.Level)
-	logLevel, err := log.LvlFromString(args.Level)
-	if err != nil {
+	if err := p.vm.logger.SetLogLevel(args.Level); err != nil {
 		return fmt.Errorf("failed to parse log level: %w ", err)
 	}
-	p.vm.setLogLevel(logLevel)
 	return nil
 }
 

plugin/evm/config.go

@@ -35,6 +35,7 @@ const (
 	defaultPriorityRegossipTxsPerAddress          = 16
 	defaultOfflinePruningBloomFilterSize   uint64 = 512 // Default size (MB) for the offline pruner to use
 	defaultLogLevel                               = "info"
+	defaultLogJSONFormat                          = false
 	defaultMaxOutboundActiveRequests              = 8
 	defaultPopulateMissingTriesParallelism        = 1024
 )
@@ -113,8 +114,9 @@ type Config struct {
 	PriorityRegossipTxsPerAddress int              `json:"priority-regossip-txs-per-address"`
 	PriorityRegossipAddresses     []common.Address `json:"priority-regossip-addresses"`
 
-	// Log level
-	LogLevel string `json:"log-level"`
+	// Log
+	LogLevel      string `json:"log-level"`
+	LogJSONFormat bool   `json:"log-json-format"`
 
 	// Address for Tx Fees (must be empty if not supported by blockchain)
 	FeeRecipient string `json:"feeRecipient"`
@@ -160,6 +162,7 @@ func (c *Config) SetDefaults() {
 	c.PriorityRegossipTxsPerAddress = defaultPriorityRegossipTxsPerAddress
 	c.OfflinePruningBloomFilterSize = defaultOfflinePruningBloomFilterSize
 	c.LogLevel = defaultLogLevel
+	c.LogJSONFormat = defaultLogJSONFormat
 	c.MaxOutboundActiveRequests = defaultMaxOutboundActiveRequests
 	c.PopulateMissingTriesParallelism = defaultPopulateMissingTriesParallelism
 }

plugin/evm/log.go

@@ -0,0 +1,67 @@
+// (c) 2019-2020, Ava Labs, Inc. All rights reserved.
+// See the file LICENSE for licensing terms.
+
+package evm
+
+import (
+	"fmt"
+	"io"
+
+	"github.com/ethereum/go-ethereum/log"
+)
+
+type SubnetEVMLogger struct {
+	log.Handler
+}
+
+// InitLogger initializes logger with alias and sets the log level and format with the original [os.StdErr] interface
+// along with the context logger.
+func InitLogger(alias string, level string, jsonFormat bool, writer io.Writer) (SubnetEVMLogger, error) {
+	logFormat := SubnetEVMTermFormat(alias)
+	if jsonFormat {
+		logFormat = SubnetEVMJSONFormat(alias)
+	}
+
+	// Create handler
+	logHandler := log.StreamHandler(writer, logFormat)
+	c := SubnetEVMLogger{Handler: logHandler}
+
+	if err := c.SetLogLevel(level); err != nil {
+		return SubnetEVMLogger{}, err
+	}
+	return c, nil
+}
+
+// SetLogLevel sets the log level of initialized log handler.
+func (c *SubnetEVMLogger) SetLogLevel(level string) error {
+	// Set log level
+	logLevel, err := log.LvlFromString(level)
+	if err != nil {
+		return err
+	}
+	log.Root().SetHandler(log.LvlFilterHandler(logLevel, c))
+	return nil
+}
+
+func SubnetEVMTermFormat(alias string) log.Format {
+	prefix := fmt.Sprintf("<%s Chain>", alias)
+	return log.FormatFunc(func(r *log.Record) []byte {
+		location := fmt.Sprintf("%+v", r.Call)
+		newMsg := fmt.Sprintf("%s %s: %s", prefix, location, r.Msg)
+		r.Msg = newMsg
+		return log.TerminalFormat(false).Format(r)
+	})
+}
+
+func SubnetEVMJSONFormat(alias string) log.Format {
+	prefix := fmt.Sprintf("%s Chain", alias)
+	return log.FormatFunc(func(r *log.Record) []byte {
+		location := fmt.Sprintf("%+v", r.Call)
+		r.KeyNames.Lvl = "level"
+		r.KeyNames.Time = "timestamp"
+		r.Ctx = append(r.Ctx, "logger", prefix)
+		r.Ctx = append(r.Ctx, "caller", location)
+
+		return log.JSONFormat().Format(r)
+	})
+}

plugin/evm/vm.go

@@ -122,7 +122,6 @@ func init() {
 	// Preserving the log level allows us to update the root handler while writing to the original
 	// [os.Stderr] that is being piped through to the logger via the rpcchainvm.
 	originalStderr = os.Stderr
-	log.Root().SetHandler(log.LvlFilterHandler(log.LvlDebug, log.StreamHandler(originalStderr, log.TerminalFormat(false))))
 }
 
 // VM implements the snowman.ChainVM interface
@@ -175,40 +174,7 @@ type VM struct {
 	multiGatherer avalanchegoMetrics.MultiGatherer
 
 	bootstrapped bool
-}
-
-// setLogLevel initializes logger and sets the log level with the original [os.StdErr] interface
-// along with the context logger.
-func (vm *VM) setLogLevel(logLevel log.Lvl) {
-	prefix, err := vm.ctx.BCLookup.PrimaryAlias(vm.ctx.ChainID)
-	if err != nil {
-		prefix = vm.ctx.ChainID.String()
-	}
-	prefix = fmt.Sprintf("<%s Chain>", prefix)
-	format := SubnetEVMFormat(prefix)
-	log.Root().SetHandler(log.LvlFilterHandler(logLevel, log.MultiHandler(
-		log.StreamHandler(originalStderr, format),
-		log.StreamHandler(vm.ctx.Log, format),
-	)))
-}
-
-func SubnetEVMFormat(prefix string) log.Format {
-	return log.FormatFunc(func(r *log.Record) []byte {
-		location := fmt.Sprintf("%+v", r.Call)
-		newMsg := fmt.Sprintf("%s %s: %s", prefix, location, r.Msg)
-		// need to deep copy since we're using a multihandler
-		// as a result it will alter R.msg twice.
-		newRecord := log.Record{
-			Time:     r.Time,
-			Lvl:      r.Lvl,
-			Msg:      newMsg,
-			Ctx:      r.Ctx,
-			Call:     r.Call,
-			KeyNames: r.KeyNames,
-		}
-		b := log.TerminalFormat(false).Format(&newRecord)
-		return b
-	})
+	logger       SubnetEVMLogger
 }
 
 /*
@@ -243,14 +209,21 @@ func (vm *VM) Initialize(
 		return err
 	}
 
-	// Set log level
-	logLevel, err := log.LvlFromString(vm.config.LogLevel)
+	vm.ctx = ctx
+
+	// Create logger
+	alias, err := vm.ctx.BCLookup.PrimaryAlias(vm.ctx.ChainID)
+	if err != nil {
+		// fallback to ChainID string instead of erroring
+		alias = vm.ctx.ChainID.String()
+	}
+
+	subnetEVMLogger, err := InitLogger(alias, vm.config.LogLevel, vm.config.LogJSONFormat, originalStderr)
 	if err != nil {
 		return fmt.Errorf("failed to initialize logger due to: %w ", err)
 	}
+	vm.logger = subnetEVMLogger
 
-	vm.ctx = ctx
-	vm.setLogLevel(logLevel)
 	if b, err := json.Marshal(vm.config); err == nil {
 		log.Info("Initializing Subnet EVM VM", "Version", Version, "Config", string(b))
 	} else {