Java日誌框架slf4j API介紹及異常接口實現分析

目錄

1. 前言
2. Facade設計模式簡介
3. slf4j綁定日誌
4. slf4j API使用
5. 後記

前言

slf4j: 簡潔的java日誌統一接口（Simple Logging Facade for Java），顧名思義，就是一個使用Facade設計模式實現的面向java Logging框架的接口開源包。 其和java數據庫鏈接工具包JDBC很像，在JDBC框架中，各個不一樣數據庫鏈接器分別針對不一樣數據庫系統來實現對應的鏈接操做，而普通程序員只須要使用統一的JDBC接口而不須要關注具體底層使用的數據庫類型，或者針對不一樣的數據庫系統寫各類兼容代碼。

Note: slf4j其實相似於適配器，可是這裏不稱呼適配器，是由於當底層log日誌系統不支持slf4j擴展時，好比log4j，就須要在二者中間增長一個適配器層來完成slf4j調用相關日誌系統的操做接口動做。例如，slf4j爲log4j提升的slf4j-log412.jar類庫，可是logback支持slf4J擴展，因此其不需適配層轉換。

一樣，slf4j 不參與具體的日誌代碼實現，它只是在代碼編譯的時候根據程序的配置來綁定具體的日誌系統。這樣，使用slf4j類庫就可讓你的代碼獨立於任意一個特定的日誌API。所以，若是編寫一個對外開發的API活着一個一樣的類庫，那麼爲了避免限制使用你類庫的代碼必須使用指定的日誌系統，你應該使用slf4j。

相對於其餘日誌框架，slf4j日誌類庫的優勢和推薦使用的原因，能夠參見 ImportNew 的譯文【 爲何要使用SLF4J而不是Log4J 】

Facade設計模式簡介

Facade模式，或者叫作外觀模式，顧名思義就是封裝各個底層子系統的提供的同一類功能接口，統一成一個更易操做使用的上層接口進而對外提供交互。有了這個上層封裝的接口，接口調用方只須要調用這個接口，而不須要關於各個子系統的具體邏輯實現。

Facade設計模式的官方定義是：Facade模式定義了一個更高層的接口，使子系統更加容易使用。

關於Facade模式的實例，平常生活中不少這樣子的例子。好比，五、1回家，能夠有好幾種方式：飛機、火車、長途汽車。在實際生活中，你回家的路線應該是：

1. 坐車去機場（火車站/長途汽車站）；
    2. 坐飛機（火車/長途汽車）到家鄉；
    3. 從家鄉飛機場（火車站/長途汽車站）到家裏。

通常來講，上面的流程是毫無問題的。可是，若是作成一個系統，你須要對外暴露3個步驟中得3個不一樣的接口，外界須要根據不一樣的交通方式選擇不一樣的調用接口，這無疑加大了接口調研的複雜度，以及系統的複雜度。以下圖所示：

使用Facade模式，封裝各個子系統的實現，對外提供3個接口：

1. 坐車其站點；
    2. 作主交通工具到家鄉；
    3. 從家鄉的站點回家裏。

所以，接口使用方不須要知道子系統具體是什麼樣的業務邏輯，其主要要在配置中，或者一開始指定交通工具，就可讓facade系統來完成下面的一系列操做。這樣，除了讓咱們的系統對外暴露接口少了，最重要的是可讓第三方以最低的成本使用咱們的接口。

slf4j綁定日誌

3.1 slf4j 設計模式說明

爲了說明slf4j採用的Facade模式，也就是若是隻引入slf4j-api包，日誌系統將沒法正常使用。例如在pom.xml文件這隻有：

<dependency> <groupId>org.slf4j</groupId> <artifactId>slf4j-api</artifactId> <version>1.7.5</version> </dependency>

而測試代碼爲：

import org.slf4j.Logger; import org.slf4j.LoggerFactory; /**  * @author: ketao Date: 14-5-3 Time: 上午1:03  * @version: \$Id$  */ public class LogTest { private static final Logger logger = LoggerFactory.getLogger(LogTest.class); public static void main(String[] args){ logger.info("Hello world"); logger.error("ERROR"); } }

執行上面的代碼會出現提示：

SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.

而若是咱們引入logback日誌系統，而且配置logback.xml日誌配置文件：

<dependency> <groupId>ch.qos.logback</groupId> <artifactId>logback-classic</artifactId> <version>1.0.13</version> </dependency>

接下來執行上面的測試代碼，則會打印日誌信息：

[2014-05-03 01:27:11 [34mINFO [0;39m com.qunar.dubbo.LogTest.main(LogTest.java:17)] Hello world
[2014-05-03 01:27:11 [1;31mERROR[0;39m com.qunar.dubbo.LogTest.main(LogTest.java:18)] ERROR

3.2 slf4j 日誌綁定流程

如3.1中的代碼所示，首先調用LoggerFactory.getLogger的方法，這個方法會在編譯的時候，綁定系統設置的真正的日誌框架，以下代碼所示：

/**  * Return a logger named according to the name parameter using the statically  * bound {@link ILoggerFactory} instance.  *  * @param name The name of the logger.  * @return logger  */ public static Logger getLogger(String name) { ILoggerFactory iLoggerFactory = getILoggerFactory(); // 這裏先獲取ILoggerFactory對象 return iLoggerFactory.getLogger(name); // 根據獲取的ILoggerFactory對象，調用其對應的日誌對象 } /**  * Return the {@link ILoggerFactory} instance in use.  * <p/>  * <p/>  * ILoggerFactory instance is bound with this class at compile time.  *  * @return the ILoggerFactory instance in use  */ public static ILoggerFactory getILoggerFactory() { if (INITIALIZATION_STATE == UNINITIALIZED) { INITIALIZATION_STATE = ONGOING_INITIALIZATION; performInitialization(); } switch (INITIALIZATION_STATE) { case SUCCESSFUL_INITIALIZATION: return StaticLoggerBinder.getSingleton().getLoggerFactory();// 這裏就能夠獲取底層日誌系統的單例對象了 case NOP_FALLBACK_INITIALIZATION: return NOP_FALLBACK_FACTORY; case FAILED_INITIALIZATION: throw new IllegalStateException(UNSUCCESSFUL_INIT_MSG); case ONGOING_INITIALIZATION: // support re-entrant behavior. // See also http://bugzilla.slf4j.org/show_bug.cgi?id=106 return TEMP_FACTORY; } throw new IllegalStateException("Unreachable code"); } }

而綁定是在getILoggerFactory()中調用的，在該方法的實現裏，會調用performInitialization()，該方法調用bind()方法（部分代碼）：

private final static void bind() { try { Set staticLoggerBinderPathSet = findPossibleStaticLoggerBinderPathSet();// 尋找程序配置的日誌系統集，具體見下面代碼 reportMultipleBindingAmbiguity(staticLoggerBinderPathSet);// 驗證多於1個日誌系統時，輸出警告信息 // the next line does the binding StaticLoggerBinder.getSingleton();// 測試是否能夠獲取該靜態綁定類單例，能夠，則置爲成功狀態，以下行；不然，會打出3.1中的NOP異常信息。 INITIALIZATION_STATE = SUCCESSFUL_INITIALIZATION; reportActualBinding(staticLoggerBinderPathSet);// 綁定，打印綁定具體日誌系統的日誌 emitSubstituteLoggerWarning();// 提交給臨時日誌factory 打印的日誌，不是重點 } catch (NoClassDefFoundError ncde) { String msg = ncde.getMessage(); if (messageContainsOrgSlf4jImplStaticLoggerBinder(msg)) { INITIALIZATION_STATE = NOP_FALLBACK_INITIALIZATION; Util.report("Failed to load class \"org.slf4j.impl.StaticLoggerBinder\"."); Util.report("Defaulting to no-operation (NOP) logger implementation"); Util.report("See " + NO_STATICLOGGERBINDER_URL + " for further details."); } } }

下面看看，slf4j是如何獲取系統中指定的真正底層日誌系統：

// We need to use the name of the StaticLoggerBinder class, but we can't reference // the class itself. private static String STATIC_LOGGER_BINDER_PATH = "org/slf4j/impl/StaticLoggerBinder.class"; private static Set findPossibleStaticLoggerBinderPathSet() { // use Set instead of list in order to deal with bug #138 // LinkedHashSet appropriate here because it preserves insertion order during iteration Set staticLoggerBinderPathSet = new LinkedHashSet(); try { ClassLoader loggerFactoryClassLoader = LoggerFactory.class .getClassLoader(); Enumeration paths; if (loggerFactoryClassLoader == null) { paths = ClassLoader.getSystemResources(STATIC_LOGGER_BINDER_PATH); } else { paths = loggerFactoryClassLoader .getResources(STATIC_LOGGER_BINDER_PATH); } while (paths.hasMoreElements()) { URL path = (URL) paths.nextElement(); staticLoggerBinderPathSet.add(path); } } catch (IOException ioe) { Util.report("Error getting resources from path", ioe); } return staticLoggerBinderPathSet; }

slf4j在適配器層或者在兼容slf4j擴展的log-api 中會有一個org/slf4j/impl/StaticLoggerBinder.class類，這樣就獲取了系統中真正的日誌系統。而後獲取該日誌的單例，打印相關的日誌信息就能夠了。好比，打印slf4j的log.info則調用logback中Logger.info()方法來打印日誌信息。

slf4j API使用

slf4j的打印日誌基本一致，主要分爲：trace,debug,info,warn,error,比log4j少了fatal級別日誌。因爲每一個級別對於的API方法級別一致，所以，這裏選用info來介紹不一樣輸入參數的API使用。

Tip: SLF4J 認爲 ERROR 與 FATAL 並無實質上的差異，因此拿掉了 FATAL 等級，只剩下其餘五種。

/**  * 純字符串形式的日誌  */ public void info(String msg); /**  * 指定一個參數和位置格式的info級別的日誌輸出形式。這個形式避免了多個object對象的建立。  */ public void info(String format, Object arg); /**  * 指定2個參數和對於位置格式的info級別的日誌輸出。  */ public void info(String format, Object arg1, Object arg2); /**  * 根據指定的參數和日誌格式來輸出info級別的日誌信息。  * 可是，須要指出這種形式雖然避免的字符串拼接的成本，可是它會私底下建立一個`Object[]`對象在調用info方法以前，即便info級別的日誌不打印。  * 所以，若是不是必須3個及以上參數的話，推薦使用兩個參數和一個參數的info日誌。  */ public void info(String format, Object... arguments); /**  * 打印拋出異常信息的info 級別日誌  */ public void info(String msg, Throwable t);

此外，須要介紹的是在slf4j中還提供了含有Marker對象的日記輸出API接口。Marker是經常被用來豐富log狀態的對象。遵照slf4j的日誌系統實現，決定了信息怎樣在使用的Marker之間傳達。實際上，不少遵照規範的日誌系統會忽視掉marker數據,因此，咱們不介紹Marker相關API接口。

下面給出各個接口的使用示例代碼：

import java.io.IOException; import org.slf4j.Logger; import org.slf4j.LoggerFactory; /**  * @author: ketao Date: 14-5-3 Time: 上午1:03  * @version: \$Id$  */ public class LogTest { private static final Logger logger = LoggerFactory.getLogger(LogTest.class); public static void main(String[] args) { logger.info("純字符串信息的info級別日誌"); logger.info("一個參數:{}的info級別日誌", "agr1"); logger.info("二個參數:agrs1:{};agrs2:{}的info級別日誌", "args1", "args2"); // 下面兩種方式均可以，通常使用上面一種就能夠了 logger.info("三個參數:agrs1:{};agrs2:{};args3:{} 的info級別日誌", "args1", "args2", "args3"); logger.info("三個參數:agrs1:{};agrs2:{};args3:{} 的info級別日誌", new Object[] { "args1", "args2", "args3" }); logger.info("======================異常相關===================================="); // 測試異常相關日誌 logger.info("拋出異常,e:", new IOException("測試拋出IO異常信息")); logger.info("二個參數:agrs1:{};agrs2:{}的info級別日誌", "args1", new IOException("測試拋出IO異常信息")); logger.info("二個參數:agrs1:{};agrs2:{}的info級別日誌", "args1", "args2", new IOException("測試拋出IO異常信息")); // 下面兩種方式均可以，通常使用上面一種就能夠了 logger.info("三個參數:agrs1:{};agrs2:{};args3:{} 的info級別日誌", "args1", "args2", new IOException("測試拋出IO異常信息")); logger.info("三個參數:agrs1:{};agrs2:{};args3:{} 的info級別日誌", "args1", "args2", "agrs3", new IOException( "測試拋出IO異常信息")); logger.info("三個參數:agrs1:{};agrs2:{};args3:{} 的info級別日誌", new Object[] { "args1", "args2", "args3", new IOException("測試拋出IO異常信息") }); logger.info("三個參數:agrs1:{};agrs2:{};args3:{} 的info級別日誌", new Object[] { "args1", "args2", new IOException("測試拋出IO異常信息") }); } }

對應輸出日誌信息：

[2014-05-03 03:47:14 [34mINFO [0;39m com.qunar.dubbo.LogTest.main(LogTest.java:20)] 純字符串信息的info級別日誌
[2014-05-03 03:47:14 [34mINFO [0;39m com.qunar.dubbo.LogTest.main(LogTest.java:21)] 一個參數:agr1的info級別日誌
[2014-05-03 03:47:14 [34mINFO [0;39m com.qunar.dubbo.LogTest.main(LogTest.java:22)] 二個參數:agrs1:args1;agrs2:args2的info級別日誌
[2014-05-03 03:47:14 [34mINFO [0;39m com.qunar.dubbo.LogTest.main(LogTest.java:24)] 三個參數:agrs1:args1;agrs2:args2;args3:args3 的info級別日誌
[2014-05-03 03:47:14 [34mINFO [0;39m com.qunar.dubbo.LogTest.main(LogTest.java:25)] 三個參數:agrs1:args1;agrs2:args2;args3:args3 的info級別日誌
[2014-05-03 03:47:14 [34mINFO [0;39m com.qunar.dubbo.LogTest.main(LogTest.java:27)] ======================異常相關====================================
[2014-05-03 03:47:14 [34mINFO [0;39m com.qunar.dubbo.LogTest.main(LogTest.java:29)] 拋出異常,e:
java.io.IOException: 測試拋出IO異常信息
    at com.qunar.dubbo.LogTest.main(LogTest.java:29) [classes/:na]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.7.0_45]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[na:1.7.0_45]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_45]
    at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_45]
    at com.intellij.rt.execution.application.AppMain.main(AppMain.java:120) [idea_rt.jar:na]
[2014-05-03 03:47:14 [34mINFO [0;39m com.qunar.dubbo.LogTest.main(LogTest.java:31)] 二個參數:agrs1:args1;agrs2:java.io.IOException: 測試拋出IO異常信息的info級別日誌
[2014-05-03 03:47:14 [34mINFO [0;39m com.qunar.dubbo.LogTest.main(LogTest.java:32)] 二個參數:agrs1:args1;agrs2:args2的info級別日誌
java.io.IOException: 測試拋出IO異常信息
    at com.qunar.dubbo.LogTest.main(LogTest.java:32) [classes/:na]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.7.0_45]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[na:1.7.0_45]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_45]
    at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_45]
    at com.intellij.rt.execution.application.AppMain.main(AppMain.java:120) [idea_rt.jar:na]
[2014-05-03 03:47:14 [34mINFO [0;39m com.qunar.dubbo.LogTest.main(LogTest.java:35)] 三個參數:agrs1:args1;agrs2:args2;args3:java.io.IOException: 測試拋出IO異常信息 的info級別日誌
[2014-05-03 03:47:14 [34mINFO [0;39m com.qunar.dubbo.LogTest.main(LogTest.java:36)] 三個參數:agrs1:args1;agrs2:args2;args3:agrs3 的info級別日誌
java.io.IOException: 測試拋出IO異常信息
    at com.qunar.dubbo.LogTest.main(LogTest.java:36) [classes/:na]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.7.0_45]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[na:1.7.0_45]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_45]
    at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_45]
    at com.intellij.rt.execution.application.AppMain.main(AppMain.java:120) [idea_rt.jar:na]
[2014-05-03 03:47:14 [34mINFO [0;39m com.qunar.dubbo.LogTest.main(LogTest.java:38)] 三個參數:agrs1:args1;agrs2:args2;args3:args3 的info級別日誌
java.io.IOException: 測試拋出IO異常信息
    at com.qunar.dubbo.LogTest.main(LogTest.java:38) [classes/:na]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.7.0_45]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[na:1.7.0_45]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_45]
    at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_45]
    at com.intellij.rt.execution.application.AppMain.main(AppMain.java:120) [idea_rt.jar:na]
[2014-05-03 03:47:14 [34mINFO [0;39m com.qunar.dubbo.LogTest.main(LogTest.java:39)] 三個參數:agrs1:args1;agrs2:args2;args3:java.io.IOException: 測試拋出IO異常信息 的info級別日誌

Note: 從代碼調用能夠看到，throwable 異常信息單獨做爲一個參數輸入，所以，若是把異常信息做爲{}佔位符中的字符串，則會調用其對應toString方法，而沒法打印異常堆棧信息。能夠看看下面的截取源碼：

public void info(String msg, Throwable t) { filterAndLog_0_Or3Plus(FQCN, null, Level.INFO, msg, null, t); } // 當日志的參數string 大於1，而且包含 Throwable類型參數，則調用下面的方法 public void info(String format, Object[] argArray) { filterAndLog_0_Or3Plus(FQCN, null, Level.INFO, format, argArray, null); } /**  * 在logback代碼中，做者代表若是不使用Object[]建立參數數組對象，則會減小20 納秒的時間開銷。  */ private void filterAndLog_0_Or3Plus(final String localFQCN, final Marker marker, final Level level, final String msg, final Object[] params, final Throwable t) { final FilterReply decision = loggerContext .getTurboFilterChainDecision_0_3OrMore(marker, this, level, msg, params, t); if (decision == FilterReply.NEUTRAL) { if (effectiveLevelInt > level.levelInt) { return; } } else if (decision == FilterReply.DENY) { return; } buildLoggingEventAndAppend(localFQCN, marker, level, msg, params, t);// 在這個方法裏面，會LoggingEvent方法構架日誌信息，而對於Throwable非空時，則會建立一個ThrowableProxy對象，具體代碼見下面。 } // 下面的代碼，是對日誌中的異常打印信息。顯然，在messageFormat裏面，使用String來處理，是沒法得到這麼豐富的異常堆棧信息的。 public ThrowableProxy(Throwable throwable) { this.throwable = throwable; this.className = throwable.getClass().getName(); this.message = throwable.getMessage(); this.stackTraceElementProxyArray = ThrowableProxyUtil.steArrayToStepArray(throwable .getStackTrace()); //下面構建詳細異常的堆棧信息，這也就是咱們在代碼輸出時，看到的一大坨at... 輸出錯誤代碼位置等。 Throwable nested = throwable.getCause(); if (nested != null) { this.cause = new ThrowableProxy(nested); this.cause.commonFrames = ThrowableProxyUtil .findNumberOfCommonFrames(nested.getStackTrace(), stackTraceElementProxyArray); } if(GET_SUPPRESSED_METHOD != null) { // this will only execute on Java 7 try { Object obj = GET_SUPPRESSED_METHOD.invoke(throwable); if(obj instanceof Throwable[]) { Throwable[] throwableSuppressed = (Throwable[]) obj; if(throwableSuppressed.length > 0) { suppressed = new ThrowableProxy[throwableSuppressed.length]; for(int i=0;i<throwableSuppressed.length;i++) { this.suppressed[i] = new ThrowableProxy(throwableSuppressed[i]); this.suppressed[i].commonFrames = ThrowableProxyUtil .findNumberOfCommonFrames(throwableSuppressed[i].getStackTrace(), stackTraceElementProxyArray); } } } } catch (IllegalAccessException e) { // ignore } catch (InvocationTargetException e) { // ignore } } }

Note: 上面代碼只是通常的步驟，對於調用Object[]形式的方法，則ThrowableProxy以前，還會對Object[]中的元素進行過濾處理，提取出最後一個元素判斷是否是 Throwable類型的對象。代碼參考以下：

final public static FormattingTuple format(final String messagePattern, Object arg1, Object arg2) { return arrayFormat(messagePattern, new Object[] { arg1, arg2 }); } //這方法會對輸入參數進行特殊處理和過濾 final public static FormattingTuple arrayFormat(final String messagePattern, final Object[] argArray) { Throwable throwableCandidate = getThrowableCandidate(argArray); ...... if (L < argArray.length - 1) { return new FormattingTuple(sbuf.toString(), argArray, throwableCandidate);// 若是元素中有Throwable類型，則size會減小，所以，對應的Throwale參數位置爲 置提取出來的異常對象 } else { return new FormattingTuple(sbuf.toString(), argArray, null); } } static final Throwable getThrowableCandidate(Object[] argArray) { if (argArray == null || argArray.length == 0) { return null; } final Object lastEntry = argArray[argArray.length - 1]; if (lastEntry instanceof Throwable) { return (Throwable) lastEntry; } return null; }

後記

slf4j的日誌，打印拋出異常的信息時，若是隻須要message，則須要在log api接口中的String 裏面對應位置添加{}符號；不然，若是想要打印全量異常棧信息，則不能也不能夠在string字符串中添加{}，否則會大失所望。