微服务系统架构之分布式traceId追踪参考实现

夜微凉，时21点06分
    为何写这篇博客呢，先交代下前言吧。日前与杭州某公司技术总监聊天闲聊技术趋势，聊起当前炙手可热的微服务架构。尤其对于微服务运维这块，颇有见解, 他们公司采用的是SpringCloud作为微服务中间件基础支撑. 对SpringCloud架构当中的traceId设计称赞不已。闲聊过程当中，我跟他吹嘘，我也实现过一款基于TCP/IP协议的中间件哟[raptor]，同样也具备traceId分布式链路追踪功能。他的原话是：这功能具备一定的技术壁垒，不是那么容易的。当时我的感觉是：哇哦，总算又遇到一个在技术上产生共鸣的人。所以啦，这篇博客就这么诞生了。
    在早期设计raptor的过程中就考虑过traceId的问题。并将之作为重点实现核心予以重视，基于微服务架构的系统运维，日志追踪分析是解决生产问题的第一技术手段，甚至可以说是唯一的手段。通过traceId分析整个微服务的调用链，数据在不同服务节点的变更都一目了然，对于定位问题至关重要。在正式切入主题之前聊点花边新闻，曾经就分布式纯异步traceId的设计思路与某金融公司架构师以及阿里云某技术主管都有过交流。当时我的提问是：我有一个Http请求，在请求时与方法调用过程中我希望有一个traceId标记下这个调用链，基于同步调用如何处理。架构师给我的回复是用ThreadLocal。完美！非常棒，对于同步调用已经基本解决了问题。我随即抛出几个问题，如果这个Http请求涉及异步执行呢？涉及子线程呢？含有多次上下文切换呢？ThreadLocal还可以么？问题四连击，智慧的火花四处飞溅。。。
    进入正题，先上一段代码吧. 还是接着上面的Http请求讨论.

package raptor;

import java.io.IOException;

import javax.servlet.ServletException;
import javax.servlet.annotation.WebServlet;
import javax.servlet.http.HttpServlet;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;

import com.eaio.uuid.UUID;

@WebServlet("/pushMessageServlet")
public class PushMessageServlet extends HttpServlet {

    private static final long serialVersionUID = 1L;

    private static final Logger LOGGER = LoggerFactory.getLogger(PushMessageServlet.class);

    private static final ThreadLocal<String> TRACEID = new ThreadLocal<String>() {
        @Override
        protected String initialValue() {
            String traceId = new UUID().toString();
            return traceId;
        }
    };

    /**
     * Default constructor.
     */
    public PushMessageServlet() {
        // TODO Auto-generated constructor stub
    }

    /**
     * @see HttpServlet#doGet(HttpServletRequest request, HttpServletResponse
     *      response)
     */
    protected void doGet(HttpServletRequest request, HttpServletResponse response)
            throws ServletException, IOException {
        MDC.put("traceId", TRACEID.get()); // 模拟同步设置traceId
        LOGGER.info("服务调用开始~");
        //xxx此处省略调用
        LOGGER.info("服务调用结束~");
    }

}

服务日志输出如下：

2019-04-26 20:50:34.913|e22a1910-6821-11e9-8148-408d5c62c7bd|[qtp326125656-54] INFO   raptor.PushMessageServlet - 服务调用开始~
2019-04-26 20:50:34.913|e22a1910-6821-11e9-8148-408d5c62c7bd|[qtp326125656-54] INFO   raptor.PushMessageServlet - 服务调用结束~

代码里手工设置MDC的部分可以转移至Filter或者ServletRequestListener里实现，这里不追究细节哈，只做演示。这段代码总体已经较为明确的解决前文所提的需求，一次请求打印同样的traceId。但依然不够完美，我们对服务Http地址多发起几笔请求，你会发现TM居然出现了traceId重复情况，说好的一次请求一个线程呢？为什么traceId会重复呢？难道web请求处理完线程不自动销毁么，是不是超怪异？在开发raptor之初我也困惑过一小段时间，后仔细思索其实主流的web容器tomcat/jetty等对于http请求基本基于NIO Reactor 主从网络IO模型，即会有一个线程池来处理。问题至此已然清晰，是线程复用导致了traceId不能针对每一笔http请求重新生成, 那我们该如何规避这种问题呢？毕竟我们也不可能为了traceId去改写容器的源码啊。于此，引申了出了raptor设计traceId实现的第一要素：针对traceId,每一次单独的线程处理业务即要保证它的生成，也要同时保证它的销毁[或者说是覆盖]。
OK啦，聊到此貌似我们都是基于同步链路调用的场景下再述说一些设计实现，但现实世界中各种异构设计，各种搞7搞8的需求贼多，甚至很多链路调用都不是基于web容器的，或者说一次微服务调用链路混合多种协议都很常见。何以处之? 唯有依赖专属研发的中间件，定制化开发才能适配各种场景，已不变应万变。那么是时候展示raptor traceId设计实现了，先卖个关子。支持同步/异步，任意组合嵌套爽到不行。。。

traceId上下文类，采用阿里巴巴TTL框架解决刚才所提线程池容器线程变量副本更新问题。

package raptor.log;

import com.alibaba.ttl.TransmittableThreadLocal;

public final class ThreadContext {
    
    public static final TransmittableThreadLocal<String> TRACEID = new TransmittableThreadLocal<String>();
    
}

客户端数据出站, 数据出站成功后回调，产生一次上下文切换需要重置traceId

    @Override
    public void pushMessage(RpcRequestBody requestBody) {
        RpcPushDefine rpc = this;
        ChannelFuture future = ctx.writeAndFlush(requestBody);
        future.addListener(new ChannelFutureListener() {
            @Override
            public void operationComplete(ChannelFuture future) throws Exception {
                //mark:回调此处会发生一次线程上下文切换,需要重置线程号.
                ThreadContext.TRACEID.set(requestBody.getTraceId());
                if (future.isSuccess()) {
                    LOGGER.info("RPC客户端数据出站SUCCESS, " + requestBody);
                    try {
                        pool.returnObject(rpc);
                    } catch (Exception e) {
                        String message = StringUtil.getErrorText(e);
                        LOGGER.error("资源释放异常,tcpId: " + rpc.getTcpId() + ", serverNode: " + serverNode + ", message: " + message);
                        pool.invalidateObject(rpc);
                    }
                } else {
                    outboundException(requestBody.getMessageId(), requestBody.getTraceId(), "Rpc出站Fail.", RpcResult.FAIL_NETWORK_TRANSPORT);
                    String message = StringUtil.getErrorText(future.cause()); 
                    LOGGER.warn("RPC客户端数据出站FAIL: " + requestBody + ", tcpId: " + rpc.getTcpId() + ", serverNode: " + serverNode + ", message: " + message); 
                    pool.invalidateObject(rpc);
                }
            }
        });
    }

客户端异步请求响应后, 数据入站产生一次上下文切换，重置traceId

    @Override
    protected void channelRead0(ChannelHandlerContext ctx, RpcResponseBody responseBody) throws Exception {
        if (responseBody.getRpcMethod().equals(HEARTBEAT_METHOD)) {
            heartbeatCount.set(0);
            LOGGER.warn("[重要!!!]tcp 心跳包收到响应,tcpId: " + getTcpId() + ", serverNode: " + serverNode);
            return;
        }
        
        ThreadContext.TRACEID.set(responseBody.getTraceId());
        responseBody.setReturnTime(new DateTime()); 
        RpcClientTaskPool.addTask(responseBody); 
        
    }

服务器端数据入站与出站各产生一次上下文切换,重置traceId

    @Override
    protected void channelRead0(ChannelHandlerContext ctx, RpcRequestBody msg) throws Exception {
        ThreadContext.TRACEID.set(msg.getTraceId());
        RpcServerTaskPool.addTask(msg, new AbstractCallBack() {
            @Override
            public void invoke(RpcResponseBody responseBody) {
                ChannelFuture future = ctx.writeAndFlush(responseBody);
                future.addListener(new ChannelFutureListener() {
                    @Override
                    public void operationComplete(ChannelFuture future) throws Exception {
                        ThreadContext.TRACEID.set(msg.getTraceId());
                        if (future.isSuccess()) {
                            LOGGER.info("RPC服务端数据出站SUCCESS, " + responseBody);
                        } else {
                            String message = StringUtil.getErrorText(future.cause());
                            LOGGER.warn("RPC服务端数据出站FAIL: " + responseBody + ", message: " + message);   
                        }
                    }
                });
            }
        });
    }

客户端与服务端业务线程池基于阿里巴巴TTL框架解决线程池内线程副本更新问题，示例代码如下：

    /**
     * @author gewx 添加任务入业务线程池
     * @param Object
     *            obj 请求参数, AbstractCallBack call 业务回调对象.
     * @return void
     **/
    public static void addTask(RpcRequestBody requestBody, AbstractCallBack call) {
        String rpcMethod = requestBody.getRpcMethod();
        String traceId = requestBody.getTraceId();
        ListenableFuture<RpcResponseBody> future = POOLTASKEXECUTOR
                .submitListenable(TtlCallable.get(new Callable<RpcResponseBody>() {
                    @Override
                    public RpcResponseBody call() throws Exception {
                        LOGGER.info("RPC服务端收到请求信息: " + requestBody);        
                        
                        RpcHandlerObject handler = RPC_MAPPING.get(rpcMethod);
                        if (handler == null) {
                            throw new RpcException("RPC参数缺失,RpcMethod is null !", RpcResult.ERROR);
                        }
                        
                        Object result = null;
                        Object [] objArray = requestBody.getBody();
                        if (ArrayUtils.isNotEmpty(objArray)) {
                                     //MethodUtils.invokeExactMethod(object, methodName); 根据类型完全匹配.
                            result = MethodUtils.invokeMethod(handler.getObject(), handler.getRpcKey(), objArray);
                        } else {
                            result = MethodUtils.invokeMethod(handler.getObject(), handler.getRpcKey());
                        }
                        
                        RpcResponseBody body = new RpcResponseBody();
                        body.setRpcCode(RpcResult.SUCCESS);
                        body.setMessageId(requestBody.getMessageId());
                        body.setTraceId(traceId);
                        body.setRpcMethod(rpcMethod);
                        body.setBody(result);
                        body.setMessage("RPC调用成功!");
                        return body;
                    }
                }));

        future.addCallback(new ListenableFutureCallback<RpcResponseBody>() {

            @Override
            public void onSuccess(RpcResponseBody body) {
                call.invoke(body);
            }

            @Override
            public void onFailure(Throwable throwable) {
                String message = "RPC 服务调用失败,message:[" + StringUtil.getErrorText(throwable) + "]";
                LOGGER.warn(rpcMethod, message);    

                /**
                 * 定义回调异常,默认响应体
                 * **/
                RpcResponseBody body = new RpcResponseBody();
                body.setRpcCode(RpcResult.FAIL);
                body.setMessageId(requestBody.getMessageId());
                body.setTraceId(traceId);
                body.setRpcMethod(rpcMethod);
                body.setMessage("RPC 服务调用失败,message:[" + ExceptionUtils.getRootCauseMessage(throwable) + "]");
                
                call.invoke(body);
            }
        });
    }

好了，博客写到这也接近尾声了，感觉写了很多，但是回头看好像也就穷贴代码了，哈哈。在小伙伴们开发分布式链路追踪日志模块的时候，可以略借鉴喔。假设基于Netty来实现，我们首先要搞清楚几个问题，线程在什么时候发生了切换，由于采用了ThreadLocal或其变种技术，凡是产生上下文切换的地方必须要重置traceId，即复写当前线程副本中的内容[Netty IO模型本身也是基于Reactor设计的，所以框架本身就存在线程池,也就存在线程副本内容复用] 。

最后献上raptor log框架实现以及一段暴力验证代码，收尾！

package raptor.log;

import org.apache.commons.lang3.StringUtils;
import org.slf4j.MDC;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import com.eaio.uuid.UUID;

/**
 * @author gewx Raptor PRC 日志框架
 **/
public final class RaptorLogger {

    enum LOGGER {
        enter, exit, info, warn, error
    }

    private static final String MDC_STATE = "state";

    private static final String MDC_TRACEID = "traceId";

    private final Logger logger;

    @SuppressWarnings("rawtypes")
    public RaptorLogger(Class c) {
        this.logger = LoggerFactory.getLogger(c);
    }

    /**
     * @author gewx 日志打印
     * @param methodName
     *            方法名, msg 打印消息body, isRepeatTraceId 是否采用新的traceId
     *            [默认true:不覆盖,false:覆盖] 备注:方法调用链最头部部分需要设置traceId,以用来追踪分布式日志栈.
     *            其它场景的日志打印无需关注这个入参,所谓调用链最头部,譬如:面向外部的Web服务的入口处,如servlet等
     * @return void
     **/
    public void enter(String methodName, String msg, boolean isRepeatTraceId) {
        if (!isRepeatTraceId) {
            ThreadContext.TRACEID.set(new UUID().toString());
        }

        MDC.put(MDC_STATE, StringUtils.trimToEmpty(methodName) + " | " + LOGGER.enter);
        MDC.put(MDC_TRACEID, ThreadContext.TRACEID.get());
        logger.info(msg);
        MDC.clear();
    }

    public void enter(String methodName, String msg) {
        enter(methodName, msg, true);
    }

    public void enter(String msg, boolean isRepeatTraceId) {
        enter(null, msg, isRepeatTraceId);
    }

    public void enter(String msg) {
        enter(null, msg);
    }

    public void exit(String methodName, String msg) {
        MDC.put(MDC_STATE, StringUtils.trimToEmpty(methodName) + " | " + LOGGER.exit);
        MDC.put(MDC_TRACEID, ThreadContext.TRACEID.get());
        logger.info(msg);
        MDC.clear();
    }

    public void exit(String msg) {
        exit(null, msg);
    }

    public void info(String methodName, String msg, boolean isRepeatTraceId) {
        if (!isRepeatTraceId) {
            ThreadContext.TRACEID.set(new UUID().toString());
        }

        MDC.put(MDC_STATE, StringUtils.trimToEmpty(methodName));
        MDC.put(MDC_TRACEID, ThreadContext.TRACEID.get());
        logger.info(msg);
        MDC.clear();
    }

    public void info(String methodName, String msg) {
        info(methodName, msg, true);
    }

    public void info(String msg, boolean isRepeatTraceId) {
        info(null, msg, isRepeatTraceId);
    }

    public void info(String msg) {
        info(null, msg);
    }

    public void warn(String methodName, String msg) {
        MDC.put(MDC_STATE, StringUtils.trimToEmpty(methodName));
        MDC.put(MDC_TRACEID, ThreadContext.TRACEID.get());
        logger.warn(msg);
        MDC.clear();
    }

    public void warn(String msg) {
        warn(null, msg);
    }

    public void error(String methodName, String msg) {
        MDC.put(MDC_STATE, StringUtils.trimToEmpty(methodName));
        MDC.put(MDC_TRACEID, ThreadContext.TRACEID.get());
        logger.error(msg);
        MDC.clear();
    }

    public void error(String msg) {
        error(null, msg);
    }

}

验证：

        boolean isTest = false;
        if (isTest) {
            //测试分布式日志
            int cpuNum = Runtime.getRuntime().availableProcessors();
            Executor pool = Executors.newFixedThreadPool(cpuNum);
            CyclicBarrier lock = new CyclicBarrier(cpuNum);
            for (int i = 0; i < cpuNum * 100; i++) {
                pool.execute(new Runnable() {
                    @Override
                    public void run() {
                        try {
                            lock.await();
                        } catch (Exception e1) {
                        }
                        final String methodName = "threadRun";
                        //参数false作用为:不复用traceId,每次请求都作为单独的事务开始.
                        LOGGER.enter(methodName,"RPC execute start!",false);
                        try {
                            RpcResponseBody resp = rpc.sendSyncMessage("mc", "LoginAuth");
                            LOGGER.info("RPC同步响应: " + resp);
                            if (RpcResult.SUCCESS.equals(resp.getRpcCode())) {
                                LOGGER.info(methodName, "同步RPC服务调用SUCCESS~");
                            } else {
                                LOGGER.warn(methodName, "同步RPC服务调用异常!");
                            }
                        } catch (RpcException e) {
                            if (RpcResult.FAIL_NETWORK_CONNECTION.equals(e.getRpcCode())) {
                                LOGGER.error(methodName, "网络连接异常, message: " + e.getMessage());
                            } else {
                                LOGGER.error(methodName, "其它异常, message: " + e.getMessage());
                            }
                        }
                        
                        LOGGER.info("RPC异步请求开始...");
                        try {
                            rpc.sendAsyncMessage("mc", "LoginAuth",new AbstractCallBack() {
                                @Override
                                public void invoke(RpcResponseBody resp) {
                                    LOGGER.info("RPC异步响应: " + resp);
                                    if (RpcResult.SUCCESS.equals(resp.getRpcCode())) {
                                        LOGGER.info(methodName, "异步RPC服务调用SUCCESS~");
                                    } else {
                                        LOGGER.warn(methodName, "异步RPC服务调用异常!");
                                    }
                                }
                            });
                        } catch (RpcException e) {
                            if (RpcResult.FAIL_NETWORK_CONNECTION.equals(e.getRpcCode())) {
                                LOGGER.error(methodName, "网络连接异常, message: " + e.getMessage());
                            } else {
                                LOGGER.error(methodName, "其它异常, message: " + e.getMessage());
                            }
                        }
                        
                        LOGGER.enter(methodName,"RPC execute end!");
                    }
                });
            }
        }

啦啦啦，我的第二篇博客，就此收篇，如有写的不足的地方欢迎留言斧正啊，技术在于交流喔。我特别欢迎有SpringCloud使用经验的小伙伴发表看后感言。
晚安时： 2019.4.26 21:44分

人面猴
序言：七十年代末，一起剥皮案震惊了整个滨河市，随后出现的几起案子，更是在滨河造成了极大的恐慌，老刑警刘岩，带你破解...
沈念sama阅读 156,265评论 4赞 359
死咒
序言：滨河连续发生了三起死亡事件，死亡现场离奇诡异，居然都是意外死亡，警方通过查阅死者的电脑和手机，发现死者居然都...
沈念sama阅读 66,274评论 1赞 288
救了他两次的神仙让他今天三更去死
文/潘晓璐我一进店门，熙熙楼的掌柜王于贵愁眉苦脸地迎上来，“玉大人，你说我怎么就摊上这事。” “怎么了？”我有些...
开封第一讲书人阅读 106,087评论 0赞 237
道士缉凶录：失踪的卖姜人
文/不坏的土叔我叫张陵，是天一观的道长。经常有香客问我，道长，这世上最难降的妖魔是什么？我笑而不...
开封第一讲书人阅读 43,479评论 0赞 203
港岛之恋（遗憾婚礼）
正文为了忘掉前任，我火速办了婚礼，结果婚礼上，老公的妹妹穿的比我还像新娘。我一直安慰自己，他们只是感情好，可当我...
茶点故事阅读 51,782评论 3赞 285
恶毒庶女顶嫁案：这布局不是一般人想出来的
文/花漫我一把揭开白布。她就那样静静地躺着，像睡着了一般。火红的嫁衣衬着肌肤如雪。梳的纹丝不乱的头发上，一...
开封第一讲书人阅读 40,218评论 1赞 207
城市分裂传说
那天，我揣着相机与录音，去河边找鬼。笑死，一个胖子当着我的面吹牛，可吹牛的内容都是我干的。我是一名探鬼主播，决...
沈念sama阅读 31,594评论 2赞 309
双鸳鸯连环套：你想象不到人心有多黑
文/苍兰香墨我猛地睁开眼，长吁一口气：“原来是场噩梦啊……” “哼！你这毒妇竟也来了？” 一声冷哼从身侧响起，我...
开封第一讲书人阅读 30,316评论 0赞 194
万荣杀人案实录
序言：老挝万荣一对情侣失踪，失踪者是张志新（化名）和其女友刘颖，没想到半个月后，有当地人在树林里发现了一具尸体，经...
沈念sama阅读 33,955评论 1赞 237
护林员之死
正文独居荒郊野岭守林人离奇死亡，尸身上长有42处带血的脓包…… 初始之章·张勋以下内容为张勋视角年9月15日...
茶点故事阅读 30,274评论 2赞 240
白月光启示录
正文我和宋清朗相恋三年，在试婚纱的时候发现自己被绿了。大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
茶点故事阅读 31,803评论 1赞 255
活死人
序言：一个原本活蹦乱跳的男人离奇死亡，死状恐怖，灵堂内的尸体忽然破棺而出，到底是诈尸还是另有隐情，我是刑警宁泽，带...
沈念sama阅读 28,177评论 2赞 250
日本核电站爆炸内幕
正文年R本政府宣布，位于F岛的核电站，受9级特大地震影响，放射性物质发生泄漏。R本人自食恶果不足惜，却给世界环境...
茶点故事阅读 32,732评论 3赞 229
男人毒药：我在死后第九天来索命
文/蒙蒙一、第九天我趴在偏房一处隐蔽的房顶上张望。院中可真热闹，春花似锦、人声如沸。这庄子的主人今日做“春日...
开封第一讲书人阅读 25,953评论 0赞 8
一桩弑父案，背后竟有这般阴谋
文/苍兰香墨我抬头看了看天上的太阳。三九已至，却和暖如春，着一层夹袄步出监牢的瞬间，已是汗流浃背。一阵脚步声响...
开封第一讲书人阅读 26,687评论 0赞 192
情欲美人皮
我被黑心中介骗来泰国打工，没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留，地道东北人。一个月前我还...
沈念sama阅读 35,263评论 2赞 267
代替公主和亲
正文我出身青楼，却偏偏与公主长得像，于是被迫代替她去往敌国和亲。传闻我的和亲对象是个残疾皇子，可洞房花烛夜当晚...
茶点故事阅读 35,189评论 2赞 258

微服务系统架构之分布式traceId追踪参考实现

推荐阅读更多精彩内容