journal和rsyslog的恩怨情仇

  

背景

        在复杂的嵌入式环境中，通常使用systemd管理服务，以及通过syslog向上层application提供日志存储功能。

        这里有如下问题：

        1.systemd自带journal日志管理。

        2.syslog流程是怎么样的。

        3.journal和rsyslog放一起会发生化学反应吗？两者如何分工协作？

环境

        本文案例基于linux开源学习项目：linux-ps / ls · GitCode

        该项目基于yocto搭建了一整套qemuarm64的环境，学习使用参考前期博文。

分析

syslog

syslog是什么

        man 一下：

        即是向系统log存储日志的一个接口。存在于glibc，供大家使用统一管理日志。

        那么他提供什么规则来撑起linux的日志？

        syslog的日志类别

        分别为如下实体定义了特定的日志输出类（misc\sys\syslog.h）：

CODE facilitynames[] =
  {
    { "auth", LOG_AUTH },
    { "authpriv", LOG_AUTHPRIV },
    { "cron", LOG_CRON },
    { "daemon", LOG_DAEMON },
    { "ftp", LOG_FTP },
    { "kern", LOG_KERN },
    { "lpr", LOG_LPR },
    { "mail", LOG_MAIL },
    { "mark", INTERNAL_MARK },		/* INTERNAL */
    { "news", LOG_NEWS },
    { "security", LOG_AUTH },		/* DEPRECATED */
    { "syslog", LOG_SYSLOG },
    { "user", LOG_USER },
    { "uucp", LOG_UUCP },
    { "local0", LOG_LOCAL0 },
    { "local1", LOG_LOCAL1 },
    { "local2", LOG_LOCAL2 },
    { "local3", LOG_LOCAL3 },
    { "local4", LOG_LOCAL4 },
    { "local5", LOG_LOCAL5 },
    { "local6", LOG_LOCAL6 },
    { "local7", LOG_LOCAL7 },
    { NULL, -1 }
  };

        举几个例子：

        #define    LOG_CRON    (9<<3)    /* clock daemon */    为定时相关的日志，于是乎，在其他代码中，基本不会混乱使用，而在crond代码中，会使用该日志实体。 （其余类似）

        syslog实体等级

        当然，每个实体均存在不同等级。

CODE prioritynames[] =
  {
    { "alert", LOG_ALERT },
    { "crit", LOG_CRIT },
    { "debug", LOG_DEBUG },
    { "emerg", LOG_EMERG },
    { "err", LOG_ERR },
    { "error", LOG_ERR },		/* DEPRECATED */
    { "info", LOG_INFO },
    { "none", INTERNAL_NOPRI },		/* INTERNAL */
    { "notice", LOG_NOTICE },
    { "panic", LOG_EMERG },		/* DEPRECATED */
    { "warn", LOG_WARNING },		/* DEPRECATED */
    { "warning", LOG_WARNING },
    { NULL, -1 }
  };

        也就是说，syslog已经定义了很多日志实体和等级供开发者选择。

        syslog流程

        （misc\syslog.c）， 实际很简单，就是添加日志前缀，向/dev/log 使用udp发送log日志，整理如下：

关键的几个地方：

        1.当openlog的时候，根据参数控制是否直接创建并连接socket。

        2.每次发送log，用户态将申请8k的buf使用，然后释放。

        3.线程之间存在锁。

        4.发送时，使用udp，MSG_NOSIGNAL，并没有使用MSG_DONTWAIT，即可能阻塞。

rsyslog是什么

        syslog仅仅是c库中转发日志的api，并没有做日志管理。而rsyslog才是日志管理模块。见：

        rsyslog的内容较多，这里给出参考资料，然后说明重要的点。

        rsyslog官网：Welcome to Rsyslog — Rsyslog documentation

        rsyslog的配置：

        rsyslog的main配置存在于/etc/rsyslog.conf，部分截图如下：

        配置规则参考：https://www.rsyslog.com/doc/configuration/index.html

        主要支持三种配置：

        1.basic format：基本方式previously known as the sysklogd format,

        举例：

                mail.info /var/log/mail.log

                mail.err @@server.example.net

        2.advanced format：reviously known as the RainerScript format,

        mail.err action(type="omfwd" protocol="tcp" queue.type="linkedList")

        3.obsolete legacy format：previously known simply as the legacy format

废弃，不在使用。

        basic format规则：

        整体规则分为：

       SELECTORS   ACTIONS

        SELECTORS   由两部分组成，a facility and a priority。

        对了，参考上述章节syslog实体和等级，等于[syslog实体].[等级]。

        比如：kern.notice    mail.info 等等。

        支持模糊匹配。

        ACTIONS： 

        就是描述log文件的行为，目前我们主要是定义文件位置。

        #mail.info -/log/mail.info

        就是将mail.info类日志存放到/log/mail.info

        -代表异步。

        好了，这里大家值得注意，/log/mail.info 这个是rsyslog存放实际日志的地方。

        journal

        问题来了，syslog这个跟journal有什么关系？

        先介绍下 journal，journal是systemd的日志管理方案。使用journalctl查看和管理systemd日志（适用于大多数现代Linux发行版）Sytemd日志由journalctl管理，journalctl本身支持落盘。

        参考资料：https://www.freedesktop.org/software/systemd/man/latest/journalctl.html# 

        示例如下：

       

        配置如下，配置说明见连接：

        

恩怨情仇

        那么问题来了，rsyslog管理日志，journal也管理日志，是独立的吗？

        在syslog和journal同时存在时，日志到底发生了什么？

        核心图：

                实际案例：

rsyslogd的线程。
:/userdata# ll /proc/1531/fd/3
lrwx------ 1 root root 64 Jan  1 13:46 /proc/1531/fd/3 -> socket:[20553]

unix  2      [ ]         DGRAM                    20553    /run/systemd/journal/syslog
unix  8      [ ]         DGRAM                    20539    /run/systemd/journal/dev-log


:/userdata# ll /proc/1535/fd/6
l-wx------ 1 root root 64 Jan  1 14:19 /proc/1535/fd/6 -> /userdata/LOG_LOCAL_LOG_DEBUG.log

strace -p 1533
recvmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="<135>Jan  1 14:20:59 LOG_NDELAY:"..., iov_len=8096}], msg_iovlen=1, msg_control=[{cmsg_len=32, cmsg_level=SOL_SOCKET, cmsg_type=SO_TIMESTAMP_OLD, cmsg_data={tv_sec=946707659, tv_usec=833484}}, {cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS, cmsg_data={pid=1585, uid=0, gid=0}}], msg_controllen=64, msg_flags=0}, MSG_DONTWAIT) = 69


/userdata# ps -elfT | grep rsys
4 S root        1531    1531       1  0  80   0 - 73219 do_sel 13:46 ?        00:00:00 /usr/sbin/rsyslogd -n -iNONE
1 S root        1531    1532       1  0  80   0 - 73219 do_sel 13:46 ?        00:00:00 /usr/sbin/rsyslogd -n -iNONE
5 S root        1531    1533       1  0  80   0 - 73219 do_sys 13:46 ?        00:00:17 /usr/sbin/rsyslogd -n -iNONE  1533
1 S root        1531    1534       1  0  80   0 - 73219 do_sys 13:46 ?        00:00:00 /usr/sbin/rsyslogd -n -iNONE
5 S root        1531    1535       1  0  80   0 - 73219 futex_ 13:46 ?        00:00:11 /usr/sbin/rsyslogd -n -iNONE  写盘
0 S root        1691    1691    1233  0  80   0 -   752 pipe_r 14:20 pts/1    00:00:00 grep rsys

unix  8      [ ]         DGRAM                    20539    /run/systemd/journal/dev-log

journald
recvmsg(5, {msg_name=0xffffef35d170, msg_namelen=128 => 0, msg_iov=[{iov_base="<135>Jan  1 14:34:47 LOG_NDELAY:"..., iov_len=24575}], msg_iovlen=1, msg_control=[{cmsg_len=32, cmsg_level=SOL_SOCKET, cmsg_type=SO_TIMESTAMP_OLD, cmsg_data={tv_sec=946708487, tv_usec=242530}}, {cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS, cmsg_data={pid=1585, uid=0, gid=0}}], msg_controllen=64, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = 69
sendmsg(5, {msg_name={sa_family=AF_UNIX, sun_path="/run/systemd/journal/syslog"}, msg_namelen=29, msg_iov=[{iov_base="<135>Jan  1 14:34:47 LOG_NDELAY:"..., iov_len=69}], msg_iovlen=1, msg_control=[{cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS, cmsg_data={pid=1585, uid=0, gid=0}}], msg_controllen=28, msg_flags=0}, MSG_NOSIGNAL) = 69
faccessat(AT_FDCWD, "/run/systemd/journal/flushed", F_OK) = 0
mkdirat(AT_FDCWD, "/var/log/journal/e62c7874699a4022a151c537eb5f3613", 0755) = -1 ENOENT (No such file or directory)
/userdata# ls -l /proc/341/fd/5
lrwx------ 1 root root 64 Jan  1 08:00 /proc/341/fd/5 -> socket:[20539]

        从上图看，当journal和rsyslog同时存在的时候：

        1、/dev/log -> /run/systemd/journal/dev-log   /dev/log的实体为journal创建的socket：

        

        2.即使如此，syslog依旧无脑向/dev/log发送、

        

        3.rsyslog不会从/dev/log接收，然而从/run/systemd/journal/syslog接收消息。

        

unix  2      [ ]         DGRAM                    12376    /run/systemd/journal/syslog

        4./run/systemd/journal/syslog由jounal写入。

        5.rsyslog从/run/systemd/journal/syslog接收消息，然后罗盘。

       

        6.journal本身支持落盘。

总结：

        在同时存在journal和rsyslog的时候，syslog将先转给journal，然后由journal转给rsyslog，rsyslog分线程存储日志。

        因此是比较波折的过程。在配置rsyslog的时候，一定将不需要的调试日志剥离。

        为啥不直接用journal?

        因为他的日志不直接可读，需要使用journalctl解析、

有问题欢迎一起讨论。