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，类继承关系如下：
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、aliyun-sdk-mns、elasticsearch-rest-high-level-client等。
尝试仅保留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)
注意到日志里不仅打印了Mapped xxx信息，并且SpringApplication应用启动成功及启动耗时信息也在日志中展示了，可在日志系统搜关键字：JVM，能方便地查到应用是否启动成功。
启用成功日志如下：
2024-11-20 21:20:20.666 [INFO ] [main] com.xxx.XxxApplication:59 [TraceId:None] - Started XxxApplication in xxx seconds (JVM running for xxx)
总结
-
在进行SpringBoot项目框架搭建时，要注意包冲突的问题，特别是依赖的三方包下的传递依赖
-
spring-jcl是Spring框架对jcl的增强，它在spring-core下，和commons-logging包名相同，如果同时有可考虑排除commons-logging依赖 -
spring-webmvc老版本有info级别打印handler mapping日志信息，新版本里代码有变动，其中打印mapping信息的日志级别是trace
补充1
-
日志框架门面接口：slf4j(simple logging facade for java)、jcl(jakarta commons logging)
-
日志框架实现：jul(java.util.logging)、log4j、log4j2、logback
-
日志框架桥接：log4j-to-slf4j、jcl-over-slf4j
补充 2
在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);
});
}
private String formatMappings(Class<?> userType, Map<Method, T> methods) {
String formattedType = Arrays.stream(ClassUtils.getPackageName(userType).split("\\."))
.map(p -> p.substring(0, 1))
.collect(Collectors.joining(".", "", "." + userType.getSimpleName()));
Function<Method, String> methodFormatter = method -> Arrays.stream(method.getParameterTypes())
.map(Class::getSimpleName)
.collect(Collectors.joining(",", "(", ")"));
return methods.entrySet().stream()
.map(e -> {
Method method = e.getKey();
return e.getValue() + ": " + method.getName() + methodFormatter.apply(method);
})
.collect(Collectors.joining("\n\t", "\n\t" + formattedType + ":" + "\n\t", ""));
}
可以看到新版本将mapping信息按handler分组进行了日志打印，日志级别为trace。
如果需要日志里看到，可修改日志级别：
<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等，可考虑将其展示出来。
浙公网安备 33010602011771号