Spring Cloud Feign 记录单个服务耗时并解决 Hystrix 线程隔离模式

随着公司业务的增长，系统的调用量也越来越多。对于第三方支付平台公司的我们，如何提高系统的稳定性是摆在我们面前的一个问题。为了解决系统稳定性问题，决定把整个服务的日志通过日志跟踪号(traceNo) 以及一次调用链中每一个单个服务的调用时间打印到每个服务特定的目录中。 单个服务打印的数据运维会记录到 ES 里面，提供大盘给各个业务系统 owner 优化服务。

分析这个需求，里面包含以下几个需求：

• 解析上游传递过来的跟踪号，添加到 MDC 中记录整个日志，并且记录在当前服务当中调用的整个耗时
  把上游传递过来的跟踪号传递到下游去，使得整个跟踪号能够串连起整个调用链

• 由于我们服务使用的是 Spring Cloud 所以可以使用 Spring 提供的 HandlerInterceptor 对调用进行增强。调用远程服务使用的是 Feign ，可以使用 Feign 的扩展 RequestInterceptor 把 MDC 里面的日志跟踪号通过 header 的形式传递给下游。

1、针对上游服务

针对上游服务我们使用 Spring 提供的 HandlerInterceptor 对调用进行增强。

1.1 Conventions

常量类，记录当前需要使用到的一些常量信息。

Conventions.java

public static class Conventions {


    /**
     * 远程调用时用来传递统一上下文UUID的HTTP HEADER
     */
    public static final String LOG_ID_HEADER         = "LOG_ID";

    /**
    * 在MDC中存放统一上下文LOGID的KEY
    */
    public static final String CTX_LOG_ID_MDC        = "ctxLogId";

}

1.2 TraceEntity

数据模型类，保存当前服务信息，跟踪号调用路径以及耗时。

TraceEntity.java

public class TraceEntity {

    /** 跟踪号 */
    private String trackNo;

    /** 服务 ID */
    private String serviceId;

    /** http path */
    private String path;

    /** 调用耗时(ms) */
    private Long time;

}

1.3 WebDigestLogTimer

一次业务调用用时时间类，记录服务调用的开始时间与结束时间。

WebDigestLogTimer.java

@Data
public class WebDigestLogTimer {
    /**
     * 开始处理时间
     */
    private Long beginTime;
    /**
     * 处理结束时间
     */
    private Long processEndTime;

}

1.4 ExecutionTimeHandlerInterceptor

通过继承 Spring MVC 提供的 HandlerInterceptorAdapter 扩展类，在服务调用可以在服务调用的前后对服务进行增强。解析上游传递过来的 MDC 信息以及服务信息并且打印到服务指定的日志文件当中。

ExecutionTimeHandlerInterceptor.java

public class ExecutionTimeHandlerInterceptor extends HandlerInterceptorAdapter {

    private final Logger logger;

    private final String serviceName;

    private ThreadLocal<WebDigestLogTimer> timer = new ThreadLocal<>();

    public ExecutionTimeHandlerInterceptor(String serviceName, String loggerName) {
        this.serviceName = serviceName;
        this.logger = LoggerFactory.getLogger(loggerName);
    }

    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) {
        addCtxLogId(request);

        WebDigestLogTimer logTimer = new WebDigestLogTimer();
        logTimer.setBeginTime(System.currentTimeMillis());
        timer.remove();
        timer.set(logTimer);
        return true;
    }

    @Override
    public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler, ModelAndView modelAndView) throws Exception {
        timer.get().setProcessEndTime(System.currentTimeMillis());
    }

    @Override
    public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Exception {
        WebDigestLogTimer logTimer = timer.get();
        Long costTime = logTimer.getProcessEndTime() - logTimer.getBeginTime();
        String path = request.getServletPath();
        String traceNo = MDC.get(Conventions.CTX_LOG_ID_MDC);
        TraceEntity traceEntity = TraceEntity.builder().trackNo(traceNo).serviceId(serviceName).path(path).time(costTime).build();
        logger.info("{} invoke {} cost time : {}, trace entity is {}", serviceName, path, costTime, JSON.toJSONString(traceEntity));
        MDC.clear();
    }

    private void addCtxLogId(HttpServletRequest request) {
        String ctxUniqId;
        if (StringUtils.isNotBlank(request.getHeader(Conventions.LOG_ID_HEADER))) {
            ctxUniqId = request.getHeader(Conventions.LOG_ID_HEADER);
        } else {
            ctxUniqId = UUID.randomUUID().toString();
        }
        MDC.put(Conventions.CTX_LOG_ID_MDC, ctxUniqId);
    }

}

2、针对于服务下游

对于服务下游来说就比较简单，使用 Feign 的请求扩展 RequestInterceptor，可以把 MDC 里面的日志跟踪号传递到请求的 header 里面，下游就可以使用上面的拦截器获取到日志跟踪号了。

LogIdRequestInterceptor

@Slf4j
public class LogIdRequestInterceptor implements RequestInterceptor {

    @Override
    public void apply(RequestTemplate template) {
        String ctxLogId = MDC.get(Conventions.CTX_LOG_ID_MDC);
        if(ctxLogId == null || ctxLogId.length() == 0) {
            log.warn("LogIdRequestInterceptor#apply get ctx log id is null");
            ctxLogId = UUID.randomUUID().toString();
        }
        template.header(Conventions.LOG_ID_HEADER, ctxLogId);
    }

}

但是这里有一个问题，在我们使用 Feign 进行远程调用的时候，使用 Hystrix 进行线程隔离模式时，无法获取ThreadLocal中信息(MDC 基于 ThteadlLocal 实现)。我们的日志号就不能往下游传递了。其实 Hystrix 里面可以使用自定义并发策略解决这个问题。

3、自定义 Hystrix 并发策略

在这里我借鉴了一下 Discovery 里面对 Hystrix 的扩展。

3.1 StrategyCallableWrapper

自定义线程包装接口，扩展 Hystrix 线程创建策略。

StrategyCallableWrapper.java

public interface StrategyCallableWrapper {

    <T> Callable<T> wrapCallable(Callable<T> callable);

}

3.2 DefaultStrategyCallableWrapper

默认的实现类，把 MDC 里面保存的日志 ID，传递到子线程里面去。

DefaultStrategyCallableWrapper.java

public class DefaultStrategyCallableWrapper implements StrategyCallableWrapper {

    @Override
    public <T> Callable<T> wrapCallable(Callable<T> callable) {
        String ctxLogId = MDC.get(Conventions.CTX_LOG_ID_MDC);
        return () -> {
            try {
                MDC.put(Conventions.CTX_LOG_ID_MDC, ctxLogId);
                return callable.call();
            } finally {
                MDC.clear();
            }
        };
    }

}

3.3 HystrixContextConcurrencyStrategy

HystrixContextConcurrencyStrategy继承 HystrixConcurrencyStrategy自定义并发策略, 解决使用 Hystrix 线程隔离模式时，无法获取ThreadLocal中信息。

HystrixContextConcurrencyStrategy.java

public class HystrixContextConcurrencyStrategy extends HystrixConcurrencyStrategy {

    @Autowired
    private StrategyCallableWrapper strategyCallableWrapper;

    private HystrixConcurrencyStrategy hystrixConcurrencyStrategy;

    public HystrixContextConcurrencyStrategy() {
        // HystrixPlugins只能注册一次策略，保留原对象
        this.hystrixConcurrencyStrategy = HystrixPlugins.getInstance().getConcurrencyStrategy();

        // Keeps references of existing Hystrix plugins.
        HystrixCommandExecutionHook commandExecutionHook = HystrixPlugins.getInstance().getCommandExecutionHook();
        HystrixEventNotifier eventNotifier = HystrixPlugins.getInstance().getEventNotifier();
        HystrixMetricsPublisher metricsPublisher = HystrixPlugins.getInstance().getMetricsPublisher();
        HystrixPropertiesStrategy propertiesStrategy = HystrixPlugins.getInstance().getPropertiesStrategy();

        HystrixPlugins.reset();

        // Registers existing plugins excepts the Concurrent Strategy plugin.
        HystrixPlugins.getInstance().registerConcurrencyStrategy(this);
        HystrixPlugins.getInstance().registerCommandExecutionHook(commandExecutionHook);
        HystrixPlugins.getInstance().registerEventNotifier(eventNotifier);
        HystrixPlugins.getInstance().registerMetricsPublisher(metricsPublisher);
        HystrixPlugins.getInstance().registerPropertiesStrategy(propertiesStrategy);
    }

    @Override
    public BlockingQueue<Runnable> getBlockingQueue(int maxQueueSize) {
        return hystrixConcurrencyStrategy.getBlockingQueue(maxQueueSize);
    }

    @Override
    public <T> HystrixRequestVariable<T> getRequestVariable(HystrixRequestVariableLifecycle<T> rv) {
        return hystrixConcurrencyStrategy.getRequestVariable(rv);
    }

    @Override
    public ThreadPoolExecutor getThreadPool(HystrixThreadPoolKey threadPoolKey, HystrixProperty<Integer> corePoolSize, HystrixProperty<Integer> maximumPoolSize, HystrixProperty<Integer> keepAliveTime, TimeUnit unit, BlockingQueue<Runnable> workQueue) {
        return hystrixConcurrencyStrategy.getThreadPool(threadPoolKey, corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue);
    }

    @Override
    public ThreadPoolExecutor getThreadPool(HystrixThreadPoolKey threadPoolKey, HystrixThreadPoolProperties threadPoolProperties) {
        return hystrixConcurrencyStrategy.getThreadPool(threadPoolKey, threadPoolProperties);
    }

    @Override
    public <T> Callable<T> wrapCallable(Callable<T> callable) {
        return strategyCallableWrapper.wrapCallable(callable);
    }

}

3.4 方便使用方接入

并且为了方便使用方接入，在这里使用 Spring Boot 的自动依赖配置功能。

HystrixStrategyAutoConfiguration.java

@Configuration
@ConditionalOnClass(Hystrix.class)
@ConditionalOnProperty(value = "logger.strategy.hystrix.threadlocal.supported", matchIfMissing = false)
public class HystrixStrategyAutoConfiguration {

    @Bean
    public HystrixContextConcurrencyStrategy hystrixContextConcurrencyStrategy() {
        return new HystrixContextConcurrencyStrategy();
    }

    @Bean
    public DefaultStrategyCallableWrapper strategyCallableWrapper(){
        return new DefaultStrategyCallableWrapper();
    }

}

在项目的资源目录添加以下文件：

+ resources
  └ META-INF
    └ spring.factories

org.springframework.boot.autoconfigure.EnableAutoConfiguration=\
com.ushareit.fintech.framework.log.trace.HystrixStrategyAutoConfiguration

使用方只有在 classpath 里面引入了 Hystrix 的 jar 包并且在配置文件中添加logger.strategy.hystrix.threadlocal.supported=true的时候才会激活 Hystrix 日志参数传递。

4、使用方如何接入

下面来看一下使用方是如何丝滑的接入这个功能的。

4.1 引入 Jar 包

需要使用这个功能，当然需要使用里面的类，所以我们需要依赖提供这些类的 Jar 包

<dependency>
    <groupId>com.xxx.xxx.framework</groupId>
    <artifactId>common-log</artifactId>
    <version>1.0.2</version>
</dependency>

4.2 配置文件(针对 Hystrix 项目)

需要在 spring boot 项目中的 application.properties 文件中添加以下配置：

logger.strategy.hystrix.threadlocal.supported=true

注意：如果你的项目中并没有使用 Hystrix，请忽略当前步骤。

4.3 上游服务 Header 处理

构建器里面添加 test-server 服务名称，以及需要打印日志的 logger 名称。然后通过 Spring 里面提供的 @Configuration 和 @EnableWebMvc 激活。

WebMvcConfig .java

@Configuration
@EnableWebMvc
public class WebMvcConfig extends WebMvcConfigurerAdapter{

    @Override
    public void addInterceptors(InterceptorRegistry registry) {
        // MDC
        ExecutionTimeHandlerInterceptor executionTimeInterceptor = new ExecutionTimeHandlerInterceptor("test-service", "WEB-DIGEST-LOGGER");
        registry.addInterceptor(executionTimeInterceptor);
    }

}

4.4 传递 Header 到下游服务

配置 LogIdRequestInterceptor 对象，把它添加到 Spring 容器里面。并且配置到 Feign 调用服务的配置类里面:

FeignConfiguration.java

##  1 FeignConfiguration

@Configuration
public class FeignConfiguration {

    @Bean
    public LogIdRequestInterceptor logIdRequestInterceptor(){
        return new LogIdRequestInterceptor();
    }

}

### 2 启动类上面添加注解
@EnableFeignClients(basePackages = { "com.xxxx.xxxx.payment.integration.service" }, defaultConfiguration = {FeignConfiguration.class})

4.5 日志配置

由于项目中使用的日志框架是 log4j2 ，所以要在 classpath:log4j2.xml 里面配置成以下信息。

<?xml version="1.0" encoding="UTF-8"?>

<!-- 设置log4j2的自身log级别为error -->
<configuration status="error">
    <Properties>
        <Property name="dir">logs</Property>
        <Property name="logFormat">[%d{yyyy-MM-dd HH:mm:ss}] [%-5level] [%t] [%X{ctxLogId}] [pay-fintech-service] [%c(%L)] %m%n
        </Property>
        <Property name="every_file_size">100MB</Property>
        <Property name="log_level">info</Property>
        <Property name="myAdditivity">false</Property>
    </Properties>

   <appenders>

       <RollingFile name="WEB-DIGEST" fileName="${dir}/web-digest.log" filePattern="${dir}/web-digest-%d{yyyy-MM-dd}-%i.log">
           <ThresholdFilter level="INFO"/>
           <PatternLayout pattern="${logFormat}"/>
           <Policies>
           <TimeBasedTriggeringPolicy/>
           <SizeBasedTriggeringPolicy size="${every_file_size}"/>
           </Policies>
       </RollingFile>
   </appenders>

   <loggers>
      <logger name="WEB-DIGEST-LOGGER" level="info" additivity="${myAdditivity}">
          <appender-ref ref="WEB-DIGEST" />
          <appender-ref ref="ERROR" />
   </logger>
   <root level="${log_level}">
      <appender-ref ref="SERVICE" />
      <appender-ref ref="CONSOLE" />
      <appender-ref ref="ERROR"  />
   </root>
   </loggers>
</configuration>

大家需要添加的内部片段如下：

日志打印地址：

       <RollingFile name="WEB-DIGEST" fileName="${dir}/web-digest.log" filePattern="${dir}/web-digest-%d{yyyy-MM-dd}-%i.log">
           <ThresholdFilter level="INFO"/>
           <PatternLayout pattern="${logFormat}"/>
           <Policies>
           <TimeBasedTriggeringPolicy/>
           <SizeBasedTriggeringPolicy size="${every_file_size}"/>
           </Policies>
       </RollingFile>

日志名称(也就是 ExecutionTimeHandlerInterceptor 里面配置的日志名称)

   <loggers>
      <logger name="WEB-DIGEST-LOGGER" level="info" additivity="false">
          <appender-ref ref="WEB-DIGEST" />
          <appender-ref ref="ERROR" />
   </logger>

是不是很顺滑？