RequestAbortedException的一次排查-Spring专区论坛-技术-SpringForAll社区

RequestAbortedException的一次排查

近期正式环境的日志经常出现org.springframework.web.client.ResourceAccessException: I/O error on GET request for "http://xxx/xxx": Request aborted; nested exception is org.apache.http.impl.execchain.RequestAbortedException: Request aborted这个异常,原以为是服务端断开了请求,后面排查才发现 http 请求里还有这么多门道。

公司的微服务调用,有些项目用的是 OpenFeign,有的直接用了 RestTemplate。用 RestTemplate 作为 Http 客户端的微服务,在启动类上都有加一段 RestTemplate 的 Bean 实例配置,就是设置了 RestTemplate 使用的 HttpClient 它的连接池最大连接数,以及 http 请求默认的连接超时和读取超时

@Bean
RestTemplate restTemplate() {
    HttpClientBuilder httpClientBuilder = HttpClients.custom();
    Integer poolSize = Runtime.getRuntime().availableProcessors() * 2 - 1;
    poolSize = poolSize < 4 ? 4 : poolSize;
    httpClientBuilder.setMaxConnTotal(poolSize * 10);
    httpClientBuilder.setMaxConnPerRoute(poolSize);
    httpClientBuilder.disableCookieManagement();
    httpClientBuilder.disableAuthCaching();
    httpClientBuilder.setConnectionTimeToLive(60, TimeUnit.SECONDS);
    RequestConfig.Builder builder = RequestConfig.custom();
    builder.setConnectionRequestTimeout(30000).setConnectTimeout(30000).setSocketTimeout(30000);
    httpClientBuilder.setDefaultRequestConfig(builder.build());
    httpClientBuilder.setKeepAliveStrategy(DefaultConnectionKeepAliveStrategy.INSTANCE);
    HttpClient httpClient = httpClientBuilder.build();
    return new DynamicTimeoutHttpRequestFactory(httpClient);
}

上述配置的连接数配置估计也是 CV 大法过来,不知道具体含义。这里排查问题的时候也了解了下:

  • maxConnTotal同一时间最大连接数
  • maxConnPerRoute同一域名同一时间最大连接数
  • connectionRequestTimout从连接池获取连接的 timeout
  • connectTimeout客户端和服务器建立连接的 timeout
  • socketTimeout客户端从服务器读取数据的 timeout

上述的配置看起来就是建立了一个连接数是(cpu线程数*2-1)*10的连接池,相同域名同一时间最多连接数是(cpu线程数*2-1),按照线上配置是 4 核心 8 线程,最大连接数是 150,相同域名最多同时就是 15。一旦用完就会阻塞在获取 httpclient 连接的位置。根据异常的堆栈日志:

Caused by: org.apache.http.impl.execchain.RequestAbortedException: Request aborted
	at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:194)
	at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:185)
	at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:89)
	at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:111)
	at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185)
	at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:83)
	at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:56)
	at org.springframework.http.client.HttpComponentsClientHttpRequest.executeInternal(HttpComponentsClientHttpRequest.java:89)
	at org.springframework.http.client.AbstractBufferingClientHttpRequest.executeInternal(AbstractBufferingClientHttpRequest.java:48)
	at org.springframework.http.client.AbstractClientHttpRequest.execute(AbstractClientHttpRequest.java:53)
	at org.springframework.http.client.InterceptingClientHttpRequest$InterceptingRequestExecution.execute(InterceptingClientHttpRequest.java:112)
	at com.taimeitech.architecture.gateway.kubernetes.devtool.resttemplate.K8sDevSupportClientHttpRequestInterceptor.intercept(K8sDevSupportClientHttpRequestInterceptor.java:37)
	at org.springframework.http.client.InterceptingClientHttpRequest$InterceptingRequestExecution.execute(InterceptingClientHttpRequest.java:88)
	at org.springframework.http.client.InterceptingClientHttpRequest.executeInternal(InterceptingClientHttpRequest.java:72)
	at org.springframework.http.client.AbstractBufferingClientHttpRequest.executeInternal(AbstractBufferingClientHttpRequest.java:48)
	at org.springframework.http.client.AbstractClientHttpRequest.execute(AbstractClientHttpRequest.java:53)
	at org.springframework.web.client.RestTemplate.doExecute(RestTemplate.java:660)
	... 35 more
Caused by: java.lang.InterruptedException
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2014)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitUntil(AbstractQueuedSynchronizer.java:2129)
	at org.apache.http.pool.AbstractConnPool.getPoolEntryBlocking(AbstractConnPool.java:378)
	at org.apache.http.pool.AbstractConnPool.access$200(AbstractConnPool.java:69)
	at org.apache.http.pool.AbstractConnPool$2.get(AbstractConnPool.java:246)
	at org.apache.http.pool.AbstractConnPool$2.get(AbstractConnPool.java:193)
	at org.apache.http.impl.conn.PoolingHttpClientConnectionManager.leaseConnection(PoolingHttpClientConnectionManager.java:303)
	at org.apache.http.impl.conn.PoolingHttpClientConnectionManager$1.get(PoolingHttpClientConnectionManager.java:279)
	at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:191)
	... 51 more

可以定位到这两行at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:194)。这行对应的代码如下:

//MainClientExec.java:194
try {
    final int timeout = config.getConnectionRequestTimeout();
    managedConn = connRequest.get(timeout > 0 ? timeout : 0, TimeUnit.MILLISECONDS);
} catch(final InterruptedException interrupted) {
    Thread.currentThread().interrupt();
    throw new RequestAbortedException("Request aborted", interrupted);
} catch(final ExecutionException ex) {
    Throwable cause = ex.getCause();
    if (cause == null) {
        cause = ex;
    }
    throw new RequestAbortedException("Request execution failed", cause);
}

这里可以看到再获取HttpClientConnection的时候,线程被 interrupt 了,然后被包装成了RequestAbortedException抛出。

看到这里我以为是connectionRequestTimeout超时导致的这个异常,但是看了 apm 内的时间线和 30 秒的比对。

apm日志

发现并没有获取连接超时,并且发现日志中还有对应 Hystrix 的报错xxx timed-out and no fallback available.,这个异常是 HystrixCommand 超时且没有 fallback 才会抛出的异常。这就很奇怪了,因为 Hystrix 的超时配置我设置的是 30 秒,我们 Hystrix 开启的时间点是方法入口,按照这个逻辑整个方法应该执行了 30 秒,但是看 apm 日志,整个 HystrixCommand 只执行了 15 秒左右。还有 15 秒去哪了?

反复查看日志和 Hystrix 文档,才发现 HystrixCommand 的执行,原来要分成两部分,在 Hystrix Thread 模式下,HystrixCommand execute 后,如果对应的 threadPool coresize 有可用的,则直接执行,如果没有可用的,则进入队列等待。而 execute 后,Hystrix 还开启了一个 time 线程用来计时,此时如果 Command 没有可用线程进入队列等待,但 time 线程还是会计时,这里耗掉了那丢失的 15 秒。

而后有空余线程来执行 Command 的时候,在发起 http 请求时,由于 HttpClient 连接池连接数不够,处于阻塞状态,又过了 15 秒,此时已超过了 Hystrix 超时的 30 秒,time 线程发起了超时 fallback,对执行命令的线程发起了 interrupt,此时获取连接而阻塞的线程就抛出了异常,然后被包装成了 RequestAbortedException 抛出。

时序

请登录后发表评论

    没有回复内容