Go如何优雅的记录操作日志

站长

2022年12月03日 07:43 · 阅读数 419

这篇文章比较硬核，会涉及到这几个知识点：协程、协程池、钩子函数、中间件以及异步方法的使用，文章最后会带大家去阅读Async的源码，了解其底层实现。

应用场景

管理后台需要记录登录用户的各种操作日志，便于出现问题时追溯管理员做了哪些操作。

同时我们也需要记录每次的请求日志到log文件中，供开发人员定位问题。

我们需要考虑哪些问题呢？

注意问题

首先需要全局添加操作日志的记录，即用户登录后的各种操作都要记录
日志记录的操作应该尽量避免对主程序的影响，不能因为记录日志而浪费性能
要记录的数据应该定义好规则，统一管理、统一入参。

先说结论

我们会用到以下知识点，来实现上面的场景，解决上面提到的注意问题：

group.Hook()和HookAfterOutput 在全局添加日志记录的入口
使用中间件实现字段的统一管理、统一入参
使用Go的协程机制提高记录日志的效率，并发执行，存入DB，供管理后台查看使用（在这里我们使用GoFrame的grpool更好的管理协程）
使用g.Log()的Async()特性异步保存请求日志到文件，方便我们技术人员查错使用。

实现流程

前言

下面的示例代码基于GoFrame 1.16版本实现，在这里不再赘述项目初始化等基础问题，感兴趣的同学可以查看这篇文章：GoFrame入门实践，里面介绍了GoFrame的特点，以及我按照官方文档学习踩得一些坑。

为了方便大家看懂逻辑，不重要的代码用使用三个竖着的.省略；GoFrame框架在下文简称gf框架。

路由文件

我们定义了ApiLog的中间件，在业务路由方法之前调用
我们定义了log()函数，其中应用到了gf框架路由的钩子函数group.Hook，用于在接口返回业务数据之后记录操作日志。
log()函数的位置在登录路由之后，业务逻辑路由之前。

package app

func Run() {
   s := g.Server()
   s.Use(middleware.Cors.CORS)
   s.Use(middleware.Logs.ApiLog)
   //AKSK换取token
   account.Token()
   //账号登录
   account.Login()
   //操作日志
   log(s)
   admin.Init(s)
   .
   .
   .
   s.Run()
}

func log(s *ghttp.Server) {
   s.Group("/", func(group *ghttp.RouterGroup) {
      group.Hook("/*", ghttp.HookAfterOutput, oper_log.OperLog.OperationLog)
   })
}

操作日志记录

下面我们来重点看一下上文中提到的钩子函数中的OperationLog()方法都实现了哪些功能，是如何实现的？

首先通过路由上下文函数获取了登录中间件中设置的UID，对登录态进行判断，只有UID不为0时才记录
根据UID去账号服务中台获取账号相关信息，用于后续的信息登记
subUserId和userNickname等都通过账号服务中台获得
本次请求的url通过r.Request对象获取
通过一系列逻辑处理，我们拼装好了需要登记的数据data
最后我们将data数据传入Invoke方法，通过协程池写入操作日志

// OperationLog 操作日志记录
func (s *operLog) OperationLog(r *ghttp.Request) {

   userId := gconv.Int(r.GetCtxVar(middleware.CtxUID))
   if userId == 0 {
      return
   }
   account, err := service2.Account.GetAccountInfo(userId)
   if nil != err {
      response.FailureCode(r, 0)
   }
   deptId := uint64(account.DeptId)
   userNickname := account.Name
   if "" == userNickname {
      userNickname = account.Phone
   }

    .
    .
    .

   userInfo := &dao.CtxUser{
      Id:           uint64(account.Id),
      UserName:     userNickname,
      SubId:        uint64(subUserId),
      DeptId:       deptId,
      UserNickname: userNickname,
      UserStatus:   account.Status,
      IsAdmin:      account.IsAdmin,
      Avatar:       "",
   }
   url := r.Request.URL //请求地址
   //获取菜单
   //获取地址对应的菜单id
    .
    .
    .

   data := &SysOperLogAdd{
      User:         userInfo,
      Menu:         menu,
      Url:          url,
      Params:       r.GetMap(),
      Method:       r.Method,
      ClientIp:     library.GetClientIp(r),
      OperatorType: 1,
   }
   s.Invoke(data)
}

使用grpool并发插入

方法非常简单，调用s.Pool.Add()方法即可。

func (s *operLog) Invoke(data *SysOperLogAdd) {
   s.Pool.Add(func() {
      //写入日志数据
      s.OperationLogAdd(data)
   })
}

是不是好奇OperationLogAdd做了什么事情，别着急，咱们接着往下看：

添加操作日志

我们最终的目的就是把上文传入的data数据存入DB

在存入DB之前我们会在做一些逻辑判断，校验传入的数据是否合规，合规则入库。

(PS：这里还有优化空间，比如我最近的一个心得体会是要充分解耦，明确各自的职责，比如可以优化成：入库前的函数做数据校验和数据组装，比如按照入库函数的要求提供数据；而入库函数不考虑校验的问题，只考虑如果以最高效的方式入库的问题。)

//OperationLogAdd 添加操作日志
func (s operLog) OperationLogAdd(data *SysOperLogAdd) {
    //省略参数校验
    .
    .
    .
    
   insertData := g.Map{
      dao.SysOperLog.C.Title:         menuTitle,
      dao.SysOperLog.C.Method:        data.Url.Path,
      dao.SysOperLog.C.RequestMethod: data.Method,
      dao.SysOperLog.C.OperatorType:  data.OperatorType,
      dao.SysOperLog.C.OperName:      data.User.UserName,
      dao.SysOperLog.C.Uid:           data.User.Id,
      dao.SysOperLog.C.SubUid:        data.User.SubId,
      dao.SysOperLog.C.DeptName:      deptName,
      dao.SysOperLog.C.OperIp:        data.ClientIp,
      dao.SysOperLog.C.OperLocation:  library.GetCityByIp(data.ClientIp),
      dao.SysOperLog.C.OperTime:      gtime.Now(),
   }    
    .
    .
    .
    
   _, err = dao.SysOperLog.Insert(insertData)
   if err != nil {
      g.Log().Error(err)
   }
}

到这里我们就已经知道如果利用协程池和钩子函数如何保持操作日志了。

是不是好奇上面提到的中间件，下面再来剖析一下日志中间件是如何实现的。

我们再来强调一下区别：

上文提到的协程池保存操作记录到DB中，是供管理员在管理后台查看的。

而日志中间件的作用是把每次网络请求的信息存入到log日志中，供开发人员查看。

请求日志中间件

我们通过下面的日志中间件可以记录：请求的链接、请求参数、响应数据、请求时间。

package middleware

import (
   "context"
   "github.com/gogf/gf/frame/g"
   "github.com/gogf/gf/net/ghttp"
   "github.com/gogf/gf/os/gtime"
   "github.com/gogf/gf/text/gregex"
   "github.com/gogf/gf/util/grand"
)

const (
   CtxAppKey      = "AK"
   CtxAppID       = "app_id"       //token|签名获取
   CtxAccountName = "account_name" //token获取
   CtxSubID       = "sub_id"       //token获取
    .
    .
    .
)

var Logs = logsMiddleware{}

type logsMiddleware struct{}

// Log 日志
func (s *logsMiddleware) Log(r *ghttp.Request) {
   r.SetCtxVar(RequestId, grand.S(20))
   r.SetCtxVar(CtxAppKey, r.GetHeader("Api-App-Key"))
   r.SetCtxVar(CtxIP, r.GetClientIp())
   r.SetCtxVar(CtxURI, r.RequestURI)
   r.Middleware.Next()
   errStr := ""
   if err := r.GetError(); err != nil {
      errStr = err.Error()
   }

   responseTime := gtime.TimestampMilli() - r.EnterTime
   g.Log().Ctx(r.Context()).Async(true).
      Cat("admin").
      Infof("请求参数: 【%v】 响应参数: 【%v】 响应时间:【%v ms】error:【%v】", r.GetBodyString(),
         r.Response.BufferString(), responseTime, errStr)
}

// ApiLog 日志
func (s *logsMiddleware) ApiLog(r *ghttp.Request) {
   r.SetCtxVar(RequestId, grand.S(20))
   r.SetCtxVar(CtxAppKey, r.GetHeader("Api-App-Key"))
   r.SetCtxVar(CtxIP, r.GetClientIp())
   r.SetCtxVar(CtxURI, r.RequestURI)

   var body, _ = gregex.ReplaceString(`\s`, "", r.GetBodyString())
   g.Log().Ctx(r.Context()).
      Cat("request").
      Infof("请求参数:【%v】", body)
   r.Middleware.Next()

   responseTime := gtime.TimestampMilli() - r.EnterTime
   g.Log().Ctx(r.Context()).Async(true).
      Cat("request").
      Infof("请求参数:【%v】响应参数:【%v】响应时间:【%v ms】", body, r.Response.BufferString(), responseTime)

}

func Ctx(req context.Context) (res context.Context) {
   res = context.Background()
   res = context.WithValue(res, RequestId, req.Value(RequestId))
   return
}

细心的同学会注意到这个方法：g.Log().Ctx(r.Context()).Async(true)，没错，我们是通过Async(true)异步的方式来记录日志的。