R·ex / Zeng


音游狗、安全狗、攻城狮、业余设计师、段子手、苦学日语的少年。

为 GORM Logger 添加 Trace ID 的过程和一点思考

起因

后端程序的运行时日志,一直是出现线上问题时帮忙调试的有利工具。我现在负责的运营平台,由于是给内部人员用的,而且大多数功能都是数据库的增删改查,于是对于日志就没有打的那么详细。直到有一天出了一次线上事故,我们足足花了三天才找到原因(其中有两天我甚至一直以为跟我们的平台没有关系)。经过那次之后,我彻底明白了日志的重要性,于是开始丰富我们的运行时日志。

在这个平台刚搭起来没多久的时候,另一个开发就做了一些基本的工作:

  • 写了 Gin 的中间件,可以为每个请求的 Context 添加一个 Request ID(下文均使用 Trace ID 替代)
  • 写了另外两个中间件,可以将 Trace ID 打到了 access.log(请求结束时)和 error.log(Panic 后 recover 时)两个文件中

后来,我又添加了业务的操作记录,可以看到谁在什么时候访问了哪个 API,以及记录了所有 JSON 格式的 Body(运营平台的所有操作均需要审计,也没有存储任何密码之类的个人信息,因此数据无需脱敏),还写了个 API 可以通过 Trace ID 查询这个请求对应的所有日志。然而线上事故发生后,我发现仅凭这些日志是没法定位问题的,因此打算对日志做一些改进:

  • 对于文件上传的操作,将文件存入公司的 S3 并将下载地址保存到操作记录
  • 为所有的 SQL 打日志,并带上 Trace ID,需要写明执行时间和影响的行数

第一条比较简单,申请一下 S3 然后用 API 就好了,主要是第二条。

GORM 的一些不足

运营平台的后端用 GORM 来操作数据库。首先我承认 GORM 是 Golang 里面数一数二的 SQL 库,但用久了之后会发现其中的一些不足,例如:

  • 无法批量插入
  • 无法存储 Context
  • 默认开启了全表 Update,并且主键为零值时 db.Model(xxx).Update 就是全表 Update

第三点官方手册没找到解决方案,反而是 GitHub Issue 里面 有人问了,答案是需要手动设置 db.BlockGlobalUpdate(true),我觉得这是最智障的设定了;前两点在 v2.0 Milestone 里面都有,但感觉遥遥无期(截止到目前只完成了 25%),一时半会儿没法靠升级来解决了。

为 GORM 添加 Logger

本文所有项目代码均作了数据脱敏和变量改名处理。

GORM 可以自定义 Logger,但很麻烦的是 Logger 必须实现这个 Interface:

type LogWriter interface {
    Println(v ...interface{})
}

type Logger struct {
    LogWriter
}

官方给出的用法是:

db.SetLogger(gorm.Logger{revel.TRACE})
db.SetLogger(log.New(os.Stdout, "\r\n", 0))

这意味着我没法把 Trace ID 传进去,因为我们的几十个 *gorm.DB 对象(由于平台横跨的业务比较广,需要连接三个团队不同国家的十几个数据库,并且分了主从库)是所有请求共用的,而且业务只有到了 DAO 层才会拿到实例:

func (g *DBInstanceGroup) ListAllData() []*Data {
    db := g.selectDB("system-1", DBTypeSlave)

    data := make([]*Data, 0)
    db.Table(dataTableName).Where("status = ?", StatusNormal).Find(&data)

    return data
}

Trace ID 被保存到了上层 Controller(gin.Handler)函数的 *gin.Context 里面,Controller 一般长这样:

func (g *ControllerGroup) ListAllDataController(c *gin.Context) {
    // How to pass this value to g.DAO.ListAllData?
    traceID := c.MustGet("traceID").(string)

    data := g.DAO.ListAllData()
    c.JSON(http.StatusOK, data)
}

如果想传递下去,意味着我要修改几乎所有的 Controller 以及 DAO 函数。这是不太现实的。既然无论如何都要修改 Controller 以提取出 Trace ID,那么能不能真的只修改 Controller,不修改 DAO 呢?

将 Trace ID 传入 Logger

其实思路很简单:

  1. 我们的 DBInstanceGroup 除了实现了一个 Interface 以外,只有一个 Map(所有的 *gorm.DB),因此浅拷贝的代价很低;
  2. DBInstanceGroup 添加一个 traceID 字段;
  3. 放弃使用 g.DAO,而是采用类似于 g.GetDAO(traceID) 的方式生成一个带有 Trace ID 的 g
  4. selectDB 时直接根据 g.traceID 生成一个新的 Logger,然后将拿到的 *gorm.DB 复制一份,将新的 Logger 塞进去。

难点主要是该如何复制一个 gorm.DB。首先里面有很多未导出的字段(包括最重要的部分 SQLCommon),因此无法通过 &gorm.DB{} 之后将值拷贝过去;由于 gorm.DB 继承自 sync.RWMutex,也没法通过函数参数按值传递的方式拷贝(会提示 Unlock passes lock by value)。

在翻阅了 GORM Docs 无果之后,我去看了源代码,发现 main.go#L105-L110 有个 New 方法,调用了一个未导出的 clone 方法,后者可以对 gorm.DB 做一次深拷贝,然后前者清空了新对象的 searchValue 两个字段,此时得到的就是一个船新的 gorm.DB 实例了。

修改之后,Controller 只需要这样,DAO 层的函数完全不用修改:

func (g *ControllerGroup) ListAllDataController(c *gin.Context) {
    traceID := c.MustGet("traceID").(string)

    data := g.GetDAO(traceID).ListAllData()
    c.JSON(http.StatusOK, data)
}

结合我之前写的通过 Trace ID 获取日志的 API,效果是:

requestAuthorizor: authorizing "create" on xxxFeature for [email protected] at xxxCountry
requestAuthorizor: permission cache hit
sql: [0.53ms, 1 rows] SELECT * FROM `a_tab`  WHERE (a_field = 'a_value') ORDER BY `a_tab`.`id` ASC LIMIT 1
sql: [0.28ms, 1 rows] SELECT * FROM `b_tab`  WHERE (`b`.`id` = 28) ORDER BY `b`.`id` ASC LIMIT 1
sql: [0.41ms, 1 rows] INSERT  INTO `c_tab` (`c_field1`,`c_field2`,`c_field3`,`c_field4`) VALUES ('091e7abc-d9d4-4387-ba83-501244bdf953',1563535445,'xxx','xxx')
externalAPI(xxxSystem): POST https://xxxSystem.example.com/path/to/api2
externalAPI(xxxSystem): 200 OK
POST /path/to/api1 | xxx.xxx.xxx.xxx | 200 | 90.16ms

这样就能知道,在运行过程中,究竟发生了什么了。

一点思考

在写这篇文章的前一天,我突然意识到,gorm.DB 本质上就是个不可变数据类型,它将所有的值都放到未导出字段中,然后对外提供修改的方法,每个可以导致值被修改的方法(WhereOffset 等)都会先执行一遍 clone,这样链式调用中每次都是返回了一个新的 gorm.DB,而一开始的那个对象始终不曾被改变。仔细翻了一下 GORM 的 文档,也验证了这一点:

All Chain Methods will clone and create a new DB object (shares one connection pool), GORM is safe for concurrent use by multiple goroutines.

然而有个问题,如果我的链式调用比较长(例如有一行形如 db.Table(x1).Select(x2).Where(x3).Offset(x4).Limit(x5).Find(&data) 的代码),那么必定会执行数次 clone,影响效率。GitHub 上面也有人提了相关的 Issue,但下面的评论并没有从本质上解决这个问题。

我觉得,GORM 可以跟 Immutable.js 学一下,提供一个类似于 asMutable 或者 withMutations 的方法。鉴于 GORM 之前一直没有引入不可变数据的概念,直接叫这个名字可能会让人疑惑;我觉得新方法可以叫做 NonThreadSafe,用法也跟之前的没有太大区别,只需要注意一点:不要复用已经 NonThreadSafe 之后的变量即可。

// only perform 1 clone here
nts := db.NonThreadSafe()
// no clone
nts.Table(x1).Select(x2).Where(x3).Offset(x4).Limit(x5).Find(&data1)
// it's dangerous! DO NOT CODE LIKE THIS!
nts.Table(y1).Where(y2).First(&data2)

如果 GORM 真的提供了这样的方法,那么在上面的代码中,clone 只会被执行一次。

版权声明:除文章开头有特殊声明的情况外,所有文章均可在遵从 CC BY 4.0 协议的情况下转载。

这是我们共同度过的

第 1369 天