zap receives the default log of gin framework

Keywords: Go Back-end

The previous two articles have introduced how to use logs in golang, and zap has been selected as our log framework in many log framework libraries. This article will explain:

How to print the request log in combination with the current mainstream Web framework gin
Encapsulate zap twice and inject trace information. Once, we can query all the complete logs of a request in the business

Here are links to the first two articles:

1. gin default Middleware

First, let's look at the simplest gin project:

func main() {
    r := gin.Default()
    r.GET("/hello", func(c *gin.Context) {
        c.String("hello jianfan.com!")
    })
    r.Run(
}

Next, let's look at the source code of gin.Default():

func Default() *Engine {
    debugPrintWARNINGDefault()
    engine := New()
    engine.Use(Logger(), Recovery())
    return engine
}

That is, when we use gin.Default(), we also use the two default middleware Logger() and Recovery() in the gin framework.

The Logger() outputs the logs of the gin framework itself to the standard output (the logs output at the terminal during our local development and debugging are its credit), and the Recovery() recovers the scene and writes 500 responses when the program has a panic.

2. zap based Middleware

The gin framework supports user-defined middleware. We can imitate the implementation of Logger() and Recovery() and use our log library to receive the logs output by the gin framework by default.
Taking zap as an example, we implement two middleware as follows:

// GinLogger receives the default log of the gin framework
func GinLogger(logger *zap.Logger) gin.HandlerFunc {
    return func(c *gin.Context) {
        start := time.Now()
        path := c.Request.URL.Path
        query := c.Request.URL.RawQuery
        c.Next()

        cost := time.Since(start)
        logger.Info(path,
            zap.Int("status", c.Writer.Status()),
            zap.String("method", c.Request.Method),
            zap.String("path", path),
            zap.String("query", query),
            zap.String("ip", c.ClientIP()),
            zap.String("user-agent", c.Request.UserAgent()),
            zap.String("errors", c.Errors.ByType(gin.ErrorTypePrivate).String()),
            zap.Duration("cost", cost),
        )
    }
}

// Ginrecovery removes the possible panic of the project
func GinRecovery(logger *zap.Logger, stack bool) gin.HandlerFunc {
    return func(c *gin.Context) {
        defer func() {
            if err := recover(); err != nil {
                // Check for a broken connection, as it is not really a
                // condition that warrants a panic stack trace.
                var brokenPipe bool
                if ne, ok := err.(*net.OpError); ok {
                    if se, ok := ne.Err.(*os.SyscallError); ok {
                        if strings.Contains(strings.ToLower(se.Error()), "broken pipe") || strings.Contains(strings.ToLower(se.Error()), "connection reset by peer") {
                            brokenPipe = true
                        }
                    }
                }

                httpRequest, _ := httputil.DumpRequest(c.Request, false)
                if brokenPipe {
                    logger.Error(c.Request.URL.Path,
                        zap.Any("error", err),
                        zap.String("request", string(httpRequest)),
                    )
                    // If the connection is dead, we can't write a status to it.
                    c.Error(err.(error)) // nolint: errcheck
                    c.Abort()
                    return
                }

                if stack {
                    logger.Error("[Recovery from panic]",
                        zap.Any("error", err),
                        zap.String("request", string(httpRequest)),
                        zap.String("stack", string(debug.Stack())),
                    )
                } else {
                    logger.Error("[Recovery from panic]",
                        zap.Any("error", err),
                        zap.String("request", string(httpRequest)),
                    )
                }
                c.AbortWithStatus(http.StatusInternalServerError)
            }
        }()
        c.Next()
    }
}

If you don't want to implement it yourself, you can use it encapsulated by others on github https://github.com/gin-contrib/zap.

In this way, we can use the two middleware defined above in the gin framework to replace the default Logger() and Recovery() of the gin framework.

r := gin.New()
r.Use(GinLogger(), GinRecovery())

3. Add Trace information

3.1 define trace information

// Define trace structure
type Trace struct {
    TraceId   string  `json:"trace_id"`
    SpanId    string  `json:"span_id"`
    Caller    string  `json:"caller"`
    SrcMethod *string `json:"srcMethod,omitempty"`
    UserId    int   `json:"user_id"`
}

// Get the context according to the context of gin to make log trace more general
func GetTraceCtx(c *gin.Context) context.Context {
    return c.MustGet(consts.TraceCtx).(context.Context)
}

3.2 packaging zap based logging tools

The wrapper method passes in the context

Parse the trace information and print it to the logger

package log

import (
  "best-practics/common"
  "best-practics/common/consts"
  "context"
  "go.uber.org/zap"
)

type LogWrapper struct {
  logger *zap.Logger
}

var Log LogWrapper

func Debug(tag string, fields ...zap.Field) {
  Log.logger.Debug(tag, fields...)
}

func DebugF(ctx context.Context, tag string, fields ...zap.Field) {
  trace := ctx.Value(consts.TraceKey).(*common.Trace)
  Log.logger.Debug(tag,
      append(fields, zap.String("trace_id", trace.TraceId), zap.Int("user_id", trace.UserId))...,
  )
}

func Info(tag string, fields ...zap.Field) {
  Log.logger.Info(tag, fields...)
}

func InfoF(ctx context.Context, tag string, fields ...zap.Field) {
  trace := ctx.Value(consts.TraceKey).(*common.Trace)
  Log.logger.Info(tag,
      append(fields, zap.String("trace_id", trace.TraceId), zap.Int("user_id", trace.UserId))...,
  )
}

func Warn(tag string, fields ...zap.Field) {
  Log.logger.Warn(tag, fields...)
}

func WarnF(ctx context.Context, tag string, fields ...zap.Field) {
  trace := ctx.Value(consts.TraceKey).(*common.Trace)
  Log.logger.Warn(tag,
      append(fields, zap.String("trace_id", trace.TraceId), zap.Int("user_id", trace.UserId))...,
  )
}

func Error(tag string, fields ...zap.Field) {
  Log.logger.Error(tag, fields...)
}

func ErrorF(ctx context.Context, tag string, fields ...zap.Field) {
  trace := ctx.Value(consts.TraceKey).(*common.Trace)
  Log.logger.Error(tag,
      append(fields, zap.String("trace_id", trace.TraceId), zap.Int("user_id", trace.UserId))...,
  )
}

func Fatal(tag string, fields ...zap.Field) {
  Log.logger.Fatal(tag, fields...)
}

func FatalF(ctx context.Context, tag string, fields ...zap.Field) {
  trace := ctx.Value(consts.TraceKey).(*common.Trace)
  Log.logger.Fatal(tag,
      append(fields, zap.String("trace_id", trace.TraceId), zap.Int("user_id", trace.UserId))...,
  )
}

3.3 solving the Caller problem

There is a problem with this method, that is, all the caller information printed is the code line corresponding to the logging tool class, not the calling place. After looking at the zap source code, when zap prints, the entire stack link of the call will be stored in memory, and the caller information at the call will be printed by default. Therefore, in order to solve this problem, AddCallerSkip needs to be added when initializing zap to skip the caller of the specified level. The core code is as follows:

logger = logger.WithOptions(zap.AddCaller(),zap.AddCallerSkip(1))

The complete zap tool classes are as follows:

/*
 * Copyright (C) 2021 Baidu, Inc. All Rights Reserved.
 */
package log

import (
  "best-practics/common"
  "best-practics/utils"
  "fmt"
  "os"
  "time"

  rotatelogs "github.com/lestrrat-go/file-rotatelogs"
  "go.uber.org/zap"
  "go.uber.org/zap/zapcore"
)

func InitZap() {
  if ok, _ := utils.PathExists(common.GlobalConfig.Zap.Director); !ok { // Determine whether there is a Director folder
      fmt.Printf("create %v directory\n", common.GlobalConfig.Zap.Director)
      _ = os.Mkdir(common.GlobalConfig.Zap.Director, os.ModePerm)
  }
  // Debug level
  debugPriority := zap.LevelEnablerFunc(func(lev zapcore.Level) bool {
      return lev == zap.DebugLevel
  })
  // log level
  infoPriority := zap.LevelEnablerFunc(func(lev zapcore.Level) bool {
      return lev == zap.InfoLevel
  })
  // Warning level
  warnPriority := zap.LevelEnablerFunc(func(lev zapcore.Level) bool {
      return lev == zap.WarnLevel
  })
  // error level
  errorPriority := zap.LevelEnablerFunc(func(lev zapcore.Level) bool {
      return lev >= zap.ErrorLevel
  })

  cores := [...]zapcore.Core{
      getEncoderCore(fmt.Sprintf("./%s/server_debug.log", common.GlobalConfig.Zap.Director), debugPriority),
      getEncoderCore(fmt.Sprintf("./%s/server_info.log", common.GlobalConfig.Zap.Director), infoPriority),
      getEncoderCore(fmt.Sprintf("./%s/server_warn.log", common.GlobalConfig.Zap.Director), warnPriority),
      getEncoderCore(fmt.Sprintf("./%s/server_error.log", common.GlobalConfig.Zap.Director), errorPriority),
  }
  logger := zap.New(zapcore.NewTee(cores[:]...), zap.AddCaller(), zap.AddCallerSkip(1))

  common.Logger = logger
}

// getEncoderConfig get zapcore.EncoderConfig
func getEncoderConfig() (config zapcore.EncoderConfig) {
  config = zapcore.EncoderConfig{
      MessageKey:     "message",
      LevelKey:       "level",
      TimeKey:        "time",
      NameKey:        "logger",
      CallerKey:      "caller",
      StacktraceKey:  common.GlobalConfig.Zap.StacktraceKey,
      LineEnding:     zapcore.DefaultLineEnding,
      EncodeLevel:    zapcore.LowercaseLevelEncoder,
      EncodeTime:     CustomTimeEncoder,
      EncodeDuration: zapcore.SecondsDurationEncoder,
      EncodeCaller:   zapcore.FullCallerEncoder,
  }
  switch {
  case common.GlobalConfig.Zap.EncodeLevel == "LowercaseLevelEncoder": // Lower case encoder (default)
      config.EncodeLevel = zapcore.LowercaseLevelEncoder
  case common.GlobalConfig.Zap.EncodeLevel == "LowercaseColorLevelEncoder": // Lowercase encoder with color
      config.EncodeLevel = zapcore.LowercaseColorLevelEncoder
  case common.GlobalConfig.Zap.EncodeLevel == "CapitalLevelEncoder": // Uppercase encoder
      config.EncodeLevel = zapcore.CapitalLevelEncoder
  case common.GlobalConfig.Zap.EncodeLevel == "CapitalColorLevelEncoder": // Uppercase encoder with color
      config.EncodeLevel = zapcore.CapitalColorLevelEncoder
  default:
      config.EncodeLevel = zapcore.LowercaseLevelEncoder
  }
  return config
}

// getEncoder get zapcore.Encoder
func getEncoder() zapcore.Encoder {
  if common.GlobalConfig.Zap.Format == "json" {
      return zapcore.NewJSONEncoder(getEncoderConfig())
  }
  return zapcore.NewConsoleEncoder(getEncoderConfig())
}

// getEncoderCore get zapcore.Core of Encoder
func getEncoderCore(fileName string, level zapcore.LevelEnabler) (core zapcore.Core) {
  writer := GetWriteSyncer(fileName) // Log segmentation using file rotatelogs
  return zapcore.NewCore(getEncoder(), writer, level)
}

// Custom log output time format
func CustomTimeEncoder(t time.Time, enc zapcore.PrimitiveArrayEncoder) {
  enc.AppendString(t.Format("2006/01/02 15:04:05"))
}

//@function: GetWriteSyncer
//@Description: add file rotatelogs to zap logger
//@return: zapcore.WriteSyncer, error
func GetWriteSyncer(file string) zapcore.WriteSyncer {
  // One file per hour
  logf, _ := rotatelogs.New(file +".%Y%m%d%H",
      rotatelogs.WithLinkName(file),
      rotatelogs.WithMaxAge(7*24*time.Hour),
      rotatelogs.WithRotationTime(time.Minute),
  )

  if common.GlobalConfig.Zap.LogInConsole {
      return zapcore.NewMultiWriteSyncer(zapcore.AddSync(os.Stdout), zapcore.AddSync(logf))
  }
  return zapcore.AddSync(logf)
}

3.4 add trace information to gin's middleware

func SetLoggerMiddleware() gin.HandlerFunc {
  return func(c *gin.Context) {
      start := time.Now()
      uuidStr := strings.ReplaceAll(uuid.New().String(), "-", "")
      path := c.Request.URL.Path
      userId := c.GetInt("user_id")
      ctx := context.WithValue(context.Background(), consts.TraceKey, &common.Trace{TraceId: uuidStr, Caller: path, UserId: userId})
      c.Set(consts.TraceCtx,ctx)

      c.Next()
      cost := time.Since(start)
      common.Logger.Info("_com_request_info",
          zap.Int("Status", c.Writer.Status()),
          zap.String("Method", c.Request.Method),
          zap.String("IP",c.ClientIP()),
          zap.String("Path",path),
          zap.String("TraceId", uuidStr),
          zap.Int("UserId", userId),
          zap.String("query", c.Request.URL.RawQuery),
          zap.String("UserAgent",c.Request.UserAgent()),
          zap.Duration("Cost",cost),
      )
  }
}

3.5 trace generated by controller layer_ context

func main() {
  r := gin.Default()
  r.GET("/hello", func(c *gin.Context) {
      // Conversion method of package in 3.1
      ctx := common.GetTraceCtx(c)
      log.WarnF(ctx,"BookNotFoundError",zap.String("test","666"))
      c.String("hello jianfan.com!")
  })
  r.Run(
}

So far, we have completed accessing zap as a log framework in a gin project, and can print complete link log information. Combined with the previous two sections, we have met the requirements for common log frameworks:

Good log write performance
Different log levels are supported. And can be separated into multiple log files
Multi output - supports standard output, files, etc
Be able to print basic information, such as calling file / function name and line number, log time, etc
Readability and structure. Json format may have separators to facilitate subsequent log collection and monitoring
For file cutting, the log can be split by hour and day, or by file size
Log writing is friendly, and automatic log trace through context is supported
File scheduled deletion
Open source, which is better supported than other open source frameworks

reference material:

https://liwenzhou.com/posts/Go/use_zap_in_gin/

I'll see you next time, Peace 😘

I am Jian Fan, an inspirational migrant worker in the new era who aims to describe the most complex problems in the simplest language. If you have any doubts about this article, please leave a message in my WeChat official account. What I can do is to help you:

Help build your own knowledge system
Real high concurrency scenarios on the Internet
Occasionally share classic scenarios and practices related to Golang and Java

My blog: https://besthpt.github.io/
My wechat: bestbear666
The official account of WeChat:

Posted by Schwalbach on Wed, 24 Nov 2021 00:37:41 -0800

Programmer Group