产品简介

我们的产品是一个匿名智能卡（可用于乘坐地铁，公交，消费）管理系统（类似于成都的天府通），用户可以下载我们的mobile app,然后管理自己的匿名智能卡， 并给智能卡手动充值（可以选择绑定银行卡也可以选择手机上已经安装的带有支付功能的app,比如某宝）或者绑定自动充值。 同时该智能卡带有积分功能， 每一笔消费都会为用户积分，积分可以用来换取商店优惠券。

该产品还有一个没有正式上线的功能， 电子钱包。 目前只有一部分内测用户享有电子钱包的功能。后文中将要讨论的timeout问题，就是电子钱包timeout的问题。

我们团队负责mobile(android和ios)的开发， 所有数据都是第三方维护的， 我们有一个backend app,名叫BFF(backend for frontend), 用来聚合所有前端需要的第三方数据。

目前该app拥有90万注册用户，通过BFF的日志我们可以知道日均活跃用户数约为20000.

Timeout 问题重述

最近我们项目遇到一个棘手的production environment read timeout的问题。话不多说， 问题以及项目框架介绍如下：

• 后端项目语言与框架 ： java+springBoot.

• 前端语言： android + ios

• 项目架构简图：
  从图中可以看出数据流向： mobile > nginxServer > BFF(Backend for frontend) > loaderBalancer > A Service > B Service

  
  

• Timeout 现象
  所有手机用户首次进入首页或者手动刷新首页的时候，便会触发check-A-display function， 电子钱包内测用户进入首页的时候，会出发get-A-list function. 这两个function都会触发 A Service 的 get-A-list 这个endpoint. 很多用户上报在首页会遇到timeout error.

• Backend timeout log

[BFF] Http Request Error ex:class org.springframework.web.client.ResourceAccessException message: I/O error on GET request for "http://xxxxxxx:xxxx/A/list": Read timed out; nested exception is java.net.SocketTimeoutException: Read timed out cause:java.net.SocketTimeoutException: Read timed out stack_trace: [org.springframework.web.client.RestTemplate.doExecute(RestTemplate.java:744), org.springframework.web.client.RestTemplate.execute(RestTemplate.java:670), org.springframework.web.client.RestTemplate.exchange(RestTemplate.java:608), 

• Resttemplate config in BFF

  @Bean
    public RestTemplate resttemplate(ObjectMapper objectMapper) throws Exception {
        
//        this is the legacy code, do not know the reason why skip the certificate validation
        TrustStrategy acceptingTrustStrategy = (cert, authType) -> true;
        SSLContext sslContext = SSLContexts.custom().loadTrustMaterial(null, acceptingTrustStrategy).build();
        SSLConnectionSocketFactory sslsf = new SSLConnectionSocketFactory(sslContext,
                NoopHostnameVerifier.INSTANCE);

        Registry<ConnectionSocketFactory> socketFactoryRegistry =
                RegistryBuilder.<ConnectionSocketFactory>create()
                        .register("https", sslsf)
                        .register("http", new PlainConnectionSocketFactory())
                        .build();

        PoolingHttpClientConnectionManager connManager = new PoolingHttpClientConnectionManager(socketFactoryRegistry);
        connManager.setMaxTotal(maxTotalConnectionPoolSize);
        connManager.setDefaultMaxPerRoute(maxPerRouteConnectionPool);


//        read timeout is 60 seconds
        RequestConfig requestConfig = RequestConfig.custom()
                .setConnectionRequestTimeout(connectionTimeout)
                .setConnectTimeout(connectionTimeout)
                .setSocketTimeout(readTimeout)
                .build();

        CloseableHttpClient httpClient = HttpClients.custom().setSSLSocketFactory(sslsf)
                .setConnectionManager(connManager)
                .setDefaultRequestConfig(requestConfig)
                .build();

        HttpComponentsClientHttpRequestFactory requestFactory =
                new HttpComponentsClientHttpRequestFactory(httpClient);
        RestTemplate restTemplate = new RestTemplate(requestFactory);

        return restTemplate;
    }

参考skip certificate validation in resttemplate,请移步这里

调查并解决问题

1.重现问题 - 2.分析日志 - 3.通过 Load Test 定位问题 - 4.解决问题

1.重现问题

因为整个流程里面设计到了太多的components（请参考下图），问题可能是真个流程里面任何一个compoment造成的，所以刚开始很难定位问题到底出在哪里，只能用最直接但通常又最有效的办法，重现问题，看日志。

当我们手动重现这个问题的时候，出发了大约30个请求，但是只得到了1个timeout. 通过查看后端日志，发现BFF已经把请求发出去了，但是一分钟后， 报了read tiemout的exception.

[BFF] Http Request Error ex:class org.springframework.web.client.ResourceAccessException message: I/O error on GET request for "http://xxxxxxx:xxxx/A/list": Read timed out; nested exception is java.net.SocketTimeoutException: Read timed out cause:java.net.SocketTimeoutException: Read timed out stack_trace: [org.springframework.web.client.RestTemplate.doExecute(RestTemplate.java:744), org.springframework.web.client.RestTemplate.execute(RestTemplate.java:670), org.springframework.web.client.RestTemplate.exchange(RestTemplate.java:608), 

由于看不到第三方A service的日志， 所以一开始我们猜测， timeout是由第三方A Service引起的。但是经过第三方确认日志后，貌似他们没有收到请求。
通过常规的手动重现问题，目前并不能帮我们准确定位问题，于是我们开始了第二个流程。

2.分析日志

我们期望通过分析后端的日志，能计算出timeout的频率，进而看是否能找到一些timeout的规律。分析结果如下：

check-A-display和get-A-list 功能最终调用的是同一个A Service, 但日志分析结果，两者的timeout 评率却是大不一样。查看不同因子， 两者的load量相差巨大。 一个是每天3万个请求，而另一个每天却只有300个请求。 这给了我们一些idea, 也许从不同的component做load test，模拟产品环境请求量， 能定位出问题在哪里。

3.通过 Load Test 定位问题

为了有效的定位问题，我们分别从下图的1，2，3处，做load test. 日均请求量3万，我们则从位置1，2，3有频率的分别发一万个请求。

以下是一个简单的load-test脚本, 每2秒钟发一个请求

#!/bin/bash
let i=0
while [ $i -lt 10000 ];
  do
  curl -k -w "$i: %{time_total} %{http_code} %{url_effective}\n" -o "./response-body.log1" -X GET https://xxxxxxx/v1/xxx \
  -H 'Content-Type: application/json' \
  -H 'X-AUTH-TOKEN: some-token' \
  -H 'X-CLIENT-ID: some-client-id' \
  -H 'cache-control: no-cache'  \
  --max-time 15 >> result.log
  
  sleep 2
 
done

以下是result.log内容格式：

0: 0.977485 200 https:/xxxxxxxx/staging/v1/xxxxx
1: 0.632129 200 https:/xxxxxxxx/staging/v1/xxxxx
2: 0.603432 200 https:/xxxxxxxx/staging/v1/xxxxx
3: 0.680654 200 https:/xxxxxxxx/staging/v1/xxxxx
4: 1.044199 200 https:/xxxxxxxx/staging/v1/xxxxx
5: 0.584414 200 https:/xxxxxxxx/staging/v1/xxxxx

非常不幸，load test结束后，我们没有得到一个timeout. 所有请求都成功了。


我们继续手动重现timeout issue, 想要找出load test跟产品环境timeout到底有什么不一样。 通过不断的手动重现这个问题，我们终于发现了不一样的地方： timeout只有在每次打开app的时候才会发生。 也就是隔一段时间后，每次打开app, 第一次创建的链接才会timeout, 第一次后的后续链接都不会timeout. 然而上一轮load test,我们是持续不断的一直发请求，中间并没有任何间隔。


于是我们改写了load test脚本，让它每10分钟，发出20个请求，然后再一次从1，2，3分别执行。以下是改写后的脚本

#!/bin/bash
let i=0
while [ $i -lt 10000 ];
do
  curl -k -w "$i: %{time_total} %{http_code} %{url_effective}\n" -o "./response-body.log1" -X GET https://xxxxxxx/v1/xxx \
  -H 'Content-Type: application/json' \
  -H 'X-AUTH-TOKEN: some-token' \
  -H 'X-CLIENT-ID: some-client-id' \
  -H 'cache-control: no-cache'  \
  --max-time 15 >> result.log

  let i=i+1
  let tmp=i%20
  echo "temp $tmp"
  if [[ $tmp -eq 0 ]];
  then
    sleep 600
  else
    sleep 2
  fi
  #sleep 2
done

非常幸运， 这一次，我们成功重现了timeout 问题。 位置1，2， 每10分钟的第一个请求都timeout了，候选19个请求都会成功。但是位置3一个timeout也没有出现。 介于BFF是收到请求的，所以这一次，我们成功定位出了问题出在BFF. 当定位出问题出在哪里后，我们就能focus在BFF上，并寻求问题的根源以及解决方案。

4.解决问题

首先，我们想到的就是resttemplate的配置是不是有问题。但google了很多资料后，resttemplate的配置貌似是没有问题的。于是我们开始换一个思路，BFF调用的很多第三方的服务，为什么只有A service出了timeout. 于是我们开始对比A Service和其他service有什么不一样。 果然还是有收获的。

BFF通过ssl调用其他第三方服务的时候，中间经过了nginx， 于是我们也通过nginx来调用A Service。果然成功解决了这个问题。

进一步思考

其实之前做了很多项目，并没有用nginx server， 通过ssl调用第三方service的时候并没有出现过read timeout。 说实话我还是没有找到根本原因， 为什么我们项目里面会出现timeout。当然，大家如果有更好的观点，更多的经验， 还希望大家能积极提供一些反馈与建议。

在网上找了一些资料， 说ssl创建连接和发请求，收response以及断开连接是比较费时的，因为涉及到握手，加密，所以对于ssl或者tsl来说，为了提高性能，一般都会用nginx 来做代理。 充分利用nginx的keep-alive等属性，会很大程度的提高reliability和performance.

当然，我猜测问题的关键确实是链接费时造成的，如果不用nginx server, 直接在resttemplate里面配置 connection idle time， 也能很大程度解决这个问题

 @Bean
    public RestTemplate resttemplate(ObjectMapper objectMapper) throws Exception {

//        this is the legacy code, do not know the reason why skip the certificate validation
        TrustStrategy acceptingTrustStrategy = (cert, authType) -> true;
        SSLContext sslContext = SSLContexts.custom().loadTrustMaterial(null, acceptingTrustStrategy).build();
        SSLConnectionSocketFactory sslsf = new SSLConnectionSocketFactory(sslContext,
                NoopHostnameVerifier.INSTANCE);

        Registry<ConnectionSocketFactory> socketFactoryRegistry =
                RegistryBuilder.<ConnectionSocketFactory>create()
                        .register("https", sslsf)
                        .register("http", new PlainConnectionSocketFactory())
                        .build();


        PoolingHttpClientConnectionManager connManager = new PoolingHttpClientConnectionManager(socketFactoryRegistry);
        connManager.setMaxTotal(maxTotalConnectionPoolSize);
        connManager.setDefaultMaxPerRoute(maxPerRouteConnectionPool);


//        read timeout is 60 seconds
        RequestConfig requestConfig = RequestConfig.custom()
                .setConnectionRequestTimeout(connectionTimeout)
                .setConnectTimeout(connectionTimeout)
                .setSocketTimeout(readTimeout)
                .build();

        CloseableHttpClient httpClient = HttpClients.custom().setSSLSocketFactory(sslsf)
                .setConnectionManager(connManager)
                .setDefaultRequestConfig(requestConfig)
                .setKeepAliveStrategy(new ConnectionKeepAliveStrategy() {
                    @Override
                    public long getKeepAliveDuration(HttpResponse response, HttpContext context) {
//                        million seconds
                        return 60000;
                    }
                })
                .build();

        HttpComponentsClientHttpRequestFactory requestFactory =
                new HttpComponentsClientHttpRequestFactory(httpClient);
        RestTemplate restTemplate = new RestTemplate(requestFactory);

        return restTemplate;
    }

但是这样的解决方案不能完全避免这个timeout问题，只能很大程度的减少这个问题。还是比较倾向于用nginx来解决这个问题。

以下是我觉得关于nginx挺好的一些资料：

• https://www.nginx.com/blog/http-keepalives-and-web-performance/
• https://www.nginx.com/blog/tuning-nginx/
• https://stackoverflow.com/questions/46419976/default-value-of-nginx-keepalive

总结

通过此次产品环境问题调查，定位， 以及最后的寻求解决方案。 我学会了:

• 在请求量比较大的时候，如何用脚本来自动化的比较真实的模拟产品环境user case.
• 在请求量比较大的时候，对性能和稳定性要求比较高的app, 要充分利用nginx给你带来的便利。