Revamp logs (0xPolygonHermez#1401)

### What does this PR do?

This PR proposes to revamp our `log` package. The idea is to have more information in the logs without having to add them manually on each log line.

This is accomplished by providing a way to get **child loggers** derived from the **root** one: 
- **Every function** that needs to inject new fields in the logs can do so by calling `WithFields` on the current logger. 
- **This returns** a new child logger that will print the provided fields on every log line (within the function scope) in addition to the parent logger fields.

### Example

```go
// use root logger
log.Debug("This is a debug log line from the root logger")

// derive a child logger from the root one, with additional fields
childLog := log.WithFields("txHash", "0xbanana", "chainId", 42)

// these two log lines will be decorated with the `txHash` and `chainId` fields
childLog.Debug("This is a debug log line")
childLog.Debug("This is another debug log line")

// derive a child logger from the previous child, adding another field
grandChildLog := childLog.WithFields("proverId", "prover123")

// this log line will be decorated with the `txHash`, `chainId` and `proverId` fields
grandChildLog.Debug("This is a debug log line from the granchild logger")

// derive another child logger from the root one, with another field
childLog2 := log.WithFields("batchNum": 8)

// this line will only have the `batchNum` field
childLog2.Debug("This is a debug log line from the second child logger")
```


**NOTE:** here 2 default fields have been added to **every** log line: `version` and `pid`.
They are purely demonstrative and can be removed/replaced with better ones.

Other logs have been decorated with fields inside `jsonrpc` and `metrics` package. The idea is to gradually start using the feature while developing.

**ENCODING**
Now the encoding of the logs can be specified in the config file choosing between `console` and `json`. The default value is `console`, but `json` can be used in a deployed environment for better logs ingestion.

### Bonus

The log message on startup has been polished a bit:
```sh
Version:      v0.0.1-RC1-5-g8538ace
Git revision: 8538ace
Git branch:   feature/revamp-logs
Go version:   go1.17.13
Built:        Fri, 02 Dec 2022 16:47:58 +0000
OS/Arch:      linux/amd64
```

The env var to pass the commit hash is not needed any more, instead it is sourced from the `Makefile` through a linker flag.

Dockerfile

@@ -13,9 +13,7 @@ RUN cd /src && make build
 
 # CONTAINER FOR RUNNING BINARY
 FROM alpine:3.16.0
-ARG BUILD_COMMIT
-ENV COMMIT_HASH $BUILD_COMMIT
 COPY --from=build /src/dist/zkevm-node /app/zkevm-node
 COPY --from=build /src/config/environments/local/local.node.config.toml /app/example.config.toml
 EXPOSE 8123
-CMD ["/bin/sh", "-c", "/app/zkevm-node run"]
+CMD ["/bin/sh", "-c", "/app/zkevm-node run"]

Makefile

@@ -1,7 +1,5 @@
-VERSION := $(shell git describe --tags --always)
-COMMIT := $(shell git rev-parse --short HEAD)
-DATE := $(shell date +%Y-%m-%dT%H:%M:%S%z)
-LDFLAGS := -ldflags "-X main.version=$(VERSION) -X main.commit=$(COMMIT) -X main.date=$(DATE)"
+include version.mk
+
 ARCH := $(shell arch)
 
 ifeq ($(ARCH),x86_64)
@@ -11,25 +9,28 @@ else
 		ARCH = arm64
 	endif
 endif
-
 GOBASE := $(shell pwd)
 GOBIN := $(GOBASE)/dist
 GOENVVARS := GOBIN=$(GOBIN) CGO_ENABLED=0 GOOS=linux GOARCH=$(ARCH)
 GOBINARY := zkevm-node
 GOCMD := $(GOBASE)/cmd
-$(eval BUILD_COMMIT:=$(shell git rev-parse --short HEAD))
+
+LDFLAGS += -X 'github.com/0xPolygonHermez/zkevm-node.Version=$(VERSION)'
+LDFLAGS += -X 'github.com/0xPolygonHermez/zkevm-node.GitRev=$(GITREV)'
+LDFLAGS += -X 'github.com/0xPolygonHermez/zkevm-node.GitBranch=$(GITBRANCH)'
+LDFLAGS += -X 'github.com/0xPolygonHermez/zkevm-node.BuildDate=$(DATE)'
 
 .PHONY: build
 build: ## Builds the binary locally into ./dist
-	$(GOENVVARS) go build $(LDFLAGS) -o $(GOBIN)/$(GOBINARY) $(GOCMD)
+	$(GOENVVARS) go build -ldflags "all=$(LDFLAGS)" -o $(GOBIN)/$(GOBINARY) $(GOCMD)
 
 .PHONY: build-docker
 build-docker: ## Builds a docker image with the node binary
-	docker build -t zkevm-node --build-arg BUILD_COMMIT="$(BUILD_COMMIT)" -f ./Dockerfile .
+	docker build -t zkevm-node -f ./Dockerfile .
 
 .PHONY: build-docker-nc
 build-docker-nc: ## Builds a docker image with the node binary - but without build cache
-	docker build --no-cache=true -t zkevm-node --build-arg BUILD_COMMIT="$(BUILD_COMMIT)" -f ./Dockerfile .
+	docker build --no-cache=true -t zkevm-node -f ./Dockerfile .
 
 .PHONY: run-rpc
 run-rpc: ## Runs all the services need to run a local zkEMV RPC node

cmd/main.go

@@ -4,21 +4,14 @@ import (
 	"fmt"
 	"os"
 
+	"github.com/0xPolygonHermez/zkevm-node"
 	"github.com/0xPolygonHermez/zkevm-node/config"
 	"github.com/0xPolygonHermez/zkevm-node/jsonrpc"
 	"github.com/0xPolygonHermez/zkevm-node/log"
-	"github.com/0xPolygonHermez/zkevm-node/test/testutils"
 	"github.com/urfave/cli/v2"
 )
 
-const (
-	// App name
-	appName = "zkevm-node"
-	// version represents the program based on the git tag
-	version = "v0.1.0"
-	// date represents the date of application was built
-	date = ""
-)
+const appName = "zkevm-node"
 
 const (
 	// AGGREGATOR is the aggregator component identifier.
@@ -33,14 +26,7 @@ const (
 	BROADCAST = "broadcast-trusted-state"
 )
 
-const (
-	//envCommitHash environment variable name for COMMIT_HASH
-	envCommitHash = "COMMIT_HASH"
-)
-
 var (
-	// commit represents the program based on the git commit
-	commit         = testutils.GetEnv(envCommitHash, "dev")
 	configFileFlag = cli.StringFlag{
 		Name:     config.FlagCfg,
 		Aliases:  []string{"c"},
@@ -78,14 +64,13 @@ var (
 func main() {
 	app := cli.NewApp()
 	app.Name = appName
-	app.Version = version
+	app.Version = zkevm.Version
 	flags := []cli.Flag{
 		&configFileFlag,
 		&yesFlag,
 		&componentsFlag,
 		&httpAPIFlag,
 	}
-	log.Infof("Starting application [Commit Hash: %s, Version: %s] ...", commit, version)
 	app.Commands = []*cli.Command{
 		{
 			Name:    "version",

cmd/run.go

@@ -11,6 +11,7 @@ import (
 	"os/signal"
 	"path/filepath"
 
+	"github.com/0xPolygonHermez/zkevm-node"
 	"github.com/0xPolygonHermez/zkevm-node/aggregator"
 	"github.com/0xPolygonHermez/zkevm-node/config"
 	"github.com/0xPolygonHermez/zkevm-node/db"
@@ -40,6 +41,8 @@ import (
 )
 
 func start(cliCtx *cli.Context) error {
+	zkevm.PrintVersion(os.Stdout)
+
 	c, err := config.Load(cliCtx)
 	if err != nil {
 		return err

cmd/version.go

@@ -1,14 +1,13 @@
 package main
 
 import (
-	"fmt"
+	"os"
 
+	"github.com/0xPolygonHermez/zkevm-node"
 	"github.com/urfave/cli/v2"
 )
 
 func versionCmd(*cli.Context) error {
-	fmt.Printf("Version = \"%v\"\n", version)
-	fmt.Printf("Build = \"%v\"\n", commit)
-	fmt.Printf("Date = \"%v\"\n", date)
+	zkevm.PrintVersion(os.Stdout)
 	return nil
 }

config/config.go

@@ -62,8 +62,8 @@ type Config struct {
 	Metrics            metrics.Config
 }
 
-// Load loads the configuration
-func Load(ctx *cli.Context) (*Config, error) {
+// Default parses the default configuration values.
+func Default() (*Config, error) {
 	var cfg Config
 	viper.SetConfigType("toml")
 
@@ -75,6 +75,15 @@ func Load(ctx *cli.Context) (*Config, error) {
 	if err != nil {
 		return nil, err
 	}
+	return &cfg, nil
+}
+
+// Load loads the configuration
+func Load(ctx *cli.Context) (*Config, error) {
+	cfg, err := Default()
+	if err != nil {
+		return nil, err
+	}
 	configFilePath := ctx.String(FlagCfg)
 	if configFilePath != "" {
 		dirName, fileName := filepath.Split(configFilePath)
@@ -114,5 +123,5 @@ func Load(ctx *cli.Context) (*Config, error) {
 		}
 		log.Debugf("Configuration loaded: \n%s\n", string(cfgJSON))
 	*/
-	return &cfg, nil
+	return cfg, nil
 }

config/config_test.go

@@ -11,6 +11,7 @@ import (
 
 	"github.com/0xPolygonHermez/zkevm-node/config"
 	"github.com/0xPolygonHermez/zkevm-node/config/types"
+	"github.com/0xPolygonHermez/zkevm-node/log"
 	"github.com/0xPolygonHermez/zkevm-node/pricegetter"
 	"github.com/0xPolygonHermez/zkevm-node/sequencer"
 	"github.com/ethereum/go-ethereum/common"
@@ -23,6 +24,18 @@ func Test_Defaults(t *testing.T) {
 		path          string
 		expectedValue interface{}
 	}{
+		{
+			path:          "Log.Environment",
+			expectedValue: log.LogEnvironment("development"),
+		},
+		{
+			path:          "Log.Level",
+			expectedValue: "debug",
+		},
+		{
+			path:          "Log.Outputs",
+			expectedValue: []string{"stderr"},
+		},
 		{
 			path:          "Synchronizer.SyncChunkSize",
 			expectedValue: uint64(100),

config/default.go

@@ -5,8 +5,9 @@ const DefaultValues = `
 IsTrustedSequencer = false
 
 [Log]
+Environment = "development" # "production" or "development"
 Level = "debug"
-Outputs = ["stdout"]
+Outputs = ["stderr"]
 
 [StateDB]
 User = "state_user"

config/environments/local/local.node.config.toml

@@ -1,8 +1,9 @@
 IsTrustedSequencer = false
 
 [Log]
+Environment = "development" # "production" or "development"
 Level = "debug"
-Outputs = ["stdout"]
+Outputs = ["stderr"]
 
 [StateDB]
 User = "state_user"

config/environments/public/public.node.config.toml

@@ -1,6 +1,7 @@
 [Log]
-Level = "debug"
-Outputs = ["stdout"]
+Environment = "development" # "production" or "development"
+Level = "info"
+Outputs = ["stderr"]
 
 [StateDB]
 User = "state_user"

etherman/etherman.go

@@ -457,7 +457,6 @@ func (etherMan *Client) forcedBatchEvent(ctx context.Context, vLog types.Log, bl
 	}
 	msg, err := tx.AsMessage(types.NewLondonSigner(tx.ChainId()), big.NewInt(0))
 	if err != nil {
-		log.Error(err)
 		return err
 	}
 	if fb.Sequencer == msg.From() {
@@ -526,7 +525,6 @@ func (etherMan *Client) sequencedBatchesEvent(ctx context.Context, vLog types.Lo
 	}
 	msg, err := tx.AsMessage(types.NewLondonSigner(tx.ChainId()), big.NewInt(0))
 	if err != nil {
-		log.Error(err)
 		return err
 	}
 	sequences, err := decodeSequences(tx.Data(), sb.NumBatch, msg.From(), vLog.TxHash, msg.Nonce())
@@ -651,7 +649,6 @@ func (etherMan *Client) forceSequencedBatchesEvent(ctx context.Context, vLog typ
 	}
 	msg, err := tx.AsMessage(types.NewLondonSigner(tx.ChainId()), big.NewInt(0))
 	if err != nil {
-		log.Error(err)
 		return err
 	}
 	fullBlock, err := etherMan.EtherClient.BlockByHash(ctx, vLog.BlockHash)

etherman/etherman_test.go

@@ -25,7 +25,7 @@ import (
 func init() {
 	log.Init(log.Config{
 		Level:   "debug",
-		Outputs: []string{"stdout"},
+		Outputs: []string{"stderr"},
 	})
 }
 

etherman/etherscan/etherscan_test.go

@@ -16,7 +16,7 @@ import (
 func init() {
 	log.Init(log.Config{
 		Level:   "debug",
-		Outputs: []string{"stdout"},
+		Outputs: []string{"stderr"},
 	})
 }
 

etherman/ethgasstation/ethgasstation_test.go

@@ -16,7 +16,7 @@ import (
 func init() {
 	log.Init(log.Config{
 		Level:   "debug",
-		Outputs: []string{"stdout"},
+		Outputs: []string{"stderr"},
 	})
 }
 

jsonrpc/handler.go

@@ -49,6 +49,7 @@ var connectionCounterMutex sync.Mutex
 // Handle is the function that knows which and how a function should
 // be executed when a JSON RPC request is received
 func (d *Handler) Handle(req Request) Response {
+	log := log.WithFields("method", req.Method, "requestId", req.ID)
 	connectionCounterMutex.Lock()
 	connectionCounter++
 	connectionCounterMutex.Unlock()
@@ -59,7 +60,7 @@ func (d *Handler) Handle(req Request) Response {
 		log.Debugf("Current open connections %d", connectionCounter)
 	}()
 	log.Debugf("Current open connections %d", connectionCounter)
-	log.Debugf("request method %s id %v params %v", req.Method, req.ID, string(req.Params))
+	log.Debugf("request params %v", string(req.Params))
 
 	service, fd, err := d.getFnHandler(req)
 	if err != nil {
@@ -90,7 +91,7 @@ func (d *Handler) Handle(req Request) Response {
 
 	output := fd.fv.Call(inArgs)
 	if err := getError(output[1]); err != nil {
-		log.Infof("failed to call method %s: [%v]%v. Params: %v", req.Method, err.ErrorCode(), err.Error(), string(req.Params))
+		log.Infof("failed call: [%v]%v. Params: %v", err.ErrorCode(), err.Error(), string(req.Params))
 		return NewResponse(req, nil, err)
 	}
 

log/config.go

@@ -2,6 +2,8 @@ package log
 
 // Config for log
 type Config struct {
+	// Environment defining the log format ("production" or "development").
+	Environment LogEnvironment `mapstructure:"Environment"`
 	// Level of log, e.g. INFO, WARN, ...
 	Level string `mapstructure:"Level"`
 	// Outputs