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 实现如下：

@ControllerAdvicepublic 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 实现如下：

@ControllerAdvicepublic 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@ResponseBodypublic 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