OpenSIPS 2.4.2 高并发下，日志丢失怎么办
问题年年有，今年特别多。最近公司对呼叫中心平台做了大幅度重构，基于OpenSIPS实现的会话管理服务，在高并发压测过程中，发现OpenSIPS的日志居然出现丢失的情况，简直让我食不知味，困惑不已。
最终虽解决了问题，但内部个中原理性尚未彻底弄明白，今日先记录在此，供同道中人参考，更希望有识之士能一解玉修心中之惑……
闲话不多说，来、来、来，翠花，上酸菜！！！！！！
1、运行环境配置
- CentOS 7.4
- Rsyslogd 8.24.0
- OpenSIPS 2.4.2
log_level=3 log_stderror=no log_facility=LOG_LOCAL0 log_name="/usr/local/opensips/sbin/opensips" xlog_buf_size=409600
1.2 rsyslog.conf 自定义日志配置如下：
将设施为local0的所有级别的日志，都输出到指定文件
local0.* /var/log/opensips/opensips.log
1.3 OpenSIPS日志输出方式：
xlog("L_INFO", "[$fU->$rU] Route to user [$tu] [ci:$ci] [xcid:$hdr(X-CID)]");2、问题现象：
- 在低并发测试场景，按上述方式使用L_INFO级别输出日志时，都能在 /var/log/opensips/opensips.log 中正常打印日志，但是在高并发（20 CPS、1500并发）下，使用L_INFO级别输出的日志，经常会丢失。
- 高并发下，opensips的日志文件，经常出现输出一次后，会等30秒才输出后续的日志。
- 高并发下 /var/log/message 文件偶尔输出提示因日志输出速率超标，而强制丢弃部分日志的信息。如下所示：
Aug 19 21:42:55 uat16599 rsyslogd: imjournal: 4188 messages lost due to rate-limiting Aug 19 21:52:56 uat16599 rsyslogd: imjournal: 5108 messages lost due to rate-limiting Aug 19 22:02:57 uat16599 rsyslogd: imjournal: 5073 messages lost due to rate-limiting3、原因分析： OpenSIPS默认情况下日志内容是直接输出到Linux rsyslogd 服务的日志文件 /etc/message 中的，但可以通过修改rsyslogd服务的规则配置，将OpenSIPS的日志输出到指定文件（比如上面提到的在rsyslog.conf 中增加 local0.*的规则）。 通过分析OpenSIPS源码我们可以得知：OpenSIPS先调用 xlog.c 的 int xlog_2(struct sip_msg* msg, char* lev, char* frm) ，然后在dprint.h文件中调用rsyslogd守护进程的 void syslog(int priority, const char *format, ...) 方法进行输出日志。从源码上看，OpenSIPS并没有控制日志输出的速率，而且没有当日志量达到某个阈值而直接丢弃日志的功能。 因此，我有理由怀疑，日志丢失是Rsyslogd服务在作祟。 那还等什么，我们去探究一下Rsyslogd的到底是怎么回事…… 从rsyslogd从5.7.1版本开始(我的系统采用的rsyslogd是8.24.0)，新增了输出速率限制功能，默认情况下，如果一个PID在5秒内不能输出超过200条日志，否则超过200条之后的消息将被丢弃，所以会报 rate-limiting 记录。 另外，CentOS7 的Rsyslogd已经默认采用 Systemd Journal来处理本地日志文件(从/etc/rsyslog.conf文件中下面几行配置可得知)
# Turn off message reception via local log socket;
# local messages are retrieved through imjournal now.
$OmitLocalLogging on
然而Systemd Journal 默认情况下，30秒内只允许记录1000条日志文件，并且每10分钟累计最大处理20000条日志，这显然不够用啊。所以我们可以通过修改 Systemd Journal 的配置/etc/systemd/journald.conf来解决该问题。
Systemd Journal 是采用异步存储日志的，而老的rsyslog则是采用同步模式。
更多关于Rsyslogd的知识请参见：https://www.rsyslog.com/doc/v8-stable/configuration/index.html
OpenSIPS的xlog 默认的日志级别是 -1(ERR级别)，如果输出日志时指定的级别大于-1, 那么就有丢失的风险。从源码上看，OpenSIPS是直接调用 syslog函数打印日志，按理不会因日志级别不同，而导致日志丢失的问题。这一点在下着实没能弄明白，要是有读者查明具体原由，烦请留言告知我，玉修在此谢过了(抱拳)。
4、解决办法：
首先我们解决Linux 系统层面
4.1 解决使用“L_INFO”级别输出日志，高压下INFO级别日志容易丢失的问题
- 方式一、去掉第一个参数“L_INFO”（将采用默认的 L_ERR级别），高压下打印也都正常
xlog("[$fU->$rU] Route to user [$tu] [ci:$ci] [xcid:$hdr(X-CID)]");
- 方式二、指定OpenSIPS的默认日志级别：xlog_default_level=3或4, 这样高并发下基本正常，偶尔依旧会丢失部分日志
xlog_default_level=3 xlog("L_INFO", "[$fU->$rU] Route to user [$tu] [ci:$ci] xcid:$hdr(X-CID)]"); xlog("[$fU->$rU] Route to user [$tu] [ci:$ci] [xcid:$hdr(X-CID)]");4.2 解决日志输出速率达到rsyslog阈值的问题 通过调整rsyslog和Systemd Journal日志输出速率相关的配置。 调整后需要重启相关服务 : sudo service rsyslog restart 、sudo systemctl restart systemd-journald 目前想到下面三种解决方案，其中后两种方法下$OmitLocalLogging=on
- 方式一、采用rsyslog同步模式处理日志【简单粗暴】
- 修改/etc/rsyslog.conf文件，注释掉下面一行即可
- #$OmitLocalLogging on
- 方式二、关闭ystemd Journal的速率限制【野蛮暴力】
- 调整Systemd Journal的配置文件/etc/systemd/journald.conf (CentOS6没有)
- RateLimitInterval=0
- RateLimitBurst=0
- 同时修改/etc/rsyslog.conf文件，增加下面几行(CentOS6下没有Journal，只需增加下面的最后两项)
- $imjournalRatelimitInterval 0 (CentOS7必选)
- $SystemLogRateLimitInterval 0 (CentOS7可选)
- $IMUXSockRateLimitInterval 0 (CentOS7可选)
- 方式三、增大速率限制上限【温文尔雅】
- 调整Systemd Journal的配置文件/etc/systemd/journald.conf (CentOS6没有)
- RateLimitInterval=5s (默认值30s)
- RateLimitBurst=4000 (默认值200)
- 同时修改/etc/rsyslog.conf文件，增加下面几行(CentOS6下没有Journal，只需增加下面的前两项)
- $SystemLogRateLimitInterval 5 (默认值5， CentOS7可选)
- $SystemLogRateLimitBurst 4000 (默认值200， CentOS7可选)
- $imjournalRatelimitInterval 25 (默认值600， CentOS7必选：不配置时，输出部分日志后，需要等10分钟才能再写入)
- $imjournalRatelimitBurst 20000 (默认值20000，CentOS7必选：貌似修改该值不起作用)
| 参数 | 说明 | 默认值 |
| log_level | OpenSIPS输出的日志详细程度，值越大，代表输出日志越详细 | [-3, 4] |
| xlog_default_level | 是否需要将日志输出到启动OpenSIPS的控制台 | -1 |
| log_stderror | 是否需要将日志输出到启动OpenSIPS的控制台 | no |
| log_name | 以守护进程方式运行OpenSIPS时，输出日志的进程名称，如默认是启动OpenSIPS的命令名 /usr/local/opensips/sbin/opensips | argv[0] |
| log_facility | 指定使用rsyslogd 的facility 输出日志，默认会将日志输出到 /var/log/messages 文件中 | LOG_DAEMON |
| xlog_buf_size | 用于缓存单行日志的空间大小，如果待输出的日志超过该阈值，OpenSIPS将丢弃，并输出一个 buffer overflow 的错误 | 4096 |
5.2 xlog函数介绍
函数：xlog([log_level, ]format_string)
支持将format_string中的将伪变量(pseudo-variable)经过计算后打印出来。支持的日志级别参照syslog服务中的级别，具体可选值如下：- L_ALERT (-3)
- L_CRIT (-2)
- L_ERR (-1) - 如果不填写log_level，则默认选这个
- L_WARN (1)
- L_NOTICE (2)
- L_INFO (3)
- L_DBG (4)
样例： xlog("Received $rm from $fu (callid: $ci)\n"); xlog("L_ERR", "key $var(username) not found in cache!\n");
5.3 syslog 功能测试
- 使用下面命令，可以手动发送日志到syslog :
logger -p local1.info "hello world"
- C语言代码测试syslog : ztest_rsyslog.c
#include#include #include #include void Info(void) { int i; int j; openlog("info",LOG_PID,LOG_LOCAL1);/*注意这里的数字1要跟 /etc/rsyslog.conf中的配置一致 local1.* /home/admin/z_test_rsyslog.log */ syslog(LOG_INFO, "hello %s","info log test"); for(j = 0; j < 100000; j++) { for(i = 0; i < 35; i++ ) { syslog(LOG_INFO|LOG_LOCAL1, "hello not execute openlog for specify progress name : %s, loop=%d, index=%d", "info log test", j, i); syslog(LOG_ERR|LOG_LOCAL1, "hello not execute openlog for specify progress name : %s, loop=%d, index=%d", "ERROR log test", j, i); } sleep(1); } } void Woring(void) { openlog("woring",LOG_PID,LOG_LOCAL1); syslog(LOG_WARNING, "hello %s","warning log test"); } int main() { Woring(); Info(); closelog(); return 0; }
编译运行：
gcc -o ztest_rsyslog_bin ztest_rsyslog.c ./ztest_rsyslog_bin 在/home/admin/z_test_rsyslog.log 文件中就会输出下面日志了Aug 26 10:58:37 LPT0570 progress-name-info[30326]: hello info log test Aug 26 10:58:37 LPT0570 progress-name-woring[30326]: hello warning log test Aug 26 18:59:36 LPT0570 ztest_rsyslog_bin: hello not execute openlog for specify progress name : info log test, loop=0, index=0 Aug 26 18:59:36 LPT0570 ztest_rsyslog_bin: hello not execute openlog for specify progress name : ERROR log test, loop=0, index=0相关文档： https://www.opensips.org/Documentation/Script-CoreParameters-2-4#toc38 https://www.rsyslog.com/doc/v8-stable/configuration/index.html https://www.rsyslog.com/doc/v8-stable/configuration/modules/imuxsock.html?highlight=omitlocallogging https://www.rsyslog.com/doc/v8-stable/configuration/modules/imjournal.html https://www.rootusers.com/how-to-change-log-rate-limiting-in-linux/