注意：本文发布于 1741 天前，文章中的一些内容可能已经过时。

起因

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

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

写了 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

其实思路很简单：

我们的 DBInstanceGroup 除了实现了一个 Interface 以外，只有一个 Map（所有的 *gorm.DB），因此浅拷贝的代价很低；
为 DBInstanceGroup 添加一个 traceID 字段；
放弃使用 g.DAO，而是采用类似于 g.GetDAO(traceID) 的方式生成一个带有 Trace ID 的 g；
在 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 做一次深拷贝，然后前者清空了新对象的 search 和 Value 两个字段，此时得到的就是一个船新的 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 本质上就是个不可变数据类型，它将所有的值都放到未导出字段中，然后对外提供修改的方法，每个可以导致值被修改的方法（Where、Offset 等）都会先执行一遍 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 只会被执行一次。

R·e^x / Zeng

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

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

起因

GORM 的一些不足

为 GORM 添加 Logger

将 Trace ID 传入 Logger

一点思考