通过slf4j/log4j的MDC/NDC 实现日志追踪

在分布式系统或者较为复杂的系统中，我们希望可以看到一个客户请求的处理过程所涉及到的所有子系统模块的处理日志。

由于slf4j/log4j基本是日志记录的标准组件，所以slf4j/log4j成为了我的重点研究对象。

slf4j/log4j支持MDC，可以实现同一请求的日志追踪功能。

基本思路是：

实现自定义Filter，在接受到http请求时，计算eventID并存储在MDC中。如果涉及分布式多系统，那么向其他子系统发送请求时，需要携带此eventID。

源代码：https://github.com/athinboy/studyjava.git

其中：

response.setHeader("eventsign", eventsign);
很有用，返回的response中，将有httpheader：eventsign:000010x1489108079237

log4j日志格式配置为：

log4j.appender.stdout.layout.ConversionPattern=%d  %logger-%5p - %X{eventid} - %m%n

在web.xml中配置自定义filter:

 1     <!--start  log4jfilter-->
 2     <filter>
 3         <filter-name>log4jfilter</filter-name>
 4         <filter-class>org.fgq.study.log4j.Log4jFilter</filter-class>
 5         <init-param>
 6             <param-name>sign</param-name>
 7             <param-value>000010x</param-value>
 8         </init-param>
 9      </filter>
10     <filter-mapping>
11         <filter-name>log4jfilter</filter-name>
12         <url-pattern>/*</url-pattern>
13     </filter-mapping>  
14     <!--end  log4jfilter-->

web.xml配置

doFilterInternal方法：

 1     protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain) throws ServletException, IOException {
 2 
 3         String eventsign;
 4 
 5         if (request.getHeader("eventsign") == null || request.getHeader("eventsign").length() == 0) {
 6             eventsign = this.sign + String.valueOf(new Date().getTime()); //计算eventID
 7 
 8             logger.error("set eventid:" + eventsign);
 9         } else {
10             eventsign = request.getHeader("eventsign");//从请求端获取eventsign
11             logger.error("get eventid from request:" + eventsign);
12 
13         }
14 
15         MDC.put("eventid",  eventsign);
16         response.setHeader("eventsign", eventsign);
17         filterChain.doFilter(request, response);
18 
19 
20     }

Log4jFilter-doFilterInternal

测试结果：

1、

Request URL:http://localhost:8084/spmvc/index.html
Request Method:GET
Status Code:304 Not Modified
Remote Address:[::1]:8084

Response Headers
Date:Fri, 10 Mar 2017 03:20:01 GMT
ETag:W/"660-1489115626000"
eventsign:000010x1489116001756

服务器端日志：
2017-03-10 11:20:01,756 org.fgq.study.log4j.Log4jFilter.doFilterInternal(Log4jFilter.java:59)ogger-ERROR - - set eventid:000010x1489116001756

2、
Request URL:http://localhost:8084/spmvc/mv/mvc/time?id=1
Request Method:GET
Status Code:200 OK
Remote Address:[::1]:8084

Response Headers
Content-Language:zh-CN
Content-Type:text/html;charset=utf-8
Date:Fri, 10 Mar 2017 03:21:02 GMT
Server:Apache-Coyote/1.1
Transfer-Encoding:chunked

Request Headers
Accept:*/*
Accept-Encoding:gzip, deflate, sdch, br
Accept-Language:zh-CN,zh;q=0.8
Connection:keep-alive
Cookie:eryewrhuewr
eventsign:eventsignOfQequest

服务器端日志：
2017-03-10 11:21:02,378 org.fgq.study.log4j.Log4jFilter.doFilterInternal(Log4jFilter.java:62)ogger-ERROR - - get eventid from request:eventsignOfQequest
2017-03-10 11:21:02,555 org.fgq.study.controller.TimeController.ShowTime(TimeController.java:34)ogger- WARN - 000010xeventsignOfQequest - get eventid:eventsignOfQequest, send request to other sub system ,and with the eventid!

返回内容：the eventsign is : eventsignOfQequest

参考： https://logback.qos.ch/manual/mdc.html