docker日志丢失问题分析

今天在工作遇到一个docker日志丢失的问题，最终一步步查找到原因了，这里记录一下过程。

问题

工作中把自己写的应用部署到kubernetes中后，用kubectl -n some-ns logs some-pod -c one-container命令查看不了该pod中container的日志，而用该命令去查看其它pod的日志，是可以正常显示的。

跟踪原因

首先怀疑是应用本身的程序问题，将应用在本机运行了一下，是可以正常输出日志到标准输出的。

接下来怀疑是kubernetes本身的问题，于是在kubernetes的某个节点上直接用docker命令运行起容器：

docker run --name some-name -d some-image
docker logs some-name # 这里还是没有输出日志

看来跟kubernetes无关，直接用docker run跑容器都没有输出日志啊。

不过一想应该docker本身应该不会存在这么大的问题，再做一个实验，同样的镜像，在我本机的docker环境中运行试一下：

docker run --name some-name -d some-image
docker logs some-name # 这里输出了日志

看来是服务器上的docker环境有些毛病。

然后看看docker的日志配置：

cat /etc/sysconfig/docker
...
OPTIONS='--selinux-enabled --log-driver=journald --signature-verification=false --graph=/data/docker'
...

docker的配置里是将日志发送到journald的，于是看下docker服务本身的日志：

journalctl _SYSTEMD_UNIT=docker.service

观察日志，日志发送应该是没有什么问题的。

接下来看看journald服务的日志：

journalctl _SYSTEMD_UNIT=systemd-journald.service
...
Jan 10 19:18:50 tshift-master systemd-journal[547]: Suppressed 1833 messages from /system.slice/docker.service
Jan 10 19:19:20 tshift-master systemd-journal[547]: Suppressed 1849 messages from /system.slice/docker.service
Jan 10 19:19:50 tshift-master systemd-journal[547]: Suppressed 1857 messages from /system.slice/docker.service
Jan 10 19:20:20 tshift-master systemd-journal[547]: Suppressed 2010 messages from /system.slice/docker.service
Jan 10 19:20:50 tshift-master systemd-journal[547]: Suppressed 1820 messages from /system.slice/docker.service
...

这里可以看到有大量的Suppressed xxx messages from /system.slice/docker.service的日志，从字面意思来理解，有很多日志被抑制了。

为啥会出现这种问题呢？参阅journald.conf的官方文档，可以看到下面这段话：

man journald.conf
...
	RateLimitInterval=, RateLimitBurst=
       Configures the rate limiting that is applied to all messages generated on the system. If, in the time interval defined by RateLimitInterval=, more messages than specified in RateLimitBurst= are logged by a service, all
       further messages within the interval are dropped until the interval is over. A message about the number of dropped messages is generated. This rate limiting is applied per-service, so that two services which log do not
       interfere with each other's limits. Defaults to 1000 messages in 30s. The time specification for RateLimitInterval= may be specified in the following units: "s", "min", "h", "ms", "us". To turn off any kind of rate
       limiting, set either value to 0.
...

也就是说docker这个服务输出日志超出了每30秒1000条的速率限制，因此超出部分的日志被journald丢弃了。

那么docker服务真的输出日志速率这么快吗？我这里用命令计算一下：

journalctl _SYSTEMD_UNIT=docker.service --since "2019-01-11 23:00:00" --until "2019-01-11 23:05:00" | wc -l
10011 # 10011/(5*60) * 30 = 1000

这样看来，docker服务输出日志的速度果然超出限制了。

解决办法

既然是docker服务输出日志的速率超限，自然有两种解法：降低docker日志的输出速率、增大journald的速率限制。

降低docker日志的输出速率

使用以下命令可以看到docker服务输出的日志：

journalctl _SYSTEMD_UNIT=docker.service --since "2019-01-11 23:00:00" --until "2019-01-11 23:05:00"

从命令的输出来看，基本都是一些容器的标准输出，而刚好出问题的服务器上运行了大量容器，而且有些容器确实在大量输出日志。当然改法自然是调整这些容器的程序，一般来说就是设置更合理的日志级别。

增大journald的速率限制

如果服务器上运行了大量容器，每个容器输出一些日志，这些日志加起来也很容易超过journald的速率限制。因此还可以直接增大journald的速率限制。

# 直接修改/etc/systemd/journald.conf，增大RateLimitBurst配置项的取值，修改完毕后重启journald服务
vim /etc/systemd/journald.conf
systemctl restart systemd-journald

其它

journald配置文件的优化

在修改journald.conf里，发现其某些配置项并不合理，可以参考这里优化一下。

增大journald的速率限制的其它办法

查看journald.conf配置文件的文档时，还发现对于较新版本的systemd来说，可以只修改某个服务对应的日志速率限制参数，这样不用修改journald.conf影响全局，可惜这个特性只有较新版本的systemd才有。

RateLimitIntervalSec=, RateLimitBurst=
Configures the rate limiting that is applied to all messages generated on the system. If, in the time interval defined by RateLimitIntervalSec=, more messages than specified in RateLimitBurst= are logged by a service, all further messages within the interval are dropped until the interval is over. A message about the number of dropped messages is generated. This rate limiting is applied per-service, so that two services which log do not interfere with each other’s limits. Defaults to 10000 messages in 30s. The time specification for RateLimitIntervalSec= may be specified in the following units: “s”, “min”, “h”, “ms”, “us”. To turn off any kind of rate limiting, set either value to 0.
If a service provides rate limits for itself through LogRateLimitIntervalSec= and/or LogRateLimitBurst= in systemd.exec(5), those values will override the settings specified here.

总结

docker的日志输出逻辑还是比较清晰的，这里就不具体介绍了，参考官方文档就可以了，出了问题冷静一步步分析还是很靠谱的。

文章目录

问题