Logback 之 MDC 日志跟踪、日志自定义

MDC实现日志跟踪

MDC在做日志跟踪的时候用的比较多。一个系统提供服务，提供给其他系统来调用，当其他系统调用的时候，入参带上一个唯一的请求标识(traceId)，把这个traceId输出到日志中，这样两个系统直接就会形成一个执行链，用traceId串联起来，当出现错误时，可以在调用方查询对应的请求日志，也可以在服务方查询请求日志。定位问题很方便。输出日志的地方很多，不能每次输出都去获取traceId，拼接到日志中，这样做很不优雅，也很容易遗漏。这个时候使用MDC配合logback中的pattern就很简单啦。

实现思路

首先请求过来，将traceId放到MDC中，然后在pattern中用表达式从MDC中获取到对应的traceId。

对MDC不熟悉的同学可以先阅读一下我的上一篇文章： Slf4j MDC 实现机制与应用

Spring Boot 实战

1、TraceContext

首先，我们封装一个 TraceContext工具类，如下：

import org.apache.commons.lang3.StringUtils;
import org.slf4j.MDC;

import java.util.concurrent.TimeUnit;

/**
 * @author Ricky Fung
 */
public abstract class TraceContext {
    private static final ThreadLocal<Long> timeThreadLocal = new ThreadLocal();

    //---------接口耗时统计
    /**
     * 开始计时
     * @return
     */
    public static long start() {
        long startTime = System.nanoTime();
        timeThreadLocal.set(startTime);
        return startTime;
    }

    /**
     * 获取接口耗时
     * @return
     */
    public static long stopAndGet() {
        long endTime = System.nanoTime();
        Long startTime = timeThreadLocal.get();
        if (startTime == null) {
            throw new IllegalArgumentException("必须先调用start方法");
        }
        //移除
        timeThreadLocal.remove();
        long costTime = endTime - startTime;
        return TimeUnit.MILLISECONDS.convert(costTime, TimeUnit.NANOSECONDS);
    }

    //---------trace相关
    public static String getTraceId() {
        return MDC.get(CommonConstants.SLF4J_TRACE_ID);
    }
    public static String getSpanId() {
        return MDC.get(CommonConstants.SLF4j_SPAN_ID);
    }

    /**
     * 获取traceId，如果不存在则生成一个
     * @return
     */
    public static String computeTraceId() {
        String traceId = getTraceId();
        if (StringUtils.isEmpty(traceId)) {
            traceId = UUIDUtils.getId();
        }
        return traceId;
    }

    public static void putTraceId(String traceId) {
        MDC.put(CommonConstants.SLF4J_TRACE_ID, traceId);
    }

    public static void putSpanId(String spanId) {
        MDC.put(CommonConstants.SLF4j_SPAN_ID, spanId);
    }

    //-------
    public static void removeTraceId() {
        MDC.remove(CommonConstants.SLF4J_TRACE_ID);
    }
    public static void removeSpanId() {
        MDC.remove(CommonConstants.SLF4j_SPAN_ID);
    }

    public static String genSpanId(String spanId) {
        if (StringUtils.isEmpty(spanId)) {
            return CommonConstants.ROOT_SPAN_ID;
        }
        return spanId+".1";
    }

    public static String rootSpanId() {
        return CommonConstants.ROOT_SPAN_ID;
    }
}

其中，CommonConstants定义了几个常量：

/**
 * @author Ricky Fung
 */
public class CommonConstants {

    //HTTP请求头字段
    public static final String TRACE_ID_HEADER = "X-Trace-Id";
    public static final String SPAN_ID_HEADER = "X-Span-Id";

    //Logback参数
    public static final String SLF4J_TRACE_ID = "X-TraceId";
    public static final String SLF4j_SPAN_ID = "X-SpanId";

    public static final String ROOT_SPAN_ID = "0";

}

2、TraceInterceptor

利用Spring MVC提供的 org.springframework.web.servlet.HandlerInterceptor 我们可以很方便的拦截HTTP请求，对请求处理前后做一些处理。

import org.apache.commons.lang3.StringUtils;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.web.servlet.handler.HandlerInterceptorAdapter;

import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;

/**
 * @author Ricky Fung
 */
public class TraceInterceptor extends HandlerInterceptorAdapter {
    private final Logger LOG = LoggerFactory.getLogger(this.getClass());

    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
        //获取trace
        String traceId = request.getHeader(CommonConstants.TRACE_ID_HEADER);
        String spanId = request.getHeader(CommonConstants.SPAN_ID_HEADER);

        if (StringUtils.isEmpty(traceId)) { //生成根
            traceId = UUIDUtils.getId();
        }
        //生成spanId
        if (StringUtils.isEmpty(spanId)) {
            spanId = CommonConstants.ROOT_SPAN_ID;
        } else {
            spanId = TraceContext.genSpanId(spanId);
        }
        //设置trace
        TraceContext.putTraceId(traceId);
        TraceContext.putSpanId(spanId);

        TraceContext.start();
        LOG.info("客服呼叫中心-链路追踪开始, traceId:{}, spanId:{}", traceId, spanId);
        return true;
    }

    @Override
    public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Exception {
        long costTime = TraceContext.stopAndGet();
        LOG.info("客服呼叫中心-链路追踪结束, 接口URI:{}, 耗时:{} ms", request.getRequestURI(), costTime);

        //清除
        TraceContext.removeTraceId();
        TraceContext.removeSpanId();
    }
}

在preHandle方法中，我们获取HttpServletRequest中的TraceId 和 SpanId，如果二者为空我们就生成一个并put到MDC中。

在afterCompletion方法中，我们做一些清理工作，清除我们之前设置的TraceId 和 SpanId。

另外，就是应用在请求三方系统时，需要带上TraceId，这样整个链路就串联起来了，代码如下：

@Resource
    private RestTemplate restTemplate;

    private String doRequest(Long userId, String token, String payload, String apiUri, HttpMethod httpMethod) {
        //trace
        String traceId = TraceContext.getTraceId();
        String spanId = TraceContext.getSpanId();

        LOG.info("客服呼叫中心-转发请求开始, userId:{}, traceId:{}, httpMethod:{}, apiUri:{}", userId, traceId, httpMethod, apiUri);

        StringBuilder sb = new StringBuilder(80);
        sb.append(bpHost).append(apiUri);
        String reqUrl = sb.toString();

        //创建请求头
        HttpHeaders headers = new HttpHeaders();
        headers.setContentType(MediaType.APPLICATION_JSON);
        headers.add(CommonConstants.AUTHORIZATION_HEADER, token);
        headers.add(CommonConstants.TRACE_ID_HEADER, StringUtils.isNotEmpty(traceId) ? traceId : StringUtils.EMPTY);
        headers.add(CommonConstants.SPAN_ID_HEADER, StringUtils.isNotEmpty(spanId) ? spanId : StringUtils.EMPTY);

        HttpEntity<String> httpEntity = new HttpEntity<>(payload, headers);
        ResponseEntity<String> responseEntity = restTemplate.exchange(reqUrl, httpMethod, httpEntity, String.class);
        if (responseEntity.getStatusCode() != HttpStatus.OK) {
            LOG.info("客服呼叫中心-转发请求, userId:{}, traceId:{} 请求服务器:{} 状态码异常:{}", userId, traceId, reqUrl, responseEntity.getStatusCodeValue());
        }
        String json = responseEntity.getBody();
        LOG.info("客服呼叫中心-转发请求, userId:{}, traceId:{}, 请求服务器:{} 响应结果:{}", userId, traceId, reqUrl, json);
        if (StringUtils.isNotEmpty(json)) {
            return json;
        }
        return null;
    }

3、日志输出

在logback.xml中如果想输出MDC中的自定义属性，可以通过 %X{propertyName} 方式。

logback-spring.xml 如下：

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <property name="LOG_PATTERN" value="%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level [%X{X-TraceId} | %X{X-SpanId}] %logger - %msg%n"/>

    <springProperty scope="context" name="prodName" source="spring.application.name" defaultValue="crm-call-center-proxy"/>

    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>${LOG_PATTERN}</pattern>
            <charset>UTF-8</charset>
        </encoder>
    </appender>

    <root level="INFO">
        <appender-ref ref="CONSOLE"/>
    </root>

</configuration>

我们通过 %X{X-TraceId} 和 %X{X-SpanId} 输出TraceContext中put到MDC中的TraceId 和 SpanId。