springboot filter and interceptor实战之mdc日志打印

1.1  mdc日志打印全局控制

1.1.1    logback配置

<property name="log.pattern" value="%d{yyyy-MM-dd'T'HH:mm:ss.SSSXXX}%level [%thread] [%logger{50}:%line] [uuid:%X{operation_id}] %msg%n"></property>

1.1.2    filter配置

@WebFilter(filterName="logFilter", urlPatterns="/*")

public class LogFilter implements Filter {

    private static final Logger log = LoggerFactory.getLogger(LogInterceptor.class);

   

    @Override

    public void init(FilterConfig filterConfig) throws ServletException {

        log.info("---------log filter init");

    }

 

    @Override

    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain)

            throws IOException, ServletException {

        log.info("log filter doFilter");

        ServletRequest requestWrapper = null;

        requestWrapper = new MyRequestWrapper((HttpServletRequest) request);

        chain.doFilter(requestWrapper, response);

    }

 

    @Override

    public void destroy() {

        log.info("-------------log filter destroy");

       

    }

}

同时需要在启动类加上扫描配置

@SpringBootApplication()

@ServletComponentScan       //扫描过滤器

public class LogApplication {

 

   public static void main(String[] args) {

       Tools.setMdc(Tools.getUuid());

      SpringApplication.run(LogApplication.class, args);

   }

}

1.1.3    自定义httpServletRequest

public class MyRequestWrapper extends HttpServletRequestWrapper {

    private String body;
    private String requestMethod;
    
    public MyRequestWrapper(HttpServletRequest request) throws IOException {
        super(request);
        StringBuilder sb = new StringBuilder();
        String line = null;
        BufferedReader reader = request.getReader();
        requestMethod = request.getMethod();
        
        while((line = reader.readLine()) != null) {
            sb.append(line);
        }
        body = sb.toString();
    }
    private boolean isPostOrPut() {
        return "POST".equalsIgnoreCase(requestMethod) || "PUT".equalsIgnoreCase(requestMethod);
    }
    @Override
    public String getQueryString() {
        if(isPostOrPut()) {
            return body;
        } else {
            return super.getQueryString();
        }
    }
    @Override
    public ServletInputStream getInputStream() throws IOException {
        ByteArrayInputStream bais = new ByteArrayInputStream(body.getBytes(CommonVar.DEFAULT_CHARSET));
        return new ServletInputStream() {
            
            @Override
            public int read() throws IOException {
                return bais.read();
            }

            @Override
            public boolean isFinished() {
                return bais.available()==0;
            }

            @Override
            public boolean isReady() {
                return true;
            }

            @Override
            public void setReadListener(ReadListener listener) {
                
            }
        };
    }
}

1.1.4    interceptor配置

public class LogInterceptor implements HandlerInterceptor{
    private static final Logger log = LoggerFactory.getLogger(LogInterceptor.class);
    
    private static final String REQUEST_START_TIME = "request_start_time";
    
    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler)
            throws Exception {
        setMdc(request);
        logRequestMsg(request);
        request.setAttribute(REQUEST_START_TIME, System.currentTimeMillis());
        System.out.println("preHandle");
        return true;
    }

    @Override
    public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler,
            ModelAndView modelAndView) throws Exception {
        HandlerInterceptor.super.postHandle(request, response, handler, modelAndView);
        System.out.println("postHandle");
    }

    @Override
    public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex)
            throws Exception {
        logRequestEnd(request);
        Tools.removeMdc();
        System.out.println("afterCompletion");
    }
    private void setMdc(HttpServletRequest request) {
        MDC.put("operation_id", Tools.getUuid());
    }
    /**
     * log request url and request cost time
     * @param request
     */
    private void logRequestEnd(HttpServletRequest request) {
        long startTime = (long) request.getAttribute(REQUEST_START_TIME);
        long endTime = System.currentTimeMillis();
        long interval = endTime - startTime;
        log.debug("request_end: {}, cost time:{}ms",request.getRequestURL(), interval);
    }
    /**
     * log request url and param
     * @param request 
     * @throws IOException
     */
    private void logRequestMsg(HttpServletRequest request) throws IOException {
        String url = request.getRequestURL().toString();
        String method = request.getMethod();
        String query = request.getQueryString();
        log.debug("request_receive: url:{},method:{},query:{}", url, method, query);
    }
}

新建config类将interceptor注册到spring

@Configuration
public class LogWebAppConfig implements WebMvcConfigurer  {

    @Override
    public void addInterceptors(InterceptorRegistry registry) {
        registry.addInterceptor(new LogInterceptor()).addPathPatterns("/**");
        WebMvcConfigurer.super.addInterceptors(registry);
    }
    
}

1.1.5    总体说明

1.1.5.1   功能说明

打印请求url，请求类型，请求参数

打印所有的请求耗时统计

使用logback的MDC机制打印日志，不了解的自行百度

1.1.5.2   问题（功能1）

post，put请求的参数在流里面，只能读取一次，如果在拦截器中读取了流，流就空了，controller层读取会报错。报错信息：

getReader() has already been called for this request preHandle

1.1.5.3 解决思想（功能1）

自定义一个httpServletRequest，提供post参数读取的方法（读完流之后将数据重新写回流中），然后重写getQueryString()方法。这个方法是get等请求获取参数的方式，在这里同样提供post请求的参数，减轻调用者的负担

使用过滤器过滤所有的请求，替换httpServletRequest为自定义的request，传递给下一条链

由于过滤器已经替换httpServletRequest，那么这里拿到的就是自定义的httpServletRequest，所以可以不用区分请求类型，直接调用getQueryString() 获取请求参数

1.1.5.4             其它功能实现

打印所有的请求耗时统计

　　实现方式是在拦截器中为request增加一个字段（本文是request_start_time），记录当前时间，在方法调用完成后从request中拿到这个字段（起始时间），根据当前时间算出调用时间间隔。

使用logback打印MDC日志

      需要在logback中配置这么一个字段（本文是operation_id），然后在拦截器的入口为这个字段设置一个uuid即可。作用是每个请求对应的日志都有这个uuid。mdc实现原理是threadLocal，所以对于线程池需要额外处理方式。

1.1.6    结果

2018-12-08T11:46:23.916+08:00 INFO [localhost-startStop-1] [com.hikvision.log.common.filter.LogInterceptor:23] [uuid:] ---------log filter init

2018-12-08T11:46:33.307+08:00 INFO [http-nio-8080-exec-3] [com.hikvision.log.common.filter.LogInterceptor:29] [uuid:] log filter doFilter

2018-12-08T11:46:33.307+08:00 INFO [http-nio-8080-exec-2] [com.hikvision.log.common.filter.LogInterceptor:29] [uuid:] log filter doFilter

2018-12-08T11:46:33.307+08:00 INFO [http-nio-8080-exec-1] [com.hikvision.log.common.filter.LogInterceptor:29] [uuid:] log filter doFilter

2018-12-08T11:46:33.326+08:00 DEBUG [http-nio-8080-exec-1] [com.hikvision.log.common.filter.LogInterceptor:67] [uuid:0002] request_receive: url:http://127.0.0.1:8080/settings,method:GET,query:null

preHandle

2018-12-08T11:46:33.326+08:00 DEBUG [http-nio-8080-exec-2] [com.hikvision.log.common.filter.LogInterceptor:67] [uuid:0003] request_receive: url:http://127.0.0.1:8080/meta,method:GET,query:null

preHandle

2018-12-08T11:46:33.328+08:00 DEBUG [http-nio-8080-exec-3] [com.hikvision.log.common.filter.LogInterceptor:67] [uuid:0004] request_receive: url:http://127.0.0.1:8080/session,method:GET,query:null

preHandle

2018-12-08T11:46:33.368+08:00 INFO [http-nio-8080-exec-2] [com.hikvision.log.web.restful.CheckDiskController:45] [uuid:0003] Get availableSpace is:173138524

2018-12-08T11:46:33.369+08:00 INFO [http-nio-8080-exec-2] [com.hikvision.log.web.restful.CheckDiskController:49] [uuid:0003] Get omcVersion is:

postHandle

2018-12-08T11:46:33.453+08:00 DEBUG [http-nio-8080-exec-3] [com.hikvision.log.common.filter.LogInterceptor:56] [uuid:0004] request_end: http://127.0.0.1:8080/session, cost time:124ms

afterCompletion

postHandle

2018-12-08T11:46:33.455+08:00 DEBUG [http-nio-8080-exec-2] [com.hikvision.log.common.filter.LogInterceptor:56] [uuid:0003] request_end: http://127.0.0.1:8080/meta, cost time:129ms

afterCompletion

postHandle

2018-12-08T11:46:33.473+08:00 DEBUG [http-nio-8080-exec-1] [com.hikvision.log.common.filter.LogInterceptor:56] [uuid:0002] request_end: http://127.0.0.1:8080/settings, cost time:147ms

afterCompletion