java aop实现http接口日志记录

http log

本文旨在讨论如何利用aop打印springboot http日志,包括访问日志、接口返回response,以及异常堆栈信息。

背景

为什么需要log

有过线上问题排查经历的同学都知道,日志可以给你提供最直白、最明确的信息。此外,通过对日志的收集、审计,可以对BI以及系统健壮性提供建议。尤其是新系统上线之初,系统稳定性不足,更需要日志监控。

为什么不实用Greys+access log

Greys 作为Java线上问题诊断工具,可以监控实时访问参数,但是对历史访问无记录,尤其是在前后分离or微服务架构下,日志是可以作为呈堂证供的存在。而access log不够灵活和强大。

方案优势

  1. 简化日志打印
  2. 统一的日志格式,可以配合收集机制
  3. 灵活,可以自由选择是否记录日志、是否忽略response、是否忽略某些参数(如file参数显然不适合记录日志)、以及是否打印header参数
  4. 日志记录比例可配置(系统稳定,流量增大之后,可以通过配置降低记录比例)
  5. 方便回溯异常请求参数
  6. 记录接口耗时

实现

AOP-面向切面编程

一句话描述,在java对象方法中增加切点,在不改变对象领域的前提下通过代理扩展功能。

切面选择

网上常见教程会选择拦截所有http请求,并打印request.parameters。但是存在问题:

  1. 不够灵活,部分参数不想打印,如文件数据(过大)、敏感数据(身份证)等。
  2. 隐式的aop,容易给维护人员造成疑惑。(个人习惯偏向于避免隐藏的aop逻辑)
  3. 部分参数通过header传输

因此,自定义日志输出@annotation HttpLog作为切点

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
/**
* 用于打印http请求访问日志
*
* @author yuheng.wang
*/
@Target(ElementType.METHOD)
@Retention(RetentionPolicy.RUNTIME)
public @interface HttpLog {
/**
* 忽略参数,避免文件or无意义参数打印
*
* @return 忽略参数数组
*/
String[] exclude() default {};

/**
* 需要打印的header参数
*
* @return header参数名数组
*/
String[] headerParams() default {};

boolean ignoreResponse() default false;

/**
* 日志记录比例
* >100 or < 0时,每次请求都会被记录
* = 0 时,不会记录
*/
int percent() default 100;
}

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
@Aspect
@Slf4j
public class HttpLogHandler {

@Pointcut("@annotation(wang.crick.study.httplog.annotation.HttpLog)")
public void logAnnotation() {
}

private Optional<HttpLog> getLogAnnotation(JoinPoint joinPoint) {
if (joinPoint instanceof MethodInvocationProceedingJoinPoint) {
Signature signature = joinPoint.getSignature();
if (signature instanceof MethodSignature) {
MethodSignature methodSignature = (MethodSignature) signature;
Method method = methodSignature.getMethod();
if (method.isAnnotationPresent(HttpLog.class)) {
return Optional.of(method.getAnnotation(HttpLog.class));
}
}
}
return Optional.empty();
}
}

打印异常信息

  1. 为了方便回溯,定义UUID形式的traceId,并通过ThreadLocal持有。
  2. 为了记录接口相应时间,定义startTime,并通过ThreadLocal持有。
  3. AfterThrowing方法不会阻碍Exception的抛出,不会影响全局异常捕获。
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
@AfterThrowing(throwing = "e", pointcut = "logAnnotation()")
public void throwing(JoinPoint joinPoint, Exception e) {
try {
Optional<HttpLog> httpLog = getLogAnnotation(joinPoint);
httpLog.ifPresent(anno -> {
if (!anno.ignoreResponse()) {
log.info("ERROR_LOG. traceId:{}, cost:{}",
traceIdThreadLocal.get(), costTime(), e);
}
});
} catch (Exception exception) {
log.warn("print error log fail!", exception);
} finally {
startTimeThreadLocal.remove();
traceIdThreadLocal.remove();
}
}

打印response

  1. 通过JSONObject.toJSONString()转换,因为restful接口常见为返回json格式。
  2. 需要判断是否忽略了response打印
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
@AfterReturning(returning = "restApiResponse", pointcut = "logAnnotation()")
public void response(JoinPoint joinPoint, Object restApiResponse) {
try {
Optional<HttpLog> httpLog = getLogAnnotation(joinPoint);
httpLog.ifPresent(anno -> {
if (!anno.ignoreResponse()) {
log.info("RESPONSE_LOG. traceId:{}, result:{}, cost:{}",
traceIdThreadLocal.get(), JSONObject.toJSONString(restApiResponse), costTime());
}
});
} catch (Exception exception) {
log.warn("print response log fail!", exception);
} finally {
startTimeThreadLocal.remove();
traceIdThreadLocal.remove();
}
}

获取请求日志

获取HttpServletRequest

重点在于获取HttpServletRequest对象,而spring已经很贴心的在initContextHolders时通过RequestContextHolder持有了RequestAttributes参数(基于ThreadLocal)。 所以我们可以很轻松的获取请求参数

1
2
3
4
5
private HttpServletRequest getRequest() {
RequestAttributes ra = RequestContextHolder.getRequestAttributes();
ServletRequestAttributes sra = (ServletRequestAttributes) ra;
return sra.getRequest();
}

获取RequestBody

!!上面获取参数的方式有一个缺陷,无法获取RequestBody参数,因为RequestBody是以流的形式读取,只能被读取一次,如果在aop中的提前读取了内容信息,后面的业务方法则无法获取。
一般的解决方案为封装一层HttpServletRequestWrapper暂存流的信息,实现多次读取。但是此种方案对需要修改HttpServletRequest,侵入性较大,所以我们采取另一种方案,基于aop+反射的特性获取java方法参数,遍历判断是否为@RequestBody参数。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
private Optional<Object> getRequestBodyParam(JoinPoint joinPoint){
if (joinPoint instanceof MethodInvocationProceedingJoinPoint) {
Signature signature = joinPoint.getSignature();
if (signature instanceof MethodSignature) {
MethodSignature methodSignature = (MethodSignature) signature;
Method method = methodSignature.getMethod();
Parameter[] methodParameters = method.getParameters();
if (null != methodParameters
&& Arrays.stream(methodParameters).anyMatch(p-> AnnotationUtils.findAnnotation(p, RequestBody.class) != null)) {
return Optional.of(joinPoint.getArgs());
}
}
}
return Optional.empty();
}

获取uri

根据拦截规则不同,getServletPath()和request.getPathInfo()可能为空,简单的做一次健壮性判断。

1
2
3
4
5
private String getRequestPath(HttpServletRequest request) {
return (null != request.getServletPath() && request.getServletPath().length() > 0)
? request.getServletPath() : request.getPathInfo();

}

日志记录百分比

  1. 接口请求量一般为平稳持续
  2. 并不需要十分精确的比例

所以通过接口访问时间戳(startTime)尾数进行判断

1
2
3
4
5
6
7
8
9
private boolean needLog(int percent, long startTimeMillis){
if (percent< 0 || percent >= 100) {
return true;
} else if (percent == 0) {
return false;
} else {
return percent > startTimeMillis % 100;
}
}

使用

加载HttpLogAspect对象

  1. 可以在@SpringBootApplication类下直接加载,也可以在HttpLogAspect中增加@Component注解。
  2. 不需要显示声明@EnableAspectJAutoProxy注解
1
2
3
4
@Bean
public HttpLogAspect httpLogAspect(){
return new HttpLogAspect();
}

Controller配置日志打印

在controller中在接口方法中通过HttpLog配置,即可实现日志记录

1
2
3
4
5
6
7
8
9
10
11
12
@GetMapping("/log/pwdExcludeResponse/{id}")
@HttpLog(headerParams="username", ignoreResponse = true, percent = 50, exclude={"avatar"})
public RestApiResponse<User> getInfoWithPwd(@PathVariable("id") int id,
@RequestParam("age") int age,
@RequestParam("avatar") MultipartFile avatar,
@RequestHeader("password") String password){
User user = new User();
user.setId(id);
user.setPassword(password);
user.setAge(age);
return RestApiResponse.success(user);
}

效果

1
2
3
4
REQUEST_LOG. traceId:737001cf-f546-4092-9c77-f7762275ddcf. requestUrl: /user/log/7 -PARAMS- age: [6], 
RESPONSE_LOG. traceId:737001cf-f546-4092-9c77-f7762275ddcf, result:{"code":10000,"data":{"age":6,"id":7,"username":"8025373076402792850"}}, cost:171
REQUEST_LOG. traceId:8c907a7e-f36a-4ccc-a931-f167b55697ee. requestUrl: /user/log/pwd/0 -PARAMS- age: [7], -HEADER_PARAMS- password: 6460630360418207541,
RESPONSE_LOG. traceId:8c907a7e-f36a-4ccc-a931-f167b55697ee, result:{"code":10000,"data":{"id":0,"password":"6460630360418207541","username":"2250855379452327045"}}, cost:9

Welcome to my other publishing channels