优雅的实现Web日志打印

小知识，大挑战！本文正在参与“程序员必备小知识”创作活动。

本文已参与 「掘力星计划」 ，赢取创作大礼包，挑战创作激励金。

背景

在启动SpringBoot Web服务之后，我们往往期望对访问服务的流量打印日志，并通过日志来对系统的运行情况进行监控或是排查问题。在非web的服务中，我们可以通过对接口/方法加上Spring Aspect切面，从而对方法的出入参进行拦截并打印日志。但是在web服务中，切面无法获取到Web服务特有的并且较为重要的一些信息，比如请求的url，请求头，响应头等内容。本文将介绍如何使用Interceptor和Filter来优雅的实现Web服务的日志打印。

小试牛刀

既然想要打出和HTTP请求体相关的信息，我们就要先引入一个概念：Interceptor。Interceptor会在请求到达Controller前对请求和响应进行处理。一个Web服务中可以有多个Interceptor，它们会按照加入的顺序来依次执行：

@Configuration
public class MvcInterceptorsAutoConfiguration extends WebMvcConfigurerAdapter {
  

    public MvcInterceptorsAutoConfiguration() {
    }

    public void addInterceptors(InterceptorRegistry registry) {
        super.addInterceptors(registry);
        registry.addInterceptor(new InterceptorA());
        registry.addInterceptor(new InterceptorB());
        registry.addInterceptor(new InterceptorC());
    }

}

这段代码中拦截器执行的顺序为InterceptorA，InterceptorB和InterceptorC。

Interceptor在SpringBoot中被抽象成了HandlerInterceptor接口，这个接口下有三个方法，分别是preHandle,postHandle和afterCompletion。这三个方法分别在请求到达Controller之前，请求从Controller执行后回到拦截器，和所有拦截器执行完毕并完成Model的渲染时执行。

public interface HandlerInterceptor {

	boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler)
			throws Exception;

	void postHandle(
			HttpServletRequest request, HttpServletResponse response, Object handler, ModelAndView modelAndView)
			throws Exception;

	void afterCompletion(
			HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex)
			throws Exception;

}

如代码所示，这些接口中都会将当前线程的HTTP请求HttpServletRequest和响应HttpServletResponse传入到方法中，因此我们可以使用它们来获得HTTP消息体中的信息。具体的日志拦截器实现如下：

@Slf4j
@Component
public class WebServerLogInterceptor extends HandlerInterceptorAdapter {
    private static final String START_TIME_ATTRIBUTE_KEY = "_start_time";

    private static final String START_LOG_TEMPLATE = "[web_server_start] [method]:{} [path]:{} [url]:{} [header]:{} [params]:{}";

    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
        // 设置请求开始时间
        request.setAttribute(START_TIME_ATTRIBUTE_KEY, System.currentTimeMillis());

        // 打印开始日志
        printStartLog(request);

        return super.preHandle(request, response, handler);
    }

    @Override
    public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler, ModelAndView modelAndView) throws Exception {
        printFinishLog(request, wrapper);

        super.postHandle(request, response, handler, modelAndView);
    }

    private void printStartLog(HttpServletRequest request) {
        try {
            String method = request.getMethod();
            String path = request.getRequestURI();
            String url = request.getRequestURL().toString();
            String header = toHeaderString(request);
            String params = JSON.toJSONString(request.getParameterMap());
            log.info(START_LOG_TEMPLATE, method, path, url, header, params);

        } catch (Exception e) {
            log.error("failed to print request info, url:{} ex:{} params:{}", request.getRequestURI(), e.getMessage(), JSON.toJSONString(request.getParameterMap()), e);
        }
    }

    private String toHeaderString(HttpServletRequest request) {
        StringBuilder stringBuilder = new StringBuilder();
        Enumeration<String> headerNames = request.getHeaderNames();
        while (headerNames.hasMoreElements()) {
            String key = headerNames.nextElement();
            String value = request.getHeader(key);
            stringBuilder.append(key).append("=").append(value).append(" ");
        }
        return stringBuilder.toString();
    }

    private void printFinishLog(HttpServletRequest request, ContentCachingResponseWrapper responseWrapper) {

    	// 计算接口耗时
        long startTime = (long) request.getAttribute(START_TIME_ATTRIBUTE_KEY);
        long now = System.currentTimeMillis();
        double duration = (now - startTime) / 1000.0;
        
        log.info("[web_server_finish] status:{} duration:{}s", response.getStatus(), duration);
    }

}

@Configuration
public class WebConfig extends MvcInterceptorsAutoConfiguration {

    @Resource
    private ConversionService conversionService;
    @Resource
    private WebServerLogInterceptor webServerLogInterceptor;

    private static final String[] LOG_PATHS = {
            "/backend/**"
    };

    @Override
    public void addInterceptors(InterceptorRegistry registry) {
        super.addInterceptors(registry);
        registry.addInterceptor(webServerLogInterceptor).addPathPatterns(LOG_PATHS);
    }

 }

可以看到我们在preHandle方法中对HTTP请求中的内容进行打印，包括header，url，path等。并且在postHandler中打印了耗时和HTTP响应状态。但是，有一点可以注意到，postHandle方法中没有打印HTTP响应的日志。这是因为HttpServletResponse内部其实使用OutputStream对响应的内容进行管理，而流只能读取一次。一旦我们这里将输出流的内容打印出来，则后续的Inteceptor将丢失之前的消息体。

于是，我们又回到了最初的起点，掏出了工具箱中的切面，怒而加Controller上。。。

那么有没有办法获取到HttpServletResponse输出流内容的同时又不至于让流失效呢？这里就要引入ContentCachingResponseWrapper类。ContentCachingResponseWrapper对HttpServletResponse加了一层适配，它缓存了HTTP响应，并额外实现了一个方法copyBodyToResponse，调用这个方法后会将将缓存的内容重新写回到原始的HttpServletResponse的输出流中。可以将ContentCachingResponseWrapper想象成信使，信使带着信件前往各个驿站交换信息，并在交换完成后将得到的结果写回到信件上并回给发起者。

我们通过在Filter上对HttpServletResponse进行包装从而在Interceptor中可以获得加上缓存的输出流：

@Order(1)
@WebFilter(filterName = "webServerLogFilter", urlPatterns = "/*")
@Slf4j
public class WebServerLogFilter extends OncePerRequestFilter {

    @Override
    protected void doFilterInternal(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse, FilterChain filterChain) throws ServletException, IOException {
        // 增加一层IO输出流
        ContentCachingResponseWrapper responseWrapper = new ContentCachingResponseWrapper(httpServletResponse);

        try {
            filterChain.doFilter(httpServletRequest, responseWrapper);
        } finally {
            // 将输出流回给当前HttpServletResponse
            responseWrapper.copyBodyToResponse();

        }

    }
}

这里声明了一个Filter并对所有的路径生效，在filterChain中将httpServletResponse进行了替换，并在filter执行完成后将缓存中的响应流回写给原来的HttpServletResponse。

在Interceptor中我们就可以读取输出流中的内容了，这里使用IOUtils获取流中的数据:

@Slf4j
@Component
public class WebServerLogInterceptor extends HandlerInterceptorAdapter {
    private static final String START_TIME_ATTRIBUTE_KEY = "_start_time";

    private static final String LOG_ID = "logId";

    private static final String START_LOG_TEMPLATE = "[web_server_start] [method]:{} [path]:{} [url]:{} [header]:{} [params]:{}";

    private static final String FINISH_LOG_TEMPLATE = "[web_server_finish] [method]:{} [path]:{} [url]:{} [duration]:{}s [params]:{} [response]:{}";

    private static final String DIGEST_LOG_TEMPLATE = "[web_server_digest] [stressTag]:{} [host]:{} [clientIp]:{} [referer]:{} [method]:{} [path]:{} [url]:{} [duration]:{}s";

    @Override
    public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler, ModelAndView modelAndView) throws Exception {
        ContentCachingResponseWrapper wrapper = (ContentCachingResponseWrapper) response;

        printFinishLog(request, wrapper);

        super.postHandle(request, response, handler, modelAndView);
    }    

    private void printFinishLog(HttpServletRequest request, ContentCachingResponseWrapper responseWrapper) throws IOException {
        try {
            // 计算接口耗时
            long startTime = (long) request.getAttribute(START_TIME_ATTRIBUTE_KEY);
            long now = System.currentTimeMillis();
            double duration = (now - startTime) / 1000.0;

            // 从输出流中获取response信息
            String responseBody = IOUtils.toString(responseWrapper.getContentInputStream(), UTF_8);

            // 打印结束日志
            String host = request.getHeader("HOST");
            String clientIp = HttpHeaderUtil.getIp(request::getHeader, "0.0.0.0");
            String referer = request.getHeader("Referer");
            String method = request.getMethod();
            String fullPath = request.getRequestURI();
            String url = request.getRequestURL().toString();
            String params = JSON.toJSONString(request.getParameterMap());
            String stressTag = request.getHeader(TTHeaders.TT_STRESS_KEY);
            log.info(FINISH_LOG_TEMPLATE, method, fullPath, url, duration, params, responseBody);
            log.info(DIGEST_LOG_TEMPLATE, stressTag, host, clientIp, referer, method, fullPath, url, duration);
        } catch (Exception e) {
            log.error("failed to print response info, url:{} ex:{}", request.getRequestURI(), e.getMessage(), e);
        }
    }

}

Filter vs Interceptor

这里你可能会想，为什么需要额外声明一个Filter来对输出流进行封装，而不是直接在Interceptor的postHandle方法中进行处理。这里就要简单提一下Filter和Interceptor的区别，先看下面这张图：

Filter其实是独立于具体的Servlet容器存在的，它在请求到达容器之前对其进行过滤。也就是说Filter可以决定这个请求是否传递给容器，也可以决定响应是否传递回调用方。Interceptor则介于分流器DispatcherServlet和具体的处理逻辑Controller之间，因此Interceptor可以感知到具体处理的Controller和Method，对于需要Controller维度或是Method维度进行处理的逻辑可以放在Interceptor中实现。

虽然二者都可以感知到请求响应，Filter的功能其实相对而言更加强大，因为它不仅能够修改请求响应的内容，还可以整个替换掉传给下游的请求响应对象，就如上文中提到的用ContentCachingResponseWrapper包装了HttpServletResponse后用新的响应流向下透传。而Interceptor并不能做这样的处理。

但是，Spring提供的HandlerInterceptor也有其强大的特性。因为其处在Spring容器中，从而可以访问到Spring上下文中的内容，比如SpringBoot web中的ModelAndView对象等，因此可以进行更细致的处理。

那么什么时候使用Filter什么时候使用Interceptor呢？通常来说，和应用无关的处理可以放在Filter中，而更细致的和具体应用相关的则可以放在Interceptor中处理。 这里给出Filter和Interceptor常见的使用场景：

Filter

• 系统安全管控
• 图片压缩和解压缩
• 数据加密和解密

Interceptor

• 应用入口处日志
• 应用维度的日志

完整代码

@Slf4j
@Component
public class WebServerLogInterceptor extends HandlerInterceptorAdapter {
    private static final String START_TIME_ATTRIBUTE_KEY = "_start_time";

    private static final String START_LOG_TEMPLATE = "[web_server_start] [method]:{} [path]:{} [url]:{} [header]:{} [params]:{}";

    private static final String FINISH_LOG_TEMPLATE = "[web_server_finish] [method]:{} [path]:{} [url]:{} [duration]:{}s [params]:{} [response]:{}";

    private static final String DIGEST_LOG_TEMPLATE = "[web_server_digest] [stressTag]:{} [host]:{} [clientIp]:{} [referer]:{} [method]:{} [path]:{} [url]:{} [duration]:{}s";

    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
        // 设置请求开始时间
        request.setAttribute(START_TIME_ATTRIBUTE_KEY, System.currentTimeMillis());

        // 打印开始日志
        printStartLog(request);

        return super.preHandle(request, response, handler);
    }

    @Override
    public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler, ModelAndView modelAndView) throws Exception {
        ContentCachingResponseWrapper wrapper = (ContentCachingResponseWrapper) response;

        printFinishLog(request, wrapper);

        super.postHandle(request, response, handler, modelAndView);
    }

    private void printStartLog(HttpServletRequest request) {
        try {
            String method = request.getMethod();
            String path = request.getRequestURI();
            String url = request.getRequestURL().toString();
            String header = toHeaderString(request);
            String params = JSON.toJSONString(request.getParameterMap());
            log.info(START_LOG_TEMPLATE, method, path, url, header, params);

        } catch (Exception e) {
            log.error("failed to print request info, url:{} ex:{} params:{}", request.getRequestURI(), e.getMessage(), JSON.toJSONString(request.getParameterMap()), e);
        }
    }

    private String toHeaderString(HttpServletRequest request) {
        StringBuilder stringBuilder = new StringBuilder();
        Enumeration<String> headerNames = request.getHeaderNames();
        while (headerNames.hasMoreElements()) {
            String key = headerNames.nextElement();
            String value = request.getHeader(key);
            stringBuilder.append(key).append("=").append(value).append(" ");
        }
        return stringBuilder.toString();
    }

    private void printFinishLog(HttpServletRequest request, ContentCachingResponseWrapper responseWrapper) {
        try {
            // 计算接口耗时
            long startTime = (long) request.getAttribute(START_TIME_ATTRIBUTE_KEY);
            long now = System.currentTimeMillis();
            double duration = (now - startTime) / 1000.0;

            // 从输出流中获取response信息
            String responseBody = IOUtils.toString(responseWrapper.getContentInputStream(), UTF_8);

            // 打印结束日志
            String host = request.getHeader("HOST");
            String clientIp = HttpHeaderUtil.getIp(request::getHeader, "0.0.0.0");
            String referer = request.getHeader("Referer");
            String method = request.getMethod();
            String fullPath = request.getRequestURI();
            String url = request.getRequestURL().toString();
            String params = JSON.toJSONString(request.getParameterMap());
            String stressTag = request.getHeader(TTHeaders.TT_STRESS_KEY);
            log.info(FINISH_LOG_TEMPLATE, method, fullPath, url, duration, params, responseBody);
            log.info(DIGEST_LOG_TEMPLATE, stressTag, host, clientIp, referer, method, fullPath, url, duration);
        } catch (Exception e) {
            log.error("failed to print response info, url:{} ex:{}", request.getRequestURI(), e.getMessage(), e);
        }
    }

}


@Order(1)
@WebFilter(filterName = "webServerLogFilter", urlPatterns = "/*")
@Slf4j
public class WebServerLogFilter extends OncePerRequestFilter {

    @Override
    protected void doFilterInternal(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse, FilterChain filterChain) throws ServletException, IOException {
        // 增加一层IO输出流
        ContentCachingResponseWrapper responseWrapper = new ContentCachingResponseWrapper(httpServletResponse);

        try {
            filterChain.doFilter(httpServletRequest, responseWrapper);
        } finally {
            // 将输出流回给当前HttpServletResponse
            responseWrapper.copyBodyToResponse();

        }

    }
}

@Configuration
public class WebConfig extends MvcInterceptorsAutoConfiguration {

    @Resource
    private WebServerLogInterceptor webServerLogInterceptor;

    private static final String[] LOG_PATHS = {
            "/backend/**"
    };

    @Override
    public void addInterceptors(InterceptorRegistry registry) {
        super.addInterceptors(registry);
        registry.addInterceptor(webServerLogInterceptor).addPathPatterns(LOG_PATHS);
    }
}