Connection leak from re-authentication in HttpExecutorServiceImpl.invokeReuqest()

[symcssn]

UPDATE: Please look at my last comment in this thread from: June 9, 2015

OS4j core/connector: 2.0.4-Snapshot (June 1st)
HttpClient 4.3.6
HttpCore 4.3.3

My application test code kept hanging after a while. I use the default pool sizes. Here is the apache debug log.

... 

2015/06/02 11:24:53:620 PDT [DEBUG] MainClientExec - Executing request HEAD {object URL} HTTP/1.1
2015/06/02 11:24:53:620 PDT [DEBUG] MainClientExec - Target auth state: UNCHALLENGED
2015/06/02 11:24:53:620 PDT [DEBUG] MainClientExec - Proxy auth state: UNCHALLENGED
2015/06/02 11:24:53:620 PDT [DEBUG] headers - http-outgoing-30 >> HEAD {object URL} HTTP/1.1
2015/06/02 11:24:53:620 PDT [DEBUG] headers - http-outgoing-30 >> Accept: application/json; charset=utf-8
2015/06/02 11:24:53:620 PDT [DEBUG] headers - http-outgoing-30 >> X-Auth-Token: {TOKEN}
2015/06/02 11:24:53:620 PDT [DEBUG] headers - http-outgoing-30 >> Host: {host URL}
2015/06/02 11:24:53:620 PDT [DEBUG] headers - http-outgoing-30 >> Connection: Keep-Alive
2015/06/02 11:24:53:620 PDT [DEBUG] headers - http-outgoing-30 >> User-Agent: OpenStack4j-Agent
2015/06/02 11:24:53:620 PDT [DEBUG] headers - http-outgoing-30 >> Accept-Encoding: gzip,deflate
2015/06/02 11:24:53:953 PDT [DEBUG] headers - http-outgoing-30 << HTTP/1.1 200 OK
2015/06/02 11:24:53:953 PDT [DEBUG] headers - http-outgoing-30 << Content-Length: 1
2015/06/02 11:24:53:953 PDT [DEBUG] headers - http-outgoing-30 << Accept-Ranges: bytes
2015/06/02 11:24:53:954 PDT [DEBUG] headers - http-outgoing-30 << Last-Modified: Tue, 02 Jun 2015 18:24:51 GMT
2015/06/02 11:24:53:954 PDT [DEBUG] headers - http-outgoing-30 << Etag: 93b885adfe0da089cdf634904fd59f71
2015/06/02 11:24:53:954 PDT [DEBUG] headers - http-outgoing-30 << X-Timestamp: 1433269490.69728
2015/06/02 11:24:53:954 PDT [DEBUG] headers - http-outgoing-30 << Content-Type: application/octet-stream
2015/06/02 11:24:53:954 PDT [DEBUG] headers - http-outgoing-30 << X-Trans-Id: tx76efdbd5b26d4a38b78a2-00556df4f5
2015/06/02 11:24:53:954 PDT [DEBUG] headers - http-outgoing-30 << Date: Tue, 02 Jun 2015 18:24:53 GMT
2015/06/02 11:24:53:954 PDT [DEBUG] headers - http-outgoing-30 << Connection: close
2015/06/02 11:24:53:954 PDT [DEBUG] DefaultManagedHttpClientConnection - http-outgoing-30: Close connection
2015/06/02 11:24:53:954 PDT [DEBUG] MainClientExec - Connection discarded
2015/06/02 11:24:53:954 PDT [DEBUG] DefaultManagedHttpClientConnection - http-outgoing-30: Close connection
2015/06/02 11:24:53:954 PDT [DEBUG] PoolingHttpClientConnectionManager - Connection released: [id: 30][route: {s}->{route URL:port}][total kept alive: 2; route allocated: 1 of 2; total allocated: 3 of 20]
2015/06/02 11:24:53:955 PDT [DEBUG] RequestAddCookies - CookieSpec selected: best-match
2015/06/02 11:24:53:955 PDT [DEBUG] RequestAuthCache - Auth cache not set in the context
2015/06/02 11:24:53:955 PDT [DEBUG] PoolingHttpClientConnectionManager - Connection request: [route: {s}->{route URL:port}][total kept alive: 2; route allocated: 1 of 2; total allocated: 3 of 20]
2015/06/02 11:24:53:955 PDT [DEBUG] PoolingHttpClientConnectionManager - Connection leased: [id: 31][route: {s}->{route URL:port}][total kept alive: 2; route allocated: 2 of 2; total allocated: 4 of 20]
2015/06/02 11:24:53:955 PDT [DEBUG] MainClientExec - Opening connection {s}->{route URL:port}
2015/06/02 11:24:53:955 PDT [DEBUG] HttpClientConnectionOperator - Connecting to {route URL}/{route IP:port}
2015/06/02 11:24:54:157 PDT [DEBUG] HttpClientConnectionOperator - Connection established {source ip:port} <->{dest ip:port}
2015/06/02 11:24:54:157 PDT [DEBUG] MainClientExec - Executing request GET {object URL} HTTP/1.1
2015/06/02 11:24:54:157 PDT [DEBUG] MainClientExec - Target auth state: UNCHALLENGED
2015/06/02 11:24:54:157 PDT [DEBUG] MainClientExec - Proxy auth state: UNCHALLENGED
2015/06/02 11:24:54:157 PDT [DEBUG] headers - http-outgoing-31 >> GET {object URL} HTTP/1.1
2015/06/02 11:24:54:157 PDT [DEBUG] headers - http-outgoing-31 >> Accept: application/json; charset=utf-8
2015/06/02 11:24:54:157 PDT [DEBUG] headers - http-outgoing-31 >> Range: bytes=0-
2015/06/02 11:24:54:157 PDT [DEBUG] headers - http-outgoing-31 >> X-Auth-Token:{TOKEN}
2015/06/02 11:24:54:157 PDT [DEBUG] headers - http-outgoing-31 >> Host: {host URL}
2015/06/02 11:24:54:157 PDT [DEBUG] headers - http-outgoing-31 >> Connection: Keep-Alive
2015/06/02 11:24:54:157 PDT [DEBUG] headers - http-outgoing-31 >> User-Agent: OpenStack4j-Agent
2015/06/02 11:24:54:157 PDT [DEBUG] headers - http-outgoing-31 >> Accept-Encoding: gzip,deflate
2015/06/02 11:24:54:395 PDT [DEBUG] headers - http-outgoing-31 << HTTP/1.1 206 Partial Content
2015/06/02 11:24:54:395 PDT [DEBUG] headers - http-outgoing-31 << Content-Length: 1
2015/06/02 11:24:54:395 PDT [DEBUG] headers - http-outgoing-31 << Accept-Ranges: bytes
2015/06/02 11:24:54:395 PDT [DEBUG] headers - http-outgoing-31 << Last-Modified: Tue, 02 Jun 2015 18:24:51 GMT
2015/06/02 11:24:54:395 PDT [DEBUG] headers - http-outgoing-31 << Content-Range: bytes 0-0/1
2015/06/02 11:24:54:395 PDT [DEBUG] headers - http-outgoing-31 << Etag: 93b885adfe0da089cdf634904fd59f71
2015/06/02 11:24:54:395 PDT [DEBUG] headers - http-outgoing-31 << X-Timestamp: 1433269490.69728
2015/06/02 11:24:54:395 PDT [DEBUG] headers - http-outgoing-31 << Content-Type: application/octet-stream
2015/06/02 11:24:54:396 PDT [DEBUG] headers - http-outgoing-31 << X-Trans-Id: tx2cdb7a2e3da3475491582-00556df4f6
2015/06/02 11:24:54:396 PDT [DEBUG] headers - http-outgoing-31 << Date: Tue, 02 Jun 2015 18:24:54 GMT
2015/06/02 11:24:54:396 PDT [DEBUG] headers - http-outgoing-31 << Connection: close
2015/06/02 11:24:54:397 PDT [DEBUG] RequestAddCookies - CookieSpec selected: best-match
2015/06/02 11:24:54:397 PDT [DEBUG] RequestAuthCache - Auth cache not set in the context
2015/06/02 11:24:54:397 PDT [DEBUG] PoolingHttpClientConnectionManager - Connection request: [route: {s}->{route URL:port}][total kept alive: 2; route allocated: 2 of 2; total allocated: 4 of 20]


FREEZING HERE

So I decided to write a simple test application to see if I can reproduce OS4j hanging again. I force synced maven before doing this. Here is the test code:

public class SimpleApp {

    private static OSClient osTenant1;

    private static ObjectStorageService objectStorage;
    private static ObjectStorageAccountService account;
    private static ObjectStorageContainerService containers;
    private static ObjectStorageObjectService objects;

    public SimpleApp() {

        osTenant1 = OSFactory.builder().endpoint(endpoint)
                .credentials(userName, password)
                .tenantName(tenantName).withConfig(config)
                .authenticate();

        objectStorage = osTenant1.objectStorage();
        account = objectStorage.account();
        containers = objectStorage.containers();
        objects = objectStorage.objects();
    }

    public static class RequestThread extends Thread
    {
        private int threadNum;
        private OSClient clientFromAccess;
        private ObjectStorageObjectService objectservice;
        private Access access;

        public RequestThread(int threadNum, Access access)
        {
            this.threadNum = threadNum;
            this.access = access;
        }

        public void run()
        {
            this.clientFromAccess = OSFactory.clientFromAccess(access, config);
            this.objectservice = clientFromAccess.objectStorage().objects();
            makeRequest(threadNum);
        }

        public  void makeRequest(int threadNum)
        {
            System.out.println("Starting requests");
            int requestNumber = 0;
            while (true)
            {
                requestNumber++;
                if (requestNumber % 50 ==0) // I varied this parameter
                {
                    System.out.println("Thread " + threadNum + " making Request #: " + requestNumber);
                }

                objectservice.list("testContainer");

                try {
                    Thread.sleep(50); // I varied this parameter
                } catch (InterruptedException e) {
                    // TODO Auto-generated catch block
                    e.printStackTrace();
                }
            }
        }
    }





    public static void main(String[] args) throws FileNotFoundException, InterruptedException {
        try {
            new SimpleApp();

            RequestThread rt1 = new RequestThread(1, osTenant1.getAccess());
            RequestThread rt2 = new RequestThread(2, osTenant1.getAccess());
            RequestThread rt3 = new RequestThread(3, osTenant1.getAccess());

            rt1.start();
            rt2.start();
            rt3.start();

            rt1.join();

        }
    }

}

My test eventually hangs after making requests:

Trial 1:

(200ms sleep, print every 50 requests)
Thread 3 making Request #: 28500
Thread 2 making Request #: 28550
Thread 1 making Request #: 28600

Freezes at this point

Trial 2:

(50ms sleep, print every 50 requests)
Thread 2 making Request #: 49100
Thread 1 making Request #: 48750
Thread 3 making Request #: 49150


Freezes at this point

Trial 3:

(50ms sleep, print every 500 requests)
Thread 1 making Request #: 47500
Thread 2 making Request #: 47500
Thread 3 making Request #: 47500


Freezes at this point

I did a netstat -b while the above test was hung and I see that a connection is established to the swift server.

 [javaw.exe]
  TCP    {ip}:8131       {swift server}:8080          ESTABLISHED
 [javaw.exe]
  TCP    {ip}:8132       {swift server}:8080          ESTABLISHED

[symcssn]

I've used the interceptor to do some more testing. I've added this code:

   static {
        initOpestack4jClientInterceptor();
    }

    private static void initOpestack4jClientInterceptor()
    {
        HttpClientConfigInterceptor interceptor = new HttpClientConfigInterceptor() {

            public void onClientCreate(HttpClientBuilder client, Builder requestConfig, Config config)
            {
                manager = new PoolingHttpClientConnectionManager(60000, TimeUnit.MILLISECONDS);
                requestConfig.setStaleConnectionCheckEnabled(true).setExpectContinueEnabled(true).setConnectionRequestTimeout(60000);
                client.setConnectionManager(manager);
            }

        };
        HttpClientFactory.registerInterceptor(interceptor);
    }

This prevents the application from hanging indefinitely.

I've also modified the makeRequest method hoping that it will reset any connections in the pool allowing me to reuse the PoolingConnectionManager. Unfortunately, after the exception is caught, no more requests are able to be made:

public  void makeRequest(int threadNum)
        {
            System.out.println("Starting requests");
            int requestNumber = 0;
            int exceptionCount = 0;

            while (exceptionCount < 2)
            {
                try {
                    requestNumber++;
                    if (requestNumber % 500 ==0)
                    {
                            System.out.println("Thread " + threadNum
                                    + " making Request #: " + requestNumber
                                    + ". Exception count: " + exceptionCount);
                    }           
                    objectservice.list("testContainer");                    
                }
                catch (ConnectionException ce)
                {
                    exceptionCount++;
                    System.out.println("Caught ConnectionException. HTTP status code: "
                            + ce.getStatus() + ". HTTP message: " + ce.getMessage());
                    manager.closeExpiredConnections(); 
                    manager.closeIdleConnections(6000, TimeUnit.MILLISECONDS);
                }
                catch (ResponseException re) 
                {
                    exceptionCount++;
                    System.out.println("Caught ResponseException. HTTP status code: "
                            + re.getStatus() + ". HTTP message: " + re.getMessage());
                    manager.closeExpiredConnections();
                    manager.closeIdleConnections(6000, TimeUnit.MILLISECONDS);
                }

            }
        }
    }

Output:

Thread 3 making Request #: 97500. Exception count: 0
Thread 2 making Request #: 97000. Exception count: 0
Thread 1 making Request #: 97500. Exception count: 0
Thread 3 making Request #: 98000. Exception count: 0
Caught ConnectionException. HTTP status code: 0. HTTP message: Timeout waiting for connection from pool
Caught ConnectionException. HTTP status code: 0. HTTP message: Timeout waiting for connection from pool
Caught ConnectionException. HTTP status code: 0. HTTP message: Timeout waiting for connection from pool
Caught ConnectionException. HTTP status code: 0. HTTP message: Timeout waiting for connection from pool
Caught ConnectionException. HTTP status code: 0. HTTP message: Timeout waiting for connection from pool
Caught ConnectionException. HTTP status code: 0. HTTP message: Timeout waiting for connection from pool
Caught ResponseException. HTTP status code: 0. HTTP message: Timeout waiting for connection from pool

I'm thinking that at this point I just have to shutdown this manager and create a new one. However, I need a way to re-register an interceptor. The register operation only happens once. Is there a way to reset the interceptor in the HttpClientFactory? I want to try to re-register a new connection pool manager after shutting this one down once it becomes unusable to see if my application can recover and continue to run properly without having to fail-stop.

[symcssn]

@gondor

I was thinking that leak is possibly happening because the responses from the requests are not being handled properly. Here is an apache document on how to release low level resources (in this case the responses) properly: http://hc.apache.org/httpcomponents-client-4.3.x/tutorial/html/fundamentals.html#d5e145

After looking through the code, a good place to handle the release of the response would be in the HttpEntityHandler class. It seems like you are closing the responses for status codes between 400-500. Is there a reason why you are not closing it for 500+?

Also, HttpExecutorServiceImpl.invokeReuqest() is an easy place to forget to release resources if the token expires. Since the request fails when the token has expired, that specific response is never returned and handled. As a result, that specific response is never closed.

UPDATE:
I've figured out why the test I wrote was not able to lease a connection from the pool. There IS a connection leak. It is coming from the above mentioned comment about HttpExecutorServiceImpl.invokeReuqest().

This is the code:

private <R> HttpResponse invokeRequest(HttpCommand<R> command) throws Exception {
        CloseableHttpResponse response = command.execute();
        if (command.getRetries() == 0 && response.getStatusLine().getStatusCode() == 401 && !command.getRequest().getHeaders().containsKey(ClientConstants.HEADER_OS4J_AUTH))
        {
            OSAuthenticator.reAuthenticate();
            command.getRequest().getHeaders().put(ClientConstants.HEADER_X_AUTH_TOKEN, OSClientSession.getCurrent().getTokenId());
            return invokeRequest(command.incrementRetriesAndReturn());
        }
        return HttpResponseImpl.wrap(response);
    }

I placed a breakpoint at line OSAuthenticator.reAuthenticate();. When the code would hit that breakpoint, I'd execute: response.close() with the debugger. When I invoked that command, I did not have any connection problems. I did that 1 more time when the token expired again. The test program kept successfully making request. The next time I hit the breakpoint, I did not call response.close(). This time, the program failed to make requests and lease connections from the pool.

For performance reasons, do we want to close the connections for all responses that are not successful (ie. 200s)? Can't we just consume the entity from the response? In these cases, is it more expensive to consume or create a new connection because the previous response was closed? It would be best to consume the entity otherwise there will be connections in "TIME_WAIT" state. At this state, the ports that the connection is using will be temporarily unavailable: http://wiki.apache.org/HttpComponents/FrequentlyAskedConnectionManagementQuestions

You need to consume the entity fully so the connection can be reused: https://hc.apache.org/httpcomponents-client-ga/quickstart.html

I'd recommend consuming entities for all responses (200-500). Obviously for GET requests that is up to the application using OS4j to consume properly.

UPDATE:
I was looking through the code. In line 55, HttpExecutorServiceImpl.invoke(HttpRequest<R>), catches an Exception and maps it to a ConnectionException. If lets say that Apache throws a ConnectTimeoutException, does the connection need to be closed/consumed/cleaned up? I am not sure what the proper way to handle that exception is.

[symcssn]

Hi @gondor

I was looking through the source code: https://github.com/gondor/openstack4j/blob/master/connectors/httpclient/src/main/java/org/openstack4j/connectors/httpclient/HttpExecutorServiceImpl.java . It seems like this connection leak during reauthentication was not addressed yet.

Thanks,

symcssn

[gondor]

Thanks for the catch. Just checked in a fix and will deploy a snapshot shortly.

[symcssn]

Thank you very much.

Why are there two different impls?

https://github.com/gondor/openstack4j/blob/master/connectors/http-connector/src/main/java/org/openstack4j/connectors/http/HttpExecutorServiceImpl.java

https://github.com/gondor/openstack4j/blob/master/connectors/httpclient/src/main/java/org/openstack4j/connectors/httpclient/HttpExecutorServiceImpl.java

I use the Http-Client jar for my connector. Would your change in the connectors/http-connector/ be reflected in connectors/httpclient/?

[gondor]

Good catch, I updated the wrong connector.

[sjpatil]

@gondor @symcssn @petergardfjall

We are using 2.10 release with httpclient and facing same issue with connection pool.

We are doing multiple server snapshot downloads in a sequence. First download works well but later downloads get stuck. As by default the max connections per route is 2; when increased withMaxConnectionsPerRoute , we could do more successful calls. But ultimately it gets stuck again after the connections are exhausted. It seems connections are open and not getting closed.

   Config config=Config.newConfig().withMaxConnectionsPerRoute(4)

Logs where it gets stuck are -

 2016/02/23 08:47:41:573 UTC [DEBUG] PoolingHttpClientConnectionManager - Connection [id: 0][route: {}->http://endpoint:5000] can be kept alive indefinitely
2016/02/23 08:47:41:573 UTC [DEBUG] PoolingHttpClientConnectionManager - Connection released: [id: 0][route: {}->http://endpoint:5000][total kept alive: 2; route allocated: 1 of 2; total allocated: 4 of 20]
 2016/02/23 08:47:41:574 UTC [DEBUG] RequestAddCookies - CookieSpec selected: best-match
 2016/02/23 08:47:41:574 UTC [DEBUG] RequestAuthCache - Auth cache not set in the context
 2016/02/23 08:47:41:574 UTC [DEBUG] PoolingHttpClientConnectionManager - Connection request: [route: {}->http://endpoint:8774][total kept alive: 2; route allocated: 2 of 2; total allocated: 4 of 20]

Our download code makes sure that the inputstream that we receive is closed. However, all operations from ServerService get stuck after the last successful download, however other calls from ImageService can be made.

[vinodborole]

closing this as the fix is added