dubbo traceId透传实现日志链路追踪(基于Filter和RpcContext实现)

Posted powerjiajun

tags:

篇首语:本文由小常识网(cha138.com)小编为大家整理,主要介绍了dubbo traceId透传实现日志链路追踪(基于Filter和RpcContext实现)相关的知识,希望对你有一定的参考价值。

一、要解决什么问题:

使用elk的过程中发现如下问题:

1.无法准确定位一个请求经过了哪些服务
2.多个请求线程的日志交替打印,不利于查看按时间顺序查看一个请求的日志。

二、期望效果

能够查看一个请求完整的链路日志,不受其它请求日志的干扰。

三、动手实现

消费端需要做什么:

1.新建一个拦截器,拦截所有请求,在调用接口前生成一个链路id(traceId)并放入log4j的MDC和dubbo的RpcContext的attachment,此处拦截器是基于jfinal实现,spring mvc可用其它拦截器或aop方案代替,只要实现生成traceId放入内存即可。

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变量(%XtraceId),用于log4j打印日志时自动打印MDC中的链路id,此时消费端所有log4j日志都会输出链路id。

# 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=%XtraceId%n%-dyyyy-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=%XtraceId%n%-dyyyy-MM-dd HH:mm:ss%n[%p]-[Thread: %t]-[%C.%M()]: %m%n

配置后的消费端log4j输出效果:

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文件,文件内容如下。

dubboRpcFilter=com.ttxn.api.filter.TraceFilter

修改consumer.xml文件,应用过滤器

<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的请求日志打印器,如下:

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配置影响的,所以我们需要做这一步。

[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,文件内容:

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变量(%XtraceId):

# 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=%XtraceId%n%-dyyyy-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=%XtraceId%n%-dyyyy-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的效果。

以上是关于dubbo traceId透传实现日志链路追踪(基于Filter和RpcContext实现)的主要内容,如果未能解决你的问题,请参考以下文章

Monolog 自动填充 RequestId / TraceId 请求链路追踪标识

Dubbo + Zipkin + Brave 实现全链路追踪

全链路参数透传

全链路参数透传

全链路参数透传

全链路参数透传