公司項目采用SpringBoot+dubbo技術棧，雖然上了elk，但是還是不能把所有的日志串聯起來。因此自己寫了一套traceId和spanId的生成方案。在此記錄下該方案的具體實現，方便后續查閱
一、 名詞解釋
traceId：鏈路Id
spanId：可以理解為服務Id，一各請求可能會調用多個服務，調用一個服務產生一個新的spanId
二、 方案介紹
2.1 traceId實現
- 請求都是從web打過來的，所web的filter攔截，生成一個traceId並put到MDC中
- dubbo消費者filter負責把調用鏈的MDC內容傳遞給生產者，即放到attachMent里面
- dubbo生產者filter負責把attachMent里面的內容取出並放到MDC中
2.2 spanId的實現
- 引入一個logicId
- logicId放在dubbo的消費者攔截器里面累加
- 當同一個業務調用多次生產者時，則消費者里面的logicId會自增並傳遞到生產者
三、 實現思路
3.1 web過濾器實現功能
doFilter前：
生成traceId;
生成 spanId；
生成一個logicId，默認值為0；
存到MDC中
doFilter后：
清除MDC相關內容
3.2 dubbo消費者
invoke前：
（1）累加logicId
（2）將traceId和spanId及logicId傳遞到 生產者
3.3 dubbo生產者
invoke前：
（1）將traceId放到MDC中
（2）取出spanId和logicId，用.拼接在一起生成一個新的spanId放到MDC中
（3）生成一個logicId，默認值為0 存到mdc中
invoke后：
清除MDC相關內容
說明：
其實dubbo生產者這過濾器和web過濾器是差不多的東西。他們都需要生成當前應用的logicId
四、 實現代碼和效果
（1）TraceUtil
package com.cybermax.vaccine.logtrace;
import org.apache.commons.lang.StringUtils;
import org.slf4j.MDC;
import java.util.UUID;
import static com.cybermax.vaccine.logtrace.TraceConstants.*;
public class TraceUtil {
/**
* description: httpFilter的方式初始化MDC，會返回traceId
* @param traceId
* @return String
* @author ZENG.XIAO.YAN
* @time 2021-01-30 20:01
*/
public static String initMDCWithHttpFilter(String traceId) {
String val = StringUtils.defaultIfBlank(traceId, generateTraceId());
MDC.put(TRACE_ID, val);
MDC.put(SPAN_ID, "0");
MDC.put(LOGIC_ID, "0");
return val;
}
/**
* logicId +1
* @param logicId
* @return
*/
public static String incrLogicId(String logicId) {
return String.valueOf(Integer.parseInt(logicId) + 1);
}
/**
* 從 MDC 中清除當前線程的 Trace信息
*/
public static void clearMDC() {
MDC.clear();
}
/**
* 生成traceId
* @return 鏈路ID
*/
public static String generateTraceId() {
return UUID.randomUUID().toString();
}
/**
* 生成新的spanId
* @param spanId
* @param logicId
* @return
*/
public static String getNewSpanId(String spanId, String logicId) {
return new StringBuilder(spanId).append(".").append(logicId).toString();
}
}（2）TraceConstants
package com.cybermax.vaccine.logtrace;
/**
* TraceConstants
*
* @author ZENG.XIAO.YAN
* @version 1.0
* @Date 2021-01-30
*/
public class TraceConstants {
/**
* 追蹤id
*/
public static final String TRACE_ID = "traceId";
/**
* 分段ID
* 同一個調用鏈下的分段調用ID
* 對於前端收到請求，生成的spanId固定都是0
* 簽名方式生成:0, 0.1, 0.1.1, 0.2
*/
public static final String SPAN_ID = "spanId";
/**
* 邏輯ID
* 同一個分段調用下的業務邏輯ID
* 標識服務內部的調用順序
*/
public static final String LOGIC_ID = "logicId";
}
(3) LogTraceHttpFilter
package com.cybermax.vaccine.logtrace;
import lombok.extern.slf4j.Slf4j;
import javax.servlet.*;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import java.io.IOException;
@Slf4j
public class LogTraceHttpFilter implements Filter {
private static final String TRACE_ID_HEAD = "ZTraceId";
@Override
public void init(FilterConfig filterConfig) {
// TODO Auto-generated method stub
}
@Override
public final void doFilter(ServletRequest servletRequest, ServletResponse servletResponse, FilterChain filterChain) throws IOException, ServletException {
try {
// 這個traceId也可以考慮從Http請求里面取，如果是null則默認用uuid
HttpServletRequest request = (HttpServletRequest) servletRequest;
HttpServletResponse response = (HttpServletResponse) servletResponse;
String traceId = TraceUtil.initMDCWithHttpFilter(getTraceId(request));
// 響應頭里面添加一個traceId，方便f12debug調試；本來是每個ajax都由前端生成traceId，由於改動成本太高，就變成響應輸出traceId
response.setHeader(LogTraceHttpFilter.TRACE_ID_HEAD, traceId);
if (log.isInfoEnabled()) {
log.info("web端接收http請求[{}]----start", request.getRequestURI());
}
filterChain.doFilter(request, response);
} finally {
// 最后清除掉MDC內容
TraceUtil.clearMDC();
}
}
@Override
public void destroy() {
}
/**
* description: 由於考慮到和其他系統對接時，可能會用其他系統傳遞進來參數作為traceId
* 因此預留此方法方便后續Override
* @return java.lang.String
* @author ZENG.XIAO.YAN
* @time 2021-01-30 20:04
*/
public String getTraceId(ServletRequest servletRequest) {
return null;
}
}（4）LogTraceConsumerFilter
package com.cybermax.vaccine.logtrace;
import lombok.extern.slf4j.Slf4j;
import org.apache.commons.lang3.StringUtils;
import org.apache.dubbo.common.constants.CommonConstants;
import org.apache.dubbo.common.extension.Activate;
import org.apache.dubbo.rpc.*;
import org.slf4j.MDC;
import java.util.Map;
@Slf4j
@Activate(group = CommonConstants.CONSUMER)
public class LogTraceConsumerFilter implements Filter {
@Override
public Result invoke(Invoker<?> invoker, Invocation invocation) throws RpcException {
// 消費者負責把調用鏈端的MDC信息傳遞到生產者
String traceId = MDC.get(TraceConstants.TRACE_ID);
String spanId = MDC.get(TraceConstants.SPAN_ID);
String logicId = MDC.get(TraceConstants.LOGIC_ID);
if (StringUtils.isNotBlank(traceId) && StringUtils.isNotBlank(spanId) && StringUtils.isNotBlank(logicId)) {
// 邏輯Id+1
String newLogicId = TraceUtil.incrLogicId(logicId);
MDC.put(TraceConstants.LOGIC_ID, newLogicId);
// 傳遞traceId spanId logicId
Map<String, String> attachments = invocation.getAttachments();
attachments.put(TraceConstants.TRACE_ID, traceId);
attachments.put(TraceConstants.SPAN_ID, spanId);
attachments.put(TraceConstants.LOGIC_ID, newLogicId);
}
return invoker.invoke(invocation);
}
}（5）LogTraceProviderFilter
package com.cybermax.vaccine.logtrace;
import lombok.extern.slf4j.Slf4j;
import org.apache.commons.collections4.MapUtils;
import org.apache.commons.lang3.StringUtils;
import org.apache.dubbo.common.constants.CommonConstants;
import org.apache.dubbo.common.extension.Activate;
import org.apache.dubbo.rpc.*;
import org.slf4j.MDC;
import java.util.Map;
@Slf4j
@Activate(group = CommonConstants.PROVIDER)
public class LogTraceProviderFilter implements Filter {
@Override
public Result invoke(Invoker<?> invoker, Invocation invocation) throws RpcException {
try {
// 生產者負責把信息放進MDC里面
Map<String, String> attachments = invocation.getAttachments();
String traceId = MapUtils.getString(attachments, TraceConstants.TRACE_ID);
String spanId = MapUtils.getString(attachments,TraceConstants.SPAN_ID);
String logicId = MapUtils.getString(attachments,TraceConstants.LOGIC_ID);
if (StringUtils.isNotBlank(traceId) && StringUtils.isNotBlank(spanId) && StringUtils.isNotBlank(logicId)) {
// 生成新的spanId
String newSpanId = TraceUtil.getNewSpanId(spanId, logicId);
MDC.put(TraceConstants.TRACE_ID, traceId);
MDC.put(TraceConstants.SPAN_ID, newSpanId);
MDC.put(TraceConstants.LOGIC_ID, "0");
}
if (log.isInfoEnabled()) {
log.info("dubbo服務執行dubbo方法{}.{}", invoker.getInterface().getName(), invocation.getMethodName());
}
Result result = invoker.invoke(invocation);
return result;
} finally {
TraceUtil.clearMDC();
}
}
}（6）配置dubbo的spi擴展
（7）日志中輸出TraceId和SpanId
下面只要關注traceId和SpanId的取值，具體的格式自己搞定
<?xml version="1.0" encoding="UTF-8"?>
<!--
默認file appender的encoder輸出json時總是有點問題，因此引入logstash-logback-encoder來改變這一現狀
-->
<included>
<appender name="FILE"
class="ch.qos.logback.core.rolling.RollingFileAppender">
<encoder
class="net.logstash.logback.encoder.LoggingEventCompositeJsonEncoder">
<providers>
<!--<timestamp>-->
<!--<timeZone>UTC</timeZone>-->
<!--</timestamp>-->
<pattern>
<!--可以直接從apollo中取值-->
<pattern>
{"time":"%d{yyyy-MM-dd'T'HH:mm:ss.SSS+08:00}",
"systemName":"%property{systemName}" ,
"level": "%level",
"traceId": "%X{traceId}",
"spanId": "%X{spanId}",
"context": "%t [%c] - %m ",
"exceptionTrace":"%exception{50}"
}%n
</pattern>
</pattern>
</providers>
</encoder>
<file>${LOG_FILE}</file>
<rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
<fileNamePattern>${LOG_FILE}.%d{yyyy-MM-dd}.%i.gz</fileNamePattern>
<maxFileSize>${LOG_FILE_MAX_SIZE:-100MB}</maxFileSize>
<maxHistory>${LOG_FILE_MAX_HISTORY:-0}</maxHistory>
</rollingPolicy>
</appender>
</included>（8）輸出的日志文件效果舉例
下面為程序里面輸出的一條日志，為了filebeat收集后不用自己寫語法去解析日志，我配置成了json格式；這不是重點，重點是下面這個json
{
"time":"2021-09-10T17:15:53.285+08:00",
"systemName":"vaccine-service-app",
"level":"INFO",
"traceId":"c2348f26-0ca6-4772-83a3-de7b7cb1aa9d",
"spanId":"0.2",
"context":"DubboServerHandler-192.168.199.42:20880-thread-199 [com.cybermax.service.realize.hession.bacterin.BacterinFCServiceImpl] - 已命中[REDIS_DEL_allBacterinMap_bactCode]緩存... ",
"exceptionTrace":""
}
效果案例二
下面再貼一張圖，這個的日志格式就不是json了，只在原來的springboot的日志格式中添加了traceId和spanId
配置的日志格式為：
${CONSOLE_LOG_PATTERN:%clr(%d{${LOG_DATEFORMAT_PATTERN:yyyy-MM-dd'T'HH:mm:ss.SSS+08:00}}){faint} %clr(${LOG_LEVEL_PATTERN:%5p}) %clr(${PID:- }){magenta} %clr([%X{traceId}] [%X{spanId}]){yellow} %clr(---){faint} %clr([%15.15t]){faint} %clr(%-40.40logger{39}){cyan} %clr(:){faint} %m%n${LOG_EXCEPTION_CONVERSION_WORD:%wEx}}
效果為:
五、總結
- 重點關注spanId的實現，traceId實現比較簡單
- 這個spanId生成后就和阿里鷹眼的效果差不多
- 這個traceId和spanId如果輸出到日志時，可以直接發送到logstash，也可以生成日志文件再用其他filebeat去收集
六、參考鏈接
《TraceId 和 SpanId 生成規則》
https://help.aliyun.com/document_detail/151840.html?spm=a2c4g.11186623.6.1162.45997711nA76Yy
《Dubbo日志鏈路追蹤TraceId選型》
https://blog.csdn.net/zlt2000/article/details/108820788