log package in go

golang, programming

本文将简要分析 golang 中自带 log 模块的源码，解析相关知识点并讲解如何将 log 重定向到不同的文件。

相关知识点

  • iota 是 constant 定义中的一个 predefiend identifier, 比较有趣，详见 iota
  • go 中 | 是按位或，|| 是逻辑或，& 也是一样
  • append 相关知识
  • io.Writer 是一个 interface, 内部只有一个 Write 方法的接口，用 os.OpenFile 打开的文件在特定 flag 下可以看作一个 io.Writer
  • 对 rune, string, byte 的讲解

代码讲解

👇自定义的 constant, 用于指定各种 flag

1
2
3
4
5
6
7
8
9
const (
	Ldate         = 1 << iota     // the date in the local time zone: 2009/01/23
	Ltime                         // the time in the local time zone: 01:23:23
	Lmicroseconds                 // microsecond resolution: 01:23:23.123123.  assumes Ltime.
	Llongfile                     // full file name and line number: /a/b/c/d.go:23
	Lshortfile                    // final file name element and line number: d.go:23. overrides Llongfile
	LUTC                          // if Ldate or Ltime is set, use UTC rather than the local time zone
	LstdFlags     = Ldate | Ltime // initial values for the standard logger
)

上面的代码 Ldate 到 LUTC 分别为 1, 2, 4, …, 32, 从 bit 的视角来看，它们 1 的位置均不相同，所以通过 | 运算可以得到有意义的消息

👇 Logger 结构体，flag 就是由上面的 constant 组成的，out 可以用于控制输出的位置

1
2
3
4
5
6
7
type Logger struct {
	mu     sync.Mutex // ensures atomic writes; protects the following fields
	prefix string     // prefix to write at beginning of each line
	flag   int        // properties
	out    io.Writer  // destination for output
	buf    []byte     // for accumulating text to write
}

通常我们使用 log 模块的时候，直接通过 log.Println 这样的 api 进行打印，原因在于 log 模块中维护了一个默认的 logger std var std = New(os.Stderr, "", LstdFlags), 默认输出在 stderr 中

我们再来看看调用 log.Println 发生了什么

1
2
3
4
5
// Println calls Output to print to the standard logger.
// Arguments are handled in the manner of fmt.Println.
func Println(v ...interface{}) {
	std.Output(2, fmt.Sprintln(v...))
}

std 就是上文中提到的 log 模块中默认维护的 logger, 再来看看 Output 方法

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
// Output writes the output for a logging event. The string s contains
// the text to print after the prefix specified by the flags of the
// Logger. A newline is appended if the last character of s is not
// already a newline. Calldepth is used to recover the PC and is
// provided for generality, although at the moment on all pre-defined
// paths it will be 2.
func (l *Logger) Output(calldepth int, s string) error {
	now := time.Now() // get this early.
	var file string
	var line int
	l.mu.Lock()
	defer l.mu.Unlock()
	if l.flag&(Lshortfile|Llongfile) != 0 {
		// Release lock while getting caller info - it's expensive.
		l.mu.Unlock()
		var ok bool
		_, file, line, ok = runtime.Caller(calldepth)
		if !ok {
			file = "???"
			line = 0
		}
		l.mu.Lock()
	}
	l.buf = l.buf[:0]
	l.formatHeader(&l.buf, now, file, line)
	l.buf = append(l.buf, s...)
	if len(s) == 0 || s[len(s)-1] != '\n' {
		l.buf = append(l.buf, '\n')
	}
	_, err := l.out.Write(l.buf)
	return err
}

乍一看可能觉得会出现 dead lock, 实际上不会，因为此时的资源只有一个锁，runtime.Caller 不会 hold / 锁住其他资源，所以这里不会有死锁的可能性。这里本质上就是做了一个无锁化的优化

l.buf = l.buf[:0] 的原因没有太懂, 类似于一种把指针移到首位之前的操作，此时 append 并不会 append 在 underlying 数组的末尾，而是直接 append 在第一个地方，把原始数组的第一个元素直接覆盖，这样相当于不用在意之前 buf 到底写了什么，不用特意地清空

l.formatHeader 作用就是在 buf 里面根据我们设置的 prefix 以及相应的 flags 把 Header 填好

最后再把 s 填进去，并且保证末尾一定有一个 \n

我们来具体看看 l.formatHeader，

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
// formatHeader writes log header to buf in following order:
//   * l.prefix (if it's not blank),
//   * date and/or time (if corresponding flags are provided),
//   * file and line number (if corresponding flags are provided).
func (l *Logger) formatHeader(buf *[]byte, t time.Time, file string, line int) {
	*buf = append(*buf, l.prefix...)
	if l.flag&(Ldate|Ltime|Lmicroseconds) != 0 {
		if l.flag&LUTC != 0 {
			t = t.UTC()
		}
		if l.flag&Ldate != 0 {
			year, month, day := t.Date()
			itoa(buf, year, 4)
			*buf = append(*buf, '/')
			itoa(buf, int(month), 2)
			*buf = append(*buf, '/')
			itoa(buf, day, 2)
			*buf = append(*buf, ' ')
		}
		if l.flag&(Ltime|Lmicroseconds) != 0 {
			hour, min, sec := t.Clock()
			itoa(buf, hour, 2)
			*buf = append(*buf, ':')
			itoa(buf, min, 2)
			*buf = append(*buf, ':')
			itoa(buf, sec, 2)
			if l.flag&Lmicroseconds != 0 {
				*buf = append(*buf, '.')
				itoa(buf, t.Nanosecond()/1e3, 6)
			}
			*buf = append(*buf, ' ')
		}
	}
	if l.flag&(Lshortfile|Llongfile) != 0 {
		if l.flag&Lshortfile != 0 {
			short := file
			for i := len(file) - 1; i > 0; i-- {
				if file[i] == '/' {
					short = file[i+1:]
					break
				}
			}
			file = short
		}
		*buf = append(*buf, file...)
		*buf = append(*buf, ':')
		itoa(buf, line, -1)
		*buf = append(*buf, ": "...)
	}
}

第一句话就很值得玩味，我们可能会提出一些疑问

  • 如果不传入 buf 的指针可以吗？
  • 传入 buf[:0] 的作用到底是什么？
  • append 中 l.prefix... 是什么意思？

先回答第一个问题，不可以，因为此时我们要对 slice 进行 append 操作，而 go 中的 append 并不是一个 in-place operation, 会返回一个 new slice，所以必须传入指针

看到这里 buf[:0] 的作用也就有感觉了，相当于返回了一个新的 slice 从头开始，append 会直接从 index 0 开始，直接覆盖之前 slice 下写的东西，不需要自己做一个 clear 的操作

slice append api 中的第二个参数允许我们传入一个 ...T, 也就是我们可以写入任意数目的元素，比如 l = append(l, 1, 2, 3, 4), go 会自动帮我们把 1, 2, 3, 4 转成一个 slice []int{1,2,3,4} 然后传入；我们当然也可以 s = []int{1,2,3}; l = append(l, s...), 会直接把 s 传入并 append. 那么在这里，l.prefix 是一个 string 类型，l.buf 是一个 []byte 类型，那么 l.prefix... 传入的到底是什么呢？

我们不妨先看看 string 和 byte 的关系, 对 rune, string, byte 的讲解，也就是说 string 可以看作一个不可变的 []byte 类型，所以直接 l.prefix... 展开也就是可以理解的了

那么如何写一个输出到固定文件的 logger 呢？

看完 source code 之后，就觉得非常 easy 了，我们可以自己构建 logger 或者把 log.std 的 Output 重定向到其他 io.Writer 即可，打开一个固定的文件就能做到这一点, 因为 os.OpenFile 返回的 *File 类型有实现 io.Writer 的 interface

比如 

1
2
3
4
5
6
7
log.SetPrefix(prefix + " ")
log.SetFlags(log.Ltime | log.Lshortfile)
logFile, err := os.OpenFile("mr-worker.log", os.O_APPEND|os.O_WRONLY|os.O_CREATE, 0600)
if err != nil {
	log.Fatalln("failed to open mr-worker.log, exit")
}
log.SetOutput(logFile)