Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Timeout waiting for connection from pool #269

Closed
dehora opened this issue Sep 2, 2014 · 22 comments
Closed

Timeout waiting for connection from pool #269

dehora opened this issue Sep 2, 2014 · 22 comments

Comments

@dehora
Copy link

dehora commented Sep 2, 2014

Timeout waiting for connection from pool

! org.apache.http.conn.ConnectionPoolTimeoutException: Timeout waiting for connection from pool
! at org.apache.http.impl.conn.PoolingClientConnectionManager.leaseConnection(PoolingClientConnectionManager.java:226) 
! at org.apache.http.impl.conn.PoolingClientConnectionManager$1.getConnection(PoolingClientConnectionManager.java:195) 
! at sun.reflect.GeneratedMethodAccessor22.invoke(Unknown Source) ~[na:na]
! at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_11]
! at java.lang.reflect.Method.invoke(Method.java:483) ~[na:1.8.0_11]
! at com.amazonaws.http.conn.ClientConnectionRequestFactory$Handler.invoke(ClientConnectionRequestFactory.java:70)
! at com.amazonaws.http.conn.$Proxy70.getConnection(Unknown Source) ~[na:na]
! at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:423)
! at org.apache.http.impl.client.AbstractHttpClient.doExecute(AbstractHttpClient.java:863)
! at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:82)
! at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:57)
! at com.amazonaws.http.AmazonHttpClient.executeHelper(AmazonHttpClient.java:446)
! at com.amazonaws.http.AmazonHttpClient.execute(AmazonHttpClient.java:256)
! at com.amazonaws.services.dynamodbv2.AmazonDynamoDBClient.invoke(AmazonDynamoDBClient.java:2908)
! at com.amazonaws.services.dynamodbv2.AmazonDynamoDBClient.query(AmazonDynamoDBClient.java:1064)

A check on connections on a server showed a lot of close waits -

netstat -a  | grep CLOSE_WAIT | wc -l 
> 987

which is often indicative of an apache client request not having a close() called. Checking cloudwatch, there was a corresponding latency increase in DDB around the time we saw this (up to 8s).

There wasn't a change in how we call DynamoDB at the time. I am wondering if there is an issue in the client if/when the server latencies are high such that connections don't get closed?

This happened on 1.8.3. We're going to upgrade to 1.8.9.1, but it's hard to tell if related code was changed, the release diffs are too big to review easily :)

@hansonchar
Copy link
Contributor

Hi @dehora,

  • What is the socketTimeout and connectionTimeout configured (via ClientConfiguration) ? Is the default (50 seconds) being used ?
  • What was the load of the application like during the time when the server latencies were high ?

Seems possible that the number of incoming requests exceeded the number of requests that could be completed (during the high server-side latency period) therefore leading to the connection pool exhaustion. A thread dump during the problematic time period could probably help confirm this.

You may also consider changing the timeout configuration to some lower values so that the application could fail-fast in face of transient high latency.

@dehora
Copy link
Author

dehora commented Sep 3, 2014

@hansonchar The timeouts were the default for 1.8.3. There was nothing unusual in terms of request load at the time (we didn't seem to trigger any limitations on ddb). Fwiw, I've had a look at the current master and can't see any obvious places where connections don't get closed.

You may also consider changing the timeout configuration to some lower values so that the application could fail-fast in face of transient high latency.

Thanks for the timeout pointers, and yep, we've wrapped the SDK calls with hystrix to introduce circuit breaking.

@hansonchar
Copy link
Contributor

Hi @dehora, as you probably already know, the socket connection timeout and read timeout can be configured at the client level via ClientConfiguration:

http://docs.aws.amazon.com/AWSJavaSDK/latest/javadoc/com/amazonaws/ClientConfiguration.html

@ferozed
Copy link

ferozed commented Apr 2, 2015

This is happening to us as well. The symptom is the exception from apache that there are no connections in the pool. Since AWS sdk encapsulates all connection management, this seems like an AWS Java sdk bug. can someone comment on the plan for fixing it?

@hansonchar
Copy link
Contributor

Hi @ferozed, can you provide more specific details, such as the version of AWS SDK for Java you are using, stack trace, client configuration, etc. ?

@ferozed
Copy link

ferozed commented Apr 2, 2015

Here is the stack:

2015-04-01 15:11:51,067 INFO  [] [com.amazonaws.http.AmazonHttpClient] Unable to execute HTTP request: Timeout waiting for connection from pool
org.apache.http.conn.ConnectionPoolTimeoutException: Timeout waiting for connection from pool
        at org.apache.http.impl.conn.tsccm.ConnPoolByRoute.getEntryBlocking(ConnPoolByRoute.java:412)
        at org.apache.http.impl.conn.tsccm.ConnPoolByRoute$1.getPoolEntry(ConnPoolByRoute.java:298)
        at org.apache.http.impl.conn.tsccm.ThreadSafeClientConnManager$1.getConnection(ThreadSafeClientConnManager.java:238)
        at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:423)
        at org.apache.http.impl.client.AbstractHttpClient.doExecute(AbstractHttpClient.java:863)
        at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:82)
        at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:106)
        at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:57)
        at com.amazonaws.http.AmazonHttpClient.executeHelper(AmazonHttpClient.java:306)
        at com.amazonaws.http.AmazonHttpClient.execute(AmazonHttpClient.java:190)
        at com.amazonaws.services.s3.AmazonS3Client.invoke(AmazonS3Client.java:2984)
        at com.amazonaws.services.s3.AmazonS3Client.getObject(AmazonS3Client.java:911)
        at com.amazonaws.services.s3.AmazonS3Client.getObject(AmazonS3Client.java:801)
        at com.mycompany.workerthread.saveOriginalImage(ImageBackupDownloader.java:104)
        at com.mycompany.workerthread.run(ImageBackupDownloader.java:78)
        at java.lang.Thread.run(Unknown Source)

Here is the client configuration

41        ClientConfiguration clientConfiguration = new ClientConfiguration();
42        clientConfiguration.setConnectionTimeout(20000);
43        this.sqsClient = new AmazonSQSClient(awsCredentials, clientConfiguration);
44        this.s3Client = new AmazonS3Client(awsCredentials, clientConfiguration);

We use sdk version 1.4.1

@hanshuo-aws
Copy link
Contributor

@ferozed Are you perhaps using the streaming API to read S3 objects but forget to close the S3Object after you consume the content?

http://docs.aws.amazon.com/AWSJavaSDK/latest/javadoc/com/amazonaws/services/s3/model/S3Object.html#getObjectContent%28%29

@ferozed
Copy link

ferozed commented Apr 3, 2015

Yep, that is the reason. Thanks for pointing it out.

@ferozed
Copy link

ferozed commented Apr 28, 2015

hi! We fixed this bug on our side, but it is happening again.

Our java process does calls to SQS and S3 at the same time. Is it possible that both AmazonSQSClient and AmazonS3Client are sharing the same underlying httpclient, and it is not the S3client, but the sqs client that is leaking?

Yesterday we had this issue surface again.

I have grepped the logs for all s3 client errors and put them into a logfile.

http://feroze.s3.amazonaws.com/log.zip?AWSAccessKeyId=AKIAI6ILPMH4QR4ISPHQ&Expires=1432835134&Signature=zPtpBNEz2QHlC%2BpBx4TqvlstTZA%3D

Please have a look at this and let me know if you see something that stands out. here is a snippet of my code....

    private void saveOriginalImage(long imageId, String bucketName, String s3Key) throws Exception
    {
        try
        {
            String s3KeySanitized = getSanitizedS3Key(s3Key);
            S3Object s3Object = s3Client.getObject(bucketName, s3KeySanitized);

            File destinationPath = getDestinationPath(imageId);
            writeS3ObjectToFile(s3Object, destinationPath);
        }
        catch (Exception e)
        {
            logWarn("Unable to save original image: ", e);
            throw e;
        }
    }

    private void writeS3ObjectToFile(S3Object s3Object, File outputFile) throws IOException
    {
        FileOutputStream outputStream = new FileOutputStream(outputFile);
        S3ObjectInputStream s3InputStream = s3Object.getObjectContent();
        try
        {
            IOUtils.copy(s3InputStream, outputStream);
        }
        finally
        {
            try {
                s3InputStream.close();
            } catch (Exception e) {
                logWarn("Unable to close s3 input stream", e);
            }
            try {
                outputStream.close();
            } catch (Exception e) {
                logWarn("Unable to close output stream", e);
            }
        }
    }

@ferozed
Copy link

ferozed commented Apr 28, 2015

Looking at the docs, I see that S3Object also implements Closeable interface. Does this object also need to be closed on error? Could that be contributing to the connection leak?

@hansonchar
Copy link
Contributor

  1. Closing S3Object is equivalent to closing the underlying input stream.
  2. If getDestinationPath failed in your code snippet for whatever reason, the S3Object will get leaked.

Hope this helps.

@ferozed
Copy link

ferozed commented Apr 29, 2015

getDestinationPath() just concatenates strings. There is very low chance of that failing.

@agargi
Copy link

agargi commented Apr 30, 2015

What if first statement of your function writeS3ObjectToFile() i.e. following fails:

FileOutputStream outputStream = new FileOutputStream(outputFile);

s3Object should be closed in saveOriginalImage() function.

@fulghum
Copy link
Contributor

fulghum commented May 1, 2015

@agargi is correct - if you ever have a reference to an S3Object, you MUST close it, otherwise you're potentially leaking an HTTP connection.

Also, if you're just writing the object contents to disk, then you can use TransferManager, or one of the over versions of getObject in AmazonS3Client that take in a file and will perform the file write for you. That would prevent you from ever having to manage/close the S3Object streams.

@ilaipi
Copy link

ilaipi commented Dec 7, 2015

This happening to me, I am only using the HttpClient lib.
The key point is we should close the HttpClient instance, is it?

@shorea
Copy link
Contributor

shorea commented Dec 7, 2015

@ilaipi I'm not sure I understand the question. Can you elaborate?

@ilaipi
Copy link

ilaipi commented Dec 8, 2015

@shorea
OK, I use

<dependency>
    <groupId>org.apache.httpcomponents</groupId>
    <artifactId>httpclient</artifactId>
    <version>4.3.6</version>
</dependency>

in my project for the request to wechat service. My code is:

private HttpClient client = HttpClients.createDefault();
    @Override
    public String post(String host, int port, String schema, String uri, String body) {
        try {
            HttpPost post = new HttpPost(uri);
            post.setConfig(requestConfig);
            post.setHeader("Accept-Charset","utf-8");
            post.setHeader("Content-Type", "application/json;charset=UTF-8");
            StringEntity entity = new StringEntity(body, "UTF-8");
            entity.setContentType("application/json;charset=UTF-8");
            entity.setContentEncoding("utf-8");
            post.setEntity(entity);
            HttpResponse execute = client.execute(new HttpHost(host, port, schema), post);
            return response(execute);
        } catch (Exception e) {
                logger.log(e);
        }
    }

without close the HttpClient instance.

After I put my project online a few days, a week almost, I got the error:

org.apache.http.conn.ConnectionPoolTimeoutException: Timeout waiting for connection from pool
        at org.apache.http.impl.conn.PoolingHttpClientConnectionManager.leaseConnection(PoolingHttpClientConnectionManager.java:254)
        at org.apache.http.impl.conn.PoolingHttpClientConnectionManager$1.get(PoolingHttpClientConnectionManager.java:231)
        at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:173)
        at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:195)
        at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:86)
        at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:108)
        at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:184)
        at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:115)
        at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:57)
        ..........

I have edited my code and published:

//private HttpClient client = HttpClients.createDefault();
    @Override
    public String post(String host, int port, String schema, String uri, String body) {
        try (CloseableHttpClient client = HttpClients.createDefault()) {
            HttpPost post = new HttpPost(uri);
            post.setConfig(requestConfig);
            post.setHeader("Accept-Charset","utf-8");
            post.setHeader("Content-Type", "application/json;charset=UTF-8");
            StringEntity entity = new StringEntity(body, "UTF-8");
            entity.setContentType("application/json;charset=UTF-8");
            entity.setContentEncoding("utf-8");
            post.setEntity(entity);
            HttpResponse execute = client.execute(new HttpHost(host, port, schema), post);
            return response(execute);
        } catch (Exception e) {
              logger.log(e);
        }
    }

I will wait for few days to see the effect.

Thanks.

@shorea
Copy link
Contributor

shorea commented Dec 8, 2015

Okay gotcha. Yeah closing the connection applies when using the raw apache client as well.

@y0299
Copy link

y0299 commented Nov 16, 2017

how to release httpClient . I have used httpClient(4.5.2). here is my code below
finally {
if (response != null) {
try {
EntityUtils.consume(response.getEntity());
} catch (IOException e) {
log.error("");
}
}
}

Do I need to close the response Object, I used EntityUtils.consume(response.getEntity())? and used PoolingHttpClientConnectionManager in my application, I have set the maxTotal and defaultMaxPerRoute. but it's still exist “Timeout waiting for connection from pool ” .

@djangofan
Copy link

FYI: I found that I was able to work around getting this error by using AmazonS3Client.getObjectAsString method, which has a finally block with a close on it, as opposed to using AmazoneS3Client.getObject , which doesn't seem to have the same closing feature.

} finally {
            IOUtils.closeQuietly(object, log);
        }

@adityar2
Copy link

adityar2 commented Jun 4, 2018

I am facing a similar issue for dynamo db read operation.

Caused by: com.amazonaws.SdkClientException: Unable to execute HTTP request: Timeout waiting for connection from pool
        at com.amazonaws.http.AmazonHttpClient$RequestExecutor.handleRetryableException(AmazonHttpClient.java:1114) ~[AWSJavaClientRuntime-1.11.x.jar:?]
        at com.amazonaws.http.AmazonHttpClient$RequestExecutor.executeHelper(AmazonHttpClient.java:1064) ~[AWSJavaClientRuntime-1.11.x.jar:?]
        at com.amazonaws.http.AmazonHttpClient$RequestExecutor.doExecute(AmazonHttpClient.java:743) ~[AWSJavaClientRuntime-1.11.x.jar:?]
        at com.amazonaws.http.AmazonHttpClient$RequestExecutor.executeWithTimer(AmazonHttpClient.java:717) ~[AWSJavaClientRuntime-1.11.x.jar:?]
        at com.amazonaws.http.AmazonHttpClient$RequestExecutor.execute(AmazonHttpClient.java:699) ~[AWSJavaClientRuntime-1.11.x.jar:?]
        at com.amazonaws.http.AmazonHttpClient$RequestExecutor.access$500(AmazonHttpClient.java:667) ~[AWSJavaClientRuntime-1.11.x.jar:?]
        at com.amazonaws.http.AmazonHttpClient$RequestExecutionBuilderImpl.execute(AmazonHttpClient.java:649) ~[AWSJavaClientRuntime-1.11.x.jar:?]
        at com.amazonaws.http.AmazonHttpClient.execute(AmazonHttpClient.java:513) ~[AWSJavaClientRuntime-1.11.x.jar:?]
        at com.amazonaws.services.dynamodbv2.AmazonDynamoDBClient.doInvoke(AmazonDynamoDBClient.java:3239) ~[AWSDynamoDBJavaModel-1.11.x.jar:?]
        at com.amazonaws.services.dynamodbv2.AmazonDynamoDBClient.invoke(AmazonDynamoDBClient.java:3215) ~[AWSDynamoDBJavaModel-1.11.x.jar:?]
        at com.amazonaws.services.dynamodbv2.AmazonDynamoDBClient.executeQuery(AmazonDynamoDBClient.java:2237) ~[AWSDynamoDBJavaModel-1.11.x.jar:?]
        at com.amazonaws.services.dynamodbv2.AmazonDynamoDBClient.query(AmazonDynamoDBClient.java:2212) ~[AWSDynamoDBJavaModel-1.11.x.jar:?]
        at com.amazonaws.services.dynamodbv2.datamodeling.DynamoDBMapper.query(DynamoDBMapper.java:1505) ~[AWSPersistenceJavaClient-1.11.x.jar:?]

As per cloudwatch logs for the DDB read call, there was a spike at that time in consumed read capacity to 326K for more than 5 datapoints in 5 min

@Pandacli
Copy link

@shorea OK, I use

<dependency>
    <groupId>org.apache.httpcomponents</groupId>
    <artifactId>httpclient</artifactId>
    <version>4.3.6</version>
</dependency>

in my project for the request to wechat service. My code is:

private HttpClient client = HttpClients.createDefault();
    @Override
    public String post(String host, int port, String schema, String uri, String body) {
        try {
            HttpPost post = new HttpPost(uri);
            post.setConfig(requestConfig);
            post.setHeader("Accept-Charset","utf-8");
            post.setHeader("Content-Type", "application/json;charset=UTF-8");
            StringEntity entity = new StringEntity(body, "UTF-8");
            entity.setContentType("application/json;charset=UTF-8");
            entity.setContentEncoding("utf-8");
            post.setEntity(entity);
            HttpResponse execute = client.execute(new HttpHost(host, port, schema), post);
            return response(execute);
        } catch (Exception e) {
                logger.log(e);
        }
    }

without close the HttpClient instance.

After I put my project online a few days, a week almost, I got the error:

org.apache.http.conn.ConnectionPoolTimeoutException: Timeout waiting for connection from pool
        at org.apache.http.impl.conn.PoolingHttpClientConnectionManager.leaseConnection(PoolingHttpClientConnectionManager.java:254)
        at org.apache.http.impl.conn.PoolingHttpClientConnectionManager$1.get(PoolingHttpClientConnectionManager.java:231)
        at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:173)
        at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:195)
        at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:86)
        at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:108)
        at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:184)
        at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:115)
        at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:57)
        ..........

I have edited my code and published:

//private HttpClient client = HttpClients.createDefault();
    @Override
    public String post(String host, int port, String schema, String uri, String body) {
        try (CloseableHttpClient client = HttpClients.createDefault()) {
            HttpPost post = new HttpPost(uri);
            post.setConfig(requestConfig);
            post.setHeader("Accept-Charset","utf-8");
            post.setHeader("Content-Type", "application/json;charset=UTF-8");
            StringEntity entity = new StringEntity(body, "UTF-8");
            entity.setContentType("application/json;charset=UTF-8");
            entity.setContentEncoding("utf-8");
            post.setEntity(entity);
            HttpResponse execute = client.execute(new HttpHost(host, port, schema), post);
            return response(execute);
        } catch (Exception e) {
              logger.log(e);
        }
    }

I will wait for few days to see the effect.

Thanks.

@shorea OK, I use

<dependency>
    <groupId>org.apache.httpcomponents</groupId>
    <artifactId>httpclient</artifactId>
    <version>4.3.6</version>
</dependency>

in my project for the request to wechat service. My code is:

private HttpClient client = HttpClients.createDefault();
    @Override
    public String post(String host, int port, String schema, String uri, String body) {
        try {
            HttpPost post = new HttpPost(uri);
            post.setConfig(requestConfig);
            post.setHeader("Accept-Charset","utf-8");
            post.setHeader("Content-Type", "application/json;charset=UTF-8");
            StringEntity entity = new StringEntity(body, "UTF-8");
            entity.setContentType("application/json;charset=UTF-8");
            entity.setContentEncoding("utf-8");
            post.setEntity(entity);
            HttpResponse execute = client.execute(new HttpHost(host, port, schema), post);
            return response(execute);
        } catch (Exception e) {
                logger.log(e);
        }
    }

without close the HttpClient instance.

After I put my project online a few days, a week almost, I got the error:

org.apache.http.conn.ConnectionPoolTimeoutException: Timeout waiting for connection from pool
        at org.apache.http.impl.conn.PoolingHttpClientConnectionManager.leaseConnection(PoolingHttpClientConnectionManager.java:254)
        at org.apache.http.impl.conn.PoolingHttpClientConnectionManager$1.get(PoolingHttpClientConnectionManager.java:231)
        at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:173)
        at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:195)
        at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:86)
        at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:108)
        at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:184)
        at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:115)
        at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:57)
        ..........

I have edited my code and published:

//private HttpClient client = HttpClients.createDefault();
    @Override
    public String post(String host, int port, String schema, String uri, String body) {
        try (CloseableHttpClient client = HttpClients.createDefault()) {
            HttpPost post = new HttpPost(uri);
            post.setConfig(requestConfig);
            post.setHeader("Accept-Charset","utf-8");
            post.setHeader("Content-Type", "application/json;charset=UTF-8");
            StringEntity entity = new StringEntity(body, "UTF-8");
            entity.setContentType("application/json;charset=UTF-8");
            entity.setContentEncoding("utf-8");
            post.setEntity(entity);
            HttpResponse execute = client.execute(new HttpHost(host, port, schema), post);
            return response(execute);
        } catch (Exception e) {
              logger.log(e);
        }
    }

I will wait for few days to see the effect.

Thanks.

Hi @ilaipi in my project have the same problem .it looks like more TCP status is CLOSE_WAIT , could you give us some advise to fix it?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests