runsisi's

technical notes

logrotate 与 ceph 日志打包

2019-02-15 runsisi#ceph

以 CentOS 7.x 为例,其他发行版可能会有所差异,比如 Ubuntu 16.04 下 cron 守护进程是 cron,而 CentOS 7.x 下是 crond,默认的 /etc/cron.daily/logrotate 任务脚本在不同发行版有不同的内容等。

logrotate 只是一个日志处理程序,默认并没有守护进程进行定时执行的能力,需要外部定时器或者手工进行触发。这个外部定时器通常来说是系统的 crond 定时任务守护进程执行。

crond 的配置一般存在如下位置:

/etc/crontab
/etc/cron.d/
/var/spool/cron
/etc/cron.daily/
/etc/cron.hourly/
/etc/cron.weekly/
/etc/cron.monthly/

其中后面四个以周期命名的文件夹顾名思义就是放置在该文件下的可执行文件会按文件夹名定义的周期周期性执行,而前面的三个需要以特殊的 cron 语法进行周期任务的定义(具体可以参考 man 5 crontab 手册页,切记 * 的意思是 first - last,即每个时间精度都会执行一次,* */5 * * * 不是每间隔 4 小时执行一次,而是每间隔 4 小时执行 60 次,因为分钟字段是 *)。

此外 crontab -ecrontab -l 等操作的是 /var/spool/cron 这个文件。

回到 logrotate,系统默认在 /etc/cron.daily/ 下有一个名为 logrotate 的 shell 脚本,内容如下:

#!/bin/sh

/usr/sbin/logrotate /etc/logrotate.conf
EXITVALUE=$?
if [ $EXITVALUE != 0 ]; then
    /usr/bin/logger -t logrotate "ALERT exited abnormally with [$EXITVALUE]"
fi
exit 0

同时注意到 /etc/logrotate.conf 里包含如下内容:

# use date as a suffix of the rotated file
dateext

# uncomment this if you want your log files compressed
#compress

# RPM packages drop log rotation information into this directory
include /etc/logrotate.d

因此,默认情况下 logrotate 会由 crond 每天执行一次,生成的日志文件会带上日期作为文件名后缀,且生成的日志文件默认是不压缩的,当然通常来说应用自己定义的日志策略(即 include 指令所指定的文件夹下的日志配置)会把 compress 选项打开。

再来看 ceph 的日志文件处理,ceph-base 安装包中带了 logrotate 的配置文件 /etc/logrotate.d/ceph,内容如下:

/var/log/ceph/*.log {
    rotate 7
    daily
    compress
    sharedscripts
    postrotate
        killall -q -1 ceph-mon ceph-mgr ceph-mds ceph-osd ceph-fuse radosgw || pkill -1 -x "ceph-mon|ceph-mgr|ceph-mds|ceph-osd|ceph-fuse|radosgw" || true
    endscript
    missingok
    notifempty
    su root ceph
}

根据 logrotate 配置文件的语法,与 daily 对应的有 hourly, weekly,monthly,yearly,即在定义的周期内只会对日志文件处理一次,但如前面所述,由于 logrotate 自身需要外部驱动执行,因此如果没有定义小于等于这个周期的 cron 任务,日志文件并不会在 logrotate 定义的周期里得到执行,从而也不会有新的打包日志生成。

默认在 dateext 存在的情况下,logrotate 生成的日志会存在如 -20180904 这样的后缀,但 hourly 结合 dateext 选项有会比较特殊,生成的后缀会加上如 -2018090416 这样的后缀,即把小时也加上了。

当然也可以通过 dateformat 选项自定义后缀,更详细的配置可以参考 man logrotate.conf 手册页。

有时可能会发现一些比较奇怪的现象,如日志文件既存在以日期作为后缀的文件名,同时也存在,以数字 1, 2, 3, 4 等作为后缀的文件名,如:

-rw-r--r-- 1 ceph ceph 1.4M Sep  4 00:00 ceph-mon.192.33.1.5.log.1.gz
-rw-r--r-- 1 ceph ceph  337 Sep 22  2016 ceph-mon.192.33.1.5.log-20160922.gz
-rw-r--r-- 1 ceph ceph  927 Sep 30  2016 ceph-mon.192.33.1.5.log-20160930.gz
-rw-r--r-- 1 ceph ceph  164 Jan 24  2018 ceph-mon.192.33.1.5.log-20180124.gz
-rw-r--r-- 1 ceph ceph  146 May  7 00:00 ceph-mon.192.33.1.5.log-20180507.gz
-rw-r--r-- 1 ceph ceph 1.5M Sep  2 23:59 ceph-mon.192.33.1.5.log.2.gz
-rw-r--r-- 1 ceph ceph 1.4M Sep  1 23:59 ceph-mon.192.33.1.5.log.3.gz
-rw-r--r-- 1 ceph ceph 1.5M Aug 31 23:59 ceph-mon.192.33.1.5.log.4.gz

通过前面的分析可知,默认的日志文件是会带日期后缀的,为何这里生成的日志没有,其实原因很简单,可能曾经为 ceph 添加过 cron 任务,如:

# crontab -l
*/45 * * * * /usr/sbin/logrotate /etc/logrotate.d/ceph >/dev/null 2>&1

或者其他定时任务(cat /etc/crontab),注意到这条命令和 /etc/cron.daily/logrotate 中命令行的差异,这个独立的 cron 任务直接指定的是 ceph 自身的 logrotate 配置文件,而不是 /etc/logrotate.conf,这样 /etc/logrotate.conf 中定义的 dateext 选项就没有生效,而默认 ceph 独立的日志配置也没有加上 dateext 这个选项,因此就不会生成带日期后缀的日志。

同时需要注意到 ceph 独立的日志配置文件里有 daily 选项,说明一天只会生成一个,当手工添加的这些 cron 任务成功执行之后,在剩下的一天时间内就没有 /etc/cron.daily/logrotate 什么事了,因此,当既存在手工的 cron 任务,又存在 /etc/cron.daily/logrotate 时,见到的通常都会是没有日期后缀的,但是可能也会存在有日志后缀的和没有日志后缀的混合存在(比如首先由 cron.daily 生成了一个有日期后缀的日志,然后 cron 每 45 分钟检查一次看需不需要再生成,当一天时间过了,大概率情况下 cron 恰好在 cron.daily 之前得到执行,因此此时会生成以数字作为后缀的日志,反之也类似)。

另外,logroate 会忽略掉 /etc/logrotate.d/ 下面的 .rpmsave 作为后缀的配置文件,因此不需要担心 /etc/logrotate.d/ceph 与 ceph.rpmsave 有冲突(看到有些环境存在 ceph.rpmsave,这是 Hammer 版本的日志配置文件):

~# logrotate /etc/logrotate.conf -v
reading config file /etc/logrotate.conf
including /etc/logrotate.d
Ignoring ceph.rpmsave, because of .rpmsave ending

logrotate 忽略如下后缀类型的文件:

// https://github.com/logrotate/logrotate/blob/66921e4d3e8036838ee173c82db75a75d63a3e86/config.c#L134
static const char *defTabooExts[] = {
    ",v",
    ".cfsaved",
    ".disabled",
    ".dpkg-bak",
    ".dpkg-del",
    ".dpkg-dist",
    ".dpkg-new",
    ".dpkg-old",
    ".dpkg-tmp",
    ".rhn-cfg-tmp-*",
    ".rpmnew",
    ".rpmorig",
    ".rpmsave",
    ".swp",
    ".ucf-dist",
    ".ucf-new",
    ".ucf-old",
    "~"
};

logrotate 在 /var/lib/logrotate/logrotate.status(Ubuntu 下为 /var/lib/logrotate/status)中记录了上一次 logrotate 处理过的日志文件的记录:

...
"/var/log/ceph/ceph-osd.46.log" 2018-11-7-11:0:2
"/var/log/openvswitch/ovsdb-server.log" 2016-7-1-21:0:0
"/var/log/telegraf/telegraf.log" 2018-11-7-0:0:1
"/var/log/btmp" 2018-11-1-0:1:1
"/var/log/ceph/ceph.audit.log" 2018-11-2-15:40:1
"/var/log/ceph/ceph-osd.18.log" 2018-5-21-19:0:1
"/var/log/wpa_supplicant.log" 2016-7-1-21:0:0
"/var/log/salt/cloud" 2016-10-10-18:0:0
"/var/log/ceph/ceph-osd.29.log" 2018-11-7-11:8:22
...

后面的时间就是对相应的日志文件上一次 rotate 的时间,由于我们通常会把日志的处理策略定义成 hourly 或者 daily,如果我们想要快速测试,可以修改这里记录的时间,使得 logrotate 认为距离上一次 rotate 时间已经足够长(即超过了 1 hour 或 1 day),从而再次进行 rotate。需要注意的是删除这个文件里的记录没用(即不会立即进行 rotate),需要修改时间才可以(也可以使用 -f 选项强制 rotate)。

同时需要注意的是,如果 rotate 将要生成的目标文件已存在,则 logrotate 不会将现有的日志进行 rotate:

rotating log /var/log/ceph/ceph-osd.29.log, log->rotateCount is 7
dateext suffix '-20181107'
glob pattern '-[0-9][0-9][0-9][0-9][0-9][0-9][0-9][0-9]'
destination /var/log/ceph/ceph-osd.29.log-20181107.gz already exists, skipping rotation
switching euid to 0 and egid to 0

logrotate 在清理老的日志的时候只会处理和 dateext 定义规则一致的文件,而且是否删除也是完全按照这个 dateext 定义的字符串进行排序(而不是按照日志文件的时间戳),而且它也会根据 compress 是否配置来决定清理的日志文件类型,即如果配置了 compress,只清理 dateext.gz 后缀文件,反之只清理 dateext 后缀文件(显然这是基于数据安全性的考虑)。

下面是一些日志文件处理前和后的对比:

~# ll | grep ceph-osd.29
-rw-r--r-- 1 ceph ceph    2583 Nov  7 12:25 ceph-osd.29.log
-rw-r--r-- 1 ceph ceph   79015 Nov  4 23:59 ceph-osd.29.log.1.gz
-rw-r--r-- 1 root ceph       0 Nov  7 12:24 ceph-osd.29.log-20181021.gz
-rw-r--r-- 1 root ceph       0 Nov  7 12:24 ceph-osd.29.log-20181023.gz
-rw-r--r-- 1 root ceph       0 Nov  7 12:24 ceph-osd.29.log-20181025
-rw-r--r-- 1 root ceph       0 Nov  7 12:24 ceph-osd.29.log-20181026.gz
-rw-r--r-- 1 root ceph       0 Nov  7 12:24 ceph-osd.29.log-20181030.gz
-rw-r--r-- 1 root ceph       0 Nov  5 23:58 ceph-osd.29.log-20181101.gz
-rw-r--r-- 1 root ceph       0 Nov  5 23:58 ceph-osd.29.log-20181102.gz
-rw-r--r-- 1 root ceph       0 Nov  7 12:24 ceph-osd.29.log-20181103
-rw-r--r-- 1 root ceph       0 Nov  5 23:58 ceph-osd.29.log-20181103.gz
-rw-r--r-- 1 root ceph       0 Nov  5 23:58 ceph-osd.29.log-20181104.gz
-rw-r--r-- 1 root ceph       0 Nov  7 10:43 ceph-osd.29.log-20181105.gz
-rw-r--r-- 1 root ceph       0 Nov  5 23:58 ceph-osd.29.log-20181106.gz
-rw-r--r-- 1 root ceph       0 Nov  5 23:58 ceph-osd.29.log-2018110823.gz
-rw-r--r-- 1 ceph ceph  105617 Nov  3 23:59 ceph-osd.29.log.2.gz
-rw-r--r-- 1 ceph ceph  132385 Nov  2 23:59 ceph-osd.29.log.3.gz
-rw-r--r-- 1 ceph ceph  128014 Nov  1 23:59 ceph-osd.29.log.4.gz
-rw-r--r-- 1 ceph ceph  143521 Oct 31 23:59 ceph-osd.29.log.5.gz
-rw-r--r-- 1 ceph ceph  103647 Oct 30 23:59 ceph-osd.29.log.6.gz
-rw-r--r-- 1 ceph ceph  100826 Oct 29 23:59 ceph-osd.29.log.7.gz

~# ll | grep ceph-osd.29
-rw-r--r-- 1 ceph ceph       0 Nov  7 12:25 ceph-osd.29.log
-rw-r--r-- 1 ceph ceph   79015 Nov  4 23:59 ceph-osd.29.log.1.gz
-rw-r--r-- 1 root ceph       0 Nov  7 12:24 ceph-osd.29.log-20181025
-rw-r--r-- 1 root ceph       0 Nov  5 23:58 ceph-osd.29.log-20181101.gz
-rw-r--r-- 1 root ceph       0 Nov  5 23:58 ceph-osd.29.log-20181102.gz
-rw-r--r-- 1 root ceph       0 Nov  7 12:24 ceph-osd.29.log-20181103
-rw-r--r-- 1 root ceph       0 Nov  5 23:58 ceph-osd.29.log-20181103.gz
-rw-r--r-- 1 root ceph       0 Nov  5 23:58 ceph-osd.29.log-20181104.gz
-rw-r--r-- 1 root ceph       0 Nov  7 10:43 ceph-osd.29.log-20181105.gz
-rw-r--r-- 1 root ceph       0 Nov  5 23:58 ceph-osd.29.log-20181106.gz
-rw-r--r-- 1 ceph ceph     549 Nov  7 12:25 ceph-osd.29.log-20181107.gz
-rw-r--r-- 1 root ceph       0 Nov  5 23:58 ceph-osd.29.log-2018110823.gz
-rw-r--r-- 1 ceph ceph  105617 Nov  3 23:59 ceph-osd.29.log.2.gz
-rw-r--r-- 1 ceph ceph  132385 Nov  2 23:59 ceph-osd.29.log.3.gz
-rw-r--r-- 1 ceph ceph  128014 Nov  1 23:59 ceph-osd.29.log.4.gz
-rw-r--r-- 1 ceph ceph  143521 Oct 31 23:59 ceph-osd.29.log.5.gz
-rw-r--r-- 1 ceph ceph  103647 Oct 30 23:59 ceph-osd.29.log.6.gz
-rw-r--r-- 1 ceph ceph  100826 Oct 29 23:59 ceph-osd.29.log.7.gz

从 logrotate 的打印可以看出来这里的处理逻辑(即是否删除老的日志文件完全按照这个 dateext 定义的字符串排序,而且由于 compress 已配置,因此只清理 .gz 文件):

rotating log /var/log/ceph/ceph-osd.29.log, log->rotateCount is 7
dateext suffix '-20181107'
glob pattern '-[0-9][0-9][0-9][0-9][0-9][0-9][0-9][0-9]'
removing /var/log/ceph/ceph-osd.29.log-20181021.gz
removing old log /var/log/ceph/ceph-osd.29.log-20181021.gz
removing /var/log/ceph/ceph-osd.29.log-20181023.gz
removing old log /var/log/ceph/ceph-osd.29.log-20181023.gz
removing /var/log/ceph/ceph-osd.29.log-20181026.gz
removing old log /var/log/ceph/ceph-osd.29.log-20181026.gz
renaming /var/log/ceph/ceph-osd.29.log to /var/log/ceph/ceph-osd.29.log-20181107
creating new /var/log/ceph/ceph-osd.29.log mode = 0644 uid = 167 gid = 167
running postrotate script
switching euid to 0 and egid to 0
compressing log with: /bin/gzip
switching uid to 0 and gid to 167
removing old log /var/log/ceph/ceph-osd.29.log-20181030.gz
switching euid to 0 and egid to 0

去掉 compress 的配置进行验证也会看到类似的结果。

前面说过 logroate 是由 crond/cron 守护进程驱动的,CentOS 下 crond 的执行历史记录在 /var/log/cron 日志文件中,Ubuntu 下 cron 的执行历史记录在 /var/log/syslog 系统日志文件中,因此 logrotate 的执行历史可以通过分析 crond 的日志得到。

如果 logroate 出现奇怪的现象,一定要记得查看系统日志,如 CentOS 下为 /var/log/messages 或 Ubuntu 下为 /var/log/syslog

日志分析小技巧

  1. 使用 vim 可以直接查看 tar.gz 类型的日志压缩文件而不需要解压缩(注意是 vim 不是 vi);
  2. 当日志文件过大时,考虑使用 vim 处理日志文件 介绍的方法清理无关日志信息之后再分析;
  3. gunzip xxx.gz 会解压得到 xxx 文件,并自动删除原始的 xxx.gz 文件;
  4. gzip xxx 会压缩并生成 xxx.gz 文件, 并自动删除原始的 xxx;