Rsyslog多个socket监听udp端口问题
2019-07-16 本文已影响0人
Raphael_yf
近期在使用rsyslog-fwd和rsyslog-kafka做日志中转集群，3台4核8G虚拟机支撑峰值约70Krps，流量大概400M左右；
但好景不长，有个业务发现日志有丢失的情况，而且丢失很严重；暂将排查过程记录如下：
通过kafka的topic监控看数据根本就没写进来，可见问题出现rsyslog这一层；排查服务器监控后就更奇怪了，日志丢失的时间段内，rsyslog服务器的网卡流量也有降低，也就是日志没到rsyslog，再向前就说应用服务器了，但应用服务器rsyslog运行正常，而且也不可能同一时间点所有服务器都出现rsyslog故障吧？
排查中转集群上的rsyslog状态，也没有任何异常日志，中转集群上配置了很多imput和相应的rule，每次出问题的都是同一个imput，给rsyslog增加了pstats监控观察后也没有任何发现，在机器上排查时，无意发现以下信息：
lsof -i:11513
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
rsyslogd 31618 root 26u IPv4 217406269 0t0 UDP *:11513
rsyslogd 31618 root 27u IPv6 217406270 0t0 UDP *:11513
rsyslogd 31618 root 71u IPv4 217843183 0t0 UDP *:11513
通一个ipv4的11513端口，有两个socket在监听，其他正常的服务器都是1个，rsyslog为什么会拉起两个socket监听同一个端口呢？
netstat -natup |grep 11513
Proto Recv-Q Send-Q Local Address Foreign Address State PID/Program name
udp 525312 0 0.0.0.0:11513 0.0.0.0:* 31618/rsyslogd
udp 0 0 0.0.0.0:11513 0.0.0.0:* 31618/rsyslogd
udp6 0 0 :::11513 :::* 31618/rsyslogd
在通过netstat查看发现第一个socket的Recv-Q长期为非0，且一直是这个值，也就是存在接收队列，难道是rsyslog性能问题？ 回想故障的时间点也不像，发生故障的时间随机、不存在高峰期故障的特征
cat /proc/net/udp
sl local_address rem_address st tx_queue rx_queue tr tm->when retrnsmt uid timeout inode ref pointer drops
338: 00000000:2CF9 00000000:0000 07 00000000:00080400 00:00000000 00000000 0 0 217843183 2 ffff968bffbd5d80 2919950
338: 00000000:2CF9 00000000:0000 07 00000000:00000000 00:00000000 00000000 0 0 217406269 2 ffff968bf22fe1c0 65990
再通过/proc/net/udp可以看到第一行记录存在大量丢包的情况(最后一列)。
初步估计整个故障的流程如下：
- 1、rsyslog重新拉起一个socket监听11513端口，具体原因未知
- 2、但rsyslog的主进程只处理了老的socket接收的数据，并没有处理新起的socket连接，但外面进来的udp数据包都发送到新socket上面
- 3、新的socket没有程序处理数据包导致接收堆积到队列，Rec-Q的值 == net.core.rmem_default
- 4、队列满了之后就出现丢包，也就是proc/net/udp中的drops
根本原因还是在为什么新起了一个socket，还要继续排查
