[pkg] zap logger

uber-go/zap @ github

資料來源

:thumbsup: A Comprehensive Guide to Zap Logging in Go @ Better Stack

slog

在 Go v1.21 之後，官方有出自己的 logger packge，稱作 log/slog，可以參考 Logging in Go with Slog: The Ultimate Guide。關於不同 logger 的比較則可以參考 Logging in Go: A Comparison of the Top 9 Libraries。

TL;DR

• 如果希望輸出的 log 都能添加特定的資料，可以考慮用 [Custom Logger](#custom logger) 或 [Child Loggers](#Child Loggers)

// 2024-05-31T12:59:08.936+0800    INFO    logger/logger.go:71
// User information  {"username": "aaron.chen", "age": 35, "is_adult": true}
logger.Info("User information",
  zap.String("username", "aaron.chen"),
  zap.Int("age", 35),
  zap.Bool("is_adult", true)
)

// 使用 zap.Error()
logger.Error("Failed to perform an operation",
  zap.String("operation", "someOperation"),
  zap.Error(errors.New("something happened")),
  zap.Int("retryAttempts", 3),
  zap.String("user", "john.doe"),
)

// 這會在 object 中產生 key, value 的 pair
zap.String([key], [value])
zap.Int([key], [value])
zap.Any([key], [value])
zap.Error([key], errors.New([value]))

// 使用 w 的話，如果有帶 key 一定要帶 value，否則會噴錯
// 因此可能的話，還是建議用 Fields
sugar.Infow([msg], [key], [value])
sugar.Infow("This is msg:", zap.String("key", "value"))

Logger

Default Logger

• logger 後面帶入的資料需要定義清楚的型別，稱作 Field，例如使用 zap.String()、zap.Int()
• 如果使用的是 zap.NewDevelopment()，會輸出到 DEBUG level 的訊息，而且會以比較友善的方式呈現
• 如果使用的是 zap.NewProduction() 只會輸出到 INFO level 的訊息

func PlayZapLogger() {
 logger := zap.Must(zap.NewDevelopment())

 defer logger.Sync()

 logger.Debug("this is a debug message")
 // User logged in  {"username": "john doe", "userid": 123456, "provider": "google"
 logger.Info("User logged in", zap.String("username", "john doe"), zap.Int("userid", 123456), zap.String("provider", "google"))
 logger.Warn("notice")
 logger.Error("this is an error")
}

SugaredLogger

和 Logger 相比，SugaredLogger 的效能較差一些，但是能夠接受的資料比較寬容，不用清楚知道資料的型別是什麼。

使用 logger.Sugar() 即可取得 SugaredLogger；如果有需要把 SugaredLogger 再轉換會 Logger 的話，則可以使用 SugaredLogger.Desugar()：

func PlaySugarLogger() {
 logger := zap.Must(zap.NewDevelopment())

 defer logger.Sync()

 sugar := logger.Sugar()
 sugar.Debug("this is a debug message")
 sugar.Info("User logged in", zap.String("username", "john doe"), zap.Int("userid", 123456), zap.String("provider", "google"))
 sugar.Warn("notice")
 sugar.Error("this is an error")
}

另外，它也提供了像是 sugar.Infoln()、sugar.Infof()、sugar.Infow() 等不同的方法：

• sugar.Info() 可以接受 any 作為它的參數，它背後使用的是 fmt.Sprintf() 來把所有參數連結成一個 msg
• 使用 sugar.Infow() 的話，要跟著下面的準則，否則會噴錯：
  • 如果有帶 key 一定要帶 value，否則會噴錯（orphaned key）
  • key 需要是 string，value 則可以是 any（loosely-typed key/value pairs）

func PlaySugarLogger() {
 logger := zap.Must(zap.NewDevelopment())

 defer logger.Sync()

 sugar := logger.Sugar()

 sugar.Info("Hello Zap Sugar")
 sugar.Infof("The current time is %s", time.Now().Format("03:04 AM"))

  // 相似於 fmt.Sprintln()
 sugar.Infoln(
  "Log data with line break.",
 )

  // 使用 w 的話，如果有帶 key 一定要帶 value，否則會噴錯
 sugar.Infow("this is message", "key", "value")
  sugar.Infow("User logged in",
  "username", "john doe",
  "userid", 123456,
  zap.String("provider", "google"),
 )
}

Log levels

// ~/go/pkg/mod/go.uber.org/zap@v1.27.0/level.go
const (
 // DebugLevel logs are typically voluminous, and are usually disabled in
 // production.
 DebugLevel = zapcore.DebugLevel
 // InfoLevel is the default logging priority.
 InfoLevel = zapcore.InfoLevel
 // WarnLevel logs are more important than Info, but don't need individual
 // human review.
 WarnLevel = zapcore.WarnLevel
 // ErrorLevel logs are high-priority. If an application is running smoothly,
 // it shouldn't generate any error-level logs.
 ErrorLevel = zapcore.ErrorLevel
 // DPanicLevel logs are particularly important errors. In development the
 // logger panics after writing the message.
 DPanicLevel = zapcore.DPanicLevel
 // PanicLevel logs a message, then panics.
 PanicLevel = zapcore.PanicLevel
 // FatalLevel logs a message, then calls os.Exit(1).
 FatalLevel = zapcore.FatalLevel
)

• Error / Warn：Error() 和 Warn() level 都會輸出程式執行的 trace，但程式會繼續往下執行
• Fatal：使用 Fatal() 的話，在寫完 log message 後，會呼叫 os.Exit(1)，程式會直接終止
• Panic / DPanic
  • 如果錯誤是可以被復原的，則應該使用 Panic()，在寫完 log message 後，它會呼叫 Panic() 而不是 os.Exit(1)。
  • DPanic 則是 panics in development，它會輸出在 DPanicLevel Level，當在 development 環境下，它會呼叫 Panic()；但在 production 環境下，則只會寫 log 而不會呼叫 Panic()
  • 如果你不希望在 log 中出現像是 Panic 或 DPanic 這兩種非標準的 Level，可以參考這裡的說明 Logging Errors with Zap，把 Panic 和 DPanic 轉換成 Error Level

logger.Debug()
logger.Info()
logger.Warn()
logger.Error()
logger.Fatal()
logger.Panic()

sugar.Info()
sugar.Infoln()
sugar.Infof()

Example Code for Logging Errors

logger := zap.Must(zap.NewDevelopment())
defer logger.Sync()

logger.Error("Failed to perform an operation",
  zap.String("operation", "someOperation"),
  zap.Error(errors.New("something happened")),
  zap.Int("retryAttempts", 3),
  zap.String("user", "john.doe"),
)

logger.Fatal("Something went terribly wrong",
    zap.String("context", "main"),
    zap.Int("code", 500),
    zap.Error(errors.New("An error occurred")),
)

Custom Logger

// Source: https://betterstack.com/community/guides/logging/go/zap/

func CreateLogger() *zap.Logger {
 encoderCfg := zap.NewProductionEncoderConfig()

 // 原本 Time '"ts":1717129469.807809' 來顯示
 // 改成用 '"timestamp":"2024-05-31T12:25:29.299+0800"' 顯示
 encoderCfg.TimeKey = "timestamp"
 encoderCfg.EncodeTime = zapcore.ISO8601TimeEncoder

 config := zap.Config{
  Level:             zap.NewAtomicLevelAt(zap.InfoLevel),
  Development:       false,
  DisableCaller:     false,
  DisableStacktrace: false,
  Sampling:          nil,
  Encoding:          "json",
  EncoderConfig:     encoderCfg,

  // logging output 的地方
  OutputPaths: []string{"stderr"},

  // 和 OutputPaths 類似，但這是用來輸出 Zap 的 internal errors 用的
  ErrorOutputPaths: []string{"stderr"},

  // 定義個在每一個 log 中都要顯示的額外資訊，例如 pid、Go 版本、commit hash、application version 等等
  InitialFields: map[string]interface{}{"pid": os.Getegid(), "version": runtime.Version()},
 }

 return zap.Must(config.Build())
}

func main() {
  logger := zapLogger.CreateLogger()
 defer logger.Sync()

 logger.Info("Hello from Zap!")
}

如果希望控制到更細的 logger 項目（例如，顏色）則可以用 zap.New() 來做。

Managing Log Files

如果要進一步管理 log 檔，則可以參考 A Complete Guide to Managing Log Files with Logrotate。

Child Loggers

除了使用 custom logger 的 InitialFields 可以添加資訊到所有的 log message 外，使用 logger.With() ，也可以建立 Child Loggers，所有使用 child loggers 輸出的 log 都會多帶這些資訊：

func CreateLoggerWithRequestId() *zap.Logger {
 logger := zap.Must(zap.NewDevelopment())
 defer logger.Sync()

 childLogger := logger.With(
  zap.String("platform", "web"),
  zap.String("requestID", "abc123"),
 )

 return childLogger
}

func main() {
 logger := zapLogger.CreateLoggerWithRequestId()
 logger.Info("user registration successful",
  zap.String("username", "aaron.chen"),
  zap.String("email", "pjchender@gmail.com"),
 )

 logger.Info("redirecting user to admin dashboard")
}

Log Sampling

不會所有 Log 都被記錄，而只會有部分的 Log 真的被記錄下來，目的是要在「Log Messages 佔用效能」和「完整紀錄」間有一個平衡。

Sampling @ Sentry

Sentry 也有類似 Sampling 這樣的概念。

使用 zapcore.NewSamplerWithOptions() 可以調整 sampling：

Use Logger In a Go Application

建立 Custom Logger：

// logger/logger.go

// source: https://github.com/betterstack-community/go-logging

package logger

import (
 "context"
 "fmt"
 "go.uber.org/zap"
 "go.uber.org/zap/zapcore"
 "gopkg.in/natefinch/lumberjack.v2"
 "log"
 "os"
 "runtime/debug"
 "sync"
)

type ctxKey struct{}

var once sync.Once
var logger *zap.Logger

// Get initializes a zap.Logger instance if it has not been initialized already
// and returns the same instance for subsequent calls
func Get() *zap.Logger {
 once.Do(func() {
  stdout := zapcore.AddSync(os.Stdout)

  file := zapcore.AddSync(&lumberjack.Logger{
   Filename:   "logs/app.log",
   MaxSize:    5, // megabytes
   MaxBackups: 10,
   MaxAge:     14, // days
   Compress:   true,
  })

  level := zap.InfoLevel
  levelEnv := os.Getenv("LOG_LEVEL")
  if levelEnv != "" {
   levelFromEnv, err := zapcore.ParseLevel(levelEnv)
   if err != nil {
    log.Println(
     fmt.Errorf("invalid level, defaulting to INFO: %w", err),
    )
   }

   level = levelFromEnv
  }

  logLevel := zap.NewAtomicLevelAt(level)

  productionCfg := zap.NewProductionEncoderConfig()
  productionCfg.TimeKey = "timestamp"
  productionCfg.EncodeTime = zapcore.ISO8601TimeEncoder

  developmentCfg := zap.NewDevelopmentEncoderConfig()
  developmentCfg.EncodeLevel = zapcore.CapitalColorLevelEncoder

  consoleEncoder := zapcore.NewConsoleEncoder(developmentCfg)
  fileEncoder := zapcore.NewJSONEncoder(productionCfg)

  var gitRevision string

  buildInfo, ok := debug.ReadBuildInfo()
  if ok {
   for _, v := range buildInfo.Settings {
    if v.Key == "vcs.revision" {
     gitRevision = v.Value
     break
    }
   }
  }

  // The NewTee() method duplicates log entries into multiple destinations (console and file)
  // extra fields are added to the JSON output alone
  core := zapcore.NewTee(
   zapcore.NewCore(consoleEncoder, stdout, logLevel),
   zapcore.NewCore(fileEncoder, file, logLevel).With(
    []zapcore.Field{
     zap.String("git_revision", gitRevision),
     zap.String("go_version", buildInfo.GoVersion),
    },
   ),
  )

  logger = zap.New(core)
 })

 return logger
}

在啟動 server 時（main 中）使用 Custom Logger：

func main() {
 l := logger.Get()
 db.InitDB()

 r := gin.Default()
 r.GET("/ping", func(c *gin.Context) {
  c.JSON(http.StatusOK, gin.H{
   "message": "pong",
  })
 })

 routes.RegisterRoutes(r)

 port := os.Getenv("PORT")
 if port == "" {
  port = "8080"
 }

 l.Info("starting application server on port:"+port, zap.String("port", port))

 err := r.Run()
 if err != nil {
  l.Fatal("start server failed", zap.Error(err))
 }
}

在 middleware 中，產生 x-request-id 並使用 custom logger：

// middlewares/logger.go

package middlewares

import (
 "fmt"
 "github.com/gin-gonic/gin"
 "github.com/rs/xid"
 "go.uber.org/zap"
)

type contextKey string

const (
 requestID contextKey = "request_id"
)

func RequestLogger(l *zap.Logger) gin.HandlerFunc {
 return func(c *gin.Context) {
  correlationID := xid.New().String()

  // set request_id in the context
  c.Set(string(requestID), correlationID)

  // set the x-request-id in the request header for further usage
  c.Request.Header.Set("x-request-id", correlationID)

  // set the x-request-id in the response header
  c.Writer.Header().Set("x-request-id", correlationID)

  // log the request information
  l.Info(
   fmt.Sprintf(
    "%s requests to %s completed",
    c.Request.Method,
    c.Request.RequestURI,
   ),
   zap.String("method", c.Request.Method),
   zap.String("path", c.Request.URL.Path),
   zap.Int("status", c.Writer.Status()),
   zap.String("ip", c.ClientIP()),
   zap.String("x-request-id", correlationID),
  )
  c.Next()
 }
}