目录
前言:
这是我上周工作过程中的一次解决问题的过程。解决的是nginx负载环境下,因为应用程序异常导致某一请求被多节点站点重复处理的问题。 我整理这个复盘的过程时,在给这个记叙文命名时思考了一段时间。 从业务角度说,应该是“一次短信重复发送问题的解决过程”,如果这样命名,过于土气;从技术角度说,应该是“nginx负载下当程序错误时会导致请求被多次重复处理”,如果这样命名,可能没人会注意了;最后,我懒得再费脑汁了,从人类智慧的角度我把它命名为“复杂的问题简单的解,小不慎则乱大谋”。
问题来了
3月16日,有客服、销售、运营人员不断反映,客户在saas预定机票完成后,会连续收到3条重复的支付提醒短信。 很多客户都投诉了这样的问题,一直以来的正常情况下这样的支付提醒短信是仅发1条的。
以下是短信平台上的截图:
前一天的3月15日周二是每周的上线日,当晚saas上过线。
迫于压力,当天下午不得不回滚3月15日的上线。回滚之后,问题不再重现。
3月15日saas的上线包括锦如和刘涛对saas所做的代码改动。刘涛涉及到的代码是审批接口,称可能不会导致这样的问题,锦如也肯定地表示不涉及到这块。 我让刘涛来排查原因,他在测试环境做了几次测试,并未发现这样的问题。我呢,由于最近忙于另一个项目,一直没来得及亲自和他一起查找原因。
问题又来了
3月17日是周四,上线日。要发布中新融创的对接程序。 晚上上线后,立即在线上订票,发现订单支付提醒短信还是会重复发3遍。
当时已经是晚上21点,我决定放下手头的活儿,来跟刘涛一起排查原因。
问题分析
客户在saas站点里预定机票,涉及到审批。审批是独立部署的一个站点。
订单的审批逻辑是这样的:客户在saas订票成功后,会跳转到统一审批页,提交审批后,统一审批系统会把审批状态通知给saas,然后重定向页面到订单流的下一个页面(由saas提供)。
Saas提供了一个由一般处理程序(文件是HandlerAirOrderExamineStatus.ashx)实现的接口,用来接收审批状态。内部大致逻辑是,修改订单的审批状态,然后会触发相应的对客通知短信。 客户重复收到的通知短信是支付提醒短信,意味着订单不需要审批。不需要审批在系统里表现在这些企业没有配置审批流。 根据现有代码逻辑,从填单页跳转到统一审批页,统一审批页初始化时没有获取到新审批,则会自动执行通知saas和页面重定向。
要补充说明一下的是,线上的审批站点和saas站点均是通过nginx做的3节点服务器的负载。
通过查看线上日志,审批系统正常,即只会在其中一个节点服务器来请求saas接口进行审批状态的通知,并未发现异常日志。而saas呢,却发现3个节点服务器都记录了同样的日志。
为什么会出现这样的情况呢? 审批在通知saas时,nginx接收到请求后应该分发给其中一个节点服务器来处理请求才对呀。
困惑
因为之前系统运行都是正常的,并未出现这种短信重发的情况,所以我们暂先不怀疑代码逻辑。
马上想到,记得运维说过,如果一个服务器处理时间超长,会自动分发给另一个节点服务器。 历史原因,获取订单详情和触发短信通知这两段代码执行比较慢,那么,我在这两段代码外面加了个Stopwatch来诊断其执行时长。
public void ProcessRequest(HttpContext context) { Stopwatch sw = new Stopwatch(); sw.Start(); if (context.Request.Params.Count == 0) { context.Response.Write("{'returnCode':'2','returnMsg':'no parameters','notifiedSMSContent':'no parameters'}"); return; } string parametersStr = context.Request.Params[0].AsToString(); SysLogToFile.WriteAuditMessage("dat修改订单状态传入参数_" + parametersStr); // 下面的是200行逻辑代码,包括获取订单详情和触发短信通知 ...... ...... ...... ...... ...... ...... ...... ...... ...... ...... ...... ...... ...... ...... ...... ...... ...... ...... ...... ...... ...... ...... ...... ...... sw.Stop(); SysLogToFile.WriteAuditMessage("审批接口响应时间" + (sw.ElapsedMilliseconds / 1000)); string returncode, returnmsg; if (flag) { returncode = "1"; returnmsg = "success"; } else { returncode = "2"; returnmsg = "fail"; } context.Response.Write("{'returnCode':'" + returncode + "','returnMsg':'" + returnmsg + "','notifiedSMSContent':'" + returnmsg + "'}"); }
发布后经测试,发现3个节点的执行时长都长达7~8秒。
那么,我们接下来就优化程序吧,以期把duration降到最小。20分钟后,我们把优化的代码再发布到服务器。发现处理时间已经下降到了1~2秒。
然而,响应时间已经都优化到2秒了,依然是3个服务器节点上都做了处理。这带给我们的是一个更大的问号。
转机
为什么会有一个更大的问号呢? 因为我们线上的系统都是分布式部署的,一个流程逻辑会涉及到多个系统之间的交互访问。 每个系统都是通过nginx做的3个节点的负载,并没有出现过这种一个请求被3个服务器节点同时响应的情况。
在这种情况,我的一贯做法是釜底抽薪。当然,这次我依然坚持釜底抽薪。
Q:怎么釜底抽薪呢?
A:把接口里的代码都注释掉。响应时间应该接近于0毫秒,难道还会出现3个节点都响应的情况?
于是,我们注释掉所有逻辑代码,只保留了最后的输出(context.Response.Write)语句,发布到服务器。
由于我们每次的测试步骤是:登陆saas,选择航班,然后订票下单,再看日志,这一系列的操作很耗时间,同时给线上系统带来了很多无效订单(垃圾数据)。这次呢,我让刘涛直接在ie里访问那个通知接口地址来测试性能。
转机来了,在ie里直接访问那个接口时,页面直接抛出了大黄页,报“System.FormatException:输入字符串的格式不正确”,是由主方法里最后的这条语句产生的:
context.Response.Write(string.Format("{'returnCode':'{0}','returnMsg':'{1}','notifiedSMSContent':'{2}'}", returncode, returnmsg, returnmsg));
即在string.Format方法里,你是不能乱用‘{’的~。
于是,修复后(改成字符串拼接了)再次上线。
再次访问那个接口,返回正常了。最大的惊喜是,SaaS那边只有一个服务器节点受理了请求。到这里呢,短信重发3次的问题终于得到了根治!
这时,我才想起来,nginx在接收到请求后,会分发给多个服务器节点中的一个节点来处理请求,但是,当出现错误响应时,nginx会自动分开给另一个节点来处理,直到没有节点可供分发,即直到所有可用节点都被分发为止。(当然,这可能是我们运维对nginx的配置策略)
后续
我们解决完这个问题,已经午夜23:40,如释重负的打车回家了。
在回去的路上,我的脑子像过电影似的过了一遍我们这一晚的处理过程。
l 复杂的问题,在你用心解决时,往往产生自很简单的一行代码。很戏剧性的是,这行代码可能是你不经意的疏忽写错了,也可能是技能受限写错的。如果,有做简单的测试,这样的问题完全是可以在开发时被发现的,而不至于花费那么长的时间来。
l 另外,我又想到,审批系统调用接口时难道没有判断响应结果就做下一步的重定向了?这个疑问在第二天咨询刘涛时得到了肯定。这样的实现不够严谨,于是,我让他加上对结果的判断。 如果事先有这个判断,那么,这样的问题在审批请求时就会被发现的,何至于经历那么漫长的排查过程呢。