記錄一次Feign調用500錯誤

前言

最近某個應用在服務間使用Feign時一直報500 status reading，嚴重影響到公司業務進行。

報錯如下：

分析思路

找到問題原因

首先跟蹤了feign源碼發現報錯是在response中返回的，然后查看被調用方無任何日志信息。此時判斷非業務異常返回。

再確認非業務異常后，通過tcpdump將tcp信息導出得到以下信息

拿到報文后，顯示自己調用該接口來測試是否報錯，但無論如何都調用成功，在經過一段時間折騰后發現host與tcp的請求地址不一致，為什么會出現這種情況？

http是應用層的東西只是規定了一種協議，而真正發起連接是tcp，而tcp只是發數據根本不知道host是啥。也就意味着host可以隨意變更。

發現host不一致時，嘗試着更改host，最終嘗試更改host也並不會引發報錯。所以到現在只能為最老實的方式 → 復制所有的header和參數與報文保持一致。此時調用報錯且與tcpdump結果一致。然后通過刪減header最終確認了是Content-Length和content-length同時存在導致tomcat服務器直接攔截了請求。

此時思路就來，那么在何時產生的兩個名稱相同但大小寫不同的key存在。接下來就跟隨Feign源碼查看問題。通過調試進入了feign初始化request的代碼SynchronousMethodHandler

public Object invoke(Object[] argv) throws Throwable {
    // 通過feignclient獲取，如果為post請求會添加Content-Length頭
    RequestTemplate template = buildTemplateFromArgs.create(argv);
    Retryer retryer = this.retryer.clone();
    while (true) {
      try {
        return executeAndDecode(template);
      } catch (RetryableException e) {
        retryer.continueOrPropagate(e);
        if (logLevel != Logger.Level.NONE) {
          logger.logRetry(metadata.configKey(), logLevel);
        }
        continue;
      }
    }
  }

Object executeAndDecode(RequestTemplate template) throws Throwable {
		// 調用所有請求攔截器獲取request
    Request request = targetRequest(template);

    if (logLevel != Logger.Level.NONE) {
      logger.logRequest(metadata.configKey(), logLevel, request);
    }

    Response response;
    long start = System.nanoTime();
    try {
      response = client.execute(request, options);
      // ensure the request is set. TODO: remove in Feign 10
      response.toBuilder().request(request).build();
    } catch (IOException e) {
      if (logLevel != Logger.Level.NONE) {
        logger.logIOException(metadata.configKey(), logLevel, e, elapsedTime(start));
      }
      throw errorExecuting(request, e);
    }

調用所有請求攔截器獲取request

Request targetRequest(RequestTemplate template) {
    for (RequestInterceptor interceptor : requestInterceptors) {
      interceptor.apply(template);
    }
    return target.apply(new RequestTemplate(template));
  }

接下來看RequestInterceptor 的實現類有哪些，最終找到同事自己寫的一個方法攔截器，如下

public class FeignInterceptor implements RequestInterceptor {
    @Override
    public void apply(RequestTemplate requestTemplate) {
        final ServletRequestAttributes attrs = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
        if (attrs != null) {
            final HttpServletRequest request = attrs.getRequest();
            final Enumeration<String> headerNames = request.getHeaderNames();
            if (headerNames != null) {
                //遍歷請求頭里面的屬性字段，將logId和token添加到新的請求頭中轉發到下游服務
                while (headerNames.hasMoreElements()) {
                    final String name = headerNames.nextElement();
                    final String value = request.getHeader(name);
                    requestTemplate.header(name, value);
                }
            }
        } else {
        }
    }
}

通過以上代碼，估計就很快發現了問題，這里將本次請求的所有header都放進了feign調用的header里面。此時通過斷點發現本次請求的請求頭全是小寫的content-length。此時就更加確信是這個問題導致。但這個攔截器我在其他服務上也看到了，但為什么偏偏只有這個服務出錯了呢。所以為了最終到本質，繼續往下看源碼

經過一系列調試最終跟蹤到了Okhttp(同事將原本默認的feign調用的httpclient換成了okhttp)

public feign.Response execute(feign.Request input, feign.Request.Options options)
      throws IOException {
    okhttp3.OkHttpClient requestScoped;
    if (delegate.connectTimeoutMillis() != options.connectTimeoutMillis()
        || delegate.readTimeoutMillis() != options.readTimeoutMillis()
        || delegate.followRedirects() != options.isFollowRedirects()) {
      requestScoped = delegate.newBuilder()
          .connectTimeout(options.connectTimeoutMillis(), TimeUnit.MILLISECONDS)
          .readTimeout(options.readTimeoutMillis(), TimeUnit.MILLISECONDS)
          .followRedirects(options.isFollowRedirects())
          .build();
    } else {
      requestScoped = delegate;
    }
    // 轉換feign request為okhttp request。
    Request request = toOkHttpRequest(input);
    Response response = requestScoped.newCall(request).execute();
    return toFeignResponse(response, input).toBuilder().request(input).build();
  }

static Request toOkHttpRequest(feign.Request input) {
    Request.Builder requestBuilder = new Request.Builder();
    requestBuilder.url(input.url());

    MediaType mediaType = null;
    boolean hasAcceptHeader = false;
    for (String field : input.headers().keySet()) {
      if (field.equalsIgnoreCase("Accept")) {
        hasAcceptHeader = true;
      }

      for (String value : input.headers().get(field)) {
				// 將所有頭放進header中，跟蹤到里面發現使用list保存
        requestBuilder.addHeader(field, value);
        if (field.equalsIgnoreCase("Content-Type")) {
          mediaType = MediaType.parse(value);
          if (input.charset() != null) {
            mediaType.charset(input.charset());
          }
        }
      }
    }
    // Some servers choke on the default accept string.
    if (!hasAcceptHeader) {
      requestBuilder.addHeader("Accept", "*/*");
    }

    byte[] inputBody = input.body();
    boolean isMethodWithBody =
        HttpMethod.POST == input.httpMethod() || HttpMethod.PUT == input.httpMethod()
            || HttpMethod.PATCH == input.httpMethod();
    if (isMethodWithBody) {
      requestBuilder.removeHeader("Content-Type");
      if (inputBody == null) {
        // write an empty BODY to conform with okhttp 2.4.0+
        // http://johnfeng.github.io/blog/2015/06/30/okhttp-updates-post-wouldnt-be-allowed-to-have-null-body/
        inputBody = new byte[0];
      }
    }

    RequestBody body = inputBody != null ? RequestBody.create(mediaType, inputBody) : null;
    requestBuilder.method(input.httpMethod().name(), body);
    return requestBuilder.build();
  }

此時還有一個以為為何原來的不報錯呢？同樣跟蹤下原來的代碼,最終跟蹤到Client#``convertAndSend

for (String field : request.headers().keySet()) {
        if (field.equalsIgnoreCase("Accept")) {
          hasAcceptHeader = true;
        }
        for (String value : request.headers().get(field)) {
          if (field.equals(CONTENT_LENGTH)) {
            if (!gzipEncodedRequest && !deflateEncodedRequest) {
              contentLength = Integer.valueOf(value);
              connection.addRequestProperty(field, value);
            }
          } else {
						// 這里面進行了一些受限header的屏蔽
            connection.addRequestProperty(field, value);
          }
        }
      }

public synchronized void addRequestProperty(String var1, String var2) {
        if (!this.connected && !this.connecting) {
            if (var1 == null) {
                throw new NullPointerException("key is null");
            } else {
                // 判斷是否允許的外部擴展頭
                if (this.isExternalMessageHeaderAllowed(var1, var2)) {
                    this.requests.add(var1, var2);
                    if (!var1.equalsIgnoreCase("Content-Type")) {
                        this.userHeaders.add(var1, var2);
                    }
                }

            }
        } else {
            throw new IllegalStateException("Already connected");
        }
    }

private static final String[] restrictedHeaders = new String[]{"Access-Control-Request-Headers", "Access-Control-Request-Method", "Connection", "Content-Length", "Content-Transfer-Encoding", "Host", "Keep-Alive", "Origin", "Trailer", "Transfer-Encoding", "Upgrade", "Via"};
private boolean isRestrictedHeader(String var1, String var2) {
        if (allowRestrictedHeaders) {
            return false;
        } else {
            var1 = var1.toLowerCase();
             // 包含了content-length        
            if (restrictedHeaderSet.contains(var1)) {
                return !var1.equals("connection") || !var2.equalsIgnoreCase("close");
            } else {
                return var1.startsWith("sec-");
            }
        }
    }

至此所有疑團消失。完結撒花！