封装SLF4J/Log4j,不再处处定义logger变量
发表时间 2016-10-19  |  浏览量:  |  分类: Java

转载请注明出处: 封装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就大功告成了。fqnOfCallingClassLoggingEvent.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对象了,我们还需要将这个对象赋值给Log4jLoggerAdapterlogger成员变量,
logger成员变量是在Log4jLoggerAdapter的构造方法中被作为参数传入的,它的来源如下图:

Logger产生流程

从上图中可以看到,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) - 常规方法输出日志

关闭

分类

Java 算法 Linux Git Go Feign Hystrix

标签

Java 字符串 算法 kmp Linux VPS VPN 系统界面 Git Socks5 Go json 网络 面试 后端开发 翻译 Feign Spring Cloud 日志 log4j slf4j Hystrix