問題

在使用skywalking監(jiān)控生產(chǎn)環(huán)境問題時(shí)龄毡，發(fā)現(xiàn)有一個(gè)請(qǐng)求的調(diào)用鏈路中微服務(wù)Platform的內(nèi)部接口inner/userinfo很奇怪的被重復(fù)調(diào)用了2次哼蛆，如下圖：

image-20190703230049833.png

分析過(guò)程

相關(guān)版本：Spring Cloud版本為Dalston.SR4，Spring Boot版本為1.5.7.RELEASE

查看inner/userinfo的服務(wù)方的2次調(diào)用分別耗時(shí)6043ms和8078ms骚勘，通過(guò)跟蹤RetryableFeignLoadBalancer類的execute方法發(fā)現(xiàn)，feign的連接超時(shí)時(shí)間connectTimeout=2000（2秒），讀超時(shí)時(shí)間readTimeout=5000（5秒）纳击，因此可以判斷服務(wù)方的2次響應(yīng)時(shí)間超過(guò)讀超時(shí)時(shí)間閾值5秒了，因此調(diào)用方最終報(bào)了超時(shí)異常RetryableException攻臀。

我們知道焕数，Spring Cloud中Feign整合了Ribbon，但Feign和Ribbon都有重試的功能刨啸，Spring Cloud為了統(tǒng)一兩者的行為堡赔，將Feign的重試策略默認(rèn)設(shè)置為 feign.Retryer#NEVER_RETRY（即永不重試）。如要使用Feign的重試功能的話设联，只需使用Ribbon的重試配置即可善已。既然這樣，那為什么會(huì)有以上現(xiàn)象呢仑荐？

進(jìn)一步研究發(fā)現(xiàn)雕拼，對(duì)于Camden以及以后的版本，F(xiàn)eign的重試可使用如下屬性進(jìn)行配置：

ribbon:
  # 同一實(shí)例最大重試次數(shù)粘招，不包括首次調(diào)用啥寇。默認(rèn)值為0
  MaxAutoRetries: 0
  # 同一個(gè)微服務(wù)其他實(shí)例的最大重試次數(shù)，不包括第一次調(diào)用的實(shí)例。默認(rèn)值為1
  MaxAutoRetriesNextServer: 1
  # 是否所有操作（GET辑甜、POST等）都允許重試衰絮。默認(rèn)值為false
  OkToRetryOnAllOperations: false

我們的服務(wù)方Platform沒有配置這些參數(shù)，因此應(yīng)該是使用了默認(rèn)值磷醋。因?yàn)槲覀働latform微服務(wù)只啟動(dòng)了一個(gè)實(shí)例猫牡，所以我重點(diǎn)關(guān)注MaxAutoRetries參數(shù)，實(shí)際跟蹤發(fā)現(xiàn)它的值也是0邓线，這跟我理解的有出入疤视选！

跟蹤Spring Cloud的源碼骇陈，發(fā)現(xiàn)Feign是在RetryTemplate的doExecute方法中進(jìn)行重試的判斷和調(diào)用的:

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方法用于判斷當(dāng)接口調(diào)用異常時(shí)是否需要進(jìn)行重試碟绑。

跟進(jìn)canRetry方法殉农，終于找到了罪魁禍?zhǔn)住狪nterceptorRetryPolicy的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)橱赠。這一行意思是烤宙，根據(jù)策略判斷是否重試服務(wù)的下一個(gè)實(shí)例。因?yàn)镸axAutoRetriesNextServer默認(rèn)值為1婿崭，因此這里會(huì)返回true拨拓，所以inner/userinfo就被調(diào)用了2次。

解決方案

找到原因就好辦了氓栈，解決方案很簡(jiǎn)單渣磷，在調(diào)用方的yml配置MaxAutoRetriesNextServer的值為0即可：

ribbon:
  # 同一實(shí)例最大重試次數(shù)，不包括首次調(diào)用颤绕。默認(rèn)值為0
  MaxAutoRetries: 0
  # 同一個(gè)微服務(wù)其他實(shí)例的最大重試次數(shù)幸海，不包括第一次調(diào)用的實(shí)例。默認(rèn)值為1
  MaxAutoRetriesNextServer: 0
  # 是否所有操作（GET奥务、POST等）都允許重試物独。默認(rèn)值為false
  OkToRetryOnAllOperations: false

配置后，在開發(fā)環(huán)境驗(yàn)證成功氯葬！

附錄

相關(guān)節(jié)點(diǎn)的異常：

1挡篓、Hystrix/IUserService#getUserInfo()/Execution節(jié)點(diǎn)的異常信息為：

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節(jié)點(diǎn)的異常信息為：

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)