【日志追蹤】（微服務應用和單體應用）-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