Dubbo 全鏈路追蹤日誌的實現

微服務架構的項目，一次請求可能會調用多個微服務，這樣就會產生多個微服務的請求日誌，當咱們想要查看整個請求鏈路的日誌時，就會變得困難，所幸的是咱們有一些集中日誌收集工具，好比很熱門的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);
        }
    }
    
    // ..
}

更多精彩文章請關注做者維護的公衆號「後端進階」，這是一個專一後端相關技術的公衆號。
關注公衆號並回復「後端」免費領取後端相關電子書籍。
歡迎分享，轉載請保留出處。