dubbo traceId透傳實現日誌鏈路追蹤（基於Filter和RpcContext實現）

時間  2019-11-22
標籤 dubbo traceid 實現 日誌 鏈路 追蹤 基於 filter rpccontext 欄目 Dubbo 简体版
原文   原文鏈接

1、要解決什麼問題：

使用elk的過程當中發現以下問題：java

1.沒法準肯定位一個請求通過了哪些服務
2.多個請求線程的日誌交替打印，不利於查看按時間順序查看一個請求的日誌。

2、指望效果

可以查看一個請求完整的鏈路日誌，不受其它請求日誌的干擾。

3、動手實現

消費端須要作什麼：

1.新建一個攔截器，攔截全部請求，在調用接口前生成一個鏈路id（traceId）並放入log4j的MDC和dubbo的RpcContext的attachment，此處攔截器是基於jfinal實現，spring mvc可用其它攔截器或aop方案代替，只要實現生成traceId放入內存便可。web

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

import org.apache.log4j.MDC;

import com.alibaba.dubbo.rpc.RpcContext;
import com.jfinal.aop.Interceptor;
import com.jfinal.aop.Invocation;
import com.jfinal.handler.Handler;
import com.jfinal.kit.StrKit;
import com.ttxn.frameworks.utils.CommonUtil;

public class TraceHandler extends Handler {

    @Override
    public void handle(String target, HttpServletRequest request, HttpServletResponse response, boolean[] isHandled) {
        String token = request.getParameter("token");
        String userId = StrKit.notBlank(token) ? CommonUtil.getUserId(token) : "VISITOR";
        String uuid = CommonUtil.getUuid();
        String traceId = userId + "-" + uuid;
        RpcContext.getContext().setAttachment("traceId", traceId);
        MDC.put("traceId", traceId);
        next.handle(target, request, response, isHandled);
    }
    
}

2.修改log4j配置文件，在打印日誌的開頭加上鍊路id變量（%X{traceId}），用於log4j打印日誌時自動打印MDC中的鏈路id，此時消費端全部log4j日誌都會輸出鏈路id。redis

# log4j.rootLogger=WARN, stdout, file
log4j.rootLogger=INFO, stdout , file
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%X{traceId}%n%-d{yyyy-MM-dd HH:mm:ss}%n[%p]-[Thread: %t]-[%C.%M()]: %m%n

# Output to the File
log4j.appender.file=org.apache.log4j.DailyRollingFileAppender
log4j.appender.file.DatePattern='_'yyyy-MM-dd'.log'
log4j.appender.file.File=${catalina.base}/logs/ttxn_log.log
log4j.appender.file.layout=org.apache.log4j.PatternLayout
log4j.appender.file.layout.ConversionPattern=%X{traceId}%n%-d{yyyy-MM-dd HH:mm:ss}%n[%p]-[Thread: %t]-[%C.%M()]: %m%n

配置後的消費端log4j輸出效果：spring

Para: [APP公告]
VISITOR-1e2f6d11ca594ea7af3118567d00f004
2019-07-31 17:37:23
[INFO]-[Thread: DubboServerHandler-192.168.5.15:20884-thread-17]-[com.ttxn.frameworks.annotation.redis.RedisCacheInterceptor.intercept()]: cache not hit key=DATA_CACHE_common.getCfg ,filed=5bm/5pKt55S15Y+w

3.自定義一個dubbo filter，爲何消費端要定義這個filter呢？緣由是一個接口可能調用多個服務或調用一個服務屢次，這樣會涉及到屢次rpc調用，而RpcContext 的 attachment只在一次rpc會話有效，因此咱們須要在每次rpc調用以前放入一次traceId，才能保證屢次rpc調用的服務端都能獲取到這個traceId，在業務代碼中每rpc一次就setAttachment一次太麻煩，因此我選擇放入過濾器，對應用開發人員透明。src/main/resources目錄下新建META-INF/dubbo/com.alibaba.dubbo.rpc.Filter文件，文件內容以下。sql

dubboRpcFilter=com.ttxn.api.filter.TraceFilter

修改consumer.xml文件，應用過濾器apache

<dubbo:consumer timeout="30000" filter="dubboRpcFilter"/>
import com.alibaba.dubbo.rpc.Filter;
import com.alibaba.dubbo.rpc.Invocation;
import com.alibaba.dubbo.rpc.Invoker;
import com.alibaba.dubbo.rpc.Result;
import com.alibaba.dubbo.rpc.RpcContext;
import com.alibaba.dubbo.rpc.RpcException;
import com.jfinal.kit.StrKit;
import com.ttxn.frameworks.utils.trace.TraceIdUtil;

public class TraceFilter implements Filter {

    @Override
    public Result invoke(Invoker<?> invoker, Invocation invocation) throws RpcException {
        String traceId = RpcContext.getContext().getAttachment("traceId");
        if ( !StrKit.isBlank(traceId) ) {
            // *) 從RpcContext裏獲取traceId並保存
            TraceIdUtil.setTraceId(traceId);
        } else {
            // *) 交互前從新設置traceId, 避免信息丟失
            traceId = TraceIdUtil.getTraceId();
            RpcContext.getContext().setAttachment("traceId", traceId);
        }
        Result result = invoker.invoke(invocation);
        return result;
    }

}

到這裏，消費端的工做就作完了，若是你和我同樣是jfinal的架構，還須要作一件事，自定義jfinal的請求日誌打印器，以下：api

import java.io.IOException;
import java.io.Writer;

import org.slf4j.MDC;

import com.alibaba.dubbo.rpc.RpcContext;
/**
 * jfinal請求日誌打印工具，用來得到jfinal action report的日誌內容，進行自定義後輸出
 * @author Administrator
 *
 */
public class JFinalActionReportWriter extends Writer {
    
    private static final String LOG_PREFIX = "[START]";
    
    public void write(String str) throws IOException {
        String traceId = MDC.get("traceId");
        System.out.print(LOG_PREFIX + traceId + str);
    }
    public void write(char[] cbuf, int off, int len) throws IOException {}
    public void flush() throws IOException {}
    public void close() throws IOException {}
}

GlobalConfig中增長以下配置架構

public void configConstant(Constants me)
    {
        ActionReporter.setWriter(new JFinalActionReportWriter());
    }

就能夠自定義jfinal請求輸出日誌內容，以下，這部分日誌是不受log4j配置影響的，因此咱們須要作這一步。mvc

[START]VISITOR-dafe84f6ee2f4d2b907a4c7ef8f8d20c
JFinal action report -------- 2019-07-31 17:37:14 ------------------------------
Url         : GET /app/subject/searchSubjectV3_4
Controller  : com.ttxn.api.controller.app.SubjectRest.(SubjectRest.java:1)
Method      : searchSubjectV3_4
Interceptor : com.ttxn.api.interceptor.APIExceptionInterceptor.(APIExceptionInterceptor.java:1)
              com.ttxn.frameworks.plugins.spring.IocInterceptor.(IocInterceptor.java:1)
              com.ttxn.api.decorator.CoverImgInterceptor.(CoverImgInterceptor.java:1)
Parameter   : query=
生產端須要作什麼：

1.和消費端同樣須要自定義dubbo攔截器，新增配置文件src\main\resources\META-INF\dubbo\com.alibaba.dubbo.rpc.Filter，文件內容：app

dubboContextFilter=com.ttxn.webservice.interceptor.dubbo.ContextFilter

修改provider.xml，對生產者應用此攔截器：

<!-- 提供方調用過程缺省攔截器，將攔截全部service -->
    <dubbo:provider filter="dubboContextFilter"/>

在自定義攔截器中獲取traceId，放入MDC：

package com.ttxn.webservice.interceptor.dubbo;

import java.lang.annotation.Annotation;
import java.sql.SQLException;

import org.apache.log4j.MDC;

import com.alibaba.dubbo.rpc.Filter;
import com.alibaba.dubbo.rpc.Invocation;
import com.alibaba.dubbo.rpc.Invoker;
import com.alibaba.dubbo.rpc.Result;
import com.alibaba.dubbo.rpc.RpcContext;
import com.alibaba.dubbo.rpc.RpcException;
import com.jfinal.kit.StrKit;
import com.jfinal.plugin.activerecord.Db;
import com.jfinal.plugin.activerecord.IAtom;
import com.ttxn.frameworks.annotation.transaction.Transaction;
import com.ttxn.frameworks.utils.trace.TraceIdUtil;

public class ContextFilter implements Filter
{
    @Override
    public Result invoke(Invoker<?> invoker, Invocation invocation)
        throws RpcException
    {
        String traceId = RpcContext.getContext().getAttachment("traceId");
        if (StrKit.notBlank(traceId)) {
            MDC.put("traceId", traceId);
        }
        
        Result result = invoker.invoke(invocation);
        return result;
    }


}

修改log4j文件，輸出格式中加上traceId變量（%X{traceId}）：

# log4j.rootLogger=WARN, stdout, file
log4j.rootLogger=INFO, stdout , file
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%X{traceId}%n%-d{yyyy-MM-dd HH:mm:ss}%n[%p]-[Thread: %t]-[%C.%M()]: %m%n

# Output to the File
log4j.appender.file=org.apache.log4j.DailyRollingFileAppender
log4j.appender.file.DatePattern='_'yyyy-MM-dd'.log'
log4j.appender.file.File=${catalina.base}/logs/ttxn_log.log
log4j.appender.file.layout=org.apache.log4j.PatternLayout
log4j.appender.file.layout.ConversionPattern=%X{traceId}%n%-d{yyyy-MM-dd HH:mm:ss}%n[%p]-[Thread: %t]-[%C.%M()]: %m%n

到此就實現了traceId從消費端到生產端的透傳，生產端log4j日誌以下：

Para: [快報]
VISITOR-1e2f6d11ca594ea7af3118567d00f004
2019-07-31 17:37:23
[INFO]-[Thread: DubboServerHandler-192.168.5.15:20884-thread-15]-[com.ttxn.frameworks.annotation.redis.RedisCacheInterceptor.intercept()]: cache not hit key=DATA_CACHE_base.newsList ,filed=15

咱們就能夠從kibana中按照traceId來過濾單次請求的全部日誌，達到方便排查bug的效果。

相關文章
相關標籤/搜索
每日一句
    每一个你不满意的现在，都有一个你没有努力的曾经。
本站公眾號
   歡迎關注本站公眾號,獲取更多信息
聯繫我們 最近搜索 最新文章 沪ICP备13005482号-10 MyBatis教程 SQL 教程 MySQL教程 Java 教程 Thymeleaf 教程 Hibernate教程 Spring教程 Redis教程