JAVA日誌記錄方法

阿新 • • 發佈：2019-01-19

1. 一個最基本的例子

使用Logging框架寫Log基本上就三個步驟

引入loggerg類和logger工廠類
宣告logger
記錄日誌

下面看一個例子
//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物件。
1 if(logger.isDebugEnabled()){
2 logger.debug("["+resultCount+"]/["+totalCount+"] of users are returned");
3 } 如果使用了引數資訊的方法，在如下程式碼中，即使沒有新增debug級別（第一行）判斷，在生產環境中，第二行程式碼只會生成一個String物件。 1 if(logger.isDebugEnabled()){
2 logger.debug("[{}]/[{}] of users in group are returned", resultCount,totalCount);
3 } 因此，為了程式碼的可讀性，我一般情況下使用引數化資訊的方法，並且不做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 Exception

2.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 如何使用不同級別的Log

SLF4J把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 Response

3.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了還省那麼一點空間嗎？