https://blog.51cto.com/leejia/1714815

 

一,问题情景:

我们有多台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

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>进行转义,认为是消息体的一部分。

发表评论

您的电子邮箱地址不会被公开。 必填项已用*标注