Dubbo全鏈路追蹤日誌的實現

摘要： 微服務架構的專案，一次請求可能會呼叫多個微服務，這樣就會產生多個微服務的請求日誌，當我們想要檢視整個請求鏈路的日誌時，就會變得困難，所幸的是我們有一些集中日誌收集工具，比如很熱門的ELK，我們需要把這些日誌串聯起來，這是一個很關鍵的問題，如果沒有串聯起來，查詢起來很是很困難，我們的做法是在開始...

微服務架構的專案，一次請求可能會呼叫多個微服務，這樣就會產生多個微服務的請求日誌，當我們想要檢視整個請求鏈路的日誌時，就會變得困難，所幸的是我們有一些集中日誌收集工具，比如很熱門的ELK，我們需要把這些日誌串聯起來，這是一個很關鍵的問題，如果沒有串聯起來，查詢起來很是很困難，我們的做法是在開始請求系統時生成一個全域性唯一的id，這個id伴隨這整個請求的呼叫週期，即當一個服務呼叫另外一個服務的時候，會往下傳遞，形成一條鏈路，當我們檢視日誌時，只需要搜尋這個id，整條鏈路的日誌都可以查出來了。

現在以dubbo微服務架構為背景，舉個栗子：

A -> B -> C

我們需要將A/B/C/三個微服務間的日誌按照鏈式列印，我們都知道Dubbo的RpcContext只能做到消費者和提供者共享同一個RpcContext，比如A->B，那麼A和B都可以獲取相同內容的RpcContext，但是B->C時，A和C就無法共享相同內容的RpcContext了，也就是無法做到鏈式列印日誌了。

那麼我們是如何做到呢？

我們可以用左手交換右手的思路來解決，假設左手是執行緒的ThreadLocal，右手是RpcContext，那麼在交換之前，我們首先將必要的日誌資訊儲存到ThreadLocal中。

在我們的專案微服務中大致分為兩種容器型別的微服務，一種是Dubbo容器，這種容器的特點是隻使用spring容器啟動，然後使用dubbo進行服務的暴露，然後將服務註冊到zookeeper，提供服務給消費者；另一種是SpringMVC容器，也即是我們常見的WEB容器，它是我們專案唯一可以對外開放介面的容器，也是充當專案的閘道器功能。

在瞭解了微服務容器之後，我們現在知道了呼叫鏈的第一層一定是在SpringMVC容器層中，那麼我們直接在這層寫個自定義攔截器就ojbk了，talk is cheap，show you the demo code：

舉例一個Demo程式碼，公共攔截器的前置攔截中程式碼如下：

public class CommonInterceptor implements HandlerInterceptor {
@Override
public boolean preHandle(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse, Object handler)
throws Exception {

// ...

// 初始化全域性的Context容器
Request request = initRequest(httpServletRequest);
// 新建一個全域性唯一的請求traceId，並set進request中
request.setTraceId(JrnGenerator.genTraceId());
// 將初始化的請求資訊放進ThreadLocal中
Context.initialLocal(request);

// ...

return true;
}

// ...

}

系統內部上下文物件：

public class Context {

// ...

private static final ThreadLocal<Request> REQUEST_LOCAL = new ThreadLocal<>();

public final static void initialLocal(Request request) {
if (null == request) {
return;
}
REQUEST_LOCAL.set(request);
}

public static Request getCurrentRequest() {
return REQUEST_LOCAL.get();
}

// ...
}

攔截器實現了org.springframework.web.servlet.HandlerInterceptor 介面，它的主要作用是用於攔截處理請求，可以在MVC層做一些日誌記錄與許可權檢查等操作，這相當於MVC層的AOP，即符合橫切關注點的所有功能都可以放入攔截器實現。

這裡的initRequest(httpServletRequest); 就是將請求資訊封裝成系統內容的請求物件Request ，並初始化一個全域性唯一的traceId放進Request中，然後再把它放進系統內部上下文ThreadLocal欄位中。

接下來講講如何將ThreadLocal中的內容放到RpcContext中，在講之前，我先來說說Dubbo基於spi擴充套件機制，官方文件對攔截器擴充套件解釋如下：

服務提供方和服務消費方呼叫過程攔截，Dubbo 本身的大多功能均基於此擴充套件點實現，每次遠端方法執行，該攔截都會被執行，請注意對效能的影響。

也就是說我們進行服務遠端呼叫前，攔截器會對此呼叫進行攔截處理，那麼就好辦了，在消費者呼叫遠端服務之前，我們可以偷偷把ThreadLocal的內容放進RpcContext容器中，我們可以基於dubbo的spi機制擴充套件兩個攔截器，一個在消費者端生效，另一個在提供者端生效：

在META-INF中加入com.alibaba.dubbo.rpc.Filter檔案，內容如下：

provider=com.objcoding.dubbo.filter.ProviderFilter
consumer=com.objcoding.dubbo.filter.ConsumerFilter

消費者端攔截處理：

public class ConsumerFilter implements Filter {
@Override
public Result invoke(Invoker<?> invoker, Invocation invocation) 
throws RpcException {

//1.從ThreadLocal獲取請求資訊
Request request = Context.getCurrentRequest();
//2.將Context引數放到RpcContext
RpcContext rpcCTX = RpcContext.getContext();
// 將初始化的請求資訊放進ThreadLocal中
Context.initialLocal(request);

// ...

}
}

Context.getCurrentRequest(); 就是從ThreadLocal中拿到Request請求內容，contextToDubboContext(request); 將Request內容放進當前執行緒的RpcContext容器中。

很容易聯想到提供者也就是把RpcContext中的內容拿出來放到ThreadLocal中：

public class ProviderFilter extends AbstractDubboFilter implements Filter{
@Override
public Result invoke(Invoker<?> invoker, Invocation invocation) 
throws RpcException {
// 1.獲取RPC遠端呼叫上下文
RpcContext rpcCTX = RpcContext.getContext();
// 2.初始化請求資訊
Request request = dubboContextToContext(rpcCTX);
// 3.將初始化的請求資訊放進ThreadLocal中
Context.initialLocal(request);

// ...

}
}

接下來我們還要配置log4j2，使得我們同一條請求在關聯的每一個容器列印的訊息，都有一個共同的traceId，那麼我們在ELK想要查詢某個請求時，只需要搜尋traceId，就可以看到整條請求鏈路的日誌了。

我們在Context上下文物件的initialLocal(Request request) 方法中在log4j2的上下文中新增traceId資訊：

public class Context {

// ...

final public static String TRACEID = "_traceid";

public final static void initialLocal(Request request) {
if (null == request) {
return;
}
// 在log4j2的上下文中新增traceId
ThreadContext.put(TRACEID, request.getTraceId());
REQUEST_LOCAL.set(request);
}

// ...
}

接下來實現org.apache.logging.log4j.core.appender.rewrite.RewritePolicy ：

@Plugin(name = "Rewrite", category = "Core", elementType = "rewritePolicy", printObject = true)
public final class MyRewritePolicy implements RewritePolicy {

// ...

@Override
public LogEvent rewrite(final LogEvent source) {
HashMap<String, String> contextMap = Maps.newHashMap(source.getContextMap());
contextMap.put(Context.TRACEID, contextMap.containsKey(Context.TRACEID) ? contextMap.get(Context.TRACEID) : NULL);
return new Log4jLogEvent.Builder(source).setContextMap(contextMap).build();
}

// ...
}

RewritePolicy的作用是我們每次輸出日誌，log4j都會呼叫這個類進行一些處理的操作。

配置log4j2.xml：

<Configuration status="warn">
<Appenders>
<Console name="Console" target="SYSTEM_OUT">
<PatternLayout
pattern="[%d{yyyy/MM/dd HH:mm:ss,SSS}][${ctx:_traceid}]%m%n" />
</Console>

<!--定義一個Rewrite-->
<Rewrite name="Rewrite">
<MyRewritePolicy/>
<!--引用輸出模板-->
<AppenderRef ref="Console"/>
</Rewrite>
</Appenders>
<Loggers>

<!--使用日誌模板-->
<Logger name="com.objcoding.MyLogger" level="debug" additivity="false">
<!--引用Rewrite-->
<AppenderRef ref="Rewrite"/>
</Logger>
</Loggers>
</Configuration>

自定義日誌類：

public class MyLogger {
private static final Logger logger = LoggerFactory.getLogger(MyLogger.class);

public static void info(String msg, Object... args) {
if (canLog() == 1 && logger.isInfoEnabled()) {
logger.info(msg, args);
}
}

public static void debug(String message, Object... args) {
if (canLog() == 1 && logger.isDebugEnabled()) {
logger.debug(message, args);
}
}

// ..
}