Go实现日志2——支持结构化和hook

代码保存在：https://github.com/liwook/Go-projects/tree/main/log/sulogV2

1.日志结构化

日志记录的事件以结构化格式(键值对，或通常是 JSON)表示，随后可以通过编程方式对其进行解析，便于对日志进行监控、警报、审计等其他形式的分析。

结构化的格式例子。

time=2023-10-08T21:09:03.912+08:00 level=INFO msg=TextHandler 姓名=陈

那这里就要回顾下(entry).log方法。

func (e *Entry) log(level Level, msg string) {e.Message = msg,e.Time = time.Now(),e.Level = levele.File, e.Line, e.Func = file, line, runtime.FuncForPC(pc).Name()e.Func = e.Func[strings.LastIndex(e.Func, "/")+1:]e.write()
}func (e *Entry) write() {e.logger.mu.Lock()defer e.logger.mu.Unlock()e.logger.opt.formatter.Format(e)e.logger.opt.output.Write(e.Buffer.Bytes())
}

在e.write()中，其主要是两步：按照规定的格式化数据后，把信息存在e.Buffer中；然后经由e.write()写入。重点在格式化数据那步，所以我们要看e.format方法。

那就回到Formatter接口。而JSON类型的是已经结构化的，重点来看看TEXT文本格式的。

文本格式结构化

在formatter.go文件中添加些常量：

//formatter.go
const (defaultTimestampFormat = time.RFC3339KeyMsg                 = "msg"KeyLevel               = "level"KeyTime                = "time"KeyFunc                = "func"KeyFile                = "file"
)

在formatter_text.go中进行修改添加：

//formatter_text.go
// 格式是： 时间 日志等级 文件:所在行号 函数名称 日志内容
func (f *TextFormatter) Format(e *Entry) error {if !f.DisableTimestamp {if f.TimestampFormat == "" {f.TimestampFormat = time.RFC3339}f.appendKeyValue(e.Buffer, KeyTime, e.Time.Format(f.TimestampFormat))}f.appendKeyValue(e.Buffer, KeyLevel, LevelName[e.Level])    //添加日志等级if !e.logger.opt.disableCaller {if e.File != "" {short := e.Filefor i := len(e.File) - 1; i > 0; i-- {if e.File[i] == '/' {short = e.File[i+1:]break}}//添加函数名和文件名f.appendKeyValue(e.Buffer, KeyFunc, short)f.appendKeyValue(e.Buffer, KeyFile, e.File+":"+strconv.Itoa(e.Line))}}f.appendKeyValue(e.Buffer, KeyMsg, e.Message)e.Buffer.WriteString("\n")return nil
}//上一节的写法，没有结构化的
func (f *TextFormatter) Format(e *Entry) error {if !f.DisableTimestamp {if f.TimestampFormat == "" {f.TimestampFormat = time.RFC3339}e.Buffer.WriteString(fmt.Sprintf("%s %s", e.Time.Format(f.TimestampFormat), LevelNameMapping[e.Level]))} else {e.Buffer.WriteString(LevelNameMapping[e.Level])}if e.File != "" {short := e.Filefor i := len(e.File) - 1; i > 0; i-- {if e.File[i] == '/' {short = e.File[i+1:]break}}e.Buffer.WriteString(fmt.Sprintf(" %s:%d %s", short, e.Line, e.Func))}e.Buffer.WriteString(" ")e.Buffer.WriteString(e.Message)e.Buffer.WriteByte('\n')return nil
}

新的Format方法也好理解，主要是增添了调用appendKeyValue方法，该方法是进行键值对格式书写的。

func (f *TextFormatter) appendKeyValue(b *bytes.Buffer, key string, value any) {if b.Len() > 0 {b.WriteByte(' ')}b.WriteString(key)b.WriteByte('=')f.appendValue(b, value)
}func (f *TextFormatter) appendValue(b *bytes.Buffer, value any) {stringVal, ok := value.(string)if !ok {stringVal = fmt.Sprint(value)b.WriteString(stringVal)} else {b.WriteString(fmt.Sprintf("%q", stringVal)) //这样就是加""符号的}
}

到现在TEXT文本格式的也可以进行结构化输出了。

sulog.Info("hello info")//输出结果
time="2024-01-29T11:45:33+08:00" level="INFO" func="main.go" file="D:/code/gWork/log/sulogV2/cmd/main.go:42" msg="hello info"

增添WithField和WithFields

做到这一步还不够，还有这种需求，想额外输出name="li" age=13这种的。就不单单是输出msg=...。

level="INFO" func="main.go" file="D:/code/gWork/log/sulogV2/cmd/main.go:42" msg="hello info" name="li" age=13

代码使用例子：两个方法WithField和WithFields

	sulog.WithField("age", "11").Info("ok withField")sulog.WithFields(sulog.Fields{"name":  "li","age":   32,}).Info("ok withFields")

调用WithField后，还可以继续调用，说明其返回值应该是logger或者entry。

在logger.go中添加这两个方法，该方法返回值是*Entry。这两个方法都需要从entryPool中获取一个entry。

//optins.go
// Fields type, used to pass to `WithFields`.
type Fields map[string]any//logger.go
func (l *logger) WithField(key string, value any) *Entry {entry := l.entry()defer l.releaseEntry(entry)return entry.WithField(key, value)
}func (l *logger) WithFields(fields Fields) *Entry {entry := l.entry()defer l.releaseEntry(entry)return entry.WithFields(fields)
}//全局的 std
func WithField(key string, value any) *Entry {return std.WithField(key, value)
}func WithFields(fields Fields) *Entry {return std.WithFields(fields)
}

那接着就到了结构体Entry中了。(Entry).WithField也是调用WithFields。

而在WithFields方法的参数中，fields的键值对的值是any类型，所以需要用到reflcect来进行类型判别筛选。WithFields返回值是*Entry，该方法中是返回了一个新Entry，所以需要拷贝*logger,data属性。

//entry.go
type Entry struct {//该结构体其他的没有改变，只是DataMap不再使用，改为使用Data,基本是一样的意思的// DataMap map[string]any //为了日志是json格式使用的Data    Fields //保存WithField中的数据.................
}// Add a single field to the Entry.
func (entry *Entry) WithField(key string, value any) *Entry {return entry.WithFields(Fields{key: value})
}// Add a map of fields to the Entry.
func (entry *Entry) WithFields(fields Fields) *Entry {data := make(Fields, len(entry.Data)+len(fields))//为了可以这样使用sulog.WithField("name","li").WithField("addr","zhong").Info(1)for k, v := range entry.Data {data[k] = v}for k, v := range fields {isErrField := falseif t := reflect.TypeOf(v); t != nil {//如果value类型是函数类型，是不符合要求的if t.Kind() == reflect.Func || (t.Kind() == reflect.Pointer && t.Elem().Kind() == reflect.Func) {isErrField = true}}if isErrField {tmp := fmt.Sprintf("can not add field %q", k)fmt.Println(tmp)} else {data[k] = v}}return &Entry{logger: entry.logger, Data: data}
}

WithFields返回*Entry后可以继续打印日志，说明Entry也需要实现Debug这些方法。

// entry打印方法
func (e *Entry) Debug(args ...any) {e.Log(3, DebugLevel, args...)        //3是调用 runtime.Caller() 时，传入的栈深度
}// 自定义格式
func (e *Entry) Debugf(format string, args ...any) {e.Logf(3, DebugLevel, format, args...)
}

在sulog.WithField("age", "11").Info("ok withField")代码中，WithField后会进行releseEntry，即entry.Buffer也被重置了。那要获取到之前的Buffer的话，那就需要在WithFields中拷贝entry.Buffer(或者重新new)，这可能会浪费些性能。

func (entry *Entry) WithFields(fields Fields) *Entry {data := make(Fields, len(entry.Data)+len(fields)).........................//return &Entry{logger: entry.logger, Data: data}return &Entry{logger: entry.logger, Data: data,Buffer:entry.Buffer}//拷贝Buffer
}

再看回到使用entry.Buffer的地方(entry).log方法中，这里是没有对entry.Buffer进行new的，直接使用的话，是会出问题的。

所以我们也可以仿照entryPool那样，也使用sync.Pool类型来做一个Buffer池。

在logger中添加sync.Pool类型的Buffer池

在logger结构体中添加如下

type logger struct {.............entryPool  *sync.PoolbufferPool *sync.Pool    //添加Buffer池
}func New(opts ...Option) *logger {logger := &logger{opt: initOptions(opts...), Hooks: make(LevelHooks)}logger.entryPool = &sync.Pool{New: func() any { return entry(logger) }}//初始化bufferPoollogger.bufferPool = &sync.Pool{New: func() any { return new(bytes.Buffer) }}return logger
}//entry.go
//创建entry  的方法就有了改变，不再需要new(bytes.Buffer)
func entry(logger *logger) *Entry {return &Entry{logger: logger,// Buffer:  new(bytes.Buffer),// DataMap: make(map[string]any, 5)Data: make(map[string]any, 5),}
}

之后修改(Entry).log方法，在其中通过bufferPool获取Buffer。

func (e *Entry) log(depth int, level Level, msg string) {e.Time = time.Now()e.Level = levele.Message = msgif !e.logger.opt.disableCaller {if pc, file, line, ok := runtime.Caller(depth); !ok {e.File = "???"e.Func = "???"} else {e.File, e.Line, e.Func = file, line, runtime.FuncForPC(pc).Name()e.Func = e.Func[strings.LastIndex(e.Func, "/")+1:]}}bufPool := e.logger.bufferPoolbuffer := bufPool.Get().(*bytes.Buffer)//获取buffere.Buffer = bufferdefer func() {    //使用完后，放回bufferPool池中e.Buffer = nilbuffer.Reset()bufPool.Put(buffer)}()e.write()
}

而且这样写，使用sulog.Info("info")也正常了，因为创建entry时候是没有new(bytes.Buffer)。

接着来看看测试例子：

sulog.WithField("name", "11").Info("ok withField")
sulog.WithFields(sulog.Fields{"name": "li","age":  32,}).Info("ok withFields")//打印结果
time="2024-01-29T13:52:42+08:00" level="INFO" func="main.go" file="D:/code/gWork/log/sulogV2/cmd/main.go:46" msg="ok withField" name="11"
time="2024-01-29T13:52:42+08:00" level="INFO" func="main.go" file="D:/code/gWork/log/sulogV2/cmd/main.go:50" msg="ok withFields" age=32 name="li"

区分WithField中的键"level" 和 sulog.Info()中的"level"

到这里是基本完成了，但还是可能会有问题，比如：

sulog.WithField("level", "debug").Info("ok withField")

这种日志等级应该是info,但是在WithField中level写到是debug,那就会有冲突了。时间和函数名那些要是也这样写的话，也会有冲突的。那该怎么做呢，那就做个区分，只要是在WithField中的，一致使用field.*来表示，level就用field.level来表示。

在formatter.go文件中添加如下代码：

该函数功能是查看WithField中要是有"level","file"这些，就把key修改成"fields.levle"等等。

//data是WithField方法中的数据
func prefixFieldClashes(data Fields) {for k, v := range data {switch k {case KeyMsg:data["fields."+KeyMsg] = vdelete(data, KeyMsg)case KeyLevel:data["fields."+KeyLevel] = vdelete(data, KeyLevel)case KeyFunc:data["fields."+KeyFunc] = vdelete(data, KeyFunc)case KeyTime:data["fields."+KeyTime] = vdelete(data, KeyTime)case KeyFile:data["fields."+KeyFile] = vdelete(data, KeyFile)}}
}

那么在JSON格式和TEXT格式的Format方法中使用。

func (f *JsonFormatter) Format(e *Entry) error {data := make(Fields, len(e.Data)+5)prefixFieldClashes(e.Data)for k, v := range e.Data {data[k] = v}if !f.DisableTimestamp {if f.TimestampFormat == "" {f.TimestampFormat = time.RFC3339}data[KeyTime] = e.Time.Format(f.TimestampFormat)}data[KeyLevel] = LevelName[e.Level]if e.File != "" {data[KeyFile] = e.File + ":" + strconv.Itoa(e.Line)data[KeyFunc] = e.Func}data[KeyMsg] = e.Messagereturn sonic.ConfigDefault.NewEncoder(e.Buffer).Encode(data)
}//TEXT文本格式的
func (f *TextFormatter) Format(e *Entry) error {prefixFieldClashes(e.Data)if !f.DisableTimestamp {................}...............f.appendKeyValue(e.Buffer, KeyMsg, e.Message)//加上WithField()中的for k, v := range e.Data {f.appendKeyValue(e.Buffer, k, v)}e.Buffer.WriteString("\n")return nil
}

来看看测试结果

	sulog.SetOptions(sulog.WithDisableCaller(true))sulog.SetOptions(sulog.WithFormatter(&sulog.JsonFormatter{DisableTimestamp: true}))sulog.WithFields(sulog.Fields{"level": "info","name":  "lihai","msg":   "this field message",}).Info("ok withField")//打印结果
{"fields.msg":"this field message","name":"lihai","fields.level":"info","level":"INFO","msg":"我们ok withField"}

在使用该日志时，鼓励用sulog.WithFields(log.Fields{}).Infof() 这种方式替代sulog.Infof("Failed to send event %s to topic %s")，也就是不是用 %s，%d 这种方式格式化，而是直接传入变量 event，topic 给 log.Fields ，这样就显得结构化日志输出，很人性化美观。

2.支持hook

钩子（Hooks），可以理解成函数，可以让我们在日志输出前或输出后进行一些额外的处理。常见的使用场景包括发送邮件、写入数据库、上传到云端等。

一个日志，是有很多日志等级的，那就可能需要筛选出符合条件的等级才能触发hook。

在logger结构体中添加变量Hooks：

即是可以添加多个日志等级的hook,一个日志等级可以有多个hook。

//新添加hooks.go文件，添加该类型
type LevelHooks map[Level][]Hook//logger.go
type logger struct {...................Hooks LevelHooks //多个日志等级的多个hook
}

定义Hook

其肯定是有对应的可执行的日志等级列表和执行的函数这两个的。

给用户使用，那我们可以定义成接口，命名为Hook。

用户实现Hook接口即可。

type Hook interface {Levels() []LevelFire(*Entry) error
}

所以在Hook中用户需要做的就是在Fire方法中定义想如何操作这一条日志的方法，在Levels方法中定义想展示的日志级别。

给LevelHooks添加方法

那肯定是有添加hook（Add）和执行所有hook(Fire)的方法。

func (hooks LevelHooks) Add(hook Hook) {for _, level := range hook.Levels() {hooks[level] = append(hooks[level], hook)}
}//执行日志等级列表中全部hook
func (hooks LevelHooks) Fire(level Level, entry *Entry) error {for _, hook := range hooks[level] {if err := hook.Fire(entry); err != nil {return err}}return nil
}

那在logger结构体中增加AddHook方法。

// 添加hook
func (l *logger) AddHook(hook Hook) {//用锁，保证了执行hook时候就不能添加hookl.mu.Lock()defer l.mu.Unlock()l.Hooks.Add(hook)
}func AddHook(hook Hook) {std.AddHook(hook)
}

很明显，(LevelHooks).Add在(logger).AddHook中调用了，而Fire没有使用，那这样的话，钩子函数就没有能执行。

执行hook

那其应该是在哪被调用呢？应该在（Entry).log中。

func (e *Entry) log(depth int, level Level, msg string) {............if !e.logger.opt.disableCaller {.....................}e.fireHooks()    //执行hook, 就是在这添加这句bufPool := e.logger.bufferPool...............e.write()
}//这种写法不好，执行hook时候一直霸占锁，不妥
func (entry *Entry) fireHooks() {entry.logger.mu.Lock()err := entry.logger.Hooks.Fire(entry.Level, entry)if err != nil {fmt.Fprintf(os.Stderr, "Failed to fire hook: %v\n", err)}entry.logger.mu.Unlock()
}

一般是很容易想到上面的fireHooks的实现，但这种实现不好，要是hook是比较耗时的操作，那就会一直霸占锁，可以会引起阻塞。

解决办法：我们可以用个临时变量把所有的hook拷贝过来，之后就可以释放锁，然后就可以执行hook。这样就不会长时间霸占锁。

func (entry *Entry) fireHooks() {var tmpHooks LevelHooks    //临时变量entry.logger.mu.Lock()tmpHooks = make(LevelHooks, len(entry.logger.Hooks))//进行拷贝for k, v := range entry.logger.Hooks {tmpHooks[k] = v}entry.logger.mu.Unlock()err := tmpHooks.Fire(entry.Level, entry) //执行hookif err != nil {fmt.Fprintf(os.Stderr, "Failed to fire hook: %v\n", err)}
}

测试：

实现Hook接口。

type hook struct{}func (h *hook) Levels() []sulog.Level {// return sulog.AllLevelsreturn []sulog.Level{sulog.InfoLevel, sulog.DebugLevel}//只有info和debug两种等级
}func (h *hook) Fire(entry *sulog.Entry) error {fmt.Printf("send emial. this is a hook func:%v\n", entry.Data)return nil
}func main() {sulog.SetOptions(sulog.WithDisableCaller(true))sulog.SetOptions(sulog.WithFormatter(&sulog.TextFormatter{DisableTimestamp: true}))sulog.AddHook(&hook{})sulog.WithField("name", "11").Info("ok withField")fmt.Println()sulog.WithField("country", "China").Error("ok withField")
}

效果：

this is a hook func:map[name:11]
level="INFO" msg="ok withField" name="11"level="ERROR" msg="ok withField" country="China"