一个 docker logs 问题引发的系列探索

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

前言

最近因为排查一个日志采集问题，和 docker logs 杠上了，然后便有了本文。

探索历程

发现问题

最近，我们发现线上的容器日志会莫名丢失最后一行，经过不断地尝试，最近确认了复现路径：如果日志最后一行不以换行符结尾，则最后一行日志会丢失。

定位问题

于是我就尝试在本地起服务打断点排查，然而无论怎么尝试，本地都没法复现线上问题。硬着头皮把可能出问题的代码挨个查阅，我也没找到可能和换行有关的逻辑。

就在一筹莫展的时候，我把关注点放在了 docker logs 的 API 上，然后发现了问题所在。感兴趣的朋友可以在本地用以下命令验证起来：

1
2
3
4
5
# run a test container
docker run --name test --rm  alpine /bin/sh -c "sleep 5; echo hello; echo -n world"

# follow its log
docker logs -f test

上述命令在不同平台的行为均有不同（Docker 版本均为 20.10）：

  1. Linux 操作系统下（本人测试时使用的 CentOS），最后的无换行符的日志会丢失
  2. Windows 操作系统下（本人测试时使用的 Win 10），最后的日志偶尔丢失
  3. MacOS 下运行最后一行日志大概率不会丢失

确认问题

同样的代码，在不同操作系统下的行为不一致，这是我万万没想到的。带着这样的迷惑，我向官方提了个 Issue，提供了完整的复现路径。

Docker 的开发很快给了响应，确认这是 docker logs -f 的问题，可能原因是某种竞态问题。开发在 22 版本中对 log follow 的功能重写（该 Bug 被修复），其中较关键的一次 提交 可能将用于修复 v20.10 版本的 Bug。

这里附上该提交的说明，感兴趣的同学可以看看变更代码：

The LogFile follower would stop immediately upon the producer closing. The close signal would race the file watcher; if a message were to be logged and the logger immediately closed, the follower could miss that last message if the close signal (formerly ProducerGone) was to win the race. Add logic to perform one more round of reading when the producer is closed to catch up on any final logs.

其它发现

日志混流分流

Docker 日志一般存储在 /var/lib/docker/containers/xxx/xxx-json.log 文件中，每一行日志存储时会通过 stream 区分 stdout/stderr，如：

1
2
{"log":"2021/08/17 15:17:23 server: Listening on 0.0.0.0:8000...\n","stream":"stdout","time":"2021-08-17T15:17:23.104438582Z"}
{"log":"2022/07/05 16:05:08 http error: Invalid request payload (err=Invalid username) (code=400)\n","stream":"stderr","time":"2022-07-05T16:05:08.274621791Z"}

如果我们通过 Docker 提供的 SDK（或者直接和 docker.sock 通讯），调用 Docker API 去获取容器日志，要如何区分 stdout/stderr 呢？这里有个示例命令行，可以参考着在本地执行看看：

1
2
3
4
docker run --rm --name test alpine /bin/sh -c "sleep 5; echo normal; echo error > /dev/stderr"

# 另起一个 shell 执行
curl -v -XGET --unix-socket /var/run/docker.sock "http://localhost/containers/test/logs?stdout=1&stderr=1&follow=1" --output out

如果用 vi 打开 out 文件，会发现在 normal 和 error 前还有一些奇怪的符号，而这些不可见的字符恰好是 Docker 用来区分当前行是 stdout 还是 stderr 的方式。

1
2
3
4
5
6
7
# cat out 的显示
normal
out

# vi out 的显示
^A^@^@^@^@^@^@^Gnormal
^B^@^@^@^@^@^@^Ferror

Docker 输出日志前，使用 StdWriter 对标准输出和错误输出混流，如果需要对混流后的内容分流，则可以使用 StdCopy 实现。我们来简单分析下 StdCopy 的 代码，人工对混流后的内容分流看看效果。

  1. 把不可见字符转换成 16 进制

    1
    \x01\x00\x00\x00\x00\x00\x00\x07normal\n\x02\x00\x00\x00\x00\x00\x00\x06error

  2. 取第一个字节的内容作判断：normal 一行首字节为 1，表示 stdout；error 一行首字节为 2，表示 stderr

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    19
    func StdCopy(dstout, dsterr io.Writer, src io.Reader) (written int64, err error) {
        // ...
        for {
            // ...
            stream := StdType(buf[stdWriterFdIndex])
    		// Check the first byte to know where to write
    		switch stream {
    		// ...
    		case Stdout:
    			// Write on stdout
    			out = dstout
    		case Stderr:
                // Write on stderr
                out = dsterr
                // ...
    		}
        }
        // ...
    }

  3. 细心的读者可能发现了，在分流时并不是想当然地根据换行符来分割，而是通过日志前的「长度信息」来判断：\x00\x00\x00\x07 对应的十进制数为 7，表示后方的日志长度为 7 个字节，与 normal\n 长度一致；\x00\x00\x00\x06 对应的十进制数为 6，与 error\n 长度一致。

    1
    frameSize = int(binary.BigEndian.Uint32(buf[stdWriterSizeIndex : stdWriterSizeIndex+4]))

日志染色

此染色并非大家熟悉的日志染色（即给日志加上跟踪 ID，便于后续的错误定位），而是单纯地希望给 stderr 的输出加上颜色。

关于 Shell 的颜色标识原理和语法大全，此处不便展开，感兴趣的同学可参考 了解 ANSI 转义码的 color 设置。

基于上面对 Docker 日志的研究，一个显而易见的方式则是自定义 StdCopy 方式，然后加上颜色标识。但其时有一种方式更简单直接：拦截进程的错误输出，添加上颜色标识再重定向到错误输出。

1
2
# 例子
echo "echo hello; echo error > /dev/stderr;" | sh -e 2> >(while read line || [ "$line" ]; do echo -e "\e[01;31m$line\e[0m" >&2; done)

使用这种方法也有一种的局限性，比如 Ubuntu 默认的 shell 是 Dash，而 Dash 不支持这种重定向，会直接报重定向错误，所以谨慎使用。

End

本篇完…