背景

目前,微服务和分布式服务架构在互联网公司被普遍应用,在国内阿里dubbo用的比较多,但是,dubbo只是一个rpc框架,缺乏全链路追踪组件,并不像springcloud是一个生态,包含了各种分布式组件。

我们公司也是用dubbo,分布式服务虽然解决了水平扩展的问题,但是却又带来了其他新的问题,比如链路追踪这一块,如果是单体应用,所有的日志都在一个项目,现在是服务集群,各个服务之间的调用关系是错综复杂的,同一个服务具体是走的哪一个机器,是根据负载均衡算法路由的,所以不好查日志。哪怕是用了elk中心化日志系统,由于同一时间并发请求数量比较高,不同的请求日志都混在一起,所以最好可以做到链路追踪,尤其是全链路追踪,即不仅仅是在同一个项目找到当前线程的所有日志,而且还要在不同项目之间找到同一个请求的所有日志。

有了全链路追踪,就可以把分布式服务的每个服务节点串起来,从而更好的排查故障和监控系统。

具体实现原理是基于业界普遍的分布式追踪id,即把唯一的分布式追踪id从入口处,一直往下传递,最后每个服务的日志都包含了该分布式服务追踪id。

线程内和跨进程

要解决两大问题,

1、解决同一个进程内的同一个线程的链路追踪
基于java线程本地变量ThreadLocal实现。

2、解决跨进程的链路追踪
即在dubbo的服务消费者和服务提供者之间传递链路id,基于dubbo上下文RpcContext实现。

架构图

dubbo服务端链路 dubbo 调用链路_链路

核心设计思想

1、进程内的线程链路追踪
所谓进程内,就是指服务消费者或服务提供者内部的链路追踪,实现原理是基于
1)扩展日志框架(比如logback)的功能
2)每次打印日志的时候,自动携带链路id

2、跨进程的链路追踪
所谓跨进程,就是指服务消费者和服务提供者是两个运行在不同机器的进程,实现原理是基于:
1)自定义dubbo拦截器
实现dubbo的Filter接口;
根据当前请求线程的所在进程是服务消费者还是服务提供者,分表做不同的业务逻辑处理。
2)服务消费者
写数据到日志ThreadLocal;
在拦截器里,写数据到dubbo上下文RpcContext。
3)服务提供者
在拦截器,从dubbo上下文RpcContext读数据;
写数据到日志ThreadLocal。

总结

1、基于ThreadLocal,实现线程链路追踪。

2、基于dubbo的扩展功能,实现跨进程链路追踪,每个进程都要引入链路追踪功能才能实现全链路追踪。

3、链路追踪id被写在每个日志的日志戳字段里,通过在elk中心化日志系统里搜索链路Id,就可以搜索到一个请求的完整日志信息。
链路id日志戳字段,需要自己扩展日志框架功能,比如可以基于slf + logback实现。

代码

跨进程

自定义扩展dubbo拦截器

/**
 * dubbo日志拦截器,作用 
1.打印消费者和提供者的入参和响应 
基于dubbo拦截器实现 

2.全链路追踪 
基于日志拦截器(线程本地变量)和dubbo上下文实现。(注:全链路追踪的每个服务,都要配置该拦截器,才能实现全链路追踪)
 */
@Activate(group = {Constants.PROVIDER, Constants.CONSUMER})
public class AccessLogExtFilter implements Filter {

public Result invoke(Invoker<?> invoker, Invocation inv) throws RpcException {
  ...
  handleTraceNo();
  ...
}

/**
 * 在消费者和提供者之间传递日志戳-流水号数据,用于链路追踪
 */
private void handleTraceNo() {
  boolean isConsumer = RpcContext.getContext().isConsumerSide();
  if (isConsumer) { //如果是消费者,写数据到dubbo上下文
    RpcContext.getContext()
        .setAttachment("xxx_TRACE_NO", LogPreFixConverter.getCurrentThreadLogPreFix(""));
  } else { //如果是提供者,从dubbo上下文读数据
    String traceNo = RpcContext.getContext().getAttachment("xxx_TRACE_NO");
    if (StringUtils.isBlank(traceNo)) { //如果消费者没有设置流水号,就随机生成
      traceNo = UUID.randomUUID().toString();
    }

    LogPreFixConverter.setLogPreFixNoAppendThread(traceNo);
  }

}

线程内

扩展日志框架logback

1)自定义字段
日志配置文件

<!-- 统一日志格式输出用|分隔方便 elk日志工具收集处理 ,默认日志格式是 时间|级别|日志戳|代码路径|扩展json(收集图表数据,无则域留空)|脱敏后日志内容 -->
 <property name="logback.pattern"
  value="%date{yyyy-MM-dd HH:mm:ss.SSS}|%-5level|%logPreFix|%class.%method:%line|%extjson|%sensitiveMsg%n" />

logPreFix是自定义字段/日志戳/全链路id。

2)实现自定义字段处理类

public class LogPreFixConverter extends ClassicConverter {
 private static final ThreadLocal<String> logPreFixThreadLocal = new ThreadLocal<String>(); //这里的实现比较复杂一点,基于线程本地变量实现全链路跟踪。

	
@Override
 public String convert(ILoggingEvent event) { //这个方法的作用,就是映射字段变量和字段变量的值
  try {
   return getCurrentThreadLogPreFix(event.getFormattedMessage());
  } catch (Throwable t) {
   // TODO 处理异常,这时不应该再打印日志避免死循环
   System.err.println("LogPreFixConverter处理异常" + t.getMessage());
  }
  return "errorLogPreFix";
 }
 
 /**
	 * 获取线程局部日志前辍
	 * 
	 * @param msg
	 *            优先通过入口日志中查找orderid tradesn 等关键字来做为前辍,如果没找到则默认生成一个
	 * @return
	 */
	public String getCurrentThreadLogPreFix(String msg) {
		String logPreFixStr = logPreFixThreadLocal.get();
		if (StringUtils.isBlank(logPreFixThreadLocal.get())) {
			// key:value value可能为空(字符串开头有空格会受影响忽略,目前通过format方法时trim);
			// 可能以空格结束,可能为最后一个字符结束
			String rexp = "(orderid|tradesn|batchid):(\\s|.+?(\\s|.$))";
			// 忽略大小写查找到key:value数据据
			Pattern pattern = Pattern.compile(rexp, Pattern.CASE_INSENSITIVE);
			Matcher matcher = pattern.matcher(msg);
			if (matcher.find()) {
				// 得到key:value
				logPreFixStr = matcher.group();
				// 得到value ,如果value是json 替换掉"
				logPreFixStr = logPreFixStr.substring(
						logPreFixStr.indexOf(":") + 1).replace("\"", "");
			}
			if (StringUtils.isBlank(logPreFixStr)) {
				logPreFixStr = generateId(12);
			}
			// 增加线程id
			logPreFixStr = new StringBuilder().append(logPreFixStr).append("-")
					.append(Thread.currentThread().getId()).toString();
			logPreFixThreadLocal.set(logPreFixStr);
		}
		return logPreFixStr;
	}