spring启动时如何自定义日志实现

一、现象

最近在编写传统的springmvc项目时，遇到了一个问题：虽然在项目的web.xml中指定了log4j的日志启动监听器Log4jServletContextListener，且开启了日志写入文件，但是日志文件中只记录业务代码中我们声明了日志记录器的日志，无法记录spring上下文启动的日志。

测试方法如下:

package com.vat;
import org.junit.Test;
import org.junit.runner.RunWith;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.context.ApplicationContext;
import org.springframework.test.context.ContextConfiguration;
import org.springframework.test.context.junit4.SpringJUnit4ClassRunner;


/**
 * @author:whh
 * @date: 2024-02-01 21:02
 * <p></p>
 */
@RunWith(SpringJUnit4ClassRunner.class)
@ContextConfiguration(locations = {"classpath:applicationcontext.xml"})
public class MvcTest {
    @Autowired
    ApplicationContext ctx;
    private static Logger LOGGER  = LoggerFactory.getLogger(MvcTest.class);
    @Test
    public void fun(){
        LOGGER.debug("123");
        System.out.println(ctx);
    }
}

观察下面的运行结果截图，我们发现红色字体是spring上下文的启动日志而灰色字体是我们打印的日志，而且在日志文件中也只记录了我们打印的日志和druid数据源的关闭日志。实时上spring上下文的启动日志也非常重要，通常用于我们观察我们的应用是否启动正常，有没有一些bean没有被spring初始化到。但是从上面看其启动日志并未记录到日志文件中。

二、思考

遇到这个问题后，便使用debug模式追踪spring上下文的启动。

首先这个测试类有一个注解@RunWith(SpringJUnit4ClassRunner.class)
即我们可以猜测是通过SpringJUnit4ClassRunner来启动spring上下文的，接着我们看下这个类的源码。

public class SpringJUnit4ClassRunner extends BlockJUnit4ClassRunner {

	private static final Log logger = LogFactory.getLog(SpringJUnit4ClassRunner.class);

	private static final Method withRulesMethod;

	// Used by RunAfterTestClassCallbacks and RunAfterTestMethodCallbacks
	private static final String MULTIPLE_FAILURE_EXCEPTION_CLASS_NAME = "org.junit.runners.model.MultipleFailureException";

	static {
		boolean junit4dot9Present = ClassUtils.isPresent(MULTIPLE_FAILURE_EXCEPTION_CLASS_NAME,
			SpringJUnit4ClassRunner.class.getClassLoader());
		if (!junit4dot9Present) {
			throw new IllegalStateException(String.format(
				"Failed to find class [%s]: SpringJUnit4ClassRunner requires JUnit 4.9 or higher.",
				MULTIPLE_FAILURE_EXCEPTION_CLASS_NAME));
		}

注意看第一行是使用静态常量初始化了一个logger对象并且这个Log的类型是org.apache.commons.logging.Log类型，学过类加载的我们都知道，静态常量是在编译器就会进行初始化。

接着进入getFactory方法，首先会获取一个类加载器，我们可以看出是
lanucherAppClassLoader。

接着往下走会往缓存中获取LogFactory，第一次肯定是null的。

接下来加载commons-logging.properties的配置文件，但是咱们没有配置，所以是空的。

最终创建了一个默认的LogFactoryImpl。

调用的LogFactoryImpl来创建Log

后面到discoverLogImplementation方法，确定具体的日志实现。

private Log discoverLogImplementation(String logCategory)
        throws LogConfigurationException {
        if (isDiagnosticsEnabled()) {
            logDiagnostic("Discovering a Log implementation...");
        }

        initConfiguration();

        Log result = null;

        // See if the user specified the Log implementation to use
        String specifiedLogClassName = findUserSpecifiedLogClassName();

        if (specifiedLogClassName != null) {
            if (isDiagnosticsEnabled()) {
                logDiagnostic("Attempting to load user-specified log class '" +
                    specifiedLogClassName + "'...");
            }

            result = createLogFromClass(specifiedLogClassName,
                                        logCategory,
                                        true);
            if (result == null) {
                StringBuffer messageBuffer =  new StringBuffer("User-specified log class '");
                messageBuffer.append(specifiedLogClassName);
                messageBuffer.append("' cannot be found or is not useable.");

                // Mistyping or misspelling names is a common fault.
                // Construct a good error message, if we can
                informUponSimilarName(messageBuffer, specifiedLogClassName, LOGGING_IMPL_LOG4J_LOGGER);
                informUponSimilarName(messageBuffer, specifiedLogClassName, LOGGING_IMPL_JDK14_LOGGER);
                informUponSimilarName(messageBuffer, specifiedLogClassName, LOGGING_IMPL_LUMBERJACK_LOGGER);
                informUponSimilarName(messageBuffer, specifiedLogClassName, LOGGING_IMPL_SIMPLE_LOGGER);
                throw new LogConfigurationException(messageBuffer.toString());
            }

            return result;
        }

最终确定为jdk的日志实现。

由于spring也是使用的org.apache.commons.logging.Log作为日志适配器，，所以会使用缓存的日志工厂LogFactoryImpl，即其日志实现也是jdk的日志，，所以和咱们自己配置log4j实现根本无关也就造成了spring上下文的日志未写入文件。

三、问题解决

怎么解决这个问题呢？这边有两个方案。
方案1：刚刚我们在调试模式模式的时，实例化LogFatory时会加载一个commons-logging.properties然后在该配置文件中加入属性
org.apache.commons.logging.LogFactory=XXX，其中XXX是自定义的LogFactory，然后在该LogFactory中指定日志的实现，但是这种方式还是有些复杂的。

方案2：使用spring的jcl方案，其实这个jcl方案是我参考了springboot启动时的日志实现原理，所以咱们只要引入下面的依赖，版本可以看实际情况，本项目的spring版本为4.2.4。

 <dependency>
      <groupId>org.springframework</groupId>
      <artifactId>spring-jcl</artifactId>
      <version>5.3.5</version>
    </dependency>

其原理是基于spi机制，通过LogAdapter进行检测具体的日志实现。

LogAdapter的static静态代码块会确定具体的日志实现。

四、结果

集成spring jcl后，咱么在启动测试类，观察结果返现控制台即文件输出日志都换成了咱们指定的log4j日志实现。

而且咱们使用jetty的maven插件，启动咱们的项目，也是有相同效果的。

五、最后

完整项目，大家可以到我的码云自行下载：

https://gitee.com/whhdev/vat/tree/master