CNS-735 they see me rollin... - rolling logs! (#1012)

* rolling logs!

* fix comments

* comment adjust

* adding on finish defered method.

ecosystem/cache/command.go

@@ -29,7 +29,7 @@ longer DefaultExpirationForNonFinalized will reduce sync QoS for "latest" reques
 			if err != nil {
 				utils.LavaFormatFatal("failed to read log level flag", err)
 			}
-			utils.LoggingLevel(logLevel)
+			utils.SetGlobalLoggingLevel(logLevel)
 
 			metricsAddress, err := cmd.Flags().GetString(FlagMetricsAddress)
 			if err != nil {

go.mod

@@ -104,6 +104,7 @@ require (
 	google.golang.org/api v0.126.0 // indirect
 	google.golang.org/appengine v1.6.7 // indirect
 	google.golang.org/genproto/googleapis/rpc v0.0.0-20230726155614-23370e0ffb3e // indirect
+	gopkg.in/natefinch/lumberjack.v2 v2.2.1 // indirect
 	pgregory.net/rapid v0.5.5 // indirect
 	sigs.k8s.io/yaml v1.3.0 // indirect
 )

go.sum

@@ -819,6 +819,8 @@ github.com/jackpal/go-nat-pmp v1.0.2/go.mod h1:QPH045xvCAeXUZOxsnwmrtiCoxIr9eob+
 github.com/jedisct1/go-minisign v0.0.0-20190909160543-45766022959e/go.mod h1:G1CVv03EnqU1wYL2dFwXxW2An0az9JTl/ZsqXQeBlkU=
 github.com/jessevdk/go-flags v0.0.0-20141203071132-1679536dcc89/go.mod h1:4FA24M0QyGHXBuZZK/XkWh8h0e1EYbRYJSGM75WSRxI=
 github.com/jessevdk/go-flags v1.4.0/go.mod h1:4FA24M0QyGHXBuZZK/XkWh8h0e1EYbRYJSGM75WSRxI=
+github.com/jhump/gopoet v0.1.0/go.mod h1:me9yfT6IJSlOL3FCfrg+L6yzUEZ+5jW6WHt4Sk+UPUI=
+github.com/jhump/goprotoc v0.5.0/go.mod h1:VrbvcYrQOrTi3i0Vf+m+oqQWk9l72mjkJCYo7UvLHRQ=
 github.com/jhump/protoreflect v1.10.1/go.mod h1:7GcYQDdMU/O/BBrl/cX6PNHpXh6cenjd8pneu5yW7Tg=
 github.com/jhump/protoreflect v1.15.1 h1:HUMERORf3I3ZdX05WaQ6MIpd/NJ434hTp5YiKgfCL6c=
 github.com/jhump/protoreflect v1.15.1/go.mod h1:jD/2GMKKE6OqX8qTjhADU1e6DShO+gavG9e0Q693nKo=
@@ -840,6 +842,7 @@ github.com/json-iterator/go v1.1.8/go.mod h1:KdQUCv79m/52Kvf8AW2vK1V8akMuk1QjK/u
 github.com/json-iterator/go v1.1.9/go.mod h1:KdQUCv79m/52Kvf8AW2vK1V8akMuk1QjK/uOdHXbAo4=
 github.com/json-iterator/go v1.1.10/go.mod h1:KdQUCv79m/52Kvf8AW2vK1V8akMuk1QjK/uOdHXbAo4=
 github.com/json-iterator/go v1.1.12 h1:PV8peI4a0ysnczrg+LtxykD8LfKY9ML6u2jnxaEnrnM=
+github.com/json-iterator/go v1.1.12/go.mod h1:e30LSqwooZae/UwlEbR2852Gd8hjQvJoHmT4TnhNGBo=
 github.com/jstemmer/go-junit-report v0.0.0-20190106144839-af01ea7f8024/go.mod h1:6v2b51hI/fHJwM22ozAgKL4VKDeJcHhJFhtBdhmNjmU=
 github.com/jstemmer/go-junit-report v0.9.1/go.mod h1:Brl9GWCQeLvo8nXZwPNNblvFj/XSXhF0NWZEnDohbsk=
 github.com/jsternberg/zap-logfmt v1.0.0/go.mod h1:uvPs/4X51zdkcm5jXl5SYoN+4RK21K8mysFmDaM/h+o=
@@ -960,6 +963,7 @@ github.com/modern-go/concurrent v0.0.0-20180306012644-bacd9c7ef1dd/go.mod h1:6dJ
 github.com/modern-go/reflect2 v0.0.0-20180701023420-4b7aa43c6742/go.mod h1:bx2lNnkwVCuqBIxFjflWJWanXIb3RllmbCylyMrvgv0=
 github.com/modern-go/reflect2 v1.0.1/go.mod h1:bx2lNnkwVCuqBIxFjflWJWanXIb3RllmbCylyMrvgv0=
 github.com/modern-go/reflect2 v1.0.2 h1:xBagoLtFs94CBntxluKeaWgTMpvLxC4ur3nMaC9Gz0M=
+github.com/modern-go/reflect2 v1.0.2/go.mod h1:yWuevngMOJpCy52FWWMvUC8ws7m/LJsjYzDa0/r8luk=
 github.com/modocache/gover v0.0.0-20171022184752-b58185e213c5/go.mod h1:caMODM3PzxT8aQXRPkAt8xlV/e7d7w8GM5g0fa5F0D8=
 github.com/mschoch/smat v0.0.0-20160514031455-90eadee771ae/go.mod h1:qAyveg+e4CE+eKJXWVjKXM4ck2QobLqTDytGJbLLhJg=
 github.com/mtibben/percent v0.2.1 h1:5gssi8Nqo8QU/r2pynCm+hBQHpkB/uNK7BJCFogWdzs=
@@ -1942,6 +1946,8 @@ gopkg.in/fsnotify.v1 v1.4.7/go.mod h1:Tz8NjZHkW78fSQdbUxIjBTcgA1z1m8ZHf0WmKUhAMy
 gopkg.in/gcfg.v1 v1.2.3/go.mod h1:yesOnuUOFQAhST5vPY4nbZsb/huCgGGXlipJsBn0b3o=
 gopkg.in/ini.v1 v1.67.0 h1:Dgnx+6+nfE+IfzjUEISNeydPJh9AXNNsWbGP9KzCsOA=
 gopkg.in/ini.v1 v1.67.0/go.mod h1:pNLf8WUiyNEtQjuu5G5vTm06TEv9tsIgeAvK8hOrP4k=
+gopkg.in/natefinch/lumberjack.v2 v2.2.1 h1:bBRl1b0OH9s/DuPhuXpNl+VtCaJXFZ5/uEFST95x9zc=
+gopkg.in/natefinch/lumberjack.v2 v2.2.1/go.mod h1:YD8tP3GAjkrDg1eZH7EGmyESg/lsYskCTPBJVb9jqSc=
 gopkg.in/natefinch/npipe.v2 v2.0.0-20160621034901-c1b8fa8bdcce h1:+JknDZhAj8YMt7GC73Ei8pv4MzjDUNPHgQWJdtMAaDU=
 gopkg.in/natefinch/npipe.v2 v2.0.0-20160621034901-c1b8fa8bdcce/go.mod h1:5AcXVHNjg+BDxry382+8OKon8SEWiKktQR07RKPsv1c=
 gopkg.in/olebedev/go-duktape.v3 v3.0.0-20200619000410-60c24ae608a6/go.mod h1:uAJfkITjFhyEEuUfm7bsmCZRbW5WRq8s9EY8HZ6hCns=

protocol/badgegenerator/badgeserver.go

@@ -67,7 +67,7 @@ func CreateBadgeGeneratorCobraCommand() *cobra.Command {
 			if err != nil {
 				utils.LavaFormatFatal("failed to read log level flag", err)
 			}
-			utils.LoggingLevel(logLevel)
+			utils.SetGlobalLoggingLevel(logLevel)
 
 			RunBadgeServer(cmd, v)
 

protocol/common/cobra_common.go

@@ -0,0 +1,46 @@
+package common
+
+import (
+	"github.com/lavanet/lava/utils"
+	"github.com/spf13/cobra"
+	"github.com/spf13/viper"
+)
+
+const (
+	RollingLogLevelFlag        = "rolling-log-level"
+	RollingLogMaxSizeFlag      = "rolling-log-max-size"
+	RollingLogMaxAgeFlag       = "rolling-log-max-age"
+	RollingLogBackupsFlag      = "rolling-log-backups"
+	RollingLogFileLocationFlag = "rolling-log-file-location"
+	RollingLogFormat           = "rolling-log-format"
+)
+
+const (
+	defaultRollingLogState        = "off"                 // off
+	defaultRollingLogMaxSize      = "100"                 // 100MB
+	defaultRollingLogMaxAge       = "1"                   // 1 day
+	defaultRollingLogFileBackups  = "3"                   // 3 files of defaultRollingLogMaxSize size
+	defaultRollingLogFileLocation = "logs/rollingRPC.log" // logs directory
+	defaultRollingLogFormat       = "json"                // defaults to json format
+)
+
+// default rolling logs behavior (if enabled) will store 3 files each 100MB for up to 1 day every time.
+func AddRollingLogConfig(cmd *cobra.Command) {
+	cmd.Flags().String(RollingLogLevelFlag, defaultRollingLogState, "rolling-log info level (off, debug, info, warn, error, fatal)")
+	cmd.Flags().String(RollingLogMaxSizeFlag, defaultRollingLogMaxSize, "rolling-log max size in MB")
+	cmd.Flags().String(RollingLogMaxAgeFlag, defaultRollingLogMaxAge, "max age in days")
+	cmd.Flags().String(RollingLogBackupsFlag, defaultRollingLogFileBackups, "Keep up to X (number) old log files before purging")
+	cmd.Flags().String(RollingLogFileLocationFlag, defaultRollingLogFileLocation, "where to store the rolling logs e.g /logs/provider1.log")
+	cmd.Flags().String(RollingLogFormat, defaultRollingLogFormat, "rolling log format (json, text)")
+}
+
+func SetupRollingLogger() func() {
+	return utils.RollingLoggerSetup(
+		viper.GetString(RollingLogLevelFlag),
+		viper.GetString(RollingLogFileLocationFlag),
+		viper.GetString(RollingLogMaxSizeFlag),
+		viper.GetString(RollingLogBackupsFlag),
+		viper.GetString(RollingLogMaxAgeFlag),
+		viper.GetString(RollingLogFormat),
+	)
+}

protocol/rpcconsumer/rpcconsumer.go

@@ -321,6 +321,9 @@ rpcconsumer consumer_examples/full_consumer_example.yml --cache-be "127.0.0.1:77
 			// set log format
 			logFormat := viper.GetString(flags.FlagLogFormat)
 			utils.JsonFormat = logFormat == "json"
+			// set rolling log.
+			closeLoggerOnFinish := common.SetupRollingLogger()
+			defer closeLoggerOnFinish()
 
 			utils.LavaFormatInfo("RPCConsumer started", utils.Attribute{Key: "args", Value: strings.Join(args, ",")})
 			clientCtx, err := client.GetClientTxContext(cmd)
@@ -381,7 +384,7 @@ rpcconsumer consumer_examples/full_consumer_example.yml --cache-be "127.0.0.1:77
 			if err != nil {
 				utils.LavaFormatFatal("failed to read log level flag", err)
 			}
-			utils.LoggingLevel(logLevel)
+			utils.SetGlobalLoggingLevel(logLevel)
 
 			test_mode, err := cmd.Flags().GetBool(common.TestModeFlagName)
 			if err != nil {
@@ -455,6 +458,7 @@ rpcconsumer consumer_examples/full_consumer_example.yml --cache-be "127.0.0.1:77
 	cmdRPCConsumer.Flags().String(metrics.MetricsListenFlagName, metrics.DisabledFlagOption, "the address to expose prometheus metrics (such as localhost:7779)")
 	cmdRPCConsumer.Flags().BoolVar(&DebugRelaysFlag, DebugRelaysFlagName, false, "adding debug information to relays")
 	cmdRPCConsumer.Flags().BoolVar(&lavasession.DebugProbes, DebugProbesFlagName, false, "adding information to probes")
+	common.AddRollingLogConfig(cmdRPCConsumer)
 	return cmdRPCConsumer
 }
 

protocol/rpcconsumer/testing.go

@@ -120,7 +120,7 @@ func CreateTestRPCConsumerCobraCommand() *cobra.Command {
 			if err != nil {
 				utils.LavaFormatFatal("failed to read log level flag", err)
 			}
-			utils.LoggingLevel(logLevel)
+			utils.SetGlobalLoggingLevel(logLevel)
 			var viper_endpoints *viper.Viper
 			viper_endpoints, err = commonlib.ParseEndpointArgs(args, Yaml_config_properties, commonlib.EndpointsConfigName)
 			if err != nil {

protocol/rpcprovider/rpcprovider.go

@@ -432,6 +432,9 @@ rpcprovider 127.0.0.1:3333 COS3 tendermintrpc "wss://www.node-path.com:80,https:
 			// set log format
 			logFormat := viper.GetString(flags.FlagLogFormat)
 			utils.JsonFormat = logFormat == "json"
+			// set rolling log.
+			closeLoggerOnFinish := common.SetupRollingLogger()
+			defer closeLoggerOnFinish()
 
 			utils.LavaFormatInfo("RPCProvider started")
 			clientCtx, err := client.GetClientTxContext(cmd)
@@ -509,7 +512,7 @@ rpcprovider 127.0.0.1:3333 COS3 tendermintrpc "wss://www.node-path.com:80,https:
 			if err != nil {
 				utils.LavaFormatFatal("failed to read log level flag", err)
 			}
-			utils.LoggingLevel(logLevel)
+			utils.SetGlobalLoggingLevel(logLevel)
 
 			// check if the command includes --pprof-address
 			pprofAddressFlagUsed := cmd.Flags().Lookup("pprof-address").Changed
@@ -582,5 +585,6 @@ rpcprovider 127.0.0.1:3333 COS3 tendermintrpc "wss://www.node-path.com:80,https:
 	cmdRPCProvider.Flags().Uint(rewardserver.RewardsSnapshotTimeoutSecFlagName, rewardserver.DefaultRewardsSnapshotTimeoutSec, "the seconds to wait until making snapshot of the rewards memory")
 	cmdRPCProvider.Flags().String(StickinessHeaderName, RPCProviderStickinessHeaderName, "the name of the header to be attacked to requests for stickiness by consumer, used for consistency")
 	cmdRPCProvider.Flags().Uint64Var(&chaintracker.PollingMultiplier, chaintracker.PollingMultiplierFlagName, 1, "when set, forces the chain tracker to poll more often, improving the sync at the cost of more queries")
+	common.AddRollingLogConfig(cmdRPCProvider)
 	return cmdRPCProvider
 }

protocol/rpcprovider/testing.go

@@ -272,7 +272,7 @@ rpcprovider --from providerWallet --endpoints "provider-public-grpc:port,jsonrpc
 				address = args[0]
 			}
 			utils.LavaFormatInfo("RPCProvider Test started", utils.Attribute{Key: "address", Value: address})
-			utils.LoggingLevel(logLevel)
+			utils.SetGlobalLoggingLevel(logLevel)
 			clientCtx = clientCtx.WithChainID(networkChainId)
 			txFactory, err := tx.NewFactoryCLI(clientCtx, cmd.Flags())
 			if err != nil {

protocol/statetracker/events.go

@@ -278,7 +278,7 @@ lavad test events 100 5000 --value banana // show all events from 5000-5100 and
 				utils.LavaFormatFatal("failed to fetch DisableInteractive flag", err)
 			}
 			utils.LavaFormatInfo("Events Lookup started", utils.Attribute{Key: "blocks", Value: blocks})
-			utils.LoggingLevel(logLevel)
+			utils.SetGlobalLoggingLevel(logLevel)
 			clientCtx = clientCtx.WithChainID(networkChainId)
 			_, err = tx.NewFactoryCLI(clientCtx, cmd.Flags())
 			if err != nil {

utils/lavalog.go

@@ -15,6 +15,7 @@ import (
 	sdk "github.com/cosmos/cosmos-sdk/types"
 	zerolog "github.com/rs/zerolog"
 	zerologlog "github.com/rs/zerolog/log"
+	"gopkg.in/natefinch/lumberjack.v2"
 )
 
 const (
@@ -28,12 +29,15 @@ const (
 	LAVA_LOG_ERROR
 	LAVA_LOG_FATAL
 	LAVA_LOG_PANIC
+	NoColor = true
 )
 
 var (
 	JsonFormat = false
 	// if set to production, this will replace some errors to warning that can be caused by misuse instead of bugs
 	ExtendedLogLevel = "development"
+	rollingLogLogger = zerolog.New(os.Stderr).Level(zerolog.Disabled) // this is the singleton rolling logger.
+	globalLogLevel   = zerolog.DebugLevel
 )
 
 type Attribute struct {
@@ -67,59 +71,119 @@ func LogLavaEvent(ctx sdk.Context, logger log.Logger, name string, attributes ma
 	ctx.EventManager().EmitEvent(sdk.NewEvent(EventPrefix+name, eventAttrs...))
 }
 
-func LoggingLevel(logLevel string) {
+func getLogLevel(logLevel string) zerolog.Level {
 	switch logLevel {
 	case "debug":
-		zerolog.SetGlobalLevel(zerolog.DebugLevel)
+		return zerolog.DebugLevel
 	case "info":
-		zerolog.SetGlobalLevel(zerolog.InfoLevel)
+		return zerolog.InfoLevel
 	case "warn":
-		zerolog.SetGlobalLevel(zerolog.WarnLevel)
+		return zerolog.WarnLevel
 	case "error":
-		zerolog.SetGlobalLevel(zerolog.ErrorLevel)
+		return zerolog.ErrorLevel
 	case "fatal":
-		zerolog.SetGlobalLevel(zerolog.FatalLevel)
+		return zerolog.FatalLevel
 	default:
-		zerolog.SetGlobalLevel(zerolog.InfoLevel)
+		return zerolog.InfoLevel
 	}
+}
+
+func SetGlobalLoggingLevel(logLevel string) {
+	// setting global level prevents us from having two different levels for example one for stdout and one for rolling log.
+	// zerolog.SetGlobalLevel(getLogLevel(logLevel))
+	globalLogLevel = getLogLevel(logLevel)
 	LavaFormatInfo("setting log level", Attribute{Key: "loglevel", Value: logLevel})
 }
 
+func RollingLoggerSetup(rollingLogLevel string, filePath string, maxSize string, maxBackups string, maxAge string, stdFormat string) func() {
+	maxSizeNumber, err := strconv.Atoi(maxSize)
+	if err != nil {
+		LavaFormatFatal("strconv.Atoi(maxSize)", err, LogAttr("maxSize", maxSize))
+	}
+	maxBackupsNumber, err := strconv.Atoi(maxBackups)
+	if err != nil {
+		LavaFormatFatal("strconv.Atoi(maxSize)", err, LogAttr("maxBackups", maxBackups))
+	}
+	maxAgeNumber, err := strconv.Atoi(maxAge)
+	if err != nil {
+		LavaFormatFatal("strconv.Atoi(maxSize)", err, LogAttr("maxAge", maxAge))
+	}
+
+	rollingLogOutput := &lumberjack.Logger{
+		Filename:   filePath,
+		MaxSize:    maxSizeNumber,
+		MaxBackups: maxBackupsNumber,
+		MaxAge:     maxAgeNumber,
+		Compress:   true,
+	}
+	var logLevel zerolog.Level
+	switch rollingLogLevel {
+	case "off":
+		return func() {} // default is disabled.
+	case "debug":
+		logLevel = zerolog.DebugLevel
+	case "info":
+		logLevel = zerolog.InfoLevel
+	case "warn":
+		logLevel = zerolog.WarnLevel
+	case "error":
+		logLevel = zerolog.ErrorLevel
+	case "fatal":
+		logLevel = zerolog.FatalLevel
+	default:
+		LavaFormatFatal("unsupported case for rollingLoggerSetup", nil, LogAttr("rollingLogLevel", rollingLogLevel))
+	}
+	// set the rolling log level.
+	if stdFormat == "json" {
+		rollingLogLogger = zerolog.New(rollingLogOutput).Level(logLevel).With().Timestamp().Logger()
+	} else {
+		rollingLogLogger = zerolog.New(zerolog.ConsoleWriter{Out: rollingLogOutput, NoColor: NoColor, TimeFormat: time.Stamp}).Level(logLevel).With().Timestamp().Logger()
+	}
+	rollingLogLogger.Debug().Msg("Starting Rolling Logger")
+	return func() { rollingLogOutput.Close() }
+}
+
 func LavaFormatLog(description string, err error, attributes []Attribute, severity uint) error {
 	zerolog.TimeFieldFormat = zerolog.TimeFormatUnix
-	NoColor := true
-
 	if JsonFormat {
-		zerologlog.Logger = zerologlog.Output(os.Stderr)
+		zerologlog.Logger = zerologlog.Output(os.Stderr).Level(globalLogLevel)
 	} else {
-		zerologlog.Logger = zerologlog.Output(zerolog.ConsoleWriter{Out: os.Stderr, NoColor: NoColor, TimeFormat: time.Stamp})
+		zerologlog.Logger = zerologlog.Output(zerolog.ConsoleWriter{Out: os.Stderr, NoColor: NoColor, TimeFormat: time.Stamp}).Level(globalLogLevel)
 	}
 
 	var logEvent *zerolog.Event
+	var rollingLoggerEvent *zerolog.Event
 	switch severity {
 	case LAVA_LOG_PANIC:
 		// prefix = "Panic:"
 		logEvent = zerologlog.Panic()
+		rollingLoggerEvent = rollingLogLogger.Panic()
 	case LAVA_LOG_FATAL:
 		// prefix = "Fatal:"
 		logEvent = zerologlog.Fatal()
+		rollingLoggerEvent = rollingLogLogger.Fatal()
 	case LAVA_LOG_ERROR:
 		// prefix = "Error:"
 		logEvent = zerologlog.Error()
+		rollingLoggerEvent = rollingLogLogger.Error()
 	case LAVA_LOG_WARN:
 		// prefix = "Warning:"
 		logEvent = zerologlog.Warn()
+		rollingLoggerEvent = rollingLogLogger.Warn()
 	case LAVA_LOG_INFO:
 		logEvent = zerologlog.Info()
+		rollingLoggerEvent = rollingLogLogger.Info()
 		// prefix = "Info:"
 	case LAVA_LOG_DEBUG:
 		logEvent = zerologlog.Debug()
+		rollingLoggerEvent = rollingLogLogger.Debug()
 		// prefix = "Debug:"
 	}
 	output := description
 	attrStrings := []string{}
 	if err != nil {
 		logEvent = logEvent.Err(err)
+		rollingLoggerEvent = rollingLoggerEvent.Err(err)
 		output = fmt.Sprintf("%s ErrMsg: %s", output, err.Error())
 	}
 	if len(attributes) > 0 {
@@ -171,12 +235,14 @@ func LavaFormatLog(description string, err error, attributes []Attribute, severi
 				st_val = fmt.Sprintf("%+v", value)
 			}
 			logEvent = logEvent.Str(key, st_val)
+			rollingLoggerEvent = rollingLoggerEvent.Str(key, st_val)
 			attrStrings = append(attrStrings, fmt.Sprintf("%s:%s", attr.Key, st_val))
 		}
 		attributesStr := "{" + strings.Join(attrStrings, ",") + "}"
 		output = fmt.Sprintf("%s %+v", output, attributesStr)
 	}
 	logEvent.Msg(description)
+	rollingLoggerEvent.Msg(description)
 	// here we return the same type of the original error message, this handles nil case as well
 	errRet := sdkerrors.Wrap(err, output)
 	if errRet == nil { // we always want to return an error if lavaFormatError was called