一次生产Feign重试问题的排查过程

问题

在使用skywalking监控生产环境问题时，发现有一个请求的调用链路中微服务Platform的内部接口inner/userinfo很奇怪的被重复调用了2次，如下图：

image-20190703230049833.png

分析过程

相关版本：Spring Cloud版本为Dalston.SR4，Spring Boot版本为1.5.7.RELEASE

查看inner/userinfo的服务方的2次调用分别耗时6043ms和8078ms，通过跟踪RetryableFeignLoadBalancer类的execute方法发现，feign的连接超时时间connectTimeout=2000（2秒），读超时时间readTimeout=5000（5秒），因此可以判断服务方的2次响应时间超过读超时时间阈值5秒了，因此调用方最终报了超时异常RetryableException。

我们知道，Spring Cloud中Feign整合了Ribbon，但Feign和Ribbon都有重试的功能，Spring Cloud为了统一两者的行为，将Feign的重试策略默认设置为 feign.Retryer#NEVER_RETRY（即永不重试）。如要使用Feign的重试功能的话，只需使用Ribbon的重试配置即可。既然这样，那为什么会有以上现象呢？

进一步研究发现，对于Camden以及以后的版本，Feign的重试可使用如下属性进行配置：

ribbon:
  # 同一实例最大重试次数，不包括首次调用。默认值为0
  MaxAutoRetries: 0
  # 同一个微服务其他实例的最大重试次数，不包括第一次调用的实例。默认值为1
  MaxAutoRetriesNextServer: 1
  # 是否所有操作（GET、POST等）都允许重试。默认值为false
  OkToRetryOnAllOperations: false

我们的服务方Platform没有配置这些参数，因此应该是使用了默认值。因为我们Platform微服务只启动了一个实例，所以我重点关注MaxAutoRetries参数，实际跟踪发现它的值也是0，这跟我理解的有出入啊！

跟踪Spring Cloud的源码，发现Feign是在RetryTemplate的doExecute方法中进行重试的判断和调用的:

protected <T, E extends Throwable> T doExecute(...) {
    ...
        while (canRetry(retryPolicy, context) && !context.isExhaustedOnly()) {

                try {
                    if (this.logger.isDebugEnabled()) {
                        this.logger.debug("Retry: count=" + context.getRetryCount());
                    }
                    // Reset the last exception, so if we are successful
                    // the close interceptors will not think we failed...
                    lastException = null;
                    return retryCallback.doWithRetry(context);
                }
                catch (Throwable e) {
          ...
        }
      ...
    }
  ...
}

其中canRetry方法用于判断当接口调用异常时是否需要进行重试。

跟进canRetry方法，终于找到了罪魁祸首——InterceptorRetryPolicy的canRetry方法：

org.springframework.cloud.client.loadbalancer.InterceptorRetryPolicy.java

    @Override
    public boolean canRetry(RetryContext context) {
        LoadBalancedRetryContext lbContext = (LoadBalancedRetryContext)context;
        if(lbContext.getRetryCount() == 0  && lbContext.getServiceInstance() == null) {
            //We haven't even tried to make the request yet so return true so we do
            lbContext.setServiceInstance(serviceInstanceChooser.choose(serviceName));
            return true;
        }
        return policy.canRetryNextServer(lbContext);
    }

留意最后一行：policy.canRetryNextServer(lbContext)。这一行意思是，根据策略判断是否重试服务的下一个实例。因为MaxAutoRetriesNextServer默认值为1，因此这里会返回true，所以inner/userinfo就被调用了2次。

解决方案

找到原因就好办了，解决方案很简单，在调用方的yml配置MaxAutoRetriesNextServer的值为0即可：

ribbon:
  # 同一实例最大重试次数，不包括首次调用。默认值为0
  MaxAutoRetries: 0
  # 同一个微服务其他实例的最大重试次数，不包括第一次调用的实例。默认值为1
  MaxAutoRetriesNextServer: 0
  # 是否所有操作（GET、POST等）都允许重试。默认值为false
  OkToRetryOnAllOperations: false

配置后，在开发环境验证成功！

附录

相关节点的异常：

1、Hystrix/IUserService#getUserInfo()/Execution节点的异常信息为：

Read timed out executing GET http://prong-cloud-server-platform/inner/userinfo

feign.RetryableException: Read timed out executing GET http://prong-cloud-server-platform/inner/userinfo
at feign.FeignException.errorExecuting(FeignException.java:67)
at feign.SynchronousMethodHandler.executeAndDecode(SynchronousMethodHandler.java:104)
at feign.SynchronousMethodHandler.invoke(SynchronousMethodHandler.java:76)
at feign.hystrix.HystrixInvocationHandler$1.run$original$guV1ukWA(HystrixInvocationHandler.java:108)
at feign.hystrix.HystrixInvocationHandler$1.run$original$guV1ukWA$accessor$1jiMEUrR(HystrixInvocationHandler.java)
at feign.hystrix.HystrixInvocationHandler$1$auxiliary$sEUgyNk3.call(Unknown Source)
at org.apache.skywalking.apm.agent.core.plugin.interceptor.enhance.InstMethodsInter.intercept(InstMethodsInter.java:93)
at feign.hystrix.HystrixInvocationHandler$1.run(HystrixInvocationHandler.java)
at com.netflix.hystrix.HystrixCommand$2.call(HystrixCommand.java:302)
at com.netflix.hystrix.HystrixCommand$2.call(HystrixCommand.java:298)
at rx.internal.operators.OnSubscribeDefer.call(OnSubscribeDefer.java:46)
at rx.internal.operators.OnSubscribeDefer.call(OnSubscribeDefer.java:35)
at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:48)
at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30)
at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:48)
at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30)
at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:48)
at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30)
at rx.Observable.unsafeSubscribe(Observable.java:10211)
at rx.internal.operators.OnSubscribeDefer.call(OnSubscribeDefer.java:51)
at rx.internal.operators.OnSubscribeDefer.call(OnSubscribeDefer.java:35)
at rx.Observable.unsafeSubscribe(Observable.java:10211)
at rx.internal.operators.OnSubscribeDoOnEach.call(OnSubscribeDoOnEach.java:41)
at rx.internal.operators.OnSubscribeDoOnEach.call(OnSubscribeDoOnEach.java:30)
at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:48)
at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30)
at rx.Observable.unsafeSubscribe(Observable.java:10211)
at rx.internal.operators.OperatorSubscribeOn$1.call(OperatorSubscribeOn.java:94)
at com.netflix.hystrix.strategy.concurrency.HystrixContexSchedulerAction$1.call(HystrixContexSchedulerAction.java:56)
at com.netflix.hystrix.strategy.concurrency.HystrixContexSchedulerAction$1.call(HystrixContexSchedulerAction.java:47)
at io.prong.autoconfigure.auth.service.ProngHystrixConcurrencyStrategy$WrappedCallable.call(ProngHystrixConcurrencyStrategy.java:121)
at com.netflix.hystrix.strategy.concurrency.HystrixContexSchedulerAction.call(HystrixContexSchedulerAction.java:69)
at rx.internal.schedulers.ScheduledAction.run(ScheduledAction.java:55)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
java.net.SocketTimeoutException: Read timed out
at feign.FeignException.errorExecuting(FeignException.java:67)
at feign.SynchronousMethodHandler.executeAndDecode(SynchronousMethodHandler.java:104)
at feign.SynchronousMethodHandler.invoke(SynchronousMethodHandler.java:76)
at feign.hystrix.HystrixInvocationHandler$1.run$original$guV1ukWA(HystrixInvocationHandler.java:108)
at feign.hystrix.HystrixInvocationHandler$1.run$original$guV1ukWA$accessor$1jiMEUrR(HystrixInvocationHandler.java)
at feign.hystrix.HystrixInvocationHandler$1$auxiliary$sEUgyNk3.call(Unknown Source)
at org.apache.skywalking.apm.agent.core.plugin.interceptor.enhance.InstMethodsInter.intercept(InstMethodsInter.java:93)
at feign.hystrix.HystrixInvocationHandler$1.run(HystrixInvocationHandler.java)
at com.netflix.hystrix.HystrixCommand$2.call(HystrixCommand.java:302)
at com.netflix.hystrix.HystrixCommand$2.call(HystrixCommand.java:298)

2、/inner/userinfo节点的异常信息为：

java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
at java.net.SocketInputStream.read(SocketInputStream.java:171)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
at java.io.BufferedInputStream.read1(BufferedInputStream.java:286)
at java.io.BufferedInputStream.read(BufferedInputStream.java:345)
at sun.net.www.http.HttpClient.parseHTTPHeader(HttpClient.java:735)
at sun.net.www.http.HttpClient.parseHTTP(HttpClient.java:678)
at sun.net.www.protocol.http.HttpURLConnection.getInputStream0(HttpURLConnection.java:1587)
at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1492)
at java.net.HttpURLConnection.getResponseCode(HttpURLConnection.java:480)
at feign.Client$Default.convertResponse(Client.java:152)
at feign.Client$Default.execute$original$Z12I5rH3(Client.java:74)
at feign.Client$Default.execute$original$Z12I5rH3$accessor$MeGe8flP(Client.java)
at feign.Client$Default$auxiliary$uXNNBULq.call(Unknown Source)
at org.apache.skywalking.apm.agent.core.plugin.interceptor.enhance.InstMethodsInter.intercept(InstMethodsInter.java:93)
at feign.Client$Default.execute(Client.java)
at org.springframework.cloud.netflix.feign.ribbon.RetryableFeignLoadBalancer$1.doWithRetry(RetryableFeignLoadBalancer.java:92)
at org.springframework.cloud.netflix.feign.ribbon.RetryableFeignLoadBalancer$1.doWithRetry(RetryableFeignLoadBalancer.java:77)
at org.springframework.retry.support.RetryTemplate.doExecute(RetryTemplate.java:287)
at org.springframework.retry.support.RetryTemplate.execute(RetryTemplate.java:164)
at org.springframework.cloud.netflix.feign.ribbon.RetryableFeignLoadBalancer.execute(RetryableFeignLoadBalancer.java:77)
at org.springframework.cloud.netflix.feign.ribbon.RetryableFeignLoadBalancer.execute(RetryableFeignLoadBalancer.java:48)
at com.netflix.client.AbstractLoadBalancerAwareClient$1.call(AbstractLoadBalancerAwareClient.java:109)
at com.netflix.loadbalancer.reactive.LoadBalancerCommand$3$1.call(LoadBalancerCommand.java:303)
at com.netflix.loadbalancer.reactive.LoadBalancerCommand$3$1.call(LoadBalancerCommand.java:287)
at rx.internal.util.ScalarSynchronousObservable$3.call(ScalarSynchronousObservable.java:231)
at rx.internal.util.ScalarSynchronousObservable$3.call(ScalarSynchronousObservable.java:228)
at rx.Observable.unsafeSubscribe(Observable.java:10211)
at rx.internal.operators.OnSubscribeConcatMap$ConcatMapSubscriber.drain(OnSubscribeConcatMap.java:286)
at rx.internal.operators.OnSubscribeConcatMap$ConcatMapSubscriber.onNext(OnSubscribeConcatMap.java:144)
at com.netflix.loadbalancer.reactive.LoadBalancerCommand$1.call(LoadBalancerCommand.java:185)
at com.netflix.loadbalancer.reactive.LoadBalancerCommand$1.call(LoadBalancerCommand.java:180)
at rx.Observable.unsafeSubscribe(Observable.java:10211)
at rx.internal.operators.OnSubscribeConcatMap.call(OnSubscribeConcatMap.java:94)
at rx.internal.operators.OnSubscribeConcatMap.call(OnSubscribeConcatMap.java:42)
at rx.Observable.unsafeSubscribe(Observable.java:10211)
at rx.internal.operators.OperatorRetryWithPredicate$SourceSubscriber$1.call(OperatorRetryWithPredicate.java:127)
at rx.internal.schedulers.TrampolineScheduler$InnerCurrentThreadScheduler.enqueue(TrampolineScheduler.java:73)
at rx.internal.schedulers.TrampolineScheduler$InnerCurrentThreadScheduler.schedule(TrampolineScheduler.java:52)
at rx.internal.operators.OperatorRetryWithPredicate$SourceSubscriber.onNext(OperatorRetryWithPredicate.java:79)
at rx.internal.operators.OperatorRetryWithPredicate$SourceSubscriber.onNext(OperatorRetryWithPredicate.java:45)
at rx.internal.util.ScalarSynchronousObservable$WeakSingleProducer.request(ScalarSynchronousObservable.java:276)
at rx.Subscriber.setProducer(Subscriber.java:209)
at rx.internal.util.ScalarSynchronousObservable$JustOnSubscribe.call(ScalarSynchronousObservable.java:138)