美文网首页spring cloud 微服务
一次生产Feign重试问题的排查过程

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

作者: 大浪滔滔 | 来源:发表于2019-07-04 00:04 被阅读171次

    问题

    在使用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)
    

    相关文章

      网友评论

        本文标题:一次生产Feign重试问题的排查过程

        本文链接:https://www.haomeiwen.com/subject/rrtkhctx.html