rsyslog center诡异丢日志问题分析解决

121饿

一，问题情景：
我们有多台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>进行转义，认为是消息体的一部分。