SpringBoot实战 之 接口日志篇

在本篇文章中不会详细介绍日志如何配置、如果切换另外一种日志工具之类的内容，只用于记录作者本人在工作过程中对日志的几种处理方式。

1. Debug 日志管理

在开发的过程中，总会遇到各种莫名其妙的问题，而这些问题的定位一般会使用到两种方式，第一种是通过手工 Debug 代码，第二种则是直接查看日志输出。Debug 代码这种方式只能在 IDE 下使用，一旦程序移交部署，就只能通过日志来跟踪定位了。

在测试环境下，我们无法使用 Debug 代码来定位问题，所以这时候需要记录所有请求的参数及对应的响应报文。而在 数据交互篇 中，我们将请求及响应的格式都定义成了Json，而且传输的数据还是存放在请求体里面。而请求体对应在 HttpServletRequest 里面又只是一个输入流，这样的话，就无法在过滤器或者拦截器里面去做日志记录了，而必须要等待输入流转换成请求模型后（响应对象转换成输出流前）做数据日志输出。

有目标那就好办了，只需要找到转换发生的地方就可以植入我们的日志了。通过源码的阅读，终于在 AbstractMessageConverterMethodArgumentResolver 个类中发现了我们的期望的那个地方，对于请求模型的转换，实现代码如下：

@SuppressWarnings("unchecked")
protected <T> Object readWithMessageConverters(HttpInputMessage inputMessage, MethodParameter parameter,
Type targetType) throws IOException, HttpMediaTypeNotSupportedException, HttpMessageNotReadableException {

MediaType contentType;
boolean noContentType = false;
try {
contentType = inputMessage.getHeaders().getContentType();
}
catch (InvalidMediaTypeException ex) {
throw new HttpMediaTypeNotSupportedException(ex.getMessage());
}
if (contentType == null) {
noContentType = true;
contentType = MediaType.APPLICATION_OCTET_STREAM;
}

Class<?> contextClass = (parameter != null ? parameter.getContainingClass() : null);
Class<T> targetClass = (targetType instanceof Class ? (Class<T>) targetType : null);
if (targetClass == null) {
ResolvableType resolvableType = (parameter != null ?
ResolvableType.forMethodParameter(parameter) : ResolvableType.forType(targetType));
targetClass = (Class<T>) resolvableType.resolve();
}

HttpMethod httpMethod = ((HttpRequest) inputMessage).getMethod();
Object body = NO_VALUE;

try {
inputMessage = new EmptyBodyCheckingHttpInputMessage(inputMessage);

for (HttpMessageConverter<?> converter : this.messageConverters) {
Class<HttpMessageConverter<?>> converterType = (Class<HttpMessageConverter<?>>) converter.getClass();
if (converter instanceof GenericHttpMessageConverter) {
GenericHttpMessageConverter<?> genericConverter = (GenericHttpMessageConverter<?>) converter;
if (genericConverter.canRead(targetType, contextClass, contentType)) {
if (logger.isDebugEnabled()) {
logger.debug("Read [" + targetType + "] as \"" + contentType + "\" with [" + converter + "]");
}
if (inputMessage.getBody() != null) {
inputMessage = getAdvice().beforeBodyRead(inputMessage, parameter, targetType, converterType);
body = genericConverter.read(targetType, contextClass, inputMessage);
body = getAdvice().afterBodyRead(body, inputMessage, parameter, targetType, converterType);
}
else {
body = getAdvice().handleEmptyBody(null, inputMessage, parameter, targetType, converterType);
}
break;
}
}
else if (targetClass != null) {
if (converter.canRead(targetClass, contentType)) {
if (logger.isDebugEnabled()) {
logger.debug("Read [" + targetType + "] as \"" + contentType + "\" with [" + converter + "]");
}
if (inputMessage.getBody() != null) {
inputMessage = getAdvice().beforeBodyRead(inputMessage, parameter, targetType, converterType);
body = ((HttpMessageConverter<T>) converter).read(targetClass, inputMessage);
body = getAdvice().afterBodyRead(body, inputMessage, parameter, targetType, converterType);
}
else {
body = getAdvice().handleEmptyBody(null, inputMessage, parameter, targetType, converterType);
}
break;
}
}
}
}
catch (IOException ex) {
throw new HttpMessageNotReadableException("Could not read document: " + ex.getMessage(), ex);
}

if (body == NO_VALUE) {
if (httpMethod == null || !SUPPORTED_METHODS.contains(httpMethod) ||
(noContentType && inputMessage.getBody() == null)) {
return null;
}
throw new HttpMediaTypeNotSupportedException(contentType, this.allSupportedMediaTypes);
}

return body;
}

上面的代码中有一处非常重要的地方，那就在在数据转换前后都存在 Advice 相关的方法调用，显然，只需要在 Advice 里面完成日志记录就可以了，下面开始实现自定义 Advice。

首先，请求体日志切面 LogRequestBodyAdvice 实现如下：

@ControllerAdvice
public class LogRequestBodyAdvice implements RequestBodyAdvice {

private Logger logger = LoggerFactory.getLogger(LogRequestBodyAdvice.class);

@Override
public boolean supports(MethodParameter methodParameter, Type targetType,
Class<? extends HttpMessageConverter<?>> converterType) {
return true;
}

@Override
public Object handleEmptyBody(Object body, HttpInputMessage inputMessage,
MethodParameter parameter, Type targetType,
Class<? extends HttpMessageConverter<?>> converterType) {
return body;
}

@Override
public HttpInputMessage beforeBodyRead(HttpInputMessage inputMessage,
MethodParameter parameter, Type targetType,
Class<? extends HttpMessageConverter<?>> converterType) throws IOException {
return inputMessage;
}

@Override
public Object afterBodyRead(Object body, HttpInputMessage inputMessage,
MethodParameter parameter, Type targetType,
Class<? extends HttpMessageConverter<?>> converterType) {
Method method = parameter.getMethod();
String classMappingUri = getClassMappingUri(method.getDeclaringClass());
String methodMappingUri = getMethodMappingUri(method);
if (!methodMappingUri.startsWith("/")) {
methodMappingUri = "/" + methodMappingUri;
}
logger.debug("uri={} | requestBody={}", classMappingUri + methodMappingUri, JSON.toJSONString(body));
return body;
}

private String getMethodMappingUri(Method method) {
RequestMapping methodDeclaredAnnotation = method.getDeclaredAnnotation(RequestMapping.class);
return methodDeclaredAnnotation == null ? "" : getMaxLength(methodDeclaredAnnotation.value());
}

private String getClassMappingUri(Class<?> declaringClass) {
RequestMapping classDeclaredAnnotation = declaringClass.getDeclaredAnnotation(RequestMapping.class);
return classDeclaredAnnotation == null ? "" : getMaxLength(classDeclaredAnnotation.value());
}

private String getMaxLength(String[] strings) {
String methodMappingUri = "";
for (String string : strings) {
if (string.length() > methodMappingUri.length()) {
methodMappingUri = string;
}
}
return methodMappingUri;
}
}

得到日志记录如下：

2017-05-02 22:48:15.435 DEBUG 888 --- [nio-8080-exec-1] c.q.funda.advice.LogRequestBodyAdvice    : uri=/sys/user/login | requestBody={"password":"123","username":"123"}

对应的，响应体日志切面 LogResponseBodyAdvice 实现如下：

@ControllerAdvice
public class LogResponseBodyAdvice implements ResponseBodyAdvice {

private Logger logger = LoggerFactory.getLogger(LogResponseBodyAdvice.class);

@Override
public boolean supports(MethodParameter returnType, Class converterType) {
return true;
}

@Override
public Object beforeBodyWrite(Object body, MethodParameter returnType, MediaType selectedContentType, Class selectedConverterType, ServerHttpRequest request, ServerHttpResponse response) {
logger.debug("uri={} | responseBody={}", request.getURI().getPath(), JSON.toJSONString(body));
return body;
}
}

得到日志记录如下：

2017-05-02 22:48:15.520 DEBUG 888 --- [nio-8080-exec-1] c.q.funda.advice.LogResponseBodyAdvice   : uri=/sys/user/login | responseBody={"code":10101,"msg":"手机号格式不合法"}

2. 异常日志管理

Debug 日志只适用于开发及测试阶段，一般应用部署生产，鉴于日志里面的敏感信息过多，往往只会在程序出现异常时输出明细的日志信息，在 ExceptionHandler 标注的方法里面输入异常日志无疑是最好的，但摆在面前的一个问题是，如何将 @RequestBody 绑定的 Model 传递给异常处理方法？我想到的是通过 ThreadLocal 这个线程本地变量来存储每一次请求的 Model，这样就可以贯穿整个请求处理流程，下面使用 ThreadLocal 来协助完成异常日志的记录。

在绑定时，将绑定 Model 有存放到 ThreadLocal：

@RestController
@RequestMapping("/sys/user")
public class UserController {

public static final ThreadLocal<Object> MODEL_HOLDER = new ThreadLocal<>();

@InitBinder
public void initBinder(WebDataBinder webDataBinder) {
MODEL_HOLDER.set(webDataBinder.getTarget());
}

}

异常处理时，从 ThreadLocal 中取出变量，并做相应的日志输出：

@ControllerAdvice
@ResponseBody
public class ExceptionHandlerAdvice {

private Logger logger = LoggerFactory.getLogger(ExceptionHandlerAdvice.class);

@ExceptionHandler(Exception.class)
public Result handleException(Exception e, HttpServletRequest request) {
logger.error("uri={} | requestBody={}", request.getRequestURI(),
JSON.toJSONString(UserController.MODEL_HOLDER.get()));
return new Result(ResultCode.WEAK_NET_WORK);
}

}

当异常产生时，输出日志如下：

2017-05-03 21:46:07.177 ERROR 633 --- [nio-8080-exec-1] c.q.funda.advice.ExceptionHandlerAdvice  : uri=/sys/user/login | requestBody={"password":"123","username":"13632672222"}

注意：当 Mapping 方法中带有多个参数时，需要将 @RequestBody 绑定的变量当作方法的最后一个参数，否则 ThreadLocal 中的值将会被其它值所替换。如果需要输出 Mapping 方法中所有参数，可以在 ThreadLocal 里面存放一个 Map 集合。

项目的 github 地址：https://github.com/qchery/funda