GitCode 开源社区

前言&引入

一个好的log模块可以帮助我们排错，分析，统计

一般来说log中需要有时间、栈信息(比如说文件名行号等)，这些东西一般某些底层log模块已经帮我们做好了。但在业务中还有很多我们需要记录的信息，比如说：在web开发中，如果我们接收到一条request，我们可能需要执行很多操作，最基本的：

• 请求数据是要记录的
• response也是要记录的

如果仅仅只有这两条的话我们实际上是可以将消息放到一行来展示，但更复杂的情况是也可能还需要记录某些其他的信息，比如说我们在这次请求中将某个消息放入了消息队列，我们可能需要将这个消息是否放置成功，内容是什么，等等记录下来。如果分行记录的话当出现问题需要排查的话可能会十分麻烦，因为线上的环境一般是并发的，我们无法保证同一个请求中的日志每行都挨在一起，所以我们一般需要一个requestId来区分哪些日志是同一个请求所产生的。所以我们可能需要这样的请求处理函数:

func HandleRequest(requestId string, requestData []byte) (response []byte) {
    log.Info(requestId, requestData)
    ...
    log.Info(requestId, "do something: A")
    ...
    log.Info(requestId, "do something: B")
    ...
    log.Info(requestId, response)
    ...
}

但这样是不是很麻烦!每次打印日志都需要额外的手动记录requestId，我们需要有个通用的东西统一记录requestId，然后只需要将msg作为参数放置进去就行了。

那么我们可能会想到一个解决办法：每个Request都作为一个结构体，这个结构体包含了一个prefix字段，用来存储像requestId这样的需要预置的前缀，那么这个结构体可能看起来是这样的：

type Request struct {
    Header []byte
    Body []byte
    Method []byte
    Url []byte
    ...
    prefix string
}

func (r *Request) Info(msg []byte) {
    log.Info(r.prefix, msg)
}

func (r *Request) SetPrefix(prefix string) {
    r.prefix = prefix
}

那么我们前面的请求处理函数可能就像这样：

func HandleRequest(r *Request) (response []byte) {
    r.Info(requestData)
    ...
    r.Info("do something: A")
    ...
    r.Info("do something: B")
    ...
    r.Info(response)
    ...
}

到这里似乎大功就告成了，但新的问题来了，因为项目中用到了http2.0，一个连接可以处理多个请求，你的老大希望每个连接都要记录日志，且能正确区分不同的连接。这时候你可能想都没想就给连接结构体Conn加上了prefix字段，然后给Conn加上了Info等记录方法，但聪明的你忽然发现自己似乎是在做一些重复的工作，为何不把日志抽离出来？于是就像这样：

// r.go
type PrefixLog struct {
    prefix string
}

func NewPrefixLog(prefix string) (pl *PrefixLog){
    return $PrefixLog{prefix}
}

func (pl *PrefixLog) Info(msg []byte){
    Log.Info(pl.prefix, msg) // 假设这里行号是30
}

type Request struct {
    Header []byte
    Body []byte
    Method []byte
    Url []byte
    ...
    *PrefixLog
}

type Conn struct {
    requestCount uint32
    *PrefixLog
}
...

这次基本大功告成！但似乎新的问题又来了，假如为了更方便的排错，我们在日志需要保存log的文件名行号信息的话，上面这种形式就有问题了，因为通过这种方式调用的话所有的日志的文件名和行号都是相同的: file_name: r.go line:30，这该咋办呢？

正文

frp中的log模块相对简单，其封装了beego的log模块，主要逻辑写在utils/log文件中，来分析一下该文件。

全局变量之Log

import (
    "github.com/fatedier/beego/logs"
)

// Log is the under log object
var Log *logs.BeeLogger

这个Log变量是frp中log模块的核心，几乎所有(或者说就是所有)的日志都是由这个Log变量来负责操作的。

初始化之init函数

func init() {
    Log = logs.NewLogger(200)
    Log.EnableFuncCallDepth(true)
    Log.SetLogFuncCallDepth(Log.GetLogFuncCallDepth() + 1)
}

这个init函数则初始化了Log对象，注意Log.SetLogFuncCallDepth(Log.GetLogFuncCallDepth() + 1)这句，大体上就是：我们的程序可以说是由一个一个的函数组成，这些函数之间相互调用，每调用一个函数就进行了一次入栈操作，当某个函数执行完就执行了出栈操作，而loggerFuncCallDepth则表示要访问的栈的位置。

关于calldepth

那这个东西有啥用呢？我们知道我们打印日志的时候有的时候希望能够在日志中输出执行log的文件以及行号信息，拿go标准库log举个例子:

// main 文件
func a() {
    ...
    b("hell0") // 假如该行行号为10
    ...
}

func wtf(msg string) {
    ...
    msg = "[WTF!!]: " + msg
    log.Printf(msg) // 假如该行行号为21
    ...
}

func main() {
    a()
}

// 标准库log中的Printf方法，注意其内部调用了Output方法，且第一个参数为2
func Printf(format string, v ...interface{}) {
    std.Output(2, fmt.Sprintf(format, v...))
}

// 这是真正执行了打印的方法
func (l *Logger) Output(calldepth int, s string) error {
    ...
}

这里函数的调用顺序是main -> a -> wtf -> log.Printf -> Output，可以说这是一个深度为5的栈，calldepth为0表示栈顶，也就是Output对应的栈空间，1则表示log.Printf对应的栈空间，2表示wtf对应的栈空间，3表示wtf......以此类推。因为log模块设置的callpath是2，也就是假如我们设置了Llongfile或者Lshortfile标识符的时候输出的文件名是main，行号为21，假如我们设置callpath为3的话，输出的文件名依然是main但行号则变为了10。

打印函数

这里打印函数就拿Info来说明吧

func Info(format string, v ...interface{}) {
    Log.Info(format, v...)
}

可以看到Info函数实际上就是调用了Log.Info方法，Log.Info做了很多关于并发控制，格式输出，buffer写入的操作，但其最主要就是做了“将我们要打印的文字输出出来”这个操作。

log文件中唯一的一个结构体: PrefixLogger

type PrefixLogger struct {
    prefix    string
    allPrefix []string
}

func (pl *PrefixLogger) AddLogPrefix(prefix string) {
    if len(prefix) == 0 {
        return
    }

    pl.prefix += "[" + prefix + "] "
    pl.allPrefix = append(pl.allPrefix, prefix)
}

// 同样，这里也仅仅列出PrefixLogger的Info方法
func (pl *PrefixLogger) Info(format string, v ...interface{}) {
    Log.Info(pl.prefix+format, v...)
}

PrefixLogger实际上就是一个具有前缀功能的很简单的结构体。