前言&引入

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

posted on 2019-03-31 16:27  MnCu  阅读(955)  评论(0编辑  收藏  举报