Async HTTP Request Connection Timeout Not Work Correctly

[madawei2699]

Backgroud

When using clj-http async requests some do not exist URL and set the connection timeout, but the connection timeout is delayed 2-3 seconds.

Test

The test version is 3.12.2, and the test way is lein repl, my lein config in ~/.lein/profiles.clj:

{
  :user {
          :plugins [[lein-midje "3.2.1"]
                    [lein-shell "0.5.0"]]
          :dependencies [[org.clojure/clojure "1.10.3"]
                    [rhizome "0.2.9"]
                    [org.clojure/core.match "1.0.0"]
                    [buddy/buddy-sign "3.1.0"]
		    [clj-http "3.12.2"]
                    [environ "1.1.0"]
                    [cheshire "5.10.0"]
                    [instaparse "1.4.10"]]
        }
}

and then, run lein repl to go to the repl environment.

(ns test (:require [clj-http.client :as client]))

Example 1

(time (deref 
  (let [response (promise)]
  (client/get "http://255.255.33.44:8001/"
                {:async?         true
                 :socket-timeout 0
                 :conn-timeout   1}
                (fn [resp]
                  (deliver response {:sucess "test"
                                     :content (:body resp)}))
                (fn [exception]
                  (deliver response {:error (.getMessage exception)})))
                                     response)))

Expectation

Cause the URL does not exist, so the time will be conn-timeout which is ~1ms.

Test Result

"Elapsed time: 3019.764098 msecs" {:error "Timeout connecting to [/255.255.33.44:8001]"}

Example 2

(time (deref 
  (let [response (promise)]
  (client/get "http://255.255.33.44:8001/"
                {:async?         true
                 :socket-timeout 0
                 :conn-timeout   5000}
                (fn [resp]
                  (deliver response {:sucess "test"
                                     :content (:body resp)}))
                (fn [exception]
                  (deliver response {:error (.getMessage exception)})))
                                     response)))

Expectation

Cause the URL does not exist, so the time will be conn-timeout which is ~5000ms.

Test Result

"Elapsed time: 7203.527474 msecs" {:error "Timeout connecting to [/255.255.33.44:8001]"}

Example 3

(time (try
     (client/get "http://255.255.33.44:8001/" {:socket-timeout 500 :connection-timeout 5000})
     (catch Exception e (str "caught exception: " (.getMessage e)))))

Expectation

Cause the URL does not exist, so the time will be conn-timeout which is ~5000ms.

Test Result

"Elapsed time: 5010.862797 msecs" "caught exception: connect timed out"

Example 4

(time (try
     (client/get "http://255.255.33.44:8001/" {:socket-timeout 500 :connection-timeout 1})
     (catch Exception e (str "caught exception: " (.getMessage e)))))

Expectation

Cause the URL does not exist, so the time will be conn-timeout which is ~1ms.

Test Result

"Elapsed time: 8.649284 msecs" "caught exception: connect timed out"

Bug

As in the above test, Example 1 and Example 2 are test requests in async mode, and Example 3 and Example 4 are control requests in sync mode. The sync mode request is as expected, but the async mode request is 2-3 seconds longer than the set conn-timeout.

[madawei2699]

After going through clj-http code, I write a sample java version to compare the results.

public class Main {
    public static void main(String[] args) throws IOReactorException {
        RequestConfig requestConfig = RequestConfig.custom()
                .setConnectTimeout(1)
                .setSocketTimeout(500)
                .setRedirectsEnabled(true)
                .build();
        HttpUriRequest httpUriRequest = new HttpGet("http://255.255.33.44:8001/");
        httpUriRequest.addHeader("Connection", "close");
        IOReactorConfig reactorConfig = IOReactorConfig.custom()
//                .setConnectTimeout(500)
//                .setSoTimeout(500)
                .setShutdownGracePeriod(1)
                .build();
        DefaultConnectingIOReactor defaultConnectingIOReactor = new DefaultConnectingIOReactor(reactorConfig);
        Registry registry = RegistryBuilder.create()
                .register("http", NoopIOSessionStrategy.INSTANCE)
                .build();
        PoolingNHttpClientConnectionManager connectionManager = new PoolingNHttpClientConnectionManager(defaultConnectingIOReactor, registry);
        HttpClientContext context = new HttpClientContext();
        context.setRequestConfig(requestConfig);
        connectionManager.setMaxTotal(1);
        CloseableHttpAsyncClient client = HttpAsyncClients.custom()
                .setConnectionManager(connectionManager)
                .build();
        client.start();
        long startTime = System.nanoTime();
        client.execute(httpUriRequest, context, new FutureCallback<HttpResponse>() {
            @Override
            public void completed(HttpResponse httpResponse) {
                StatusLine statusLine = httpResponse.getStatusLine();
                int statusCode = statusLine.getStatusCode();
                long stopTime = System.nanoTime();
                System.out.print("=====completed, timeElapsed: ");
                System.out.print(TimeUnit.MILLISECONDS.convert(System.nanoTime() - startTime, TimeUnit.NANOSECONDS));
                System.out.println(" ms");
                System.out.print(statusCode);
            }

            @Override
            public void failed(Exception e) {
                System.out.print("=====failed, timeElapsed: ");
                System.out.print(TimeUnit.MILLISECONDS.convert(System.nanoTime() - startTime, TimeUnit.NANOSECONDS));
                System.out.println(" ms");
                System.out.print("=====error msg: " + e.getMessage());
                try {
                    connectionManager.shutdown();
                } catch (IOException ex) {
                    ex.printStackTrace();
                }
            }

            @Override
            public void cancelled() {
                httpUriRequest.abort();
                try {
                    connectionManager.shutdown();
                } catch (IOException e) {
                    e.printStackTrace();
                }
            }
        });
    }
}

When setConnectTimeout(1), the time elapsed is ~1129ms. When setConnectTimeout(500), the time elapsed is ~1142ms. When setConnectTimeout(1000), the time elapsed is ~1115ms. When setConnectTimeout(1100), the time elapsed is ~2099ms. When setConnectTimeout(1200), the time elapsed is ~2106ms. When setConnectTimeout(1300), the time elapsed is ~2091ms. When setConnectTimeout(1500), the time elapsed is ~2095ms. When setConnectTimeout(2000), the time elapsed is ~2110ms. When setConnectTimeout(2500), the time elapsed is ~3121ms. When setConnectTimeout(3000), the time elapsed is ~3098ms. When setConnectTimeout(4000), the time elapsed is ~4117ms. When setConnectTimeout(5000), the time elapsed is ~5110ms.

So it seems like code execute time is about ~1000ms, it takes at least 1 second from the start of the request to fail if the connect timeout is less than ~1000ms.

But synchronous requests do not have such high latency (interval from request to failure), I guess because asynchronous requests require a lot of setup code to be processed, including the creation of connection pools, so the creation of asynchronous request clients is time-consuming expensively.

[madawei2699]

After some research, I figure out a way to solve my problem which used clojure.core.async to implement the HTTP client async feature.

Here is the main code(gist):

;; lein repl

(ns test (:require [clojure.core.async :as async]
                   [clj-http.client :as client]))

;; define test data
(def urls ["http://www.google.com" "http://www.google1.com" "http://255.255.33.44:8001/"])

;; use async/go to build a async http client
(defn fetch-async
  [url]
  (let [ret (async/promise-chan)]
    (async/go
      (try
        (let [res (client/get url {:socket-timeout 500 
                                   :connection-timeout 500})]
          (async/put! ret {:result :success :msg (:status res)}))
      (catch Exception e (async/put! ret {:result :error :msg (.getMessage e)}))))
  ret))

;; use async/go to build a async http client but disable apache http client retry feature
(defn fetch-async-without-retry
  [url]
  (let [ret (async/promise-chan)]
    (async/go
      (try
        (let [res (client/get url {:socket-timeout 500 
                                   :connection-timeout 1000
                                   :retry-handler (fn [ex try-count http-context]
                                                    (if (> try-count 0) false true))})]
          (async/put! ret {:result :success :msg (:status res)}))
      (catch Exception e (async/put! ret {:result :error :msg (.getMessage e)}))))
  ret))

;; test fetach a domain url
(time (async/<!! (fetch-async "http://www.google1.com")))

;; test fetach an ip url
(time (async/<!! (fetch-async "http://255.255.33.44:8001/")))

;; block main thread to get all response data
(let [res-promise (map #(fetch-async %) urls)]
    (map #(async/<!! %) res-promise))

;; metric the execute time
(let [res-promise (map #(fetch-async %) urls)]
    (map #(time (async/<!! %)) res-promise))

(time (let [res-promise (map #(fetch-async %) urls)]
    (map #(async/<!! %) res-promise)))

(let [res-promise (map #(fetch-async %) urls)]
    (time (map #(async/<!! %) res-promise)))

and the result is good.

"Elapsed time: 470.619411 msecs" ;; http://www.google.com
"Elapsed time: 882.209614 msecs" ;; http://www.google1.com, this is caused by apache HTTP client retry feature, if you disable it, the time is 0.020235 msecs
"Elapsed time: 0.018817 msecs" ;; http://255.255.33.44:8001/

From the above test results, we can see that after the first request takes 500ms (which is the connect-timeout we set), the other requests are executed asynchronously and the total time is almost 500ms at the end. Moreover, the async/go process is very lightweight and does not consume as many resources and execution time as a thread does.

[DerGuteMoritz]

Note that here:

    (async/go
      (try
        (let [res (client/get url {:socket-timeout 500 
                                   :connection-timeout 1000
                                   :retry-handler (fn [ex try-count http-context]
                                                    (if (> try-count 0) false true))})]
          (async/put! ret {:result :success :msg (:status res)}))****

you're doing a blocking call (client/get) in the async/go block which ties up the underlying thread. Quoting from the async/go docstring:

go blocks should not (either directly or indirectly) perform operations that may block indefinitely. Doing so risks depleting the fixed pool of go block threads, causing all go block processing to stop. This includes core.async blocking ops (those ending in !!) and other blocking IO.