1. 一個(gè)最基本的例子
使用Logging框架寫Log基本上就三個(gè)步驟
- 引入loggerg類和logger工廠類
- 聲明logger
- 記錄日志
下面看一個(gè)例子
//1. 引入slf4j接口的Logger和LoggerFactory
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
public class UserService {
//2. 聲明一個(gè)Logger，這個(gè)是static的方式，我比較習(xí)慣這么寫。
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;
}
}
兩種方式的優(yōu)劣概述如下：
- 靜態(tài)Logger對象相對來說更符合語義，節(jié)省CPU，節(jié)省內(nèi)存，不支持注入
- 對象變量Logger支持注入，對于一個(gè)JVM中運(yùn)行的多個(gè)引用了同一個(gè)類庫的應(yīng)用程序，可以在不同的應(yīng)用程序中對同個(gè)類的Logger進(jìn)行不同的配置。比如Tomcat上部署了倆個(gè)應(yīng)用，他們都引用了同一個(gè)lib。
2. Logger接口的方法
Logger接口分為倆個(gè)版本，一個(gè)帶Marker版本和一個(gè)沒帶Marker版本的。帶Marker版本的我沒用過就不介紹了。沒帶Marker版本的接口方法可以分為以下兩組：
2.1 判斷Logger級別是否開啟的方法
- public boolean isTraceEnabled();
- public boolean isDebugEnabled();
- public boolean isInfoEnabled();
- public boolean isWarnEnabled();
- public boolean isErrorEnabled();
這組方法的作用主要是避免沒必要的log信息對象的產(chǎn)生，尤其是對于不支持參數(shù)化信息的Log框架(Log4j 1, commons-logging)。如下面的例子所示，如果沒有加debug級別判斷，在Debug級別被禁用的環(huán)境（生產(chǎn)環(huán)境）中，第二行的代碼將沒有必要的產(chǎn)生多個(gè)String對象。
1 if(logger.isDebugEnabled()){
2 logger.debug("["+resultCount+"]/["+totalCount+"] of users are returned");
3 }
如果使用了參數(shù)信息的方法，在如下代碼中，即使沒有添加debug級別（第一行）判斷，在生產(chǎn)環(huán)境中，第二行代碼只會生成一個(gè)String對象。
1 if(logger.isDebugEnabled()){
2 logger.debug("[{}]/[{}] of users in group are returned", resultCount,totalCount);
3 }
因此，為了代碼的可讀性，我一般情況下使用參數(shù)化信息的方法，并且不做Logger級別是否開啟的判斷，換句話說，這組方法我一般情況下不會用。
2.2 log信息的方法
2.2.1 方法說明
Logger中有五個(gè)級別：track,debug,info,warn,error。對于每個(gè)級別，分別有五個(gè)log方法，以info級別為例子：
- public void info(String msg);
無參數(shù)的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);
支持一個(gè)參數(shù)的參數(shù)化log方法，例子：
logger.info("開始導(dǎo)入配置文件[{}]","/somePath/config.properties");
輸出
2014-08-11 23:36:17,787 [main] INFO c.j.training.logging.service.UserService - 開始導(dǎo)入配置文件[/somePath/config.properties]
- public void info(String format, Object arg1, Object arg2);
支持倆個(gè)參數(shù)的參數(shù)化log方法，例子：
logger.info("開始從配置文件[{}]中讀取配置項(xiàng)[{}]的值","/somePath/config.properties","maxSize");
輸出
2014-08-11 23:36:17,789 [main] INFO c.j.training.logging.service.UserService - 開始從配置文件[/somePath/config.properties]中讀取配置項(xiàng)[maxSize]的值
- public void info(String format, Object... arguments);
支持多個(gè)參數(shù)的參數(shù)化log方法，對比上面的倆個(gè)方法來說，會多增加構(gòu)造一個(gè)Object[]的開銷。例子：
logger.info("在配置文件[{}]中讀取到配置項(xiàng)[{}]的值為[{}]","/somePath/config.properties","maxSize", 5);
輸出
2014-08-11 23:36:17,789 [main] INFO c.j.training.logging.service.UserService - 在配置文件[/somePath/config.properties]中讀取到配置項(xiàng)[maxSize]的值為[5]
- public void info(String msg, Throwable t);
無參數(shù)化記錄log異常信息
logger.info("讀取配置文件時(shí)出現(xiàn)異常",new FileNotFoundException("File not exists"));
輸出
2014-08-11 23:36:17,794 [main] INFO c.j.training.logging.service.UserService - 讀取配置文件時(shí)出現(xiàn)異常
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]
參數(shù)化說明
在上面的例子中，我們可以看到log信息中的{}將會按照順序被后面的參數(shù)所替換。這樣帶來了一個(gè)好處：如果在運(yùn)行時(shí)不需要打印該Log，則不會重復(fù)產(chǎn)生String對象。
2.2.2 如何Log Exception
2.2.2.1 把Exception作為Log方法的最后一個(gè)參數(shù)
上面講的參數(shù)化Log方法的中的最后一個(gè)參數(shù)如果是一個(gè)Exception類型的對象的時(shí)候，logback將會打印該Exception的StackTrace信息。看下面的這個(gè)例子：
logger.info("讀取配置文件[{}]時(shí)出錯(cuò)。","/somePath/config.properties",new FileNotFoundException("File not exists"));
上面的代碼在執(zhí)行的時(shí)候會輸出如下內(nèi)容：
2014-08-12 00:22:49,167 [main] INFO c.j.training.logging.service.UserService - 讀取配置文件[/somePath/config.properties]時(shí)出錯(cuò)。
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信息中的參數(shù)
另外需要注意的時(shí)，該Exception不會作為參數(shù)化內(nèi)容中的參數(shù)進(jìn)行替換。比如下面的代碼：
logger.info("讀取配置文件[{}]時(shí)出錯(cuò)。異常為[{}]","/somePath/config.properties",new FileNotFoundException("File not exists"));
其執(zhí)行結(jié)果如下所示，第二個(gè)參數(shù)沒有進(jìn)行替換
2014-08-12 00:25:37,994 [main] INFO c.j.training.logging.service.UserService - 讀取配置文件[/somePath/config.properties]時(shí)出錯(cuò)。異常為[{}]
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 參數(shù)化Exception
如果你就是不想要打印StackTrace，就是要將其參數(shù)化的話怎么弄？一般情況下不建議這么做，因?yàn)槟惆袳xception中有用的東西吃掉了。但是如果你非要這么做的話，也不是不可以，有倆個(gè)方法：
- 把Exception的toString()方法的返回值作為參數(shù)
例子如下所示，注意我們不用ex.getMessage()而是用toString()方法，原因在于不是每個(gè)Message實(shí)例都有Message，但是默認(rèn)的toString()方法里面包括有Message
logger.info("讀取配置文件[{}]時(shí)出錯(cuò)。異常為[{}]","/somePath/config.properties",new FileNotFoundException("File not exists").toString());
執(zhí)行結(jié)果為：
2014-08-12 00:29:24,018 [main] INFO c.j.training.logging.service.UserService - 讀取配置文件[/somePath/config.properties]時(shí)出錯(cuò)。異常為[java.io.FileNotFoundException: File not exists]
- 不要讓Exception成為最后一個(gè)參數(shù)
例子如下：
logger.info("讀取參數(shù)[{}]的時(shí)候出錯(cuò)：[{}], 請檢查你的配置文件[{}]","maxSize",new FileNotFoundException("File not exists"),"/somePath/config.properties");
執(zhí)行結(jié)果為：
2014-08-12 00:35:11,125 [main] INFO c.j.training.logging.service.UserService - 讀取參數(shù)[maxSize]的時(shí)候出錯(cuò)：[java.io.FileNotFoundException: File not exists], 請檢查你的配置文件[/somePath/config.properties]
3. Log什么
前面講了怎么使用Loggger的方法log日志，下面繼續(xù)講講在什么地方需要記錄什么級別的log，以及需要記錄什么內(nèi)容。
3.1 如何使用不同級別的Log
SLF4J把Log分成了Error，Warn，Info，Debug和Trace五個(gè)級別。我們可以把這倆個(gè)級別分成兩組
3.1.1 用戶級別
Error、Warn和Info這三個(gè)級別的Log會出現(xiàn)在生產(chǎn)環(huán)境上，他們必須是運(yùn)維人員能閱讀明白的
3.1.1.1 Error
- 影響到程序正常運(yùn)行、當(dāng)前請求正常運(yùn)行的異常情況,例如：
- 打開配置文件失敗
- 第三方應(yīng)用網(wǎng)絡(luò)連接異常
- SQLException
- 不應(yīng)該出現(xiàn)的情況，例如：
- 某個(gè)Service方法返回的List里面應(yīng)該有元素的時(shí)候缺獲得一個(gè)空List
- 做字符轉(zhuǎn)換的時(shí)候居然報(bào)錯(cuò)說沒有GBK字符集
3.1.1.2 Warn
- 不應(yīng)該出現(xiàn)但是不影響程序、當(dāng)前請求正常運(yùn)行的異常情況，例如：
- 有容錯(cuò)機(jī)制的時(shí)候出現(xiàn)的錯(cuò)誤情況
- 找不到配置文件，但是系統(tǒng)能自動創(chuàng)建配置文件
- 即將接近臨界值的時(shí)候，例如：
3.1.1.3 Info
- 系統(tǒng)運(yùn)行信息
- 外部接口部分
- 客戶端請求參數(shù)和返回給客戶端的結(jié)果
- 調(diào)用第三方時(shí)的調(diào)用參數(shù)和調(diào)用結(jié)果
3.1.2 開發(fā)級別
Debug和Trace這倆個(gè)級別主要是在開發(fā)期間使用或者當(dāng)系統(tǒng)出現(xiàn)問題后開發(fā)人員介入調(diào)試的時(shí)候用的，需要有助于提供詳細(xì)的信息。
3.1.2.1 Debug
如果你習(xí)慣在代碼實(shí)現(xiàn)中寫：
//1. 獲取用戶基本薪資
//2. 獲取用戶休假情況
//3. 計(jì)算用戶應(yīng)得薪資
不妨這么寫試試
logger.debug("開始獲取員工[{}] [{}]年基本薪資",employee,year);
logger.debug("獲取員工[{}] [{}]年的基本薪資為[{}]",employee,year,basicSalary);
logger.debug("開始獲取員工[{}] [{}]年[{}]月休假情況",employee,year,month);
logger.debug("員工[{}][{}]年[{}]月年假/病假/事假為[{}]/[{}]/[{}]",employee,year,month,annualLeaveDays,sickLeaveDays,noPayLeaveDays);
logger.debug("開始計(jì)算員工[{}][{}]年[{}]月應(yīng)得薪資",employee,year,month);
logger.debug("員工[{}] [{}]年[{}]月應(yīng)得薪資為[{}]",employee,year,month,actualSalary);
3.1.2.2 Trace
主要用于記錄系統(tǒng)運(yùn)行中的完整信息，比如完整的HTTP Request和Http Response
3.2 Log中的要點(diǎn)
3.2.1 Log上下文
在Log中必須盡量帶入上下文的信息，對比以下倆個(gè)Log信息，后者比前者更有作用
- "開始導(dǎo)入配置文件"
- "開始導(dǎo)入配置文件[/etc/myService/config.properties]"
3.2.2 考慮Log的讀者
對于用戶級別的Log，它的讀者可能是使用了你的框架的其他開發(fā)者，可能是運(yùn)維人員，可能是普通用戶。你需要盡量以他們可以理解的語言來組織Log信息，如果你的Log能對他們的使用提供有用的幫助就更好了。
下面的兩條Log中，前者對于非代碼維護(hù)人員的幫助不大，后者更容易理解。
- "開始執(zhí)行g(shù)etUserInfo 方法，用戶名[jimmy]"
- "開始獲取用戶信息，用戶名[jimmy]"
下面的這個(gè)Log對于框架的使用者提供了極大的幫助
- "無法解析參數(shù)[12 03, 2013]，birthDay參數(shù)需要符合格式[yyyy-MM-dd]"
3.2.3 Log中的變量用[]與普通文本區(qū)分開來
把變量和普通文本隔離有這么幾個(gè)作用
- 在你閱讀Log的時(shí)候容易捕捉到有用的信息
- 在使用工具分析Log的時(shí)候可以更方便抓取
- 在一些情況下不容易混淆
對比以下下面的兩條Log，前者發(fā)生了混淆：
- "獲取用戶lj12月份發(fā)郵件記錄數(shù)"
- "獲取用戶[lj1][2]月份發(fā)郵件記錄數(shù)"
3.2.4 Error或者Warn級別中碰到Exception的情況盡量log 完整的異常信息
Error和Warn級別是比較嚴(yán)重的情況，意味著系統(tǒng)出錯(cuò)或者危險(xiǎn)，我們需要更多的信息來幫助分析原因，這個(gè)時(shí)候越多的信息越有幫助。這個(gè)時(shí)候最好的做法是Log以下全部內(nèi)容：
- 你是在做什么事情的時(shí)候出錯(cuò)了
- 你是在用什么數(shù)據(jù)做這個(gè)事情的時(shí)候出錯(cuò)了
- 出錯(cuò)的信息是什么
對比下面三個(gè)Log語句，第一個(gè)提供了詳盡的信息，第二個(gè)只提供了部分信息，Exception的Message不一定包含有用的信息，第三個(gè)只告訴你出錯(cuò)了，其他的你一無所知。
- log.error("獲取用戶[{}]的用戶信息時(shí)出錯(cuò)",userName,ex);
- log.error("獲取用戶[{}]的用戶信息時(shí)報(bào)錯(cuò)，錯(cuò)誤信息：[{}]",userName,ex.getMessage());
- log.error("獲取用戶信息時(shí)出錯(cuò)");
3.2.5 對于Exception，要每次都Log StackTrace嗎？
在一些Exception處理機(jī)制中，我們會每層或者每個(gè)Service對應(yīng)一個(gè)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);
}
這個(gè)時(shí)候問題來了，在最底層出錯(cuò)的地方Log了異常的StackTrace，在你把這個(gè)異常外上層拋的過程中，在最外層的異常處理層的時(shí)候，還會再Log一次異常的StackTrace，這樣子你的Log中會有大篇的重復(fù)信息。
我碰到這種情況一般是這么處理的：Log之！原因有以下這幾個(gè)方面：
- 這個(gè)信息很重要，我不確認(rèn)再往上的異常處理層中是否會正常的把它的StackTrace打印出來。
- 如果這個(gè)異常信息在往上傳遞的過程中被多次包裝，到了最外層打印StackTrace的時(shí)候最底層的真正有用的出錯(cuò)原因有可能不會被打印出來。
- 如果有人改變了LogbackException打印的配置，使得不能完全打印的時(shí)候，這個(gè)信息可能就丟了。
- 就算重復(fù)了又怎么樣？都Error了都Warning了還省那么一點(diǎn)空間嗎？