Spring Boot 使用 Aspect 完整記錄(log) Restful API 的request、response,且可以寫成一行log

前言

網路上可以找到各種寫log的作法,有透過filter、interceptor、aspect
但總會有些缺陷,無法完整的記錄
像filter,只取得到request
interceptor,取得到request、response、method,但拿不到入參

不然就是response部份寫在@AfterReturning()裡,如下:

1
2
3
4
@AfterReturning(returning = "ret", pointcut = "logPointCut()")
public void doAfterReturning(Object ret) throws Throwable {
logger.info("response: " + ret);
}

導致log強迫拆成多行來寫

經過多方資料的拼湊後,總算用aspect成功寫出完整的log
且可以直接一條log完整記錄!

輸出範例

實際log記錄方式,依需求自行調整,僅提供範例寫法

為便於閱讀,範例裡仍寫成多行
但可以寫成只有一行log完整記錄request、response詳細內容

GET(範例)

API:http://localhost:8080/hello?id=123&name=andy&age=18

1
2
3
4
5
6
7
8
9
10
11
12
[2021-06-18 10:17:25.988] [http-nio-8080-exec-3] [INFO ] [com.example.demo.core.logging.HttpLogAspect] - ------------------------------------------ 
[2021-06-18 10:17:25.991] [http-nio-8080-exec-3] [INFO ] [com.example.demo.core.logging.HttpLogAspect] - [0:0:0:0:0:0:0:1] [GET] [http://localhost:8080/hello] [DemoController.hello()] [46 ms]
[2021-06-18 10:17:25.992] [http-nio-8080-exec-3] [INFO ] [com.example.demo.core.logging.HttpLogAspect] - -----------------REQUEST------------------
[2021-06-18 10:17:26.118] [http-nio-8080-exec-3] [INFO ] [com.example.demo.core.logging.HttpLogAspect] - request parameter: {
"id" : [ "123" ],
"name" : [ "andy" ],
"age" : [ "18" ]
}
[2021-06-18 10:17:26.119] [http-nio-8080-exec-3] [INFO ] [com.example.demo.core.logging.HttpLogAspect] - request body:
[2021-06-18 10:17:26.121] [http-nio-8080-exec-3] [INFO ] [com.example.demo.core.logging.HttpLogAspect] - -----------------RESPONSE-----------------
[2021-06-18 10:17:26.148] [http-nio-8080-exec-3] [INFO ] [com.example.demo.core.logging.HttpLogAspect] - RESPONSE: "hello!"
[2021-06-18 10:17:26.149] [http-nio-8080-exec-3] [INFO ] [com.example.demo.core.logging.HttpLogAspect] - ------------------------------------------

POST(範例)

API:http://localhost:8080/user,新增user

1
2
3
4
5
6
7
8
9
10
11
12
13
[2021-06-18 10:19:47.857] [http-nio-8080-exec-2] [INFO ] [com.example.demo.core.logging.HttpLogAspect] - ------------------------------------------ 
[2021-06-18 10:19:47.857] [http-nio-8080-exec-2] [INFO ] [com.example.demo.core.logging.HttpLogAspect] - [0:0:0:0:0:0:0:1] [POST] [http://localhost:8080/user] [Cm0099Controller.createUser()] [84 ms]
[2021-06-18 10:19:47.857] [http-nio-8080-exec-2] [INFO ] [com.example.demo.core.logging.HttpLogAspect] - -----------------REQUEST------------------
[2021-06-18 10:19:47.857] [http-nio-8080-exec-2] [INFO ] [com.example.demo.core.logging.HttpLogAspect] - request parameter: { }
[2021-06-18 10:19:47.857] [http-nio-8080-exec-2] [INFO ] [com.example.demo.core.logging.HttpLogAspect] - request body: {"name":"andy","age":18,"phone":0912345678}
[2021-06-18 10:19:47.858] [http-nio-8080-exec-2] [INFO ] [com.example.demo.core.logging.HttpLogAspect] - -----------------RESPONSE-----------------
[2021-06-18 10:19:47.881] [http-nio-8080-exec-2] [INFO ] [com.example.demo.core.logging.HttpLogAspect] - RESPONSE: {
"id" : "1",
"name" : "andy",
"age" : "18",
"phone" : "0912345678"
}
[2021-06-18 10:19:47.881] [http-nio-8080-exec-2] [INFO ] [com.example.demo.core.logging.HttpLogAspect] - ------------------------------------------

作法

SpringBootApplication增加@ServletComponentScan

打開Spring Boot 入口程式,增加@ServletComponentScan裝飾器,使Spring Boot可以使用WebFilter裝飾器

1
2
3
4
5
6
7
8
9
@SpringBootApplication
[email protected]
public class DemoApplication {

public static void main(String[] args) {
SpringApplication.run(DemoApplication.class, args);
}

}

增加LogFilter,以wrapper request

因request的流在進入aop時被關閉了,若由request取body,會拋exception
故包裝一份在aop寫log時可以取body

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
@WebFilter
public class LogFilter extends OncePerRequestFilter {

private final Logger logger = LoggerFactory.getLogger(getClass());

@Override
protected void doFilterInternal(HttpServletRequest httpServletRequest,
HttpServletResponse httpServletResponse,
FilterChain filterChain) throws ServletException, IOException {

httpServletRequest = new ContentCachingRequestWrapper(httpServletRequest, 1024); // 最大長度取1024,依需要自行調整數字

filterChain.doFilter(httpServletRequest, httpServletResponse);
}
}

增加LogAspect,實際寫log

相關說明都在註解裡了

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
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
@Aspect
@Component
public class LogAspect {

private final Logger logger = LoggerFactory.getLogger(getClass());

@Autowired
private ObjectMapper mapper;

@Pointcut("bean(*Controller)") // 抓取所有Controller,可依實際需求調整
public void logPointCut() { }

@Around("logPointCut()")
public Object logging(ProceedingJoinPoint joinPoint) throws Throwable {
long startTime = System.currentTimeMillis();

ServletRequestAttributes attributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
HttpServletRequest request = attributes.getRequest();

// 僅取到Controller名字,去掉前面package的路徑。實務上同一專案不同路徑卻同一命名機會應該頗低
// 若仍想印完整,拿掉`lastPointIndex`,直接印`joinPoint.getSignature().getDeclaringTypeName()`即可
int lastPointIndex = joinPoint.getSignature().getDeclaringTypeName().lastIndexOf(".") + 1;
String class_method = joinPoint.getSignature().getDeclaringTypeName().substring(lastPointIndex) + "." +
joinPoint.getSignature().getName() + "()";

Object responseBody = joinPoint.proceed();
logger.info("------------------------------------------");
// [IP] [方法(GET/POST)] [API網址] [controller.method()] [執行時間]
logger.info("[{}] [{}] [{}] [{}] [{} ms]", request.getRemoteAddr(), request.getMethod(), request.getRequestURL(), class_method, System.currentTimeMillis() - startTime);
logger.info("-----------------REQUEST------------------");
logger.info("request parameter: {}", mapper.writerWithDefaultPrettyPrinter().writeValueAsString(request.getParameterMap())); // 若想要一行呈現,拿掉`writerWithDefaultPrettyPrinter()`,寫成`mapper.writeValueAsString(參數)`即可
logger.info("request body: {}", getPayload(request));
logger.info("-----------------RESPONSE-----------------");
logger.info("RESPONSE: {}",this.mapper.writerWithDefaultPrettyPrinter().writeValueAsString(responseBody)); // / 若想要一行呈現,拿掉`writerWithDefaultPrettyPrinter()`,寫成`mapper.writeValueAsString(參數)`即可
logger.info("------------------------------------------");

return responseBody;
}

private String getPayload(HttpServletRequest request) {
ContentCachingRequestWrapper wrapper = WebUtils.getNativeRequest(request, ContentCachingRequestWrapper.class);
if (wrapper != null) {
byte[] buf = wrapper.getContentAsByteArray();
if (buf.length > 0) {
try {
int length = Math.min(buf.length, 1024);// 最多只印出1024長度
return new String(buf, 0, length, wrapper.getCharacterEncoding());
} catch (UnsupportedEncodingException ex) {
return "[unknown]";
}
}
}
return "";
}
}

心得

網路上查到Aspect的解法,都會提到:

1
2
3
4
// ...(doBefore)...
Object object = proceedingJoinPoint.proceed();
// ...(doAfter)...
return object;

但卻沒人說明到proceedingJoinPoint.proceed();回傳的object,就是responseBody
一直在想辦法由HttpServletResponse res = attributes.getResponse();去找Body,但都找不到
而Java直接print object.toString(),也是object代號而已= =

結果答案就眼前。真是眾裡尋他千百度,就在燈火闌珊處…

參考資料

Spring AOP @Around output request parameters and return parameters
spring boot aop打印http請求回復日誌包含請求體