|
級別: 中級
Charles Chan , 首席顧問, Ambrose Software Inc.
2005 年 9 月 05 日
在企業(yè)級的開發(fā)過程中，我們不可避免地會碰到很多問題；如果您希望在開發(fā)過程的后期能夠有效地捕捉 bug，那就需要一種有效的日志策略。但是在一個企業(yè)的應(yīng)用程序中要想實現(xiàn)有效地記錄日志，需要進(jìn)行一番規(guī)劃，并設(shè)計一些準(zhǔn)則。在本文中，顧問 Charles Chan 將向您介紹一些最好的實踐，從而幫助您從項目一開始就編寫有用的日志代碼。
如果您是一名開發(fā)人員，那您很可能就已經(jīng)具有這種經(jīng)驗：您已經(jīng)開發(fā)了一些代碼以及一些測試用例。應(yīng)用程序經(jīng)過了嚴(yán)格的 QA 測試，您確信代碼可以完全適合業(yè)務(wù)的需求。然而，在將應(yīng)用程序最終交付終端用戶的手里時，卻會出現(xiàn)一些預(yù)想不到的問題。如果沒有適當(dāng)?shù)娜罩鞠ⅲ赡苄枰ㄙM幾天的時間來診斷這些問題。不幸的是，大部分項目對于日志都沒有一個清晰的策略。如果沒有這種策略，系統(tǒng)產(chǎn)生的日志消息就有可能無益于問題的分析和解決。在本文中，我們將討論企業(yè)應(yīng)用程序日志的各個方面的問題。您將看到一個 Java? 平臺上日志 API 的概述，學(xué)習(xí)一些最好的編寫日志代碼的實踐，并了解如果需要在產(chǎn)品環(huán)境中對詳細(xì)日志重新進(jìn)行排序，應(yīng)該如何處理。
選擇日志 API
在使用 Java 平臺進(jìn)行開發(fā)時，可以使用兩個主要的日志 API：Apache Log4J 和 Java Logging API，在 1.4 及更高版本的 Java 平臺中都提供了這兩個 API。與 Java Logging API 相比，Log4J 更加成熟，特性也更加豐富。這兩個日志的實現(xiàn)都采用了一個類似的設(shè)計模式（如圖 1 所示）。除非您的公司限制要使用第三方的庫，否則我強烈建議使用 Log4J。如果您不能決定使用哪個 API，就可以使用 Apache Commons Logging API，它對底層的日志實現(xiàn)進(jìn)行了封裝。從理論上來說，這樣不用修改代碼就可以進(jìn)行日志實現(xiàn)的切換。然而，實際上您很少會切換日志的實現(xiàn)；因此，我不建議使用 Apache Commons Logging API，因為它的復(fù)雜性并不沒有給您帶來其他特性。
日志概述
Log4J 和 Java Logging API 都采用了類似的設(shè)計和使用模式（如圖 1 和清單 1 所示）。消息首先被創(chuàng)建，然后傳遞給一個具有特定優(yōu)先權(quán)的日志對象。這些消息的目的和格式是由輸出處理程序及其布局所決定。
圖 1. 日志實現(xiàn)的主要組件
清單 1. 日志對象的實例化和使用
import org.apache.log4j.Logger;
public class MyClass {
/*
* Obtain a logger for a message category. In this case, the message category is
* the fully qualified class name of MyClass.
*/
private static final Logger logger = Logger.getLogger(MyClass.class.getName());
...
public void myMethod() {
...
if (logger.isDebugEnabled()) {
logger.debug("Executing with parameters: " + param1 + ":" + param2);
}
}
}
|
一個好的日志實現(xiàn)中提供了很多不同的輸出處理程序，最常見的文件輸出處理程序和終端輸出處理程序。Log4J 還提供了一些處理程序?qū)⑾l(fā)布到一個 JMS 主題中，或者將消息插入一個數(shù)據(jù)庫表中。盡管這編寫一個定制的附加器并不困難，但是編寫和維護(hù)這種代碼的總體成本不應(yīng)低估。消息的格式可以通過 Layout 對象進(jìn)行配置。最常見的 layout 對象是 PatternLayout，它根據(jù)所提供的模式對消息進(jìn)行格式化。
清單 2 給出了一個 Log4J 的樣例配置文件，它負(fù)責(zé)配置 FileAppender。在這種配置中，com.ambrosesoft.log.MyClass 類中的錯誤消息被發(fā)送給 FileAppender，后者將其寫入一個名為 log.txt 的文件中。這些消息是根據(jù)與這個添加器相關(guān)的 layout（在這種情況中是 PatternLayout）進(jìn)行格式化的。
清單 2. Log4J XML 配置樣例文件
日志最佳實踐
關(guān)于日志，您要做的一個最重要的選擇可能是確定一種模式，將每個日志消息分配給一個特定的 類別。常見的一種實踐是使用每個類的全名，這些類的操作會被作為一個消息類別在日志中記錄（正如我們在清單 1 中看到的一樣），這是因為這可以讓開發(fā)人員更細(xì)粒度地記錄每個類的設(shè)置。然而，這只有在使用日志消息來跟蹤執(zhí)行過程時才能良好地工作。在企業(yè)級的應(yīng)用程序中，有很多其他類型的日志消息。舉例來說，一條日志消息可能是為安全顧問產(chǎn)生的，而另外一條日志消息則可能是會為了幫助進(jìn)行性能調(diào)優(yōu)而產(chǎn)生的。如果這兩條消息所關(guān)注的是同一個類，這樣就會被分配給相同的類別，這將很難在日志輸出結(jié)果中對其進(jìn)行區(qū)分。
為了避免這個問題，應(yīng)用程序應(yīng)該具有一組專用的日志記錄程序，它們都進(jìn)行了獨特的分類，如清單 3 所示。每個日志記錄程序都可以配置自己的優(yōu)先級和輸出處理程序。例如，安全性日志記錄程序可以在將日志寫入目的地之前對消息進(jìn)行加密。有時應(yīng)用程序的設(shè)計者應(yīng)該與使用日志的用戶（例如安全顧問）一起來商討日志的輸出格式，從而對這些消息進(jìn)行更好的控制。
清單 3. 專用的日志記錄程序
import org.apache.log4j.Logger;
public interface Loggers {
Logger performance = Logger.getLogger("performance");
Logger security = Logger.getLogger("security");
Logger business = Logger.getLogger("business");
}
...
public class MyClass {
....
if (Loggers.security.isWarnEnabled()) {
Loggers.security.warn("Access denied: Username [" + userName + "] ...");
}
...
}
|
選擇日志的級別
一個 類別 （例如 security）中的消息可以具有不同的 優(yōu)先級。有些消息是為了調(diào)試而產(chǎn)生的，有些是為了警告而產(chǎn)生的，有些則是出現(xiàn)錯誤而產(chǎn)生的。消息的不同優(yōu)先級可以通過記錄 級別 來產(chǎn)生。最常用的日志級別有：
- Debug: 這個級別的消息中包含了非常廣泛的上下文信息。通常用于問題診斷。
- Info: 這些消息包含了一些有助于在產(chǎn)品環(huán)境中（粒度較粗）幫助跟蹤執(zhí)行過程的上下文消息。
- Warning: 警告消息，說明系統(tǒng)中可能存在問題。例如，如果這個消息類別是有關(guān)安全性方面的，那么如果檢測到字典攻擊，就應(yīng)該產(chǎn)生一條警告消息。
- Error: 錯誤消息說明系統(tǒng)中出現(xiàn)了嚴(yán)重的問題。這種問題通常都是不可恢復(fù)的，需要人工進(jìn)行干預(yù)。
標(biāo)準(zhǔn)的 Java Logging API 和 Apache Log4J 在此之外又提供了一些日志級別。日志級別的主要目標(biāo)是幫助您過濾有用信息中的噪聲。為了防止出現(xiàn)使用錯誤的級別以及降低日志消息的效用的情況，在開始編碼之前，必須為開發(fā)人員提供一個清晰的指導(dǎo)方針。
日志消息的格式
一旦選定日志記錄程序并建立起日志級別之后，就可以開始構(gòu)建日志消息了。在這樣做時，重要的是要包含盡可能多的上下文信息，例如用戶提供的參數(shù)，其他應(yīng)用程序的狀態(tài)信息。記錄日志對象的一種方法是將它們轉(zhuǎn)換成 XML。第三方庫，例如 XStream（請參閱 參考資料）可以自動將 Java 對象轉(zhuǎn)換成 XML 。盡管這是一種非常強大的機(jī)制，但是我們必須要考慮在速度與詳細(xì)程度之間達(dá)到一種平衡。除了典型的應(yīng)用程序狀態(tài)信息之外，還應(yīng)該記錄以下信息：
- 線程 ID: 企業(yè)級的應(yīng)用程序通常都是在多線程的環(huán)境中運行的。使用線程 ID 信息，您就可以將多個請求區(qū)分開來。
- 調(diào)用程序的標(biāo)識: 調(diào)用程序的標(biāo)識也是非常重要的信息。由于不同的用戶具有不同的特權(quán)，它們的執(zhí)行路徑也可能會有很大的不同。將用戶的標(biāo)識放到日志消息中，這對于對安全性敏感的應(yīng)用程序是非常大的一個幫助。
- 時間戳: 通常來說，用戶只能近似地知道問題發(fā)生的時間。如果沒有時間戳，就很難讓別人來判斷問題的原因所在。
- 源代碼信息: 這包括類名、方法名和行號。除非您非常關(guān)注安全性，否則我建議您保留調(diào)試標(biāo)記（
-g），即使在編譯產(chǎn)品時也是如此。如果沒有調(diào)試標(biāo)記，Java 編譯器就會刪除所有的行號信息，從而極大地減少日志消息的可用性。
上面這些信息（除了調(diào)用程序標(biāo)識）都是由日志實現(xiàn)自動獲取的。為了將這些信息包含到消息中，您只需要為輸出處理程序配置一個適當(dāng)?shù)?layout 模式即可。要捕獲調(diào)用者的標(biāo)識，您可以利用 Log4J 中的診斷上下文特性（更多信息請參閱 參考資料）。診斷上下文讓您可以將上下文信息與當(dāng)前正在運行的線程關(guān)聯(lián)在一起。這些信息可以在為輸出進(jìn)行格式化的同時而包含到每條消息中。
在 J2EE Web 應(yīng)用程序中，應(yīng)用邏輯將用戶標(biāo)識保存到診斷上下文中最好的地方是在一個 servlet 過濾器中。清單 4 中顯示了要實現(xiàn)這種功能的必要代碼。它使用了 Log4J 1.3 alpha 中提供的映射診斷上下文類（MDC）。您可以使用 Log4J 1.2 中提供的嵌套診斷上下文（NDC）實現(xiàn)相同的功能。有關(guān) servlet 過濾器的更多通用信息，請參閱 參考資料 中的信息。
清單 4. 在 servlet 過濾器中使用診斷上下文
import javax.servlet.Filter;
...
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpSession;
import org.apache.log4j.MDC;
public class LoggerFilter implements Filter {
public void doFilter(ServletRequest request, ServletResponse response,
FilterChain chain) throws IOException, ServletException {
// Retrieves the session object from the current request.
HttpSession session = ((HttpServletRequest)request).getSession();
// Put the username into the diagnostic context.
// Use %X{username} in the layout pattern to include this information.
MDC.put("username", session.getAttribute("username"));
// Continue processing the rest of the filter chain.
chain.doFilter(request, response);
// Remove the username from the diagnostic context.
MDC.remove("username");
}
...
}
|
使用 AspectJ 跟蹤執(zhí)行情況
在對問題進(jìn)行診斷時，通常跟蹤程序的執(zhí)行情況會很有幫助。您可以在程序執(zhí)行的不同地方持續(xù)發(fā)送日志消息嗎？例如方法的入口函數(shù)和出口函數(shù)。這是一個老問題，在出現(xiàn) AspectJ 之前一直都沒有什么好的解決方案。使用 AspectJ，可以在應(yīng)用程序的不同地方執(zhí)行代碼段。在 AspectJ 中，這些地方都稱為 point cut，在 point cut 處所執(zhí)行的代碼稱為 advice。point cut 和advice 合稱 aspect。
關(guān)于 AspectJ，有一件事情非常神奇，aspect 不用很多努力就可以應(yīng)用到整個應(yīng)用程序中。有關(guān) AspectJ 的更多信息，請參閱 參考資料。清單 5 給出了一個 AspectJ 源文件的例子，它用來對方法的入口和出口函數(shù)記錄日志。在這個例子中，跟蹤日志程序?qū)⒃诿看芜M(jìn)入或退出 com.ambrosesoft 包的一個共有方法時都會記錄一條日志。
清單 5. 使用 AspectJ 記錄方法的入口和出口
import org.apache.log4j.Logger;
import java.lang.reflect.Field;
public aspect AutoTrace {
private static final Logger logger = Logger.getLogger(AutoTrace.class);
pointcut publicMethods() : execution(public * com.ambrosesoft..*(..));
pointcut loggableCalls() : publicMethods();
/**
* Inspect the class and find its logger object. If none is found, use
* the one defined here.
*/
private Logger getLogger(org.aspectj.lang.JoinPoint joinPoint) {
try {
/*
* Try to discover the logger object.
* The logger object must be a static field called logger.
*/
Class declaringType = joinPoint.getSignature().getDeclaringType();
Field loggerField = declaringType.getField("logger");
loggerField.setAccessible(true);
return (Logger)loggerField.get(null);
} catch(NoSuchFieldException e) {
/*
* Cannot find a logger object, use the internal one.
*/
return logger;
} catch(Exception e) {
throw new RuntimeException(e);
}
}
/**
* An aspect to log method entry.
*/
before() : loggableCalls(){
getLogger(thisJoinPoint).debug("Entering.." + thisJoinPoint.getSignature().toString());
}
/**
* An aspect to log method exit.
*/
after() : loggableCalls(){
getLogger(thisJoinPoint).debug("Exiting.." + thisJoinPoint.getSignature().toString());
}
}
|
 |
產(chǎn)品環(huán)境中的日志
一旦應(yīng)用程序處于產(chǎn)品環(huán)境中之后，您通常都需要關(guān)閉調(diào)試或信息日志消息，從而對運行時的性能進(jìn)行優(yōu)化。然而，當(dāng)有些不好的事情發(fā)生時，您又不能在開發(fā)環(huán)境中重現(xiàn)這個問題，那就可能需要在產(chǎn)品環(huán)境中激活調(diào)試消息了。重要的是能夠修改日志的設(shè)置，而不用關(guān)閉服務(wù)器。診斷產(chǎn)品的問題即使不用花費數(shù)天來進(jìn)行詳細(xì)的調(diào)研，通常也需要幾個小時的時間。在這段時間之內(nèi)，開發(fā)人員需要激活或關(guān)閉應(yīng)用程序不同范圍的日志。如果每次修改日志的設(shè)置之后都需要重新啟動產(chǎn)品應(yīng)用程序，那么情況就會變得非常不可靠了。
幸運的是，Log4J 提供了一種簡單的機(jī)制來解決這個問題。在 Log4J 1.2 中，DOMConfigurator 中的 configureAndWatch() 方法會對 Log4J 進(jìn)行配置，并自動監(jiān)視日志配置文件中的變化。這在清單 6 中進(jìn)行了闡述。（注意，在 Log4J 1.3（目前仍是 alpha 版本） 中并不推薦使用 DOMConfigurator，它使用了一個更加靈活的實現(xiàn) JoranConfigurator。）
為了確保 configureAndWatch() 是在 Log4J 初始化之前調(diào)用的，您應(yīng)該在啟動類中調(diào)用它。不同的應(yīng)用程序服務(wù)器采用了不同的機(jī)制來執(zhí)行啟動代碼（更多信息請參閱 參考資料）。詳細(xì)信息請查看應(yīng)用服務(wù)器的實現(xiàn)。有些應(yīng)用服務(wù)器可能需要您將 Log4J 的庫放到服務(wù)器的 classpath 中。日志配置文件應(yīng)該保存到一個需要日志的人可以訪問的位置。
清單 6. 使用 DOMConfigurator 配置 Log4J
/*
* Configure Log4J library and periodically monitor log4j.xml for any update.
*/
DOMConfigurator.configureAndWatch("/apps/config/log4j.xml");
|
如果您的日志配置文件不能方便地進(jìn)行訪問（例如您的產(chǎn)品環(huán)境是由一個不同的組織進(jìn)行維護(hù)的），那么您就必須使用一種不同的策略。標(biāo)準(zhǔn)的方法是使用 JMX，它提供了一個標(biāo)準(zhǔn)的 API 來管理自己的應(yīng)用程序設(shè)置。在現(xiàn)代 JMX 兼容的服務(wù)器中，您可以使用管理 bean （或 MBeans ）來擴(kuò)展應(yīng)用服務(wù)器的管理終端的功能（更多有關(guān)使用 JMX 以及在 WebSphere Application Server 6.0 中使用 JMX 的內(nèi)容，請參閱 參考資料 一節(jié)。）由于 JMX 方法非常復(fù)雜，如果您的情況需要使用 JMX，那就應(yīng)該只用作這個用途。
記錄敏感的數(shù)據(jù)
在記錄產(chǎn)品環(huán)境中的日志時，除了技術(shù)方面的挑戰(zhàn)之外，還存在一些業(yè)務(wù)問題需要克服。例如，記錄敏感的信息可能會引起安全性的問題。并沒有任何限制可以防止您將某個用戶的用戶名和密碼保存到正文文件中。您還必須要保護(hù)其他敏感信息，例如 e-mail 地址、電話號碼以及帳號信息。安全顧問和設(shè)計師有責(zé)任要確保這些信息不會未加任何處理就保存到日志中。對敏感信息使用安全性專用的日志程序可以幫助降低風(fēng)險。您可以給這個日志程序配置一個專用的附加器，從而使用一種加密的格式來保存消息，或者將其保存到一個安全的地方。然而，防止出現(xiàn)安全風(fēng)險的最佳方法是在項目開始之前就設(shè)置適當(dāng)?shù)木幋a規(guī)范，并在檢查代碼時強制施行這些規(guī)范。
從異常中提取有用信息
當(dāng)發(fā)生一個非預(yù)期的異常時 —— 例如，如果數(shù)據(jù)庫連接突然失效了，或者系統(tǒng)資源變得很低了 —— 就必須對其適當(dāng)?shù)剡M(jìn)行處理，否則就會丟失有用的信息，這些信息在診斷問題時是非常有幫助的。首先，必須記錄異常及其堆棧跟蹤狀況。其次，應(yīng)該使用一種用戶界面友好的方式來標(biāo)識錯誤頁面，這對于終端用戶和技術(shù)支持小組來說都是非常有幫助的。
技術(shù)支持小組在接到一個技術(shù)支持電話時所面臨的一個挑戰(zhàn)是在用戶所報告的問題與特定的日志異常之間建立某種關(guān)聯(lián)。非常有用的一種簡單技術(shù)是為每個異常都記錄一個唯一的 ID。這個 ID 可以告訴用戶，也可以包含在終端用戶所填寫的問題報告表單中。這樣可以減少技術(shù)支持團(tuán)隊成員猜測的時間，讓他們可以快速對問題作出響應(yīng)。考慮到可讀性的問題，可以定期對 ID 進(jìn)行回收。
日志文件的管理
一個非常繁忙的應(yīng)用程序的日志文件可能會迅速變得非常大。較大的日志文件很難使用，這是因為它們需要過濾大量的噪聲才能找到有用的信號。Log 循環(huán) 是常見的一個可以幫助解決這個問題的實踐。日志循環(huán)會周期性地對舊日志進(jìn)行歸檔，這樣新消息就可以總能寫到一個相對較小的文件中。日志消息降低了一些效用來提高速度；您可能很少需要參考一周之前的日志消息。在 Log4J 1.2 中， DailyRollingFileAppender 附加器可以根據(jù)所提供的日期模式來循環(huán)使用日志文件。（在 Log4J 1.3 中，已經(jīng)對這個循環(huán)日志文件附加器重新進(jìn)行了設(shè)計。現(xiàn)在您可以提供一種策略來控制如何進(jìn)行循環(huán)了。例如， TimeBasedRollingPolicy 定義了一種基于時間和日期的循環(huán)模式。）清單 7 顯示了讓 Log4J 在每天午夜對自己的日志文件進(jìn)行循環(huán)所采用的配置片斷。
清單 7. 使用 DailyRollingFileAppender 循環(huán)使用日志文件
集群環(huán)境中的日志
現(xiàn)在有越來越多的企業(yè)級應(yīng)用程序是在集群環(huán)境或分布式環(huán)境中進(jìn)行部署的。然而，集群環(huán)境中的日志需要更多規(guī)劃，因為消息都是從不同的源頭生成的（通常是不同的機(jī)器）。如果要對不同的機(jī)器記錄日志，那就必須對這些機(jī)器的時間戳進(jìn)行同步，否則日志消息的次序就混亂了。對機(jī)器間時鐘進(jìn)行同步的一種簡單方法是使用一個時間服務(wù)器。有兩種方法可以設(shè)置時間服務(wù)器。您可以指定一臺內(nèi)部的機(jī)器作為時間服務(wù)器。然后其他機(jī)器就可以使用網(wǎng)絡(luò)時間協(xié)議（NTP）來與時間服務(wù)器的時間戳進(jìn)行同步。另外，您可以使用 Internet 上提供的時間服務(wù)器（請參閱 參考資料）。在 AIX 上，xntpd 守護(hù)進(jìn)程用來對不同機(jī)器的系統(tǒng)時間進(jìn)行同步。當(dāng)機(jī)器具有相同的時間之后，就可以對日志一起進(jìn)行分析了。
在集群環(huán)境中搜集日志消息還面臨著一些挑戰(zhàn)。在這種環(huán)境中保存日志消息的一種簡單方法是將它們保存到主機(jī)特定的日志文件中。當(dāng)集群是使用 session affinity 配置時，這可以很好地工作 —— 如果對某個特定用戶會話的請求都要到同一個服務(wù)器上，并且 EJB 也都是部署在本地的。在這種配置中，集群中的機(jī)器所產(chǎn)生的日志文件都可以獨立進(jìn)行分析。如果不是這種情況 —— 換而言之，如果任何給定的請求都可以由多臺機(jī)器進(jìn)行處理 —— 那么對不同日志文件中的日志消息進(jìn)行分析就會變得更加困難。在這種情況中，一種好的辦法是使用系統(tǒng)管理軟件來管理日志消息，例如 IBM Tivoli? 軟件（請參閱 參考資料 中的鏈接）。這種軟件對所有的日志消息（在系統(tǒng)管理軟件的術(shù)語中稱之為 事件）提供了一個綜合的視圖，從而便于管理員使用。系統(tǒng)管理軟件也可以根據(jù)所接收到的事件的類型觸發(fā)一些操作（例如發(fā)送 e-mail 消息或傳呼消息）。
結(jié)束語
在本文中，我們介紹了在規(guī)劃日志策略時需要考慮哪些問題。正如在編程時所碰到的問題一樣，從一開始就采用一個經(jīng)過詳細(xì)考慮的規(guī)劃要比在進(jìn)行的同時規(guī)劃更能節(jié)省工作量。良好的日志策略可以極大地幫助對問題進(jìn)行診斷。最終，終端用戶可以獲得更好的應(yīng)用程序，并能從技術(shù)支持團(tuán)隊獲得迅速的響應(yīng)。
參考資料
|
關(guān)于作者
 |
|
|
Charles Chan 是一名獨立軟件顧問，在加拿大的 Toronto 工作。他的興趣包括分布式系統(tǒng)、高性能計算、國際化以及軟件設(shè)計模式。在空閑時間，他為開源社區(qū)貢獻(xiàn)自己的成果。 | |