java日志框架 java日志配置等需要注意的幾個方面

前言

1. 日志框架眾多，兼容問題

2. 日志配置復(fù)雜，容易出錯

3. 日志異步亂用，導(dǎo)致日志錯亂

4. DefaultErrorHandler存在線程安全問題

5. 需要禁止的一些操作

6. 需要注意的一些操作

7. 系統(tǒng)異常處理原則和實踐

總結(jié)

前言

在日常開發(fā)中，如果你是一名后端開發(fā)人員，想必應(yīng)該非常清楚在應(yīng)用系統(tǒng)運行期間，打印日志有多么重要。

它不但能夠記錄服務(wù)運行情況及軌跡，還有助于提升故障排查及定位問題的效率，甚至還可以對其進行分析及監(jiān)控，洞察系統(tǒng)隱患，提前預(yù)警防范。

如果輸出的日志是毫無價值的，或者是存在問題的時候，會給我我們帶來很多不必要的麻煩。

今天和大家聊一聊日志，希望大家看完之后能夠得到一些幫助。

1. 日志框架眾多，兼容問題

我們會接觸到不同的日志框架，很多人都認為打印日志是一件簡單的事情，但不合理的日志打印會給我們排查問題帶來困擾。

常用的日志框架：Logbcak、Log4J、Log4j2、commons-logging

在使用過程中會去調(diào)用他們各自的API，完成日志信息的記錄，各種各樣的API就造成了很混亂的感覺，同時還要避免同時使用他們，會造成死循環(huán)。為了解決這個問題應(yīng)該采用日志門面。

什么是日志門面？

日志門面，是門面模式的一個典型的應(yīng)用。

門面模式(Facade Pattern) ，也稱之為外觀模式，其核心為:外部與一個子系統(tǒng)的通信必須通過一個統(tǒng)一的外觀對象進行， 使得子系統(tǒng)更易于使用。

解決方案： SLF4J（Simple Logging Facade For Java）

org.projectlombok
lombok
true



org.slf4j
slf4j-api
1.6.1

這樣做的最大好處，就是業(yè)務(wù)層的開發(fā)不需要關(guān)心底層日志框架的實現(xiàn)及細節(jié)，在編碼的時候也不需要考慮日后更換框架所帶來的成本。這也是門面模式所帶來的好處。

2. 日志配置復(fù)雜，容易出錯

在使用日志框架的時候，我們會根據(jù)一些定制化的不同級別的日志輸出，進行自定義的變更配置，下面整理了下我們需要注意的一些點。

（1）錯誤配置LevelFilter造成日志重復(fù)記錄

 
INFO

問題分析：

我們可以跟進一下源碼來定位下，為什么沒有過濾INFO的日志信息

publicAbstractMatcherFilter(){
this.onMatch=FilterReply.NEUTRAL;
this.onMismatch=FilterReply.NEUTRAL;
}

默認是NEUTRAL，默認交給下一個過濾器處理,否則調(diào)用onMismatch定義的處理方式處理，默認也是交給下一個過濾器處理

大概的意思就明白了，因為我們沒有配置 onMatch 和 onMismatc h，所以默認交給了下一個過濾器執(zhí)行。

解決方案：

由于沒有配置 onMatch 和 onMismatch 屬性，導(dǎo)致一直交給下一個過濾器處理，

只要加上配置就可以解決

 
DENY
 
ACCEPT

3. 日志異步亂用，導(dǎo)致日志錯亂

什么情況下我們會考慮使用異步，那肯定是為了提高性能瓶頸，特別是針對一些突發(fā)日志的應(yīng)用程序比較有利，提高吞吐量。

AsyncAppender 顧名思義是個異步Appender，采用異步方式處理日志，在其內(nèi)部維護了一個 BlockingQueue 阻塞隊列，每次處理日志時，都先嘗試把 Log4jLogEvent 事件存入隊列中，然后交由后臺線程從隊列中取出事件并處理（把日志交由 AsyncAppender 所關(guān)聯(lián)的Appender處理），但隊列長度總是有限的，且隊列默認大小是128，如果日志量過大或日志異步線程處理不及時，就很可能導(dǎo)致日志隊列被打滿。

官網(wǎng)也為我們提供的對比圖

下圖比較了同步記錄器、異步追加器和異步記錄器的吞吐量。這是所有線程的總吞吐量。在具有 64 個線程的測試中，異步記錄器比異步追加器快 12 倍，比同步記錄器快 68 倍。

異步記錄器的吞吐量隨著線程數(shù)的增加而增加，而同步記錄器和異步追加器的吞吐量或多或少是恒定的，而不管執(zhí)行日志記錄的線程數(shù)如何。

（1）異步日志丟失行號、方法名等信息

false

看到前面的？,就是我們丟失的行號、方法名等信息

主要是因為includeCallerData屬性設(shè)置為false的原因

includeCallerData作用：控制是否收集調(diào)用方數(shù)據(jù)，設(shè)置為false目的是為了提高性能

true

（2） 異步日志出現(xiàn)丟失

在異步日志中有關(guān)鍵的三個屬性值，他決定了日志是否出現(xiàn)丟失的問題

模擬打印500次的INFO級別的日志信息

@GetMapping("/testPerformance")
publicvoidtestPerformance(){
StopWatchstopWatch=newStopWatch();
stopWatch.start();
IntStream.rangeClosed(1,500).forEach(val->{
log.info("{},{}",val,"writelog"+val);
});
stopWatch.stop();
log.info("result{}",stopWatch.prettyPrint());
}

執(zhí)行結(jié)果：

根據(jù)圖片我們可以看到，我們進行了500次循環(huán)，但是打印結(jié)果的數(shù)據(jù)存在缺失。

分析源碼

AsyncAppender 類主要繼承了 AsyncAppenderBase類

下面我們來看一下源碼

publicclassAsyncAppenderBaseextendsUnsynchronizedAppenderBaseimplementsAppenderAttachable{
AppenderAttachableImplaai=newAppenderAttachableImpl();
BlockingQueueblockingQueue;
publicstaticfinalintDEFAULT_QUEUE_SIZE=256;
intqueueSize=256;
intappenderCount=0;
staticfinalintUNDEFINED=-1;
intdiscardingThreshold=-1;
booleanneverBlock=false;
AsyncAppenderBase.Workerworker=newAsyncAppenderBase.Worker();
publicstaticfinalintDEFAULT_MAX_FLUSH_TIME=1000;
intmaxFlushTime=1000;

publicAsyncAppenderBase(){
}

if(this.discardingThreshold==-1){
this.discardingThreshold=this.queueSize/5;
}

queueSize 屬性

作用:用于控制阻塞隊列大小，防止隊列塞滿后阻塞，默認為256，內(nèi)存中最多保存256條日志。

discardingThreshold 屬性

作用:控制丟棄日志的閾值，默認值-1，需要注意的是，這里的閾值是指行數(shù)，不是百分比

privatevoidput(EeventObject){
if(this.neverBlock){
this.blockingQueue.offer(eventObject);
}else{
this.putUninterruptibly(eventObject);
}

}

問題分析：

因為 queueSize 的默認為256，所以內(nèi)存中最多保存256條日志，當?shù)竭_ discardingThreshold 剩余總行數(shù)的五分之一時，就會進行日志丟棄的操作。

解決方案：

通過修改關(guān)鍵的屬性值，來進行日志丟失問題的解決

false
0

我們只需要將 discardingThreshold 設(shè)置為0，他表示不進行日志的丟棄操作，這樣就可以達到保證日志不丟失的目的。

（3）異步日志內(nèi)存撐爆

因為異步里面主要使用 BlockingQueue 阻塞隊列，隊列都會存在的一個問題就是過大的時候肯定就會造成OOM。

所以 queueSize 設(shè)置特別大，也會造成 OOM 異常。

（4） 異步日志出現(xiàn)阻塞

業(yè)務(wù)場景：

a. 調(diào)用后端RPC服務(wù)超時，導(dǎo)致調(diào)用方大量線程阻塞

b. 輸出異常日志導(dǎo)致大量線程阻塞

關(guān)鍵屬性：neverBlock屬性

作用:隊列滿的時候，加入數(shù)據(jù)是否丟棄，默認不丟棄

是的時候調(diào)用 offer() 方法不阻塞，否的時候調(diào)用 put() 方法阻塞。

我們來看一下這部分的源碼

privatevoidput(EeventObject){
if(this.neverBlock){
this.blockingQueue.offer(eventObject);
}else{
this.putUninterruptibly(eventObject);
}

}

privatevoidputUninterruptibly(EeventObject){
booleaninterrupted=false;

try{
while(true){
try{
this.blockingQueue.put(eventObject);
return;
}catch(InterruptedExceptionvar7){
interrupted=true;
}
}
}finally{
if(interrupted){
Thread.currentThread().interrupt();
}

}
}

在默認情況下，就會調(diào)用putUninterruptibly阻塞方法，拋出 OOM 異常后，會一直阻塞著。

所以，當我們設(shè)置過大的隊列或者不愿意犧牲日志的情況下可能會導(dǎo)致線程的阻塞問題。

我們需要做好取舍的工作，看一看是性能有限還是數(shù)據(jù)安全優(yōu)先

4. DefaultErrorHandler存在線程安全問題

//org.apache.logging.log4j.core.appender.DefaultErrorHandler
privatestaticfinalLoggerLOGGER=StatusLogger.getLogger();
privatestaticfinalintMAX_EXCEPTIONS=3;
//5min時間間隔
privatestaticfinallongEXCEPTION_INTERVAL=TimeUnit.MINUTES.toNanos(5);
privateintexceptionCount=0;
privatelonglastException=System.nanoTime()-EXCEPTION_INTERVAL-1;
publicvoiderror(finalStringmsg){
finallongcurrent=System.nanoTime();
//當前時間距離上次異常處理時間間隔超過5min或者異常處理數(shù)小于3次
if(current-lastException>EXCEPTION_INTERVAL
||exceptionCount++

	

	DefaultErrorHandler 內(nèi)部在處理異常日志時增加了條件限制，只有下述兩個條件任一滿足 時才會處理，從而避免大量異常日志導(dǎo)致的性能問題。

	兩條日志處理間隔超過5min。

	異常日志數(shù)量不超過3次。

	lastException 用于標記上次異常的時間戳，該變量可能被多線程訪問，無法保證多線程情況下的線程安全。

	exceptionCount用于統(tǒng)計異常日志次數(shù)，該變量可能被多線程訪問，無法保證多線程情況下的線程安全。

	5. 需要禁止的一些操作

	【強制】ERROR 級別日志需打印堆棧，而非 ERROR 級別日志則不需要。

	【強制】禁止日志打印內(nèi)容中僅打印特殊字符或數(shù)字的情況。

	【強制】禁止使用 Logback/Log4j2 等的 API，應(yīng)使用 SLF4J 的 API。

	【強制】禁止日志不能打印客戶敏感信息，如身份證號，銀行卡號。

	6. 需要注意的一些操作

	【建議】日志內(nèi)容中應(yīng)包含關(guān)鍵特征類信息，例如：用戶標識或流水號。

	【建議】應(yīng)采用異步打印模式，且打印時建議關(guān)閉打印位置信息。

	【建議】日志打印若出現(xiàn)堵塞，建議至少丟棄 INFO 級別以上的日志。

	【建議】每條日志在語義上可獨立被理解，減少上下文關(guān)聯(lián)理解。

	【建議】打印異常堆棧信息,調(diào)用方法log.error(Object message, Throwable e) ，正確寫法：log.error("訂單【"+orderId+"】詳情查詢異常：, e);

	【強制】在接口/方法的入口/出口處，打印請求及響應(yīng)參數(shù)日志。

	7. 系統(tǒng)異常處理原則和實踐

	異常處理原則

	（1）具體明確的原則。具體而不是泛化地拋出異常，明確捕獲哪種類型的異常，而不是泛化地捕獲Exception類型的異常?？梢詫ν籺ry塊定義多個catch塊。

	（2）更泛化的異常類型放在最后的catch塊，如IOException。

	（3）提早拋出的原則。提早拋出異常（又稱＂快速失敗＂），異常得以清晰又準確。

	（4）延遲捕獲的原則，在合適的層面捕獲異常。如在web前端捕獲、處理異常，可以有效通知用戶并提供處理意見。

	異常處理實踐

	（1）在堆棧跟蹤中包含引起異常的原因 。

	（2）檢查型異常轉(zhuǎn)為運行時異常。如throw new RuntimeException("查詢失敗"，sqlException)。

	（3）禁止catch塊為空。

	異常處理建議

	（1）catch塊中，ex.printStacktrace()只是將異常輸出到控制臺，沒有任何意義。而且這里出現(xiàn)了異常并沒有中斷程序，進而調(diào)用代碼繼續(xù)執(zhí)行，導(dǎo)致更多的異常。

	（2）不要在PC網(wǎng)頁、H5、APP界面上顯示異常類名或者打印異常堆棧信息，這種東西對用戶沒有幫助。

	（3）不要將異常包含在循環(huán)語句塊中（特別注意循環(huán)代碼塊中調(diào)用方法中包含異常處理），異常處理占用系統(tǒng)資源。

	（4）多層次打印異常,會導(dǎo)致異常日志重復(fù)累贅。在合適的處理層打印異常日志信息和處理異常。

	（5）不要在 finally 內(nèi)部使用 return 語句。它不僅會影響函數(shù)的正確返回值，而且它可能還會導(dǎo)致一些異常處理過程的意外終止，最終導(dǎo)致某些異常的丟失。

	總結(jié)

	關(guān)于日志，確實是我們?nèi)粘Ｖ惺褂米疃?，但卻最容易忽視的地方，只要線上一出現(xiàn)問題我們只能通過日志來復(fù)現(xiàn)問題，

	只有規(guī)范的輸出日志才能讓我們的排查做到事半功倍，主要從日志的兼容性、異步日志問題、需要禁止和注意的一些操作，

	在之后的輸出日志的時候，保持著更嚴謹?shù)膽B(tài)度。

	


	作者小郭的技術(shù)筆記，在此特別鳴謝！