Linux下的日志服务Rsyslog

  当前公司的业务系统是自己搞了个日志服务,其实也就是对格式化后的消息使用UDP发送做了一个封装,然后日志服务端根据执行进程名字创建对应的日志文件后,对相同服务的日志内容的聚集和落盘操作,并且日志文件每日进行截断保存。由于一些异常交易的跟踪排查都通过日志文件进行跟踪,所以平时对日志文件的依赖还是比较大的,但使用过程中发现这个自研的日志系统问题多多:
  (1). 日志文件的内容经常会乱序,虽然根据时间戳可以判断日志的先后顺序,但人为跳来跳去总有些别扭。在多线程环境下每发一条日志都会创建一个UDP socket,所以预想在今后随着业务增长和线程数目增加,日志量攀升的情况下这种乱序现象会更为的严重;
  (2). 有时候本该有的日志没有发现,不知道是执行流程改了还是怀疑是日志本身丢失了,毕竟是UDP协议发送的,可靠性是得不到保障的;
  (3). 采用自定义的日志格式,虽然zabbix也能进行一些正则匹配,但是我想后续接入专业的日志分析处理系统可能会比较困难,这里把所有的日志元数据都格式化死到消息体里面的;
  (4). 日志消息没法按照level灵活的分文件存放,查阅日志需要在一大堆的调试信息中寻找,费神费力,所以效率真心堪忧。

  一句话三个字儿:坑爹啊!所以在此强烈建议规模不大研发能力又有限的公司,还是应该选择成熟、大众、主流的后台开发组件:一方面这些开源组件对你遇到的和将要遇到的坑,人家都遇到帮你填了;二来他们通常构架灵活,扩充和修改方便,而且围绕他们做的配套工具和组件周边也比较丰富,很多事情都不必自己再做了。虽然,对程序员来说造一个轮子很简单,通过造轮子对比也是一个很好的学习进步方式,更厉害的是轮子对公来说也是KPI亮点,但是没有严格论证测试就将其推向生产环境是一个极度不负责任的行为,情况严重的话会给后续的开发维护带来不小的负担。
  由于现在业务规模也不大,而且也没有对日志做深入研究挖掘的需求,那些高大上的Logstash、ElasticSearch啥的就先不上了。其实syslog的增强版rsyslog、syslog-ng本身就功能丰富,稳定可靠,而且rsyslog现在已经是Linux发行版内置的默认日志服务,自定义服务在其中添加个ruleset、filter啥的也是妥妥滴,在感觉rsyslog和syslog-ng没有明显差异的情况下(不过确实后者的配置文件更加友好一些),就先不折腾了,免得运维哥哥嫌我们烦……

一、Rsyslog基本使用

  这里首先教大家先跑起来吧。Rsyslog是作为服务端运行的,而应用程序如果想要使用,只需要调用原先的syslog的操作接口就可以了:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
bool log_init(int log_level) {
openlog(program_invocation_short_name, LOG_PID , LOG_USER);
setlogmask (LOG_UPTO (log_level));
return true;
}
void log_api(int priority, const char *file, int line, const char *func, const char *msg, ...) {
int n = 0;
char buf[MAX_LOG_BUF_SIZE + 2] = {0,};
n += sprintf(buf + n,"[%s:%d][%s][%ld]-- ", file, line, func, (long)pthread_self());
va_list arg_ptr;
va_start(arg_ptr, msg);
int ret = vsnprintf(buf + n, MAX_LOG_BUF_SIZE - n, msg, arg_ptr);
va_end(arg_ptr);
n = (ret >= MAX_LOG_BUF_SIZE - n) ? MAX_LOG_BUF_SIZE : (n + ret);
buf[n++] = '\n'; buf[n] = 0;
::syslog(priority, buf);
}

  syslog本身会记录消息产生的环境参数,所以主机名、IP地址、时间戳、程序名等信息都会产生,这些内容不用手动封装到消息内容体中。当然,为了使用方便,可以定义各种level的调用宏,其形定义如下所示:

1
2
#define log_info(...) Log::instance().log_api( LOG_INFO, __FILE__, __LINE__, __FUNCTION__, __VA_ARGS__)
#define log_debug(...) Log::instance().log_api( LOG_DEBUG, __FILE__, __LINE__, __FUNCTION__, __VA_ARGS__)

  至于程序中怎么调用这些宏,我就不用说了吧。当系统跑起来时候,你可能会失望:/var/log下面啥也没有,这才是正常的。其实你只需要在/etc/rsyslog.d/中随便命名一个conf文件,内容如下:

1
2
3
if $programname == 'tibank' then /var/log/tibank/tibank.log
# Uncomment the following to stop logging anything that matches the last rule.
& ~

  然后重启rsyslog服务,那么你的日志消息就会路由到指定文件了。这个配置文件可以简单的就像上面使用程序名过滤,而且直接使用syslog的默认接口,当然也可以设置将日志功能变的更强大、好用和美观,至于怎么设置就是下面介绍的内容了。

二、Rsyslog基础结构

  Rsyslog维系了v5、v7、v8三个分支,而且他们的配置都不兼容,这点大家都吐过槽了,我也懒得说了。因为线上服务用的CentOS-6.x,系统自带v5分支,所以下文就按照v5的分支说明。
  Rsyslog的结构还是挺简单的,其定位就是高性能、强安全、模块化的设计。Rsyslog主要包括输入模块(input module)、过滤模块和输出模块(output module)三体,输入模块支持文件、网络等形式的内容输入,中部是rulesets构成的消息处理规则的核心,当输入的消息匹配到某个条件的时候,该消息就会被执行相应的操作(action),通常是执行写入到某个文件、写入某个数据库、邮件发送或转发到远程主机等操作。
rsyslog
  在Rsyslog中,一个ruleset可以拥有一个或者多个rule构成,对于一个指定的input,只可以有一个ruleset与之绑定,以处理这个输入的消息。用户可以创建自定义ruleset,系统本身有一个默认的RSYSLOG_DefaultRuleset。
  用户可以创建自定义ruleset,每个rule会包含一个过滤器filter和一个操作列表action list(可以包含一个或者多个action)。filter提供yes、no的条件匹配选项以控制执行流,当一个filter匹配满足(filter结果为yes)的时候,其相应的action list将会被执行。默认情况,当输入模块传入一个消息的时候,ruleset会从头至尾将所有的rules依次求值检验,而无论之前是否已经成功匹配。如果想要匹配某个rule,然后停止后续处理,需要在action list中显式调用discard操作来放弃继续求值匹配rules,这个操作就是“~”符号。
  Rsyslog使用简单,主要就是在开始的时候设置好其配置文件,然后rsyslogd守候进程会默默地帮助处理一切。

2.1 模板template

  Template在Rsyslog中是一个重要的部分,可以用来帮助对输出的消息格式化,帮助生成动态文件名等操作,如果操作数据库的话Template就更加不可缺少了,总之就是其定义规则形式,然后被其他模块调用。其操作语法为:

1
2
3
$template MyTemplateName,"\7Text %property% some more text\n", <options>
$template TraditionalFormat,"%timegenerated% %HOSTNAME% %syslogtag%%msg%\\n"
$template DynFile,"/var/log/system-%HOSTNAME%.log"

  其中模板的内容字符串可以使用通常的转义字符。Rsyslog内置了一些模板,这些末班都以RSYSLOG_前缀命名。

2.2 Rsyslog Properties

  Rsyslog将数据元称之为properties,通常都是从输入消息中提取出来的重要属性信息,可以方便的被用在模板、条件判断等位置。
  重要的properties有:msg、hostname、fromhost、fromhost-ip、syslogtag、programname、syslogfacility|syslogseverity、timegenerated(高精度的消息收到时间)、timereported(消息本身的低精度时间戳)。
  上面说到这些properties可以方便的用到Template等需要的位置,访问语法为:

1
%property:fromChar:toChar:options%

  fromChar和toChar表示其值的字符范围,从1开始计数,收尾闭区间包含,结尾可用$表示。复杂情况还可以使用正则表达式来选取。options可以执行一些相关的选项,比如:uppercase、lowercase、date-rfc3339等。

2.3 Filters过滤模块

  Rsyslog的过滤模块算是消息处理的核心,其支持三种类型的过滤:
  (1) 传统的severity、facility选择器
  这是Linux最传统的消息过滤器,其selector的格式为”facilicy.priority”,其字段的值可以参照man syslog的输出。
  默认情况下,匹配到优先级为priority及其比他高的消息都会被命中执行action,此外Rsyslog还做了一些小扩展:”*“用以表示任意facility和severity;=表示指定优先级而不会命中更高优先级;!表示匹配条件取反;多个facility可以和同一个severity搭配,他们之间用逗号分隔。
  此外,还可以联合多个selector条件,他们之间用分号分隔,然后同用一个action。
  (2) 基于property的过滤器
  这是rsyslog特有的,可以基于上面说到的properites对消息进行过滤,其基本语法为:

1
2
:property, [!]compare-operation, "value"
:msg, regex, "fatal . * error"

  !表示匹配条件的结果取反。合法常用的比较操作有:contains、isequal、startswith、regex等,而且值部分如果有引号、右斜杠需要进行特殊字符转义。下面这个例子表示所有包含informational的消息不放到第二个日志文件中去:

1
2
3
* . * /var/log/allmsgs-including-informational.log
:msg, contains, "informational" ~
* . * /var/log/allmsgs-but-informational.log

  (3) 基于表达式的过滤器
  表达式匹配是最灵活强大的过滤方式,比如最开始的程序名匹配,其支持布尔、数字、字符串的比较操作。其操作格式为:

1
if expr then action-part-of-selector-line

  property的过滤器可以用表达式来书写

1
2
3
* . * /var/log/file1 # the traditional way
if $msg contains 'error' then /var/log/errlog # the expression-based way
if $syslogfacility-text == 'local0' and $msg startswith 'DEVNAME' and ($msg contains ˓→'error1' or $msg contains 'error0') then /var/log/somelog

2.4 Actions

  当上面的过滤模块匹配得当后,相应的Actions就会被执行,通常的操作有:输出到某个日志文件中、写入到数据中、转发到远程其他主机等。对于一个selector,可以指定多个action操作,额外的操作使用&打头依次排列:

1
2
3
* .=crit :omusrmsg:rger
& root
& /var/log/critmsgs

  最典型的操作就是将消息计入到日志文件中。在action中指明日志文件的路径就可以了,默认情况下每条消息都是同步到磁盘的,可以在前面添加“-”表示不进行每条消息同步操作,就可以在消息持久化和日志性能之间做出选择。
  文件名可以是静态指定的,也可以根据文件尺寸、消息来源、日期等信息进行动态规划文件名。文件名模板以?打头,其设置格式为:

1
2
$template DynFile,"/var/log/%HOSTNAME%/%programname%.log"
* . * [-]?DynFile[;MyTemplate]

  常规文件还有很多参数可以设置,比如创建文件的unmask、文件属主等新。

2.5 输入输出模块

  上面说到Rsyslog是模块化设计的,那么输入输出模块就是最好的体现,在Ruleset开始的时候,可以根据本模块的输入输出源加载需要的模块,当然根据模块的不同还有很多个性化的参数需要设置指明。
  常见的输入模块比如imfile、imtcp、imudp等,输出模块可用ommail、ommysql等。当然每个输入或者输出的模块差异很大,所以他们的参数也各不相同,需要的时候查阅相关的文档。

三、Rsyslog项目实战

  好吧,看了半天感觉还是运维的工作,基本是配置完路由工作后就可以直接使用了。下面就以我们最常见的生产服务器将日志转发到日志服务器,并进行消息格式化的简单例子来说明。
  (1) 客户服务器
  客户服务器很简单,就将本地的日志转发到远程的主机就可以了。通过syslog的日志手册,我们发现openlog的最后一个参数是指明facility来着的,其中我们可以使用LOG_LOCAL0~LOG_LOCAL6中的一个作为参数(好像LOG_LOCAL7保留给了boot message,就不要用它了),后续再处理日志的时候可以方便的使用facility进行过滤。我们再/etc/rsyslog.d/下面随便建立一个conf文件,其内容如下:

1
2
3
local6.* @@192.168.0.10:8999
# not process later
& ~

  上面的@@表示使用TCP协议进行转发,而如果@表示使用UDP协议进行转发。
  (2) 日志服务器
  首先日志服务器要能收到客户机发过来的日志,就需要配置对应的输入模块imtcp、imudp……,使用$InputTCPServerRun 8999就可以了,但是此处需要注意的是如果多个客户端分别以不同的端口向服务器发送日志,为了进行隔离,最好将不同的端口绑定到不同的Ruleset上面,可以参考附录的《Multiple Rulesets》,这个比较重要,否则你的Action可能执行不了,甚至造成消息丢失。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
$ModLoad imtcp
#define rulesets first
$RuleSet syslogruleset
$template SyslogFormat,"[%fromhost-ip%][%TIMESTAMP:::date-rfc3339%]<%syslogseverity-text%>%msg%\n"
$template DailyErrorFileLogs,"/data/logs/paybank/%$YEAR%%$MONTH%/%programname%.error.log_%$YEAR%%$MONTH%%$DAY%"
$template DailyInfoFileLogs,"/data/logs/paybank/%$YEAR%%$MONTH%/%programname%.info.log_%$YEAR%%$MONTH%%$DAY%"
$template DailyDebugFileLogs,"/data/logs/paybank/%$YEAR%%$MONTH%/%programname%.debug.log_%$YEAR%%$MONTH%%$DAY%"
if $syslogfacility-text contains 'local6' and $syslogseverity <= 3 then ?DailyErrorFileLogs;SyslogFormat
if $syslogfacility-text contains 'local6' and $syslogseverity <= 6 then ?DailyInfoFileLogs;SyslogFormat
if $syslogfacility-text contains 'local6' then ?DailyDebugFileLogs;SyslogFormat
& ~
$InputTCPServerBindRuleset syslogruleset
$InputTCPServerRun 8999

  上面的配置,首先加载imtcp模块,然后自定义一个ruleset,在ruleset中我们定义了日志条目的模板和动态文件的模板,并在后面的Filter部分根据日志的等级路由到不同的文件里面去。最后,关键的一部是先绑定ruleset,然后再启动TCP侦听服务。
  下周就打算将手下的服务日志都替换成syslog的,希望开头所提到的问题能一劳永逸地被解决。上面已经将不同等级的日志录入到各个不同的文件中去,所以也希望业务代码能够按照规范和约束使用日志接口,调试、提示、错误类别的信息分开来,后续监控、查找也会方便很多!

本文完!

参考