Gracefully implement Web log printing

Small knowledge, big challenge! This article is participating in the creation activity of “Essential Tips for Programmers”.

This article has participated in the “Digitalstar Project” and won a creative gift package to challenge the creative incentive money.

background

After starting the SpringBoot Web service, we often expect to print a log of the traffic accessing the service, and use the log to monitor the operating status of the system or troubleshoot problems. In a non-Web service, we can intercept and log method entry and exit arguments by adding Spring Aspect facets to the interface/method. In a Web service, however, the aspect does not get the important information that is unique to the Web service, such as the URL of the request, the request header, the response, and so on. This article will show you how to use Interceptor and Filter to implement log printing elegantly for Web services.

A profound

In order to type information related to the HTTP request body, we need to introduce a concept: Interceptor. The Interceptor processes the request and response before it reaches the Controller. There can be multiple interceptors in a Web service, and they are executed in the order in which they are added:

@Configuration
public class MvcInterceptorsAutoConfiguration extends WebMvcConfigurerAdapter {
  

    public MvcInterceptorsAutoConfiguration(a) {}public void addInterceptors(InterceptorRegistry registry) {
        super.addInterceptors(registry);
        registry.addInterceptor(new InterceptorA());
        registry.addInterceptor(new InterceptorB());
        registry.addInterceptor(newInterceptorC()); }}Copy the code

This code is InterceptorA, InterceptorB, and InterceptorC.

The Interceptor is abstracted from SpringBoot into the HandlerInterceptor interface, which has three methods: preHandle,postHandle, and afterCompletion. These methods are executed before the request reaches the Controller, after the request is executed from the Controller back to the interceptor, and after all interceptors have executed and finished rendering the 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;

}

Copy the code

As the code shows, each of these interfaces passes the current thread’s HTTP request HttpServletRequest and response HttpServletResponse into the method, so we can use them to get information from the BODY of the HTTP message. The specific log interceptor implementation is as follows:

@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 {
        // Set the request start time
        request.setAttribute(START_TIME_ATTRIBUTE_KEY, System.currentTimeMillis());

        // Prints the start log
        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) {

    	// Calculate the interface time
        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); }}Copy the code

You can see that in the preHandle method we print the contents of the HTTP request, including headers, URLS, path, and so on. The elapsed time and HTTP response status are printed in postHandler. One thing to note, however, is that the postHandle method does not print the HTTP response log. This is because HttpServletResponse internally uses an OutputStream to manage the content of the response, which can only be read once. Once we print out the contents of the output stream here, subsequent Inteceptor will lose the previous message body.

So, we returned to the original starting point, took out the toolbox of the cut, anger and add Controller…

Is there a way to get the content of the HttpServletResponse output stream without losing it? Here will introduce ContentCachingResponseWrapper class. ContentCachingResponseWrapper added a layer of adaptation to the HttpServletResponse, it caches the HTTP response, and additional copyBodyToResponse implements a method, Calling this method writes the cached contents back into the output stream of the original HttpServletResponse. Might think ContentCachingResponseWrapper as Courier, Courier takes a letter to the post exchange information, and after completion of the exchange will be written back to the result of the letter and back to the initiator.

We get a cached output stream from the Interceptor by wrapping HttpServletResponse on the Filter:

@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 {
        // Add a layer of IO output streams
        ContentCachingResponseWrapper responseWrapper = new ContentCachingResponseWrapper(httpServletResponse);

        try {
            filterChain.doFilter(httpServletRequest, responseWrapper);
        } finally {
            // Return the output stream to the current HttpServletResponseresponseWrapper.copyBodyToResponse(); }}}Copy the code

A Filter is declared and applies to all paths, httpServletResponse is replaced in the filterChain, and the cached response flows back to the original httpServletResponse after the Filter execution is complete.

In the Interceptor, we can read from the output stream. Here we use IOUtils to get data from the stream:

@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 {
            // Calculate the interface time
            long startTime = (long) request.getAttribute(START_TIME_ATTRIBUTE_KEY);
            long now = System.currentTimeMillis();
            double duration = (now - startTime) / 1000.0;

            // Get response information from the output stream
            String responseBody = IOUtils.toString(responseWrapper.getContentInputStream(), UTF_8);

            // Prints the end log
            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); }}}Copy the code

Filter vs Interceptor

Here you may be wondering why you need to declare an extra Filter to encapsulate the output stream, rather than processing it directly in the Interceptor’s postHandle method. Here’s a quick reference to the difference between a Filter and a Interceptor:

The Filter exists independently of the specific Servlet container and filters requests before they reach the container. That is, the Filter can determine whether the request is passed to the container or whether the response is passed back to the caller. The Interceptor is in between the DispatcherServlet and the Controller of the specific processing logic, so the Interceptor is aware of the Controller and Method of the specific processing. Logic that needs to be handled in the Controller or Method dimension can be implemented in the Interceptor.

Although both are aware of the request response, the Filter is relatively more powerful because it can not only modify the content of the request response, but also replace the entire request response object passed downstream. As mentioned in the packing in ContentCachingResponseWrapper the HttpServletResponse with a new response to passthrough. The Interceptor doesn’t do this.

However, the HandlerInterceptor provided by Spring also has its own powerful features. Because it is in the Spring container, it has access to content in the Spring context, such as the ModelAndView object in the SpringBoot Web, so it can be processed more carefully.

So when do you use a Filter and when do you use an Interceptor? Generally speaking, application-independent processing can be placed in the Filter, while more detailed application-specific processing can be placed in the Interceptor. Here are some common usage scenarios for filters and interceptors:

Filter

• System Security Control
• Image compression and decompression
• Data encryption and decryption

Interceptor

• Application entry Logs
• Application dimension logs

The complete code

@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 {
        // Set the request start time
        request.setAttribute(START_TIME_ATTRIBUTE_KEY, System.currentTimeMillis());

        // Prints the start log
        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 {
            // Calculate the interface time
            long startTime = (long) request.getAttribute(START_TIME_ATTRIBUTE_KEY);
            long now = System.currentTimeMillis();
            double duration = (now - startTime) / 1000.0;

            // Get response information from the output stream
            String responseBody = IOUtils.toString(responseWrapper.getContentInputStream(), UTF_8);

            // Prints the end log
            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 {
        // Add a layer of IO output streams
        ContentCachingResponseWrapper responseWrapper = new ContentCachingResponseWrapper(httpServletResponse);

        try {
            filterChain.doFilter(httpServletRequest, responseWrapper);
        } finally {
            // Return the output stream to the current HttpServletResponseresponseWrapper.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); }}Copy the code