JOHOYA: 2007

0. 前言

因為之前的專案有了 Web Service 的撰寫經驗之後，深深覺得中間層的東西非得要一個好的 log tools 才方便日後上線後的除錯，由於之前聽同事推薦過 log4net 這個東西，想說就拿來試用在新的專案上
以我個人的喜好來說，覺得用這種 3rd party 的東西總覺得一定要找到目前大家公認說好的我才會想要去用他，所以第一步就是上網找了找關於 log4net 的評論，好死不死的看到 MS 的 Application Blocks 裡面有個 "Logging and Instrumentation Application Block" :

Logging and Instrumentation Application Block

當時就很直覺的想說應該來用這套大概會比較對，用 MS 的東西總不怕將來新版本的 .Net framework 出來之後馬上面臨不相容的問題吧？！不過一想到了之前看過 MS UIP block 的經驗之後，理性告訴我不應該對 MS 的 Application Blocks 寄予可以得到足夠支援資訊的期望，所以就找到了下面這篇比較:

Microsoft Enterprise Library Logging Block compared to Log4net

其中有一點是 MS 的缺點：要改變 trace level 時因為要動到 web.config，所以會重新啟動 Web application ，而 log4net 可以不用，這一點讓我對 log4net 加了不少分數，加上要使用 M$ 的東西似乎要用到另一個 Application Block: Configuration Block，想一想要看懂兩個 Block 可能要花掉的時間之後，就覺得算了，目標就鎖定 log4net 好了，另外有個優點是 log4net 支援 "階層式" 的 log 紀錄，當時看到這點時不是很懂，下面用到時我才知道這有什麼好處

log4net 官方文件

說實在的，log4net 的文件實在寫得也不太親民，講解不清楚之外，範例也很少，幸好它實際上是不難的東西，自己試用了一下之後也就可以進入狀況了，以下寫個簡易的入門文件，詳細的設定就可以參照上面那個網址

1. 安裝

在 log4net 網站上抓到 log4net 之後解開，裡面已經有 compile 好的 .Net 1.1 版 log4net.dll (目前也有.Net 2.0版的)，直接在 VS 方案總管中的參考資料夾中加入即可，如果是團隊開發時，也可以像我們一樣考慮把這類共用的 dll 檔案丟到某個特定的網路磁碟機上供大家 share，那樣子就不用每個人都要安裝，當團隊大不好溝通時這是個不錯的方法

2. 使用前的設定

log4net 使用時需要參考一個設定檔(雖然可以不參考設定檔，但是這樣子的話 log 是寫到 console 去，那對我的們 web application 是沒意義的)，那個設定檔可以放在 web.config (或 app.config) 中，也可以放在另外一個獨立檔案，我建議是放在另外一個獨立檔案中，因為放在 web.config 裡面的話，每次要改變 log 的 trace level 時，會 "順便" 讓網站重新啟動，那就失去了 log4net 最重要的優點了 (註: 此設定檔中不可含有任何中文字在內, 否則執行上會有問題)

我是把檔案放在我的 BonusAPI Web service 的根目錄下面，叫做 BonusAPI.log4net，內容如下：

<log4net>

<appender name="RollingFile" type="log4net.Appender.RollingFileAppender">
<file value="BonusAPI.log" />
<appendToFile value="true" />
<maximumFileSize value="100KB" />
<maxSizeRollBackups value="2" />

<layout type="log4net.Layout.PatternLayout">
<conversionPattern value="%date{dd MMM yyyy HH:mm:ss,fff} [%5level] %thread %logger - %message%newline" />
</layout>
</appender>


<root>
<level value="DEBUG" />
<appender-ref ref="RollingFile" />
</root>
</log4net>

其中第一個段落 appender 部分用來定義 log 可以寫到哪裡去，我目前採用的是 RollingFile ，表示是寫到檔案去，但超過 100kb 時會自動換檔名 (和 IIS log 一樣)，appender 除了檔案之外還可以有許多選擇，可以寫到資料庫 (SQL Server, Oracle...)，可以寫到特定 E-Mail 去，寫到 Windows EventLog，寫到 ASP.Net Trace log (所以不需要 Trace.warn 了，透過 Windows 的 Net send 送出，寫到 Telnet, UDP 去 (這樣子好像可以在自己的電腦上弄個小程式專門收這些 log ，判斷到有嚴重意外時就跳出一個 "Your system got fatal exception!!!"，蠻酷的)

第二個段落中有個 level value 就是指 trace level ，我先設定為 DEBUG ，這表示所有優先權大於 DEBUG 的訊息都會被 log 下來，以下是 log4net 的 trace level 種類
越下面的優先權越高：

ALL
DEBUG
INFO
WARN
ERROR
FATAL
OFF

下面一行是說我要採用 RollingFile 這個 appender 作為 log 的輸入地，由於這裡可以放一個以上的 appender ，那表示我可以同時寫 log 又同時把 log 寄到某個 e-mail 去，或是當哪天系統發生嚴重問題時，我可以再把 log 寫到資料庫中，而且進行這些改變時完全不需要重新啟動你的 web application

3. 基本入門

以下以一個我的 Web service method 為例來說明，我的程式如下，紅字的部分是和 log4net 有關或比較重要的部分

public class BonusAPI : System.Web.Services.WebService
{
// 宣告要使用 log4net 元件
private static readonly ILog log =
LogManager.GetLogger(typeof(BonusAPI));

public BonusAPI()
{
// 設定檔的位置，利用 ConfigureAndWatch 這個 method 表示會自動偵測該檔案是否有變動
log4net.Config.XmlConfigurator.ConfigureAndWatch(new System.IO.FileInfo(AppDomain.CurrentDomain.BaseDirectory.ToString() + "BonusAPI.log4net"));
}

public int BeginTransaction(out string TranID, string TerminalID, string TerminalPassword)
{
........
........
OracleCommand cmd;
TranID = null;

// 使用 log.Info 丟 log
log.Info("BeginTransaction() called");

// 使用 log.Debug 丟這種無關緊要的 log ，以後 debug 時
// 拿來看執行到哪裡出錯時很方便
log.Debug("Before calling AuthChk in BeginTransaction()");
if(AuthChk(HttpContext.Current.Request.UserHostAddress, TerminalID, TerminalPassword) != 0)
return(1);
log.Debug("After calling AuthChk in BeginTransaction()");
conn = new OracleConnection(ConfigurationSettings.AppSettings["connStr"]);
log.Debug("Before opening DB connetion");
conn.Open();
log.Debug("DB open successfully");
.......
try
{
.......
log.Debug("Before execute command 1");
cmd.ExecuteOracleNonQuery(out rowid);
log.Debug("Before execute command 2");
cmd.ExecuteOracleNonQuery(out rowid);
.......
return(0);
.......
}
catch(Exception e)
{
// 真正發生嚴重意外時用 log.Fatal 寫 log
log.Fatal("寫入資料庫失敗", e);
return(999);
}
finally
{
log.Debug("Ready to closing DB ");
conn.Close();
}
}
}

依上面這個範例來看，由於我在設定檔中設定的 trace level 是 DEBUG ，所以 DEBUG 以上的 log 都會記錄到，在測試環境時很方便，寫出來的 log 會是這樣子：

18 Aug 2005 16:37:56,826 DEBUG 1732 BonusAPI.BonusAPI - Ready to closing DB
18 Aug 2005 16:39:03,762 [ INFO] 2936 BonusAPI.BonusAPI - BeginTransaction() called
18 Aug 2005 16:39:03,762 [DEBUG] 2936 BonusAPI.BonusAPI - Before calling AuthChk in BeginTransaction()
18 Aug 2005 16:39:03,762 [DEBUG] 2936 BonusAPI.BonusAPI - After calling AuthChk in BeginTransaction()
18 Aug 2005 16:39:03,762 [DEBUG] 2936 BonusAPI.BonusAPI - Before opening DB connetion
18 Aug 2005 16:39:03,762 [DEBUG] 2936 BonusAPI.BonusAPI - DB open successfully
18 Aug 2005 16:39:03,762 [DEBUG] 2936 BonusAPI.BonusAPI - Before execute command 1
18 Aug 2005 16:39:03,762 [DEBUG] 2936 BonusAPI.BonusAPI - Before execute command 2
18 Aug 2005 16:39:03,778 [DEBUG] 2936 BonusAPI.BonusAPI - Ready to closing DB

上線之後如果我為了提升執行效能所以把 trace level 開成 INFO ，表示上線的程式只有 INFO 以上的 log 會被記錄下來，所以 log 會只有這樣子：

18 Aug 2005 16:39:03,762 [ INFO] 2936 BonusAPI.BonusAPI - BeginTransaction() called

簡單很多，省掉了不少系統資源，不巧的是系統在上線後發生了狀況， log 看起來像是這樣子：

18 Aug 2005 16:39:03,762 [ INFO] 2936 BonusAPI.BonusAPI - BeginTransaction() called
18 Aug 2005 16:39:03,778 [FATAL] 2936 BonusAPI.BonusAPI - 寫入資料庫失敗
System.Data.OracleClient.OracleException: ORA-00903: invalid table name
at System.Data.OracleClient.OracleConnection.CheckError(OciErrorHandle errorHandle, Int32 rc)
at System.Data.OracleClient.OracleCommand.Execute(OciHandle statementHandle, CommandBehavior behavior, Boolean isReader, Boolean needRowid, OciHandle& rowidDescriptor, ArrayList& refCursorParameterOrdinals)
at System.Data.OracleClient.OracleCommand.Execute(OciHandle statementHandle, CommandBehavior behavior, Boolean needRowid, OciHandle& rowidDescriptor)
at System.Data.OracleClient.OracleCommand.ExecuteNonQueryInternal(Boolean needRowid, OciHandle& rowidDescriptor)

看了看程式這裡執行了兩個 SQL Command ，但不太確定是那個 SQL 出的問題，所以我們就可以暫時的把線上系統的 trace level 開成 INFO ，雖然會稍微犧牲一點效能，但因為不用重新啟動系統，所以不引響線上的使用者，接著出現的 log 是這樣子：

18 Aug 2005 16:37:56,826 DEBUG 1732 BonusAPI.BonusAPI - Ready to closing DB
18 Aug 2005 16:39:03,762 [ INFO] 2936 BonusAPI.BonusAPI - BeginTransaction() called
18 Aug 2005 16:39:03,762 [DEBUG] 2936 BonusAPI.BonusAPI - Before calling AuthChk in BeginTransaction()
18 Aug 2005 16:39:03,762 [DEBUG] 2936 BonusAPI.BonusAPI - After calling AuthChk in BeginTransaction()
18 Aug 2005 16:39:03,762 [DEBUG] 2936 BonusAPI.BonusAPI - Before opening DB connetion
18 Aug 2005 16:39:03,762 [DEBUG] 2936 BonusAPI.BonusAPI - DB open successfully
18 Aug 2005 16:39:03,762 [DEBUG] 2936 BonusAPI.BonusAPI - Before execute command 1
18 Aug 2005 16:39:03,778 [FATAL] 2936 BonusAPI.BonusAPI - 寫入資料庫失敗
System.Data.OracleClient.OracleException: ORA-00903: invalid table name
at System.Data.OracleClient.OracleConnection.CheckError(OciErrorHandle errorHandle, Int32 rc)
at System.Data.OracleClient.OracleCommand.Execute(OciHandle statementHandle, CommandBehavior behavior, Boolean isReader, Boolean needRowid, OciHandle& rowidDescriptor, ArrayList& refCursorParameterOrdinals)
at System.Data.OracleClient.OracleCommand.Execute(OciHandle statementHandle, CommandBehavior behavior, Boolean needRowid, OciHandle& rowidDescriptor)
at System.Data.OracleClient.OracleCommand.ExecuteNonQueryInternal(Boolean needRowid, OciHandle& rowidDescriptor)

結果我們可以發現 log 中沒有執行到 Before execute command 2 這個地方，這時候我們知道問題所在，就可以趕快先把線上系統的 trace level 弄回 INFO 模式，完全不影響系統運作

4. 階層式？

之前聽同事有提過 log4net 有所謂的 Hierarchy 設定，那表示我們要使用 log 的時候要先想好 log 的 hierarchy ？想到這裡我本來也是一頭霧水，因為總覺得寫 log 就寫 log 嘛，還一定要為這些亂七八糟的 log 規劃個 hierarchy 才來寫 log ，log 的階層還有一些繼承的關係$#!?，感覺上多了一堵牆在那裡，不太容易親近
不過看了文件之後，才發現我們一般的使用上其實可以根本不用去管 log hierarchy 的規劃，也不用去管那些繼承不繼承的關係，反正在使用時就是在每個 class 的第一行用上這個 method：

private static readonly ILog log = LogManager.GetLogger(typeof([你這個class的名稱]));

對啦，那個階層就按照我們原本程式的 class 就對了，文件上也提到大多數人也是這樣子來使用，那樣子 log 看起來也會很直覺，一看就會知道是那個程式模組出了問題，不會說是你程式的 class 階層規劃是個樣子，log 又是另外一個樣子，最後很難對得上延伸我上面的例子來接著舉例，由於我的 Web service 呼叫了取得設定檔的這個 method ，所以我的 Web service 就是所有的 log 的 root 層，也就是最高層

log4net.Config.XmlConfigurator.ConfigureAndWatch(new System.IO.FileInfo(AppDomain.CurrentDomain.BaseDirectory.ToString() + "BonusAPI.log4net"));

一旦我的 Web Service 要加入另一個公用函式庫(假設我們團隊有個工具函式庫叫做 CommonLib) 的功能時，只要 CommonLib 有使用 log4net 的話，那 CommonLib 所寫的 log 就會跟著 root 層的設定跑，也就是寫到我 Web service 所定義的 log 檔案去，當然當這個 CommonLib 用在別一個系統時，就會跟著別的系統的 root 層設定寫到該寫的地方去，方便的很
那定義階層的用意在哪呢？我目前的心得是，有了這個階層之後，就可以利用 config file 做一些事情，例如在 CommonLib 中，net.commonlib.webutil 這個 namespace 以下都是我負責的程式碼，所以日後上線後我可以在 config file 中設定，只把所有 net.commonlib.webutil 所產生的 error log 寄往我的 E-Mail appender 設定去，這對於系統上線後的維護分工來說會有很大的幫助

5. 中間層的應用

其實最需要用到 log4net 這種東西的地方應該是系統中間層部分的程式碼了，就舉 CommonLib 來看好了，因為 CommonLib可能被拿去用在某個後台系統中，也可能拿去用在某個前台系統，還可能用在 Batch 程式裡，更可能被放在 Web Service 下使用，套在不同的應用環境下可能就會有不同的 log 記錄需求，例如套用在 Web 應用程式時，我們可能會要把 log 是會記到 ASP.Net 的 trace.axd 頁面中，套用在 Batch 程式和 Web Service 下時我們希望 log 會記錄到文字檔甚至是 Windows 事件中等等...
由於中間層程式碼的特性是它不會被單獨使用，一定是跟著應用的環境走，例如跟著前台走或跟著 Web Service 走，所以在使用 log4net 時也就不應該自行去參考 log4net 的設定檔，所以不應該在中間層程式碼中使用到下列的函示 (或同功能函示)

log4net.Config.XmlConfigurator.ConfigureAndWatch(...);

所以中間層要加入 log4net 機制的典型範例應該看起來如下：

using System;
...
using log4net; // 引用 log4net library 當然是必須的嘍
// using log4net.Config; 因為不需要參考 config 檔案，所以不用引用這個
namespace net.commonlib.webutil {
///
/// webutil 的摘要描述。
///
public class webutil {
// 加上這行
private static readonly ILog log = LogManager.GetLogger(typeof(webutil));

public webutil()
{
log.Info("進入 webutil();"); // 使用範例, 個人建議再進入/離開函示前都 log info
.....
log.Info("離開 webutil();"); // 使用範例, 個人建議再進入/離開函示前都 log info
}
.....

也許有人開始擔心了，中間層開始改成這個樣子之後，但是我的前台、我的後台並沒有加上 log4net 的機制，會造成執行時期或編譯時期的錯誤嗎？
答案是不會的，例如前台程式中若沒有呼叫 log4net.Config.XmlConfigurator.ConfigureAndWatch(...); 時，表示 log4net 的 log root 並沒有建立，所以中間層在 GetLogger(...); 時便找不到 log root 來繼承，所以 log 也就自動停止作用，也不會有錯誤訊息，唯一要住的只有在編譯時要記得把 log4net.dll 放在參考資料夾中，部署到線上環境時也要記得丟上去，那就沒有問題了

6. 各種 log level 的使用建議

log4net 的 log level 除了 ALL 和 OFF 之外，算起來有 5 種 level 可以讓程式設計師使用，以專案管理的角度來看，自然希望每個 level 的使用時機會有一定的指導原則，以免到時候需要藉由 log 來檢視問題了，會有不知道該「開」到哪一層的困擾，或是既使把設定「開」到的 ERROR 層級了，log 跑出來還是一大堆和「錯誤」無關的資訊，既浪費系統效能又影響問題處理時間，所以以下先就個人看法為每個可用的 level 定義其使用時機，提供給各位參考：

DEBUG 建議使用在各種阿哩不答的情況下，例如 log 一下變數 i 的值現在是什麼，現在程式跑到某個地方了等等...
INFO 建議使用在各種重要的進入點之前或之後，例如函示進入前，離開前，資料庫開啟前，開啟後，下 SQL 前，SQL 後等等...
WARN 建議使用在 catch 到錯誤狀況的程式碼內，或那種是問題但不希望因此被打擾到的問題時用這個(例如程式跑到缺貨處理那一段，但缺貨這件事商管人員本來就會透過 E-Mail 或 Daily review 知道啊，關我程式設計師什麼事，就用 WARN 吧)
最後，有遇到 try ... catch 的時候都至少用這個 level 吧，畢竟那可能是個你之前沒想過會遇到的狀況
ERROR catch 到錯誤時，比 WARN 嚴重的狀況時就用這個 level 吧
FATAL 在 catch 到錯誤狀況的時候若是不嚴重的問題(eg. 資料庫連不上) 就使用 ERROR level ，若是嚴重的問題時(eg. 公司首頁錯誤，沒辦法信用卡刷卡... 這種一定會被釘的) 就使用 FATAL level 吧

基本上，在使用 DEBUG 和 INFO level ，建議不要在呼叫的那一行中有一些 "計算" 的工作，例如：

log.Info("xxx 本次累積的的紅利點數" + (i / 30).ToString());

這種形式就是個錯誤的示範，因為雖然 log.Info 這一行在上線時可以藉由 config 檔的設定抑制這一行的輸出，但中間的算式還是會耗掉系統資源，所以對於 DEBUG 和 INFO level 來說，基本原則就是能以純文字描述的時候就以純文字描述就好，至多也只是附上一兩個變數在訊息中間也就足夠了
至於 ERROR 和 FATAL level 可能就不應該有這種限制了，一來是因為會用到 ERROR 和 FATAL level 的地方大概多是在 catch 到 error 的段落裡，那些段落正常時也就根本不會被執行到，所以資訊多一點，算式多一點也無所謂，二來是遇到 ERROR 和 FATAL 狀況時本來就需要比較多的資訊來做判斷。
那 WARN level 呢？就請各位自己斟酌了，當然 log4net 的 FAQ 文件上有提到使用上節省系統資源的作法，各位再參考看看了：

http://logging.apache.org/log4net/release/faq.html#perf-not-logging

我個人以為一個正常上線的系統，平時它的 log level 設定應該是設定在 ERROR 層級，也就是只有程式中 log.Error() 和 log.Fatal() 寫出的訊息才會被記錄下來，遇到問題時，可能也是逐步先開 WARN level 或 INFO level 來追問題，不得已時才開最影響效能的 DEBUG level 才對，所以我想各位對於什麼樣的 log 該以什麼樣的 level 去記錄也會有一個自己的底了才對

7. 其它 Appender

除了前面範例所提到的 RollingFile Appender 之外，我自己還有使用的是 SMTP Appender 和 AspNetTraceAppender ，前者可以在系統發生錯誤狀況時寄警告信給我自己，後者可以讓我直接以同樣的 log 語法把偵錯資訊寫到 ASP.Net 的 trace.axd 頁面中，以下為兩者的範例：

<appender name="SmtpAppender" type="log4net.Appender.SmtpAppender">
<to value="xxx@yourcompany.com.tw" />
<from value="xxx@yourcompany.com.tw" />
<subject value="test logging message" />
<smtpHost value="172.18.xxx.xxx" />
<bufferSize value="512" />
<lossy value="true" />
<evaluator type="log4net.Core.LevelEvaluator">
<threshold value="ERROR"/>
</evaluator>
<layout type="log4net.Layout.PatternLayout">
<conversionPattern value="%newline%date [%thread] %-5level %logger [%ndc] - %message%newline%newline%newline" />
</layout>
</appender>

<appender name="AspNetTraceAppender" type="log4net.Appender.AspNetTraceAppender" >
<layout type="log4net.Layout.PatternLayout">
<conversionPattern value="%date [%thread] %-5level %logger [%property{NDC}] - %message%newline" />
</layout>
</appender>


<root>
<level value="DEBUG" />
<appender-ref ref="RollingFile" />
<appender-ref ref="SmtpAppender " />
<appender-ref ref="AspNetTraceAppender" />
</root>
....
....

SMTP Appender 中需要指定 SMTP Server 的位置，如果所在網域裡面找不到可用 STMP Server 的話，可能要自己另外架設一個，另外在上述的設定範例中有個 evaluator 段落是用來篩選錯誤層級的，此處標明 ERROR 表示只有 ERROR 以及 ERROR 以上層級的 log 才會以 STMP Appender 來處理。
至於 AspNetTraceAppender 就不多說了，就是透過 ASP.NET 內建的 trace 機制送出，基本上要記得 web.config 中相對於 trace 的段落要記得設定，否則也跑出不來。

8. 結論

log4net 真是個 debug 的好幫手，因為也可以利用 appender 把 log 寫到 trace.warn 相同的地方去，等於可以取代 Trace.Warn 的功能，你可以在測試環境時把 log 寫到 Trace.Warn 中，在正式環境發生問題時把 log 寫到檔案去方便 debug
不過大家別把 debugging log 和商業流程中的 "狀態紀錄" 搞混了，雖然 log4net 也可以把 log 寫到資料庫去，但不表示我們可以把一些使用記錄之類的東西透過 log4net 丟出去(例如某筆網路交易的信用卡刷卡記錄, 來電記錄之類的)，一來是 log4net 記錄到資料庫的時候只能夠以他定義的特定 schema 來記錄，適用於工程師事後除錯用的，不容易「查詢」，二來這東西也不能確保在 mission critical 的環境下運作正常，所以商業上用到的 "狀態紀錄" 這類東西大家還是乖乖的開 Table ，利用 DB 的 transaction 功能來避免交易失誤吧

JOHOYA

2007年7月24日星期二

Windows 2003 sp2 造成 Crystal Report 的 Export 功能失效

2007年3月6日星期二

log4net 介紹

網誌存檔

標籤

關於我自己

參觀人次