rsyslog center詭異丢日志問題分析解決

一，問題情景：

我們有多台apache server，apache上的access log會通過rsyslog client傳送給rsyslog center彙總并展示給使用者。最近一段時間，有多個使用者回報自己的access log不全，有丢失的現象。而我們之前的相關變更是把使用者的debug日志和info日志放在相同的一個日志級别中傳輸。

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

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

三，問題解決

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

有可能是由于某使用者的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>進行轉義，認為是消息體的一部分。

本文轉自 leejia1989 51CTO部落格，原文連結：http://blog.51cto.com/leejia/1714815，如需轉載請自行聯系原作者