RestTemplate打印日志的正確知識

背景

現在隨着微服務的逐漸發展，越來越多的公司開始采用微服務架構，但隨之而來的問題是，服務間如何調用，如何還能負載均衡，還必須開箱即用？答案就是Spring的RestTemplate啦（並不一定要使用RestTemplate，也不一定要是微服務架構，涉及到Http調用的服務，方式都可以，我這個是為了引出主題），但伴隨而來的是一個問題，如何打印好日志，留下現場（防止扯皮），這才是我們關心的。這也是我們這篇文章的主題-RestTemplate打印日志的正確姿勢。好了，不湊字數了，接下來進入正文。

1. 老實人干事

作為一個老實人，對於打日志這類請求，就是通過代理，找出核心方法，在方法后，打印日志參數即可。實時，我也就是這么做的，如下圖：

我把RestTemplate的最底層方法進行了包裝，然后在執行后，返回結果前但因日志。這樣做，說實話，沒毛病，並且我拿去運行，放在線上運行了好長一段時間，沒出任何問題。但是..但是...，現實就是偏偏就欺(bu)負(xi)老(xin)實(ren)人(zhen)

2. 老實人翻盤

為什么說是欺(bu)負(xi)老(xin)實(ren)人(zhen)呢？最近我在看代碼的時候，發現了ResTemplate提供了一個方法RestTemplate#setInterceptors，我們通過名稱就知道，是設置攔截器的。只看名稱，那還不一定，我們需要去瞅瞅源碼才行。

2.1 源碼追蹤

setInterceptors方法如下：

// 設置攔截器
public void setInterceptors(List<ClientHttpRequestInterceptor> interceptors) {
	// Take getInterceptors() List as-is when passed in here
	if (this.interceptors != interceptors) {
        	this.interceptors.clear();
		this.interceptors.addAll(interceptors);
                // 對攔截器進行排序
	        AnnotationAwareOrderComparator.sort(this.interceptors);
	}
}

setInterceptors邏輯很簡單，就是添加攔截器。我們接下來要看看攔截器是在哪里使用的，這也是我們需要確認的點。接着往下。

// 構建RequestFactory
public ClientHttpRequestFactory getRequestFactory() {
  // 獲取攔截器
  List<ClientHttpRequestInterceptor> interceptors = getInterceptors();
  if (!CollectionUtils.isEmpty(interceptors)) {
    // 攔截器不為空
    ClientHttpRequestFactory factory = this.interceptingRequestFactory;
    if (factory == null) {
      // 使用攔截器構建的RequestFactory
      factory = new InterceptingClientHttpRequestFactory(super.getRequestFactory(), interceptors);
      this.interceptingRequestFactory = factory;
    }
    return factory;
  }
  else {
    // 返回默認的 SimpleClientHttpRequestFactory，可以自己查看一下
    return super.getRequestFactory();
  }
}

在getRequestFactory中搜尋到了攔截器的使用，是通過攔截器，構建了一個InterceptingClientHttpRequestFactory對象。目前，我們通過名字大意可以看到，是構建了一個攔截器的請求工廠，但還是沒有具體信息，讓我們接着往下，看看這個InterceptingClientHttpRequestFactory里面是怎么使用的。

省略中間簡單的邏輯，我們找到了最終邏輯。在InterceptingRequestExecution源代碼如下：

private class InterceptingRequestExecution implements ClientHttpRequestExecution {

  private final Iterator<ClientHttpRequestInterceptor> iterator;

  public InterceptingRequestExecution() {
    // 胡哦哦去攔截器的迭代器
    this.iterator = interceptors.iterator();
  }

  @Override
  public ClientHttpResponse execute(HttpRequest request, byte[] body) throws IOException {
    if (this.iterator.hasNext()) {
      ClientHttpRequestInterceptor nextInterceptor = this.iterator.next();
      //每次將當前對象傳入，循環迭代調用攔截器
      return nextInterceptor.intercept(request, body, this);
    }
    else {
      // 當攔截器執行完，開始執行請求邏輯
      HttpMethod method = request.getMethod();
      Assert.state(method != null, "No standard HTTP method");
      ClientHttpRequest delegate = requestFactory.createRequest(request.getURI(), method);
      request.getHeaders().forEach((key, value) -> delegate.getHeaders().addAll(key, value));
      ...
      // 執行請求，並返回執行結果對象。ClientHttpResponse
      return delegate.execute();
    }
  }
}

在執行execute方法時，循環調用攔截器方法。當攔截器執行完后，構建請求對象，執行請求。請求執行完，返回請求結果對象。

3. 撥開迷霧

源碼看我我TM悟了，原來別人提供了攔截器，我還自己搞那么復雜。這不是吃力不討好嗎？那不行，我的改造我的代碼。

3.1 實現攔截器接口-ClientHttpRequestInterceptor

貼上我寫的代碼，如下所示：

/**
 * <br>日志攔截器</br>
 *
 * @author fattyca1
 * @since 1.0
 */
@Slf4j
public class LoggingRequestInterceptor implements ClientHttpRequestInterceptor {
		// 用來記錄接口執行時間的最小接收值
    private final long timeoutMs;

    public LoggingRequestInterceptor(long timeoutMs) {
        this.timeoutMs = timeoutMs;
    }

    @Override
    public ClientHttpResponse intercept(HttpRequest request, byte[] body, ClientHttpRequestExecution execution) throws IOException {

        long start = System.currentTimeMillis();
        ClientHttpResponse response = execution.execute(request, body);
        long cost = System.currentTimeMillis() - start;
        if (cost > timeoutMs) {
            log.warn("Request uri: [{}], Cost times: {}ms", request.getURI(), cost);
        }
      	// 打印日志
        trace(request, body, response);
        return response;
    }

    private void trace(HttpRequest request, byte[] body, ClientHttpResponse response) throws IOException {
        // 記錄日志
        String responseStr = IOUtils.toString(response.getBody(), StandardCharsets.UTF_8);
        log.info(
                "\n" +
                        "URI             : {}, \n" +
                        "Method       : {}, \n" +
                        "Headers      : {}, \n" +
                        "Param         : {}, \n" +
                        "RespStatus  : {}, \n" +
                        "Response    : {}", request.getURI(),
                request.getMethod(), request.getHeaders(), new String(body, StandardCharsets.UTF_8), response.getStatusCode(), responseStr);
    }
}

代碼邏輯很簡單，實現攔截器，在攔截器中執行請求的時候，根據入參，出參，並打印結果。

3.2 構建RestTemplate對象

構建RestTemplate對象代碼如下所示：

private RestTemplateWrapper buildHttpRestTemplate(CloseableHttpClient client) {
    RestTemplateWrapper restTemplate = new RestTemplateWrapper();
    HttpComponentsClientHttpRequestFactory clientHttpRequestFactory
            = new HttpComponentsClientHttpRequestFactory(client);
    // 連接超時
    clientHttpRequestFactory.setConnectTimeout(httpClientProperties.getConnectionTimeOut());
    // 數據讀取超時時間
    clientHttpRequestFactory.setReadTimeout(httpClientProperties.getSocketTimeOut());
    // 連接不夠用的等待時間
    clientHttpRequestFactory.setConnectionRequestTimeout(httpClientProperties.getConnectionRequestTimeout());
    // 需要支持從response重復獲取body數據
    // restTemplate.setRequestFactory(new BufferingClientHttpRequestFactory(clientHttpRequestFactory));
    restTemplate.setRequestFactory(clientHttpRequestFactory);
    // 設置攔截器
    restTemplate.setInterceptors(Collections.singletonList(new LoggingRequestInterceptor(httpClientProperties.getLogTimeoutMs())));
    return restTemplate;
}

我們通過一些列操作，到了構建RestTemplate對象這，並且設置了攔截器，可以開開心心的去注入RestTemplate對象啦。

3.3 坑，你躲開了嗎

大家拿着RestTemplate開開心心去使用的時候，發現了沒，會出錯！！！ 是的，會報錯！！！好氣，我辛辛苦苦搞半天，還會出錯，錯誤如下：

Caused by: java.io.IOException: Attempted read from closed stream.

出現這個錯誤原因，主要是因為response.getBody()只能獲取一次，在后續RestTemplate獲取輸出轉化時會再次調用response.getBody()。

 // 攔截器的打印日志代碼中 response.getBody() 只能獲取一次，然后會關閉流，有興趣的可以看看源碼
 String responseStr = IOUtils.toString(response.getBody(), StandardCharsets.UTF_8);

既然知道問題了，那我們就得修改，那怎么修改呢？經過一番查找，找出了這個類BufferingClientHttpRequestFactory，瞅瞅這個注釋（我懷疑就是坑！！不然為啥正好有一個這樣的包裝類）：

/**
 * Wrapper for a {@link ClientHttpRequestFactory} that buffers
 * all outgoing and incoming streams in memory.
 *
 * <p>Using this wrapper allows for multiple reads of the
 * {@linkplain ClientHttpResponse#getBody() response body}.
 */
public class BufferingClientHttpRequestFactory extends AbstractClientHttpRequestFactoryWrapper {
  
}

注釋中清楚地寫着，可以多次調用ClientHttpResponse#getBody()。現在我們知道怎么解決這個問題了，那么就根據它的使用方法，重新構建RestTemplate對象。代碼如下（上方構建RestTemplate對象中的注釋打開）：

private RestTemplateWrapper buildHttpRestTemplate(CloseableHttpClient client) {
  RestTemplateWrapper restTemplate = new RestTemplateWrapper();
  HttpComponentsClientHttpRequestFactory clientHttpRequestFactory
    = new HttpComponentsClientHttpRequestFactory(client);
  // 連接超時
  clientHttpRequestFactory.setConnectTimeout(httpClientProperties.getConnectionTimeOut());
  // 數據讀取超時時間
  clientHttpRequestFactory.setReadTimeout(httpClientProperties.getSocketTimeOut());
  // 連接不夠用的等待時間
  clientHttpRequestFactory.setConnectionRequestTimeout(httpClientProperties.getConnectionRequestTimeout());
  //通過BufferingClientHttpRequestFactory對象包裝現有的ResquestFactory，用來支持多次調用getBody()方法
  restTemplate.setRequestFactory(new BufferingClientHttpRequestFactory(clientHttpRequestFactory));
  // 打印記錄
  restTemplate.setInterceptors(Collections.singletonList(new LoggingRequestInterceptor(httpClientProperties.getLogTimeoutMs())));
  return restTemplate;
}

至此，我們在開始運行，才發行可以走的通。

4 總結

阿~ 疏通了，舒服了，代碼看着也舒服了，這樣才是代碼的正確打開方式。這樣也讓我們對代碼設計有的更深的了解，在設計代碼時，需要預留一些接口設置，用來拓展，或方便別人。

這只是Interceptor一次小小的使用，並不代表只能用來打印日志，我們可以根據攔截器設置cookie，header信息等，都是可以的。