rsyslog center詭異丟日誌問題分析解決

標籤：rsyslog   received oversize message   framing error in received tcp message   

一，問題情景：

我們有多台apache server，apache上的access log會通過rsyslog client傳送給rsyslog center匯總並展示給使用者。最近一段時間，有多個使用者反饋自己的access log不全，有丟失的現象。

二,尋找原因及解決辦法：

1,部署監控

我們給一個rsyslog center做了一個監控，每2min鐘curl 5次指定的url，然後看rsyslog center是否出現此log，把每2min的丟失數量展示在graphite中。以便於我們對日誌的丟失比率有一個直觀的掌控。

2,分析監控圖

發現日誌是時丟時不丟，並且丟失比率也不固定。

3,分析log

一個請求被哪台apache處理，我們在log中有欄位來記錄。分析rsyslog center我監控url的log，發現一個奇怪的現象。例如：監控發現連續4個小時丟日誌，而這四個小時中的log中處理監控url的都沒有出現某一台apache server。而接下來不丟的2小時，這台apache server又出現了。再過一段時間又變成另一台apache server不在rsyslog center中。而監控的url的log在apache server本地的log中，都是正常的，沒有丟失現象。

4,抓包分析

在rsyslog center通過抓包分析，發現在丟的日誌，在rsyslog center server抓包是能抓到的，所以當時認為這個丟日誌的問題和服務端有關係。

5,根據分析，認為是rsyslog 效能跟不上導致丟日誌，故做了如下操作：

rsyslog的main queue和action queue進行調優;

rsyslog升級到最新穩定版;

把某各個apache組的log分到另一台機器上進行處理;

結果：問題依舊，丟日誌情況沒有任何改觀

6,分析rsyslog 錯誤log

rsyslog client端沒有報錯，一切正常;

rsyslog server段的報錯如下：

Nov 19 16:02:01 received oversize message: size is 90887294 bytes, max msg size is 4096, truncating...
Nov 19 16:02:41 Framing Error in received TCP message: delimiter is not SP but has ASCII value 46.
Nov 19 16:02:49 Uncompression of a message failed with return code -3 - enable debug logging if you need further information. Message ignored.
Nov 19 16:03:13 Framing Error in received TCP message: delimiter is not SP but has ASCII value 45.
Nov 19 16:03:13 Framing Error in received TCP message: delimiter is not SP but has ASCII value 46.
Nov 19 16:03:24 Framing Error in received TCP message: delimiter is not SP but has ASCII value 35.
Nov 19 16:03:24 Framing Error in received TCP message: delimiter is not SP but has ASCII value -27.

不應該出現的詭異現象：

(1)log中竟然會有received oversize message的報錯，我們的log都是一條一條發送的，並且一條log也就最大2kB，小於MaxMessageSize，不應該出現oversize的情況。

(2)在rsyslog center中發現了以<158>開頭的access log，並且這種log是多條挨著一起出現。看了一下大小，一片多條log的總大小恰好和MaxMessageSize很接近。並且，<158>是rsyslog協議的一部分，是local3的info日誌，rsyslog竟然沒有解析。

尋找rsyslog error：

1,出現received oversize message

很明顯就是rsyslog接收到的訊息到單條message大於了MaxMessageSize大小，所以給截斷了。保留了MaxMessageSize，其餘的都丟棄了。丟棄了90MB的日誌。

2,出現Framing Error in received TCP message: delimiter is not SP but has ASCII value 46.：

看這條日誌報錯，根據源碼分析，是因為使用了TCP Message with octet-counter的一種方式。看rsyslog配置，和SupportOctetCountedFraming這個參數有關，預設是On。If set to “on”, the legacy octed-counted framing (similar to RFC5425 framing) is activated. 

那我們接著來看octed-counted framing：

通過查看官方文檔，我們知道：它是只適用於tcp的一種把多條message放在一條message中發送的解決辦法，使用這種方式，rsyslog client在發送這條大message的時候，可以在第一個包中加上message的長度，具體格式應該為“length <158>message"。這樣就成功解決了多條message放在一台message中發送的問題了。如果length和<158>之間沒有空格的話，就會報類似Framing Error in received TCP message: delimiter is not SP的錯誤。

源碼地址：https://github.com/rsyslog/rsyslog/blob/a9133e3e8c48491eeb7b87ec27b780532aa04649/runtime/tcps_sess.c#L386

rsyslog關於octed-counted framing的解釋：http://www.rsyslog.com/doc/v8-stable/configuration/modules/omfwd.html

三，問題解決

匯總上面所有資訊，再根據我們雲平台幾十萬應用的業務情境。我們推斷：

有可能是由於某使用者的debug或者info log中，包含了斷行符號控制符\n，而我們rsyslog client段的設定檔中EscapeControlCharactersOnReceive是off的，即不對控制符做轉義，所以含有\n控制符的log被發送給了rsyslog center。而rsyslog center是根據斷行符號控制符\n來判斷是不是一條log的。如果使用者的log中包含類似欄位：GET /123/id=123&\n90887294--sdf，那麼rsyslog會把”GET /123/id=123&“當作一條log，而把90887294作為下一條message的長度，並且會有剛才的Framing Error的報錯。rsyslog會等待接收90887294byte的資料，然後判斷大於了MaxMessageSize 4KB，然後rsyslog就只儲存了從90887294開始之後的4KB日誌，剩下的90887294 - 4*1024= 90883198byte的資料全被截斷丟棄。這就有了received oversize message的報錯。

issues：https://github.com/rsyslog/rsyslog/issues/111

解決辦法：

1,開啟rsyslog client的EscapeControlCharactersOnReceive為on狀態。對斷行符號控制符進行轉義，即可避免此問題

影響：把使用者log中的\n轉換成了以#開頭的三位八位元#012。（根基ascii錶轉換）

2,關閉rsyslog center的SupportOctetCountedFraming為off狀態。即不支援Octet資料流。

影響：當使用者log中有\n的時候，log會被截斷。

詭異問題解釋：

1,第一個問題已經解答了

2,出現連續的<158>的日誌，是因為rsyslog center接受了90887294位元組資料，只保留了4KB資料，而4KB資料中可能有多條log，而每條log都以<158>開頭，rsyslog 並沒有對<158>進行轉義，認為是訊息體的一部分。

本文出自 “佳” 部落格，請務必保留此出處http://leejia.blog.51cto.com/4356849/1714815

rsyslog center詭異丟日誌問題分析解決