个人在 Spring 应用下切面日志实践分享
前言
最近参与了几个项目的开发,感觉日志系统有点杂乱无章:有用 info
的有用 error
的,也有所有信息输出在单一文件里的
也可能是每个人排查错误的方式有差异,我个人比较习惯的一套日志记录的最佳实践原则大体如下:
info
级别我理解是提示,标记
,通常我习惯拿来输出一些调试过程中的参数、结果、提示语信息,更严格的情况下上述信息也可以调整为debug
级别warn
级别习惯拿来输出一些不影响程序运行但可能有风险或者可能与预期业务运行不同的信息error
级别输出确实阻碍系统运行或者业务上错误的结果,比如抛出的异常信息- 一个全局
info
级别的文件(比如application.log
)来记录程序运行中所有的info
(及以上)信息,该文件的主要用途是个人在非本地环境下调试时,在全局文件下方便查看自己的输出标识(一般调试完后会移除相关输出代码) - 一个全局
error
级别的文件(比如error.log
)来记录所有程序中的error
信息,该文件主要是总览所有报错信息,方便快速定位异常、做相关预警操作等 - 个人习惯以层级维度划分日志文件来记录该层级下所有的
info
(及以上)信息,比如controller(web)
service
层,这样排查错误更具有针对性,可以层层递推排查问题,该部分的实现通常依托于Spring AOP
分享一份个人 demo
,该 demo
基于 SpringBoot + Logback(默认)
实现,通过 Logback
配置 + Spring AOP
完成日志的记录
logback-spring.xml
先贴一份 logback
配置,相对通用可用作参考,定义了最佳实践中提到一些常规的 Logger
比如 CONSOLE
application
error
controller
service
,详情如下
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<include resource="org/springframework/boot/logging/logback/defaults.xml"/>
<springProperty scope="context" name="springAppName" source="spring.application.name"/>
<!-- spring cloud sleuth 下适用 -->
<property name="PATTERN"
value="%clr(%d{yyyy-MM-dd HH:mm:ss.SSS}){faint} %clr(${LOG_LEVEL_PATTERN:-%5p}) %clr(${PID:- }){magenta} %clr(---){faint} %clr([%15.15t]){faint} %clr(%-40.40logger{39}){cyan} %clr(:){faint} %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}"/>
<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>${PATTERN}</pattern>
<charset>utf8</charset>
</encoder>
</appender>
<appender name="application"
class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>application.log</file>
<encoder>
<pattern>${PATTERN}</pattern>
</encoder>
<rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
<fileNamePattern>application.%d{yyyy-MM-dd}.%i.log</fileNamePattern>
<maxHistory>7</maxHistory>
<maxFileSize>50MB</maxFileSize>
<totalSizeCap>10GB</totalSizeCap>
</rollingPolicy>
<filter class="ch.qos.logback.classic.filter.ThresholdFilter">
<level>info</level>
</filter>
</appender>
<appender name="controller"
class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>controller.log</file>
<encoder>
<pattern>${PATTERN}</pattern>
</encoder>
<rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
<fileNamePattern>controller.%d{yyyy-MM-dd}.%i.log</fileNamePattern>
<maxHistory>7</maxHistory>
<maxFileSize>50MB</maxFileSize>
<totalSizeCap>10GB</totalSizeCap>
</rollingPolicy>
<filter class="ch.qos.logback.classic.filter.ThresholdFilter">
<level>info</level>
</filter>
</appender>
<appender name="service"
class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>service.log</file>
<encoder>
<pattern>${PATTERN}</pattern>
</encoder>
<rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
<fileNamePattern>service.%d{yyyy-MM-dd}.%i.log</fileNamePattern>
<maxHistory>7</maxHistory>
<maxFileSize>50MB</maxFileSize>
<totalSizeCap>10GB</totalSizeCap>
</rollingPolicy>
<filter class="ch.qos.logback.classic.filter.ThresholdFilter">
<level>info</level>
</filter>
</appender>
<appender name="error"
class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>error.log</file>
<encoder>
<pattern>${PATTERN}</pattern>
</encoder>
<rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
<fileNamePattern>error.%d{yyyy-MM-dd}.%i.log</fileNamePattern>
<maxHistory>7</maxHistory>
<maxFileSize>50MB</maxFileSize>
<totalSizeCap>10GB</totalSizeCap>
</rollingPolicy>
<filter class="ch.qos.logback.classic.filter.ThresholdFilter">
<level>error</level>
</filter>
</appender>
<root level="info">
<appender-ref ref="CONSOLE" />
<appender-ref ref="application"/>
<appender-ref ref="error"/>
</root>
<logger name="application" level="info" additivity="false">
<appender-ref ref="application"/>
<appender-ref ref="error"/>
</logger>
<logger name="controller" level="info" additivity="false">
<appender-ref ref="controller"/>
<appender-ref ref="error"/>
</logger>
<logger name="service" level="info" additivity="false">
<appender-ref ref="service"/>
<appender-ref ref="error"/>
</logger>
</configuration>
PATTERN
适用于引入spring-cloud-sleuth
的项目,否则日志格式会有点怪异但不影响查看application
是默认Logger
,error
记录全局ERROR
级别信息
LogRecorder
public interface LogRecorder {
// 获取适合的 logger
Logger getLogger();
default void warn(String message) {
Optional.ofNullable(getLogger())
.ifPresent(logger -> logger.warn(message));
}
default void info(String message) {
Optional.ofNullable(getLogger())
.ifPresent(logger -> logger.info(message));
}
default void error(String message) {
Optional.ofNullable(getLogger())
.ifPresent(logger -> logger.error(message));
}
}
- 顶层接口,主要提供了
info
warn
error
方法的常规实现 getLogger
方法获取适合的Logger
对象由子类复写
SimpleLogRecorder
@Component
public class SimpleLogRecorder implements LogRecorder {
public static final String APPLICATION_LOGGER_NAME = "application";
@Override
public Logger getLogger() {
return LoggerFactory.getLogger(APPLICATION_LOGGER_NAME);
}
}
- 一个通用实现,该类实际就是用来记录全局
info
文件的,默认由application
记录 - 该类是一个
bean
组件,可直接注入使用
CommonPointcuts
public class CommonPointcuts {
// web 层,通常为 controller 层
@Pointcut("execution(* com.example.logapp.controller.*.*(..))")
public void webLayerPointcut() {
}
// 逻辑层,通常即 service 层
@Pointcut("execution(* com.example.logapp.service.*.*(..))")
public void serviceLayerPointcut() {
}
}
切面层基类,维护切面的最佳实践,可用于具体切面通知的 Pointcut
声明
AopLogRecorder
public interface AopLogRecorder extends LogRecorder {
/**
* Before 切面,默认记录参数信息
* @param jp
*/
default void before(JoinPoint jp) {
String className = jp.getSignature().getDeclaringTypeName();
String methodName = jp.getSignature().getName();
Object[] args = jp.getArgs();
info(MessageFormat.format(
"开始调用目标方法 - {0}#{1},参数为: {2}"
, className, methodName, JSONObject.toJSONString(args)
));
}
/**
* AfterReturning 切面,默认描述返回结果,仅处理 ResponseEntity
* @param jp
* @param retVal
*/
default void afterReturning(JoinPoint jp, ResponseEntity retVal) {
String className = jp.getSignature().getDeclaringTypeName();
String methodName = jp.getSignature().getName();
info(MessageFormat.format(
"调用目标方法{3} - {0}#{1},结果为: {2}"
, className, methodName, JSONObject.toJSONString(retVal)
, retVal.getSuccessFlag() ? "成功" : "失败"
));
}
/**
* AfterThrow 切面,默认记录报错信息
* @param jp
* @param e
*/
default void afterThrow(JoinPoint jp, Throwable e) {
String className = jp.getSignature().getDeclaringTypeName();
String methodName = jp.getSignature().getName();
error(MessageFormat.format(
"调用目标方法异常 - {0}#{1},异常信息: {2}"
, className, methodName, e.getMessage()
));
}
/**
* Around 通知,这里会捕获掉异常进行处理,适合 web layer
* @param pjp
*/
default Object around(ProceedingJoinPoint pjp) {
String className = pjp.getSignature().getDeclaringTypeName();
String methodName = pjp.getSignature().getName();
Object[] args = pjp.getArgs();
info(MessageFormat.format(
"调用目标方法 - {0}#{1},参数为: {2}"
, className, methodName, JSONObject.toJSONString(args)
));
Object retVal = null;
try {
retVal = pjp.proceed();
} catch (Throwable e) {
error(MessageFormat.format(
"调用目标方法异常 - {0}#{1},异常信息: {2}"
, className, methodName, e.getMessage()
));
return ResponseEntity.error();
}
Optional.ofNullable(retVal)
.filter(result -> result instanceof ResponseEntity)
.map(result -> (ResponseEntity) result)
.ifPresent(t -> info(MessageFormat.format(
"调用目标方法{3} - {0}#{1},结果为: {2}"
, className, methodName, JSONObject.toJSONString(t)
, t.getSuccessFlag() ? "成功" : "失败"
)));
return retVal;
}
}
- 切面日志基类
- 提供
before
afterReturning
afterThrow
的默认实现:before
通常记录参数信息、afterReturning
提供记录结果信息、afterThrow
记录报错的异常信息,可由子类选择性的使用,比如service
层的日志处理 - 提供
around
默认实现,一站式的通用日志处理,同时会包装处理方法执行异常的情况,比如web
层的日志处理 - 子类可进行选择性的覆盖以实现对应场景功能
WebLayerAopLogRecorder
@Aspect
@Component
public class WebLayerAopLogRecorder implements AopLogRecorder {
private static final String WEB_LAYER_LOGGER_NAME = "controller";
@Override
@Around("com.example.logapp.log.CommonPointcuts.webLayerPointcut()")
public Object around(ProceedingJoinPoint pjp) {
return AopLogRecorder.super.around(pjp);
}
@Override
public Logger getLogger() {
return LoggerFactory.getLogger(WEB_LAYER_LOGGER_NAME);
}
}
- 最终的日志切面层实现
- 此处是
controller
层的切面,沿用父类定义的around
切面通知,指定对应的Pointcut
getLogger()
方法指定对应的Logger
为controller
ServiceLayerAopLogRecorder
@Aspect
@Component
public class ServiceLayerAopLogRecorder implements AopLogRecorder {
private static final String SERVICE_LAYER_LOGGER_NAME = "service";
@Override
@Before("com.example.logapp.log.CommonPointcuts.serviceLayerPointcut()")
public void before(JoinPoint jp) {
AopLogRecorder.super.before(jp);
}
@Override
@AfterReturning(
pointcut = "com.example.logapp.log.CommonPointcuts.serviceLayerPointcut()"
, returning = "retVal"
)
public void afterReturning(JoinPoint jp, ResponseEntity retVal) {
AopLogRecorder.super.afterReturning(jp, retVal);
}
@Override
@AfterThrowing(
pointcut = "com.example.logapp.log.CommonPointcuts.serviceLayerPointcut()"
, throwing = "e"
)
public void afterThrow(JoinPoint jp, Throwable e) {
AopLogRecorder.super.afterThrow(jp, e);
}
@Override
public Logger getLogger() {
return LoggerFactory.getLogger(SERVICE_LAYER_LOGGER_NAME);
}
}
- 同上,此处是
service
层的切面日志处理,采用细粒度的切面逻辑分别处理方法执行前后的记录操作 getLogger()
方法指定对应的Logger
为service
SimpleLogRecorder 使用
@Component
public class TestApp {
@Autowired
SimpleLogRecorder simpleLogRecorder;
public String hello(String name) {
simpleLogRecorder.info(name);
return "hello " + name;
}
}
- 上述的场景一般都维护固定的日志信息:比如 入参、返回值 等,但在具体的调试场景中往往需要一些赋值信息的输出才能更好的定位问题
- 此时使用全局的
info
记录即可,在此demo
中直接注入SimpleLogRecorder
组件使用即可
总结
本文分享了个人在 Spring
应用下切面日志最佳实践,整合 Spring Cloud Sleuth
后有了 traceId
的协助,更是能在多链路调用中快速定位问题,加快前后端沟通效率
关于整合 Spring Cloud Sleuth
,可以参考