一、背景

最近公司一个系统发生线上故障，系统架构为C/S的，客户端是APP；系统的功能有：联系人、短信、通话记录等，每个业务都有备份、恢复的功能，即用户可以在APP内备份自己的联系人、短信、通话记录至服务端，然后可以后续某个时间段恢复数据。

服务端架构如下：

第1层Nginx，主要做一些流量清洗、流控等处理；

第2层是应用层，分应用接入层和服务层，应用接入层做一些参数检查和登录检查等，服务层处理业务逻辑，这2层之间通过RPC通信；

底层的存储是Mysql和Hbase，Mysql存一些元数据，真正的业务数据存放在Hbase中；

该系统经过几次接手，没有人能对系统逻辑理解很清楚；

该系统从去年下半年开始一直偶尔有500的报错，但每次重启就好了，本次发生故障后，重启仍然是大量500；

二、问题分析

先查看接入层日志，发现大量的500错误：

Nginx错误日志如下：

发现是连接应用接入层超时，应该是应用接入层压力大，赶紧将接入层扩容，增加了1倍的服务器；

应用层扩容后，发现连接Hbase报错超时了（这里就不列日志了，日志很重要~）。

因为Hbase扩容后需要Rebalance，这个过程需要一段时间，为了尽量减少对线上影响，开始在nginx上限流，具体是通过access_by_lua_file指令进行限流，代码如下：

local headers = ngx.req.get_headers()
 local token = headers["xxx"]
 local tokenHash

 if (token == nil) or (token == "") then
   return
 end
  
 tokenHash = ngx.crc32_long(token)
 if ((tokenHash % 64) == 1 then
 else
   ngx.exit(505)
 end

代码比较简单，先从http头中取出标识，然后hash一下，然后让1/64的流量返回给后端，其余的直接返回505。

为什么不返回200呢，因为这样会丢失数据，以联系人为例，同步过程如下：

客户端将最后一次修改/增加的联系人增量上传给服务端，如果这时候服务端返回200，客户端以为服务端保存成功，下次就不会上传上次的数据了。

经过上述处理后，运维同学反应机房带宽打爆了，通过分析发现流量爆增10倍以上，和客户端的同学确认，如果服务端返回的不是200客户端会马上重试。

怎么办呢，将上面的代码改下，加个sleep：

local headers = ngx.req.get_headers()
local token = headers["xxx"]
local tokenHash

if (token == nil) or (token == "") then
  return
end
  
tokenHash = ngx.crc32_long(token)
if ((tokenHash % 64) == 1 then
else
  ngx.sleep(120)
  ngx.exit(505)
end

我们查了资料， ngx.sleep不会阻塞nginx进程，所以才敢放心的用。

这样处理之后，带宽还是满了，问题没有解决，因为所有在线客户端基本上都在重试了；

这时候Hbase扩容完了，我们将接入层、服务层的应用都重启了，现象是有一段时间是200，过会又是500了，通过日志分析发现前后端的超时时间不一致，导致nginx返回给应用是500，实际上后端还在处理；

调整了nginx几个超时时间：

proxy_connect_timeout 60s;
 proxy_send_timeout 60s;
 proxy_read_timeout 60s;

RPC的超时间也改为60秒，这样应用有些缓和，但还是有不少500报错；

再通过分析日志发现后端请求处理的请求是几分钟前的日志：

Nginx日志如下：

可以看到服务层的日志是在15：43：10左右处理的，而进入nginx的时间是15：24：44，前后差了19分钟，但我们的超时时间是60秒，这是为什么呢？

再分析下代码，原因是 因为RPC框架设计的不合理，此框架线程池参考的是Dubbo设计的，有threads和queues的配置，只不过框架中queues参数不能改，默认是threads*100，即如果线程数设置为500，则等待队列是50000，并且一直要处理等待队列才能处理新请求，所以造成新请求一直在nginx层报超时，但后端服务层还在处理很早以前的请求，即做一些无用功。

此时修改框架已经来不及，为了解决问题，我们再次进行限流，不过限流策略有些调整，即让每个客户端都有时间处理：

--入口函数
function run()
    local headers = ngx.req.get_headers()
    local token = headers["XXX"]
    local tokenHash
    local curTimeSec
    local minute
    local baseNum

    if (token == nil) or (token == "") then
        return
    end

    --current time
    curTimeSec = os.time()
    minute = math.floor(curTimeSec / 60)
    baseNum = 10

    tokenHash = ngx.crc32_long(token)
    if ((tokenHash % baseNum) == (minute % baseNum)) then
    else
          ngx.sleep(20)
          ngx.exit(505)
    end
end

--启动
run()

经过上面处理后，问题最终得到解决。

三、写在最后

整体来说，系统问题就是RPC框架设计不合理， queues参数写死并且还不能调整，作为一个中间件，面对的场景较多，需要一些参数来让使用者平衡具体场景的差异；

此次排查主要的手段有：

1、限流，主要是通过lua进行实现；

2、仔细分析日志发现应用是否正常，特别是系统异常日志的打印很重要；

3、从接入层到底层存储调和的超时时间对应上，从上往下可以逐渐小些，但不能下层比上层的大；