記錄一次非常麻煩的除錯

可樂加品客發表於2023-05-05

此次記錄一次非常麻煩的除錯問題,不是純知識分享,只是記錄這次除錯過程引以為戒。

問題簡介

這個功能是公司2021年寫的老功能,一直都沒有更新過程式碼,這次在匯入一個1.03G的大檔案進行讀取的過程中出問題了。
簡單介紹一下這個功能:
公司使用的spring boot框架構建專案,該功能為專案內的一個介面呼叫功能。該功能首先,透過遠端介面下載檔案到區域網sftp伺服器上;下載完畢後將伺服器檔案下載到本機指定位置內;最後讀取檔案內容,識別其中的資料,將合法資料新增到資料庫中。
出現的問題:

  1. 匯出日誌時,try...catch欄位不產生任何報錯,但是實際上沒有任何動作。
  2. 記憶體溢位問題。
  3. json讀取異常。
  4. 待補充。

問題解決過程

1、try...catch...欄位不產生任何報錯的問題。

這個問題屬實是最大問題了,也是困擾很久的問題。
起因是這個功能沒有任何報錯,但是動作只進行到【下載檔案到sftp伺服器上】,之後的步驟就沒出現了。

  1. 首先注意到沒有任何報錯的過程,於是新增了Logger類,對各個步驟新增了logger以便檢視輸入。

    這個處理方式是:

    • 引入logger相關類,之後在操作類中建立Logger物件,格式如下:

      import org.slf4j.Logger;
      import org.slf4j.LoggerFactory;
      public class assetSyncForXN {
          private static final Logger logger = LoggerFactory.getLogger(assetSyncForXN.class);
      }
      
    • 在專案模組的application.yml配置中,配置logger的顯示許可權:

      logging:
        level:
          com.***.***: ERROR
      # 這裡注意一下:level代表等級,代表下面的包能夠展示日誌log最低的等級。
      # 下面的示例語句,左邊【com.***.***】代表包名,表示這個包下面的所有的包含類,都有這個的最低展示許可權。
      # 右邊【ERROR】表示【最低】展示許可權,從低到高依次為DEBUG<INFO<WARNING<ERROR<CRITICAL,而日誌中展示的log,只展示與該許可權相同或更高許可權的log
      # 打個比方:示例中這樣寫的許可權,我們在這個包下面打出來的日誌中就只能看見ERROR許可權的log和CRITICAL許可權的log。
      

      這樣我們就可以在每一句加入logger提示,這些提示語可以在日誌中顯示,就可以看到程式碼執行到哪一步停下了。

      順帶寫一下log在java中如何用:

      @Autowired
      private Environment env;
      private static RestTemplate restTemplate = AuthRestTemplate.restTemplate();
      
      //譬如我們寫一個連通方法,我們連通指定的url,獲取他的例項物件,取其中的聯通碼資料
      public void assetAllSync() {
          String url = env.getProperty("syncAssetXN.allUrl");
          //可以像String一樣拼接,這個就是打出一個普通的String
          logger.info("=========url:"+url);
          ResponseEntity<HashMap> result = restTemplate.getForEntity(url, HashMap.class);
          logger.info("=============================");
          //可以用花括號指代一個變數,變數放在後面用逗號隔開,裡面存放Object型別的內容
          logger.debug("result:{}",result);
          logger.info("================聯通碼:{}",result.getStatusCode());
      }
      
  2. 這樣我定位了問題的位置,但是卻不清楚問題的原因。我找了一下發現在try...catch..塊上面有問題,於是發現了catch{}部分裡面很匪夷所思的寫了一個這個catch:

    catch(Exception e){
        throw new BizIllegalArgumentException("讀取檔案============"+e.getMessage());
    }
    

    我這邊發現這個【BizIllegalArgumentException】類是公司內部寫的一個異常,而這個異常,一是不會在返回值內出現任何報錯,二是在日誌內沒有任何反饋資訊,這就是導致看不出來問題的原因,這個只有一個迅速結束程式的功能,所以我擴充了一下:

    catch(Exception e){
        logger.error("內部錯誤1:{}",e);
        throw new BizIllegalArgumentException("讀取檔案============"+e.getMessage());
    }
    

    這樣列印出來了錯誤,指向問題:

    下載至sftp伺服器完畢後,將sftp伺服器檔案下載到本機指定位置內這個過程中,原本傳遞來的【sftp地址】引數應該是一個資料夾而不是直接定位到檔案,結果發現傳遞過來的引數是一個檔案,應該是呼叫的介面修改過。(這個不是重點,不詳細說了)

    這導致下載時,其中有一個ChannelSftp.cd(directory)方法的引數是一個檔案,這自然會報錯,所以我修改了,程式也進行到了下一步。

    備註:

    這裡一定要注意一點,並不是說,這種自己編寫的異常一定打不出來日誌,而是因為部分框架構建的時候有問題(譬如我們公司的框架構建的時候就有問題。。。),以至於打不出log,正常情況還是可以的。不過為了以防萬一,大家還是用我上面說的那個方法打log比較好。

2、記憶體溢位問題。

這個不是最噁心的問題,但是確實是一個警示,告訴我們程式中不僅要注意時間複雜度,更要注意空間。

這個問題的報錯簡單粗暴:

image-20230427194646413

直接告訴你超記憶體了,這個解決也很簡單粗暴,在application.yml裡面新增一個配置

msdf:
  java:
    options: -Xmx8g
# -Xmx後面的8g就是指給該執行模組分配8g的記憶體

分配一下記憶體就可以了,預設的記憶體分配時很小的(俺不清楚這個預設是多少,有興趣可以查查),一般只要到達98%的記憶體分配時就會報這個問題。所以建議給application.yml新增該配置。

當然,我們關注的是原因,總不能遇到這種情況就無腦加記憶體。

先放上程式碼:(已知,saveDir是一個資料夾,裡面存放了一個1G的txt檔案)

File saveDir = new File(env.getProperty("syncAssetXN.savePath"));
if(!saveDir.exists()){//儲存檔案路徑是否存在,不存在重新建立
    saveDir.mkdirs();
}
SftpClientUtil.downloadByDirectory(callerSftpAddress,env.getProperty("syncAssetXN.savePath"),client);
logger.info("===================關閉連線===========");
client.disconnect();
logger.info("==============listFiles.length:{}",saveDir.listFiles().length);
if(saveDir.listFiles().length>0){// 獲取到資產資訊檔案
    logger.info("=============獲取到資產資訊檔案===============");
    for(File f: saveDir.listFiles()){
        String assetJson = "";
        try{
            logger.info("====1====:"+f.getName());
            InputStream is = new FileInputStream(f);
            logger.info("====2====");
            int iAvail = is.available();
            logger.info("======3======");
            byte[] bytes = new byte[iAvail];
            logger.info("======4======");
            is.read(bytes);
            logger.info("======5======");
            assetJson = '[' + new String(bytes) +']';
            logger.info("======close======");
            is.close();
        }catch(Exception e){
            logger.error("內部錯誤1:{}",e);
            throw new BizIllegalArgumentException("讀取檔案============"+e.getMessage());
            //                                    e.printStackTrace();

        }
        buildAssetList(assetJson);
        logger.info("close build!");
        f.delete();
    }

}else{
    logger.error("上傳檔案為空");
    throw new BizIllegalArgumentException("上傳檔案為空");
}

其實用一個很粗略的計算就能算出來了,變數無論如何都是存在記憶體中處理的,

首先:saveDir,1g

其次:for迴圈中有一個f的檔案,也是1g

在者:is這個流變數,放入的是f的流,1g

還有:為bytes分配了1g的大小空間

還包括對各種資料的處理什麼的,assetJson的大小也是1g,算來已經5g多了,更別說別的了,預設的資料量是怎麼都存不了的,就會報這個問題了。

遇到這種情況,

  • 首先是,最好多用更加區域性變數,少用更全域性的變數,用的變數的存活時間不能過長;
  • 其次變數一定要控制大小,譬如這個bytes的大小,顯然不用一下子分配1g,這個bytes也是要新增到assetJson變數裡面的,所以就是一個多餘的變數,可以做一個迴圈,將bytes大小每次少分配一點,也儘快清掉bytes,讓這個變數反覆新增到assetJson中。

3、json讀取異常。

講一下這個問題的發現歷史。

  1. 當上一個記憶體溢位問題解決後,之後就可以進行到【最後讀取檔案內容,識別其中的資料,將合法資料新增到資料庫中】這個過程了,但是在這時報了一個錯誤:

    image-20230428092042012

    複製出來,免得有想找的小夥伴找不著相關的問題解決辦法:

    com.alibaba.fastjson.JSONException: syntax error, expect [, actual {, pos 0, fieldName null
    

    這個問題解釋過來就是:json欄位在某個位置本來應該是’[‘,實際上是’{‘

    出現問題的java程式碼:

    JSONArray jsonArray = JSONArray.parseArray(assetJson);
    

    當呼叫這個程式碼時,parseArray會逐字解析變成jsonArray變數,當解析到本該是中括號符號時,出現的卻是花括號,這就出問題了。

    如果你的json欄位很短,我們可以開啟json欄位確認一下,但如果你的欄位很長,比如我這個1g(編輯器都沒辦法開啟這個檔案,開啟就會卡死),那怎麼確認?

    我們可以仔細思考一下json語句的格式,正常的json欄位需要讀取為一個一個一個物件的話,中間都是透過花括號和逗號分隔開的,而把各個【json物件】合在一起的方式,就是類似於【Map】一樣的中括號拉在一塊的。所以這個中括號,要不就是在一整個json語句的外部,把整體框住;要不就是在每個json物件內框住一個map。

    這個時候,要不就是推測,要不就是和提供資料方確認,這個欄位的問題是出現在哪,我這裡直接就是推測,大概就是整個json語句沒被中括號框住,事實確實是這樣,於是我把json語句的賦值上加了一箇中括號,這個問題就解決了。

  2. 解決該問題後,程式開始讀取每條資料,此時沒有任何問題,但是新增到資料庫的過程出問題了:

    image-20230428094507462

    圖片裡面寫的很雜,我發一下:

    invalid byte sequence for encoding "UTF8": 0x00  Call getNextException to see other errors in the batch.;
    

    解釋一下,大概就是說型別不合法,與sql編碼UTF8不一樣!這是批次插入時出現的資訊。

    於是想辦法看一下:linux伺服器系統的編碼和PGSQL的編碼一樣,都是UTF8。且sql複製到navicat上直接執行,完全沒有問題。

    苦思冥想許久,我發現為什麼複製過去了的數值,前面和後面不一樣捏,我們看一下區別:

    image-20230428094633406上面是資料庫的

    image-20230428094704886

    這個上面是報錯日誌裡面的

    NUL各位應該懂得都懂,就是UTF8無法解析的字元,大概要不是一些亂碼,要不就是一些特殊符號,這是妥妥的資料問題咯,那為什麼會出現複製過來就變成空格了的情況捏,我直接查了一下知乎,有位大佬講了一下原因。

    image-20230428095001361

    說這麼長就是說:複製的時候會根據編碼方式修改。那麼這個編碼方式透過我們複製貼上到sql的就是修改過的內容,但是透過程式直接傳遞是沒有進行任何修改的。而又因為我們看的報錯日誌是utf8格式,這說明,這個欄位部分數值是不能透過utf8解析的,問題就是出現在這裡了。

    這種錯誤如何解決就得看大家了,要不就是從根源上解決,直接找資料提供方的麻煩;要不就是自己在程式碼上面修改一下對這個欄位的資料,可以透過進行一次UTF8的轉換將資料的問題資訊消掉(我這邊就是這麼弄的);也可以直接判斷這種問題資訊就不要錄入了,當然,這個實現起來得看各位的需求。

    那麼給大家參考一下第二種我做的方式:

    byte[] bytes = data.getBytes("UTF-8");
    String softwareName = new String(bytes, "UTF-8");
    

    這樣就可以把原來的data轉化為utf-8格式的softwareName變數(轉兩次,保險)

4、備註

  1. 打log的時候,如果只是單步log,程式執行一次就不會再執行的,這種沒啥問題;但是遇到要遍歷大資料的時候裡面打log一定要謹慎,我這個txt檔案內有158w條資料,打log的時候給遍歷過程內新增了log,結果就是執行奇慢,在我現在寫這篇文章的時候還在跑,跑了8個小時了!
  2. json判斷的時候一定要仔細,譬如我上面說的那些問題,json稍微出現一點問題,這個資料就會影響全域性,批次新增這個資料的時候就報錯,導致後面的資料新增不了,程式就中斷了。所以當大家有這個需求的時候,對json的判斷要多上心,前面準備的越足,即使程式執行慢點,但是這比之後多次除錯好吧。

碎碎念(非正文)

當寫這篇文章的時候,本人還在測試這個功能的執行情況,執行正常確實已經到最後一步了,但是由於log和資料量的問題,以及測試伺服器太拉跨導致跑了很久很久還沒跑完,所以我還在等待ing。

這個程式碼是別人寫的,我不敢怎麼去修改太多邏輯,我只能在判斷上面下點功夫,所以我建議如果是改別人的老程式碼的這種任務就不要去接。

從開始說起吧

這個任務在開始的時候,需求方發了我資料,當然,資料我是打不開的,電腦帶不動;然後發了我報錯日誌,想想三百多M的日誌,打倒是打得開就是特別費勁,一點開,好嘛,從當日0點到當時的日誌全給我發過來了,更好笑的是,日誌裡面沒有任何相關內容就結束了,所以那個日誌我找了半小時沒有任何意義。

這個時候我想到打log,琢磨很久,寫了一部分log給現場的人員發了更新包。很神奇啊,有的log他就是不顯示,只有你把後面的一些問題解決了才會顯示(那不提示log我怎麼知道是哪裡的問題);有的log玄學,一會顯示一會不顯示;我最後好不容易定位try..catch裡面加了一些log才找著,真的是噁心。

而當我找到問題所在時,我發現需求和我現在發現的問題對不上。需求說的是:東西下載到本地了,但是資料庫沒資料。我這邊發現,根本沒有進行到下載到本地的操作就結束了。於是我遠端檢視現場,發現只是下載到sftp而已。我發現了這個問題就下班了。

下班回家,被組長罵了一頓,說我不管人家的需求,我說我管了,組長說你有什麼問題你就說,不能不管(反正就是不聽不聽)。第二天問了我加班的同事,告訴我那個人打小報告了,說我沒處理。唉,我真的沒話說。

後來嘛,讓需求問資料提供方,是不是資料給的有問題,不問,一直卡著,我只能在我這邊和現場處理這個,現場也不配合,一會不知道幹啥去了,我有次急了,發現遠端的時候桌面沒動靜;一會又電腦壞了不能弄。反正挺折磨的,來來回回因為現場和需求方耽擱了五天還沒處理完這個bug。

後面好不容易能下載到資料了,那邊又說,資料量對不上,就出現了我上面說的最後一個問題,也不知道後面還有沒有問題,我這一週都耗這了,我昨天半夜還在看資料有沒有跑完。

真的,如果有人看到這裡,而且有程式設計師工作的話,我的建議:

  1. 如果程式碼很久沒有變動,但是突然出了問題,大機率是資料提供方出現問題,及時丟鍋,找資料提供方確認資料格式,內容的變動是否有問題。
  2. 如果你的領導無緣無故罵你,一定是有人背後推動,請記住,要不有能耐找到幕後黑手,要不就直接回懟,你明明做了,無緣無故罵你,一概都是有毛病的人。
  3. 如果你的需求和現場不配合,群裡懟,找領導反應,事情鬧大,噁心他們,請記住,都是幹活的,都是平等的,沒必要好口氣,他們不配合就不要慣著。
  4. 如果你的需求是你以前就很煩的需求,請儘量不要接他的活。

最後我還是要吐槽,這個提需求的**,需求講不明白,自己也搞不懂需求本身,打小報告還,跟小學生似的,催又催的急,交接東西又不積極,真噁心到我了,急急急急急急。

相關文章