「鍾馗抓鬼系列」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 的機制其實會發生在兩個時機點：
- 已經運用中的 log4net 再下次寫入 log 的時候，判斷出上次寫入和這次寫入的日期不同，會先進行 rename 再開新的檔案才寫入。
- log4net 剛接受組態的初始化，會先偵測既有的 log 檔案的最後修改日期是否相同，若不同會立刻進行 rename 再開新檔案。
所幸之前因為追蹤別的問題，我手上有留下一份客戶該程式的原始碼 copy，打開發現：
很遺憾的, log4net 查覺出跨日而決定進行 rename 的動作比"阻擋的檢查點"還要早就發生。實際驗證，XmlConfigurator.ConfigureAndWatch(new FileInfo("log4net.config")); 這行程式碼只要在跨日之後啟動立即就會進行 rename，如果將上述兩個區塊的順序對掉，先讓"阻擋的檢查點"發生，之後才初始化 log4net 的組態設定，這個問題就可以解決。
客戶接受上述建議修改，問題終結，Case closed！
留言
張貼留言