From f526f8cfcea7e8aa0345eae97c6c6bd02e03c5ca Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ra=C3=BAl=20S=C3=A1nchez?= Date: Thu, 31 Oct 2024 17:53:06 +0100 Subject: [PATCH] Update logger to facilitate the use of global logger (#150) * Update logger to facilitate the use of global logger * Fix demo-cli typo * Fix linter errors * Using global log at pkg metrics and runner * Update CI for deprectaed steps * Removing already fixed fixme comment * Updated logger README.md using ia * Fix logger README.md --- .github/workflows/checks.golang.yml | 2 +- Makefile | 6 ++ cmd/demo-cli/main.go | 1 + pkg/cli/config.go | 7 +- pkg/cli/handlers.go | 6 +- pkg/cli/root.go | 23 ++-- pkg/logger/README.md | 162 ++++++++++++++++++++++++++++ pkg/logger/global.go | 88 +++++++++++++++ pkg/logger/logger.go | 65 +++-------- pkg/logger/methods.go | 2 +- pkg/metrics/prometheus.go | 12 +-- pkg/metrics/service_metrics.go | 15 ++- pkg/runner/runner.go | 9 +- 13 files changed, 311 insertions(+), 87 deletions(-) create mode 100644 pkg/logger/README.md create mode 100644 pkg/logger/global.go diff --git a/.github/workflows/checks.golang.yml b/.github/workflows/checks.golang.yml index f86019d..7912205 100644 --- a/.github/workflows/checks.golang.yml +++ b/.github/workflows/checks.golang.yml @@ -14,7 +14,7 @@ jobs: runs-on: ubuntu-latest steps: - name: Checkout - uses: actions/checkout@v3 + uses: actions/checkout@v4 with: submodules: true - uses: actions/setup-go@v3 diff --git a/Makefile b/Makefile index e66170d..a958500 100644 --- a/Makefile +++ b/Makefile @@ -47,6 +47,12 @@ check-modtidy: go mod tidy git diff --exit-code -- go.mod go.sum +fmt: + gofmt -l -s -w . + +vet: + go vet ./... + lint: golangci-lint --version golangci-lint run diff --git a/cmd/demo-cli/main.go b/cmd/demo-cli/main.go index 552e249..2006e68 100644 --- a/cmd/demo-cli/main.go +++ b/cmd/demo-cli/main.go @@ -13,6 +13,7 @@ func main() { EnvPrefix: "golem", GitVersion: version.GitVersion, GitRevision: version.GitRevision, + LogLevel: "debug", } // Define application level features diff --git a/pkg/cli/config.go b/pkg/cli/config.go index f033443..45b1238 100644 --- a/pkg/cli/config.go +++ b/pkg/cli/config.go @@ -1,7 +1,6 @@ package cli import ( - "context" "fmt" "github.com/zondax/golem/pkg/logger" "strings" @@ -15,7 +14,7 @@ func SetupConfiguration(c *cobra.Command) { c.PersistentFlags().StringVarP(&configFileFlag, "config", "c", "", "The path to the config file to use.") err := viper.BindPFlag("config", c.PersistentFlags().Lookup("config")) if err != nil { - logger.GetLoggerFromContext(context.Background()).Fatalf("unable to bind config flag: %+v", err) + logger.Fatalf("unable to bind config flag: %+v", err) } viper.SetConfigName("config") // config file name without extension @@ -50,12 +49,12 @@ func LoadConfig[T Config]() (*T, error) { configFileOverride := viper.GetString("config") if configFileOverride != "" { viper.SetConfigFile(configFileOverride) - logger.GetLoggerFromContext(context.Background()).Infof("Using config file: %s", viper.ConfigFileUsed()) + logger.Infof("Using config file: %s", viper.ConfigFileUsed()) } err = viper.ReadInConfig() if err != nil { - logger.GetLoggerFromContext(context.Background()).Fatalf("%+v", err) + logger.Fatalf("%+v", err) } // adds all default+configFile values in viper to struct diff --git a/pkg/cli/handlers.go b/pkg/cli/handlers.go index e150a81..9563038 100644 --- a/pkg/cli/handlers.go +++ b/pkg/cli/handlers.go @@ -1,11 +1,11 @@ package cli import ( - "context" - "github.com/zondax/golem/pkg/logger" "os" "os/signal" "syscall" + + "github.com/zondax/golem/pkg/logger" ) var defaultConfigHandler DefaultConfigHandler @@ -15,7 +15,7 @@ func setupCloseHandler(handler CleanUpHandler) { signal.Notify(c, os.Interrupt, syscall.SIGTERM) go func() { <-c - logger.GetLoggerFromContext(context.Background()).Warn("\r- Ctrl+C pressed in Terminal") + logger.Warn("\r- Ctrl+C pressed in Terminal") if handler != nil { handler() diff --git a/pkg/cli/root.go b/pkg/cli/root.go index 9a34b25..1a77710 100644 --- a/pkg/cli/root.go +++ b/pkg/cli/root.go @@ -2,11 +2,11 @@ package cli import ( "fmt" + "os" + "github.com/spf13/cobra" "github.com/spf13/viper" - "github.com/zondax/golem/pkg/constants" "github.com/zondax/golem/pkg/logger" - "os" ) type AppSettings struct { @@ -16,6 +16,7 @@ type AppSettings struct { EnvPrefix string // environment variable MYAPP_..... GitVersion string GitRevision string + LogLevel string // Global log level for the app } type CLI struct { @@ -50,9 +51,9 @@ func (c *CLI) init() { Run: func(cmd *cobra.Command, args []string) { err := c.checkConfig() if err != nil { - fmt.Printf("%s\n", c.checkConfig().Error()) + logger.Errorf("%s\n", c.checkConfig().Error()) } else { - fmt.Printf("Configuration OK\n") + logger.Infof("Configuration OK\n") } }, } @@ -61,15 +62,18 @@ func (c *CLI) init() { Use: "version", Short: "Print version", Run: func(cmd *cobra.Command, args []string) { - fmt.Printf("%s\n", c.GetVersionString()) + logger.Infof("%s\n", c.GetVersionString()) }, } c.GetRoot().AddCommand(checkCmd) c.GetRoot().AddCommand(versionCmd) - // TODO: We can make this optional? and more configurable if we see the need - logger.InitLogger(logger.Config{Level: constants.DebugLevel}) + // If app log level is defined it is configued, logger.defaultConfig by default + if len(c.app.LogLevel) > 0 { + logger.InitLogger(logger.Config{Level: c.app.LogLevel}) + } + setupCloseHandler(nil) // Set Configuration Defaults setupDefaultConfiguration(func() { @@ -91,10 +95,7 @@ func (c *CLI) GetVersionString() string { func (c *CLI) Run() { if err := c.rootCmd.Execute(); err != nil { - _, err := fmt.Fprintln(os.Stderr, err) - if err != nil { - return - } + logger.Error(err.Error()) _ = logger.Sync() os.Exit(1) } diff --git a/pkg/logger/README.md b/pkg/logger/README.md new file mode 100644 index 0000000..5693f81 --- /dev/null +++ b/pkg/logger/README.md @@ -0,0 +1,162 @@ +# Logger Package + +A structured logging package built on top of [uber-go/zap](https://github.com/uber-go/zap), providing both global and context-aware logging capabilities with sensible defaults. + +## Features + +- Built on top of the high-performance zap logger +- Supports both structured and printf-style logging +- Context-aware logging +- Global and instance-based logging +- Configurable log levels and encoding formats +- Request ID tracking support +- Easy integration with existing applications + +## Installation + +```go +go get -u github.com/zondax/golem/pkg/logger +``` + +## Quick Start + +```go +// Initialize with default configuration +logger.InitLogger(logger.Config{ + Level: "info", + Encoding: "json", +}) + +// Basic logging +logger.Info("Server started") +logger.Error("Connection failed") + +// Structured logging with fields +log := logger.NewLogger( + logger.Field{Key: "service", Value: "api"}, + logger.Field{Key: "version", Value: "1.0.0"}, +) +log.Info("Service initialized") +``` + +## Configuration + +### Logger Config + +```go +type Config struct { + Level string `json:"level"` // Logging level + Encoding string `json:"encoding"` // Output format +} +``` + +### Log Levels + +Available log levels (in order of increasing severity): +- `debug`: Detailed information for debugging +- `info`: General operational information +- `warn`: Warning messages for potentially harmful situations +- `error`: Error conditions that should be addressed +- `dpanic`: Critical errors in development that cause panic +- `panic`: Critical errors that cause panic in production +- `fatal`: Fatal errors that terminate the program + +### Encoding Formats + +1. **JSON Format** (Default) + - Recommended for production + - Machine-readable structured output + ```json + {"level":"INFO","ts":"2024-03-20T10:00:00.000Z","msg":"Server started","service":"api"} + ``` + +2. **Console Format** + - Recommended for development + - Human-readable output + ``` + 2024-03-20T10:00:00.000Z INFO Server started service=api + ``` + +## Advanced Usage + +### Context-Aware Logging + +```go +// Create a context with logger +ctx := context.Background() +log := logger.NewLogger(logger.Field{ + Key: logger.RequestIDKey, + Value: "req-123", +}) +ctx = logger.ContextWithLogger(ctx, log) + +// Get logger from context +contextLogger := logger.GetLoggerFromContext(ctx) +contextLogger.Info("Processing request") +``` + +### Structured Logging with Fields + +```go +log := logger.NewLogger() +log.WithFields( + zap.String("user_id", "12345"), + zap.String("action", "login"), + zap.Int("attempt", 1), +).Info("User login attempt") +``` + +### Printf-Style Logging + +```go +logger.Infof("Processing item %d of %d", current, total) +logger.Errorf("Failed to connect to %s: %v", host, err) +``` + +## Best Practices + +1. **Use Structured Logging** + ```go + // Good + log.WithFields( + zap.String("user_id", "12345"), + zap.String("action", "purchase"), + zap.Float64("amount", 99.99), + ).Info("Purchase completed") + + // Avoid + log.Infof("User %s completed purchase of $%.2f", userID, amount) + ``` + +2. **Include Request IDs** + ```go + log.WithFields( + zap.String(logger.RequestIDKey, requestID), + ).Info("Handling request") + ``` + +3. **Proper Error Logging** + ```go + if err != nil { + log.WithFields( + zap.Error(err), + zap.String("operation", "database_query"), + ).Error("Query failed") + } + ``` + +4. **Resource Cleanup** + ```go + defer logger.Sync() + ``` + +## Performance Considerations + +- The logger is designed to be zero-allocation in most cases +- JSON encoding is more CPU-intensive but provides structured data +- Log level checks are performed atomically +- Field allocation is optimized for minimal overhead + +## Thread Safety + +The logger is completely thread-safe and can be used concurrently from multiple goroutines. diff --git a/pkg/logger/global.go b/pkg/logger/global.go new file mode 100644 index 0000000..573cc9b --- /dev/null +++ b/pkg/logger/global.go @@ -0,0 +1,88 @@ +package logger + +import ( + "go.uber.org/zap" +) + +func ReplaceGlobals(logger *zap.Logger) func() { + return zap.ReplaceGlobals(logger) +} + +func SetGlobalConfig(config Config) func() { + logger := configureAndBuildLogger(config) + return ReplaceGlobals(logger) +} + +func L() *zap.Logger { + return zap.L() +} + +func S() *zap.SugaredLogger { + return zap.S() +} + +func Info(msg string) { + L().Info(msg) +} + +func Debug(msg string) { + L().Debug(msg) +} + +func Warn(msg string) { + L().Warn(msg) +} + +func Error(msg string) { + L().Error(msg) +} + +func DPanic(msg string) { + L().DPanic(msg) +} + +func Panic(msg string) { + L().Panic(msg) +} + +func Fatal(msg string) { + L().Fatal(msg) +} + +func Infof(template string, args ...interface{}) { + S().Infof(template, args...) +} + +func Debugf(template string, args ...interface{}) { + S().Debugf(template, args...) +} + +func Warnf(template string, args ...interface{}) { + S().Warnf(template, args...) +} + +func Errorf(template string, args ...interface{}) { + S().Errorf(template, args...) +} + +func DPanicf(template string, args ...interface{}) { + S().DPanicf(template, args...) +} + +func Panicf(template string, args ...interface{}) { + S().Panicf(template, args...) +} + +func Fatalf(template string, args ...interface{}) { + S().Fatalf(template, args...) +} + +func Sync() error { + // Sync global logger + err := L().Sync() + if err != nil { + return err + } + // Sync global sugar logger + return S().Sync() +} diff --git a/pkg/logger/logger.go b/pkg/logger/logger.go index 66d7494..f56062b 100644 --- a/pkg/logger/logger.go +++ b/pkg/logger/logger.go @@ -1,10 +1,10 @@ package logger import ( + "strings" + "go.uber.org/zap" "go.uber.org/zap/zapcore" - "strings" - "sync" ) const ( @@ -14,10 +14,10 @@ const ( var ( defaultConfig = Config{ - Level: "info", + Level: "info", + Encoding: "json", } - baseLogger *zap.Logger - lock sync.RWMutex + defaultOptions = []zap.Option{zap.AddCallerSkip(1), zap.AddStacktrace(zapcore.ErrorLevel)} ) type Config struct { @@ -34,49 +34,35 @@ type Logger struct { logger *zap.Logger } -var stringToLevel = map[string]zapcore.Level{ - "debug": zapcore.DebugLevel, - "info": zapcore.InfoLevel, - "warn": zapcore.WarnLevel, - "error": zapcore.ErrorLevel, - "fatal": zapcore.FatalLevel, - "panic": zapcore.PanicLevel, +func init() { + InitLogger(defaultConfig) } func InitLogger(config Config) { - lock.Lock() - defer lock.Unlock() - - baseLogger = configureAndBuildLogger(config) + baseLogger := configureAndBuildLogger(config) zap.ReplaceGlobals(baseLogger) } func NewLogger(opts ...interface{}) *Logger { - lock.Lock() - defer lock.Unlock() - var config *Config - var fields []Field + var zapFields []zap.Field for _, opt := range opts { switch opt := opt.(type) { case Config: config = &opt case Field: - fields = append(fields, opt) + zapFields = append(zapFields, zap.Any(opt.Key, opt.Value)) } } - logger := configureAndBuildLogger(defaultConfig) - if baseLogger != nil { - logger = baseLogger.WithOptions(zap.AddCallerSkip(1)) - } + logger := L().WithOptions(defaultOptions...) if config != nil { logger = configureAndBuildLogger(*config) } - logger = logger.With(toZapFields(fields)...) + logger = logger.With(zapFields...) return &Logger{logger: logger} } @@ -91,35 +77,16 @@ func configureAndBuildLogger(config Config) *zap.Logger { encoderConfig.EncodeLevel = zapcore.CapitalLevelEncoder cfg.EncoderConfig = encoderConfig - level := zapcore.InfoLevel - if l, ok := stringToLevel[strings.ToLower(config.Level)]; ok { - level = l + level, err := zapcore.ParseLevel(strings.ToLower(config.Level)) + if err != nil { + level = zapcore.InfoLevel } cfg.Level = zap.NewAtomicLevelAt(level) - logger, err := cfg.Build(zap.AddCallerSkip(1), zap.AddStacktrace(zapcore.ErrorLevel)) + logger, err := cfg.Build(defaultOptions...) if err != nil { panic(initializingLogError + err.Error()) } return logger } - -func Sync() error { - lock.Lock() - defer lock.Unlock() - - return baseLogger.Sync() -} - -func DefaultConfig() Config { - return defaultConfig -} - -func toZapFields(fields []Field) []zap.Field { - var zapFields []zap.Field - for _, field := range fields { - zapFields = append(zapFields, zap.Any(field.Key, field.Value)) - } - return zapFields -} diff --git a/pkg/logger/methods.go b/pkg/logger/methods.go index c2064ed..0ae518e 100644 --- a/pkg/logger/methods.go +++ b/pkg/logger/methods.go @@ -71,7 +71,7 @@ func (l *Logger) WithFields(fields ...zap.Field) *Logger { } func (l *Logger) IsDebugEnabled() bool { - return baseLogger.Core().Enabled(zap.DebugLevel) + return l.logger.Core().Enabled(zap.DebugLevel) } func GetLoggerFromContext(ctx context.Context) *Logger { diff --git a/pkg/metrics/prometheus.go b/pkg/metrics/prometheus.go index ec28fbe..2ef4b2f 100644 --- a/pkg/metrics/prometheus.go +++ b/pkg/metrics/prometheus.go @@ -1,7 +1,6 @@ package metrics import ( - "context" "fmt" "github.com/go-chi/chi/v5" "github.com/prometheus/client_golang/prometheus" @@ -64,7 +63,7 @@ func (t *taskMetrics) AppName() string { func (t *taskMetrics) Start() error { router := chi.NewRouter() - logger.GetLoggerFromContext(context.Background()).Infof("Metrics (prometheus) starting: %v", t.port) + logger.Infof("Metrics (prometheus) starting: %v", t.port) // Prometheus path router.Get(t.path, promhttp.Handler().(http.HandlerFunc)) @@ -77,12 +76,13 @@ func (t *taskMetrics) Start() error { err := server.ListenAndServe() if err != nil { - logger.GetLoggerFromContext(context.Background()).Errorf("Prometheus server error: %v", err) - } else { - logger.GetLoggerFromContext(context.Background()).Errorf("Prometheus server serving at port %s", t.port) + logger.Errorf("Prometheus server error: %v", err) + return err } - return err + logger.Infof("Prometheus server serving at port %s", t.port) + + return nil } func (t *taskMetrics) Stop() error { diff --git a/pkg/metrics/service_metrics.go b/pkg/metrics/service_metrics.go index 8ca0265..48c2007 100644 --- a/pkg/metrics/service_metrics.go +++ b/pkg/metrics/service_metrics.go @@ -1,7 +1,6 @@ package metrics import ( - "context" "github.com/shirou/gopsutil/cpu" "github.com/shirou/gopsutil/net" "github.com/zondax/golem/pkg/logger" @@ -46,34 +45,34 @@ func UpdateSystemMetrics(metricsServer TaskMetrics, updateInterval time.Duration var m runtime.MemStats runtime.ReadMemStats(&m) if err := metricsServer.UpdateMetric(memoryUsageBytes, float64(m.Alloc)); err != nil { - logger.GetLoggerFromContext(context.Background()).Errorf("error updating %v: %v", memoryUsageBytes, err) + logger.Errorf("error updating %v: %v", memoryUsageBytes, err) } cpuPercents, _ := cpu.Percent(time.Second, false) if err := metricsServer.UpdateMetric(cpuUsagePercent, cpuPercents[0]); err != nil { - logger.GetLoggerFromContext(context.Background()).Errorf("error updating %v: %v", cpuUsagePercent, err) + logger.Errorf("error updating %v: %v", cpuUsagePercent, err) } netIO, _ := net.IOCounters(false) if err := metricsServer.UpdateMetric(bytesSent, float64(netIO[0].BytesSent)); err != nil { - logger.GetLoggerFromContext(context.Background()).Errorf("error updating %v: %v", bytesSent, err) + logger.Errorf("error updating %v: %v", bytesSent, err) } if err := metricsServer.UpdateMetric(bytesReceived, float64(netIO[0].BytesRecv)); err != nil { - logger.GetLoggerFromContext(context.Background()).Errorf("error updating %v: %v", bytesReceived, err) + logger.Errorf("error updating %v: %v", bytesReceived, err) } conns, _ := net.Connections("all") if err := metricsServer.UpdateMetric(activeConnections, float64(len(conns))); err != nil { - logger.GetLoggerFromContext(context.Background()).Errorf("error updating %v: %v", activeConnections, err) + logger.Errorf("error updating %v: %v", activeConnections, err) } if err := metricsServer.UpdateMetric(goroutinesCount, float64(runtime.NumGoroutine())); err != nil { - logger.GetLoggerFromContext(context.Background()).Errorf("error updating %v: %v", goroutinesCount, err) + logger.Errorf("error updating %v: %v", goroutinesCount, err) } threads := pprof.Lookup("threadcreate").Count() if err := metricsServer.UpdateMetric(threadsCount, float64(threads)); err != nil { - logger.GetLoggerFromContext(context.Background()).Errorf("error updating %v: %v", threadsCount, err) + logger.Errorf("error updating %v: %v", threadsCount, err) } time.Sleep(updateInterval) diff --git a/pkg/runner/runner.go b/pkg/runner/runner.go index 76b7f7b..7bc73e9 100644 --- a/pkg/runner/runner.go +++ b/pkg/runner/runner.go @@ -3,11 +3,13 @@ package runner import ( "context" "fmt" - "golang.org/x/sync/errgroup" "os" "os/signal" "syscall" "time" + + "github.com/zondax/golem/pkg/logger" + "golang.org/x/sync/errgroup" ) type Task interface { @@ -60,8 +62,7 @@ func (tr *TaskRunner) sendError(te TaskError) { case tr.errCh <- te: break default: - // FIXME: log error at least? Nobody is registered to receive errors - fmt.Printf("No receiver ready! error not sent! %s\n", te.Err.Error()) + logger.Errorf("No receiver ready! error not sent! %s\n", te.Err.Error()) } } @@ -105,7 +106,7 @@ func (tr *TaskRunner) StartAndWait() { tr.Start() err := tr.Wait() if err != nil { - fmt.Println("Error waiting for tasks to finish: ", err) + logger.Errorf("Waiting for tasks to finish: ", err) } }