golang日志滚动-lumberjack源码学习

简述

在日常的开发过程中, 我们总会遇到日志文件需要滚动分割的需求. 在各大golang的日志库中, 有的实现了滚动分片功能, 有的干脆不提供, 且各种日志库的实现的方式都不相同. 这时如果我们想用任意一个日志库都做到日志滚动, 该怎么做呢?

最好的办法就是在初始化logger时, 用已经实现了日志滚动的writer替换掉原有的writer, 这样无论使用什么日志库, 都可以实现滚动功能. lumberjack就为我们提供了这样一个writer. 比如我们使用logrus日志库时, 只需在初始化时调用SetLogger()函数传入我们创建好的lumberjack writer就可以了.

源码分析

1. 代码统计

使用cloc工具进行源码统计, cloc --by-file-by-lang --exclude-dir=.github --exclude-lang=YAML,Markdown [project-dir], 结果如下(省略yaml等标记型语言相关统计):

File	blank	comment	code
./lumberjack_test.go	162	91	563
./linux_test.go	38	9	158
./testing_test.go	12	19	60
./rotate_test.go	4	2	19
./example_test.go	2	2	13
./lumberjack.go	69	137	335
./chown_linux.go	3	1	15
./chown.go	3	1	7
SUM:	293	262	1170

lumberjack的go代码总行数为1170行, 其中测试类代码占813(=563+158+60+19+13)行, 实际有效代码只有357行.

2.使用示例

我们以官方的示例作为开头, 代码如下:

log.SetOutput(&lumberjack.Logger{
    Filename:   "/var/log/myapp/foo.log",
    MaxSize:    500, // megabytes
    MaxBackups: 3,
    MaxAge:     28, //days
    Compress:   true, // disabled by default
})

使用方法也非常简单直接:

1. 初始化lumberjack.Logger
2. 设置日志库的output为上面初始化lumberjack logger

3. 详细解读

鉴于库中出去测试代码之外, 实际有效的文件只有3个, 且其中的两个只是简单封装了操作系统的chown api, 所以我们只看lumberjack.go这一个文件就够了.

lumberjack logger本质上就是个实现了golang的writer和closer接口的struct, 这也就意味着, 我们在使用它当做日志库的底层writer时, 只会用到它的Write()和Close()方法. 下面就来看看Write()方法的实现, 到底是如何做到滚动的, 代码如下:

func (l *Logger) Write(p []byte) (n int, err error) {
   l.mu.Lock() // 加锁防止多个协程同时写, 将日志写乱
   defer l.mu.Unlock()

   writeLen := int64(len(p))
   // 如果写入数据量大于设定的单个日志文件的大小, 则直接报错返回
   // 这意味着我们一定要保证每次写入的量一定要小于初始化logger时设置的MaxSize
   if writeLen > l.max() {
      return 0, fmt.Errorf(
         "write length %d exceeds maximum file size %d", writeLen, l.max(),
      )
   }

   // 打开文件
   if l.file == nil {
      if err = l.openExistingOrNew(len(p)); err != nil {
         return 0, err
      }
   }

   // 当要写入数据量加上当前已写入数据量, 大于文件最大大小时, 执行日志滚动
   if l.size+writeLen > l.max() {
      if err := l.rotate(); err != nil {
         return 0, err
      }
   }

   n, err = l.file.Write(p) // 写入日志数据
   l.size += int64(n) // 更新写入量的记录值

   return n, err
}

整个过程比较简单:

1. 加锁
2. 检查写入数据量是否超过最大文件最大大小
3. 如果没有打开文件, 则打开
4. 当要写入数据量加上当前已写入数据量, 大于文件最大大小时, 执行日志滚动
5. 写入日志数据并更新当前已写入量的记录值

主要的逻辑在openExistingOrNew()和rotate()方法中, 先来看openExistingOrNew(), 代码如下:

func (l *Logger) openExistingOrNew(writeLen int) error {
    l.mill() // 这行到底是做什么的呢?

    filename := l.filename()
    info, err := osStat(filename)
    if os.IsNotExist(err) {
        return l.openNew()
    }
    if err != nil {
        return fmt.Errorf("error getting log file info: %s", err)
    }

    if info.Size()+int64(writeLen) >= l.max() {
        return l.rotate() // 这里又一次调用了rotate方法, 与上面的逻辑一样
    }

    file, err := os.OpenFile(filename, os.O_APPEND|os.O_WRONLY, 0644)
    if err != nil {
        return l.openNew() // 如果打开文件报错, 那就新开一个文件接着写
    }
    l.file = file
    l.size = info.Size()
    return nil
}

上面涉及rotate(),openNew(),mill()的调用, 其中mill()这么方法名字上看不出具体是做什么的. 我们先去看rotate(), 因为openNew()和mill()也被rotate()调用, 代码如下:

func (l *Logger) rotate() error {
    if err := l.close(); err != nil {
        return err
    }
    if err := l.openNew(); err != nil {
        return err
    }
    l.mill()
    return nil
}

看样子rotate()的逻辑非常简单, 无非是关掉原有日志文件, 然后创建新文件, 而且这里有调用了一次mill(). 现在看到这里还剩下面的问题没有搞清楚:

1. 创建新文件的话, 原文件和新文件的名字不能相同, 这个如何处理?
2. 日志文件存放过多或过期如何清理?

为了解答上面的问题, 我们继续看openNew(), 代码如下:

func (l *Logger) openNew() error {
    err := os.MkdirAll(l.dir(), 0755)
    if err != nil {
        return fmt.Errorf("can't make directories for new logfile: %s", err)
    }

    name := l.filename()
    mode := os.FileMode(0600)
    info, err := osStat(name)
    if err == nil {
        // Copy the mode off the old logfile.
        mode = info.Mode()
        // move the existing file
        // 果然是在这里进行文件改名的, 看样子是把原日志文件加个时间后缀
        newname := backupName(name, l.LocalTime)
        if err := os.Rename(name, newname); err != nil {
            return fmt.Errorf("can't rename log file: %s", err)
        }

        // this is a no-op anywhere but linux
        if err := chown(name, info); err != nil {
            return err
        }
    }

    // we use truncate here because this should only get called when we've moved
    // the file ourselves. if someone else creates the file in the meantime,
    // just wipe out the contents.
    f, err := os.OpenFile(name, os.O_CREATE|os.O_WRONLY|os.O_TRUNC, mode)
    if err != nil {
        return fmt.Errorf("can't open new logfile: %s", err)
    }
    l.file = f
    l.size = 0 // 重置计数器
    return nil
}

重命名具体格式:

func backupName(name string, local bool) string {
    // 省略部分代码
    timestamp := t.Format(backupTimeFormat) // backupTimeFormat = "2006-01-02T15-04-05.000"
    // 我们得到的文件名形如: /dir/xxx-service-2021-01-01T01-01-01.000.log
    return filepath.Join(dir, fmt.Sprintf("%s-%s%s", prefix, timestamp, ext))
}

这里也就解答了问题1, lumberjack把原日志文件重命名加上时间, 这样已原有的文件名打开一个新的文件继续写.

上面各种方法里面处处调用mill(), 看来很重要.

// startMill是一个sync.Once实例, millCh是一个bool类型的channel
func (l *Logger) mill() {
    l.startMill.Do(func() {
        l.millCh = make(chan bool, 1)
        go l.millRun()
    })
    select {
    case l.millCh <- true:
    default:
    }
}

这个函数启动了一个millRun()协程, 而且为了使协程在全局只启动一次, 用了sync.Once.Do(). 也就是说这个函数除了第一次会启动millRun(), 它主要的功能只是往millCh里发一个true信号......我们只能继续深挖以下millRun()了:

func (l *Logger) millRun() {
    for range l.millCh {
        _ = l.millRunOnce()
    }
}

millRun()只是起到从millCh里面一直读信号, 每次收到一个信号就调用一次millRunOnce, 看来这个方法才是真正在做事情.

func (l *Logger) millRunOnce() error {
    // 如果既不设置最大备份文件个数, 也不设置文件最久保留时间, 更不设置文件需要压缩, 那就啥事也不做, 直接return
    if l.MaxBackups == 0 && l.MaxAge == 0 && !l.Compress {
        return nil
    }

    // 取到所有旧的文件
    files, err := l.oldLogFiles()
    if err != nil {
        return err
    }

    var compress, remove []logInfo
    // 超过设置的最多备份旧日志个数, 规划待删除清单
    if l.MaxBackups > 0 && l.MaxBackups < len(files) {
        // preserved看似是个map, 但这个在整个上下文语义来看, 其实是当作了set用, 因为每个存到里面的key的value都是true
        preserved := make(map[string]bool)
        var remaining []logInfo
        for _, f := range files {
            // Only count the uncompressed log file or the
            // compressed log file, not both.
            fn := f.Name()
            if strings.HasSuffix(fn, compressSuffix) {
                fn = fn[:len(fn)-len(compressSuffix)]
            }
            preserved[fn] = true
            // 当这个set超出了设置的文件备份数最大值时, 后面的被放到待删除清单中
            if len(preserved) > l.MaxBackups {
                remove = append(remove, f)
            } else {
                // 没超出的放到保留清单中
                remaining = append(remaining, f)
            }
        }
        files = remaining // 更新清单
    }
    // 检查清单中的文件是否超过了设置的最大保留期
    if l.MaxAge > 0 {
        diff := time.Duration(int64(24*time.Hour) * int64(l.MaxAge))
        cutoff := currentTime().Add(-1 * diff)

        var remaining []logInfo
        for _, f := range files {
            if f.timestamp.Before(cutoff) {
                // 超出的被放到待删除清单中
                remove = append(remove, f)
            } else {
                // 没超出的放到保留清单中
                remaining = append(remaining, f)
            }
        }
        files = remaining // 更新清单
    }
    // 如需压缩
    if l.Compress {
        for _, f := range files {
            if !strings.HasSuffix(f.Name(), compressSuffix) {
                // 放到压缩文件清单中
                compress = append(compress, f)
            }
        }
    }
    // 删除不需要保留的文件
    for _, f := range remove {
        errRemove := os.Remove(filepath.Join(l.dir(), f.Name()))
        if err == nil && errRemove != nil {
            err = errRemove
        }
    }
    // 执行压缩
    for _, f := range compress {
        fn := filepath.Join(l.dir(), f.Name())
        errCompress := compressLogFile(fn, fn+compressSuffix)
        if err == nil && errCompress != nil {
            err = errCompress
        }
    }

    return err
}

从上面的逻辑可以知道, millRunOnce()就是清理日志文件以及压缩文件的执行者. 但这里有一个细节: 在规划清理清单的过程中, 只是顺序遍历了旧文件, 把超出的文件放入待删除清单, 看来oldLogFiles()方法取出的文件是按时间排好序的.

func (l *Logger) oldLogFiles() ([]logInfo, error) {
    files, err := ioutil.ReadDir(l.dir())
    if err != nil {
        return nil, fmt.Errorf("can't read log file directory: %s", err)
    }
    logFiles := []logInfo{}

    prefix, ext := l.prefixAndExt()

    for _, f := range files {
        if f.IsDir() {
            continue
        }
        // timeFromName方法可以把文件名中的时间后缀提取出来, 这里返回值t的类型是time.Time
        if t, err := l.timeFromName(f.Name(), prefix, ext); err == nil {
            logFiles = append(logFiles, logInfo{t, f})
            continue
        }
        if t, err := l.timeFromName(f.Name(), prefix, ext+compressSuffix); err == nil {
            logFiles = append(logFiles, logInfo{t, f})
            continue
        }
        // error parsing means that the suffix at the end was not generated
        // by lumberjack, and therefore it's not a backup file.
    }
  
    // 果然这里进行了排序操作
    sort.Sort(byFormatTime(logFiles))

    return logFiles, nil
}

这里使用logInfo类型和byFormatTime类型:

type logInfo struct {
    timestamp time.Time
    os.FileInfo
}

// byFormatTime实现了sort接口
type byFormatTime []logInfo
// sort函数是按升序排列的
// 按时间戳大小来排序, 根据上面调用者的需求
// 要把新的文件往前排, 把老的文件往后排
// 即时间戳越大的文件越less
func (b byFormatTime) Less(i, j int) bool {
    return b[i].timestamp.After(b[j].timestamp)
}

func (b byFormatTime) Swap(i, j int) {
    b[i], b[j] = b[j], b[i]
}

func (b byFormatTime) Len() int {
    return len(b)
}