Apache HttpClient 4.3 does not honor keep alive

Question

On the nGinx server side, connection-keep alive is set for clients for upto 30 seconds. But using this code and the attached logs, HttpClient 4.3. does not honor keep alive and closes the connection after every request. Why is this happening?

I come to that conclusion after trying netstat -an repeatedly and finding out that the client is opening different ports at different times during the for loop execution and FIN states going by every 2 seconds.

The logs given below also show that the connection is closed after everyrequest

static ConnectionKeepAliveStrategy myStrategy = new ConnectionKeepAliveStrategy() {
    public long getKeepAliveDuration(HttpResponse response, HttpContext context) {
            return 30 * 1000;
    }
};

public static void main(String[] args) throws Exception {

    java.util.logging.Logger.getLogger("org.apache.http.wire").setLevel(java.util.logging.Level.FINER);
    java.util.logging.Logger.getLogger("org.apache.http.headers").setLevel(java.util.logging.Level.FINER);

    System.setProperty("org.apache.commons.logging.Log", "org.apache.commons.logging.impl.SimpleLog");
    System.setProperty("org.apache.commons.logging.simplelog.showdatetime", "true");
    System.setProperty("org.apache.commons.logging.simplelog.log.httpclient.wire", "debug");
    System.setProperty("org.apache.commons.logging.simplelog.log.org.apache.http", "debug");
    System.setProperty("org.apache.commons.logging.simplelog.log.org.apache.http.headers", "debug");

    callServer();
}

public static void callServer() throws Exception {

    KeyStore keyStore = KeyStore.getInstance("pkcs12");

    FileInputStream instream = new FileInputStream(new File("/engineering/workspace/nginx_pilot/keystores/clientkeystore.pkcs"));
    try {
        keyStore.load(instream, "****".toCharArray());
    } finally {
        instream.close();
    }

    KeyStore trustStore = KeyStore.getInstance(KeyStore.getDefaultType());

    instream = new FileInputStream(new File("/engineering/workspace/nginx_pilot/keystores/serverKeystore.jks"));
    try {
        trustStore.load(instream, "****".toCharArray());
    } finally {
        instream.close();
    }

    SSLContext sslContext = SSLContexts.custom().loadKeyMaterial(keyStore, "pass".toCharArray()).loadTrustMaterial(trustStore).build();
    SSLConnectionSocketFactory sslsf = new SSLConnectionSocketFactory(sslContext, SSLConnectionSocketFactory.ALLOW_ALL_HOSTNAME_VERIFIER);

    CloseableHttpClient httpclient = HttpClients.custom().setSSLSocketFactory(sslsf).setConnectionReuseStrategy(DefaultConnectionReuseStrategy.INSTANCE).build();

    CloseableHttpResponse response = null;

    try {
        HttpGet httpget = new HttpGet("https://" + getString() + ":8443/GenevaServers/GetConfig/unit.test.asset.ast1");

        System.out.println("executing request" + httpget.getRequestLine());

        for (int i = 0; i < 10000; i++) {
            System.out.println("Beginning");
            long currentTimeMillis = System.currentTimeMillis();
            response = httpclient.execute(httpget);
            System.out.println((System.currentTimeMillis() - currentTimeMillis) + "ms");
            HttpEntity entity = response.getEntity();
            System.out.println(IOUtils.toString(entity.getContent()));
            EntityUtils.consume(entity);
            System.out.println("End");
        }
    } catch (Exception e) {
        e.printStackTrace();
    }finally {
        response.close();
        httpclient.close();
    }
}

These are the logs.

2014/01/22 19:24:50:252 PST [DEBUG] RequestAddCookies - CookieSpec selected: best-match
2014/01/22 19:24:50:252 PST [DEBUG] RequestAuthCache - Auth cache not set in the context
2014/01/22 19:24:50:252 PST [DEBUG] PoolingHttpClientConnectionManager - Connection      request: [route: {s}->https://ichor.corp.com:8443][total kept alive: 2; route allocated: 2 of 2; total allocated: 2 of 20]
2014/01/22 19:24:50:253 PST [DEBUG] DefaultManagedHttpClientConnection - http-outgoing-0:    Close connection
2014/01/22 19:24:50:254 PST [DEBUG] PoolingHttpClientConnectionManager - Connection leased: [id: 2][route: {s}->https://ichor.corp.com:8443][total kept alive: 1; route allocated:    2 of 2; total allocated: 2 of 20]
2014/01/22 19:24:50:254 PST [DEBUG] MainClientExec - Opening connection {s}-  >https://ichor.corp.com:8443
2014/01/22 19:24:50:254 PST [DEBUG] HttpClientConnectionManager - Connecting to    ichor.corp.com/17.169.1.18:8443
2014/01/22 19:24:50:392 PST [DEBUG] MainClientExec - Executing request GET /GenevaServers/GetConfig/unit.test.asset.ast1 HTTP/1.1
2014/01/22 19:24:50:392 PST [DEBUG] MainClientExec - Target auth state: UNCHALLENGED
2014/01/22 19:24:50:392 PST [DEBUG] MainClientExec - Proxy auth state: UNCHALLENGED
2014/01/22 19:24:50:392 PST [DEBUG] headers - http-outgoing-2 >> GET   /GenevaServers/GetConfig/unit.test.asset.ast1 HTTP/1.1
2014/01/22 19:24:50:392 PST [DEBUG] headers - http-outgoing-2 >> Host: ichor.corp.com:8443
2014/01/22 19:24:50:392 PST [DEBUG] headers - http-outgoing-2 >> Connection: Keep-Alive
2014/01/22 19:24:50:392 PST [DEBUG] headers - http-outgoing-2 >> User-Agent: Apache- HttpClient/4.3.1 (java 1.5)
2014/01/22 19:24:50:392 PST [DEBUG] headers - http-outgoing-2 >> Accept-Encoding: gzip,deflate
2014/01/22 19:24:50:392 PST [DEBUG] wire - http-outgoing-2 >> "GET /GenevaServers/GetConfig/unit.test.asset.ast1 HTTP/1.1[\r][\n]"
2014/01/22 19:24:50:392 PST [DEBUG] wire - http-outgoing-2 >> "Host: ichor.corp.com:8443[\r][\n]"
2014/01/22 19:24:50:392 PST [DEBUG] wire - http-outgoing-2 >> "Connection: Keep-Alive[\r][\n]"
2014/01/22 19:24:50:392 PST [DEBUG] wire - http-outgoing-2 >> "User-Agent: Apache-HttpClient/4.3.1 (java 1.5)[\r][\n]"
2014/01/22 19:24:50:392 PST [DEBUG] wire - http-outgoing-2 >> "Accept-Encoding: gzip,deflate[\r][\n]"
2014/01/22 19:24:50:393 PST [DEBUG] wire - http-outgoing-2 >> "[\r][\n]"
2014/01/22 19:24:50:462 PST [DEBUG] wire - http-outgoing-2 << "HTTP/1.1 200 OK[\r][\n]"
2014/01/22 19:24:50:462 PST [DEBUG] wire - http-outgoing-2 << "Server: nginx/1.4.1[\r][\n]"
2014/01/22 19:24:50:463 PST [DEBUG] wire - http-outgoing-2 << "Date: Thu, 23 Jan 2014 03:24:09 GMT[\r][\n]"
2014/01/22 19:24:50:463 PST [DEBUG] wire - http-outgoing-2 << "Content-Type: application/json[\r][\n]"
2014/01/22 19:24:50:463 PST [DEBUG] wire - http-outgoing-2 << "Content-Length: 270[\r][\n]"
2014/01/22 19:24:50:463 PST [DEBUG] wire - http-outgoing-2 << "Connection: keep-alive[\r][\n]"
2014/01/22 19:24:50:463 PST [DEBUG] wire - http-outgoing-2 << "[\r][\n]"

Any advice would be of great help. Thank you in advance.

Answer 1

It certainly does but this is a special case

SSLContext sslContext = SSLContexts.custom().loadKeyMaterial(keyStore, "pass".toCharArray()).loadTrustMaterial(trustStore).build();
SSLConnectionSocketFactory sslsf = new SSLConnectionSocketFactory(sslContext, SSLConnectionSocketFactory.ALLOW_ALL_HOSTNAME_VERIFIER);

You are using SSL key to authenticate with the target server. This makes the connection represent a particular user and carry a particular security context. In other words the connection has a particular state (user principal). Most likely you do not want this connection to be leased to an arbitrary execution thread that may represent an entirely different user, do you? HttpClient 4 (unlike its predecessors) tracks stateful connections and makes sure they cannot be re-used by threads with a different execution context.

There are several ways you can solve the problem

1. Recommended. Make all logically related requests share the same execution context

2. Manually manage connection state

3. Disable connection state tracking. This measure will have security repercussions, so it must be considered carefully