单机服务日志跟踪traceId

生产环境出问题，我们都是通过看日志来排查问题，但是一个请求内部调用了哪些方法我们不知道，排查问题比较麻烦。这时候我们需要使用traceId来跟踪一次请求的路径，这样看日志的时候会方便很多。

成熟的日志跟踪系统有很多，比如logstash，ZipKin、鹰眼等，但这些系统都比较庞大，使用起来会比较繁琐，还需要安装其他一些工具，但是他们的功能很齐全。如果只是想简单的跟踪下日志，那么也可以自己来实现。下面讲解下如何自己来实现日志跟踪。

想法：我们可以使用拦截器来对请求做拦截，给每个请求生成一个唯一的标识，然后把唯一标识加入到日志中。
解决：看了下日志相关的文档，发现MDC这个东西不错，正是我们需要的，他是Mapped Diagnostic Context的缩写（映射调试上下文），MDC是 log4j 和 logback 提供的一种方便在多线程条件下记录日志的功能。MDC 可以看成是一个与当前线程绑定的Map，可以往其中添加键值对。MDC 中包含的内容可以被同一线程中执行的代码所访问。当前线程的子线程会继承其父线程中的 MDC 的内容。当需要记录日志时，只需要从 MDC 中获取所需的信息即可。MDC 的内容则由程序在适当的时候保存进去。对于一个 Web 应用来说，通常是在请求被处理的最开始保存这些数据。

首先创建拦截器

package com.xxx.interceptor;


import com.google.common.collect.Lists;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;
import org.springframework.stereotype.Component;
import org.springframework.web.servlet.ModelAndView;
import org.springframework.web.servlet.handler.HandlerInterceptorAdapter;

import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import java.util.Enumeration;
import java.util.List;
import java.util.UUID;


@Component
public class LogInterceptor extends HandlerInterceptorAdapter {
    private final Logger logger = LoggerFactory.getLogger(LogInterceptor.class);
    private String executeTime = "executeTime";

    @Override
    public boolean preHandle(HttpServletRequest req, HttpServletResponse res, Object arg2) throws Exception {
        //开始时间
        long beginTime = System.currentTimeMillis();
        ThreadLocalUtil.setData(executeTime, beginTime);

        String traceId = UUID.randomUUID().toString().replaceAll("-", "");
        MDC.put("traceId",  String.format("(traceId:%s)",traceId));

        logger.info("{}===============START================", "|**");

        String method = req.getMethod();
        logger.info("{}Request{method={}, url={}", "|**", method, req.getRequestURI());

        buildHeaderParam(req);

        buildRequestParam(req);
        return true;
    }

    
    private void buildHeaderParam(HttpServletRequest req) {
        List<String> headerList = Lists.newArrayList("token","xxx");
        StringBuilder headerSb = new StringBuilder();
        Enumeration enu = req.getHeaderNames();
        while (enu.hasMoreElements()) {
            String paraName = (String) enu.nextElement();
            if(headerList.contains(paraName)){
                headerSb.append(paraName).append("=").append(req.getHeader(paraName)).append(",");
            }
        }
        logger.info("{}HeaderParams:[{}]", "|**", headerSb);
    }

    
    private void buildRequestParam(HttpServletRequest req) {
        StringBuilder sb = new StringBuilder();
        Enumeration enu = req.getParameterNames();
        while (enu.hasMoreElements()) {
            String paraName = (String) enu.nextElement();
            sb.append(paraName).append("=").append(req.getParameter(paraName)).append(",");
        }
        logger.info("{}RequestParams:[{}]", "|**", sb);
    }

    @Override
    public void afterCompletion(HttpServletRequest req, HttpServletResponse res, Object arg2, Exception arg3) throws Exception {
        long endTime = System.currentTimeMillis();
        long duration = endTime - (long) ThreadLocalUtil.getData(executeTime);
        String response = (String) ThreadLocalUtil.getData("ResponseData");//输出返回值
        logger.info("{}reponse:{}", "|**", response);

        logger.info("{}===============END:{} 毫秒===============", "|**", duration);
    }

    @Override
    public void postHandle(HttpServletRequest arg0, HttpServletResponse arg1,
                           Object arg2, ModelAndView arg3) throws Exception {
    }

}

拦截所有controller，完成调用之后，设置输出参数到ThreadLocal

@Aspect
@Component
public class ApiControllerAspect {

    @Pointcut("execution(* com.xxx.xxx.xxx..*(..))")
    public void logPointCut() {
    }

    @AfterReturning(pointcut = "logPointCut()", returning = "rtv")
    public void doAfter(Object rtv) {
        ThreadLocalUtil.setData("ResponseData", JSON.toJSONString(rtv));
    }
}

logback的配置文件

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true" scanPeriod="60 seconds" debug="false">

    <springProperty scope="context" name="log.path" source="logging.root"
                    defaultValue="${catalina.home:-./../}/logs"/>
    <springProperty scope="context" name="app.name" source="spring.application.name" />
    <conversionRule conversionWord="clr" converterClass="org.springframework.boot.logging.logback.ColorConverter" />
    <conversionRule conversionWord="wex" converterClass="org.springframework.boot.logging.logback.WhitespaceThrowableProxyConverter" />
    <conversionRule conversionWord="wEx" converterClass="org.springframework.boot.logging.logback.ExtendedWhitespaceThrowableProxyConverter" />
    <property name="CONSOLE_LOG_PATTERN" value="${CONSOLE_LOG_PATTERN:-%clr(%d{yyyy-MM-dd HH:mm:ss.SSS}){faint} %clr(${LOG_LEVEL_PATTERN:-%5p}) %clr(${PID:- }){magenta} %clr(---){faint} %clr([%15.15t]){faint} %clr(%-40.40logger{39}){cyan} %clr(:){faint} %m %X{traceId} %n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}}"/>

    <appender name="ERROR-APPENDER" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${log.path}/${app.name}/common-error.log</file>
        <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>ERROR</level>
            <onMatch>ACCEPT</onMatch>
            <onMismatch>DENY</onMismatch>
        </filter>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <FileNamePattern>
                ${log.path}/${app.name}/common-error.log.%d{yyyy-MM-dd}
            </FileNamePattern>
            <MaxHistory>30</MaxHistory>
        </rollingPolicy>
        <encoder charset="UTF-8">
            <pattern>
                ${CONSOLE_LOG_PATTERN}
            </pattern>
        </encoder>
    </appender>
    <appender name="DEFAULT-APPENDER" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${log.path}/${app.name}/common-default.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <FileNamePattern>
                ${log.path}/${app.name}/common-default.log.%d{yyyy-MM-dd}
            </FileNamePattern>
            <MaxHistory>10</MaxHistory>
        </rollingPolicy>
        <encoder charset="UTF-8">
            <pattern>
                ${CONSOLE_LOG_PATTERN}
            </pattern>
        </encoder>
    </appender>

    <!--  控制台输出  -->
    <appender name="stdout" class="ch.qos.logback.core.ConsoleAppender">
        <encoder charset="UTF-8">
            <pattern>
                ${CONSOLE_LOG_PATTERN}
            </pattern>
        </encoder>
    </appender>

    <root level="INFO">
        <appender-ref ref="DEFAULT-APPENDER"/>
        <appender-ref ref="ERROR-APPENDER"/>
        <appender-ref ref="stdout"/>
    </root>
    <logger name="org.mybatis" level="DEBUG" />
   
</configuration>

完成以上的配置，那么单机服务器日志跟踪已经完成了，
效果