Apache HttpClient 5.x配置请求超时后仍收到超时时长外响应的问题排查求助

我开发了一个服务端应用，实现了队列机制，会故意将入站请求延迟5秒再返回响应。

在客户端侧，我使用的是最新版Apache HttpClient 5.3.1，并且配置了4秒的请求超时。但我观察到一个奇怪的现象：有些请求明明服务端会hold住5秒，客户端却还是在4秒超时后收到了响应，这个问题是随机出现的——有时候请求会正常在4秒时超时，但其他时候客户端依然能在5秒后收到响应，完全没有规律可循。

问题现象 #

• 该问题随机发生：部分请求会在4秒时正确超时，但另一些请求会在5秒后收到服务端响应
• 没有固定的触发规律，无法预测何时超时会生效、何时会收到延迟的响应

客户端代码实现 #

package com.vendor;
import java.net.URI;
import java.security.KeyManagementException;
import java.security.KeyStoreException;
import java.security.NoSuchAlgorithmException;
import java.security.cert.X509Certificate;
import java.util.ArrayList;
import java.util.List;
import java.util.concurrent.ExecutionException;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import java.util.concurrent.Future;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.atomic.AtomicLong;

import javax.net.ssl.SSLContext;

import org.apache.hc.client5.http.async.methods.SimpleHttpRequest;
import org.apache.hc.client5.http.async.methods.SimpleHttpResponse;
import org.apache.hc.client5.http.async.methods.SimpleRequestBuilder;
import org.apache.hc.client5.http.classic.methods.HttpPost;
import org.apache.hc.client5.http.config.RequestConfig;
import org.apache.hc.client5.http.impl.async.CloseableHttpAsyncClient;
import org.apache.hc.client5.http.impl.async.HttpAsyncClientBuilder;
import org.apache.hc.client5.http.impl.async.HttpAsyncClients;
import org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager;
import org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManagerBuilder;
import org.apache.hc.client5.http.ssl.DefaultClientTlsStrategy;
import org.apache.hc.client5.http.ssl.NoopHostnameVerifier;
import org.apache.hc.core5.concurrent.FutureCallback;
import org.apache.hc.core5.http.ContentType;
import org.apache.hc.core5.net.URIBuilder;
import org.apache.hc.core5.reactor.IOReactorConfig;
import org.apache.hc.core5.ssl.SSLContexts;
import org.apache.hc.core5.ssl.TrustStrategy;
import org.apache.hc.core5.util.Timeout;

public class AsyncHttpClientBulkRequests {

    public static void main(String[] args) throws InterruptedException {
        // Number of requests
        AtomicLong successCounter = new AtomicLong(0);
        AtomicLong failCounter = new AtomicLong(0);
        AtomicLong cancelCounter = new AtomicLong(0);
        AtomicLong deadlineCounter = new AtomicLong(0);
        
        int totalRequests = 10000;
        
        try {
            IOReactorConfig ioReactorConfig = IOReactorConfig.custom()
                    .setSoTimeout(Timeout.ofMilliseconds(4000))
                    .setIoThreadCount(Runtime.getRuntime().availableProcessors()).build();
            
            CloseableHttpAsyncClient asyncclient = null;
            
            HttpAsyncClientBuilder builder = HttpAsyncClients.custom();

            setConnectionProperties(builder, createConnectionmanager());

            asyncclient = builder.setIOReactorConfig(ioReactorConfig).build();

            asyncclient.start();

            ExecutorService executorService = Executors.newFixedThreadPool(10);

            List<Future<SimpleHttpResponse>> futures = new ArrayList<>();

            for (int i = 0; i < totalRequests; i++) {
                int requestId = i; // For tracking
                
                URIBuilder uribuilder = new URIBuilder("http://localhost:18888/dynamicResponseThreadWait");

                URI uri = uribuilder.build();

                HttpPost httpPost = new HttpPost(uri);
                SimpleHttpRequest httpRequest = SimpleRequestBuilder.copy(httpPost).build();
                
                 RequestConfig requestConfig = RequestConfig.custom()
                        .setConnectTimeout(4000, TimeUnit.MILLISECONDS)
                        .setResponseTimeout(4000, TimeUnit.MILLISECONDS).build();
                httpRequest.setConfig(requestConfig);
                
                 String requestBody ="{\r\n"
                        + "    \"threadWaitInMilliSeconds\": \"5000\",\r\n"
                        + "    \"ResponseKey\": \"1999999990\",\r\n"
                        + "    \"ResponseData\": {\r\n"
                        + "        \"1999999990\": "+requestId+"\r\n"
                        + "    }\r\n"
                        + "}";
                
                httpRequest.setBody(requestBody, ContentType.APPLICATION_JSON);
                
                long startTime = System.currentTimeMillis(); // Record start time

                /// Submit each request to the client and add a callback
                futures.add(asyncclient.execute(httpRequest, new FutureCallback<>() {
                    @Override
                    public void completed(SimpleHttpResponse response) {
                        
                         long endTime = System.currentTimeMillis();
                         long responseTimeMs = endTime - startTime;

                        successCounter.incrementAndGet();
                        System.err.println("Request:"+ requestId+ " completed with status: "+response.getCode() + ", TimeDiff:"+responseTimeMs);
                    }

                    @Override
                    public void failed(Exception ex) {
                         long endTime = System.currentTimeMillis();
                         long responseTimeMs = endTime - startTime;
                         failCounter.incrementAndGet();
                         
                        //System.out.println("Request "+requestId+ " failed: " +ex.getMessage()+", responseTimeMs:"+responseTimeMs);
                    }

                    @Override
                    public void cancelled() {
                        cancelCounter.incrementAndGet();
                        System.out.printf("Request %d cancelled%n", requestId);
                    }
                    
                    
                }));
                
            }

         // Wait for all requests to complete
            for (Future<SimpleHttpResponse> future : futures) {
                try {
                    future.get(); // Wait for completion
                } catch (ExecutionException | InterruptedException e) {
                   //System.err.println("Error waiting for request to complete: " + e.getMessage());
                }
            }

            executorService.shutdown();
            executorService.awaitTermination(1, TimeUnit.MINUTES);

            System.out.println("All requests completed! TotalCount : " + totalRequests);
            System.out.println("SuccessCounter: "+ successCounter.get());
            System.out.println("FailCounter: "+ failCounter.get());
            System.out.println("CancelCounter: " + cancelCounter.get());
            System.out.println("DeadlineCounter: " + deadlineCounter.get());
            
        } catch (Exception e) {
            e.printStackTrace();
        }
    }
    
   protected static PoolingAsyncClientConnectionManager createConnectionmanager() throws KeyManagementException, NoSuchAlgorithmException, KeyStoreException {
        
        TrustStrategy acceptingTrustStrategy = new TrustStrategy() {
            @Override
            public boolean isTrusted(X509Certificate[] certificate, String authType) {
                return true;
            }
        };

        SSLContext sslContext = SSLContexts.custom().loadTrustMaterial(null, acceptingTrustStrategy).build();
        return PoolingAsyncClientConnectionManagerBuilder.create().setTlsStrategy(new DefaultClientTlsStrategy(sslContext, NoopHostnameVerifier.INSTANCE)).build();
    }
   
   protected static void setConnectionProperties(HttpAsyncClientBuilder builder, PoolingAsyncClientConnectionManager connectionManager) {
        
        if (connectionManager != null) {
            connectionManager.setDefaultMaxPerRoute(100);
            connectionManager.setMaxTotal(1000);
            builder.setConnectionManager(connectionManager);
        }
    }
}

预期结果 #

如果请求处理时间超过4秒，客户端应该触发超时，不会收到任何响应。

实际结果 #

部分请求会在5秒后收到服务端响应，例如以下日志输出：

Request:109 completed with status: 200, TimeDiff:9145
Request:115 completed with status: 200, TimeDiff:9143
Request:105 completed with status: 200, TimeDiff:9146
Request:116 completed with status: 200, TimeDiff:9143

备注：内容来源于stack exchange，提问作者manish parihar