封装SLF4J/Log4j，不再处处定义logger变量-log4j-to-slf4j

自从开始使用日志组件后，每个类都是这样子的结构:

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

这是一件相当烦人事，必须对他进行封装，使得我们能够通过这样的方法来调用：

public class A { 
    public void methodA() { 
        Logger.debug("Nice!"); 
    } 
}  
1.
2.
3.
4.
5.

最简单的版本

开始动手后，用最简单的方法封装出了***个版本:

// cn.hjktech.slf4j.Logger 
public class Logger { 
    private static final org.slf4j.Logger logger = LoggerFactory.getLogger(Logger.class);; 
    ... 
    public static void debug(...) { 
        logger.debug(...); 
        ... 
    } 
    ... 
}  
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.

看起来很美好，但测试后发现这种方法会有一个很严重的问题：我们打印的日志通畅都带有调用方的信息，如类名、方法名、行数、时间等，其中类名、方法名、行数都是极其关键的信息，但是使用上述的方法来输出日志的话，这三个信息都变成Logger这个类的信息，而不是调用方的信息，这显然是无法忍受的事。

当然不能就这样了事，既然正常使用的方法能输出正确的信息，那么肯定是有办法可以实现的，我们希望最终的结果是调用Logger.debug(..)打印出来的信息都是完全正确的。

分析源码

此时写个demo来debug跟进一下：

public class TestLog { 
    @Test 
    public void logTest() { 
        // 在此处打断点 
        LoggerFactory.getLogger(TestLog.class).debug("看看执行流程"); 
    } 
}  
1.
2.
3.
4.
5.
6.
7.

发现最终输出的日志字符串是在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(); 
}  
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.

其中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 
1.

那么这个链表的结构就是(括号中代表存储的信息):

DatePatternConverter(时间点)           -> LiteralPatternConverter(" ")   ->  
BasicPatternConverter(LEVEL)          -> LiteralPatternConverter("[")   ->  
CategoryPatternConverter(LoggerName)  -> LiteralPatternConverter("] [") ->  
BasicPatternConverter(线程名)          -> LiteralPatternConverter("] (") -> 
LocationPatternConverter(所在类)       -> LiteralPatternConverter(":")   ->  
LocationPatternConverter(所在行)       -> LiteralPatternConverter(") -") ->  
BasicPatternConverter(日志串)          -> LiteralPatternConverter("\n")  ->  
1.
2.
3.
4.
5.
6.
7.

根据这个链表生成日志字符串类似这样:

2016-10-17-13-42,449 DEBUG [TestLog] [main] (TestLog.java:14) - Excuse me? 
1.

那么现在目标很明确了，我们要使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; 
}  
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.
22.
23.
24.
25.
26.
27.
28.
29.
30.
31.
32.
33.
34.
35.
36.
37.
38.
39.
40.

其中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(); 
    ... 
}  
1.
2.
3.
4.
5.

而如果没有配合SLF4J使用时，fqnOfCallingClass的值则来源于org.apache.log4j.Logger类：

public class Logger extends Category { 
    ... 
    private static final String FQCN = Logger.class.getName(); 
    .... 
}  
1.
2.
3.
4.
5.

代理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); 
        } 
    } 
}  
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.
22.
23.
24.
25.
26.
27.
28.
29.
30.
31.

代理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; 
    } 
}  
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.
22.
23.
24.
25.
26.
27.
28.
29.
30.
31.

实现流程和最终代码

我们最终实现方案如下：

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); 
    } 
}  
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.
22.
23.
24.
25.
26.
27.
28.
29.
30.
31.
32.
33.
34.
35.
36.
37.
38.
39.
40.
41.
42.
43.
44.
45.
46.
47.
48.
49.
50.
51.
52.
53.
54.
55.
56.
57.
58.
59.
60.
61.
62.
63.
64.

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; 
    } 
}  
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.
22.
23.
24.
25.
26.
27.
28.
29.
30.
31.
32.
33.
34.
35.
36.
37.
38.
39.
40.
41.
42.
43.
44.
45.
46.
47.
48.
49.
50.
51.
52.
53.
54.
55.
56.
57.
58.
59.
60.
61.
62.
63.
64.
65.
66.

测试

public class TestLog { 
 
    @Test 
    public void logTest() { 
        Logger.debug((Marker)null, "这是调用封装的Logger输出日志"); 
        LoggerFactory.getLogger(TestLog.class).info("常规方法输出日志"); 
    } 
}  
1.
2.
3.
4.
5.
6.
7.
8.

输出结果：

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) - 常规方法输出日志  
1.
2.