SpringBoot项目框架搭建日志相关容易被忽视的细节

问题

项目A、B，都基于SpringBoot技术栈开发。
发现其中项目A在本地IDE启动时控制台会打印spring-webmvc里@Controller的mapping映射信息，其中一行如下：

2024-11-20 21:10:12  [ main:76835 ] - [ INFO ] org.springframework.web.servlet.handler.AbstractHandlerMethodMapping$MappingRegistry.register(AbstractHandlerMethodMapping.java:547) Mapped "{[/openapi/xxx/xxx],methods=[POST]}" onto public com.xxx.JsonResult<com.xxx.vo.resp.XxxRespVo> com.xxx.XxxOpenApi.xxx(com.xxx.vo.req.XxxReqVo)

而项目B的控制台却没有，是什么原因？

项目A在本地控制台有该日志信息，而在测试环境、生产环境的日志文件、阿里云日志收集里却找不到相关的mapping映射信息；
这又是什么原因呢？

注：项目里配置了3个日志appender：
ch.qos.logback.core.ConsoleAppender // 日志输出到控制台，本地IDE使用
ch.qos.logback.core.rolling.RollingFileAppender //日志输出到文件，测试、生产环境使用
com.aliyun.openservices.log.logback.LoghubAppender // 日志输出到阿里云的Loghub，测试、生产环境使用

分析&解决

项目A和B都通过logback-spring.xml来进行日志相关参数配置，
其中日志输出格式配置如下：

<property name="console.pattern" value="%d{yyyy-MM-dd HH:mm:ss.SSS} [%-5level] [%t] %logger{36}:%line [TraceId:%X{X-B3-TraceId:-None}] - %msg%n"/>
<property name="aliLogHub.encoder.pattern" value="%d{yyyy-MM-dd HH:mm:ss.SSS} [%-5level] [%t] %logger{36}:%line [TraceId:%X{X-B3-TraceId:-None}] - %msg%n"/>

检查日志配置除了应用名、文件目录相关，其它配置是一致的。

注意到一个细节：本地控制台输出的@Controller的mapping映射信息日志格式，跟配置的日志格式不同。
如配置时间是到毫秒，而只打印到了秒，2024-11-20 20:10:12，后面的格式也不匹配。

接着检查项目的依赖，发现两个项目spring-boot版本不同,
项目A版本号是2.0.4.RELEASE，项目B版本号是2.3.12.RELEASE。

spring-boot-starer-web的2.0.4.RELEASE版本，它依赖的spring-webmvc版本是5.0.8.RELEASE；
spring-boot-starer-web的2.3.12.RELEASE版本，它依赖的spring-webmvc版本是5.2.15.RELEASE；

在项目A里，spring-webmvc版本5.0.8.RELEASE，根据控制台打印的日志信息，找到相关的类，梳理类继承关系如下：
RequestMappingHandlerMapping->RequestMappingInfoHandlerMapping->AbstractHandlerMethodMapping->AbstractHandlerMapping
->WebApplicationObjectSupport->ApplicationObjectSupport
可以看到类的继承层级很多。

其中RequestMappingHandlerMapping类实现了InitializingBean接口，在afterPropertiesSet方法里，

@Override
@SuppressWarnings("deprecation")
public void afterPropertiesSet() {
    this.config = new RequestMappingInfo.BuilderConfiguration();
    this.config.setUrlPathHelper(getUrlPathHelper());
    this.config.setPathMatcher(getPathMatcher());
    this.config.setSuffixPatternMatch(useSuffixPatternMatch());
    this.config.setTrailingSlashMatch(useTrailingSlashMatch());
    this.config.setRegisteredSuffixPatternMatch(useRegisteredSuffixPatternMatch());
    this.config.setContentNegotiationManager(getContentNegotiationManager());

    super.afterPropertiesSet();
}

调用了父类AbstractHandlerMethodMapping的afterPropertiesSet()方法：

@Override
public void afterPropertiesSet() {
    initHandlerMethods();
}

依次找到调用链路：
initHandlerMethods->detectHandlerMethods->registerHandlerMethod->MappingRegistry#register

找到了日志打印的地方：

public void register(T mapping, Object handler, Method method) {
    this.readWriteLock.writeLock().lock();
    try {
        HandlerMethod handlerMethod = createHandlerMethod(handler, method);
        assertUniqueMethodMapping(handlerMethod, mapping);

        if (logger.isInfoEnabled()) {
            logger.info("Mapped \"" + mapping + "\" onto " + handlerMethod);
        }
        this.mappingLookup.put(mapping, handlerMethod);
    ...
   }
   ...
}

注意到这里的日志打印级别是info。

而在项目B里，spring-webmvc版本5.2.15.RELEASE，
调用链路如下：
initHandlerMethods->processCandidateBean->detectHandlerMethods->registerHandlerMethod->MappingRegistry#register
多了一个方法processCandidateBean，推测是重构时封装了方法，这里区别不大。

在MappingRegistry#register方法里：

public void register(T mapping, Object handler, Method method) {
    // Assert that the handler method is not a suspending one.
    if (KotlinDetector.isKotlinType(method.getDeclaringClass())) {
        Class<?>[] parameterTypes = method.getParameterTypes();
        if ((parameterTypes.length > 0) && "kotlin.coroutines.Continuation".equals(parameterTypes[parameterTypes.length - 1].getName())) {
            throw new IllegalStateException("Unsupported suspending handler method detected: " + method);
        }
    }
    this.readWriteLock.writeLock().lock();
    try {
        HandlerMethod handlerMethod = createHandlerMethod(handler, method);
        validateMethodMapping(handlerMethod, mapping);
        this.mappingLookup.put(mapping, handlerMethod);
    
        List<String> directUrls = getDirectUrls(mapping);
        for (String url : directUrls) {
            this.urlLookup.add(url, mapping);
    } ....
    ...

注意到在this.mappingLookup.put(mapping, handlerMethod);上面的mapping日志打印代码没有了。

因此解答了第1个问题，@Controller的mapping映射信息在1个项目里有日志打印，另1个项目里没有，
=>2个项目spring-boot版本不同，依赖的的spring-webmvc版本不同，新版本里去掉了日志打印。

接着来看第2个问题，项目A本地控制台有mapping日志信息，为什么日志文件里和阿里云日志里却没有？

回想刚发现的一个细节，mapping映射信息日志的格式，跟项目里logback配置的日志格式不同，
推测这里的logger不一样，在代码里找到logger定义如下：

import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
...
public abstract class ApplicationObjectSupport implements ApplicationContextAware {
	/** Logger that is available to subclasses */
	protected final Log logger = LogFactory.getLog(getClass());
    ...
}

logger是在父类定义的，注意到它的类型是org.apache.commons.logging.Log，通过org.apache.commons.logging.LogFactory创建。

在项目A、B里，使用的是slf4j的logger，也是目前项目开发经常用到的。

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

private Logger logger = LoggerFactory.getLogger(Xxx.class);

或

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

private Logger logger = LoggerFactory.getLogger(getClass());

或用lombok的@Slf4j注解:

import lombok.extern.slf4j.Slf4j;

@Slf4j
public class Xxx {
  ...
}

由于项目的logback-spring.xml里配置了文件和阿里云的log appender，因此项目里打印的日志输出到了文件和阿里云日志存储。
而Spring框架里使用org.apache.commons.logging.Log，这是个日志门面接口，推测它实现类不是logback，
没用到logback里配置的log appender，因此日志仅打印到控制台；
这里解答了第2个问题。

在ApplicationObjectSupport类，在IDEA里通过LogFactory.getLog(getClass())点进去看：
跳转到LogFactory类里的方法：

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

注意到，类的jar显示是spring-jcl-5.0.8.RELEASE-sources.jar，而类的package是package org.apache.commons.logging;

尝试在return getLog(clazz.getName())这一行打个断点，然后启动项目，发现IDEA在断点左边有个红色的x提示，光标指上去没有任何提示，并且断点并未走到。

想到可能有类冲突，于是换一种方式，Ctrl+N搜索LogFactory类，有多个结果：

spirng-jcl 5.0.8.release
tomcat-embed-core 8.5.32
commons-logging 1.1.3
mybatis 3.5.0
hutool-all 5.6.5
...

其中跟源码里package(org.apache.commons.logging)相同的除了spirng-jcljar包，还有commons-loggingjar包，版本是1.1.3。

打开commons-logging里的LogFactory类：

public static Log getLog(Class clazz) throws LogConfigurationException {
    return getFactory().getInstance(clazz);
}

在getLog(Class clazz)的方法里return getFactory().getInstance(clazz);这一行打上断点，然后启动项目，发现程序进到了断点；
由于LogFactory是个抽象类，getInstance(clazz)方法是抽象的，在它的实现类LogFactoryImpl里打断点跟踪代码，
层层跟踪调试后，发现在discoverLogImplementation方法里，是通过classesToDiscover预先设置的实现类来创建logger实例的，
定义如下：

private static final String LOGGING_IMPL_LOG4J_LOGGER = "org.apache.commons.logging.impl.Log4JLogger";
...
private static final String[] classesToDiscover = {
        LOGGING_IMPL_LOG4J_LOGGER,
        "org.apache.commons.logging.impl.Jdk14Logger",
        "org.apache.commons.logging.impl.Jdk13LumberjackLogger",
        "org.apache.commons.logging.impl.SimpleLog"
};

可以看到里面有4个实现类，定义了实现类的全路径，没有logback，第1个是Log4JLogger。

在IDEA里通过Maven Helper插件，查看项目的pom.xml，发现项目里同时有spring-jcl、commons-logging依赖，
其中spring-jcl是spring-core下的，而commons-logging在多个依赖包下有，如：
aliyun-log-logback-appender、elasticsearch-rest-high-level-client、aliyun-sdk-mns等。

尝试仅保留spring-jcl，把commons-logging依赖排除掉：

<!-- 阿里日志相关配置 -->
<dependency>
    <groupId>com.aliyun.openservices</groupId>
    <artifactId>aliyun-log-logback-appender</artifactId>
        <exclusions>
            <exclusion>
                <artifactId>commons-logging</artifactId>
                <groupId>commons-logging</groupId>
            </exclusion>
        </exclusions>
</dependency>

修改pom.xml后重启项目A，观察mapping日志信息输出格式跟logback-spring.xml一致了。

2024-11-20 21:13:14.520 [INFO ] [main] o.s.w.s.m.m.a.RequestMappingHandlerMapping:547  [TraceId:None] - Mapped "{[/openapi/xxx/xxx],methods=[POST]}" onto public com.xxx.JsonResult<com.xxx.vo.resp.XxxRespVo> com.xxx.XxxOpenApi.xxx(com.xxx.vo.req.XxxReqVo)

总结

• 在基于SpringBoot项目框架搭建时，要注意日志报冲突的问题，如spring-jcl和commons-logging，可考虑排除commons-logging依赖

• spring-webmvc老版本有info级别打印handler mapping日志信息，新版本里代码有变动，其中打印mapping信息的日志级别是trace

补充

在spring-webmvc的5.2.15.RELEASE版本里，查看源码发现，mapping信息也有日志打印，只是换了一个地方，并且日志级别是trace。

protected void detectHandlerMethods(Object handler) {
    ...
    if (logger.isTraceEnabled()) {
        logger.trace(formatMappings(userType, methods));
    }
    methods.forEach((method, mapping) -> {
        Method invocableMethod = AopUtils.selectInvocableMethod(method, userType);
        registerHandlerMethod(handler, invocableMethod, mapping);
    });
}

如果需要日志里看到，可修改日志级别：

<logger level="TRACE" name="org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerMapping">
    <appender-ref ref="ASYNC_STDOUT"/>
</logger>

注：如果项目里定制了RequestMappingHandlerMapping，如Xxx extends RequestMappingHandlerMapping，那么logger里的name要改为自定义的类名Xxx

个人觉得spring-webmvc的handler mapping日志是很有用的信息，能直观的看到项目暴露了哪些HTTP API，
包括项目里开发的Controller、spring-boot actuator、Swagger API等，可考虑在开发环境展示日志。