記一次JS執行順序引起的問題排查過程

前一段時間參與了公司火車票系統的開發工作，主要負責接口對接及頁面調整的工作。這半個月以來，雖然要投入到其它項目的開發，但偶爾也會被喊去解決一些火車票系統的Bug。今天同僚忽然喊我，說生産環境出了一個問題，使用者本來要預定8月31日的火車，但系統出票卻是8月30日的。

使用者在火車票系統的互動流程較為簡單，首先使用者選擇出發站、終點站以及乘車日期，點選查詢按鈕列出可預定車次資訊，每一行車次資訊後都有一個預定按鈕，友善使用者直接預定車次。使用者點選預定按鈕時，會向背景發起一個ajax請求，校驗車次餘票是否充足。如果餘票充足，就為使用者産生訂單。

針對使用者遇到的這個問題，結合系統流程以及背景日志，我發現，之是以會出8月30日的票，是因為一個名為queryKey的字段。這個字段每次查詢都會帶回到頁面，且隻會根據出發站、始發站和乘車日期的生成，是一個32位的加密字元串。使用者在查詢餘票時這個字段就已經與日期不符，即查詢餘票必要的兩個字段queryKey和trainDate不比對。生成queryKey是8月30日的，但是乘車日期卻是8月31日。後續訂單的生成也是如此，兩個字段都在我們的系統中用到，但是送出給供應商時，卻隻需要queryKey一個字段。這樣，傳遞的乘車日期字段就被忽略，進而為使用者出了8月30日的票。

在背景日志系統中，我看到使用者進行了兩次車票查詢，分别是8月30日與8月31日的，也就生成了兩個queryKey。而使用者點選預定按鈕傳遞的queryKey和乘車日期，是不比對的。

2016-08-29 15:15:04,843|default task-17|INFO|SearchTrainAction|查詢車次清單，出發車站＝臨汾,到達車站＝太原南,乘車時間＝2016-08-30
2016-08-29 15:15:04,844|default task-17|INFO|SupplierApiServiveImpl|queryTrainNumList, params : [ travelTime : 2016-08-30, fromStation : 臨汾, arriveStation : 太原南 ]
2016-08-29 15:15:04,846|default task-17|INFO|SupplierApiExecutorImpl|In queryLeftTicket, FromStation : 臨汾, ToStation : 太原南, <span style="color:#ff0000;"><strong>TravelDate : 2016-08-30</strong></span>
2016-08-29 15:15:04,846|default task-17|INFO|SupplierApiExecutorImpl|Request ESB Interface, ServerCode : TrainSS, Operation : trainSearchtrain, urlQueryStr : channel=A82B52447443217B&fromstation=臨汾&tostation=太原南&traindate=20160830&sign=ADE7A0857C60A16681A44947801512AE
2016-08-29 15:15:04,847|default task-17|INFO|HttpClientBase|sendGetRequest:request:url : http://api.host.com/esb/train/trainSearchtrain?channel=A82B52447443217B&fromstation=臨汾&tostation=太原南&traindate=20160830&sign=ADE7A0857C60A16681A44947801512AEdata : nulldataEnc : UTF-8connectTimeOut : 50000soTimeOut : 50000
2016-08-29 15:15:05,363|default task-17|INFO|HttpClientBase|sendGetRequest:調用服務http://api.host.com/esb/train/trainSearchtrain?channel=A82B52447443217B&fromstation=臨汾&tostation=太原南&traindate=20160830&sign=ADE7A0857C60A16681A44947801512AE耗時統計資訊：0
2016-08-29 15:15:05,366|default task-17|INFO|HttpClientBase|sendGetRequest:response:<strong><span style="color:#ff0000;">{"queryKey":"4f9b82b9ddb6309649cabbc270c538e1"}</span></strong>
2016-08-29 15:15:05,371|default task-17|INFO|SupplierApiExecutorImpl|ESB Interface Return Data : {"queryKey":"4f9b82b9ddb6309649cabbc270c538e1"}
2016-08-29 15:15:05,385|default task-17|INFO|SupplierApiServiveImpl|queryTrainNumList, search success. data size : 31

2016-08-29 15:15:31,988|default task-38|INFO|SupplierApiExecutorImpl|checkTicketNum 餘票數量查詢，請求參數 : {"trainNo":"D2506",<strong><span style="color:#ff0000;">"queryKey":"4f9b82b9ddb6309649cabbc270c538e1"</span></strong>,"fromStation":"臨汾","seatClass":"secondseat","toStation":"太原南",<strong><span style="color:#ff0000;">"trainDate":"2016-08-31"</span></strong>}
2016-08-29 15:15:31,989|default task-38|INFO|HttpClientBase|sendGetRequest:request:url : http://api.host.com/esb/train/trainSearchTrainTicketQuantity?channel=A82B52447443217B&fromstation=臨汾&querykey=4f9b82b9ddb6309649cabbc270c538e1&seatclass=secondseat&tostation=太原南&traindate=20160831&trainno=D2506&sign=5F667FCCA62C1EC73F86DB547E22C0C9data : nulldataEnc : UTF-8connectTimeOut : 50000soTimeOut : 50000
2016-08-29 15:15:32,073|default task-38|INFO|HttpClientBase|sendGetRequest:調用服務http://api.host.com/esb/train/trainSearchTrainTicketQuantity?channel=A82B52447443217B&fromstation=臨汾&querykey=4f9b82b9ddb6309649cabbc270c538e1&seatclass=secondseat&tostation=太原南&traindate=20160831&trainno=D2506&sign=5F667FCCA62C1EC73F86DB547E22C0C9耗時統計資訊：0
2016-08-29 15:15:32,074|default task-38|INFO|HttpClientBase|sendGetRequest:response:166
2016-08-29 15:15:32,074|default task-38|INFO|SupplierApiExecutorImpl|checkTicketNum 餘票數量查詢供應商傳回結果：166



2016-08-29 15:15:05,070|default task-2|INFO|SearchTrainAction|查詢車次清單，出發車站＝臨汾,到達車站＝太原南,乘車時間＝2016-08-31
2016-08-29 15:15:05,071|default task-2|INFO|SupplierApiServiveImpl|queryTrainNumList, params : [ travelTime : 2016-08-31, fromStation : 臨汾, arriveStation : 太原南 ]
2016-08-29 15:15:05,073|default task-2|INFO|SupplierApiExecutorImpl|In queryLeftTicket, FromStation : 臨汾, ToStation : 太原南, <strong><span style="color:#ff0000;">TravelDate : 2016-08-31</span></strong>
2016-08-29 15:15:05,074|default task-2|INFO|SupplierApiExecutorImpl|Request ESB Interface, ServerCode : TrainSS, Operation : trainSearchtrain, urlQueryStr : channel=A82B52447443217B&fromstation=臨汾&tostation=太原南&traindate=20160831&sign=E3718E128AB5A2037DD2CC7331154379
2016-08-29 15:15:05,074|default task-2|INFO|HttpClientBase|sendGetRequest:request:url : http://api.host.com/esb/train/trainSearchtrain?channel=A82B52447443217B&fromstation=臨汾&tostation=太原南&traindate=20160831&sign=E3718E128AB5A2037DD2CC7331154379data : nulldataEnc : UTF-8connectTimeOut : 50000soTimeOut : 50000
2016-08-29 15:15:05,219|default task-2|INFO|HttpClientBase|sendGetRequest:調用服務http://api.host.com/esb/train/trainSearchtrain?channel=A82B52447443217B&fromstation=臨汾&tostation=太原南&traindate=20160831&sign=E3718E128AB5A2037DD2CC7331154379耗時統計資訊：0
2016-08-29 15:15:05,221|default task-2|INFO|HttpClientBase|sendGetRequest:response:<strong><span style="color:#ff0000;">{"queryKey":"bd9469f27c5a536a672c45d3135d7282"}</span></strong>
2016-08-29 15:15:05,227|default task-2|INFO|SupplierApiExecutorImpl|ESB Interface Return Data : {"queryKey":"bd9469f27c5a536a672c45d3135d7282"}
2016-08-29 15:15:05,240|default task-2|INFO|SupplierApiServiveImpl|queryTrainNumList, search success. data size : 31

2016-08-29 15:14:54,646|default task-64|INFO|SupplierApiExecutorImpl|checkTicketNum 餘票數量查詢，請求參數 : {"trainNo":"D2506",<strong><span style="color:#ff0000;">"queryKey":"bd9469f27c5a536a672c45d3135d7282"</span></strong>,"fromStation":"臨汾","seatClass":"secondseat","toStation":"太原南",<span style="color:#ff0000;"><strong>"trainDate":"2016-08-31"</strong></span>}
2016-08-29 15:14:54,648|default task-64|INFO|HttpClientBase|sendGetRequest:request:url : http://api.host.com/esb/train/trainSearchTrainTicketQuantity?channel=A82B52447443217B&fromstation=臨汾&querykey=bd9469f27c5a536a672c45d3135d7282&seatclass=secondseat&tostation=太原南&traindate=20160831&trainno=D2506&sign=1121D99DDA3F835DC70E911531FA98A5data : nulldataEnc : UTF-8connectTimeOut : 50000soTimeOut : 50000
2016-08-29 15:14:54,755|default task-64|INFO|HttpClientBase|sendGetRequest:調用服務http://api.host.com/esb/train/trainSearchTrainTicketQuantity?channel=A82B52447443217B&fromstation=臨汾&querykey=bd9469f27c5a536a672c45d3135d7282&seatclass=secondseat&tostation=太原南&traindate=20160831&trainno=D2506&sign=1121D99DDA3F835DC70E911531FA98A5耗時統計資訊：0
2016-08-29 15:14:54,756|default task-64|INFO|HttpClientBase|sendGetRequest:response:166
2016-08-29 15:14:54,757|default task-64|INFO|SupplierApiExecutorImpl|checkTicketNum 餘票數量查詢供應商傳回結果：166
           

上面的日志是我整理後的結果，原始日志因為線程問題，各部分列印是有交替的，根據列印時間可以看出，task-2和task-17就是交替執行的。

可以看出，task-17中的queryKey和乘車日期表示為8月30日，task-2中的queryKey和乘車日期表示為8月31日。但是在第一次點選預定按鈕時發起的task-38中，queryKey是task-17的queryKey，日期卻是8月31日。由于供應商出票是根據queryKey來的，就造成了表面上請求8月31日車票，實際上出8月30日的車票。

根據日志來看，task-2和task-17交替執行，我的第一個念頭就是是不是多線程引起資料同步問題。但經過排查，queryKey也好，乘車日期也好，都是通過傳值傳遞的，沒有資料共享。

整理一下思路，首先queryKey和trainDate(乘車日期)都是通過請求傳遞的，那麼到底是哪個環節出現了資料傳遞錯誤的結果呢？從日志裡可以看出，頁面查詢傳回的資料是沒有問題的，而到了點選預定按鈕時，資料就出現了錯誤，在這兩步之間并沒有其他能事件發生。我覺得問題就出在頁面查詢資料産生以後，預定按鈕餘票校驗請求發起之前。

翻看預定按鈕點選事件處理的JS代碼，能看出queryKey和trainDate都是直接從頁面上擷取的。檢查代碼也能看出來，邏輯上并沒有什麼問題，經測試兩個字段也都可以正确擷取到。

此時我注意到，使用者在查詢車次的時候，兩點查詢間隔非常之短，分别是2016-08-29 15:15:04,843和2016-08-29 15:15:05,070，不到0.2s的間隔，說明使用者是連續點選了日期翻頁。聯系到頁面使用ajax加載車次清單，經過與同僚讨論，我們終于找出了對使用者出現這種情況的最好解釋。

首先使用者極短時間内發起兩次不同日期的車次查詢請求，每次查詢，頁面都同步修改日期控件的日期。第一次查詢8月30日車次，第二次查詢8月31日車次。經過兩次查詢，日期控件顯示為8月31日。請求發送到背景後，背景另個請求分别在兩個線程中處理，當然，線程是由服務容器管理。恰好兩次請求中，第二次請求的8月31日車次資訊先被傳回，并在頁面渲染。繼而第一次請求的8月30日車次資訊緊接着也被傳回，并渲染頁面。兩次請求完畢後，較遲傳回的第一次查詢的8月30日車次資訊就在頁面上展示了，而8月31日車次資訊被覆寫。這一過程極快，使用者肉眼無法感覺。

由于日期控件在點選切換日期後就向伺服器端發起了請求，此後過程與日期控件無關，是以日期控件仍然是最後一次翻頁到的8月31日。當使用者點選車次清單中的預定按鈕時，從車次資訊中拿到的queryKey就是8月30日的queryKey，而從日期控件中擷取到的日期卻是8月31日。是以，使用者最終得到的出票結果為8月30日乘車的車票。

這個問題的根本原因在于，沒有正确的去擷取使用者查詢的乘車日期，頁面JS使用不當，想當然的認為作為查詢條件的日期就是與查詢結果是一緻的。其實可以作一個類比，我在之前的團隊中，發現項目中很多查詢功能——即上面是查詢條件輸入框，下面是查詢結果表格——都存在類似的問題。比如說，使用者輸入一個條件A，點選查詢按鈕，得到結果A1,；然後修改條件為B，但是并不點選查詢按鈕，則下面的表格顯示的仍是A1的結果。此時點選翻頁或是導出資料，代碼中竟然重新從輸入框中擷取條件并組裝URL發起請求！這種處理的結果就是，使用者在頁面上看到的是A1的結果，但是導出的資料卻是B1。我認為這是及不合理的！

作為解決方案，我建議同僚将查詢條件的乘車日期，與查詢結果綁定在一起，并且在查詢結果渲染完成後，重新檢查日期控件與查詢條件是否一緻，如不一緻，則需要給日期控件重新指派。當然，更為嚴謹一點，當使用者點選了一次日期控件發起請求後，請求結果處理完成之前，應禁止使用者再次點選日期控件發起請求。但這樣的話使用者體驗可能會比較差，沒有采用。

在定位這個問題時，我能感受到同僚的想法是伺服器端出現了問題，第一個念頭是想檢查背景代碼。但是，我覺得排查程式Bug時，應該先觀察問題表象，判斷問題可能出現的節點，并在節點附近定位問題。結合日志以及代碼邏輯，不放過任何一個細節，問題才能得到解決。另外一點，JS代碼執行過程比較不易控制，編寫JS代碼時，應盡量考慮到資料的嚴謹性。