Spring5新特性的LOG系统和Spring5.2.8的LOG部分的更新

前言

上篇博客【JAVA的日志体系的部分补缺】说了下Java上的原生Log系统，最近刚好在研究Spring5的源码，于是顺便把这个研究了下。尤其是网上关于Spring5新特性的博客质量也是参差不齐，就写一篇帖子总结一下Spring5 Log系统是怎么运作的。更多Spring内容进入【Spring解读系列目录】。

打印日志

为了说明区别我们还是要做个例子打印一下Spring初始化的日志输出，作为一个参照。下面使用的是Spring 5.0.4版本，为什么用老版本，后面介绍新版本的时候会说。

public class MainTest {
    public static void main(String[] args) {
        AnnotationConfigApplicationContext anno=new AnnotationConfigApplicationContext(AppConfig.class);
        anno.start();
    }
}
运行结果，出现的是JUL打印结果：
Sep 22, 2020 2:14:39 PM org.springframework.context.support.AbstractApplicationContext prepareRefresh
INFO: Refreshing org.springframework.context.annotation.AnnotationConfigApplicationContext@4ccabbaa: startup date [Tue Sep 22 14:14:39 CST 2020]; root of context hierarchy

Spring4

我们知道Spring4中采取的是原生JCL的LOG打印，位置如下。是在启动的时候调用构造方法进行实例化的。但是JCL方式其实只有两个内置的实现LOG。没有很强的扩展性，因此Spring5就把LOG实现方式修改了。

public AbstractApplicationContext() {
    /**
     * 典型的JCL获取方式，另外一个力证就是这个logger对象是在
     *  org.apache.commons.logging包下，因此JCL跑不掉了。
     *  但是神奇是的Spring5在同样的地方，同样的代码却得到了
     *  不一样的结果。即便引入了Log4J，Spring还是我行我素的
     *  使用JUL去打印。
     */
    this.logger = LogFactory.getLog(this.getClass());
    ......
}

原生的JCL

我们之前分析过JCL的源码之所以能够进行选择，是因为使用了for循环遍历一个预先存放了类名的数组实现的，做到了找到哪个用哪个（源码解析参考【JAVA的日志体系的部分补缺】）。但是Spring5这里明显已经修改了这个逻辑。

Spring5的JCL

既然猜测修改了内容，那么我就进去看下修改了什么进入getLog()方法。

public static Log getLog(Class<?> clazz) {
    return getLog(clazz.getName());
}

发现这是个套子，接着进去getLog()。

public static Log getLog(String name) {
    switch(logApi) {
    case LOG4J:
        return LogFactory.Log4jDelegate.createLog(name);
    case SLF4J_LAL:
        return LogFactory.Slf4jDelegate.createLocationAwareLog(name);
    case SLF4J:
        return LogFactory.Slf4jDelegate.createLog(name);
    default:
        return LogFactory.JavaUtilDelegate.createLog(name);
    }
}

发现这个getLog()已经被改的面目全非了。由于有了一个switch语句，每次初始化Spring都会把logApi这个匹配参数这是为JUL，也导致了Spring的log一直在走default这的逻辑，对Log的打印使用JUL的实现。所以可以说Spring5中的日志打印系统就是JUL。如果想要修改Spring5的系统打印格式，只有从logApi这里下手，我们先看看这是个啥。

// 声明
private static LogFactory.LogApi logApi;
//发现是一个enum
private static enum LogApi {
    LOG4J,
    SLF4J_LAL,
    SLF4J,
    JUL;
    private LogApi() {
    }
}

发现这里只是一个enum，完全无法修改。那么只能交给Spring去处理，难道就没有办法修改了吗？其实有办法的，只要打开case LOG4J里的逻辑，也就是LogFactory.Log4jDelegate.createLog(name);就会发现Spring5中默认使用的Log4J其实是Log4J2的包，而不是Log4J。想要验证这点其实很简单，可以在maven中加入Log4J的依赖，如果这里报错那就一定引入错了。如果引入Log4J2就不报错了，那就说明引入的依赖没有问题。

//这里引入的是Log4j 2.x的包
import org.apache.logging.log4j.spi.ExtendedLogger;
import org.apache.logging.log4j.spi.LoggerContext;

private static final LoggerContext loggerContext = LogManager.getContext(LogFactory.Log4jLog.class.getClassLoader(), false);
private final ExtendedLogger logger;

public Log4jLog(String name) {
    this.logger = loggerContext.getLogger(name);
}

修改LogApi

那么我们怎么才能改变这个默认值呢？还是在LogFactory这个类里面有一个static块。

static {
    logApi = LogFactory.LogApi.JUL;
    ClassLoader cl = LogFactory.class.getClassLoader();
    try {
	 	//Try Log4j 2.x API  这里是源码注释，使用了Log4j 2.x
        cl.loadClass("org.apache.logging.log4j.spi.ExtendedLogger");
        logApi = LogFactory.LogApi.LOG4J;
    } catch (ClassNotFoundException var6) {
        try {
            cl.loadClass("org.slf4j.spi.LocationAwareLogger");
            logApi = LogFactory.LogApi.SLF4J_LAL;
        } catch (ClassNotFoundException var5) {
            try {
                cl.loadClass("org.slf4j.Logger");
                logApi = LogFactory.LogApi.SLF4J;
            } catch (ClassNotFoundException var4) {
            }
        }
    }
}

看到这里就很清楚了。在加载静态数据的时候Spring会对Log4J2的类进行加载，如果加载不到。报错，在catch中继续加载SLF4J_LAL，如果还加载不到。接着报错，加载SLF4J，如果还加载不到，那就用默认值JUL了。而且这里官方注释也写清楚了Spring的Log4J是2.x。所以其实Spring-JCL和原始JCL看起来是换汤不换药，都是通过写死的类去加载。

所以想用Log4J就有两种方式:

1. 引入Log4J 2并且配置好log4j2-test.properties文件：

<dependency>
  <groupId>org.apache.logging.log4j</groupId>
  <artifactId>log4j-api</artifactId>
  <version>2.11.2</version>
</dependency>
<dependency>
  <groupId>org.apache.logging.log4j</groupId>
  <artifactId>log4j-core</artifactId>
  <version>2.11.2</version>
</dependency>

log4j2-test.properties：
rootLogger.level = info
rootLogger.appenderRef.stdout.ref = STDOUT
appender.console.type = Console
appender.console.name = STDOUT
appender.console.layout.type = PatternLayout
appender.console.layout.pattern = %m%n

打印测试，修改Spring系统使用Log4J 2
Refreshing org.springframework.context.annotation.AnnotationConfigApplicationContext@f4168b8: startup date [Tue Sep 22 13:54:43 CST 2020]; root of context hierarchy

2. 通过SLF4J引入Log4J：

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

打印测试，修改Spring系统使用SLF4J引入Log4J
2020-09-22 13:57:45,209 INFO [org.springframework.context.annotation.AnnotationConfigApplicationContext] - Refreshing org.springframework.context.annotation.AnnotationConfigApplicationContext@ed17bee: startup date [Tue Sep 22 13:57:45 CST 2020]; root of context hierarchy

Spring5.2.8的LOG部分的更新

以上代码是在Spring 5.0.4版本基础上讲解的，为什么要分开呢？因为Spring公司在新的版本中又变卦了，如果使用Spring5.2.8作为输出，什么都打印不出来，这是为什么呢？因为Spring最新版本中Log打印的逻辑被更新了：

Spring5.2.8
protected void prepareRefresh() {
   ......
   if (logger.isDebugEnabled()) {
      if (logger.isTraceEnabled()) {
         logger.trace("Refreshing " + this);
      }
      else {
         logger.debug("Refreshing " + getDisplayName());
      }
   }
   ......
}
Spring 5.0.4
protected void prepareRefresh() {
    ......
    if (this.logger.isInfoEnabled()) {
        this.logger.info("Refreshing " + this);
    }
    ......
}

笔者把这里源码的对比贴出来了，在5.0.4版本中只要是info就可以被打印，但是在5.2.8版本中只有被trace或者debug的情况下才会被打印出来，这就是和为什么会选择低版本进行演示的原因。但是同样也能从Spring4->Spring5.0.x->Spring5.2.x这一系列的不同版本看出Spring的演进。

Spring5.2.8的LOG打印

知道了这点，怎么打印也相当简单了，引入必要的包，然后设置一下打印级别为Debug就可以了，这里只举一个例子。

<!--Log4J API-->
<dependency>
  <groupId>org.slf4j</groupId>
  <artifactId>slf4j-api</artifactId>
  <version>1.7.30</version>
</dependency>
<dependency>
  <groupId>org.slf4j</groupId>
  <artifactId>slf4j-log4j12</artifactId>
  <version>1.7.30</version>
</dependency>

log4j.properties
log4j.rootLogger=DEBUG, stdout
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.Target = System.out
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%d %p [%c] - %m%n

运行输出：
2020-09-22 14:28:38,710 DEBUG [org.springframework.context.annotation.AnnotationConfigApplicationContext] - Refreshing org.springframework.context.annotation.AnnotationConfigApplicationContext@7fbe847c
2020-09-22 14:28:38,776 DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] - Creating shared instance of singleton bean 'org.springframework.context.annotation.internalConfigurationAnnotationProcessor'
2020-09-22 14:28:39,326 DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] - Creating shared instance of singleton bean 'org.springframework.context.event.internalEventListenerProcessor'
2020-09-22 14:28:39,347 DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] - Creating shared instance of singleton bean 'org.springframework.context.event.internalEventListenerFactory'
2020-09-22 14:28:39,361 DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] - Creating shared instance of singleton bean 'org.springframework.context.annotation.internalAutowiredAnnotationProcessor'
2020-09-22 14:28:39,365 DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] - Creating shared instance of singleton bean 'org.springframework.context.annotation.internalCommonAnnotationProcessor'
2020-09-22 14:28:39,380 DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] - Creating shared instance of singleton bean 'appConfig'

总结

总结一下Spring4和Spring5在日志逻辑上的区别：

• Spring4：使用了一个内置数组，然后for循环其中的类名，发现类名可用，就加载出来然后使用。虽然有四个但是由于第二个就是JUL14，因此其实只有Log4J和JUL两个作为LOG的备选使用。

• Spring5：使用static预先处理每一个可能的类型，一旦发现ClassLoader能够加载就更新LogApi的值，然后使用switch对LogApi的值进行匹配，匹配到哪个用哪个。如果都不匹配使用默认的加载类JUL打印日志。