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 = level

	e.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.RFC3339
	KeyMsg                 = "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.File
			for 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.File
		for 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 := false
		if 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.Pool
	bufferPool *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) }}
    //初始化bufferPool
	logger.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 = level
	e.Message = msg

	if !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.bufferPool
	buffer := bufPool.Get().(*bytes.Buffer)//获取buffer
	e.Buffer = buffer
	defer func() {    //使用完后，放回bufferPool池中
		e.Buffer = nil
		buffer.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] = v
			delete(data, KeyMsg)
		case KeyLevel:
			data["fields."+KeyLevel] = v
			delete(data, KeyLevel)
		case KeyFunc:
			data["fields."+KeyFunc] = v
			delete(data, KeyFunc)
		case KeyTime:
			data["fields."+KeyTime] = v
			delete(data, KeyTime)
		case KeyFile:
			data["fields."+KeyFile] = v
			delete(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.Message

	return 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() []Level
	Fire(*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时候就不能添加hook
	l.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) //执行hook
	if 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.AllLevels
	return []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"