前言

1. 日志框架眾多，兼容問(wèn)題

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

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

4. DefaultErrorHandler存在線程安全問(wèn)題

5. 需要禁止的一些操作

6. 需要注意的一些操作

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

總結(jié)

前言

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

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

如果輸出的日志是毫無(wú)價(jià)值的，或者是存在問(wèn)題的時(shí)候，會(huì)給我我們帶來(lái)很多不必要的麻煩。

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

1. 日志框架眾多，兼容問(wèn)題

我們會(huì)接觸到不同的日志框架，很多人都認(rèn)為打印日志是一件簡(jiǎn)單的事情，但不合理的日志打印會(huì)給我們排查問(wèn)題帶來(lái)困擾。

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

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

什么是日志門(mén)面？

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

門(mén)面模式(Facade Pattern) ，也稱(chēng)之為外觀模式，其核心為:外部與一個(gè)子系統(tǒng)的通信必須通過(guò)一個(gè)統(tǒng)一的外觀對(duì)象進(jìn)行， 使得子系統(tǒng)更易于使用。

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

org.projectlombok
lombok
true



org.slf4j
slf4j-api
1.6.1

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

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

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

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

 
INFO

問(wèn)題分析：

我們可以跟進(jìn)一下源碼來(lái)定位下，為什么沒(méi)有過(guò)濾INFO的日志信息

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

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

大概的意思就明白了，因?yàn)槲覀儧](méi)有配置 onMatch 和 onMismatc h，所以默認(rèn)交給了下一個(gè)過(guò)濾器執(zhí)行。

解決方案：

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

只要加上配置就可以解決

 
DENY
 
ACCEPT

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

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

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

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

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

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

（1）異步日志丟失行號(hào)、方法名等信息

false

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

主要是因?yàn)閕ncludeCallerData屬性設(shè)置為false的原因

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

true

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

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

模擬打印500次的INFO級(jí)別的日志信息

@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ù)圖片我們可以看到，我們進(jìn)行了500次循環(huán)，但是打印結(jié)果的數(shù)據(jù)存在缺失。

分析源碼

AsyncAppender 類(lèi)主要繼承了 AsyncAppenderBase類(lèi)

下面我們來(lái)看一下源碼

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 屬性

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

discardingThreshold 屬性

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

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

}

問(wèn)題分析：

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

解決方案：

通過(guò)修改關(guān)鍵的屬性值，來(lái)進(jìn)行日志丟失問(wèn)題的解決

false
0

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

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

因?yàn)楫惒嚼锩嬷饕褂?BlockingQueue 阻塞隊(duì)列，隊(duì)列都會(huì)存在的一個(gè)問(wèn)題就是過(guò)大的時(shí)候肯定就會(huì)造成OOM。

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

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

業(yè)務(wù)場(chǎng)景：

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

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

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

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

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

我們來(lái)看一下這部分的源碼

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();
}

}
}

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

所以，當(dāng)我們?cè)O(shè)置過(guò)大的隊(duì)列或者不愿意犧牲日志的情況下可能會(huì)導(dǎo)致線程的阻塞問(wèn)題。

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

4. DefaultErrorHandler存在線程安全問(wèn)題

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

	

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

	兩條日志處理間隔超過(guò)5min。

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

	lastException 用于標(biāo)記上次異常的時(shí)間戳，該變量可能被多線程訪問(wèn)，無(wú)法保證多線程情況下的線程安全。

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

	5. 需要禁止的一些操作

	【強(qiáng)制】ERROR 級(jí)別日志需打印堆棧，而非 ERROR 級(jí)別日志則不需要。

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

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

	【強(qiáng)制】禁止日志不能打印客戶敏感信息，如身份證號(hào)，銀行卡號(hào)。

	6. 需要注意的一些操作

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

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

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

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

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

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

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

	異常處理原則

	（1）具體明確的原則。具體而不是泛化地拋出異常，明確捕獲哪種類(lèi)型的異常，而不是泛化地捕獲Exception類(lèi)型的異常。可以對(duì)同一try塊定義多個(gè)catch塊。

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

	（3）提早拋出的原則。提早拋出異常（又稱(chēng)＂快速失敗＂），異常得以清晰又準(zhǔn)確。

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

	異常處理實(shí)踐

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

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

	（3）禁止catch塊為空。

	異常處理建議

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

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

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

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

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

	總結(jié)

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

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

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

	


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