Golang中使用注释注解打印日志

　　背景
　　前一段时间线上出现了一个问题：在压测后偶尔会出现一台机器查询数据无结果但是没有返回  err   的情况，导致后续处理都出错。由于当时我们仅在最外层打印了 err   ，没有打印入参和出参，所以导致很难排查问题到底出现在哪一环节。
　　经过艰难地排查出问题后，感觉需要在代码里添加打印关键函数的入参和出参数，但这个逻辑都是重复的，也不想将这一逻辑侵入开发流程，所以就想到了代码生成方式的注释注解。即我们提前定义好一个注释注解（例如： // @Log()  ），并且在 Docker 中编译前运行代码生成的逻辑，将所有拥有该注释注解的函数进行修改，在函数体前面添加打印入参和出参的逻辑。这样就不需要让日志打印侵入到业务代码中，并且后续可以很方便替换成其他的打印逻辑（例如根据@Log   内的参数或者返回值等自定义日志级别）。 编写代码
　　我们可以使用 AST 的方式去解析、识别并修改代码，  go/ast   已经提供了相应的功能，我们查看我们关心的节点部分及其相关的信息结构，可以使用 goast-viewer  直接查看 AST ，当然也可以本地进行调试。 遍历 .go 文件
　　首先需要使用  filepath.Walk   函数遍历指定文件夹下的所有文件，对每一个文件都会执行传入的 walkFn   函数。 walkFn   函数会将 .go   文件解析成 AST ，将其交由注释注解的处理器处理，然后根据是否修改了 AST 决定是否生成新的代码。 // walkFn 函数会对每个 .go 文件处理，并调用注解处理器 func walkFn(path string, info os.FileInfo, err error) error {     // 如果是文件夹，或者不是 .go 文件，则直接返回不处理     if info.IsDir() || !strings.HasSuffix(info.Name(), ＂.go＂) {         return nil     }       // 将 .go 文件解析成 AST     fileSet, file, err := parseFile(path)     // 如果注解修改了内容，则需要生成新的代码     if logannotation.Overwrite(path, fileSet, file) {         buf := &bytes.Buffer{}         if err := format.Node(buf, fileSet, file); err != nil {             panic(err)         }           // 如果不需要替换，则生成到另一个文件         if !replace {             lastSlashIndex := strings.LastIndex(path, ＂/＂)             genDirPath :=path[:lastSlashIndex] + ＂/_gen/＂             if err := os.Mkdir(genDirPath, 0755); err != nil && os.IsNotExist(err){                 panic(err)             }             path = genDirPath + path[lastSlashIndex+1:]         }           if err := ioutil.WriteFile(path, buf.Bytes(), info.Mode()); err != nil {             panic(err)         }     }       return nil }遍历 AST
　　当注释注解处理器拿到 AST 后，就需要使用  astutil.Apply   函数遍历整颗 AST ，并对每个节点进行处理，同时为了方便修改时添加 import   ，我们包一层函数供内部调用，并把一些关键信息打包在一起。 // Overwrite 会对每个 file 处理，运行注册的注解 handler ，并返回其是否被修改 func Overwrite(filepath string, fileSet *token.FileSet, file *ast.File) (modified bool) {     // 初始化处理本次文件所需的信息对象     info := &Info{         Filepath: filepath,         NamedImportAdder: func(name string, path string) bool {             return astutil.AddNamedImport(fileSet, file, name, path)         },     }       // 遍历当前文件 ast 上的所有节点     astutil.Apply(file, nil, func(cursor *astutil.Cursor) bool {         // 处理 log 注解         info.Node = cursor.Node()         nodeModified, err := Handler.Handle(info)         if err != nil {             panic(err)         }           if nodeModified {             modified = nodeModified         }           return true     })       return }识别注释注解
　　接下来我们就需要识别注释注解，跳过不相关的节点，示例中不做额外处理，仅当注释为  @Log()   才认为需要处理，可以根据需要添加相应的逻辑。 func (h *handler) Handle(info *Info) (modified bool, err error) {     // log 注解只用于函数     funcDecl, ok := info.Node.(*ast.FuncDecl)     if !ok {         return     }       // 如果没有注释，则直接处理下一个     if funcDecl.Doc == nil {         return     }       // 如果不是可以处理的注解，则直接返回     doc := strings.Trim(funcDecl.Doc.Text(), ＂	  ＂)     if doc != ＂@Log()＂ {         return     }     ... }获取函数入参和出参
　　首先我们需要获取函数的入参和出参，这里我们以出参举例。出参定义在  funcDecl.Type.Results   ，并且可能没有指定名称，所以需要先为以 _0  , _1  , ...   这样的形式为没有名称的变量设置默认名称，然后按照顺序获取所有变量的名称列表。 // SetDefaultNames 给没有名字的 Field 设置默认的名称 // 默认名称格式：_0, _1, ... // true: 表示至少设置了一个名称 // false: 表示未设置过名称 func SetDefaultNames(fields ...*ast.Field) bool {     index := 0     for _, field := range fields {         if field.Names == nil {             field.Names = NewIdents(fmt.Sprintf(＂_%v＂, index))             index++         }     }       return index > 0 }获取打印语句
　　假设我们所需的打印语句为：  log.Logger.WithContext(ctx).WithField(＂filepath＂, filepath).Infof(format, arg0, arg1)   ，那么函数选择器的表达式可以直接使用 parser.ParseExpr   函数生成，其中的参数 (format, arg0, arg1)   手动拼接即可。 // NewCallExpr 产生一个调用表达式 // 待产生表达式：log.Logger.WithContext(ctx).Infof(arg0, arg1) // 其中： //    funcSelector = ＂log.Logger.WithContext(ctx).Infof＂ //     args = (＂arg0＂, ＂arg1＂) // 调用语句：NewCallExpr(＂log.Logger.WithContext(ctx).Infof＂, ＂arg0＂, ＂arg1＂) func NewCallExpr(funcSelector string, args ...string) (*ast.CallExpr, error) {     // 获取函数对应的表达式     funcExpr, err := parser.ParseExpr(funcSelector)     if err != nil {         return nil, err     }       // 组装参数列表     argsExpr := make([]ast.Expr, len(args))     for i, arg := range args {         argsExpr[i] = ast.NewIdent(arg)     }       return &ast.CallExpr{         Fun:  funcExpr,         Args: argsExpr,     }, nil }
　　由于出参需要等函数执行完毕后执行，所以打印出参的语句还需要放在  defer   函数内执行。 // NewFuncLitDefer 产生一个 defer 语句，运行一个匿名函数，函数体是入参语句列表 func NewFuncLitDefer(funcStmts ...ast.Stmt) *ast.DeferStmt {     return &ast.DeferStmt{         Call: &ast.CallExpr{             Fun: NewFuncLit(&ast.FuncType{}, funcStmts...),         },     } }修改函数体
　　至此我们已经获得了打印入参和出参的语句，接下来就是把他们放在原本函数体的最前面，保证开始和结束时执行。  toBeAddedStmts := []ast.Stmt{     &ast.ExprStmt{X: beforeExpr},     // 离开函数时的语句使用 defer 调用     NewFuncLitDefer(&ast.ExprStmt{X: afterExpr}), }   // 我们将添加的语句放在函数体最前面 funcDecl.Body.List = append(toBeAddedStmts, funcDecl.Body.List...)运行
　　为了测试我们的注释注解是否工作正确，我们使用如下代码进行测试：  package main   import (     ＂context＂     ＂logannotation/testdata/log＂ )   func main() {     fn(context.Background(), 1, ＂2＂, ＂3＂, true) }   // @Log() func fn(ctx context.Context, a int, b, c string, d bool) (int, string, string) {     log.Logger.WithContext(ctx).Infof(＂#fn executing...＂)     return a, b, c }
　　运行  go run logannotation/cmd/generator /Users/idealism/Workspaces/Go/golang-log-annotation/testdata   执行代码生成，在 /Users/idealism/Workspaces/Go/golang-log-annotation/testdata/_gen   下可找到生成的代码： package main   import (     ＂context＂     ＂logannotation/testdata/log＂ )   func main() {     fn(context.Background(), 1, ＂2＂, ＂3＂, true) }   func fn(ctx context.Context, a int, b, c string, d bool) (_0 int, _1 string, _2 string) {     log.Logger.WithContext(         ctx).WithField(＂filepath＂, ＂/Users/idealism/Workspaces/Go/golang-log-annotation/testdata/main.go＂).Infof(＂#fn start, params: %+v, %+v, %+v, %+v＂, a, b, c, d)     defer func() {         log.Logger.WithContext(             ctx).WithField(＂filepath＂, ＂/Users/idealism/Workspaces/Go/golang-log-annotation/testdata/main.go＂).Infof(＂#fn end, results: %+v, %+v, %+v＂, _0, _1, _2)     }()       log.Logger.WithContext(ctx).Infof(＂#fn executing...＂)     return a, b, c }
　　可以看到已经按照我们的想法正确生成了代码，并且运行后能按照正确的顺序打印正确的入参和出参。实际使用时会在  ctx   中加入 apm 的 traceId   ，并且在 logrus   的 Hooks   中将其在打印前放入到 Fields   中，这样搜索的时候可以将同一请求的所有日志聚合在一起。 INFO[0000] #fn start, params: 1, 2, 3, true              filepath=/Users/idealism/Workspaces/Go/golang-log-annotation/testdata/main.go INFO[0000] #fn executing...                              INFO[0000] #fn end, results: 1, 2, 3                     filepath=/Users/idealism/Workspaces/Go/golang-log-annotation/testdata/main.go扩展
　　以上代码是一种简单方式地定制化处理注解，仅处理了打印日志这一逻辑，当然还存在更多扩展的可能性和优化。  注册自定义注解（这样可以把更多重复逻辑抽出来，例如：参数校验、缓存等逻辑）  同时使用多个注解  注解解析成语法树，支持注解参数  生成的代码仅在需要时换行
　　相关  Demo   可以在 golang-log-annotation  找到。