前言：
這是我上周工作過(guò)程中的一次解決問(wèn)題的過(guò)程。解決的是nginx負(fù)載下站點(diǎn)錯(cuò)誤響應(yīng)導(dǎo)致其他節(jié)點(diǎn)重復(fù)響應(yīng)。 我在整理這個(gè)記敘文時(shí)，在給這個(gè)文檔命名時(shí)思考了一段時(shí)間。 從業(yè)務(wù)角度說(shuō)，應(yīng)該是“一次短信重復(fù)發(fā)送問(wèn)題解決過(guò)程”，如果這樣命名，過(guò)于土氣；從技術(shù)角度說(shuō)，應(yīng)該是“nginx負(fù)載下站點(diǎn)錯(cuò)誤響應(yīng)會(huì)導(dǎo)致其他節(jié)點(diǎn)重復(fù)響應(yīng)”，如果這樣命名，可能沒人會(huì)注意了；最后，我懶得再費(fèi)腦汁了，從人類智慧的角度我把它命名為“復(fù)雜的問(wèn)題，簡(jiǎn)單的解，小處不謹(jǐn)慎，”。
問(wèn)題來(lái)了
3月16日，有客服、銷售、運(yùn)營(yíng)人員反映，客戶在saas預(yù)定機(jī)票完成后，會(huì)連續(xù)收到3條重復(fù)的支付提醒短信。 ?很多客戶都投訴了這樣的問(wèn)題，一直以來(lái)的正常情況是僅發(fā)1條的。
以下是短信平臺(tái)上的截圖：
前一天的3月15日是上線日，當(dāng)晚saas上過(guò)線。
迫于壓力，當(dāng)天下午不得不回滾3月15日的上線?；貪L之后，問(wèn)題不再重現(xiàn)。
3月15日saas的上線包括錦如和劉濤對(duì)saas所做的代碼改動(dòng)。劉濤涉及到的代碼是審批接口，稱可能不會(huì)導(dǎo)致這樣的問(wèn)題，錦如也肯定地表示不涉及到這塊。 我讓劉濤來(lái)排查原因，他在測(cè)試環(huán)境做了幾次測(cè)試，并未發(fā)現(xiàn)這樣的問(wèn)題。我呢，由于最近忙于另一個(gè)項(xiàng)目，一直沒來(lái)得及親自和他一起查找原因。
問(wèn)題又來(lái)了
3月17日是周四，上線日。要發(fā)布中新融創(chuàng)的對(duì)接程序。 晚上上線后，立即在線上訂票，發(fā)現(xiàn)訂單支付提醒短信還是會(huì)重復(fù)發(fā)3遍。
當(dāng)時(shí)已經(jīng)是晚上21點(diǎn)，我決定放下手頭的活兒，來(lái)跟劉濤一起排查原因。
問(wèn)題分析
客戶在saas站點(diǎn)里預(yù)定機(jī)票，涉及到審批。審批是獨(dú)立的一個(gè)站點(diǎn)。
訂單的審批邏輯是這樣的：客戶在saas訂票成功后，會(huì)跳轉(zhuǎn)到統(tǒng)一審批頁(yè)，提交審批后，統(tǒng)一審批系統(tǒng)會(huì)把審批狀態(tài)通知給saas，然后重定向頁(yè)面到訂單流的下一個(gè)頁(yè)面（由saas提供）。
Saas提供了一個(gè)由一般處理程序（文件是HandlerAirOrderExamineStatus.ashx）實(shí)現(xiàn)的接口，用來(lái)接收審批狀態(tài)。內(nèi)部大致邏輯是，修改訂單的審批狀態(tài)，然后會(huì)觸發(fā)相應(yīng)的對(duì)客提醒短信。 客戶重復(fù)收到的短信是支付提醒短信，那么，意味著訂單不需要審批。不需要審批在系統(tǒng)里表現(xiàn)在這些企業(yè)配置審批流。 根據(jù)現(xiàn)有代碼邏輯，從填單頁(yè)跳轉(zhuǎn)到統(tǒng)一審批頁(yè)，統(tǒng)一審批頁(yè)初始化時(shí)沒有獲取到新審批，則會(huì)自動(dòng)執(zhí)行通知saas和頁(yè)面重定向。
要補(bǔ)充說(shuō)明一下的是，線上的審批站點(diǎn)和saas站點(diǎn)均是通過(guò)nginx做的3臺(tái)服務(wù)器的負(fù)載。
通過(guò)查看線上日志，審批系統(tǒng)正常，即只會(huì)在其中一臺(tái)服務(wù)器節(jié)點(diǎn)來(lái)請(qǐng)求saas接口進(jìn)行審批狀態(tài)的通知，并未發(fā)現(xiàn)異常日志。而saas呢，卻發(fā)現(xiàn)3臺(tái)服務(wù)器都記錄了同樣的日志。
為什么會(huì)出現(xiàn)這樣的情況呢？ 審批在通知saas時(shí)，nginx接收到請(qǐng)求后應(yīng)該分發(fā)給其中一個(gè)節(jié)點(diǎn)服務(wù)器來(lái)處理請(qǐng)求才對(duì)呀。
困惑
因?yàn)橹跋到y(tǒng)運(yùn)行都是正常的，并未出現(xiàn)這種短信重發(fā)的情況，所以我們暫先不懷疑代碼邏輯。
馬上想到，記得運(yùn)維說(shuō)過(guò)，如果一個(gè)服務(wù)器處理時(shí)間超長(zhǎng)，會(huì)自動(dòng)分發(fā)給另一個(gè)節(jié)點(diǎn)服務(wù)器。 歷史原因，獲取訂單詳情和觸發(fā)短信通知這兩段代碼執(zhí)行比較慢，那么，我在這兩段代碼外面加了個(gè)Stopwatch來(lái)診斷其執(zhí)行時(shí)長(zhǎng)。
publicvoidProcessRequest(HttpContext context)
{
Stopwatch sw=newStopwatch();
sw.Start();if(context.Request.Params.Count ==0)
{
context.Response.Write("{'returnCode':'2','returnMsg':'no parameters','notifiedSMSContent':'no parameters'}");return;
}stringparametersStr = context.Request.Params[0].AsToString();
SysLogToFile.WriteAuditMessage("dat修改訂單狀態(tài)傳入?yún)?shù)_"+parametersStr);//下面的是200行邏輯代碼，包括獲取訂單詳情和觸發(fā)短信通知...... ...... ...... ...... ...... ...... ...... ......
...... ...... ...... ...... ...... ...... ...... ......
...... ...... ...... ...... ...... ...... ...... ......
sw.Stop();
SysLogToFile.WriteAuditMessage("審批接口響應(yīng)時(shí)間"+ (sw.ElapsedMilliseconds /1000));stringreturncode, returnmsg;if(flag)
{ returncode="1"; returnmsg ="success"; }else{
returncode="2"; returnmsg ="fail";
}
context.Response.Write("{'returnCode':'"+ returncode +"','returnMsg':'"+ returnmsg +"','notifiedSMSContent':'"+ returnmsg +"'}");
}
發(fā)布后經(jīng)測(cè)試，發(fā)現(xiàn)3個(gè)節(jié)點(diǎn)的執(zhí)行時(shí)長(zhǎng)都長(zhǎng)達(dá)7~8秒。
那么，我們接下來(lái)就優(yōu)化程序吧，以期把duration降到最小。20分鐘后，我們把優(yōu)化的代碼再發(fā)布到服務(wù)器。發(fā)現(xiàn)處理時(shí)間已經(jīng)下降到了1~2秒。
然而，響應(yīng)時(shí)間已經(jīng)都優(yōu)化到2秒了，依然是3個(gè)服務(wù)器節(jié)點(diǎn)上都做了處理。這帶給我們的是一個(gè)更大的問(wèn)號(hào)。
轉(zhuǎn)機(jī)
為什么會(huì)有一個(gè)更大的問(wèn)號(hào)呢？ 因?yàn)槲覀兙€上的系統(tǒng)都是分布式部署的，一個(gè)流程邏輯會(huì)涉及到多個(gè)系統(tǒng)之間的交互訪問(wèn)。 每個(gè)系統(tǒng)都是通過(guò)nginx做的3個(gè)節(jié)點(diǎn)的負(fù)載，并沒有出現(xiàn)過(guò)這種一個(gè)請(qǐng)求被3個(gè)服務(wù)器節(jié)點(diǎn)同時(shí)響應(yīng)的情況。
在這種情況，我的一貫做法是釜底抽薪。當(dāng)然，這次我依然堅(jiān)持釜底抽薪。
Q：釜底抽薪是什么方式呢？
A：把接口里的代碼都注釋掉。響應(yīng)時(shí)間應(yīng)該接近于0毫秒，難道還會(huì)出現(xiàn)3個(gè)節(jié)點(diǎn)都響應(yīng)的情況？
于是，我們注釋掉所有邏輯代碼，只保留了最后的輸出（context.Response.Write）語(yǔ)句，發(fā)布到服務(wù)器。
由于我們每次的測(cè)試步驟是：登陸saas，選擇航班，然后訂票下單，再看日志，這一系列的操作很耗時(shí)間，同時(shí)給線上系統(tǒng)帶來(lái)了很多無(wú)效訂單（垃圾數(shù)據(jù)）。這次呢，我讓劉濤直接訪問(wèn)那個(gè)通知接口地址來(lái)測(cè)試性能。
轉(zhuǎn)機(jī)來(lái)了，在ie里直接訪問(wèn)那個(gè)接口時(shí)，頁(yè)面直接拋出了大黃頁(yè)，報(bào)“System.FormatException：輸入字符串的格式不正確”，是由主方法里最后的這條語(yǔ)句產(chǎn)生的：
context.Response.Write(string.Format("{'returnCode':'{0}','returnMsg':'{1}','notifiedSMSContent':'{2}'}", returncode, returnmsg, returnmsg));
即在string.Format方法里，你是不能亂用‘{’的~。
于是，修復(fù)后（改成字符串拼接了）再次上線。
再次訪問(wèn)那個(gè)接口，返回正常了。
這時(shí)，最大的驚喜是，只有一個(gè)服務(wù)器節(jié)點(diǎn)處理了請(qǐng)求，短信重發(fā)3次的問(wèn)題得到了根治。
這時(shí)，我才想起來(lái)，nginx在接收到請(qǐng)求后，會(huì)分發(fā)給多個(gè)服務(wù)器節(jié)點(diǎn)中的一個(gè)節(jié)點(diǎn)來(lái)處理請(qǐng)求，但是，當(dāng)出現(xiàn)錯(cuò)誤響應(yīng)時(shí)，nginx會(huì)自動(dòng)分開給另一個(gè)節(jié)點(diǎn)來(lái)處理，直到?jīng)]有節(jié)點(diǎn)可供分發(fā)，即直到所有可用節(jié)點(diǎn)都被分發(fā)為止。（當(dāng)然，這可能是我們運(yùn)維對(duì)nginx的配置策略）
后續(xù)
我們解決完這個(gè)問(wèn)題，已經(jīng)午夜23:40，如釋重負(fù)的打車回家了。
在回去的路上，我的腦子像過(guò)電影似的過(guò)了一遍我們這一晚的處理過(guò)程。
l? 復(fù)雜的問(wèn)題，在你用心解決時(shí)，往往產(chǎn)生自很簡(jiǎn)單的一行代碼。很戲劇性的是，這行代碼可能是你不經(jīng)意的疏忽寫錯(cuò)了，也可能是技能受限寫錯(cuò)的。如果，有做簡(jiǎn)單的測(cè)試，這樣的問(wèn)題完全是可以在開發(fā)時(shí)被發(fā)現(xiàn)的，而不至于花費(fèi)那么長(zhǎng)的時(shí)間來(lái)。
l? 另外，我又想到，審批系統(tǒng)調(diào)用接口時(shí)難道沒有判斷響應(yīng)結(jié)果就做下一步的重定向了？這個(gè)疑問(wèn)在第二天咨詢劉濤時(shí)得到了肯定。這樣的實(shí)現(xiàn)不夠嚴(yán)謹(jǐn)，于是，我讓他加上對(duì)結(jié)果的判斷。 如果事先有這個(gè)判斷，那么，這樣的問(wèn)題在審批請(qǐng)求時(shí)就會(huì)被發(fā)現(xiàn)的，何至于經(jīng)歷那么漫長(zhǎng)的排查過(guò)程呢。
