1. 一個最基本的例子
使用Logging框架寫Log基本上就三個步驟
- 引入loggerg類和logger工廠類
- 聲明logger
- 記錄日志
下面看一個例子
//1. 引入slf4j接口的Logger和LoggerFactory
import 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對象相對來說更符合語義，節省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]
例子如下：
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
- 系統運行信息
- 外部接口部分
- 客戶端請求參數和返回給客戶端的結果
- 調用第三方時的調用參數和調用結果
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了還省那么一點空間嗎？