【日志追踪】（微服务应用和单体应用）-logback中的MDC机制
一.MDC介绍
MDC（Mapped Diagnostic Contexts）映射诊断上下文，该特征是logback提供的一种方便在多线程条件下的记录日志的功能，
某些应用程序采用多线程的方式来处理多个用户的请求。在一个用户的使用过程中，可能有多个不同的线程来进行处理。典型的例子是 Web 应用服务器。当用户访问某个页面时，应用服务器可能会创建一个新的线程来处理该请求，也可能从线程池中复用已有的线程。在一个用户的会话存续期间，可能有多个线程处理过该用户的请求。这使得比较难以区分不同用户所对应的日志。当需要追踪某个用户在系统中的相关日志记录时，就会变得很麻烦。
MDC正是用于解决上述问题的，MDC 可以看成是一个与当前线程绑定的哈希表，可以往其中添加键值对。MDC 中包含的内容可以被同一线程中执行的代码所访问。当前线程的子线程会继承其父线程中的 MDC 的内容。当需要记录日志时，只需要从 MDC 中获取所需的信息即可。MDC 的内容则由程序在适当的时候保存进去。对于一个 Web 应用来说，通常是在请求被处理的最开始保存这些数据。
通俗点来说：
MDC为每一个请求创建一条独立的可识别的的日志，方便追踪和查看，特别是在分布式系统中，分布式日志追踪往往对于问题诊断是特别重要的；
二.MDC在单体应用中的案例
环境：JDK8+Springboot2.x（已经默认集成了logback日志框架）
过滤器或者拦截器中设置MDC日志，为了尽量每个请求尽量唯一，这里使用UUID作为ID
/** * @author: Gabriel * @date: 2020/1/28 21:14 * @description 过滤器 */ @Slf4j @Component @WebFilter(urlPatterns = "/**",filterName = "tlFilter") public class ThreadLocalFilter implements Filter { @Override public void init(FilterConfig filterConfig) throws ServletException { log.info("过滤器初始化"); } @Override public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse, FilterChain filterChain) throws IOException, ServletException { //添加MDC日志 String logtrackId = UUID.randomUUID(true).toString(); MDC.put("logTrackId",logtrackId); log.info("过滤器执行中"); try { filterChain.doFilter(servletRequest, servletResponse); }finally{ //移除MDC日志 MDC.remove(logtrackId); } log.info("过滤器执行完成"); } @Override public void destroy() { log.info("过滤器销毁"); } }
logback.xml配置文件
日志输出需要添加 %X{logTrackId} 其中logTrackId为MDC的key值
<?xml version="1.0" encoding="UTF-8"?> <configuration scan="true" scanPeriod="60 seconds" debug="false"> <!--定义日志文件的存储地址 勿在 LogBack 的配置中使用相对路径 注意：如果部署在在linux系统中 这里可以文件路径替换为linux文件路径即可--> <property name="LOG_HOME" value="src/main/resources/log.properties"/> <!--<property name="LOG_HOME" value="/Users/weibinbin/logs/carton"/>--> <!-- 控制台输出 --> <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder"> <!--格式化输出：%d表示日期，%-5level：级别从左显示5个字符宽度%msg：日志消息，%n是换行符--> <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level [%c-%L][%X{logTrackId}] %msg%n</pattern> <charset>UTF-8</charset> <!-- 此处设置字符集 --> </encoder> <filter class="ch.qos.logback.classic.filter.LevelFilter"> <level>INFO</level> </filter> </appender> <!-- 按照每天生成info日志文件 --> <appender name="infoLog" class="ch.qos.logback.core.rolling.RollingFileAppender"> <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder"> <!--格式化输出：%d表示日期，%-5level：级别从左显示5个字符宽度%msg：日志消息，%n是换行符--> <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level [%c-%L][%X{logTrackId}] %msg%n</pattern> <charset>UTF-8</charset> <!-- 此处设置字符集 --> </encoder> <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy"> <!--日志文件输出的文件名--> <FileNamePattern>${LOG_HOME}/info/info.%d{yyyyMMdd}.%i.log</FileNamePattern> <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP"> <!-- or whenever the file size reaches 64 MB --> <maxFileSize>500 MB</maxFileSize> </timeBasedFileNamingAndTriggeringPolicy> <!--日志文件保留天数--> <maxHistory>365</maxHistory> </rollingPolicy> <filter class="ch.qos.logback.classic.filter.LevelFilter"> <level>INFO</level> </filter> <prudent>false</prudent> </appender> <!-- 按照每天生成error日志文件 --> <appender name="errorLog" class="ch.qos.logback.core.rolling.RollingFileAppender"> <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder"> <!--格式化输出：%d表示日期，%-5level：级别从左显示5个字符宽度 %msg：日志消息，%n是换行符--> <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level [%c-%L][%X{logTrackId}] %msg%n</pattern> <charset>UTF-8</charset> <!-- 此处设置字符集 --> </encoder> <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy"> <!--日志文件输出的文件名--> <FileNamePattern>${LOG_HOME}/error/error.%d{yyyyMMdd}.%i.log</FileNamePattern> <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP"> <!-- or whenever the file size reaches 64 MB --> <maxFileSize>500 MB</maxFileSize> </timeBasedFileNamingAndTriggeringPolicy> <!--日志文件保留天数--> <maxHistory>365</maxHistory> </rollingPolicy> <filter class="ch.qos.logback.classic.filter.LevelFilter"> <level>ERROR</level> <onMatch>ACCEPT</onMatch> <onMismatch>DENY</onMismatch> </filter> <prudent>false</prudent> </appender> <!-- 日志输出级别 --> <root level="INFO"> <appender-ref ref="STDOUT"/> <appender-ref ref="infoLog"/> <appender-ref ref="errorLog"/> </root> </configuration>
测试
三.MDC在分布式系统中的应用
这里以SpringCloud微服务框架来说明 日志请求链路
1.网关服务（以Zuul为例）在预处理过滤器中，在请求进行路由之前设置MDC 日志ID，传递到下游的应用服务
/** * @Author: Gabriel * @Date: 2019/6/30 12:37 * @Version 1.0 * @Discription Zuul API网关过滤器 */ @Slf4j @Component public class AccessFilter extends ZuulFilter { /** * 过滤器的4中类型 pre：请求在被路由之前执行 routing：在路由请求时调用 post：在routing和errror过滤器之后调用 error：处理请求时发生错误调用 */ @Override public String filterType() { return "pre"; } /** * 过滤器的顺序 * 数字越小,越被优先被执行 * @return */ @Override public int filterOrder() { return 0; } /** * 过滤器是否被执行 * 返回true / false * 实际运用中我们可以利用该方法来指定过滤器的有效范围 * @return */ @Override public boolean shouldFilter() { return true; } /** * 过滤器执行的具体逻辑 * 这里的例子是校验头信息中是否有accessToken 这个信息 * @return * @throws ZuulException */ @Override public Object run() throws ZuulException { String logTrackId = UUID.randomUUID().toString(); MDC.put("logTrackId", logTrackId); //获取请求上下文对象 RequestContext ctx = RequestContext.getCurrentContext(); HttpServletRequest request = ctx.getRequest(); //添加请求头 ctx.addZuulRequestHeader("logTrackId", logTrackId); //打印日志 log.info("send {} request to {}", request.getMethod(),request.getRequestURL().toString()); // ...省略相关业务代码,主要演示日志链路 return null; } }
2.应用服务 拦截器中收到网关请求头传递过来的MDC 日志ID，进行PUT到本次请求关联的先成功中，请求执行完成后，销毁该日志ID
/** * @author: Gabriel * @date: 2020/2/9 1:02 * @description 拦截器 */ @Slf4j @Component public class URIInterceptor implements HandlerInterceptor { @Override public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception { // 统一日志标记 String logTrackId = request.getHeader("logTrackId"); if (StringUtils.isEmpty(logTrackId)) { logTrackId = String.valueOf(System.currentTimeMillis()); } MDC.put("logTrackId", logTrackId); request.setCharacterEncoding("UTF-8"); request.setAttribute("interfaceStartTime", System.currentTimeMillis()); response.setCharacterEncoding("UTF-8"); response.setHeader("content-type", "text/html;charset=UTF-8"); String uri = request.getRequestURI(); String method = request.getMethod(); String userAgent = request.getHeader("User-Agent"); log.info(String.format("##########【%s】，%s，%s", uri, method, userAgent)); return true; } @Override public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler, ModelAndView modelAndView) throws Exception { } @Override public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Exception { String uri = request.getRequestURI(); String method = request.getMethod(); long interfaceStartTime = (Long) request.getAttribute("interfaceStartTime"); long interfaceEndTime = System.currentTimeMillis(); long times = interfaceEndTime - interfaceStartTime; if (times > 1000) { log.info(String.format("==========【%s】，%s，耗时：%s，请检查是否异常", uri, method, times)); } else { log.info(String.format("==========【%s】，%s，耗时：%s", uri, method, times)); } MDC.remove("logTrackId"); } }
拦截器注册
/** * @author: Gabriel * @date: 2020/2/9 1:08 * @description 拦截器注册 */ @Configuration @Order public class MyWebMvcConfig implements WebMvcConfigurer { @Autowired private URIInterceptor uriInterceptor; @Override public void addInterceptors(InterceptorRegistry registry) { registry.addInterceptor(uriInterceptor).addPathPatterns("/**"); } }
Gabriel
