Spring Boot整合分布式调用链追踪

    如果是传统的巨服务架构,有日志就能够满足基本的需求了。

    但面对微服务,事情变得有一些复杂:

    • 微服务之间存在复杂的调用链路,例如A -> B -> C
    • 为了高可用,每个微服务可能存在多个实例

    设想我们有A, B, C三个微服务,每个微服务有2个实例,在调用链A -> B -> C的过程中,发生了异常,导致某个请求挂掉了。

    此时,我们已经有日志系统了,该如何检查呢?我们需要一次检查2个A服务,如果运气不好的话,可能没有异常,我们接下来检查B服务,也可能没有异常,最后检查C服务,发现了异常。

    在上述任务排查过程中不难看出,在微服务架构下,各个服务的相互调用非常复杂。

    实际上,我们可以引入调用链的追踪机制,来查明这种关系。

    调用链追踪是这样一直机制:对于每一次调用,例如从A开始,就生成一条”调用链路”并赋一个追踪信息(后简称TraceId),调用到B时,会继承这个TraceId,如果它又调用了C服务,这个TraceId也会传递下去,直到调用链的末端。若是另一次调用链条,则会使用另一个随机生成的TraceId。

    针对这种追踪机制,业界已经存在了一些较为成熟的方案,例如Zipkin能够很好的完成链路调用的追踪工作。

    如果你使用的是Spring Boot全家桶,那么Zipkin可以较为方便地集成进来,可以参考。

    本书将选择一种更为直接的方式:手写代码实现调用追踪,并将它整合进日志系统中。

    这样做的好处有:

    • 如果你用过Zipkin,就能发现,它并不能覆盖全部的代码。通过手写代码的方式,我们能够更细粒度的控制追踪的实现。
    • ZipKin默认是需要独立存储的,对于常年运行的系统来说,无论是运维还是机器,都会造成一定的浪费。在我们的架构下,会把追踪与日志进行融合,节省Zipkin带来的额外成本。
    • 打日志时会自动带上TraceId,让调试和定位问题更加方便。

    幸运的是,Logback中提供了Mapped Diagnostic Context的功能,我们可以将一些变量存储到MDC中,在打日志中,将它打印出来。

    要说明的是,MDC是线程独立、线程安全的,而在我们的架构中,无论是HTTP还是RPC请求,都是在各自独立的线程中完成的,与MDC的机制可以很好地契合。

    我们来看一下TraceId的存取:

    如上所示: 我们直接调用MDC的put, get , remove方法完成了traceId(TraceId)的存取

    traceId可以根据需求随机生成:

    1. import java.util.Random;
    2. /**
    3. * @author coder4
    4. */
    5. public class TraceIdUtils {
    6. private static final Random random = new Random(System.currentTimeMillis());
    7. public static String getTraceId() {
    8. // 随机正整数的16进制化
    9. return Long.toString(Math.abs(random.nextLong()), 16);
    10. }
    11. }

    如上所属,我们随机生成正整数,并将其格式化为16进制字符串,方便查看。

    至于TraceId的生成时机,我们稍后进行讨论。

    根据前面的描述,应该可以想到,当TraceId为空的情况下,我们需要生成一个新的TraceId。

    换句话说,当访问是”源头”的情况下,标志着一次追踪的开始,例如:

    • HTTP请求开始之前
    • 消息队列监听器接收新消息时

    下面来看一下实现。首先,我们可以通过Filter机制,实现HTTP请求中的TraceId分配:

    如上所示,我们通过Spring MVC的AbstractRequestLoggingFilter接口,在发起请求之前生成一个全新的TraceId,并在请求结束后清理这个TraceId。

    1. nfiguration
    2. @ConditionalOnWebApplication
    3. public class TraceIdRequestLoggingFilterConfiguration {
    4. @Bean
    5. public TraceIdRequestLoggingFilter createTraceIdMDCFilter() {
    6. return new TraceIdRequestLoggingFilter();
    7. }
    8. }

    代码比较简单,不再详细讨论了。

    在消息队列的事件监听器中,也可以采取类似的方法新建TraceId:

    当然,如果对每个事件监听器都做上述处理,未免有些麻烦,可以使用抽象基类或者AOP的方式统一,这里不再详细展开。

    前面说了TraceId的全新生成,在另外一些情况中,只需要继承环境中已有的TraceId,不需要重新生成,例如:

    • RPC调用,一般情况是在HTTP请求中、或者消息队列中发起,此时系统中已有了一个TraceId
    • 服务内各类之间的相互调用,由于并不是与外界隔离的入口,一般都已经存在了一个TraceId,所以也不需要生成。

    前面已经提到,每次完整请求都是在各自独立的线程中完成的,因此”服务内各类之间”的相互调用,不需要额外处理,直接从MDC获取TraceId即可。

    我们重点看一下RPC中,如何传递TraceId。

    我们的技术架构使用了Thrife RPC,可以通过自定义协议的方式,将TraceId自动传递过去:

    1. import com.coder4.sbmvt.trace.TraceIdContext;
    2. import com.coder4.sbmvt.trace.TraceIdUtils;
    3. import org.apache.thrift.TException;
    4. import org.apache.thrift.protocol.TBinaryProtocol;
    5. import org.apache.thrift.protocol.TField;
    6. import org.apache.thrift.protocol.TProtocol;
    7. import org.apache.thrift.protocol.TProtocolFactory;
    8. import org.apache.thrift.protocol.TType;
    9. import org.apache.thrift.transport.TTransport;
    10. import org.slf4j.Logger;
    11. import org.slf4j.LoggerFactory;
    12. /**
    13. * @author coder4
    14. */
    15. public static final short TRACE_ID_FIELD = Short.MAX_VALUE;
    16. private Logger LOG = LoggerFactory.getLogger(getClass());
    17. public TraceBinaryProtocol(TTransport trans) {
    18. super(trans);
    19. }
    20. public TraceBinaryProtocol(TTransport trans, boolean strictRead, boolean strictWrite) {
    21. super(trans, strictRead, strictWrite);
    22. }
    23. public TraceBinaryProtocol(TTransport trans, long stringLengthLimit,
    24. long containerLengthLimit, boolean strictRead,
    25. boolean strictWrite) {
    26. super(trans, stringLengthLimit, containerLengthLimit, strictRead, strictWrite);
    27. }
    28. @Override
    29. public void writeFieldStop() throws TException {
    30. // get traceId from context
    31. String traceId = TraceIdContext.getTraceId();
    32. if (traceId == null || traceId.isEmpty()) {
    33. // generate new one if not avaliable
    34. traceId = TraceIdUtils.getTraceId();
    35. TraceIdContext.setTraceId(traceId);
    36. }
    37. // parse traceId
    38. TField field = new TField("", TType.STRING, TRACE_ID_FIELD);
    39. writeFieldBegin(field);
    40. writeString(traceId);
    41. writeFieldEnd();
    42. // super
    43. super.writeFieldStop();
    44. }
    45. @Override
    46. public TField readFieldBegin() throws TException {
    47. TField field = super.readFieldBegin();
    48. // read traceId
    49. while (true) {
    50. case TRACE_ID_FIELD:
    51. if (field.type == TType.STRING) {
    52. // set traceId to context
    53. String traceId = readString();
    54. TraceIdContext.setTraceId(traceId);
    55. readFieldEnd();
    56. } else {
    57. TProtocolUtil.skip(this, field.type);
    58. LOG.error("traceId field type is not string");
    59. }
    60. break;
    61. default:
    62. return field;
    63. }
    64. field = super.readFieldBegin();
    65. }
    66. }
    67. public static class Factory extends TBinaryProtocol.Factory implements TProtocolFactory {
    68. public Factory() {
    69. super();
    70. }
    71. public Factory(boolean strictRead, boolean strictWrite) {
    72. super(strictRead, strictWrite);
    73. }
    74. public Factory(boolean strictRead, boolean strictWrite, long stringLengthLimit, long containerLengthLimit) {
    75. super(strictRead, strictWrite, stringLengthLimit, containerLengthLimit);
    76. }
    77. @Override
    78. public TProtocol getProtocol(TTransport trans) {
    79. TraceBinaryProtocol protocol =
    80. new TraceBinaryProtocol(trans, stringLengthLimit_, containerLengthLimit_,
    81. strictRead_, strictWrite_);
    82. return protocol;
    83. }
    84. }
    85. }

    如上所示,我们继承了TBinaryProtocol,实现了TraceBinaryProtocol。

    • 它在writeFieldStop即写完其他字段后,追加了一个特殊字段TRACE_ID。字段TRACE_ID对应的值,首先会从MDC中获取,若取不到则需要重新生成。

    经过上面的努力,在我们的架构下,所有请求相关的处理,都会自动带上一个TRACE_ID,我们再来看一下如何将其展示在日志中:

    我们在logback的Pattern中添加”[tr=%mdc{TRACE_ID:-0}]”一项,表示从MDC中获取key为TRACE_ID的数据,若取不到则打印0。

    完整的Pattern如下:

    你会发现,不同的请求中,[tc=xxx]中的TraceId会发生变化。但在同一次请求中调用了多个类,则TraceId会保持、传递下去。