封裝SLF4J/Log4j，再也不到處定義logger變量

轉載請註明出處: 封裝SLF4J/Log4j，再也不到處定義logger變量

懶得看實現過程的能夠直接跳到最後看實現流程圖和代碼實現。Logback和log4j是內部實現類似，因此能夠用相似的思路實現。

自從開始使用日誌組件後， 每一個類都是這樣子的結構:

public class A {
    public static final Logger logger = LoggerFactory.getLogger(A.class);
}

這是一件至關煩人事，必須對他進行封裝，使得咱們可以經過這樣的方法來調用：

public class A {
    public void methodA() {
        Logger.debug("Nice!");
    }
}

最簡單的版本

開始動手後，用最簡單的方法封裝出了第一個版本:

// cn.hjktech.slf4j.Logger
public class Logger {
    private static final org.slf4j.Logger logger = LoggerFactory.getLogger(Logger.class);;
    ...
    public static void debug(...) {
        logger.debug(...);
        ...
    }
    ...
}

看起來很美好， 但測試後發現這種方法會有一個很嚴重的問題： 咱們打印的日誌通暢都帶有調用方的信息， 如類名、方法名、行數、時間等，其中類名、方法名、行數都是極其關鍵的信息，可是使用上述的方法來輸出日誌的話，這三個信息都變成Logger這個類的信息，而不是調用方的信息， 這顯然是沒法忍受的事。

固然不能就這樣了事，既然正常使用的方法能輸出正確的信息，那麼確定是有辦法能夠實現的，咱們但願最終的結果是調用Logger.debug(..)打印出來的信息都是徹底正確的。

分析源碼

此時寫個demo來debug跟進一下：

public class TestLog {
    @Test
    public void logTest() {
        // 在此處打斷點
        LoggerFactory.getLogger(TestLog.class).debug("看看執行流程");
    }
}

發現最終輸出的日誌字符串是在PatternLayout.format方法(Logback則是PatternLayoutBase.writeLoopOnConverters方法)中生成的，方法代碼以下：

// Log4j
public String format(LoggingEvent event) {
    // Reset working stringbuffer
    if(sbuf.capacity() > MAX_CAPACITY) {
        sbuf = new StringBuffer(BUF_SIZE);
    } else {
        sbuf.setLength(0);
    }

    PatternConverter c = head;

    while(c != null) {
        c.format(sbuf, event);
        c = c.next;
    }
    return sbuf.toString();
}

其中head指向一個類型爲PatternConverter(Logback中是: Converter)的鏈表，這個鏈表的節點是在日誌類初始化的時候，根據你日誌配置文件裏的ConversionPattern生成的，好比個人log4j.properties中是這樣配置的:

log4j.appender.SOUT_LOGGER.layout.ConversionPattern=%d{yyyy-MM-dd-HH-mm,SSS} %p [%c] [%t] (%F:%L) %l - %m%n

那麼這個鏈表的結構就是(括號中表明存儲的信息):

DatePatternConverter(時間點)           -> LiteralPatternConverter(" ")   -> 
BasicPatternConverter(LEVEL)          -> LiteralPatternConverter("[")   -> 
CategoryPatternConverter(LoggerName)  -> LiteralPatternConverter("] [") -> 
BasicPatternConverter(線程名)          -> LiteralPatternConverter("] (") ->
LocationPatternConverter(所在類)       -> LiteralPatternConverter(":")   -> 
LocationPatternConverter(所在行)       -> LiteralPatternConverter(") -") -> 
BasicPatternConverter(日誌串)          -> LiteralPatternConverter("\n")  ->

根據這個鏈表生成日誌字符串相似這樣:
2016-10-17-13-42,449 DEBUG [TestLog] [main] (TestLog.java:14) - Excuse me?

那麼如今目標很明確了，咱們要使LocationPatternConverter的輸出爲咱們真正打印紙日的類的信息，繼續跟進到PatternConverter.format(LocationPatternConverter的父類)方法，其內部生成了一個LocationInfo對象，該類的構造方法中以下：

for(int i = elements.length - 1; i >= 0; i--) {
    // 獲取第i幀的類名
    String thisClass = (String) getClassNameMethod.invoke(elements[i], noArgs);
    if(fqnOfCallingClass.equals(thisClass)) {
        // 若是類名和fqnOfCallingClass相等，則認爲i + 1幀是代碼中實際調用方法的
        int caller = i + 1;
        if (caller < elements.length) {
            // 記錄實際調用類的類名
            className = prevClass;
            // 記錄實際調用的方法名
            methodName = (String) getMethodNameMethod.invoke(elements[caller], noArgs);
            // 記錄實際調用類所在的文件名
            fileName = (String) getFileNameMethod.invoke(elements[caller], noArgs);
            if (fileName == null) {
                fileName = NA;
            }
            // 記錄調用日誌方法的行數
            int line = ((Integer) getLineNumberMethod.invoke(elements[caller], noArgs)).intValue();
            if (line < 0) {
                lineNumber = NA;
            } else {
                lineNumber = String.valueOf(line);
            }
            // 拼接成最終要輸出到日誌的字符串， 如：TestLog.logTest(TestLog.java:14)
            StringBuffer buf = new StringBuffer();
            buf.append(className);
            buf.append(".");
            buf.append(methodName);
            buf.append("(");
            buf.append(fileName);
            buf.append(":");
            buf.append(lineNumber);
            buf.append(")");
            this.fullInfo = buf.toString();
        }
        return;
    }
    // 記錄上一幀的類名
    prevClass = thisClass;
}

其中elements是當前方法調用棧的堆棧軌跡，這段代碼經過遍歷堆棧軌跡每一幀的類名並和fqnOfCallingClass比較，若是相符的話，則認爲它的上一幀是實際調用方法。

以下圖中，fqnOfCallingClass的值是org.slf4j.impl.Log4jLoggerAdapter，而在堆棧軌跡總能夠發現類的上一個幀正好是咱們的實際調用類TestLog.logTest：

所以，咱們如今只須要讓fqnOfCallingClass的值變成咱們封裝的日誌類cn.hjktech.slf4j.Logger就大功告成了。fqnOfCallingClass是LoggingEvent.getLocationInformation建立LocationInfo時傳入的參數，而LoggingEvent又是在Category.forcedLog方法中建立的，而且繼續網上追蹤，會發現fqnOfCallingClass的值最終來源於org.slf4j.impl.Log4jLoggerAdapter這個類:

public final class Log4jLoggerAdapter extends MarkerIgnoringBase implements LocationAwareLogger, Serializable {
    ...
    static final String FQCN = Log4jLoggerAdapter.class.getName();
    ...
}

而若是沒有配合SLF4J使用時，fqnOfCallingClass的值則來源於org.apache.log4j.Logger類：

public class Logger extends Category {
    ...
    private static final String FQCN = Logger.class.getName();
    ....
}

代理Logger類來修改FQCN

好了，如今咱們只須要修改這個值就好了。第一反應是使用反射去掉final修飾符，而後修改它的值，這種方法雖然對咱們本身的代碼可行，可是當引入其它框架，而且其它框架也使用的Log4j時，就會致使它們的日誌信息出錯，由於它們並非調用的咱們封裝的Logger工具類，它們日誌的堆棧軌跡中不會有咱們工具類（如cn.hjktech.slf4j.Logger），所以咱們須要另尋它法。

既然經過反射行不通， 那麼咱們能夠經過動態代理的方式，在構造LoggingEvent對象以前將FQCN這個參數的值給替換掉，在跟蹤過程當中發現Log4jLoggerAdapter最終都是調用的org.apache.log4j.Logger.log方法並將FQCN最爲參數傳入，所以org.apache.log4j.Logger這個類就是咱們要代理的類了。

瞭解JDK代理的人都知道，使用的條件是被代理類必須實現某一個接口，而org.apache.log4j.Logger.log這個方法並非來自於某一個接口，因此咱們選擇使用Cglib：

// cn.hjktech.slf4j.Logger
public class Logger {
    private static org.slf4j.Logger logger;
    private static final String FQCN = Logger.class.getName();

    static {
        try {
            Enhancer eh = new Enhancer();
            eh.setSuperclass(org.apache.log4j.Logger.class);
            eh.setCallbackType(LogInterceptor.class);
            Class c = eh.createClass();
            Enhancer.registerCallbacks(c, new LogInterceptor[]{new LogInterceptor()});
            Constructor<org.apache.log4j.Logger> constructor = c.getConstructor(String.class);
            org.apache.log4j.Logger loggerProxy= constructor.newInstance(Logger.class.getName());
            ...
        } catch (...) {
            throw new RuntimeException("初始化Logger失敗", e);
        }
    }

    private static class LogInterceptor implements MethodInterceptor {
        public Object intercept(Object o, Method method, Object[] objects, MethodProxy methodProxy) throws Throwable {
            // 只攔截log方法。
            if (objects.length != 4 || !method.getName().equals("log"))
                return methodProxy.invokeSuper(o, objects);
            // 替換傳給log方法的第一個參數爲咱們自定義的FQCN
            objects[0] = FQCN;
            return methodProxy.invokeSuper(o, objects);
        }
    }
}

代理defaultFactory

如今咱們已經有了被代理的loggerProxy對象了，咱們還須要將這個對象賦值給Log4jLoggerAdapter的logger成員變量，
logger成員變量是在Log4jLoggerAdapter的構造方法中被做爲參數傳入的，它的來源以下圖：

從上圖中能夠看到，LogManager.getLoggerRepository方法返回的對象中持有defaultFactory對象，所以我還須要代理這個對象，將它產生的'logger'對象替換成咱們的'logger'就大功告成了，而且makeNewLoggerInstance方法是在LoggerFactory接口中定義的，因此咱們只須要使用JDK的動態代理就能夠完成了。實現代碼以下：

static {
    try {
        ...
        LoggerRepository loggerRepository = LogManager.getLoggerRepository();
        org.apache.log4j.spi.LoggerFactory lf = ReflectionUtil.getFieldValue(loggerRepository, "defaultFactory");
        Object loggerFactoryProxy = Proxy.newProxyInstance(
            LoggerFactory.class.getClassLoader(),
            new Class[]{LoggerFactory.class},
            new NewLoggerHandler(loggerProxy)
        );

        ReflectionUtil.setFieldValue(loggerRepository, "defaultFactory", loggerFactoryProxy);
            logger = org.slf4j.LoggerFactory.getLogger(Logger.class.getName());
        ReflectionUtil.setFieldValue(loggerRepository, "defaultFactory", lf);
    } catch (...) {
        throw new RuntimeException("初始化Logger失敗", e);
    }
}

private static class NewLoggerHandler implements InvocationHandler {
    private final org.apache.log4j.Logger proxyLogger;

    public NewLoggerHandler(org.apache.log4j.Logger proxyLogger) {
        this.proxyLogger = proxyLogger;
    }

    @Override
    public Object invoke(Object proxy, Method method, Object[] args) throws Throwable {
        return proxyLogger;
    }
}

實現流程和最終代碼

咱們最終實現方案以下：

Logger的代碼以下:

public class Logger {
    private static org.slf4j.Logger logger;
    private static final String FQCN = Logger.class.getName();
    
    static {
        try {
            Enhancer eh = new Enhancer();
            eh.setSuperclass(org.apache.log4j.Logger.class);
            eh.setCallbackType(LogInterceptor.class);
            Class c = eh.createClass();
            Enhancer.registerCallbacks(c, new LogInterceptor[]{new LogInterceptor()});

            Constructor<org.apache.log4j.Logger> constructor = c.getConstructor(String.class);
            org.apache.log4j.Logger loggerProxy = constructor.newInstance(Logger.class.getName());

            LoggerRepository loggerRepository = LogManager.getLoggerRepository();
            org.apache.log4j.spi.LoggerFactory lf = ReflectionUtil.getFieldValue(loggerRepository, "defaultFactory");
            Object loggerFactoryProxy = Proxy.newProxyInstance(
                LoggerFactory.class.getClassLoader(),
                new Class[]{LoggerFactory.class},
                new NewLoggerHandler(loggerProxy)
            );

            ReflectionUtil.setFieldValue(loggerRepository, "defaultFactory", loggerFactoryProxy);
            logger = org.slf4j.LoggerFactory.getLogger(Logger.class.getName());
            ReflectionUtil.setFieldValue(loggerRepository, "defaultFactory", lf);
        } catch (
            IllegalAccessException |
                NoSuchMethodException |
                InvocationTargetException |
                InstantiationException e) {
            throw new RuntimeException("初始化Logger失敗", e);
        }
    }

    private static class LogInterceptor implements MethodInterceptor {
        public Object intercept(Object o, Method method, Object[] objects, MethodProxy methodProxy) throws Throwable {
            // 只攔截log方法。
            if (objects.length != 4 || !method.getName().equals("log"))
                return methodProxy.invokeSuper(o, objects);
            objects[0] = FQCN;
            return methodProxy.invokeSuper(o, objects);
        }
    }

    private static class NewLoggerHandler implements InvocationHandler {
        private final org.apache.log4j.Logger proxyLogger;

        public NewLoggerHandler(org.apache.log4j.Logger proxyLogger) {
            this.proxyLogger = proxyLogger;
        }

        @Override
        public Object invoke(Object proxy, Method method, Object[] args) throws Throwable {
            return proxyLogger;
        }
    }

    // 剩下的Logger須要封裝的方法能夠根據本身的須要來實現
    // 我我的認爲slf4j的api足夠好用了，因此大部分只是寫了一些相似下面的代碼
    public static void debug(String msg) {
        logger.debug(msg);
    }
}

ReflectionUtil的代碼以下：

public class ReflectionUtil {
    public static <T> T getFieldValue(@NotNull Object object,
                                      @NotNull String fullName) throws IllegalAccessException {
        return getFieldValue(object, fullName, false);
    }

    public static <T> T getFieldValue(@NotNull Object object,
                                      @NotNull String fieldName,
                                      boolean traceable) throws IllegalAccessException {
        Field field;
        String[] fieldNames = fieldName.split("\\.");
        for (String targetField : fieldNames) {
            field = searchField(object.getClass(), targetField, traceable);
            if (field == null)
                return null;

            object = getValue(object, field);
        }

        return (T) object;
    }

    private static Field searchField(Class c, String targetField, boolean traceable) {
        do {
            Field[] fields = c.getDeclaredFields();
            for (Field f : fields) {
                if (f.getName().equals(targetField)) {
                    return f;
                }
            }
            c = c.getSuperclass();
            traceable = traceable && c != Object.class;
        } while (traceable);

        return null;
    }

    private static <T> T getValue(Object target, Field field) throws IllegalAccessException {
        if (!field.isAccessible())
            field.setAccessible(true);
        return (T) field.get(target);
    }

    public static boolean setFieldValue(@NotNull Object target,
                                        @NotNull String fieldName,
                                        @NotNull Object value) throws IllegalAccessException {
        return setFieldValue(target, fieldName, value, false);
    }

    public static boolean setFieldValue(@NotNull Object target,
                                        @NotNull String fieldName,
                                        @NotNull Object value,
                                        boolean traceable) throws IllegalAccessException {
        Field field = searchField(target.getClass(), fieldName, traceable);
        if (field != null)
            return setValue(field, target, value);
        return false;
    }

    private static boolean setValue(Field field, Object target, Object value) throws IllegalAccessException {
        if (!field.isAccessible())
            field.setAccessible(true);
        field.set(target, value);
        return true;
    }
}

測試

public class TestLog {

    @Test
    public void logTest() {
        Logger.debug((Marker)null, "這是調用封裝的Logger輸出日誌");
        LoggerFactory.getLogger(TestLog.class).info("常規方法輸出日誌");
    }
}

輸出結果：

2016-10-19-15-00,308 DEBUG [cn.hjktech.slf4j.Logger] [main] (TestLog.java:13) TestLog.logTest(TestLog.java:13) - 這是調用封裝的Logger輸出日誌

2016-10-19-15-00,311 INFO [TestLog] [main] (TestLog.java:14) TestLog.logTest(TestLog.java:14) - 常規方法輸出日誌