feat: adding zerolog logging to cosmovisor (cosmos#10217)

* adding zerolog to cosmovisor

* replacing println with logger

* fixing tests

* fixing err log format

* addign changelog

* fixing formatting

* using fields in loggin

* using fields in logging

Co-authored-by: Jonathan Gimeno <[email protected]>

cosmovisor/CHANGELOG.md

@@ -49,6 +49,7 @@ Ref: https://keepachangelog.com/en/1.0.0/
 
 + [\#10018](https://github.com/cosmos/cosmos-sdk/pull/10018) Strict boolean argument parsing: cosmovisor will fail if user will not set correctly a boolean variable. Correct values are: "true", "false", "" (not setting) - all case not sensitive.
 + [\#10036](https://github.com/cosmos/cosmos-sdk/pull/10036) Improve logs when downloading the binary.
++ [\#10217](https://github.com/cosmos/cosmos-sdk/pull/10217) Replacing logging to use zerolog.
 
 ## v0.1 2021-08-06
 

cosmovisor/args.go

@@ -247,7 +247,7 @@ func (cfg *Config) UpgradeInfo() UpgradeInfo {
 	return cfg.currentUpgrade
 
 returnError:
-	fmt.Println("[cosmovisor], error reading", filename, err)
+	Logger.Error().Err(err).Str("filename", filename).Msg("failed to read")
 	cfg.currentUpgrade.Name = "_"
 	return cfg.currentUpgrade
 }

cosmovisor/cmd/cosmovisor/main.go

@@ -1,16 +1,16 @@
 package main
 
 import (
-	"fmt"
 	"os"
 
 	"github.com/cosmos/cosmos-sdk/cosmovisor"
 	"github.com/cosmos/cosmos-sdk/cosmovisor/cmd/cosmovisor/cmd"
 )
 
 func main() {
+	cosmovisor.SetupLogging()
 	if err := Run(os.Args[1:]); err != nil {
-		fmt.Fprintf(os.Stderr, "[cosmovisor] %+v\n", err)
+		cosmovisor.Logger.Error().Err(err).Msg("")
 		os.Exit(1)
 	}
 }
@@ -31,11 +31,11 @@ func Run(args []string) error {
 	doUpgrade, err := launcher.Run(args, os.Stdout, os.Stderr)
 	// if RestartAfterUpgrade, we launch after a successful upgrade (only condition LaunchProcess returns nil)
 	for cfg.RestartAfterUpgrade && err == nil && doUpgrade {
-		fmt.Println("[cosmovisor] upgrade detected, relaunching the app ", cfg.Name)
+		cosmovisor.Logger.Info().Str("app", cfg.Name).Msg("upgrade detected, relaunching")
 		doUpgrade, err = launcher.Run(args, os.Stdout, os.Stderr)
 	}
 	if doUpgrade && err == nil {
-		fmt.Println("[cosmovisor] upgrade detected, DAEMON_RESTART_AFTER_UPGRADE is off. Verify new upgrade and start cosmovisor again.")
+		cosmovisor.Logger.Info().Msg("upgrade detected, DAEMON_RESTART_AFTER_UPGRADE is off. Verify new upgrade and start cosmovisor again.")
 	}
 
 	return err

cosmovisor/go.mod

@@ -28,6 +28,7 @@ require (
 	github.com/mitchellh/go-homedir v1.0.0 // indirect
 	github.com/mitchellh/go-testing-interface v1.0.0 // indirect
 	github.com/pmezard/go-difflib v1.0.0 // indirect
+	github.com/rs/zerolog v1.25.0 // indirect
 	github.com/ulikunitz/xz v0.5.5 // indirect
 	go.opencensus.io v0.23.0 // indirect
 	golang.org/x/lint v0.0.0-20210508222113-6edffad5e616 // indirect
@@ -36,7 +37,7 @@ require (
 	golang.org/x/oauth2 v0.0.0-20210402161424-2e8d93401602 // indirect
 	golang.org/x/sys v0.0.0-20210510120138-977fb7262007 // indirect
 	golang.org/x/text v0.3.5 // indirect
-	golang.org/x/tools v0.1.2 // indirect
+	golang.org/x/tools v0.1.5 // indirect
 	golang.org/x/xerrors v0.0.0-20200804184101-5ec99f83aff1 // indirect
 	google.golang.org/appengine v1.6.7 // indirect
 	google.golang.org/grpc v1.38.0 // indirect

cosmovisor/go.sum

@@ -53,6 +53,7 @@ github.com/client9/misspell v0.3.4/go.mod h1:qj6jICC3Q7zFZvVWo7KLAzC3yx5G7kyvSDk
 github.com/cncf/udpa/go v0.0.0-20191209042840-269d4d468f6f/go.mod h1:M8M6+tZqaGXZJjfX53e64911xZQV5JYwmTeXPW+k8Sc=
 github.com/cncf/udpa/go v0.0.0-20200629203442-efcf912fb354/go.mod h1:WmhPx2Nbnhtbo57+VJT5O0JRkEi1Wbu0z5j0R8u5Hbk=
 github.com/cncf/udpa/go v0.0.0-20201120205902-5459f2c99403/go.mod h1:WmhPx2Nbnhtbo57+VJT5O0JRkEi1Wbu0z5j0R8u5Hbk=
+github.com/coreos/go-systemd/v22 v22.3.2/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc=
 github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
 github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c=
 github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
@@ -67,6 +68,7 @@ github.com/fatih/color v1.7.0/go.mod h1:Zm6kSWBoL9eyXnKyktHP6abPY2pDugNf5Kwzbycv
 github.com/go-gl/glfw v0.0.0-20190409004039-e6da0acd62b1/go.mod h1:vR7hzQXu2zJy9AVAgeJqvqgH9Q5CA+iKCZ2gyEVpxRU=
 github.com/go-gl/glfw/v3.3/glfw v0.0.0-20191125211704-12ad95a8df72/go.mod h1:tQ2UAYgL5IevRw8kRxooKSPJfGvJ9fJQFa0TUsXzTg8=
 github.com/go-gl/glfw/v3.3/glfw v0.0.0-20200222043503-6f7a984d4dc4/go.mod h1:tQ2UAYgL5IevRw8kRxooKSPJfGvJ9fJQFa0TUsXzTg8=
+github.com/godbus/dbus/v5 v5.0.4/go.mod h1:xhWf0FNVPg57R7Z0UbKHbJfkEywrmjJnf7w5xrFpKfA=
 github.com/golang/glog v0.0.0-20160126235308-23def4e6c14b/go.mod h1:SBH7ygxi8pfUlaOkMMuAQtPIUF8ecWP5IEl/CR7VP2Q=
 github.com/golang/groupcache v0.0.0-20190702054246-869f871628b6/go.mod h1:cIg4eruTrX1D+g88fzRXU5OdNfaM+9IcxsU14FzY7Hc=
 github.com/golang/groupcache v0.0.0-20191227052852-215e87163ea7/go.mod h1:cIg4eruTrX1D+g88fzRXU5OdNfaM+9IcxsU14FzY7Hc=
@@ -171,10 +173,14 @@ github.com/otiai10/curr v1.0.0/go.mod h1:LskTG5wDwr8Rs+nNQ+1LlxRjAtTZZjtJW4rMXl6
 github.com/otiai10/mint v1.3.0/go.mod h1:F5AjcsTsWUqX+Na9fpHb52P8pcRX2CI6A3ctIT91xUo=
 github.com/otiai10/mint v1.3.2 h1:VYWnrP5fXmz1MXvjuUvcBrXSjGE6xjON+axB/UrpO3E=
 github.com/otiai10/mint v1.3.2/go.mod h1:/yxELlJQ0ufhjUwhshSj+wFjZ78CnZ48/1wtmBH1OTc=
+github.com/pkg/errors v0.9.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0=
 github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM=
 github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
 github.com/prometheus/client_model v0.0.0-20190812154241-14fe0d1b01d4/go.mod h1:xMI15A0UPsDsEKsMN9yxemIoYk6Tm2C1GtYGdfGttqA=
 github.com/rogpeppe/go-internal v1.3.0/go.mod h1:M8bDsm7K2OlrFYOpmOWEs/qY81heoFRclV5y23lUDJ4=
+github.com/rs/xid v1.3.0/go.mod h1:trrq9SKmegXys3aeAKXMUTdJsYXVwGY3RLcfgqegfbg=
+github.com/rs/zerolog v1.25.0 h1:Rj7XygbUHKUlDPcVdoLyR91fJBsduXj5fRxyqIQj/II=
+github.com/rs/zerolog v1.25.0/go.mod h1:7KHcEGe0QZPOm2IE4Kpb5rTh6n1h2hIgS5OOnu1rUaI=
 github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
 github.com/stretchr/testify v1.2.2/go.mod h1:a8OnRcib4nhh0OaRAV+Yts87kKdq0PP7pXfy6kDkUVs=
 github.com/stretchr/testify v1.4.0/go.mod h1:j7eGeouHqKxXV5pUuKE4zz7dFj8WfuZ+81PSLYec5m4=
@@ -397,6 +403,7 @@ golang.org/x/tools v0.0.0-20210105154028-b0ab187a4818/go.mod h1:emZCQorbCU4vsT4f
 golang.org/x/tools v0.1.0/go.mod h1:xkSsbof2nBLbhDlRMhhhyNLN/zl3eTqcnHD5viDpcZ0=
 golang.org/x/tools v0.1.2 h1:kRBLX7v7Af8W7Gdbbc908OJcdgtK8bOz9Uaj8/F1ACA=
 golang.org/x/tools v0.1.2/go.mod h1:o0xws9oXOQQZyjljx8fwUC0k7L1pTE6eaCbjGeHmOkk=
+golang.org/x/tools v0.1.5/go.mod h1:o0xws9oXOQQZyjljx8fwUC0k7L1pTE6eaCbjGeHmOkk=
 golang.org/x/xerrors v0.0.0-20190717185122-a985d3407aa7/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=
 golang.org/x/xerrors v0.0.0-20191011141410-1b5146add898/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=
 golang.org/x/xerrors v0.0.0-20191204190536-9bdfabe68543/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=

cosmovisor/logger.go

@@ -0,0 +1,15 @@
+package cosmovisor
+
+import (
+	"os"
+	"time"
+
+	"github.com/rs/zerolog"
+)
+
+var Logger zerolog.Logger
+
+func SetupLogging() {
+	output := zerolog.ConsoleWriter{Out: os.Stdout, TimeFormat: time.Kitchen}
+	Logger = zerolog.New(output).With().Str("module", "cosmovisor").Timestamp().Logger()
+}

cosmovisor/process.go

@@ -5,7 +5,6 @@ import (
 	"fmt"
 	"io"
 	"io/ioutil"
-	"log"
 	"os"
 	"os/exec"
 	"os/signal"
@@ -40,7 +39,7 @@ func (l Launcher) Run(args []string, stdout, stderr io.Writer) (bool, error) {
 	if err := EnsureBinary(bin); err != nil {
 		return false, fmt.Errorf("current binary is invalid: %w", err)
 	}
-	fmt.Println("[cosmovisor] running ", bin, args)
+	Logger.Info().Str("path", bin).Strs("args", args).Msg("running app")
 	cmd := exec.Command(bin, args...)
 	cmd.Stdout = stdout
 	cmd.Stderr = stderr
@@ -53,7 +52,7 @@ func (l Launcher) Run(args []string, stdout, stderr io.Writer) (bool, error) {
 	go func() {
 		sig := <-sigs
 		if err := cmd.Process.Signal(sig); err != nil {
-			log.Fatal(bin, "terminated. Error:", err)
+			Logger.Fatal().Err(err).Str("bin", bin).Msg("terminated")
 		}
 	}()
 
@@ -92,7 +91,7 @@ func (l Launcher) WaitForUpgradeOrExit(cmd *exec.Cmd) (bool, error) {
 	select {
 	case <-l.fw.MonitorUpdate(currentUpgrade):
 		// upgrade - kill the process and restart
-		fmt.Println("[cosmovisor] Daemon shutting down in an attempt to restart")
+		Logger.Info().Msg("Daemon shutting down in an attempt to restart")
 		_ = cmd.Process.Kill()
 	case err := <-cmdDone:
 		l.fw.Stop()
@@ -133,7 +132,7 @@ func doBackup(cfg *Config) error {
 		stStr := fmt.Sprintf("%d-%d-%d", st.Year(), st.Month(), st.Day())
 		dst := filepath.Join(cfg.Home, fmt.Sprintf("data"+"-backup-%s", stStr))
 
-		fmt.Printf("starting to take backup of data directory at time %s", st)
+		Logger.Info().Time("backup start time", st).Msg("starting to take backup of data directory")
 
 		// copy the $DAEMON_HOME/data to a backup dir
 		err = copy.Copy(filepath.Join(cfg.Home, "data"), dst)
@@ -144,9 +143,7 @@ func doBackup(cfg *Config) error {
 
 		// backup is done, lets check endtime to calculate total time taken for backup process
 		et := time.Now()
-		timeTaken := et.Sub(st)
-		fmt.Printf("backup saved at location: %s, completed at time: %s\n"+
-			"time taken to complete the backup: %s", dst, et, timeTaken)
+		Logger.Info().Str("backup saved at", dst).Time("backup completion time", et).TimeDiff("time taken to complete backup", et, st).Msg("backup completed")
 	}
 
 	return nil
@@ -166,15 +163,14 @@ func doPreUpgrade(cfg *Config) error {
 
 		if err != nil {
 			if err.(*exec.ExitError).ProcessState.ExitCode() == 1 {
-				fmt.Println("pre-upgrade command does not exist. continuing the upgrade.")
+				Logger.Info().Msg("pre-upgrade command does not exist. continuing the upgrade.")
 				return nil
 			}
 			if err.(*exec.ExitError).ProcessState.ExitCode() == 30 {
 				return fmt.Errorf("pre-upgrade command failed : %w", err)
 			}
 			if err.(*exec.ExitError).ProcessState.ExitCode() == 31 {
-				fmt.Println("pre-upgrade command failed. retrying. attempt:", counter)
-				fmt.Println(err)
+				Logger.Error().Err(err).Int("attempt", counter).Msg("pre-upgrade command failed. retrying")
 				continue
 			}
 		}

cosmovisor/scanner.go

@@ -4,7 +4,6 @@ import (
 	"encoding/json"
 	"errors"
 	"fmt"
-	"log"
 	"os"
 	"path/filepath"
 	"time"
@@ -94,7 +93,7 @@ func (fw *fileWatcher) CheckUpdate(currentUpgrade UpgradeInfo) bool {
 	}
 	info, err := parseUpgradeInfoFile(fw.filename)
 	if err != nil {
-		log.Fatal("Can't parse upgrade info file. Err: ", err)
+		Logger.Fatal().Err(err).Msg("Can't parse upgrade info file")
 		return false
 	}
 	if !fw.initialized { // daemon has restarted

cosmovisor/upgrade.go

@@ -36,11 +36,11 @@ func DoUpgrade(cfg *Config, info UpgradeInfo) error {
 	}
 
 	// If not there, then we try to download it... maybe
-	fmt.Println("[cosmovisor] No upgrade binary found, beginning to download it")
+	Logger.Info().Msg("No upgrade binary found, beginning to download it")
 	if err := DownloadBinary(cfg, info); err != nil {
 		return fmt.Errorf("cannot download binary. %w", err)
 	}
-	fmt.Println("[cosmovisor] Downloading binary complete")
+	Logger.Info().Msg("Downloading binary complete")
 
 	// and then set the binary again
 	if err := EnsureBinary(cfg.UpgradeBin(info.Name)); err != nil {