2015年1月11日 星期日

「鍾馗抓鬼系列」log4net 檔案清空之謎

        身為多年 log4net 忠實用戶,最近接獲客戶報案,說 Rolling File Appender 會在跨日一過午夜就將 log 檔案內容清除,只留下 0 byte 的空殼。對方採用我曾在 blog 推薦的多年調製而成的家傳祕方的組態設定log4net.config),竟然會遇到如此前所未聞的離奇事件!?

        上網 google 搜尋是否有他人遇到類似狀況,卻毫無線索。太陽底下無鮮事,全天下沒有別人遇到的事情,通常也不該發生在我周遭,畢竟我樂透從沒中過(不過我也都不買,這樣要中獎對老天爺來說應該是有難度),但是客戶現場截圖又不得不讓我閉嘴,不敢過度質疑:



        如上圖,這張圖片是在 12/23 日截取,可以看到 ALL-XXX.log 在當天早上(10:16:27AM)是有內容的(258KB),但是只要跨日之後,就會變成像 12/22 或是 12/21 那樣,內容清空只剩下 0 byte 的檔案

        客戶有一百多台機器執行相同的程式,幾乎每天都發生類似的現象,但這現象也不是非常穩定,可能連續四五天但卻有一天的 log 內容可以倖存,發生率大約 90%。

        我跟客戶領取他的程式經過數次測試模擬(透過更改作業系統時間模擬),皆無法重現這現象,我猜想或許跟環境因素有關,於是親自跑客戶的現場試圖親眼觀察該現象。然而沒想到的是,我們找了一台內部測試機器,經過調整作業系統時間的做法企圖捕捉這現象,竟然沒辦法重現!

        懷疑是環境問題的我,來到案發的犯罪現場竟然還是抓不到任何線索?不得已之下,總是得稍微懷疑一下客戶做了什麼手腳,無論是否有特殊執行的排程程式、或是閒置磁碟空間是否足夠、是否有詭異的防毒軟體作怪...,死馬當活馬醫,皆無所獲。

        唯一發現以前不知道的最新事實:就是客戶有開發一個監控所有業務程式運作的 Deamon,這個 Deamon 只要發現這些 24 小時運作的程式如果發生意外 crash 結束執行,會自動重新啟動死掉的業務程式,所以一旦我手動關閉掉此樁懸案的主角,每五分鐘,該 Deamon 會把它重新呼喚起來恢復執行。

        那是否因此有可能,該業務程式同時執行多個併行的實例,造成 log 檔案的寫入互相影響?不過當下我也無法立即透過這個解釋容量歸零的原因。

        而這懸案的程式主角,客戶也在其中加入自我檢查,只要發現已經有啟動的實例,便會自我了斷,不給他重複執行的機會。

        這個機制在我滑鼠點擊下反覆驗證,的確沒辦法保持兩個程序實例共同運作。

        經過幾次反覆測試,跟在我自己家裡實驗的結果完全相同,沒有任何檔案清空的狀況!這下子好了,我 IT 生涯經歷過幾次鍾馗抓鬼的聊齋軼事看來又要增添一樁。

        每次出現這種聊齋事件,退隱江湖的念頭就會在我腦袋盤旋,不過每每總是在我拿出金盆裝滿水之前,老天爺總會在我腦中給我一條靈光乍現生路,讓我這幾年下來還能繼續在這個領域騙吃騙喝撐了好幾年。

        「永遠都要對客戶提供的資訊質疑!」這些年來我跑各種支援任務,學到最血淋淋的經驗就是:儘信客戶,不如沒客戶屁啦)!

        客戶端的這支 Deamon 程式的存在,是兩邊環境最大的差異,就算客戶咬定該 Deamon 只有在監控的業務程式 process 消失才會重新啟動新的 process。但假設這支 Deamon 有 bug,會不斷重複啟動呢?如果客戶之所以感受不到這個 bug 的存在,是因為業務程式自我了斷的第二道防線的作用呢?

        終於,我根據這條線索重現了客戶所說的現象,請看影片演示:


        log4net 的 RollingFileAppender 跨日 rename 的機制其實會發生在兩個時機點
  1. 已經運用中的 log4net 再下次寫入 log 的時候,判斷出上次寫入和這次寫入的日期不同,會先進行 rename 再開新的檔案才寫入。
  2. log4net 剛接受組態的初始化,會先偵測既有的 log 檔案的最後修改日期是否相同,若不同會立刻進行 rename 再開新檔案。
        所幸之前因為追蹤別的問題,我手上有留下一份客戶該程式的原始碼 copy,打開發現:


        很遺憾的, log4net 查覺出跨日而決定進行 rename 的動作比"阻擋的檢查點"還要早就發生。實際驗證,XmlConfigurator.ConfigureAndWatch(new FileInfo("log4net.config")); 這行程式碼只要在跨日之後啟動立即就會進行 rename,如果將上述兩個區塊的順序對掉,先讓"阻擋的檢查點"發生,之後才初始化 log4net 的組態設定,這個問題就可以解決

        客戶接受上述建議修改,問題終結,Case closed!


沒有留言:

張貼留言