手撕分布式日志链路追踪

吕哥架构

已于 2022-02-08 16:32:26 修改

阅读量408

点赞数 1

文章标签：过滤器分布式网关 java log4j

于 2021-05-18 23:40:41 首次发布

本文链接：https://blog.csdn.net/super_scan/article/details/120415532

版权

一、需求

微服务架构，SpringMVC，Dubbo框架，帮助业务开发人员快速排查问题。

1、实现通过唯一的logId串联本次请求所有的日志信息

2、实现分段(RPC)与汇总(HTTP)计时统计

二、方案

利用日志组件的 MDC机制来设置logId，输出日志格式上带上logId
logId的串联实现，有几种场景要考虑全了

1、请求的源头有哪些？这个涉及到logId的产生与清理

1）网关进来的请求

2）任务调度发起的请求

2、请求执行过程中换线程的场景有哪些？这个涉及到logId的传递与清理

1）进程内（JVM内）异步执行（线程池和自定义子线程）

2）进程之间的异步执行（RPC调用，JVM之间）

计时的实现与记录

1）网关过滤器中打印本次请求总耗时

2）网关拦截器中打印本次请求 url以及映射的dubbo 接口，方法，参数等信息

3）生产者过滤器中打印调用的：dubbo URL，接口，方法，token，参数，耗时等信息

4）网关、生产者过滤器、消费者过滤器、log组件相互协作完成 logId的传递（Dubbo的RpcContext+ThreadLocal工具+log4j的 ThreadContext）

5）异步线程组件：记录接口、方法、参数、任务耗时

6）任务调度中记录，调度执行耗时情况

来个图概括下

总体方案

三、实现

1、网关过滤器

@Configuration
public class ConfigFilter {
    @Bean
    public FilterRegistrationBean registFilter() {
        FilterRegistrationBean registration = new FilterRegistrationBean();
        registration.setFilter(new FilterResponseTime());
        registration.addUrlPatterns("/*");
        registration.setName("FilterResponseTime");
        registration.setOrder(1);
        return registration;
    }
    static class FilterResponseTime implements Filter {
        @Override
        public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse, FilterChain filterChain) throws IOException, ServletException {
            long start = System.currentTimeMillis();
            String uri = ((HttpServletRequest)servletRequest).getRequestURI();
            ThreadContext.put(CommonConst.logId, LogIdUtil.getLogId());
            try {
                filterChain.doFilter(servletRequest,servletResponse);
            }finally {
                log.error(uri+"耗时"+(System.currentTimeMillis()-start)+"ms");
                ThreadContext.clearAll();
            }
        }
        @Override
        public void destroy() {
            log.info("--- FilterResponseTime destroy ---");
        }
    }
}

2、dubbo消费者过滤器

public class ConsumingFilter implements Filter {
    private static Logger log = LoggerFactory.getLogger(BaseConsumingFilter.class);


    @Override
    public Result invoke(Invoker<?> invoker, Invocation invocation) throws RpcException {
        setDistributedTracingContext();
        return invoker.invoke(invocation);
    }


    /**
     * 设置分布式链路跟踪上下文信息
     */
    protected void setDistributedTracingContext() {
        if (ThreadContext.get(CommonConst.logId)==null) {
            ThreadContext.put(CommonConst.logId, LogIdUtil.getLogId());
        }
        RpcContext.getContext().setAttachment(CommonConst.logId, ThreadContext.get(CommonConst.logId));
    }
}

3、dubbo提供者过滤器

public class ProvidingFilter implements Filter {
    private static Logger log = LoggerFactory.getLogger(BaseProvidingFilter.class);
    @Override
    public Result invoke(Invoker<?> invoker, Invocation invocation) throws RpcException {
        //计时---
        long startTime = System.currentTimeMillis();
        try {
            //分布式链路追踪
            String logId = saveDistributedTracingContext();
            //log
            dubboRpcLog(invoker, invocation);
            //业务实现调用
            Result result = invoker.invoke(invocation);


            if (result.hasException()) {
                //异常统一处理
                exceptionHandle(invocation, logId, result);
            }
            return result;
        }finally {
            //----计时-----
            logTimeCost(invoker.getInterface().getName(), invocation.getMethodName(), startTime,System.currentTimeMillis());
            ThreadContext.clearAll();
        }


    }


    /**
     * 异常加工
     * @param invocation
     * @param logId
     * @param result
     */
    private void exceptionHandle(Invocation invocation, String logId, Result result) {
        if (result.getException() instanceof BusinessException) {
            BusinessException busiEx = (BusinessException) result.getException();
            busiEx.setLogId(logId);
            busiEx.setStackTrace(getErrorStack(busiEx));
        } else {
            //OutOfMemoryError和StackOverflowError都会走到这里记录
            log.error("异常标记",result.getException());
            String msg = result.getException().getMessage();
            if (StringUtil.isEmpty(msg)) {
                msg = result.getException().toString();
            }
            BusinessException ex = new BusinessException("", msg);
            ex.setStackTrace(result.getException().getStackTrace());
            ex.setLogId(logId);
            ((RpcResult) result).setException(ex);
        }
    }


    /**
     * 记录调用日志
     * @param invoker
     * @param invocation
     */
    private void dubboRpcLog(Invoker<?> invoker, Invocation invocation) {


        StringBuilder message = new StringBuilder();
        message.append("dubboUrl:").append(invoker.getUrl()).append(";");
        message.append("interface:").append(invoker.getInterface().getName()).append(";");
        message.append("methodName:").append(invocation.getMethodName()).append(";");
        message.append("tokenStr:").append(RpcContext.getContext().getAttachment(CommonConst.tokenStr)).append(";");
        message.append("DbKey:").append(RpcContext.getContext().getAttachment(CommonConst.dbKey)).append(";");
        message.append("orgId:").append(RpcContext.getContext().getAttachment(CommonConst.orgId)).append(";");


        Class<?>[] parameterTypes = invocation.getParameterTypes();
        Object[] arguments = invocation.getArguments();


        if (parameterTypes!=null||parameterTypes.length>0) {
            message.append("arguments:");
            boolean isFileType = false;
            for (int i = 0; i < parameterTypes.length; i++) {
                if (FileTransferDto.class.isAssignableFrom(parameterTypes[i])) {
                    isFileType=true;
                }
            }
            if (!isFileType) {//排除文件传输类型的参数
                message.append(JSON.toJSONString(arguments));
            }
        }


        log.error(message.toString());
    }


    /**
     * 从dubbo上下文获取 跟踪信息，保存到 当前线程上下文中
     * @return
     */
    private String saveDistributedTracingContext() {
        String logId = RpcContext.getContext().getAttachment(CommonConst.logId);
        if (StringUtil.isEmpty(logId)) {
            logId = LogIdUtil.getLogId();
        }
        ThreadContext.put(CommonConst.logId, logId);
        return logId;
    }
    /**
     * 打印计时信息
     * @return
     */
    private void logTimeCost(String interfaceName,String methodName, long startTime,long stopTime) {
        StringBuilder logbuider = new StringBuilder("interfaceTimeCost:");
        logbuider.append(interfaceName);
        logbuider.append(",");
        logbuider.append(methodName);
        logbuider.append(",");
        logbuider.append(stopTime-startTime);
        log.error(logbuider.toString());
    }
}

4、异步线程池上下文传递工具

5、日志格式的设置 log4j2.xml 里这句就是新增的logId的位置：LOGID:%X{logId}

<appenders>  
        <!-- 定义控制台输出 -->  
        <Console name="Console" target="SYSTEM_OUT" follow="true">  
            <PatternLayout pattern="%date{yyyy-MM-dd HH:mm:ss.SSS} %level [LOGID:%X{logId}] [%thread][%file:%line] - %msg%n" />
        </Console>  
        <!-- 调试日志 -->  
        <RollingRandomAccessFile name="DevLog" fileName="${LOG_HOME}/${APP_NAME}.log"  
            filePattern="${LOG_HOME}/${APP_NAME}.%d{yyyy-MM-dd-HH}.log">  
            <PatternLayout pattern="%date{yyyy-MM-dd HH:mm:ss.SSS} %level [LOGID:%X{logId}] [%thread][%file:%line] - %msg%n" />
            <Policies>  
                <TimeBasedTriggeringPolicy interval="1" modulate="true" />  
            </Policies>  
        </RollingRandomAccessFile>  
    </appenders>

四、总结

1、目前分布式链路追踪组件的主要方案有：Java探针技术（字节码织入增强方向）和过滤器、拦截器（AOP方向）。

2、目前项目中靠这个自研的够用了，暂时没有引入第三方追踪组件的想法。

3、阿里云日志时间排序这块有点瑕疵，目前阿里云日志是按照日志收集时间来排序的，而我想要的是按原始产生日志的时间来排序，并且阿里云日志不能在毫秒级进行排序，还需要研究下怎么解决这些问题。

4、框架自身的一些公共线程日志没法搞logId插入，比如：Dubbo的RPC调用IO线程，本身就是大家共用的，如果在发送和接收过程中发生IO异常，好像就没得搞了，比如下面的两个异常：

[New I/O worker #1][Log4j2Logger.java:73] - Data length too large: 1895857664, max payload: 8388608, channel: NettyChannel [channel=[id: 0xbe23f2b5, /172.31.5.38:36596 => /172.31.2.196:21880]]\n\"\
[DubboClientHandler-172.31.1.191:21880-thread-44][Log4j2Logger.java:77] -  Dubbo client can not supported string message: sq",

5、如果想RPC中使用了不需要返回值的异步，消费者端的计时统计会不太准确，但是可以查看提供者端的计时统计。

6、如果有异常发生时，会将logId加到响应报文中返回到前端，方便开发解决问题。

7、针对目前的缺陷还得想想办法解决，达到的目标是只要有异常日志就要有问题来源的线索日志即可