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
}
@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