封裝SLF4J/Log4j,不再處處定義logger變量
自從開始使用日志組件后, 每個類都是這樣子的結構:
- 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) - 常規方法輸出日志