frp源码剖析-frp中的log模块

前言&引入

一个好的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实际上就是一个具备前缀功能的很简单的结构体。