golang:微服务架构下的日志追踪系统（二）

背景

在使用Gin框架进行服务开发时，我们遇到了一个日志记录的问题。由于Gin的上下文（*gin.Context）实现了context.Context接口，在调用日志记录器的Info、Warn、Error等方法时，直接传递Gin的上下文通常不会导致编译错误。会导致我们在《golang:微服务架构下的日志追踪系统》一文中定义的日志统计维度信息无法正确串联。

为了解决这一问题，我们之前的解决方案是让业务方在使用日志记录器时，将Gin的上下文手动转换为context.Context。

但这种方案带来了一个明显的弊端：它依赖于开发人员的主动转换，而开发人员往往会忘记进行这一步操作，直接传递Gin的上下文，从而导致日志并未按照预期格式打印。这不仅增加了开发人员的负担，也降低了日志系统的可靠性和准确性。

解决方案

针对上述问题，我们提出了一种更为优雅的解决方案：在日志记录器的方法内部封装Gin上下文到context.Context的转换逻辑。这样一来，开发人员在使用日志记录器时无需再关心上下文的转换问题，只需直接传递Gin的上下文即可。

接下来，我们将这一转换逻辑集成到日志记录器的各个方法中，确保无论传入的是Gin的上下文还是context.Context，都能正确记录日志信息。

在封装的方法中实现gin的context的转换即可。

// gin context to context
func GinContextToContext(ctx context.Context) context.Context {if v, ok := ctx.(*gin.Context); ok {if v == nil || v.Request == nil {return context.Background()}return v.Request.Context()}return ctx
}

完整的逻辑。

package loggerimport ("context""errors""fmt""time""{{your module}}}/go-core/utils/constant""github.com/gin-gonic/gin""go.uber.org/zap""go.uber.org/zap/zapcore""gorm.io/gorm""gorm.io/gorm/logger""gorm.io/gorm/utils"
)// Logger logger for gorm2
type Logger struct {log *zap.Loggerlogger.ConfigcustomFields []func(ctx context.Context) zap.Field
}// Option logger/recover option
type Option func(l *Logger)// WithCustomFields optional custom field
func WithCustomFields(fields ...func(ctx context.Context) zap.Field) Option {return func(l *Logger) {l.customFields = fields}
}// WithConfig optional custom logger.Config
func WithConfig(cfg logger.Config) Option {return func(l *Logger) {l.Config = cfg}
}// SetGormDBLogger set db logger
func SetGormDBLogger(db *gorm.DB, l logger.Interface) {db.Logger = l
}// New logger form gorm2
func New(zapLogger *zap.Logger, opts ...Option) logger.Interface {l := &Logger{log: zapLogger,Config: logger.Config{SlowThreshold:             200 * time.Millisecond,Colorful:                  false,IgnoreRecordNotFoundError: false,LogLevel:                  logger.Warn,},}for _, opt := range opts {opt(l)}return l
}// NewDefault new default logger
// 初始化一个默认的 logger
func NewDefault(zapLogger *zap.Logger) logger.Interface {return New(zapLogger, WithCustomFields(func(ctx context.Context) zap.Field {v := ctx.Value("Request-Id")if v == nil {return zap.Skip()}if vv, ok := v.(string); ok {return zap.String("trace", vv)}return zap.Skip()}, func(ctx context.Context) zap.Field {v := ctx.Value("method")if v == nil {return zap.Skip()}if vv, ok := v.(string); ok {return zap.String("method", vv)}return zap.Skip()}, func(ctx context.Context) zap.Field {v := ctx.Value("path")if v == nil {return zap.Skip()}if vv, ok := v.(string); ok {return zap.String("path", vv)}return zap.Skip()}, func(ctx context.Context) zap.Field {v := ctx.Value("version")if v == nil {return zap.Skip()}if vv, ok := v.(string); ok {return zap.String("version", vv)}return zap.Skip()}),WithConfig(logger.Config{SlowThreshold:             200 * time.Millisecond,Colorful:                  false,IgnoreRecordNotFoundError: false,LogLevel:                  logger.Info,}))
}// 用于支持微服务架构下的链路追踪
func NewTracingLogger(zapLogger *zap.Logger) logger.Interface {return New(zapLogger, WithCustomFields(// trace是链路追踪的唯一标识// span是当前请求的唯一标识// parent_span是父请求的唯一标识func(ctx context.Context) zap.Field {v := ctx.Value(constant.CONTEXT_KEY_TRACE)if v == nil {return zap.Skip()}if vv, ok := v.(string); ok {return zap.String(constant.CONTEXT_KEY_TRACE, vv)}return zap.Skip()}, func(ctx context.Context) zap.Field {v := ctx.Value(constant.CONTEXT_KEY_SPAN)if v == nil {return zap.Skip()}if vv, ok := v.(string); ok {return zap.String(constant.CONTEXT_KEY_SPAN, vv)}return zap.Skip()}, func(ctx context.Context) zap.Field {v := ctx.Value(constant.CONTEXT_KEY_PARENT_SPAN)if v == nil {return zap.Skip()}if vv, ok := v.(string); ok {return zap.String(constant.CONTEXT_KEY_PARENT_SPAN, vv)}return zap.Skip()}, func(ctx context.Context) zap.Field {v := ctx.Value(constant.CONTEXT_KEY_METHOD)if v == nil {return zap.Skip()}if vv, ok := v.(string); ok {return zap.String(constant.CONTEXT_KEY_METHOD, vv)}return zap.Skip()}, func(ctx context.Context) zap.Field {v := ctx.Value(constant.CONTEXT_KEY_PATH)if v == nil {return zap.Skip()}if vv, ok := v.(string); ok {return zap.String(constant.CONTEXT_KEY_PATH, vv)}return zap.Skip()}, func(ctx context.Context) zap.Field {v := ctx.Value(constant.CONTEXT_KEY_VERSION)if v == nil {return zap.Skip()}if vv, ok := v.(string); ok {return zap.String(constant.CONTEXT_KEY_VERSION, vv)}return zap.Skip()}, func(ctx context.Context) zap.Field {// 用于标识调用方服务名v := ctx.Value(constant.CONTEXT_KEY_CALLER_SERVICE_NAME)if v == nil {return zap.Skip()}if vv, ok := v.(string); ok {return zap.String(constant.CONTEXT_KEY_CALLER_SERVICE_NAME, vv)}return zap.Skip()}, func(ctx context.Context) zap.Field {// 用于标识调用方ipv := ctx.Value(constant.CONTEXT_KEY_CALLER_IP)if v == nil {return zap.Skip()}if vv, ok := v.(string); ok {return zap.String(constant.CONTEXT_KEY_CALLER_IP, vv)}return zap.Skip()}),WithConfig(logger.Config{SlowThreshold:             200 * time.Millisecond,Colorful:                  false,IgnoreRecordNotFoundError: false,LogLevel:                  logger.Info,}))
}// gin context to context
func GinContextToContext(ctx context.Context) context.Context {if v, ok := ctx.(*gin.Context); ok {if v == nil || v.Request == nil {return context.Background()}return v.Request.Context()}return ctx
}// LogMode log mode
func (l *Logger) LogMode(level logger.LogLevel) logger.Interface {newLogger := *lnewLogger.LogLevel = levelreturn &newLogger
}// Info print info
func (l Logger) Info(ctx context.Context, msg string, args ...interface{}) {if l.LogLevel >= logger.Info {ctx = GinContextToContext(ctx)//预留10个字段位置fields := make([]zap.Field, 0, 10+len(l.customFields))fields = append(fields, zap.String("file", utils.FileWithLineNum()))for _, customField := range l.customFields {fields = append(fields, customField(ctx))}now := time.Now().UnixMilli()// 从ctx中获取操作的开始时间if v := ctx.Value(constant.CONTEXT_KEY_EXECUTE_START_TIME); v != nil {if vv, ok := v.(int64); ok {// 计算操作的执行时间,以毫秒为单位duration := now - vv// 将操作的执行时间放入ctxfields = append(fields, zap.Int64(constant.CONTEXT_KEY_EXECUTE_DURATION, duration))}}for _, arg := range args {if vv, ok := arg.(zapcore.Field); ok {if len(vv.String) > 0 {fields = append(fields, zap.String(vv.Key, vv.String))} else if vv.Integer > 0 {fields = append(fields, zap.Int64(vv.Key, vv.Integer))} else {fields = append(fields, zap.Any(vv.Key, vv.Interface))}}}l.log.Info(msg, fields...)}
}// Warn print warn messages
func (l Logger) Warn(ctx context.Context, msg string, args ...interface{}) {if l.LogLevel >= logger.Warn {ctx = GinContextToContext(ctx)//预留10个字段位置fields := make([]zap.Field, 0, 10+len(l.customFields))fields = append(fields, zap.String("file", utils.FileWithLineNum()))for _, customField := range l.customFields {fields = append(fields, customField(ctx))}for _, arg := range args {if vv, ok := arg.(zapcore.Field); ok {if len(vv.String) > 0 {fields = append(fields, zap.String(vv.Key, vv.String))} else if vv.Integer > 0 {fields = append(fields, zap.Int64(vv.Key, vv.Integer))} else {fields = append(fields, zap.Any(vv.Key, vv.Interface))}}}l.log.Warn(msg, fields...)}
}// Error print error messages
func (l Logger) Error(ctx context.Context, msg string, args ...interface{}) {if l.LogLevel >= logger.Error {ctx = GinContextToContext(ctx)//预留10个字段位置fields := make([]zap.Field, 0, 10+len(l.customFields))fields = append(fields, zap.String("file", utils.FileWithLineNum()))for _, customField := range l.customFields {fields = append(fields, customField(ctx))}for _, arg := range args {if vv, ok := arg.(zapcore.Field); ok {if len(vv.String) > 0 {fields = append(fields, zap.String(vv.Key, vv.String))} else if vv.Integer > 0 {fields = append(fields, zap.Int64(vv.Key, vv.Integer))} else {fields = append(fields, zap.Any(vv.Key, vv.Interface))}}}l.log.Error(msg, fields...)}
}// Trace print sql message
func (l Logger) Trace(ctx context.Context, begin time.Time, fc func() (string, int64), err error) {if l.LogLevel <= logger.Silent {return}ctx = GinContextToContext(ctx)fields := make([]zap.Field, 0, 6+len(l.customFields))elapsed := time.Since(begin)switch {case err != nil && l.LogLevel >= logger.Error && (!l.IgnoreRecordNotFoundError || !errors.Is(err, gorm.ErrRecordNotFound)):for _, customField := range l.customFields {fields = append(fields, customField(ctx))}fields = append(fields,zap.Error(err),zap.String("file", utils.FileWithLineNum()),zap.Duration("latency", elapsed),)sql, rows := fc()if rows == -1 {fields = append(fields, zap.String("rows", "-"))} else {fields = append(fields, zap.Int64("rows", rows))}fields = append(fields, zap.String("sql", sql))l.log.Error("", fields...)case elapsed > l.SlowThreshold && l.SlowThreshold != 0 && l.LogLevel >= logger.Warn:for _, customField := range l.customFields {fields = append(fields, customField(ctx))}fields = append(fields,zap.Error(err),zap.String("file", utils.FileWithLineNum()),zap.String("slow!!!", fmt.Sprintf("SLOW SQL >= %v", l.SlowThreshold)),zap.Duration("latency", elapsed),)sql, rows := fc()if rows == -1 {fields = append(fields, zap.String("rows", "-"))} else {fields = append(fields, zap.Int64("rows", rows))}fields = append(fields, zap.String("sql", sql))l.log.Warn("", fields...)case l.LogLevel == logger.Info:for _, customField := range l.customFields {fields = append(fields, customField(ctx))}fields = append(fields,zap.Error(err),zap.String("file", utils.FileWithLineNum()),zap.Duration("latency", elapsed),)sql, rows := fc()if rows == -1 {fields = append(fields, zap.String("rows", "-"))} else {fields = append(fields, zap.Int64("rows", rows))}fields = append(fields, zap.String("sql", sql))l.log.Info("", fields...)}
}// Immutable custom immutable field
// Deprecated: use Any instead
func Immutable(key string, value interface{}) func(ctx context.Context) zap.Field {return Any(key, value)
}// Any custom immutable any field
func Any(key string, value interface{}) func(ctx context.Context) zap.Field {field := zap.Any(key, value)return func(ctx context.Context) zap.Field { return field }
}// String custom immutable string field
func String(key string, value string) func(ctx context.Context) zap.Field {field := zap.String(key, value)return func(ctx context.Context) zap.Field { return field }
}// Int64 custom immutable int64 field
func Int64(key string, value int64) func(ctx context.Context) zap.Field {field := zap.Int64(key, value)return func(ctx context.Context) zap.Field { return field }
}// Uint64 custom immutable uint64 field
func Uint64(key string, value uint64) func(ctx context.Context) zap.Field {field := zap.Uint64(key, value)return func(ctx context.Context) zap.Field { return field }
}// Float64 custom immutable float32 field
func Float64(key string, value float64) func(ctx context.Context) zap.Field {field := zap.Float64(key, value)return func(ctx context.Context) zap.Field { return field }
}

测试用例

package loggerimport ("context""fmt""net/http""net/http/httptest""testing""time""{{your module}}/go-core/utils/constant""github.com/gin-gonic/gin""go.uber.org/zap"
)// Mock function to create a gin context
func createGinContext() *gin.Context {w := httptest.NewRecorder()// Create a mock request with an attached contextreq, _ := http.NewRequest(http.MethodPost, "/api/v1/users", nil)ctx := context.Background()// Here you can set values in the contextctx = context.WithValue(ctx, constant.CONTEXT_KEY_SPAN, "123456")ctx = context.WithValue(ctx, constant.CONTEXT_KEY_PARENT_SPAN, "parent_span_123456")ctx = context.WithValue(ctx, constant.CONTEXT_KEY_TRACE, "trace_id_123456")ctx = context.WithValue(ctx, constant.CONTEXT_KEY_METHOD, "POST")ctx = context.WithValue(ctx, constant.CONTEXT_KEY_PATH, "/api/v1/users")ctx = context.WithValue(ctx, constant.CONTEXT_KEY_VERSION, "v1.0.0")ctx = context.WithValue(ctx, constant.CONTEXT_KEY_CALLER_SERVICE_NAME, "user-service")ctx = context.WithValue(ctx, constant.CONTEXT_KEY_CALLER_IP, "172.0.0.3")req = req.WithContext(ctx)// Create the Gin contextc, _ := gin.CreateTestContext(w)c.Request = reqreturn c
}// 测试ginContextWithLogger
func TestGinContextWithLogger(t *testing.T) {// 创建一个 zap logger 实例zapLogger, _ := zap.NewProduction()defer zapLogger.Sync() // 确保日志被刷新// 创建一个带有自定义字段和配置的 Logger 实例customLogger := NewTracingLogger(zapLogger)// 创建一个 Gin contextc := createGinContext()// 测试 Info 方法customLogger.Info(c, "This is an info message")// 测试 Warn 方法customLogger.Warn(c, "This is a warning message")// 测试 Error 方法customLogger.Error(c, "This is an error message")// 测试 Trace 方法，模拟一个慢查询slowQueryBegin := time.Now()slowQueryFunc := func() (string, int64) {return "SELECT * FROM users", 100}time.Sleep(2 * time.Second) // 模拟一个慢查询customLogger.Trace(c, slowQueryBegin, slowQueryFunc, nil)// 测试 Trace 方法，模拟一个错误查询errorQueryBegin := time.Now()errorQueryFunc := func() (string, int64) {return "SELECT * FROM non_existent_table", 0}customLogger.Trace(c, errorQueryBegin, errorQueryFunc, fmt.Errorf("table not found"))// 由于日志是异步的，我们需要在测试结束时等待一段时间以确保所有日志都被输出time.Sleep(500 * time.Millisecond)
}