zap 日志库的死锁问题

发表于 分类于 阅读次数： Valine： 本文字数： 2.2k 阅读时长 ≈ 2 分钟

前言

之前写了个日志处理的服务，用到了鼎鼎大名的 uber-go/zap 库落盘日志文件，但总会有疑似协程泄露的问题。

最近对这个服务做了重构，加了些日志协助定位，发现竟然是 zap 库的一个 Bug 导致协程阻塞，一直无法正常退出，进而带来之前的协程泄露问题。

问题细节

已经有人在这个 Issue 里，把问题的原因分析写得挺清楚了，这里再简单阐述下。

项目需要使用 zap 的 BufferedWriteSyncer 去落盘日志文件，它内部有一个常驻的 flushLoop 方法，会定期执行 Sync 方法把缓冲区的日志写入文件中。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
// flushLoop flushes the buffer at the configured interval until Stop is
// called.
func (s *BufferedWriteSyncer) flushLoop() {
	defer close(s.done)

	for {
		select {
		case <-s.ticker.C:
			// we just simply ignore error here
			// because the underlying bufio writer stores any errors
			// and we return any error from Sync() as part of the close
			_ = s.Sync()
		case <-s.stop:
			return
		}
	}
}

Sync 方法开始执行时，会先去获取锁，然后再调用内部 writer 的 Flush 方法。

1
2
3
4
5
6
7
8
9
10
11
12
// Sync flushes buffered log data into disk directly.
func (s *BufferedWriteSyncer) Sync() error {
	s.mu.Lock()
	defer s.mu.Unlock()

	var err error
	if s.initialized {
		err = s.writer.Flush()
	}

	return multierr.Append(err, s.WS.Sync())
}

当我们调用 BufferedWriteSyncer 的 Stop 方法时，它有三个较关键的逻辑：

  1. 获取锁
  2. 通过关闭 stop 通道，通知 flushLoop 退出
  3. 等待 flushLoop 退出
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
// Stop closes the buffer, cleans up background goroutines, and flushes
// remaining unwritten data.
func (s *BufferedWriteSyncer) Stop() (err error) {
	var stopped bool

	// Critical section.
	func() {
		s.mu.Lock()
		defer s.mu.Unlock()

		if !s.initialized {
			return
		}

		stopped = s.stopped
		if stopped {
			return
		}
		s.stopped = true

		s.ticker.Stop()
		close(s.stop) // tell flushLoop to stop
		<-s.done      // and wait until it has
	}()

	// Don't call Sync on consecutive Stops.
	if !stopped {
		err = s.Sync()
	}

	return err
}

整个流程乍一看没啥大毛病，我之前排查问题的时候，也多次粗看过这部分代码，心想这么一个业界通用的库，应该这点逻辑不会存在啥大问题。但直到我在 Stop 前后都打了日志，问题再次出现时拿到了十足的证据，才确定是 zap 库的逻辑问题。

这里的关键问题在于flushLoop 里 for 循环里的两个 case 触发顺序，当以下情况发生时：

  1. Stop 方法内部先取得了锁，然后通知 flushLoop 退出
  2. flushLoop 先进入了 ticker 的分支逻辑，然后调用 Sync 方法
  3. Sync 方法尝试获取锁（但这个锁目前还未被 Stop 方法释放）

Stop 方法在等 flushLoop 退出，而 flushLoop 调用的 Sync 方法在等 Stop 释放锁，进而导致死锁。

在实际应用时，flushLoop 大部分情况下会先取到 stop 的信号，然后正常退出，所以给这个问题的发生具有偶然性而且概率不高。

问题解决

官方修复的思路其实比较直接，详情可以查看 PR。

大概思路是，Stop 的锁逻辑主要是为正常读写其内部变量 stopped，在写完 stopped 变量之后及时把锁释放，然后再等待 flushLoop 退出。

如果是我，我可能会另外加一个状态 stopping 用来描述当前处于正在停止的状态，只有 Stop 和 flushLoop 都正常退出了，才将 stopped 置为 true。

小结

Golang 的 goroutine 让异步逻辑/多线程（协程）开发变得容易，但在处理多协程的时序上，依然很容易踩坑，比如 一个 docker logs 问题引发的系列探索 这里讲到的也是类似的问题。

所以在处理多协程/超时逻辑等问题上要尤其小心，避免不必要的协程泄露问题；另外在排查问题时，不要迷信某些库，他们其实也会犯错误。