問題年年有，今年特別多。最近公司對呼叫中心平台做了大幅度重構，基於OpenSIPS實現的會話管理服務，在高並發壓測過程中，發現OpenSIPS的日志居然出現丟失的情況，簡直讓我食不知味，困惑不已。
最終雖解決了問題，但內部個中原理性尚未徹底弄明白，今日先記錄在此，供同道中人參考，更希望有識之士能一解玉修心中之惑……
閑話不多說，來、來、來，翠花，上酸菜！！！！！！
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 是采用異步存儲日志的，而老的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必選：貌似修改該值不起作用)
5、知識拓展
5.1 OpenSIPS 日志相關的參數介紹
|
參數
|
說明
|
默認值
|
| 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<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
相關文檔：