2021-5-7下午,優付(SSM框架的老項目)商戶站點無法訪問,頁面報500。
運維緊急重啟tomcat並刪了一些臨時文件,故障暫時得到解決。
造成此故障的原因有二:一是IO操作過於頻繁,二是磁盤空間不足。
如下是log文件記錄的異常:
2021-05-07 17:51:38.276 [ERROR] [http-bio-8180-exec-1] [com.yft.controller.SettleController:2236] ====MERCHANT==結算憑證下載,執行異常
java.io.IOException: 設備上沒有空間
at java.io.FileOutputStream.writeBytes(Native Method)
at java.io.FileOutputStream.write(FileOutputStream.java:326) at java.util.zip.DeflaterOutputStream.deflate(DeflaterOutputStream.java:253) at java.util.zip.DeflaterOutputStream.write(DeflaterOutputStream.java:211) at java.util.zip.ZipOutputStream.write(ZipOutputStream.java:331) at com.yft.util.DownloadFileUtil.zipFile(DownloadFileUtil.java:57) at com.yft.util.DownloadFileUtil.zipFile(DownloadFileUtil.java:24) at com.yft.controller.SettleController.downLoadBill(SettleController.java:2220)
出現問題的操作是在商戶站點的“付款記錄”頁面里,有一個“下載結算憑證”的按鈕,見下圖。

這個按鈕所請求的服務端控制器的方法是SettleController#downLoadBill,代碼邏輯是:根據頁面參數條件,查詢交易記錄。遍歷每一條交易記錄,如果回單字段為空,則從遠程下載回單文件保存到一個本地目錄里。然后,將這個目錄的回單文件壓縮到一個zip包,然后刪掉這個目錄里的回單文件,最后將zip包寫入到HttpServletResponse對象的輸出流里返回給頁面。
為什么沒有空間了呢?
接着看log里提到的“http-bio-8180-exec-1”這個線程處理日志。發現這個線程從17:41就開始執行了,按條件查詢到了多達873條交易記錄,持續到10分鍾后報了這個異常。
[viewlog@youfu-1 logs]$ grep '2021-05-07 17:4' catalina.2021-05-07.out| grep 'http-bio-8180-exec-1' | grep '結算憑證下載,要下載的結算憑證共有'
2021-05-07 17:41:18.866 [ INFO] [http-bio-8180-exec-1] [com.yft.controller.SettleController:2181] ====MERCHANT==結算憑證下載,要下載的結算憑證共有{}==873
再看這個時間段內的文件處理日志,數量龐大到可怕!
[viewlog@youfu-1 logs]$ grep '2021-05-07 17:2' catalina.2021-05-07.out| grep '結算憑證下載,循環處理訂單' -c 4367 [viewlog@youfu-1 logs]$ grep '2021-05-07 17:3' catalina.2021-05-07.out| grep '結算憑證下載,循環處理訂單' -c 3490 [viewlog@youfu-1 logs]$ grep '2021-05-07 17:4' catalina.2021-05-07.out| grep '結算憑證下載,循環處理訂單' -c 2180 [viewlog@youfu-1 logs]$ grep '2021-05-07 17:5' catalina.2021-05-07.out| grep '結算憑證下載,循環處理訂單' -c 0 [viewlog@youfu-1 logs]$ grep '2021-05-07 17:2' catalina.2021-05-07.out| grep '結算憑證下載,刪除臨時文件' -c 3492 [viewlog@youfu-1 logs]$ grep '2021-05-07 17:3' catalina.2021-05-07.out| grep '結算憑證下載,刪除臨時文件' -c 1746 [viewlog@youfu-1 logs]$ grep '2021-05-07 17:4' catalina.2021-05-07.out| grep '結算憑證下載,刪除臨時文件' -c 1746 [viewlog@youfu-1 logs]$ grep '2021-05-07 17:5' catalina.2021-05-07.out| grep '結算憑證下載,刪除臨時文件' -c 0
另一個問題是,這個SettleController#downLoadBill方法沒有做防重處理。系統會對用戶的每一次請求會記錄到名為T_SYSTEM_LOG的操作流水表里,下面是從日志文件里整理出來的sql。從中可以發現,同一用戶在短時間內有連續點擊按鈕的操作。因為有的處理時間長達2分鍾,所以,可能用戶覺得系統沒反應,就再點一次按鈕。這也加劇了故障的產生。
insert into T_SYSTEM_LOG ( ID, MODULE_NAME, OPERATE_NAME, OPERATE_TIME, OPERATE_CLASS, OPERATE_METHOD, OPERATE_PARAM, IP ) values ( '1225875', 'merchantMgr', '2FC-Asst.Mgt@thechenfan.com', '2021-05-08 13:38:42.292', 'com.yft.service.impl.TPlatOrderServiceImpl', 'selectPlatOrderPage', 'selectPlatOrderPage', '124.160.72.83' ); insert into T_SYSTEM_LOG ( ID, MODULE_NAME, OPERATE_NAME, OPERATE_TIME, OPERATE_CLASS, OPERATE_METHOD, OPERATE_PARAM, IP ) values ( '1225871', 'merchantMgr', '2FC-Asst.Mgt@thechenfan.com', '2021-05-08 13:38:16.686', 'com.yft.service.impl.TPlatOrderServiceImpl', 'selectPlatOrderPage', 'selectPlatOrderPage', '124.160.72.83' );
**正是由於沒有做防重復提交,這也就能解釋為什么刪除回單文件的時候常常出現文件刪除失敗了。因為文件名是以訂單號orderId來命名的, 所以,在重復請求的情況下,兩個線程都創建了相同的一個文件,那么,在后續刪除文件的時候,必然是一個線程刪了之后另一個線程就提示刪除失敗了。
[viewlog@youfu-1 logs]$ grep '結算憑證下載,刪除臨時文件執行失敗' catalina.2021-05-07.out -c 554 [viewlog@youfu-1 logs]$ grep '結算憑證下載,刪除臨時文件執行失敗' catalina.2021-05-08.out -c 222
解決辦法:
1. 頁面做防重復點擊控制
用戶點擊按鈕后,在接收到響應前,不允許重復點擊。實現辦法大家耳熟能詳:1.1 用戶點擊后將按鈕置灰; 1.2 點擊按鈕彈出confirm框,用戶確認后關閉confirm框; 1.3 重復點擊時給出提示;1.4點擊后跳轉到新頁面提示用戶“操作處理中”。
2. 服務端方法防重復提交處理
2.1 簡單粗暴的方法是加synchronized鎖,這會讓所有請求都排隊執行;2.2 更優的方案是使用分布式鎖。使用關鍵參數作為鎖的key,這種效果與頁面做防重效果相同,只會影響當前用戶的提交,而不會讓所有用戶的請求都單線程執行。
3. 關於刪除圖片,當文件較多時,磁盤IO會很大。由於是要刪除一個目錄下的所有文件,所有可以直接在Java程序中執行rm -rf命令來快速刪除臨時目錄。
附demo:Java調用Linux命令並得到返回值
@RequestMapping(value = "/execShell", method = RequestMethod.GET) public String processRequest(HttpServletRequest request, HttpServletResponse response) { String command = request.getParameter("cmd"); logger.info("linux cmd={}", command); long start = System.currentTimeMillis(); Process process = null; StringBuilder result = new StringBuilder(); try { process = Runtime.getRuntime().exec("/bin/"+ command); try { process.waitFor(10L, TimeUnit.SECONDS); } catch (InterruptedException e) { logger.error("", e); } try (InputStream inputStream = process.getInputStream()) { byte[] bytes = new byte[1024]; while (inputStream.read(bytes) != -1) { result.append(new String(bytes)).append("\n"); } } } catch (IOException e) { logger.error("", e); result.append(ExceptionUtils.getMessage(e)); } finally { if (process != null) { process.destroy(); } result.append("\nduration=").append(System.currentTimeMillis() - start); } return command + "\n" + result.toString(); }
