GROUNDWORK-1502 Provide logger based on zerolog

Author: Pavlo Sumkin

config/config.go

@@ -14,8 +14,10 @@ import (
 	"sync"
 	"time"
 
-	"github.com/gwos/tcg/log"
+	"github.com/gwos/tcg/logger"
 	"github.com/kelseyhightower/envconfig"
+	"github.com/rs/zerolog"
+	"github.com/rs/zerolog/log"
 	"go.opentelemetry.io/otel/attribute"
 	"go.opentelemetry.io/otel/exporters/trace/jaeger"
 	"go.opentelemetry.io/otel/sdk/resource"
@@ -67,7 +69,7 @@ const (
 	InstallationModeS                        = "STANDALONE"
 )
 
-// LogLevel defines levels for logrus
+// LogLevel defines levels in logrus-style
 type LogLevel int
 
 // Enum levels
@@ -117,6 +119,8 @@ type Connector struct {
 	// If count is 0, old versions are removed rather than rotated.
 	LogFileRotate int      `yaml:"logFileRotate"`
 	LogLevel      LogLevel `yaml:"logLevel"`
+	LogNoColor    bool     `yaml:"logNoColor"`
+	LogTimeFormat string   `yaml:"logTimeFormat"`
 
 	// NatsAckWait is the time the NATS server will wait before resending a message
 	// Should be greater then the GWClient request duration
@@ -335,15 +339,17 @@ func defaults() Config {
 	return Config{
 		Connector: &Connector{
 			ControllerAddr:          ":8099",
-			ControllerReadTimeout:   time.Duration(time.Second * 10),
-			ControllerWriteTimeout:  time.Duration(time.Second * 20),
-			ControllerStartTimeout:  time.Duration(time.Second * 4),
-			ControllerStopTimeout:   time.Duration(time.Second * 4),
+			ControllerReadTimeout:   time.Second * 10,
+			ControllerWriteTimeout:  time.Second * 20,
+			ControllerStartTimeout:  time.Second * 4,
+			ControllerStopTimeout:   time.Second * 4,
 			LogCondense:             0,
 			LogFileMaxSize:          1024 * 1024 * 10, // 10MB
 			LogFileRotate:           5,
 			LogLevel:                1,
-			NatsAckWait:             time.Duration(time.Second * 30),
+			LogNoColor:              false,
+			LogTimeFormat:           time.RFC3339,
+			NatsAckWait:             time.Second * 30,
 			NatsMaxInflight:         1024,
 			NatsMaxPubAcksInflight:  1024,
 			NatsMaxPayload:          1024 * 1024 * 80, // 80MB
@@ -352,10 +358,10 @@ func defaults() Config {
 			NatsMonitorPort:         0,
 			NatsStoreDir:            "natsstore",
 			NatsStoreType:           "FILE",
-			NatsStoreMaxAge:         time.Duration(time.Hour * 24 * 10), // 10days
-			NatsStoreMaxBytes:       1024 * 1024 * 1024 * 50,            // 50GB
-			NatsStoreBufferSize:     1024 * 1024 * 2,                    // 2MB
-			NatsStoreReadBufferSize: 1024 * 1024 * 2,                    // 2MB
+			NatsStoreMaxAge:         time.Hour * 24 * 10,     // 10days
+			NatsStoreMaxBytes:       1024 * 1024 * 1024 * 50, // 50GB
+			NatsStoreBufferSize:     1024 * 1024 * 2,         // 2MB
+			NatsStoreReadBufferSize: 1024 * 1024 * 2,         // 2MB
 		},
 		DSConnection:  &DSConnection{},
 		Jaegertracing: &Jaegertracing{},
@@ -365,54 +371,54 @@ func defaults() Config {
 // GetConfig implements Singleton pattern
 func GetConfig() *Config {
 	once.Do(func() {
-		logBuf := make(map[string]interface{}, 3)
+		/* buffer the logging while configuring */
+		logBuf := &logger.LogBuffer{
+			Level: zerolog.TraceLevel,
+			Size:  16,
+		}
+		log.Logger = zerolog.New(logBuf).
+			With().Timestamp().Caller().Logger()
+		log.Info().Msgf("Build info: %s / %s", buildTag, buildTime)
+
 		c := defaults()
 		cfg = &c
-
 		if data, err := ioutil.ReadFile(cfg.configPath()); err != nil {
-			logBuf["ioutil.ReadFile"] = err
+			log.Warn().Err(err).
+				Str("configPath", cfg.configPath()).
+				Msg("could not read config")
 		} else {
 			if err := yaml.Unmarshal(data, cfg); err != nil {
-				logBuf["yaml.Unmarshal"] = err
+				log.Err(err).
+					Str("configPath", cfg.configPath()).
+					Msg("could not parse config")
 			}
 		}
-
 		if err := envconfig.Process(EnvConfigPrefix, cfg); err != nil {
-			logBuf["envconfig.Process"] = err
-		}
-
-		log.Config(
-			cfg.Connector.LogFile,
-			cfg.Connector.LogFileMaxSize,
-			cfg.Connector.LogFileRotate,
-			int(cfg.Connector.LogLevel),
-			cfg.Connector.LogCondense,
-		)
-		log.Info(fmt.Sprintf("Build info: %s / %s", buildTag, buildTime))
-		if len(logBuf) > 0 {
-			log.With(logBuf).Warn()
+			log.Err(err).
+				Str("EnvConfigPrefix", EnvConfigPrefix).
+				Msg("could not process config environment")
 		}
+		cfg.initLogger()
+		logger.WriteLogBuffer(logBuf)
 	})
 	return cfg
 }
 
 func (cfg Config) configPath() string {
 	configPath := os.Getenv(string(ConfigEnv))
 	if configPath == "" {
-		wd, err := os.Getwd()
-		if err != nil {
-			log.Warn(err)
-			wd = ""
+		configPath = ConfigName
+		if wd, err := os.Getwd(); err == nil {
+			configPath = path.Join(wd, ConfigName)
 		}
-		configPath = path.Join(wd, ConfigName)
 	}
 	return configPath
 }
 
 func (cfg *Config) loadConnector(data []byte) (*ConnectorDTO, error) {
 	var dto ConnectorDTO
 	if err := json.Unmarshal(data, &dto); err != nil {
-		log.Error("|config.go| : [loadConnector] : ", err.Error())
+		log.Err(err).Msg("could not parse connector")
 		return nil, err
 	}
 	cfg.Connector.AgentID = dto.AgentID
@@ -437,7 +443,7 @@ func (cfg *Config) loadAdvancedPrefixes(data []byte) error {
 		} `json:"advanced,omitempty"`
 	}
 	if err := json.Unmarshal(data, &s); err != nil {
-		log.Error("|config.go| : [loadAdvancedPrefixes] : ", err.Error())
+		log.Err(err).Msg("could not parse advanced")
 		return err
 	}
 	for _, c := range cfg.GWConnections {
@@ -484,10 +490,14 @@ func (cfg *Config) LoadConnectorDTO(data []byte) (*ConnectorDTO, error) {
 	newCfg := &c
 	/* load config file */
 	if data, err := ioutil.ReadFile(newCfg.configPath()); err != nil {
-		log.Warn(err)
+		log.Warn().Err(err).
+			Str("configPath", cfg.configPath()).
+			Msg("could not read config")
 	} else {
 		if err := yaml.Unmarshal(data, newCfg); err != nil {
-			log.Warn(err)
+			log.Warn().Err(err).
+				Str("configPath", newCfg.configPath()).
+				Msg("could not parse config")
 		}
 	}
 	/* load as ConnectorDTO */
@@ -505,15 +515,20 @@ func (cfg *Config) LoadConnectorDTO(data []byte) (*ConnectorDTO, error) {
 	}
 	/* override config file */
 	if output, err := yaml.Marshal(newCfg); err != nil {
-		log.Warn(err)
+		log.Err(err).
+			Msg("could not prepare config for writing")
 	} else {
 		if err := ioutil.WriteFile(newCfg.configPath(), output, 0644); err != nil {
-			log.Warn(err)
+			log.Err(err).
+				Str("configPath", newCfg.configPath()).
+				Msg("could not write config")
 		}
 	}
 	/* load environment */
 	if err := envconfig.Process(EnvConfigPrefix, newCfg); err != nil {
-		log.Warn(err)
+		log.Err(err).
+			Str("EnvConfigPrefix", EnvConfigPrefix).
+			Msg("could not process config environment")
 	}
 	/* process PMC */
 	if cfg.IsConfiguringPMC() {
@@ -526,13 +541,7 @@ func (cfg *Config) LoadConnectorDTO(data []byte) (*ConnectorDTO, error) {
 	cfg.GWConnections = newCfg.GWConnections
 
 	/* update logger */
-	log.Config(
-		cfg.Connector.LogFile,
-		cfg.Connector.LogFileMaxSize,
-		cfg.Connector.LogFileRotate,
-		int(cfg.Connector.LogLevel),
-		cfg.Connector.LogCondense,
-	)
+	cfg.initLogger()
 
 	return dto, nil
 }
@@ -593,13 +602,13 @@ func (cfg Config) initJaegertracing() (*sdktrace.TracerProvider, error) {
 				jaeger.WithAgentPort(port),
 			)
 		} else {
-			log.Warn(err)
+			log.Err(err).Msg("could not parse the JaegerAgent")
 			return nil, err
 		}
 	case len(tcgJaegerCollector) != 0:
 		endpointOption = jaeger.WithCollectorEndpoint(jaeger.WithEndpoint(tcgJaegerCollector))
 	default:
-		log.Debug(errNotConfigured)
+		log.Debug().Msg(errNotConfigured.Error())
 		return nil, errNotConfigured
 	}
 
@@ -614,7 +623,7 @@ func (cfg Config) initJaegertracing() (*sdktrace.TracerProvider, error) {
 
 	exporter, err := jaeger.NewRawExporter(endpointOption)
 	if err != nil {
-		log.Warn(err)
+		log.Err(err).Msg("could not create exporter")
 		return nil, err
 	}
 	tp := sdktrace.NewTracerProvider(
@@ -626,6 +635,24 @@ func (cfg Config) initJaegertracing() (*sdktrace.TracerProvider, error) {
 	return tp, nil
 }
 
+func (cfg Config) initLogger() {
+	opts := []logger.Option{
+		logger.WithCondense(cfg.Connector.LogCondense),
+		logger.WithLastErrors(10),
+		logger.WithLevel([...]zerolog.Level{3, 2, 1, 0}[cfg.Connector.LogLevel]),
+		logger.WithNoColor(cfg.Connector.LogNoColor),
+		logger.WithTimeFormat(cfg.Connector.LogTimeFormat),
+	}
+	if cfg.Connector.LogFile != "" {
+		opts = append(opts, logger.WithLogFile(&logger.LogFile{
+			FilePath: cfg.Connector.LogFile,
+			MaxSize:  cfg.Connector.LogFileMaxSize,
+			Rotate:   cfg.Connector.LogFileRotate,
+		}))
+	}
+	logger.SetLogger(opts...)
+}
+
 // Decrypt decrypts small messages
 // golang.org/x/crypto/nacl/secretbox
 func Decrypt(message, secret []byte) ([]byte, error) {

go.mod

@@ -35,6 +35,7 @@ require (
 	github.com/prometheus/common v0.29.0
 	github.com/prometheus/prometheus v2.5.0+incompatible
 	github.com/robfig/cron/v3 v3.0.1
+	github.com/rs/zerolog v1.23.0
 	github.com/shirou/gopsutil v3.21.5+incompatible
 	github.com/sirupsen/logrus v1.8.1
 	github.com/stretchr/testify v1.7.0

go.sum

@@ -83,6 +83,7 @@ github.com/circonus-labs/circonus-gometrics v2.3.1+incompatible/go.mod h1:nmEj6D
 github.com/circonus-labs/circonusllhist v0.1.3/go.mod h1:kMXHVDlOchFAehlya5ePtbp5jckzBHf4XRpQvBOLI+I=
 github.com/client9/misspell v0.3.4/go.mod h1:qj6jICC3Q7zFZvVWo7KLAzC3yx5G7kyvSDkc90ppPyw=
 github.com/cncf/udpa/go v0.0.0-20191209042840-269d4d468f6f/go.mod h1:M8M6+tZqaGXZJjfX53e64911xZQV5JYwmTeXPW+k8Sc=
+github.com/coreos/go-systemd/v22 v22.3.2/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc=
 github.com/cpuguy83/go-md2man/v2 v2.0.0-20190314233015-f79a8a8ca69d/go.mod h1:maD7wRr/U5Z6m/iR4s+kqSMx2CaBsrgA7czyZG/E6dU=
 github.com/creack/pty v1.1.9/go.mod h1:oKZEueFk5CKHvIhNR5MUki03XCEU+Q6VDXinZuGJ33E=
 github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
@@ -167,6 +168,7 @@ github.com/go-playground/validator/v10 v10.4.1/go.mod h1:nlOn6nFhuKACm19sB/8EGNn
 github.com/go-sql-driver/mysql v1.6.0 h1:BCTh4TKNUYmOmMUcQ3IipzF5prigylS7XXjEkfCHuOE=
 github.com/go-sql-driver/mysql v1.6.0/go.mod h1:DCzpHaOWr8IXmIStZouvnhqoel9Qv2LBy8hT2VhHyBg=
 github.com/go-stack/stack v1.8.0/go.mod h1:v0f6uXyyMGvRgIKkXu+yp6POWl0qKG85gN/melR3HDY=
+github.com/godbus/dbus/v5 v5.0.4/go.mod h1:xhWf0FNVPg57R7Z0UbKHbJfkEywrmjJnf7w5xrFpKfA=
 github.com/gogo/protobuf v1.1.1/go.mod h1:r8qH/GZQm5c6nD/R0oafs1akxWv10x8SbQlK7atdtwQ=
 github.com/gogo/protobuf v1.3.2 h1:Ov1cvc58UF3b5XjBnZv7+opcTcQFZebYjWzi34vdm4Q=
 github.com/gogo/protobuf v1.3.2/go.mod h1:P1XiOD3dCwIKUDQYPy72D8LYyHL2YPYrpS2s69NZV8Q=
@@ -401,6 +403,9 @@ github.com/robfig/cron/v3 v3.0.1 h1:WdRxkvbJztn8LMz/QEvLN5sBU+xKpSqwwUO1Pjr4qDs=
 github.com/robfig/cron/v3 v3.0.1/go.mod h1:eQICP3HwyT7UooqI/z+Ov+PtYAWygg1TEWWzGIFLtro=
 github.com/rogpeppe/fastuuid v1.2.0/go.mod h1:jVj6XXZzXRy/MSR5jhDC/2q6DgLz+nrA6LYCDYWNEvQ=
 github.com/rogpeppe/go-internal v1.3.0/go.mod h1:M8bDsm7K2OlrFYOpmOWEs/qY81heoFRclV5y23lUDJ4=
+github.com/rs/xid v1.2.1/go.mod h1:+uKXf+4Djp6Md1KODXJxgGQPKngRmWyn10oCKFzNHOQ=
+github.com/rs/zerolog v1.23.0 h1:UskrK+saS9P9Y789yNNulYKdARjPZuS35B8gJF2x60g=
+github.com/rs/zerolog v1.23.0/go.mod h1:6c7hFfxPOy7TacJc4Fcdi24/J0NKYGzjG8FWRI916Qo=
 github.com/russross/blackfriday/v2 v2.0.1/go.mod h1:+Rmxgy9KzJVeS9/2gXHxylqXiyQDYRxCVz55jmeOWTM=
 github.com/shirou/gopsutil v3.21.5+incompatible h1:OloQyEerMi7JUrXiNzy8wQ5XN+baemxSl12QgIzt0jc=
 github.com/shirou/gopsutil v3.21.5+incompatible/go.mod h1:5b4v6he4MtMOwMlS0TUMTu2PcXUg8+E1lC7eC3UO/RA=

logger/logfile.go

@@ -0,0 +1,74 @@
+package logger
+
+import (
+	"fmt"
+	"os"
+	"sync"
+)
+
+// LogFile provides file rotation
+type LogFile struct {
+	mu       sync.Mutex
+	file     *os.File
+	fileSize int64
+
+	FilePath string
+	MaxSize  int64
+	Rotate   int
+}
+
+// Close implements io.Closer interface
+func (f *LogFile) Close() error {
+	return f.file.Close()
+}
+
+// Write implements io.Writer interface
+func (f *LogFile) Write(p []byte) (int, error) {
+	f.mu.Lock()
+	defer f.mu.Unlock()
+
+	if f.file == nil {
+		f.open()
+	}
+	if f.file != nil &&
+		(f.MaxSize > 0 && f.MaxSize < f.fileSize+int64(len(p))) {
+		f.rotate()
+	}
+
+	n, err := f.file.Write(p)
+	if err != nil {
+		f.open()
+		n, err = f.file.Write(p)
+	}
+	if err == nil {
+		f.fileSize += int64(n)
+	}
+	return n, err
+}
+
+func (f *LogFile) open() {
+	if f.file != nil {
+		_ = f.file.Close()
+	}
+	if file, err := os.OpenFile(f.FilePath,
+		os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0644); err == nil {
+		f.file = file
+		if fileInfo, err := file.Stat(); err == nil {
+			f.fileSize = fileInfo.Size()
+		}
+	}
+}
+
+func (f *LogFile) rotate() {
+	filename := f.file.Name()
+	_ = f.file.Close()
+	if f.Rotate == 0 {
+		_ = os.Remove(filename)
+	} else {
+		for i := f.Rotate; i > 0; i-- {
+			_ = os.Rename(fmt.Sprintf("%s.%d", filename, i-1), fmt.Sprintf("%s.%d", filename, i))
+		}
+		_ = os.Rename(filename, fmt.Sprintf("%s.%d", filename, 1))
+	}
+	f.open()
+}