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