問題年年有，今年特別多。最近公司對呼叫中心平臺做了大幅度重構，基於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 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 日誌相關的引數介紹
|
引數
|
說明
|
預設值
|
| 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
相關文件：