go-zero使用Gorm时日志追踪trace问题处理
go-zero中的自带model使用起来没有特别舒心(其实功能都满足,主要是不习惯)。Gorm大家都很熟悉,也都用习惯了,但是要把Gorm中的logger与go-zero中的logx串起来,还是需要花一点心思的。
注入logger
首先是要解决logger。 我这里参考的是Summer老师GormLogger ( https://github.com/summerblue/gohub/blob/G02_1.19/pkg/logger/gorm_logger.go )。 把其中zap调用部分换成go-zero的logx就完事了。
package gormlogger
import (
"auth/api/config"
"auth/pkg/utils"
"context"
"errors"
"time"
"github.com/zeromicro/go-zero/core/logx"
"github.com/zeromicro/go-zero/core/service"
"gorm.io/gorm"
"gorm.io/gorm/logger"
)
type GormLogger struct {
SlowThreshold time.Duration
c config.Config
}
func NewGormLogger(c config.Config) *GormLogger {
return &GormLogger{
SlowThreshold: 200 * time.Millisecond, // 一般超过200毫秒就算慢查所以不使用配置进行更改
c: c,
}
}
var _ logger.Interface = (*GormLogger)(nil)
func (l *GormLogger) LogMode(lev logger.LogLevel) logger.Interface {
return &GormLogger{}
}
func (l *GormLogger) Info(ctx context.Context, msg string, data ...interface{}) {
logx.WithContext(ctx).Infof(msg, data)
}
func (l *GormLogger) Warn(ctx context.Context, msg string, data ...interface{}) {
logx.WithContext(ctx).Errorf(msg, data)
}
func (l *GormLogger) Error(ctx context.Context, msg string, data ...interface{}) {
logx.WithContext(ctx).Errorf(msg, data)
}
func (l *GormLogger) Trace(ctx context.Context, begin time.Time, fc func() (sql string, rowsAffected int64), err error) {
// 获取运行时间
elapsed := time.Since(begin)
// 获取 SQL 语句和返回条数
sql, rows := fc()
// 通用字段
logFields := []logx.LogField{
logx.Field("sql", sql),
logx.Field("time", utils.MicrosecondsStr(elapsed)),
logx.Field("rows", rows),
}
// Gorm 错误
if err != nil {
// 记录未找到的错误使用 warning 等级
if errors.Is(err, gorm.ErrRecordNotFound) {
logx.WithContext(ctx).Infow("Database ErrRecordNotFound", logFields...)
} else {
// 其他错误使用 error 等级
logFields = append(logFields, logx.Field("catch error", err))
logx.WithContext(ctx).Errorw("Database Error", logFields...)
}
}
// 慢查询日志
if l.SlowThreshold != 0 && elapsed > l.SlowThreshold {
logx.WithContext(ctx).Sloww("Database Slow Log", logFields...)
}
// 非生产模式下,记录所有 SQL 请求
if l.c.Mode != service.ProMode {
logx.WithContext(ctx).Infow("Database Query", logFields...)
}
}
然后在db初始化的时候,在config里丢logger进去就可以
dbSqlite, err := gorm.Open(sqlite.Open("mydb.db"), &gorm.Config{
Logger: gormlogger.NewGormLogger(),
})
if err != nil {
panic("failed to connect database")
}
trace
到以上的操作都很简单,现在使用Gorm进行查询就能在go-zero日志中查看相关信息了。 但是最关键的trace追踪还没有接上来, 对于日志分析会有一定的困难。
所以现在问题的关键就在于怎么把请求中含有traceid的上下文信息带到gorm中。
在GormLogger中,已经能发现Gorm本身就支持上下文信息的传递。 在Gorm的指针*gorm.DB
也有提供携带上下文的方法
dbSqlite.WithContext(ctx)
所以现在要做的,就是在每次请求中,调用Gorm进行查询前,先把请求中的上下文信息通过WithContext()
传递给Gorm。最终GormLogger会把这个上下文信息传递给logx, trace信息就能顺利记录到日志中了。
例如在logic中这样写
func (l *ExampleLogic) Example(req types.ExampleReq) (*types.ExampleResp, error) {
dbSqlite, err := gorm.Open(sqlite.Open(DB_FILE_SQLITE_SMSSERVICE), &gorm.Config{
Logger: gormlogger.NewGormLogger(),
})
if err != nil {
panic("failed to connect database")
}
dbSqlite.WithContext(l.ctx).Where("1=1").Find()
return &types.ExampleResp{}, nil
}
把trace延续到协程中
如果请求中涉及到协程的应用,需要把trace上下文信息带到协程中,就会引发一个上下文生命周期的问题:
- 请求协程A,生成上下文并注入trace信息
- 处理过程中,新建协程B,把协程A的上下文带到协程B中,进行一些db的异步处理。
- 协程A处理完毕,上下文关闭
- 协程B中的Gorm接收到上下文关闭的chan信号,也直接关闭请求
这不符合实际需求,我们希望把上下文中的trace信息带到协程B中,且希望协程B只使用其中的Value功能。
我们在一般使用上下文context的时候,大多数情况都是使用 context.WithXXXXXX()
的功能,即基于父上下文,继承出一个子上下文出来。
在这种场景我们不能使用子上下文,因为父上下文(即请求协程A的上下文)关闭之后,所有的子上下文都会收到关闭信号。
最终我在 go-zero 官方社区微信群中,从群友学到了一招:给上下文套一个父级。 而且 go-zero 也提供了相关的 package 可以直接使用: contextx.ValueOnlyFrom()
https://github.com/zeromicro/go-zero/blob/master/core/contextx/valueonlycontext.go#L25
实际使用中,只要把上下文套进去就完事了,例如:
func (l *ExampleLogic) Example(req types.ExampleReq) (*types.ExampleResp, error) {
dbSqlite, err := gorm.Open(sqlite.Open(DB_FILE_SQLITE_SMSSERVICE), &gorm.Config{
Logger: gormlogger.NewGormLogger(),
})
if err != nil {
panic("failed to connect database")
}
dbSqlite.WithContext(contextx.ValueOnlyFrom(l.ctx)).Where("1=1").Find()
return &types.ExampleResp{}, nil
}
本作品采用 知识共享署名-相同方式共享 4.0 国际许可协议 进行许可。