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日志信息，新版本里代码修改，并且日志级别是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等，可考虑在开发环境展示日志。