1.背景
我们在日常排查问题过程中知道，入参传错是导致接口调用失败的常见原因之一。特别是提供给第三方调用的回调接口和openAPI接口，由于无法保证第三方开发人员的水平，经常问题不断，反反复复找你问为啥掉不通，甚至吐槽写的“啥玩意接口”，这时候你肯定一脸懵逼，怒火中烧，想展开撕逼甩锅大战，但是对方有可能是甲方金主爸爸并且你没有第一时间掌握证据证明证是对方调用的问题，你只能忍着问他是如何调接口的，卑微请求他把传参发过来看看。。。为了扭转局势，挺直腰杆怼回去：能不能靠谱点？今天我们就来讲讲系统服务中如何优雅地实现统一打印接口API参数日志，方便服务端开发快速甩锅还能拿出证据！！！
当然需要注意的是，日志打印太多对性能是有一定影响的，并且如果使用ELK架构收集分布式系统日志，也会加大日志收集同步的压力，甚至造成高延迟。所以我们打印日志得分环境和接口的重要程度，一般只需要在测试环境开启，这样第三方联调时候肯定先在测试环境联调通过，最后才正式调线上环境的接口，当然有些接口很重要，排查问题凭证在线上也需要保留，这时候线上的接口参数日志也需要打印着。这就要求我们需要做到：打印参数日志的环境和接口都可以配置指定，主打的就是一个动态灵活性。
话不多说，接下来就来看看我们如何实现这个功能需求
2.实现
说到统一实现，肯定就想到了切面处理。面向切面编程是一种编程范式，它作为 OOP 面向对象编程的一种补充，用于处理系统中分布于各个模块的横切关注点，比如事务管理、权限控制、缓存控制、日志打印等等。在讲切面实现打印日志之前，先来看看动态灵活可配置性咋实现？
2.1 控制环境是否打印接口参数日志
这个实现起来比较简单，我们只需要在配置文件里面设置一个是否开启打印接口参数日志的开关即可：
@Data
@ConfigurationProperties(prefix = "ptc.apiLog")
public class ApiLogProperties {
/**
* 是否开启接口日志打印, 默认
*/
private Boolean enable = Boolean.FALSE;
}
这里默认为false表示不开启接口参数日志打印，然后在自动配置类中使用：
@Configuration
@EnableConfigurationProperties({
ApiLogProperties.class})
@PropertySource("classpath:/web-default.properties")
public class PlasticeneWebAutoConfiguration {
/**
* 注入api 日志打印拦截器
* @return
*/
@Bean
// @ConditionalOnProperty(name = "ptc.apiLog.enable", havingValue = "true")
public ApiLogPrintAspect apiLogPrintAspect() {
return new ApiLogPrintAspect();
}
}
注意这里注入ApiLogPrintAspect并没有使用条件装配，条件装配代码已经被注释掉了，这样做的原因是，我们在下面切面类进行开关判断，这样可以借助于动态配置更新开关接口参数打印，就不需要重启服务了。还有其实上面的的属性配置类不一定需要，因为我们也可以根据ptc.api.log.enable直接注入获取value值，这中属性配置类一般针对一个功能点下有多个配置才适用一点，我这里写了是为了实现Spring Boot业务系统中自定义配置自动提示:
关于如何实现Spring Boot业务系统中自定义配置自动提示不清楚的可以自行查阅资料了解。
2.2 控制接口是否打印参数日志
这种需要指定某个接口是否需要打印参数日志的动态配置都需要借助于注解实现：
@Retention(RetentionPolicy.RUNTIME)
@Target({
ElementType.TYPE, ElementType.METHOD})
@Documented
public @interface ApiLog {
}
这个注解定义很简单，连属性都没有，因为只需要在接口方法或所在类打上标识即可，注解可以作用于类上或者接口方法上，作用于类上时意味着该类下的所有方法都需要打印接口参数日志哦。
项目推荐：基于SpringBoot2.x、SpringCloud和SpringCloudAlibaba企业级系统架构底层框架封装，解决业务开发时常见的非功能性需求，防止重复造轮子，方便业务快速开发和企业技术栈框架统一管理。引入组件化的思想实现高内聚低耦合并且高度可配置化，做到可插拔。严格控制包依赖和统一版本管理，做到最少化依赖。注重代码规范和注释，非常适合个人学习和企业使用
Github地址：https://github.com/plasticene/plasticene-boot-starter-parent
Gitee地址：https://gitee.com/plasticene3/plasticene-boot-starter-parent
微信公众号：Shepherd进阶笔记
交流探讨qun：Shepherd_126
2.3 AOP切面实现日志打印
这里使用AOP切面使用此功能，当然也可以使用过滤器filter实现日志切面的效果，但是注意是用filter时候，对入参的获取要谨慎处理，通过request.getInputStream(或者getReader)读取请求数据流(能解析出content-Type为 application/x-www-form-urlencoded ，application/json , text/xml这三种提交方式的数据（注：multipart/form-data不行），但是！！！在后续controller接口中无法获取该数据流。主要原因在于不能在过滤器中读取一次二进制流（字符流），又在另外一个Servlet中读取一次，即一个InputSteam(BufferedReader)对象在被读取完成后，将无法再次被读取。这个我们在之前的总结中分析过，详见：Spring Boot如何实现接口参数加解密。回到正题来看看切面逻辑：
@Aspect
@Slf4j
@Order(value = OrderConstant.AOP_API_LOG)
public class ApiLogPrintAspect {
@Resource
private ApiLogProperties apiLogProperties;
/**
* 声明切点
*
* @param joinPoint 切入点
*表达式示例：
* 任意公共方法的执行：execution(public * *(..))
* 任何一个以“set”开始的方法的执行：execution(* set*(..))
* AccountService 接口的任意方法的执行：execution(* com.xyz.service.AccountService.*(..))
* 定义在service包里的任意方法的执行： execution(* com.xyz.service.*.*(..))
* 定义在service包和所有子包里的任意类的任意方法的执行：execution(* com.xyz.service..*.*(..))
* @return 返回值
* @throws Throwable 异常
*/
@Around("execution(* com.plasticene..controller..*(..))")
public Object timeAround(ProceedingJoinPoint joinPoint) throws Throwable {
// 这里做开关判断，而不是根据开关条件注入切面bean，是因为为了方便修改配置开关动态更新来控制开关打印接口参数日志
if (!apiLogProperties.getEnable()) {
return joinPoint.proceed();
}
ApiLog apiLog = getApiLog(joinPoint);
if (Objects.isNull(apiLog)) {
return joinPoint.proceed();
}
long start = System.currentTimeMillis();
HttpServletRequest request = getRequest();
RequestInfo requestInfo = new RequestInfo();
requestInfo.setIp(request.getRemoteAddr());
requestInfo.setUrl(request.getRequestURL().toString());
requestInfo.setHttpMethod(request.getMethod());
requestInfo.setClassMethod(String.format("%s.%s", joinPoint.getSignature().getDeclaringTypeName(),
joinPoint.getSignature().getName()));
requestInfo.setRequestParams(getRequestParams(joinPoint, request));
log.info("Request Info : {}", JsonUtils.toJsonString(requestInfo));
Object result = joinPoint.proceed();
log.info("Response result: {}", JsonUtils.toJsonString(result));
log.info("time cost: {}", System.currentTimeMillis() - start);
return result;
}
private Object getRequestParams(ProceedingJoinPoint joinPoint, HttpServletRequest request) throws UnsupportedEncodingException {
Object[] args = joinPoint.getArgs();
Object params = null;
String queryString = request.getQueryString();
String method = request.getMethod();
if (args.length > 0) {
// 有body的接口类型，这时候要排除HttpServletRequest request, HttpServletResponse response作为接口方法参数
if ("POST".equals(method) || "PUT".equals(method) || "DELETE".equals(method)) {
int length = args.length;
int index = 0;
Object object = null;
while (index < length) {
Object o = args[index];
index++;
if (o instanceof HttpServletRequest || o instanceof HttpServletResponse) {
continue;
} else {
object = o;
break;
}
}
if (object instanceof MultipartFile) {
MultipartFile multipartFile = (MultipartFile) object;
params = MessageFormat.format("文件名: {0}, 大小: {1}", multipartFile.getOriginalFilename(), multipartFile.getSize());
} else {
params = object;
}
// 方法为get时，当接口参数为路径参数，那么此时queryString为null
} else if ("GET".equals(method) && StrUtil.isNotBlank(queryString)) {
params = URLDecoder.decode(queryString, "utf-8");
}
}
return params;
}
private HttpServletRequest getRequest() {
ServletRequestAttributes requestAttributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
HttpServletRequest request = requestAttributes.getRequest();
return request;
}
private ApiLog getApiLog(JoinPoint joinPoint) {
MethodSignature methodSignature = (MethodSignature) joinPoint.getSignature();
Method method = methodSignature.getMethod();
ApiLog apiLog = method.getAnnotation(ApiLog.class);
if (Objects.isNull(apiLog)) {
apiLog = method.getDeclaringClass().getAnnotation(ApiLog.class);
}
return apiLog;
}
}
可以看到我们对接口入参进行一定的解析适配，AOP的切入点execution(* com.plasticene..controller..*(..))，必须满足这个包路径才执行切面逻辑，这符合一个公司的项目服务结构规范，以相同前缀为包名方便后续做相关统一拦截逻辑处理，紧接着判断了日志开关和是否打上了@ApiLog标记，最后对接口请求参数和响应参数进行日志打印，这里的日志打印只在一行中打印，也没有什么格式，这样可以有效减少日志量，因为我们平时查日志肯定都是根据traceId来查询一次请求的参数打印，查到之后直接copy出来找一个在线JSON解析工具就可以清楚看到日志信息了。同时这里使用@Order(value = OrderConstant.AOP_API_LOG)控制切面组件的执行顺序， 通过@Order(i)注解来指定优先级，注意：i 值越小，优先级则越高。
2.4 使用示例
在业务项目服务的配置文件开启打印日志开关
ptc:
api:
log:
enable: true
编写测试接口：
@PostMapping("/test/api/log")
@ApiLog
public User printApiLog(@RequestBody User user) throws InterruptedException {
log.info("api log打印啦....");
TimeUnit.SECONDS.sleep(1);
return user;
}
接口调用：
控制台日志打印如下：
[1719387065344552960] [INFO ] [2023-11-01 00:13:16.007] [http-nio-18888-exec-1@29351] com.plasticene.boot.web.core.aop.ApiLogPrintAspect timeAround : Request Info : {"ip":"127.0.0.1","url":"http://127.0.0.1:18888/fds/test/test/api/log","httpMethod":"POST","classMethod":"com.plasticene.fast.controller.TestController.printApiLog","requestParams":{"createTime":null,"updateTime":null,"creator":null,"updater":null,"id":123,"username":null,"password":null,"name":"she哈哈","mobile":"1234556457","gender":1,"status":null,"email":"shepherd@163.com","remark":"测试打印api日志啦"}}
[1719387065344552960] [INFO ] [2023-11-01 00:13:16.073] [http-nio-18888-exec-1@29351] com.plasticene.fast.controller.TestController printApiLog$original$kjC7ivXx : api log打印啦....
[1719387065344552960] [INFO ] [2023-11-01 00:13:17.087] [http-nio-18888-exec-1@29351] com.plasticene.boot.web.core.aop.ApiLogPrintAspect timeAround : Response result: {"createTime":null,"updateTime":null,"creator":null,"updater":null,"id":123,"username":null,"password":null,"name":"she哈哈","mobile":"1234556457","gender":1,"status":null,"email":"shepherd@163.com","remark":"测试打印api日志啦"}
[1719387065344552960] [INFO ] [2023-11-01 00:13:17.090] [http-nio-18888-exec-1@29351] com.plasticene.boot.web.core.aop.ApiLogPrintAspect timeAround : time cost: 1115
可以看到对接口入参和出参都进行详细的打印，但是发现接口参数日志和业务的日志耦合在一起，不太好区分。所以我们就想着把接口参数日志单独打印输出到一个日志文件中，方便查询。其实只需要把上面切面类的@Slf4j指定一个topic
@Slf4j(topic = "ptc.api.log")
然后再日志配置文件进行关联部分配置：
<!-- 2.5 interface接口日志，时间滚动输出 -->
<appender name="INTERFACE_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
<!-- 正在记录的日志文档的路径及文档名 -->
<file>${log.path}/app-interface.log</file>
<!--日志文档输出格式-->
<encoder>
<pattern>${CONSOLE_LOG_PATTERN}</pattern>
<charset>UTF-8</charset> <!-- 此处设置字符集 -->
</encoder>
<!-- 日志记录器的滚动策略，按日期，按大小记录 -->
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<fileNamePattern>${log.path}/app-interface-%d{yyyy-MM-dd}.%i.log</fileNamePattern>
<timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
<maxFileSize>100MB</maxFileSize>
</timeBasedFileNamingAndTriggeringPolicy>
<!--日志文档保留天数-->
<maxHistory>15</maxHistory>
</rollingPolicy>
<!-- 此日志文档只记录info级别的 -->
<filter class="ch.qos.logback.classic.filter.LevelFilter">
<level>info</level>
<onMatch>ACCEPT</onMatch>
<onMismatch>DENY</onMismatch>
</filter>
</appender>
<logger name="ptc.api.log" level="info" additivity="false">
<Appender-ref ref="CONSOLE"/>
<appender-ref ref="INTERFACE_FILE"/>
</logger>
需要完整的logback.xml日志文件请留言，我单独私发，这里碍于篇幅问题就不全部展示了。
再次执行上面测试接口示例，日志文件收集如下：接口参数打印的日志单独收集到了app-interface文件中
而我们接口逻辑中打印的日志输出到了app-info中：
3.总结
以上全部就是我们对打印接口参数日志的功能实现方案分析总结，合理打印输出日志有助于提高排查问题的效率，但是也不能随心所欲地打印日志，会对接口性能造成一定影响和分布式日志收集同步延时等。同时我们也分析如何实现动态灵活性，做到可插拔，最后对日志进行分类归档，方便查询。
