玉修

玉修

关注
发信
关注(28)粉丝(399)

OpenSIPS 2.4.2 高并发下，日志丢失怎么办

 
问题年年有，今年特别多。最近公司对呼叫中心平台做了大幅度重构，基于OpenSIPS实现的会话管理服务，在高并发压测过程中，发现OpenSIPS的日志居然出现丢失的情况，简直让我食不知味，困惑不已。
最终虽解决了问题，但内部个中原理性尚未彻底弄明白，今日先记录在此，供同道中人参考，更希望有识之士能一解玉修心中之惑……
 
闲话不多说，来、来、来，翠花，上酸菜！！！！！！
OpenSIPS 2.4.2 高并发下，日志丢失怎么办-LMLPHP
 
1、运行环境配置
  • CentOS      7.4
  • Rsyslogd    8.24.0
  • OpenSIPS  2.4.2
1.1 OpenSIPS日志参数配置如下：
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-limiting
3、原因分析：
 
    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函数打印日志，按理不会因日志级别不同，而导致日志丢失的问题。这一点在下着实没能弄明白，要是有读者查明具体原由，烦请留言告知我，玉修在此谢过了(抱拳)。
 
OpenSIPS 2.4.2 高并发下，日志丢失怎么办-LMLPHP
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 restrat 、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=20000   (默认值200)
  • 同时修改/etc/rsyslog.conf文件，增加下面几行(CentOS6下没有Journal，只需增加下面的前两项)
  • $SystemLogRateLimitInterval 5       (默认值5，      CentOS7可选)
  • $SystemLogRateLimitBurst 20000  (默认值200，   CentOS7可选)
  • $imjournalRatelimitInterval 5           (默认值600，   CentOS7必选：不配置时，输出部分日志后，需要等10分钟才能再写入)
  • $imjournalRatelimitBurst 20000      (默认值20000，CentOS7必选：貌似修改该值不起作用)
 
5、知识拓展
 
5.1 OpenSIPS 日志相关的参数介绍
 
 

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<stdio.h>
#include<stdlib.h>
#include <syslog.h>
#include <unistd.h>

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
 相关文档：
 
08-30 04:36
Powered by LMLPHP ©2024 玉修 0.061543