Logrus 日志分析

概述

这是我在了解 Logrus 这个日志库时做的一个笔记记录，主要是介绍一些 logrus 的特性，以及我尝试这些特性时的一些个人观点，同时，我还会简单解析一下 logrus 是如何实现这些特性的。

核心组件

Logger
    - Out io.Writer
    - Hooks LevelHooks
    - Formatter Formatter
    - Level Level
    - entryPool sync.Pool
    - BufferPool BufferPool
Hook                    <interface>
    - Levels() []Level
    - Fire(*Entry) error
Formatter                <interface>
    - Format(*Entry) ([]byte, error)
Entry
    - Logger *Logger
    - Data Fields
    - Time time.Time
    - Level Level
    - Caller *runtime.Frame
    - Buffer *bytes.Buffer
    - Context context.Context

组件交互顺序

所以从核心组件的字段来看，大概也可以了解到顺序是怎么样的，这里再给出一张图以打印一个 Info 级别的日志内容来看下实际顺序是怎么样的：

代码版本：v1.8.1

[root@liqiang.io]# logrus.Infof("xxxx")
logger.go:164 func (logger *Logger) Infof(format string, args ...interface{}) {
    --> logger.go:165 logger.Logf(InfoLevel, format, args...)
        --> logger.go:148 func (logger *Logger) Logf(level Level, format string, args ...interface{}) {
            --> logger.go:149 if logger.IsLevelEnabled(level) {
            --> logger.go:150     entry := logger.newEntry()
                --> logger.go:96 entry, ok := logger.entryPool.Get().(*Entry)
            --> logger.go:151     entry.Logf(level, format, args...)
                --> entry.go:336 func (entry *Entry) Logf(level Level, format string, args ...interface{}) {
                    --> entry.go:337 if entry.Logger.IsLevelEnabled(level) {
                    --> entry.go:338     entry.Log(level, fmt.Sprintf(format, args...))
                        --> entry.go:292 if entry.Logger.IsLevelEnabled(level) {
                        --> entry.go:293     entry.log(level, fmt.Sprint(args...))
                            --> entry.go:221 func (entry *Entry) log(level Level, msg string) {
                                --> entry.go:224 newEntry := entry.Dup()
                                --> entry.go:233 newEntry.Logger.mu.Lock()
                                --> entry.go:234 reportCaller := newEntry.Logger.ReportCaller
                                --> entry.go:235 newEntry.Logger.mu.Unlock()
                                --> entry.go:237 if reportCaller {
                                --> entry.go:238     newEntry.Caller = getCaller()
                                --> entry.go:241 newEntry.fireHooks()
                                    --> entry.go:265 entry.Logger.mu.Lock()
                                    --> entry.go:266 tmpHooks = make(LevelHooks, len(entry.Logger.Hooks))
                                    --> entry.go:267 for k, v := range entry.Logger.Hooks {
                                    --> entry.go:268     tmpHooks[k] = v
                                    --> entry.go:270 entry.Logger.mu.Unlock()
                                    --> entry.go:272 err := tmpHooks.Fire(entry.Level, entry)
                                        --> hooks.go:27 for _, hook := range hooks[level] {
                                        --> hooks.go:28     if err := hook.Fire(entry); err != nil {
                                --> entry.go:243 buffer = getBuffer()
                                --> entry.go:249 newEntry.Buffer = buffer
                                --> entry.go:251 newEntry.write()
                                    --> entry.go:279 serialized, err := entry.Logger.Formatter.Format(entry)
                                    --> entry.go:284 entry.Logger.mu.Lock()
                                    --> entry.go:285 defer entry.Logger.mu.Unlock()
                                    --> entry.go:286 if _, err := entry.Logger.Out.Write(serialized); err != nil {
            --> logger.go:152     logger.releaseEntry(entry)
                --> logger.go:104 entry.Data = map[string]interface{}{}
                --> logger.go:105 logger.entryPool.Put(entry)

从上面可以看出，主要的业务逻辑还是在 Entry 中完成，然后 Entry 中包含了一个 Logger 的引用，formatter 和 hook 都是通过这个引用来获取的，然后在 entry 中执行，同时还需要注意到的是这里面调用了好几次的锁，但是持续时间都很短，可能性能影响也不是很大（这个需要 benchmark 一下看看）。

总的来说，整体链条都还比较清晰，没有过于复杂的设计，概念也比较明确，所以就不看再多的东西了，值得学习的一个是这里面用到了几个池，这个对于高性能场景还是很有借鉴意义的，减少内存的分配和回收，还有比如一些小细节：tmpHooks = make(LevelHooks, len(entry.Logger.Hooks))，这些都是值得学习的。

问题解答

hook 是什么

hook 是对特定的 log level 执行的一段代码，可以针对特定的 log level 做特定的工作，例如 Error 的时候，向错误跟踪服务发送一个信息之类的。（我觉得不是太必要，可以通过多个 handler 来实现？）

Formatter 是什么

interface 定义：

[root@liqiang.io]# cat formatter.go
type Formatter interface {
    Format(*Entry) ([]byte, error)
}

就是定义怎么将 Entry 转化成 []byte 的结构。

比较独特的特性

Fatal 处理器
线程安全
- 不管是不注册 hook，还是注册的 hook 执行都是线程安全的.
- 写出 logger.Out 也是安全的:
  - 从上面可以看到这个写出 logger.Out 过程是加锁的，当然，这在一定程度上降低了性能；
  - 但是如果 logger.Out 是一个以 O_APPEND 标志打开的 os 文件的话，并且每次写出数据都小于 4K，其实也可以不加锁，这样性能会高很多。
    - Why？see also：Are Files Appends Really Atomic?

一些评价

优点

完全兼容 Go 的标准库日志模块，日志级别也比较全面;
结构化的日志管理，和一条日志记录不一样，有利于日志分析；
允许使用者通过 hook 的方式将日志分发到其他的地方，但是，我觉得不是必须的；
Entry 的实现对于共同上下文的场景很有帮助；
可以通过 Formmater 自定义日志的格式；
线程安全：日志并发写操作通过 mutex 进行保护的。

坏处

对于日志输出，没有携带行号和文件名，这个比较遗憾，但是通过 Caller 可以获取到函数名（大概可以定位到哪个文件了）；
输出到本地文件系统没有提供日志分割功能，这是别人吐槽的一个观点，但是我不支持，我认为者不属于日志库的功能；
结构化的日志有利于分析，但是其实也不利于开发阅读，所以这其实是一种选择，但是对于真实工业环境，我觉得这也不算一个缺点吧。

格物致知

All Posts