Java 寫 Log

標籤：runner   說明   eth   不同的   完整   mod   上下文   預設   www   

. 一個最基本的例子使用Logging架構寫Log基本上就三個步驟

1. 引入loggerg類和logger工廠類
2. 聲明logger
3. 記錄日誌

下面看一個例子

//1. 引入slf4j介面的Logger和LoggerFactoryimport org.slf4j.Logger;import org.slf4j.LoggerFactory;public class UserService {  //2. 聲明一個Logger，這個是static的方式，我比較習慣這麼寫。  private final static Logger logger = LoggerFactory.getLogger(UserService.class);  public boolean verifyLoginInfo(String userName, String password) {    //3. log it，輸出的log資訊將會是："Start to verify User [Justfly]    logger.info("Start to verify User [{}]", userName);    return false;  }}

 

其中的第二步，關於Logger對象是否要聲明為靜態業界有過一些討論，Logback的作者最早是推薦使用物件變數的方式來聲明，後來他自己也改變了想法。想詳細瞭解的同學可以去看一下: http://slf4j.org/faq.html#declared_static兩種方式的優劣概述如下：

• 靜態Logger對象相對來說更符合語義，節省CPU，節省記憶體，不支援注入
• 物件變數Logger支援注入，對於一個JVM中啟動並執行多個引用了同一個類庫的應用程式，可以在不同的應用程式中對同個類的Logger進行不同的配置。比如Tomcat上部署了倆個應用，他們都引用了同一個lib。

2. Logger介面的方法Logger介面分為倆個版本，一個帶Marker版本和一個沒帶Marker版本的。帶Marker版本的我沒用過就不介紹了。沒帶Marker版本的介面方法可以分為以下兩組：2.1 判斷Logger層級是否開啟的方法

• public boolean isTraceEnabled();
• public boolean isDebugEnabled();
• public boolean isInfoEnabled();
• public boolean isWarnEnabled();
• public boolean isErrorEnabled();

這 組方法的作用主要是避免沒必要的log資訊對象的產生，尤其是對於不支援參數化資訊的Log架構(Log4j 1, commons-logging)。如下面的例子所示，如果沒有加debug層級判斷，在Debug層級被禁用的環境（生產環境）中，第二行的代碼將沒有 必要的產生多個String對象。

if(logger.isDebugEnabled()){   logger.debug("["+resultCount+"]/["+totalCount+"] of users are returned");}

 

如果使用了參數資訊的方法，在如下代碼中，即使沒有添加debug層級（第一行）判斷，在生產環境中，第二行代碼只會產生一個String對象。

if(logger.isDebugEnabled()){   logger.debug("[{}]/[{}] of users in group are returned", resultCount,totalCount); }

 

因此，為了代碼的可讀性，我一般情況下使用參數化資訊的方法，並且不做Logger層級是否開啟的判斷，換句話說，這組方法我一般情況下不會用。2.2 log資訊的方法2.2.1 方法說明Logger中有五個層級：track,debug,info,warn,error。對於每個層級，分別有五個log方法，以info層級為例子：

• public void info(String msg);

無參數的log方法，例子：

logger.info("開始初始化設定檔讀模數塊");

 

輸出

2014-08-11 23:36:17,783 [main] INFO  c.j.training.logging.service.UserService - 開始初始化設定檔讀模數塊

 

• public void info(String format, Object arg);

支援一個參數的參數化log方法，例子：

logger.info("開始匯入設定檔[{}]","/somePath/config.properties");

 

輸出

2014-08-11 23:36:17,787 [main] INFO  c.j.training.logging.service.UserService - 開始匯入設定檔[/somePath/config.properties]

• public void info(String format, Object arg1, Object arg2);

支援倆個參數的參數化log方法，例子：

logger.info("開始從設定檔[{}]中讀取配置項[{}]的值","/somePath/config.properties","maxSize");

 

輸出2014-08-11 23:36:17,789 [main] INFO  c.j.training.logging.service.UserService - 開始從設定檔[/somePath/config.properties]中讀取配置項[maxSize]的值

• public void info(String format, Object... arguments);

支援多個參數的參數化log方法，對比上面的倆個方法來說，會多增加構造一個Object[]的開銷。例子：

logger.info("在設定檔[{}]中讀取到配置項[{}]的值為[{}]","/somePath/config.properties","maxSize", 5);

 

輸出
2014-08-11 23:36:17,789 [main] INFO  c.j.training.logging.service.UserService - 在設定檔[/somePath/config.properties]中讀取到配置項[maxSize]的值為[5]

• public void info(String msg, Throwable t);

無參數化記錄log異常資訊

logger.info("讀取設定檔時出現異常",new FileNotFoundException("File not exists"));

 輸出

2014-08-11 23:36:17,794 [main] INFO  c.j.training.logging.service.UserService - 讀取設定檔時出現異常
java.io.FileNotFoundException: File not exists
  at cn.justfly.training.logging.service.UserServiceTest.testLogResult(UserServiceTest.java:31) ~[test-classes/:na]
  at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.6.0_45]
  at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) ~[na:1.6.0_45]
  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) ~[na:1.6.0_45]
  at java.lang.reflect.Method.invoke(Method.java:597) ~[na:1.6.0_45]
參數化說明在上面的例子中，我們可以看到log資訊中的{}將會按照順序被後面的參數所替換。這樣帶來了一個好處：如果在運行時不需要列印該Log，則不會重複產生String對象。2.2.2 如何Log Exception2.2.2.1 把Exception作為Log方法的最後一個參數

上面講的參數化Log方法的中的最後一個參數如果是一個Exception類型的對象的時候，logback將會列印該Exception的StackTrace資訊。看下面的這個例子：

logger.info("讀取設定檔[{}]時出錯。","/somePath/config.properties",new FileNotFoundException("File not exists"));

上面的代碼在執行的時候會輸出如下內容：
2014-08-12 00:22:49,167 [main] INFO  c.j.training.logging.service.UserService - 讀取設定檔[/somePath/config.properties]時出錯。
java.io.FileNotFoundException: File not exists
  at cn.justfly.training.logging.service.UserServiceTest.testLogResult(UserServiceTest.java:30) [test-classes/:na]
  at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.6.0_45]
  at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) ~[na:1.6.0_45]
  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) ~[na:1.6.0_45]
  at java.lang.reflect.Method.invoke(Method.java:597) ~[na:1.6.0_45]
  at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47) [junit.jar:na]
  at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12) [junit.jar:na]
  at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44) [junit.jar:na]
  at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17) [junit.jar:na]
  at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:271) [junit.jar:na]2.2.2.2 Exception不會替換log資訊中的參數

另外需要注意的時，該Exception不會作為參數化內容中的參數進行替換。比如下面的代碼：

logger.info("讀取設定檔[{}]時出錯。異常為[{}]","/somePath/config.properties",new FileNotFoundException("File not exists"));

 

其執行結果如下所示，第二個參數沒有進行替換2014-08-12 00:25:37,994 [main] INFO  c.j.training.logging.service.UserService - 讀取設定檔[/somePath/config.properties]時出錯。異常為[{}]
java.io.FileNotFoundException: File not exists
  at cn.justfly.training.logging.service.UserServiceTest.testLogResult(UserServiceTest.java:30) [test-classes/:na]
  at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.6.0_45]
  at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) ~[na:1.6.0_45]
  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) ~[na:1.6.0_45]
  at java.lang.reflect.Method.invoke(Method.java:597) ~[na:1.6.0_45]2.2.2.3 參數化Exception如果你就是不想要列印StackTrace，就是要將其參數化的話怎麼弄？一般情況下不建議這麼做，因為你把Exception中有用的東西吃掉了。但是如果你非要這麼做的話，也不是不可以，有倆個方法：

• 把Exception的toString()方法的傳回值作為參數

例子如下所示，注意我們不用ex.getMessage()而是用toString()方法，原因在於不是每個Message執行個體都有Message，但是預設的toString()方法裡麵包括有Message

logger.info("讀取設定檔[{}]時出錯。異常為[{}]","/somePath/config.properties",new FileNotFoundException("File not exists").toString());

 

執行結果為：2014-08-12 00:29:24,018 [main] INFO  c.j.training.logging.service.UserService - 讀取設定檔[/somePath/config.properties]時出錯。異常為[java.io.FileNotFoundException: File not exists]

• 不要讓Exception成為最後一個參數

例子如下：

logger.info("讀取參數[{}]的時候出錯：[{}], 請檢查你的設定檔[{}]","maxSize",new FileNotFoundException("File not exists"),"/somePath/config.properties");

 

執行結果為：2014-08-12 00:35:11,125 [main] INFO  c.j.training.logging.service.UserService - 讀取參數[maxSize]的時候出錯：[java.io.FileNotFoundException: File not exists], 請檢查你的設定檔[/somePath/config.properties]3. Log什麼前面講了怎麼使用Loggger的方法log日誌，下面繼續講講在什麼地方需要記錄什麼層級的log，以及需要記錄什麼內容。3.1 如何使用不同層級的LogSLF4J把Log分成了Error，Warn，Info，Debug和Trace五個層級。我們可以把這倆個層級分成兩組3.1.1 使用者層級Error、Warn和Info這三個層級的Log會出現在生產環境上，他們必須是營運人員能閱讀明白的3.1.1.1 Error

• 影響到程式正常運行、當前請求正常啟動並執行異常情況,例如：
• 開啟設定檔失敗
• 第三方應用網路連接異常
• SQLException
• 不應該出現的情況，例如：
• 某個Service方法返回的List裡面應該有元素的時候缺獲得一個空List
• 做字元轉換的時候居然報錯說沒有GBK字元集

3.1.1.2 Warn

• 不應該出現但是不影響程式、當前請求正常啟動並執行異常情況，例如：
• 有容錯機制的時候出現的錯誤情況
• 找不到設定檔，但是系統能自動建立設定檔
• 即將接近臨界值的時候，例如：
• 緩衝池佔用達到警告線

3.1.1.3 Info

• 系統運行資訊
• Service方法的出入口
• 主要邏輯中的分步驟
• 外部介面部分
• 用戶端請求參數和返回給用戶端的結果
• 調用第三方時的調用參數和調用結果

3.1.2 開發層級Debug和Trace這倆個層級主要是在開發期間使用或者當系統出現問題後開發人員介入調試的時候用的，需要有助於提供詳細的資訊。3.1.2.1 Debug

• 用於記錄程式變數，例如：
• 多次迭代中的變數
• 用於替代代碼中的注釋

如果你習慣在代碼實現中寫：//1. 擷取使用者基本薪資

//2. 擷取使用者休假情況

//3. 計算使用者應得薪資
不妨這麼寫試試

logger.debug("開始擷取員工[{}] [{}]年基本薪資",employee,year);logger.debug("擷取員工[{}] [{}]年的基本薪資為[{}]",employee,year,basicSalary);logger.debug("開始擷取員工[{}] [{}]年[{}]月休假情況",employee,year,month);logger.debug("員工[{}][{}]年[{}]月年假/病假/事假為[{}]/[{}]/[{}]",employee,year,month,annualLeaveDays,sickLeaveDays,noPayLeaveDays);logger.debug("開始計算員工[{}][{}]年[{}]月應得薪資",employee,year,month);logger.debug("員工[{}] [{}]年[{}]月應得薪資為[{}]",employee,year,month,actualSalary);

 

3.1.2.2 Trace主要用於記錄系統運行中的完整資訊，比如完整的HTTP Request和Http Response3.2 Log中的要點3.2.1 Log上下文在Log中必須盡量帶入內容相關的資訊，對比以下倆個Log資訊，後者比前者更有作用

• "開始匯入設定檔"
• "開始匯入設定檔[/etc/myService/config.properties]"

3.2.2 考慮Log的讀者對於使用者層級的Log，它的讀者可能是使用了你的架構的其他開發人員，可能是營運人員，可能是普通使用者。你需要盡量以他們可以理解的語言來組織Log資訊，如果你的Log能對他們的使用提供有用的協助就更好了。下面的兩條Log中，前者對於非代碼維護人員的協助不大，後者更容易理解。

• "開始執行getUserInfo 方法，使用者名稱[jimmy]"
• "開始擷取使用者資訊，使用者名稱[jimmy]"

下面的這個Log對於架構的使用者提供了極大的協助

• "無法解析參數[12 03, 2013]，birthDay參數需要符合格式[yyyy-MM-dd]"

3.2.3 Log中的變數用[]與普通文本區分開來把變數和普通文本隔離有這麼幾個作用

• 在你閱讀Log的時候容易捕捉到有用的資訊
• 在使用工具分析Log的時候可以更方便抓取
• 在一些情況下不容易混淆

對比以下下面的兩條Log，前者發生了混淆：

• "擷取使用者lj12月份發郵件記錄數"
• "擷取使用者[lj1][2]月份發郵件記錄數"

3.2.4 Error或者Warn層級中碰到Exception的情況盡量log 完整的異常資訊Error和Warn層級是比較嚴重的情況，意味著系統出錯或者危險，我們需要更多的資訊來協助分析原因，這個時候越多的資訊越有協助。這個時候最好的做法是Log以下全部內容：

• 你是在做什麼事情的時候出錯了
• 你是在用什麼資料做這個事情的時候出錯了
• 出錯的資訊是什麼

對比下面三個Log語句，第一個提供了詳盡的資訊，第二個只提供了部分資訊，Exception的Message不一定包含有用的資訊，第三個只告訴你出錯了，其他的你一無所知。

• log.error("擷取使用者[{}]的使用者資訊時出錯",userName,ex);
• log.error("擷取使用者[{}]的使用者資訊時報錯，錯誤資訊：[{}]",userName,ex.getMessage());
• log.error("擷取使用者資訊時出錯");

3.2.5 對於Exception，要每次都Log StackTrace嗎？

在一些Exception處理機制中，我們會每層或者每個Service對應一個RuntimeException類，並把他們拋出去，留給最外層的異常處理層處理。典型代碼如下:

try{  }catch(Exception ex){  String errorMessage=String.format("Error while reading information of user [%s]",userName);  logger.error(errorMessage,ex);  throw new UserServiceException(errorMessage,ex);}

 

這個時候問題來了，在最底層出錯的地方Log了異常的StackTrace，在你把這個異常外上層拋的過程中，在最外層的異常處理層的時候，還會再Log一次異常的StackTrace，這樣子你的Log中會有大篇的重複資訊。我碰到這種情況一般是這麼處理的：Log之！原因有以下這幾個方面：

• 這個資訊很重要，我不確認再往上的異常處理層中是否會正常的把它的StackTrace列印出來。
• 如果這個異常資訊在往上傳遞的過程中被多次封裝，到了最外層列印StackTrace的時候最底層的真正有用的出錯原因有可能不會被列印出來。
• 如果有人改變了LogbackException列印的配置，使得不能完全列印的時候，這個資訊可能就丟了。
• 就算重複了又怎麼樣？都Error了都Warning了還省那麼一點空間嗎？

 

Java 寫 Log