记一次APP和DB间流量异常问题的排查

Posted 2020-10-26

###情景
通过zabbix监控发现有一个应用和数据库之间存在不定时的流量异常（也不频繁），具体为应用server的入向流量和数据库server的出向流量会有短时间（通常在一分钟左右）的激增，甚至快达到千兆网卡的传输上限。
###分析过程
通过症状，几乎可以断定是由于某些sql语句需要返回大量数据导致。但这次问题的分析结果确是很不顺利（其中有我前期方法不当的原因）。

初次分析：因为在那之前做了一个针对于故障/异常分析的日志分析系统(详见)，并且基于此完成了两次异常uri的定位为题。所以惯性思维还是用这套东西来对流量异常时间段内出现的请求，按照出现次数或响应时间或者响应大小排序，观察。折腾了一通，然这个方法就不是分析这个问题最直接的方法，自然分析不出啥结果。
在这期间也想到了tcpdump抓包，但是有两个问题：因为异常时间不固定；不合适的方法会导致抓包产生的文件体积非常大。当时也没相处好方法来抓包，所以就没再深究这个想法。

再次分析：仔细想还是抓包才是最直接的方法。于是写了一个脚本，在应用server上每隔5s计算一下之前5s的入向流量的带宽，根据应用和数据库之间正常的流量设置一个阈值，超过次阈值则触发抓包动作。这次是能看到一部分异常的流量了，但是由于这个脚本的机制是先判断流量再触发抓包，所以先天缺陷是无法抓到引发流量异常的sql的。

最终分析，大脑经过一夜的后台运行，终于想到了一个“完美”的抓包方法，大致思路如下：

开始抓包，通过tcpdump的-w 参数将结果写到文件。然后在死循环里每隔5s计算一下前5s的平均流量，跟阈值相比：
如果小于阈值，则kill掉之前的tcpdump进行，重新开始一个tcpdump，抓包数据还写到先前的文件中（会覆盖掉之前内容，解决了抓包文件不断变大的问题）；
如果大于阈值，则继续抓包，下一次循环再检测流量，若下一个5s周期流量降到了阈值之内，则kill掉tcpdump进程，同时将抓包文件重命名（这个是可以用来分析的有效抓包数据），然后再开启新的tcpdump重复之前的动作。

来看一下具体脚本（这个脚本是整个过程的关键）

#!/bin/sh
#by ljk 2017/03/18
#对于不定期出现的网络流量异常进行合理抓包

file=/proc/net/dev
i=0    #用来标记是否出现了流量异常以及异常持续了几个检测周期
cd /usr/local/src/mysql-sniffer/logs/query/
alias capture=‘tcpdump -nnvv port 3306 -w tcpdump.txt &>/dev/null‘

(capture) &    #放到后台执行，不至于阻塞主进程的逻辑

while true;do
    RX_bytes=`cat $file|grep eth0|sed ‘s/^ *//g‘|awk -F‘[ :]+‘ ‘{print $2}‘`
    sleep 10    #间隔10s
    RX_bytes_later=`cat $file|grep eth0|sed ‘s/^ *//g‘|awk -F‘[ :]+‘ ‘{print $2}‘`
    speed_RX=`echo "scale=0;($RX_bytes_later - $RX_bytes)*8/1024/1024/10"|bc`

    tcpdump_pid=`ps -ef|grep tcpdump|grep -v grep|awk ‘{print $2}‘`

    if [ $speed_RX -lt 15 ];then    #我的阈值是15Mb
        kill -9 $tcpdump_pid
        if [ $i -gt 0 ];then
            mv tcpdump.txt "$i"_tcpdump_`date  +"%F_%H:%M:%S"`
        fi

        (capture) &
        i=0
    else
        i=$(($i+1))
    fi
done

把该脚本放到后台运行，然后我很轻松的抓取到了一次异常周期内的数据包，然后通过wireshark进行分析，也很快的找到了问题sql，不出所料，就是因为对用户输入的验证不够严谨，导致where条件里出现了空字串进而需要返回将近全表的数据（真坑）。